asterisk hang if call rejected

[mpmc]

Interesting one. If a call comes in as "BUSY" A.K.A REJECTED, the module will hang asterisk & it'll need to be force killed. Going from the asterisk logs it appears to try and answer the call anyway.

[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: dsp.c:745 dtmf_detect: DTMF best '1' Erow=0.0000E+00 Ecol=0.0000E+00 Erc=0.0000E+00 Et=0.0000E+00
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:934 channel_write: [quectel0] write call idx 2 state 2
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:691 channel_read: [quectel0] read call idx 2 state 2 audio_fd 27
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:629 timing_write: [quectel0] write silence
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:705 channel_read: [quectel0] *** timing ***
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:691 channel_read: [quectel0] read call idx 2 state 2 audio_fd 27
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: dsp.c:745 dtmf_detect: DTMF best '1' Erow=0.0000E+00 Ecol=0.0000E+00 Erc=0.0000E+00 Et=0.0000E+00
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: dsp.c:745 dtmf_detect: DTMF best '1' Erow=0.0000E+00 Ecol=0.0000E+00 Erc=0.0000E+00 Et=0.0000E+00
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:934 channel_write: [quectel0] write call idx 2 state 2
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:691 channel_read: [quectel0] read call idx 2 state 2 audio_fd 27
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:629 timing_write: [quectel0] write silence
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:705 channel_read: [quectel0] *** timing ***
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:691 channel_read: [quectel0] read call idx 2 state 2 audio_fd 27
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: dsp.c:745 dtmf_detect: DTMF best '1' Erow=0.0000E+00 Ecol=0.0000E+00 Erc=0.0000E+00 Et=0.0000E+00
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:934 channel_write: [quectel0] write call idx 2 state 2
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:691 channel_read: [quectel0] read call idx 2 state 2 audio_fd 27
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:629 timing_write: [quectel0] write silence
[2022-03-05 23:39:07] DEBUG[53295][C-00000003]: channel.c:705 channel_read: [quectel0] *** timing ***

I suspect I must be missing something in the incoming context?

[incoming-mobile]
exten => sms,1,Verbose(Incoming SMS from ${CALLERID(num)} ${BASE64_DECODE(${SMS_BASE64})})
exten => sms,n,Set(FILE(/tmp/sms.txt,,,a)=${STRFTIME(${EPOCH},,%Y-%m-%d %H:%M:%S)} - ${CALLERID(num)}: ${BASE64_DECODE(${SMS_BASE64})})
exten => sms,n,System(echo >> /tmp/sms.txt)
exten => sms,n,Wait(3)
exten => sms,n,Hangup()

exten => _.,1,Set(CALLERID(name)=${CALLERID(num)})
exten => _.,n,Gosub(from-trunk,${EXTEN},1)
exten => _.,n,Wait(3)
exten => _.,n,Hangup()

[grelasroberto]

Not sure if its related, but I having a similar situation handling outbound international call, delays more to connect than local ones...

[Mar 6 12:22:25] DEBUG[26312]: at_read.c:80 at_read: [quectel0] receive 46 byte, used 46, free 2002, read 0, write 46
[Mar 6 12:22:25] DEBUG[26312]: at_read.c:95 at_read: [quectel0] [
+CLCC: 1,0,2,0,0,"+",145

OK
]
[Mar 6 12:22:25] DEBUG[26312]: at_response.c:1156 at_response_clcc: [quectel0] CLCC callidx 1 dir 0 state 2 mode 0 mpty 0 number +584241474689 type 145
[Mar 6 12:22:25] DEBUG[26312]: at_response.c:225 at_response_ok: [quectel0] AT+CLCC sent successfully
[Mar 6 12:22:25] DEBUG[26312]: at_queue.c:221 at_queue_remove_cmd: [quectel0] remove command 'AT+CLCC' expected response 'OK' real 'OK' cmd 3/3 flags 0x01 from queue
[Mar 6 12:22:25] DEBUG[26312]: at_queue.c:69 at_queue_remove: [quectel0] remove task with 3 command(s) begin with 'AT+CLIR' expected response 'OK' from queue
[Mar 6 12:22:25] DEBUG[26312]: at_queue.c:246 at_queue_run: [quectel0] write command 'AT+CLCC' expected response 'OK' length 8
]Mar 6 12:22:25] DEBUG[26312]: at_queue.c:191 at_write: [quectel0] [AT+CLCC
[Mar 6 12:22:25] DEBUG[26596][C-00000000]: channel.c:691 channel_read: [quectel0] read call idx 1 state 2 audio_fd 26
[Mar 6 12:22:25] DEBUG[26312]: at_read.c:80 at_read: [quectel0] receive 46 byte, used 46, free 2002, read 0, write 46
[Mar 6 12:22:25] DEBUG[26312]: at_read.c:95 at_read: [quectel0] [
+CLCC: 1,0,2,0,0,"+,145

OK
]

That was the last log before module halted and I had to restart asterisk.

[mpmc]

I managed to fix the hang on BUSY by simulating call end like @IchthysMaranatha added for NO_CARRIER. and it no longer crashes.

@IchthysMaranatha I dunno if you want to cherry pick it and add it to your master or add a better fix (I'm sure there is one!) https://github.com/mpmc/asterisk-chan-quectel/commits/master

[IchthysMaranatha]

I did not understand the scenario. Do you get BUSY message on minicom? If I get a call that is cut by sender I get a 'missed_call' message for which I've added call handling. If I dial a call that is rejected it ends in 'no carrier' for which also I've added call handling. I do not ever receive a busy message.
Main problem is simcom has no call termination with dsci and everything has to be manually handled. Finding all possible means of identifying termination without double termination was a big headache.

[IchthysMaranatha]

Please do check with this when free 9d35852

[IchthysMaranatha]

Please do check and let me know, as I cannot check this myself. Thanks.

[mpmc]

@IchthysMaranatha pulled latest master.

• Things have gone back toopentty: unable to open /dev/ttyUSB4: Device or resource busy regardless of if the call is answered or busy. This can be ignored though as it's the exclusive lock issue with systemd and the "hack" I did on my branch isn't in yours. - If you can call commenting out a few lines a hack, heh, look at me, I'm super hacker now /s ;)
• minicom output shows just BUSY not followed by NO_CARRIER so the module is stuck until asterisk is restarted. Interestingly I'll randomly get both or just one. UK providers are weird!!

[IchthysMaranatha]

Thanks for the update. I'll put in your fix then for busy, That one works right, for all scenarios - with and without 'no carrier' ? Without any problems in subsequent calls?
With AT$QCRCIND=1 do you get remote call end every time even for rejection? And do you get the message once or twice like me?

[mpmc]

Thanks for the update. I'll put in your fix then for busy, That one works right, for all scenarios - with and without 'no carrier' ? Without any problems in subsequent calls?

Yes, on master, it works as expected when using the non-root exclusive lock bypass mentioned.

With AT$QCRCIND=1 do you get remote call end every time even for rejection? And do you get the message once or twice like me?

I haven't tried this, I'll have to investigate.

[gerwsx]

When checking the latest diffs I'm wondering if it was intentional to remove the line: "at_response_busy(pvt, AST_CONTROL_BUSY);" for all devices?

 
                        case RES_BUSY:
                                ast_log (LOG_ERROR, "[%s] Receive BUSY\n", PVT_ID(pvt));
-                               at_response_busy(pvt, AST_CONTROL_BUSY);
+                               if (pvt->is_simcom) {
+                                       request_clcc(pvt);
+
+                                       if (pvt->dialing) {
+                                       
+                                               char str2[20]="VOICE CALL: END: 0";
+                                               at_response_cend (pvt, str2);
                                                break;
+                                                           }
+                                                      }
+
+                               return 0;
 
                        case RES_NO_DIALTONE:
                                ast_log (LOG_ERROR, "[%s] Receive NO DIALTONE\n", PVT_ID(pvt));

[IchthysMaranatha]

Yes, the change was deliberate as I thought that quectel will have dsci urc for both call initiation and termination, whereas Huawei may not have a cend when busy. Again this is just my assumption as I do not receive the 'busy' urc to test it out myself. Do you get the busy urc on a quectel? If you do not face issues with the way it was earlier, I'll roll back the change for quectel.

I'm also thinking about changing call termination method for simcom, if someone is willing to run some tests with minicom, please update in this thread.