Context Navigation

← Previous Ticket
Next Ticket →

Ticket #264 (closed defect: fixed)

Opened 3 years ago

Last modified 2 years ago

portNotOpenError on resume if GSM has been released

Reported by:	lindi	Owned by:	mickey
Priority:	major	Milestone:
Component:	framework/ogsmd	Version:
Keywords:		Cc:

Description

Steps to reproduce:
1) RequestResource("GSM")
2) ReleaseResource("GSM")
3) Usage.Suspend
4) press power button

Expected results:
4) phone resumes from suspend

Actual results:
4) phone resumes from suspend but frameworkd prints the following exception:

2008.11.28 16:58:34 ousaged  INFO     Disabled GSM in 0.8 seconds
2008.11.28 16:58:34 ousaged  INFO     Releasing GSM for vanished user :1.10
2008.11.28 17:01:06 ousaged  INFO     resuming all resources
Traceback (most recent call last):
  File "/var/lib/python-support/python2.5/framework/subsystems/ogsmd/gsm/channel.py", line 460, in _handleCommandTimeout
    self.serial.write( "\x1A" )
  File "/usr/lib/python2.5/site-packages/serial/serialposix.py", line 328, in write
    if self.fd is None: raise portNotOpenError
serial.serialutil.SerialException: Port not open

Change History

comment:1 Changed 3 years ago by mickey

Which branch is that? This seems to work for me in master. Can you test with that?

comment:2 Changed 3 years ago by lindi

Sorry for forgeting to mention the version number. The bug was reported on 28.11. so according to my backups I was running fso-frameworkd 0.8.4.3-20081123-1:

$ grep -A10 "Package: fso-frameworkd$" /home/scratch/neo/2008-1*/var/lib/dpkg/status |grep Version
/home/scratch/neo/2008-10-19/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-10-20/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-10-21/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-10-22/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-10-23/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-10-24/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-10-25/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-10-26/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-10-27/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-10-28/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-10-29/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-10-30/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-10-31/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-11-01/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-11-02/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-11-03/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-11-04/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-11-07/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-11-09/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-11-14/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-11-16/var/lib/dpkg/status-Version: 0.2.0-git20080909-6
/home/scratch/neo/2008-11-17/var/lib/dpkg/status-Version: 0.2.0-git20080909-7
/home/scratch/neo/2008-11-18/var/lib/dpkg/status-Version: 0.2.0-git20080909-7
/home/scratch/neo/2008-11-19/var/lib/dpkg/status-Version: 0.8.4.3-20081118-2
/home/scratch/neo/2008-11-20/var/lib/dpkg/status-Version: 0.8.4.3-20081118-2
/home/scratch/neo/2008-11-25/var/lib/dpkg/status-Version: 0.8.4.3-20081123-1
/home/scratch/neo/2008-11-26/var/lib/dpkg/status-Version: 0.8.4.3-20081123-1
/home/scratch/neo/2008-11-27/var/lib/dpkg/status-Version: 0.8.4.3-20081123-1
/home/scratch/neo/2008-11-28/var/lib/dpkg/status-Version: 0.8.4.3-20081123-1
/home/scratch/neo/2008-11-29/var/lib/dpkg/status-Version: 0.8.4.3-20081123-1
/home/scratch/neo/2008-12-01/var/lib/dpkg/status-Version: 0.8.4.3-20081123-1
/home/scratch/neo/2008-12-02/var/lib/dpkg/status-Version: 0.8.4.3-20081123-1
/home/scratch/neo/2008-12-03/var/lib/dpkg/status-Version: 0.8.4.3-20081130-1

I do not know a reliable way to reproduce the bug. It does not seem to happen every time even if I follow steps 1-4.

comment:3 Changed 3 years ago by lindi

I hit this today again with fso-frameworkd 0.8.4.3-20081130-1 on stable-tracking 80f4b5 kernel.

comment:4 Changed 3 years ago by lindi

I now got fso-frameworkd to a state where this occurs every time about 10-13 seconds after I have released GSM (no suspend needed!):

2008.12.13 20:32:33 ousaged  INFO     Disabled GSM in 0.5 seconds
Traceback (most recent call last):
  File "/var/lib/python-support/python2.5/framework/subsystems/ogsmd/gsm/channel.py", line 460, in _handleCommandTimeout
    self.serial.write( "\x1A" )
  File "/usr/lib/python2.5/site-packages/serial/serialposix.py", line 328, in write
    if self.fd is None: raise portNotOpenError
serial.serialutil.SerialException: Port not open

Here's full output I see when I release GSM:

2008.12.13 20:34:58 ogsmd    DEBUG    |...|...|...|...|...|...|...|...|...> DeviceSetAntennaPower.__init__: ENTER (<framework.subsystems.ogsmd.objects.Device at /org/freesmartphone/GSM/Device at 0x2531f0>, <function <lambda> at 0x87aa70>, <function <lambda> at 0x87afb0>),{'power': dbus.Boolean(False)}
2008.12.13 20:34:58 ogsmd    DEBUG    |...|...|...|...|...|...|...|...|...> DeviceSetAntennaPower.__init__: LEAVE
2008.12.13 20:34:58 ogsmd    DEBUG    (<MiscChannel via /dev/pts/7>: last communication with modem was 23 seconds ago. Sending EOF to wakeup)
2008.12.13 20:34:58 ogsmd    DEBUG    <MiscChannel via /dev/pts/7> queue is: deque([('AT+CPIN?\r\n', <bound method DeviceSetAntennaPower.intermediateResponse of <ogsmd.modems.abstract.mediator.DeviceSetAntennaPower object at 0x8448d0>>, <bound method DeviceSetAntennaPower.errorFromChannel of <ogsmd.modems.abstract.mediator.DeviceSetAntennaPower object at 0x8448d0>>, 15)])
2008.12.13 20:34:58 ogsmd    DEBUG    <MiscChannel via /dev/pts/7>: sending 10 bytes: 'AT+CPIN?\r\n'
2008.12.13 20:34:58 ogsmd    DEBUG    <MiscChannel via /dev/pts/7>: got 22 bytes from: '\r\n+CPIN: READY\r\n\r\nOK\r\n'
2008.12.13 20:34:58 ogsmd    DEBUG    <MiscChannel via /dev/pts/7>: COMPLETED 'AT+CPIN?' => ['+CPIN: READY', 'OK']
2008.12.13 20:34:58 ogsmd    DEBUG    <MiscChannel via /dev/pts/7> queue is: deque([('AT+CFUN=0\r\n', <bound method DeviceSetAntennaPower.responseFromChannel of <ogsmd.modems.abstract.mediator.DeviceSetAntennaPower object at 0x8448d0>>, <bound method DeviceSetAntennaPower.errorFromChannel of <ogsmd.modems.abstract.mediator.DeviceSetAntennaPower object at 0x8448d0>>, 10)])
2008.12.13 20:34:58 ogsmd    DEBUG    <MiscChannel via /dev/pts/7>: sending 11 bytes: 'AT+CFUN=0\r\n'
2008.12.13 20:34:58 ogsmd    DEBUG    <UnsolicitedResponseChannel via /dev/pts/8>: got 16 bytes from: '%CSTAT: PHB, 0\r\n'
2008.12.13 20:34:58 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:58 ogsmd.objects INFO     sim ready status False
2008.12.13 20:34:58 ogsmd    INFO     full readyness now False
2008.12.13 20:34:58 ogsmd    DEBUG    <UnsolicitedResponseChannel via /dev/pts/8>: got 16 bytes from: '%CSTAT: SMS, 0\r\n'
2008.12.13 20:34:58 ogsmd    INFO     subsystem SMS readyness now False
2008.12.13 20:34:58 ogsmd    INFO     full readyness now False
2008.12.13 20:34:58 ogsmd    DEBUG    <UnsolicitedResponseChannel via /dev/pts/8>: got 48 bytes from: '%CSTAT: PHB, 0\r\n%CSTAT: PHB, 0\r\n%CSTAT: PHB, 0\r\n'
2008.12.13 20:34:58 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:58 ogsmd    INFO     full readyness now False
2008.12.13 20:34:58 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:58 ogsmd    INFO     full readyness now False
2008.12.13 20:34:58 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:58 ogsmd    INFO     full readyness now False
2008.12.13 20:34:58 ogsmd    DEBUG    <UnsolicitedResponseChannel via /dev/pts/8>: got 80 bytes from: '%CSTAT: PHB, 0\r\n%CSTAT: PHB, 0\r\n%CSTAT: PHB, 0\r\n%CSTAT: PHB, 0\r\n%CSTAT: PHB, 0\r\n'
2008.12.13 20:34:59 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:59 ogsmd    INFO     full readyness now False
2008.12.13 20:34:59 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:59 ogsmd    INFO     full readyness now False
2008.12.13 20:34:59 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:59 ogsmd    INFO     full readyness now False
2008.12.13 20:34:59 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:59 ogsmd    INFO     full readyness now False
2008.12.13 20:34:59 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:59 ogsmd    INFO     full readyness now False
2008.12.13 20:34:59 ogsmd    DEBUG    <UnsolicitedResponseChannel via /dev/pts/8>: got 80 bytes from: '%CSTAT: PHB, 0\r\n%CSTAT: PHB, 1\r\n%CSTAT: PHB, 0\r\n%CSTAT: PHB, 0\r\n%CSTAT: PHB, 0\r\n'
2008.12.13 20:34:59 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:59 ogsmd    INFO     full readyness now False
2008.12.13 20:34:59 ogsmd    INFO     subsystem PHB readyness now True
2008.12.13 20:34:59 ogsmd    INFO     full readyness now False
2008.12.13 20:34:59 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:59 ogsmd    INFO     full readyness now False
2008.12.13 20:34:59 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:59 ogsmd    INFO     full readyness now False
2008.12.13 20:34:59 ogsmd    INFO     subsystem PHB readyness now False
2008.12.13 20:34:59 ogsmd    INFO     full readyness now False
2008.12.13 20:35:00 ogsmd    DEBUG    <MiscChannel via /dev/pts/7>: got 6 bytes from: '\r\nOK\r\n'
2008.12.13 20:35:00 ogsmd    DEBUG    <MiscChannel via /dev/pts/7>: COMPLETED 'AT+CFUN=0' => ['OK']
2008.12.13 20:35:00 ogsmd    DEBUG    |...|...|...|...|...|...|...|...|...|...|...> DeviceSetAntennaPower.responseFromChannel: ENTER ('AT+CFUN=0', ['OK']),{}
2008.12.13 20:35:00 ogsmd    DEBUG    |...|...|...|...|...|...|...|...|...|...|...> DeviceSetAntennaPower.responseFromChannel: LEAVE
2008.12.13 20:35:00 ogsmd    DEBUG    <UnsolicitedResponseChannel via /dev/pts/8>: got 52 bytes from: '\r\n+CGEV: ME DETACH\r\n\r\n%CGEV: ME DETACH\r\n\r\n+CREG: 0\r\n'
2008.12.13 20:35:00 ogsmd    INFO     <UnsolicitedResponseChannel via /dev/pts/8>: unhandled unsolicited data incoming: '+CGEV: ME DETACH'
2008.12.13 20:35:00 ogsmd    INFO     <UnsolicitedResponseChannel via /dev/pts/8>: unhandled unsolicited data incoming: '%CGEV: ME DETACH'
2008.12.13 20:35:00 ogsmd    DEBUG    |...|...|...|...|...|...|...|...|...|...|...|...|...> NetworkGetStatus.__init__: ENTER (<framework.subsystems.ogsmd.objects.Device at /org/freesmartphone/GSM/Device at 0x2531f0>, <bound method UnsolicitedResponseDelegate.statusOK of <framework.subsystems.ogsmd.modems.ti_calypso.unsolicited.UnsolicitedResponseDelegate object at 0x881590>>, <bound method UnsolicitedResponseDelegate.statusERR of <framework.subsystems.ogsmd.modems.ti_calypso.unsolicited.UnsolicitedResponseDelegate object at 0x881590>>),{}
2008.12.13 20:35:00 ogsmd    DEBUG    |...|...|...|...|...|...|...|...|...|...|...|...|...> NetworkGetStatus.__init__: LEAVE
2008.12.13 20:35:00 ogsmd    DEBUG    <MiscChannel via /dev/pts/7> queue is: deque([('AT+CPIN?\r\n', <bound method DeviceSetAntennaPower.intermediateResponse2 of <ogsmd.modems.abstract.mediator.DeviceSetAntennaPower object at 0x8448d0>>, <bound method DeviceSetAntennaPower.errorFromChannel of <ogsmd.modems.abstract.mediator.DeviceSetAntennaPower object at 0x8448d0>>, 15), ('AT+CSQ\r\n', <bound method NetworkGetStatus.genResponseFromChannel of <ogsmd.modems.abstract.mediator.NetworkGetStatus object at 0x8811d0>>, <bound method NetworkGetStatus.genErrorFromChannel of <ogsmd.modems.abstract.mediator.NetworkGetStatus object at 0x8811d0>>, 10)])
2008.12.13 20:35:00 ogsmd    DEBUG    <MiscChannel via /dev/pts/7>: sending 10 bytes: 'AT+CPIN?\r\n'
2008.12.13 20:35:00 frameworkd.resource INFO     setting resource status for GSM from enabled to disabling
2008.12.13 20:35:00 ogsmd    DEBUG    |...|...|...|...|...|...|...|...|...> MiscChannel.close: ENTER (),{}
2008.12.13 20:35:00 ogsmd    DEBUG    |...|...|...|...|...|...|...|...|...> MiscChannel.close: LEAVE
2008.12.13 20:35:00 ogsmd    DEBUG    |...|...|...|...|...|...|...|...|...|...> UnsolicitedResponseChannel.close: ENTER (),{}
2008.12.13 20:35:00 ogsmd    DEBUG    |...|...|...|...|...|...|...|...|...|...> UnsolicitedResponseChannel.close: LEAVE
2008.12.13 20:35:00 ogsmd    DEBUG    |...|...|...|...|...|...|...|...|...> CallChannel.close: ENTER (),{}
2008.12.13 20:35:00 ogsmd    DEBUG    |...|...|...|...|...|...|...|...|...> CallChannel.close: LEAVE
2008.12.13 20:35:01 frameworkd.resource INFO     setting resource status for GSM from disabling to disabled
2008.12.13 20:35:01 ousaged  INFO     Disabled GSM in 0.5 seconds
Traceback (most recent call last):
  File "/var/lib/python-support/python2.5/framework/subsystems/ogsmd/gsm/channel.py", line 460, in _handleCommandTimeout
    self.serial.write( "\x1A" )
  File "/usr/lib/python2.5/site-packages/serial/serialposix.py", line 328, in write
    if self.fd is None: raise portNotOpenError
serial.serialutil.SerialException: Port not open

comment:5 Changed 3 years ago by mickey

Can you retry with ms5?

comment:6 Changed 3 years ago by daniel

This probably is a race condition in the resource transitions. It looks to me like we'er trying to resume GSM although it has been disabled. In general suspend should wait if any resource is in the "disabling" state (actually if it is in any *ing state) until it has completed the transition.

comment:7 Changed 2 years ago by mickey

Status changed from new to closed
Resolution set to fixed

I can't seem to reproduce this using fsousaged. Please reopen, if you can.

Note: See TracTickets for help on using tickets.

Download in other formats: