Ticket #291 (closed defect: fixed)
framework could not handle sms from taiwanese SIM
| Reported by: | vegyraupe | Owned by: | daniel |
|---|---|---|---|
| Priority: | major | Milestone: | milestone5.5 |
| Component: | framework/ogsmd/sms | Version: | |
| Keywords: | Cc: | mirko@… |
Description (last modified by jluebbe) (diff)
i tried to access the messagebook on a taiwanese SIM today and always got a dbus timeout. What i did was (in a larger file, this is an excerpt):
import dbus
bus = dbus.SystemBus(mainloop=tichy.mainloop.dbus_loop)
self.gsm = bus.get_object('org.freesmartphone.ogsmd','/org/freesmartphone/GSM/Device')
self.gsm_sim = dbus.Interface(self.gsm,'org.freesmartphone.GSM.SIM')
self.messages = self.gsm_sim.RetrieveMessagebook('all')
The traceback i get is:
2008.12.06 07:09:23 ogsmd ERROR unhandled exception in response callback: 'utf16' codec can't decode byte 0xff in position 110: truncated data
Traceback (most recent call last):
File "/usr/lib/python2.5/site-packages/framework/subsystems/ogsmd/gsm/channel.py", line 379, in handleResponseToRequest
ok_cb( reqstring.strip(), response )
File "/usr/lib/python2.5/site-packages/framework/subsystems/ogsmd/gsm/decor.py", line 45, in logIt
result = fn( *args, **kwargs )
File "/usr/lib/python2.5/site-packages/framework/subsystems/ogsmd/modems/abstract/mediator.py", line 772, in responseFromChannel
sms = ogsmd.gsm.sms.decodeSMS( line, dir)
File "/usr/lib/python2.5/site-packages/framework/subsystems/ogsmd/gsm/sms.py", line 98, in decodeSMS
parse_userdata( sms, ud_len, bytes[offset:] )
File "/usr/lib/python2.5/site-packages/framework/subsystems/ogsmd/gsm/sms.py", line 136, in parse_userdata
sms.ud = userdata.decode( sms.dcs_alphabet )
File "/usr/lib/python2.5/encodings/utf_16_be.py", line 16, in decode
return codecs.utf_16_be_decode(input, errors, True)
UnicodeDecodeError: 'utf16' codec can't decode byte 0xff in position 110: truncated data
/mirko
Change History
comment:2 Changed 3 years ago by mickey
Can you please reproduce this problem with setting the log level to DEBUG in /etc/frameworkd.conf?
[frameworkd] log_level = DEBUG
comment:3 Changed 3 years ago by mickey
- Owner changed from jluebbe to mickey
- Component changed from framework/ousaged to framework/ogsmd
comment:4 follow-up: ↓ 6 Changed 3 years ago by daniel
In order to debug that problem I need the PDU of the message (for example through a log with log_level set to DEBUG)
comment:5 Changed 3 years ago by jluebbe
- Status changed from new to assigned
- Owner changed from mickey to daniel
- Milestone set to milestone5
comment:6 in reply to: ↑ 4 Changed 3 years ago by vegyraupe
Replying to daniel:
In order to debug that problem I need the PDU of the message (for example through a log with log_level set to DEBUG)
The output above was DEBUG. Right now I am not in possession of the SIM, but I'll try to get someone else to reproduce the error and paste the frameworkd output here.
comment:7 Changed 3 years ago by daniel
Please add log_level=DEBUG to the [ogsmd] section. That should enable gsm debugging. Also setting log_to=file and log_destination=/path/to/log and attaching the file to this bug would be great.
(Not sure how you're doing that right now)
comment:9 follow-up: ↓ 11 Changed 3 years ago by daniel
Mirko, any news here?
I still need the PDU to debug this error thoroughly.
comment:10 Changed 3 years ago by vegyraupe
I wrote a mail to the SIM's owner asking for 5 minutes of his time to reproduce the error. Will get back asap.
comment:11 in reply to: ↑ 9 Changed 3 years ago by vegyraupe
Replying to daniel:
Mirko, any news here?
I still need the PDU to debug this error thoroughly.
We reproduced the error. Here is the log, hope it helps, if you need more, jsut let me/us know.
2009.01.15 18:17:26 ogsmd.channel DEBUG <MiscChannel? via /dev/pts/0>: got 16 bytes from: '+CMGL: 9,193\r\n' 2009.01.15 18:17:26 ogsmd.channel DEBUG <MiscChannel? via /dev/pts/0>: got 204 bytes from: '0791889653782485440C918896937736370008901041914043234A0500030102024E0D67036709592A59277684554F984C624D662F00274E284E0D904E4E164E8B96E3659967094FDD96AA4E5F4E0D4E005B9A6BD48F035B8951680022000A002D002D000A\r\n' 2009.01.15 18:17:26 ogsmd.channel DEBUG <MiscChannel? via /dev/pts/0>: got 107 bytes from: '+CMGL: 10,133\r\n0791889653782485040C9188969377363700009010419150402310207A794E4FBBCFA076793E0F9FCB\r\n\r\nOK\r\n' 2009.01.15 18:17:26 ogsmd.channel DEBUG <MiscChannel? via /dev/pts/0>: COMPLETED 'AT+CMGL=4' => ['+CMGL: 1,1126', '079188966300000904038177F70008202131116521236F6B618FCE4F7F7528906050B396FB4FE1670D52D9002E4F9D96FB7E3D898F5B9A8ACB63096307793A586B5BEB530588DD4E0A5BA262368CC7659953614E2656DE50B3002C0020906050B35C0765BC653652305F8C003200345C0F6642516770BA60A8958B901A672C9580865F002EFF', '+CMGL: 2,1137', '079188966300000904038177F70010409030215174238B5076393C2F83CC69361BF4AED3412690398C07A5DD203ABA0C1AD6E7F477BB2C0725DDE6B7BC1DA6A7DF6ED0302C2783C2747A788C2E9341F43728FFAECB41F0F078ED0281B2EFBA1CD47E8BD3EC32E89E66B341E232283CA6A7ED617A990CBAA7E9E8B41B24A381D0EFBA7C0EAAC3DF6E90BC3C2EA7ED65B20B', '+CMGL: 3,177', '0791889663000019040C918896631030990008802170917500233A672A63A54F8696FB003000320032003700350038003000310033003800200031901A00310032002F00300037002000310039003A00350036000A', '+CMGL: 4,177', '0791889663001016040C918896631030990008901041911054233A672A63A54F8696FB003000390038003000340034003700370033003800200031901A00300031002F00310034002000310036003A00300033000A', '+CMGL: 5,1159', '0791889653782485440C918896937736370008901041913081238C050003000301006F00700065006E006D006F006B006F00200031003A000A0022621160F36211501176846C1172595C3E72595C319019717D687469BB69B47A316AA579BE70BA79BE548C54089BCA70BA4EBA4EE554084EE5548C70BA8CB4757065BC5E384EBA4E0D670354275929573067096B636C235E5585918591856953BB5BD2597D559D4E0D6703611F', '+CMGL: 6,1159', '0791889653782485440C918896937736370008901041913022238C05000300030266F076EE96DC611F4E00524752477A315947602A4E8B4E005806758A62105C716C344E4B959363A54E2D50B75175712165784EF68863670D52D95BE6969B670354E167977ACB583457304E3B5E2D57309EDE5FC3740660F389814EF64E0D5B58572858345730534057DF4E2D5FC39748580267038AC75230905489C08CDE8CDC59D36C0F0022', '+CMGL: 7,133', '0791889653782485440C918896937736370008901041913042230E050003000303000A002D002D000A', '+CMGL: 8,1159', '0791889653782485440C918896937736370008901041914013238C050003010201006F00700065006E006D006F006B006F00200031003A000A00229019500B93758FA8597D96E35BEB4E28300170BA4EC09EBC59296C2390199EBC51B7003F59297A7A7070707076848AB053D776844E86554A0021624B5BEB8FA88996529F80FD770B8D774F8665B94FBF591A4E86002C53EA89815B574E0D592A96E3770B768461C98A7290FD', '+CMGL: 9,193', '0791889653782485440C918896937736370008901041914043234A0500030102024E0D67036709592A59277684554F984C624D662F00274E284E0D904E4E164E8B96E3659967094FDD96AA4E5F4E0D4E005B9A6BD48F035B8951680022000A002D002D000A', '+CMGL: 10,133', '0791889653782485040C9188969377363700009010419150402310207A794E4FBBCFA076793E0F9FCB', 'OK'] 2009.01.15 18:17:26 ogsmd.channel ERROR unhandled exception in response callback: 'utf16' codec can't decode byte 0xff in position 110: truncated data Traceback (most recent call last):
File "/usr/lib/python2.5/site-packages/framework/subsystems/ogsmd/gsm/channel.py", line 392, in handleResponseToRequest
ok_cb( reqstring.strip(), response )
File "/usr/lib/python2.5/site-packages/framework/subsystems/ogsmd/modems/abstract/mediator.py", line 885, in responseFromChannel
sms = ogsmd.gsm.sms.SMS.decode( line, direction )
File "/usr/lib/python2.5/site-packages/framework/subsystems/ogsmd/gsm/sms.py", line 182, in decode
sms._parse_userdata( ud_len, bytes[offset:] )
File "/usr/lib/python2.5/site-packages/framework/subsystems/ogsmd/gsm/sms.py", line 241, in _parse_userdata
self.ud = userdata.decode( self.dcs_alphabet )
File "/usr/lib/python2.5/encodings/utf_16_be.py", line 16, in decode
return codecs.utf_16_be_decode(input, errors, True)
UnicodeDecodeError?: 'utf16' codec can't decode byte 0xff in position 110: truncated data 2009.01.15 18:17:26 ogsmd.channel DEBUG <MiscChannel? via /dev/pts/0>: sending 26 bytes: 'AT+CPBS="SM";+CPBR=1,140\r\n' 2009.01.15 18:17:26 ogsmd.channel DEBUG <MiscChannel? via /dev/pts/0>: got 6 bytes from: '\r\nOK\r\n' 2009.01.15 18:17:26 ogsmd.channel DEBUG <MiscChannel? via /dev/pts/0>: COMPLETED 'AT+CPBS="SM";+CPBR=1,140' => OK?
comment:12 Changed 3 years ago by charlie
I have a log file of this problem, can't attach it to the trac system, I don't know the reason...
Here is the end of the log file :
2009.01.16 11:33:12 ogsmd DEBUG <MiscChannel via /dev/pts/2>: got 17 bytes from: '+CMGL: 35,3,,22\r\n'
2009.01.16 11:33:12 ogsmd DEBUG <MiscChannel via /dev/pts/2>: got 62 bytes from: '0791889653784434013E0C9188969366423600000AE8329BFD06D1CB733A\r\n'
2009.01.16 11:33:12 ogsmd DEBUG <MiscChannel via /dev/pts/2>: got 17 bytes from: '+CMGL: 36,3,,23\r\n'
2009.01.16 11:33:12 ogsmd DEBUG <MiscChannel via /dev/pts/2>: got 64 bytes from: '0791889653784434013F0A81909366423600000CE8329BFD06D1CB733A4806\r\n'
2009.01.16 11:33:13 ogsmd DEBUG <MiscChannel via /dev/pts/2>: TIMEOUT 'AT+CMGL=4' => ???
2009.01.16 11:33:13 ogsmd DEBUG |...|...|...|...|...|...> SimRetrieveMessagebook.errorFromChannel: ENTER ('AT+CMGL=4', ('timeout', 10)),{}
2009.01.16 11:33:13 ogsmd DEBUG |...|...|...|...|...|...> SimRetrieveMessagebook.errorFromChannel: LEAVE
2009.01.16 11:33:13 ogsmd DEBUG |...|...|...|...|...> SimRetrieveMessagebook.__del__: ENTER (),{}
2009.01.16 11:33:13 ogsmd DEBUG |...|...|...|...|...> SimRetrieveMessagebook.__del__: LEAVE
2009.01.16 11:33:13 ogsmd DEBUG <MiscChannel via /dev/pts/2>: got 77 bytes from: '+CMGL: 37,1,,21\r\n0791889653704434240C9188969366423600008011529102802302C834\r\n'
2009.01.16 11:33:13 ogsmd INFO <MiscChannel via /dev/pts/2>: unhandled unsolicited data incoming: '+CMGL: 1,1,,148'
2009.01.16 11:33:13 ogsmd INFO <MiscChannel via /dev/pts/2>: unhandled unsolicited data incoming: '0791889653704434240C9188969366423600008011529102802302C834'
I haven't have a look at the code, but my guess is that the timeout is not reseted after each receiving of line from the CMGL reply...
comment:13 Changed 3 years ago by daniel
- Milestone changed from milestone5 to milestone6
The traceback itself should be fixed now, but the userdata will still not decode.
Charlie: The timeout should be a different issue, please open a new bug and attach the full log for it.
comment:14 Changed 3 years ago by daniel
- Component changed from framework/ogsmd to framework/ogsmd/sms
comment:15 Changed 3 years ago by daniel
- Status changed from assigned to accepted
Okay mirko, I got found the problem.
The message at position 4 is causing the problem.
'079188966300000904038177F70008202131116521236F6B618FCE4F7F7528906050B396FB4FE1670D52D9002E4F9D96FB7E3D898F5B9A8ACB63096307793A586B5BEB530588DD4E0A5BA262368CC7659953614E2656DE50B3002C0020906050B35C0765BC653652305F8C003200345C0F6642516770BA60A8958B901A672C9580865F002EFF'
The last two characters, FF seem to be padding and are added at the end of the message for some reason. I need to check whether the userdata length field actually tells us that this isn't part of the message any more and then cut it off.
comment:16 Changed 3 years ago by daniel
Really strange, the userdata length indicates 111 octets following, which is the UCS2 message *including* the 0xFF at the end.
Since UCS2 always has a character encoding of 2 bytes per character this is completely moot, there should never ever be UCS2 encoded user data with an odd number of octets... Now at least this isn't a multipart message and all your ucs2 encoded multipart messages are decoded okay so this alleviates my fear that multipart messages might be split in the middle of a ucs2 character.
comment:17 Changed 3 years ago by daniel
- Status changed from accepted to closed
- Resolution set to fixed
Okay, fixed in [0d1ce53f338ef1592701324118abdfe167b19bfe]. If userdata decoding fails for some reason we retry with relaxed error handling. Problematic characters will be replaced with the unicode replace character (\ufffd). I'm still not sure whether this is a valid short message and we should just ignore the 0xff, but unless you find me more messages or manage to reproduce this problem (i.e. send a message with the same length from the same phone and have this issue appear again) I'm going to maintain that this message is not completely to spec.
log before the error:
2008.12.06 07:24:06 oeventsd INFO Receive IdleState?, status = lock
2008.12.06 07:24:26 odeviced.idlenotifier INFO framework.subsystems.odeviced.idlenotifier state change to suspend
2008.12.06 07:24:26 oeventsd INFO DebugAction? : dbus trigger test
2008.12.06 07:24:26 oeventsd INFO Receive IdleState?, status = suspend
2008.12.06 07:24:26 oeventsd INFO Receive IdleState?, status = suspend
2008.12.06 07:24:26 oeventsd INFO Receive IdleState?, status = suspend
2008.12.06 07:29:50 frameworkd.resource INFO setting resource status for GSM from enabled to disabling
2008.12.06 07:29:51 frameworkd.resource INFO setting resource status for GSM from disabling to disabled
2008.12.06 07:29:51 ousaged INFO Disabled GSM in 0.5 seconds
2008.12.06 07:29:51 ousaged INFO Releasing GSM for vanished user :1.21
2008.12.06 07:30:10 frameworkd.resource INFO setting resource status for GSM from disabled to enabling
2008.12.06 07:30:11 ogsmd INFO <CallChannel? via unknown>: Creating channel with timeout = 3600 seconds
2008.12.06 07:30:11 ogsmd INFO <UnsolicitedResponseChannel? via unknown>: Creating channel with timeout = 10 seconds
2008.12.06 07:30:11 ogsmd INFO <MiscChannel? via unknown>: Creating channel with timeout = 10 seconds
2008.12.06 07:30:11 ogsmd WARNING Attempting to create the call handler more than once.
2008.12.06 07:30:21 ogsmd INFO <MiscChannel? via unknown>: initializing
2008.12.06 07:30:21 ogsmd INFO <MiscChannel? via /dev/pts/1>: responding OK
2008.12.06 07:30:21 ogsmd INFO <UnsolicitedResponseChannel? via unknown>: initializing
2008.12.06 07:30:21 ogsmd INFO <UnsolicitedResponseChannel? via /dev/pts/2>: responding OK
2008.12.06 07:30:21 ogsmd INFO <CallChannel? via unknown>: initializing
2008.12.06 07:30:21 ogsmd INFO <CallChannel? via /dev/pts/3>: responding OK
2008.12.06 07:30:21 frameworkd.resource INFO setting resource status for GSM from enabling to enabled
2008.12.06 07:30:21 ousaged INFO Enabled GSM in 10.9 seconds
2008.12.06 07:30:24 ogsmd INFO subsystem PHB readyness now False
2008.12.06 07:30:24 ogsmd.objects INFO sim ready status False
2008.12.06 07:30:24 ogsmd INFO full readyness now False
2008.12.06 07:30:25 ogsmd INFO subsystem PHB readyness now False
2008.12.06 07:30:25 ogsmd INFO full readyness now False
2008.12.06 07:30:25 ogsmd INFO subsystem PHB readyness now False
2008.12.06 07:30:25 ogsmd INFO full readyness now False
2008.12.06 07:30:25 ogsmd.objects INFO auth status changed to READY
2008.12.06 07:30:25 ogsmd INFO subsystem PHB readyness now False
2008.12.06 07:30:25 ogsmd INFO full readyness now False
2008.12.06 07:30:28 ogsmd INFO subsystem PHB readyness now False
2008.12.06 07:30:28 ogsmd INFO full readyness now False
2008.12.06 07:30:28 ogsmd INFO subsystem PHB readyness now False
2008.12.06 07:30:28 ogsmd INFO full readyness now False
2008.12.06 07:30:29 ogsmd INFO subsystem PHB readyness now False
2008.12.06 07:30:29 ogsmd INFO full readyness now False
2008.12.06 07:30:30 ogsmd INFO full readyness now False
2008.12.06 07:30:30 ogsmd INFO subsystem PHB readyness now False
2008.12.06 07:30:30 ogsmd INFO full readyness now False
2008.12.06 07:30:30 ogsmd INFO subsystem SMS readyness now True
2008.12.06 07:30:30 ogsmd INFO full readyness now False
2008.12.06 07:30:34 ogsmd INFO subsystem PHB readyness now True
2008.12.06 07:30:34 ogsmd.objects INFO sim ready status True
2008.12.06 07:30:34 ogsmd INFO full readyness now True
2008.12.06 07:30:39 ogsmd.objects INFO org.freesmartphone.GSM.Network.SignalStrength?: 89
2008.12.06 07:30:39 ogsmd.objects INFO org.freesmartphone.GSM.Network.Status: {'strength': 89, 'cid': '271F', 'registration': 'home', 'lac': '047F', 'mode': 'automatic', 'provider': 'FarEasTone?'}
2008.12.06 07:30:40 ogsmd.objects INFO org.freesmartphone.GSM.Network.Status: {'strength': 89, 'cid': '271F', 'registration': 'home', 'lac': '047F', 'mode': 'automatic', 'provider': 'FarEasTone?'}
2008.12.06 07:30:41 ogsmd.objects INFO org.freesmartphone.GSM.Network.SignalStrength?: 79
2008.12.06 07:30:42 ogsmd.objects INFO org.freesmartphone.GSM.Network.SignalStrength?: 90
2008.12.06 07:31:01 odeviced.idlenotifier INFO framework.subsystems.odeviced.idlenotifier state change to busy
2008.12.06 07:31:01 oeventsd INFO DebugAction? : dbus trigger test
2008.12.06 07:31:01 oeventsd INFO Receive IdleState?, status = busy
2008.12.06 07:31:01 oeventsd INFO call dbus signal /org/freesmartphone/Device/Display/pcf50633_bl SetBrightness?((90,))
2008.12.06 07:31:01 oeventsd INFO Receive IdleState?, status = busy
2008.12.06 07:31:02 oeventsd INFO Receive IdleState?, status = busy
2008.12.06 07:31:02 oeventsd INFO signal SetBrightness? responded : ()
2008.12.06 07:31:06 ogsmd.objects INFO org.freesmartphone.GSM.Network.SignalStrength?: 79