[Apr 26 16:42:53] VERBOSE[1635] logger.c: Asterisk Event Logger restarted [Apr 26 16:42:53] VERBOSE[1635] logger.c: Asterisk Queue Logger restarted [Apr 26 16:43:06] VERBOSE[1632] logger.c: <--- SIP read from 79.129.85.99:5060 ---> INVITE sip:123456@192.168.253.201:5060 SIP/2.0 CSeq: 1 INVITE Via: SIP/2.0/UDP 79.129.85.99:5060;branch=z9hG4bKcf7f8ffd-0404-1910-9651-00234d1569f6;rport User-Agent: Open-Phone/3.8.0 From: "4477840012155" ;tag=bb618ffd-0404-1910-9650-00234d1569f6 Call-ID: af638ffd-0404-1910-9650-00234d1569f6@VLASIS Organization: Vox Lucida To: Contact: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING Content-Type: application/sdp Content-Length: 192 Max-Forwards: 70 v=0 o=- 1303825381 1 IN IP4 79.129.85.99 s=Open-Phone/3.8.0 c=IN IP4 79.129.85.99 t=0 0 m=audio 5010 RTP/AVP 18 a=sendrecv a=rtpmap:18 G729/8000/1 a=fmtp:18 annexb=no a=maxptime:250 <-------------> [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 0: INVITE sip:123456@192.168.253.201:5060 SIP/2.0 (46) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 1: CSeq: 1 INVITE (14) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 2: Via: SIP/2.0/UDP 79.129.85.99:5060;branch=z9hG4bKcf7f8ffd-0404-1910-9651-00234d1569f6;rport (91) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 3: User-Agent: Open-Phone/3.8.0 (28) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 4: From: "4477840012155" ;tag=bb618ffd-0404-1910-9650-00234d1569f6 (95) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 5: Call-ID: af638ffd-0404-1910-9650-00234d1569f6@VLASIS (52) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 6: Organization: Vox Lucida (24) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 7: To: (37) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 8: Contact: (41) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 9: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING (77) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 10: Content-Type: application/sdp (29) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 11: Content-Length: 192 (19) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 12: Max-Forwards: 70 (16) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 13: (0) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Line: v=0 (3) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Line: o=- 1303825381 1 IN IP4 79.129.85.99 (36) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Line: s=Open-Phone/3.8.0 (18) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Line: c=IN IP4 79.129.85.99 (21) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Line: t=0 0 (5) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Line: m=audio 5010 RTP/AVP 18 (23) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Line: a=sendrecv (10) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Line: a=rtpmap:18 G729/8000/1 (23) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Line: a=fmtp:18 annexb=no (19) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Line: a=maxptime:250 (14) [Apr 26 16:43:06] VERBOSE[1632] logger.c: --- (13 headers 10 lines) --- [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Setting NAT on RTP to Off [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Allocating new SIP dialog for af638ffd-0404-1910-9650-00234d1569f6@VLASIS - INVITE (With RTP) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Apr 26 16:43:06] VERBOSE[1632] logger.c: Sending to 79.129.85.99 : 5060 (no NAT) [Apr 26 16:43:06] VERBOSE[1632] logger.c: Using INVITE request as basis request - af638ffd-0404-1910-9650-00234d1569f6@VLASIS [Apr 26 16:43:06] VERBOSE[1632] logger.c: Found peer 'test1' [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Setting NAT on RTP to Off [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Processing session-level SDP o=- 1303825381 1 IN IP4 79.129.85.99... UNSUPPORTED. [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Processing session-level SDP s=Open-Phone/3.8.0... UNSUPPORTED. [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Processing session-level SDP c=IN IP4 79.129.85.99... OK. [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Apr 26 16:43:06] VERBOSE[1632] logger.c: Found RTP audio format 18 [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Apr 26 16:43:06] VERBOSE[1632] logger.c: Found audio description format G729 for ID 18 [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000/1... OK. [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED. [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Processing media-level (audio) SDP a=maxptime:250... UNSUPPORTED. [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: T38 state changed to 0 on channel [Apr 26 16:43:06] VERBOSE[1632] logger.c: Capabilities: us - 0x108 (alaw|g729), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729) [Apr 26 16:43:06] VERBOSE[1632] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Our T38 capability = (0), peer T38 capability (0), joint T38 capability (0) [Apr 26 16:43:06] VERBOSE[1632] logger.c: Peer audio RTP is at port 79.129.85.99:5010 [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: We're settling with these formats: 0x100 (g729) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Checking SIP call limits for device test1 [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Updating call counter for incoming call [Apr 26 16:43:06] VERBOSE[1632] logger.c: Looking for 123456 in test (domain 192.168.253.201) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: *** Our native formats are 0x100 (g729) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: *** Joint capabilities are 0x100 (g729) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: *** Our capabilities are 0x108 (alaw|g729) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: This channel will not be able to handle video. [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: build_route: Contact hop: [Apr 26 16:43:06] VERBOSE[1632] logger.c: list_route: hop: [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: SIP/test1-00000000: New call is still down.... Trying... [Apr 26 16:43:06] VERBOSE[1632] logger.c: <--- Transmitting (NAT) to 79.129.85.99:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 79.129.85.99:5060;branch=z9hG4bKcf7f8ffd-0404-1910-9651-00234d1569f6;received=79.129.85.99;rport=5060 From: "4477840012155" ;tag=bb618ffd-0404-1910-9650-00234d1569f6 To: Call-ID: af638ffd-0404-1910-9650-00234d1569f6@VLASIS CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Length: 0 <------------> [Apr 26 16:43:06] DEBUG[1632] devicestate.c: Notification of state change to be queued on device/channel SIP/test1 [Apr 26 16:43:06] DEBUG[1636] pbx.c: Launching 'NoOp' [Apr 26 16:43:06] VERBOSE[1636] logger.c: -- Executing [123456@test:1] NoOp("SIP/test1-00000000", "") in new stack [Apr 26 16:43:06] DEBUG[1636] pbx.c: Launching 'Dial' [Apr 26 16:43:06] VERBOSE[1636] logger.c: -- Executing [123456@test:2] Dial("SIP/test1-00000000", "SIP/123456@PBX||") in new stack [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Asked to create a SIP channel with formats: 0x100 (g729) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Setting NAT on RTP to Off [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: *** Our native formats are 0x100 (g729) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: *** Our capabilities are 0x100 (g729) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: *** Our preferred formats from the incoming channel are 0x100 (g729) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: This channel will not be able to handle video. [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Early remote bridge setting SIP '1c7817e80bc8104c16b418943f771661@192.168.253.201' - Sending media to 79.129.85.99 [Apr 26 16:43:06] DEBUG[1636] rtp.c: Seeded SDP of 'SIP/PBX-00000001' with that of 'SIP/test1-00000000' [Apr 26 16:43:06] DEBUG[1636] channel.c: Not copying variable DIALEDTIME. [Apr 26 16:43:06] DEBUG[1636] channel.c: Not copying variable ANSWEREDTIME. [Apr 26 16:43:06] DEBUG[1636] channel.c: Not copying variable DIALEDPEERNAME. [Apr 26 16:43:06] DEBUG[1636] channel.c: Not copying variable DIALEDPEERNUMBER. [Apr 26 16:43:06] DEBUG[1636] channel.c: Not copying variable DIALSTATUS. [Apr 26 16:43:06] DEBUG[1636] channel.c: Not copying variable SIPCALLID. [Apr 26 16:43:06] DEBUG[1636] channel.c: Not copying variable SIPUSERAGENT. [Apr 26 16:43:06] DEBUG[1636] channel.c: Not copying variable SIPDOMAIN. [Apr 26 16:43:06] DEBUG[1636] channel.c: Not copying variable SIPURI. [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Outgoing Call for 123456 [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Updating call counter for outgoing call [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: ** Our capability: 0x100 (g729) Video flag: False [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: ** Our prefcodec: 0x100 (g729) [Apr 26 16:43:06] VERBOSE[1636] logger.c: Audio is at 192.168.253.201 port 14008 [Apr 26 16:43:06] VERBOSE[1636] logger.c: Adding codec 0x100 (g729) to SDP [Apr 26 16:43:06] VERBOSE[1636] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: -- Done with adding codecs to SDP [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Done building SDP. Settling with this capability: 0x100 (g729) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 0: INVITE sip:123456@79.129.85.104 SIP/2.0 (39) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.253.201:5060;branch=z9hG4bK134bcd88;rport (66) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 2: From: "4477840012155" ;tag=as4bf7b337 (72) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 3: To: (30) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 4: Contact: (44) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 5: Call-ID: 1c7817e80bc8104c16b418943f771661@192.168.253.201 (57) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 9: Date: Tue, 26 Apr 2011 13:43:06 GMT (35) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 11: Supported: replaces (19) [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Apr 26 16:43:06] VERBOSE[1636] logger.c: Reliably Transmitting (no NAT) to 79.129.85.104:5060: INVITE sip:123456@79.129.85.104 SIP/2.0 Via: SIP/2.0/UDP 192.168.253.201:5060;branch=z9hG4bK134bcd88;rport From: "4477840012155" ;tag=as4bf7b337 To: Contact: Call-ID: 1c7817e80bc8104c16b418943f771661@192.168.253.201 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Tue, 26 Apr 2011 13:43:06 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 260 v=0 o=root 1606 1606 IN IP4 79.129.85.99 s=session c=IN IP4 79.129.85.99 t=0 0 m=audio 5010 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Apr 26 16:43:06] VERBOSE[1636] logger.c: -- Called 123456@PBX [Apr 26 16:43:06] DEBUG[1608] devicestate.c: No provider found, checking channel drivers for SIP - test1 [Apr 26 16:43:06] DEBUG[1608] chan_sip.c: Checking device state for peer test1 [Apr 26 16:43:06] DEBUG[1608] devicestate.c: Changing state for SIP/test1 - state 1 (Not in use) [Apr 26 16:43:06] DEBUG[1631] app_queue.c: Device 'SIP/test1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 26 16:43:06] VERBOSE[1632] logger.c: <--- SIP read from 79.129.85.104:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 192.168.253.201:5060;branch=z9hG4bK134bcd88;received=79.129.85.100;rport=5060 From: "4477840012155" ;tag=as4bf7b337 To: ;tag=as44a94a1b Call-ID: 1c7817e80bc8104c16b418943f771661@192.168.253.201 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 <-------------> [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 0: SIP/2.0 404 Not Found (21) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.253.201:5060;branch=z9hG4bK134bcd88;received=79.129.85.100;rport=5060 (94) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 2: From: "4477840012155" ;tag=as4bf7b337 (72) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 3: To: ;tag=as44a94a1b (45) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 4: Call-ID: 1c7817e80bc8104c16b418943f771661@192.168.253.201 (57) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 8: Contact: (35) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 9: Content-Length: 0 (17) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 10: (0) [Apr 26 16:43:06] VERBOSE[1632] logger.c: --- (10 headers 0 lines) --- [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: = Found Their Call ID: 1c7817e80bc8104c16b418943f771661@192.168.253.201 Their Tag Our tag: as4bf7b337 [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Acked pending invite 102 [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #4 [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Stopping retransmission on '1c7817e80bc8104c16b418943f771661@192.168.253.201' of Request 102: Match Found [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: SIP response 404 to standard invite [Apr 26 16:43:06] VERBOSE[1632] logger.c: Transmitting (no NAT) to 79.129.85.104:5060: ACK sip:123456@79.129.85.104 SIP/2.0 Via: SIP/2.0/UDP 192.168.253.201:5060;branch=z9hG4bK134bcd88;rport From: "4477840012155" ;tag=as4bf7b337 To: ;tag=as44a94a1b Contact: Call-ID: 1c7817e80bc8104c16b418943f771661@192.168.253.201 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Setting SIP_ALREADYGONE on dialog 1c7817e80bc8104c16b418943f771661@192.168.253.201 [Apr 26 16:43:06] VERBOSE[1636] logger.c: -- SIP/PBX-00000001 is circuit-busy [Apr 26 16:43:06] DEBUG[1636] channel.c: Hanging up channel 'SIP/PBX-00000001' [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Hangup call SIP/PBX-00000001, SIP callid 1c7817e80bc8104c16b418943f771661@192.168.253.201) [Apr 26 16:43:06] DEBUG[1636] devicestate.c: Notification of state change to be queued on device/channel SIP/PBX [Apr 26 16:43:06] VERBOSE[1636] logger.c: == Everyone is busy/congested at this time (1:0/1/0) [Apr 26 16:43:06] DEBUG[1636] rtp.c: Channel '' has no RTP, not doing anything [Apr 26 16:43:06] DEBUG[1636] app_dial.c: Exiting with DIALSTATUS=CONGESTION. [Apr 26 16:43:06] VERBOSE[1636] logger.c: == Auto fallthrough, channel 'SIP/test1-00000000' status is 'CONGESTION' [Apr 26 16:43:06] VERBOSE[1636] logger.c: <--- Reliably Transmitting (NAT) to 79.129.85.99:5060 ---> SIP/2.0 503 Service Unavailable Via: SIP/2.0/UDP 79.129.85.99:5060;branch=z9hG4bKcf7f8ffd-0404-1910-9651-00234d1569f6;received=79.129.85.99;rport=5060 From: "4477840012155" ;tag=bb618ffd-0404-1910-9650-00234d1569f6 To: ;tag=as3c66f481 Call-ID: af638ffd-0404-1910-9650-00234d1569f6@VLASIS CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces X-Asterisk-HangupCause: Unallocated (unassigned) number X-Asterisk-HangupCauseCode: 1 Content-Length: 0 <------------> [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Setting SIP_ALREADYGONE on dialog af638ffd-0404-1910-9650-00234d1569f6@VLASIS [Apr 26 16:43:06] DEBUG[1636] channel.c: Soft-Hanging up channel 'SIP/test1-00000000' [Apr 26 16:43:06] DEBUG[1636] devicestate.c: Notification of state change to be queued on device/channel SIP/test1 [Apr 26 16:43:06] DEBUG[1636] channel.c: Soft-Hanging up channel 'SIP/test1-00000000' [Apr 26 16:43:06] DEBUG[1636] pbx.c: Launching 'Hangup' [Apr 26 16:43:06] VERBOSE[1636] logger.c: -- Executing [h@test:1] Hangup("SIP/test1-00000000", "17") in new stack [Apr 26 16:43:06] DEBUG[1636] pbx.c: Spawn extension (test,h,1) exited non-zero on 'SIP/test1-00000000' [Apr 26 16:43:06] VERBOSE[1636] logger.c: == Spawn extension (test, h, 1) exited non-zero on 'SIP/test1-00000000' [Apr 26 16:43:06] DEBUG[1636] channel.c: Hanging up channel 'SIP/test1-00000000' [Apr 26 16:43:06] DEBUG[1636] chan_sip.c: Hangup call SIP/test1-00000000, SIP callid af638ffd-0404-1910-9650-00234d1569f6@VLASIS) [Apr 26 16:43:06] DEBUG[1636] devicestate.c: Notification of state change to be queued on device/channel SIP/test1 [Apr 26 16:43:06] DEBUG[1608] devicestate.c: No provider found, checking channel drivers for SIP - PBX [Apr 26 16:43:06] DEBUG[1608] chan_sip.c: Checking device state for peer PBX [Apr 26 16:43:06] DEBUG[1608] devicestate.c: Changing state for SIP/PBX - state 1 (Not in use) [Apr 26 16:43:06] DEBUG[1608] devicestate.c: No provider found, checking channel drivers for SIP - test1 [Apr 26 16:43:06] DEBUG[1608] chan_sip.c: Checking device state for peer test1 [Apr 26 16:43:06] DEBUG[1608] devicestate.c: Changing state for SIP/test1 - state 1 (Not in use) [Apr 26 16:43:06] DEBUG[1608] devicestate.c: No provider found, checking channel drivers for SIP - test1 [Apr 26 16:43:06] DEBUG[1608] chan_sip.c: Checking device state for peer test1 [Apr 26 16:43:06] DEBUG[1608] devicestate.c: Changing state for SIP/test1 - state 1 (Not in use) [Apr 26 16:43:06] DEBUG[1631] app_queue.c: Device 'SIP/PBX' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 26 16:43:06] DEBUG[1631] app_queue.c: Device 'SIP/test1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 26 16:43:06] DEBUG[1631] app_queue.c: Device 'SIP/test1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 26 16:43:06] VERBOSE[1632] logger.c: <--- SIP read from 79.129.85.99:5060 ---> ACK sip:123456@192.168.253.201:5060 SIP/2.0 CSeq: 1 ACK Via: SIP/2.0/UDP 79.129.85.99:5060;branch=z9hG4bKcf7f8ffd-0404-1910-9651-00234d1569f6;rport From: "4477840012155" ;tag=bb618ffd-0404-1910-9650-00234d1569f6 Call-ID: af638ffd-0404-1910-9650-00234d1569f6@VLASIS To: ;tag=as3c66f481 Content-Length: 0 Max-Forwards: 70 <-------------> [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 0: ACK sip:123456@192.168.253.201:5060 SIP/2.0 (43) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 1: CSeq: 1 ACK (11) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 2: Via: SIP/2.0/UDP 79.129.85.99:5060;branch=z9hG4bKcf7f8ffd-0404-1910-9651-00234d1569f6;rport (91) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 3: From: "4477840012155" ;tag=bb618ffd-0404-1910-9650-00234d1569f6 (95) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 4: Call-ID: af638ffd-0404-1910-9650-00234d1569f6@VLASIS (52) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 5: To: ;tag=as3c66f481 (52) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 6: Content-Length: 0 (17) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 7: Max-Forwards: 70 (16) [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Header 8: (0) [Apr 26 16:43:06] VERBOSE[1632] logger.c: --- (8 headers 0 lines) --- [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: = No match Their Call ID: 1c7817e80bc8104c16b418943f771661@192.168.253.201 Their Tag as44a94a1b Our tag: as4bf7b337 [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: = Found Their Call ID: af638ffd-0404-1910-9650-00234d1569f6@VLASIS Their Tag bb618ffd-0404-1910-9650-00234d1569f6 Our tag: as3c66f481 [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #6 [Apr 26 16:43:06] DEBUG[1632] chan_sip.c: Stopping retransmission on 'af638ffd-0404-1910-9650-00234d1569f6@VLASIS' of Response 1: Match Found [Apr 26 16:43:06] VERBOSE[1632] logger.c: Really destroying SIP dialog '1c7817e80bc8104c16b418943f771661@192.168.253.201' Method: INVITE [Apr 26 16:43:06] VERBOSE[1632] logger.c: Really destroying SIP dialog 'af638ffd-0404-1910-9650-00234d1569f6@VLASIS' Method: ACK