Investigation of failure to report received SMS

[Neil Jerram]

I'm not sure if this is really news.  Apologies if not.  I've been
experiencing a lot of unreported SMSs - by which I mean that the phone
receives an SMS, but it is not announced at the time of receipt - and
have just managed to catch some useful logs for an occurrence of this.

There's at least one ticket in FSO trac in this area
(http://trac.freesmartphone.org/ticket/506), but it claims only to
happen after a suspend.  In my Debian system I never suspend (because
it doesn't work), so I don't think that can be an ingredient in my
cases.

When this happens, I only find out about the SMSs later, usually after
a reboot or restarting zhone, because those actions cause a complete
new read of the message book.  The timestamp on the SMSs shows when
they were really received by the phone.  (I assume - does it make
sense that the network or the modem itself would add a timestamp?)

Today I received two SMSs (actually two parts of a CSM message) with
times 17:32:11 and 17:32:12.  The frameworkd log around that time says

2010.01.29 17:24:03.875 ogsmd.device         INFO
org.freesmartphone.GSM.Network.SignalStrength: 81
2010.01.29 17:25:22.975 ogsmd.device         INFO
org.freesmartphone.GSM.Network.SignalStrength: 86
2010.01.29 17:32:21.670 ogsmd.device         INFO
org.freesmartphone.GSM.Network.CypherStatus: enabled: unknown
2010.01.29 17:32:27.515 ogsmd.device         INFO
org.freesmartphone.GSM.Network.CypherStatus: enabled: unknown
2010.01.29 17:33:00.575 ogsmd.device         INFO
org.freesmartphone.GSM.Network.SignalStrength: 81
2010.01.29 17:35:04.865 ogsmd.device         INFO
org.freesmartphone.GSM.Network.SignalStrength: 86

For comparison, the frameworkd log around the time of a successful receipt says

2010.01.29 18:20:56.289 ogsmd.device         INFO
org.freesmartphone.GSM.Network.SignalStrength: 87
2010.01.29 18:21:15.8 odeviced.idlenotifier INFO
odeviced.idlenotifier state change to idle_dim
2010.01.29 18:23:04.205 ogsmd.device         INFO
org.freesmartphone.GSM.Network.CypherStatus: enabled: unknown
2010.01.29 18:23:06.790 ogsmd.device         WARNING  incoming message
on sim storage index 6
2010.01.29 18:23:06.816 oeventsd.fso_triggers WARNING  Receive
IncomingMessage on index = 6
2010.01.29 18:23:09.89 odeviced.audio       INFO     sound status
/usr/share/sounds/yue-fso/jmf2.ogg playing {}

(Note that I've raised some logs about incoming messages from DEBUG to
WARNING, for this investigation.)

Those CypherStatus logs look like a clue to me.  My guesses are that
the CypherStatus message is something to do with the encoding or
encryption of the subsequent SMS, and that sometimes frameworkd fails
to cope with receiving two messages in quick succession from the
modem.

I will carry on looking into this, but if anyone has any thoughts or
input, or if this is all already well understood, please say.

Regards,
        Neil