[Touch] Incoming call gets silent randomly

Status changed to 'Confirmed' because the bug affects multiple users.

@Anupam: please collect the media-hub log: /home/phablet/.cache/upstart/media-hub.log

Here is the latest log. I got a call on 2016-08-31 at around 06:31 UTC, there was no ringtone (TBH it rang for a fraction of a second and stopped abruptly. I had the phone just in front of me, so I could observe this behaviour. Otherwise I couldn't possibly have realised this.). Got another at around 06:46 UTC, this time rang fine.

The log does show that on the first call the playback started and then paused within less than a few tenths of a second but did not stop for 6 seconds. The second call did not pause for 5 seconds and then immediately stopped. Presumably the status went to stopped when the call was answered.

[II 2016-08-31 06:31:04.883664] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::playing
[II 2016-08-31 06:31:05.032598] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::paused
[II 2016-08-31 06:31:05.038372] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::paused
[II 2016-08-31 06:31:05.059649] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::paused
[II 2016-08-31 06:31:11.386511] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::paused
[II 2016-08-31 06:31:11.398468] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::stopped

Does this indicate there are multiple threads running that should not? Many of the log messages are repeated in seemingly random ways. For example the second call reported this three times in a few 100ths, whereas normally its once. I see the same in my logs.

[II 2016-08-31 06:46:24.320900] [engine.cpp:442@play] Engine: playing uri: file:///home/phablet/.local/share/ubuntu-system-settings/Music/Auld%20Lang%20Syne.ogg
[II 2016-08-31 06:46:24.341765] [engine.cpp:442@play] Engine: playing uri: file:///home/phablet/.local/share/ubuntu-system-settings/Music/Auld%20Lang%20Syne.ogg
[II 2016-08-31 06:46:24.356592] [engine.cpp:442@play] Engine: playing uri: file:///home/phablet/.local/share/ubuntu-system-settings/Music/Auld%20Lang%20Syne.ogg

@Pat yes, you're right. I answered the first call after 5-6 seconds. In case of the second one, the caller aborted the call after 5-6 seconds.

@Pat: that doesn't look right. For a normal case, you should only see one Engine: playing uri: ...

Normal output should look like this:

[II 2016-09-01 12:58:26.995539] [engine.cpp:73@on_playbin_state_changed] State changed on playbin: READY
[II 2016-09-01 12:58:26.995731] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::ready
PulseAudio event for sink with index 0 received.
[II 2016-09-01 12:58:27.032896] [pulse_audio_output_observer.cpp:323@on_query_for_primary_sink_finished] Checking if port is available -> 0
PulseAudio sink details for sink.primary with index 0 is available:
  Output to wired headphone: false
  Output to wired headset: false
[DD 2016-09-01 12:58:27.199917] [track_list_skeleton.cpp:702@current_iterator] Wrapping d->current_track back to begin()
[DD 2016-09-01 12:58:27.201450] [player_implementation.cpp:129@operator()] Setting state for parent: 0xec838214
[II 2016-09-01 12:58:27.202742] [player_implementation.cpp:158@operator()] Requesting power state
[II 2016-09-01 12:58:27.203175] [engine.cpp:73@on_playbin_state_changed] State changed on playbin: PAUSED
[TT 2016-09-01 12:58:27.203987] [player_implementation.cpp:200@request_power_state]
[II 2016-09-01 12:58:27.204181] [player_implementation.cpp:216@request_power_state] Requesting new system wakelock.
[TT 2016-09-01 12:58:27.204319] [state_controller.cpp:210@request_acquire]
[II 2016-09-01 12:58:27.204794] [player_implementation.cpp:218@request_power_state] Requested new system wakelock.
[II 2016-09-01 12:58:27.204041] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::paused
[II 2016-09-01 12:58:27.207937] [engine.cpp:73@on_playbin_state_changed] State changed on playbin: PLAYING
[II 2016-09-01 12:58:27.208175] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::playing
[II 2016-09-01 12:58:27.210584] [player_implementation.cpp:94@operator()] Acquired new system state: SystemState::active
[II 2016-09-01 12:58:27.207938] [engine.cpp:455@play] Engine: playing uri: file:///usr/share/sounds/ubuntu/ringtones/Ubuntu.ogg
[II 2016-09-01 12:58:27.216218] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::playing

Experienced this once again after OTA-13. This is turning into a very annoying issue, certainly worse than bug #1544477. I don't usually get many incoming calls, but need to pick up the ones I get as most of them are important/urgent.

@Pat @Jim Does it have to do with the fact that I use a custom ringtone? If so, I can switch to a system ringtone.

My guess is its not the ringtone. Based on the log and the symptom that sometimes you hear the ring briefly and it stops, I am assuming some scenario where multiple threads are running and there is a race condition as to whether you hear the ringtone or not. How that condition arises is unknown.

@Anupam: sorry to hear that you're still experiencing this issue. It's been a difficult one to pin down indeed. I've yet to reproduce the same symptoms that you're experiencing. That being said, if you can continue to try and notice much more precise times that it occurs and document those here, that will greatly help in us being able to reproduce this issue and come up with a confident fix.

I've noticed same issue on BQ E5 on OTA-12 and OTA-13. Sometimes incomming call gets silent after a split second (I can hear a blip of sound).

Attaching syslog and unity8.log of that exact minute it happened. There are no lines in media-hub log.

Experienced once again on September 27 at around 10:48.

Got two calls within ~1 minute on September 28 at around 10:55 UTC. First one didn't ring, second one rang.

Anupam: your last 3 comments have been the start of some useful information. Thanks for observing more closely and providing the logs along with time reference to look at the logs. Very helpful, thanks.

Once more on September 29, at around 11:43 UTC.

Another one on September 29, at around 14:39 UTC

I experinced this too. I had a call at 2016-09-29 16:27

I experienced once again on September 29, at around 15:00 hrs, but unfortunately forgot to save a copy of the log before a reboot.

P.S. Worse part is when I tried to activate vibration on incoming calls so that I don't miss any of those, I hit an issue: bug #1628042.

@jim afaict this change to fix the deadlock made it into ota12 at the final hour
http://bazaar.launchpad.net/~phablet-team/media-hub/trunk/revision/198
at least ota12 has media-hub version 4.2.0+15.04.20160704-0ubuntu1
Would be worth reviewing it again to see if it could have triggered this symptom.

@Pat: I was looking into this a bit more the other day, reading the attached logs. This no longer seems like a media-hub issue and instead seems more like an issue at one of the higher software layers. If you look at the time in the media-hub logs where Anupam has stated it happened to him, you'll see media-hub try to play the ringtone and then in less than 1 second it pauses it. It won't pause it itself so that means it's most likely a bug at the controlling layer above the media stack.

Excuse this naive comment, but if I'm not mistaken, while the phone rings on an incoming call, pressing the power button pauses the ringtone. Is it possible that the same/similar action is simulated here even when the user is not pressing the power button?

@anupam thats an interesting theory, I got a log of when the power button is pressed and it goes from paused to stopped almost instantly, whereas your logs generally show a delay and stopped is only issued once the call is answered.

@jim I still thinks its a thread issue in media hub, I can't get by the fact that its logging engine playing uri multiple times on each incoming call and logging paused multiple times. Perhaps thats benign but unclear to me why the same code is executed more than once "sometimes".

Today I decided to ignore a phone call from one person. She tried her luck several times(i think something like6-8 times). Every second or every third call came without a ringing sound, screen awoke and the phone vibrated but stayed mute. Here a log from a media-hub:

http://paste.ubuntu.com/23292258/

I do not know if it has anything in common the bug about sms notification is still valid for me:
https://bugs.launchpad.net/ubuntu/+source/pulseaudio/+bug/1544477

current built number:35
krillin
channel: ubuntu-touch/stable/bq-aquaris.en
last update: 20.09.2016
version version 35
version ubuntu 20160913
tag:OTA-13
version device: 20160606-ab415b2
version custom: 20160831-991-38-18
---------------------------------------------------

@pat: have added this to the backlog of things to investigate. Will see if it's possible to reliably reproduce this issue and identify the root cause.

I can confirm this occurs on Meizu Pro 5 with OTA-13 as well.

This affects me too on my E5. When it happens not only the ring of the call is muted but all application can't play sounds trough the bigger speaker.
Please we must find a fix. I notice this since ota 11.

Can someone tell me which app manages all sounds and speakers? Is it media-hub?

@Andrea: media-hub manages the playback state of nearly all playback sessions on Ubuntu Touch. It utilizes pulseaudio for the sound server. Any sounds coming from the web browser or web apps do not use media-hub. Ringtone and notification sounds all go through media-hub for playback.

Thanks.. I'll see if i can understand what happens..

I can reproduce this bug often when i want to use viva-voce during a call.. Suddently the bigger speaker stops playing any sound and this can last hours.

This part from the description of bug #1642635 sounds interesting:
"It seems to me that this is most likely to happen if I haven't used the phone in a while. If I answer the call (because I notice the screen) or make a call, testing immediately after the phone does seem to consistently ring."

I experienced the same. Once I couldn't pick up the call because of no ringtone. Then I called the same person after ~5 minutes and asked them to call me back in an attempt to reproduce the issue. They called after ~5 minutes, but that time the ringer worked fine. Also as I mentioned in comment #18, I got two calls within ~1 minute. First one didn't ring, but the second one rang.

I can reproduce this fairly reliably (~50%) if my phone hasn't been used in a while. Enough that I've caught a video of it doing it. media-hub.log attached.

If I unlock the phone and go into the sound settings (from the sound indicator), then turn the screen off, then the phone reliably doesn't fail a second time.

I believe there's some race associated with slow I/O. Perhaps it happens if relevant code paths need to be swapped in on an incoming call? I also believe this is a regression in the last or previous OTA.

Please ping me on IRC (rbasak) if I can help further with debugging this.

@Andrea, Anupam, Robie: That's interesting indeed and might explain why I've never been able to reproduce this myself. I would always have been actively engaged with the phone when trying to reproduce this.

Still present after OTA-14.
I noticed something new today. Got a call on 2016-12-09 at around 15:11 UTC, there was not ringtone (but I answered the call). After ~2 minutes (at around 15:13 UTC), I got a text message but I didn't hear any sound alert. It is not like bug #1544477, where *all* SMS and screenshots used to get silent until a reboot.

With OTA-14 it's still the same - sometimes I can hear ring tone only for split a second (~200ms maybe). I can answer the call and talk normally.

Attached yet another syslog (received call at 21:19).

I've had this exact behaviour for a long time on my BQ Aquarius E4.5. With OTA-14 as well.

Please reconsider the Importance of this bug, as it makes the phone unusable for it's basic function (reliably receiving calls).

In E4.5 with OTA-15
It makes a vibration.

Ubuntu Touch is no longer supported.