Hi, We're testing an IPSMGW solution, as per 3GPP 24.341, signalling flows in section B.5
In the attached log, sprout is not applying the Tel URI to the P-Asserted-Identity header in the SIP MESSAGE as per section B-5.3 (page 35). Can you confirm if Sprout supports this use-case? and if so how can I configure it to apply both the SIP and Tel URI values for the P-Asserted-Identity in the sip MESSAGE sent to the IP-SM-GW. thanks Steve Yeoman ------------------------------------------------------------------------------------------ Steve Yeoman, Software Engineer, http://www.opencloud.com
==> sprout/sprout_20151103T220000Z.txt <== --end msg-- 03-11-2015 22:28:26.655 UTC Debug common_sip_processing.cpp:253: Skipping SAS logging for OPTIONS response 03-11-2015 22:28:26.655 UTC Debug pjsip: tdta0x7f3a0c09 Destroying txdata Response msg 200/OPTIONS/cseq=29107 (tdta0x7f3a0c09ed20) 03-11-2015 22:28:26.655 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f39ec04aff8 03-11-2015 22:28:26.655 UTC Debug thread_dispatcher.cpp:199: Request latency = 142us 03-11-2015 22:28:27.655 UTC Verbose pjsip: tcps0x7f39ec27 TCP connection closed 03-11-2015 22:28:27.655 UTC Debug connection_tracker.cpp:91: Connection 0x7f39ec273608 has been destroyed 03-11-2015 22:28:27.655 UTC Verbose pjsip: tcps0x7f39ec27 TCP transport destroyed with reason 70016: End of file (PJ_EEOF) ==> sprout/log_20151103T220000Z.txt <== 03-11-2015 22:17:44.781 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=<urn:uuid:100da80d-454f-538b-8001-ca0713d2a32a> CONTACT_URI=sip:[email protected]:33010;transport=TCP;ob EXPIRES=600 03-11-2015 22:22:02.523 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=<urn:uuid:100da80d-454f-538b-8001-ca0713d2a32a> CONTACT_URI=sip:[email protected]:52259;transport=TCP;ob EXPIRES=0 03-11-2015 22:22:08.114 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=<urn:uuid:100da80d-454f-538b-8001-ca0713d2a32a> CONTACT_URI=sip:[email protected]:45217;transport=TCP;ob EXPIRES=600 03-11-2015 22:22:37.411 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=<urn:uuid:100da80d-454f-538b-8001-ca0713d2a32a> CONTACT_URI=sip:[email protected]:37410;transport=TCP;ob EXPIRES=0 03-11-2015 22:22:40.831 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=<urn:uuid:100da80d-454f-538b-8001-ca0713d2a32a> CONTACT_URI=sip:[email protected]:41149;transport=TCP;ob EXPIRES=600 03-11-2015 22:23:37.657 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=<urn:uuid:100da80d-454f-538b-8001-ca0713d2a32a> CONTACT_URI=sip:[email protected]:44815;transport=TCP;ob EXPIRES=0 03-11-2015 22:24:55.862 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=<urn:uuid:100da80d-454f-538b-8001-ca0713d2a32a> CONTACT_URI=sip:[email protected]:35040;transport=TCP;ob EXPIRES=600 ==> homer/homer-err.log <== Traceback (most recent call last): Failure: twisted.internet.error.ConnectionRefusedError: Connection was refused by other side: 111: Connection refused. Unhandled error in Deferred: Unhandled Error Traceback (most recent call last): Failure: twisted.internet.error.ConnectionRefusedError: Connection was refused by other side: 111: Connection refused. Unhandled error in Deferred: Unhandled Error Traceback (most recent call last): Failure: twisted.internet.error.ConnectionRefusedError: Connection was refused by other side: 111: Connection refused. ==> homestead/homestead_20151103T220000Z.txt <== 03-11-2015 22:28:29.966 UTC Debug dnscachedresolver.cpp:701: Adding record to cache entry, TTL=0, expiry=1446589709 03-11-2015 22:28:29.966 UTC Debug dnscachedresolver.cpp:705: Update cache entry expiry to 1446589709 03-11-2015 22:28:29.966 UTC Debug dnscachedresolver.cpp:647: Adding hss-instance to cache expiry list with deletion time of 1446590009 03-11-2015 22:28:29.966 UTC Debug dnscachedresolver.cpp:295: Received all query responses 03-11-2015 22:28:29.966 UTC Debug dnscachedresolver.cpp:323: Pulling 1 records from cache for hss-instance A 03-11-2015 22:28:29.966 UTC Debug baseresolver.cpp:351: Found 1 A/AAAA records, randomizing 03-11-2015 22:28:29.966 UTC Debug baseresolver.cpp:493: 172.31.42.68:3868 transport 132 is not blacklisted 03-11-2015 22:28:29.966 UTC Debug baseresolver.cpp:372: Added a server, now have 1 of 2 03-11-2015 22:28:29.966 UTC Debug baseresolver.cpp:410: Adding 0 servers from blacklist ==> homestead/access_20151103T220000Z.txt <== 03-11-2015 22:26:55.449 UTC 200 GET /ping 0.000000 seconds 03-11-2015 22:27:05.467 UTC 200 GET /ping 0.000000 seconds 03-11-2015 22:27:15.489 UTC 200 GET /ping 0.000000 seconds 03-11-2015 22:27:25.513 UTC 200 GET /ping 0.000000 seconds 03-11-2015 22:27:35.536 UTC 200 GET /ping 0.000000 seconds 03-11-2015 22:27:45.560 UTC 200 GET /ping 0.000000 seconds 03-11-2015 22:27:55.585 UTC 200 GET /ping 0.000000 seconds 03-11-2015 22:28:05.603 UTC 200 GET /ping 0.000000 seconds 03-11-2015 22:28:15.622 UTC 200 GET /ping 0.000000 seconds 03-11-2015 22:28:25.642 UTC 200 GET /ping 0.000000 seconds ==> homestead-prov/homestead-prov_20150922T170000Z.txt <== 22-09-2015 17:34:32.138 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 22-09-2015 17:35:19.919 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 22-09-2015 17:51:01.307 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20150923T130000Z.txt <== 23-09-2015 13:58:08.628 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151021T180000Z.txt <== 21-10-2015 18:57:49.486 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151021T190000Z.txt <== 21-10-2015 19:05:55.777 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 21-10-2015 19:09:46.261 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 21-10-2015 19:22:37.215 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151021T210000Z.txt <== 21-10-2015 21:53:54.911 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151022T120000Z.txt <== 22-10-2015 12:28:07.264 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151027T210000Z.txt <== 27-10-2015 21:40:16.002 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151028T130000Z.txt <== 28-10-2015 13:58:29.804 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151029T140000Z.txt <== 29-10-2015 14:21:48.874 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151029T150000Z.txt <== 29-10-2015 15:53:07.923 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151029T170000Z.txt <== 29-10-2015 17:51:25.067 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151101T140000Z.txt <== 01-11-2015 14:21:37.175 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151101T150000Z.txt <== 01-11-2015 15:09:56.410 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151102T140000Z.txt <== 02-11-2015 14:00:50.193 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151102T160000Z.txt <== 02-11-2015 16:53:41.560 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov_20151103T140000Z.txt <== 03-11-2015 14:23:58.990 UTC INFO main.py:73: Going to listen for HTTP on UNIX socket /tmp/.homestead-prov-sock-0 ==> homestead-prov/homestead-prov-err.log <== Unhandled error in Deferred: Unhandled Error Traceback (most recent call last): Failure: twisted.internet.error.ConnectionRefusedError: Connection was refused by other side: 111: Connection refused. Unhandled error in Deferred: Unhandled Error Traceback (most recent call last): Failure: twisted.internet.error.ConnectionRefusedError: Connection was refused by other side: 111: Connection refused. ==> homestead-prov/homestead-prov-err.log.old <== Unhandled error in Deferred: Unhandled Error Traceback (most recent call last): Failure: twisted.internet.error.ConnectionRefusedError: Connection was refused by other side: 111: Connection refused. Unhandled error in Deferred: Unhandled Error Traceback (most recent call last): Failure: twisted.internet.error.ConnectionRefusedError: Connection was refused by other side: 111: Connection refused. ==> homestead/homestead_20151103T220000Z.txt <== 03-11-2015 22:28:34.966 UTC Debug diameterresolver.cpp:91: DiameterResolver::resolve for realm , host hss-instance, family 2 03-11-2015 22:28:34.966 UTC Debug baseresolver.cpp:503: Attempt to parse hss-instance as IP address 03-11-2015 22:28:34.967 UTC Debug dnscachedresolver.cpp:664: Removing record for hss-instance (type 1, expiry time 1446589709) from the expiry list 03-11-2015 22:28:34.967 UTC Verbose dnscachedresolver.cpp:237: Check cache for hss-instance type 1 03-11-2015 22:28:34.967 UTC Debug dnscachedresolver.cpp:252: Expired entry found in cache 03-11-2015 22:28:34.967 UTC Debug dnscachedresolver.cpp:279: Create and execute DNS query transaction 03-11-2015 22:28:34.967 UTC Debug dnscachedresolver.cpp:291: Wait for query responses 03-11-2015 22:28:34.967 UTC Debug dnscachedresolver.cpp:432: Received DNS response for hss-instance type A 03-11-2015 22:28:34.967 UTC Debug dnsparser.cpp:90: Parsing DNS message 000000: d6618580 00010001 00000000 0c687373 2d696e73 74616e63 65000001 0001c00c .a.. .... .... .hss -ins tanc e... .... 000020: 00010001 00000000 0004ac1f 2a44 .... .... .... *D 03-11-2015 22:28:34.967 UTC Debug dnsparser.cpp:95: Parsing header at offset 0x0 03-11-2015 22:28:34.967 UTC Debug dnsparser.cpp:98: 1 questions, 1 answers, 0 authorities, 0 additional records 03-11-2015 22:28:34.967 UTC Debug dnsparser.cpp:103: Parsing question 1 at offset 0xc 03-11-2015 22:28:34.967 UTC Debug dnsparser.cpp:229: Parsed domain name = hss-instance, encoded length = 14 03-11-2015 22:28:34.967 UTC Debug dnsparser.cpp:112: Parsing answer 1 at offset 0x1e 03-11-2015 22:28:34.967 UTC Debug dnsparser.cpp:229: Parsed domain name = hss-instance, encoded length = 2 03-11-2015 22:28:34.967 UTC Debug dnsparser.cpp:282: Resource Record NAME=hss-instance TYPE=A CLASS=IN TTL=0 RDLENGTH=4 03-11-2015 22:28:34.967 UTC Debug dnsparser.cpp:287: Parse A record RDATA 03-11-2015 22:28:34.967 UTC Debug dnsparser.cpp:142: Answer records hss-instance 0 IN A 172.31.42.68 03-11-2015 22:28:34.967 UTC Debug dnsparser.cpp:143: Authority records 03-11-2015 22:28:34.967 UTC Debug dnsparser.cpp:144: Additional records 03-11-2015 22:28:34.967 UTC Debug dnscachedresolver.cpp:701: Adding record to cache entry, TTL=0, expiry=1446589714 03-11-2015 22:28:34.967 UTC Debug dnscachedresolver.cpp:705: Update cache entry expiry to 1446589714 03-11-2015 22:28:34.967 UTC Debug dnscachedresolver.cpp:647: Adding hss-instance to cache expiry list with deletion time of 1446590014 03-11-2015 22:28:34.967 UTC Debug dnscachedresolver.cpp:295: Received all query responses 03-11-2015 22:28:34.967 UTC Debug dnscachedresolver.cpp:323: Pulling 1 records from cache for hss-instance A 03-11-2015 22:28:34.967 UTC Debug baseresolver.cpp:351: Found 1 A/AAAA records, randomizing 03-11-2015 22:28:34.967 UTC Debug baseresolver.cpp:493: 172.31.42.68:3868 transport 132 is not blacklisted 03-11-2015 22:28:34.967 UTC Debug baseresolver.cpp:372: Added a server, now have 1 of 2 03-11-2015 22:28:34.967 UTC Debug baseresolver.cpp:410: Adding 0 servers from blacklist ==> sprout/sprout_20151103T220000Z.txt <== 03-11-2015 22:28:35.654 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 03-11-2015 22:28:35.654 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) 03-11-2015 22:28:35.655 UTC Verbose pjsip: tcplis:5054 TCP listener 172.31.45.86:5054: got incoming TCP connection from 172.31.45.86:44774, sock=1393 03-11-2015 22:28:35.655 UTC Verbose pjsip: tcps0x7f39ec27 TCP server transport created 03-11-2015 22:28:35.656 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=29116 (rdata0x7f39ec273940) 03-11-2015 22:28:35.656 UTC Verbose common_sip_processing.cpp:119: RX 347 bytes Request msg OPTIONS/cseq=29116 (rdata0x7f39ec273940) from TCP 172.31.45.86:44774: --start msg-- OPTIONS sip:[email protected]:5054 SIP/2.0 Via: SIP/2.0/TCP 172.31.45.86;rport;branch=z9hG4bK-29116 Max-Forwards: 2 To: <sip:[email protected]:5054> From: poll-sip <sip:[email protected]>;tag=29116 Call-ID: poll-sip-29116 CSeq: 29116 OPTIONS Contact: <sip:172.31.45.86> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 03-11-2015 22:28:35.656 UTC Debug common_sip_processing.cpp:211: Skipping SAS logging for OPTIONS request 03-11-2015 22:28:35.656 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f39ec04aff8 for worker threads 03-11-2015 22:28:35.656 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f39ec04aff8 03-11-2015 22:28:35.656 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=29116 (rdata0x7f39ec04aff8) 03-11-2015 22:28:35.656 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=29116 (tdta0x7f3a18013770) created 03-11-2015 22:28:35.656 UTC Verbose common_sip_processing.cpp:135: TX 277 bytes Response msg 200/OPTIONS/cseq=29116 (tdta0x7f3a18013770) to TCP 172.31.45.86:44774: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP 172.31.45.86;rport=44774;received=172.31.45.86;branch=z9hG4bK-29116 Call-ID: poll-sip-29116 From: "poll-sip" <sip:[email protected]>;tag=29116 To: <sip:[email protected]>;tag=z9hG4bK-29116 CSeq: 29116 OPTIONS Content-Length: 0 --end msg-- 03-11-2015 22:28:35.656 UTC Debug common_sip_processing.cpp:253: Skipping SAS logging for OPTIONS response 03-11-2015 22:28:35.656 UTC Debug pjsip: tdta0x7f3a1801 Destroying txdata Response msg 200/OPTIONS/cseq=29116 (tdta0x7f3a18013770) 03-11-2015 22:28:35.656 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f39ec04aff8 03-11-2015 22:28:35.656 UTC Debug thread_dispatcher.cpp:199: Request latency = 172us ==> homestead/homestead_20151103T220000Z.txt <== 03-11-2015 22:28:35.658 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 03-11-2015 22:28:35.658 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) ==> homestead/access_20151103T220000Z.txt <== 03-11-2015 22:28:35.658 UTC 200 GET /ping 0.000000 seconds ==> sprout/sprout_20151103T220000Z.txt <== 03-11-2015 22:28:36.261 UTC Verbose pjsip: tcplis:5052 TCP listener 172.31.45.86:5052: got incoming TCP connection from 172.31.42.105:13686, sock=1395 03-11-2015 22:28:36.261 UTC Verbose pjsip: tcps0x7f39ec27 TCP server transport created 03-11-2015 22:28:36.261 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg MESSAGE/cseq=5000 (rdata0x7f39ec276930) 03-11-2015 22:28:36.261 UTC Verbose common_sip_processing.cpp:119: RX 868 bytes Request msg MESSAGE/cseq=5000 (rdata0x7f39ec276930) from TCP 172.31.42.105:13686: --start msg-- MESSAGE sip:[email protected];transport=tcp SIP/2.0 Via: SIP/2.0/TCP 172.31.42.105:5054;branch=z9hG4bK+cb03199300f7bce59301287929c3575f1+sip+1+a64dea99 From: "6505550202" <sip:[email protected]>;tag=172.31.42.105+1+163a93cf+e8453296 Content-Length: 34 P-Charging-Function-Addresses: ccf=pri_ccf_address P-Charging-Vector: icid-value=0dc5634c81eb7de32642b435a4d95ec6 To: "sc" <sip:[email protected]> Record-Route: <sip:172.31.42.105:5054;lr> Route: <sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;orig> P-Served-User: sip:[email protected] P-Asserted-Identity: sip:[email protected] Call-ID: 0gQAAC8WAAACBAAALxYAAGbURwtzZGnMldhGyYBaA2c0CVJCDkRfbARVxTSfWvg6@172.31.42.105 CSeq: 5000 MESSAGE Max-Forwards: 69 P-Visited-Network-ID: example.com Content-Type: application/vnd.3gpp.sms --end msg-- 03-11-2015 22:28:36.262 UTC Debug pjutils.cpp:1707: Logging SAS Call-ID marker, Call-ID 0gQAAC8WAAACBAAALxYAAGbURwtzZGnMldhGyYBaA2c0CVJCDkRfbARVxTSfWvg6@172.31.42.105 03-11-2015 22:28:36.262 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f39ec139e78 for worker threads 03-11-2015 22:28:36.262 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f39ec139e78 03-11-2015 22:28:36.262 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg MESSAGE/cseq=5000 (rdata0x7f39ec139e78) 03-11-2015 22:28:36.262 UTC Debug authentication.cpp:666: Authentication module invoked 03-11-2015 22:28:36.262 UTC Debug authentication.cpp:532: Request does not need authentication - not on S-CSCF port 03-11-2015 22:28:36.262 UTC Debug authentication.cpp:676: Request does not need authentication 03-11-2015 22:28:36.262 UTC Debug basicproxy.cpp:91: Process MESSAGE request 03-11-2015 22:28:36.262 UTC Verbose sproutletproxy.cpp:425: Sproutlet Proxy transaction (0x7f3a14013770) created 03-11-2015 22:28:36.262 UTC Debug basicproxy.cpp:1242: Report SAS start marker - trail (276) 03-11-2015 22:28:36.262 UTC Debug pjutils.cpp:744: Cloned Request msg MESSAGE/cseq=5000 (rdata0x7f39ec139e78) to tdta0x7f3a14000fc0 03-11-2015 22:28:36.262 UTC Debug pjsip: tsx0x7f3a14002 Transaction created for Request msg MESSAGE/cseq=5000 (rdata0x7f39ec139e78) 03-11-2015 22:28:36.262 UTC Debug pjsip: tsx0x7f3a14002 Incoming Request msg MESSAGE/cseq=5000 (rdata0x7f39ec139e78) in state Null 03-11-2015 22:28:36.262 UTC Debug pjsip: tsx0x7f3a14002 State changed from Null to Trying, event=RX_MSG 03-11-2015 22:28:36.262 UTC Debug basicproxy.cpp:212: tsx0x7f3a14002498 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying 03-11-2015 22:28:36.262 UTC Debug pjsip: endpoint Response msg 408/MESSAGE/cseq=5000 (tdta0x7f3a1403b3c0) created 03-11-2015 22:28:36.262 UTC Debug sproutletproxy.cpp:102: Find target Sproutlet for request 03-11-2015 22:28:36.262 UTC Debug sproutletproxy.cpp:136: Found next routable URI: sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;orig 03-11-2015 22:28:36.262 UTC Debug sproutletproxy.cpp:175: No Sproutlet found using service name or host 03-11-2015 22:28:36.262 UTC Debug sproutletproxy.cpp:180: Find default service for port 5052 03-11-2015 22:28:36.262 UTC Verbose sproutletproxy.cpp:1022: Created Sproutlet icscf-0x7f3a140139c0 for Request msg MESSAGE/cseq=5000 (tdta0x7f3a14000fc0) 03-11-2015 22:28:36.262 UTC Verbose sproutletproxy.cpp:1906: Routing Request msg MESSAGE/cseq=5000 (tdta0x7f3a14000fc0) (900 bytes) to downstream sproutlet icscf: --start msg-- MESSAGE sip:[email protected];transport=tcp SIP/2.0 Via: SIP/2.0/TCP 172.31.42.105:5054;received=172.31.42.105;branch=z9hG4bK+cb03199300f7bce59301287929c3575f1+sip+1+a64dea99 From: "6505550202" <sip:[email protected]>;tag=172.31.42.105+1+163a93cf+e8453296 P-Charging-Function-Addresses: ccf=pri_ccf_address P-Charging-Vector: icid-value="0dc5634c81eb7de32642b435a4d95ec6" To: "sc" <sip:[email protected]> Record-Route: <sip:172.31.42.105:5054;lr> Route: <sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;orig> P-Served-User: <sip:[email protected]> P-Asserted-Identity: <sip:[email protected]> Call-ID: 0gQAAC8WAAACBAAALxYAAGbURwtzZGnMldhGyYBaA2c0CVJCDkRfbARVxTSfWvg6@172.31.42.105 CSeq: 5000 MESSAGE Max-Forwards: 69 P-Visited-Network-ID: example.com Content-Type: application/vnd.3gpp.sms Content-Length: 34 --end msg-- 03-11-2015 22:28:36.262 UTC Debug pjutils.cpp:761: Cloned tdta0x7f3a14000fc0 to tdta0x7f3a1403c3d0 03-11-2015 22:28:36.262 UTC Debug sproutletproxy.cpp:1083: Remove top Route header Route: <sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;orig> 03-11-2015 22:28:36.262 UTC Debug sproutletproxy.cpp:1591: Adding message 0x7f3a1403c9e0 => txdata 0x7f3a1403c478 mapping 03-11-2015 22:28:36.262 UTC Verbose sproutletproxy.cpp:1444: icscf-0x7f3a140139c0 pass initial request Request msg MESSAGE/cseq=5000 (tdta0x7f3a1403c3d0) to Sproutlet 03-11-2015 22:28:36.262 UTC Debug pjutils.cpp:562: Next hop node is encoded in Request-URI 03-11-2015 22:28:36.262 UTC Debug acr.cpp:49: Created ACR (0x7f3a14002cc0) 03-11-2015 22:28:36.262 UTC Debug icscfsproutlet.cpp:501: I-CSCF initialize transaction for non-REGISTER request 03-11-2015 22:28:36.262 UTC Debug icscfsproutlet.cpp:516: Originating request 03-11-2015 22:28:36.262 UTC Debug pjutils.cpp:363: Served user from P-Served-User header 03-11-2015 22:28:36.262 UTC Debug icscfrouter.cpp:420: Perform LIR - impu sip:[email protected], originating true, auth_type None 03-11-2015 22:28:36.263 UTC Debug httpconnection.cpp:183: Allocated CURL handle 0x7f3a1403e520 03-11-2015 22:28:36.263 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host ec2-52-3-140-139.compute-1.amazonaws.com, port 8888, family 2 03-11-2015 22:28:36.263 UTC Debug baseresolver.cpp:503: Attempt to parse ec2-52-3-140-139.compute-1.amazonaws.com as IP address 03-11-2015 22:28:36.263 UTC Debug dnscachedresolver.cpp:664: Removing record for ec2-52-3-140-139.compute-1.amazonaws.com (type 1, expiry time 1446589576) from the expiry list 03-11-2015 22:28:36.263 UTC Debug dnscachedresolver.cpp:664: Removing record for ec2-52-3-140-139.compute-1.amazonaws.com (type 1, expiry time 1446589682) from the expiry list 03-11-2015 22:28:36.263 UTC Verbose dnscachedresolver.cpp:237: Check cache for ec2-52-3-140-139.compute-1.amazonaws.com type 1 03-11-2015 22:28:36.263 UTC Debug dnscachedresolver.cpp:252: Expired entry found in cache 03-11-2015 22:28:36.264 UTC Debug dnscachedresolver.cpp:279: Create and execute DNS query transaction 03-11-2015 22:28:36.264 UTC Debug dnscachedresolver.cpp:291: Wait for query responses 03-11-2015 22:28:36.265 UTC Debug dnscachedresolver.cpp:432: Received DNS response for ec2-52-3-140-139.compute-1.amazonaws.com type A 03-11-2015 22:28:36.265 UTC Debug dnsparser.cpp:90: Parsing DNS message 000000: d9678180 00010001 00000000 10656332 2d35322d 332d3134 302d3133 3909636f .g.. .... .... .ec2 -52- 3-14 0-13 9.co 000020: 6d707574 652d3109 616d617a 6f6e6177 7303636f 6d000001 0001c00c 00010001 mput e-1. amaz onaw s.co m... .... .... 000040: 0000003c 0004ac1f 2d56 ...< .... -V 03-11-2015 22:28:36.265 UTC Debug dnsparser.cpp:95: Parsing header at offset 0x0 03-11-2015 22:28:36.265 UTC Debug dnsparser.cpp:98: 1 questions, 1 answers, 0 authorities, 0 additional records 03-11-2015 22:28:36.265 UTC Debug dnsparser.cpp:103: Parsing question 1 at offset 0xc 03-11-2015 22:28:36.265 UTC Debug dnsparser.cpp:229: Parsed domain name = ec2-52-3-140-139.compute-1.amazonaws.com, encoded length = 42 03-11-2015 22:28:36.265 UTC Debug dnsparser.cpp:112: Parsing answer 1 at offset 0x3a 03-11-2015 22:28:36.265 UTC Debug dnsparser.cpp:229: Parsed domain name = ec2-52-3-140-139.compute-1.amazonaws.com, encoded length = 2 03-11-2015 22:28:36.265 UTC Debug dnsparser.cpp:282: Resource Record NAME=ec2-52-3-140-139.compute-1.amazonaws.com TYPE=A CLASS=IN TTL=60 RDLENGTH=4 03-11-2015 22:28:36.265 UTC Debug dnsparser.cpp:287: Parse A record RDATA 03-11-2015 22:28:36.265 UTC Debug dnsparser.cpp:142: Answer records ec2-52-3-140-139.compute-1.amazonaws.com 60 IN A 172.31.45.86 03-11-2015 22:28:36.265 UTC Debug dnsparser.cpp:143: Authority records 03-11-2015 22:28:36.265 UTC Debug dnsparser.cpp:144: Additional records 03-11-2015 22:28:36.265 UTC Debug dnscachedresolver.cpp:701: Adding record to cache entry, TTL=60, expiry=1446589776 03-11-2015 22:28:36.265 UTC Debug dnscachedresolver.cpp:705: Update cache entry expiry to 1446589776 03-11-2015 22:28:36.265 UTC Debug dnscachedresolver.cpp:647: Adding ec2-52-3-140-139.compute-1.amazonaws.com to cache expiry list with deletion time of 1446590076 03-11-2015 22:28:36.265 UTC Debug dnscachedresolver.cpp:295: Received all query responses 03-11-2015 22:28:36.265 UTC Debug dnscachedresolver.cpp:323: Pulling 1 records from cache for ec2-52-3-140-139.compute-1.amazonaws.com A 03-11-2015 22:28:36.265 UTC Debug baseresolver.cpp:351: Found 1 A/AAAA records, randomizing 03-11-2015 22:28:36.265 UTC Debug baseresolver.cpp:493: 172.31.45.86:8888 transport 6 is not blacklisted 03-11-2015 22:28:36.265 UTC Debug baseresolver.cpp:372: Added a server, now have 1 of 5 03-11-2015 22:28:36.265 UTC Debug baseresolver.cpp:410: Adding 0 servers from blacklist 03-11-2015 22:28:36.265 UTC Debug httpconnection.cpp:595: Sending HTTP request : http://ec2-52-3-140-139.compute-1.amazonaws.com:8888/impu/sip%3A6505550202%40example.com/location?originating=true (trying 172.31.45.86) on new connection ==> homestead/homestead_20151103T220000Z.txt <== 03-11-2015 22:28:36.266 UTC Verbose httpstack.cpp:286: Process request for URL /impu/sip%3A6505550202%40example.com/location, args originating=true 03-11-2015 22:28:36.266 UTC Debug handlers.cpp:689: Parsed HTTP request: public ID sip:[email protected], originating true, authorization type 03-11-2015 22:28:36.266 UTC Debug cx.cpp:237: Building Location-Info request for sip:[email protected] 03-11-2015 22:28:36.266 UTC Debug freeDiameter: No Session-Id AVP found in message 0x7f2884000f90 03-11-2015 22:28:36.266 UTC Verbose diameterstack.cpp:1337: Sending Diameter message of type 302 on transaction 0x7f28840019f0 with timeout 200 03-11-2015 22:28:36.266 UTC Debug freeDiameter: GOING TO SEND TO '172.31.42.68': '3GPP/Location-Info-Request'16777216/302 f:RP-- src:'(nil)' len:20 {C:263/l:8,C:260/l:8,C:277/l:12,C:264/l:8,C:296/l:8,C:293/l:8,C:283/l:8,V:10415/C:633/l:16,V:10415/C:601/l:12} 03-11-2015 22:28:36.266 UTC Debug diameterstack.cpp:819: Processing a sent diameter message 03-11-2015 22:28:36.266 UTC Debug diameterstack.cpp:821: Got existing trail ID: 3921 03-11-2015 22:28:36.266 UTC Debug diameterstack.cpp:879: Raising correlating marker with diameter session ID = ec2-52-3-140-139.compute-1.amazonaws.com;1446560650;540 03-11-2015 22:28:36.266 UTC Debug freeDiameter: Sending 320b data on connection {----} TCP,#1230->172.31.42.68(3868) 03-11-2015 22:28:36.268 UTC Debug freeDiameter: 'STATE_OPEN' <-- 'FDEVP_CNX_MSG_RECV' (0x7f286c0024c0,272) '172.31.42.68' 03-11-2015 22:28:36.268 UTC Debug diameterstack.cpp:799: Processing a received diameter message 03-11-2015 22:28:36.268 UTC Debug diameterstack.cpp:812: Got existing trail ID: 3921 03-11-2015 22:28:36.269 UTC Debug diameterstack.cpp:879: Raising correlating marker with diameter session ID = ec2-52-3-140-139.compute-1.amazonaws.com;1446560650;540 03-11-2015 22:28:36.269 UTC Debug freeDiameter: Peer timeout reset to 30 seconds (+/- 2) 03-11-2015 22:28:36.269 UTC Debug freeDiameter: '172.31.42.68' in state 'STATE_OPEN' waiting for next event. 03-11-2015 22:28:36.269 UTC Debug freeDiameter: Iterating on rules of AVP: 'Vendor-Specific-Application-Id'. 03-11-2015 22:28:36.269 UTC Debug freeDiameter: Iterating on rules of COMMAND: '3GPP/Location-Info-Answer'. 03-11-2015 22:28:36.269 UTC Debug freeDiameter: Calling callback registered when query was sent (0x4581c0, 0x7f28840019f0) 03-11-2015 22:28:36.269 UTC Verbose diameterstack.cpp:1007: Got Diameter response of type 302 - calling callback on transaction 0x7f28840019f0 03-11-2015 22:28:36.269 UTC Debug handlers.cpp:730: Received Location-Info answer with result 2001/0 03-11-2015 22:28:36.269 UTC Debug handlers.cpp:746: Got Server-Name sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP 03-11-2015 22:28:36.269 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /impu/sip%3A6505550202%40example.com/location, args originating=true ==> homestead/access_20151103T220000Z.txt <== 03-11-2015 22:28:36.269 UTC 200 GET /impu/sip%3A6505550202%40example.com/location 0.002864 seconds ==> sprout/sprout_20151103T220000Z.txt <== 03-11-2015 22:28:36.269 UTC Debug httpconnection.cpp:610: Received HTTP response: status=200, doc={"result-code":2001,"scscf":"sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP"} 03-11-2015 22:28:36.269 UTC Debug icscfrouter.cpp:237: HSS returned S-CSCF sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP as target 03-11-2015 22:28:36.269 UTC Debug acr.cpp:83: Sending Null ACR (0x7f3a14002cc0) 03-11-2015 22:28:36.269 UTC Debug icscfrouter.cpp:115: SCSCF specified by HSS: sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP 03-11-2015 22:28:36.269 UTC Debug icscfsproutlet.cpp:709: Found SCSCF for non-REGISTER 03-11-2015 22:28:36.269 UTC Debug sproutletproxy.cpp:1218: Sproutlet send_request 0x7f3a1403c9e0 03-11-2015 22:28:36.269 UTC Verbose sproutletproxy.cpp:1254: icscf-0x7f3a140139c0 sending Request msg MESSAGE/cseq=5000 (tdta0x7f3a1403c3d0) on fork 0 03-11-2015 22:28:36.269 UTC Debug sproutletproxy.cpp:1606: Processing actions from sproutlet - 0 responses, 1 requests 03-11-2015 22:28:36.269 UTC Debug sproutletproxy.cpp:1641: Processing request 0x7f3a1403c478, fork = 0 03-11-2015 22:28:36.269 UTC Debug sproutletproxy.cpp:1759: icscf-0x7f3a140139c0 transmitting request on fork 0 03-11-2015 22:28:36.269 UTC Debug sproutletproxy.cpp:1773: icscf-0x7f3a140139c0 store reference to non-ACK request Request msg MESSAGE/cseq=5000 (tdta0x7f3a1403c3d0) on fork 0 03-11-2015 22:28:36.269 UTC Debug sproutletproxy.cpp:1598: Removing message 0x7f3a1403c9e0 => txdata 0x7f3a1403c478 mapping 03-11-2015 22:28:36.269 UTC Debug sproutletproxy.cpp:102: Find target Sproutlet for request 03-11-2015 22:28:36.269 UTC Debug sproutletproxy.cpp:136: Found next routable URI: sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;orig 03-11-2015 22:28:36.269 UTC Debug sproutletproxy.cpp:175: No Sproutlet found using service name or host 03-11-2015 22:28:36.269 UTC Debug sproutletproxy.cpp:180: Find default service for port 5054 03-11-2015 22:28:36.269 UTC Debug scscfsproutlet.cpp:401: S-CSCF Transaction (0x7f3a140ab740) created 03-11-2015 22:28:36.269 UTC Verbose sproutletproxy.cpp:1022: Created Sproutlet scscf-0x7f3a140ab740 for Request msg MESSAGE/cseq=5000 (tdta0x7f3a1403c3d0) 03-11-2015 22:28:36.269 UTC Verbose sproutletproxy.cpp:1906: Routing Request msg MESSAGE/cseq=5000 (tdta0x7f3a1403c3d0) (900 bytes) to downstream sproutlet scscf: --start msg-- MESSAGE sip:[email protected];transport=tcp SIP/2.0 Via: SIP/2.0/TCP 172.31.42.105:5054;received=172.31.42.105;branch=z9hG4bK+cb03199300f7bce59301287929c3575f1+sip+1+a64dea99 From: "6505550202" <sip:[email protected]>;tag=172.31.42.105+1+163a93cf+e8453296 P-Charging-Function-Addresses: ccf=pri_ccf_address P-Charging-Vector: icid-value="0dc5634c81eb7de32642b435a4d95ec6" To: "sc" <sip:[email protected]> Record-Route: <sip:172.31.42.105:5054;lr> P-Served-User: <sip:[email protected]> P-Asserted-Identity: <sip:[email protected]> Call-ID: 0gQAAC8WAAACBAAALxYAAGbURwtzZGnMldhGyYBaA2c0CVJCDkRfbARVxTSfWvg6@172.31.42.105 CSeq: 5000 MESSAGE Max-Forwards: 68 P-Visited-Network-ID: example.com Route: <sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;orig> Content-Type: application/vnd.3gpp.sms Content-Length: 34 --end msg-- 03-11-2015 22:28:36.269 UTC Debug pjutils.cpp:761: Cloned tdta0x7f3a1403c3d0 to tdta0x7f3a140abd10 03-11-2015 22:28:36.269 UTC Debug sproutletproxy.cpp:1083: Remove top Route header Route: <sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;orig> 03-11-2015 22:28:36.269 UTC Debug sproutletproxy.cpp:1591: Adding message 0x7f3a140ac320 => txdata 0x7f3a140abdb8 mapping 03-11-2015 22:28:36.269 UTC Verbose sproutletproxy.cpp:1444: scscf-0x7f3a140ab740 pass initial request Request msg MESSAGE/cseq=5000 (tdta0x7f3a140abd10) to Sproutlet 03-11-2015 22:28:36.269 UTC Info scscfsproutlet.cpp:443: S-CSCF received initial request 03-11-2015 22:28:36.269 UTC Debug pjutils.cpp:2330: Adding session expires header with default value 03-11-2015 22:28:36.269 UTC Debug scscfsproutlet.cpp:733: Route header references this system 03-11-2015 22:28:36.269 UTC Debug scscfsproutlet.cpp:779: No ODI token, or invalid ODI token, on request - logging ICID marker 0dc5634c81eb7de32642b435a4d95ec6 for B2BUA AS correlation 03-11-2015 22:28:36.269 UTC Debug scscfsproutlet.cpp:792: Got our Route header, session case orig, OD=None 03-11-2015 22:28:36.269 UTC Debug pjutils.cpp:363: Served user from P-Served-User header 03-11-2015 22:28:36.269 UTC Debug pjutils.cpp:257: aor_from_uri converted sip:[email protected] to sip:[email protected] 03-11-2015 22:28:36.269 UTC Debug acr.cpp:49: Created ACR (0x7f3a1406ca40) 03-11-2015 22:28:36.269 UTC Debug scscfsproutlet.cpp:921: Looking up iFCs for sip:[email protected] for new AS chain 03-11-2015 22:28:36.269 UTC Debug hssconnection.cpp:567: Making Homestead request for /impu/sip%3A6505550202%40example.com/reg-data 03-11-2015 22:28:36.269 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host ec2-52-3-140-139.compute-1.amazonaws.com, port 8888, family 2 03-11-2015 22:28:36.269 UTC Debug baseresolver.cpp:503: Attempt to parse ec2-52-3-140-139.compute-1.amazonaws.com as IP address 03-11-2015 22:28:36.269 UTC Verbose dnscachedresolver.cpp:237: Check cache for ec2-52-3-140-139.compute-1.amazonaws.com type 1 03-11-2015 22:28:36.269 UTC Debug dnscachedresolver.cpp:323: Pulling 1 records from cache for ec2-52-3-140-139.compute-1.amazonaws.com A 03-11-2015 22:28:36.269 UTC Debug baseresolver.cpp:351: Found 1 A/AAAA records, randomizing 03-11-2015 22:28:36.269 UTC Debug baseresolver.cpp:493: 172.31.45.86:8888 transport 6 is not blacklisted 03-11-2015 22:28:36.269 UTC Debug baseresolver.cpp:372: Added a server, now have 1 of 5 03-11-2015 22:28:36.269 UTC Debug baseresolver.cpp:410: Adding 0 servers from blacklist 03-11-2015 22:28:36.269 UTC Debug baseresolver.cpp:503: Attempt to parse 172.31.45.86 as IP address 03-11-2015 22:28:36.269 UTC Debug httpconnection.cpp:595: Sending HTTP request : http://ec2-52-3-140-139.compute-1.amazonaws.com:8888/impu/sip%3A6505550202%40example.com/reg-data (trying 172.31.45.86) ==> homestead/homestead_20151103T220000Z.txt <== 03-11-2015 22:28:36.270 UTC Verbose httpstack.cpp:286: Process request for URL /impu/sip%3A6505550202%40example.com/reg-data, args (null) 03-11-2015 22:28:36.270 UTC Debug handlers.cpp:984: Parsed HTTP request: private ID , public ID sip:[email protected] 03-11-2015 22:28:36.270 UTC Debug handlers.cpp:928: Determining request type from '{"reqtype": "call"}' 03-11-2015 22:28:36.270 UTC Debug handlers.cpp:972: New value of _type is 2 03-11-2015 22:28:36.270 UTC Debug handlers.cpp:1022: Try to find IMS Subscription information in the cache 03-11-2015 22:28:36.270 UTC Debug cassandra_store.cpp:279: Getting thread-local Client 03-11-2015 22:28:36.270 UTC Debug cassandra_store.cpp:129: Generated Cassandra timestamp 1446589716270207 03-11-2015 22:28:36.270 UTC Debug cache.cpp:350: Issuing get for key sip:[email protected] 03-11-2015 22:28:36.270 UTC Debug cassandra_store.cpp:762: Failed ONE read for get_row. Try QUORUM 03-11-2015 22:28:36.272 UTC Debug cache.cpp:370: Retrieved XML column with TTL 979 and value <?xml version="1.0" encoding="UTF-8"?><IMSSubscription><PrivateID>[email protected]</PrivateID><ServiceProfile><PublicIdentity><Identity>sip:[email protected]</Identity><Extension><IdentityType>0</IdentityType></Extension></PublicIdentity><InitialFilterCriteria><Priority>4</Priority><TriggerPoint><ConditionTypeCNF>1</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>INVITE</Method><Extension><RegistrationType>1</RegistrationType><RegistrationType>2</RegistrationType></Extension></SPT><SPT><ConditionNegated>0</ConditionNegated><Group>1</Group><SessionCase>0</SessionCase><Extension><RegistrationType>1</RegistrationType><RegistrationType>2</RegistrationType></Extension></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=scc</ServerName><DefaultHandling>1</DefaultHandling><Extension><IncludeRegisterRequest/><IncludeRegisterResponse/></Extension></ApplicationServer><ProfilePartIndicator>0</ProfilePartIndicator></InitialFilterCriteria><InitialFilterCriteria><Priority>1</Priority><TriggerPoint><ConditionTypeCNF>1</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>REGISTER</Method><Extension><RegistrationType>0</RegistrationType></Extension></SPT><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>REGISTER</Method><Extension><RegistrationType>1</RegistrationType></Extension></SPT><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>REGISTER</Method><Extension><RegistrationType>2</RegistrationType></Extension></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-172-31-18-87.ec2.internal:5060;transport=tcp</ServerName><DefaultHandling>0</DefaultHandling><Extension><IncludeRegisterRequest/><IncludeRegisterResponse/></Extension></ApplicationServer></InitialFilterCriteria><InitialFilterCriteria><Priority>2</Priority><TriggerPoint><ConditionTypeCNF>1</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>INVITE</Method><Extension></Extension></SPT><SPT><ConditionNegated>0</ConditionNegated><Group>1</Group><SIPHeader><Header>To</Header><Content>sip:[email protected]</Content></SIPHeader><Extension></Extension></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=mmtel</ServerName><DefaultHandling>0</DefaultHandling><Extension><IncludeRegisterRequest/><IncludeRegisterResponse/></Extension></ApplicationServer></InitialFilterCriteria><InitialFilterCriteria><Priority>12</Priority><TriggerPoint><ConditionTypeCNF>1</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>MESSAGE</Method><Extension></Extension></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-172-31-18-87.ec2.internal:5060;transport=tcp</ServerName><DefaultHandling>0</DefaultHandling><Extension><IncludeRegisterRequest/><IncludeRegisterResponse/></Extension></ApplicationServer><ProfilePartIndicator>0</ProfilePartIndicator></InitialFilterCriteria><InitialFilterCriteria><Priority>5</Priority><TriggerPoint><ConditionTypeCNF>1</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>INVITE</Method><Extension><RegistrationType>1</RegistrationType><RegistrationType>2</RegistrationType></Extension></SPT><SPT><ConditionNegated>0</ConditionNegated><Group>1</Group><SessionCase>0</SessionCase><Extension><RegistrationType>1</RegistrationType><RegistrationType>2</RegistrationType></Extension></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=mmtel</ServerName><DefaultHandling>0</DefaultHandling><Extension><IncludeRegisterRequest/><IncludeRegisterResponse/></Extension></ApplicationServer><ProfilePartIndicator>0</ProfilePartIndicator></InitialFilterCriteria><InitialFilterCriteria><Priority>6</Priority><TriggerPoint><ConditionTypeCNF>1</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>INVITE</Method><Extension></Extension></SPT><SPT><ConditionNegated>0</ConditionNegated><Group>1</Group><SessionCase>3</SessionCase><Extension></Extension></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=mmtel</ServerName><DefaultHandling>0</DefaultHandling><Extension><IncludeRegisterRequest/><IncludeRegisterResponse/></Extension></ApplicationServer><ProfilePartIndicator>1</ProfilePartIndicator></InitialFilterCriteria><InitialFilterCriteria><Priority>7</Priority><TriggerPoint><ConditionTypeCNF>1</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>INVITE</Method><Extension></Extension></SPT><SPT><ConditionNegated>0</ConditionNegated><Group>1</Group><SessionCase>4</SessionCase><Extension></Extension></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=mmtel</ServerName><DefaultHandling>0</DefaultHandling><Extension><IncludeRegisterRequest/><IncludeRegisterResponse/></Extension></ApplicationServer></InitialFilterCriteria><InitialFilterCriteria><Priority>8</Priority><TriggerPoint><ConditionTypeCNF>1</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>INVITE</Method><Extension></Extension></SPT><SPT><ConditionNegated>0</ConditionNegated><Group>1</Group><SessionCase>1</SessionCase><Extension></Extension></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=mmtel</ServerName><DefaultHandling>0</DefaultHandling><Extension><IncludeRegisterRequest/><IncludeRegisterResponse/></Extension></ApplicationServer><ProfilePartIndicator>0</ProfilePartIndicator></InitialFilterCriteria><InitialFilterCriteria><Priority>9</Priority><TriggerPoint><ConditionTypeCNF>1</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>INVITE</Method><Extension></Extension></SPT><SPT><ConditionNegated>0</ConditionNegated><Group>1</Group><SessionCase>1</SessionCase><Extension></Extension></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=scc</ServerName><DefaultHandling>1</DefaultHandling><Extension><IncludeRegisterRequest/><IncludeRegisterResponse/></Extension></ApplicationServer><ProfilePartIndicator>0</ProfilePartIndicator></InitialFilterCriteria><InitialFilterCriteria><Priority>10</Priority><TriggerPoint><ConditionTypeCNF>1</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>INVITE</Method><Extension></Extension></SPT><SPT><ConditionNegated>0</ConditionNegated><Group>1</Group><SessionCase>2</SessionCase><Extension></Extension></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=mmtel</ServerName><DefaultHandling>0</DefaultHandling><Extension><IncludeRegisterRequest/><IncludeRegisterResponse/></Extension></ApplicationServer><ProfilePartIndicator>1</ProfilePartIndicator></InitialFilterCriteria><InitialFilterCriteria><Priority>11</Priority><TriggerPoint><ConditionTypeCNF>1</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>INVITE</Method><Extension></Extension></SPT><SPT><ConditionNegated>0</ConditionNegated><Group>1</Group><SessionCase>2</SessionCase><Extension></Extension></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=scc</ServerName><DefaultHandling>1</DefaultHandling><Extension><IncludeRegisterRequest/><IncludeRegisterResponse/></Extension></ApplicationServer><ProfilePartIndicator>1</ProfilePartIndicator></InitialFilterCriteria></ServiceProfile></IMSSubscription> 03-11-2015 22:28:36.272 UTC Debug cache.cpp:382: Retrieved is_registered column with value True and TTL 979 03-11-2015 22:28:36.272 UTC Debug cache.cpp:411: Retrived primary_ccf column with value pri_ccf_address 03-11-2015 22:28:36.272 UTC Debug handlers.cpp:1051: Got IMS subscription from cache 03-11-2015 22:28:36.273 UTC Debug handlers.cpp:1067: TTL for this database record is 979, IMS Subscription XML is not empty, registration state is REGISTERED, and the charging addresses are Primary CCF: pri_ccf_address 03-11-2015 22:28:36.273 UTC Debug handlers.cpp:1159: Handling call 03-11-2015 22:28:36.273 UTC Debug handlers.cpp:1340: Sending 200 response (body was {"reqtype": "call"}) 03-11-2015 22:28:36.273 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /impu/sip%3A6505550202%40example.com/reg-data, args (null) ==> homestead/access_20151103T220000Z.txt <== 03-11-2015 22:28:36.273 UTC 200 PUT /impu/sip%3A6505550202%40example.com/reg-data 0.003151 seconds ==> sprout/sprout_20151103T220000Z.txt <== 03-11-2015 22:28:36.273 UTC Debug httpconnection.cpp:896: Received header http/1.1200ok with value 03-11-2015 22:28:36.273 UTC Debug httpconnection.cpp:896: Received header content-length with value 9655 03-11-2015 22:28:36.273 UTC Debug httpconnection.cpp:896: Received header content-type with value text/plain 03-11-2015 22:28:36.273 UTC Debug httpconnection.cpp:896: Received header with value 03-11-2015 22:28:36.273 UTC Debug httpconnection.cpp:610: Received HTTP response: status=200, doc=<ClearwaterRegData> <RegistrationState>REGISTERED</RegistrationState> <IMSSubscription> <PrivateID>[email protected]</PrivateID> <ServiceProfile> <PublicIdentity> <Identity>sip:[email protected]</Identity> <Extension> <IdentityType>0</IdentityType> </Extension> </PublicIdentity> <InitialFilterCriteria> <Priority>4</Priority> <TriggerPoint> <ConditionTypeCNF>1</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>INVITE</Method> <Extension> <RegistrationType>1</RegistrationType> <RegistrationType>2</RegistrationType> </Extension> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <SessionCase>0</SessionCase> <Extension> <RegistrationType>1</RegistrationType> <RegistrationType>2</RegistrationType> </Extension> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=scc</ServerName> <DefaultHandling>1</DefaultHandling> <Extension> <IncludeRegisterRequest/> <IncludeRegisterResponse/> </Extension> </ApplicationServer> <ProfilePartIndicator>0</ProfilePartIndicator> </InitialFilterCriteria> <InitialFilterCriteria> <Priority>1</Priority> <TriggerPoint> <ConditionTypeCNF>1</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>REGISTER</Method> <Extension> <RegistrationType>0</RegistrationType> </Extension> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>REGISTER</Method> <Extension> <RegistrationType>1</RegistrationType> </Extension> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>REGISTER</Method> <Extension> <RegistrationType>2</RegistrationType> </Extension> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:ip-172-31-18-87.ec2.internal:5060;transport=tcp</ServerName> <DefaultHandling>0</DefaultHandling> <Extension> <IncludeRegisterRequest/> <IncludeRegisterResponse/> </Extension> </ApplicationServer> </InitialFilterCriteria> <InitialFilterCriteria> <Priority>2</Priority> <TriggerPoint> <ConditionTypeCNF>1</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>INVITE</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <SIPHeader> <Header>To</Header> <Content>sip:[email protected]</Content> </SIPHeader> <Extension/> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=mmtel</ServerName> <DefaultHandling>0</DefaultHandling> <Extension> <IncludeRegisterRequest/> <IncludeRegisterResponse/> </Extension> </ApplicationServer> </InitialFilterCriteria> <InitialFilterCriteria> <Priority>12</Priority> <TriggerPoint> <ConditionTypeCNF>1</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>MESSAGE</Method> <Extension/> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:ip-172-31-18-87.ec2.internal:5060;transport=tcp</ServerName> <DefaultHandling>0</DefaultHandling> <Extension> <IncludeRegisterRequest/> <IncludeRegisterResponse/> </Extension> </ApplicationServer> <ProfilePartIndicator>0</ProfilePartIndicator> </InitialFilterCriteria> <InitialFilterCriteria> <Priority>5</Priority> <TriggerPoint> <ConditionTypeCNF>1</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>INVITE</Method> <Extension> <RegistrationType>1</RegistrationType> <RegistrationType>2</RegistrationType> </Extension> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <SessionCase>0</SessionCase> <Extension> <RegistrationType>1</RegistrationType> <RegistrationType>2</RegistrationType> </Extension> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=mmtel</ServerName> <DefaultHandling>0</DefaultHandling> <Extension> <IncludeRegisterRequest/> <IncludeRegisterResponse/> </Extension> </ApplicationServer> <ProfilePartIndicator>0</ProfilePartIndicator> </InitialFilterCriteria> <InitialFilterCriteria> <Priority>6</Priority> <TriggerPoint> <ConditionTypeCNF>1</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>INVITE</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <SessionCase>3</SessionCase> <Extension/> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=mmtel</ServerName> <DefaultHandling>0</DefaultHandling> <Extension> <IncludeRegisterRequest/> <IncludeRegisterResponse/> </Extension> </ApplicationServer> <ProfilePartIndicator>1</ProfilePartIndicator> </InitialFilterCriteria> <InitialFilterCriteria> <Priority>7</Priority> <TriggerPoint> <ConditionTypeCNF>1</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>INVITE</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <SessionCase>4</SessionCase> <Extension/> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=mmtel</ServerName> <DefaultHandling>0</DefaultHandling> <Extension> <IncludeRegisterRequest/> <IncludeRegisterResponse/> </Extension> </ApplicationServer> </InitialFilterCriteria> <InitialFilterCriteria> <Priority>8</Priority> <TriggerPoint> <ConditionTypeCNF>1</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>INVITE</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <SessionCase>1</SessionCase> <Extension/> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=mmtel</ServerName> <DefaultHandling>0</DefaultHandling> <Extension> <IncludeRegisterRequest/> <IncludeRegisterResponse/> </Extension> </ApplicationServer> <ProfilePartIndicator>0</ProfilePartIndicator> </InitialFilterCriteria> <InitialFilterCriteria> <Priority>9</Priority> <TriggerPoint> <ConditionTypeCNF>1</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>INVITE</Method> <Extension/> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <SessionCase>1</SessionCase> <Extension/> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:ip-172-31-17-33.ec2.internal:5060;transport=tcp;oc-mode=scc</ServerName> <DefaultHandling>1</DefaultHandling> <Extension> <IncludeRegisterRequest/> <IncludeRegisterResponse/> </Extension> </ApplicationServer> <ProfilePartIndicator>0</ProfilePartIndicator> </InitialFilterCriteria> <InitialFilterCriteria> <Priority>10</Priority> <TriggerPoint> <ConditionTypeCNF>1</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>03-11-2015 22:28:36.273 UTC Previous log was truncated by 1535 characters 03-11-2015 22:28:36.273 UTC Debug hssconnection.cpp:353: Processing Identity node from HSS XML - sip:[email protected] 03-11-2015 22:28:36.273 UTC Debug hssconnection.cpp:414: Found CCF: pri_ccf_address 03-11-2015 22:28:36.273 UTC Debug scscfsproutlet.cpp:925: Successfully looked up iFCs 03-11-2015 22:28:36.273 UTC Debug aschain.cpp:71: Creating AsChain 0x7f3a140ae050 with 11 IFC and adding to map 03-11-2015 22:28:36.273 UTC Debug aschain.cpp:73: Attached ACR (0x7f3a1406ca40) to chain 03-11-2015 22:28:36.273 UTC Debug scscfsproutlet.cpp:1058: S-CSCF sproutlet transaction 0x7f3a140ab740 linked to AsChain AsChain-orig[0x7f3a140ae050]:1/11 03-11-2015 22:28:36.273 UTC Debug scscfsproutlet.cpp:951: Single Record-Route - initiation of originating handling 03-11-2015 22:28:36.273 UTC Debug sproutletproxy.cpp:325: Creating URI for scscf 03-11-2015 22:28:36.273 UTC Debug sproutletproxy.cpp:329: Add services parameter 03-11-2015 22:28:36.273 UTC Debug sproutletproxy.cpp:337: sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;service=scscf 03-11-2015 22:28:36.273 UTC Info scscfsproutlet.cpp:501: Found served user, so apply services 03-11-2015 22:28:36.273 UTC Debug scscfsproutlet.cpp:1066: Performing originating initiating request processing 03-11-2015 22:28:36.273 UTC Debug ifchandler.cpp:436: SPT class Method: result false 03-11-2015 22:28:36.273 UTC Debug ifchandler.cpp:540: Add to group 0 val false 03-11-2015 22:28:36.273 UTC Debug ifchandler.cpp:436: SPT class Method: result false 03-11-2015 22:28:36.273 UTC Debug ifchandler.cpp:540: Add to group 0 val false 03-11-2015 22:28:36.273 UTC Debug ifchandler.cpp:436: SPT class Method: result false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:571: iFC does not match 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class Method: result false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class SIPHeader: result false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 1 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 1 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:571: iFC does not match 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class Method: result false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class SessionCase: result true 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 1 val true 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 1 val true 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:571: iFC does not match 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class Method: result false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class SessionCase: result true 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 1 val true 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 1 val true 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:571: iFC does not match 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:491: iFC ProfilePartIndicator unreg doesn't match 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class Method: result false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class SessionCase: result false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 1 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 1 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:571: iFC does not match 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class Method: result false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class SessionCase: result false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 1 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 1 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:571: iFC does not match 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class Method: result false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class SessionCase: result false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 1 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 0 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 1 val false 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:571: iFC does not match 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:491: iFC ProfilePartIndicator unreg doesn't match 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:491: iFC ProfilePartIndicator unreg doesn't match 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:436: SPT class Method: result true 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:540: Add to group 0 val true 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:558: Result group 0 val true 03-11-2015 22:28:36.274 UTC Debug ifchandler.cpp:564: iFC matches 03-11-2015 22:28:36.274 UTC Debug aschain.cpp:194: Matched iFC AsChain-orig[0x7f3a140ae050]:11/11 03-11-2015 22:28:36.274 UTC Info ifchandler.cpp:683: Found (triggered) server sip:ip-172-31-18-87.ec2.internal:5060;transport=tcp 03-11-2015 22:28:36.274 UTC Info scscfsproutlet.cpp:1187: Routing to Application Server sip:ip-172-31-18-87.ec2.internal:5060;transport=tcp with ODI token odi_T1ahv2IOsx for AsChain-orig[0x7f3a140ae050]:11/11 03-11-2015 22:28:36.274 UTC Debug sproutletproxy.cpp:1218: Sproutlet send_request 0x7f3a140ac320 03-11-2015 22:28:36.274 UTC Verbose sproutletproxy.cpp:1254: scscf-0x7f3a140ab740 sending Request msg MESSAGE/cseq=5000 (tdta0x7f3a140abd10) on fork 0 03-11-2015 22:28:36.275 UTC Debug sproutletproxy.cpp:397: Started Sproutlet timer, id = 139887420818688, duration = 2.000 03-11-2015 22:28:36.275 UTC Debug sproutletproxy.cpp:1606: Processing actions from sproutlet - 0 responses, 1 requests 03-11-2015 22:28:36.275 UTC Debug sproutletproxy.cpp:1641: Processing request 0x7f3a140abdb8, fork = 0 03-11-2015 22:28:36.275 UTC Debug sproutletproxy.cpp:1759: scscf-0x7f3a140ab740 transmitting request on fork 0 03-11-2015 22:28:36.275 UTC Debug sproutletproxy.cpp:1773: scscf-0x7f3a140ab740 store reference to non-ACK request Request msg MESSAGE/cseq=5000 (tdta0x7f3a140abd10) on fork 0 03-11-2015 22:28:36.275 UTC Debug sproutletproxy.cpp:1598: Removing message 0x7f3a140ac320 => txdata 0x7f3a140abdb8 mapping 03-11-2015 22:28:36.275 UTC Debug sproutletproxy.cpp:102: Find target Sproutlet for request 03-11-2015 22:28:36.275 UTC Debug sproutletproxy.cpp:136: Found next routable URI: sip:ip-172-31-18-87.ec2.internal:5060;transport=tcp;lr 03-11-2015 22:28:36.275 UTC Debug sproutletproxy.cpp:756: No local sproutlet matches request 03-11-2015 22:28:36.275 UTC Debug pjsip: tsx0x7f3a140af Transaction created for Request msg MESSAGE/cseq=5000 (tdta0x7f3a140abd10) 03-11-2015 22:28:36.275 UTC Debug basicproxy.cpp:1604: Added trail identifier 630 to UAC transaction 03-11-2015 22:28:36.275 UTC Debug pjutils.cpp:562: Next hop node is encoded in top route header 03-11-2015 22:28:36.275 UTC Debug sipresolver.cpp:86: SIPResolver::resolve for name ip-172-31-18-87.ec2.internal, port 5060, transport 6, family 2 03-11-2015 22:28:36.275 UTC Debug baseresolver.cpp:503: Attempt to parse ip-172-31-18-87.ec2.internal as IP address 03-11-2015 22:28:36.275 UTC Debug sipresolver.cpp:128: Port is specified 03-11-2015 22:28:36.275 UTC Debug sipresolver.cpp:296: Perform A/AAAA record lookup only, name = ip-172-31-18-87.ec2.internal 03-11-2015 22:28:36.275 UTC Verbose dnscachedresolver.cpp:237: Check cache for ip-172-31-18-87.ec2.internal type 1 03-11-2015 22:28:36.275 UTC Debug dnscachedresolver.cpp:323: Pulling 1 records from cache for ip-172-31-18-87.ec2.internal A 03-11-2015 22:28:36.275 UTC Debug baseresolver.cpp:351: Found 1 A/AAAA records, randomizing 03-11-2015 22:28:36.275 UTC Debug baseresolver.cpp:493: 172.31.18.87:5060 transport 6 is not blacklisted 03-11-2015 22:28:36.275 UTC Debug baseresolver.cpp:372: Added a server, now have 1 of 5 03-11-2015 22:28:36.275 UTC Debug baseresolver.cpp:410: Adding 0 servers from blacklist 03-11-2015 22:28:36.275 UTC Info pjutils.cpp:1008: Resolved destination URI sip:ip-172-31-18-87.ec2.internal:5060;transport=tcp;lr to 1 servers 03-11-2015 22:28:36.275 UTC Debug pjutils.cpp:562: Next hop node is encoded in top route header 03-11-2015 22:28:36.275 UTC Debug basicproxy.cpp:1627: Next hop ip-172-31-18-87.ec2.internal is not a stateless proxy 03-11-2015 22:28:36.275 UTC Debug basicproxy.cpp:1641: Sending request for sip:[email protected];transport=tcp 03-11-2015 22:28:36.275 UTC Debug pjsip: tsx0x7f3a140af Sending Request msg MESSAGE/cseq=5000 (tdta0x7f3a140abd10) in state Null 03-11-2015 22:28:36.275 UTC Debug pjsip: endpoint Request msg MESSAGE/cseq=5000 (tdta0x7f3a140abd10): skipping target resolution because address is already set 03-11-2015 22:28:36.275 UTC Verbose pjsip: tcpc0x7f3a140b TCP client transport created 03-11-2015 22:28:36.275 UTC Verbose pjsip: tcpc0x7f3a140b TCP transport 172.31.45.86:57773 is connecting to 172.31.18.87:5060... 03-11-2015 22:28:36.275 UTC Verbose common_sip_processing.cpp:135: TX 1236 bytes Request msg MESSAGE/cseq=5000 (tdta0x7f3a140abd10) to TCP 172.31.18.87:5060: --start msg-- MESSAGE sip:[email protected];transport=tcp SIP/2.0 Via: SIP/2.0/TCP 172.31.45.86:57773;rport;branch=z9hG4bKPjG-jBnHcbNo0MnqE.cYF22Sfh5iD9y8YJ Route: <sip:ip-172-31-18-87.ec2.internal:5060;transport=tcp;lr> Route: <sip:[email protected]:5054;transport=tcp;lr;orig> Record-Route: <sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Via: SIP/2.0/TCP 172.31.42.105:5054;received=172.31.42.105;branch=z9hG4bK+cb03199300f7bce59301287929c3575f1+sip+1+a64dea99 From: "6505550202" <sip:[email protected]>;tag=172.31.42.105+1+163a93cf+e8453296 P-Charging-Function-Addresses: ccf=pri_ccf_address P-Charging-Vector: icid-value="0dc5634c81eb7de32642b435a4d95ec6";orig-ioi=example.com To: "sc" <sip:[email protected]> Record-Route: <sip:172.31.42.105:5054;lr> P-Asserted-Identity: <sip:[email protected]> Call-ID: 0gQAAC8WAAACBAAALxYAAGbURwtzZGnMldhGyYBaA2c0CVJCDkRfbARVxTSfWvg6@172.31.42.105 CSeq: 5000 MESSAGE Max-Forwards: 67 P-Visited-Network-ID: example.com Session-Expires: 600 P-Served-User: <sip:[email protected]>;sescase=orig;regstate=reg Content-Type: application/vnd.3gpp.sms Content-Length: 34 --end msg-- 03-11-2015 22:28:36.275 UTC Debug pjsip: tsx0x7f3a140af State changed from Null to Calling, event=TX_MSG 03-11-2015 22:28:36.275 UTC Debug basicproxy.cpp:212: tsx0x7f3a140af888 - tu_on_tsx_state UAC, TSX_STATE TX_MSG state=Calling 03-11-2015 22:28:36.275 UTC Debug basicproxy.cpp:1797: tsx0x7f3a140af888 - uac_tsx = 0x7f3a140adf90, uas_tsx = 0x7f3a14013770 03-11-2015 22:28:36.275 UTC Debug basicproxy.cpp:1805: TX_MSG event on current UAC transaction 03-11-2015 22:28:36.275 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f39ec139e78 03-11-2015 22:28:36.275 UTC Debug thread_dispatcher.cpp:199: Request latency = 13400us 03-11-2015 22:28:36.285 UTC Verbose pjsip: tcpc0x7f3a140b TCP transport 172.31.45.86:57773 is connected to 172.31.18.87:5060 03-11-2015 22:28:36.353 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Response msg 202/MESSAGE/cseq=5000 (rdata0x7f3a140b0560) 03-11-2015 22:28:36.353 UTC Verbose common_sip_processing.cpp:119: RX 669 bytes Response msg 202/MESSAGE/cseq=5000 (rdata0x7f3a140b0560) from TCP 172.31.18.87:5060: --start msg-- SIP/2.0 202 Accepted Via: SIP/2.0/TCP 172.31.45.86:57773;rport=57773;branch=z9hG4bKPjG-jBnHcbNo0MnqE.cYF22Sfh5iD9y8YJ Via: SIP/2.0/TCP 172.31.42.105:5054;received=172.31.42.105;branch=z9hG4bK+cb03199300f7bce59301287929c3575f1+sip+1+a64dea99 From: "6505550202" <sip:[email protected]>;tag=172.31.42.105+1+163a93cf+e8453296 To: "sc" <sip:[email protected]>;tag=YMoTrg Call-ID: 0gQAAC8WAAACBAAALxYAAGbURwtzZGnMldhGyYBaA2c0CVJCDkRfbARVxTSfWvg6@172.31.42.105 CSeq: 5000 MESSAGE Record-Route: <sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Record-Route: <sip:172.31.42.105:5054;lr> Content-Length: 0 --end msg-- 03-11-2015 22:28:36.353 UTC Debug pjutils.cpp:1707: Logging SAS Call-ID marker, Call-ID 0gQAAC8WAAACBAAALxYAAGbURwtzZGnMldhGyYBaA2c0CVJCDkRfbARVxTSfWvg6@172.31.42.105 03-11-2015 22:28:36.353 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f39ec02f6b8 for worker threads 03-11-2015 22:28:36.353 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f39ec02f6b8 03-11-2015 22:28:36.353 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 202/MESSAGE/cseq=5000 (rdata0x7f39ec02f6b8) 03-11-2015 22:28:36.353 UTC Debug pjsip: tsx0x7f3a140af Incoming Response msg 202/MESSAGE/cseq=5000 (rdata0x7f39ec02f6b8) in state Calling 03-11-2015 22:28:36.353 UTC Debug pjsip: tsx0x7f3a140af State changed from Calling to Completed, event=RX_MSG 03-11-2015 22:28:36.353 UTC Debug basicproxy.cpp:212: tsx0x7f3a140af888 - tu_on_tsx_state UAC, TSX_STATE RX_MSG state=Completed 03-11-2015 22:28:36.353 UTC Debug basicproxy.cpp:1797: tsx0x7f3a140af888 - uac_tsx = 0x7f3a140adf90, uas_tsx = 0x7f3a14013770 03-11-2015 22:28:36.353 UTC Debug basicproxy.cpp:1805: RX_MSG event on current UAC transaction 03-11-2015 22:28:36.353 UTC Debug basicproxy.cpp:1868: tsx0x7f3a140af888 - RX_MSG on active UAC transaction 03-11-2015 22:28:36.354 UTC Debug basicproxy.cpp:1379: Dissociate UAC transaction 0x7f3a140adf90 for target 0 03-11-2015 22:28:36.354 UTC Verbose sproutletproxy.cpp:1906: Routing Response msg 202/MESSAGE/cseq=5000 (tdta0x7f3a200d7f00) (572 bytes) to upstream sproutlet scscf: --start msg-- SIP/2.0 202 Accepted Via: SIP/2.0/TCP 172.31.42.105:5054;received=172.31.42.105;branch=z9hG4bK+cb03199300f7bce59301287929c3575f1+sip+1+a64dea99 From: "6505550202" <sip:[email protected]>;tag=172.31.42.105+1+163a93cf+e8453296 To: "sc" <sip:[email protected]>;tag=YMoTrg Call-ID: 0gQAAC8WAAACBAAALxYAAGbURwtzZGnMldhGyYBaA2c0CVJCDkRfbARVxTSfWvg6@172.31.42.105 CSeq: 5000 MESSAGE Record-Route: <sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Record-Route: <sip:172.31.42.105:5054;lr> Content-Length: 0 --end msg-- 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1591: Adding message 0x7f3a200d8510 => txdata 0x7f3a200d7fa8 mapping 03-11-2015 22:28:36.354 UTC Verbose sproutletproxy.cpp:1491: scscf-0x7f3a140ab740 received final response Response msg 202/MESSAGE/cseq=5000 (tdta0x7f3a200d7f00) on fork 0, state = Terminated 03-11-2015 22:28:36.354 UTC Info scscfsproutlet.cpp:566: S-CSCF received response 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:405: Cancelled Sproutlet timer, id = 139887420818688 03-11-2015 22:28:36.354 UTC Info pjutils.cpp:2107: Adding new PCFA header 03-11-2015 22:28:36.354 UTC Debug pjutils.cpp:2116: Adding CCF pri_ccf_address to PCFA header 03-11-2015 22:28:36.354 UTC Verbose sproutletproxy.cpp:1281: scscf-0x7f3a140ab740 sending Response msg 202/MESSAGE/cseq=5000 (tdta0x7f3a200d7f00) 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1606: Processing actions from sproutlet - 1 responses, 0 requests 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1681: Aggregating response with status code 202 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1714: Forward 2xx response 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1598: Removing message 0x7f3a200d8510 => txdata 0x7f3a200d7fa8 mapping 03-11-2015 22:28:36.354 UTC Verbose sproutletproxy.cpp:1906: Routing Response msg 202/MESSAGE/cseq=5000 (tdta0x7f3a200d7f00) (624 bytes) to upstream sproutlet icscf: --start msg-- SIP/2.0 202 Accepted Via: SIP/2.0/TCP 172.31.42.105:5054;received=172.31.42.105;branch=z9hG4bK+cb03199300f7bce59301287929c3575f1+sip+1+a64dea99 From: "6505550202" <sip:[email protected]>;tag=172.31.42.105+1+163a93cf+e8453296 To: "sc" <sip:[email protected]>;tag=YMoTrg Call-ID: 0gQAAC8WAAACBAAALxYAAGbURwtzZGnMldhGyYBaA2c0CVJCDkRfbARVxTSfWvg6@172.31.42.105 CSeq: 5000 MESSAGE Record-Route: <sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Record-Route: <sip:172.31.42.105:5054;lr> P-Charging-Function-Addresses: ccf=pri_ccf_address Content-Length: 0 --end msg-- 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1591: Adding message 0x7f3a200d8510 => txdata 0x7f3a200d7fa8 mapping 03-11-2015 22:28:36.354 UTC Verbose sproutletproxy.cpp:1491: icscf-0x7f3a140139c0 received final response Response msg 202/MESSAGE/cseq=5000 (tdta0x7f3a200d7f00) on fork 0, state = Terminated 03-11-2015 22:28:36.354 UTC Debug icscfsproutlet.cpp:777: Check retry conditions for non-REGISTER, S-CSCF responsive 03-11-2015 22:28:36.354 UTC Verbose sproutletproxy.cpp:1281: icscf-0x7f3a140139c0 sending Response msg 202/MESSAGE/cseq=5000 (tdta0x7f3a200d7f00) 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1606: Processing actions from sproutlet - 1 responses, 0 requests 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1681: Aggregating response with status code 202 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1714: Forward 2xx response 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1598: Removing message 0x7f3a200d8510 => txdata 0x7f3a200d7fa8 mapping 03-11-2015 22:28:36.354 UTC Debug pjsip: tsx0x7f3a14002 Sending Response msg 202/MESSAGE/cseq=5000 (tdta0x7f3a200d7f00) in state Trying 03-11-2015 22:28:36.354 UTC Verbose common_sip_processing.cpp:135: TX 624 bytes Response msg 202/MESSAGE/cseq=5000 (tdta0x7f3a200d7f00) to TCP 172.31.42.105:13686: --start msg-- SIP/2.0 202 Accepted Via: SIP/2.0/TCP 172.31.42.105:5054;received=172.31.42.105;branch=z9hG4bK+cb03199300f7bce59301287929c3575f1+sip+1+a64dea99 From: "6505550202" <sip:[email protected]>;tag=172.31.42.105+1+163a93cf+e8453296 To: "sc" <sip:[email protected]>;tag=YMoTrg Call-ID: 0gQAAC8WAAACBAAALxYAAGbURwtzZGnMldhGyYBaA2c0CVJCDkRfbARVxTSfWvg6@172.31.42.105 CSeq: 5000 MESSAGE Record-Route: <sip:ec2-52-3-140-139.compute-1.amazonaws.com:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Record-Route: <sip:172.31.42.105:5054;lr> P-Charging-Function-Addresses: ccf=pri_ccf_address Content-Length: 0 --end msg-- 03-11-2015 22:28:36.354 UTC Debug pjsip: tsx0x7f3a14002 State changed from Trying to Completed, event=TX_MSG 03-11-2015 22:28:36.354 UTC Debug basicproxy.cpp:212: tsx0x7f3a14002498 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Completed 03-11-2015 22:28:36.354 UTC Verbose sproutletproxy.cpp:1673: icscf-0x7f3a140139c0 suiciding 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1028: Destroying SproutletWrapper 0x7f3a14013a00 03-11-2015 22:28:36.354 UTC Debug acr.cpp:83: Sending Null ACR (0x7f3a14002cc0) 03-11-2015 22:28:36.354 UTC Debug acr.cpp:54: Destroyed ACR (0x7f3a14002cc0) 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1037: Free original request Request msg MESSAGE/cseq=5000 (tdta0x7f3a14000fc0) (tdta0x7f3a14000fc0) 03-11-2015 22:28:36.354 UTC Verbose sproutletproxy.cpp:1673: scscf-0x7f3a140ab740 suiciding 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1028: Destroying SproutletWrapper 0x7f3a14088c40 03-11-2015 22:28:36.354 UTC Debug scscfsproutlet.cpp:407: S-CSCF Transaction (0x7f3a140ab740) destroyed 03-11-2015 22:28:36.354 UTC Debug aschain.h:139: AsChain dec ref 0x7f3a140ae050 -> 0 03-11-2015 22:28:36.354 UTC Debug aschain.cpp:79: Destroying AsChain 0x7f3a140ae050 03-11-2015 22:28:36.354 UTC Debug aschain.cpp:97: Sending ACR (0x7f3a1406ca40) from AS chain 03-11-2015 22:28:36.354 UTC Debug acr.cpp:83: Sending Null ACR (0x7f3a1406ca40) 03-11-2015 22:28:36.354 UTC Debug acr.cpp:54: Destroyed ACR (0x7f3a1406ca40) 03-11-2015 22:28:36.354 UTC Debug sproutletproxy.cpp:1037: Free original request Request msg MESSAGE/cseq=5000 (tdta0x7f3a1403c3d0) (tdta0x7f3a1403c3d0) 03-11-2015 22:28:36.354 UTC Debug pjsip: tdta0x7f3a1403 Destroying txdata Request msg MESSAGE/cseq=5000 (tdta0x7f3a1403c3d0) 03-11-2015 22:28:36.354 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f39ec02f6b8 03-11-2015 22:28:36.354 UTC Debug thread_dispatcher.cpp:199: Request latency = 566us 03-11-2015 22:28:36.364 UTC Debug pjsip: tsx0x7f3a140af Timeout timer event 03-11-2015 22:28:36.364 UTC Debug pjsip: tsx0x7f3a140af State changed from Completed to Terminated, event=TIMER 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:212: tsx0x7f3a140af888 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Terminated 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:1797: tsx0x7f3a140af888 - uac_tsx = 0x7f3a140adf90, uas_tsx = (nil) 03-11-2015 22:28:36.364 UTC Debug pjsip: tsx0x7f3a14002 Timeout timer event 03-11-2015 22:28:36.364 UTC Debug pjsip: tsx0x7f3a14002 State changed from Completed to Terminated, event=TIMER 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:212: tsx0x7f3a14002498 - tu_on_tsx_state UAS, TSX_STATE TIMER state=Terminated 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:1252: Report SAS end marker - trail (276) 03-11-2015 22:28:36.364 UTC Debug pjsip: tsx0x7f3a140af Timeout timer event 03-11-2015 22:28:36.364 UTC Debug pjsip: tsx0x7f3a140af State changed from Terminated to Destroyed, event=TIMER 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:212: tsx0x7f3a140af888 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Destroyed 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:1797: tsx0x7f3a140af888 - uac_tsx = 0x7f3a140adf90, uas_tsx = (nil) 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:1969: tsx0x7f3a140af888 - UAC tsx destroyed 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:1521: BasicProxy::UACTsx destructor (0x7f3a140adf90) 03-11-2015 22:28:36.364 UTC Debug pjsip: tdta0x7f3a140a Destroying txdata Request msg MESSAGE/cseq=5000 (tdta0x7f3a140abd10) 03-11-2015 22:28:36.364 UTC Debug pjsip: tsx0x7f3a14002 Timeout timer event 03-11-2015 22:28:36.364 UTC Debug pjsip: tsx0x7f3a14002 State changed from Terminated to Destroyed, event=TIMER 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:212: tsx0x7f3a14002498 - tu_on_tsx_state UAS, TSX_STATE TIMER state=Destroyed 03-11-2015 22:28:36.364 UTC Debug sproutletproxy.cpp:644: tsx0x7f3a14002498 - UAS tsx destroyed 03-11-2015 22:28:36.364 UTC Debug sproutletproxy.cpp:951: Safe for UASTsx to suicide 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:1427: Transaction ((nil)) suiciding 03-11-2015 22:28:36.364 UTC Verbose sproutletproxy.cpp:441: Sproutlet Proxy transaction (0x7f3a14013770) destroyed 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:442: BasicProxy::UASTsx destructor (0x7f3a14013770) 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:457: Disconnect UAC transactions from UAS transaction 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:471: Free original request 03-11-2015 22:28:36.364 UTC Debug pjsip: tdta0x7f3a1400 Destroying txdata Request msg MESSAGE/cseq=5000 (tdta0x7f3a14000fc0) 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:480: Free un-used best response 03-11-2015 22:28:36.364 UTC Debug pjsip: tdta0x7f3a1403 Destroying txdata Response msg 408/MESSAGE/cseq=5000 (tdta0x7f3a1403b3c0) 03-11-2015 22:28:36.364 UTC Debug basicproxy.cpp:501: BasicProxy::UASTsx destructor completed 03-11-2015 22:28:36.364 UTC Debug pjsip: tdta0x7f3a200d Destroying txdata Response msg 202/MESSAGE/cseq=5000 (tdta0x7f3a200d7f00) 03-11-2015 22:28:36.364 UTC Debug pjsip: tsx0x7f3a14002 Transaction destroyed! 03-11-2015 22:28:36.364 UTC Debug pjsip: tsx0x7f3a140af Transaction destroyed! 03-11-2015 22:28:36.656 UTC Verbose pjsip: tcps0x7f39ec27 TCP connection closed 03-11-2015 22:28:36.656 UTC Debug connection_tracker.cpp:91: Connection 0x7f39ec273608 has been destroyed 03-11-2015 22:28:36.656 UTC Verbose pjsip: tcps0x7f39ec27 TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 03-11-2015 22:28:36.672 UTC Verbose pjsip: tcplis:5052 TCP listener 172.31.45.86:5052: got incoming TCP connection from 172.31.45.86:47454, sock=1393 03-11-2015 22:28:36.672 UTC Verbose pjsip: tcps0x7f39ec27 TCP server transport created 03-11-2015 22:28:36.673 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=29117 (rdata0x7f39ec273940) 03-11-2015 22:28:36.673 UTC Verbose common_sip_processing.cpp:119: RX 347 bytes Request msg OPTIONS/cseq=29117 (rdata0x7f39ec273940) from TCP 172.31.45.86:47454: --start msg-- OPTIONS sip:[email protected]:5052 SIP/2.0 Via: SIP/2.0/TCP 172.31.45.86;rport;branch=z9hG4bK-29117 Max-Forwards: 2 To: <sip:[email protected]:5052> From: poll-sip <sip:[email protected]>;tag=29117 Call-ID: poll-sip-29117 CSeq: 29117 OPTIONS Contact: <sip:172.31.45.86> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 03-11-2015 22:28:36.673 UTC Debug common_sip_processing.cpp:211: Skipping SAS logging for OPTIONS request 03-11-2015 22:28:36.673 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f39ec02f6b8 for worker threads 03-11-2015 22:28:36.673 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f39ec02f6b8 03-11-2015 22:28:36.673 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=29117 (rdata0x7f39ec02f6b8) 03-11-2015 22:28:36.673 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=29117 (tdta0x7f3a1c086680) created 03-11-2015 22:28:36.673 UTC Verbose common_sip_processing.cpp:135: TX 277 bytes Response msg 200/OPTIONS/cseq=29117 (tdta0x7f3a1c086680) to TCP 172.31.45.86:47454: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP 172.31.45.86;rport=47454;received=172.31.45.86;branch=z9hG4bK-29117 Call-ID: poll-sip-29117 From: "poll-sip" <sip:[email protected]>;tag=29117 To: <sip:[email protected]>;tag=z9hG4bK-29117 CSeq: 29117 OPTIONS Content-Length: 0 --end msg-- 03-11-2015 22:28:36.673 UTC Debug common_sip_processing.cpp:253: Skipping SAS logging for OPTIONS response 03-11-2015 22:28:36.673 UTC Debug pjsip: tdta0x7f3a1c08 Destroying txdata Response msg 200/OPTIONS/cseq=29117 (tdta0x7f3a1c086680) 03-11-2015 22:28:36.673 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f39ec02f6b8 03-11-2015 22:28:36.673 UTC Debug thread_dispatcher.cpp:199: Request latency = 205us 03-11-2015 22:28:37.673 UTC Verbose pjsip: tcps0x7f39ec27 TCP connection closed 03-11-2015 22:28:37.673 UTC Debug connection_tracker.cpp:91: Connection 0x7f39ec273608 has been destroyed 03-11-2015 22:28:37.673 UTC Verbose pjsip: tcps0x7f39ec27 TCP transport destroyed with reason 70016: End of file (PJ_EEOF)
_______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
