Ticket #301 (closed defect: fixed)
Unable to send modem commands to disable unsolicited responses, therefore unable to suspend
| Reported by: | PaulFertser | Owned by: | mickey |
|---|---|---|---|
| Priority: | major | Milestone: | |
| Component: | framework/ogsmd | Version: | milestone4 |
| Keywords: | Cc: |
Description
Here're the snippets from the logs showing what's going on.
2008.12.16 12:58:17 odeviced.input INFO name POWER pressed 0
2008.12.16 12:58:17 odeviced.input INFO name POWER released 0
2008.12.16 12:58:17 oeventsd INFO call dbus signal /org/freesmartphone/Usage Suspend(())
2008.12.16 12:58:17 ousaged INFO suspending all resources
2008.12.16 12:58:17 ogsmd DEBUG <UnsolicitedResponseChannel via /dev/pts/1>: got 20 bytes from: '\r\n%CSQ: 31, 99, 3\r\n'
2008.12.16 12:58:17 ogsmd.objects INFO org.freesmartphone.GSM.Network.SignalStrength: 100
2008.12.16 12:58:17 frameworkd.resource INFO setting resource status for GSM from enabled to suspending
2008.12.16 12:58:17 ogsmd.modem.abstract DEBUG prepareForSuspend ACK from channel <MiscChannel via /dev
/pts/0> received
2008.12.16 12:58:17 ogsmd.modem.abstract DEBUG prepareForSuspend ACK from channel <CallChannel via /dev
/pts/2> received
2008.12.16 12:58:17 ogsmd DEBUG <UnsolicitedResponseChannel via /dev/pts/1> queue is: deque([('AT+CTZU=0\r\n', None, None, 10), ('AT+CTZR=0\r\n', None, None, 10), ('AT+CREG=0\r\n', None, None, 10), ('AT+CGREG=0\r\n', None, None, 10), ('AT+CGEREP=0,0\r\n', None, None, 10), ('AT+CNMI=2,1,0,0,0\r\n', None, None, 10), ('AT%CSQ=0\r\n', None, None, 10), ('AT%CGEREP=0\r\n', None, None, 10), ('AT%CGREG=0\r\n', None, None, 10), ('AT%CBHZ=0\r\n', <function done at 0x912cf0>, <function done at 0x912cf0>, 10)])
2008.12.16 12:58:17 ogsmd DEBUG <UnsolicitedResponseChannel via /dev/pts/1>: sending 11 bytes: 'AT+CTZU=0\r\n'
2008.12.16 12:58:28 ogsmd DEBUG <UnsolicitedResponseChannel via /dev/pts/1>: TIMEOUT 'AT+CTZU=0' => ???
.......
2008.12.16 12:59:45 ogsmd DEBUG |...|...|...|...|...|...|...|...|...> SimRetrieveMessagebook.__init_
_: ENTER (<framework.subsystems.ogsmd.objects.Device at /org/freesmartphone/GSM/Device at 0x5cee30>, <function <lambda> at 0x912d30>, <function <lambda> at 0x912db0>),{'category': dbus.String(u'unsent')}
2008.12.16 12:59:45 ogsmd DEBUG |...|...|...|...|...|...|...|...|...> SimRetrieveMessagebook.__init_
_: LEAVE
.....
2008.12.16 12:59:47 ogsmd DEBUG <UnsolicitedResponseChannel via /dev/pts/1>: got 20 bytes from: '\r\n%CSQ: 31, 99, 4\r\n'
See Ticket #259, there the AtCommandChannel no longer operates and it seems it's the also the case here (no +CMGL=2 sent despite being requested), though the timeout occured on another channel.
Dec 16 12:58:15 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1742:watchdog(): Enter Dec 16 12:58:15 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1744:watchdog(): Serial state is 2 Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1553:serial_device_read(): Enter Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1563:serial_device_read(): Serial Data Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:374:syslogdump(): <s 00000000: 7e 09 ef 0d 0a 25 43 53-51 3a 20 20 33 31 2c 20 ~.<EF>..%CSQ: 31, Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:374:syslogdump(): <s 00000010: 39 39 2c 20 33 0d 0a 40-7e . . . . . . . 99, 3..@~ Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:870:gsm0710_buffer_write(): Enter Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:886:gsm0710_buffer_write(): Leave Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1360:extract_frames(): Enter Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1045:gsm0710_advanced_buffer_get_ frame(): Enter Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1121:gsm0710_advanced_buffer_get_ frame(): Leave success Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1371:extract_frames(): Frame is U I or UIH Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1374:extract_frames(): Frame chan nel > 0, pseudo channel Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1045:gsm0710_advanced_buffer_get_ frame(): Enter Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1474:extract_frames(): Leave Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1577:serial_device_read(): Leave keep watching Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:560:pseudo_device_read(): Enter Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:576:pseudo_device_read(): Data from channel 2, 11 bytes Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:398:write_frame(): Enter Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:374:syslogdump(): >s 00000000: f9 f9 . . . . . .- . . . . . . . . <F9><F9> Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:425:write_frame(): Sending frame to channel 2 Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:374:syslogdump(): >s 00000000: 7e 0b ef 41 54 2b 43 54-5a 55 3d 30 0d 0a 9a 7e ~.<EF>AT+CTZU=0..<9A>~ Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:491:write_frame(): Leave Dec 16 12:58:17 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:591:pseudo_device_read(): Leave Dec 16 12:58:20 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1742:watchdog(): Enter Dec 16 12:58:20 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1744:watchdog(): Serial state is 2 Dec 16 12:58:25 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1742:watchdog(): Enter Dec 16 12:58:25 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1744:watchdog(): Serial state is 2 Dec 16 12:58:28 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:560:pseudo_device_read(): Enter Dec 16 12:58:28 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:576:pseudo_device_read(): Data from channel 2, 1 bytes Dec 16 12:58:28 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:398:write_frame(): Enter Dec 16 12:58:28 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:374:syslogdump(): >s 00000000: f9 f9 . . . . . .- . . . . . . . . <F9><F9> Dec 16 12:58:28 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:425:write_frame(): Sending frame to channel 2 Dec 16 12:58:28 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:374:syslogdump(): >s 00000000: 7e 0b ef 1a 9a 7e . .- . . . . . . . . ~.<EF>.<9A>~ Dec 16 12:58:28 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:491:write_frame(): Leave Dec 16 12:58:28 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:591:pseudo_device_read(): Leave Dec 16 12:58:30 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1742:watchdog(): Enter Dec 16 12:58:30 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1744:watchdog(): Serial state is 2 ...... Dec 16 12:59:45 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1742:watchdog(): Enter Dec 16 12:59:45 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1744:watchdog(): Serial state is 2 Dec 16 12:59:47 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1553:serial_device_read(): Enter Dec 16 12:59:47 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:1563:serial_device_read(): Serial Data Dec 16 12:59:47 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:374:syslogdump(): <s 00000000: 7e 09 ef 0d 0a 25 43 53-51 3a 20 20 33 31 2c 20 ~.<EF>..%CSQ: 31, Dec 16 12:59:47 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:374:syslogdump(): <s 00000010: 39 39 2c 20 34 0d 0a 40-7e . . . . . . . 99, 4..@~ Dec 16 12:59:47 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:870:gsm0710_buffer_write(): Enter Dec 16 12:59:47 debian-gta02 /usr/sbin/gsm0710muxd[10179]: gsm0710muxd.c:886:gsm0710_buffer_write(): Leave
Change History
comment:2 Changed 4 years ago by daniel
Okay, this doesn't look good, but it's not really clear what the problem is. Does you phone respond if you start mickeyterm and enter AT+CTZU=?, AT+CTZU?, AT+CTZU=0
What does gsmdevice.GetInfo?() say (what firmware do you have)?
comment:3 Changed 4 years ago by PaulFertser
gsm_ac_gp_fd_pu_em_cph_ds_vc_cal35_ri_36_amd8_ts0-Moko10
Oh, it was long enough for me to forget whether i have tried to issue this commands in mickeyterm or not. I think i have tried something similar and there were no errors.
In any case, if there's a timeout here, the state should change back from "suspending" to "enabled" and the channel and the parser shouldn't be stuck.
comment:4 Changed 4 years ago by mickey
Since you did some important bugfixes to gsm0710muxd (which might as well be the underlying problem here), can you recheck again?
I acknowledge that we have to do something on the higher levels though, if preparing the modem for suspends fail. I'm just not sure what yet.
comment:5 Changed 4 years ago by PaulFertser
I check suspend/resume every day but this bug wasn't easily reproducible. I'm following HEAD closely from yesterday.
I suspect this timeout may be caused by the silent sleep "feature" of calypso and unfortunately i have not tried to implement any workaround in gsm0710muxd yet.
comment:7 Changed 4 years ago by mickey
The silent sleep "feature" will be handled differently in fso-abyss, so I expect this to be fixed when we migrate towards the new muxer. Lets keep this open until then.
comment:9 Changed 4 years ago by mickey
- Status changed from new to closed
- Resolution set to fixed
We strongly recommend to use fso-abyss these days, it shows much more predictable behaviour and takes care about modems with a deep sleep function. Please reopen if you can reproduce this problem w/ fso-abyss.
Note: See
TracTickets for help on using
tickets.
Another log from seemingly the same issue, now using FSO HEAD:
2008.12.20 17:19:55 ogsmd DEBUG <UnsolicitedResponseChannel via /dev/pts/2>: got 20 bytes from: '\r\n%CSQ: 31, 99, 4\r\n' 2008.12.20 17:19:55 ogsmd.device INFO org.freesmartphone.GSM.Network.SignalStrength: 100 2008.12.20 17:20:43 ogsmd DEBUG (<MiscChannel via /dev/pts/1>: last communication with modem was 48 seconds ago. Sending EOF to wakeup) 2008.12.20 17:20:43 ogsmd DEBUG <MiscChannel via /dev/pts/1> queue is: deque([('AT+CMGL=2\r\n', <bound method SimRetrieveMessagebook.responseFromChannel of <ogsmd.modems.abstract.mediator.SimRetrieveMessagebook object at 0x9c08f0>>, <bound method SimRetrieveMessagebook.errorFromChannel of <ogsmd.modems.abstract.mediator.SimRetrieveMessagebook object at 0x9c08f0>>, 10)]) 2008.12.20 17:20:43 ogsmd DEBUG <MiscChannel via /dev/pts/1>: sending 11 bytes: 'AT+CMGL=2\r\n' 2008.12.20 17:20:43 ogsmd DEBUG <MiscChannel via /dev/pts/1>: got 19 bytes from: '\r\n+CMS ERROR: 321\r\n' 2008.12.20 17:20:43 ogsmd DEBUG <MiscChannel via /dev/pts/1>: COMPLETED 'AT+CMGL=2' => ['+CMS ERROR: 321'] 2008.12.20 17:20:44 ogsmd DEBUG <MiscChannel via /dev/pts/1> queue is: deque([]) 2008.12.20 17:20:44 ogsmd DEBUG <MiscChannel via /dev/pts/1>: nothing in request queue 2008.12.20 17:21:29 odeviced.idlenotifier INFO odeviced.idlenotifier state change to busy 2008.12.20 17:21:29 oeventsd INFO DebugAction : dbus trigger test 2008.12.20 17:21:29 oeventsd INFO Receive IdleState, status = busy 2008.12.20 17:21:29 oeventsd INFO call dbus signal /org/freesmartphone/Device/Display/gta02_bl SetBrightness((90,)) 2008.12.20 17:21:29 oeventsd INFO Receive IdleState, status = busy 2008.12.20 17:21:29 oeventsd INFO Receive IdleState, status = busy 2008.12.20 17:21:29 oeventsd INFO signal SetBrightness responded : () 2008.12.20 17:21:33 ogsmd DEBUG <UnsolicitedResponseChannel via /dev/pts/2>: got 20 bytes from: '\r\n%CSQ: 31, 99, 3\r\n' 2008.12.20 17:21:33 ogsmd.device INFO org.freesmartphone.GSM.Network.SignalStrength: 100 2008.12.20 17:21:34 odeviced.input INFO name POWER pressed 0 2008.12.20 17:21:35 odeviced.input INFO name POWER released 0 2008.12.20 17:21:35 oeventsd INFO call dbus signal /org/freesmartphone/Usage Suspend(()) 2008.12.20 17:21:35 ousaged INFO suspending all resources... 2008.12.20 17:21:35 frameworkd.resource INFO setting resource status for GSM from enabled to suspending 2008.12.20 17:21:35 ogsmd.modem.abstract DEBUG prepareForSuspend ACK from channel <MiscChannel via /dev/pts/1> received 2008.12.20 17:21:35 ogsmd.modem.abstract DEBUG prepareForSuspend ACK from channel <CallChannel via /dev/pts/3> received 2008.12.20 17:21:35 ogsmd DEBUG <UnsolicitedResponseChannel via /dev/pts/2> queue is: deque([('AT+CTZU=0\r\n', None, None, 10), ('AT+CTZR=0\r\n', None, None, 10), ('AT+CREG=0\r\n', None, None, 10), ('AT+CGREG=0\r\n', None, None, 10), ('AT+CGEREP=0,0\r\n', None, None, 10), ('AT+CNMI=2,1,0,0,0\r\n', None, None, 10), ('AT%CSQ=0\r\n', None, None, 10), ('AT%CPRI=0\r\n', None, None, 10), ('AT%CGEREP=0\r\n', None, None, 10), ('AT%CGREG=0\r\n', None, None, 10), ('AT%CBHZ=0\r\n', <function done at 0x9eb130>, <function done at 0x9eb130>, 10)]) 2008.12.20 17:21:35 ogsmd DEBUG <UnsolicitedResponseChannel via /dev/pts/2>: sending 11 bytes: 'AT+CTZU=0\r\n' 2008.12.20 17:21:39 odeviced.idlenotifier INFO odeviced.idlenotifier state change to idle 2008.12.20 17:21:39 oeventsd INFO DebugAction : dbus trigger test 2008.12.20 17:21:39 oeventsd INFO Receive IdleState, status = idle 2008.12.20 17:21:39 oeventsd INFO Receive IdleState, status = idle 2008.12.20 17:21:39 oeventsd INFO Receive IdleState, status = idle 2008.12.20 17:21:43 ogsmd DEBUG (<MiscChannel via /dev/pts/1>: last communication with modem was 8 seconds ago. Sending EOF to wakeup) 2008.12.20 17:21:43 ogsmd DEBUG <MiscChannel via /dev/pts/1> queue is: deque([('AT+CMGL=2\r\n', <bound method SimRetrieveMessagebook.responseFromChannel of <ogsmd.modems.abstract.mediator.SimRetrieveMessagebook object at 0x9c0490>>, <bound method SimRetrieveMessagebook.errorFromChannel of <ogsmd.modems.abstract.mediator.SimRetrieveMessagebook object at 0x9c0490>>, 10)]) 2008.12.20 17:21:43 ogsmd DEBUG <MiscChannel via /dev/pts/1>: sending 11 bytes: 'AT+CMGL=2\r\n' 2008.12.20 17:21:43 ogsmd DEBUG <MiscChannel via /dev/pts/1>: got 19 bytes from: '\r\n+CMS ERROR: 321\r\n' 2008.12.20 17:21:43 ogsmd DEBUG <MiscChannel via /dev/pts/1>: COMPLETED 'AT+CMGL=2' => ['+CMS ERROR: 321'] 2008.12.20 17:21:43 ogsmd DEBUG <MiscChannel via /dev/pts/1> queue is: deque([]) 2008.12.20 17:21:43 ogsmd DEBUG <MiscChannel via /dev/pts/1>: nothing in request queue 2008.12.20 17:21:46 ogsmd DEBUG <UnsolicitedResponseChannel via /dev/pts/2>: TIMEOUT 'AT+CTZU=0' => ???