[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:     -- <IAX2/3331-4800> 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