Opened 6 years ago

Closed 5 years ago

Last modified 4 years ago

#383 closed defect (worksforme)

when registration=denied call to Register() timeouts

Reported by: lindi Owned by: daniel
Priority: major Milestone: milestone5.5
Component: framework/ogsmd Version:
Keywords: Cc: seba.dos1@…

Description

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

Attachments (2)

debug.bz2 (17.7 KB) - added by lindi 6 years ago.
/var/log/debug from 16:00 to 17:19
syslog2.bz2 (6.8 KB) - added by lindi 5 years ago.
syslog 2009-03-16 1700-1800

Download all attachments as: .zip

Change History (17)

comment:1 Changed 6 years ago by 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)

Changed 6 years ago by lindi

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

comment:2 Changed 6 years ago by 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']

comment:3 Changed 5 years ago by daniel

  • Milestone set to milestone5.5

This should be fixable in ms5.5

comment:4 Changed 5 years ago by daniel

  • Owner changed from mickey to daniel
  • Status changed from new to assigned

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

comment:5 Changed 5 years ago by 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...

comment:6 Changed 5 years ago by 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?

comment:7 Changed 5 years ago by 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?

comment:8 Changed 5 years ago by lindi

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

comment:9 Changed 5 years ago by daniel

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

Changed 5 years ago by lindi

syslog 2009-03-16 1700-1800

comment:10 Changed 5 years ago by daniel

  • Status changed from assigned to in_testing

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.

comment:11 Changed 5 years ago by lindi

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

comment:12 Changed 5 years ago by dos

  • Cc seba.dos1@… added

comment:13 Changed 5 years ago by 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.

comment:14 Changed 5 years ago by stefan

  • Resolution set to worksforme
  • Status changed from in_testing to closed

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.

Note: See TracTickets for help on using tickets.