Operating system name and version:

Armbian

netadmin@zeropi:/var/www/html$ uname -a
Linux zeropi 5.4.28-sunxi #20.02.7 SMP Sat Mar 28 14:32:15 CET 2020 armv7l GNU/Linux


Version of smsd:

netadmin@zeropi:~$ apt show smstools
Package: smstools
Version: 3.1.21-3
Priority: optional
Section: comm
Maintainer: Debian Mobcom Maintainers <Debian-mobcom-maintainers@lists.alioth.debian.org>
Installed-Size: 1,150 kB
Depends: debconf (>= 1.4.69), ucf (>= 0.2, adduser, libc6 (>= 2.15), libmm14 (>= 1.4.0), lsb-base
Homepage: http://smstools3.kekekasvi.com
Tag: hardware::modem, role::program, use::transmission
Download-Size: 337 kB
APT-Manual-Installed: yes
APT-Sources: http://httpredir.debian.org/debian buster/main armhf Packages
Description: SMS server tools for GSM modems

Smsd installed from: sources / package repository / from elsewhere...

Armbian version of the Debian Buster package.

Name and model of a modem / phone:

USB modem, Qualcom 9600

Interface: serial / USB / some adapter...

USB ttyUSB0 to USB module



Hi All

I'm trying to configure an SMS gateway.

The hardware is a Zeropi

The operating system is Armbian

And the modem is a USB dongle:

Ebay origin here

This identifies as a Qualcom device, the vendor describes it -
Specification:
Type: Network Card
Chip: Qualcomm 9600


I have the server, operating system and the modem device set up and sort of working.

If I put a message in the output directory, it is sent, and a correct response generated and correctly received into the incoming directory.

However presumably it's dispatch is not correctly advised to smstools, as it is sent three times, receives three replies and then is moved to the failed directory.

I'm presently testing sending BAL messages to the network suppliers gateway using a short code.

smsd.conf has the following functional lines. I've removed comments for brevity

_________________________________________________________

devices = GSM1
outgoing = /var/spool/sms/outgoing
checked = /var/spool/sms/checked
incoming = /var/spool/sms/incoming
logfile = /var/log/smstools/smsd.log
infofile = /var/run/smstools/smsd.working
pidfile = /var/run/smstools/smsd.pid
outgoing = /var/spool/sms/outgoing
checked = /var/spool/sms/checked
failed = /var/spool/sms/failed
incoming = /var/spool/sms/incoming
sent = /var/spool/sms/sent
stats = /var/log/smstools/smsd_stats

receive_before_send = no

autosplit = 3


[GSM1]
init = ATE0;+CPMS="ME","ME","ME";+CMGF=0;
device = /dev/ttyUSB0
incoming = yes
pin = 0000
baudrate = 19200
memory_start = 0

_________________________________________________


I have a wireshark trace of the traffic on ttyUSB0 for a cycle from startup of smstools to the message appearing in the failed directory.

I have a text file with the USB/AT traffic extracted from that capture, filtered and fully decoded, and the original capture file available, but they are rather large to post here.

It may be obvious from the symptoms what is happening, I do not properly understand how smstools would be informed of the transmission of a message, so I'm struggling.

I cannot find an exact match to the dongle I'm using in the forum, so I suspect something critical is omitted from the initialization string I'm using.

I can easily set up to send AT commands direct to the modem, if anyone can suggest suitable diagnostics.

Thanks in advance for any help offered.

Harry

Log of the exchange

2020-04-09 15:21:25,6, GSM1: I have to send 1 short message for /var/spool/sms/checked/another-message 2020-04-09 15:21:25,6, GSM1: Sending SMS from to s2732 2020-04-09 15:21:25,6, GSM1: Checking if modem is ready 2020-04-09 15:21:25,7, GSM1: -> AT 2020-04-09 15:21:25,7, GSM1: Command is sent, waiting for the answer. (5) 2020-04-09 15:21:25,7, GSM1: <- OK 2020-04-09 15:21:25,6, GSM1: Pre-initializing modem 2020-04-09 15:21:25,7, GSM1: -> ATE0 2020-04-09 15:21:25,7, GSM1: Command is sent, waiting for the answer. (10) 2020-04-09 15:21:25,7, GSM1: <- OK 2020-04-09 15:21:25,7, GSM1: -> AT+CMEE=1;+CREG=2 2020-04-09 15:21:25,7, GSM1: Command is sent, waiting for the answer. (10) 2020-04-09 15:21:25,7, GSM1: <- OK 2020-04-09 15:21:25,6, GSM1: Checking if modem needs PIN 2020-04-09 15:21:25,7, GSM1: -> AT+CPIN? 2020-04-09 15:21:25,7, GSM1: Command is sent, waiting for the answer. (10) 2020-04-09 15:21:25,7, GSM1: <- +CPIN: READY OK 2020-04-09 15:21:25,6, GSM1: Initializing modem 2020-04-09 15:21:26,7, GSM1: -> ATE0;+CPMS="ME","ME","ME";+CMGF=0; 2020-04-09 15:21:26,7, GSM1: Command is sent, waiting for the answer. (10) 2020-04-09 15:21:26,7, GSM1: <- +CPMS: 0,23,0,23,0,23 OK 2020-04-09 15:21:26,7, GSM1: -> AT+CSQ 2020-04-09 15:21:26,7, GSM1: Command is sent, waiting for the answer. (10) 2020-04-09 15:21:26,7, GSM1: <- +CSQ: 25,99 OK 2020-04-09 15:21:26,6, GSM1: Signal Strength Indicator: (25,99) -63 dBm (Excellent), Bit Error Rate: not known or not detectable 2020-04-09 15:21:26,6, GSM1: Checking if Modem is registered to the network 2020-04-09 15:21:26,7, GSM1: -> AT+CREG? 2020-04-09 15:21:26,7, GSM1: Command is sent, waiting for the answer. (10) 2020-04-09 15:21:26,7, GSM1: <- +CREG: 2,1, FFFE, 323304, 7 OK 2020-04-09 15:21:26,6, GSM1: Modem is registered to the network 2020-04-09 15:21:26,6, GSM1: Selecting PDU mode 2020-04-09 15:21:26,7, GSM1: -> AT+CMGF=0 2020-04-09 15:21:26,7, GSM1: Command is sent, waiting for the answer. (5) 2020-04-09 15:21:26,7, GSM1: <- OK 2020-04-09 15:21:26,7, GSM1: -> AT+CMGS=14 2020-04-09 15:21:26,7, GSM1: Command is sent, waiting for the answer. (10) 2020-04-09 15:21:26,7, GSM1: <- > 2020-04-09 15:21:26,7, GSM1: -> 001100048172230000FF04CDA2B30A^Z 2020-04-09 15:21:26,7, GSM1: Command is sent, waiting for the answer. (60) 2020-04-09 15:22:26,7, GSM1: Incorrect answer, put_command expected (OK)|(ERROR), timeout occurred. 1. 2020-04-09 15:22:26,7, GSM1: <- 2020-04-09 15:22:26,3, GSM1: The modem answer was not OK: 2020-04-09 15:22:26,5, GSM1: Waiting 10 sec. before retrying 2020-04-09 15:22:36,6, GSM1: Checking if modem is ready

It looks like SMS tools is timing out waiting for a response after sending the message to the modem.That timeout seems short, the whole exchange taking less than a second. Is that timeout configurable somewhere?

Harry

I've found the timeout parameter, and extended it to 10 seconds.
From this it is clear that the modem is not responding in any reasonable timescale.

Still investigating. SMStools is clearly expecting a response, and I assume the modem is waiting for more data.

I've tried various terminations to the message without changing the problem.

Still looking at the modem configuration, I seem to get reasonable responses to any commands entered manually.

Harry

I'm pretty stumped.


My present diagnostics:

smsd logfile for a send message:

2020-04-16 14:10:34,5, smsd: SMS To: s2732. Moved file /var/spool/sms/outgoing/testmessage3 to /var/spool/sms/checked
2020-04-16 14:10:34,6, GSM1: I have to send 1 short message for /var/spool/sms/checked/testmessage3
2020-04-16 14:10:34,6, GSM1: Sending SMS from to s2732
2020-04-16 14:10:34,6, GSM1: Checking if modem is ready
2020-04-16 14:10:34,7, GSM1: -> AT
2020-04-16 14:10:34,7, GSM1: Command is sent, waiting for the answer. (5)
2020-04-16 14:10:34,7, GSM1: <- OK
2020-04-16 14:10:34,6, GSM1: Pre-initializing modem
2020-04-16 14:10:34,7, GSM1: -> ATE0
2020-04-16 14:10:34,7, GSM1: Command is sent, waiting for the answer. (10)
2020-04-16 14:10:34,7, GSM1: <- OK
2020-04-16 14:10:34,7, GSM1: -> AT+CMEE=1;+CREG=2
2020-04-16 14:10:34,7, GSM1: Command is sent, waiting for the answer. (10)
2020-04-16 14:10:34,7, GSM1: <- OK
2020-04-16 14:10:34,6, GSM1: Checking if modem needs PIN
2020-04-16 14:10:34,7, GSM1: -> AT+CPIN?
2020-04-16 14:10:34,7, GSM1: Command is sent, waiting for the answer. (10)
2020-04-16 14:10:34,7, GSM1: <- +CPIN: READY OK
2020-04-16 14:10:34,6, GSM1: Initializing modem
2020-04-16 14:10:35,7, GSM1: -> ATE0;+CPMS="ME","ME","ME";+CSCS="GSM";+CSCS?;
2020-04-16 14:10:35,7, GSM1: Command is sent, waiting for the answer. (10)
2020-04-16 14:10:35,7, GSM1: <- +CPMS: 0,23,0,23,0,23 +CSCS: "GSM" OK
2020-04-16 14:10:35,7, GSM1: -> AT+CSQ
2020-04-16 14:10:35,7, GSM1: Command is sent, waiting for the answer. (10)
2020-04-16 14:10:35,7, GSM1: <- +CSQ: 26,99 OK
2020-04-16 14:10:35,6, GSM1: Signal Strength Indicator: (26,99) -61 dBm (Excellent), Bit Error Rate: not known or not detectable
2020-04-16 14:10:35,6, GSM1: Checking if Modem is registered to the network
2020-04-16 14:10:35,7, GSM1: -> AT+CREG?
2020-04-16 14:10:35,7, GSM1: Command is sent, waiting for the answer. (10)
2020-04-16 14:10:35,7, GSM1: <- +CREG: 2,1, FFFE, 323301, 7 OK
2020-04-16 14:10:35,6, GSM1: Modem is registered to the network
2020-04-16 14:10:35,6, GSM1: Selecting PDU mode
2020-04-16 14:10:35,7, GSM1: -> AT+CMGF=0
2020-04-16 14:10:35,7, GSM1: Command is sent, waiting for the answer. (5)
2020-04-16 14:10:35,7, GSM1: <- OK
2020-04-16 14:10:35,7, GSM1: -> AT+CMGS=14
2020-04-16 14:10:35,7, GSM1: Command is sent, waiting for the answer. (10)
2020-04-16 14:10:35,7, GSM1: <- >
2020-04-16 14:10:35,7, GSM1: -> 001100048172230000FF04CDB2BB0E
2020-04-16 14:10:35,7, GSM1: Command is sent, waiting for the answer. (60)
2020-04-16 14:11:35,7, GSM1: Incorrect answer, put_command expected (OK)|(ERROR), timeout occurred. 1.
2020-04-16 14:11:35,7, GSM1: <-
2020-04-16 14:11:35,3, GSM1: The modem answer was not OK:
2020-04-16 14:11:35,5, GSM1: Waiting 10 sec. before retrying


Wireshark Decode of the exchange, from AT+CMGS to the end of the timeout:

No. Time Source Destination Protocol Length Info
1 0.000000 host 5.3.1 USB/AT 75 URB_BULK out, AT Command: AT+CMGS=14

Frame 1: 75 bytes on wire (600 bits), 75 bytes captured (600 bits)
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Apr 16, 2020 15:10:35.487572000 BST
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1587046235.487572000 seconds
[Time delta from previous captured frame: 0.000000000 seconds]
[Time delta from previous displayed frame: 0.000000000 seconds]
[Time since reference or first frame: 0.000000000 seconds]
Frame Number: 1
Frame Length: 75 bytes (600 bits)
Capture Length: 75 bytes (600 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: usb:at]
USB URB
[Source: host]
[Destination: 5.3.1]
URB id: 0x00000000d13d9b00
URB type: URB_SUBMIT ('S')
URB transfer type: URB_BULK (0x03)
Endpoint: 0x01, Direction: OUT
0... .... = Direction: OUT (0)
.... 0001 = Endpoint number: 1
Device: 3
URB bus id: 5
Device setup request: not relevant ('-')
Data: present (0)
URB sec: 1587046235
URB usec: 487572
URB status: Operation now in progress (-EINPROGRESS) (-115)
URB length [bytes]: 11
Data length [bytes]: 11
[Response in: 2]
[bInterfaceClass: Unknown (0xffff)]
Unused Setup Header
Interval: 0
Start frame: 0
Copy of Transfer Flags: 0x00000000
Number of ISO descriptors: 0
AT Command: AT+CMGS=14
AT Command: AT+CMGS=14\r

No. Time Source Destination Protocol Length Info
2 0.000144 5.3.1 host USB 64 URB_BULK out

Frame 2: 64 bytes on wire (512 bits), 64 bytes captured (512 bits)
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Apr 16, 2020 15:10:35.487716000 BST
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1587046235.487716000 seconds
[Time delta from previous captured frame: 0.000144000 seconds]
[Time delta from previous displayed frame: 0.000144000 seconds]
[Time since reference or first frame: 0.000144000 seconds]
Frame Number: 2
Frame Length: 64 bytes (512 bits)
Capture Length: 64 bytes (512 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: usb]
USB URB
[Source: 5.3.1]
[Destination: host]
URB id: 0x00000000d13d9b00
URB type: URB_COMPLETE ('C')
URB transfer type: URB_BULK (0x03)
Endpoint: 0x01, Direction: OUT
0... .... = Direction: OUT (0)
.... 0001 = Endpoint number: 1
Device: 3
URB bus id: 5
Device setup request: not relevant ('-')
Data: not present ('>')
URB sec: 1587046235
URB usec: 487716
URB status: Success (0)
URB length [bytes]: 11
Data length [bytes]: 0
[Request in: 1]
[Time from request: 0.000144000 seconds]
[bInterfaceClass: Unknown (0xffff)]
Unused Setup Header
Interval: 0
Start frame: 0
Copy of Transfer Flags: 0x00000000
Number of ISO descriptors: 0

No. Time Source Destination Protocol Length Info
3 0.008725 5.3.2 host USB/AT 68 URB_BULK in, AT Command: >

Frame 3: 68 bytes on wire (544 bits), 68 bytes captured (544 bits)
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Apr 16, 2020 15:10:35.496297000 BST
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1587046235.496297000 seconds
[Time delta from previous captured frame: 0.008581000 seconds]
[Time delta from previous displayed frame: 0.008581000 seconds]
[Time since reference or first frame: 0.008725000 seconds]
Frame Number: 3
Frame Length: 68 bytes (544 bits)
Capture Length: 68 bytes (544 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: usb:at]
USB URB
[Source: 5.3.2]
[Destination: host]
URB id: 0x00000000d13d9300
URB type: URB_COMPLETE ('C')
URB transfer type: URB_BULK (0x03)
Endpoint: 0x82, Direction: IN
1... .... = Direction: IN (1)
.... 0010 = Endpoint number: 2
Device: 3
URB bus id: 5
Device setup request: not relevant ('-')
Data: present (0)
URB sec: 1587046235
URB usec: 496297
URB status: Success (0)
URB length [bytes]: 4
Data length [bytes]: 4
[bInterfaceClass: Unknown (0xffff)]
Unused Setup Header
Interval: 0
Start frame: 0
Copy of Transfer Flags: 0x00000200
Number of ISO descriptors: 0
AT Command: >
AT Command: \r\n>

No. Time Source Destination Protocol Length Info
4 0.008767 host 5.3.2 USB 64 URB_BULK in

Frame 4: 64 bytes on wire (512 bits), 64 bytes captured (512 bits)
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Apr 16, 2020 15:10:35.496339000 BST
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1587046235.496339000 seconds
[Time delta from previous captured frame: 0.000042000 seconds]
[Time delta from previous displayed frame: 0.000042000 seconds]
[Time since reference or first frame: 0.008767000 seconds]
Frame Number: 4
Frame Length: 64 bytes (512 bits)
Capture Length: 64 bytes (512 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: usb]
USB URB
[Source: host]
[Destination: 5.3.2]
URB id: 0x00000000d13d9300
URB type: URB_SUBMIT ('S')
URB transfer type: URB_BULK (0x03)
Endpoint: 0x82, Direction: IN
1... .... = Direction: IN (1)
.... 0010 = Endpoint number: 2
Device: 3
URB bus id: 5
Device setup request: not relevant ('-')
Data: not present ('<')
URB sec: 1587046235
URB usec: 496339
URB status: Operation now in progress (-EINPROGRESS) (-115)
URB length [bytes]: 4096
Data length [bytes]: 0
[bInterfaceClass: Unknown (0xffff)]
Unused Setup Header
Interval: 0
Start frame: 0
Copy of Transfer Flags: 0x00000200
Number of ISO descriptors: 0

No. Time Source Destination Protocol Length Info
5 0.121420 host 5.3.1 USB 95 URB_BULK out

Frame 5: 95 bytes on wire (760 bits), 95 bytes captured (760 bits)
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Apr 16, 2020 15:10:35.608992000 BST
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1587046235.608992000 seconds
[Time delta from previous captured frame: 0.112653000 seconds]
[Time delta from previous displayed frame: 0.112653000 seconds]
[Time since reference or first frame: 0.121420000 seconds]
Frame Number: 5
Frame Length: 95 bytes (760 bits)
Capture Length: 95 bytes (760 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: usb]
USB URB
[Source: host]
[Destination: 5.3.1]
URB id: 0x00000000d13d9b00
URB type: URB_SUBMIT ('S')
URB transfer type: URB_BULK (0x03)
Endpoint: 0x01, Direction: OUT
0... .... = Direction: OUT (0)
.... 0001 = Endpoint number: 1
Device: 3
URB bus id: 5
Device setup request: not relevant ('-')
Data: present (0)
URB sec: 1587046235
URB usec: 608992
URB status: Operation now in progress (-EINPROGRESS) (-115)
URB length [bytes]: 31
Data length [bytes]: 31
[bInterfaceClass: Unknown (0xffff)]
Unused Setup Header
Interval: 0
Start frame: 0
Copy of Transfer Flags: 0x00000000
Number of ISO descriptors: 0
Leftover Capture Data: 303031313030303438313732323330303030464630344344...



I don't think I can attach the actual capture file, I'll happily mail it if anyone is interested.


As far as I read the AT spec the exchange should look something like:

Quote

If PDU mode (see AT+CMGF=0)
AT+CMGC=<length> <CR> PDU can be entered <CTRL-Z> / <ESC>
Response(s)
+CMGC: <mr>[, <ackpdu>]
OK
If sending fails
ERROR
+CMS ERROR

I can find no sign of the <CTRL-Z> I expected in the decode, but that may be simply my ignorance.


FYI the decodes are captured via a usbmon interface monitoring ttyUSB0

Harry

I do not have an exact AT command set for the modem I'm using, it's a cheap 4G dongle.

I've found several AT command sets on the internet that seem to match up to the responses I can get from this modem.

Those command sets seem to suggest that they expect the syntax

command "AT+CMGC=<length ???of the pdu presumably??> <CR>"
response ">"
command "body of the pdu" <CTRL Z>
response "variable text" OK

This ties in fairly well with the logs I've captured, and the source of smstools.

// Send modem command // 3.1.5: initial timeout changed 1 --> 2 and for PDU 6 --> 12. put_command(command, answer, sizeof(answer), "cmgs", "(>)|(ERROR)"); // Send message if command was successful if (!strstr(answer,"ERROR")) { put_command(command2, answer ,sizeof(answer), "pdu", EXPECT_OK_ERROR);

If and only if that "pdu" in the put command, includes a terminating <CTRL Z> in the pdu

However that terminating <CTRL Z> seems redundant, the AT+CMGC has already specified the length of the pdu to be transferred.

So I have no certainty that smsd feels the need to send it, or add it to the end of the pdu (or it may include it in the pdu length it sent in the +CGMS initial command). I'm still digging through the source to try and establish that it does or does not. My code fu is severely lacking so if anyone can confirm or deny that I'd be very grateful.

I think it's possible that what is happening is that smsd is not sending a terminating <CTRL Z> or is confusing the modem by including it in the pdu length so the modem does not view it as the separate terminator that the modem is waiting for.

With the timeout set at 10 seconds, we have a ten second "Mexican standoff" with the modem holding its answer waiting a completion command from smsd, and smsd waiting for an OK from the modem. When smsd times out and sends its clean up commands to the modem, the modem does not abort the send, but stops waiting for a termination command, views the message as completed, and sends it onward.

smsd however views it as failed, and tries again. and again... Hence the three copies of the message, and the three replies recieved.

I'm still working my way through the code for building the pdu to try and verify if this is a realistic interpretation of the problem.


Harry

Sorry for the late response. I have been partially offline.

It looks like your modem is "too cheap". It accepts the message, as it sends it, but it does not tell that it was sent. Usually modems will give the message number, which can be used with delivery reports and so on.

Do you have any other devices to test?

As far as I can remember, there has been some devices which have been targeted other functions than SMS, and they have SMS functionality too, but it's failing. Perhaps there is some answer, but not what was expected.

To make some more tests with your modem, you could use the global setting log_read_from_modem. The expected answer should contain OK or ERROR, and with this logging we can see what is coming from the modem, if anything. If nothing, unfortunately not much can be done.

Have you tried to send a message to your handset? It may be a different case from the modems point of view, as the number is a standard international number, not a short number.

I have satisfied myself that smsd is sending the terminating CTRL-Z.

I've tried the exchange manually. I'm not entirely sure I did it correctly, but I get no response.

So I'm regretfully coming to the same conclusion.

Harry

Just to tidy up this thread, I've replaced the GSM dongle with a "Huawei E160 3G Mobile Broadband USB Dongle".

For unrelated reasons I've had to rebuild the Armbian platform it's running on, so testing has been delayed a bit, but the upshot is that smstools is behaving perfectly.

I'm still learning my way around the configuration options, but I'm happily sending and receiving SMS texts.

Thanks for the support and the correct diagnosis of the issues with the other dongle.

Harry