chan_cellphone.so => (Bluetooth Cellphone Driver) Asterisk Ready. ]Feb 5 05:55:58] DEBUG[15940]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+CIND=? ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ [Feb 5 05:55:59] DEBUG[15940]: 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:55:59] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+CIND=? ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ [Feb 5 05:55:59] DEBUG[15940]: 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:55:59] DEBUG[15940]: chan_cellphone.c:863 do_monitor: CIEV_CALL=8 CIEV_CALLSETUP=0 ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+CIND? ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIND: 4,5,0,0,1,1,0,0,0,0 ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+CMER=3,0,0,1 ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK ]Feb 5 05:55:59] DEBUG[15940]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+CLIP=1 ]Feb 5 05:56:00] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:00] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK ]Feb 5 05:56:00] DEBUG[15940]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+VGS=7 ]Feb 5 05:56:00] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:00] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK [Feb 5 05:56:00] DEBUG[15940]: chan_cellphone.c:895 do_monitor: Device CellA online and ready. CALL 12345678 from a diffrent cellphone ]Feb 5 05:56:08] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:08] DEBUG[15940]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [ ]Feb 5 05:56:08] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [RING ]Feb 5 05:56:08] DEBUG[15940]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [RING ]Feb 5 05:56:08] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:08] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CLIP: "12345678",161,,,"" ]Feb 5 05:56:11] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:11] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [RING [Feb 5 05:56:11] DEBUG[15940]: pbx.c:1693 pbx_extension_helper: Launching 'Wait' ]Feb 5 05:56:11] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:11] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CLIP: "12345678",161,,,"" ]Feb 5 05:56:13] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:13] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,4 ]Feb 5 05:56:13] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:13] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,5 ]Feb 5 05:56:14] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:14] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [RING ]Feb 5 05:56:14] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:14] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CLIP: "12345678",161,,,"" [Feb 5 05:56:15] DEBUG[15940]: pbx.c:1693 pbx_extension_helper: Launching 'Answer' ]Feb 5 05:56:15] DEBUG[15940]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [ATA [Feb 5 05:56:15] DEBUG[15940]: pbx.c:1693 pbx_extension_helper: Launching 'Set' [Feb 5 05:56:15] DEBUG[15940]: pbx.c:1693 pbx_extension_helper: Launching 'Set' [Feb 5 05:56:15] DEBUG[15940]: pbx.c:1693 pbx_extension_helper: Launching 'Playback' [Feb 5 05:56:15] DEBUG[15940]: channel.c:2755 set_format: Set channel CELL/CellA-0338 to write format gsm [Feb 5 05:56:15] DEBUG[15940]: chan_cellphone.c:595 cel_devicestate: Checking device state for device CellA [Feb 5 05:56:15] DEBUG[15940]: 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:56:15] DEBUG[15940]: sched.c:205 sched_settime: Request to schedule in the past?!?! ]Feb 5 05:56:15] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:15] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK [Feb 5 05:56:16] DEBUG[15940]: chan_cellphone.c:1134 do_sco_listen: Incoming Audio Connection from device 00:0F:DE:2A:C1:4C [Feb 5 05:56:16] DEBUG[15940]: chan_cellphone.c:1149 do_sco_listen: Set Audio Connection fd OK. ]Feb 5 05:56:16] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:16] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 6,1 ]Feb 5 05:56:16] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:16] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 8,1 ]Feb 5 05:56:16] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:16] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,4 ]Feb 5 05:56:16] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:16] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,5 ]Feb 5 05:56:17] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:17] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,4 ]Feb 5 05:56:17] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:17] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,5 [Feb 5 05:56:35] DEBUG[15940]: channel.c:2755 set_format: Set channel CELL/CellA-0338 to write format slin [Feb 5 05:56:35] DEBUG[15940]: pbx.c:1693 pbx_extension_helper: Launching 'Echo' ]Feb 5 05:56:37] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:37] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 8,0 [Feb 5 05:56:37] DEBUG[15940]: pbx.c:2289 __ast_pbx_run: Spawn extension (default,s,6) exited non-zero on 'CELL/CellA-0338' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '"CellA" <12345678",161,,,">' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '12345678",161,,,"' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 's' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'default' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'CELL/CellA-0338' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Echo' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-05 05:56:11' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-05 05:56:15' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-05 05:56:37' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '26' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '22' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1170651371.0' [Feb 5 05:56:37] DEBUG[15940]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 5 05:56:37] DEBUG[15940]: channel.c:1589 ast_hangup: Hanging up channel 'CELL/CellA-0338' [Feb 5 05:56:37] DEBUG[15940]: chan_cellphone.c:402 cel_hangup: Hanging up device CellA. ]Feb 5 05:56:37] DEBUG[15940]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [AT+CHUP [Feb 5 05:56:37] DEBUG[15940]: chan_cellphone.c:595 cel_devicestate: Checking device state for device CellA [Feb 5 05:56:37] DEBUG[15940]: chan_cellphone.c:595 cel_devicestate: Checking device state for device CellA [Feb 5 05:56:37] DEBUG[15940]: 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:56:37] DEBUG[15940]: 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:56:38] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:56:38] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK HANGUP. Everything works fine. Then wait a couple of seconds, and call again. ]Feb 5 05:57:24] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:57:24] DEBUG[15940]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [ ]Feb 5 05:57:24] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 6,0 ]Feb 5 05:57:24] DEBUG[15940]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [+CIEV: 6,0 ]Feb 5 05:57:24] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:57:24] DEBUG[15940]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [ ]Feb 5 05:57:24] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [RING ]Feb 5 05:57:24] DEBUG[15940]: chan_cellphone.c:900 do_monitor: Device 00:0F:DE:2A:C1:4C CellA [RING ]Feb 5 05:57:24] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:57:24] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CLIP: "12345678",161,,,"" ]Feb 5 05:57:27] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:57:27] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [RING [Feb 5 05:57:27] DEBUG[15940]: pbx.c:1693 pbx_extension_helper: Launching 'Wait' ]Feb 5 05:57:27] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:57:27] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CLIP: "12345678",161,,,"" ]Feb 5 05:57:28] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:57:28] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,4 ]Feb 5 05:57:30] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:57:30] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CIEV: 2,5 ]Feb 5 05:57:30] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:57:30] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [RING ]Feb 5 05:57:30] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:57:30] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [+CLIP: "12345678",161,,,"" [Feb 5 05:57:31] DEBUG[15940]: pbx.c:1693 pbx_extension_helper: Launching 'Answer' ]Feb 5 05:57:31] DEBUG[15940]: chan_cellphone.c:651 rfcomm_write: rfcomm_write() (20) [ATA [Feb 5 05:57:31] DEBUG[15940]: pbx.c:1693 pbx_extension_helper: Launching 'Set' [Feb 5 05:57:31] DEBUG[15940]: pbx.c:1693 pbx_extension_helper: Launching 'Set' [Feb 5 05:57:31] DEBUG[15940]: pbx.c:1693 pbx_extension_helper: Launching 'Playback' [Feb 5 05:57:31] DEBUG[15940]: channel.c:2755 set_format: Set channel CELL/CellA-5f4a to write format gsm [Feb 5 05:57:31] DEBUG[15940]: chan_cellphone.c:595 cel_devicestate: Checking device state for device CellA [Feb 5 05:57:31] DEBUG[15940]: 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:57:31] DEBUG[15940]: sched.c:205 sched_settime: Request to schedule in the past?!?! [Feb 5 05:57:31] DEBUG[15940]: sched.c:205 sched_settime: Request to schedule in the past?!?! ]Feb 5 05:57:31] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [ ]Feb 5 05:57:31] DEBUG[15940]: chan_cellphone.c:826 do_monitor: rfcomm_read() (20) [OK [Feb 5 05:57:51] DEBUG[15940]: channel.c:2755 set_format: Set channel CELL/CellA-5f4a to write format slin [Feb 5 05:57:51] DEBUG[15940]: pbx.c:1693 pbx_extension_helper: Launching 'Echo' This time I can't hear anything. After about 20 seconds, my phone tells me that the bluetooth connection to the handset (computer) is lost