when registration=denied call to Register() timeouts

[lindi]

My fr got to a state where Status signal says

(registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)

and trying to call Register() of gsm network interface timeouts with

org.freedesktop.DBus.Error.NoReply?: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

SetAntennaPower? does not timeout so this is not an instance of #348 where all calls timeout. What should I call to re-try registration to network?

Version info:

kernel: Linux ginger 2.6.28-GTA02_lindi-andy-tracking_b8b36e5ec3db71d5-mokodev #53 PREEMPT Sun Feb 22 13:08:50 UTC 2009 armv4tl GNU/Linux
kernel cmdline: rootfstype=jffs2 root=/dev/mtdblock6 console=ttySAC2,115200 console=tty0 loglevel=8 regular_boot mtdparts=physmap-flash:-(nor);neo1973-nand:0x00040000(u-boot),0x00040000(u-boot_env),0x00800000(kernel),0x000a0000(splash),0x00040000(factory),0x0f6a0000(rootfs) rootfstype=ext2 root=/dev/mmcblk0p2 rootdelay=5 panic=10 mem=127M
gsm0710muxd: abcbcd7cc532a8834906de3fc24c8f8fe7643cd4
frameworkd: e6c36e917cc75809f60fa587b68bbf6be0c5bf58
u-boot: U-Boot 1.3.2+gitr46+dc633f4be2527f844158aa5085c278b0c3039d3f (Aug  8 2008 - 03:58:49)
xglamo: 1.3.0.0+git20080807-3
distro: debian gnu/linux unstable
dialer: kapula Thu Feb 5 02:10:58 EET 2009 timo.lindfors@iki.fi
gsm firmware: gsm_ac_gp_fd_pu_em_cph_ds_vc_cal35_ri_36_amd8_ts0-Moko11b1
hardware revision:  0350

[lindi]

It seems to sometimes fail also with

org.freesmartphone.GSM.Network.NotPresent?

Anyways, I am attaching full /var/log/debug output so that you can correlate it against Status signals:

2009-03-15 16:27:23 cbNetworkStatus (code 24405) (cid F68B) (act GSM) (provider Elisa) (lac 232D) (strength 47) (mode automatic) (registration roaming)
2009-03-15 16:27:42 cbNetworkStatus (code 24405) (cid F59C) (act GSM) (provider Elisa) (lac 232D) (strength 40) (mode automatic) (registration roaming)
2009-03-15 16:28:08 cbNetworkStatus (strength 0) (cid F59C) (act GSM) (lac 232D) (mode automatic) (registration unregistered)
2009-03-15 16:31:41 cbNetworkStatus (strength 0) (cid F59C) (act GSM) (lac 232D) (mode automatic) (registration unregistered)
2009-03-15 16:31:42 cbNetworkStatus (registration unregistered) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 16:31:43 cbNetworkStatus (strength 0) (cid F59C) (act GSM) (lac 232D) (mode automatic) (registration unregistered)
2009-03-15 16:31:50 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 16:31:50 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 16:35:02 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 16:35:03 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 16:52:28 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 16:52:28 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 16:57:20 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 16:57:20 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 17:17:30 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 17:17:30 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 17:18:18 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 17:18:18 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 17:19:00 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 17:19:00 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 17:19:27 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)
2009-03-15 17:19:27 cbNetworkStatus (registration denied) (act GSM) (mode automatic) (lac 232D) (cid F59C)

[lindi]

/var/log/debug from 16:00 to 17:19

[daniel]

For the record it looks like the Register() call is returned with a CME ERROR: 30 which causes ogsmd to throw a traceback so the DBus call times out:

Mar 15 17:49:23 ginger ogsmd.channel DEBUG    <MiscChannel via /dev/pts/2>: sending 13 bytes: 'AT+COPS=0,0\r\n'
Mar 15 17:49:23 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None
Mar 15 17:49:23 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: got 12 bytes: '\r\n+CREG: 2\r\n'
Mar 15 17:49:31 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None
Mar 15 17:49:31 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: got 16 bytes: '%CSTAT: PHB, 0\r\n'
Mar 15 17:49:31 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None
Mar 15 17:49:31 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: got 16 bytes: '%CSTAT: SMS, 1\r\n'
Mar 15 17:49:34 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToSend: watch timeout = None
Mar 15 17:49:34 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: sending 11 bytes: 'AT+CSMS=1\r\n'
Mar 15 17:49:34 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = 12107
Mar 15 17:49:34 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: got 22 bytes: '\r\n+CSMS: 1,1,1\r\n\r\nOK\r\n'
Mar 15 17:49:34 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: COMPLETED 'AT+CSMS=1' => ['+CSMS: 1,1,1', 'OK']
Mar 15 17:49:34 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToSend: watch timeout = None
Mar 15 17:49:34 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: sending 19 bytes: 'AT+CNMI=2,1,2,1,1\r\n'
Mar 15 17:49:34 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = 12110
Mar 15 17:49:34 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: got 6 bytes: '\r\nOK\r\n'
Mar 15 17:49:34 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: COMPLETED 'AT+CNMI=2,1,2,1,1' => ['OK']
Mar 15 17:49:34 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToSend: watch timeout = None
Mar 15 17:49:35 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None
Mar 15 17:49:35 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: got 17 bytes: '%CSTAT: EONS, 1\r\n'
Mar 15 17:49:54 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None
Mar 15 17:49:54 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: got 16 bytes: '%CSTAT: PHB, 1\r\n'
Mar 15 17:49:54 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None
Mar 15 17:49:54 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: got 16 bytes: '%CSTAT: RDY, 1\r\n'
Mar 15 17:49:55 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToSend: watch timeout = None
Mar 15 17:49:55 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: sending 11 bytes: 'AT+CSMS=1\r\n'
Mar 15 17:49:55 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = 12117
Mar 15 17:49:55 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: got 22 bytes: '\r\n+CSMS: 1,1,1\r\n\r\nOK\r\n'
Mar 15 17:49:55 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: COMPLETED 'AT+CSMS=1' => ['+CSMS: 1,1,1', 'OK']
Mar 15 17:49:55 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToSend: watch timeout = None
Mar 15 17:49:55 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: sending 19 bytes: 'AT+CNMI=2,1,2,1,1\r\n'
Mar 15 17:49:55 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = 12120
Mar 15 17:49:55 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: got 6 bytes: '\r\nOK\r\n'
Mar 15 17:49:55 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: COMPLETED 'AT+CNMI=2,1,2,1,1' => ['OK']
Mar 15 17:49:55 ginger ogsmd.channel DEBUG    <UnsolicitedResponseChannel via /dev/pts/3>: _readyToSend: watch timeout = None
Mar 15 17:50:21 ginger ogsmd.channel DEBUG    <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 12105
Mar 15 17:50:21 ginger ogsmd.channel DEBUG    <MiscChannel via /dev/pts/2>: got 18 bytes: '\r\n+CME ERROR: 30\r\n'
Mar 15 17:50:21 ginger ogsmd.channel DEBUG    <MiscChannel via /dev/pts/2>: COMPLETED 'AT+COPS=0,0' => ['+CME ERROR: 30']

[daniel]

This should be fixable in ms5.5

[daniel]

+CME ERROR: 30 means "No network service" which is a valid answer in that case. Need to check why ogsmd doesn't expect this..

[daniel]

Okay, nothing obvious in the code... You can reproduce this reliably I assume? Could you please stop frameworkd and run it from the console (do not use the init script). There are certain backtraces that only show up on stderr...

[lindi]

No sorry I do not have an easy way to reproduce this. I can not run frameworkd without --daemonize since then it does not write its pidfile which I need to kill frameworkd automatically. (Since I don't have a reliable way to reproduce this bug I can not manually start frameworkd from console for the next 3 months in the hope that I'll hit this.) Could you make frameworkd write pidfile even without --daemonize?

[daniel]

This could be an issue with the default dbus timeout. The 58 seconds is pretty close to the 60 seconds dbus timeout. Can you provide some more (before and after) lines of the frameworkd log so I can be sure?

[lindi]

Hmm, which time range do you exactly want? I have daily backup from 1.1.2009 onwards.

[daniel]

The minutes before Mar 15 17:49:23 and after Mar 15 17:50:21 in the framework log would be interesting.

[lindi]

syslog 2009-03-16 1700-1800

[daniel]

Just to be sure: This is not completely reproducible, right?

The fso/ms5.5 branch in openembedded has the timeout set to 200 seconds since commit 0234f3f02c7ae611ba72481b59cb020a6a0c29be.

Please test an image where this patch is already applied. This should be fixed now.

[lindi]

Nope, this is not easy to reproduce. I'll pay attention to that commit when I next git pull frameworkd.

[daniel]

One thing to note ist that if you're using debian (and as a result an unpatched dbus version) the client timeout will only be 30 seconds.

Not sure how debian will work around that.

[stefan]

Have you been able to reproduce this with a longer timeout? We don't run into this, but we are using images from OE, with the timeout patch, only.

Please reopen if you run into it with a longer timeout.

[bascorp]

 ????? ????????? ??????