search

bg111 / asterisk-chan-dongle

Automatically exported from code.google.com/p/asterisk-chan-dongle
Other
351 stars 319 forks source link

callwaiting=auto cause dongle state invalid and no longer connectable even reboot. #244

Open ulion opened 7 years ago

ulion commented 7 years ago

When the sim has call wait enabled. and in dongle.conf setup callwaiting=auto as default set in raspbx does. then when the asterisk boot up, in the asterisk console run: dongle show device state dongle0 it display "Call Waiting : Disabled" the call waiting did work with this setup (not work when callwaiting=yes sadly).

the problem is, when the call waiting finally got no pickup, the dongle lost connection, changed to Invalid state:

[2017-03-05 20:51:35] DEBUG[2212] at_queue.c: [dongle0] insert task with 1 commands begin with 'AT' expected response 'OK' after head of queue
[2017-03-05 20:51:35] DEBUG[2212] at_queue.c: [dongle0] write command 'AT' expected response 'OK' length 3
[2017-03-05 20:51:35] DEBUG[2212] at_queue.c: [dongle0] [AT^M]
[2017-03-05 20:51:35] DEBUG[6574][C-00000001] channel.c: [dongle0] read call idx 1 state 0 audio_fd 23
[2017-03-05 20:51:35] DEBUG[6574][C-00000001] dsp.c: DTMF best '6' Erow=2.2910E+07 Ecol=2.5642E+08 Erc=2.7933E+08 Et=2.9454E+07
[2017-03-05 20:51:35] DEBUG[6574][C-00000001] channel.c: [dongle0] read call idx 1 state 0 audio_fd 23
[2017-03-05 20:51:35] DEBUG[6574][C-00000001] channel.c: [dongle0] write silence
[2017-03-05 20:51:35] DEBUG[6574][C-00000001] channel.c: [dongle0] *** timing ***
[2017-03-05 20:51:35] DEBUG[6574][C-00000001] channel.c: [dongle0] read call idx 1 state 0 audio_fd 23
[2017-03-05 20:51:35] DEBUG[6574][C-00000001] dsp.c: DTMF best '*' Erow=1.3435E+09 Ecol=9.5517E+08 Erc=2.2986E+09 Et=2.5309E+08
[2017-03-05 20:51:35] DEBUG[6574][C-00000001] dsp.c: DTMF best '2' Erow=2.2440E+09 Ecol=7.1621E+09 Erc=9.4061E+09 Et=4.9232E+08
[2017-03-05 20:51:35] DEBUG[6574][C-00000001] channel.c: [dongle0] read call idx 1 state 0 audio_fd 23
[2017-03-05 20:51:35] DEBUG[6574][C-00000001] channel.c: [dongle0] write silence

....

[2017-03-05 20:51:36] DEBUG[6574][C-00000001] channel.c: [dongle0] *** timing ***
[2017-03-05 20:51:36] DEBUG[6574][C-00000001] channel.c: [dongle0] read call idx 1 state 0 audio_fd 23
[2017-03-05 20:51:36] DEBUG[6574][C-00000001] dsp.c: DTMF best '#' Erow=5.8244E+04 Ecol=3.6418E+04 Erc=9.4662E+04 Et=1.8242E+04
[2017-03-05 20:51:36] DEBUG[6574][C-00000001] dsp.c: DTMF best 'A' Erow=1.5461E+06 Ecol=8.3173E+05 Erc=2.3779E+06 Et=8.2875E+06
[2017-03-05 20:51:36] ERROR[2212] chan_dongle.c: [dongle0] timedout while waiting 'OK' in response to 'AT'
[2017-03-05 20:51:36] DEBUG[2212] chan_dongle.c: [dongle0] Dongle disconnecting, hanging up channels
[2017-03-05 20:51:36] DEBUG[2212] at_queue.c: [dongle0] [AT+CHLD=11^M]
[2017-03-05 20:51:36] DEBUG[2212] channel.c: [dongle0] call idx 1 mpty 0, change state from 'active' to 'released' has channel
[2017-03-05 20:51:36] DEBUG[2212] channel.c: [dongle0] call idx 1 disactivated
[2017-03-05 20:51:36] DEBUG[2212] cpvt.c: [dongle0] destroy cpvt for call_idx 1 dir 1 state 'released' flags 8 has channel
[2017-03-05 20:51:36] DEBUG[6574][C-00000001] pbx.c: Spawn extension (ivr-1,s,12) exited non-zero on 'Dongle/dongle0-0100000000'
[2017-03-05 20:51:36] VERBOSE[6574][C-00000001] pbx.c: Spawn extension (ivr-1, s, 12) exited non-zero on 'Dongle/dongle0-0100000000'
[2017-03-05 20:51:36] DEBUG[6574][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'Dongle/dongle0-0100000000'
[2017-03-05 20:51:36] DEBUG[6574][C-00000001] channel.c: Soft-Hanging (0x80) up channel 'Dongle/dongle0-0100000000'
[2017-03-05 20:51:36] DEBUG[6574][C-00000001] pbx.c: Launching 'Hangup'
[2017-03-05 20:51:36] VERBOSE[6574][C-00000001] pbx.c: Executing [h@ivr-1:1] Hangup("Dongle/dongle0-0100000000", "") in new stack
[2017-03-05 20:51:36] DEBUG[6574][C-00000001] channel.c: Soft-Hanging (0x20) up channel 'Dongle/dongle0-0100000000'
[2017-03-05 20:51:36] DEBUG[6574][C-00000001] pbx.c: Spawn extension (ivr-1,h,1) exited non-zero on 'Dongle/dongle0-0100000000'
[2017-03-05 20:51:36] VERBOSE[6574][C-00000001] pbx.c: Spawn extension (ivr-1, h, 1) exited non-zero on 'Dongle/dongle0-0100000000'
[2017-03-05 20:51:36] DEBUG[6574][C-00000001] channel.c: Hanging up channel 'Dongle/dongle0-0100000000'
[2017-03-05 20:51:36] DEBUG[2097] cdr.c: Finalized CDR for Dongle/dongle0-0100000000 - start 1488718274.397800 answer 1488718274.959635 end 1488718296.731090 dispo ANSWERED
[2017-03-05 20:51:36] DEBUG[2044] devicestate.c: No provider found, checking channel drivers for Dongle - dongle0
[2017-03-05 20:51:36] DEBUG[2044] channel.c: Checking device state for device dongle0
[2017-03-05 20:51:36] DEBUG[2212] at_queue.c: [dongle0] remove task with 1 command(s) begin with 'AT' expected response 'OK' from queue
[2017-03-05 20:51:36] DEBUG[2114] res_odbc.c: Reusing ODBC handle 0x3eb1e8 from class 'asteriskcdrdb'
[2017-03-05 20:51:36] DEBUG[2114] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('HANGUP',{ts '2017-03-05 20:51:36.742038'},'01234567','01234567','','','+1234567890','h','ivr-1','Dongle/dongle0-0100000000','','',3,'','1488718274.2','1488718274.2','','','{"hangupcause":16,"hangupsource":"dialplan/builtin","dialstatus":""}')]
[2017-03-05 20:51:36] VERBOSE[2212] chan_dongle.c: [dongle0] Dongle has disconnected
[2017-03-05 20:51:36] DEBUG[2044] devicestate.c: Changing state for Dongle/dongle0 - state 4 (Invalid)
[2017-03-05 20:51:36] DEBUG[2044] devicestate.c: No provider found, checking channel drivers for Dongle - dongle0
[2017-03-05 20:51:36] DEBUG[2044] channel.c: Checking device state for device dongle0
[2017-03-05 20:51:36] DEBUG[2044] devicestate.c: Changing state for Dongle/dongle0 - state 4 (Invalid)
[2017-03-05 20:51:36] DEBUG[2214] app_queue.c: Device 'Dongle/dongle0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[2017-03-05 20:51:36] DEBUG[2114] res_odbc.c: Releasing ODBC handle 0x3eb1e8 into pool
[2017-03-05 20:51:36] DEBUG[2114] res_odbc.c: Reusing ODBC handle 0x3eb1e8 from class 'asteriskcdrdb'
[2017-03-05 20:51:36] DEBUG[2114] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('CHAN_END',{ts '2017-03-05 20:51:36.978853'},'01234567','01234567','','','+1234567890','h','ivr-1','Dongle/dongle0-0100000000','','',3,'','1488718274.2','1488718274.2','','','')]
[2017-03-05 20:51:37] DEBUG[2114] res_odbc.c: Releasing ODBC handle 0x3eb1e8 into pool
[2017-03-05 20:51:37] DEBUG[2114] res_odbc.c: Reusing ODBC handle 0x3eb1e8 from class 'asteriskcdrdb'
[2017-03-05 20:51:37] DEBUG[2114] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('LINKEDID_END',{ts '2017-03-05 20:51:37.28703'},'01234567','01234567','','','+1234567890','h','ivr-1','Dongle/dongle0-0100000000','','',3,'','1488718274.2','1488718274.2','','','')]
[2017-03-05 20:51:37] DEBUG[2114] res_odbc.c: Releasing ODBC handle 0x3eb1e8 into pool
[2017-03-05 20:51:37] DEBUG[2097] res_odbc.c: Reusing ODBC handle 0x3eb1e8 from class 'asteriskcdrdb'
[2017-03-05 20:51:37] DEBUG[2097] cdr_adaptive_odbc.c: Executing [INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid,did) VALUES ({ ts '2017-03-05 20:51:14' },'"01234567" <01234567>','01234567','s','ivr-1','Dongle/dongle0-0100000000','WaitExten','8,',22,21,'ANSWERED',3,'1488718274.2','+1234567890')]
[2017-03-05 20:51:37] DEBUG[2097] res_odbc.c: Releasing ODBC handle 0x3eb1e8 into pool
[2017-03-05 20:51:38] DEBUG[6220][C-00000000] res_rtp_asterisk.c: Got RTCP report of 100 bytes
[2017-03-05 20:51:38] DEBUG[6220][C-00000000] res_rtp_asterisk.c: Unknown RTCP packet (pt=205) received from 192.168.1.16:51371
[2017-03-05 20:51:39] DEBUG[2211] chan_dongle.c: [dongle0] Trying ports discovery for IMEI XXXXXXXXXXXXXX IMSI XXXXXXXXXXXXXX
...

it then keep failing to connect to the dongle even restart the system.

so any idea what's the bug which caused this? I'm using E-180 with firmware version 11.126 it seems I have to set callwaiting=no to avoid this, but what exactly caused this issue, is it possible we figure it out and fix it?

bg111 commented 7 years ago

im not publish chan_dongle for asterisk version > 1.8 but yout log has references to cel. This mean not 1.6 or 1.8 version of asterisk ? If yes better if you ask authors of sources you use.

callwaiting=auto mean do not send set AT+CCWA=?,?,1 command to dongle.

ulion commented 7 years ago

@bg111 it is newest version of raspbx

ulion commented 7 years ago

and the problem is that when the call wait going on or finished, how will the dongle handle it or affected by it, it's simple to test, if you have other or similar device, setup same env callwaiting=auto but sim with call wait enabled, it will display it's disabled but it indeed works. then when the line is busy, call to the sim, wait it until it hang up, the issue will happen.