Unable to send modem commands to disable unsolicited responses, therefore unable to suspend

[PaulFertser]

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 

[PaulFertser]

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' => ???

[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)?

[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.

[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.

[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.

[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.

[mickey]

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.