Hi Shiva, The logs you sent were just from Bono, but everything looks normal there – could you send me a log file from Sprout as well?
poll_cassandra_ring being in ‘Waiting’ state is normal – that shouldn’t be causing this problem. It looks similar to previous problems we’ve seen where Sprout couldn’t contact memcached (e.g. because cluster_settings was wrong), which is why I asked if your IP configuration was correct. It’s worth double-checking this, though, so can you: · Check that /etc/clearwater/cluster_settings is valid · Run ‘sudo service sprout reload’ to force /etc/clearwater/cluster_settings to be re-read (and check the Sprout logs and syslog for any errors or warnings) · Run ‘netstat -tnlp’ to check that memcached is listening on port 11211? Thanks, Rob -- Rob Day Software Engineer, Project Clearwater From: Shiva Charan [mailto:[email protected]] Sent: 08 July 2015 10:50 To: Robert Day Subject: Re: [Clearwater] zoiper client number registration fails Hi Rob, Just to add on, earlier we had a issue with the cluster setting which we changed and it went through. Is there any other changes needed for this issue? Thanks, Shiva On Thu, Jul 2, 2015 at 3:39 PM, Shiva Charan <[email protected]<mailto:[email protected]>> wrote: Hi Rob, Yes I have double checked with the ip configuration, everything is in place. I have attached the log file and the homestead monit status output. poll_cassandra_ring is still in waiting state will that make a difference? Thanks, Shiva On Wed, Jul 1, 2015 at 2:21 AM, Robert Day <[email protected]<mailto:[email protected]>> wrote: Hi Shiva, The logs you attached seem to be very short (covering only a 10-millisecond period, and one message in the REGISTER flow), so I haven’t been able to diagnose the issue from them. Is it possible for you to copy off and attach the full log files, rather than a short extract from them? The only things that immediately come to mind as possible causes are: • If your environment uses DHCP, the IP addresses of your VMs may have changed, and you may need to change configuration to reflect this. • The Cassandra database on Homestead may not be running (or may be frequently restarting). Running ‘sudo monit status’ on Homestead should show whether this is the case. Best, Rob -- Rob Day Software Engineer, Project Clearwater From: Shiva Charan [mailto:[email protected]<mailto:[email protected]>] Sent: 30 June 2015 15:25 To: Robert Day Subject: Re: [Clearwater] zoiper client number registration fails Hi Rob, Due to an infrastructure issue we had to restart all the virtual machines after which the calls( from zopier client) are not being registered. Attached here are the bono and sprout logs, any inputs? Shiva On Mon, Jun 22, 2015 at 12:23 PM, Shiva Charan <[email protected]<mailto:[email protected]>> wrote: Hi Rob, Its working now :). There was a IP mismatch in the cluster_settings file. Shiva On Fri, Jun 19, 2015 at 6:46 PM, Shiva Charan <[email protected]<mailto:[email protected]>> wrote: Hi Rob, Thanks for your reply, sorry about the bono log pleas find the log files attached along with the syslog of bono node. syslog shows an error regarding smtp and also few files missing in lib folder. Also attached the config file I am using, the clearwater version of nodes are follows, [ellis]clearwater1@Ellis1:/etc/clearwater$ dpkg-query -W ellis ellis 1.0-150605.133914 [bono]clearwater2@clearwater:~$ dpkg-query -W bono bono 1.0-150216.174621 [sprout]sprout1@sprout1:~$ dpkg-query -W sprout sprout 1.0-150329.161304 [homer]clearwater4@clearwater:~$ dpkg-query -W homer homer 1.0-150213.175004 [homestead]clearwater@ubuntu:~$ dpkg-query -W homestead homestead 1.0-150227.194739 [ralf]clearwater6@clearwater:~$ dpkg-query -W ralf ralf 1.0-150213.143613 Thanks, Shiva On Fri, Jun 19, 2015 at 1:10 AM, Robert Day <[email protected]<mailto:[email protected]>> wrote: Hi Shiva, It looks like those logs might have been truncated – they only contain about 30 lines each, but I’d expect more. Could you send the full log files through from Bono, Sprout and Homestead? (Homestead logs will be useful in investigating authentication failures like this, as they’ll contain information about the subscriber state.) Could you also send the contents of /var/log/syslog? We log high-level troubleshooting logs there, so if there are connectivity issues or similar configuration problems, that might show up in a log there. Thanks, Rob -- Rob Day Software Engineer, Project Clearwater From: [email protected]<mailto:[email protected]> [mailto:[email protected]<mailto:[email protected]>] On Behalf Of Shiva Charan Sent: 17 June 2015 19:26 To: [email protected]<mailto:[email protected]> Subject: [Clearwater] zoiper client number registration fails Hi, In my manual install setup all the services are running but when i try to register a number created from the UI the registration fails. Logs for Bono and Sprout are attached to mail. also the log_current for bono is as below. Bono log_current.txt 17-06-2015 18:00:01.267 UTC Call-Disconnected: CALL_ID=NDc4MjY4Nzk5NzkyMWExMWZiMGFhNzY4MDU4YTUzZDY. REASON=401 17-06-2015 18:00:01.328 UTC Call-Disconnected: CALL_ID=NDc4MjY4Nzk5NzkyMWExMWZiMGFhNzY4MDU4YTUzZDY. REASON=401 17-06-2015 18:00:01.390 UTC Call-Disconnected: CALL_ID=NDc4MjY4Nzk5NzkyMWExMWZiMGFhNzY4MDU4YTUzZDY. REASON=401 17-06-2015 18:00:01.451 UTC Call-Disconnected: Please suggest. Shiva
--end msg-- 02-07-2015 09:35:14.076 UTC Debug stack.cpp:470: Queuing cloned received message 0x7f7658035488 for worker threads 02-07-2015 09:35:14.076 UTC Debug stack.cpp:206: Worker thread dequeue message 0x7f7658035488 02-07-2015 09:35:14.076 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 401/REGISTER/cseq=2469 (rdata0x7f7658035488) 02-07-2015 09:35:14.076 UTC Debug pjsip: tsx0x7f764c053 Incoming Response msg 401/REGISTER/cseq=2469 (rdata0x7f7658035488) in state Calling 02-07-2015 09:35:14.076 UTC Debug pjsip: tsx0x7f764c053 State changed from Calling to Completed, event=RX_MSG 02-07-2015 09:35:14.076 UTC Debug stateful_proxy.cpp:368: tsx0x7f764c053758 - tu_on_tsx_state UAC, TSX_STATE RX_MSG state=Completed 02-07-2015 09:35:14.076 UTC Debug stateful_proxy.cpp:4425: tsx0x7f764c053758 - uac_data = 0x7f764c1750c0, uas_data = 0x7f764c051d00 02-07-2015 09:35:14.076 UTC Debug stateful_proxy.cpp:4464: tsx0x7f764c053758 - RX_MSG on active UAC transaction 02-07-2015 09:35:14.076 UTC Debug trustboundary.cpp:57: Strip trusted headers 02-07-2015 09:35:14.076 UTC Debug stateful_proxy.cpp:3406: tsx0x7f764c053758 - Final response, so disconnect UAS and UAC transactions 02-07-2015 09:35:14.076 UTC Debug pjsip: tdta0x7f764c12 Destroying txdata Response msg 408/REGISTER/cseq=2469 (tdta0x7f764c120f10) 02-07-2015 09:35:14.076 UTC Debug stateful_proxy.cpp:3933: Dissociate UAC transaction 0x7f764c1750c0 (0) 02-07-2015 09:35:14.076 UTC Debug pjsip: tsx0x7f764c120 Sending Response msg 401/REGISTER/cseq=2469 (tdta0x7f76441bf860) in state Trying 02-07-2015 09:35:14.076 UTC Debug pjsip: sip_resolve.c Target '10.0.0.46:35599' type=UDP resolved to '10.0.0.46:35599' type=UDP (UDP transport) 02-07-2015 09:35:14.076 UTC Verbose stack.cpp:259: TX 515 bytes Response msg 401/REGISTER/cseq=2469 (tdta0x7f76441bf860) to UDP 10.0.0.46:35599: --start msg-- SIP/2.0 401 Unauthorized^M Via: SIP/2.0/UDP 204.57.98.108:35599;received=10.0.0.46;branch=z9hG4bK-d8754z-1a13a70a8aa173df-1---d8754z-^M Call-ID: OTVkNTlkZGY1N2YyYzA2YTdlYzRjNTJmYzVjZDQ4YmE.^M From: "6010000000" <sip:[email protected]>;tag=1f06387a^M To: "6010000000" <sip:[email protected]>;tag=z9hG4bKPj2UwMb1h4hKhlZnwaMjxl7oL0FMIa7f7B^M CSeq: 2469 REGISTER^M WWW-Authenticate: Digest realm="10.0.0.44",nonce="1788573b3c8cb334",opaque="57a4532e5689b958",stale=true,algorithm=MD5,qop="auth"^M Content-Length: 0^M ^M --end msg-- 02-07-2015 09:35:14.076 UTC Debug pjsip: tsx0x7f764c120 State changed from Trying to Completed, event=TX_MSG 02-07-2015 09:35:14.076 UTC Debug stateful_proxy.cpp:368: tsx0x7f764c1207a8 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Completed 02-07-2015 09:35:14.076 UTC Debug stateful_proxy.cpp:953: Request received on non-trusted port 5060 02-07-2015 09:35:14.076 UTC Debug stateful_proxy.cpp:3731: Report SAS end marker - trail (d74) 02-07-2015 09:35:14.076 UTC Debug stack.cpp:208: Worker thread completed processing message 0x7f7658035488 02-07-2015 09:35:14.076 UTC Debug stack.cpp:214: Request latency = 621us 02-07-2015 09:35:14.078 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=2470 (rdata0x2916518) 02-07-2015 09:35:14.078 UTC Verbose stack.cpp:243: RX 984 bytes Request msg REGISTER/cseq=2470 (rdata0x2916518) from UDP 10.0.0.46:35599: --start msg-- REGISTER sip:10.0.0.44;transport=UDP SIP/2.0^M Via: SIP/2.0/UDP 204.57.98.108:35599;branch=z9hG4bK-d8754z-c73377af215a4a1f-1---d8754z-^M Max-Forwards: 70^M Contact: <sip:[email protected]:35599;rinstance=85e91bf934a2fe62;transport=UDP>^M To: "6010000000"<sip:[email protected];transport=UDP>^M From: "6010000000"<sip:[email protected];transport=UDP>;tag=1f06387a^M Call-ID: OTVkNTlkZGY1N2YyYzA2YTdlYzRjNTJmYzVjZDQ4YmE.^M CSeq: 2470 REGISTER^M Expires: 3600^M Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE^M Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri^M User-Agent: Z 3.6.25251 r25476^M Authorization: Digest username="[email protected]",realm="10.0.0.44",nonce="1788573b3c8cb334",uri="sip:10.0.0.44;transport=UDP",response="ac85c2949d22e33fe5eb1efea45ff268",cnonce="007117e02127ac5053b725fb12cb8438",nc=00000001,qop=auth,algorithm=MD5,opaque="57a4532e5689b958"^M Allow-Events: presence, kpml^M Content-Length: 0^M ^M --end msg-- 02-07-2015 09:35:14.078 UTC Debug stack.cpp:470: Queuing cloned received message 0x7f7658035488 for worker threads 02-07-2015 09:35:14.078 UTC Debug pjsip: tsx0x7f764c053 Timeout timer event 02-07-2015 09:35:14.078 UTC Debug pjsip: tsx0x7f764c053 State changed from Completed to Terminated, event=TIMER 02-07-2015 09:35:14.078 UTC Debug stateful_proxy.cpp:368: tsx0x7f764c053758 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Terminated 02-07-2015 09:35:14.078 UTC Debug stateful_proxy.cpp:4425: tsx0x7f764c053758 - uac_data = 0x7f764c1750c0, uas_data = (nil) 02-07-2015 09:35:14.078 UTC Debug stack.cpp:206: Worker thread dequeue message 0x7f7658035488 02-07-2015 09:35:14.078 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=2470 (rdata0x7f7658035488) 02-07-2015 09:35:14.078 UTC Debug stateful_proxy.cpp:260: Proxy RX request 02-07-2015 09:35:14.078 UTC Debug pjsip: tsx0x7f764c053 Timeout timer event 02-07-2015 09:35:14.078 UTC Debug pjutils.cpp:680: Cloned Request msg REGISTER/cseq=2470 (rdata0x7f7658035488) to tdta0x7f76380800e0 02-07-2015 09:35:14.078 UTC Debug stateful_proxy.cpp:953: Request received on non-trusted port 5060 02-07-2015 09:35:14.078 UTC Debug pjsip: tsx0x7f764c053 State changed from Terminated to Destroyed, event=TIMER 02-07-2015 09:35:14.078 UTC Debug stateful_proxy.cpp:368: tsx0x7f764c053758 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Destroyed 02-07-2015 09:35:14.078 UTC Debug stateful_proxy.cpp:4425: tsx0x7f764c053758 - uac_data = 0x7f764c1750c0, uas_data = (nil) 02-07-2015 09:35:14.078 UTC Debug stateful_proxy.cpp:4512: tsx0x7f764c053758 - UAC tsx destroyed 02-07-2015 09:35:14.078 UTC Debug stateful_proxy.cpp:1225: Perform access proxy routing for REGISTER request 02-07-2015 09:35:14.078 UTC Debug stateful_proxy.cpp:1262: Message requires outbound support 02-07-2015 09:35:14.078 UTC Debug pjsip: tdta0x7f764c17 Destroying txdata Request msg REGISTER/cseq=2469 (tdta0x7f764c1751f0) 02-07-2015 09:35:14.079 UTC Debug flowtable.cpp:91: Find or create flow for transport udp0x241ce20 (1), remote address 10.0.0.46:35599 02-07-2015 09:35:14.079 UTC Debug flowtable.cpp:115: Found flow record 0x7f76340028a0 02-07-2015 09:35:14.079 UTC Debug flowtable.cpp:602: Dialog count now 2 for flow 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:1274: Found or created flow data record, token = jzFk19/BH7 02-07-2015 09:35:14.079 UTC Info pjutils.cpp:446: Adding integrity-protected=ip-assoc-pending indicator to message 02-07-2015 09:35:14.079 UTC Debug flowtable.cpp:619: Dialog count now 1 for flow 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:1183: Mark originating 02-07-2015 09:35:14.079 UTC Info stateful_proxy.cpp:1204: Route request to upstream proxy sip:10.0.0.42:5054;transport=TCP;lr;orig 02-07-2015 09:35:14.079 UTC Debug acr.cpp:1706: Create RalfACR for node type P-CSCF with role Originating 02-07-2015 09:35:14.079 UTC Debug acr.cpp:48: Created ACR (0x7f7638075120) 02-07-2015 09:35:14.079 UTC Debug acr.cpp:166: Created P-CSCF Ralf ACR 02-07-2015 09:35:14.079 UTC Debug acr.cpp:205: Set record type for P/S-CSCF 02-07-2015 09:35:14.079 UTC Debug acr.cpp:213: Non-dialog message => EVENT_RECORD 02-07-2015 09:35:14.079 UTC Debug acr.cpp:1434: Stored 0 subscription identifiers 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:596: Trust mode INBOUND_EDGE_CLIENT(,-rsp,-pch), serving state None 02-07-2015 09:35:14.079 UTC Debug pjsip: tsx0x7f7638145 Transaction created for Request msg REGISTER/cseq=2470 (rdata0x7f7658035488) 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:2259: UASTransaction constructor (0x7f7638145f80) 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:2260: ACR (0x7f7638075120) 02-07-2015 09:35:14.079 UTC Debug pjsip: tsx0x7f7638145 Incoming Request msg REGISTER/cseq=2470 (rdata0x7f7658035488) in state Null 02-07-2015 09:35:14.079 UTC Debug pjsip: tsx0x7f7638145 State changed from Null to Trying, event=RX_MSG 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:368: tsx0x7f7638145818 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying 02-07-2015 09:35:14.079 UTC Debug pjsip: endpoint Response msg 408/REGISTER/cseq=2470 (tdta0x7f7638141af0) created 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:3707: Report SAS start marker - trail (d75) 02-07-2015 09:35:14.079 UTC Debug trustboundary.cpp:67: Add P-Charging headers 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:3796: Allocating transaction and data for target 0 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:4205: Stripping loose routes from proxied message 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:4232: Adding a Route header to sip:10.0.0.42:5054;transport=TCP 02-07-2015 09:35:14.079 UTC Debug pjsip: tsx0x7f7638158 Transaction created for Request msg REGISTER/cseq=2470 (tdta0x7f7638142b00) 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:3823: Adding trail identifier 3445 to UAC transaction 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:3842: Updating request URI and route for target 0 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:4300: Transport tcpc0x7f762c0549c8 (TCP to 10.0.0.42:5054) pre-selected for transaction 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:4318: Sending request for sip:10.0.0.44;transport=UDP 02-07-2015 09:35:14.079 UTC Debug pjsip: tsx0x7f7638158 Sending Request msg REGISTER/cseq=2470 (tdta0x7f7638142b00) in state Null 02-07-2015 09:35:14.079 UTC Debug pjsip: endpoint Request msg REGISTER/cseq=2470 (tdta0x7f7638142b00): skipping target resolution because address is already set 02-07-2015 09:35:14.079 UTC Verbose stack.cpp:259: TX 1278 bytes Request msg REGISTER/cseq=2470 (tdta0x7f7638142b00) to TCP 10.0.0.42:5054: --start msg-- REGISTER sip:10.0.0.44;transport=UDP SIP/2.0^M Via: SIP/2.0/TCP 10.0.0.44:42513;rport;branch=z9hG4bKPjuczhYhnVlwSTbOR7EPnYlgipQfonYWW6^M Path: <sip:jzFk19/[email protected]:5058;transport=TCP;lr;ob>^M Via: SIP/2.0/UDP 204.57.98.108:35599;received=10.0.0.46;branch=z9hG4bK-d8754z-c73377af215a4a1f-1---d8754z-^M Max-Forwards: 70^M Contact: <sip:[email protected]:35599;transport=UDP;rinstance=85e91bf934a2fe62>^M To: "6010000000" <sip:[email protected]>^M From: "6010000000" <sip:[email protected]>;tag=1f06387a^M Call-ID: OTVkNTlkZGY1N2YyYzA2YTdlYzRjNTJmYzVjZDQ4YmE.^M CSeq: 2470 REGISTER^M Expires: 3600^M Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE^M Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri^M User-Agent: Z 3.6.25251 r25476^M Authorization: Digest username="[email protected]", realm="10.0.0.44", nonce="1788573b3c8cb334", uri="sip:10.0.0.44;transport=UDP", response="ac85c2949d22e33fe5eb1efea45ff268", algorithm=MD5, cnonce="007117e02127ac5053b725fb12cb8438", opaque="57a4532e5689b958", qop=auth, nc=00000001,integrity-protected=ip-assoc-pending^M Allow-Events: presence, kpml^M P-Visited-Network-ID: 10.0.0.44^M Session-Expires: 600^M Route: <sip:10.0.0.42:5054;transport=TCP;lr;orig>^M Content-Length: 0^M ^M --end msg-- 02-07-2015 09:35:14.079 UTC Debug pjsip: tsx0x7f7638158 State changed from Null to Calling, event=TX_MSG 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:368: tsx0x7f7638158c98 - tu_on_tsx_state UAC, TSX_STATE TX_MSG state=Calling 02-07-2015 09:35:14.079 UTC Debug stateful_proxy.cpp:4425: tsx0x7f7638158c98 - uac_data = 0x7f7638146320, uas_data = 0x7f7638145f80 02-07-2015 09:35:14.079 UTC Debug stack.cpp:208: Worker thread completed processing message 0x7f7658035488 02-07-2015 09:35:14.079 UTC Debug stack.cpp:214: Request latency = 1335us 02-07-2015 09:35:14.124 UTC Debug pjsip: tsx0x7f7650161 Timeout timer event 02-07-2015 09:35:14.124 UTC Debug pjsip: tsx0x7f7650161 State changed from Completed to Terminated, event=TIMER 02-07-2015 09:35:14.124 UTC Debug stateful_proxy.cpp:368: tsx0x7f7650161e88 - tu_on_tsx_state UAS, TSX_STATE TIMER state=Terminated 02-07-2015 09:35:14.124 UTC Debug pjsip: tsx0x7f7650161 Timeout timer event 02-07-2015 09:35:14.124 UTC Debug pjsip: tsx0x7f7650161 State changed from Terminated to Destroyed, event=TIMER 02-07-2015 09:35:14.124 UTC Debug stateful_proxy.cpp:368: tsx0x7f7650161e88 - tu_on_tsx_state UAS, TSX_STATE TIMER state=Destroyed 02-07-2015 09:35:14.124 UTC Debug stateful_proxy.cpp:3497: tsx0x7f7650161e88 - UAS tsx destroyed 02-07-2015 09:35:14.124 UTC Debug stateful_proxy.cpp:2304: UASTransaction destructor (0x7f76501625f0) 02-07-2015 09:35:14.124 UTC Debug stateful_proxy.cpp:2324: Disconnect UAC transactions from UAS transaction 02-07-2015 09:35:14.124 UTC Debug stateful_proxy.cpp:2370: Transaction is not linked to an AS chain(s) 02-07-2015 09:35:14.124 UTC Debug stateful_proxy.cpp:2371: Upstream ACR = 0x7f765012e7a0, Downstream ACR = 0x7f765012e7a0 02-07-2015 09:35:14.125 UTC Verbose acr.cpp:617: Sending P-CSCF Ralf ACR (0x7f765012e7a0) 02-07-2015 09:35:14.125 UTC Debug acr.cpp:633: Building message 02-07-2015 09:35:14.125 UTC Debug acr.cpp:650: Adding peers meta-data, 0 ccfs, 0 ecfs 02-07-2015 09:35:14.125 UTC Debug acr.cpp:689: Building event 02-07-2015 09:35:14.125 UTC Debug acr.cpp:694: Adding Account-Record-Type AVP 1 02-07-2015 09:35:14.125 UTC Debug acr.cpp:714: Adding Service-Information AVP group 02-07-2015 09:35:14.125 UTC Debug acr.cpp:724: Adding 1 Subscription-Id AVPs 02-07-2015 09:35:14.125 UTC Debug acr.cpp:750: Adding IMS-Information AVP group 02-07-2015 09:35:14.125 UTC Debug acr.cpp:755: Adding Event-Type AVP group 02-07-2015 09:35:14.125 UTC Debug acr.cpp:784: Adding 0 Calling-Party-Address AVPs 02-07-2015 09:35:14.125 UTC Debug acr.cpp:804: Adding Called-Party-Address AVP 02-07-2015 09:35:14.125 UTC Debug acr.cpp:825: Adding 0 Called-Asserted-Identity AVPs 02-07-2015 09:35:14.125 UTC Debug acr.cpp:846: Adding 0 Associated-URI AVPs 02-07-2015 09:35:14.125 UTC Debug acr.cpp:865: Adding Time-Stamps AVP group 02-07-2015 09:35:14.125 UTC Debug acr.cpp:955: Adding 0 Transit-IOI-List AVPs 02-07-2015 09:35:14.125 UTC Debug acr.cpp:1031: Adding 0 Early-Media-Description AVPs 02-07-2015 09:35:14.125 UTC Debug acr.cpp:1059: Adding 0 Message-Body AVPs 02-07-2015 09:35:14.125 UTC Debug acr.cpp:1139: Adding Cause-Code(401) AVP to ACR[Interim] 02-07-2015 09:35:14.125 UTC Debug acr.cpp:1145: Adding 0 Reason-Header AVPs 02-07-2015 09:35:14.125 UTC Debug acr.cpp:1163: Adding 0 Access-Network-Information AVPs 02-07-2015 09:35:14.125 UTC Debug acr.cpp:1181: Adding From-Address AVP 02-07-2015 09:35:14.125 UTC Debug acr.cpp:1203: Adding Route-Header-Transmitted AVP 02-07-2015 09:35:14.125 UTC Debug httpresolver.cpp:70: HttpResolver::resolve for host 10.0.0.34, port 10888, family 2 02-07-2015 09:35:14.125 UTC Debug baseresolver.cpp:501: Attempt to parse 10.0.0.34 as IP address 02-07-2015 09:35:14.125 UTC Debug httpresolver.cpp:78: Target is an IP address 02-07-2015 09:35:14.125 UTC Debug httpconnection.cpp:553: Sending HTTP request : http://10.0.0.34:10888/call-id/OTVkNTlkZGY1N2YyYzA2YTdlYzRjNTJmYzVjZDQ4YmE. (trying 10.0.0.34) on new connection 02-07-2015 09:35:14.126 UTC Debug httpconnection.cpp:854: Received header http/1.1400badrequest with value 02-07-2015 09:35:14.126 UTC Debug httpconnection.cpp:854: Received header content-length with value 0 02-07-2015 09:35:14.126 UTC Debug httpconnection.cpp:854: Received header with value 02-07-2015 09:35:14.127 UTC Debug httpconnection.cpp:568: Received HTTP response: status=400, doc= 02-07-2015 09:35:14.127 UTC Error httpconnection.cpp:688: cURL failure with cURL error code 0 (see man 3 libcurl-errors) and HTTP error code 400 02-07-2015 09:35:14.127 UTC Warning acr.cpp:627: Failed to send Ralf ACR message (0x7f765012e7a0), rc = 400 02-07-2015 09:35:14.127 UTC Debug acr.cpp:53: Destroyed ACR (0x7f765012e7a0) 02-07-2015 09:35:14.127 UTC Debug stateful_proxy.cpp:2400: Free original request (0x7f7650184458) 02-07-2015 09:35:14.127 UTC Debug pjsip: tdta0x7f765018 Destroying txdata Request msg REGISTER/cseq=1922 (tdta0x7f76501843b0) 02-07-2015 09:35:14.127 UTC Debug stateful_proxy.cpp:2431: UASTransaction destructor completed 02-07-2015 09:35:14.127 UTC Debug pjsip: tdta0x7f764c15 Destroying txdata Response msg 401/REGISTER/cseq=1922 (tdta0x7f764c151d40) 02-07-2015 09:35:14.127 UTC Debug pjsip: tsx0x7f7650161 Transaction destroyed! 02-07-2015 09:35:14.127 UTC Debug pjsip: tsx0x7f7650132 Transaction destroyed! 02-07-2015 09:35:14.134 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Response msg 401/REGISTER/cseq=2470 (rdata0x7f762c054cb8) 02-07-2015 09:35:14.134 UTC Verbose stack.cpp:243: RX 629 bytes Response msg 401/REGISTER/cseq=2470 (rdata0x7f762c054cb8) from TCP 10.0.0.42:5054: --start msg-- SIP/2.0 401 Unauthorized^M Via: SIP/2.0/TCP 10.0.0.44:42513;rport=42513;received=10.0.0.44;branch=z9hG4bKPjuczhYhnVlwSTbOR7EPnYlgipQfonYWW6^M Via: SIP/2.0/UDP 204.57.98.108:35599;received=10.0.0.46;branch=z9hG4bK-d8754z-c73377af215a4a1f-1---d8754z-^M Call-ID: OTVkNTlkZGY1N2YyYzA2YTdlYzRjNTJmYzVjZDQ4YmE.^M From: "6010000000" <sip:[email protected]>;tag=1f06387a^M To: "6010000000" <sip:[email protected]>;tag=z9hG4bKPjuczhYhnVlwSTbOR7EPnYlgipQfonYWW6^M CSeq: 2470 REGISTER^M WWW-Authenticate: Digest realm="10.0.0.44",nonce="7ca7f44c715d34c0",opaque="00ecfe893d32be42",stale=true,algorithm=MD5,qop="auth"^M Content-Length: 0^M ^M --end msg-- 02-07-2015 09:35:14.134 UTC Debug stack.cpp:470: Queuing cloned received message 0x7f7658035488 for worker threads 02-07-2015 09:35:14.134 UTC Debug stack.cpp:206: Worker thread dequeue message 0x7f7658035488 02-07-2015 09:35:14.134 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 401/REGISTER/cseq=2470 (rdata0x7f7658035488) 02-07-2015 09:35:14.134 UTC Debug pjsip: tsx0x7f7638158 Incoming Response msg 401/REGISTER/cseq=2470 (rdata0x7f7658035488) in state Calling 02-07-2015 09:35:14.134 UTC Debug pjsip: tsx0x7f7638158 State changed from Calling to Completed, event=RX_MSG 02-07-2015 09:35:14.134 UTC Debug stateful_proxy.cpp:368: tsx0x7f7638158c98 - tu_on_tsx_state UAC, TSX_STATE RX_MSG state=Completed 02-07-2015 09:35:14.134 UTC Debug stateful_proxy.cpp:4425: tsx0x7f7638158c98 - uac_data = 0x7f7638146320, uas_data = 0x7f7638145f80 02-07-2015 09:35:14.134 UTC Debug stateful_proxy.cpp:4464: tsx0x7f7638158c98 - RX_MSG on active UAC transaction 02-07-2015 09:35:14.134 UTC Debug trustboundary.cpp:57: Strip trusted headers 02-07-2015 09:35:14.134 UTC Debug stateful_proxy.cpp:3406: tsx0x7f7638158c98 - Final response, so disconnect UAS and UAC transactions 02-07-2015 09:35:14.134 UTC Debug pjsip: tdta0x7f763814 Destroying txdata Response msg 408/REGISTER/cseq=2470 (tdta0x7f7638141af0) 02-07-2015 09:35:14.134 UTC Debug stateful_proxy.cpp:3933: Dissociate UAC transaction 0x7f7638146320 (0) 02-07-2015 09:35:14.135 UTC Debug pjsip: tsx0x7f7638145 Sending Response msg 401/REGISTER/cseq=2470 (tdta0x7f763c03f930) in state Trying 02-07-2015 09:35:14.135 UTC Debug pjsip: sip_resolve.c Target '10.0.0.46:35599' type=UDP resolved to '10.0.0.46:35599' type=UDP (UDP transport) 02-07-2015 09:35:14.135 UTC Verbose stack.cpp:259: TX 515 bytes Response msg 401/REGISTER/cseq=2470 (tdta0x7f763c03f930) to UDP 10.0.0.46:35599: --start msg-- SIP/2.0 401 Unauthorized^M Via: SIP/2.0/UDP 204.57.98.108:35599;received=10.0.0.46;branch=z9hG4bK-d8754z-c73377af215a4a1f-1---d8754z-^M Call-ID: OTVkNTlkZGY1N2YyYzA2YTdlYzRjNTJmYzVjZDQ4YmE.^M From: "6010000000" <sip:[email protected]>;tag=1f06387a^M To: "6010000000" <sip:[email protected]>;tag=z9hG4bKPjuczhYhnVlwSTbOR7EPnYlgipQfonYWW6^M CSeq: 2470 REGISTER^M WWW-Authenticate: Digest realm="10.0.0.44",nonce="7ca7f44c715d34c0",opaque="00ecfe893d32be42",stale=true,algorithm=MD5,qop="auth"^M Content-Length: 0^M ^M --end msg-- 02-07-2015 09:35:14.135 UTC Debug pjsip: tsx0x7f7638145 State changed from Trying to Completed, event=TX_MSG 02-07-2015 09:35:14.135 UTC Debug stateful_proxy.cpp:368: tsx0x7f7638145818 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Completed 02-07-2015 09:35:14.135 UTC Debug stateful_proxy.cpp:953: Request received on non-trusted port 5060 02-07-2015 09:35:14.135 UTC Debug stateful_proxy.cpp:3731: Report SAS end marker - trail (d75) 02-07-2015 09:35:14.135 UTC Debug stack.cpp:208: Worker thread completed processing message 0x7f7658035488 02-07-2015 09:35:14.135 UTC Debug stack.cpp:214: Request latency = 674us 02-07-2015 09:35:14.137 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=2471 (rdata0x2927ed8) 02-07-2015 09:35:14.137 UTC Verbose stack.cpp:243: RX 984 bytes Request msg REGISTER/cseq=2471 (rdata0x2927ed8) from UDP 10.0.0.46:35599: --start msg-- REGISTER sip:10.0.0.44;transport=UDP SIP/2.0^M Via: SIP/2.0/UDP 204.57.98.108:35599;branch=z9hG4bK-d8754z-efbb9b6d031e2338-1---d8754z-^M Max-Forwards: 70^M Contact: <sip:[email protected]:35599;rinstance=85e91bf934a2fe62;transport=UDP>^M To: "6010000000"<sip:[email protected];transport=UDP>^M From: "6010000000"<sip:[email protected];transport=UDP>;tag=1f06387a^M Call-ID: OTVkNTlkZGY1N2YyYzA2YTdlYzRjNTJmYzVjZDQ4YmE.^M CSeq: 2471 REGISTER^M Expires: 3600^M Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE^M Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri^M User-Agent: Z 3.6.25251 r25476^M Authorization: Digest username="[email protected]",realm="10.0.0.44",nonce="7ca7f44c715d34c0",uri="sip:10.0.0.44;transport=UDP",response="2d903ce2639fa1aae05e18b2c0df8f4c",cnonce="9dfdd48624445346096239abd1e49a4d",nc=00000001,qop=auth,algorithm=MD5,opaque="00ecfe893d32be42"^M Allow-Events: presence, kpml^M Content-Length: 0^M --end msg-- 02-07-2015 09:35:14.137 UTC Debug stack.cpp:470: Queuing cloned received message 0x7f7658035488 for worker threads 02-07-2015 09:35:14.137 UTC Debug pjsip: tsx0x7f7638158 Timeout timer event 02-07-2015 09:35:14.137 UTC Debug pjsip: tsx0x7f7638158 State changed from Completed to Terminated, event=TIMER 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:368: tsx0x7f7638158c98 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Terminated 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:4425: tsx0x7f7638158c98 - uac_data = 0x7f7638146320, uas_data = (nil) 02-07-2015 09:35:14.137 UTC Debug stack.cpp:206: Worker thread dequeue message 0x7f7658035488 02-07-2015 09:35:14.137 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=2471 (rdata0x7f7658035488) 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:260: Proxy RX request 02-07-2015 09:35:14.137 UTC Debug pjutils.cpp:680: Cloned Request msg REGISTER/cseq=2471 (rdata0x7f7658035488) to tdta0x7f7630137e80 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:953: Request received on non-trusted port 5060 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:1225: Perform access proxy routing for REGISTER request 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:1262: Message requires outbound support 02-07-2015 09:35:14.137 UTC Debug flowtable.cpp:91: Find or create flow for transport udp0x241ce20 (1), remote address 10.0.0.46:35599 02-07-2015 09:35:14.137 UTC Debug flowtable.cpp:115: Found flow record 0x7f76340028a0 02-07-2015 09:35:14.137 UTC Debug flowtable.cpp:602: Dialog count now 2 for flow 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:1274: Found or created flow data record, token = jzFk19/BH7 02-07-2015 09:35:14.137 UTC Info pjutils.cpp:446: Adding integrity-protected=ip-assoc-pending indicator to message 02-07-2015 09:35:14.137 UTC Debug flowtable.cpp:619: Dialog count now 1 for flow 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:1183: Mark originating 02-07-2015 09:35:14.137 UTC Info stateful_proxy.cpp:1204: Route request to upstream proxy sip:10.0.0.42:5054;transport=TCP;lr;orig 02-07-2015 09:35:14.137 UTC Debug acr.cpp:1706: Create RalfACR for node type P-CSCF with role Originating 02-07-2015 09:35:14.137 UTC Debug acr.cpp:48: Created ACR (0x7f7630080460) 02-07-2015 09:35:14.137 UTC Debug acr.cpp:166: Created P-CSCF Ralf ACR 02-07-2015 09:35:14.137 UTC Debug acr.cpp:205: Set record type for P/S-CSCF 02-07-2015 09:35:14.137 UTC Debug acr.cpp:213: Non-dialog message => EVENT_RECORD 02-07-2015 09:35:14.137 UTC Debug acr.cpp:1434: Stored 0 subscription identifiers 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:596: Trust mode INBOUND_EDGE_CLIENT(,-rsp,-pch), serving state None 02-07-2015 09:35:14.137 UTC Debug pjsip: tsx0x7f7630139 Transaction created for Request msg REGISTER/cseq=2471 (rdata0x7f7658035488) 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:2259: UASTransaction constructor (0x7f763013a2d0) 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:2260: ACR (0x7f7630080460) 02-07-2015 09:35:14.137 UTC Debug pjsip: tsx0x7f7630139 Incoming Request msg REGISTER/cseq=2471 (rdata0x7f7658035488) in state Null 02-07-2015 09:35:14.137 UTC Debug pjsip: tsx0x7f7630139 State changed from Null to Trying, event=RX_MSG 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:368: tsx0x7f7630139b68 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying 02-07-2015 09:35:14.137 UTC Debug pjsip: endpoint Response msg 408/REGISTER/cseq=2471 (tdta0x7f763013a460) created 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:3707: Report SAS start marker - trail (d76) 02-07-2015 09:35:14.137 UTC Debug trustboundary.cpp:67: Add P-Charging headers 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:3796: Allocating transaction and data for target 0 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:4205: Stripping loose routes from proxied message 02-07-2015 09:35:14.137 UTC Debug stateful_proxy.cpp:4232: Adding a Route header to sip:10.0.0.42:5054;transport=TCP 02-07-2015 09:35:14.138 UTC Debug pjsip: tsx0x7f763015a Transaction created for Request msg REGISTER/cseq=2471 (tdta0x7f7630157d30) 02-07-2015 09:35:14.138 UTC Debug stateful_proxy.cpp:3823: Adding trail identifier 3446 to UAC transaction 02-07-2015 09:35:14.138 UTC Debug stateful_proxy.cpp:3842: Updating request URI and route for target 0 02-07-2015 09:35:14.138 UTC Debug stateful_proxy.cpp:4300: Transport tcpc0x7f762c01f4d8 (TCP to 10.0.0.42:5054) pre-selected for transaction 02-07-2015 09:35:14.138 UTC Debug stateful_proxy.cpp:4318: Sending request for sip:10.0.0.44;transport=UDP 02-07-2015 09:35:14.138 UTC Debug stateful_proxy.cpp:4318: Sending request for sip:10.0.0.44;transport=UDP 02-07-2015 09:35:14.138 UTC Debug pjsip: tsx0x7f763015a Sending Request msg REGISTER/cseq=2471 (tdta0x7f7630157d30) in state Null 02-07-2015 09:35:14.138 UTC Debug pjsip: endpoint Request msg REGISTER/cseq=2471 (tdta0x7f7630157d30): skipping target resolution because address is already set 02-07-2015 09:35:14.138 UTC Verbose stack.cpp:259: TX 1278 bytes Request msg REGISTER/cseq=2471 (tdta0x7f7630157d30) to TCP 10.0.0.42:5054: --start msg-- REGISTER sip:10.0.0.44;transport=UDP SIP/2.0^M Via: SIP/2.0/TCP 10.0.0.44:52213;rport;branch=z9hG4bKPj8fWH4vsjviOrYgyoWx.vGjvaRzivwsm2^M Path: <sip:jzFk19/[email protected]:5058;transport=TCP;lr;ob>^M Via: SIP/2.0/UDP 204.57.98.108:35599;received=10.0.0.46;branch=z9hG4bK-d8754z-efbb9b6d031e2338-1---d8754z-^M Max-Forwards: 70^M Contact: <sip:[email protected]:35599;transport=UDP;rinstance=85e91bf934a2fe62>^M To: "6010000000" <sip:[email protected]>^M From: "6010000000" <sip:[email protected]>;tag=1f06387a^M Call-ID: OTVkNTlkZGY1N2YyYzA2YTdlYzRjNTJmYzVjZDQ4YmE.^M CSeq: 2471 REGISTER^M Expires: 3600^M Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE^M Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri^M User-Agent: Z 3.6.25251 r25476^M Authorization: Digest username="[email protected]", realm="10.0.0.44", nonce="7ca7f44c715d34c0", uri="sip:10.0.0.44;transport=UDP", response="2d903ce2639fa1aae05e18b2c0df8f4c", algorithm=MD5, cnonce="9dfdd48624445346096239abd1e49a4d", opaque="00ecfe893d32be42", qop=auth, nc=00000001,integrity-protected=ip-assoc-pending^M Allow-Events: presence, kpml^M P-Visited-Network-ID: 10.0.0.44^M Session-Expires: 600^M Route: <sip:10.0.0.42:5054;transport=TCP;lr;orig>^M Content-Length: 0^M ^M --end msg--
The Monit daemon 5.8.1 uptime: 1h 41m Process 'snmpd' status Running monitoring status Monitored pid 1160 parent pid 1 uid 109 effective uid 109 gid 115 uptime 3h 1m children 0 memory kilobytes 8036 memory kilobytes total 8036 memory percent 0.0% memory percent total 0.0% cpu percent 0.0% cpu percent total 0.0% data collected Thu, 02 Jul 2015 04:50:23 Process 'nginx' status Running monitoring status Monitored pid 1145 parent pid 1 uid 0 effective uid 0 gid 0 uptime 3h 1m children 4 memory kilobytes 1244 memory kilobytes total 8592 memory percent 0.0% memory percent total 0.0% cpu percent 0.0% cpu percent total 0.0% port response time 0.000s to 127.0.0.1:80/ping [HTTP via TCP] data collected Thu, 02 Jul 2015 04:50:23 Program 'poll_homestead' status Status ok monitoring status Monitored last started Thu, 02 Jul 2015 04:50:23 last exit value 0 data collected Thu, 02 Jul 2015 04:50:23 Process 'homestead' status Running monitoring status Monitored pid 1766 parent pid 1 uid 999 effective uid 999 gid 999 uptime 3h 1m children 0 memory kilobytes 41268 memory kilobytes total 41268 memory percent 0.2% memory percent total 0.2% cpu percent 0.1% cpu percent total 0.1% data collected Thu, 02 Jul 2015 04:50:23 Program 'poll_homestead-prov' status Status ok monitoring status Monitored last started Thu, 02 Jul 2015 04:50:23 last exit value 0 data collected Thu, 02 Jul 2015 04:50:23 Process 'homestead-prov' status Running monitoring status Monitored pid 7991 parent pid 1 uid 0 effective uid 0 gid 0 uptime 1h 40m children 0 memory kilobytes 44268 memory kilobytes total 44268 memory percent 0.2% memory percent total 0.2% cpu percent 0.0% cpu percent total 0.0% data collected Thu, 02 Jul 2015 04:50:23 Process 'clearwater_diags_monitor' status Running monitoring status Monitored pid 7782 parent pid 1 uid 0 effective uid 0 gid 0 uptime 1h 41m children 1 memory kilobytes 1632 memory kilobytes total 2012 memory percent 0.0% memory percent total 0.0% cpu percent 0.0% cpu percent total 0.0% data collected Thu, 02 Jul 2015 04:50:23 Program 'poll_cassandra_ring' status Waiting monitoring status Waiting last started Thu, 02 Jul 2015 04:46:03 last exit value 0 data collected Thu, 02 Jul 2015 04:50:03 Process 'cassandra' status Running monitoring status Monitored pid 1398 parent pid 1396 uid 106 effective uid 106 gid 113 uptime 3h 1m children 0 memory kilobytes 4547396 memory kilobytes total 4547396 memory percent 27.6% memory percent total 27.6% cpu percent 0.1% cpu percent total 0.1% data collected Thu, 02 Jul 2015 04:50:23 System 'ubuntu' status Running monitoring status Monitored load average [0.00] [0.01] [0.05] cpu 0.2%us 0.2%sy 0.0%wa memory usage 4913784 kB [29.9%] swap usage 0 kB [0.0%] data collected Thu, 02 Jul 2015 04:50:23
_______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/listinfo/clearwater
