No notification audio after call with baresip

[gdt]

I am having two problems at once which are perhaps related. This issue is about the broken notification audio.

Test setup is asterisk 16.5 with pjsip and baresip-studio 15.1.1 from f-droid, connecting via TLS and Lineage 15.1. Connection is over LAN (access point and switches, no firewalling). Baresip registers fine, and I can dial a "hello world" extension and hear the message. But the Hangup() does not work and baresip continues to act as if it is in the call. (Calling from a real phone on an FXS port on a SIP adaptor receives hangup and a new dial tone.) I can then push hangup and all seems ok.

After such a call, I have no notification audio, despite the volumes looking ok. Force-quit or regular quit of baresip does not help. The only thing I have found to fix audio is to reboot the phone.

(I know I need to run adb, but I'm posting here partly to see if anyone else is seeing this, absent a mailinglist.)

[juha-h]

If you cannot hangup the call, there most likely is some SIP signaling issue. Get logcat or pcap trace.

I need to check that sound focus is released at Quit.

[gdt]

Me pushing hangup works. It's the hangup from the server that doesn't. An obi hardphone gets hung up fine (which I realize doesn't prove anything). I will get a logcat.

[gdt]

Recently, call hangup (from server) seems to be working normally, at least on an asterisk test call to a hello-world file. However, notification audio still ended up broken.

[juha-h]

Greg Troxel writes:

Recently, call hangup (from server) seems to be working normally, at least on an asterisk test call to a hello-world file. However, notification audio still ended up broken.

Sorry, I don't understand what you mean by "notification audio".

[gdt]

Sorry for being unclear. Let me try to describe again.

My phone has multiple volume controls, for media/playback, for ringing for incoming calls, for alarms, and for notifications. As I understand this is from AOSP and totally normal. Ignoring media and alarms, one can set the volume for ringing for calls separately from the volume for notifications, which includes incoming SMS, Signal, email, and various other things. Without baresip in the picture, this works entirely as I would expect. As an example, incoming email messages in k-9 cause a vibration and a sound.

After I have run baresip, I find that incoming email messages cause vibration only and no sound. Even after exiting or force-killing baresip, I still have no sound on incoming email. So far the only way I have found to get notifications (that should make noise and normally do) to play their sounds is to reboot the phone.

[gdt]

I will try to experiment to find out more precisely is causing this, in terms of just starting baresip and exiting, vs making an outgoing call, vs incoming call.

[juha-h]

In latest baresip version 16.0.0, audio focus is abandoned also when baresip is quit. Normally it is abandoned when call is closed. So this is just a safety measure if something goes wrong.

Try with that version and take 'adb logcat | grep Baresip' if the problem persists. Logcat shows when audio is focused and abandoned.

[gdt]

Thanks for working on this. I updated to 16.0.1 from f-droid, and found some reproduction information.

Setup is baresip on phone, on same wifi lan as asterisk, with a normal asterisk setup including an extension for "hello world" (that says that and hangs up). I find that if I call the hello world number, then notification audio is broken. If I then dial an invalid extension, notification audio returns.

With hello world, I see a "Call closed: Connection reset by peer" toast as the call ends. New mail vibrates but does not sound. I did this again, and hung up before it finished, and got "Call closed: Connection reset by user". Still no sound. I then dialed 3 digits that aren't an extension (and aren't a PSTN number) and got "Call failed: 484 Address incomplete". Then, new mail got a notification. This seems repeatable.

Dialing hello world to provoke failure, and exiting via "3dot Quit", no notification sound. Restarting, and dialing an invalid extension, then notification sound returned.

On to logcat in a separate comment.

[gdt]

I made a call to hello world, and then to invalid extension. This is the lines that say Baresip and audio, with addresses blinded. I see three start calls in the troubled case, and one destroy with started=1. In the call that fixes things, I see no start calls and a destroy with started=0.

02-17 20:03:52.006 25499 25522 D Baresip Lib: stream: update 'audio'
02-17 20:03:52.006 25499 25522 D Baresip Lib: stream: audio: starting RTCP with remote ASTERISK:10649
02-17 20:03:52.007 25499 25522 D Baresip Lib: audio: Set audio decoder: G722 16000Hz 1ch
02-17 20:03:52.007 25499 25522 D Baresip Lib: audio: start
02-17 20:03:52.007 25499 25522 D Baresip Lib: audio: create recv buffer [20 - 160 ms] [640 - 5120 bytes]
02-17 20:03:52.040 25499 25522 D Baresip Lib: audio: player started with sample format S16LE
02-17 20:03:52.040 25499 25522 D Baresip Lib: audio: Set audio encoder: G722 16000Hz 1ch
02-17 20:03:52.040 25499 25522 D Baresip Lib: audio: start
02-17 20:03:52.163 25499 25522 D Baresip Lib: audio: source started with sample format S16LE
02-17 20:03:52.163 25499 25522 D Baresip Lib: audio tx pipeline:    opensles ---> webrtc_aec ---> G722
02-17 20:03:52.163 25499 25522 D Baresip Lib: audio rx pipeline:    o
02-17 20:03:52.163 25499 25522 D Baresip Lib: audio: start
02-17 20:03:53.251 25499 25521 D Baresip Lib: ua event (CALL_RTPESTAB) audio
02-17 20:03:53.252 25499 25522 D Baresip Lib: stream: incoming rtp for 'audio' established, receiving from ASTERISKLAN:10648
02-17 20:03:55.780 25499 25522 D Baresip Lib: audio: destroyed (started=1)

02-17 20:05:51.981 25499 25522 D Baresip Lib: audio: destroyed (started=0)

[juha-h]

Greg Troxel writes:

I made a call to hello world, and then to invalid extension. This is the lines that say Baresip and audio, with addresses blinded. I see three start calls in the troubled case, and one destroy with started=1. In the call that fixes things, I see no start calls and a destroy with started=0.

Thanks for debugging. Could you show also the earlier debug lines from the time you placed the call?

[gdt]

(BTW, looks like call established log line is split into two.)

HWE: hello world extension
USER: user portion of AOR (which is USER@asterisk.example.com)
PORT: port number for sip/TLS

LADDR: phone's addr on lan
ASTWAN: asterisk public IP
ATLAN: asterisk LAN IP (same subnet as LADDR)

02-17 20:03:51.855 25499 25499 D Baresip Lib: connecting ua 505072890640 to sip:HWE@asterisk.example.com:PORT
02-17 20:03:51.856 25499 25522 D Baresip Lib: ua: using best effort AF: af=AF_INET
02-17 20:03:51.857 25499 25522 D Baresip Lib: call: alloc with params laddr=LADDR, af=AF_INET, use_rtp=1
02-17 20:03:51.859 25499 25522 D Baresip Lib: call: use_video=0
02-17 20:03:51.859 25499 25522 D Baresip Lib: call: connecting to 'sip:HWE@asterisk.example.com:PORT'..
02-17 20:03:52.000 25499 25522 D Baresip Lib: call: SIP Progress: 100 Trying (/)
02-17 20:03:52.006 25499 25522 D Baresip Lib: call: got SDP answer (241 bytes)
02-17 20:03:52.006 25499 25522 D Baresip Lib: call: update media
02-17 20:03:52.006 25499 25522 D Baresip Lib: stream: update 'audio'
02-17 20:03:52.006 25499 25522 D Baresip Lib: stream: audio: starting RTCP with remote ASTWAN:10649
02-17 20:03:52.007 25499 25522 D Baresip Lib: audio: Set audio decoder: G722 16000Hz 1ch
02-17 20:03:52.007 25499 25522 D Baresip Lib: audio: start
02-17 20:03:52.007 25499 25522 D Baresip Lib: audio: create recv buffer [20 - 160 ms] [640 - 5120 bytes]
02-17 20:03:52.007 25499 25522 D Baresip Lib: opensles: opening player 16000Hz, 1channels
02-17 20:03:52.040 25499 25522 D Baresip Lib: audio: player started with sample format S16LE
02-17 20:03:52.040 25499 25522 D Baresip Lib: audio: Set audio encoder: G722 16000Hz 1ch
02-17 20:03:52.040 25499 25522 D Baresip Lib: audio: start
02-17 20:03:52.040 25499 25522 D Baresip Lib: webrtc_aec: creating shared state: [16000 Hz, 1 channels, subframe 160 samples, num_bands 1]
02-17 20:03:52.045 25499 25522 D Baresip Lib: opensles: opening recorder 16000Hz, 1channels
02-17 20:03:52.163 25499 25521 D Baresip Lib: ua event (CALL_ESTABLISHED) sip:HWE@asterisk.example.com:PORT
02-17 20:03:52.163 25499 25521 D Baresip Lib: sending ua/call 505072890640/505494916752 event call established
02-17 20:03:52.163 25499 25522 D Baresip Lib: audio: source started with sample format S16LE
02-17 20:03:52.163 25499 25522 D Baresip Lib: audio tx pipeline:    opensles ---> webrtc_aec ---> G722
02-17 20:03:52.163 25499 25522 D Baresip Lib: audio rx pipeline:    o
02-17 20:03:52.163 25499 25522 D Baresip Lib: pensles <--- webrtc_aec <--- G722
02-17 20:03:52.163 25499 25522 D Baresip Lib: call: stream start (active=1)
02-17 20:03:52.163 25499 25522 D Baresip Lib: audio: start
02-17 20:03:52.163 25499 25522 D Baresip Lib: USER@asterisk.example.com: Call established: sip:HWE
02-17 20:03:52.163 25499 25522 D Baresip Lib: @asterisk.example.com:PORT
02-17 20:03:53.251 25499 25521 D Baresip Lib: ua event (CALL_RTPESTAB) audio
02-17 20:03:53.252 25499 25522 D Baresip Lib: stream: incoming rtp for 'audio' established, receiving from ASTLAN:10648
02-17 20:03:55.671 25499 25522 D Baresip Lib: sip:HWE@asterisk.example.com:PORT: session closed: Connection reset by peer
02-17 20:03:55.769 25499 25521 D Baresip Lib: ua event (CALL_CLOSED) Connection reset by peer
02-17 20:03:55.769 25499 25521 D Baresip Lib: sending ua/call 505072890640/505494916752 event call closed,Connection reset by peer
02-17 20:03:55.779 25499 25522 D Baresip Lib: sip:USER@asterisk.example.com:PORT: Call with sip:HWE@asterisk.example.com:PORT terminated (duration: 3 secs)
02-17 20:03:55.780 25499 25522 D Baresip Lib: audio: destroyed (started=1)

[gdt]

call that restores:

BADE: some extension that asterisk rejects, e.g. HWE+1

02-17 20:05:51.444 25499 25499 D Baresip Lib: connecting ua 505072890640 to sip:BADE@asterisk.example.com:PORT
02-17 20:05:51.445 25499 25522 D Baresip Lib: ua: using best effort AF: af=AF_INET
02-17 20:05:51.445 25499 25522 D Baresip Lib: call: alloc with params laddr=LADDR, af=AF_INET, use_rtp=1
02-17 20:05:51.447 25499 25522 D Baresip Lib: call: use_video=0
02-17 20:05:51.447 25499 25522 D Baresip Lib: call: connecting to 'sip:BADE@asterisk.example.com:PORT'..
02-17 20:05:51.603 25499 25522 D Baresip Lib: sip:BADE@asterisk.example.com:PORT: session closed: 484 Address Incomplete
02-17 20:05:51.603 25499 25521 D Baresip Lib: ua event (CALL_CLOSED) 484 Address Incomplete
02-17 20:05:51.603 25499 25522 D Baresip Lib: opensles: opening player 8000Hz, 1channels
02-17 20:05:51.649 25499 25521 D Baresip Lib: sending ua/call 505072890640/505494917200 event call closed,484 Address Incomplete
02-17 20:05:51.981 25499 25522 D Baresip Lib: audio: destroyed (started=0)
02-17 20:05:54.655 25499 25522 D Baresip Lib: play: player complete.

[juha-h]

Sorry that I didn't notice earlier, but could you include all Baresip logcat messages, not just those from Baresip Lib.

On Linux

adb logcat | grep Baresip

Those from Baresip Service would show when audio was focused and focus released.

[juha-h]

Greg Troxel writes:

Setup is baresip on phone, on same wifi lan as asterisk, with a normal asterisk setup including an extension for "hello world" (that says that and hangs up). I find that if I call the hello world number, then notification audio is broken. If I then dial an invalid extension, notification audio returns.

Can you check from SIP packet trace if Asterisk uses early media (18x response) to play "hello world" or it is responding with 200?

[gdt]

I was only grepping for Baresip, but maybe need to check some debug flag in settings. Hard to check SIP inside TLS, but maybe I can reconfigure for a test.

[gdt]

I agree my trace above sort of looks like early media, but my dialplan uses Answer and not Progress, so the docs say I am not doing early media. I'll look more.

[juha-h]

Notifications should now be enabled after a call in 17.0.0. For some reason, Android does not like if audio mode is set more than once to the same value. Reopen if still an issue.

[gdt]

I will reopen if still a problem, but would like to point out that f-droid is still at 16.0.1

[juha-h]

Greg Troxel writes:

I will reopen if still a problem, but would like to point out that f-droid is still at 16.0.1

I know. There is some issue with f-droid app generation that affects many apps that use native code. I'm sure that they are working on it.