[New Thread -1215247472 (LWP 13621)] -- Bluetooth Device mals has connected. ]Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:813 rfcomm_write: rfcomm_write() (mals) [AT+BRSF=4 [Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [+BRSF: 33] [Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [OK] ]Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:813 rfcomm_write: rfcomm_write() (mals) [AT+CIND=? [Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [+CIND: ("service",(0,1)),("call",(0,1)),("callsetup",(0-3))] [Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:1077 do_monitor_phone: CIEV_CALL=2 CIEV_CALLSETUP=3 [Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [OK] ]Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:813 rfcomm_write: rfcomm_write() (mals) [AT+CIND? [Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [+CIND: 1,0,0] [Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [OK] ]Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:813 rfcomm_write: rfcomm_write() (mals) [AT+CMER=3,0,0,1 [Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [OK] ]Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:813 rfcomm_write: rfcomm_write() (mals) [AT+CLIP=1 [Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [OK] ]Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:813 rfcomm_write: rfcomm_write() (mals) [AT+CMGF=1 [Apr 5 13:03:52] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [ERROR] -- Bluetooth Device mals initialised and ready. [Apr 5 13:04:11] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [+CIEV: 3,1] [Apr 5 13:04:11] DEBUG[13621]: chan_cellphone.c:1129 do_monitor_phone: Device 00:18:AF:33:EE:D9 mals [+CIEV: 3,1] [Apr 5 13:04:11] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [RING] [Apr 5 13:04:11] DEBUG[13621]: chan_cellphone.c:1129 do_monitor_phone: Device 00:18:AF:33:EE:D9 mals [RING] [Apr 5 13:04:11] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [+CLIP: "0889466353",145] [New Thread -1215493232 (LWP 13622)] [Apr 5 13:04:11] DEBUG[13622]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' -- Executing [s@incoming:1] Dial("CELL/mals-fa28", "SIP/0889466631@cdu&SIP/malsekiga|25|rt") in new stack [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:15310 sip_request_call: Asked to create a SIP channel with formats: 0x40 (slin) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3805 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3807 sip_new: *** Our capabilities are 0x10f (g723|gsm|ulaw|alaw|g729) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3810 sip_new: *** Our preferred formats from the incoming channel are 0x40 (slin) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Apr 5 13:04:11] DEBUG[13622]: rtp.c:1558 ast_rtp_make_compatible: Channel 'CELL/mals-fa28' has no RTP, not doing anything [Apr 5 13:04:11] DEBUG[13622]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-incoming-s-1. [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:2830 sip_call: Outgoing Call for 0889466631 [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:2845 sip_call: Our T38 capability (0), joint T38 capability (0) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:6188 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x40 (slin) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) -- Called 0889466631@cdu [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:15310 sip_request_call: Asked to create a SIP channel with formats: 0x40 (slin) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3805 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3807 sip_new: *** Our capabilities are 0x3f1fff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|jpeg|png|h261|h263|h263p|h264) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3810 sip_new: *** Our preferred formats from the incoming channel are 0x40 (slin) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Apr 5 13:04:11] DEBUG[13622]: rtp.c:1558 ast_rtp_make_compatible: Channel 'CELL/mals-fa28' has no RTP, not doing anything [Apr 5 13:04:11] DEBUG[13622]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-incoming-s-1. [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:2830 sip_call: Outgoing Call for malsekiga [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:2845 sip_call: Our T38 capability (0), joint T38 capability (0) [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:6188 add_sdp: ** Our capability: 0x3f0efe (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|ilbc|g726aal2|jpeg|png|h261|h263|h263p|h264) Video flag: False [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x40 (slin) [Apr 5 13:04:11] DEBUG[13608]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '68ae1fbf711e3f6f72b415f50393427a@138.80.54.113' Request 102: Found [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:6206 add_sdp: This call needs video offers, but there's no video support enabled! [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Apr 5 13:04:11] DEBUG[13622]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x3f0efe (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|ilbc|g726aal2|jpeg|png|h261|h263|h263p|h264) -- Called malsekiga [Apr 5 13:04:11] DEBUG[13622]: channel.c:2435 ast_indicate_data: Driver for channel 'CELL/mals-fa28' does not support indication 3, emulating it [Apr 5 13:04:11] DEBUG[13622]: channel.c:2587 ast_prod: Prodding channel 'CELL/mals-fa28' [Apr 5 13:04:12] DEBUG[13608]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7278cf904ea50bf80cdc75f071085eab@138.80.54.113' Request 102: Found [Apr 5 13:04:12] DEBUG[13608]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7278cf904ea50bf80cdc75f071085eab@138.80.54.113' Request 102: Found [Apr 5 13:04:12] DEBUG[13608]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '68ae1fbf711e3f6f72b415f50393427a@138.80.54.113' Request 102: Found [Apr 5 13:04:12] DEBUG[13608]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/cdu-08ce7278 [Apr 5 13:04:12] DEBUG[13608]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0x8 (alaw) [Apr 5 13:04:12] DEBUG[13608]: channel.c:2845 set_format: Set channel SIP/cdu-08ce7278 to read format ulaw [Apr 5 13:04:12] DEBUG[13608]: channel.c:2845 set_format: Set channel SIP/cdu-08ce7278 to write format ulaw -- Call on SIP/cdu-08ce7278 left from hold -- SIP/cdu-08ce7278 is making progress passing it to CELL/mals-fa28 [Apr 5 13:04:12] DEBUG[13608]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7278cf904ea50bf80cdc75f071085eab@138.80.54.113' Request 102: Found [Apr 5 13:04:12] DEBUG[13608]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/malsekiga-08cebf38 -- SIP/malsekiga-08cebf38 is ringing [Apr 5 13:04:12] DEBUG[13580]: chan_sip.c:15244 sip_devicestate: Checking device state for peer malsekiga [Apr 5 13:04:12] DEBUG[13580]: devicestate.c:287 do_state_change: Changing state for SIP/malsekiga - state 1 (Not in use) [New Thread -1215738992 (LWP 13627)] [Apr 5 13:04:12] DEBUG[13627]: app_queue.c:546 changethread: Device 'SIP/malsekiga' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Thread -1215738992 (LWP 13627) exited] [Apr 5 13:04:14] DEBUG[13622]: rtp.c:873 ast_rtcp_read: Got RTCP report of 108 bytes [Apr 5 13:04:14] DEBUG[13608]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Apr 5 13:04:14] DEBUG[13608]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '68ae1fbf711e3f6f72b415f50393427a@138.80.54.113' of Request 102: Match Not Found [Apr 5 13:04:14] DEBUG[13608]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/cdu-08ce7278 [Apr 5 13:04:14] DEBUG[13608]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0x8 (alaw) [Apr 5 13:04:14] DEBUG[13608]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Apr 5 13:04:14] DEBUG[13608]: chan_sip.c:7980 build_route: build_route: Contact hop: -- Call on SIP/cdu-08ce7278 left from hold [Apr 5 13:04:14] DEBUG[13622]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/cdu-08ce7278 -- SIP/cdu-08ce7278 answered CELL/mals-fa28 [Apr 5 13:04:14] DEBUG[13622]: rtp.c:1468 ast_rtp_early_bridge: Channel 'CELL/mals-fa28' has no RTP, not doing anything [Apr 5 13:04:14] DEBUG[13622]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/malsekiga-08cebf38' [Apr 5 13:04:14] DEBUG[13622]: chan_sip.c:3312 sip_hangup: Hangup call SIP/malsekiga-08cebf38, SIP callid 7278cf904ea50bf80cdc75f071085eab@138.80.54.113) [Apr 5 13:04:14] DEBUG[13622]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Apr 5 13:04:14] DEBUG[13622]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '7278cf904ea50bf80cdc75f071085eab@138.80.54.113' of Request 102: Match Not Found [Apr 5 13:04:14] DEBUG[13622]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/malsekiga-08cebf38 [Apr 5 13:04:14] DEBUG[13622]: channel.c:2845 set_format: Set channel CELL/mals-fa28 to read format alaw [Apr 5 13:04:14] DEBUG[13622]: channel.c:2845 set_format: Set channel SIP/cdu-08ce7278 to write format alaw [Apr 5 13:04:14] DEBUG[13622]: channel.c:2845 set_format: Set channel SIP/cdu-08ce7278 to read format slin ]Apr 5 13:04:14] DEBUG[13622]: chan_cellphone.c:813 rfcomm_write: rfcomm_write() (mals) [ATA [Apr 5 13:04:14] DEBUG[13622]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel CELL/mals-fa28 [Apr 5 13:04:14] DEBUG[13580]: chan_sip.c:15244 sip_devicestate: Checking device state for peer cdu [Apr 5 13:04:14] DEBUG[13580]: devicestate.c:287 do_state_change: Changing state for SIP/cdu - state 1 (Not in use) [New Thread -1215738992 (LWP 13628)] [Apr 5 13:04:14] DEBUG[13580]: chan_sip.c:15244 sip_devicestate: Checking device state for peer malsekiga [Apr 5 13:04:14] DEBUG[13580]: devicestate.c:287 do_state_change: Changing state for SIP/malsekiga - state 1 (Not in use) [Apr 5 13:04:14] DEBUG[13628]: app_queue.c:546 changethread: Device 'SIP/cdu' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Thread -1215738992 (LWP 13628) exited] [Apr 5 13:04:14] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [OK] [New Thread -1215984752 (LWP 13629)] [Apr 5 13:04:14] DEBUG[13580]: chan_cellphone.c:715 cel_devicestate: Checking device state for device mals [Apr 5 13:04:14] DEBUG[13580]: devicestate.c:287 do_state_change: Changing state for CELL/mals - state 2 (In use) [Apr 5 13:04:14] DEBUG[13629]: app_queue.c:546 changethread: Device 'SIP/malsekiga' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Thread -1215984752 (LWP 13629) exited] [New Thread -1215738992 (LWP 13630)] [Apr 5 13:04:15] DEBUG[13583]: chan_cellphone.c:1546 do_sco_listen: Incoming Audio Connection from device 00:18:AF:33:EE:D9 MTU is 16 [Apr 5 13:04:15] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [+CIEV: 2,1] [Apr 5 13:04:15] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [+CIEV: 3,0] [Apr 5 13:04:15] DEBUG[13630]: app_queue.c:546 changethread: Device 'CELL/mals' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Thread -1215738992 (LWP 13630) exited] [Apr 5 13:04:15] DEBUG[13622]: rtp.c:2689 ast_rtp_write: Ooh, format changed from unknown to alaw [Apr 5 13:04:15] DEBUG[13622]: rtp.c:2706 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Apr 5 13:04:15] DEBUG[13608]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '7278cf904ea50bf80cdc75f071085eab@138.80.54.113' of Request 102: Match Not Found [Apr 5 13:04:15] DEBUG[13608]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '7278cf904ea50bf80cdc75f071085eab@138.80.54.113' of Request 102: Match Found [Apr 5 13:04:15] DEBUG[13608]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Apr 5 13:04:16] DEBUG[13622]: rtp.c:873 ast_rtcp_read: Got RTCP report of 112 bytes [Apr 5 13:04:21] DEBUG[13622]: rtp.c:873 ast_rtcp_read: Got RTCP report of 132 bytes [Apr 5 13:04:24] DEBUG[13622]: rtp.c:873 ast_rtcp_read: Got RTCP report of 132 bytes [Apr 5 13:04:28] DEBUG[13622]: rtp.c:873 ast_rtcp_read: Got RTCP report of 132 bytes [Apr 5 13:04:31] DEBUG[13622]: rtp.c:873 ast_rtcp_read: Got RTCP report of 132 bytes [Apr 5 13:04:36] DEBUG[13622]: rtp.c:873 ast_rtcp_read: Got RTCP report of 132 bytes [Apr 5 13:04:39] DEBUG[13622]: rtp.c:873 ast_rtcp_read: Got RTCP report of 132 bytes [Apr 5 13:04:46] DEBUG[13608]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog '7278cf904ea50bf80cdc75f071085eab@138.80.54.113' [Apr 5 13:04:46] DEBUG[13608]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 7278cf904ea50bf80cdc75f071085eab@138.80.54.113 Really destroying SIP dialog '7278cf904ea50bf80cdc75f071085eab@138.80.54.113' Method: INVITE [Apr 5 13:04:47] DEBUG[13622]: rtp.c:873 ast_rtcp_read: Got RTCP report of 132 bytes [Apr 5 13:04:49] DEBUG[13622]: chan_cellphone.c:640 cel_read: cel_read() read error 107. [Apr 5 13:04:49] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [+CIEV: 2,0] [Apr 5 13:04:49] DEBUG[13622]: channel.c:3800 ast_generic_bridge: Didn't get a frame from channel: CELL/mals-fa28 [Apr 5 13:04:49] DEBUG[13622]: channel.c:4118 ast_channel_bridge: Bridge stops bridging channels CELL/mals-fa28 and SIP/cdu-08ce7278 [Apr 5 13:04:49] DEBUG[13622]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/cdu-08ce7278' [Apr 5 13:04:49] DEBUG[13622]: chan_sip.c:3312 sip_hangup: Hangup call SIP/cdu-08ce7278, SIP callid 68ae1fbf711e3f6f72b415f50393427a@138.80.54.113) [Apr 5 13:04:49] DEBUG[13622]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/cdu-08ce7278 [Apr 5 13:04:49] DEBUG[13622]: rtp.c:1468 ast_rtp_early_bridge: Channel 'CELL/mals-fa28' has no RTP, not doing anything [Apr 5 13:04:49] DEBUG[13622]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 5 13:04:49] DEBUG[13622]: pbx.c:2393 __ast_pbx_run: Spawn extension (incoming,s,1) exited non-zero on 'CELL/mals-fa28' == Spawn extension (incoming, s, 1) exited non-zero on 'CELL/mals-fa28' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '"mals" <0889466353>' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0889466353' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 's' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'incoming' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'CELL/mals-fa28' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/cdu-08ce7278' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/0889466631@cdu&SIP/malsekiga|25|rt' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-05 13:04:11' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-05 13:04:14' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-05 13:04:49' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '38' [Apr 5 13:04:49] DEBUG[13580]: chan_sip.c:15244 sip_devicestate: Checking device state for peer cdu [Apr 5 13:04:49] DEBUG[13580]: devicestate.c:287 do_state_change: Changing state for SIP/cdu - state 1 (Not in use) [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '35' [Apr 5 13:04:49] DEBUG[13608]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '68ae1fbf711e3f6f72b415f50393427a@138.80.54.113' of Request 103: Match Not Found Really destroying SIP dialog '68ae1fbf711e3f6f72b415f50393427a@138.80.54.113' Method: INVITE [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1175744051.0' [Apr 5 13:04:49] DEBUG[13622]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 5 13:04:49] DEBUG[13622]: channel.c:1693 ast_hangup: Hanging up channel 'CELL/mals-fa28' [Apr 5 13:04:49] DEBUG[13622]: chan_cellphone.c:504 cel_hangup: Hanging up device mals. ]Apr 5 13:04:49] DEBUG[13622]: chan_cellphone.c:813 rfcomm_write: rfcomm_write() (mals) [AT+CHUP [Apr 5 13:04:49] DEBUG[13622]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel CELL/mals-fa28 [Apr 5 13:04:49] DEBUG[13622]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel CELL/mals-fa28 [Apr 5 13:04:49] DEBUG[13621]: chan_cellphone.c:1035 do_monitor_phone: rfcomm_read() (mals) [OK] [Thread -1215493232 (LWP 13622) exited] [New Thread -1215738992 (LWP 13648)] [Apr 5 13:04:49] DEBUG[13580]: chan_cellphone.c:715 cel_devicestate: Checking device state for device mals [Apr 5 13:04:49] DEBUG[13580]: devicestate.c:287 do_state_change: Changing state for CELL/mals - state 1 (Not in use) [Apr 5 13:04:49] DEBUG[13648]: app_queue.c:546 changethread: Device 'SIP/cdu' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Thread -1215738992 (LWP 13648) exited] [New Thread -1215493232 (LWP 13650)] [Apr 5 13:04:50] DEBUG[13580]: chan_cellphone.c:715 cel_devicestate: Checking device state for device mals [Apr 5 13:04:50] DEBUG[13580]: devicestate.c:287 do_state_change: Changing state for CELL/mals - state 1 (Not in use) [New Thread -1215738992 (LWP 13651)] [Apr 5 13:04:50] DEBUG[13651]: app_queue.c:546 changethread: Device 'CELL/mals' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Thread -1215738992 (LWP 13651) exited] [Apr 5 13:04:50] DEBUG[13650]: app_queue.c:546 changethread: Device 'CELL/mals' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Thread -1215493232 (LWP 13650) exited] [Apr 5 13:04:51] DEBUG[13608]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 5 13:04:51] DEBUG[13608]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '690d101235437bc5124ecace3ddb1ee7@138.80.54.113' of Request 102: Match Not Found Really destroying SIP dialog '690d101235437bc5124ecace3ddb1ee7@138.80.54.113' Method: OPTIONS