Stuck dongle/asterisk with Ast >= 12 and/or jitterbuffer

[vitasgul]

Stuck asterisk occurs when resetting answered
call by the called party.
It helps only restart Ubuntu.
I tried with Asterisk 13 and 14 versions.
The problem does not occur every time a chance. Approximately 30 percent of the cases it is when the called party answers, and then end the call.

crash_log1.txt
crash_log2.txt
crash_log3.txt
crash_log4.txt
crash_log5.txt

[wdoekes]

Thanks for the report. Note that I do not run this software, nor do I own a dongle. So I can be of limited help in fixing this.

If you come up with a fix, I'll be happy to review and merge.

[multijohn]

Hello
I too have the same problem with versions 13.14 and 14.3 of the asterisk
in ubuntu 16! But I had no problem with ubuntu 14.04 and asterisk 13.07!
I do not know where to begin!
I tried the dongle and on usb2 port, but nothing! (It Was on usb3).
in which versions of ubuntu and the asterisk do you have these problems?
Is there any solution?
Thank u!

[multijohn]

Well,
I have reproduced the problem several times, It happens when the other party hangs up first!
Doing "fwconsole restart" gives "Asterisk is still running and we can't stop it!" .
Only restart the OS (ubuntu 16.04) fix the situation until the next time!
Thank u!

[multijohn]

Well,
In my case , the solution was in dongle.conf!
I had enable everything about jitter buffer, and that was the problem!
Now that i restored the settings of jitter buffer to their defaults in dongle.conf, chan_dongle works good again!
Thank u!

[wdoekes]

Awesome, glad you got that sorted.

[garronej]

Hello,

First @wdoekes thank you so mutch for your work, this fork mater to me a great deal.

Regarding the issue here, indeed disableing the jitter buffer solve the problem but this is not an acceptable solution as the jbuffer improve significantly the quality of the calls, without it, in my experience it is hardly possible to have a conversation because of frame drops.

I have made several tests:
-With asterisk 11.6 and 11.22 the bug does NOT appear.
-With asterisk 12, 13.8, 14.4 the bug appear all the time.

It's realy a shame because pjproject was introduced on version 12...

In my senario:

1. Someone call the SIM inside the dongle,
2. Asterisk dial SIP/alice
3. Communication is established.
4. The caller hang up.
5. *if asterisk version >= 12 and jitter buffer is enabled ----> crash
   *else ---> call ends without issues

Senario with asterisk 11.6, jitter buffer enabled ( SUCCESS ):

ast11.6_jbuffer_enabled_SUCCESS.txt

Senario with asterisk 12, jitter buffer disabled ( SUCCESS ):

ast12-jbuffer_disabled_SUCCESS.txt

Senario with asterisk 12, jitter buffer enabled ( ERROR ):

ast12_jbuffer_enabled_FAIL.txt

I expect the relevent information to be after the AT message ^CEND ( Call end indication )...

If this issue could be solved it would be realy amaysing.

Regards

[multijohn]

Hello,
I have enabled jbuffer, from asterisk side, in sip settings and i thing it work's on all channels!
Please tell me if i am wrong!

Thank u!

[garronej]

Hi @multijhon

Interesting...

My attempt to enable the jbuffer on Asterisk's side where unsuccessfull on Asterisk 11. I was still facing severe frame drop so I just assumed it did not work this way without futher investigation.

Maybe it does work in newer version of Asterisk or maybe I have messed up in the configuration.

Are you using chan_pjsip or chan_sip ?

I will do some more testing but could you show me how you configured sip.conf ( or pjsip.conf )
regarding to jitter buffer so I am shure I do things wright.

Regards

[multijohn]

Hi again,
I am using chan_sip !

Thanks

[garronej]

Okay thanks,

What version of asterisk are you using?
Can you provide me with your sip.conf file ( the part where you configured jitter buffer ) so I can be shure we are on the same page.

Regars

[wdoekes]

In the success case, I see this:

[Apr  8 20:12:15] DEBUG[26401][C-00000000]: channel.c:4873 ast_prod: Prodding channel 'Dongle/Dongle358586-0100000000'
[Apr  8 20:12:16] DEBUG[26388]: at_read.c:80 at_read: [Dongle358586] receive 11 byte, used 11, free 2037, read 0, write 11
[Apr  8 20:12:16] DEBUG[26388]: at_read.c:95 at_read: [Dongle358586] [
^RSSI:2
]

And in the failure case, there is a BOOT command before the CEND instead.

Not sure if that helps any. I can't tell much more from your logs though.

[garronej]

Hi @wdoekes, thanks for having a look.

Yeah ^BOOT and ^RSSI are not relevant here, they are AT unsolicited results codes ( URC ) that the modem send unpredictably, it's normal if they don't appear exacty at the same points in every logs...

What we can see from the log is that when chan_dongle receive ^CEND from the Dongle ( URC that indicate that the call have been hung up ) in the success case it proccess the information:

at_read.c:95 at_read: [Dongle358586] [
^CEND:1,5,104,16
]
at_response.c:739 at_response_cend: [Dongle358586] CEND: call_index 1 duration 5 end_status 104 cc_cause 16 Line disconnected

But in the failure case chan dongle dongle does not show sign of life after receving ^CEND.

As I understood, you don't run the software yourself and you don't even have a device so it gona be hard for you to fix that I assume...

Anyway I am already extremely grateful for your work, everything works fine until asterisk 11 so it's allright :)

Cheers

[wdoekes]

You could try to get thread/locking info from Asterisk, either through:

• gdb; when it's hung, you can do thread apply all bt and thread apply all bt full
• from Asterisk if you compile with lock debugging (DEBUG_THREADS) enabled (core show locks)
• by adding lots more ast_debug() along the route to the problem

I would guess the problem takes this route and gets stuck somewhere along the way.

(As you say, the first ast_debug is seen, the second one isn't.)

chan_dongle.c: do_monitor_phone():
  ...
  at_read()
  at_read_result_iov()
  at_read_result_classification()
  at_response()

at_read.c: at_read()
  ...
  ast_debug (5, "[%s] receive %zu byte, used %zu, free %zu, read %zu, write %zu\n",

at_response.c: at_response()
  const struct at_queue_cmd* ecmd = at_queue_head_cmd(pvt);
  ...
  at_response_cend(pvt, str)

at_response.c: at_response_cend()
  request_clcc(pvt) --> at_enque_clcc()

at_command.c: at_enque_clcc()
  at_queue_insert_const(... CMD_AT_CLCC ...)

at_queue.c: at_queue_insert_const()
  at_queue_add(cpvt, cmds, cmdsno, athead) == NULL || at_queue_run(cpvt->pvt)

at_queue.c: at_queue_add()
  ...
  ast_debug (4, "[%s] insert task with %u commands begin with '%s' expected response '%s' %s of queue\n",

[garronej]

Hello @wdoekes and thank you for your reply!

Sorry I did not found the time to perform the log earlyer but here it is:

ast12_jbuffer_enabled_FAIL_core_show_lock.txt

I chose the method where I compile asterisk with DEBUG_THREADS.
Same senario as before, asterisk 12, fail with jiter buffer.

I hope I dit the log right,
It is extremely verbose as I set the debug level at 29 "core set debug 29".

Thank you for your time :)

Regards

[wdoekes]

The log looks useful. Apparently ast_read calls channel_read, and the channel and the pvt->lock are both locked.

=== Thread ID: 0x6f6f3430 (do_monitor_phone     started at [  491] chan_dongle.c start_monitor())
=== ---> Waiting for Lock #0 (chan_dongle.c): MUTEX 460 do_monitor_phone &pvt->lock 0x75e0f27c (1)
=== --- ---> Locked Here: channel.c line 653 (channel_read)
=== -------------------------------------------------------------------
===
=== Thread ID: 0x6f72f430 (pbx_thread           started at [ 6656] pbx.c ast_pbx_start())
=== ---> Lock #0 (channel.c): MUTEX 3789 __ast_read chan 0x7630bca8 (1)
=== ---> Lock #1 (channel.c): MUTEX 653 channel_read &pvt->lock 0x75e0f27c (1)

My best guess from that debug log would be that we're waiting for read().

What happens to the log if you add this?

--- a/channel.c
+++ b/channel.c
@@ -686,7 +686,9 @@ static struct ast_frame* channel_read (struct ast_channel* channel)
                cpvt->a_read_frame.offset = AST_FRIENDLY_OFFSET;
                cpvt->a_read_frame.src = AST_MODULE;
 
+               ast_debug(1, "Before read: %d, %d, %d\n", CPVT_IS_MASTER(cpvt), pvt->audio_fd, cpvt->rd_pipe[PIPE_READ]);
                res = read (CPVT_IS_MASTER(cpvt) ? pvt->audio_fd : cpvt->rd_pipe[PIPE_READ], cpvt->a_read_frame.data.ptr, FRAME_SIZE);
+               ast_debug(1, "After read: %zd\n", res);
                if (res <= 0)
                {
                        if (errno != EAGAIN && errno != EINTR)

I'd be interested in the log lines surrounding "*** Phone hangup ***" again, and especially whether it stalls at "Before read" and doesn't go past "After read". And whether the CPVT_IS_MASTER(cpvt) value changes, causing the read to read on the wrong pipe.

If the read() isn't the cause of the lock, then attaching gdb to asterisk and getting a 'thread apply all bt' would help.

[garronej]

Apparently you had the right guess ! 👍 :)

ast12_jbuffer_enabled_FAIL_core_show_lock_with_trace_around_read.txt

[wdoekes]

Okay. Try this then:

diff --git a/chan_dongle.c b/chan_dongle.c
index 29a13cd..401049c 100644
--- a/chan_dongle.c
+++ b/chan_dongle.c
@@ -601,6 +601,13 @@ static void pvt_start(struct pvt * pvt)
 			pvt->audio_fd = opentty(PVT_STATE(pvt, audio_tty), &pvt->alock);
 			if (pvt->audio_fd >= 0)
 			{
+				/* Set data_fd and audio_fd to non-blocking */
+				long flags;
+				flags = fcntl(pvt->data_fd, F_GETFL);
+				fcntl(pvt->data_fd, F_SETFL, flags | O_NONBLOCK);
+				flags = fcntl(pvt->audio_fd, F_GETFL);
+				fcntl(pvt->audio_fd, F_SETFL, flags | O_NONBLOCK);
+
 				if (start_monitor (pvt))
 				{
 					pvt->connected = 1;

[garronej]

Everything work fine with the jbuffer enabled now 😃

I will update you if I run across any issue related to this fix but as far as I can see the problem seems to be solved!

@wdoekes You are a great dude thank you verry mutch!

Cheers