High costs due to SMS being sent multiple times

[Niklas Wenzel]

When sending text messages, Ubuntu displays the loading spinner for a very long time. In the provider's monthly reports, I can see that the message has been sent multiple times, even though I only sent one message to one recipient and the message was short enough not to be broken into separate ones.

======= Old description: =======

When having a bad network connection, Ubuntu tries to send SMS multiple times but fails to recognize which messages have already been sent, resulting in very high costs due to the same message actually being sent several times.

I found this when looking through my provider's monthly reports and I remember being on train journeys with very bad network connections on these days. See the attached screenshots.

==========

This happened on a Nexus 4 running on the stable channel (with up-to-date images at the given times).

[Niklas Wenzel (nikwen)]

The worst one.

[Niklas Wenzel (nikwen)]

Another one.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Matthias Apitz (gubu)]

What I do not fully understand is: AFAIK SMS is sent upstream to the provider with AT cmds, like this example:

AT+CMGF=1
OK
AT+CMGS="+49170xxxxxxxxxx"
<CR>This is the text message.
+CMGS: 4711
OK

(+CMGF=1 is text mode, =1 PDU mode).

The response from the provider could be OK or ERROR. Have you looked into the MySQL database in the phone to see what is there about the messages. If you need how to look into, see here: http://www.unixarea.de/bq/bq-aquaris-e45-ubuntu.txt (chap. 15).

[Niklas Wenzel (nikwen)]

Thank you for your reply, Matthias!

There is only one line in the database per message. Both rows have a messageStatus of 4 which seems to be correct.

[Matthias Apitz (gubu)]

El domingo, 2 de agosto de 2015 13:38:47 (CEST), Niklas Wenzel escribió:
> Thank you for your reply, Matthias!
>
> There is only one line in the database per message. Both rows have a
> messageStatus of 4 which seems to be correct.
>

please specify exactly:
a) how many SMS you sent/typed
b) how many the provider made of them
c) check with the receivers, how many they received
d) check the times in the MySQL database with what the provider says

--
Sent from my Ubuntu phone
http://www.unixarea.de/

[Niklas Wenzel (nikwen)]

a) I sent one SMS every time.
b) Those were short enough to be sent as one SMS by the provider.
c) The receivers' phones are displaying only one SMS.
d) The MySQL database has only one entry both times.
   For the first screenshot its timestamp is 2015-07-12T19:31:58.664
   for the second one it says 2015-05-30T11:31:17.015.

[Matthias Apitz (gubu)]

comparing the database timestamps and the provider times (from the screenshots) we see:

database provider
19:31:58.664 21:32:05 ... 21:32:45
11:31:17.015 13:31:21 ... 13:31:32

i.e. (ignoring the 2 hour diff due to TZ) it seems that the database timestamp is made when the SMS is "queued" for delivery and not from the last send attempt;

are there other log files (the question goes to Canonical) about the send attempts?

[Niklas Wenzel (nikwen)]

Yes, after converting it to the right time zone (UTC+2) it becomes

21:31:58.664 21:32:05 ... 21:32:45
13:31:17.015 13:31:21 ... 13:31:32.

As I remember seeing the phone trying to send it for a relatively long time on July 12th, it really seems as if there is some issue with queueing the messages and recognizing when sending one failed.

Btw, thank you for your help. :)

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

What brings my attention here is that apparently the receiver is seeing only one message (comment #7). It is possible that the receiver phone detects receiving 2 messages that are exactly the same and shows only one, but I would say that is not usual.

I would like to know if in some case the receiver shows more than one message. It is not impossible that the operator is wrongly charging for non-sent SMS.

On the other hand, in the attached files it can be seen that messages are retried in quite regular intervals (between 5-7 seconds). It is possible that somewhere in the stack there is a 5 seconds time-out and the message is retried without actually waiting for some response from the modem, which is what should be done.

[Matthias Apitz (gubu)]

what we need here is the log file of the AT cmds chated with the modem; if there is rumor that it might go wrong (in bad network conditions) Canonical should clarify how to get them and how to make sure that they are not purged in short time;

[Matthias Apitz (gubu)]

the AT chats can be monitored online from the ring buffers with:

$ sudo /system/bin/logcat -b radio

but this does not help to analyze weeks later what was going on :-(

[Niklas Wenzel (nikwen)]

@Alfonso: Thank you very much for your response. I really hope that this will be fixed soon because I agree with your comment from the mailing list that this is "worrying".

[Matthias Apitz (gubu)]

this is how the SMS could be monitored on sending to the modem, but only "online" or short after the sending:

root@ubuntu-phablet:/home/phablet# /system/bin/logcat -b radio | tee /tmp/radio.out

(btw: one should better use: /system/bin/logcat -b radio -v time
to get as well the timestamps)

...
I/use-Rlog/RLOG-AT( 1821): AT read start
I/use-Rlog/RLOG-MUXD( 1234): [gsm0710muxd] 3557:main(): Frames received/dropped: 6560/0
I/use-Rlog/RLOG-MUXD( 1234): [gsm0710muxd] 1573:gsm0710_base_buffer_get_frame(): Get a complete frame. ch:2, ctrl:239, len:34
I/use-Rlog/RLOG-MUXD( 1234): [gsm0710muxd] 2162:extract_frames(): Writing 34 byte frame received on channel 2 to /dev/pts/5
I/use-Rlog/RLOG-MUXD( 1234): [gsm0710muxd] 2181:extract_frames(): write() returned. Written 34/34 bytes of frame to /dev/pts/5
D/use-Rlog/RLOG-AT( 1821):
D/use-Rlog/RLOG-AT( 1821): +ECSQ: 11, 99, -368, -400, -28
D/use-Rlog/RLOG-AT( 1821): AT< +ECSQ: 11, 99, -368, -400, -28
D/use-Rlog/RLOG-AT( 1821): RIL_URC_READER:+ECSQ: 11, 99, -368, -400, -28
D/use-Rlog/RLOG-AT( 1821): RIL_URC_READER Enter processLine
D/use-Rlog/RLOG-RIL( 1821): Nw URC:+ECSQ: 11, 99, -368, -400, -28
I/use-Rlog/RLOG-RILC( 1821): RIL(1) UNSOLICITED: UNSOL_SIGNAL_STRENGTH length:76
I/use-Rlog/RLOG-RILC( 1821): 01 00 00 00 F1 03 00 00 0B 00 00 00 63 00 00 00
I/use-Rlog/RLOG-RILC( 1821): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
I/use-Rlog/RLOG-RILC( 1821): 00 00 00 00 63 00 00 00 FF FF FF 7F FF FF FF 7F
I/use-Rlog/RLOG-RILC( 1821): 2D 01 00 00 FF FF FF 7F 01 00 00 00 00 00 00 00
I/use-Rlog/RLOG-RILC( 1821): 90 FE FF FF 70 FE FF FF E4 FF FF FF 0B 00 00 00
I/use-Rlog/RLOG-AT( 1821): AT read start
I/use-Rlog/RLOG-MUXD( 1234): [gsm0710muxd] 1573:gsm0710_base_buffer_get_frame(): Get a complete frame. ch:2, ctrl:239, len:34
I/use-Rlog/RLOG-MUXD( 1234): [gsm0710muxd] 2162:extract_frames(): Writing 34 byte frame received on channel 2 to /dev/pts/5
I/use-Rlog/RLOG-MUXD( 1234): [gsm0710muxd] 2181:extract_frames(): write() returned. Written 34/34 bytes of frame to /dev/pts/5
D/use-Rlog/RLOG-AT( 1821):
D/use-Rlog/RLOG-AT( 1821): +ECSQ: 11, 99, -372, -398, -24
D/use-Rlog/RLOG-AT( 1821): AT< +ECSQ: 11, 99, -372, -398, -24
D/use-Rlog/RLOG-AT( 1821): RIL_URC_READER:+ECSQ: 11, 99, -372, -398, -24
D/use-Rlog/RLOG-AT( 1821): RIL_URC_READER Enter processLine
D/use-Rlog/RLOG-RIL( 1821): Nw URC:+ECSQ: 11, 99, -372, -398, -24
I/use-Rlog/RLOG-RILC( 1821): RIL(1) UNSOLICITED: UNSOL_SIGNAL_STRENGTH length:76
I/use-Rlog/RLOG-RILC( 1821): 01 00 00 00 F1 03 00 00 0B 00 00 00 63 00 00 00
I/use-Rlog/RLOG-RILC( 1821): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
I/use-Rlog/RLOG-RILC( 1821): 00 00 00 00 63 00 00 00 FF FF FF 7F FF FF FF 7F
I/use-Rlog/RLOG-RILC( 1821): 2D 01 00 00 FF FF FF 7F 01 00 00 00 00 00 00 00
I/use-Rlog/RLOG-RILC( 1821): 8C FE FF FF 72 FE FF FF E8 FF FF FF 0B 00 00 00
I/use-Rlog/RLOG-AT( 1821): AT read start
I/use-Rlog/RLOG-MUXD( 1234): [gsm0710muxd] 3557:main(): Frames received/dropped: 6562/0
I/use-Rlog/RLOG-RILC( 1821): RIL(1) SOCKET REQUEST: SEND_SMS length:348
I/use-Rlog/RLOG-RILC( 1821): 19 00 00 00 27 02 00 00 02 00 00 00 FF FF FF FF
I/use-Rlog/RLOG-RILC( 1821): xx xx xx xx xx xx xx xx xx xx xx xx xx xx xx ...

[Niklas Wenzel (nikwen)]

This happened again yesterday. With GOOD network connection!!! But this time I was able to fetch the log file using the command Matthias posted.

[Niklas Wenzel (nikwen)]

Here's the log. (I x-ed out what I thought were some personal identifiers.)

[Niklas Wenzel (nikwen)]

(Btw, I'm using a SIM card from the German provider "Aldi Talk".)

[Niklas Wenzel (nikwen)]

Here's the new screenshot from my provider.

[Niklas Wenzel (nikwen)]

And it just happened again. I think I'll stop using my phone for SMS now!

[Matthias Apitz (gubu)]

in the attached log file of Cooment #16 is nothing about AT cmds or SMS, please check;

[Niklas Wenzel (nikwen)]

Yes, that's true. Instead, there is an "assertion failed" block less than 5 secons after each SMS that shows up in the web interface.

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

@Niklas, the radio log for mako is not very useful, could you attach /var/log/syslog and ~/.cache/upstart/* ?

[Niklas Wenzel (nikwen)]

@Alfonso, I'll do that later today. Thank you for your reply. :)
What logs from ~/.cache/upstart/ do you need? There are so many in there...

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

@Niklas, just do a tarball with it all and attach to the bug ;)

[Niklas Wenzel (nikwen)]

@Alfonso, It's not that I can't but that I don't want to upload all of my application logs. So which ones do you need?

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

@Niklas, application-failed.log*, application-legacy-dialer-app-.log*, dbus.log*, ofono-setup.log*, telephony-service-indicator.log* are of interest. Maybe you could send the logs to me via private e-mail if you do not feel comfortable posting them here.

[Niklas Wenzel (nikwen)]

@Alfonso Thanks. :)
I just built the tar file and will x out any personal information when I come home and then upload them.

[Niklas Wenzel (nikwen)]

@Alfonso, here you go. :)
I x-ed out all phone numbers and all personal identifiers.

[Niklas Wenzel (nikwen)]

Oh, and I decided to send you the syslog via email as it is simply to long to go through looking for information to censor. While it doesn't contain the part from August 10, it contains the part when the issue appeared yesterday.

[Niklas Wenzel (nikwen)]

Ok, it looks like I need to correct something here. The messages actually had to be splitted into multiple smaller ones. However, the number of messages being sent according to the provider is still too high.

The one from August 10 had 356 chars, the one from August 11 had 334 ones, so with 160 characters per message both should have fitted into 3 messages each if I'm not mistaken, right?

[Niklas Wenzel (nikwen)]

Ok, forget about this! I just found something out. Using some special characters (including some accents included in the name of the messages' recipient) lowers the character count per message to 70!!!
With that in mind, the length of each message perfectly translates to its costs. Sorry for all the inconvenience caused by this bug report!
I just wish we had some way to tell when messages get broken into multiple ones.

Anyway, thanks a lot for your help!!!

[Niklas Wenzel (nikwen)]

Here's the bug report for that: https://bugs.launchpad.net/ubuntu/+source/messaging-app/+bug/1484664