GNOME Bugzilla – Bug 696723
[MM 0.8] SMS parsing failure
Last modified: 2014-10-15 09:37:49 UTC
UMW190 with a Verizon SIM installed, CMGL=4 says: ModemManager[30613]: <debug> [1364406009.493937] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): --> 'AT+CMGL=4<CR>' ModemManager[30613]: <debug> [1364406009.616694] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): <-- '<CR><LF>+CMGL: 17,3,35<CR><LF>079100F40D1101000F001000B917118336058F300001954747A0E4ACF41F27298CDCE83C6EF371B0402814020<CR><LF>+CMGL: 15,3,35<CR><LF>079100F40D1101000F001000B917118336058F300001954747A0E4ACF41F27298CDCE83C6EF371B0402814020<CR><LF>+CMGL: 13,3,35<CR><LF>079100F40D1101000F001000B917118336058F300001954747A0E4ACF41F27298CDCE83C6EF371B0402814020<CR><LF>+CMGL: 11,3,35<CR><LF>079100F40D1101000F001000B917118336058F300 ModemManager[30613]: <debug> [1364406009.617126] [mm-iface-modem-messaging.c:762] load_initial_sms_parts_ready(): Couldn't load SMS parts from storage 'me': 'Couldn't parse SMS list response: only 2 fields parsed' ModemManager[30613]: <debug> [1364406009.617189] [mm-broadband-modem.c:5843] modem_messaging_load_initial_sms_parts(): Listing SMS parts in storage 'sm' ModemManager[30613]: <debug> [1364406009.617234] [mm-broadband-modem.c:5026] mm_broadband_modem_lock_sms_storages(): Locking SMS storages to: mem1 (SM), mem2 (none)... Haven't looked into it, just dumping it here.
The +CMGL response here doesn't contain 4 fields as we expected, so instead of: +CMGL: <index>,<status>,<alpha>,<length>\r\n<PDU> it has: +CMGL: <index>,<status>,<something>\r\n<PDU>
I pushed a fix to the "aleksander/pantech-sms-fixes" branch which covers this issue, and tested with an Option modem to make sure I didn't break the previous logic. Dan, could you test it with the UMW190?
Fix parses the CMGL correctly, but the SMS decoding doesn't appear to work because the hex PDUs that the UMW190 returns have an odd number of bytes. Thus hex -> binary decoding fails. Note that all of them are the exact same message. Switching to text mode gives us: +CMGR: "STO SENT","<my phone # in UCS2" 00540068006900730020006900730020007200650061006C006C007900200063006F006F006C002000200020002000200020 where the message body is 'This is really cool ' which is actually an SMS message I have sent from the device when testing SMS sending at one point. So clearly the message is there, but perhaps the UMW190 is mangling the PDU or something? I don't have time to decode the PDU and match it up to the text mode data right now.
Next best thing about the UMW190; USB interface 4 is normally detected as an AT port because it actually replies to AT commands during probing: ModemManager[27915]: <debug> [1364853607.277726] [mm-at-serial-port.c:408] debug_log(): (ttyUSB6): --> 'ATE0<CR>' ModemManager[27915]: <debug> [1364853607.285704] [mm-at-serial-port.c:408] debug_log(): (ttyUSB6): <-- '<CR><LF>ERROR<CR><LF>' ... ModemManager[27915]: <debug> [1364853607.465752] [mm-at-serial-port.c:408] debug_log(): (ttyUSB6): --> 'AT+CMER=3,0,0,1<CR>' ModemManager[27915]: <debug> [1364853607.483446] [mm-at-serial-port.c:408] debug_log(): (ttyUSB6): <-- '<CR><LF>ERROR<CR><LF>' because it's the WMC port, which accepts WMC commands using WMC encapsulation that actually uses at commands (AT*WMC=xxxx). You don't get incoming SMS notification via the AT ports, you get them via the *WMC* port: ModemManager[27915]: <debug> [1364853855.469749] [mm-at-serial-port.c:408] debug_log(): (ttyUSB6): <-- '\200}1}"} } } 00~' how cool is that? NOT.
ModemManager does correctly parse a new SMS sent *to* the device, so I think our problem is just parsing the "STO SENT" messages already in the device. Not a block for 0.8.
(In reply to comment #4) > Next best thing about the UMW190; USB interface 4 is normally detected as an AT > port because it actually replies to AT commands during probing: > > ModemManager[27915]: <debug> [1364853607.277726] [mm-at-serial-port.c:408] > debug_log(): (ttyUSB6): --> 'ATE0<CR>' > ModemManager[27915]: <debug> [1364853607.285704] [mm-at-serial-port.c:408] > debug_log(): (ttyUSB6): <-- '<CR><LF>ERROR<CR><LF>' > ... > ModemManager[27915]: <debug> [1364853607.465752] [mm-at-serial-port.c:408] > debug_log(): (ttyUSB6): --> 'AT+CMER=3,0,0,1<CR>' > ModemManager[27915]: <debug> [1364853607.483446] [mm-at-serial-port.c:408] > debug_log(): (ttyUSB6): <-- '<CR><LF>ERROR<CR><LF>' > > because it's the WMC port, which accepts WMC commands using WMC encapsulation > that actually uses at commands (AT*WMC=xxxx). > What would be a good way to detect that a port is WMC? We could add that into the probing logic. Maybe an initial check to see if "AT" itself gives "ERROR", and if it does, check if an AT*WMC command works? > You don't get incoming SMS notification via the AT ports, you get them via the > *WMC* port: > > ModemManager[27915]: <debug> [1364853855.469749] [mm-at-serial-port.c:408] > debug_log(): (ttyUSB6): <-- '\200}1}"} } } 00~' > > how cool is that? NOT. Is that an actual PDU sent raw in the port? Or a WMC binary stream?
(In reply to comment #3) > Fix parses the CMGL correctly, I merged the CMGL parsing fix, leaving the bug open until the PDU parsing fix is done.
> ModemManager[30613]: <debug> [1364406009.493937] [mm-at-serial-port.c:397] > debug_log(): (ttyACM0): --> 'AT+CMGL=4<CR>' > ModemManager[30613]: <debug> [1364406009.616694] [mm-at-serial-port.c:397] > debug_log(): (ttyACM0): <-- '<CR><LF>+CMGL: > 17,3,35<CR><LF>079100F40D1101000F001000B917118336058F300001954747A0E4ACF41F27298CDCE83C6EF371B0402814020<CR><LF>+CMGL: > 15,3,35<CR><LF>079100F40D1101000F001000B917118336058F300001954747A0E4ACF41F27298CDCE83C6EF371B0402814020<CR><LF>+CMGL: > 13,3,35<CR><LF>079100F40D1101000F001000B917118336058F300001954747A0E4ACF41F27298CDCE83C6EF371B0402814020<CR><LF>+CMGL: > 11,3,35<CR><LF>079100F40D1101000F001000B917118336058F300 > ModemManager[30613]: <debug> [1364406009.617126] Just wondering... are these the real PDU contents, or did you fix them to add them to the bugreport? The SMSC address reports 7 digits, but it just contains 3 (004)...
(In reply to comment #6) > (In reply to comment #4) > > Next best thing about the UMW190; USB interface 4 is normally detected as an AT > > port because it actually replies to AT commands during probing: > > > > ModemManager[27915]: <debug> [1364853607.277726] [mm-at-serial-port.c:408] > > debug_log(): (ttyUSB6): --> 'ATE0<CR>' > > ModemManager[27915]: <debug> [1364853607.285704] [mm-at-serial-port.c:408] > > debug_log(): (ttyUSB6): <-- '<CR><LF>ERROR<CR><LF>' > > ... > > ModemManager[27915]: <debug> [1364853607.465752] [mm-at-serial-port.c:408] > > debug_log(): (ttyUSB6): --> 'AT+CMER=3,0,0,1<CR>' > > ModemManager[27915]: <debug> [1364853607.483446] [mm-at-serial-port.c:408] > > debug_log(): (ttyUSB6): <-- '<CR><LF>ERROR<CR><LF>' > > > > because it's the WMC port, which accepts WMC commands using WMC encapsulation > > that actually uses at commands (AT*WMC=xxxx). > > > > What would be a good way to detect that a port is WMC? We could add that into > the probing logic. Maybe an initial check to see if "AT" itself gives "ERROR", > and if it does, check if an AT*WMC command works? We can use libwmc to send the buffer returned by wmc_cmd_init_new() (set wmc2 to TRUE for now) and then parse the result; if it parses, then it's WMC. With WMCv2 and v3 formats, the command is *sent* with AT encapsulation (AT*WMC=xxxx\r\n) but the reply is pure binary with no AT encapsulation. > > > You don't get incoming SMS notification via the AT ports, you get them via the > > *WMC* port: > > > > ModemManager[27915]: <debug> [1364853855.469749] [mm-at-serial-port.c:408] > > debug_log(): (ttyUSB6): <-- '\200}1}"} } } 00~' > > > > how cool is that? NOT. > > Is that an actual PDU sent raw in the port? Or a WMC binary stream? I'm pretty sure that's not the PDU, that's just an indication that a new SMS has arrived. The PDU for this case was something like "asdfasdfasdfasdf" and the contents of the WMC indication don't match up. What we could do is listen for the WMC indication and then reload all the SMS messages and compare? Not too important though, I think WMC is hopefully going away in the future.
(In reply to comment #8) > > ModemManager[30613]: <debug> [1364406009.493937] [mm-at-serial-port.c:397] > > debug_log(): (ttyACM0): --> 'AT+CMGL=4<CR>' > > ModemManager[30613]: <debug> [1364406009.616694] [mm-at-serial-port.c:397] > > debug_log(): (ttyACM0): <-- '<CR><LF>+CMGL: > > 17,3,35<CR><LF>079100F40D1101000F001000B917118336058F300001954747A0E4ACF41F27298CDCE83C6EF371B0402814020<CR><LF>+CMGL: > > 15,3,35<CR><LF>079100F40D1101000F001000B917118336058F300001954747A0E4ACF41F27298CDCE83C6EF371B0402814020<CR><LF>+CMGL: > > 13,3,35<CR><LF>079100F40D1101000F001000B917118336058F300001954747A0E4ACF41F27298CDCE83C6EF371B0402814020<CR><LF>+CMGL: > > 11,3,35<CR><LF>079100F40D1101000F001000B917118336058F300 > > ModemManager[30613]: <debug> [1364406009.617126] > > Just wondering... are these the real PDU contents, or did you fix them to add > them to the bugreport? The SMSC address reports 7 digits, but it just contains > 3 (004)... These are the real PDUs from the device, not modified. I also noticed the wrong SMSC address but didn't have time to look into it.
(In reply to comment #10) > (In reply to comment #8) > > > ModemManager[30613]: <debug> [1364406009.493937] [mm-at-serial-port.c:397] > > > debug_log(): (ttyACM0): --> 'AT+CMGL=4<CR>' > > > ModemManager[30613]: <debug> [1364406009.616694] [mm-at-serial-port.c:397] > > > debug_log(): (ttyACM0): <-- '<CR><LF>+CMGL: > > > 17,3,35<CR><LF>079100F40D1101000F001000B917118336058F300001954747A0E4ACF41F27298CDCE83C6EF371B0402814020<CR><LF>+CMGL: > > > 15,3,35<CR><LF>079100F40D1101000F001000B917118336058F300001954747A0E4ACF41F27298CDCE83C6EF371B0402814020<CR><LF>+CMGL: > > > 13,3,35<CR><LF>079100F40D1101000F001000B917118336058F300001954747A0E4ACF41F27298CDCE83C6EF371B0402814020<CR><LF>+CMGL: > > > 11,3,35<CR><LF>079100F40D1101000F001000B917118336058F300 > > > ModemManager[30613]: <debug> [1364406009.617126] > > > > Just wondering... are these the real PDU contents, or did you fix them to add > > them to the bugreport? The SMSC address reports 7 digits, but it just contains > > 3 (004)... > > These are the real PDUs from the device, not modified. I also noticed the > wrong SMSC address but didn't have time to look into it. I have a branch which allows wrong length of the address reported, and the parsing goes a bit further, but still doesn't completely fix it. Will give it more time another day.
Moving bugreport to the new ModemManager bugzilla in fd.o; summarized the issue there as well. Please subscribe to the new bugreport to get new updates. https://bugs.freedesktop.org/show_bug.cgi?id=85045 Closing this report as NOTGNOME.