[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: = No match Their Call ID: 333232837-5062-310@192.168.0.8 Their Tag 1036797295 Our tag: as5b7769e2
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: = No match Their Call ID: 1693981358-5068-505@192.168.0.7 Their Tag 692402733 Our tag: as170cc25e
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: = No match Their Call ID: 1394539361-5064-828@192.168.0.7 Their Tag 1627163612 Our tag: as5f15bf50
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: = No match Their Call ID: 1708030692-5060-122@192.168.0.8 Their Tag 52015999 Our tag: as24b80c2d
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Setting NAT on RTP to Off
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Setting NAT on UDPTL to Off
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Allocating new SIP dialog for 1547819775-5062-295@192.168.0.7 - INVITE (With RTP)
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Dec 12 16:38:36] DEBUG[22160] acl.c: ##### Testing 192.168.0.7 with 0.0.0.0
[Dec 12 16:38:36] DEBUG[22160] acl.c: ##### Testing 192.168.0.7 with 192.168.0.0
[Dec 12 16:38:36] DEBUG[22160] acl.c: ##### Testing 192.168.0.7 with 10.0.0.0
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Setting NAT on RTP to On
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Setting NAT on UDPTL to On
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: = Found Their Call ID: 1547819775-5062-295@192.168.0.7 Their Tag 2074339809 Our tag: as2515e4b3
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Stopping retransmission on '1547819775-5062-295@192.168.0.7' of Response 2940: Match Found
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: = Found Their Call ID: 1547819775-5062-295@192.168.0.7 Their Tag 2074339809 Our tag: as2515e4b3
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Dec 12 16:38:36] DEBUG[22160] acl.c: ##### Testing 192.168.0.7 with 0.0.0.0
[Dec 12 16:38:36] DEBUG[22160] acl.c: ##### Testing 192.168.0.7 with 192.168.0.0
[Dec 12 16:38:36] DEBUG[22160] acl.c: ##### Testing 192.168.0.7 with 10.0.0.0
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Setting NAT on RTP to On
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Setting NAT on UDPTL to On
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing session-level SDP o=11 8002 8000 IN IP4 192.168.0.7... UNSUPPORTED.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.0.7... OK.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:4 G723/8000... OK.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 iLBC/8000... OK.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=fmtp:97 mode=20... UNSUPPORTED.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:102 G729E/8000... UNSUPPORTED.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:100 AAL2-G726-16/8000... UNSUPPORTED.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16,32-36,54... UNSUPPORTED.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: T38 state changed to 0 on channel <none>
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw)
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Checking SIP call limits for device 11
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Updating call counter for incoming call
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: Call from peer '11' is 1 out of 5
[Dec 12 16:38:36] DEBUG[22160] devicestate.c: Notification of state change to be queued on device/channel SIP/11
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: *** Our native formats are 0x8 (alaw) 
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) 
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: *** Our capabilities are 0xe (gsm|ulaw|alaw) 
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: This channel will not be able to handle video.
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: build_route: Contact hop: <sip:11@192.168.0.7:5062>
[Dec 12 16:38:36] DEBUG[21542] devicestate.c: No provider found, checking channel drivers for SIP - 11
[Dec 12 16:38:36] DEBUG[22160] chan_sip.c: SIP/11-000001d3: New call is still down.... Trying... 
[Dec 12 16:38:36] DEBUG[21542] chan_sip.c: Checking device state for peer 11
[Dec 12 16:38:36] DEBUG[21542] devicestate.c: Changing state for SIP/11 - state 2 (In use)
[Dec 12 16:38:36] DEBUG[22160] devicestate.c: Notification of state change to be queued on device/channel SIP/11
[Dec 12 16:38:36] DEBUG[21542] devicestate.c: No provider found, checking channel drivers for SIP - 11
[Dec 12 16:38:36] DEBUG[21542] chan_sip.c: Checking device state for peer 11
[Dec 12 16:38:36] DEBUG[21542] devicestate.c: No provider found, checking channel drivers for SIP - 11
[Dec 12 16:38:36] DEBUG[21542] chan_sip.c: Checking device state for peer 11
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Launching 'Set'
[Dec 12 16:38:36] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:1] Set("SIP/11-000001d3", "CALLERID(num)=0229871197") in new stack
[Dec 12 16:38:36] DEBUG[22208] app_queue.c: Device 'SIP/11' changed to state '2' (In use)
[Dec 12 16:38:36] DEBUG[21542] devicestate.c: Changing state for SIP/11 - state 2 (In use)
[Dec 12 16:38:36] DEBUG[21542] devicestate.c: No provider found, checking channel drivers for SIP - 11
[Dec 12 16:38:36] DEBUG[21542] chan_sip.c: Checking device state for peer 11
[Dec 12 16:38:36] DEBUG[22208] app_queue.c: Device 'SIP/11' changed to state '2' (In use)
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Launching 'misdn_check_l2l1'
[Dec 12 16:38:36] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:2] misdn_check_l2l1("SIP/11-000001d3", "g:isdn-port-two|1") in new stack
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Launching 'Dial'
[Dec 12 16:38:36] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:3] Dial("SIP/11-000001d3", "mISDN/g:isdn-port-two/253607230||TW") in new stack
[Dec 12 16:38:36] WARNING[24376] chan_misdn.c: Could not Dial out on group 'isdn-port-two'.
[Dec 12 16:38:36] WARNING[24376] app_dial.c: Unable to create channel of type 'mISDN' (cause 0 - Unknown)
[Dec 12 16:38:36] VERBOSE[24376] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Dec 12 16:38:36] DEBUG[24376] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Dec 12 16:38:36] DEBUG[24376] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Launching 'NoOp'
[Dec 12 16:38:36] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:4] NoOp("SIP/11-000001d3", "DIALSTATUS: CHANUNAVAIL") in new stack
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Expression result is '0'
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Launching 'GotoIf'
[Dec 12 16:38:36] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:5] GotoIf("SIP/11-000001d3", "0?user-unavailable|s|1") in new stack
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Not taking any branch
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Expression result is '0'
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Launching 'GotoIf'
[Dec 12 16:38:36] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:6] GotoIf("SIP/11-000001d3", "0?user-unavailable|s|1") in new stack
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Not taking any branch
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Launching 'misdn_check_l2l1'
[Dec 12 16:38:36] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:7] misdn_check_l2l1("SIP/11-000001d3", "g:isdn-port-one|1") in new stack
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Launching 'Dial'
[Dec 12 16:38:36] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:8] Dial("SIP/11-000001d3", "mISDN/g:isdn-port-one/253607230||TW") in new stack
[Dec 12 16:38:36] WARNING[24376] chan_misdn.c: Could not Dial out on group 'isdn-port-one'.
[Dec 12 16:38:36] WARNING[24376] app_dial.c: Unable to create channel of type 'mISDN' (cause 0 - Unknown)
[Dec 12 16:38:36] VERBOSE[24376] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Dec 12 16:38:36] DEBUG[24376] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Dec 12 16:38:36] DEBUG[24376] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Launching 'NoOp'
[Dec 12 16:38:36] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:9] NoOp("SIP/11-000001d3", "DIALSTATUS: CHANUNAVAIL") in new stack
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Expression result is '0'
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Launching 'GotoIf'
[Dec 12 16:38:36] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:10] GotoIf("SIP/11-000001d3", "0?user-unavailable|s|1") in new stack
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Not taking any branch
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Expression result is '0'
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Launching 'GotoIf'
[Dec 12 16:38:36] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:11] GotoIf("SIP/11-000001d3", "0?user-unavailable|s|1") in new stack
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Not taking any branch
[Dec 12 16:38:36] DEBUG[24376] pbx.c: Launching 'misdn_check_l2l1'
[Dec 12 16:38:36] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:12] misdn_check_l2l1("SIP/11-000001d3", "g:isdn-port-three|1") in new stack
[Dec 12 16:38:37] DEBUG[24376] pbx.c: Launching 'Dial'
[Dec 12 16:38:37] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:13] Dial("SIP/11-000001d3", "mISDN/g:isdn-port-three/253607230||TW") in new stack
[Dec 12 16:38:37] DEBUG[24376] rtp.c: Channel 'mISDN/4-u1111' has no RTP, not doing anything
[Dec 12 16:38:37] DEBUG[24376] channel.c: Not copying variable DIALEDTIME.
[Dec 12 16:38:37] DEBUG[24376] channel.c: Not copying variable ANSWEREDTIME.
[Dec 12 16:38:37] DEBUG[24376] channel.c: Not copying variable DIALEDPEERNAME.
[Dec 12 16:38:37] DEBUG[24376] channel.c: Not copying variable DIALEDPEERNUMBER.
[Dec 12 16:38:37] DEBUG[24376] channel.c: Not copying variable DIALSTATUS.
[Dec 12 16:38:37] DEBUG[24376] channel.c: Not copying variable SIPCALLID.
[Dec 12 16:38:37] DEBUG[24376] channel.c: Not copying variable SIPUSERAGENT.
[Dec 12 16:38:37] DEBUG[24376] channel.c: Not copying variable SIPDOMAIN.
[Dec 12 16:38:37] DEBUG[24376] channel.c: Not copying variable SIPURI.
[Dec 12 16:38:37] DEBUG[24376] devicestate.c: Notification of state change to be queued on device/channel mISDN/4
[Dec 12 16:38:37] VERBOSE[24376] logger.c:     -- Called g:isdn-port-three/253607230
[Dec 12 16:38:37] DEBUG[21542] devicestate.c: No provider found, checking channel drivers for mISDN - 4
[Dec 12 16:38:37] DEBUG[21542] channel.c: Avoiding initial deadlock for channel '0xb3401c00'
[Dec 12 16:38:37] DEBUG[21542] devicestate.c: Changing state for mISDN/4 - state 2 (In use)
[Dec 12 16:38:37] DEBUG[22208] app_queue.c: Device 'mISDN/4' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec 12 16:38:37] DEBUG[21726] devicestate.c: Notification of state change to be queued on device/channel mISDN/1
[Dec 12 16:38:37] DEBUG[21542] devicestate.c: No provider found, checking channel drivers for mISDN - 1
[Dec 12 16:38:37] DEBUG[21542] devicestate.c: Changing state for mISDN/1 - state 6 (Ringing)
[Dec 12 16:38:37] DEBUG[22208] app_queue.c: Device 'mISDN/1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Dec 12 16:38:37] VERBOSE[24375] logger.c:     -- mISDN/1-u1112 is ringing
[Dec 12 16:38:37] DEBUG[24375] rtp.c: Channel 'mISDN/1-u1112' has no RTP, not doing anything
[Dec 12 16:38:43] DEBUG[24376] channel.c: Hanging up channel 'mISDN/4-u1111'
[Dec 12 16:38:43] DEBUG[24376] chan_misdn.c: misdn_hangup(mISDN/4-u1111)
[Dec 12 16:38:43] DEBUG[24376] devicestate.c: Notification of state change to be queued on device/channel mISDN/4
[Dec 12 16:38:43] VERBOSE[24376] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Dec 12 16:38:43] DEBUG[24376] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Dec 12 16:38:43] DEBUG[24376] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Dec 12 16:38:43] DEBUG[24376] pbx.c: Launching 'NoOp'
[Dec 12 16:38:43] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:14] NoOp("SIP/11-000001d3", "DIALSTATUS: CHANUNAVAIL") in new stack
[Dec 12 16:38:43] DEBUG[24376] pbx.c: Expression result is '0'
[Dec 12 16:38:43] DEBUG[24376] pbx.c: Launching 'GotoIf'
[Dec 12 16:38:43] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:15] GotoIf("SIP/11-000001d3", "0?user-unavailable|s|1") in new stack
[Dec 12 16:38:43] DEBUG[24376] pbx.c: Not taking any branch
[Dec 12 16:38:43] DEBUG[24376] pbx.c: Expression result is '0'
[Dec 12 16:38:43] DEBUG[24376] pbx.c: Launching 'GotoIf'
[Dec 12 16:38:43] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:16] GotoIf("SIP/11-000001d3", "0?user-unavailable|s|1") in new stack
[Dec 12 16:38:43] DEBUG[24376] pbx.c: Not taking any branch
[Dec 12 16:38:43] DEBUG[24376] pbx.c: Launching 'Goto'
[Dec 12 16:38:43] VERBOSE[24376] logger.c:     -- Executing [0253607230@Ext_11:17] Goto("SIP/11-000001d3", "chan-unavailable|s|1") in new stack
[Dec 12 16:38:43] VERBOSE[24376] logger.c:     -- Goto (chan-unavailable,s,1)
[Dec 12 16:38:43] DEBUG[24376] pbx.c: Launching 'ResetCDR'
[Dec 12 16:38:43] VERBOSE[24376] logger.c:     -- Executing [s@chan-unavailable:1] ResetCDR("SIP/11-000001d3", "w") in new stack
[Dec 12 16:38:43] DEBUG[21542] devicestate.c: No provider found, checking channel drivers for mISDN - 4
[Dec 12 16:38:43] DEBUG[21542] devicestate.c: Changing state for mISDN/4 - state 6 (Ringing)
[Dec 12 16:38:43] DEBUG[22208] app_queue.c: Device 'mISDN/4' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Dec 12 16:38:43] DEBUG[21726] devicestate.c: Notification of state change to be queued on device/channel mISDN/4
[Dec 12 16:38:43] DEBUG[21542] devicestate.c: No provider found, checking channel drivers for mISDN - 4
[Dec 12 16:38:43] DEBUG[21542] devicestate.c: Changing state for mISDN/4 - state 6 (Ringing)
[Dec 12 16:38:43] DEBUG[22208] app_queue.c: Device 'mISDN/4' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.