[Mar 4 20:16:21] ERROR[2178] app_voicemail.c: Couldn't find mailbox 37 in context default [Mar 4 20:16:32] ERROR[2178] app_voicemail.c: Couldn't find mailbox 37 in context default [Mar 4 20:16:43] ERROR[2178] app_voicemail.c: Couldn't find mailbox 37 in context default [Mar 4 20:16:54] ERROR[2178] app_voicemail.c: Couldn't find mailbox 37 in context default [Mar 4 20:17:05] ERROR[2178] app_voicemail.c: Couldn't find mailbox 37 in context default [Mar 4 20:17:16] DEBUG[2178] app_voicemail.c: Mailbox is set to 37 [Mar 4 20:17:16] ERROR[2178] app_voicemail.c: Couldn't find mailbox 37 in context default [Mar 4 20:17:18] DEBUG[4585] http.c: mmm ... cookie! Name: 'mansession_id' Value: '15b88fb5' [Mar 4 20:17:18] DEBUG[4585] http.c: mmm ... cookie! Name: 'username' Value: 'admin' [Mar 4 20:17:18] DEBUG[4585] http.c: mmm ... cookie! Name: 'rwaccess' Value: 'yes' [Mar 4 20:17:18] DEBUG[4585] manager.c: Manager received command 'ping' [Mar 4 20:17:21] DEBUG[2178] chan_sip.c: Setting NAT on RTP to Off [Mar 4 20:17:21] DEBUG[2178] chan_sip.c: Setting NAT on UDPTL to Off [Mar 4 20:17:21] DEBUG[2178] chan_sip.c: Allocating new SIP dialog for 00075098-10c80011-16aa974b-3e8e4249@172.17.15.156 - INVITE (With RTP) [Mar 4 20:17:21] DEBUG[2178] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Mar 4 20:17:21] DEBUG[2178] chan_sip.c: Setting NAT on RTP to Off [Mar 4 20:17:21] DEBUG[2178] chan_sip.c: Setting NAT on UDPTL to Off [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: = Found Their Call ID: 00075098-10c80011-16aa974b-3e8e4249@172.17.15.156 Their Tag 0007509810c8001d53114588-3c4cf997 Our tag: as2d76e1ec [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Stopping retransmission on '00075098-10c80011-16aa974b-3e8e4249@172.17.15.156' of Response 101: Match Found [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: = Found Their Call ID: 00075098-10c80011-16aa974b-3e8e4249@172.17.15.156 Their Tag 0007509810c8001d53114588-3c4cf997 Our tag: as2d76e1ec [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Setting NAT on RTP to Off [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Setting NAT on UDPTL to Off [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing session-level SDP o=Cisco-SIPUA 19157 0 IN IP4 172.17.15.156... UNSUPPORTED. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 172.17.15.156... OK. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: T38 state changed to 0 on channel [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Checking SIP call limits for device 31 [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Updating call counter for incoming call [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Call from user '31' is 1 out of 100 [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: This channel will not be able to handle video. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: build_route: Contact hop: [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: SIP/31-0000005a: New call is still down.... Trying... [Mar 4 20:17:22] DEBUG[2178] devicestate.c: Notification of state change to be queued on device/channel SIP/31 [Mar 4 20:17:22] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:22] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:22] DEBUG[2173] devicestate.c: Changing state for SIP/31 - state 1 (Not in use) [Mar 4 20:17:22] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:22] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:22] DEBUG[4586] pbx.c: Launching 'Dial' [Mar 4 20:17:22] VERBOSE[4586] logger.c: -- Executing [39@DLPN_To_Town:1] Dial("SIP/31-0000005a", "SIP/39") in new stack [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: Our T38 capability (3856) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: Setting NAT on RTP to Off [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: Setting NAT on UDPTL to Off [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: This channel will not be able to handle video. [Mar 4 20:17:22] DEBUG[4586] channel.c: Not copying variable DIALEDTIME. [Mar 4 20:17:22] DEBUG[4586] channel.c: Not copying variable ANSWEREDTIME. [Mar 4 20:17:22] DEBUG[4586] channel.c: Not copying variable DIALEDPEERNAME. [Mar 4 20:17:22] DEBUG[4586] channel.c: Not copying variable DIALEDPEERNUMBER. [Mar 4 20:17:22] DEBUG[4586] channel.c: Not copying variable DIALSTATUS. [Mar 4 20:17:22] DEBUG[4586] channel.c: Not copying variable SIPCALLID. [Mar 4 20:17:22] DEBUG[4586] channel.c: Not copying variable SIPUSERAGENT. [Mar 4 20:17:22] DEBUG[4586] channel.c: Not copying variable SIPDOMAIN. [Mar 4 20:17:22] DEBUG[4586] channel.c: Not copying variable SIPURI. [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: Outgoing Call for 39 [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: Call to peer '39' is 1 out of 100 [Mar 4 20:17:22] DEBUG[4586] devicestate.c: Notification of state change to be queued on device/channel SIP/39 [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: Our T38 capability (3856), joint T38 capability (3856) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: -- Done with adding codecs to SDP [Mar 4 20:17:22] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=51) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Mar 4 20:17:22] VERBOSE[4586] logger.c: -- Called 39 [Mar 4 20:17:22] DEBUG[2194] app_queue.c: Device 'SIP/31' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:17:22] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:22] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:22] DEBUG[2173] devicestate.c: Changing state for SIP/39 - state 6 (Ringing) [Mar 4 20:17:22] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:22] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:22] DEBUG[2194] app_queue.c: Device 'SIP/39' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: = Found Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag Our tag: as65ccebdf [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245' Request 102: Found [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: SIP response 100 to standard invite [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: = Found Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag Our tag: as65ccebdf [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245' Request 102: Found [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: SIP response 180 to standard invite [Mar 4 20:17:22] DEBUG[2178] devicestate.c: Notification of state change to be queued on device/channel SIP/39 [Mar 4 20:17:22] VERBOSE[4586] logger.c: -- SIP/39-0000005b is ringing [Mar 4 20:17:22] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:22] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:22] DEBUG[2173] devicestate.c: Changing state for SIP/39 - state 6 (Ringing) [Mar 4 20:17:22] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:22] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:22] DEBUG[2194] app_queue.c: Device 'SIP/39' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: = Found Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag 6231074f28f5c1cb Our tag: as65ccebdf [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Acked pending invite 102 [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Stopping retransmission on '6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245' of Request 102: Match Found [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: SIP response 200 to standard invite [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing session-level SDP o=39 8000 8000 IN IP4 172.17.15.166... UNSUPPORTED. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing session-level SDP c=IN IP4 172.17.15.166... OK. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: T38 state changed to 0 on channel SIP/39-0000005b [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: We have an owner, now see if we need to change this call [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:22] DEBUG[2178] devicestate.c: Notification of state change to be queued on device/channel SIP/39 [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: build_route: Contact hop: [Mar 4 20:17:22] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:22] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:22] DEBUG[2173] devicestate.c: Changing state for SIP/39 - state 2 (In use) [Mar 4 20:17:22] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:22] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:22] DEBUG[4586] devicestate.c: Notification of state change to be queued on device/channel SIP/39 [Mar 4 20:17:22] VERBOSE[4586] logger.c: -- SIP/39-0000005b answered SIP/31-0000005a [Mar 4 20:17:22] DEBUG[4586] devicestate.c: Notification of state change to be queued on device/channel SIP/31 [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: SIP answering channel: SIP/31-0000005a [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: Setting framing from config on incoming call [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: -- Done with adding codecs to SDP [Mar 4 20:17:22] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:22] DEBUG[4586] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Mar 4 20:17:22] VERBOSE[4586] logger.c: -- Packet2Packet bridging SIP/31-0000005a and SIP/39-0000005b [Mar 4 20:17:22] DEBUG[2194] app_queue.c: Device 'SIP/39' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 4 20:17:22] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:22] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:22] DEBUG[2173] devicestate.c: Changing state for SIP/39 - state 2 (In use) [Mar 4 20:17:22] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:22] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:22] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:22] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:22] DEBUG[2173] devicestate.c: Changing state for SIP/31 - state 1 (Not in use) [Mar 4 20:17:22] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:22] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:22] DEBUG[2194] app_queue.c: Device 'SIP/39' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 4 20:17:22] DEBUG[2194] app_queue.c: Device 'SIP/31' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: = No match Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag 6231074f28f5c1cb Our tag: as65ccebdf [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: = Found Their Call ID: 00075098-10c80011-16aa974b-3e8e4249@172.17.15.156 Their Tag 0007509810c8001d53114588-3c4cf997 Our tag: as1a65d90d [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Mar 4 20:17:22] DEBUG[2178] chan_sip.c: Stopping retransmission on '00075098-10c80011-16aa974b-3e8e4249@172.17.15.156' of Response 102: Match Found [Mar 4 20:17:23] DEBUG[4587] http.c: mmm ... cookie! Name: 'mansession_id' Value: '15b88fb5' [Mar 4 20:17:23] DEBUG[4587] http.c: mmm ... cookie! Name: 'username' Value: 'admin' [Mar 4 20:17:23] DEBUG[4587] http.c: mmm ... cookie! Name: 'rwaccess' Value: 'yes' [Mar 4 20:17:23] DEBUG[4587] manager.c: Manager received command 'ping' [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: = Found Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag 6231074f28f5c1cb Our tag: as65ccebdf [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: Processing session-level SDP o=39 8000 8001 IN IP4 172.17.15.166... UNSUPPORTED. [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: Processing session-level SDP c=IN IP4 172.17.15.166... OK. [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=sendonly... OK. [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED. [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: T38 state changed to 0 on channel SIP/39-0000005b [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: We have an owner, now see if we need to change this call [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: SIP/39-0000005b: This call is UP.... [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: Setting framing from config on incoming call [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: -- Done with adding codecs to SDP [Mar 4 20:17:24] DEBUG[2178] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=51) [Mar 4 20:17:24] DEBUG[2178] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Mar 4 20:17:24] VERBOSE[4586] logger.c: -- Started music on hold, class 'default', on SIP/31-0000005a [Mar 4 20:17:24] DEBUG[4586] channel.c: Scheduling timer at 160 sample intervals [Mar 4 20:17:24] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:24] DEBUG[4586] channel.c: Generator got voice, switching to phase locked mode [Mar 4 20:17:24] DEBUG[4586] channel.c: Scheduling timer at 0 sample intervals [Mar 4 20:17:24] DEBUG[4586] channel.c: Set channel SIP/31-0000005a to write format slin [Mar 4 20:17:24] DEBUG[4586] res_musiconhold.c: SIP/31-0000005a Opened file 0 '/var/lib/asterisk/moh/macroform-the_simplicity' [Mar 4 20:17:24] DEBUG[4586] rtp.c: Ooh, format changed from unknown to ulaw [Mar 4 20:17:24] DEBUG[4586] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[2178] chan_sip.c: = Found Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag 6231074f28f5c1cb Our tag: as65ccebdf [Mar 4 20:17:25] DEBUG[2178] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Mar 4 20:17:25] DEBUG[2178] chan_sip.c: Stopping retransmission on '6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245' of Response 63806: Match Found [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:25] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:26] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[2178] app_voicemail.c: Mailbox is set to 37 [Mar 4 20:17:27] ERROR[2178] app_voicemail.c: Couldn't find mailbox 37 in context default [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: = Found Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag 6231074f28f5c1cb Our tag: as65ccebdf [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: **** Received REFER (9) - Command in SIP REFER [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: chan1->name: SIP/39-0000005b [Mar 4 20:17:27] DEBUG[2178] channel.c: Soft-Hanging up channel 'SIP/31-0000005a' [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: Blind transfer succeeded. Telling transferer. [Mar 4 20:17:27] VERBOSE[4586] logger.c: -- Stopped music on hold on SIP/31-0000005a [Mar 4 20:17:27] DEBUG[4586] channel.c: Set channel SIP/31-0000005a to write format ulaw [Mar 4 20:17:27] DEBUG[4586] channel.c: Scheduling timer at 0 sample intervals [Mar 4 20:17:27] DEBUG[4586] rtp.c: Oooh, got a hangup [Mar 4 20:17:27] DEBUG[4586] channel.c: Returning from native bridge, channels: SIP/31-0000005a, SIP/39-0000005b [Mar 4 20:17:27] DEBUG[4586] channel.c: Hanging up channel 'SIP/39-0000005b' [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Call to peer '39' removed from call limit 100 [Mar 4 20:17:27] DEBUG[4586] devicestate.c: Notification of state change to be queued on device/channel SIP/39 [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245. [Mar 4 20:17:27] DEBUG[4586] devicestate.c: Notification of state change to be queued on device/channel SIP/39 [Mar 4 20:17:27] DEBUG[4586] rtp.c: Channel '' has no RTP, not doing anything [Mar 4 20:17:27] DEBUG[4586] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Mar 4 20:17:27] DEBUG[4586] pbx.c: Spawn extension (DLPN_To_Town,37,0) exited non-zero on 'SIP/31-0000005a' [Mar 4 20:17:27] VERBOSE[4586] logger.c: == Spawn extension (DLPN_To_Town, 37, 0) exited non-zero on 'SIP/31-0000005a' [Mar 4 20:17:27] DEBUG[4586] pbx.c: Launching 'Dial' [Mar 4 20:17:27] VERBOSE[4586] logger.c: -- Executing [37@DLPN_To_Town:1] Dial("SIP/31-0000005a", "SIP/37") in new stack [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Our T38 capability (3856) [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Setting NAT on RTP to Off [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Setting NAT on UDPTL to Off [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: *** Our capabilities are 0x6 (gsm|ulaw) [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: This channel will not be able to handle video. [Mar 4 20:17:27] DEBUG[4586] rtp.c: Seeded SDP of 'SIP/37-0000005c' with that of 'SIP/31-0000005a' [Mar 4 20:17:27] DEBUG[4586] channel.c: Not copying variable DIALEDTIME. [Mar 4 20:17:27] DEBUG[4586] channel.c: Not copying variable ANSWEREDTIME. [Mar 4 20:17:27] DEBUG[4586] channel.c: Not copying variable DIALEDPEERNAME. [Mar 4 20:17:27] DEBUG[4586] channel.c: Not copying variable DIALEDPEERNUMBER. [Mar 4 20:17:27] DEBUG[4586] channel.c: Not copying variable DIALSTATUS. [Mar 4 20:17:27] DEBUG[4586] channel.c: Copying soft-transferable variable SIPTRANSFER_REFERER. [Mar 4 20:17:27] DEBUG[4586] channel.c: Copying soft-transferable variable SIPTRANSFER. [Mar 4 20:17:27] DEBUG[4586] channel.c: Not copying variable SIPDOMAIN. [Mar 4 20:17:27] DEBUG[4586] channel.c: Not copying variable BLINDTRANSFER. [Mar 4 20:17:27] DEBUG[4586] channel.c: Not copying variable BRIDGEPEER. [Mar 4 20:17:27] DEBUG[4586] channel.c: Not copying variable SIPCALLID. [Mar 4 20:17:27] DEBUG[4586] channel.c: Not copying variable SIPUSERAGENT. [Mar 4 20:17:27] DEBUG[4586] channel.c: Not copying variable SIPURI. [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Outgoing Call for 37 [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Call to peer '37' is 1 out of 100 [Mar 4 20:17:27] DEBUG[4586] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Our T38 capability (3856), joint T38 capability (3856) [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: ** Our capability: 0x6 (gsm|ulaw) Video flag: False [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: -- Done with adding codecs to SDP [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=54) [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Done building SDP. Settling with this capability: 0x6 (gsm|ulaw) [Mar 4 20:17:27] VERBOSE[4586] logger.c: -- Called 37 [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Done building SDP. Settling with this capability: 0x0 (nothing) [Mar 4 20:17:27] DEBUG[4586] chan_sip.c: Initializing already initialized SIP dialog 00075098-10c80011-16aa974b-3e8e4249@172.17.15.156 (presumably reinvite) [Mar 4 20:17:27] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:27] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:27] DEBUG[2173] devicestate.c: Changing state for SIP/39 - state 1 (Not in use) [Mar 4 20:17:27] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:27] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:27] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:27] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:27] DEBUG[2173] devicestate.c: Changing state for SIP/39 - state 1 (Not in use) [Mar 4 20:17:27] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:27] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:27] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:27] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:27] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 6 (Ringing) [Mar 4 20:17:27] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:27] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:27] DEBUG[2194] app_queue.c: Device 'SIP/39' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:17:27] DEBUG[2194] app_queue.c: Device 'SIP/39' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:17:27] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: = Found Their Call ID: 7adf10262594f44b430e1e356a2ea053@172.17.15.245 Their Tag Our tag: as082cffc5 [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7adf10262594f44b430e1e356a2ea053@172.17.15.245' Request 102: Found [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: SIP response 100 to standard invite [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: = Found Their Call ID: 7adf10262594f44b430e1e356a2ea053@172.17.15.245 Their Tag Our tag: as082cffc5 [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7adf10262594f44b430e1e356a2ea053@172.17.15.245' Request 102: Found [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: SIP response 180 to standard invite [Mar 4 20:17:27] DEBUG[2178] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:17:27] VERBOSE[4586] logger.c: -- SIP/37-0000005c is ringing [Mar 4 20:17:27] DEBUG[4586] rtp.c: Setting early bridge SDP of 'SIP/31-0000005a' with that of 'SIP/37-0000005c' [Mar 4 20:17:27] DEBUG[4586] channel.c: Driver for channel 'SIP/31-0000005a' does not support indication 3, emulating it [Mar 4 20:17:27] DEBUG[4586] channel.c: Set channel SIP/31-0000005a to write format slin [Mar 4 20:17:27] DEBUG[4586] channel.c: Scheduling timer at 160 sample intervals [Mar 4 20:17:27] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:27] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:27] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 6 (Ringing) [Mar 4 20:17:27] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:27] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:27] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Generator got voice, switching to phase locked mode [Mar 4 20:17:27] DEBUG[4586] channel.c: Scheduling timer at 0 sample intervals [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: = No match Their Call ID: 7adf10262594f44b430e1e356a2ea053@172.17.15.245 Their Tag eaff4519210ee579 Our tag: as082cffc5 [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: = Found Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag 6231074f28f5c1cb Our tag: as65ccebdf [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: Stopping retransmission on '6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245' of Request 103: Match Found [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: = No match Their Call ID: 7adf10262594f44b430e1e356a2ea053@172.17.15.245 Their Tag eaff4519210ee579 Our tag: as082cffc5 [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: = Found Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag 6231074f28f5c1cb Our tag: as65ccebdf [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: Stopping retransmission on '6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245' of Request 104: Match Found [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: = No match Their Call ID: 7adf10262594f44b430e1e356a2ea053@172.17.15.245 Their Tag eaff4519210ee579 Our tag: as082cffc5 [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: = No match Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag 6231074f28f5c1cb Our tag: as65ccebdf [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: = Found Their Call ID: 00075098-10c80011-16aa974b-3e8e4249@172.17.15.156 Their Tag 0007509810c8001d53114588-3c4cf997 Our tag: as1a65d90d [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: Acked pending invite 102 [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: Stopping retransmission on '00075098-10c80011-16aa974b-3e8e4249@172.17.15.156' of Request 102: Match Found [Mar 4 20:17:27] VERBOSE[2178] logger.c: -- Got SIP response 400 "Bad Request" back from 172.17.15.156 [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: Setting SIP_ALREADYGONE on dialog 00075098-10c80011-16aa974b-3e8e4249@172.17.15.156 [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: = No match Their Call ID: 7adf10262594f44b430e1e356a2ea053@172.17.15.245 Their Tag eaff4519210ee579 Our tag: as082cffc5 [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: = Found Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag 6231074f28f5c1cb Our tag: as65ccebdf [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: Setting SIP_ALREADYGONE on dialog 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 [Mar 4 20:17:27] DEBUG[2178] chan_sip.c: Received bye, no owner, selfdestruct soon. [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:27] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4588] http.c: mmm ... cookie! Name: 'mansession_id' Value: '15b88fb5' [Mar 4 20:17:28] DEBUG[4588] http.c: mmm ... cookie! Name: 'username' Value: 'admin' [Mar 4 20:17:28] DEBUG[4588] http.c: mmm ... cookie! Name: 'rwaccess' Value: 'yes' [Mar 4 20:17:28] DEBUG[4588] manager.c: Manager received command 'ping' [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:28] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:29] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:30] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:30] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:30] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:30] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:30] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:30] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: = Found Their Call ID: 7adf10262594f44b430e1e356a2ea053@172.17.15.245 Their Tag eaff4519210ee579 Our tag: as082cffc5 [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Acked pending invite 102 [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Stopping retransmission on '7adf10262594f44b430e1e356a2ea053@172.17.15.245' of Request 102: Match Found [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: SIP response 200 to standard invite [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing session-level SDP o=37 8000 8000 IN IP4 172.17.17.90... UNSUPPORTED. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing session-level SDP c=IN IP4 172.17.17.90... OK. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: T38 state changed to 0 on channel SIP/37-0000005c [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: We have an owner, now see if we need to change this call [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:30] DEBUG[2178] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: build_route: Contact hop: [Mar 4 20:17:30] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:30] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:30] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 2 (In use) [Mar 4 20:17:30] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:30] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:30] DEBUG[4586] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:17:30] VERBOSE[4586] logger.c: -- SIP/37-0000005c answered SIP/31-0000005a [Mar 4 20:17:30] DEBUG[4586] rtp.c: Setting early bridge SDP of 'SIP/31-0000005a' with that of 'SIP/37-0000005c' [Mar 4 20:17:30] DEBUG[4586] channel.c: Set channel SIP/31-0000005a to write format ulaw [Mar 4 20:17:30] DEBUG[4586] channel.c: Scheduling timer at 0 sample intervals [Mar 4 20:17:30] VERBOSE[4586] logger.c: -- Native bridging SIP/31-0000005a and SIP/37-0000005c [Mar 4 20:17:30] DEBUG[4586] chan_sip.c: Sending reinvite on SIP '7adf10262594f44b430e1e356a2ea053@172.17.15.245' - It's audio soon redirected to IP 0.0.0.0 [Mar 4 20:17:30] DEBUG[4586] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Mar 4 20:17:30] DEBUG[4586] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Mar 4 20:17:30] DEBUG[4586] chan_sip.c: -- Done with adding codecs to SDP [Mar 4 20:17:30] DEBUG[4586] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=54) [Mar 4 20:17:30] DEBUG[4586] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Mar 4 20:17:30] DEBUG[4586] chan_sip.c: Initializing already initialized SIP dialog 7adf10262594f44b430e1e356a2ea053@172.17.15.245 (presumably reinvite) [Mar 4 20:17:30] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 4 20:17:30] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:30] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:30] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 2 (In use) [Mar 4 20:17:30] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:30] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:30] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 4 20:17:30] DEBUG[4586] rtp.c: Ooh, format changed from unknown to ulaw [Mar 4 20:17:30] DEBUG[4586] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: = Found Their Call ID: 7adf10262594f44b430e1e356a2ea053@172.17.15.245 Their Tag eaff4519210ee579 Our tag: as082cffc5 [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Acked pending invite 103 [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Stopping retransmission on '7adf10262594f44b430e1e356a2ea053@172.17.15.245' of Request 103: Match Found [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: SIP response 200 to RE-invite on outgoing call 7adf10262594f44b430e1e356a2ea053@172.17.15.245 [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing session-level SDP o=37 8000 8001 IN IP4 172.17.17.90... UNSUPPORTED. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing session-level SDP c=IN IP4 172.17.17.90... OK. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED. [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: T38 state changed to 0 on channel SIP/37-0000005c [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: We have an owner, now see if we need to change this call [Mar 4 20:17:30] DEBUG[2178] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:30] DEBUG[2178] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:17:30] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:30] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:30] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 2 (In use) [Mar 4 20:17:30] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:30] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:30] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 4 20:17:33] DEBUG[4589] http.c: mmm ... cookie! Name: 'mansession_id' Value: '15b88fb5' [Mar 4 20:17:33] DEBUG[4589] http.c: mmm ... cookie! Name: 'username' Value: 'admin' [Mar 4 20:17:33] DEBUG[4589] http.c: mmm ... cookie! Name: 'rwaccess' Value: 'yes' [Mar 4 20:17:33] DEBUG[4589] manager.c: Manager received command 'ping' [Mar 4 20:17:38] DEBUG[2178] app_voicemail.c: Mailbox is set to 37 [Mar 4 20:17:38] ERROR[2178] app_voicemail.c: Couldn't find mailbox 37 in context default [Mar 4 20:17:38] DEBUG[4590] http.c: mmm ... cookie! Name: 'mansession_id' Value: '15b88fb5' [Mar 4 20:17:38] DEBUG[4590] http.c: mmm ... cookie! Name: 'username' Value: 'admin' [Mar 4 20:17:38] DEBUG[4590] http.c: mmm ... cookie! Name: 'rwaccess' Value: 'yes' [Mar 4 20:17:38] DEBUG[4590] manager.c: Manager received command 'ping' [Mar 4 20:17:43] DEBUG[2178] chan_sip.c: = Found Their Call ID: 7adf10262594f44b430e1e356a2ea053@172.17.15.245 Their Tag eaff4519210ee579 Our tag: as082cffc5 [Mar 4 20:17:43] DEBUG[2178] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Mar 4 20:17:43] DEBUG[2178] chan_sip.c: Setting SIP_ALREADYGONE on dialog 7adf10262594f44b430e1e356a2ea053@172.17.15.245 [Mar 4 20:17:43] DEBUG[2178] chan_sip.c: Received bye, issuing owner hangup [Mar 4 20:17:43] DEBUG[4586] rtp.c: Oooh, got a hangup [Mar 4 20:17:43] DEBUG[4586] channel.c: Returning from native bridge, channels: SIP/31-0000005a, SIP/37-0000005c [Mar 4 20:17:43] DEBUG[4586] channel.c: Hanging up channel 'SIP/37-0000005c' [Mar 4 20:17:43] DEBUG[4586] chan_sip.c: Hangup call SIP/37-0000005c, SIP callid 7adf10262594f44b430e1e356a2ea053@172.17.15.245) [Mar 4 20:17:43] DEBUG[4586] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:43] DEBUG[4586] chan_sip.c: Call to peer '37' removed from call limit 100 [Mar 4 20:17:43] DEBUG[4586] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:17:43] DEBUG[4586] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:17:43] DEBUG[4586] rtp.c: Channel '' has no RTP, not doing anything [Mar 4 20:17:43] DEBUG[4586] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Mar 4 20:17:43] DEBUG[4586] pbx.c: Spawn extension (DLPN_To_Town,37,1) exited non-zero on 'SIP/31-0000005a' [Mar 4 20:17:43] VERBOSE[4586] logger.c: == Spawn extension (DLPN_To_Town, 37, 1) exited non-zero on 'SIP/31-0000005a' [Mar 4 20:17:43] DEBUG[4586] channel.c: Soft-Hanging up channel 'SIP/31-0000005a' [Mar 4 20:17:43] DEBUG[4586] channel.c: Hanging up channel 'SIP/31-0000005a' [Mar 4 20:17:43] DEBUG[4586] chan_sip.c: Hangup call SIP/31-0000005a, SIP callid 00075098-10c80011-16aa974b-3e8e4249@172.17.15.156) [Mar 4 20:17:43] DEBUG[4586] chan_sip.c: Updating call counter for incoming call [Mar 4 20:17:43] DEBUG[4586] chan_sip.c: Call from user '31' removed from call limit 100 [Mar 4 20:17:43] DEBUG[4586] devicestate.c: Notification of state change to be queued on device/channel SIP/31 [Mar 4 20:17:43] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:43] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:43] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 1 (Not in use) [Mar 4 20:17:43] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:43] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:43] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:43] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:43] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 1 (Not in use) [Mar 4 20:17:43] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:43] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:43] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:43] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:43] DEBUG[2173] devicestate.c: Changing state for SIP/31 - state 1 (Not in use) [Mar 4 20:17:43] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:43] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:43] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:17:43] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:17:43] DEBUG[2194] app_queue.c: Device 'SIP/31' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:17:43] DEBUG[4591] http.c: mmm ... cookie! Name: 'mansession_id' Value: '15b88fb5' [Mar 4 20:17:43] DEBUG[4591] http.c: mmm ... cookie! Name: 'username' Value: 'admin' [Mar 4 20:17:43] DEBUG[4591] http.c: mmm ... cookie! Name: 'rwaccess' Value: 'yes' [Mar 4 20:17:43] DEBUG[4591] manager.c: Manager received command 'ping' [Mar 4 20:17:44] VERBOSE[2178] logger.c: Really destroying SIP dialog '7adf10262594f44b430e1e356a2ea053@172.17.15.245' Method: BYE [Mar 4 20:17:44] VERBOSE[2178] logger.c: Really destroying SIP dialog '00075098-10c80011-16aa974b-3e8e4249@172.17.15.156' Method: ACK [Mar 4 20:17:45] DEBUG[2178] chan_sip.c: = No match Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag 6231074f28f5c1cb Our tag: as65ccebdf [Mar 4 20:17:45] DEBUG[2178] chan_sip.c: Invalid SIP message - rejected , no callid, len 567 [Mar 4 20:17:48] DEBUG[4592] http.c: mmm ... cookie! Name: 'mansession_id' Value: '15b88fb5' [Mar 4 20:17:48] DEBUG[4592] http.c: mmm ... cookie! Name: 'username' Value: 'admin' [Mar 4 20:17:48] DEBUG[4592] http.c: mmm ... cookie! Name: 'rwaccess' Value: 'yes' [Mar 4 20:17:48] DEBUG[4592] manager.c: Manager received command 'ping' [Mar 4 20:17:49] DEBUG[2178] app_voicemail.c: Mailbox is set to 37 [Mar 4 20:17:49] ERROR[2178] app_voicemail.c: Couldn't find mailbox 37 in context default [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: = No match Their Call ID: 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 Their Tag 6231074f28f5c1cb Our tag: as65ccebdf [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Setting NAT on RTP to Off [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Setting NAT on UDPTL to Off [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Allocating new SIP dialog for 2182f5e6902ddd1d@172.17.15.166 - INVITE (With RTP) [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Setting NAT on RTP to Off [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Setting NAT on UDPTL to Off [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: = Found Their Call ID: 2182f5e6902ddd1d@172.17.15.166 Their Tag a52204d7f89cff94 Our tag: as2977b66a [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Stopping retransmission on '2182f5e6902ddd1d@172.17.15.166' of Response 52754: Match Found [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: = Found Their Call ID: 2182f5e6902ddd1d@172.17.15.166 Their Tag a52204d7f89cff94 Our tag: as2977b66a [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Setting NAT on RTP to Off [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Setting NAT on UDPTL to Off [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Processing session-level SDP o=39 8000 8001 IN IP4 172.17.15.166... UNSUPPORTED. [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Processing session-level SDP c=IN IP4 172.17.15.166... OK. [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED. [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: T38 state changed to 0 on channel [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Checking SIP call limits for device 39 [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Updating call counter for incoming call [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: Call from user '39' is 1 out of 100 [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: This channel will not be able to handle video. [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: build_route: Contact hop: [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: SIP/39-0000005d: New call is still down.... Trying... [Mar 4 20:17:49] DEBUG[2178] devicestate.c: Notification of state change to be queued on device/channel SIP/39 [Mar 4 20:17:49] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:49] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:49] DEBUG[2173] devicestate.c: Changing state for SIP/39 - state 1 (Not in use) [Mar 4 20:17:49] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:49] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:49] DEBUG[4593] pbx.c: Launching 'Dial' [Mar 4 20:17:49] VERBOSE[4593] logger.c: -- Executing [31@DLPN_To_Town:1] Dial("SIP/39-0000005d", "SIP/31") in new stack [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: Our T38 capability (3856) [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: Setting NAT on RTP to Off [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: Setting NAT on UDPTL to Off [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: This channel will not be able to handle video. [Mar 4 20:17:49] DEBUG[4593] channel.c: Not copying variable DIALEDTIME. [Mar 4 20:17:49] DEBUG[4593] channel.c: Not copying variable ANSWEREDTIME. [Mar 4 20:17:49] DEBUG[4593] channel.c: Not copying variable DIALEDPEERNAME. [Mar 4 20:17:49] DEBUG[4593] channel.c: Not copying variable DIALEDPEERNUMBER. [Mar 4 20:17:49] DEBUG[4593] channel.c: Not copying variable DIALSTATUS. [Mar 4 20:17:49] DEBUG[4593] channel.c: Not copying variable SIPCALLID. [Mar 4 20:17:49] DEBUG[4593] channel.c: Not copying variable SIPUSERAGENT. [Mar 4 20:17:49] DEBUG[4593] channel.c: Not copying variable SIPDOMAIN. [Mar 4 20:17:49] DEBUG[4593] channel.c: Not copying variable SIPURI. [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: Outgoing Call for 31 [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: Call to peer '31' is 1 out of 100 [Mar 4 20:17:49] DEBUG[4593] devicestate.c: Notification of state change to be queued on device/channel SIP/31 [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: Our T38 capability (3856), joint T38 capability (3856) [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: -- Done with adding codecs to SDP [Mar 4 20:17:49] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=54) [Mar 4 20:17:49] DEBUG[4593] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Mar 4 20:17:49] VERBOSE[4593] logger.c: -- Called 31 [Mar 4 20:17:49] DEBUG[2194] app_queue.c: Device 'SIP/39' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:17:49] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:49] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:49] DEBUG[2173] devicestate.c: Changing state for SIP/31 - state 6 (Ringing) [Mar 4 20:17:49] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:49] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:49] DEBUG[2194] app_queue.c: Device 'SIP/31' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: = Found Their Call ID: 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 Their Tag Our tag: as60e0c701 [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245' Request 102: Found [Mar 4 20:17:49] DEBUG[2178] chan_sip.c: SIP response 100 to standard invite [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: = Found Their Call ID: 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 Their Tag Our tag: as60e0c701 [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245' Request 102: Found [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: SIP response 180 to standard invite [Mar 4 20:17:50] DEBUG[2178] devicestate.c: Notification of state change to be queued on device/channel SIP/31 [Mar 4 20:17:50] VERBOSE[4593] logger.c: -- SIP/31-0000005e is ringing [Mar 4 20:17:50] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:50] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:50] DEBUG[2173] devicestate.c: Changing state for SIP/31 - state 6 (Ringing) [Mar 4 20:17:50] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:50] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:50] DEBUG[2194] app_queue.c: Device 'SIP/31' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: = Found Their Call ID: 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 Their Tag 0007509810c8001e6877fe87-49d07234 Our tag: as60e0c701 [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Acked pending invite 102 [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Stopping retransmission on '43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245' of Request 102: Match Found [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: SIP response 200 to standard invite [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Processing session-level SDP o=Cisco-SIPUA 18995 0 IN IP4 172.17.15.156... UNSUPPORTED. [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 172.17.15.156... OK. [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: T38 state changed to 0 on channel SIP/31-0000005e [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: We have an owner, now see if we need to change this call [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:50] DEBUG[2178] devicestate.c: Notification of state change to be queued on device/channel SIP/31 [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: build_route: Contact hop: [Mar 4 20:17:50] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:50] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:50] DEBUG[2173] devicestate.c: Changing state for SIP/31 - state 2 (In use) [Mar 4 20:17:50] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:50] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:50] DEBUG[4593] devicestate.c: Notification of state change to be queued on device/channel SIP/31 [Mar 4 20:17:50] VERBOSE[4593] logger.c: -- SIP/31-0000005e answered SIP/39-0000005d [Mar 4 20:17:50] DEBUG[4593] devicestate.c: Notification of state change to be queued on device/channel SIP/39 [Mar 4 20:17:50] DEBUG[4593] chan_sip.c: SIP answering channel: SIP/39-0000005d [Mar 4 20:17:50] DEBUG[4593] chan_sip.c: Setting framing from config on incoming call [Mar 4 20:17:50] DEBUG[4593] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Mar 4 20:17:50] DEBUG[4593] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Mar 4 20:17:50] DEBUG[4593] chan_sip.c: -- Done with adding codecs to SDP [Mar 4 20:17:50] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:50] DEBUG[4593] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Mar 4 20:17:50] VERBOSE[4593] logger.c: -- Packet2Packet bridging SIP/39-0000005d and SIP/31-0000005e [Mar 4 20:17:50] DEBUG[2194] app_queue.c: Device 'SIP/31' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 4 20:17:50] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:50] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:50] DEBUG[2173] devicestate.c: Changing state for SIP/31 - state 2 (In use) [Mar 4 20:17:50] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:50] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:50] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:50] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:50] DEBUG[2173] devicestate.c: Changing state for SIP/39 - state 1 (Not in use) [Mar 4 20:17:50] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:50] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:50] DEBUG[2194] app_queue.c: Device 'SIP/31' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 4 20:17:50] DEBUG[2194] app_queue.c: Device 'SIP/39' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: = No match Their Call ID: 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 Their Tag 0007509810c8001e6877fe87-49d07234 Our tag: as60e0c701 [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: = Found Their Call ID: 2182f5e6902ddd1d@172.17.15.166 Their Tag a52204d7f89cff94 Our tag: as65399fa6 [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Mar 4 20:17:50] DEBUG[2178] chan_sip.c: Stopping retransmission on '2182f5e6902ddd1d@172.17.15.166' of Response 52755: Match Found [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: = Found Their Call ID: 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 Their Tag 0007509810c8001e6877fe87-49d07234 Our tag: as60e0c701 [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Processing session-level SDP o=Cisco-SIPUA 18995 1 IN IP4 172.17.15.156... UNSUPPORTED. [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 172.17.15.156... OK. [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED. [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=sendonly... OK. [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: T38 state changed to 0 on channel SIP/31-0000005e [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: We have an owner, now see if we need to change this call [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: SIP/31-0000005e: This call is UP.... [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Setting framing from config on incoming call [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: -- Done with adding codecs to SDP [Mar 4 20:17:52] DEBUG[2178] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=54) [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Mar 4 20:17:52] VERBOSE[4593] logger.c: -- Started music on hold, class 'default', on SIP/39-0000005d [Mar 4 20:17:52] DEBUG[4593] channel.c: Scheduling timer at 160 sample intervals [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:52] DEBUG[4593] channel.c: Generator got voice, switching to phase locked mode [Mar 4 20:17:52] DEBUG[4593] channel.c: Scheduling timer at 0 sample intervals [Mar 4 20:17:52] DEBUG[4593] channel.c: Set channel SIP/39-0000005d to write format slin [Mar 4 20:17:52] DEBUG[4593] res_musiconhold.c: SIP/39-0000005d Opened file 2 '/var/lib/asterisk/moh/macroform-cold_day' [Mar 4 20:17:52] DEBUG[4593] rtp.c: Ooh, format changed from unknown to ulaw [Mar 4 20:17:52] DEBUG[4593] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: = Found Their Call ID: 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 Their Tag 0007509810c8001e6877fe87-49d07234 Our tag: as60e0c701 [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Mar 4 20:17:52] DEBUG[2178] chan_sip.c: Stopping retransmission on '43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245' of Response 101: Match Found [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:52] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4594] http.c: mmm ... cookie! Name: 'mansession_id' Value: '15b88fb5' [Mar 4 20:17:53] DEBUG[4594] http.c: mmm ... cookie! Name: 'username' Value: 'admin' [Mar 4 20:17:53] DEBUG[4594] http.c: mmm ... cookie! Name: 'rwaccess' Value: 'yes' [Mar 4 20:17:53] DEBUG[4594] manager.c: Manager received command 'ping' [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: = Found Their Call ID: 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 Their Tag 0007509810c8001e6877fe87-49d07234 Our tag: as60e0c701 [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: **** Received REFER (9) - Command in SIP REFER [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: chan1->name: SIP/31-0000005e [Mar 4 20:17:53] DEBUG[2178] channel.c: Soft-Hanging up channel 'SIP/39-0000005d' [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: Blind transfer succeeded. Telling transferer. [Mar 4 20:17:53] VERBOSE[4593] logger.c: -- Stopped music on hold on SIP/39-0000005d [Mar 4 20:17:53] DEBUG[4593] channel.c: Set channel SIP/39-0000005d to write format ulaw [Mar 4 20:17:53] DEBUG[4593] channel.c: Scheduling timer at 0 sample intervals [Mar 4 20:17:53] DEBUG[4593] rtp.c: Oooh, got a hangup [Mar 4 20:17:53] DEBUG[4593] channel.c: Returning from native bridge, channels: SIP/39-0000005d, SIP/31-0000005e [Mar 4 20:17:53] DEBUG[4593] channel.c: Hanging up channel 'SIP/31-0000005e' [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Call to peer '31' removed from call limit 100 [Mar 4 20:17:53] DEBUG[4593] devicestate.c: Notification of state change to be queued on device/channel SIP/31 [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245. [Mar 4 20:17:53] DEBUG[4593] devicestate.c: Notification of state change to be queued on device/channel SIP/31 [Mar 4 20:17:53] DEBUG[4593] rtp.c: Channel '' has no RTP, not doing anything [Mar 4 20:17:53] DEBUG[4593] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Mar 4 20:17:53] DEBUG[4593] pbx.c: Spawn extension (DLPN_To_Town,37,0) exited non-zero on 'SIP/39-0000005d' [Mar 4 20:17:53] VERBOSE[4593] logger.c: == Spawn extension (DLPN_To_Town, 37, 0) exited non-zero on 'SIP/39-0000005d' [Mar 4 20:17:53] DEBUG[4593] pbx.c: Launching 'Dial' [Mar 4 20:17:53] VERBOSE[4593] logger.c: -- Executing [37@DLPN_To_Town:1] Dial("SIP/39-0000005d", "SIP/37") in new stack [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Our T38 capability (3856) [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Setting NAT on RTP to Off [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Setting NAT on UDPTL to Off [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: *** Our capabilities are 0x6 (gsm|ulaw) [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: This channel will not be able to handle video. [Mar 4 20:17:53] DEBUG[4593] channel.c: Not copying variable DIALEDTIME. [Mar 4 20:17:53] DEBUG[4593] channel.c: Not copying variable ANSWEREDTIME. [Mar 4 20:17:53] DEBUG[4593] channel.c: Not copying variable DIALEDPEERNAME. [Mar 4 20:17:53] DEBUG[4593] channel.c: Not copying variable DIALEDPEERNUMBER. [Mar 4 20:17:53] DEBUG[4593] channel.c: Not copying variable DIALSTATUS. [Mar 4 20:17:53] DEBUG[4593] channel.c: Copying soft-transferable variable SIPTRANSFER_REFERER. [Mar 4 20:17:53] DEBUG[4593] channel.c: Copying soft-transferable variable SIPTRANSFER. [Mar 4 20:17:53] DEBUG[4593] channel.c: Not copying variable SIPDOMAIN. [Mar 4 20:17:53] DEBUG[4593] channel.c: Not copying variable BLINDTRANSFER. [Mar 4 20:17:53] DEBUG[4593] channel.c: Not copying variable BRIDGEPEER. [Mar 4 20:17:53] DEBUG[4593] channel.c: Not copying variable SIPCALLID. [Mar 4 20:17:53] DEBUG[4593] channel.c: Not copying variable SIPUSERAGENT. [Mar 4 20:17:53] DEBUG[4593] channel.c: Not copying variable SIPURI. [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Outgoing Call for 37 [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Call to peer '37' is 1 out of 100 [Mar 4 20:17:53] DEBUG[4593] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Our T38 capability (3856), joint T38 capability (3856) [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: ** Our capability: 0x6 (gsm|ulaw) Video flag: False [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: -- Done with adding codecs to SDP [Mar 4 20:17:53] DEBUG[4593] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=57) [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Done building SDP. Settling with this capability: 0x6 (gsm|ulaw) [Mar 4 20:17:53] VERBOSE[4593] logger.c: -- Called 37 [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Done building SDP. Settling with this capability: 0x0 (nothing) [Mar 4 20:17:53] DEBUG[4593] chan_sip.c: Initializing already initialized SIP dialog 2182f5e6902ddd1d@172.17.15.166 (presumably reinvite) [Mar 4 20:17:53] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:53] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:53] DEBUG[2173] devicestate.c: Changing state for SIP/31 - state 1 (Not in use) [Mar 4 20:17:53] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:53] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:53] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:53] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:53] DEBUG[2173] devicestate.c: Changing state for SIP/31 - state 1 (Not in use) [Mar 4 20:17:53] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 31 [Mar 4 20:17:53] DEBUG[2173] chan_sip.c: Checking device state for peer 31 [Mar 4 20:17:53] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:53] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:53] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 6 (Ringing) [Mar 4 20:17:53] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:53] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:53] DEBUG[2194] app_queue.c: Device 'SIP/31' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:17:53] DEBUG[2194] app_queue.c: Device 'SIP/31' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:17:53] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: = Found Their Call ID: 2cb847bb427d935951f616f43cbc74b4@172.17.15.245 Their Tag Our tag: as40690467 [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '2cb847bb427d935951f616f43cbc74b4@172.17.15.245' Request 102: Found [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: SIP response 100 to standard invite [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: = Found Their Call ID: 2cb847bb427d935951f616f43cbc74b4@172.17.15.245 Their Tag Our tag: as40690467 [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '2cb847bb427d935951f616f43cbc74b4@172.17.15.245' Request 102: Found [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: SIP response 180 to standard invite [Mar 4 20:17:53] DEBUG[2178] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:17:53] VERBOSE[4593] logger.c: -- SIP/37-0000005f is ringing [Mar 4 20:17:53] DEBUG[4593] channel.c: Driver for channel 'SIP/39-0000005d' does not support indication 3, emulating it [Mar 4 20:17:53] DEBUG[4593] channel.c: Set channel SIP/39-0000005d to write format slin [Mar 4 20:17:53] DEBUG[4593] channel.c: Scheduling timer at 160 sample intervals [Mar 4 20:17:53] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:53] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:53] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 6 (Ringing) [Mar 4 20:17:53] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:53] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:53] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: = No match Their Call ID: 2cb847bb427d935951f616f43cbc74b4@172.17.15.245 Their Tag 6756a5091bcbcacb Our tag: as40690467 [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: = No match Their Call ID: 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 Their Tag 0007509810c8001e6877fe87-49d07234 Our tag: as60e0c701 [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: = Found Their Call ID: 2182f5e6902ddd1d@172.17.15.166 Their Tag a52204d7f89cff94 Our tag: as65399fa6 [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: Acked pending invite 102 [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: Stopping retransmission on '2182f5e6902ddd1d@172.17.15.166' of Request 102: Match Found [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: SIP response 200 to RE-invite on outgoing call 2182f5e6902ddd1d@172.17.15.166 [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: Processing session-level SDP o=39 8000 8002 IN IP4 172.17.15.166... UNSUPPORTED. [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: Processing session-level SDP c=IN IP4 172.17.15.166... OK. [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: T38 state changed to 0 on channel SIP/39-0000005d [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: We have an owner, now see if we need to change this call [Mar 4 20:17:53] DEBUG[2178] chan_sip.c: Updating call counter for incoming call [Mar 4 20:17:54] DEBUG[2178] chan_sip.c: = No match Their Call ID: 2cb847bb427d935951f616f43cbc74b4@172.17.15.245 Their Tag 6756a5091bcbcacb Our tag: as40690467 [Mar 4 20:17:54] DEBUG[2178] chan_sip.c: = Found Their Call ID: 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 Their Tag 0007509810c8001e6877fe87-49d07234 Our tag: as60e0c701 [Mar 4 20:17:54] DEBUG[2178] chan_sip.c: Stopping retransmission on '43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245' of Request 103: Match Found [Mar 4 20:17:54] DEBUG[2178] chan_sip.c: = No match Their Call ID: 2cb847bb427d935951f616f43cbc74b4@172.17.15.245 Their Tag 6756a5091bcbcacb Our tag: as40690467 [Mar 4 20:17:54] DEBUG[2178] chan_sip.c: = Found Their Call ID: 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 Their Tag 0007509810c8001e6877fe87-49d07234 Our tag: as60e0c701 [Mar 4 20:17:54] DEBUG[2178] chan_sip.c: Stopping retransmission on '43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245' of Request 104: Match Found [Mar 4 20:17:54] DEBUG[2178] chan_sip.c: = No match Their Call ID: 2cb847bb427d935951f616f43cbc74b4@172.17.15.245 Their Tag 6756a5091bcbcacb Our tag: as40690467 [Mar 4 20:17:54] DEBUG[2178] chan_sip.c: = Found Their Call ID: 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 Their Tag 0007509810c8001e6877fe87-49d07234 Our tag: as60e0c701 [Mar 4 20:17:54] DEBUG[2178] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Mar 4 20:17:54] DEBUG[2178] chan_sip.c: Setting SIP_ALREADYGONE on dialog 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 [Mar 4 20:17:54] DEBUG[2178] chan_sip.c: Received bye, no owner, selfdestruct soon. [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: = Found Their Call ID: 2cb847bb427d935951f616f43cbc74b4@172.17.15.245 Their Tag 6756a5091bcbcacb Our tag: as40690467 [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Acked pending invite 102 [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Stopping retransmission on '2cb847bb427d935951f616f43cbc74b4@172.17.15.245' of Request 102: Match Found [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: SIP response 200 to standard invite [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Processing session-level SDP o=37 8000 8000 IN IP4 172.17.17.90... UNSUPPORTED. [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Processing session-level SDP c=IN IP4 172.17.17.90... OK. [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED. [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: T38 state changed to 0 on channel SIP/37-0000005f [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: We have an owner, now see if we need to change this call [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:56] DEBUG[2178] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:17:56] DEBUG[2178] chan_sip.c: build_route: Contact hop: [Mar 4 20:17:56] DEBUG[4593] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:17:56] VERBOSE[4593] logger.c: -- SIP/37-0000005f answered SIP/39-0000005d [Mar 4 20:17:56] DEBUG[4593] channel.c: Set channel SIP/39-0000005d to write format ulaw [Mar 4 20:17:56] DEBUG[4593] channel.c: Scheduling timer at 0 sample intervals [Mar 4 20:17:56] VERBOSE[4593] logger.c: -- Packet2Packet bridging SIP/39-0000005d and SIP/37-0000005f [Mar 4 20:17:56] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:56] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:56] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 2 (In use) [Mar 4 20:17:56] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:56] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:56] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:56] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:56] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 2 (In use) [Mar 4 20:17:56] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:17:56] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:17:56] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 4 20:17:56] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 4 20:17:58] DEBUG[4595] http.c: mmm ... cookie! Name: 'mansession_id' Value: '15b88fb5' [Mar 4 20:17:58] DEBUG[4595] http.c: mmm ... cookie! Name: 'username' Value: 'admin' [Mar 4 20:17:58] DEBUG[4595] http.c: mmm ... cookie! Name: 'rwaccess' Value: 'yes' [Mar 4 20:17:58] DEBUG[4595] manager.c: Manager received command 'ping' [Mar 4 20:17:59] DEBUG[2178] chan_sip.c: Auto destroying SIP dialog '6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245' [Mar 4 20:17:59] DEBUG[2178] chan_sip.c: Destroying SIP dialog 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 [Mar 4 20:17:59] VERBOSE[2178] logger.c: Really destroying SIP dialog '6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245' Method: BYE [Mar 4 20:17:59] DEBUG[2178] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:17:59] DEBUG[2178] chan_sip.c: Call to peer '39' removed from call limit 100 [Mar 4 20:17:59] DEBUG[2178] devicestate.c: Notification of state change to be queued on device/channel SIP/39 [Mar 4 20:17:59] DEBUG[2178] chan_sip.c: This call did not properly clean up call limits. Call ID 6e4b8a235b9a60444f24c0ac2c8266af@172.17.15.245 [Mar 4 20:17:59] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:59] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:59] DEBUG[2173] devicestate.c: Changing state for SIP/39 - state 1 (Not in use) [Mar 4 20:17:59] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:17:59] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:17:59] DEBUG[2194] app_queue.c: Device 'SIP/39' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:18:00] DEBUG[2178] app_voicemail.c: Mailbox is set to 37 [Mar 4 20:18:00] ERROR[2178] app_voicemail.c: Couldn't find mailbox 37 in context default [Mar 4 20:18:01] DEBUG[2178] chan_sip.c: = Found Their Call ID: 2cb847bb427d935951f616f43cbc74b4@172.17.15.245 Their Tag 6756a5091bcbcacb Our tag: as40690467 [Mar 4 20:18:01] DEBUG[2178] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Mar 4 20:18:01] DEBUG[2178] chan_sip.c: Setting SIP_ALREADYGONE on dialog 2cb847bb427d935951f616f43cbc74b4@172.17.15.245 [Mar 4 20:18:01] DEBUG[2178] chan_sip.c: Received bye, issuing owner hangup [Mar 4 20:18:01] DEBUG[4593] rtp.c: Oooh, got a hangup [Mar 4 20:18:01] DEBUG[4593] channel.c: Returning from native bridge, channels: SIP/39-0000005d, SIP/37-0000005f [Mar 4 20:18:01] DEBUG[4593] channel.c: Hanging up channel 'SIP/37-0000005f' [Mar 4 20:18:01] DEBUG[4593] chan_sip.c: Hangup call SIP/37-0000005f, SIP callid 2cb847bb427d935951f616f43cbc74b4@172.17.15.245) [Mar 4 20:18:01] DEBUG[4593] chan_sip.c: Updating call counter for outgoing call [Mar 4 20:18:01] DEBUG[4593] chan_sip.c: Call to peer '37' removed from call limit 100 [Mar 4 20:18:01] DEBUG[4593] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:18:01] DEBUG[4593] devicestate.c: Notification of state change to be queued on device/channel SIP/37 [Mar 4 20:18:01] DEBUG[4593] rtp.c: Channel '' has no RTP, not doing anything [Mar 4 20:18:01] DEBUG[4593] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Mar 4 20:18:01] DEBUG[4593] pbx.c: Spawn extension (DLPN_To_Town,37,1) exited non-zero on 'SIP/39-0000005d' [Mar 4 20:18:01] VERBOSE[4593] logger.c: == Spawn extension (DLPN_To_Town, 37, 1) exited non-zero on 'SIP/39-0000005d' [Mar 4 20:18:01] DEBUG[4593] channel.c: Soft-Hanging up channel 'SIP/39-0000005d' [Mar 4 20:18:01] DEBUG[4593] channel.c: Hanging up channel 'SIP/39-0000005d' [Mar 4 20:18:01] DEBUG[4593] chan_sip.c: Hangup call SIP/39-0000005d, SIP callid 2182f5e6902ddd1d@172.17.15.166) [Mar 4 20:18:01] DEBUG[4593] chan_sip.c: Updating call counter for incoming call [Mar 4 20:18:01] DEBUG[4593] chan_sip.c: Call from user '39' removed from call limit 100 [Mar 4 20:18:01] DEBUG[4593] devicestate.c: Notification of state change to be queued on device/channel SIP/39 [Mar 4 20:18:01] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:18:01] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:18:01] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 1 (Not in use) [Mar 4 20:18:01] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:18:01] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:18:01] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:18:01] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:18:01] DEBUG[2173] devicestate.c: Changing state for SIP/37 - state 1 (Not in use) [Mar 4 20:18:01] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 37 [Mar 4 20:18:01] DEBUG[2173] chan_sip.c: Checking device state for peer 37 [Mar 4 20:18:01] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:18:01] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:18:01] DEBUG[2173] devicestate.c: Changing state for SIP/39 - state 1 (Not in use) [Mar 4 20:18:01] DEBUG[2173] devicestate.c: No provider found, checking channel drivers for SIP - 39 [Mar 4 20:18:01] DEBUG[2173] chan_sip.c: Checking device state for peer 39 [Mar 4 20:18:01] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:18:01] DEBUG[2194] app_queue.c: Device 'SIP/37' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:18:01] DEBUG[2194] app_queue.c: Device 'SIP/39' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 4 20:18:01] DEBUG[2178] chan_sip.c: = No match Their Call ID: 2cb847bb427d935951f616f43cbc74b4@172.17.15.245 Their Tag 6756a5091bcbcacb Our tag: as40690467 [Mar 4 20:18:01] DEBUG[2178] chan_sip.c: = No match Their Call ID: 43fd6b1d69069c9522d5ac6f78626a11@172.17.15.245 Their Tag 0007509810c8001e6877fe87-49d07234 Our tag: as60e0c701 [Mar 4 20:18:01] DEBUG[2178] chan_sip.c: = Found Their Call ID: 2182f5e6902ddd1d@172.17.15.166 Their Tag a52204d7f89cff94 Our tag: as65399fa6 [Mar 4 20:18:01] DEBUG[2178] chan_sip.c: Stopping retransmission on '2182f5e6902ddd1d@172.17.15.166' of Request 103: Match Found [Mar 4 20:18:01] VERBOSE[2178] logger.c: Really destroying SIP dialog '2cb847bb427d935951f616f43cbc74b4@172.17.15.245' Method: BYE [Mar 4 20:18:01] VERBOSE[2178] logger.c: Really destroying SIP dialog '2182f5e6902ddd1d@172.17.15.166' Method: ACK [Mar 4 20:18:03] DEBUG[4596] http.c: mmm ... cookie! Name: 'mansession_id' Value: '15b88fb5' [Mar 4 20:18:03] DEBUG[4596] http.c: mmm ... cookie! Name: 'username' Value: 'admin' [Mar 4 20:18:03] DEBUG[4596] http.c: mmm ... cookie! Name: 'rwaccess' Value: 'yes' [Mar 4 20:18:03] DEBUG[4596] manager.c: Manager received command 'ping' [Mar 4 20:18:08] DEBUG[4597] http.c: mmm ... cookie! Name: 'mansession_id' Value: '15b88fb5' [Mar 4 20:18:08] DEBUG[4597] http.c: mmm ... cookie! Name: 'username' Value: 'admin' [Mar 4 20:18:08] DEBUG[4597] http.c: mmm ... cookie! Name: 'rwaccess' Value: 'yes' [Mar 4 20:18:08] DEBUG[4597] manager.c: Manager received command 'ping' [Mar 4 20:18:11] DEBUG[2178] app_voicemail.c: Mailbox is set to 37 [Mar 4 20:18:11] ERROR[2178] app_voicemail.c: Couldn't find mailbox 37 in context default [Mar 4 20:18:13] DEBUG[4598] http.c: mmm ... cookie! Name: 'mansession_id' Value: '15b88fb5' [Mar 4 20:18:13] DEBUG[4598] http.c: mmm ... cookie! Name: 'username' Value: 'admin' [Mar 4 20:18:13] DEBUG[4598] http.c: mmm ... cookie! Name: 'rwaccess' Value: 'yes' [Mar 4 20:18:13] DEBUG[4598] manager.c: Manager received command 'ping'