Hi James, The timer errors you are seeing are benign in this case. They don't stop registrations from succeeding or being authenticated. (There's a fix for this issue (https://github.com/Metaswitch/cpp-common/issues/42) and it will be present in our next release).
The re-REGISTER not being challenged is fine - Bono recognises that it's come over an authenticated flow, and adds "integrity-protected=ip-assoc-yes" to the authorization header, which means Sprout won't challenge it. If the registration expires, or is explicitly deregistered, and then a client tries to register again then they will have to be authenticated again. The OPTIONS poll is rejected because it's coming from a different source than the REGISTER and so is not authenticated - the port in the Contact header is different in the REGISTER and the OPTIONS. Ellie From: [email protected] [mailto:[email protected]] On Behalf Of James Coleman Sent: 04 March 2014 14:01 To: [email protected] Subject: [Clearwater] chronos timer http 405 errors when receiving REGISTER. Hello, With latest (Another Nine and a Half Weeks) release of clearwater chat is working well initially. There is something a bit funny going on though maintaining chat for more than a few minutes. When problem starts there seem to be a good few errors like this in sprout logs: 03-03-2014 12:15:44.985 Error httpconnection.cpp:390: http://localhost:7253/timers failed at server 127.0.0.1 : HTTP response code said error (22 405) : fatal 03-03-2014 12:15:44.985 Error httpconnection.cpp:429: cURL failure with cURL error code 22 (see man 3 libcurl-errors) and HTTP error code 405 Those 405 errors always appear when REGISTER is received. After the 405 error seen the response to register is always 200 OK (even if no Auth was done). In context . . . When an initial REGISTER is received from clients the usual sequence happens: REGISTER(Auth empty)->, <-401(with nonce), REGISTER(with response)->, <-200 OK OPTIONS queries happen. INVITE starting chat happens. REGISTER is sent again from client(s). Sprout logs a bunch of httpconnection.cpp timers errors. The RESISTER sequence seems to go okay sometimes. But other times I observed the initial REGISTER with empty Auth getting a 200 OK response, Example of messages in sprout log when this happened: 03-03-2014 12:15:44.980 Info authentication.cpp:406: Request integrity protected by edge proxy 03-03-2014 12:15:44.985 Error httpconnection.cpp:390: http://localhost:7253/timers failed at server 127.0.0.1 : HTTP response code said error (22 405) : fatal 03-03-2014 12:15:44.985 Error httpconnection.cpp:429: cURL failure with cURL error code 22 (see man 3 libcurl-errors) and HTTP error code 405 03-03-2014 12:15:44.985 Verbose stack.cpp:237: TX 1010 bytes Response msg 200/REGISTER/cseq=4729 (tdta0x7fcd3c373f80) to TCP 10.124.51.133:41827<http://10.124.51.133:41827>: I have included a log of this heppening below. It can be seen subsequent to the REGISTER 200 answer to REGISTER with empty Auth info that an OPTIONS receives a 403 forbidden. Conclusion: Probably at that point in sprout if error retrieving timer then REGISTER response should be error not 200. But I'm not sure what is causing the timer errors. Questions: What is causing those httpconnection.cpp timers errors? Is something misbehaving and how can it be fixed? Thanks for your help already with use of clearwater! James. my reference: grep Error sprout/sprout_20140303_1200.txt @12:15:44 in log | . | | | 15. SIP REGISTER(empty auth values) | |-------------------------------->| | | Error httpconnection.cpp:390: http://localhost:7253/timers failed in logs | 16. SIP 200 (OK with Service-Route)<------------->| |<--------------------------------| | | . | | 15. REGISTER with empty auth values sent 16. SIP 200 ok in response to empty auth values **PROBLEM** @12:16:48 in log | . | | | 17. SIP OPTIONS | | |-------------------------------->| | | 18. SIP 403 (Forbidden) | | |<--------------------------------| | | . | | 17. OPTIONS 18. OPTIONS answered with 403 forbidden. The system doesn't regard the handset as authenticated. >From sprout log: REGISTER with empty auth received, timer error and REGISTER >response 200 03-03-2014 12:15:44.242 Verbose pjsip: tcplis:5054 TCP listener 10.124.51.133:5054<http://10.124.51.133:5054>: got incoming TCP connection from 10.124.51.133:35374<http://10.124.51.133:35374>, sock=145 03-03-2014 12:15:44.242 Verbose pjsip: tcps0x7fcd0c28 TCP server transport created 03-03-2014 12:15:44.242 Verbose pjsip: tcplis:5054 TCP listener 10.124.51.133:5054<http://10.124.51.133:5054>: got incoming TCP connection from 10.124.51.133:37834<http://10.124.51.133:37834>, sock=190 03-03-2014 12:15:44.242 Verbose pjsip: tcps0x7fcd0c39 TCP server transport created 03-03-2014 12:15:44.248 Verbose pjsip: tcps0x7fcd0c38 TCP connection closed 03-03-2014 12:15:44.248 Verbose pjsip: tcps0x7fcd0c4c TCP connection closed 03-03-2014 12:15:44.248 Verbose pjsip: tcps0x7fcd0c38 TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 03-03-2014 12:15:44.248 Verbose pjsip: tcps0x7fcd0c4c TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 03-03-2014 12:15:44.980 Verbose stack.cpp:221: RX 1218 bytes Request msg REGISTER/cseq=4729 (rdata0x7fcd0c0759a8) from TCP 10.124.51.133:41827<http://10.124.51.133:41827>: --start msg-- REGISTER sip:openims.test SIP/2.0 Path: sip:[email protected]:5058;transport=TCP;lr;ob Via: SIP/2.0/TCP 10.124.51.133:41827;rport;branch=z9hG4bKPjFz9BQkd4gVzM0tYcYOZexCzzG3BumYHb Via: SIP/2.0/TCP 192.168.127.233:49470;rport=49470;received=89.100.100.100;branch=z9hG4bKPjUKSUy86luxlm-qq.J.9V1brTiqzp2wxB Max-Forwards: 69 From: <sip:[email protected]>;tag=7MQ6ubQ3jb1.kESJoDEWy8bai.8s63vB To: <sip:[email protected]> Call-ID: q6QfUaaLaOacs66AJ-VaE4fekF0yCW4T CSeq: 4729 REGISTER Authorization: DIGEST username="[email protected]", realm="openims.test", nonce="", uri="sip:openims.test", response="",integrity-protected=ip-assoc-yes User-Agent: IM-client/OMA1.0 RCSAndrd/2.3.14 COMLib/3.1.0 Contact: <sip:[email protected]:49470;ob>;q=0.5;+sip.instance="<urn:gsma:imei:35592104-359096-5>";+g.3gpp.cs-voice;+g.3gpp.iari-ref="urn%3Aurn-7%3A3gpp-application.ims.iari.gsma-is";+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.oma.cpm.msg";+g.oma.sip-im Expires: 600000 Allow: PRACK, INFO, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: gruu Route: <sip:10.124.51.133:5054;transport=TCP;lr;orig> Content-Length: 0 --end msg-- 03-03-2014 12:15:44.980 Info authentication.cpp:406: Request integrity protected by edge proxy 03-03-2014 12:15:44.985 Error httpconnection.cpp:390: http://localhost:7253/timers failed at server 127.0.0.1 : HTTP response code said error (22 405) : fatal 03-03-2014 12:15:44.985 Error httpconnection.cpp:429: cURL failure with cURL error code 22 (see man 3 libcurl-errors) and HTTP error code 405 03-03-2014 12:15:44.985 Verbose stack.cpp:237: TX 1010 bytes Response msg 200/REGISTER/cseq=4729 (tdta0x7fcd3c373f80) to TCP 10.124.51.133:41827<http://10.124.51.133:41827>: --start msg-- SIP/2.0 200 OK Service-Route: <sip:10.124.51.133:5054;transport=TCP;lr;orig> Via: SIP/2.0/TCP 10.124.51.133:41827;rport=41827;received=10.124.51.133;branch=z9hG4bKPjFz9BQkd4gVzM0tYcYOZexCzzG3BumYHb Via: SIP/2.0/TCP 192.168.127.233:49470;rport=49470;received=89.100.100.100;branch=z9hG4bKPjUKSUy86luxlm-qq.J.9V1brTiqzp2wxB Call-ID: q6QfUaaLaOacs66AJ-VaE4fekF0yCW4T From: <sip:[email protected]>;tag=7MQ6ubQ3jb1.kESJoDEWy8bai.8s63vB To: <sip:[email protected]>;tag=z9hG4bKPjFz9BQkd4gVzM0tYcYOZexCzzG3BumYHb CSeq: 4729 REGISTER Supported: outbound Contact: sip:[email protected]:49470;ob;q=0.5;expires=300;+sip.instance="<urn:gsma:imei:35592104-359096-5>";+g.3gpp.cs-voice;+g.3gpp.iari-ref="urn%3Aurn-7%3A3gpp-application.ims.iari.gsma-is";+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.oma.cpm.msg";+g.oma.sip-im Require: outbound Path: sip:[email protected]:5058;transport=TCP;lr;ob P-Associated-URI: sip:[email protected] Content-Length: 0 --end msg-- 03-03-2014 12:15:44.985 Info registration_utils.cpp:138: Found 0 Application Servers . . 03-03-2014 12:16:49.120 Verbose stack.cpp:221: RX 1287 bytes Request msg OPTIONS/cseq=23252 (rdata0x7f3f000a5648) from UDP 89.100.100.100:56338<http://89.100.100.100:56338>: --start msg-- OPTIONS sip:[email protected];user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.127.233:56338;rport;branch=z9hG4bKPjq84tpUZyMULIysDiJo.0qBe1Axv8hSnt Max-Forwards: 70 From: <sip:[email protected]>;tag=Wd4vdsXM4qLmhNRE6v3fZKxc42N3BFe0 To: <sip:[email protected];user=phone> Call-ID: fvJU1oQSTgPXvf0FG1K2j3Dyt6GqUQQV CSeq: 23252 OPTIONS Route: <sip:54.199.199.199:5060;lr> Route: <sip:10.124.51.133:5054;transport=TCP;lr;orig> User-Agent: IM-client/OMA1.0 RCSAndrd/2.3.14 COMLib/3.1.0 Contact: <sip:[email protected]:56338;ob>;+g.3gpp.iari-ref="urn%3Aurn-7%3A3gpp-application.ims.iari.joyn.intmsg,urn%3Aurn-7%3A3gpp-application.ims.iari.rcs.ftthu mb,urn%3Aurn-7%3A3gpp-application.ims.iari.rcse.ft,urn%3Aurn-7%3A3gpp-application.ims.iari.rcse.im<http://3A3gpp-application.ims.iari.rcse.im>";+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.oma.cpm.msg";+sip.i nstance="<urn:gsma:imei:35592104-359096-5>" Accept-Contact: *;+g.3gpp.iari-ref="urn%3Aurn-7%3A3gpp-application.ims.iari.joyn.intmsg,urn%3Aurn-7%3A3gpp-application.ims.iari.rcs.ftthumb,urn%3Aurn-7%3A3gpp-application.im s.iari.rcse.ft,urn%3Aurn-7%3A3gpp-application.ims.iari.rcse.im<http://3A3gpp-application.ims.iari.rcse.im>";+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.oma.cpm.msg" P-Preferred-Identity: <sip:[email protected]> Content-Length: 0 --end msg-- 03-03-2014 12:16:49.120 Warning stateful_proxy.cpp:1193: Rejecting request from untrusted source 03-03-2014 12:16:49.120 Verbose stack.cpp:237: TX 406 bytes Response msg 403/OPTIONS/cseq=23252 (tdta0x7f3eec001870) to UDP 89.100.100.100:56338<http://89.100.100.100:56338>: --start msg-- SIP/2.0 403 Forbidden Via: SIP/2.0/UDP 192.168.127.233:56338;rport=56338;received=89.100.100.100;branch=z9hG4bKPjq84tpUZyMULIysDiJo.0qBe1Axv8hSnt Call-ID: fvJU1oQSTgPXvf0FG1K2j3Dyt6GqUQQV From: <sip:[email protected]>;tag=Wd4vdsXM4qLmhNRE6v3fZKxc42N3BFe0 To: <sip:[email protected];user=phone>;tag=z9hG4bKPjq84tpUZyMULIysDiJo.0qBe1Axv8hSnt CSeq: 23252 OPTIONS Content-Length: 0 --end msg-- [Image removed by sender.] [Image removed by sender.]<http://www.linkedin.com/company/76647?trk=fc_badge> openmindnetworks.com<http://openmindnetworks.com>
<<inline: ~WRD000.jpg>>
_______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/listinfo/clearwater
