[Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 874c5e93bce332dc@192.168.200.115 - INVITE (With RTP) [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:11361 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:1039 parse_sip_options: * SIP extension value: 1 for call 874c5e93bce332dc@192.168.200.115 [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:7258 check_user_full: Setting NAT on RTP to 0 [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:7262 check_user_full: Setting NAT on VRTP to 0 [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:3209 find_call: = Found Their Call ID: 874c5e93bce332dc@192.168.200.115 Their Tag abaac25f155bb00e Our tag: as682b45de [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:11361 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:1407 __sip_ack: Stopping retransmission on '874c5e93bce332dc@192.168.200.115' of Response 14422: Match Found [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:3209 find_call: = Found Their Call ID: 874c5e93bce332dc@192.168.200.115 Their Tag abaac25f155bb00e Our tag: as682b45de [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:11361 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:7258 check_user_full: Setting NAT on RTP to 0 [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:7262 check_user_full: Setting NAT on VRTP to 0 [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:10652 handle_request_invite: Checking SIP call limits for device sip1 [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:2212 update_call_counter: Updating call counter for incoming call [Mar 9 15:53:04] DEBUG[21583]: chan_sip.c:6169 build_route: build_route: Contact hop: [Mar 9 15:53:04] DEBUG[21575]: chan_sip.c:11940 sip_devicestate: Checking device state for peer sip1 [Mar 9 15:53:04] DEBUG[21575]: devicestate.c:189 do_state_change: Changing state for SIP/sip1 - state 2 (In use) [Mar 9 15:53:04] DEBUG[21635]: pbx.c:1678 pbx_extension_helper: Launching 'Dial' [Mar 9 15:53:04] -- Executing Dial("SIP/sip1-081a5d08", "CELL/T68i/069981857275") in new stack [Mar 9 15:53:04] DEBUG[21635]: channel.c:2911 ast_channel_inherit_variables: Not copying variable STACK-internal-3333-1. [Mar 9 15:53:04] DEBUG[21635]: channel.c:2911 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Mar 9 15:53:04] DEBUG[21635]: channel.c:2911 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. free(): invalid pointer 0xb722a9e4! [Mar 9 15:53:04] DEBUG[21635]: channel.c:2911 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Mar 9 15:53:04] DEBUG[21635]: channel.c:2911 ast_channel_inherit_variables: Not copying variable SIPURI. [Mar 9 15:53:04] DEBUG[21635]: chan_cellphone.c:462 cel_call: Calling T68i/069981857275 on CELL/T68i-64f8 [Mar 9 15:53:04] -- Called T68i/069981857275 [Mar 9 15:53:04] DEBUG[21635]: channel.c:2392 set_format: Set channel CELL/T68i-64f8 to read format slin [Mar 9 15:53:04] DEBUG[21635]: channel.c:2392 set_format: Set channel SIP/sip1-081a5d08 to write format slin [Mar 9 15:53:04] DEBUG[21635]: channel.c:2392 set_format: Set channel SIP/sip1-081a5d08 to read format slin [Mar 9 15:53:04] DEBUG[21635]: channel.c:2392 set_format: Set channel CELL/T68i-64f8 to write format slin [Mar 9 15:53:04] DEBUG[21636]: app_queue.c:490 changethread: Device 'SIP/sip1' changed to state '2' (In use) but we don't care because they're not a member of any queue. ]Mar 9 15:53:04] DEBUG[21599]: chan_cellphone.c:840 rfcomm_write: rfcomm_write() (T68i) [ATD069981857275; ///// HERE IS BEFORE HANGUP - NOTHING HAPPENS HERE UNTIL I HANGUP THE SIP-PHONE [Mar 9 15:53:28] DEBUG[21583]: chan_sip.c:3209 find_call: = Found Their Call ID: 874c5e93bce332dc@192.168.200.115 Their Tag abaac25f155bb00e Our tag: as08b6d18b [Mar 9 15:53:28] DEBUG[21583]: chan_sip.c:11361 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL [Mar 9 15:53:28] DEBUG[21635]: channel.c:1365 ast_hangup: Hanging up channel 'CELL/T68i-64f8' [Mar 9 15:53:28] DEBUG[21635]: chan_cellphone.c:484 cel_hangup: Hanging up device T68i. ]Mar 9 15:53:28] DEBUG[21635]: chan_cellphone.c:840 rfcomm_write: rfcomm_write() (T68i) [AT+CHUP [Mar 9 15:53:28] DEBUG[21635]: app_dial.c:1658 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Mar 9 15:53:28] DEBUG[21635]: pbx.c:2317 __ast_pbx_run: Spawn extension (internal,3333,1) exited non-zero on 'SIP/sip1-081a5d08' [Mar 9 15:53:28] DEBUG[21575]: chan_cellphone.c:735 cel_devicestate: Checking device state for device T68i [Mar 9 15:53:28] DEBUG[21575]: devicestate.c:189 do_state_change: Changing state for CELL/T68i - state 1 (Not in use) [Mar 9 15:53:28] DEBUG[21583]: chan_sip.c:3209 find_call: = Found Their Call ID: 874c5e93bce332dc@192.168.200.115 Their Tag abaac25f155bb00e Our tag: as08b6d18b [Mar 9 15:53:28] DEBUG[21583]: chan_sip.c:11540 sipsock_read: Failed to grab lock, trying again... [Mar 9 15:53:28] DEBUG[21583]: chan_sip.c:3209 find_call: = Found Their Call ID: 874c5e93bce332dc@192.168.200.115 Their Tag abaac25f155bb00e Our tag: as08b6d18b [Mar 9 15:53:28] DEBUG[21583]: chan_sip.c:11540 sipsock_read: Failed to grab lock, trying again... [Mar 9 15:53:28] > cdr_odbc: Query Successful! [Mar 9 15:53:28] DEBUG[21635]: channel.c:1365 ast_hangup: Hanging up channel 'SIP/sip1-081a5d08' [Mar 9 15:53:28] DEBUG[21635]: chan_sip.c:2421 sip_hangup: Hangup call SIP/sip1-081a5d08, SIP callid 874c5e93bce332dc@192.168.200.115) [Mar 9 15:53:28] DEBUG[21635]: chan_sip.c:2429 sip_hangup: update_call_counter(sip1) - decrement call limit counter [Mar 9 15:53:28] DEBUG[21635]: chan_sip.c:2212 update_call_counter: Updating call counter for incoming call [Mar 9 15:53:28] DEBUG[21583]: chan_sip.c:3209 find_call: = Found Their Call ID: 874c5e93bce332dc@192.168.200.115 Their Tag abaac25f155bb00e Our tag: as08b6d18b [Mar 9 15:53:28] DEBUG[21583]: chan_sip.c:11361 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 9 15:53:28] DEBUG[21583]: chan_sip.c:1407 __sip_ack: Stopping retransmission on '874c5e93bce332dc@192.168.200.115' of Response 14423: Match Found [Mar 9 15:53:28] DEBUG[21575]: chan_sip.c:11940 sip_devicestate: Checking device state for peer sip1 [Mar 9 15:53:28] DEBUG[21575]: devicestate.c:189 do_state_change: Changing state for SIP/sip1 - state 1 (Not in use) [Mar 9 15:53:28] DEBUG[21583]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 874c5e93bce332dc@192.168.200.115 - ACK (No RTP) [Mar 9 15:53:28] DEBUG[21583]: chan_sip.c:11361 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 9 15:53:28] DEBUG[21702]: app_queue.c:490 changethread: Device 'CELL/T68i' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 9 15:53:28] DEBUG[21703]: app_queue.c:490 changethread: Device 'SIP/sip1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. ]Mar 9 15:53:34] DEBUG[21599]: chan_cellphone.c:840 rfcomm_write: rfcomm_write() (T68i) [AT+CHUP ]Mar 9 15:53:36] DEBUG[21599]: chan_cellphone.c:840 rfcomm_write: rfcomm_write() (T68i) [AT+CHUP ]Mar 9 15:53:38] DEBUG[21599]: chan_cellphone.c:840 rfcomm_write: rfcomm_write() (T68i) [AT+CHUP ]Mar 9 15:53:40] DEBUG[21599]: chan_cellphone.c:840 rfcomm_write: rfcomm_write() (T68i) [AT+CHUP ]Mar 9 15:53:42] DEBUG[21599]: chan_cellphone.c:840 rfcomm_write: rfcomm_write() (T68i) [AT+CHUP ]Mar 9 15:53:44] DEBUG[21599]: chan_cellphone.c:840 rfcomm_write: rfcomm_write() (T68i) [AT+CHUP [Mar 9 15:53:46] DEBUG[21599]: chan_cellphone.c:1311 do_monitor: Device T68i failed to hangup after 6 tries, disconnecting. ]Mar 9 15:53:46] DEBUG[21599]: chan_cellphone.c:840 rfcomm_write: rfcomm_write() (T68i) [AT+CHUP [Mar 9 15:53:48] -- Bluetooth Device T68i has connected. ]Mar 9 15:53:48] DEBUG[21758]: chan_cellphone.c:840 rfcomm_write: rfcomm_write() (T68i) [AT+BRSF=4