[May 26 11:08:39] DEBUG[11703]: chan_sip.c:5000 do_setnat: Setting NAT on RTP to On
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:5008 do_setnat: Setting NAT on UDPTL to On
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:7286 sip_alloc: Allocating new SIP dialog for 4aa676800e1ac2724734f39b149660de@INCOMING-SIP-SERVER - INVITE (With RTP)
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:21650 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:5000 do_setnat: Setting NAT on RTP to Off
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:5008 do_setnat: Setting NAT on UDPTL to Off
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP o=root 13639 13639 IN IP4 INCOMING-SIP-SERVER... UNSUPPORTED.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP s=session... UNSUPPORTED.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP c=IN IP4 INCOMING-SIP-SERVER... OK.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:8540 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw)
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:20034 handle_request_invite: Checking SIP call limits for device 
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:5634 update_call_counter: Updating call counter for incoming call
[May 26 11:08:39] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - multi-00
[May 26 11:08:39] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer multi-00
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:6653 sip_new: *** Our native formats are 0x8 (alaw) 
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:6654 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw) 
[May 26 11:08:39] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/multi-00 - state 2 (In use)
[May 26 11:08:39] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/multi-00' state '2'
[May 26 11:08:39] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/multi-00' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:6655 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) 
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:6656 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:6686 sip_new: This channel will not be able to handle video.
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:12514 build_route: build_route: Contact hop: <sip:CALLER-A@INCOMING-SIP-SERVER>
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:20293 handle_request_invite: SIP/multi-00-00000004: New call is still down.... Trying... 
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:3556 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for INCOMING-SIP-SERVER:5060
[May 26 11:08:39] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - multi-00
[May 26 11:08:39] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer multi-00
[May 26 11:08:39] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/multi-00 - state 2 (In use)
[May 26 11:08:39] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/multi-00' state '2'
[May 26 11:08:39] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/multi-00' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 26 11:08:39] DEBUG[5231]: pbx.c:3692 pbx_extension_helper: Launching 'Dial'
    -- Executing [123@in_world:1] Dial("SIP/multi-00-00000004", "SIP/phonea,30") in new stack
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:23105 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw)
  == Using SIP RTP CoS mark 5
  == Using UDPTL CoS mark 5
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:7286 sip_alloc: Allocating new SIP dialog for 053220212e6fd90438ad6ba90b0eeb64@SERVER - INVITE (With RTP)
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:5000 do_setnat: Setting NAT on RTP to On
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:5008 do_setnat: Setting NAT on UDPTL to On
[May 26 11:08:39] DEBUG[5231]: acl.c:506 ast_ouraddrfor: Found IP address for this socket
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:3677 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address SERVER:5060
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:6653 sip_new: *** Our native formats are 0x8 (alaw) 
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:6654 sip_new: *** Joint capabilities are 0x8 (alaw) 
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:6655 sip_new: *** Our capabilities are 0x8 (alaw) 
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:6656 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:6658 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) 
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:6686 sip_new: This channel will not be able to handle video.
[May 26 11:08:39] DEBUG[5231]: channel.c:4335 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[May 26 11:08:39] DEBUG[5231]: channel.c:4335 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[May 26 11:08:39] DEBUG[5231]: channel.c:4335 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[May 26 11:08:39] DEBUG[5231]: channel.c:4335 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[May 26 11:08:39] DEBUG[5231]: channel.c:4335 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[May 26 11:08:39] DEBUG[5231]: channel.c:4335 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[May 26 11:08:39] DEBUG[5231]: channel.c:4335 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[May 26 11:08:39] DEBUG[5231]: channel.c:4335 ast_channel_inherit_variables: Not copying variable SIPURI.
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:5418 sip_call: Outgoing Call for phonea
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:5634 update_call_counter: Updating call counter for outgoing call
[May 26 11:08:39] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
[May 26 11:08:39] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:39] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 6 (Ringing)
[May 26 11:08:39] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '6'
[May 26 11:08:39] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:10111 add_sdp: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:10112 add_sdp: ** Our prefcodec: 0x8 (alaw) 
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:10223 add_sdp: -- Done with adding codecs to SDP
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:10359 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:3270 initialize_initreq: Initializing initreq for method INVITE - callid 1e09c1c646e9c18675c7a5d0098cc5a9@SERVER
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:3556 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 86.59.13.51:6281
    -- Called phoneaLI> 
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:4133 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1e09c1c646e9c18675c7a5d0098cc5a9@SERVER' Request 102: Found
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:17596 handle_response_invite: SIP response 100 to standard invite
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:4133 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1e09c1c646e9c18675c7a5d0098cc5a9@SERVER' Request 102: Found
[May 26 11:08:39] DEBUG[11703]: chan_sip.c:17596 handle_response_invite: SIP response 180 to standard invite
[May 26 11:08:39] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
[May 26 11:08:39] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:39] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 6 (Ringing)
[May 26 11:08:39] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '6'
    -- SIP/phonea-00000005 is ringing
[May 26 11:08:39] DEBUG[5231]: chan_sip.c:3556 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for INCOMING-SIP-SERVER:5060
[May 26 11:08:39] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:4055 __sip_ack: Acked pending invite 102
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:4092 __sip_ack: Stopping retransmission on '1e09c1c646e9c18675c7a5d0098cc5a9@SERVER' of Request 102: Match Found
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:17596 handle_response_invite: SIP response 200 to standard invite
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP o=- 417130 417130 IN IP4 192.168.2.170... UNSUPPORTED.
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP s=-... UNSUPPORTED.
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP c=IN IP4 86.59.13.51... OK.
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:8540 process_sdp: We're settling with these formats: 0x8 (alaw)
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:8545 process_sdp: We have an owner, now see if we need to change this call
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:5634 update_call_counter: Updating call counter for outgoing call
[May 26 11:08:40] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
[May 26 11:08:40] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:12514 build_route: build_route: Contact hop: <sip:phonea@86.59.13.51:1198>
[May 26 11:08:40] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 2 (In use)
[May 26 11:08:40] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '2'
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:3556 __sip_xmit: Trying to put 'ACK sip:g00' onto UDP socket destined for 86.59.13.51:6281
[May 26 11:08:40] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 26 11:08:40] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
    -- SIP/phonea-00000005 answered SIP/multi-00-00000004
[May 26 11:08:40] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:40] DEBUG[5231]: chan_sip.c:6190 sip_answer: SIP answering channel: SIP/multi-00-00000004
[May 26 11:08:40] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 2 (In use)
[May 26 11:08:40] DEBUG[5231]: rtp.c:2687 ast_rtp_new_source: Setting the marker bit due to a source update
[May 26 11:08:40] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '2'
[May 26 11:08:40] DEBUG[5231]: chan_sip.c:10422 transmit_response_with_sdp: Setting framing from config on incoming call
[May 26 11:08:40] DEBUG[5231]: chan_sip.c:10111 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True Text flag: True
[May 26 11:08:40] DEBUG[5231]: chan_sip.c:10112 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[May 26 11:08:40] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - multi-00
[May 26 11:08:40] DEBUG[5231]: chan_sip.c:10223 add_sdp: -- Done with adding codecs to SDP
[May 26 11:08:40] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer multi-00
[May 26 11:08:40] DEBUG[5231]: chan_sip.c:10359 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
[May 26 11:08:40] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/multi-00 - state 2 (In use)
[May 26 11:08:40] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/multi-00' state '2'
[May 26 11:08:40] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 26 11:08:40] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/multi-00' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 26 11:08:40] DEBUG[5231]: chan_sip.c:3556 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for INCOMING-SIP-SERVER:5060
[May 26 11:08:40] DEBUG[5231]: features.c:2555 ast_bridge_call: bridge answer set, chan answer set
[May 26 11:08:40] DEBUG[5231]: rtp.c:2687 ast_rtp_new_source: Setting the marker bit due to a source update
[May 26 11:08:40] DEBUG[5231]: rtp.c:2687 ast_rtp_new_source: Setting the marker bit due to a source update
    -- Packet2Packet bridging SIP/multi-00-00000004 and SIP/phonea-00000005
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:21650 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[May 26 11:08:40] DEBUG[11703]: chan_sip.c:4092 __sip_ack: Stopping retransmission on '4aa676800e1ac2724734f39b149660de@INCOMING-SIP-SERVER' of Response 102: Match Found
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:21650 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP o=- 417130 417131 IN IP4 192.168.2.170... UNSUPPORTED.
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP s=-... UNSUPPORTED.
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP c=IN IP4 0.0.0.0... OK.
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=sendonly... OK.
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8540 process_sdp: We're settling with these formats: 0x8 (alaw)
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:8545 process_sdp: We have an owner, now see if we need to change this call
[May 26 11:08:41] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:20357 handle_request_invite: SIP/phonea-00000005: This call is UP.... 
[May 26 11:08:41] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:41] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 8 (On Hold)
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:3556 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 86.59.13.51:6281
[May 26 11:08:41] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '8'
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:10422 transmit_response_with_sdp: Setting framing from config on incoming call
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:10111 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:10112 add_sdp: ** Our prefcodec: 0x8 (alaw) 
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:10223 add_sdp: -- Done with adding codecs to SDP
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:10359 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:3556 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 86.59.13.51:6281
[May 26 11:08:41] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '8' (On Hold) but we don't care because they're not a member of any queue.
[May 26 11:08:41] DEBUG[5231]: rtp.c:2687 ast_rtp_new_source: Setting the marker bit due to a source update
    -- Started music on hold, class 'default', on SIP/multi-00-00000004
[May 26 11:08:41] DEBUG[5231]: channel.c:2423 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[May 26 11:08:41] DEBUG[5231]: rtp.c:2687 ast_rtp_new_source: Setting the marker bit due to a source update
[May 26 11:08:41] DEBUG[5231]: channel.c:2537 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[May 26 11:08:41] DEBUG[5231]: channel.c:2423 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[May 26 11:08:41] DEBUG[5231]: channel.c:3725 set_format: Set channel SIP/multi-00-00000004 to write format slin
[May 26 11:08:41] DEBUG[5231]: res_musiconhold.c:303 ast_moh_files_next: SIP/multi-00-00000004 Opened file 0 '/var/lib/asterisk/moh-files/default/plswait'
[May 26 11:08:41] DEBUG[5231]: rtp.c:3878 ast_rtp_write: Ooh, format changed from unknown to alaw
[May 26 11:08:41] DEBUG[5231]: rtp.c:3904 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:21650 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[May 26 11:08:41] DEBUG[11703]: chan_sip.c:4092 __sip_ack: Stopping retransmission on '1e09c1c646e9c18675c7a5d0098cc5a9@SERVER' of Response 101: Match Found
[May 26 11:08:42] DEBUG[5231]: rtp.c:1035 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 26 11:08:42] DEBUG[5231]: rtp.c:881 create_dtmf_frame: Sending dtmf: 52 (4), at INCOMING-SIP-SERVER
[May 26 11:08:42] DEBUG[5231]: rtp.c:1035 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 26 11:08:42] DEBUG[5231]: rtp.c:1035 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 26 11:08:42] DEBUG[5231]: rtp.c:1035 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 26 11:08:42] DEBUG[5231]: rtp.c:881 create_dtmf_frame: Sending dtmf: 52 (4), at INCOMING-SIP-SERVER
[May 26 11:08:42] DEBUG[5231]: rtp.c:1035 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 26 11:08:42] DEBUG[5231]: rtp.c:1035 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 26 11:08:42] DEBUG[11703]: chan_sip.c:21650 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS
[May 26 11:08:42] DEBUG[11703]: chan_sip.c:3556 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 86.59.13.51:6281
[May 26 11:08:43] DEBUG[11703]: acl.c:506 ast_ouraddrfor: Found IP address for this socket
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:3677 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address SERVER:5060
  == Using SIP RTP CoS mark 5
  == Using UDPTL CoS mark 5
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:5000 do_setnat: Setting NAT on RTP to On
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:5008 do_setnat: Setting NAT on UDPTL to On
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:7286 sip_alloc: Allocating new SIP dialog for cb002e25-a1a6319e@192.168.2.170 - INVITE (With RTP)
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:21650 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:5000 do_setnat: Setting NAT on RTP to On
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:5008 do_setnat: Setting NAT on UDPTL to On
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:3556 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 86.59.13.51:6281
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:21650 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:4092 __sip_ack: Stopping retransmission on 'cb002e25-a1a6319e@192.168.2.170' of Response 101: Match Found
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:21650 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:5000 do_setnat: Setting NAT on RTP to On
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:5008 do_setnat: Setting NAT on UDPTL to On
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP o=- 417536 417536 IN IP4 192.168.2.170... UNSUPPORTED.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP s=-... UNSUPPORTED.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP c=IN IP4 86.59.13.51... OK.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:104 L16/16000... OK.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:8540 process_sdp: We're settling with these formats: 0x8 (alaw)
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:20034 handle_request_invite: Checking SIP call limits for device phonea
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:5634 update_call_counter: Updating call counter for incoming call
[May 26 11:08:43] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
[May 26 11:08:43] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:43] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 8 (On Hold)
[May 26 11:08:43] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '8'
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:6653 sip_new: *** Our native formats are 0x8 (alaw) 
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:6654 sip_new: *** Joint capabilities are 0x8 (alaw) 
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:6655 sip_new: *** Our capabilities are 0x8 (alaw) 
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:6656 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:6686 sip_new: This channel will not be able to handle video.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:12514 build_route: build_route: Contact hop: <sip:phonea@86.59.13.51:1198>
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:20293 handle_request_invite: SIP/phonea-00000006: New call is still down.... Trying... 
[May 26 11:08:43] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '8' (On Hold) but we don't care because they're not a member of any queue.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:3556 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 86.59.13.51:6281
[May 26 11:08:43] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
[May 26 11:08:43] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:43] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 8 (On Hold)
[May 26 11:08:43] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '8'
[May 26 11:08:43] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '8' (On Hold) but we don't care because they're not a member of any queue.
[May 26 11:08:43] DEBUG[5232]: pbx.c:3692 pbx_extension_helper: Launching 'Answer'
    -- Executing [456@outcust:1] Answer("SIP/phonea-00000006", "") in new stack
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:6190 sip_answer: SIP answering channel: SIP/phonea-00000006
[May 26 11:08:43] DEBUG[5232]: rtp.c:2687 ast_rtp_new_source: Setting the marker bit due to a source update
[May 26 11:08:43] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
[May 26 11:08:43] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:43] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 8 (On Hold)
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:10422 transmit_response_with_sdp: Setting framing from config on incoming call
[May 26 11:08:43] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '8'
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:10111 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:10112 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:10223 add_sdp: -- Done with adding codecs to SDP
[May 26 11:08:43] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '8' (On Hold) but we don't care because they're not a member of any queue.
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:10359 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:3556 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 86.59.13.51:6281
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:21650 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:4092 __sip_ack: Stopping retransmission on 'cb002e25-a1a6319e@192.168.2.170' of Response 102: Match Found
[May 26 11:08:43] DEBUG[5232]: rtp.c:1676 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 86.59.13.51:6693
[May 26 11:08:43] DEBUG[5232]: pbx.c:3692 pbx_extension_helper: Launching 'Dial'
    -- Executing [456@outcust:2] Dial("SIP/phonea-00000006", "SIP/phoneb,30") in new stack
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:23105 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw)
  == Using SIP RTP CoS mark 5
  == Using UDPTL CoS mark 5
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:7286 sip_alloc: Allocating new SIP dialog for 7c42ea89700ca04c351716c97c27928c@SERVER - INVITE (With RTP)
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:5000 do_setnat: Setting NAT on RTP to On
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:5008 do_setnat: Setting NAT on UDPTL to On
[May 26 11:08:43] DEBUG[5232]: acl.c:506 ast_ouraddrfor: Found IP address for this socket
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:3677 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address SERVER:5060
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:6653 sip_new: *** Our native formats are 0x8 (alaw) 
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:6654 sip_new: *** Joint capabilities are 0x8 (alaw) 
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:6655 sip_new: *** Our capabilities are 0x8 (alaw) 
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:6656 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:6658 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) 
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:6686 sip_new: This channel will not be able to handle video.
[May 26 11:08:43] DEBUG[5232]: channel.c:4335 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[May 26 11:08:43] DEBUG[5232]: channel.c:4335 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[May 26 11:08:43] DEBUG[5232]: channel.c:4335 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[May 26 11:08:43] DEBUG[5232]: channel.c:4335 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[May 26 11:08:43] DEBUG[5232]: channel.c:4335 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[May 26 11:08:43] DEBUG[5232]: channel.c:4335 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[May 26 11:08:43] DEBUG[5232]: channel.c:4335 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[May 26 11:08:43] DEBUG[5232]: channel.c:4335 ast_channel_inherit_variables: Not copying variable SIPURI.
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:5418 sip_call: Outgoing Call for phoneb
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:5634 update_call_counter: Updating call counter for outgoing call
[May 26 11:08:43] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phoneb
[May 26 11:08:43] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phoneb
[May 26 11:08:43] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phoneb - state 6 (Ringing)
[May 26 11:08:43] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phoneb' state '6'
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:10111 add_sdp: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:10112 add_sdp: ** Our prefcodec: 0x8 (alaw) 
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:10223 add_sdp: -- Done with adding codecs to SDP
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:10359 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:3270 initialize_initreq: Initializing initreq for method INVITE - callid 157468ab2b8ca26436ac0a001a669f02@SERVER
[May 26 11:08:43] DEBUG[5232]: chan_sip.c:3556 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 86.59.13.51:4927
    -- Called phonebLI> 
[May 26 11:08:43] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phoneb' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:4133 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '157468ab2b8ca26436ac0a001a669f02@SERVER' Request 102: Found
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:17596 handle_response_invite: SIP response 100 to standard invite
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:4133 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '157468ab2b8ca26436ac0a001a669f02@SERVER' Request 102: Found
[May 26 11:08:43] DEBUG[11703]: chan_sip.c:17596 handle_response_invite: SIP response 180 to standard invite
[May 26 11:08:43] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phoneb
[May 26 11:08:43] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phoneb
[May 26 11:08:43] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phoneb - state 6 (Ringing)
[May 26 11:08:43] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phoneb' state '6'
    -- SIP/phoneb-00000007 is ringing
[May 26 11:08:43] DEBUG[5232]: channel.c:3247 ast_indicate_data: Driver for channel 'SIP/phonea-00000006' does not support indication 3, emulating it
[May 26 11:08:43] DEBUG[5232]: channel.c:3725 set_format: Set channel SIP/phonea-00000006 to write format slin
[May 26 11:08:43] DEBUG[5232]: channel.c:2423 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[May 26 11:08:43] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phoneb' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[May 26 11:08:43] DEBUG[5232]: channel.c:2537 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[May 26 11:08:43] DEBUG[5232]: channel.c:2423 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[May 26 11:08:43] DEBUG[5232]: rtp.c:3878 ast_rtp_write: Ooh, format changed from unknown to alaw
[May 26 11:08:43] DEBUG[5232]: rtp.c:3904 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:4055 __sip_ack: Acked pending invite 102
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:4092 __sip_ack: Stopping retransmission on '157468ab2b8ca26436ac0a001a669f02@SERVER' of Request 102: Match Found
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:17596 handle_response_invite: SIP response 200 to standard invite
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP o=- 218375 218375 IN IP4 192.168.2.77... UNSUPPORTED.
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP s=-... UNSUPPORTED.
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP c=IN IP4 86.59.13.51... OK.
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:8191 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:8355 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:8540 process_sdp: We're settling with these formats: 0x8 (alaw)
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:8545 process_sdp: We have an owner, now see if we need to change this call
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:5634 update_call_counter: Updating call counter for outgoing call
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:12514 build_route: build_route: Contact hop: <sip:phoneb@86.59.13.51:6206>
[May 26 11:08:46] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phoneb
[May 26 11:08:46] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phoneb
[May 26 11:08:46] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phoneb - state 2 (In use)
[May 26 11:08:46] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phoneb' state '2'
[May 26 11:08:46] DEBUG[11703]: chan_sip.c:3556 __sip_xmit: Trying to put 'ACK sip:g00' onto UDP socket destined for 86.59.13.51:4927
[May 26 11:08:46] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phoneb
[May 26 11:08:46] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phoneb
[May 26 11:08:46] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phoneb' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[May 26 11:08:46] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phoneb - state 2 (In use)
[May 26 11:08:46] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phoneb' state '2'
[May 26 11:08:46] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phoneb' changed to state '2' (In use) but we don't care because they're not a member of any queue.
    -- SIP/phoneb-00000007 answered SIP/phonea-00000006
[May 26 11:08:46] DEBUG[5232]: channel.c:3725 set_format: Set channel SIP/phonea-00000006 to write format alaw
[May 26 11:08:46] DEBUG[5232]: channel.c:2423 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[May 26 11:08:46] DEBUG[5232]: features.c:2555 ast_bridge_call: bridge answer set, chan answer set
[May 26 11:08:46] DEBUG[5232]: rtp.c:2687 ast_rtp_new_source: Setting the marker bit due to a source update
[May 26 11:08:46] DEBUG[5232]: rtp.c:2687 ast_rtp_new_source: Setting the marker bit due to a source update
    -- Packet2Packet bridging SIP/phonea-00000006 and SIP/phoneb-00000007
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:21650 handle_incoming: **** Received REFER (9) - Command in SIP REFER
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:13614 get_refer_info: Attended transfer: Will use Replace-Call-ID : cb002e25-a1a6319e@192.168.2.170 (No check of from/to tags)
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:13421 get_sip_pvt_byid_locked: Looking for callid cb002e25-a1a6319e@192.168.2.170 (fromtag 8a1adc7932e9375ao1 totag as0fad9055)
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:13481 get_sip_pvt_byid_locked: Matched INCOMING call - their tag is 8a1adc7932e9375ao1 Our tag is as0fad9055
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:3556 __sip_xmit: Trying to put 'SIP/2.0 202' onto UDP socket destined for 86.59.13.51:6281
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:18912 attempt_transfer: Sip transfer:--------------------
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:18914 attempt_transfer: -- Transferer to PBX channel: SIP/phonea-00000005 State Up
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:18918 attempt_transfer: -- Transferer to PBX second channel (target): SIP/phonea-00000006 State Up
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:18922 attempt_transfer: -- Bridged call to transferee: SIP/multi-00-00000004 State Up
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:18926 attempt_transfer: -- Bridged call to transfer target: SIP/phoneb-00000007 State Up
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:18929 attempt_transfer: -- END Sip transfer:--------------------
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:18935 attempt_transfer: SIP transfer: Four channels to handle
    -- Stopped music on hold on SIP/multi-00-00000004
[May 26 11:08:47] DEBUG[11703]: channel.c:3725 set_format: Set channel SIP/multi-00-00000004 to write format alaw
[May 26 11:08:47] DEBUG[11703]: channel.c:2423 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:18951 attempt_transfer: SIP transfer: trying to masquerade SIP/multi-00-00000004 into SIP/phonea-00000006
[May 26 11:08:47] DEBUG[11703]: channel.c:4273 ast_channel_masquerade: Planning to masquerade channel SIP/multi-00-00000004 into the structure of SIP/phonea-00000006
[May 26 11:08:47] DEBUG[11703]: channel.c:4285 ast_channel_masquerade: Done planning to masquerade channel SIP/multi-00-00000004 into the structure of SIP/phonea-00000006
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:18956 attempt_transfer: SIP transfer: Succeeded to masquerade channels.
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:3556 __sip_xmit: Trying to put 'NOTIFY sip:' onto UDP socket destined for 86.59.13.51:6281
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:20503 local_attended_transfer: SIP attended transfer: Unlocking channel SIP/phonea-00000006
[May 26 11:08:47] DEBUG[5232]: channel.c:4411 ast_do_masquerade: Actually Masquerading SIP/multi-00-00000004(6) into the structure of SIP/phonea-00000006(6)
[May 26 11:08:47] DEBUG[5232]: channel.c:4424 ast_do_masquerade: Got clone lock for masquerade on 'SIP/multi-00-00000004' at 0x83fa5e8
[May 26 11:08:47] DEBUG[5232]: chan_sip.c:6345 sip_fixup: SIP Fixup: New owner for dialogue cb002e25-a1a6319e@192.168.2.170: SIP/multi-00-00000004<MASQ> (Old parent: SIP/multi-00-00000004)
[May 26 11:08:47] DEBUG[5232]: chan_sip.c:5998 sip_hangup: Hangup call SIP/multi-00-00000004<MASQ>, SIP callid cb002e25-a1a6319e@192.168.2.170
[May 26 11:08:47] DEBUG[5232]: chan_sip.c:5634 update_call_counter: Updating call counter for incoming call
[May 26 11:08:47] DEBUG[5232]: chan_sip.c:3556 __sip_xmit: Trying to put 'BYE sip:g00' onto UDP socket destined for 86.59.13.51:6281
[May 26 11:08:47] DEBUG[5232]: channel.c:4610 ast_do_masquerade: Putting channel SIP/multi-00-00000004 in 8/8 formats
[May 26 11:08:47] DEBUG[5232]: chan_sip.c:6345 sip_fixup: SIP Fixup: New owner for dialogue 4aa676800e1ac2724734f39b149660de@INCOMING-SIP-SERVER: SIP/multi-00-00000004 (Old parent: SIP/phonea-00000006<ZOMBIE>)
[May 26 11:08:47] DEBUG[5232]: channel.c:3247 ast_indicate_data: Driver for channel 'SIP/multi-00-00000004' does not support indication 3, emulating it
[May 26 11:08:47] DEBUG[5232]: channel.c:3725 set_format: Set channel SIP/multi-00-00000004 to write format slin
[May 26 11:08:47] DEBUG[5232]: channel.c:2423 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[May 26 11:08:47] DEBUG[5232]: channel.c:4656 ast_do_masquerade: Released clone lock on 'SIP/phonea-00000006<ZOMBIE>'
[May 26 11:08:47] DEBUG[5232]: channel.c:4665 ast_do_masquerade: Done Masquerading SIP/multi-00-00000004 (6)
[May 26 11:08:47] DEBUG[5232]: rtp.c:4309 bridge_p2p_loop: p2p-rtp-bridge: Oooh, something is weird, backing out
    -- Packet2Packet bridging SIP/multi-00-00000004 and SIP/phoneb-00000007
[May 26 11:08:47] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
[May 26 11:08:47] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:47] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 8 (On Hold)
[May 26 11:08:47] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '8'
[May 26 11:08:47] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '8' (On Hold) but we don't care because they're not a member of any queue.
[May 26 11:08:47] DEBUG[5231]: rtp.c:4309 bridge_p2p_loop: p2p-rtp-bridge: Oooh, something is weird, backing out
[May 26 11:08:47] DEBUG[5231]: channel.c:5202 ast_channel_bridge: Bridge stops because we're zombie or need a soft hangup: c0=SIP/phonea-00000006<ZOMBIE>, c1=SIP/phonea-00000005, flags: Yes,Yes,No,No
[May 26 11:08:47] DEBUG[5231]: rtp.c:2687 ast_rtp_new_source: Setting the marker bit due to a source update
[May 26 11:08:47] DEBUG[5231]: channel.c:5304 ast_channel_bridge: Bridge stops bridging channels SIP/phonea-00000006<ZOMBIE> and SIP/phonea-00000005
[May 26 11:08:47] DEBUG[5231]: cdr_addon_mysql.c:307 mysql_log: Inserting a CDR record.
[May 26 11:08:47] DEBUG[5231]: cdr_addon_mysql.c:310 mysql_log: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid) VALUES ('2010-05-26 11:08:39','\"CALLER-A\" <CALLER-A>','CALLER-A','123','in_world','SIP/multi-00-00000004','SIP/phonea-00000005','Dial','SIP/phonea,30','8','7','ANSWERED','3','1274864919.4')
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '"CALLER-A" <CALLER-A>'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'CALLER-A'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '123'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'in_world'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'SIP/multi-00-00000004'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'SIP/phonea-00000005'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'Dial'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'SIP/phonea,30'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '2010-05-26 11:08:39'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '2010-05-26 11:08:40'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '2010-05-26 11:08:47'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '8'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '7'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '(null)'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '1274864919.4'
[May 26 11:08:47] DEBUG[5231]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '(null)'
[May 26 11:08:47] DEBUG[5232]: channel.c:2537 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[May 26 11:08:47] DEBUG[5232]: channel.c:2423 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[May 26 11:08:47] DEBUG[5232]: rtp.c:3878 ast_rtp_write: Ooh, format changed from unknown to alaw
[May 26 11:08:47] DEBUG[5232]: rtp.c:3904 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160
[May 26 11:08:47] DEBUG[5231]: channel.c:1240 channel_find_locked: Avoiding initial deadlock for channel '0xb68f14d0'
[May 26 11:08:47] DEBUG[5231]: channel.c:1760 ast_hangup: Hanging up channel 'SIP/phonea-00000005'
[May 26 11:08:47] DEBUG[5231]: chan_sip.c:5634 update_call_counter: Updating call counter for outgoing call
[May 26 11:08:47] DEBUG[5231]: chan_sip.c:5979 sip_hangup: SIP Transfer: Not hanging up right now... Rescheduling hangup for 1e09c1c646e9c18675c7a5d0098cc5a9@SERVER.
[May 26 11:08:47] DEBUG[5231]: rtp.c:2145 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[May 26 11:08:47] DEBUG[5231]: app_dial.c:2317 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[May 26 11:08:47] DEBUG[5231]: pbx.c:4306 __ast_pbx_run: Spawn extension (in_world,123,1) exited non-zero on 'SIP/phonea-00000006<ZOMBIE>'
  == Spawn extension (in_world, 123, 1) exited non-zero on 'SIP/phonea-00000006<ZOMBIE>'
[May 26 11:08:47] DEBUG[5231]: channel.c:1655 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/phonea-00000006<ZOMBIE>'
[May 26 11:08:47] DEBUG[5231]: channel.c:1764 ast_hangup: Hanging up zombie 'SIP/phonea-00000006<ZOMBIE>'
[May 26 11:08:47] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
[May 26 11:08:47] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:47] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 1 (Not in use)
[May 26 11:08:47] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '1'
[May 26 11:08:47] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
[May 26 11:08:47] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:47] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 1 (Not in use)
[May 26 11:08:47] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '1'
[May 26 11:08:47] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
[May 26 11:08:47] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:47] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 1 (Not in use)
[May 26 11:08:47] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '1'
[May 26 11:08:47] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phonea
[May 26 11:08:47] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phonea
[May 26 11:08:47] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phonea - state 1 (Not in use)
[May 26 11:08:47] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phonea' state '1'
[May 26 11:08:47] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 26 11:08:47] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 26 11:08:47] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 26 11:08:47] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phonea' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:4092 __sip_ack: Stopping retransmission on '1e09c1c646e9c18675c7a5d0098cc5a9@SERVER' of Request 103: Match Found
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:4092 __sip_ack: Stopping retransmission on 'cb002e25-a1a6319e@192.168.2.170' of Request 102: Match Found
[May 26 11:08:47] DEBUG[11703]: chan_sip.c:5781 sip_destroy: Destroying SIP dialog cb002e25-a1a6319e@192.168.2.170
[May 26 11:08:48] DEBUG[11703]: chan_sip.c:3979 __sip_autodestruct: Auto destroying SIP dialog '78bd40485940eb840055934a349e3362@213.235.242.210'
[May 26 11:08:48] DEBUG[11703]: chan_sip.c:5781 sip_destroy: Destroying SIP dialog 78bd40485940eb840055934a349e3362@213.235.242.210
[May 26 11:08:49] DEBUG[11703]: chan_sip.c:3979 __sip_autodestruct: Auto destroying SIP dialog '03a514305e903077669eb6e7654cd933@213.235.242.211'
[May 26 11:08:49] DEBUG[11703]: chan_sip.c:5781 sip_destroy: Destroying SIP dialog 03a514305e903077669eb6e7654cd933@213.235.242.211
[May 26 11:08:49] DEBUG[11703]: chan_sip.c:21650 handle_incoming: **** Received BYE (8) - Command in SIP BYE
[May 26 11:08:49] DEBUG[11703]: chan_sip.c:3281 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 4aa676800e1ac2724734f39b149660de@INCOMING-SIP-SERVER
[May 26 11:08:49] DEBUG[11703]: chan_sip.c:21150 handle_request_bye: Received bye, issuing owner hangup
[May 26 11:08:49] DEBUG[11703]: chan_sip.c:3556 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for INCOMING-SIP-SERVER:5060
[May 26 11:08:49] DEBUG[5232]: channel.c:3725 set_format: Set channel SIP/multi-00-00000004 to write format alaw
[May 26 11:08:49] DEBUG[5232]: channel.c:2423 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[May 26 11:08:49] DEBUG[5232]: rtp.c:4340 bridge_p2p_loop: p2p-rtp-bridge: Ooh, got a hangup
[May 26 11:08:49] DEBUG[5232]: channel.c:5231 ast_channel_bridge: Returning from native bridge, channels: SIP/multi-00-00000004, SIP/phoneb-00000007
[May 26 11:08:49] DEBUG[5232]: cdr_addon_mysql.c:307 mysql_log: Inserting a CDR record.
[May 26 11:08:49] DEBUG[5232]: cdr_addon_mysql.c:310 mysql_log: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2010-05-26 11:08:43','\"Stefan Schmidt\" <phonea>','phonea','456','outcust','SIP/phonea-00000006','SIP/phoneb-00000007','Dial','SIP/phoneb,30','6','3','ANSWERED','3','41_phonea','1274864923.6')
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '"Stefan Schmidt" <phonea>'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'phonea'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '456'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'outcust'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'SIP/phonea-00000006'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'SIP/phoneb-00000007'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'Dial'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'SIP/phoneb,30'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '2010-05-26 11:08:43'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '2010-05-26 11:08:46'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '2010-05-26 11:08:49'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '6'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '3'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '41_phonea'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '1274864923.6'
[May 26 11:08:49] DEBUG[5232]: pbx.c:3520 pbx_substitute_variables_helper_full: Function result is '(null)'
[May 26 11:08:49] DEBUG[5232]: channel.c:1760 ast_hangup: Hanging up channel 'SIP/phoneb-00000007'
[May 26 11:08:49] DEBUG[5232]: chan_sip.c:5998 sip_hangup: Hangup call SIP/phoneb-00000007, SIP callid 157468ab2b8ca26436ac0a001a669f02@SERVER
[May 26 11:08:49] DEBUG[5232]: chan_sip.c:5634 update_call_counter: Updating call counter for outgoing call
[May 26 11:08:49] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phoneb
[May 26 11:08:49] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phoneb
[May 26 11:08:49] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phoneb - state 1 (Not in use)
[May 26 11:08:49] DEBUG[5232]: chan_sip.c:3556 __sip_xmit: Trying to put 'BYE sip:g00' onto UDP socket destined for 86.59.13.51:4927
[May 26 11:08:49] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phoneb' state '1'
[May 26 11:08:49] DEBUG[5232]: rtp.c:2145 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[May 26 11:08:49] DEBUG[5232]: app_dial.c:2317 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[May 26 11:08:49] DEBUG[5232]: pbx.c:4306 __ast_pbx_run: Spawn extension (outcust,456,2) exited non-zero on 'SIP/multi-00-00000004'
[May 26 11:08:49] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - phoneb
[May 26 11:08:49] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer phoneb
[May 26 11:08:49] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/phoneb - state 1 (Not in use)
[May 26 11:08:49] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/phoneb' state '1'
[May 26 11:08:49] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phoneb' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 26 11:08:49] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/phoneb' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
  == Spawn extension (outcust, 456, 2) exited non-zero on 'SIP/multi-00-00000004'
[May 26 11:08:49] DEBUG[5232]: channel.c:1655 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/multi-00-00000004'
[May 26 11:08:49] DEBUG[5232]: channel.c:1760 ast_hangup: Hanging up channel 'SIP/multi-00-00000004'
[May 26 11:08:49] DEBUG[5232]: chan_sip.c:5998 sip_hangup: Hangup call SIP/multi-00-00000004, SIP callid 4aa676800e1ac2724734f39b149660de@INCOMING-SIP-SERVER
[May 26 11:08:49] DEBUG[5232]: chan_sip.c:5634 update_call_counter: Updating call counter for incoming call
[May 26 11:08:49] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - multi-00
[May 26 11:08:49] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer multi-00
[May 26 11:08:49] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/multi-00 - state 1 (Not in use)
[May 26 11:08:49] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/multi-00' state '1'
[May 26 11:08:49] DEBUG[11690]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - multi-00
[May 26 11:08:49] DEBUG[11690]: chan_sip.c:23011 sip_devicestate: Checking device state for peer multi-00
[May 26 11:08:49] DEBUG[11690]: devicestate.c:460 do_state_change: Changing state for SIP/multi-00 - state 1 (Not in use)
[May 26 11:08:49] DEBUG[11690]: devicestate.c:440 devstate_event: device 'SIP/multi-00' state '1'
[May 26 11:08:49] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/multi-00' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 26 11:08:49] DEBUG[11695]: app_queue.c:1084 handle_statechange: Device 'SIP/multi-00' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 26 11:08:49] DEBUG[11703]: chan_sip.c:4092 __sip_ack: Stopping retransmission on '157468ab2b8ca26436ac0a001a669f02@SERVER' of Request 103: Match Found
[May 26 11:08:49] DEBUG[11703]: chan_sip.c:5781 sip_destroy: Destroying SIP dialog 4aa676800e1ac2724734f39b149660de@INCOMING-SIP-SERVER
[May 26 11:08:49] DEBUG[11703]: chan_sip.c:5781 sip_destroy: Destroying SIP dialog 157468ab2b8ca26436ac0a001a669f02@SERVER
[May 26 11:08:50] DEBUG[11703]: chan_sip.c:3979 __sip_autodestruct: Auto destroying SIP dialog '04629faa35f1706f320f87896d90d392@213.235.242.214'
[May 26 11:08:50] DEBUG[11703]: chan_sip.c:5781 sip_destroy: Destroying SIP dialog 04629faa35f1706f320f87896d90d392@213.235.242.214
[May 26 11:08:51] DEBUG[11703]: chan_sip.c:21650 handle_incoming: **** Received BYE (8) - Command in SIP BYE
[May 26 11:08:51] DEBUG[11703]: chan_sip.c:3281 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 1e09c1c646e9c18675c7a5d0098cc5a9@SERVER
[May 26 11:08:51] DEBUG[11703]: chan_sip.c:21153 handle_request_bye: Received bye, no owner, selfdestruct soon.
[May 26 11:08:51] DEBUG[11703]: chan_sip.c:3556 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 86.59.13.51:6281
voip-dev-01-01-1002*CLI> core set debug 0