[Sep 14 21:25:03] VERBOSE[15154] logger.c: Asterisk Ready. [Sep 14 21:25:13] VERBOSE[15154] logger.c: -- Remote UNIX connection [Sep 14 21:25:29] DEBUG[15154] chan_sip.c: That's odd... Got a request in unknown dialog. Callid 041dc6d429f0b6453693a1d72e158530@192.168.111.187 [Sep 14 21:25:29] DEBUG[15154] chan_sip.c: Invalid SIP message - rejected , no callid, len 476 [Sep 14 21:25:30] VERBOSE[15154] logger.c: == Using TOS bits 0 [Sep 14 21:25:30] VERBOSE[15154] logger.c: == Using CoS mark 5 [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Setting NAT on RTP to Off [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Allocating new SIP dialog for NTA5MTNjY2Y0NDg1ZDkxNDBlZWEwMDk2ODI4ZDcxZDk. - INVITE (With RTP) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Setting NAT on RTP to Off [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: = Found Their Call ID: NTA5MTNjY2Y0NDg1ZDkxNDBlZWEwMDk2ODI4ZDcxZDk. Their Tag 313cef6e Our tag: as33dd1337 [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Stopping retransmission on 'NTA5MTNjY2Y0NDg1ZDkxNDBlZWEwMDk2ODI4ZDcxZDk.' of Response 1: Match Found [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: = Found Their Call ID: NTA5MTNjY2Y0NDg1ZDkxNDBlZWEwMDk2ODI4ZDcxZDk. Their Tag 313cef6e Our tag: as33dd1337 [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Setting NAT on RTP to Off [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: T38 state changed to 0 on channel [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Checking SIP call limits for device 82 [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Updating call counter for incoming call [Sep 14 21:25:30] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Sep 14 21:25:30] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: This channel will not be able to handle video. [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: build_route: Contact hop: [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: SIP/82-0821ad80: New call is still down.... Trying... [Sep 14 21:25:30] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/82-0821ad80 [Sep 14 21:25:30] DEBUG[15154] pbx.c: Launching 'Dial' [Sep 14 21:25:30] VERBOSE[15154] logger.c: -- Executing [81@test:1] Dial("SIP/82-0821ad80", "SIP/81,,tT") in new stack [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Sep 14 21:25:30] VERBOSE[15154] logger.c: == Using TOS bits 0 [Sep 14 21:25:30] VERBOSE[15154] logger.c: == Using CoS mark 5 [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Setting NAT on RTP to Off [Sep 14 21:25:30] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Sep 14 21:25:30] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: This channel will not be able to handle video. [Sep 14 21:25:30] DEBUG[15154] rtp.c: Seeded SDP of 'SIP/81-0824cc20' with that of 'SIP/82-0821ad80' [Sep 14 21:25:30] DEBUG[15154] channel.c: Not copying variable STACK-test-81-1. [Sep 14 21:25:30] DEBUG[15154] channel.c: Not copying variable SIPCALLID. [Sep 14 21:25:30] DEBUG[15154] channel.c: Not copying variable SIPDOMAIN. [Sep 14 21:25:30] DEBUG[15154] channel.c: Not copying variable SIPURI. [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Outgoing Call for 81 [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Updating call counter for outgoing call [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: This call needs video offers, but there's no video support enabled! [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: -- Done with adding codecs to SDP [Sep 14 21:25:30] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Initializing initreq for method INVITE - callid 5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187 [Sep 14 21:25:30] VERBOSE[15154] logger.c: -- Called 81 [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: = Found Their Call ID: 5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187 Their Tag Our tag: as621742c3 [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187' Request 102: Found [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: SIP response 100 to standard invite [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: = Found Their Call ID: 5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187 Their Tag Our tag: as621742c3 [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187' Request 102: Found [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: SIP response 180 to standard invite [Sep 14 21:25:30] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/81-0824cc20 [Sep 14 21:25:30] VERBOSE[15154] logger.c: -- SIP/81-0824cc20 is ringing [Sep 14 21:25:30] DEBUG[15154] rtp.c: Setting early bridge SDP of 'SIP/82-0821ad80' with that of 'SIP/81-0824cc20' [Sep 14 21:25:30] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 82 [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Checking device state for peer 82 [Sep 14 21:25:30] DEBUG[15154] devicestate.c: Changing state for SIP/82 - state 1 (Not in use) [Sep 14 21:25:30] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 81 [Sep 14 21:25:30] DEBUG[15154] chan_sip.c: Checking device state for peer 81 [Sep 14 21:25:30] DEBUG[15154] devicestate.c: Changing state for SIP/81 - state 1 (Not in use) [Sep 14 21:25:30] DEBUG[15154] app_queue.c: Device 'SIP/82' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:25:30] DEBUG[15154] app_queue.c: Device 'SIP/81' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: = No match Their Call ID: 5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187 Their Tag 3a722ce5b9e43331 Our tag: as621742c3 [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: = Found Their Call ID: NTA5MTNjY2Y0NDg1ZDkxNDBlZWEwMDk2ODI4ZDcxZDk. Their Tag 313cef6e Our tag: as40a77303 [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: Setting SIP_ALREADYGONE on dialog NTA5MTNjY2Y0NDg1ZDkxNDBlZWEwMDk2ODI4ZDcxZDk. [Sep 14 21:26:01] DEBUG[15154] rtp.c: Channel '' has no RTP, not doing anything [Sep 14 21:26:01] DEBUG[15154] channel.c: Hanging up channel 'SIP/81-0824cc20' [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: Hangup call SIP/81-0824cc20, SIP callid 5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187 [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: Hanging up channel in state Ringing (not UP) [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: Acked pending invite 102 [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: Stopping retransmission on '5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187' of Request 102: Match Found [Sep 14 21:26:01] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/81-0824cc20 [Sep 14 21:26:01] NOTICE[15154] cdr.c: CDR on channel 'SIP/81-0824cc20' not posted [Sep 14 21:26:01] DEBUG[15154] app_dial.c: Exiting with DIALSTATUS=CANCEL. [Sep 14 21:26:01] DEBUG[15154] pbx.c: Spawn extension (test,81,1) exited non-zero on 'SIP/82-0821ad80' [Sep 14 21:26:01] VERBOSE[15154] logger.c: == Spawn extension (test, 81, 1) exited non-zero on 'SIP/82-0821ad80' [Sep 14 21:26:01] DEBUG[15154] channel.c: Soft-Hanging up channel 'SIP/82-0821ad80' [Sep 14 21:26:01] DEBUG[15154] channel.c: Hanging up channel 'SIP/82-0821ad80' [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: Hangup call SIP/82-0821ad80, SIP callid NTA5MTNjY2Y0NDg1ZDkxNDBlZWEwMDk2ODI4ZDcxZDk. [Sep 14 21:26:01] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/82-0821ad80 [Sep 14 21:26:01] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 81 [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: Checking device state for peer 81 [Sep 14 21:26:01] DEBUG[15154] devicestate.c: Changing state for SIP/81 - state 1 (Not in use) [Sep 14 21:26:01] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 82 [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: Checking device state for peer 82 [Sep 14 21:26:01] DEBUG[15154] devicestate.c: Changing state for SIP/82 - state 1 (Not in use) [Sep 14 21:26:01] DEBUG[15154] app_queue.c: Device 'SIP/81' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:01] DEBUG[15154] app_queue.c: Device 'SIP/82' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: = Found Their Call ID: 5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187 Their Tag 3a722ce5b9e43331 Our tag: as621742c3 [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: Stopping retransmission on '5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187' of Request 102: Match Found [Sep 14 21:26:01] WARNING[15154] chan_sip.c: Remote host can't match request CANCEL to call '5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187'. Giving up. [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: = No match Their Call ID: 5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187 Their Tag 9dc08503df8632b6 Our tag: as621742c3 [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: = Found Their Call ID: NTA5MTNjY2Y0NDg1ZDkxNDBlZWEwMDk2ODI4ZDcxZDk. Their Tag 313cef6e Our tag: as40a77303 [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Sep 14 21:26:01] DEBUG[15154] chan_sip.c: Stopping retransmission on 'NTA5MTNjY2Y0NDg1ZDkxNDBlZWEwMDk2ODI4ZDcxZDk.' of Response 2: Match Found [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: = No match Their Call ID: 5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187 Their Tag 9dc08503df8632b6 Our tag: as621742c3 [Sep 14 21:26:11] VERBOSE[15154] logger.c: == Using TOS bits 0 [Sep 14 21:26:11] VERBOSE[15154] logger.c: == Using CoS mark 5 [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Setting NAT on RTP to Off [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Allocating new SIP dialog for ODNhMTUwYTAyM2M0NWQwY2Y0NmVmZmE4Mjc5MWNlYzk. - INVITE (With RTP) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Setting NAT on RTP to Off [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: = Found Their Call ID: ODNhMTUwYTAyM2M0NWQwY2Y0NmVmZmE4Mjc5MWNlYzk. Their Tag 1b71614b Our tag: as0a6f0b76 [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Stopping retransmission on 'ODNhMTUwYTAyM2M0NWQwY2Y0NmVmZmE4Mjc5MWNlYzk.' of Response 1: Match Found [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: = Found Their Call ID: ODNhMTUwYTAyM2M0NWQwY2Y0NmVmZmE4Mjc5MWNlYzk. Their Tag 1b71614b Our tag: as0a6f0b76 [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Setting NAT on RTP to Off [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: T38 state changed to 0 on channel [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Checking SIP call limits for device 82 [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Updating call counter for incoming call [Sep 14 21:26:11] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Sep 14 21:26:11] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: This channel will not be able to handle video. [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: build_route: Contact hop: [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: SIP/82-0821ad80: New call is still down.... Trying... [Sep 14 21:26:11] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/82-0821ad80 [Sep 14 21:26:11] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 82 [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Checking device state for peer 82 [Sep 14 21:26:11] DEBUG[15154] devicestate.c: Changing state for SIP/82 - state 1 (Not in use) [Sep 14 21:26:11] DEBUG[15154] app_queue.c: Device 'SIP/82' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:11] DEBUG[15154] pbx.c: Launching 'Dial' [Sep 14 21:26:11] VERBOSE[15154] logger.c: -- Executing [81@test:1] Dial("SIP/82-0821ad80", "SIP/81,,tT") in new stack [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Sep 14 21:26:11] VERBOSE[15154] logger.c: == Using TOS bits 0 [Sep 14 21:26:11] VERBOSE[15154] logger.c: == Using CoS mark 5 [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Setting NAT on RTP to Off [Sep 14 21:26:11] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Sep 14 21:26:11] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: This channel will not be able to handle video. [Sep 14 21:26:11] DEBUG[15154] rtp.c: Seeded SDP of 'SIP/81-08253c78' with that of 'SIP/82-0821ad80' [Sep 14 21:26:11] DEBUG[15154] channel.c: Not copying variable STACK-test-81-1. [Sep 14 21:26:11] DEBUG[15154] channel.c: Not copying variable SIPCALLID. [Sep 14 21:26:11] DEBUG[15154] channel.c: Not copying variable SIPDOMAIN. [Sep 14 21:26:11] DEBUG[15154] channel.c: Not copying variable SIPURI. [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Outgoing Call for 81 [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Updating call counter for outgoing call [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: This call needs video offers, but there's no video support enabled! [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: -- Done with adding codecs to SDP [Sep 14 21:26:11] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Initializing initreq for method INVITE - callid 4ce8525b19e9d5666808d11c08f1846d@192.168.111.187 [Sep 14 21:26:11] VERBOSE[15154] logger.c: -- Called 81 [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: = Found Their Call ID: 4ce8525b19e9d5666808d11c08f1846d@192.168.111.187 Their Tag Our tag: as3c1b99aa [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4ce8525b19e9d5666808d11c08f1846d@192.168.111.187' Request 102: Found [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: SIP response 100 to standard invite [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: = Found Their Call ID: 4ce8525b19e9d5666808d11c08f1846d@192.168.111.187 Their Tag Our tag: as3c1b99aa [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4ce8525b19e9d5666808d11c08f1846d@192.168.111.187' Request 102: Found [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: SIP response 180 to standard invite [Sep 14 21:26:11] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/81-08253c78 [Sep 14 21:26:11] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 81 [Sep 14 21:26:11] DEBUG[15154] chan_sip.c: Checking device state for peer 81 [Sep 14 21:26:11] DEBUG[15154] devicestate.c: Changing state for SIP/81 - state 1 (Not in use) [Sep 14 21:26:11] DEBUG[15154] app_queue.c: Device 'SIP/81' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:11] VERBOSE[15154] logger.c: -- SIP/81-08253c78 is ringing [Sep 14 21:26:11] DEBUG[15154] rtp.c: Setting early bridge SDP of 'SIP/82-0821ad80' with that of 'SIP/81-08253c78' [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: = Found Their Call ID: 4ce8525b19e9d5666808d11c08f1846d@192.168.111.187 Their Tag 5f374477c9b01e62 Our tag: as3c1b99aa [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: Acked pending invite 102 [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: Stopping retransmission on '4ce8525b19e9d5666808d11c08f1846d@192.168.111.187' of Request 102: Match Found [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: SIP response 200 to standard invite [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: T38 state changed to 0 on channel SIP/81-08253c78 [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: We have an owner, now see if we need to change this call [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: Updating call counter for outgoing call [Sep 14 21:26:12] VERBOSE[15154] logger.c: --- set_address_from_contact host '192.168.111.238' [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: build_route: Contact hop: [Sep 14 21:26:12] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/81-08253c78 [Sep 14 21:26:12] VERBOSE[15154] logger.c: -- SIP/81-08253c78 answered SIP/82-0821ad80 [Sep 14 21:26:12] DEBUG[15154] rtp.c: Setting early bridge SDP of 'SIP/82-0821ad80' with that of 'SIP/81-08253c78' [Sep 14 21:26:12] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/82-0821ad80 [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: SIP answering channel: SIP/82-0821ad80 [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: Setting framing from config on incoming call [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: -- Done with adding codecs to SDP [Sep 14 21:26:12] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Sep 14 21:26:12] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 81 [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: Checking device state for peer 81 [Sep 14 21:26:12] DEBUG[15154] devicestate.c: Changing state for SIP/81 - state 1 (Not in use) [Sep 14 21:26:12] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 82 [Sep 14 21:26:12] DEBUG[15154] chan_sip.c: Checking device state for peer 82 [Sep 14 21:26:12] DEBUG[15154] devicestate.c: Changing state for SIP/82 - state 1 (Not in use) [Sep 14 21:26:12] DEBUG[15154] app_queue.c: Device 'SIP/81' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:12] DEBUG[15154] app_queue.c: Device 'SIP/82' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:12] DEBUG[15154] rtp.c: Got RTCP report of 132 bytes [Sep 14 21:26:13] DEBUG[15154] chan_sip.c: = No match Their Call ID: 4ce8525b19e9d5666808d11c08f1846d@192.168.111.187 Their Tag 5f374477c9b01e62 Our tag: as3c1b99aa [Sep 14 21:26:13] DEBUG[15154] chan_sip.c: = Found Their Call ID: ODNhMTUwYTAyM2M0NWQwY2Y0NmVmZmE4Mjc5MWNlYzk. Their Tag 1b71614b Our tag: as14c56a10 [Sep 14 21:26:13] DEBUG[15154] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Sep 14 21:26:13] DEBUG[15154] chan_sip.c: Stopping retransmission on 'ODNhMTUwYTAyM2M0NWQwY2Y0NmVmZmE4Mjc5MWNlYzk.' of Response 2: Match Found [Sep 14 21:26:13] DEBUG[15154] rtp.c: Ooh, format changed from unknown to ulaw [Sep 14 21:26:13] DEBUG[15154] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Sep 14 21:26:13] DEBUG[15154] rtp.c: Ooh, format changed from unknown to ulaw [Sep 14 21:26:13] DEBUG[15154] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] rtp.c: Sending dtmf: 35 (#), at 192.168.111.100 [Sep 14 21:26:15] DEBUG[15154] channel.c: Got DTMF begin on channel (SIP/82-0821ad80) [Sep 14 21:26:15] DEBUG[15154] channel.c: Bridge stops bridging channels SIP/82-0821ad80 and SIP/81-08253c78 [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] rtp.c: Sending dtmf: 35 (#), at 192.168.111.100 [Sep 14 21:26:15] DEBUG[15154] channel.c: Got DTMF end on channel (SIP/82-0821ad80) [Sep 14 21:26:15] DEBUG[15154] channel.c: Bridge stops bridging channels SIP/82-0821ad80 and SIP/81-08253c78 [Sep 14 21:26:15] DEBUG[15154] res_features.c: Feature interpret: chan=SIP/82-0821ad80, peer=SIP/81-08253c78, sense=1, features=2 [Sep 14 21:26:15] DEBUG[15154] res_features.c: Executing Attended Transfer SIP/82-0821ad80, SIP/81-08253c78 (sense=1) [Sep 14 21:26:15] VERBOSE[15154] logger.c: -- Started music on hold, class 'default', on SIP/81-08253c78 [Sep 14 21:26:15] DEBUG[15154] channel.c: Set channel SIP/82-0821ad80 to write format gsm [Sep 14 21:26:15] VERBOSE[15154] logger.c: -- Playing 'pbx-transfer.gsm' (language 'en') [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] rtp.c: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 21:26:15] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:15] DEBUG[15154] channel.c: Set channel SIP/81-08253c78 to write format slin [Sep 14 21:26:15] DEBUG[15154] res_musiconhold.c: SIP/81-08253c78 Opened file 0 '/var/lib/asterisk/moh/fpm-sunshine' [Sep 14 21:26:15] DEBUG[15154] rtp.c: Difference is 1240, ms is 175 [Sep 14 21:26:15] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:15] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:15] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:16] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:16] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:16] DEBUG[15154] channel.c: Set channel SIP/82-0821ad80 to write format ulaw [Sep 14 21:26:16] DEBUG[15154] channel.c: Set channel SIP/82-0821ad80 to write format slin [Sep 14 21:26:16] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:16] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:16] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:16] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:19] DEBUG[15154] rtp.c: Got RTCP report of 176 bytes [Sep 14 21:26:19] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:19] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:19] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:19] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000008 (len = 4) [Sep 14 21:26:19] DEBUG[15154] rtp.c: Sending dtmf: 56 (8), at 192.168.111.100 [Sep 14 21:26:19] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000008 (len = 4) [Sep 14 21:26:19] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000008 (len = 4) [Sep 14 21:26:19] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:19] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000008 (len = 4) [Sep 14 21:26:19] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:19] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000008 (len = 4) [Sep 14 21:26:19] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:19] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000008 (len = 4) [Sep 14 21:26:19] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:19] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000008 (len = 4) [Sep 14 21:26:19] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:19] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000008 (len = 4) [Sep 14 21:26:19] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:19] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000008 (len = 4) [Sep 14 21:26:19] DEBUG[15154] rtp.c: Sending dtmf: 56 (8), at 192.168.111.100 [Sep 14 21:26:19] DEBUG[15154] channel.c: Set channel SIP/82-0821ad80 to write format ulaw [Sep 14 21:26:19] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000008 (len = 4) [Sep 14 21:26:19] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000008 (len = 4) [Sep 14 21:26:19] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:19] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:19] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:20] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000000 (len = 4) [Sep 14 21:26:20] DEBUG[15154] rtp.c: Sending dtmf: 48 (0), at 192.168.111.100 [Sep 14 21:26:20] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000000 (len = 4) [Sep 14 21:26:20] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000000 (len = 4) [Sep 14 21:26:20] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:20] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000000 (len = 4) [Sep 14 21:26:20] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:20] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000000 (len = 4) [Sep 14 21:26:20] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:20] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000000 (len = 4) [Sep 14 21:26:20] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:20] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000000 (len = 4) [Sep 14 21:26:20] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:20] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000000 (len = 4) [Sep 14 21:26:20] DEBUG[15154] rtp.c: Sending dtmf: 48 (0), at 192.168.111.100 [Sep 14 21:26:20] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000000 (len = 4) [Sep 14 21:26:20] DEBUG[15154] rtp.c: - RTP 2833 Event: 00000000 (len = 4) [Sep 14 21:26:20] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:20] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:22] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:22] DEBUG[15154] rtp.c: Got RTCP report of 176 bytes [Sep 14 21:26:22] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:23] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:23] DEBUG[15154] channel.c: Not copying variable BRIDGEPEER. [Sep 14 21:26:23] DEBUG[15154] channel.c: Not copying variable DIALEDPEERNUMBER. [Sep 14 21:26:23] DEBUG[15154] channel.c: Not copying variable DIALEDPEERNAME. [Sep 14 21:26:23] DEBUG[15154] channel.c: Not copying variable STACK-test-81-1. [Sep 14 21:26:23] DEBUG[15154] channel.c: Not copying variable SIPCALLID. [Sep 14 21:26:23] DEBUG[15154] channel.c: Not copying variable SIPDOMAIN. [Sep 14 21:26:23] DEBUG[15154] channel.c: Not copying variable SIPURI. [Sep 14 21:26:23] DEBUG[15154] channel.c: Driver for channel 'SIP/82-0821ad80' does not support indication 3, emulating it [Sep 14 21:26:23] DEBUG[15154] channel.c: Set channel SIP/82-0821ad80 to write format slin [Sep 14 21:26:23] DEBUG[15154] pbx.c: Launching 'Dial' [Sep 14 21:26:23] VERBOSE[15154] logger.c: -- Executing [80@test:1] Dial("Local/80@test-9a8e;2", "SIP/80,,tT") in new stack [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Sep 14 21:26:23] VERBOSE[15154] logger.c: == Using TOS bits 0 [Sep 14 21:26:23] VERBOSE[15154] logger.c: == Using CoS mark 5 [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: Setting NAT on RTP to Off [Sep 14 21:26:23] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Sep 14 21:26:23] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: This channel will not be able to handle video. [Sep 14 21:26:23] DEBUG[15154] rtp.c: Channel 'Local/80@test-9a8e;2' has no RTP, not doing anything [Sep 14 21:26:23] DEBUG[15154] channel.c: Not copying variable STACK-test-80-1. [Sep 14 21:26:23] DEBUG[15154] channel.c: Not copying variable TRANSFERERNAME. [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: Outgoing Call for 80 [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: Updating call counter for outgoing call [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: This call needs video offers, but there's no video support enabled! [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: -- Done with adding codecs to SDP [Sep 14 21:26:23] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: Initializing initreq for method INVITE - callid 0aa8a4dc0c57a48a62880656082884c5@192.168.111.187 [Sep 14 21:26:23] VERBOSE[15154] logger.c: -- Called 80 [Sep 14 21:26:23] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:23] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:23] DEBUG[15154] rtp.c: Difference is 31992, ms is 4019 [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: = Found Their Call ID: 0aa8a4dc0c57a48a62880656082884c5@192.168.111.187 Their Tag Our tag: as3a3de611 [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '0aa8a4dc0c57a48a62880656082884c5@192.168.111.187' Request 102: Found [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: SIP response 100 to standard invite [Sep 14 21:26:23] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:23] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:23] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:23] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: = Found Their Call ID: 0aa8a4dc0c57a48a62880656082884c5@192.168.111.187 Their Tag Our tag: as3a3de611 [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '0aa8a4dc0c57a48a62880656082884c5@192.168.111.187' Request 102: Found [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: SIP response 180 to standard invite [Sep 14 21:26:23] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/80-08263b60 [Sep 14 21:26:23] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 80 [Sep 14 21:26:23] DEBUG[15154] chan_sip.c: Checking device state for peer 80 [Sep 14 21:26:23] DEBUG[15154] devicestate.c: Changing state for SIP/80 - state 1 (Not in use) [Sep 14 21:26:23] DEBUG[15154] app_queue.c: Device 'SIP/80' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:23] VERBOSE[15154] logger.c: -- SIP/80-08263b60 is ringing [Sep 14 21:26:23] VERBOSE[15154] logger.c: -- Local/80@test-9a8e;1 is ringing [Sep 14 21:26:23] DEBUG[15154] channel.c: Driver for channel 'SIP/82-0821ad80' does not support indication 3, emulating it [Sep 14 21:26:23] DEBUG[15154] channel.c: Set channel SIP/82-0821ad80 to write format ulaw [Sep 14 21:26:23] DEBUG[15154] channel.c: Set channel SIP/82-0821ad80 to write format slin [Sep 14 21:26:23] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:23] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:25] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:25] DEBUG[15154] rtp.c: Got RTCP report of 176 bytes [Sep 14 21:26:25] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:25] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:25] DEBUG[15154] chan_sip.c: = No match Their Call ID: 0aa8a4dc0c57a48a62880656082884c5@192.168.111.187 Their Tag e43fac4dc9093604i0 Our tag: as3a3de611 [Sep 14 21:26:25] DEBUG[15154] chan_sip.c: = No match Their Call ID: 4ce8525b19e9d5666808d11c08f1846d@192.168.111.187 Their Tag 5f374477c9b01e62 Our tag: as3c1b99aa [Sep 14 21:26:25] DEBUG[15154] chan_sip.c: = Found Their Call ID: ODNhMTUwYTAyM2M0NWQwY2Y0NmVmZmE4Mjc5MWNlYzk. Their Tag 1b71614b Our tag: as14c56a10 [Sep 14 21:26:25] DEBUG[15154] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Sep 14 21:26:25] DEBUG[15154] chan_sip.c: Setting SIP_ALREADYGONE on dialog ODNhMTUwYTAyM2M0NWQwY2Y0NmVmZmE4Mjc5MWNlYzk. [Sep 14 21:26:25] DEBUG[15154] chan_sip.c: Received bye, issuing owner hangup [Sep 14 21:26:25] DEBUG[15154] channel.c: Set channel SIP/82-0821ad80 to write format ulaw [Sep 14 21:26:25] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:33] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:33] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:33] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:33] DEBUG[15154] chan_sip.c: Auto destroying SIP dialog '5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187' [Sep 14 21:26:33] DEBUG[15154] chan_sip.c: Destroying SIP dialog 5da8e48e0c346a2b4daaeea5245bc9da@192.168.111.187 [Sep 14 21:26:33] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] NOTICE[15154] res_features.c: We exceeded our AT-timeout [Sep 14 21:26:38] DEBUG[15154] channel.c: Hanging up channel 'Local/80@test-9a8e;1' [Sep 14 21:26:38] DEBUG[15154] channel.c: Hanging up channel 'SIP/80-08263b60' [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Hangup call SIP/80-08263b60, SIP callid 0aa8a4dc0c57a48a62880656082884c5@192.168.111.187 [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Hanging up channel in state Ringing (not UP) [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Acked pending invite 102 [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Stopping retransmission on '0aa8a4dc0c57a48a62880656082884c5@192.168.111.187' of Request 102: Match Found [Sep 14 21:26:38] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/80-08263b60 [Sep 14 21:26:38] NOTICE[15154] cdr.c: CDR on channel 'SIP/80-08263b60' not posted [Sep 14 21:26:38] DEBUG[15154] app_dial.c: Exiting with DIALSTATUS=CANCEL. [Sep 14 21:26:38] DEBUG[15154] pbx.c: Spawn extension (test,80,1) exited non-zero on 'Local/80@test-9a8e;2' [Sep 14 21:26:38] VERBOSE[15154] logger.c: == Spawn extension (test, 80, 1) exited non-zero on 'Local/80@test-9a8e;2' [Sep 14 21:26:38] DEBUG[15154] channel.c: Soft-Hanging up channel 'Local/80@test-9a8e;2' [Sep 14 21:26:38] DEBUG[15154] channel.c: Hanging up channel 'Local/80@test-9a8e;2' [Sep 14 21:26:38] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 80 [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Checking device state for peer 80 [Sep 14 21:26:38] DEBUG[15154] devicestate.c: Changing state for SIP/80 - state 1 (Not in use) [Sep 14 21:26:38] DEBUG[15154] app_queue.c: Device 'SIP/80' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:38] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel Local/80@test-9a8e;2 [Sep 14 21:26:38] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for Local - 80@test [Sep 14 21:26:38] DEBUG[15154] chan_local.c: Checking if extension 80@test exists (devicestate) [Sep 14 21:26:38] DEBUG[15154] devicestate.c: Changing state for Local/80@test - state 1 (Not in use) [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] DEBUG[15154] app_queue.c: Device 'Local/80@test' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:38] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel Local/80@test-9a8e;1 [Sep 14 21:26:38] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for Local - 80@test [Sep 14 21:26:38] DEBUG[15154] chan_local.c: Checking if extension 80@test exists (devicestate) [Sep 14 21:26:38] DEBUG[15154] devicestate.c: Changing state for Local/80@test - state 1 (Not in use) [Sep 14 21:26:38] DEBUG[15154] app_queue.c: Device 'Local/80@test' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:38] NOTICE[15154] cdr.c: CDR on channel 'Local/80@test-9a8e;1' not posted [Sep 14 21:26:38] DEBUG[15154] channel.c: Not copying variable BRIDGEPEER. [Sep 14 21:26:38] DEBUG[15154] channel.c: Not copying variable DIALEDPEERNUMBER. [Sep 14 21:26:38] DEBUG[15154] channel.c: Not copying variable SIPCALLID. [Sep 14 21:26:38] DEBUG[15154] channel.c: Driver for channel 'SIP/81-08253c78' does not support indication 3, emulating it [Sep 14 21:26:38] VERBOSE[15154] logger.c: -- Stopped music on hold on SIP/81-08253c78 [Sep 14 21:26:38] DEBUG[15154] channel.c: Set channel SIP/81-08253c78 to write format ulaw [Sep 14 21:26:38] DEBUG[15154] channel.c: Set channel SIP/81-08253c78 to write format slin [Sep 14 21:26:38] DEBUG[15154] pbx.c: Launching 'Dial' [Sep 14 21:26:38] VERBOSE[15154] logger.c: -- Executing [82@test:1] Dial("Local/82@test-e196;2", "SIP/82,,tT") in new stack [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Sep 14 21:26:38] VERBOSE[15154] logger.c: == Using TOS bits 0 [Sep 14 21:26:38] VERBOSE[15154] logger.c: == Using CoS mark 5 [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Setting NAT on RTP to Off [Sep 14 21:26:38] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Sep 14 21:26:38] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: This channel will not be able to handle video. [Sep 14 21:26:38] DEBUG[15154] rtp.c: Channel 'Local/82@test-e196;2' has no RTP, not doing anything [Sep 14 21:26:38] DEBUG[15154] channel.c: Not copying variable STACK-test-82-1. [Sep 14 21:26:38] DEBUG[15154] channel.c: Not copying variable TRANSFERERNAME. [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Outgoing Call for 82 [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Updating call counter for outgoing call [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: = No match Their Call ID: 761e1c680686affa26f8f2006b4e14d2@192.168.111.187 Their Tag Our tag: as302496d3 [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: = Found Their Call ID: 0aa8a4dc0c57a48a62880656082884c5@192.168.111.187 Their Tag e43fac4dc9093604i0 Our tag: as3a3de611 [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Stopping retransmission on '0aa8a4dc0c57a48a62880656082884c5@192.168.111.187' of Request 102: Match Found [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: This call needs video offers, but there's no video support enabled! [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: -- Done with adding codecs to SDP [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Initializing initreq for method INVITE - callid 761e1c680686affa26f8f2006b4e14d2@192.168.111.187 [Sep 14 21:26:38] VERBOSE[15154] logger.c: -- Called 82 [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: = Found Their Call ID: 761e1c680686affa26f8f2006b4e14d2@192.168.111.187 Their Tag Our tag: as302496d3 [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '761e1c680686affa26f8f2006b4e14d2@192.168.111.187' Request 102: Found [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: SIP response 180 to standard invite [Sep 14 21:26:38] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/82-08261b60 [Sep 14 21:26:38] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 82 [Sep 14 21:26:38] DEBUG[15154] chan_sip.c: Checking device state for peer 82 [Sep 14 21:26:38] DEBUG[15154] devicestate.c: Changing state for SIP/82 - state 1 (Not in use) [Sep 14 21:26:38] DEBUG[15154] app_queue.c: Device 'SIP/82' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:38] VERBOSE[15154] logger.c: -- SIP/82-08261b60 is ringing [Sep 14 21:26:38] VERBOSE[15154] logger.c: -- Local/82@test-e196;1 is ringing [Sep 14 21:26:38] DEBUG[15154] channel.c: Driver for channel 'SIP/81-08253c78' does not support indication 3, emulating it [Sep 14 21:26:38] DEBUG[15154] channel.c: Set channel SIP/81-08253c78 to write format ulaw [Sep 14 21:26:38] DEBUG[15154] channel.c: Set channel SIP/81-08253c78 to write format slin [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:38] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:48] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:48] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:48] DEBUG[15154] chan_sip.c: = No match Their Call ID: 761e1c680686affa26f8f2006b4e14d2@192.168.111.187 Their Tag db38471f Our tag: as302496d3 [Sep 14 21:26:48] DEBUG[15154] chan_sip.c: = No match Their Call ID: 0aa8a4dc0c57a48a62880656082884c5@192.168.111.187 Their Tag e43fac4dc9093604i0 Our tag: as3a3de611 [Sep 14 21:26:48] DEBUG[15154] chan_sip.c: = No match Their Call ID: 4ce8525b19e9d5666808d11c08f1846d@192.168.111.187 Their Tag 5f374477c9b01e62 Our tag: as3c1b99aa [Sep 14 21:26:48] DEBUG[15154] chan_sip.c: = No match Their Call ID: ODNhMTUwYTAyM2M0NWQwY2Y0NmVmZmE4Mjc5MWNlYzk. Their Tag 1b71614b Our tag: as14c56a10 [Sep 14 21:26:48] DEBUG[15154] chan_sip.c: Allocating new SIP dialog for ZmRjYThlNDlmZDU5ZDEwNDNjYzExZmNhMTJhNzE1NTU. - SUBSCRIBE (No RTP) [Sep 14 21:26:48] DEBUG[15154] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Sep 14 21:26:48] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:48] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:48] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:48] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:48] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:48] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:48] DEBUG[15154] chan_sip.c: = Found Their Call ID: ZmRjYThlNDlmZDU5ZDEwNDNjYzExZmNhMTJhNzE1NTU. Their Tag 8a51b049 Our tag: as1759ae90 [Sep 14 21:26:48] DEBUG[15154] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Sep 14 21:26:48] NOTICE[15154] chan_sip.c: Received SIP subscribe for peer without mailbox: 82 [Sep 14 21:26:48] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:49] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:49] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:49] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:53] NOTICE[15154] res_features.c: We exceeded our AT-timeout [Sep 14 21:26:53] DEBUG[15154] channel.c: Set channel SIP/81-08253c78 to write format ulaw [Sep 14 21:26:53] DEBUG[15154] channel.c: Hanging up channel 'Local/82@test-e196;1' [Sep 14 21:26:53] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel Local/82@test-e196;1 [Sep 14 21:26:53] NOTICE[15154] cdr.c: CDR on channel 'Local/82@test-e196;1' not posted [Sep 14 21:26:53] VERBOSE[15154] logger.c: -- Started music on hold, class 'default', on SIP/81-08253c78 [Sep 14 21:26:53] DEBUG[15154] channel.c: Not copying variable RTPAUDIOQOS. [Sep 14 21:26:53] DEBUG[15154] channel.c: Not copying variable BRIDGEPEER. [Sep 14 21:26:53] DEBUG[15154] channel.c: Not copying variable DIALEDPEERNUMBER. [Sep 14 21:26:53] DEBUG[15154] channel.c: Not copying variable DIALEDPEERNAME. [Sep 14 21:26:53] DEBUG[15154] channel.c: Not copying variable STACK-test-81-1. [Sep 14 21:26:53] DEBUG[15154] channel.c: Not copying variable SIPCALLID. [Sep 14 21:26:53] DEBUG[15154] channel.c: Not copying variable SIPDOMAIN. [Sep 14 21:26:53] DEBUG[15154] channel.c: Not copying variable SIPURI. [Sep 14 21:26:53] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for Local - 82@test [Sep 14 21:26:53] DEBUG[15154] chan_local.c: Checking if extension 82@test exists (devicestate) [Sep 14 21:26:53] DEBUG[15154] devicestate.c: Changing state for Local/82@test - state 1 (Not in use) [Sep 14 21:26:53] DEBUG[15154] app_queue.c: Device 'Local/82@test' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:53] DEBUG[15154] pbx.c: Launching 'Dial' [Sep 14 21:26:53] VERBOSE[15154] logger.c: -- Executing [80@test:1] Dial("Local/80@test-6762;2", "SIP/80,,tT") in new stack [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Sep 14 21:26:53] VERBOSE[15154] logger.c: == Using TOS bits 0 [Sep 14 21:26:53] VERBOSE[15154] logger.c: == Using CoS mark 5 [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: Setting NAT on RTP to Off [Sep 14 21:26:53] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Sep 14 21:26:53] DEBUG[15154] frame.c: Could not find preferred codec - Going for the best codec [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: This channel will not be able to handle video. [Sep 14 21:26:53] DEBUG[15154] rtp.c: Channel 'Local/80@test-6762;2' has no RTP, not doing anything [Sep 14 21:26:53] DEBUG[15154] channel.c: Not copying variable STACK-test-80-1. [Sep 14 21:26:53] DEBUG[15154] channel.c: Not copying variable TRANSFERERNAME. [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: Outgoing Call for 80 [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: Updating call counter for outgoing call [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: This call needs video offers, but there's no video support enabled! [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: -- Done with adding codecs to SDP [Sep 14 21:26:53] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: Initializing initreq for method INVITE - callid 333fe2e21d54fd40299f867e6a04ac04@192.168.111.187 [Sep 14 21:26:53] VERBOSE[15154] logger.c: -- Called 80 [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: = Found Their Call ID: 333fe2e21d54fd40299f867e6a04ac04@192.168.111.187 Their Tag Our tag: as7f1a2d06 [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '333fe2e21d54fd40299f867e6a04ac04@192.168.111.187' Request 102: Found [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: SIP response 100 to standard invite [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: = Found Their Call ID: 333fe2e21d54fd40299f867e6a04ac04@192.168.111.187 Their Tag Our tag: as7f1a2d06 [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '333fe2e21d54fd40299f867e6a04ac04@192.168.111.187' Request 102: Found [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: SIP response 180 to standard invite [Sep 14 21:26:53] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/80-0825fb10 [Sep 14 21:26:53] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 80 [Sep 14 21:26:53] DEBUG[15154] chan_sip.c: Checking device state for peer 80 [Sep 14 21:26:53] DEBUG[15154] devicestate.c: Changing state for SIP/80 - state 1 (Not in use) [Sep 14 21:26:53] DEBUG[15154] app_queue.c: Device 'SIP/80' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:53] VERBOSE[15154] logger.c: -- SIP/80-0825fb10 is ringing [Sep 14 21:26:53] VERBOSE[15154] logger.c: -- Local/80@test-6762;1 is ringing [Sep 14 21:26:53] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:53] DEBUG[15154] channel.c: Set channel SIP/81-08253c78 to write format slin [Sep 14 21:26:53] DEBUG[15154] res_musiconhold.c: SIP/81-08253c78 Opened file 0 '/var/lib/asterisk/moh/fpm-sunshine' [Sep 14 21:26:53] DEBUG[15154] rtp.c: Difference is 3848, ms is 501 [Sep 14 21:26:53] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:53] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:53] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:54] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:54] DEBUG[15154] channel.c: Hanging up channel 'SIP/82-08261b60' [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: Hangup call SIP/82-08261b60, SIP callid 761e1c680686affa26f8f2006b4e14d2@192.168.111.187 [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: Hanging up channel in state Ringing (not UP) [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: Acked pending invite 102 [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: Stopping retransmission on '761e1c680686affa26f8f2006b4e14d2@192.168.111.187' of Request 102: Match Found [Sep 14 21:26:54] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/82-08261b60 [Sep 14 21:26:54] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 82 [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: Checking device state for peer 82 [Sep 14 21:26:54] DEBUG[15154] devicestate.c: Changing state for SIP/82 - state 1 (Not in use) [Sep 14 21:26:54] DEBUG[15154] app_queue.c: Device 'SIP/82' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:54] NOTICE[15154] cdr.c: CDR on channel 'SIP/82-08261b60' not posted [Sep 14 21:26:54] DEBUG[15154] app_dial.c: Exiting with DIALSTATUS=CANCEL. [Sep 14 21:26:54] DEBUG[15154] pbx.c: Spawn extension (test,82,1) exited non-zero on 'Local/82@test-e196;2' [Sep 14 21:26:54] VERBOSE[15154] logger.c: == Spawn extension (test, 82, 1) exited non-zero on 'Local/82@test-e196;2' [Sep 14 21:26:54] DEBUG[15154] channel.c: Soft-Hanging up channel 'Local/82@test-e196;2' [Sep 14 21:26:54] DEBUG[15154] channel.c: Hanging up channel 'Local/82@test-e196;2' [Sep 14 21:26:54] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel Local/82@test-e196;2 [Sep 14 21:26:54] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for Local - 82@test [Sep 14 21:26:54] DEBUG[15154] chan_local.c: Checking if extension 82@test exists (devicestate) [Sep 14 21:26:54] DEBUG[15154] devicestate.c: Changing state for Local/82@test - state 1 (Not in use) [Sep 14 21:26:54] DEBUG[15154] app_queue.c: Device 'Local/82@test' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:26:54] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:54] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:54] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:54] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:54] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: = No match Their Call ID: 333fe2e21d54fd40299f867e6a04ac04@192.168.111.187 Their Tag 18f2ff79a7b4288ei0 Our tag: as7f1a2d06 [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: = Found Their Call ID: 761e1c680686affa26f8f2006b4e14d2@192.168.111.187 Their Tag db38471f Our tag: as302496d3 [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: Stopping retransmission on '761e1c680686affa26f8f2006b4e14d2@192.168.111.187' of Request 102: Match Found [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: = No match Their Call ID: 333fe2e21d54fd40299f867e6a04ac04@192.168.111.187 Their Tag 18f2ff79a7b4288ei0 Our tag: as7f1a2d06 [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: = Found Their Call ID: 761e1c680686affa26f8f2006b4e14d2@192.168.111.187 Their Tag db38471f Our tag: as302496d3 [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: Stopping retransmission on '761e1c680686affa26f8f2006b4e14d2@192.168.111.187' of Request 102: Match Not Found [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: SIP response 487 to standard invite [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: Updating call counter for outgoing call [Sep 14 21:26:54] DEBUG[15154] chan_sip.c: Setting SIP_ALREADYGONE on dialog 761e1c680686affa26f8f2006b4e14d2@192.168.111.187 [Sep 14 21:26:54] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:26:54] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:27:01] DEBUG[15154] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 14 21:27:02] DEBUG[15154] chan_sip.c: = No match Their Call ID: 333fe2e21d54fd40299f867e6a04ac04@192.168.111.187 Their Tag 18f2ff79a7b4288ei0 Our tag: as7f1a2d06 [Sep 14 21:27:02] DEBUG[15154] chan_sip.c: = No match Their Call ID: 0aa8a4dc0c57a48a62880656082884c5@192.168.111.187 Their Tag e43fac4dc9093604i0 Our tag: as3a3de611 [Sep 14 21:27:02] DEBUG[15154] chan_sip.c: = Found Their Call ID: 4ce8525b19e9d5666808d11c08f1846d@192.168.111.187 Their Tag 5f374477c9b01e62 Our tag: as3c1b99aa [Sep 14 21:27:02] DEBUG[15154] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Sep 14 21:27:02] DEBUG[15154] chan_sip.c: Setting SIP_ALREADYGONE on dialog 4ce8525b19e9d5666808d11c08f1846d@192.168.111.187 [Sep 14 21:27:02] DEBUG[15154] chan_sip.c: Received bye, issuing owner hangup [Sep 14 21:27:02] VERBOSE[15154] logger.c: -- Stopped music on hold on SIP/81-08253c78 [Sep 14 21:27:02] DEBUG[15154] channel.c: Set channel SIP/81-08253c78 to write format ulaw [Sep 14 21:27:08] NOTICE[15154] res_features.c: We exceeded our AT-timeout [Sep 14 21:27:08] DEBUG[15154] channel.c: Hanging up channel 'Local/80@test-6762;1' [Sep 14 21:27:08] DEBUG[15154] channel.c: Hanging up channel 'SIP/80-0825fb10' [Sep 14 21:27:08] DEBUG[15154] chan_sip.c: Hangup call SIP/80-0825fb10, SIP callid 333fe2e21d54fd40299f867e6a04ac04@192.168.111.187 [Sep 14 21:27:08] DEBUG[15154] chan_sip.c: Hanging up channel in state Ringing (not UP) [Sep 14 21:27:08] DEBUG[15154] chan_sip.c: Acked pending invite 102 [Sep 14 21:27:08] DEBUG[15154] chan_sip.c: Stopping retransmission on '333fe2e21d54fd40299f867e6a04ac04@192.168.111.187' of Request 102: Match Found [Sep 14 21:27:08] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel SIP/80-0825fb10 [Sep 14 21:27:08] NOTICE[15154] cdr.c: CDR on channel 'SIP/80-0825fb10' not posted [Sep 14 21:27:08] DEBUG[15154] app_dial.c: Exiting with DIALSTATUS=CANCEL. [Sep 14 21:27:08] DEBUG[15154] pbx.c: Spawn extension (test,80,1) exited non-zero on 'Local/80@test-6762;2' [Sep 14 21:27:08] VERBOSE[15154] logger.c: == Spawn extension (test, 80, 1) exited non-zero on 'Local/80@test-6762;2' [Sep 14 21:27:08] DEBUG[15154] channel.c: Soft-Hanging up channel 'Local/80@test-6762;2' [Sep 14 21:27:08] DEBUG[15154] channel.c: Hanging up channel 'Local/80@test-6762;2' [Sep 14 21:27:08] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for SIP - 80 [Sep 14 21:27:08] DEBUG[15154] chan_sip.c: Checking device state for peer 80 [Sep 14 21:27:08] DEBUG[15154] devicestate.c: Changing state for SIP/80 - state 1 (Not in use) [Sep 14 21:27:08] DEBUG[15154] app_queue.c: Device 'SIP/80' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:27:08] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel Local/80@test-6762;2 [Sep 14 21:27:08] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for Local - 80@test [Sep 14 21:27:08] DEBUG[15154] chan_local.c: Checking if extension 80@test exists (devicestate) [Sep 14 21:27:08] DEBUG[15154] devicestate.c: Changing state for Local/80@test - state 1 (Not in use) [Sep 14 21:27:08] DEBUG[15154] app_queue.c: Device 'Local/80@test' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:27:08] DEBUG[15154] devicestate.c: Notification of state change to be queued on device/channel Local/80@test-6762;1 [Sep 14 21:27:08] DEBUG[15154] devicestate.c: No provider found, checking channel drivers for Local - 80@test [Sep 14 21:27:08] DEBUG[15154] chan_local.c: Checking if extension 80@test exists (devicestate) [Sep 14 21:27:08] DEBUG[15154] devicestate.c: Changing state for Local/80@test - state 1 (Not in use) [Sep 14 21:27:08] DEBUG[15154] app_queue.c: Device 'Local/80@test' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 21:27:08] NOTICE[15154] cdr.c: CDR on channel 'Local/80@test-6762;1' not posted [Sep 14 21:27:12] VERBOSE[15212] logger.c: Asterisk Event Logger Started /var/log/asterisk/event_log [Sep 14 21:27:12] VERBOSE[15212] logger.c: Asterisk Dynamic Loader Starting: [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Parsing '/etc/asterisk/modules.conf': [Sep 14 21:27:12] DEBUG[15212] config.c: Parsing /etc/asterisk/modules.conf [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Found [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Parsing '/etc/asterisk/dnsmgr.conf': [Sep 14 21:27:12] DEBUG[15212] config.c: Parsing /etc/asterisk/dnsmgr.conf [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Found [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Parsing '/etc/asterisk/http.conf': [Sep 14 21:27:12] DEBUG[15212] config.c: Parsing /etc/asterisk/http.conf [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Found [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action Ping [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action Events [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action Logoff [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action Login [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action Challenge [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action Hangup [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action Status [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action Setvar [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action Getvar [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action GetConfig [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action GetConfigJSON [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action UpdateConfig [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action Redirect [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action Originate [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action Command [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action ExtensionState [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action AbsoluteTimeout [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action MailboxStatus [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action MailboxCount [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action ListCommands [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action SendText [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action UserEvent [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action WaitEvent [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action CoreSettings [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Manager registered action CoreStatus [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Parsing '/etc/asterisk/manager.conf': [Sep 14 21:27:12] DEBUG[15212] config.c: Parsing /etc/asterisk/manager.conf [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Found [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Parsing '/etc/asterisk/cdr.conf': [Sep 14 21:27:12] DEBUG[15212] config.c: Parsing /etc/asterisk/cdr.conf [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Found [Sep 14 21:27:12] NOTICE[15212] cdr.c: CDR simple logging enabled. [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Parsing '/etc/asterisk/rtp.conf': [Sep 14 21:27:12] DEBUG[15212] config.c: Parsing /etc/asterisk/rtp.conf [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Found [Sep 14 21:27:12] VERBOSE[15212] logger.c: == RTP Allocating from port range 10000 -> 20000 [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Parsing '/etc/asterisk/udptl.conf': [Sep 14 21:27:12] DEBUG[15212] config.c: Parsing /etc/asterisk/udptl.conf [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Found [Sep 14 21:27:12] VERBOSE[15212] logger.c: == UDPTL allocating from port range 4000 -> 4999 [Sep 14 21:27:12] VERBOSE[15212] logger.c: Asterisk PBX Core Initializing [Sep 14 21:27:12] VERBOSE[15212] logger.c: Registering builtin applications: [Sep 14 21:27:12] VERBOSE[15212] logger.c: [Answer] [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Registered application 'Answer' [Sep 14 21:27:12] VERBOSE[15212] logger.c: [BackGround] [Sep 14 21:27:12] VERBOSE[15212] logger.c: == Parsing '/etc/asterisk/features.conf': [Sep 14 21:27:12] DEBUG[15212] config.c: Parsing /etc/asterisk/features.conf