Hi Ellie, Yes you're right, it was in homestead not sprout.
I installed the homestead-dbg package and tried the same test again. Oddly, this time there was no crash at all. log attached. It looks fine now. ------------------------------------------------------------------------------------------ Steve Yeoman, Software Engineer, http://www.opencloud.com Tel: +1 647 342 6183, Mobile: +1 416 662 4490 On 24 November 2015 at 13:30, Eleanor Merry <[email protected]> wrote: > Hi Steve, > > > > In the attached logs it looks like Homestead is crashing, not Sprout. Is > that what you’re seeing? > > > > Can you please install the homestead-dbg package and send me the trace > when this crashes? This will generate better diagnostics. > > > > Ellie > > > > *From:* Clearwater [mailto:[email protected]] > *On Behalf Of *Steve Yeoman > *Sent:* 24 November 2015 18:21 > *To:* [email protected] > *Subject:* [Clearwater] sprout crash for SIP message sent from IPSMGW > > > > Hi, > > > > I noticed that Sprout crashes if an IPSMGW sends a Mobile Terminating SIP > Message with the SCSCF address as the Request URI. Log attached. > > > > The message is not 100% correct according to 3GPP TS 24.341 (Table B 6 1), > as it has the Request-URI and Route headers switched. Sprout works fine if > the Request-URI is the destination and the Route is the sprout address. So > it's an edge case. > > > > Presumably the crash should be handled better though. It's possible that > messages like this will be received by sprout. > > > > cheers > > Steve > > > > > > > > > > > > > > > > ------------------------------------------------------------------------------------------ > > Steve Yeoman, Software Engineer, http://www.opencloud.com > > Tel: +1 647 342 6183, Mobile: +1 416 662 4490 > > >
24-11-2015 18:47:35.699 UTC Debug baseresolver.cpp:353: Found 1 A/AAAA records, randomizing 24-11-2015 18:47:35.699 UTC Debug baseresolver.cpp:495: 172.31.42.68:3868 transport 132 is not blacklisted 24-11-2015 18:47:35.699 UTC Debug baseresolver.cpp:374: Added a server, now have 1 of 2 24-11-2015 18:47:35.699 UTC Debug baseresolver.cpp:412: Adding 0 servers from blacklist ==> sprout/sprout_20151124T180000Z.txt <== 24-11-2015 18:47:39.792 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg MESSAGE/cseq=792181 (rdata0x2713128) 24-11-2015 18:47:39.792 UTC Verbose common_sip_processing.cpp:119: RX 723 bytes Request msg MESSAGE/cseq=792181 (rdata0x2713128) from UDP 172.31.12.69:5060: --start msg-- MESSAGE sip:172.31.45.86:5054 SIP/2.0 From: <sip:[email protected]:5060>;oc-node=101;lr;transport=udp;tag=XPNnSA To: <sip:[email protected]> Call-ID: RIQNTdjsjQE1KsyoPjRUsA CSeq: 792181 MESSAGE Max-Forwards: 70 Via: SIP/2.0/UDP 172.31.12.69:5060;oc-node=101;rport;branch=z9hG4bK4tNUos9oIrPfUeMs5zk3eA;ext, SIP/2.0/UDP 172.31.12.69:5060;oc-node=101;rport;branch=z9hG4bKmHL2YHajQ7GlLZusptvlAQ P-Asserted-Identity: <sip:[email protected]:5060> Content-Type: application/vnd.3gpp.sms Content-Length: 48 Accept-Contact: *;+g.3gpp.smsip;require;explicit Request-Disposition: no-fork Route: <sip:[email protected]> VPU --end msg-- 24-11-2015 18:47:39.792 UTC Debug pjutils.cpp:1707: Logging SAS Call-ID marker, Call-ID RIQNTdjsjQE1KsyoPjRUsA 24-11-2015 18:47:39.792 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f33003e8208 for worker threads 24-11-2015 18:47:39.792 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f33003e8208 24-11-2015 18:47:39.792 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg MESSAGE/cseq=792181 (rdata0x7f33003e8208) 24-11-2015 18:47:39.792 UTC Debug authentication.cpp:666: Authentication module invoked 24-11-2015 18:47:39.792 UTC Debug authentication.cpp:676: Request does not need authentication 24-11-2015 18:47:39.792 UTC Debug basicproxy.cpp:91: Process MESSAGE request 24-11-2015 18:47:39.792 UTC Verbose sproutletproxy.cpp:425: Sproutlet Proxy transaction (0x7f32fc43a350) created 24-11-2015 18:47:39.792 UTC Debug basicproxy.cpp:1242: Report SAS start marker - trail (985) 24-11-2015 18:47:39.792 UTC Debug pjutils.cpp:744: Cloned Request msg MESSAGE/cseq=792181 (rdata0x7f33003e8208) to tdta0x7f32fc438390 24-11-2015 18:47:39.792 UTC Debug pjsip: tsx0x7f32fc49c Transaction created for Request msg MESSAGE/cseq=792181 (rdata0x7f33003e8208) 24-11-2015 18:47:39.792 UTC Debug pjsip: tsx0x7f32fc49c Incoming Request msg MESSAGE/cseq=792181 (rdata0x7f33003e8208) in state Null 24-11-2015 18:47:39.792 UTC Debug pjsip: tsx0x7f32fc49c State changed from Null to Trying, event=RX_MSG 24-11-2015 18:47:39.792 UTC Debug basicproxy.cpp:212: tsx0x7f32fc49c378 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying 24-11-2015 18:47:39.792 UTC Debug pjsip: endpoint Response msg 408/MESSAGE/cseq=792181 (tdta0x7f32fc49cae0) created 24-11-2015 18:47:39.792 UTC Debug sproutletproxy.cpp:102: Find target Sproutlet for request 24-11-2015 18:47:39.792 UTC Debug sproutletproxy.cpp:136: Found next routable URI: sip:[email protected] 24-11-2015 18:47:39.792 UTC Debug sproutletproxy.cpp:261: Found user - +6505550202 24-11-2015 18:47:39.792 UTC Debug sproutletproxy.cpp:261: Found user - +6505550202 24-11-2015 18:47:39.793 UTC Debug sproutletproxy.cpp:261: Found user - +6505550202 24-11-2015 18:47:39.793 UTC Debug sproutletproxy.cpp:261: Found user - +6505550202 24-11-2015 18:47:39.793 UTC Debug sproutletproxy.cpp:175: No Sproutlet found using service name or host 24-11-2015 18:47:39.793 UTC Debug sproutletproxy.cpp:180: Find default service for port 5054 24-11-2015 18:47:39.793 UTC Debug scscfsproutlet.cpp:401: S-CSCF Transaction (0x7f32fc439e50) created 24-11-2015 18:47:39.793 UTC Verbose sproutletproxy.cpp:1022: Created Sproutlet scscf-0x7f32fc439e50 for Request msg MESSAGE/cseq=792181 (tdta0x7f32fc438390) 24-11-2015 18:47:39.793 UTC Verbose sproutletproxy.cpp:1906: Routing Request msg MESSAGE/cseq=792181 (tdta0x7f32fc438390) (753 bytes) to downstream sproutlet scscf: --start msg-- MESSAGE sip:172.31.45.86:5054 SIP/2.0 From: <sip:[email protected]>;tag=XPNnSA;oc-node=101;lr;transport=udp To: <sip:[email protected]> Call-ID: RIQNTdjsjQE1KsyoPjRUsA CSeq: 792181 MESSAGE Max-Forwards: 70 Via: SIP/2.0/UDP 172.31.12.69:5060;rport=5060;received=172.31.12.69;branch=z9hG4bK4tNUos9oIrPfUeMs5zk3eA;oc-node=101;ext Via: SIP/2.0/UDP 172.31.12.69:5060;rport;branch=z9hG4bKmHL2YHajQ7GlLZusptvlAQ;oc-node=101 P-Asserted-Identity: <sip:[email protected]:5060> Accept-Contact: *;+g.3gpp.smsip;explicit;require Request-Disposition: no-fork Route: <sip:[email protected]> Content-Type: application/vnd.3gpp.sms Content-Length: 48 VPU --end msg-- 24-11-2015 18:47:39.793 UTC Debug pjutils.cpp:761: Cloned tdta0x7f32fc438390 to tdta0x7f32fc49daf0 24-11-2015 18:47:39.793 UTC Debug sproutletproxy.cpp:1083: Remove top Route header Route: <sip:[email protected]> 24-11-2015 18:47:39.793 UTC Debug sproutletproxy.cpp:1591: Adding message 0x7f32fc49e100 => txdata 0x7f32fc49db98 mapping 24-11-2015 18:47:39.793 UTC Verbose sproutletproxy.cpp:1444: scscf-0x7f32fc439e50 pass initial request Request msg MESSAGE/cseq=792181 (tdta0x7f32fc49daf0) to Sproutlet 24-11-2015 18:47:39.793 UTC Info scscfsproutlet.cpp:443: S-CSCF received initial request 24-11-2015 18:47:39.793 UTC Debug pjutils.cpp:2330: Adding session expires header with default value 24-11-2015 18:47:39.793 UTC Debug scscfsproutlet.cpp:733: Route header references this system 24-11-2015 18:47:39.793 UTC Debug scscfsproutlet.cpp:786: No ODI token, or invalid ODI token, on request, and no P-Charging-Vector header (so can't log ICID for correlation) 24-11-2015 18:47:39.793 UTC Debug scscfsproutlet.cpp:792: Got our Route header, session case term, OD=None 24-11-2015 18:47:39.793 UTC Debug pjutils.cpp:257: aor_from_uri converted sip:172.31.45.86 to sip:172.31.45.86 24-11-2015 18:47:39.793 UTC Debug acr.cpp:49: Created ACR (0x7f32fc1c0660) 24-11-2015 18:47:39.793 UTC Debug scscfsproutlet.cpp:921: Looking up iFCs for sip:172.31.45.86 for new AS chain 24-11-2015 18:47:39.793 UTC Debug hssconnection.cpp:567: Making Homestead request for /impu/sip%3A172.31.45.86/reg-data 24-11-2015 18:47:39.793 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host ec2-52-3-140-139.compute-1.amazonaws.com, port 8888, family 2 24-11-2015 18:47:39.793 UTC Debug baseresolver.cpp:503: Attempt to parse ec2-52-3-140-139.compute-1.amazonaws.com as IP address 24-11-2015 18:47:39.793 UTC Verbose dnscachedresolver.cpp:237: Check cache for ec2-52-3-140-139.compute-1.amazonaws.com type 1 24-11-2015 18:47:39.793 UTC Debug dnscachedresolver.cpp:252: Expired entry found in cache 24-11-2015 18:47:39.793 UTC Debug dnscachedresolver.cpp:279: Create and execute DNS query transaction 24-11-2015 18:47:39.793 UTC Debug dnscachedresolver.cpp:291: Wait for query responses 24-11-2015 18:47:39.795 UTC Debug dnscachedresolver.cpp:432: Received DNS response for ec2-52-3-140-139.compute-1.amazonaws.com type A 24-11-2015 18:47:39.795 UTC Debug dnsparser.cpp:90: Parsing DNS message 000000: be918180 00010001 00000000 10656332 2d35322d 332d3134 302d3133 3909636f .... .... .... .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 24-11-2015 18:47:39.795 UTC Debug dnsparser.cpp:95: Parsing header at offset 0x0 24-11-2015 18:47:39.795 UTC Debug dnsparser.cpp:98: 1 questions, 1 answers, 0 authorities, 0 additional records 24-11-2015 18:47:39.795 UTC Debug dnsparser.cpp:103: Parsing question 1 at offset 0xc 24-11-2015 18:47:39.795 UTC Debug dnsparser.cpp:229: Parsed domain name = ec2-52-3-140-139.compute-1.amazonaws.com, encoded length = 42 24-11-2015 18:47:39.795 UTC Debug dnsparser.cpp:112: Parsing answer 1 at offset 0x3a 24-11-2015 18:47:39.795 UTC Debug dnsparser.cpp:229: Parsed domain name = ec2-52-3-140-139.compute-1.amazonaws.com, encoded length = 2 24-11-2015 18:47:39.795 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 24-11-2015 18:47:39.795 UTC Debug dnsparser.cpp:287: Parse A record RDATA 24-11-2015 18:47:39.795 UTC Debug dnsparser.cpp:142: Answer records ec2-52-3-140-139.compute-1.amazonaws.com 60 IN A 172.31.45.86 24-11-2015 18:47:39.795 UTC Debug dnsparser.cpp:143: Authority records 24-11-2015 18:47:39.795 UTC Debug dnsparser.cpp:144: Additional records 24-11-2015 18:47:39.795 UTC Debug dnscachedresolver.cpp:701: Adding record to cache entry, TTL=60, expiry=1448390919 24-11-2015 18:47:39.795 UTC Debug dnscachedresolver.cpp:705: Update cache entry expiry to 1448390919 24-11-2015 18:47:39.795 UTC Debug dnscachedresolver.cpp:647: Adding ec2-52-3-140-139.compute-1.amazonaws.com to cache expiry list with deletion time of 1448391219 24-11-2015 18:47:39.795 UTC Debug dnscachedresolver.cpp:295: Received all query responses 24-11-2015 18:47:39.795 UTC Debug dnscachedresolver.cpp:323: Pulling 1 records from cache for ec2-52-3-140-139.compute-1.amazonaws.com A 24-11-2015 18:47:39.795 UTC Debug baseresolver.cpp:351: Found 1 A/AAAA records, randomizing 24-11-2015 18:47:39.795 UTC Debug baseresolver.cpp:493: 172.31.45.86:8888 transport 6 is not blacklisted 24-11-2015 18:47:39.795 UTC Debug baseresolver.cpp:372: Added a server, now have 1 of 5 24-11-2015 18:47:39.795 UTC Debug baseresolver.cpp:410: Adding 0 servers from blacklist 24-11-2015 18:47:39.795 UTC Debug httpconnection.cpp:595: Sending HTTP request : http://ec2-52-3-140-139.compute-1.amazonaws.com:8888/impu/sip%3A172.31.45.86/reg-data (trying 172.31.45.86) on new connection ==> homestead/homestead_20151124T180000Z.txt <== 24-11-2015 18:47:39.796 UTC Verbose httpstack.cpp:286: Process request for URL /impu/sip%3A172.31.45.86/reg-data, args (null) 24-11-2015 18:47:39.796 UTC Debug handlers.cpp:984: Parsed HTTP request: private ID , public ID sip:172.31.45.86 24-11-2015 18:47:39.796 UTC Debug handlers.cpp:928: Determining request type from '{"reqtype": "call"}' 24-11-2015 18:47:39.796 UTC Debug handlers.cpp:972: New value of _type is 2 24-11-2015 18:47:39.796 UTC Debug handlers.cpp:1022: Try to find IMS Subscription information in the cache 24-11-2015 18:47:39.796 UTC Debug cassandra_store.cpp:284: Getting thread-local Client 24-11-2015 18:47:39.796 UTC Debug cassandra_store.cpp:129: Generated Cassandra timestamp 1448390859796221 24-11-2015 18:47:39.796 UTC Debug cache.cpp:350: Issuing get for key sip:172.31.45.86 24-11-2015 18:47:39.796 UTC Debug cassandra_store.cpp:745: Failed TWO read for get_row. Try ONE 24-11-2015 18:47:39.797 UTC Debug communicationmonitor.cpp:78: Check communication monitor state for alarm 1501 24-11-2015 18:47:39.797 UTC Debug communicationmonitor.cpp:88: Alarm currently clear - successful attempts 1, failures 0 24-11-2015 18:47:39.797 UTC Debug handlers.cpp:1051: Got IMS subscription from cache 24-11-2015 18:47:39.797 UTC Debug handlers.cpp:1067: TTL for this database record is 0, IMS Subscription XML is empty, registration state is NOT_REGISTERED, and the charging addresses are empty 24-11-2015 18:47:39.797 UTC Debug handlers.cpp:1171: Handling call 24-11-2015 18:47:39.797 UTC Debug handlers.cpp:1178: Moving to unregistered state 24-11-2015 18:47:39.797 UTC Debug cx.cpp:618: Building Server-Assignment request for /sip:172.31.45.86 24-11-2015 18:47:39.797 UTC Debug freeDiameter: No Session-Id AVP found in message 0x7f8bac00afb0 24-11-2015 18:47:39.797 UTC Verbose diameterstack.cpp:1423: Sending Diameter message of type 301 on transaction 0x7f8bac00fb80 with timeout 200 24-11-2015 18:47:39.797 UTC Debug diameterstack.cpp:397: Routing out callback from freeDiameter 24-11-2015 18:47:39.797 UTC Debug realmmanager.cpp:189: freeDiameter routing score for candidate 172.31.42.68 is changing from 13 to 12 24-11-2015 18:47:39.797 UTC Debug freeDiameter: GOING TO SEND TO '172.31.42.68': '3GPP/Server-Assignment-Request'16777216/301 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:601/l:12,V:10415/C:602/l:12,V:10415/C:614/l:16,V:10415/C:624/l:16} 24-11-2015 18:47:39.797 UTC Debug diameterstack.cpp:905: Processing a sent diameter message 24-11-2015 18:47:39.797 UTC Debug diameterstack.cpp:907: Got existing trail ID: 101 24-11-2015 18:47:39.798 UTC Debug diameterstack.cpp:965: Raising correlating marker with diameter session ID = ec2-52-3-140-139.compute-1.amazonaws.com;1448390059;17 24-11-2015 18:47:39.798 UTC Debug freeDiameter: Sending 400b data on connection {----} TCP,#637->172.31.42.68(3868) 24-11-2015 18:47:39.800 UTC Debug freeDiameter: 'STATE_OPEN' <-- 'FDEVP_CNX_MSG_RECV' (0x7f8bcc00b160,216) '172.31.42.68' 24-11-2015 18:47:39.800 UTC Debug diameterstack.cpp:885: Processing a received diameter message 24-11-2015 18:47:39.800 UTC Debug diameterstack.cpp:898: Got existing trail ID: 101 24-11-2015 18:47:39.800 UTC Debug diameterstack.cpp:965: Raising correlating marker with diameter session ID = ec2-52-3-140-139.compute-1.amazonaws.com;1448390059;17 24-11-2015 18:47:39.800 UTC Debug freeDiameter: Peer timeout reset to 30 seconds (+/- 2) 24-11-2015 18:47:39.800 UTC Debug freeDiameter: '172.31.42.68' in state 'STATE_OPEN' waiting for next event. 24-11-2015 18:47:39.800 UTC Debug freeDiameter: Iterating on rules of AVP: 'Vendor-Specific-Application-Id'. 24-11-2015 18:47:39.800 UTC Debug freeDiameter: Iterating on rules of AVP: 'Experimental-Result'. 24-11-2015 18:47:39.800 UTC Debug freeDiameter: Iterating on rules of COMMAND: '3GPP/Server-Assignment-Answer'. 24-11-2015 18:47:39.800 UTC Debug freeDiameter: Calling callback registered when query was sent (0x459370, 0x7f8bac00fb80) 24-11-2015 18:47:39.800 UTC Verbose diameterstack.cpp:1093: Got Diameter response of type 301 - calling callback on transaction 0x7f8bac00fb80 24-11-2015 18:47:39.800 UTC Debug communicationmonitor.cpp:78: Check communication monitor state for alarm 1502 24-11-2015 18:47:39.800 UTC Debug communicationmonitor.cpp:88: Alarm currently clear - successful attempts 1, failures 0 24-11-2015 18:47:39.800 UTC Debug handlers.cpp:1532: Received Server-Assignment answer with result code 0 24-11-2015 18:47:39.800 UTC Info handlers.cpp:1594: Server-Assignment answer with result code 0 - reject 24-11-2015 18:47:39.800 UTC Verbose httpstack.cpp:69: Sending response 500 to request for URL /impu/sip%3A172.31.45.86/reg-data, args (null) ==> homestead/access_20151124T180000Z.txt <== 24-11-2015 18:47:39.800 UTC 500 PUT /impu/sip%3A172.31.45.86/reg-data 0.004830 seconds ==> sprout/sprout_20151124T180000Z.txt <== 24-11-2015 18:47:39.800 UTC Debug httpconnection.cpp:896: Received header http/1.1500internalservererror with value 24-11-2015 18:47:39.801 UTC Debug httpconnection.cpp:896: Received header content-length with value 0 24-11-2015 18:47:39.801 UTC Debug httpconnection.cpp:896: Received header with value 24-11-2015 18:47:39.801 UTC Debug httpconnection.cpp:610: Received HTTP response: status=500, doc= 24-11-2015 18:47:39.801 UTC Error httpconnection.cpp:743: cURL failure with cURL error code 0 (see man 3 libcurl-errors) and HTTP error code 500 24-11-2015 18:47:39.801 UTC Error hssconnection.cpp:593: Could not get subscriber data from HSS 24-11-2015 18:47:39.801 UTC Debug scscfsproutlet.cpp:930: Failed to retrieve ServiceProfile for sip:172.31.45.86 24-11-2015 18:47:39.801 UTC Info scscfsproutlet.cpp:478: Failed to determine served user for request, reject with 404 status code 24-11-2015 18:47:39.801 UTC Debug sproutletproxy.cpp:1591: Adding message 0x7f32fc4a1750 => txdata 0x7f32fc4a11e8 mapping 24-11-2015 18:47:39.801 UTC Verbose sproutletproxy.cpp:1281: scscf-0x7f32fc439e50 sending Response msg 404/MESSAGE/cseq=792181 (tdta0x7f32fc4a1140) 24-11-2015 18:47:39.801 UTC Debug sproutletproxy.cpp:1598: Removing message 0x7f32fc49e100 => txdata 0x7f32fc49db98 mapping 24-11-2015 18:47:39.801 UTC Debug sproutletproxy.cpp:1358: Free message tdta0x7f32fc49daf0 24-11-2015 18:47:39.801 UTC Debug pjsip: tdta0x7f32fc49 Destroying txdata Request msg MESSAGE/cseq=792181 (tdta0x7f32fc49daf0) 24-11-2015 18:47:39.801 UTC Debug sproutletproxy.cpp:1606: Processing actions from sproutlet - 1 responses, 0 requests 24-11-2015 18:47:39.801 UTC Debug sproutletproxy.cpp:1681: Aggregating response with status code 404 24-11-2015 18:47:39.801 UTC Debug sproutletproxy.cpp:1731: 3xx/4xx/5xx/6xx response 24-11-2015 18:47:39.801 UTC Debug sproutletproxy.cpp:1735: Best 3xx/4xx/5xx/6xx response so far 24-11-2015 18:47:39.801 UTC Debug sproutletproxy.cpp:1628: All UAC responded 24-11-2015 18:47:39.801 UTC Debug sproutletproxy.cpp:1598: Removing message 0x7f32fc4a1750 => txdata 0x7f32fc4a11e8 mapping 24-11-2015 18:47:39.801 UTC Debug pjsip: tsx0x7f32fc49c Sending Response msg 404/MESSAGE/cseq=792181 (tdta0x7f32fc4a1140) in state Trying 24-11-2015 18:47:39.801 UTC Verbose common_sip_processing.cpp:135: TX 473 bytes Response msg 404/MESSAGE/cseq=792181 (tdta0x7f32fc4a1140) to UDP 172.31.12.69:5060: --start msg-- SIP/2.0 404 Not Found Via: SIP/2.0/UDP 172.31.12.69:5060;rport=5060;received=172.31.12.69;branch=z9hG4bK4tNUos9oIrPfUeMs5zk3eA;oc-node=101;ext Via: SIP/2.0/UDP 172.31.12.69:5060;rport;branch=z9hG4bKmHL2YHajQ7GlLZusptvlAQ;oc-node=101 Call-ID: RIQNTdjsjQE1KsyoPjRUsA From: <sip:[email protected]>;tag=XPNnSA;oc-node=101;lr;transport=udp To: <sip:[email protected]>;tag=z9hG4bK4tNUos9oIrPfUeMs5zk3eA CSeq: 792181 MESSAGE Content-Length: 0 --end msg-- 24-11-2015 18:47:39.801 UTC Debug pjsip: tsx0x7f32fc49c State changed from Trying to Completed, event=TX_MSG 24-11-2015 18:47:39.801 UTC Debug basicproxy.cpp:212: tsx0x7f32fc49c378 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Completed 24-11-2015 18:47:39.801 UTC Verbose sproutletproxy.cpp:1673: scscf-0x7f32fc439e50 suiciding 24-11-2015 18:47:39.801 UTC Debug sproutletproxy.cpp:1028: Destroying SproutletWrapper 0x7f32fc284bf0 24-11-2015 18:47:39.801 UTC Debug scscfsproutlet.cpp:407: S-CSCF Transaction (0x7f32fc439e50) destroyed 24-11-2015 18:47:39.801 UTC Debug acr.cpp:83: Sending Null ACR (0x7f32fc1c0660) 24-11-2015 18:47:39.801 UTC Debug acr.cpp:54: Destroyed ACR (0x7f32fc1c0660) 24-11-2015 18:47:39.801 UTC Debug sproutletproxy.cpp:1037: Free original request Request msg MESSAGE/cseq=792181 (tdta0x7f32fc438390) (tdta0x7f32fc438390) 24-11-2015 18:47:39.801 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f33003e8208 24-11-2015 18:47:39.801 UTC Debug thread_dispatcher.cpp:199: Request latency = 8914us ==> homestead/homestead_20151124T180000Z.txt <== 24-11-2015 18:47:40.699 UTC Debug diameterresolver.cpp:91: DiameterResolver::resolve for realm , host hss-instance, family 2 24-11-2015 18:47:40.699 UTC Debug baseresolver.cpp:505: Attempt to parse hss-instance as IP address 24-11-2015 18:47:40.699 UTC Debug dnscachedresolver.cpp:664: Removing record for hss-instance (type 1, expiry time 1448390855) from the expiry list 24-11-2015 18:47:40.699 UTC Verbose dnscachedresolver.cpp:237: Check cache for hss-instance type 1 24-11-2015 18:47:40.699 UTC Debug dnscachedresolver.cpp:252: Expired entry found in cache 24-11-2015 18:47:40.699 UTC Debug dnscachedresolver.cpp:279: Create and execute DNS query transaction 24-11-2015 18:47:40.699 UTC Debug dnscachedresolver.cpp:291: Wait for query responses 24-11-2015 18:47:40.699 UTC Debug dnscachedresolver.cpp:432: Received DNS response for hss-instance type A 24-11-2015 18:47:40.699 UTC Debug dnsparser.cpp:90: Parsing DNS message 000000: b3968580 00010001 00000000 0c687373 2d696e73 74616e63 65000001 0001c00c .... .... .... .hss -ins tanc e... .... 000020: 00010001 00000000 0004ac1f 2a44 .... .... .... *D 24-11-2015 18:47:40.699 UTC Debug dnsparser.cpp:95: Parsing header at offset 0x0 24-11-2015 18:47:40.699 UTC Debug dnsparser.cpp:98: 1 questions, 1 answers, 0 authorities, 0 additional records 24-11-2015 18:47:40.699 UTC Debug dnsparser.cpp:103: Parsing question 1 at offset 0xc 24-11-2015 18:47:40.699 UTC Debug dnsparser.cpp:229: Parsed domain name = hss-instance, encoded length = 14 24-11-2015 18:47:40.699 UTC Debug dnsparser.cpp:112: Parsing answer 1 at offset 0x1e 24-11-2015 18:47:40.699 UTC Debug dnsparser.cpp:229: Parsed domain name = hss-instance, encoded length = 2 24-11-2015 18:47:40.699 UTC Debug dnsparser.cpp:282: Resource Record NAME=hss-instance TYPE=A CLASS=IN TTL=0 RDLENGTH=4 24-11-2015 18:47:40.699 UTC Debug dnsparser.cpp:287: Parse A record RDATA 24-11-2015 18:47:40.699 UTC Debug dnsparser.cpp:142: Answer records hss-instance 0 IN A 172.31.42.68 24-11-2015 18:47:40.699 UTC Debug dnsparser.cpp:143: Authority records 24-11-2015 18:47:40.699 UTC Debug dnsparser.cpp:144: Additional records 24-11-2015 18:47:40.699 UTC Debug dnscachedresolver.cpp:701: Adding record to cache entry, TTL=0, expiry=1448390860 24-11-2015 18:47:40.699 UTC Debug dnscachedresolver.cpp:705: Update cache entry expiry to 1448390860 24-11-2015 18:47:40.699 UTC Debug dnscachedresolver.cpp:647: Adding hss-instance to cache expiry list with deletion time of 1448391160 24-11-2015 18:47:40.699 UTC Debug dnscachedresolver.cpp:295: Received all query responses 24-11-2015 18:47:40.699 UTC Debug dnscachedresolver.cpp:323: Pulling 1 records from cache for hss-instance A 24-11-2015 18:47:40.699 UTC Debug baseresolver.cpp:353: Found 1 A/AAAA records, randomizing 24-11-2015 18:47:40.699 UTC Debug baseresolver.cpp:495: 172.31.42.68:3868 transport 132 is not blacklisted 24-11-2015 18:47:40.699 UTC Debug baseresolver.cpp:374: Added a server, now have 1 of 2 24-11-2015 18:47:40.699 UTC Debug baseresolver.cpp:412: Adding 0 servers from blacklist
_______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
