[ofono] Image 147 does not register to GSM on bootup

[Michael Zanetti]

Starting with image 147, for me, ofono does not register to GSM on bootup any more. Image 145 was fine, I did not try 146.

Loggin in and manually restarting ofono makes it work. Increasing the pre-start sleep timeout to a bigger value works around the issue. (Maguro seems to be ok with 10 seconds, Mako seems to require a bit more. 15 seems ok for Mako).

Here is the ofono log when booting up in the default configuration: http://paste.ubuntu.com/5729434/

[Tony Espy (awe)]

@Michael

I'm kinda stumped. I've tried to reproduce this on both maguro and mako, using the version of ofono included with image 147, and a newer version of ofono with some tracing improvements.

I'm assuming when you said "pre-sleep" timeout, you meant the timeout in the ofono upstart job.

To reproduce, I just tried lowering the pre-sleep timeout as far as I could to see if I could trigger the failure. On maguro, lowering the pre-sleep timeout made no difference until I got it down to 2, then instead of the failure you report, I got a socket connection error. Note each of my attempts was triggered by a reboot.

Just to be on the safe side, I tried this both with and without an active Wi-Fi connection on both devices.

Is there any other differences you can think about? Had you installed any other package, or modified any other configuration files on the system that might have made a difference? Anything special about your SIM?

Also, just to confirm... you can reproduce this on both devices, correct? Can you reproduce it consistently?

I also spent some time looking at the code, and the only theory I have is that there's a race and that the SIM_STATUS command is received by RILD after the socket has connected, but before the UNSOL_RIL_CONNECTED message is sent.

[Michael Zanetti (mzanetti)]

> I'm assuming when you said "pre-sleep" timeout, you meant the timeout in the ofono upstart job.

yes

> To reproduce, I just tried lowering the pre-sleep timeout as far as I could to see if I could trigger the failure.
> On maguro, lowering the pre-sleep timeout made no difference until I got it down to 2, then instead of the
> failure you report, I got a socket connection error. Note each of my attempts was triggered by a reboot.

> Just to be on the safe side, I tried this both with and without an active Wi-Fi connection on both devices.

> Is there any other differences you can think about? Had you installed any other package, or modified any
> other configuration files on the system that might have made a difference? Anything special about your SIM?

Hmm... Not really... This just happens directly after the fresh flashing.

> Also, just to confirm... you can reproduce this on both devices, correct? Can you reproduce it consistently?

I just flashed image 152 to the Maguro and it did connect successfully. Removed the SIM card and put it into the Mako and flashed 152 too. It does not connect, not even after multiple reboots. So yes, I can reproduce this, but with image 152, it seems only on the Mako (which already has been more fragile when I initially reported this).

> I also spent some time looking at the code, and the only theory I have is that there's a race and that the
> SIM_STATUS command is received by RILD after the socket has connected, but before the
> UNSOL_RIL_CONNECTED message is sent.

I don't know much about how ofono talks with the SIM so I can't really give useful input here.

If you need more logs or want me to try anything special, just ask, I'm happy to provide whatever I can.

[Michael Zanetti (mzanetti)]

Here's the log for image 152 on Mako: http://paste.ubuntu.com/5736012/

[Tony Espy (awe)]

I still haven't been able to reproduce the failure on either of my phones, and I've tried to make them almost identical to your setup ( ie. active Wi-Fi connection, NM 3g connection configured, ... ).

That said, I've discussed with rsalvetti, and what I will do is build a modified version of ofono which makes the code explicitly wait for the RIL_CONNECTED to be received before allowing the device plugin to query for the SIM card.

We've also discussed adding retry logic to both the socket open call, and the processing of the initial GET_SIM_STATUS request.

I'll attach a .deb for you to test later today.

[Tony Espy (awe)]

@Michael

Here's a test build for you to try out. Can you please make "-d" is specified in the ofono upstart job, and report back your results?

I still have a couple of other improvements on the start-up sequence I'm working on, but this change ensures that we don't send a GET_SIM_STATUS request until after we've received a RIL_CONNECTED message.

[Michael Zanetti (mzanetti)]

Hey Tony,

unfortunately this doesn't seem to solve the issue here:

http://paste.ubuntu.com/5752324/

[Tony Espy (awe)]

@Michael

Hmmmm, OK so much for my first theory regarding a race with the RIL_CONNECTED event.

Here's a new version with retry logic added to the GET_SIM_STATUS operation. This code gives up after ~20s, however I will discuss with some of the other guys the possibility of not capping the actual number of retries, but instead raising the interval between attempts at some point...

[Michael Zanetti (mzanetti)]

Yay! Seems to work.

Installed the package on mako, rebooted and immediately received some SMS. Calling works both ways.