rendered paste body[Feb 5 05:24:06] DEBUG[13969]: config.c:851 config_text_file_load: Parsing /etc/asterisk/cellphone.conf
[Feb 5 05:24:06] DEBUG[13969]: chan_cellphone.c:1184 cel_load_config: Loading device CellA.
[Feb 5 05:24:06] DEBUG[13969]: channel.c:421 ast_channel_register: Registered handler for 'CELL' (Bluetooth Cellphone Driver)
chan_cellphone.so => (Bluetooth Cellphone Driver)
Asterisk Ready.
]Feb 5 05:24:07] DEBUG[13969]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+CIND=?
]Feb 5 05:24:07] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
[Feb 5 05:24:07] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIND: ("battchg",(0-5)),("signal",(0-5)),("batterywarning",(0-1)),("chargerconnected",(0-1)),("service",(0-1)),("sounder",(0-1)),("message",(0-1)),("call",(0-1)),("]oam",(0-1)),("smsfull",(0-1))
]Feb 5 05:24:07] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:07] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK
]Feb 5 05:24:07] DEBUG[13969]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+CIND=?
]Feb 5 05:24:07] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
[Feb 5 05:24:07] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIND: ("battchg",(0-5)),("signal",(0-5)),("batterywarning",(0-1)),("chargerconnected",(0-1)),("service",(0-1)),("sounder",(0-1)),("message",(0-1)),("call",(0-1)),("]oam",(0-1)),("smsfull",(0-1))
[Feb 5 05:24:07] DEBUG[13969]: chan_cellphone.c:863 do_monitor: CIEV_CALL=8 CIEV_CALLSETUP=0
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+CIND?
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIND: 4,5,0,0,1,1,0,0,0,0
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+CMER=3,0,0,1
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+CLIP=1
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+VGS=7
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK
[Feb 5 05:24:08] DEBUG[13969]: chan_cellphone.c:895 do_monitor: Device CellA online and ready.
]Feb 5 05:24:19] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:19] DEBUG[13969]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [
]Feb 5 05:24:19] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 6,0
]Feb 5 05:24:19] DEBUG[13969]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [+CIEV: 6,0
]Feb 5 05:24:19] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:19] DEBUG[13969]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [
]Feb 5 05:24:19] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [RING
]Feb 5 05:24:19] DEBUG[13969]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [RING
]Feb 5 05:24:19] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:19] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CLIP: "12345678",161,,,""
]Feb 5 05:24:23] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:23] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [RING
[Feb 5 05:24:23] DEBUG[13969]: pbx.c:1693 pbx_extension_helper: Launching 'Wait'
]Feb 5 05:24:23] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:23] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CLIP: "12345678",161,,,""
]Feb 5 05:24:26] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:26] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [RING
]Feb 5 05:24:26] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:26] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CLIP: "12345678",161,,,""
[Feb 5 05:24:27] DEBUG[13969]: pbx.c:1693 pbx_extension_helper: Launching 'Answer'
]Feb 5 05:24:27] DEBUG[13969]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [ATA
[Feb 5 05:24:27] DEBUG[13969]: pbx.c:1693 pbx_extension_helper: Launching 'Set'
[Feb 5 05:24:27] DEBUG[13969]: pbx.c:1693 pbx_extension_helper: Launching 'Set'
[Feb 5 05:24:27] DEBUG[13969]: pbx.c:1693 pbx_extension_helper: Launching 'Playback'
[Feb 5 05:24:27] DEBUG[13969]: channel.c:2755 set_format: Set channel CELL/CellA-4e8d to write format gsm
[Feb 5 05:24:27] DEBUG[13969]: chan_cellphone.c:595 cel_devicestate: Checking device state for device CellA
[Feb 5 05:24:27] DEBUG[13969]: app_queue.c:568 changethread: Device 'CELL/CellA' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Feb 5 05:24:27] DEBUG[13969]: sched.c:205 sched_settime: Request to schedule in the past?!?!
]Feb 5 05:24:27] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:27] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK
[Feb 5 05:24:27] DEBUG[13969]: chan_cellphone.c:1134 do_sco_listen: Incoming Audio Connection from device 00:0F:DE:2A:C1:4C
[Feb 5 05:24:27] DEBUG[13969]: chan_cellphone.c:1149 do_sco_listen: Set Audio Connection fd OK.
]Feb 5 05:24:27] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:27] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 6,1
]Feb 5 05:24:27] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:27] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 8,1
]Feb 5 05:24:29] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:29] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,3
]Feb 5 05:24:29] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:29] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,4
]Feb 5 05:24:30] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:30] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,5
]Feb 5 05:24:31] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:31] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,4
]Feb 5 05:24:31] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:31] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,5
]Feb 5 05:24:37] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:37] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,4
]Feb 5 05:24:37] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:24:37] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,5
[Feb 5 05:24:46] DEBUG[13969]: channel.c:2755 set_format: Set channel CELL/CellA-4e8d to write format slin
[Feb 5 05:24:46] DEBUG[13969]: pbx.c:1693 pbx_extension_helper: Launching 'Echo'
]Feb 5 05:25:01] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:25:01] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 8,0
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:2289 __ast_pbx_run: Spawn extension (default,s,6) exited non-zero on 'CELL/CellA-4e8d'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '"CellA" <12345678",161,,,">'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '12345678",161,,,"'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 's'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'default'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'CELL/CellA-4e8d'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is ''
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Echo'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is ''
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-05 05:24:23'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-05 05:24:27'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-05 05:25:01'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '38'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '34'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is ''
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1170649463.0'
[Feb 5 05:25:01] DEBUG[13969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is ''
[Feb 5 05:25:01] DEBUG[13969]: channel.c:1589 ast_hangup: Hanging up channel 'CELL/CellA-4e8d'
[Feb 5 05:25:01] DEBUG[13969]: chan_cellphone.c:402 cel_hangup: Hanging up device CellA.
]Feb 5 05:25:01] DEBUG[13969]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+CHUP
[Feb 5 05:25:01] DEBUG[13969]: chan_cellphone.c:595 cel_devicestate: Checking device state for device CellA
[Feb 5 05:25:01] DEBUG[13969]: chan_cellphone.c:595 cel_devicestate: Checking device state for device CellA
[Feb 5 05:25:01] DEBUG[13969]: app_queue.c:568 changethread: Device 'CELL/CellA' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb 5 05:25:01] DEBUG[13969]: app_queue.c:568 changethread: Device 'CELL/CellA' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
]Feb 5 05:25:01] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:25:01] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK
END OF ECHO CALL
]Feb 5 05:26:02] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:26:02] DEBUG[13969]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [
]Feb 5 05:26:02] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 6,0
]Feb 5 05:26:02] DEBUG[13969]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [+CIEV: 6,0
]Feb 5 05:26:02] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:26:02] DEBUG[13969]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [
]Feb 5 05:26:02] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [RING
]Feb 5 05:26:02] DEBUG[13969]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [RING
]Feb 5 05:26:02] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:26:02] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CLIP: "12345678",161,,,""
]Feb 5 05:26:05] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:26:05] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [RING
[Feb 5 05:26:05] DEBUG[13969]: pbx.c:1693 pbx_extension_helper: Launching 'Wait'
]Feb 5 05:26:05] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:26:05] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CLIP: "12345678",161,,,""
]Feb 5 05:26:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:26:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [RING
]Feb 5 05:26:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:26:08] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CLIP: "12345678",161,,,""
[Feb 5 05:26:09] DEBUG[13969]: pbx.c:1693 pbx_extension_helper: Launching 'Answer'
]Feb 5 05:26:09] DEBUG[13969]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [ATA
[Feb 5 05:26:09] DEBUG[13969]: pbx.c:1693 pbx_extension_helper: Launching 'Set'
[Feb 5 05:26:09] DEBUG[13969]: pbx.c:1693 pbx_extension_helper: Launching 'Set'
[Feb 5 05:26:09] DEBUG[13969]: pbx.c:1693 pbx_extension_helper: Launching 'Playback'
[Feb 5 05:26:09] DEBUG[13969]: channel.c:2755 set_format: Set channel CELL/CellA-7a20 to write format gsm
[Feb 5 05:26:09] DEBUG[13969]: chan_cellphone.c:595 cel_devicestate: Checking device state for device CellA
[Feb 5 05:26:09] DEBUG[13969]: app_queue.c:568 changethread: Device 'CELL/CellA' changed to state '2' (In use) but we don't care because they're not a member of any queue.
]Feb 5 05:26:09] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [
]Feb 5 05:26:09] DEBUG[13969]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK
[Feb 5 05:26:29] DEBUG[13969]: channel.c:2755 set_format: Set channel CELL/CellA-7a20 to write format slin
[Feb 5 05:26:29] DEBUG[13969]: pbx.c:1693 pbx_extension_helper: Launching 'Echo'