SIM not ready

[Michael 'Mickey' Lauer]

Am Freitag, den 18.07.2008, 11:05 +0800 schrieb Guillaume Chereau:
> On Thu, 2008-07-17 at 19:40 +0200, Michael 'Mickey' Lauer wrote:
> > Charlie,
> > 
> > we talked about a bug where you receive a SIM not ready when accessing
> > the phonebook/messagebook. Can you reproduce that and send me the full
> > log of ogsmd (with FRAMEWORK_DEBUG=1) from a failed run, please?
> > 
> > Did this happen in-between normal operation or right after a toggle of
> > SetAntennaPower?
> > 
> > :M:
> > 
> 
> Hi,
> 
> The problem happens when I do this sequence of operations (apparently
> independently of what I do before) :
> 
> RetrievePhonebook()
> # Don't wait
> StoreEntry(index, "test", "0287515071")
> 
> where index is a valid index.
> 
> When I try this I get the following answer :
> DBusException: org.freesmartphone.GSM.Device.Failed: DeviceFailed:
> org.freesmartphone.GSM.Device.Failed: Unhandled CME ERROR: SIM busy
> 
> If I put a time.sleep(10) between the operations then it works (I can
> then check that the entry is indeed correctly added)
> 
> So I guess the problem is just a matter of having a method like
> WaitReady(), or maybe a Signal, or both.
> 
> 
> The trace from ogsmd is  :
> 
>  |...|...|...|...|...|...> SimStoreEntry.__init__: ENTER (<framework.subsystems.ogsmd.objects.Device at /org/freesmartphone/GSM/Device at 0x2cdb30>, <function <lambda> at 0x442f70>, <function <lambda> at 0x442470>),{'index': dbus.Int32(9), 'number': dbus.String(u'0287515071'), 'name': dbus.String(u'test')} 
>  |...|...|...|...|...|...> SimStoreEntry.__init__: LEAVE 
>  |...|...|...|...|...|...|...|...> MiscChannel.enqueue: ENTER (u'+CPBS="SM";+CPBW=9,"0287515071",129,"test"', <bound method SimStoreEntry.responseFromChannel of <ogsmd.modems.abstract.mediator.SimStoreEntry object at 0x40757290>>, <bound method SimStoreEntry.errorFromChannel of <ogsmd.modems.abstract.mediator.SimStoreEntry object at 0x40757290>>),{} 
>  |...|...|...|...|...|...|...|...> MiscChannel.enqueue: LEAVE 
>  |...|...|...> MiscChannel._readyToSend: ENTER (13, 4),{} 
>  |...|...|...|...|...> MiscChannel.readyToSend: ENTER (),{} 
> (<framework.subsystems.ogsmd.modems.ti_calypso.channel.MiscChannel object at 0x335bd0>: sending 46 bytes to /dev/pts/2: u'AT+CPBS="SM";+CPBW=9,"0287515071",129,"test"\r\n')
>  |...|...|...|...|...> MiscChannel.readyToSend: LEAVE 
>  |...|...|...> MiscChannel._readyToSend: LEAVE 
>  |...|...|...> MiscChannel._readyToRead: ENTER (13, 1),{} 
> (<framework.subsystems.ogsmd.modems.ti_calypso.channel.MiscChannel object at 0x335bd0>: got 18 bytes from /dev/pts/2: '\r\n+CME ERROR: 14\r\n')
>  |...|...|...|...|...> MiscChannel.readyToRead: ENTER ('\r\n+CME ERROR: 14\r\n',),{} 
>  |...|...|...|...|...|...|...|...|...|...> MiscChannel._handleResponseToRequest: ENTER (['+CME ERROR: 14'],),{} 
> (<framework.subsystems.ogsmd.modems.ti_calypso.channel.MiscChannel object at 0x335bd0>: COMPLETED 'AT+CPBS="SM";+CPBW=9,"0287515071",129,"test"' => ['+CME ERROR: 14'])
>  |...|...|...|...|...|...|...|...|...|...|...|...|...> SimStoreEntry.responseFromChannel: ENTER (u'AT+CPBS="SM";+CPBW=9,"0287515071",129,"test"', ['+CME ERROR: 14']),{} 
>  |...|...|...|...|...|...|...|...|...|...|...|...|...|...|...> SimStoreEntry._handleCmeCmsExtError: ENTER ('+CME ERROR: 14',),{} 
>  |...|...|...|...|...|...|...|...|...|...|...|...|...|...|...> SimStoreEntry._handleCmeCmsExtError: LEAVE 
>  |...|...|...|...|...|...|...|...|...|...|...|...|...> SimStoreEntry.responseFromChannel: LEAVE 
>  |...|...|...|...|...|...|...|...|...|...|...> SimStoreEntry.__del__: ENTER (),{} 
>  |...|...|...|...|...|...|...|...|...|...|...> SimStoreEntry.__del__: LEAVE 
>  |...|...|...|...|...|...|...|...|...|...> MiscChannel._handleResponseToRequest: LEAVE 
>  |...|...|...|...|...> MiscChannel.readyToRead: LEAVE 
>  |...|...|...> MiscChannel._readyToRead: LEAVE 
>  |...|...|...> MiscChannel._readyToSend: ENTER (13, 4),{} 
>  |...|...|...|...|...> MiscChannel.readyToSend: ENTER (),{} 
>  |...|...|...|...|...> MiscChannel.readyToSend: LEAVE 
>  |...|...|...> MiscChannel._readyToSend: LEAVE 
>  |...|...|...> UnsolicitedResponseChannel._readyToRead: ENTER (14, 1),{} 
> (<framework.subsystems.ogsmd.modems.ti_calypso.channel.UnsolicitedResponseChannel object at 0x335af0>: got 16 bytes from /dev/pts/3: '%CSTAT: PHB, 1\r\n')
>  |...|...|...|...|...> UnsolicitedResponseChannel.readyToRead: ENTER ('%CSTAT: PHB, 1\r\n',),{} 
>  |...|...|...|...|...|...|...|...|...|...> UnsolicitedResponseChannel._handleUnsolicitedResponse: ENTER (['%CSTAT: PHB, 1'],),{} 
> (<framework.subsystems.ogsmd.modems.ti_calypso.channel.UnsolicitedResponseChannel object at 0x335af0>: unsolicited data incoming: %CSTAT: PHB, 1)
>  |...|...|...|...|...|...|...|...|...|...> UnsolicitedResponseChannel._handleUnsolicitedResponse: LEAVE 
>  |...|...|...|...|...> UnsolicitedResponseChannel.readyToRead: LEAVE 
>  |...|...|...> UnsolicitedResponseChannel._readyToRead: LEAVE 
> framework: 'framework.subsystems.odeviced.idlenotifier state change to IDLE'
> framework: 'framework.subsystems.odeviced.idlenotifier state change to IDLE_DIM'
> 
> 
> 
> 
> I also see something a little bit strange : If I call
> RetrievePhonebook() before doing a call, then it returns an empty list.
> 
> That is : with this sequence of operations :
> 
>   SetAntennaPower
>   Register
>   Initiate
>   # Wait for CallStatus outgoing
>   Release
>   # Wait for CallStatus inactive
>   RetrievePhonebook
> 
> It works (I get the phone book)
> 
> But with this one :
> 
>   SetAntennaPower
>   Register
>   RetrievePhonebook
> 
> I get en empty phone book
> Not sure if I forget to do something or if it is a bug, but in any case,
> I'll prefer RetrievePhonebook raising an exception instead of returning
> an empty list.
> 
> should I open a ticket ? 

Yes, please.

This is a really good bug report, by the way, thanks. I have enough
information to fix it now.

:M: