Hi Anne, Thanks for replying.
Attaching the file for the relevant duration. Thanks, Nishank On Tue, Aug 21, 2018 at 2:34 PM, Anne Boffey <anne.bof...@metaswitch.com> wrote: > Hi Nishank, > > > > A 408 Request Timeout could be coming from Clearwater (because its > requests upstream are timing out) or from Zoiper (because its requests to > Clearwater are timing out). > > > > To help tell which is the case, could you turn on debug logging on Bono, by > following the steps here: > > http://clearwater.readthedocs.io/en/stable/Troubleshooting_and_Recovery.html#bono > and see if the SIP INVITE and 408 appear in Bono’s logs. > > > > Then if you reproduce the problem, and send us the logs from the time of the > reproduced problem (the logs are in /var/log/bono/bono*.txt) we can take a > look at those and see if that shows where the problem is. > > > > Thanks, > > Anne. > > > > _______________________________________________ > Clearwater mailing list > Clearwater@lists.projectclearwater.org > http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists. > projectclearwater.org > >
21-08-2018 10:01:25.608 UTC [7ffb047f0700] Debug baseresolver.cpp:587: 40.40.40.5:5052;transport=TCP has state: WHITE 21-08-2018 10:01:25.608 UTC [7ffb047f0700] Debug baseresolver.cpp:587: 171.168.1.162:5052;transport=TCP has state: WHITE 21-08-2018 10:01:25.608 UTC [7ffb047f0700] Debug baseresolver.cpp:883: Added a whitelisted server to targets, now have 1 of 1 21-08-2018 10:01:25.608 UTC [7ffb047f0700] Debug sip_connection_pool.cpp:154: Successfully resolved icscf.sprout.clearwater.local to IPv4 address 21-08-2018 10:01:25.608 UTC [7ffb047f0700] Verbose pjsip: tcpc0x3d1ab38 tcp->base.local_name: 40.40.40.6 21-08-2018 10:01:25.608 UTC [7ffb047f0700] Verbose pjsip: tcpc0x3d1ab38 TCP client transport created 21-08-2018 10:01:25.608 UTC [7ffb047f0700] Verbose pjsip: tcpc0x3d1ab38 TCP transport 40.40.40.6:5058 is connecting to 171.168.1.162:5052... 21-08-2018 10:01:25.608 UTC [7ffb047f0700] Debug sip_connection_pool.cpp:224: Created transport tcpc0x3d1ab38 in slot 37 (40.40.40.6:5058 to 171.168.1.162:5052) 21-08-2018 10:01:25.619 UTC [7ffb027ec700] Verbose pjsip: tcpc0x3d1ab38 TCP transport 40.40.40.6:5058 is connected to 171.168.1.162:5052 21-08-2018 10:01:25.619 UTC [7ffb027ec700] Debug sip_connection_pool.cpp:317: Transport tcpc0x3d1ab38 in slot 37 has connected 21-08-2018 10:01:29.094 UTC [7ffb288ad700] Status alarm.cpp:244: Reraising all alarms with a known state 21-08-2018 10:01:29.094 UTC [7ffb288ad700] Debug alarm.cpp:303: AlarmReqAgent: queue overflowed 21-08-2018 10:01:29.094 UTC [7ffb288ad700] Status alarm.cpp:37: sprout issued 1005.1 alarm 21-08-2018 10:01:29.094 UTC [7ffb288ad700] Debug alarm.cpp:303: AlarmReqAgent: queue overflowed 21-08-2018 10:01:29.094 UTC [7ffb288ad700] Status alarm.cpp:37: sprout issued 1012.3 alarm 21-08-2018 10:01:29.094 UTC [7ffb288ad700] Debug alarm.cpp:303: AlarmReqAgent: queue overflowed 21-08-2018 10:01:29.094 UTC [7ffb288ad700] Status alarm.cpp:37: sprout issued 1013.3 alarm 21-08-2018 10:01:29.838 UTC [7ffb027ec700] Debug pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1 (rdata0x3f51dc8) 21-08-2018 10:01:29.838 UTC [7ffb027ec700] Verbose common_sip_processing.cpp:87: RX 986 bytes Request msg INVITE/cseq=1 (rdata0x3f51dc8) from UDP 171.168.1.1:53782: --start msg-- INVITE sip:6505550596@clearwater.opnfv;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 171.168.1.1:53782;branch=z9hG4bK-d8754z-6510dfc0584fdd17-1---d8754z- Max-Forwards: 70 Route: <sip:scscf.sprout.clearwater.local;transport=TCP;lr;username="6505550288%40clearwater.opnfv";nonce="74d8483d78adebc7";orig> Contact: <sip:6505550288@171.168.1.1:53782;transport=UDP> To: <sip:6505550596@clearwater.opnfv;transport=UDP> From: <sip:6505550288@clearwater.opnfv;transport=UDP>;tag=d2855c60 Call-ID: NTAxODE3ZjA5OWJkMzI3ZjFiMzEyMGE1NzA3ZDJmMWU. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri User-Agent: Z 3.3.25608 r25552 Allow-Events: presence, kpml Content-Length: 161 v=0 o=Z 0 0 IN IP4 171.168.1.1 s=Z c=IN IP4 171.168.1.1 t=0 0 m=audio 8000 RTP/AVP 8 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv --end msg-- 21-08-2018 10:01:29.838 UTC [7ffb027ec700] Debug pjutils.cpp:1882: Logging SAS Call-ID marker, Call-ID NTAxODE3ZjA5OWJkMzI3ZjFiMzEyMGE1NzA3ZDJmMWU. 21-08-2018 10:01:29.838 UTC [7ffb027ec700] Debug thread_dispatcher.cpp:568: Received message 0x3f51dc8 21-08-2018 10:01:29.838 UTC [7ffb027ec700] Debug thread_dispatcher.cpp:585: Admitted request 0x3f51dc8 21-08-2018 10:01:29.838 UTC [7ffb027ec700] Debug thread_dispatcher.cpp:620: Incoming message 0x3f51dc8 cloned to 0x7ffaf401c888 21-08-2018 10:01:29.838 UTC [7ffb027ec700] Debug thread_dispatcher.cpp:639: Queuing cloned received message 0x7ffaf401c888 for worker threads with priority 0 21-08-2018 10:01:29.838 UTC [7ffb027ec700] Debug event_statistic_accumulator.cpp:32: Accumulate 0 for 0x3947a58 21-08-2018 10:01:29.839 UTC [7ffb027ec700] Debug event_statistic_accumulator.cpp:32: Accumulate 0 for 0x3947ad0 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug utils.cpp:872: Added IOHook 0x7ffb02fecdf0 to stack. There are now 1 hooks 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:181: Worker thread dequeue message 0x7ffaf401c888 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:186: Request latency so far = 216us 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1 (rdata0x7ffaf401c888) 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug uri_classifier.cpp:139: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug uri_classifier.cpp:173: Classified URI sip:6505550596@clearwater.opnfv;transport=UDP as 4 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug bono.cpp:235: Proxy RX request 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug pjutils.cpp:727: Cloned Request msg INVITE/cseq=1 (rdata0x7ffaf401c888) to tdta0x7ffaf8088500 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug bono.cpp:775: Request received on non-trusted port 5060 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug bono.cpp:1017: Perform access proxy routing for INVITE request 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug uri_classifier.cpp:139: home domain: false, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug uri_classifier.cpp:173: Classified URI sip:scscf.sprout.clearwater.local;transport=TCP;lr;username="6505550288%40clearwater.opnfv";nonce="74d8483d78adebc7";orig as 5 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug pjutils.cpp:537: Found Route header, URI = sip:scscf.sprout.clearwater.local;transport=TCP;lr;username="6505550288%40clearwater.opnfv";nonce="74d8483d78adebc7";orig 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug bono.cpp:1154: Message received on non-trusted port 5060 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug flowtable.cpp:111: Find flow for transport udp0x3cfab70 (1), remote address 171.168.1.1:53782 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug flowtable.cpp:577: Dialog count now 2 for flow sip:6505550288@clearwater.opnfv 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug flowtable.cpp:125: Found flow record 0x7ffaf806e200 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug bono.cpp:1206: Message received on known client flow 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug bono.cpp:1224: Request has no P-Preferred-Identity headers, so check for default identity on flow 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug pjutils.cpp:489: Adding P-Asserted-Identity header: sip:6505550288@clearwater.opnfv 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug bono.cpp:1293: Routing initial request from client to upstream Sprout 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug uri_classifier.cpp:139: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug uri_classifier.cpp:173: Classified URI sip:6505550596@clearwater.opnfv;transport=UDP as 4 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug bono.cpp:924: Request received on authentication flow - check for Service-Route 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug pjutils.cpp:302: Served user from P-Asserted-Identity header 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Verbose bono.cpp:931: Found Service-Route for served user sip:6505550288@clearwater.opnfv - sip:scscf.sprout.clearwater.local;transport=TCP;lr;orig;username=6505550288%40clearwater.opnfv;nonce=74d8483d78adebc7 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Info bono.cpp:994: Route request to upstream proxy sip:scscf.sprout.clearwater.local;transport=TCP;lr;orig;username=6505550288%40clearwater.opnfv;nonce=74d8483d78adebc7 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug uri_classifier.cpp:139: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug uri_classifier.cpp:173: Classified URI sip:6505550596@clearwater.opnfv;transport=UDP as 4 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug uri_classifier.cpp:139: home domain: false, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug uri_classifier.cpp:173: Classified URI sip:scscf.sprout.clearwater.local;transport=TCP;lr;username="6505550288%40clearwater.opnfv";nonce="74d8483d78adebc7";orig as 5 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug pjutils.cpp:537: Found Route header, URI = sip:scscf.sprout.clearwater.local;transport=TCP;lr;username="6505550288%40clearwater.opnfv";nonce="74d8483d78adebc7";orig 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug bono.cpp:1415: Add record route header(s) 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug bono.cpp:1420: Message received from client - double Record-Route 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug pjutils.cpp:578: Added Record-Route header, URI = sip:fRmE9KkKHY@bono-6u36f7.clearwater.local:5060;transport=UDP;lr 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug pjutils.cpp:578: Added Record-Route header, URI = sip:40.40.40.6:5058;transport=TCP;lr 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug flowtable.cpp:594: Dialog count now 1 for flow sip:6505550288@clearwater.opnfv 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug acr.cpp:1797: Create RalfACR for node type P-CSCF with role Originating 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug acr.cpp:24: Created ACR (0x7ffaf815a6f0) 21-08-2018 10:01:29.839 UTC [7ffb02fed700] Debug acr.cpp:170: Created P-CSCF Ralf ACR 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug uri_classifier.cpp:139: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug uri_classifier.cpp:173: Classified URI sip:6505550596@clearwater.opnfv;transport=UDP as 4 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug uri_classifier.cpp:139: home domain: false, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug uri_classifier.cpp:173: Classified URI sip:scscf.sprout.clearwater.local;transport=TCP;lr;username="6505550288%40clearwater.opnfv";nonce="74d8483d78adebc7";orig as 5 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug pjutils.cpp:537: Found Route header, URI = sip:scscf.sprout.clearwater.local;transport=TCP;lr;username="6505550288%40clearwater.opnfv";nonce="74d8483d78adebc7";orig 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug acr.cpp:210: Set record type for P/S-CSCF 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug acr.cpp:237: Dialog-initiating INVITE => START_RECORD 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug acr.cpp:1518: Stored 0 subscription identifiers 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug bono.cpp:443: Trust mode INBOUND_EDGE_CLIENT(,-rsp,-pch), serving state None 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug pjsip: tsx0x7ffaf8039 Transaction created for Request msg INVITE/cseq=1 (rdata0x7ffaf401c888) 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug bono.cpp:1741: UASTransaction constructor (0x7ffaf8008000) 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug bono.cpp:1742: ACR (0x7ffaf815a6f0) 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug pjsip: tsx0x7ffaf8039 Incoming Request msg INVITE/cseq=1 (rdata0x7ffaf401c888) in state Null 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug pjsip: tsx0x7ffaf8039 State changed from Null to Trying, event=RX_MSG 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug bono.cpp:347: tsx0x7ffaf8039c88 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug pjsip: endpoint Response msg 408/INVITE/cseq=1 (tdta0x7ffaf80b6f00) created 21-08-2018 10:01:29.840 UTC [7ffb02fed700] Debug bono.cpp:2323: Report SAS start marker - trail (d3f0) 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug trustboundary.cpp:44: Add P-Charging headers 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug session_expires_helper.cpp:99: Set session expires to 600 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug bono.cpp:2397: Allocating transaction and data for target 0 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug bono.cpp:2654: Stripping loose routes from proxied message 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug bono.cpp:2661: Stripped a Route header from proxied message 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug bono.cpp:2681: Adding a Route header to sip:scscf.sprout.clearwater.local:0;transport=TCP 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug pjsip: tsx0x7ffaf8003 Transaction created for Request msg INVITE/cseq=1 (tdta0x7ffaf80fa300) 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug bono.cpp:2424: Adding trail identifier 54256 to UAC transaction 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug bono.cpp:2443: Updating request URI and route for target 0 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug bono.cpp:2731: Resolve next hop destination 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug pjutils.cpp:518: Next hop node is encoded in top route header 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug sipresolver.cpp:84: SIPResolver::resolve for name scscf.sprout.clearwater.local, port 0, transport 6, family 2 21-08-2018 10:01:29.841 UTC [7ffb02fed700] Debug utils.cpp:446: Attempt to parse scscf.sprout.clearwater.local as IP address 21-08-2018 10:01:29.842 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:250: Searching for DNS record matching _sip._tcp.scscf.sprout.clearwater.local in the static cache 21-08-2018 10:01:29.842 UTC [7ffb02fed700] Debug static_dns_cache.cpp:303: No static records found matching _sip._tcp.scscf.sprout.clearwater.local 21-08-2018 10:01:29.842 UTC [7ffb02fed700] Verbose static_dns_cache.cpp:327: No matching CNAME record found in static cache 21-08-2018 10:01:29.842 UTC [7ffb02fed700] Debug static_dns_cache.cpp:303: No static records found matching _sip._tcp.scscf.sprout.clearwater.local 21-08-2018 10:01:29.842 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:269: _sip._tcp.scscf.sprout.clearwater.local not found in the static cache 21-08-2018 10:01:29.842 UTC [7ffb02fed700] Verbose dnscachedresolver.cpp:314: Check cache for _sip._tcp.scscf.sprout.clearwater.local type 33 21-08-2018 10:01:29.842 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:320: No entry found in cache 21-08-2018 10:01:29.842 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:323: Create cache entry pending query 21-08-2018 10:01:29.842 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:371: Create and execute DNS query transaction 21-08-2018 10:01:29.842 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:1074: Executing DNS lookup for _sip._tcp.scscf.sprout.clearwater.local (type SRV) 21-08-2018 10:01:29.843 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:384: Wait for query responses 21-08-2018 10:01:29.845 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:120: Pausing stopwatch due to DNS query 21-08-2018 10:01:29.845 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:553: Received DNS response for _sip._tcp.scscf.sprout.clearwater.local type SRV - status is 4 (Domain name not found) 21-08-2018 10:01:29.845 UTC [7ffb02fed700] Warning dnscachedresolver.cpp:698: Failed to retrieve record for _sip._tcp.scscf.sprout.clearwater.local: Domain name not found 21-08-2018 10:01:29.845 UTC [7ffb02fed700] Debug dnsparser.cpp:65: Parsing DNS message 000000: ec9c8583 00010000 00010000 045f7369 70045f74 63700573 63736366 06737072 .... .... .... ._si p._t cp.s cscf .spr 000020: 6f75740a 636c6561 72776174 6572056c 6f63616c 00002100 01c02300 06000100 out. clea rwat er.l ocal ..!. ..#. .... 000040: 00012c00 21026e73 c0230561 646d696e c023780b 5db00000 0e100000 0e100000 ..,. !.ns .#.a dmin .#x. ]... .... .... 000060: 0e100000 012c .... ., 21-08-2018 10:01:29.845 UTC [7ffb02fed700] Debug dnsparser.cpp:70: Parsing header at offset 0x0 21-08-2018 10:01:29.845 UTC [7ffb02fed700] Debug dnsparser.cpp:73: 1 questions, 0 answers, 1 authorities, 0 additional records 21-08-2018 10:01:29.845 UTC [7ffb02fed700] Debug dnsparser.cpp:78: Parsing question 1 at offset 0xc 21-08-2018 10:01:29.845 UTC [7ffb02fed700] Debug dnsparser.cpp:204: Parsed domain name = _sip._tcp.scscf.sprout.clearwater.local, encoded length = 41 21-08-2018 10:01:29.845 UTC [7ffb02fed700] Debug dnsparser.cpp:96: Parsing NS record 1 at offset 0x39 21-08-2018 10:01:29.845 UTC [7ffb02fed700] Debug dnsparser.cpp:204: Parsed domain name = clearwater.local, encoded length = 2 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug dnsparser.cpp:257: Resource Record NAME=clearwater.local TYPE=SOA CLASS=IN TTL=300 RDLENGTH=33 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug dnsparser.cpp:117: Answer records 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug dnsparser.cpp:118: Authority records clearwater.local 300 IN SOA 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug dnsparser.cpp:119: Additional records 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:829: Adding _sip._tcp.scscf.sprout.clearwater.local to cache expiry list with deletion time of 1534846289 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:126: Resuming stopwatch after DNS query 21-08-2018 10:01:29.846 UTC [7ffb027ec700] Info pjsip: ioq_epoll The transport thread spent 6799 microseconds processing an event. 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:392: Received all query responses 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:424: Pulling 0 records from cache for _sip._tcp.scscf.sprout.clearwater.local SRV 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:287: Found result for query _sip._tcp.scscf.sprout.clearwater.local (canonical domain: _sip._tcp.scscf.sprout.clearwater.local) 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug sipresolver.cpp:302: Perform A/AAAA record lookup only, name = scscf.sprout.clearwater.local 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:250: Searching for DNS record matching scscf.sprout.clearwater.local in the static cache 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug static_dns_cache.cpp:303: No static records found matching scscf.sprout.clearwater.local 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Verbose static_dns_cache.cpp:327: No matching CNAME record found in static cache 21-08-2018 10:01:29.846 UTC [7ffb02fed700] Debug static_dns_cache.cpp:303: No static records found matching scscf.sprout.clearwater.local 21-08-2018 10:01:29.847 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:269: scscf.sprout.clearwater.local not found in the static cache 21-08-2018 10:01:29.847 UTC [7ffb02fed700] Verbose dnscachedresolver.cpp:314: Check cache for scscf.sprout.clearwater.local type 1 21-08-2018 10:01:29.847 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:320: No entry found in cache 21-08-2018 10:01:29.847 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:323: Create cache entry pending query 21-08-2018 10:01:29.847 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:371: Create and execute DNS query transaction 21-08-2018 10:01:29.847 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:1074: Executing DNS lookup for scscf.sprout.clearwater.local (type A) 21-08-2018 10:01:29.847 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:384: Wait for query responses 21-08-2018 10:01:29.847 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:120: Pausing stopwatch due to DNS query 21-08-2018 10:01:29.847 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:553: Received DNS response for scscf.sprout.clearwater.local type A - status is 0 (Successful completion) 21-08-2018 10:01:29.847 UTC [7ffb02fed700] Debug dnsparser.cpp:65: Parsing DNS message 000000: 497a8580 00010002 00010002 05736373 63660673 70726f75 740a636c 65617277 Iz.. .... .... .scs cf.s prou t.cl earw 000020: 61746572 056c6f63 616c0000 010001c0 0c000100 01000001 2c000428 282805c0 ater .loc al.. .... .... .... ,..( ((.. 000040: 0c000100 01000001 2c0004ab a801a2c0 19000200 0100000e 10000502 6e73c019 .... .... ,... .... .... .... .... ns.. 000060: c05b0001 00010000 0e100004 aba801ae c05b0001 00010000 0e100004 2828280d .[.. .... .... .... .[.. .... .... (((. 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:70: Parsing header at offset 0x0 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:73: 1 questions, 2 answers, 1 authorities, 2 additional records 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:78: Parsing question 1 at offset 0xc 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:204: Parsed domain name = scscf.sprout.clearwater.local, encoded length = 31 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:87: Parsing answer 1 at offset 0x2f 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:204: Parsed domain name = scscf.sprout.clearwater.local, encoded length = 2 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:257: Resource Record NAME=scscf.sprout.clearwater.local TYPE=A CLASS=IN TTL=300 RDLENGTH=4 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:262: Parse A record RDATA 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:87: Parsing answer 2 at offset 0x3f 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:204: Parsed domain name = scscf.sprout.clearwater.local, encoded length = 2 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:257: Resource Record NAME=scscf.sprout.clearwater.local TYPE=A CLASS=IN TTL=300 RDLENGTH=4 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:262: Parse A record RDATA 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:96: Parsing NS record 1 at offset 0x4f 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:204: Parsed domain name = clearwater.local, encoded length = 2 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:257: Resource Record NAME=clearwater.local TYPE=NS CLASS=IN TTL=3600 RDLENGTH=5 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:105: Parsing additional record 1 at offset 0x60 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:204: Parsed domain name = ns.clearwater.local, encoded length = 2 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:257: Resource Record NAME=ns.clearwater.local TYPE=A CLASS=IN TTL=3600 RDLENGTH=4 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:262: Parse A record RDATA 21-08-2018 10:01:29.848 UTC [7ffb02fed700] Debug dnsparser.cpp:105: Parsing additional record 2 at offset 0x70 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnsparser.cpp:204: Parsed domain name = ns.clearwater.local, encoded length = 2 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnsparser.cpp:257: Resource Record NAME=ns.clearwater.local TYPE=A CLASS=IN TTL=3600 RDLENGTH=4 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnsparser.cpp:262: Parse A record RDATA 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnsparser.cpp:117: Answer records scscf.sprout.clearwater.local 300 IN A 40.40.40.5 scscf.sprout.clearwater.local 300 IN A 171.168.1.162 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnsparser.cpp:118: Authority records clearwater.local 3600 IN NS 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnsparser.cpp:119: Additional records ns.clearwater.local 3600 IN A 171.168.1.174 ns.clearwater.local 3600 IN A 40.40.40.13 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:586: DNS response for scscf.sprout.clearwater.local - response contains 2 answers 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:885: Adding record to cache entry, TTL=300, expiry=1534845989 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:892: Update cache entry expiry to 1534845989 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:885: Adding record to cache entry, TTL=300, expiry=1534845989 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:885: Adding record to cache entry, TTL=3600, expiry=1534849289 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:892: Update cache entry expiry to 1534849289 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:885: Adding record to cache entry, TTL=3600, expiry=1534849289 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:829: Adding ns.clearwater.local to cache expiry list with deletion time of 1534849589 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:829: Adding scscf.sprout.clearwater.local to cache expiry list with deletion time of 1534846289 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:126: Resuming stopwatch after DNS query 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:392: Received all query responses 21-08-2018 10:01:29.849 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:424: Pulling 2 records from cache for scscf.sprout.clearwater.local A 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug dnscachedresolver.cpp:287: Found result for query scscf.sprout.clearwater.local (canonical domain: scscf.sprout.clearwater.local) 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug baseresolver.cpp:192: Found 2 A/AAAA records, creating iterator 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Info pjutils.cpp:1001: Resolved destination URI sip:scscf.sprout.clearwater.local;transport=TCP;lr;orig;username=6505550288%40clearwater.opnfv;nonce=74d8483d78adebc7 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug baseresolver.cpp:812: Attempting to get 5 targets for host:scscf.sprout.clearwater.local. allowed_host_state = 3 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug baseresolver.cpp:575: 40.40.40.5:5060;transport=TCP graylist time elapsed 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug baseresolver.cpp:587: 40.40.40.5:5060;transport=TCP has state: WHITE 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug baseresolver.cpp:575: 171.168.1.162:5060;transport=TCP graylist time elapsed 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug baseresolver.cpp:587: 171.168.1.162:5060;transport=TCP has state: WHITE 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug baseresolver.cpp:587: 40.40.40.5:5060;transport=TCP has state: WHITE 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug baseresolver.cpp:883: Added a whitelisted server to targets, now have 1 of 5 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug baseresolver.cpp:587: 171.168.1.162:5060;transport=TCP has state: WHITE 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug baseresolver.cpp:883: Added a whitelisted server to targets, now have 2 of 5 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug bono.cpp:2769: Sending request for sip:6505550596@clearwater.opnfv;transport=UDP 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug pjsip: tsx0x7ffaf8003 Sending Request msg INVITE/cseq=1 (tdta0x7ffaf80fa300) in state Null 21-08-2018 10:01:29.850 UTC [7ffb02fed700] Debug pjsip: endpoint Request msg INVITE/cseq=1 (tdta0x7ffaf80fa300): skipping target resolution because address is already set 21-08-2018 10:01:29.851 UTC [7ffb02fed700] Verbose pjsip: tcpc0x7ffaf811 tcp->base.local_name: 40.40.40.6 21-08-2018 10:01:29.851 UTC [7ffb02fed700] Verbose pjsip: tcpc0x7ffaf811 TCP client transport created 21-08-2018 10:01:29.851 UTC [7ffb02fed700] Verbose pjsip: tcpc0x7ffaf811 TCP transport 40.40.40.6:5058 is connecting to 40.40.40.5:5060... 21-08-2018 10:01:29.851 UTC [7ffb02fed700] Verbose common_sip_processing.cpp:103: TX 1281 bytes Request msg INVITE/cseq=1 (tdta0x7ffaf80fa300) to TCP 40.40.40.5:5060: --start msg-- INVITE sip:6505550596@clearwater.opnfv;transport=UDP SIP/2.0 Record-Route: <sip:40.40.40.6:5058;transport=TCP;lr> Record-Route: <sip:fRmE9KkKHY@bono-6u36f7.clearwater.local:5060;transport=UDP;lr> Via: SIP/2.0/TCP 40.40.40.6:5058;rport;branch=z9hG4bKPj0Tebo.vd80-5akZcKfLDUvUHb5WUkvGb Via: SIP/2.0/UDP 171.168.1.1:53782;received=171.168.1.1;branch=z9hG4bK-d8754z-6510dfc0584fdd17-1---d8754z- Max-Forwards: 70 Contact: <sip:6505550288@171.168.1.1:53782;transport=UDP> To: <sip:6505550596@clearwater.opnfv> From: <sip:6505550288@clearwater.opnfv>;tag=d2855c60 Call-ID: NTAxODE3ZjA5OWJkMzI3ZjFiMzEyMGE1NzA3ZDJmMWU. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri User-Agent: Z 3.3.25608 r25552 Allow-Events: presence, kpml P-Asserted-Identity: <sip:6505550288@clearwater.opnfv> Session-Expires: 600 Route: <sip:scscf.sprout.clearwater.local;transport=TCP;lr;orig;username=6505550288%40clearwater.opnfv;nonce=74d8483d78adebc7> Content-Type: application/sdp Content-Length: 161 v=0 o=Z 0 0 IN IP4 171.168.1.1 s=Z c=IN IP4 171.168.1.1 t=0 0 m=audio 8000 RTP/AVP 8 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv --end msg-- 21-08-2018 10:01:29.851 UTC [7ffb02fed700] Debug pjsip: tsx0x7ffaf8003 State changed from Null to Calling, event=TX_MSG 21-08-2018 10:01:29.851 UTC [7ffb02fed700] Debug bono.cpp:347: tsx0x7ffaf8003fd8 - tu_on_tsx_state UAC, TSX_STATE TX_MSG state=Calling 21-08-2018 10:01:29.851 UTC [7ffb02fed700] Debug bono.cpp:2869: tsx0x7ffaf8003fd8 - uac_data = 0x7ffaf809f670, uas_data = 0x7ffaf8008000 21-08-2018 10:01:29.851 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:273: Worker thread completed processing message 0x7ffaf401c888 21-08-2018 10:01:29.851 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:287: Request latency = 9347us 21-08-2018 10:01:29.852 UTC [7ffb02fed700] Debug event_statistic_accumulator.cpp:32: Accumulate 9347 for 0x3943b08 21-08-2018 10:01:29.852 UTC [7ffb02fed700] Debug event_statistic_accumulator.cpp:32: Accumulate 9347 for 0x3943b50 21-08-2018 10:01:29.852 UTC [7ffb02fed700] Debug load_monitor.cpp:341: Not recalculating rate as we haven't processed 20 requests yet (only 3). 21-08-2018 10:01:29.852 UTC [7ffb02fed700] Debug utils.cpp:878: Removed IOHook 0x7ffb02fecdf0 to stack. There are now 0 hooks 21-08-2018 10:01:29.852 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:161: Attempting to process queue element 21-08-2018 10:01:29.856 UTC [7ffb027ec700] Info pjsip: tcpc0x7ffaf811 TCP connect() error: Connection refused [code=120111] 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Info pjsip: tcpc0x7ffaf811 Unable to connect to 40.40.40.5:5060 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Info pjsip: tsx0x7ffaf8003 Failed to send Request msg INVITE/cseq=1 (tdta0x7ffaf80fa300)! err=120111 (Connection refused) 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf8003 State changed from Calling to Terminated, event=TRANSPORT_ERROR 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Debug bono.cpp:347: tsx0x7ffaf8003fd8 - tu_on_tsx_state UAC, TSX_STATE TRANSPORT_ERROR state=Terminated 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Debug bono.cpp:2869: tsx0x7ffaf8003fd8 - uac_data = 0x7ffaf809f670, uas_data = 0x7ffaf8008000 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Debug bono.cpp:2888: Failed to connected to server, so add to blacklist 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Debug baseresolver.cpp:226: Add 40.40.40.5:5060;transport=TCP to blacklist for 30 seconds, graylist for 0 seconds 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Debug bono.cpp:2980: Attempt to retry request to alternate server 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf4001 Transaction created for Request msg INVITE/cseq=1 (tdta0x7ffaf80fa300) 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Debug bono.cpp:2992: Created transaction for retry, so send request 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf4001 Sending Request msg INVITE/cseq=1 (tdta0x7ffaf80fa300) in state Null 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Debug pjsip: endpoint Request msg INVITE/cseq=1 (tdta0x7ffaf80fa300): skipping target resolution because address is already set 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Verbose pjsip: tcpc0x7ffaf401 tcp->base.local_name: 40.40.40.6 21-08-2018 10:01:29.857 UTC [7ffb027ec700] Verbose pjsip: tcpc0x7ffaf401 TCP client transport created 21-08-2018 10:01:29.858 UTC [7ffb027ec700] Verbose pjsip: tcpc0x7ffaf401 TCP transport 40.40.40.6:5058 is connecting to 171.168.1.162:5060... 21-08-2018 10:01:29.858 UTC [7ffb027ec700] Verbose common_sip_processing.cpp:103: TX 1281 bytes Request msg INVITE/cseq=1 (tdta0x7ffaf80fa300) to TCP 171.168.1.162:5060: --start msg-- INVITE sip:6505550596@clearwater.opnfv;transport=UDP SIP/2.0 Record-Route: <sip:40.40.40.6:5058;transport=TCP;lr> Record-Route: <sip:fRmE9KkKHY@bono-6u36f7.clearwater.local:5060;transport=UDP;lr> Via: SIP/2.0/TCP 40.40.40.6:5058;rport;branch=z9hG4bKPj34GGiocxLYZJgWuwJQSoqXPTuYRE3ySJ Via: SIP/2.0/UDP 171.168.1.1:53782;received=171.168.1.1;branch=z9hG4bK-d8754z-6510dfc0584fdd17-1---d8754z- Max-Forwards: 70 Contact: <sip:6505550288@171.168.1.1:53782;transport=UDP> To: <sip:6505550596@clearwater.opnfv> From: <sip:6505550288@clearwater.opnfv>;tag=d2855c60 Call-ID: NTAxODE3ZjA5OWJkMzI3ZjFiMzEyMGE1NzA3ZDJmMWU. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri User-Agent: Z 3.3.25608 r25552 Allow-Events: presence, kpml P-Asserted-Identity: <sip:6505550288@clearwater.opnfv> Session-Expires: 600 Route: <sip:scscf.sprout.clearwater.local;transport=TCP;lr;orig;username=6505550288%40clearwater.opnfv;nonce=74d8483d78adebc7> Content-Type: application/sdp Content-Length: 161 v=0 o=Z 0 0 IN IP4 171.168.1.1 s=Z c=IN IP4 171.168.1.1 t=0 0 m=audio 8000 RTP/AVP 8 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv --end msg-- 21-08-2018 10:01:29.858 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf4001 State changed from Null to Calling, event=TX_MSG 21-08-2018 10:01:29.858 UTC [7ffb027ec700] Debug bono.cpp:347: tsx0x7ffaf40019c8 - tu_on_tsx_state UAC, TSX_STATE TX_MSG state=Calling 21-08-2018 10:01:29.858 UTC [7ffb027ec700] Debug bono.cpp:2869: tsx0x7ffaf40019c8 - uac_data = 0x7ffaf809f670, uas_data = 0x7ffaf8008000 21-08-2018 10:01:29.858 UTC [7ffb027ec700] Debug pjsip: tcpc0x7ffaf811 TCP send() error, sent=-120111 21-08-2018 10:01:29.858 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf8003 Timeout timer event 21-08-2018 10:01:29.858 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf8003 State changed from Terminated to Destroyed, event=TIMER 21-08-2018 10:01:29.858 UTC [7ffb027ec700] Debug bono.cpp:347: tsx0x7ffaf8003fd8 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Destroyed 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Verbose pjsip: tcpc0x7ffaf811 TCP transport destroyed with reason 120111: Connection refused 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Info pjsip: tcpc0x7ffaf401 TCP connect() error: Connection refused [code=120111] 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Info pjsip: tcpc0x7ffaf401 Unable to connect to 171.168.1.162:5060 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Info pjsip: tsx0x7ffaf4001 Failed to send Request msg INVITE/cseq=1 (tdta0x7ffaf80fa300)! err=120111 (Connection refused) 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf4001 State changed from Calling to Terminated, event=TRANSPORT_ERROR 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Debug bono.cpp:347: tsx0x7ffaf40019c8 - tu_on_tsx_state UAC, TSX_STATE TRANSPORT_ERROR state=Terminated 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Debug bono.cpp:2869: tsx0x7ffaf40019c8 - uac_data = 0x7ffaf809f670, uas_data = 0x7ffaf8008000 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Debug bono.cpp:2888: Failed to connected to server, so add to blacklist 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Debug baseresolver.cpp:226: Add 171.168.1.162:5060;transport=TCP to blacklist for 30 seconds, graylist for 0 seconds 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Debug bono.cpp:2930: tsx0x7ffaf40019c8 - UAC tsx terminated while still connected to UAS tsx 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Debug bono.cpp:2933: Timeout or transport error 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Debug bono.cpp:2149: tsx0x7ffaf40019c8 - Not forked request 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Debug acr.cpp:581: Failed to start session, change record type to EVENT_RECORD 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf8039 Sending Response msg 408/INVITE/cseq=1 (tdta0x7ffaf80b6f00) in state Trying 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Debug pjsip: sip_resolve.c Target '171.168.1.1:53782' type=UDP resolved to '171.168.1.1:53782' type=UDP (UDP transport) 21-08-2018 10:01:29.859 UTC [7ffb027ec700] Verbose common_sip_processing.cpp:103: TX 371 bytes Response msg 408/INVITE/cseq=1 (tdta0x7ffaf80b6f00) to UDP 171.168.1.1:53782: --start msg-- SIP/2.0 408 Request Timeout Via: SIP/2.0/UDP 171.168.1.1:53782;received=171.168.1.1;branch=z9hG4bK-d8754z-6510dfc0584fdd17-1---d8754z- Call-ID: NTAxODE3ZjA5OWJkMzI3ZjFiMzEyMGE1NzA3ZDJmMWU. From: <sip:6505550288@clearwater.opnfv>;tag=d2855c60 To: <sip:6505550596@clearwater.opnfv>;tag=z9hG4bK-d8754z-6510dfc0584fdd17-1---d8754z- CSeq: 1 INVITE Content-Length: 0 --end msg-- 21-08-2018 10:01:29.860 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf8039 State changed from Trying to Completed, event=TX_MSG 21-08-2018 10:01:29.860 UTC [7ffb027ec700] Debug bono.cpp:347: tsx0x7ffaf8039c88 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Completed 21-08-2018 10:01:29.860 UTC [7ffb027ec700] Debug bono.cpp:775: Request received on non-trusted port 5060 21-08-2018 10:01:29.860 UTC [7ffb027ec700] Debug bono.cpp:2332: Report SAS end marker - trail (d3f0) 21-08-2018 10:01:29.860 UTC [7ffb027ec700] Debug bono.cpp:2156: tsx0x7ffaf40019c8 - Disconnect UAS tsx from UAC tsx 21-08-2018 10:01:29.860 UTC [7ffb027ec700] Debug bono.cpp:2534: Dissociate UAC transaction 0x7ffaf809f670 (0) 21-08-2018 10:01:29.860 UTC [7ffb027ec700] Debug pjsip: tcpc0x7ffaf401 TCP send() error, sent=-120111 21-08-2018 10:01:29.860 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf4001 Timeout timer event 21-08-2018 10:01:29.860 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf4001 State changed from Terminated to Destroyed, event=TIMER 21-08-2018 10:01:29.860 UTC [7ffb027ec700] Debug bono.cpp:347: tsx0x7ffaf40019c8 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Destroyed 21-08-2018 10:01:29.860 UTC [7ffb027ec700] Debug bono.cpp:2869: tsx0x7ffaf40019c8 - uac_data = 0x7ffaf809f670, uas_data = (nil) 21-08-2018 10:01:29.861 UTC [7ffb027ec700] Debug bono.cpp:2956: tsx0x7ffaf40019c8 - UAC tsx destroyed 21-08-2018 10:01:29.861 UTC [7ffb027ec700] Debug pjsip: tdta0x7ffaf80f Destroying txdata Request msg INVITE/cseq=1 (tdta0x7ffaf80fa300) 21-08-2018 10:01:29.861 UTC [7ffb027ec700] Verbose pjsip: tcpc0x7ffaf401 TCP transport destroyed with reason 120111: Connection refused 21-08-2018 10:01:29.861 UTC [7ffb027ec700] Debug pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1 (rdata0x3f63788) 21-08-2018 10:01:29.861 UTC [7ffb027ec700] Verbose common_sip_processing.cpp:87: RX 540 bytes Request msg ACK/cseq=1 (rdata0x3f63788) from UDP 171.168.1.1:53782: --start msg-- ACK sip:6505550596@clearwater.opnfv;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 171.168.1.1:53782;branch=z9hG4bK-d8754z-6510dfc0584fdd17-1---d8754z- Max-Forwards: 70 Route: <sip:scscf.sprout.clearwater.local;transport=TCP;lr;username="6505550288%40clearwater.opnfv";nonce="74d8483d78adebc7";orig> To: <sip:6505550596@clearwater.opnfv>;tag=z9hG4bK-d8754z-6510dfc0584fdd17-1---d8754z- From: <sip:6505550288@clearwater.opnfv;transport=UDP>;tag=d2855c60 Call-ID: NTAxODE3ZjA5OWJkMzI3ZjFiMzEyMGE1NzA3ZDJmMWU. CSeq: 1 ACK Content-Length: 0 --end msg-- 21-08-2018 10:01:29.861 UTC [7ffb027ec700] Debug thread_dispatcher.cpp:568: Received message 0x3f63788 21-08-2018 10:01:29.861 UTC [7ffb027ec700] Debug thread_dispatcher.cpp:585: Admitted request 0x3f63788 21-08-2018 10:01:29.861 UTC [7ffb027ec700] Debug thread_dispatcher.cpp:620: Incoming message 0x3f63788 cloned to 0x7ffaf401c888 21-08-2018 10:01:29.861 UTC [7ffb027ec700] Debug thread_dispatcher.cpp:639: Queuing cloned received message 0x7ffaf401c888 for worker threads with priority 0 21-08-2018 10:01:29.861 UTC [7ffb027ec700] Debug event_statistic_accumulator.cpp:32: Accumulate 0 for 0x3947a58 21-08-2018 10:01:29.861 UTC [7ffb027ec700] Debug event_statistic_accumulator.cpp:32: Accumulate 0 for 0x3947ad0 21-08-2018 10:01:29.861 UTC [7ffb02fed700] Debug utils.cpp:872: Added IOHook 0x7ffb02fecdf0 to stack. There are now 1 hooks 21-08-2018 10:01:29.861 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:181: Worker thread dequeue message 0x7ffaf401c888 21-08-2018 10:01:29.861 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:186: Request latency so far = 329us 21-08-2018 10:01:29.861 UTC [7ffb02fed700] Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1 (rdata0x7ffaf401c888) 21-08-2018 10:01:29.861 UTC [7ffb02fed700] Debug uri_classifier.cpp:139: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 21-08-2018 10:01:29.862 UTC [7ffb02fed700] Debug uri_classifier.cpp:173: Classified URI sip:6505550596@clearwater.opnfv;transport=UDP as 4 21-08-2018 10:01:29.862 UTC [7ffb02fed700] Debug pjsip: tsx0x7ffaf8039 Incoming Request msg ACK/cseq=1 (rdata0x7ffaf401c888) in state Completed 21-08-2018 10:01:29.862 UTC [7ffb02fed700] Debug pjsip: tsx0x7ffaf8039 State changed from Completed to Confirmed, event=RX_MSG 21-08-2018 10:01:29.862 UTC [7ffb02fed700] Debug bono.cpp:347: tsx0x7ffaf8039c88 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Confirmed 21-08-2018 10:01:29.862 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:273: Worker thread completed processing message 0x7ffaf401c888 21-08-2018 10:01:29.862 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:287: Request latency = 729us 21-08-2018 10:01:29.862 UTC [7ffb02fed700] Debug event_statistic_accumulator.cpp:32: Accumulate 729 for 0x3943b08 21-08-2018 10:01:29.862 UTC [7ffb02fed700] Debug event_statistic_accumulator.cpp:32: Accumulate 729 for 0x3943b50 21-08-2018 10:01:29.862 UTC [7ffb02fed700] Debug load_monitor.cpp:341: Not recalculating rate as we haven't processed 20 requests yet (only 4). 21-08-2018 10:01:29.862 UTC [7ffb02fed700] Debug utils.cpp:878: Removed IOHook 0x7ffb02fecdf0 to stack. There are now 0 hooks 21-08-2018 10:01:29.862 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:161: Attempting to process queue element 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf8039 Timeout timer event 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf8039 State changed from Confirmed to Terminated, event=TIMER 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug bono.cpp:347: tsx0x7ffaf8039c88 - tu_on_tsx_state UAS, TSX_STATE TIMER state=Terminated 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf8039 Timeout timer event 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf8039 State changed from Terminated to Destroyed, event=TIMER 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug bono.cpp:347: tsx0x7ffaf8039c88 - tu_on_tsx_state UAS, TSX_STATE TIMER state=Destroyed 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug bono.cpp:2189: tsx0x7ffaf8039c88 - UAS tsx destroyed 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug bono.cpp:2496: tsx0x7ffaf8039c88 - Cancel 0 pending UAC transactions 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug bono.cpp:2505: tsx0x7ffaf8039c88 - Check target 0, UAC data = (nil), UAC tsx = (nil) 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug bono.cpp:1786: UASTransaction destructor (0x7ffaf8008000) 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug bono.cpp:1806: Disconnect UAC transactions from UAS transaction 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug bono.cpp:1816: Upstream ACR = 0x7ffaf815a6f0, Downstream ACR = 0x7ffaf815a6f0 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Verbose acr.cpp:641: Sending P-CSCF Ralf ACR (0x7ffaf815a6f0) 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug acr.cpp:674: Building message 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug acr.cpp:691: Adding peers meta-data, 1 ccfs, 0 ecfs 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug acr.cpp:730: Building event 21-08-2018 10:01:29.872 UTC [7ffb027ec700] Debug acr.cpp:735: Adding Account-Record-Type AVP 1 21-08-2018 10:01:29.873 UTC [7ffb027ec700] Debug acr.cpp:755: Adding Service-Information AVP group 21-08-2018 10:01:29.873 UTC [7ffb027ec700] Debug acr.cpp:765: Adding 0 Subscription-Id AVPs 21-08-2018 10:01:29.873 UTC [7ffb027ec700] Debug acr.cpp:791: Adding IMS-Information AVP group 21-08-2018 10:01:29.873 UTC [7ffb027ec700] Debug acr.cpp:796: Adding Event-Type AVP group 21-08-2018 10:01:29.873 UTC [7ffb027ec700] Debug acr.cpp:825: Adding 0 Calling-Party-Address AVPs 21-08-2018 10:01:29.873 UTC [7ffb027ec700] Debug acr.cpp:845: Adding Called-Party-Address AVP 21-08-2018 10:01:29.873 UTC [7ffb027ec700] Debug acr.cpp:866: Adding 0 Called-Asserted-Identity AVPs 21-08-2018 10:01:29.873 UTC [7ffb027ec700] Debug acr.cpp:887: Adding 0 Associated-URI AVPs 21-08-2018 10:01:29.873 UTC [7ffb027ec700] Debug acr.cpp:906: Adding Time-Stamps AVP group 21-08-2018 10:01:29.873 UTC [7ffb027ec700] Debug acr.cpp:996: Adding 0 Transit-IOI-List AVPs 21-08-2018 10:01:29.873 UTC [7ffb027ec700] Debug acr.cpp:1072: Adding 0 Early-Media-Description AVPs 21-08-2018 10:01:29.873 UTC [7ffb027ec700] Debug acr.cpp:1104: Adding 0 Message-Body AVPs 21-08-2018 10:01:29.874 UTC [7ffb027ec700] Debug acr.cpp:1198: Adding Cause-Code(408) AVP to ACR[Interim] 21-08-2018 10:01:29.874 UTC [7ffb027ec700] Debug acr.cpp:1204: Adding 0 Reason-Header AVPs 21-08-2018 10:01:29.874 UTC [7ffb027ec700] Debug acr.cpp:1222: Adding 0 Access-Network-Information AVPs 21-08-2018 10:01:29.874 UTC [7ffb027ec700] Debug acr.cpp:1240: Adding From-Address AVP 21-08-2018 10:01:29.874 UTC [7ffb027ec700] Debug acr.cpp:1255: Adding Route-Header-Received AVP 21-08-2018 10:01:29.874 UTC [7ffb027ec700] Debug acr.cpp:1262: Adding Route-Header-Transmitted AVP 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Debug a_record_resolver.cpp:57: ARecordResolver::resolve_iter for host dime.clearwater.local, port 10888, family 2 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Debug utils.cpp:446: Attempt to parse dime.clearwater.local as IP address 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Debug dnscachedresolver.cpp:250: Searching for DNS record matching dime.clearwater.local in the static cache 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Debug static_dns_cache.cpp:303: No static records found matching dime.clearwater.local 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Verbose static_dns_cache.cpp:327: No matching CNAME record found in static cache 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Debug static_dns_cache.cpp:303: No static records found matching dime.clearwater.local 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Debug dnscachedresolver.cpp:269: dime.clearwater.local not found in the static cache 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Verbose dnscachedresolver.cpp:314: Check cache for dime.clearwater.local type 1 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Debug dnscachedresolver.cpp:424: Pulling 2 records from cache for dime.clearwater.local A 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Debug dnscachedresolver.cpp:287: Found result for query dime.clearwater.local (canonical domain: dime.clearwater.local) 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Debug baseresolver.cpp:192: Found 2 A/AAAA records, creating iterator 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Debug utils.cpp:446: Attempt to parse dime.clearwater.local as IP address 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Debug baseresolver.cpp:812: Attempting to get 1 targets for host:dime.clearwater.local. allowed_host_state = 3 21-08-2018 10:01:29.874 UTC [7ffb0affd700] Debug baseresolver.cpp:587: 171.168.1.176:10888;transport=TCP has state: WHITE 21-08-2018 10:01:29.875 UTC [7ffb0affd700] Debug baseresolver.cpp:587: 40.40.40.12:10888;transport=TCP has state: WHITE 21-08-2018 10:01:29.875 UTC [7ffb0affd700] Debug baseresolver.cpp:587: 171.168.1.176:10888;transport=TCP has state: WHITE 21-08-2018 10:01:29.875 UTC [7ffb0affd700] Debug baseresolver.cpp:883: Added a whitelisted server to targets, now have 1 of 1 21-08-2018 10:01:29.875 UTC [7ffb0affd700] Debug connection_pool.h:207: Request for connection to IP: 171.168.1.176, port: 10888 21-08-2018 10:01:29.875 UTC [7ffb0affd700] Debug connection_pool.h:220: Found existing connection 0x7ffafc0028e0 in pool 21-08-2018 10:01:29.875 UTC [7ffb0affd700] Debug httpclient.cpp:312: Set CURLOPT_RESOLVE: dime.clearwater.local:10888:171.168.1.176 21-08-2018 10:01:29.875 UTC [7ffb0affd700] Debug httpclient.cpp:343: Sending HTTP request : http://dime.clearwater.local:10888/call-id/NTAxODE3ZjA5OWJkMzI3ZjFiMzEyMGE1NzA3ZDJmMWU. (trying 171.168.1.176) 21-08-2018 10:01:29.875 UTC [7ffb027ec700] Debug acr.cpp:29: Destroyed ACR (0x7ffaf815a6f0) 21-08-2018 10:01:29.876 UTC [7ffb027ec700] Debug bono.cpp:1835: Free original request (0x7ffaf80885a8) 21-08-2018 10:01:29.876 UTC [7ffb027ec700] Debug pjsip: tdta0x7ffaf808 Destroying txdata Request msg INVITE/cseq=1 (tdta0x7ffaf8088500) 21-08-2018 10:01:29.876 UTC [7ffb027ec700] Debug bono.cpp:1851: UASTransaction destructor completed 21-08-2018 10:01:29.876 UTC [7ffb027ec700] Debug pjsip: tdta0x7ffaf80b Destroying txdata Response msg 408/INVITE/cseq=1 (tdta0x7ffaf80b6f00) 21-08-2018 10:01:29.876 UTC [7ffb027ec700] Info pjsip: timer.c The transport thread spent 4163 microseconds processing a callback. 21-08-2018 10:01:29.876 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf8039 Transaction destroyed! 21-08-2018 10:01:29.876 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf8003 Transaction destroyed! 21-08-2018 10:01:29.876 UTC [7ffb027ec700] Debug pjsip: tsx0x7ffaf4001 Transaction destroyed! 21-08-2018 10:01:29.877 UTC [7ffb0affd700] Debug httpclient.cpp:719: Received header http/1.1200ok with value 21-08-2018 10:01:29.877 UTC [7ffb0affd700] Debug httpclient.cpp:720: Header pointer: 0x7ffb0affcbf0 21-08-2018 10:01:29.877 UTC [7ffb0affd700] Debug httpclient.cpp:719: Received header content-length with value 0 21-08-2018 10:01:29.877 UTC [7ffb0affd700] Debug httpclient.cpp:720: Header pointer: 0x7ffb0affcbf0 21-08-2018 10:01:29.878 UTC [7ffb0affd700] Debug httpclient.cpp:719: Received header with value 21-08-2018 10:01:29.878 UTC [7ffb0affd700] Debug httpclient.cpp:720: Header pointer: 0x7ffb0affcbf0 21-08-2018 10:01:29.878 UTC [7ffb0affd700] Debug httpclient.cpp:383: Received HTTP response: status=200, doc= 21-08-2018 10:01:29.878 UTC [7ffb0affd700] Debug baseresolver.cpp:672: Successful response from 171.168.1.176:10888;transport=TCP 21-08-2018 10:01:29.878 UTC [7ffb0affd700] Debug connection_pool.h:244: Release connection to IP: 171.168.1.176, port: 10888 to pool 21-08-2018 10:01:29.878 UTC [7ffb0affd700] Debug communicationmonitor.cpp:57: Checking communication changes - successful attempts 2, failures 0 21-08-2018 10:01:31.157 UTC [7ffb027ec700] Verbose pjsip: tcplis:5058 TCP listener 40.40.40.6:5058: got incoming TCP connection from 40.40.40.6:43620, sock=130 21-08-2018 10:01:31.157 UTC [7ffb027ec700] Verbose pjsip: tcps0x7ffaf401 tcp->base.local_name: 40.40.40.6 21-08-2018 10:01:31.157 UTC [7ffb027ec700] Verbose pjsip: tcps0x7ffaf401 TCP server transport created 21-08-2018 10:01:31.158 UTC [7ffb027ec700] Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1050567 (rdata0x7ffaf401cb40) 21-08-2018 10:01:31.158 UTC [7ffb027ec700] Verbose common_sip_processing.cpp:87: RX 345 bytes Request msg OPTIONS/cseq=1050567 (rdata0x7ffaf401cb40) from TCP 40.40.40.6:43620: --start msg-- OPTIONS sip:poll-sip@40.40.40.6:5058 SIP/2.0 Via: SIP/2.0/TCP 40.40.40.6;rport;branch=z9hG4bK-1050567 Max-Forwards: 2 To: <sip:poll-sip@40.40.40.6:5058> From: poll-sip <sip:poll-sip@40.40.40.6>;tag=1050567 Call-ID: poll-sip-1050567 CSeq: 1050567 OPTIONS Contact: <sip:40.40.40.6> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 21-08-2018 10:01:31.158 UTC [7ffb027ec700] Debug uri_classifier.cpp:139: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 21-08-2018 10:01:31.158 UTC [7ffb027ec700] Debug uri_classifier.cpp:173: Classified URI sip:poll-sip@40.40.40.6:5058 as 3 21-08-2018 10:01:31.158 UTC [7ffb027ec700] Debug common_sip_processing.cpp:180: Skipping SAS logging for OPTIONS request 21-08-2018 10:01:31.158 UTC [7ffb027ec700] Debug thread_dispatcher.cpp:568: Received message 0x7ffaf401cb40 21-08-2018 10:01:31.158 UTC [7ffb027ec700] Debug thread_dispatcher.cpp:585: Admitted request 0x7ffaf401cb40 21-08-2018 10:01:31.158 UTC [7ffb027ec700] Debug thread_dispatcher.cpp:620: Incoming message 0x7ffaf401cb40 cloned to 0x7ffaf401f0a8 21-08-2018 10:01:31.158 UTC [7ffb027ec700] Debug thread_dispatcher.cpp:639: Queuing cloned received message 0x7ffaf401f0a8 for worker threads with priority 15 21-08-2018 10:01:31.158 UTC [7ffb027ec700] Debug event_statistic_accumulator.cpp:32: Accumulate 0 for 0x3947a88 21-08-2018 10:01:31.158 UTC [7ffb027ec700] Debug event_statistic_accumulator.cpp:32: Accumulate 0 for 0x3947ad0 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug utils.cpp:872: Added IOHook 0x7ffb02fecdf0 to stack. There are now 1 hooks 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:181: Worker thread dequeue message 0x7ffaf401f0a8 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:186: Request latency so far = 104us 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1050567 (rdata0x7ffaf401f0a8) 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug uri_classifier.cpp:139: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug uri_classifier.cpp:173: Classified URI sip:poll-sip@40.40.40.6:5058 as 3 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=1050567 (tdta0x7ffaf8088500) created 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Verbose common_sip_processing.cpp:103: TX 279 bytes Response msg 200/OPTIONS/cseq=1050567 (tdta0x7ffaf8088500) to TCP 40.40.40.6:43620: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP 40.40.40.6;rport=43620;received=40.40.40.6;branch=z9hG4bK-1050567 Call-ID: poll-sip-1050567 From: "poll-sip" <sip:poll-sip@40.40.40.6>;tag=1050567 To: <sip:poll-sip@40.40.40.6>;tag=z9hG4bK-1050567 CSeq: 1050567 OPTIONS Content-Length: 0 --end msg-- 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug common_sip_processing.cpp:275: Skipping SAS logging for OPTIONS response 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug pjsip: tdta0x7ffaf808 Destroying txdata Response msg 200/OPTIONS/cseq=1050567 (tdta0x7ffaf8088500) 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:273: Worker thread completed processing message 0x7ffaf401f0a8 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:287: Request latency = 292us 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug event_statistic_accumulator.cpp:32: Accumulate 292 for 0x3943ad8 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug event_statistic_accumulator.cpp:32: Accumulate 292 for 0x3943b50 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug load_monitor.cpp:341: Not recalculating rate as we haven't processed 20 requests yet (only 5). 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug utils.cpp:878: Removed IOHook 0x7ffb02fecdf0 to stack. There are now 0 hooks 21-08-2018 10:01:31.158 UTC [7ffb02fed700] Debug thread_dispatcher.cpp:161: Attempting to process queue element 21-08-2018 10:01:33.160 UTC [7ffb027ec700] Verbose pjsip: tcps0x7ffaf401 TCP connection closed 21-08-2018 10:01:33.160 UTC [7ffb027ec700] Debug connection_tracker.cpp:67: Connection 0x7ffaf401c808 has been destroyed 21-08-2018 10:01:33.160 UTC [7ffb027ec700] Verbose pjsip: tcps0x7ffaf401 TCP transport destroyed with reason 70016: End of file (PJ_EEOF)
_______________________________________________ Clearwater mailing list Clearwater@lists.projectclearwater.org http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
