[2012-10-05 10:43:22] VERBOSE[26144] config.c: == Parsing '/etc/asterisk/logger.conf': [2012-10-05 10:43:22] VERBOSE[26144] config.c: == Found [2012-10-05 10:43:22] VERBOSE[26144] logger.c: Asterisk Queue Logger restarted [2012-10-05 10:43:46] DEBUG[19205] chan_iax2.c: ip callno count incremented to 2 for 172.20.250.91 [2012-10-05 10:43:46] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:43:46] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:43:46] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:43:46] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 0 (Unknown) [2012-10-05 10:43:46] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '0' [2012-10-05 10:43:46] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:43:46] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:43:46] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:43:46] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:43:46] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 0 (Unknown) [2012-10-05 10:43:46] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '0' [2012-10-05 10:43:46] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:43:46] DEBUG[19208] chan_iax2.c: schedule decrement of callno used for 172.20.250.91 in 60 seconds [2012-10-05 10:43:47] DEBUG[19200] chan_sip.c: Allocating new SIP dialog for 712b961205e9e2a330093962506ab2f2@172.20.250.12:5060 - OPTIONS (No RTP) [2012-10-05 10:43:47] DEBUG[19200] acl.c: For destination '200.155.5.83', our source address is '172.20.250.12'. [2012-10-05 10:43:47] DEBUG[19200] chan_sip.c: Target address 200.155.5.83:5060 is not local, substituting externaddr [2012-10-05 10:43:47] DEBUG[19200] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 189.108.207.226:5060 [2012-10-05 10:43:47] DEBUG[19200] chan_sip.c: Initializing initreq for method OPTIONS - callid 10caf307622e9db3568bd52461091b15@189.108.207.226:5060 [2012-10-05 10:43:47] DEBUG[19200] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 200.155.5.83:5060 [2012-10-05 10:43:47] DEBUG[19200] chan_sip.c: = Looking for Call ID: 10caf307622e9db3568bd52461091b15@189.108.207.226:5060 (Checking To) --From tag as2230d425 --To-tag as1ed59161 [2012-10-05 10:43:47] DEBUG[19200] chan_sip.c: Stopping retransmission on '10caf307622e9db3568bd52461091b15@189.108.207.226:5060' of Request 102: Match Found [2012-10-05 10:43:47] DEBUG[19200] chan_sip.c: Destroying SIP dialog 10caf307622e9db3568bd52461091b15@189.108.207.226:5060 [2012-10-05 10:44:01] DEBUG[19203] chan_iax2.c: ip callno count decremented to 1 for 172.20.250.91 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 3 [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 2 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: Allocating new SIP dialog for 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 - REGISTER (No RTP) [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 3 [2012-10-05 10:44:22] DEBUG[19200] acl.c: For destination '200.155.5.83', our source address is '172.20.250.12'. [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: Target address 200.155.5.83:5060 is not local, substituting externaddr [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 189.108.207.226:5060 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 4 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: Scheduled a registration timeout for 200.155.5.83 id #15436 [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: Initializing initreq for method REGISTER - callid 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: REGISTER attempt 1 to 110215@200.155.5.83 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 200.155.5.83:5060 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 3 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: = Looking for Call ID: 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 (Checking To) --From tag as3bfecf92 --To-tag [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: = Looking for Call ID: 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 (Checking To) --From tag as3bfecf92 --To-tag as1de17a72 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: Stopping retransmission on '3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12' of Request 3091: Match Found [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 4 [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 3 [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:44:22] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: Initializing already initialized SIP dialog 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 (presumably reinvite) [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: REGISTER attempt 2 to 110215@200.155.5.83 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 200.155.5.83:5060 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: = Looking for Call ID: 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 (Checking To) --From tag as789d4349 --To-tag [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: = Looking for Call ID: 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 (Checking To) --From tag as789d4349 --To-tag as1de17a72 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: Stopping retransmission on '3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12' of Request 3092: Match Found [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: Registration successful [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: Cancelling timeout 15436 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 2 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 1 [2012-10-05 10:44:22] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 2 [2012-10-05 10:44:31] DEBUG[19212] chan_iax2.c: ip callno count incremented to 2 for 172.20.250.91 [2012-10-05 10:44:31] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:44:31] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:44:31] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:44:31] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 0 (Unknown) [2012-10-05 10:44:31] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '0' [2012-10-05 10:44:31] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:44:31] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:44:31] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:44:31] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:44:31] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 0 (Unknown) [2012-10-05 10:44:31] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '0' [2012-10-05 10:44:31] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:44:31] DEBUG[19204] chan_iax2.c: schedule decrement of callno used for 172.20.250.91 in 60 seconds [2012-10-05 10:44:46] DEBUG[19203] chan_iax2.c: ip callno count decremented to 1 for 172.20.250.91 [2012-10-05 10:44:47] DEBUG[19200] chan_sip.c: Allocating new SIP dialog for 49e62e886dd762417e2603b96cc94ab7@172.20.250.12:5060 - OPTIONS (No RTP) [2012-10-05 10:44:47] DEBUG[19200] acl.c: For destination '200.155.5.83', our source address is '172.20.250.12'. [2012-10-05 10:44:47] DEBUG[19200] chan_sip.c: Target address 200.155.5.83:5060 is not local, substituting externaddr [2012-10-05 10:44:47] DEBUG[19200] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 189.108.207.226:5060 [2012-10-05 10:44:47] DEBUG[19200] chan_sip.c: Initializing initreq for method OPTIONS - callid 0cfe973a14fbaca94fb5518c177c1474@189.108.207.226:5060 [2012-10-05 10:44:47] DEBUG[19200] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 200.155.5.83:5060 [2012-10-05 10:44:47] DEBUG[19200] chan_sip.c: = Looking for Call ID: 0cfe973a14fbaca94fb5518c177c1474@189.108.207.226:5060 (Checking To) --From tag as60b9e7f9 --To-tag as33635427 [2012-10-05 10:44:47] DEBUG[19200] chan_sip.c: Stopping retransmission on '0cfe973a14fbaca94fb5518c177c1474@189.108.207.226:5060' of Request 102: Match Found [2012-10-05 10:44:47] DEBUG[19200] chan_sip.c: Destroying SIP dialog 0cfe973a14fbaca94fb5518c177c1474@189.108.207.226:5060 [2012-10-05 10:44:49] DEBUG[19208] chan_iax2.c: ip callno count incremented to 2 for 172.20.250.91 [2012-10-05 10:44:49] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:44:49] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:44:49] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:44:49] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 0 (Unknown) [2012-10-05 10:44:49] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '0' [2012-10-05 10:44:49] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:44:49] DEBUG[19209] chan_iax2.c: peercnt entry 172.20.250.91 modified limit:2048 registered:0[2012-10-05 10:44:49] VERBOSE[19209] chan_iax2.c: -- Unregistered IAX2 '3331' (AUTHENTICATED) [2012-10-05 10:44:49] DEBUG[19209] devicestate.c: device 'IAX2/3331' state '5' [2012-10-05 10:44:49] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [2012-10-05 10:44:49] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:44:49] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:44:49] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=0, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:44:49] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 5 (Unavailable) [2012-10-05 10:44:49] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '5' [2012-10-05 10:44:49] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [2012-10-05 10:44:49] DEBUG[19210] chan_iax2.c: schedule decrement of callno used for 172.20.250.91 in 60 seconds [2012-10-05 10:44:50] DEBUG[19212] chan_iax2.c: ip callno count incremented to 3 for 172.20.250.91 [2012-10-05 10:44:50] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:44:50] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:44:50] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=0, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:44:50] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 5 (Unavailable) [2012-10-05 10:44:50] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '5' [2012-10-05 10:44:50] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [2012-10-05 10:44:50] VERBOSE[19213] chan_iax2.c: -- Registered IAX2 '3331' (AUTHENTICATED) at 172.20.250.91:4569 [2012-10-05 10:44:50] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:44:50] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:44:50] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:44:50] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 0 (Unknown) [2012-10-05 10:44:50] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '0' [2012-10-05 10:44:50] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:44:50] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:44:50] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:44:50] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 0 (Unknown) [2012-10-05 10:44:50] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '0' [2012-10-05 10:44:50] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:44:50] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:44:50] DEBUG[19204] chan_iax2.c: schedule decrement of callno used for 172.20.250.91 in 60 seconds [2012-10-05 10:44:54] DEBUG[19200] chan_sip.c: Auto destroying SIP dialog '3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12' [2012-10-05 10:44:54] DEBUG[19200] chan_sip.c: Destroying SIP dialog 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 [2012-10-05 10:45:05] DEBUG[19210] chan_iax2.c: ip callno count incremented to 1 for 172.20.250.101 [2012-10-05 10:45:05] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3332 [2012-10-05 10:45:05] DEBUG[19191] chan_iax2.c: Checking device state for device 3332 [2012-10-05 10:45:05] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3332? addr=0, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:45:05] DEBUG[19191] devicestate.c: Changing state for IAX2/3332 - state 5 (Unavailable) [2012-10-05 10:45:05] DEBUG[19191] devicestate.c: device 'IAX2/3332' state '5' [2012-10-05 10:45:05] DEBUG[19224] app_queue.c: Device 'IAX2/3332' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [2012-10-05 10:45:05] VERBOSE[19211] chan_iax2.c: -- Registered IAX2 '3332' (AUTHENTICATED) at 172.20.250.101:4569 [2012-10-05 10:45:05] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3332 [2012-10-05 10:45:05] DEBUG[19191] chan_iax2.c: Checking device state for device 3332 [2012-10-05 10:45:05] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3332? addr=-1407911323, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:45:05] DEBUG[19191] devicestate.c: Changing state for IAX2/3332 - state 0 (Unknown) [2012-10-05 10:45:05] DEBUG[19191] devicestate.c: device 'IAX2/3332' state '0' [2012-10-05 10:45:05] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3332 [2012-10-05 10:45:05] DEBUG[19191] chan_iax2.c: Checking device state for device 3332 [2012-10-05 10:45:05] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3332? addr=-1407911323, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:45:05] DEBUG[19191] devicestate.c: Changing state for IAX2/3332 - state 0 (Unknown) [2012-10-05 10:45:05] DEBUG[19191] devicestate.c: device 'IAX2/3332' state '0' [2012-10-05 10:45:05] DEBUG[19224] app_queue.c: Device 'IAX2/3332' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:45:05] DEBUG[19224] app_queue.c: Device 'IAX2/3332' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:45:05] DEBUG[19212] chan_iax2.c: schedule decrement of callno used for 172.20.250.101 in 60 seconds [2012-10-05 10:45:12] DEBUG[19205] chan_iax2.c: ip callno count incremented to 4 for 172.20.250.91 [2012-10-05 10:45:12] VERBOSE[19207] chan_iax2.c: -- Accepting AUTHENTICATED call from 172.20.250.91: > requested format = gsm, > requested prefs = (), > actual format = gsm, > host prefs = (gsm), > priority = mine [2012-10-05 10:45:12] DEBUG[26164] pbx.c: Launching 'Answer' [2012-10-05 10:45:12] VERBOSE[26164] pbx.c: -- Executing [3332@default:1] Answer("IAX2/3331-4800", "") in new stack [2012-10-05 10:45:12] DEBUG[26164] chan_iax2.c: Answering IAX2 call [2012-10-05 10:45:12] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:45:12] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:45:12] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:45:12] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 2 (In use) [2012-10-05 10:45:12] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '2' [2012-10-05 10:45:12] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-10-05 10:45:12] DEBUG[19211] chan_iax2.c: Ooh, voice format changed to 'gsm' [2012-10-05 10:45:12] DEBUG[26164] pbx.c: Launching 'Playback' [2012-10-05 10:45:12] VERBOSE[26164] pbx.c: -- Executing [3332@default:2] Playback("IAX2/3331-4800", "beep") in new stack [2012-10-05 10:45:12] DEBUG[26164] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2012-10-05 10:45:12] VERBOSE[26164] file.c: -- Playing 'beep.gsm' (language 'br') [2012-10-05 10:45:12] DEBUG[26164] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-10-05 10:45:12] DEBUG[26164] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-10-05 10:45:12] DEBUG[26164] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-10-05 10:45:12] DEBUG[26164] pbx.c: Launching 'Monitor' [2012-10-05 10:45:12] VERBOSE[26164] pbx.c: -- Executing [3332@default:3] Monitor("IAX2/3331-4800", "wav,first_monitor_file_in_only,o") in new stack [2012-10-05 10:45:12] DEBUG[26164] pbx.c: Launching 'Wait' [2012-10-05 10:45:12] VERBOSE[26164] pbx.c: -- Executing [3332@default:4] Wait("IAX2/3331-4800", "10") in new stack [2012-10-05 10:45:22] DEBUG[26164] pbx.c: Launching 'StopMonitor' [2012-10-05 10:45:22] VERBOSE[26164] pbx.c: -- Executing [3332@default:5] StopMonitor("IAX2/3331-4800", "") in new stack [2012-10-05 10:45:22] DEBUG[26164] pbx.c: Launching 'Monitor' [2012-10-05 10:45:22] VERBOSE[26164] pbx.c: -- Executing [3332@default:6] Monitor("IAX2/3331-4800", "wav,second_monitor_file_mix,m") in new stack [2012-10-05 10:45:22] DEBUG[26164] pbx.c: Result of 'EXTEN' is '3332' [2012-10-05 10:45:22] DEBUG[26164] pbx.c: Launching 'Dial' [2012-10-05 10:45:22] VERBOSE[26164] pbx.c: -- Executing [3332@default:7] Dial("IAX2/3331-4800", "IAX2/3332") in new stack [2012-10-05 10:45:22] DEBUG[26164] chan_iax2.c: ip callno count incremented to 2 for 172.20.250.101 [2012-10-05 10:45:22] DEBUG[26164] rtp_engine.c: Can't find native functions for channel 'IAX2/3332-9931' [2012-10-05 10:45:22] DEBUG[26164] rtp_engine.c: Seeded SDP of 'IAX2/3332-9931' with that of 'IAX2/3331-4800' [2012-10-05 10:45:22] DEBUG[26164] channel.c: Not copying variable DIALEDTIME. [2012-10-05 10:45:22] DEBUG[26164] channel.c: Not copying variable ANSWEREDTIME. [2012-10-05 10:45:22] DEBUG[26164] channel.c: Not copying variable DIALEDPEERNAME. [2012-10-05 10:45:22] DEBUG[26164] channel.c: Not copying variable DIALEDPEERNUMBER. [2012-10-05 10:45:22] DEBUG[26164] channel.c: Not copying variable DIALSTATUS. [2012-10-05 10:45:22] DEBUG[26164] channel.c: Copying hard-transferable variable MONITORED. [2012-10-05 10:45:22] DEBUG[26164] channel.c: Not copying variable PLAYBACKSTATUS. [2012-10-05 10:45:22] DEBUG[26164] chan_iax2.c: prepending 2 to prefs [2012-10-05 10:45:22] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3332 [2012-10-05 10:45:22] DEBUG[19191] chan_iax2.c: Checking device state for device 3332 [2012-10-05 10:45:22] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3332? addr=-1407911323, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:45:22] DEBUG[19191] devicestate.c: Changing state for IAX2/3332 - state 6 (Ringing) [2012-10-05 10:45:22] DEBUG[19191] devicestate.c: device 'IAX2/3332' state '6' [2012-10-05 10:45:22] DEBUG[19224] app_queue.c: Device 'IAX2/3332' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [2012-10-05 10:45:22] VERBOSE[26164] app_dial.c: -- Called IAX2/3332 [2012-10-05 10:45:22] VERBOSE[19211] chan_iax2.c: -- Call accepted by 172.20.250.101 (format gsm) [2012-10-05 10:45:22] VERBOSE[19211] chan_iax2.c: -- Format for call is gsm [2012-10-05 10:45:22] VERBOSE[26164] app_dial.c: -- IAX2/3332-9931 is ringing [2012-10-05 10:45:25] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3332 [2012-10-05 10:45:25] DEBUG[19191] chan_iax2.c: Checking device state for device 3332 [2012-10-05 10:45:25] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3332? addr=-1407911323, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:45:25] DEBUG[19191] devicestate.c: Changing state for IAX2/3332 - state 2 (In use) [2012-10-05 10:45:25] DEBUG[19191] devicestate.c: device 'IAX2/3332' state '2' [2012-10-05 10:45:25] DEBUG[19224] app_queue.c: Device 'IAX2/3332' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-10-05 10:45:25] VERBOSE[26164] app_dial.c: -- IAX2/3332-9931 answered IAX2/3331-4800 [2012-10-05 10:45:25] DEBUG[26164] features.c: bridge answer set, chan answer set [2012-10-05 10:45:25] DEBUG[26164] features.c: Removing dialed interfaces datastore on IAX2/3332-9931 since we're bridging [2012-10-05 10:45:25] DEBUG[19204] chan_iax2.c: Ooh, voice format changed to 'gsm' [2012-10-05 10:45:31] DEBUG[19203] chan_iax2.c: ip callno count decremented to 3 for 172.20.250.91 [2012-10-05 10:45:33] DEBUG[19212] chan_iax2.c: JB STATS:IAX2/3331-4800 ping=3 ljitterms=-1 ljbdelayms=0 ltotlost=-1 lrecentlosspct=-1 ldropped=0 looo=-1 lrecvd=-1 rjitterms=0 rjbdelayms=0 rtotlost=0 rrecentlosspct=0 rdropped=0 rooo=0 rrecvd=0 [2012-10-05 10:45:35] DEBUG[19212] chan_iax2.c: ip callno count incremented to 4 for 172.20.250.91 [2012-10-05 10:45:35] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:45:35] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:45:35] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:45:35] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 2 (In use) [2012-10-05 10:45:35] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '2' [2012-10-05 10:45:35] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-10-05 10:45:35] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:45:35] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:45:35] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:45:35] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 2 (In use) [2012-10-05 10:45:35] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '2' [2012-10-05 10:45:35] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-10-05 10:45:35] DEBUG[19206] chan_iax2.c: schedule decrement of callno used for 172.20.250.91 in 60 seconds [2012-10-05 10:45:43] DEBUG[19204] chan_iax2.c: JB STATS:IAX2/3332-9931 ping=6 ljitterms=-1 ljbdelayms=0 ltotlost=-1 lrecentlosspct=-1 ldropped=0 looo=-1 lrecvd=-1 rjitterms=0 rjbdelayms=0 rtotlost=0 rrecentlosspct=0 rdropped=0 rooo=0 rrecvd=0 [2012-10-05 10:45:44] DEBUG[19209] chan_iax2.c: Immediately destroying 4800, having received hangup [2012-10-05 10:45:44] DEBUG[26164] channel.c: Didn't get a frame from channel: IAX2/3331-4800 [2012-10-05 10:45:44] DEBUG[26164] channel.c: Bridge stops bridging channels IAX2/3331-4800 and IAX2/3332-9931 [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is '2012-10-05 10:45:12' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is '3331' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is 'default' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is 'IAX2/3331-4800' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is 'IAX2/3332-9931' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is 'Dial' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is 'IAX2/3332' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is '32' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is '19' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is 'ANSWERED' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is 'DOCUMENTATION' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is '(null)' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is '1349444712.12' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is '(null)' [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Function result is '(null)' [2012-10-05 10:45:44] DEBUG[26164] cdr_sqlite3_custom.c: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2012-10-05 10:45:12','3331','default','IAX2/3331-4800','IAX2/3332-9931','Dial','IAX2/3332','32','19','ANSWERED','DOCUMENTATION','','1349444712.12','','') [2012-10-05 10:45:44] DEBUG[26164] channel.c: Hanging up channel 'IAX2/3332-9931' [2012-10-05 10:45:44] DEBUG[26164] chan_iax2.c: We're hanging up IAX2/3332-9931 now... [2012-10-05 10:45:44] VERBOSE[26164] chan_iax2.c: -- Hungup 'IAX2/3332-9931' [2012-10-05 10:45:44] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3332 [2012-10-05 10:45:44] DEBUG[19191] chan_iax2.c: Checking device state for device 3332 [2012-10-05 10:45:44] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3332? addr=-1407911323, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:45:44] DEBUG[19191] devicestate.c: Changing state for IAX2/3332 - state 0 (Unknown) [2012-10-05 10:45:44] DEBUG[19191] devicestate.c: device 'IAX2/3332' state '0' [2012-10-05 10:45:44] DEBUG[19224] app_queue.c: Device 'IAX2/3332' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:45:44] DEBUG[26164] app_dial.c: Exiting with DIALSTATUS=ANSWER. [2012-10-05 10:45:44] DEBUG[26164] pbx.c: Spawn extension (default,3332,7) exited non-zero on 'IAX2/3331-4800' [2012-10-05 10:45:44] VERBOSE[26164] pbx.c: == Spawn extension (default, 3332, 7) exited non-zero on 'IAX2/3331-4800' [2012-10-05 10:45:44] DEBUG[26164] channel.c: Soft-Hanging up channel 'IAX2/3331-4800' [2012-10-05 10:45:44] DEBUG[26164] channel.c: Hanging up channel 'IAX2/3331-4800' [2012-10-05 10:45:44] DEBUG[26164] chan_iax2.c: We're hanging up IAX2/3331-4800 now... [2012-10-05 10:45:44] DEBUG[26164] chan_iax2.c: Really destroying IAX2/3331-4800 now... [2012-10-05 10:45:44] DEBUG[26164] chan_iax2.c: schedule decrement of callno used for 172.20.250.91 in 60 seconds [2012-10-05 10:45:44] VERBOSE[26164] chan_iax2.c: -- Hungup 'IAX2/3331-4800' [2012-10-05 10:45:44] DEBUG[26164] res_monitor.c: monitor executing ( nice -n 19 sox -m "/var/spool/asterisk/monitor/second_monitor_file_mix-in.wav" "/var/spool/asterisk/monitor/second_monitor_file_mix-out.wav" "/var/spool/asterisk/monitor/second_monitor_file_mix.wav" && rm -f "/var/spool/asterisk/monitor/second_monitor_file_mix-"* ) & [2012-10-05 10:45:44] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:45:44] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:45:44] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:45:44] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 0 (Unknown) [2012-10-05 10:45:44] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '0' [2012-10-05 10:45:44] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:45:44] DEBUG[19214] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [2012-10-05 10:45:44] DEBUG[19212] chan_iax2.c: schedule decrement of callno used for 172.20.250.101 in 60 seconds [2012-10-05 10:45:47] DEBUG[19200] chan_sip.c: Allocating new SIP dialog for 603995da64c710a56349a53e34a54990@172.20.250.12:5060 - OPTIONS (No RTP) [2012-10-05 10:45:47] DEBUG[19200] acl.c: For destination '200.155.5.83', our source address is '172.20.250.12'. [2012-10-05 10:45:47] DEBUG[19200] chan_sip.c: Target address 200.155.5.83:5060 is not local, substituting externaddr [2012-10-05 10:45:47] DEBUG[19200] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 189.108.207.226:5060 [2012-10-05 10:45:47] DEBUG[19200] chan_sip.c: Initializing initreq for method OPTIONS - callid 1ec9eaf30ed02d7d02cb83ae36b0b666@189.108.207.226:5060 [2012-10-05 10:45:47] DEBUG[19200] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 200.155.5.83:5060 [2012-10-05 10:45:47] DEBUG[19200] chan_sip.c: = Looking for Call ID: 1ec9eaf30ed02d7d02cb83ae36b0b666@189.108.207.226:5060 (Checking To) --From tag as101df3f2 --To-tag as1743b365 [2012-10-05 10:45:47] DEBUG[19200] chan_sip.c: Stopping retransmission on '1ec9eaf30ed02d7d02cb83ae36b0b666@189.108.207.226:5060' of Request 102: Match Found [2012-10-05 10:45:47] DEBUG[19200] chan_sip.c: Destroying SIP dialog 1ec9eaf30ed02d7d02cb83ae36b0b666@189.108.207.226:5060 [2012-10-05 10:45:49] DEBUG[19203] chan_iax2.c: ip callno count decremented to 3 for 172.20.250.91 [2012-10-05 10:45:50] DEBUG[19203] chan_iax2.c: ip callno count decremented to 2 for 172.20.250.91 [2012-10-05 10:45:51] DEBUG[19208] chan_iax2.c: ip callno count incremented to 3 for 172.20.250.101 [2012-10-05 10:45:51] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3332 [2012-10-05 10:45:51] DEBUG[19191] chan_iax2.c: Checking device state for device 3332 [2012-10-05 10:45:51] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3332? addr=-1407911323, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:45:51] DEBUG[19191] devicestate.c: Changing state for IAX2/3332 - state 0 (Unknown) [2012-10-05 10:45:51] DEBUG[19191] devicestate.c: device 'IAX2/3332' state '0' [2012-10-05 10:45:51] DEBUG[19224] app_queue.c: Device 'IAX2/3332' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:45:51] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3332 [2012-10-05 10:45:51] DEBUG[19191] chan_iax2.c: Checking device state for device 3332 [2012-10-05 10:45:51] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3332? addr=-1407911323, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:45:51] DEBUG[19191] devicestate.c: Changing state for IAX2/3332 - state 0 (Unknown) [2012-10-05 10:45:51] DEBUG[19191] devicestate.c: device 'IAX2/3332' state '0' [2012-10-05 10:45:51] DEBUG[19224] app_queue.c: Device 'IAX2/3332' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:45:51] DEBUG[19210] chan_iax2.c: schedule decrement of callno used for 172.20.250.101 in 60 seconds [2012-10-05 10:46:05] DEBUG[19203] chan_iax2.c: ip callno count decremented to 2 for 172.20.250.101 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 3 [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 2 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: Allocating new SIP dialog for 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 - REGISTER (No RTP) [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 3 [2012-10-05 10:46:07] DEBUG[19200] acl.c: For destination '200.155.5.83', our source address is '172.20.250.12'. [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: Target address 200.155.5.83:5060 is not local, substituting externaddr [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 189.108.207.226:5060 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 4 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: Scheduled a registration timeout for 200.155.5.83 id #15447 [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: Initializing initreq for method REGISTER - callid 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: REGISTER attempt 1 to 110215@200.155.5.83 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 200.155.5.83:5060 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 3 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: = Looking for Call ID: 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 (Checking To) --From tag as2fe64775 --To-tag [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: = Looking for Call ID: 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 (Checking To) --From tag as2fe64775 --To-tag as48b3b67a [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: Stopping retransmission on '3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12' of Request 3093: Match Found [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 4 [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 3 [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: Splitting '200.155.5.83' into... [2012-10-05 10:46:07] DEBUG[19200] netsock2.c: ...host '200.155.5.83' and port ''. [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: Initializing already initialized SIP dialog 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 (presumably reinvite) [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: REGISTER attempt 2 to 110215@200.155.5.83 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 200.155.5.83:5060 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: = Looking for Call ID: 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 (Checking To) --From tag as36ccf594 --To-tag [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: = Looking for Call ID: 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12 (Checking To) --From tag as36ccf594 --To-tag as48b3b67a [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: Stopping retransmission on '3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12' of Request 3094: Match Found [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: Registration successful [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: Cancelling timeout 15447 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 2 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 1 [2012-10-05 10:46:07] DEBUG[19200] chan_sip.c: SIP Registry 200.155.5.83: refcount now 2 [2012-10-05 10:46:20] DEBUG[19206] chan_iax2.c: ip callno count incremented to 3 for 172.20.250.91 [2012-10-05 10:46:20] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:46:20] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:46:20] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:46:20] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 0 (Unknown) [2012-10-05 10:46:20] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '0' [2012-10-05 10:46:20] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:46:20] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3331 [2012-10-05 10:46:20] DEBUG[19191] chan_iax2.c: Checking device state for device 3331 [2012-10-05 10:46:20] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3331? addr=-1407911333, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:46:20] DEBUG[19191] devicestate.c: Changing state for IAX2/3331 - state 0 (Unknown) [2012-10-05 10:46:20] DEBUG[19191] devicestate.c: device 'IAX2/3331' state '0' [2012-10-05 10:46:20] DEBUG[19224] app_queue.c: Device 'IAX2/3331' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:46:20] DEBUG[19205] chan_iax2.c: schedule decrement of callno used for 172.20.250.91 in 60 seconds [2012-10-05 10:46:35] DEBUG[19203] chan_iax2.c: ip callno count decremented to 2 for 172.20.250.91 [2012-10-05 10:46:36] DEBUG[19210] chan_iax2.c: ip callno count incremented to 3 for 172.20.250.101 [2012-10-05 10:46:36] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3332 [2012-10-05 10:46:36] DEBUG[19191] chan_iax2.c: Checking device state for device 3332 [2012-10-05 10:46:36] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3332? addr=-1407911323, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:46:36] DEBUG[19191] devicestate.c: Changing state for IAX2/3332 - state 0 (Unknown) [2012-10-05 10:46:36] DEBUG[19191] devicestate.c: device 'IAX2/3332' state '0' [2012-10-05 10:46:36] DEBUG[19224] app_queue.c: Device 'IAX2/3332' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:46:36] DEBUG[19191] devicestate.c: No provider found, checking channel drivers for IAX2 - 3332 [2012-10-05 10:46:36] DEBUG[19191] chan_iax2.c: Checking device state for device 3332 [2012-10-05 10:46:36] DEBUG[19191] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3332? addr=-1407911323, defaddr=0 maxms=0, lastms=0 [2012-10-05 10:46:36] DEBUG[19191] devicestate.c: Changing state for IAX2/3332 - state 0 (Unknown) [2012-10-05 10:46:36] DEBUG[19191] devicestate.c: device 'IAX2/3332' state '0' [2012-10-05 10:46:36] DEBUG[19224] app_queue.c: Device 'IAX2/3332' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [2012-10-05 10:46:36] DEBUG[19213] chan_iax2.c: schedule decrement of callno used for 172.20.250.101 in 60 seconds [2012-10-05 10:46:39] DEBUG[19200] chan_sip.c: Auto destroying SIP dialog '3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12' [2012-10-05 10:46:39] DEBUG[19200] chan_sip.c: Destroying SIP dialog 3a19d8db7b2a59f54b23002d2b132e8a@172.20.250.12