[Jun 25 00:45:38] VERBOSE[10286] logger.c: <--- SIP read from 213.131.156.66:5060 ---> INVITE sip:0303123456@123.456.789.123 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 From: "0705123456";tag=d4ff9921 To: "0303123456" Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 INVITE Record-Route: X-Ecan: On Content-Length: 261 User-Agent: LEICA-1.8.18 Supported: timer Content-Type: application/sdp Allow: INVITE, ACK, BYE, CANCEL Min-SE: 7200 Session-Expires: 7200;refresher=uac Contact: Max-Forwards: 68 v=0 o=- 2093054175 0 IN IP4 213.50.89.4 s=- c=IN IP4 213.50.89.4 t=0 0 m=audio 4920 RTP/AVP 8 18 0 101 a=fmtp:18 annexb=yes a=fmtp:101 0-15 a=T38MaxBitRate:14400 a=rtpmap:101 telephone-event/8000 a=T38FaxVersion:0 a=sendrecv m=image 4922 udptl t38 <-------------> [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 0: INVITE sip:0303123456@123.456.789.123 SIP/2.0 (43) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 1: Record-Route: (60) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 2: Record-Route: (79) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21 (67) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 4: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g (142) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 5: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 6: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 7: To: "0303123456" (60) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 8: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 9: CSeq: 1 INVITE (14) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 10: Record-Route: (39) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 11: X-Ecan: On (10) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 12: Content-Length: 261 (19) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 13: User-Agent: LEICA-1.8.18 (24) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 14: Supported: timer (16) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 15: Content-Type: application/sdp (29) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 16: Allow: INVITE, ACK, BYE, CANCEL (31) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 17: Min-SE: 7200 (12) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 18: Session-Expires: 7200;refresher=uac (35) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 19: Contact: (47) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 20: Max-Forwards: 68 (16) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 21: (0) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: v=0 (3) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: o=- 2093054175 0 IN IP4 213.50.89.4 (35) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: s=- (3) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: c=IN IP4 213.50.89.4 (20) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: t=0 0 (5) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: m=audio 4920 RTP/AVP 8 18 0 101 (31) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=fmtp:18 annexb=yes (20) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=fmtp:101 0-15 (15) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=T38MaxBitRate:14400 (21) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=T38FaxVersion:0 (17) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=sendrecv (10) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: m=image 4922 udptl t38 (22) [Jun 25 00:45:38] VERBOSE[10286] logger.c: --- (21 headers 13 lines) --- [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Setting NAT on RTP to Off [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Allocating new SIP dialog for MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. - INVITE (With RTP) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Begin: parsing SIP "Supported: timer" [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Found SIP option: -timer- [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Matched SIP option: timer [Jun 25 00:45:38] VERBOSE[10286] logger.c: Sending to 213.131.156.66 : 5060 (no NAT) [Jun 25 00:45:38] VERBOSE[10286] logger.c: Using INVITE request as basis request - MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. [Jun 25 00:45:38] VERBOSE[10286] logger.c: Found peer 'voipprovider' [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Setting NAT on RTP to Off [Jun 25 00:45:38] VERBOSE[10286] logger.c: Found RTP audio format 8 [Jun 25 00:45:38] VERBOSE[10286] logger.c: Found RTP audio format 18 [Jun 25 00:45:38] VERBOSE[10286] logger.c: Found RTP audio format 0 [Jun 25 00:45:38] VERBOSE[10286] logger.c: Found RTP audio format 101 [Jun 25 00:45:38] WARNING[10286] chan_sip.c: Unsupported SDP media type in offer: image 4922 udptl t38 [Jun 25 00:45:38] VERBOSE[10286] logger.c: Peer audio RTP is at port 213.50.89.4:4920 [Jun 25 00:45:38] VERBOSE[10286] logger.c: Got unsupported a:fmtp in SDP offer [Jun 25 00:45:38] VERBOSE[10286] logger.c: Got unsupported a:fmtp in SDP offer [Jun 25 00:45:38] VERBOSE[10286] logger.c: Found audio description format telephone-event for ID 101 [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: T38 state changed to 0 on channel [Jun 25 00:45:38] VERBOSE[10286] logger.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Jun 25 00:45:38] VERBOSE[10286] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 25 00:45:38] VERBOSE[10286] logger.c: Peer audio RTP is at port 213.50.89.4:4920 [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Checking SIP call limits for device voipprovider [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Updating call counter for incoming call [Jun 25 00:45:38] VERBOSE[10286] logger.c: Looking for 0303123456 in rs_incoming (domain 123.456.789.123) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: *** Our native formats are 0x8 (alaw) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: This channel will not be able to handle video. [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: build_route: Record-Route hop: [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: build_route: Record-Route hop: [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: build_route: Record-Route hop: [Jun 25 00:45:38] VERBOSE[10286] logger.c: list_route: hop: [Jun 25 00:45:38] VERBOSE[10286] logger.c: list_route: hop: [Jun 25 00:45:38] VERBOSE[10286] logger.c: list_route: hop: [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: SIP/voipprovider-0821c288: New call is still down.... Trying... [Jun 25 00:45:38] VERBOSE[10286] logger.c: <--- Transmitting (no NAT) to 213.131.156.66:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 Record-Route: Record-Route: Record-Route: From: "0705123456";tag=d4ff9921 To: "0303123456" Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 1: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 (91) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 2: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g (142) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 4: Record-Route: (60) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 5: Record-Route: (79) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 6: Record-Route: (39) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 7: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 8: To: "0303123456" (60) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 9: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 10: CSeq: 1 INVITE (14) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 11: User-Agent: Asterisk PBX (24) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 12: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 13: Supported: replaces (19) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 14: Contact: (39) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 15: Content-Length: 0 (17) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 16: (0) [Jun 25 00:45:38] DEBUG[10286] devicestate.c: Notification of state change to be queued on device/channel SIP/voipprovider-0821c288 [Jun 25 00:45:38] DEBUG[10286] devicestate.c: Notification of state change to be queued on device/channel SIP/voipprovider [Jun 25 00:45:38] DEBUG[10273] devicestate.c: No provider found, checking channel drivers for SIP - voipprovider-0821c288 [Jun 25 00:45:38] DEBUG[10273] chan_sip.c: Checking device state for peer voipprovider-0821c288 [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Gosub' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_incoming:1] Gosub("SIP/voipprovider-0821c288", "rs_preferences|0303123456|1") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_preferences:1] Set("SIP/voipprovider-0821c288", "rs_location=ste") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_preferences:2] Set("SIP/voipprovider-0821c288", "rs_id=1") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_preferences:3] Set("SIP/voipprovider-0821c288", "rs_callerid=0303123456") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_preferences:4] Set("SIP/voipprovider-0821c288", "rs_trustednumbers="XXXXXXXX") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_preferences:5] Set("SIP/voipprovider-0821c288", "rs_dial=XXXXXXX") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_preferences:6] Set("SIP/voipprovider-0821c288", "rs_copyright=") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_preferences:7] Set("SIP/voipprovider-0821c288", "rs_borrowflags=1") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_preferences:8] Set("SIP/voipprovider-0821c288", "CHANNEL(language)=sv") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_preferences:9] Set("SIP/voipprovider-0821c288", "tz=Europe/Stockholm") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_preferences:10] Set("SIP/voipprovider-0821c288", "rs_moh=sv") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_preferences:11] Set("SIP/voipprovider-0821c288", "rs_moh_nosoundtransfer=sv-nst") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Return' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_preferences:12] Return("SIP/voipprovider-0821c288", "") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Goto' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [0303123456@rs_incoming:2] Goto("SIP/voipprovider-0821c288", "rs_incoming_externalcall|s|1") in new stack [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Goto (rs_incoming_externalcall,s,1) [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Answer' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [s@rs_incoming_externalcall:1] Answer("SIP/voipprovider-0821c288", "") in new stack [Jun 25 00:45:38] DEBUG[13730] devicestate.c: Notification of state change to be queued on device/channel SIP/voipprovider-0821c288 [Jun 25 00:45:38] DEBUG[13730] devicestate.c: Notification of state change to be queued on device/channel SIP/voipprovider [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: SIP answering channel: SIP/voipprovider-0821c288 [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Setting framing from config on incoming call [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jun 25 00:45:38] VERBOSE[13730] logger.c: Audio is at 123.456.789.123 port 10884 [Jun 25 00:45:38] VERBOSE[13730] logger.c: Adding codec 0x8 (alaw) to SDP [Jun 25 00:45:38] VERBOSE[13730] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 25 00:45:38] VERBOSE[13730] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: -- Done with adding codecs to SDP [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Jun 25 00:45:38] VERBOSE[13730] logger.c: <--- Reliably Transmitting (no NAT) to 213.131.156.66:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 Record-Route: Record-Route: Record-Route: From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 10269 10269 IN IP4 123.456.789.123 s=session c=IN IP4 123.456.789.123 t=0 0 m=audio 10884 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 1: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 (91) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 2: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g (142) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 3: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 4: Record-Route: (60) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 5: Record-Route: (79) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 6: Record-Route: (39) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 7: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 8: To: "0303123456";tag=as6a319264 (75) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 9: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 10: CSeq: 1 INVITE (14) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 11: User-Agent: Asterisk PBX (24) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 12: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 13: Supported: replaces (19) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 14: Contact: (39) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 15: Content-Type: application/sdp (29) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 16: Content-Length: 266 (19) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Header 17: (0) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: v=0 (3) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: o=root 10269 10269 IN IP4 123.456.789.123 (39) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: s=session (9) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: c=IN IP4 123.456.789.123 (22) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: t=0 0 (5) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: m=audio 10884 RTP/AVP 8 0 101 (29) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: a=ptime:20 (10) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: Line: a=sendrecv (10) [Jun 25 00:45:38] DEBUG[13730] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 25 00:45:38] DEBUG[13730] pbx.c: Function result is '1' [Jun 25 00:45:38] DEBUG[13730] pbx.c: Expression result is '0' [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'GotoIf' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [s@rs_incoming_externalcall:2] GotoIf("SIP/voipprovider-0821c288", "0?3:11") in new stack [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Goto (rs_incoming_externalcall,s,11) [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'NoOp' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [s@rs_incoming_externalcall:11] NoOp("SIP/voipprovider-0821c288", "Finish if-rs_incoming_externalcall-419") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [s@rs_incoming_externalcall:12] Set("SIP/voipprovider-0821c288", "TIMEOUT(digit)=2") in new stack [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Digit timeout set to 2 [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [s@rs_incoming_externalcall:13] Set("SIP/voipprovider-0821c288", "TIMEOUT(response)=10") in new stack [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Response timeout set to 10 [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'SetMusicOnHold' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [s@rs_incoming_externalcall:14] SetMusicOnHold("SIP/voipprovider-0821c288", "sv") in new stack [Jun 25 00:45:38] DEBUG[13730] pbx.c: Expression result is '1' [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'GotoIf' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [s@rs_incoming_externalcall:15] GotoIf("SIP/voipprovider-0821c288", "1?16:19") in new stack [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Goto (rs_incoming_externalcall,s,16) [Jun 25 00:45:38] DEBUG[13730] pbx.c: Function result is '0705123456' [Jun 25 00:45:38] DEBUG[13730] func_strings.c: FUNCTION REGEX (030380633|030367640|030367641|0737267656|0705123456)(0705123456) [Jun 25 00:45:38] DEBUG[13730] pbx.c: Function result is '1' [Jun 25 00:45:38] DEBUG[13730] pbx.c: Expression result is '1' [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'GotoIf' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [s@rs_incoming_externalcall:16] GotoIf("SIP/voipprovider-0821c288", "1?17:18") in new stack [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Goto (rs_incoming_externalcall,s,17) [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Goto' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [s@rs_incoming_externalcall:17] Goto("SIP/voipprovider-0821c288", "rs_adminmenu|call_in|1") in new stack [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Goto (rs_adminmenu,call_in,1) [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'Ringing' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [call_in@rs_adminmenu:1] Ringing("SIP/voipprovider-0821c288", "") in new stack [Jun 25 00:45:38] DEBUG[13730] channel.c: Driver for channel 'SIP/voipprovider-0821c288' does not support indication 3, emulating it [Jun 25 00:45:38] DEBUG[13730] channel.c: Set channel SIP/voipprovider-0821c288 to write format slin [Jun 25 00:45:38] DEBUG[13730] channel.c: Scheduling timer at 160 sample intervals [Jun 25 00:45:38] DEBUG[13730] pbx.c: Launching 'WaitExten' [Jun 25 00:45:38] VERBOSE[13730] logger.c: -- Executing [call_in@rs_adminmenu:2] WaitExten("SIP/voipprovider-0821c288", "2") in new stack [Jun 25 00:45:38] DEBUG[10273] devicestate.c: Changing state for SIP/voipprovider-0821c288 - state 4 (Invalid) [Jun 25 00:45:38] DEBUG[10273] devicestate.c: No provider found, checking channel drivers for SIP - voipprovider [Jun 25 00:45:38] DEBUG[10273] chan_sip.c: Checking device state for peer voipprovider [Jun 25 00:45:38] DEBUG[10273] devicestate.c: Changing state for SIP/voipprovider - state 1 (Not in use) [Jun 25 00:45:38] DEBUG[10273] devicestate.c: No provider found, checking channel drivers for SIP - voipprovider-0821c288 [Jun 25 00:45:38] DEBUG[10273] chan_sip.c: Checking device state for peer voipprovider-0821c288 [Jun 25 00:45:38] DEBUG[10279] app_queue.c: Device 'SIP/voipprovider-0821c288' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 25 00:45:38] DEBUG[10279] app_queue.c: Device 'SIP/voipprovider' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 00:45:38] DEBUG[10273] devicestate.c: Changing state for SIP/voipprovider-0821c288 - state 4 (Invalid) [Jun 25 00:45:38] DEBUG[10273] devicestate.c: No provider found, checking channel drivers for SIP - voipprovider [Jun 25 00:45:38] DEBUG[10273] chan_sip.c: Checking device state for peer voipprovider [Jun 25 00:45:38] DEBUG[10273] devicestate.c: Changing state for SIP/voipprovider - state 1 (Not in use) [Jun 25 00:45:38] DEBUG[10279] app_queue.c: Device 'SIP/voipprovider-0821c288' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 25 00:45:38] DEBUG[10279] app_queue.c: Device 'SIP/voipprovider' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 00:45:38] VERBOSE[10286] logger.c: <--- SIP read from 213.131.156.66:5060 ---> INVITE sip:0303123456@123.456.789.123 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 From: "0705123456";tag=d4ff9921 To: "0303123456" Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 INVITE Record-Route: X-Ecan: On Content-Length: 261 User-Agent: LEICA-1.8.18 Supported: timer Content-Type: application/sdp Allow: INVITE, ACK, BYE, CANCEL Min-SE: 7200 Session-Expires: 7200;refresher=uac Contact: Max-Forwards: 68 v=0 o=- 2093054175 0 IN IP4 213.50.89.4 s=- c=IN IP4 213.50.89.4 t=0 0 m=audio 4920 RTP/AVP 8 18 0 101 a=fmtp:18 annexb=yes a=fmtp:101 0-15 a=T38MaxBitRate:14400 a=rtpmap:101 telephone-event/8000 a=T38FaxVersion:0 a=sendrecv m=image 4922 udptl t38 <-------------> [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 0: INVITE sip:0303123456@123.456.789.123 SIP/2.0 (43) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 1: Record-Route: (60) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 2: Record-Route: (79) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21 (67) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 4: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g (142) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 5: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 6: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 7: To: "0303123456" (60) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 8: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 9: CSeq: 1 INVITE (14) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 10: Record-Route: (39) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 11: X-Ecan: On (10) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 12: Content-Length: 261 (19) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 13: User-Agent: LEICA-1.8.18 (24) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 14: Supported: timer (16) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 15: Content-Type: application/sdp (29) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 16: Allow: INVITE, ACK, BYE, CANCEL (31) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 17: Min-SE: 7200 (12) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 18: Session-Expires: 7200;refresher=uac (35) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 19: Contact: (47) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 20: Max-Forwards: 68 (16) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 21: (0) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: v=0 (3) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: o=- 2093054175 0 IN IP4 213.50.89.4 (35) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: s=- (3) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: c=IN IP4 213.50.89.4 (20) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: t=0 0 (5) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: m=audio 4920 RTP/AVP 8 18 0 101 (31) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=fmtp:18 annexb=yes (20) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=fmtp:101 0-15 (15) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=T38MaxBitRate:14400 (21) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=T38FaxVersion:0 (17) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=sendrecv (10) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: m=image 4922 udptl t38 (22) [Jun 25 00:45:38] VERBOSE[10286] logger.c: --- (21 headers 13 lines) --- [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: = Found Their Call ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. Their Tag d4ff9921 Our tag: as6a319264 [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Ignoring SIP message because of retransmit (INVITE Seqno 1, ours 1) [Jun 25 00:45:38] VERBOSE[10286] logger.c: Ignoring this INVITE request [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Got a SIP re-transmit of INVITE for call MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: SIP/voipprovider-0821c288: This call is UP.... [Jun 25 00:45:38] VERBOSE[10286] logger.c: <--- Transmitting (no NAT) to 213.131.156.66:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 Record-Route: Record-Route: Record-Route: From: "0705123456";tag=d4ff9921 To: "0303123456" Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 1: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 (91) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 2: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g (142) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 4: Record-Route: (60) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 5: Record-Route: (79) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 6: Record-Route: (39) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 7: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 8: To: "0303123456" (60) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 9: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 10: CSeq: 1 INVITE (14) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 11: User-Agent: Asterisk PBX (24) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 12: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 13: Supported: replaces (19) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 14: Contact: (39) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 15: Content-Length: 0 (17) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 16: (0) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Setting framing from config on incoming call [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jun 25 00:45:38] VERBOSE[10286] logger.c: Audio is at 123.456.789.123 port 10884 [Jun 25 00:45:38] VERBOSE[10286] logger.c: Adding codec 0x8 (alaw) to SDP [Jun 25 00:45:38] VERBOSE[10286] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 25 00:45:38] VERBOSE[10286] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: -- Done with adding codecs to SDP [Jun 25 00:45:38] DEBUG[10286] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Jun 25 00:45:38] VERBOSE[10286] logger.c: <--- Reliably Transmitting (no NAT) to 213.131.156.66:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 Record-Route: Record-Route: Record-Route: From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 10269 10270 IN IP4 123.456.789.123 s=session c=IN IP4 123.456.789.123 t=0 0 m=audio 10884 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 1: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 (91) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 2: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g (142) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 4: Record-Route: (60) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 5: Record-Route: (79) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 6: Record-Route: (39) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 7: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 8: To: "0303123456";tag=as6a319264 (75) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 9: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 10: CSeq: 1 INVITE (14) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 11: User-Agent: Asterisk PBX (24) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 12: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 13: Supported: replaces (19) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 14: Contact: (39) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 15: Content-Type: application/sdp (29) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 16: Content-Length: 266 (19) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 17: (0) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: v=0 (3) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: o=root 10269 10270 IN IP4 123.456.789.123 (39) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: s=session (9) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: c=IN IP4 123.456.789.123 (22) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: t=0 0 (5) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: m=audio 10884 RTP/AVP 8 0 101 (29) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=ptime:20 (10) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Line: a=sendrecv (10) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 25 00:45:38] DEBUG[13730] rtp.c: Ooh, format changed from unknown to alaw [Jun 25 00:45:38] DEBUG[13730] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [Jun 25 00:45:38] VERBOSE[10286] logger.c: <--- SIP read from 213.131.156.66:5060 ---> ACK sip:0303123456@123.456.789.123 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.2;i=b21 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-vu_slcjvlh2mro61uoihtw-o5arzyutf0dyuttbrfnh9ka Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-1626f6560e9a3244-1---d8754z-;received=213.50.88.3;rport=45127 From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 ACK Record-Route: Content-Length: 0 Contact: Max-Forwards: 68 P-hint: rr-enforced <-------------> [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 0: ACK sip:0303123456@123.456.789.123 SIP/2.0 (40) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 1: Record-Route: (60) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 2: Record-Route: (79) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.2;i=b21 (67) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 4: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-vu_slcjvlh2mro61uoihtw-o5arzyutf0dyuttbrfnh9ka (136) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 5: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-1626f6560e9a3244-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 6: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 7: To: "0303123456";tag=as6a319264 (75) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 8: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 9: CSeq: 1 ACK (11) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 10: Record-Route: (39) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 11: Content-Length: 0 (17) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 12: Contact: (47) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 13: Max-Forwards: 68 (16) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 14: P-hint: rr-enforced (19) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 15: (0) [Jun 25 00:45:38] VERBOSE[10286] logger.c: --- (15 headers 0 lines) --- [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: = Found Their Call ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. Their Tag d4ff9921 Our tag: as6a319264 [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #2848 [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Stopping retransmission on 'MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc.' of Response 1: Match Found [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Generator got voice, switching to phase locked mode [Jun 25 00:45:38] DEBUG[13730] channel.c: Scheduling timer at 0 sample intervals [Jun 25 00:45:38] DEBUG[13730] rtp.c: Got RTCP report of 80 bytes [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] VERBOSE[10286] logger.c: <--- SIP read from 213.131.156.66:5060 ---> ACK sip:0303123456@123.456.789.123 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.2;i=b21 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-cw9kwhf+syd2sv6pq6mxew-o5arzyutf0dyuttbrfnh9ka Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-42327153e7bd193d-1---d8754z-;received=213.50.88.3;rport=45127 From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 ACK Record-Route: Content-Length: 0 Contact: Max-Forwards: 68 P-hint: rr-enforced <-------------> [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 0: ACK sip:0303123456@123.456.789.123 SIP/2.0 (40) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 1: Record-Route: (60) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 2: Record-Route: (79) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.2;i=b21 (67) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 4: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-cw9kwhf+syd2sv6pq6mxew-o5arzyutf0dyuttbrfnh9ka (136) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 5: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-42327153e7bd193d-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 6: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 7: To: "0303123456";tag=as6a319264 (75) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 8: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 9: CSeq: 1 ACK (11) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 10: Record-Route: (39) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 11: Content-Length: 0 (17) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 12: Contact: (47) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 13: Max-Forwards: 68 (16) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 14: P-hint: rr-enforced (19) [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: Header 15: (0) [Jun 25 00:45:38] VERBOSE[10286] logger.c: --- (15 headers 0 lines) --- [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: = Found Their Call ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. Their Tag d4ff9921 Our tag: as6a319264 [Jun 25 00:45:38] DEBUG[10286] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:38] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: SIP TIMER: Rescheduling retransmission #2847 (1) SIP/2.0 - 1 [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #2847)) [Jun 25 00:45:39] VERBOSE[10286] logger.c: Retransmitting #1 (no NAT) to 213.131.156.66:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 Record-Route: Record-Route: Record-Route: From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 10269 10269 IN IP4 123.456.789.123 s=session c=IN IP4 123.456.789.123 t=0 0 m=audio 10884 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] VERBOSE[10286] logger.c: <--- SIP read from 213.131.156.66:5060 ---> ACK sip:0303123456@123.456.789.123 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.2;i=b21 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-sjkfti0ur3w4gfz_9mqjsa-o5arzyutf0dyuttbrfnh9ka Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-c67a1e2994fdf771-1---d8754z-;received=213.50.88.3;rport=45127 From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 ACK Record-Route: Content-Length: 0 Contact: Max-Forwards: 68 P-hint: rr-enforced <-------------> [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 0: ACK sip:0303123456@123.456.789.123 SIP/2.0 (40) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 1: Record-Route: (60) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 2: Record-Route: (79) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.2;i=b21 (67) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 4: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-sjkfti0ur3w4gfz_9mqjsa-o5arzyutf0dyuttbrfnh9ka (136) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 5: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-c67a1e2994fdf771-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 6: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 7: To: "0303123456";tag=as6a319264 (75) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 8: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 9: CSeq: 1 ACK (11) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 10: Record-Route: (39) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 11: Content-Length: 0 (17) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 12: Contact: (47) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 13: Max-Forwards: 68 (16) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 14: P-hint: rr-enforced (19) [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: Header 15: (0) [Jun 25 00:45:39] VERBOSE[10286] logger.c: --- (15 headers 0 lines) --- [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: = Found Their Call ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. Their Tag d4ff9921 Our tag: as6a319264 [Jun 25 00:45:39] DEBUG[10286] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:39] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: SIP TIMER: Rescheduling retransmission #2847 (2) SIP/2.0 - 1 [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #2847)) [Jun 25 00:45:40] VERBOSE[10286] logger.c: Retransmitting #2 (no NAT) to 213.131.156.66:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 Record-Route: Record-Route: Record-Route: From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 10269 10269 IN IP4 123.456.789.123 s=session c=IN IP4 123.456.789.123 t=0 0 m=audio 10884 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] VERBOSE[13730] logger.c: -- Timeout on SIP/voipprovider-0821c288, continuing... [Jun 25 00:45:40] DEBUG[13730] pbx.c: Launching 'Goto' [Jun 25 00:45:40] VERBOSE[13730] logger.c: -- Executing [call_in@rs_adminmenu:3] Goto("SIP/voipprovider-0821c288", "menu|1") in new stack [Jun 25 00:45:40] VERBOSE[13730] logger.c: -- Goto (rs_adminmenu,menu,1) [Jun 25 00:45:40] DEBUG[13730] pbx.c: Launching 'WaitExten' [Jun 25 00:45:40] VERBOSE[13730] logger.c: -- Executing [menu@rs_adminmenu:1] WaitExten("SIP/voipprovider-0821c288", "1") in new stack [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] VERBOSE[10286] logger.c: <--- SIP read from 213.131.156.66:5060 ---> ACK sip:0303123456@123.456.789.123 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.2;i=b21 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-zk507t3fh8kug_qr7bfcyw-o5arzyutf0dyuttbrfnh9ka Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-8c3b2e488107b41a-1---d8754z-;received=213.50.88.3;rport=45127 From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 ACK Record-Route: Content-Length: 0 Contact: Max-Forwards: 68 P-hint: rr-enforced <-------------> [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 0: ACK sip:0303123456@123.456.789.123 SIP/2.0 (40) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 1: Record-Route: (60) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 2: Record-Route: (79) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.2;i=b21 (67) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 4: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-zk507t3fh8kug_qr7bfcyw-o5arzyutf0dyuttbrfnh9ka (136) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 5: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-8c3b2e488107b41a-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 6: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 7: To: "0303123456";tag=as6a319264 (75) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 8: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 9: CSeq: 1 ACK (11) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 10: Record-Route: (39) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 11: Content-Length: 0 (17) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 12: Contact: (47) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 13: Max-Forwards: 68 (16) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 14: P-hint: rr-enforced (19) [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: Header 15: (0) [Jun 25 00:45:40] VERBOSE[10286] logger.c: --- (15 headers 0 lines) --- [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: = Found Their Call ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. Their Tag d4ff9921 Our tag: as6a319264 [Jun 25 00:45:40] DEBUG[10286] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:40] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] DEBUG[13730] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Jun 25 00:45:41] VERBOSE[13730] logger.c: -- Timeout on SIP/voipprovider-0821c288, continuing... [Jun 25 00:45:41] DEBUG[13730] pbx.c: Launching 'BackGround' [Jun 25 00:45:41] VERBOSE[13730] logger.c: -- Executing [menu@rs_adminmenu:2] BackGround("SIP/voipprovider-0821c288", "rs_adminmenu_welcome") in new stack [Jun 25 00:45:41] DEBUG[13730] channel.c: Set channel SIP/voipprovider-0821c288 to write format alaw [Jun 25 00:45:41] DEBUG[13730] channel.c: Scheduling timer at 0 sample intervals [Jun 25 00:45:41] DEBUG[13730] channel.c: Set channel SIP/voipprovider-0821c288 to write format slin [Jun 25 00:45:41] DEBUG[13730] channel.c: Scheduling timer at 160 sample intervals [Jun 25 00:45:41] VERBOSE[13730] logger.c: -- Playing 'rs_adminmenu_welcome' (language 'rs-sv') [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: SIP TIMER: Rescheduling retransmission #2847 (3) SIP/2.0 - 1 [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #2847)) [Jun 25 00:45:42] VERBOSE[10286] logger.c: Retransmitting #3 (no NAT) to 213.131.156.66:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 Record-Route: Record-Route: Record-Route: From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 10269 10269 IN IP4 123.456.789.123 s=session c=IN IP4 123.456.789.123 t=0 0 m=audio 10884 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jun 25 00:45:42] VERBOSE[10286] logger.c: <--- SIP read from 213.131.156.66:5060 ---> ACK sip:0303123456@123.456.789.123 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.2;i=b21 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-aymawgjrr9khr7axjlwp_g-o5arzyutf0dyuttbrfnh9ka Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-57da2e7c7fccf405-1---d8754z-;received=213.50.88.3;rport=45127 From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 ACK Record-Route: Content-Length: 0 Contact: Max-Forwards: 68 P-hint: rr-enforced <-------------> [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 0: ACK sip:0303123456@123.456.789.123 SIP/2.0 (40) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 1: Record-Route: (60) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 2: Record-Route: (79) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.2;i=b21 (67) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 4: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-aymawgjrr9khr7axjlwp_g-o5arzyutf0dyuttbrfnh9ka (136) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 5: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-57da2e7c7fccf405-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 6: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 7: To: "0303123456";tag=as6a319264 (75) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 8: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 9: CSeq: 1 ACK (11) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 10: Record-Route: (39) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 11: Content-Length: 0 (17) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 12: Contact: (47) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 13: Max-Forwards: 68 (16) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 14: P-hint: rr-enforced (19) [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: Header 15: (0) [Jun 25 00:45:42] VERBOSE[10286] logger.c: --- (15 headers 0 lines) --- [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: = Found Their Call ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. Their Tag d4ff9921 Our tag: as6a319264 [Jun 25 00:45:42] DEBUG[10286] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 25 00:45:43] DEBUG[13730] channel.c: Scheduling timer at 117 sample intervals [Jun 25 00:45:43] DEBUG[13730] channel.c: Scheduling timer at 0 sample intervals [Jun 25 00:45:43] DEBUG[13730] channel.c: Scheduling timer at 0 sample intervals [Jun 25 00:45:43] DEBUG[13730] channel.c: Set channel SIP/voipprovider-0821c288 to write format alaw [Jun 25 00:45:43] DEBUG[13730] pbx.c: Launching 'WaitExten' [Jun 25 00:45:43] VERBOSE[13730] logger.c: -- Executing [menu@rs_adminmenu:3] WaitExten("SIP/voipprovider-0821c288", "1") in new stack [Jun 25 00:45:44] VERBOSE[13730] logger.c: -- Timeout on SIP/voipprovider-0821c288, continuing... [Jun 25 00:45:44] DEBUG[13730] pbx.c: Expression result is '0' [Jun 25 00:45:44] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:44] VERBOSE[13730] logger.c: -- Executing [menu@rs_adminmenu:4] Set("SIP/voipprovider-0821c288", "i=0") in new stack [Jun 25 00:45:44] DEBUG[13730] pbx.c: Expression result is '1' [Jun 25 00:45:44] DEBUG[13730] pbx.c: Launching 'GotoIf' [Jun 25 00:45:44] VERBOSE[13730] logger.c: -- Executing [menu@rs_adminmenu:5] GotoIf("SIP/voipprovider-0821c288", "1?6:28") in new stack [Jun 25 00:45:44] VERBOSE[13730] logger.c: -- Goto (rs_adminmenu,menu,6) [Jun 25 00:45:44] DEBUG[13730] pbx.c: Launching 'BackGround' [Jun 25 00:45:44] VERBOSE[13730] logger.c: -- Executing [menu@rs_adminmenu:6] BackGround("SIP/voipprovider-0821c288", "rs_adminmenu_youhave4choices") in new stack [Jun 25 00:45:44] DEBUG[13730] channel.c: Set channel SIP/voipprovider-0821c288 to write format slin [Jun 25 00:45:44] DEBUG[13730] rtp.c: Difference is 8320, ms is 1060 [Jun 25 00:45:44] DEBUG[13730] channel.c: Scheduling timer at 160 sample intervals [Jun 25 00:45:44] VERBOSE[13730] logger.c: -- Playing 'rs_adminmenu_youhave4choices' (language 'rs-sv') [Jun 25 00:45:45] DEBUG[13730] rtp.c: Got RTCP report of 80 bytes [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: Sending dtmf: 50 (2), at 213.50.89.4 [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: Sending dtmf: 50 (2), at 213.50.89.4 [Jun 25 00:45:45] DEBUG[13730] channel.c: Scheduling timer at 0 sample intervals [Jun 25 00:45:45] DEBUG[13730] channel.c: Set channel SIP/voipprovider-0821c288 to write format alaw [Jun 25 00:45:45] DEBUG[13730] pbx.c: Oooh, got something to jump out with ('2')! [Jun 25 00:45:45] VERBOSE[13730] logger.c: == CDR updated on SIP/voipprovider-0821c288 [Jun 25 00:45:45] DEBUG[13730] pbx.c: Launching 'Goto' [Jun 25 00:45:45] VERBOSE[13730] logger.c: -- Executing [2@rs_adminmenu:1] Goto("SIP/voipprovider-0821c288", "rs_borrowmeeting|menu|1") in new stack [Jun 25 00:45:45] VERBOSE[13730] logger.c: -- Goto (rs_borrowmeeting,menu,1) [Jun 25 00:45:45] DEBUG[13730] pbx.c: Launching 'Wait' [Jun 25 00:45:45] VERBOSE[13730] logger.c: -- Executing [menu@rs_borrowmeeting:1] Wait("SIP/voipprovider-0821c288", "2") in new stack [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:45] DEBUG[13730] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: SIP TIMER: Rescheduling retransmission #2847 (4) SIP/2.0 - 1 [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #2847)) [Jun 25 00:45:46] VERBOSE[10286] logger.c: Retransmitting #4 (no NAT) to 213.131.156.66:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 Record-Route: Record-Route: Record-Route: From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 10269 10269 IN IP4 123.456.789.123 s=session c=IN IP4 123.456.789.123 t=0 0 m=audio 10884 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jun 25 00:45:46] VERBOSE[10286] logger.c: <--- SIP read from 213.131.156.66:5060 ---> ACK sip:0303123456@123.456.789.123 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 213.131.156.66;branch=0;i=b21 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-trmpfprslb7pivezvftg8q-o5arzyutf0dyuttbrfnh9ka Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-bef67f544870c912-1---d8754z-;received=213.50.88.3;rport=45127 From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 ACK Record-Route: Content-Length: 0 Contact: Max-Forwards: 68 P-hint: rr-enforced <-------------> [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 0: ACK sip:0303123456@123.456.789.123 SIP/2.0 (40) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 1: Record-Route: (60) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 2: Record-Route: (79) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/UDP 213.131.156.66;branch=0;i=b21 (46) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 4: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-trmpfprslb7pivezvftg8q-o5arzyutf0dyuttbrfnh9ka (136) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 5: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-bef67f544870c912-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 6: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 7: To: "0303123456";tag=as6a319264 (75) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 8: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 9: CSeq: 1 ACK (11) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 10: Record-Route: (39) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 11: Content-Length: 0 (17) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 12: Contact: (47) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 13: Max-Forwards: 68 (16) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 14: P-hint: rr-enforced (19) [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: Header 15: (0) [Jun 25 00:45:46] VERBOSE[10286] logger.c: --- (15 headers 0 lines) --- [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: = Found Their Call ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. Their Tag d4ff9921 Our tag: as6a319264 [Jun 25 00:45:46] DEBUG[10286] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 25 00:45:47] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:47] VERBOSE[13730] logger.c: -- Executing [menu@rs_borrowmeeting:2] Set("SIP/voipprovider-0821c288", "TIMEOUT(digit)=4") in new stack [Jun 25 00:45:47] VERBOSE[13730] logger.c: -- Digit timeout set to 4 [Jun 25 00:45:47] DEBUG[13730] pbx.c: Launching 'Playback' [Jun 25 00:45:47] VERBOSE[13730] logger.c: -- Executing [menu@rs_borrowmeeting:3] Playback("SIP/voipprovider-0821c288", "rs_borrow_menu") in new stack [Jun 25 00:45:47] DEBUG[13730] channel.c: Set channel SIP/voipprovider-0821c288 to write format slin [Jun 25 00:45:47] DEBUG[13730] rtp.c: Difference is 16352, ms is 2064 [Jun 25 00:45:47] DEBUG[13730] channel.c: Scheduling timer at 160 sample intervals [Jun 25 00:45:47] VERBOSE[13730] logger.c: -- Playing 'rs_borrow_menu' (language 'rs-sv') [Jun 25 00:45:48] DEBUG[13730] channel.c: Scheduling timer at 131 sample intervals [Jun 25 00:45:48] DEBUG[13730] channel.c: Scheduling timer at 0 sample intervals [Jun 25 00:45:48] DEBUG[13730] channel.c: Scheduling timer at 0 sample intervals [Jun 25 00:45:48] DEBUG[13730] channel.c: Set channel SIP/voipprovider-0821c288 to write format alaw [Jun 25 00:45:48] DEBUG[13730] pbx.c: Function result is '' [Jun 25 00:45:48] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:48] VERBOSE[13730] logger.c: -- Executing [menu@rs_borrowmeeting:4] Set("SIP/voipprovider-0821c288", "rs_connected=") in new stack [Jun 25 00:45:48] DEBUG[13730] pbx.c: Expression result is '0' [Jun 25 00:45:48] DEBUG[13730] pbx.c: Launching 'Set' [Jun 25 00:45:48] VERBOSE[13730] logger.c: -- Executing [menu@rs_borrowmeeting:5] Set("SIP/voipprovider-0821c288", "loops=0") in new stack [Jun 25 00:45:48] DEBUG[13730] pbx.c: Expression result is '1' [Jun 25 00:45:48] DEBUG[13730] pbx.c: Launching 'GotoIf' [Jun 25 00:45:48] VERBOSE[13730] logger.c: -- Executing [menu@rs_borrowmeeting:6] GotoIf("SIP/voipprovider-0821c288", "1?7:25") in new stack [Jun 25 00:45:48] VERBOSE[13730] logger.c: -- Goto (rs_borrowmeeting,menu,7) [Jun 25 00:45:48] DEBUG[13730] pbx.c: Expression result is '1' [Jun 25 00:45:48] DEBUG[13730] pbx.c: Launching 'GotoIf' [Jun 25 00:45:48] VERBOSE[13730] logger.c: -- Executing [menu@rs_borrowmeeting:7] GotoIf("SIP/voipprovider-0821c288", "1?8:10") in new stack [Jun 25 00:45:48] VERBOSE[13730] logger.c: -- Goto (rs_borrowmeeting,menu,8) [Jun 25 00:45:48] DEBUG[13730] pbx.c: Launching 'BackGround' [Jun 25 00:45:48] VERBOSE[13730] logger.c: -- Executing [menu@rs_borrowmeeting:8] BackGround("SIP/voipprovider-0821c288", "rs_borrow_notrecording_anounce") in new stack [Jun 25 00:45:48] DEBUG[13730] channel.c: Set channel SIP/voipprovider-0821c288 to write format slin [Jun 25 00:45:48] DEBUG[13730] channel.c: Scheduling timer at 160 sample intervals [Jun 25 00:45:48] VERBOSE[13730] logger.c: -- Playing 'rs_borrow_notrecording_anounce' (language 'rs-sv') [Jun 25 00:45:48] DEBUG[13730] rtp.c: Got RTCP report of 80 bytes [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: SIP TIMER: Rescheduling retransmission #2847 (5) SIP/2.0 - 1 [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #2847)) [Jun 25 00:45:50] VERBOSE[10286] logger.c: Retransmitting #5 (no NAT) to 213.131.156.66:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 Record-Route: Record-Route: Record-Route: From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 10269 10269 IN IP4 123.456.789.123 s=session c=IN IP4 123.456.789.123 t=0 0 m=audio 10884 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jun 25 00:45:50] VERBOSE[10286] logger.c: <--- SIP read from 213.131.156.66:5060 ---> ACK sip:0303123456@123.456.789.123 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 213.131.156.66;branch=0;i=b21 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-4yuqx4hockbitca2yassoa-o5arzyutf0dyuttbrfnh9ka Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-b6eb487ecc3cdd51-1---d8754z-;received=213.50.88.3;rport=45127 From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 ACK Record-Route: Content-Length: 0 Contact: Max-Forwards: 68 P-hint: rr-enforced <-------------> [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 0: ACK sip:0303123456@123.456.789.123 SIP/2.0 (40) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 1: Record-Route: (60) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 2: Record-Route: (79) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/UDP 213.131.156.66;branch=0;i=b21 (46) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 4: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-4yuqx4hockbitca2yassoa-o5arzyutf0dyuttbrfnh9ka (136) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 5: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-b6eb487ecc3cdd51-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 6: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 7: To: "0303123456";tag=as6a319264 (75) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 8: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 9: CSeq: 1 ACK (11) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 10: Record-Route: (39) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 11: Content-Length: 0 (17) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 12: Contact: (47) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 13: Max-Forwards: 68 (16) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 14: P-hint: rr-enforced (19) [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: Header 15: (0) [Jun 25 00:45:50] VERBOSE[10286] logger.c: --- (15 headers 0 lines) --- [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: = Found Their Call ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. Their Tag d4ff9921 Our tag: as6a319264 [Jun 25 00:45:50] DEBUG[10286] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 25 00:45:54] DEBUG[13730] channel.c: Scheduling timer at 15 sample intervals [Jun 25 00:45:54] DEBUG[13730] channel.c: Scheduling timer at 0 sample intervals [Jun 25 00:45:54] DEBUG[13730] channel.c: Scheduling timer at 0 sample intervals [Jun 25 00:45:54] DEBUG[13730] channel.c: Set channel SIP/voipprovider-0821c288 to write format alaw [Jun 25 00:45:54] DEBUG[13730] pbx.c: Launching 'Goto' [Jun 25 00:45:54] VERBOSE[13730] logger.c: -- Executing [menu@rs_borrowmeeting:9] Goto("SIP/voipprovider-0821c288", "11") in new stack [Jun 25 00:45:54] VERBOSE[13730] logger.c: -- Goto (rs_borrowmeeting,menu,11) [Jun 25 00:45:54] DEBUG[13730] pbx.c: Launching 'NoOp' [Jun 25 00:45:54] VERBOSE[13730] logger.c: -- Executing [menu@rs_borrowmeeting:11] NoOp("SIP/voipprovider-0821c288", "Finish if-for-rs_borrowmeeting-492-493") in new stack [Jun 25 00:45:54] DEBUG[13730] pbx.c: Launching 'WaitExten' [Jun 25 00:45:54] VERBOSE[13730] logger.c: -- Executing [menu@rs_borrowmeeting:12] WaitExten("SIP/voipprovider-0821c288", "8") in new stack [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: SIP TIMER: Rescheduling retransmission #2847 (6) SIP/2.0 - 1 [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #2847)) [Jun 25 00:45:54] VERBOSE[10286] logger.c: Retransmitting #6 (no NAT) to 213.131.156.66:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK82ea.cfe2a351.0;i=b21;received=213.131.156.66 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mvy9hxk1kcnsdl60d7sptw-UAC.1-oqcp+xitfexak0dtznkgi9g Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-96aa933c198b9d36-1---d8754z-;received=213.50.88.3;rport=45127 Record-Route: Record-Route: Record-Route: From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 10269 10269 IN IP4 123.456.789.123 s=session c=IN IP4 123.456.789.123 t=0 0 m=audio 10884 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jun 25 00:45:54] VERBOSE[10286] logger.c: <--- SIP read from 213.131.156.66:5060 ---> ACK sip:0303123456@123.456.789.123 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 213.131.156.66;branch=0;i=b21 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-ahue5dwqeppwtkpqo0cwja-o5arzyutf0dyuttbrfnh9ka Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-78eae377f71c911e-1---d8754z-;received=213.50.88.3;rport=45127 From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 1 ACK Record-Route: Content-Length: 0 Contact: Max-Forwards: 68 P-hint: rr-enforced <-------------> [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 0: ACK sip:0303123456@123.456.789.123 SIP/2.0 (40) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 1: Record-Route: (60) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 2: Record-Route: (79) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/UDP 213.131.156.66;branch=0;i=b21 (46) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 4: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-ahue5dwqeppwtkpqo0cwja-o5arzyutf0dyuttbrfnh9ka (136) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 5: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-78eae377f71c911e-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 6: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 7: To: "0303123456";tag=as6a319264 (75) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 8: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 9: CSeq: 1 ACK (11) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 10: Record-Route: (39) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 11: Content-Length: 0 (17) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 12: Contact: (47) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 13: Max-Forwards: 68 (16) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 14: P-hint: rr-enforced (19) [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: Header 15: (0) [Jun 25 00:45:54] VERBOSE[10286] logger.c: --- (15 headers 0 lines) --- [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: = Found Their Call ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. Their Tag d4ff9921 Our tag: as6a319264 [Jun 25 00:45:54] DEBUG[10286] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 25 00:45:56] DEBUG[13730] rtp.c: Got RTCP report of 80 bytes [Jun 25 00:45:58] WARNING[10286] chan_sip.c: Maximum retries exceeded on transmission MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. for seqno 1 (Critical Response) [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: Setting SIP_ALREADYGONE on dialog MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. [Jun 25 00:45:58] WARNING[10286] chan_sip.c: Hanging up call MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. - no reply to our critical packet. [Jun 25 00:45:58] DEBUG[13730] pbx.c: Spawn extension (rs_borrowmeeting,menu,12) exited non-zero on 'SIP/voipprovider-0821c288' [Jun 25 00:45:58] VERBOSE[13730] logger.c: == Spawn extension (rs_borrowmeeting, menu, 12) exited non-zero on 'SIP/voipprovider-0821c288' [Jun 25 00:45:58] DEBUG[13730] channel.c: Soft-Hanging up channel 'SIP/voipprovider-0821c288' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Launching 'NoOp' [Jun 25 00:45:58] VERBOSE[13730] logger.c: -- Executing [h@rs_borrowmeeting:1] NoOp("SIP/voipprovider-0821c288", "This hangup triggers the h extension") in new stack [Jun 25 00:45:58] DEBUG[13730] channel.c: Hanging up channel 'SIP/voipprovider-0821c288' [Jun 25 00:45:58] DEBUG[13730] chan_sip.c: Hangup call SIP/voipprovider-0821c288, SIP callid MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc.) [Jun 25 00:45:58] DEBUG[13730] devicestate.c: Notification of state change to be queued on device/channel SIP/voipprovider-0821c288 [Jun 25 00:45:58] DEBUG[13730] devicestate.c: Notification of state change to be queued on device/channel SIP/voipprovider [Jun 25 00:45:58] DEBUG[10273] devicestate.c: No provider found, checking channel drivers for SIP - voipprovider-0821c288 [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is '"0705123456" <0705123456>' [Jun 25 00:45:58] DEBUG[10273] chan_sip.c: Checking device state for peer voipprovider-0821c288 [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is '0705123456' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is 'menu' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is 'rs_borrowmeeting' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is 'SIP/voipprovider-0821c288' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is '' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is 'WaitExten' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is '8' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is '2008-06-25 00:45:38' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is '2008-06-25 00:45:38' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is '2008-06-25 00:45:58' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is '20' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is '20' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is 'ANSWERED' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is 'DOCUMENTATION' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is '' [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is '1214347538.238' [Jun 25 00:45:58] DEBUG[10273] devicestate.c: Changing state for SIP/voipprovider-0821c288 - state 4 (Invalid) [Jun 25 00:45:58] DEBUG[13730] pbx.c: Function result is '' [Jun 25 00:45:58] DEBUG[10273] devicestate.c: No provider found, checking channel drivers for SIP - voipprovider [Jun 25 00:45:58] DEBUG[10273] chan_sip.c: Checking device state for peer voipprovider [Jun 25 00:45:58] DEBUG[10273] devicestate.c: Changing state for SIP/voipprovider - state 1 (Not in use) [Jun 25 00:45:58] DEBUG[10279] app_queue.c: Device 'SIP/voipprovider-0821c288' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 25 00:45:58] DEBUG[10279] app_queue.c: Device 'SIP/voipprovider' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 00:45:58] VERBOSE[10286] logger.c: Really destroying SIP dialog 'MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc.' Method: ACK [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: ---------- SIP HISTORY for 'MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc.' [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: * SIP Call [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 001. Rx INVITE / 1 INVITE / sip:0303123456@123.456.789.123 [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 002. NewChan Channel SIP/voipprovider-0821c288 - from MWQxOGM5YmZkOTJmMDgyYTA1 [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 003. TxResp SIP/2.0 / 1 INVITE - 100 Trying [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 004. TxRespRel SIP/2.0 / 1 INVITE - 200 OK [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 005. Rx INVITE / 1 INVITE / sip:0303123456@123.456.789.123 [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 006. TxResp SIP/2.0 / 1 INVITE - 100 Trying [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 007. TxRespRel SIP/2.0 / 1 INVITE - 200 OK [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 008. Rx ACK / 1 ACK / sip:0303123456@123.456.789.123 [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 009. Rx ACK / 1 ACK / sip:0303123456@123.456.789.123 [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 010. ReTx 1000 SIP/2.0 200 OK [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 011. Rx ACK / 1 ACK / sip:0303123456@123.456.789.123 [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 012. ReTx 2000 SIP/2.0 200 OK [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 013. Rx ACK / 1 ACK / sip:0303123456@123.456.789.123 [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 014. ReTx 4000 SIP/2.0 200 OK [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 015. Rx ACK / 1 ACK / sip:0303123456@123.456.789.123 [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 016. ReTx 4000 SIP/2.0 200 OK [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 017. Rx ACK / 1 ACK / sip:0303123456@123.456.789.123 [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 018. ReTx 4000 SIP/2.0 200 OK [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 019. Rx ACK / 1 ACK / sip:0303123456@123.456.789.123 [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 020. ReTx 4000 SIP/2.0 200 OK [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 021. Rx ACK / 1 ACK / sip:0303123456@123.456.789.123 [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 022. MaxRetries (Critical) [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: 023. Hangup Cause No user responding [Jun 25 00:45:58] DEBUG[10286] chan_sip.c: ---------- END SIP HISTORY for 'MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc.' [Jun 25 00:46:50] VERBOSE[10286] logger.c: <--- SIP read from 213.131.156.66:5060 ---> BYE sip:0303123456@123.456.789.123 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK52ea.4b5eb343.0;i=b21 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mscbtu2g514beqe3ei9naq-UAC-o41rix1jww1yzfyqld8snlg Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-f86beb7d32b31b14-1---d8754z-;received=213.50.88.3;rport=45127 From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 2 BYE Record-Route: Content-Length: 0 Contact: Max-Forwards: 68 P-hint: rr-enforced <-------------> [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 0: BYE sip:0303123456@123.456.789.123 SIP/2.0 (40) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 1: Record-Route: (60) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 2: Record-Route: (79) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 3: Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK52ea.4b5eb343.0;i=b21 (67) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 4: Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mscbtu2g514beqe3ei9naq-UAC-o41rix1jww1yzfyqld8snlg (140) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 5: Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-f86beb7d32b31b14-1---d8754z-;received=213.50.88.3;rport=45127 (117) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 6: From: "0705123456";tag=d4ff9921 (75) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 7: To: "0303123456";tag=as6a319264 (75) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 8: Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. (53) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 9: CSeq: 2 BYE (11) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 10: Record-Route: (39) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 11: Content-Length: 0 (17) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 12: Contact: (47) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 13: Max-Forwards: 68 (16) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 14: P-hint: rr-enforced (19) [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Header 15: (0) [Jun 25 00:46:50] VERBOSE[10286] logger.c: --- (15 headers 0 lines) --- [Jun 25 00:46:50] VERBOSE[10286] logger.c: Sending to 213.131.156.66 : 5060 (no NAT) [Jun 25 00:46:50] VERBOSE[10286] logger.c: <--- Transmitting (no NAT) to 213.131.156.66:5060 ---> SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/UDP 213.131.156.66;branch=z9hG4bK52ea.4b5eb343.0;i=b21;received=213.131.156.66 Via: SIP/2.0/TLS kst-sipp.sipgw.tdcsong.se:5061;received=213.50.75.168;branch=z9hG4bK-yxa-mscbtu2g514beqe3ei9naq-UAC-o41rix1jww1yzfyqld8snlg Via: SIP/2.0/TCP 213.50.88.3:5060;branch=z9hG4bK-d8754z-f86beb7d32b31b14-1---d8754z-;received=213.50.88.3;rport=45127 From: "0705123456";tag=d4ff9921 To: "0303123456";tag=as6a319264 Call-ID: MWQxOGM5YmZkOTJmMDgyYTA1NjIwZDk4YzE3ODExODc. CSeq: 2 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Jun 25 00:46:50] DEBUG[10286] chan_sip.c: Invalid SIP message - rejected , no callid, len 887