Delay of approx. 60 seconds when an outgoing call is innitiated by the IN CAR bluetooth system

[Uranicus]

My system:

current build number: 228
device name: krillin
channel: ubuntu-touch/rc-proposed/bq-aquaris.en
last update: 2016-01-13 08:28:26
version version: 228
version ubuntu: 20160113
version device: 20160108-efc96d8
version custom: 20151111--36-46-vivid

Since several days (not weeks, so something has changed in the last couple days!) I have the following situation with my BQ 4.5 in my car. When I initiate a call from the IN CAR system (where my phone is connected to) I experience sometimes the normal behaviour that the call is directly established.

Sometimes nothing happens. The call is not established and my in car system says that the attempt to carry out a call has failed (this message comes after approx. 15 seconds after initiation of the call).
Then approx. 60 seconds after the initiation of the call the call is all of a sudden established (without any further interaction). I currently was not able to find a logic in this. Here my "log"-file of what I did today:

-----

13.01.2016

9:00 h call initiated from car, call directly established
9:03 h call initiated from car (phone book), approx. 60 sec. delay between initiation and call being established
9:06 h call initiated from car, call directly established
9:09 h call initiated from car (phone book), approx. 60 sec. delay between initiation and call being established

9:26 h New pairing between phone and car, retry

9:30 h call initiated from car, call directly established
9:33 h call initiated from car (phone book), approx. 60 sec. delay between initiation and call being established
9:36 h call initiated from car, call directly established
9:39 h call initiated from car (phone book), approx. 60 sec. delay between initiation and call being established
9:42 h call initiated from car, call directly established
9:45 h call initiated from car, call directly established (this time again via phone book)
9:48 h call initiated from car (via voice command), approx. 60 sec. delay between initiation and call being established
9:52 h call initiated from phone itself, call established and correctly routed via car speaker

I have added the syslog, upstart-files to the bug report for further analysis.

Uranicus

[Jean-Baptiste Lallement (jibel)]

I can reproduce the problem with a Garmin Nüvi and latest krillin rc-proposed. It seems that the call is not initiated when the device is suspended. As soon as the device wakes up, the call starts.

[Jean-Baptiste Lallement (jibel)]

It's clearly a recent regression . I tried 6 times with krillin rc-proposed 220 (20160104) and couldn't reproduce the issue. Then upgraded to latest build (230) and reproduced the issue immediately.

[Launchpad Janitor (janitor)]

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

[Jean-Baptiste Lallement (jibel)]

Here is a syslog from krillin rc-proposed 230 when the problem is reproduced.
@20:18:20 the call is initiated from the BT device, the device wakes up and there is an ATD command to setup the call but immediately the device suspends again.

Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.068163][SPM] md_settle = 99, settle = 99
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.068163][SPM] sec = 5400, wakesrc = 0x3204564 (1)(1)
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.068163][SPM] wake up by CONN (0x80000c00)(0x400)(250871)
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.068163][SPM] event_reg = 0x90010000, isr = 0x10, r13 = 0xea060842
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.068163]wdt enable spm timer.....
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.068163][WDT] resume(1)
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.068169]Suspended for 0.000 seconds
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.071005][MATV] resume
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.071119]Mali<1>: Mali PM: mali_pm_resume
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.071515][Serial_Core]: By pass Set termio
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.071526][UART0] Resume(0)!
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.071545][UART1] Resume(0)!
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.071559]GPIO_UART_URXD3_PIN is not properly set p2
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.071570][UART2] Resume(0)!
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.071584]GPIO_UART_URXD4_PIN is not properly set p2
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.071595][UART3] Resume(0)!
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.258608]sd card rocr <0xc0ff8000>
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.262823][Reset and init thermal controller]
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.262852][PTP] PTP_INIT_02() start (ptp_level = 0x0).
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.262860][PTP] DCVOFFSETIN = 0xffffff2a
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.262867][PTP] AGEVOFFSETIN = 0x0
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.262884][PTP] PTP_MON_MODE() start (ptp_level = 0x0).
Jan 14 20:18:20 ubuntu-phablet ofonod[1923]: Server: < ATD0629161837;\r
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.263513]Restarting tasks ... done.
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.268147][pm_notifier_call_chain]: there are 4 notify callbacks, event = 4
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.268206]msdc: 0,mmc_schedule_delayed_work ret= 1
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.268264]msdc: 1,mmc_schedule_delayed_work ret= 1
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.268286]PM: suspend exit 2016-01-14 20:18:20.198010769 UTC
Jan 14 20:18:20 ubuntu-phablet kernel: [ 187.268514]PM: suspend entry 2016-01-14 20:18:20.198236077 UTC
...

Then nothing happens until 20:20:12 (112s) and the device finally wakes up, it makes the call and the display turns on.

Jan 14 20:20:12 ubuntu-phablet kernel: [ 187.553595]Restarting tasks ... done.
Jan 14 20:20:12 ubuntu-phablet kernel: [ 187.564436][pm_notifier_call_chain]: there are 4 notify callbacks, event = 4
Jan 14 20:20:12 ubuntu-phablet kernel: [ 187.564493]msdc: 0,mmc_schedule_delayed_work re...

[Łukasz Zemczak (sil2100)]

This bug was fixed in the package ofono 1.17.bzr6910+15.04.20160115.3-0ubuntu1 in https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/stable-phone-overlay

---------------

ofono (1.17.bzr6910+15.04.20160115.3-0ubuntu1) vivid; urgency=medium

  [ Simon Fels ]
  [ Simon Fels]

  * voicecall: acquire wakelock when starting a HFP initated voicecall
    (LP: #1533716)
  * plugins: add android wakelock implementation
  * src: add wakelock abstraction

  [ CI Train Bot ]
  * No-change rebuild.

ofono (1.17.bzr6908+16.04.20151203-0ubuntu1) xenial; urgency=medium

  [ Tony Espy ]
  * Add unit test test-rilmodem-cs

  [ Simon Fels ]
  * voicecall: don't dereference a supplied null value

  [ Alfonso Sanchez-Beato ]
  * Support handling incoming calls for HFP + multi-SIM

  [ CI Train Bot ]
  * New rebuild forced.

 -- Tony Espy <email address hidden> Fri, 15 Jan 2016 17:37:10 +0000

[Uranicus (matthias.ritter)]

Dear all,

I have tested it today several times on:

current build number: 232
device name: krillin
channel: ubuntu-touch/rc-proposed/bq-aquaris.en
last update: 2016-01-16 08:03:38
version version: 232
version ubuntu: 20160116
version device: 20160108-efc96d8
version custom: 20160111-926-36--vivid

and it works great. Thanks to all developers for this great piece of work! Very well done,

Uranicus

[Launchpad Janitor (janitor)]

This bug was fixed in the package ofono - 1.17.bzr6910+16.04.20160115.3-0ubuntu1

---------------
ofono (1.17.bzr6910+16.04.20160115.3-0ubuntu1) xenial; urgency=medium

  [ Simon Fels ]
  [ Simon Fels]

  * voicecall: acquire wakelock when starting a HFP initated voicecall
    (LP: #1533716)
  * plugins: add android wakelock implementation
  * src: add wakelock abstraction

  [ CI Train Bot ]
  * No-change rebuild.

 -- Tony Espy <email address hidden> Fri, 15 Jan 2016 17:37:10 +0000