Operating system name and version: CentOS 5.3
Version of smsd: 3.0.10
Smsd installed from: EPEL package repository
Name and model of a modem / phone: Motorola A1200r (Ming)
Interface: USB

Hi folks,
First, thanks to Stefan, Keke and everyone who contributed to SMSTools. It is really nifty.

I'm setting it up so my server can send alerts when something breaks. I just discovered the tool last night, and had it up and running in just a couple of hours. I've already reached this goal, but I noticed a problem along the way.

SMSTools will ignore incoming SMS. The msg is received on the phone. The smsd log file shows the message is there, but nothing is ever created in the incoming directory.

I'm hoping someone can make a suggestion for what to look for to debug this issue.

My setup.
/etc/smsd.conf
devices = GSM0 logfile = /var/log/smsd/smsd.log loglevel = 7 user = smsd infofile = /var/run/smsd/working pidfile = /var/run/smsd/pid [GSM0] device = /dev/ttyACM0 incoming = yes init=at+cpms="SM","SM","SM" primary_memory = SM memory_start = 0

/var/log/smsd/smsd.log
(extract)
2010-02-26 16:54:19,2, smsd: Smsd v3.0.10 started. 2010-02-26 16:54:19,2, smsd: Running as smsd:uucp. 2010-02-26 16:54:19,6, smsd: File mode creation mask: 022 (0644, rw-r--r--). 2010-02-26 16:54:19,6, GSM0: Modem handler 0 has started. ... 2010-02-26 16:54:19,7, GSM0: -> ATE0+CMEE=1 2010-02-26 16:54:19,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:54:19,7, GSM0: <- ATE0+CMEE=1 OK 2010-02-26 16:54:19,6, GSM0: Initializing modem 2010-02-26 16:54:19,7, GSM0: -> at+cpms="SM","SM","SM" 2010-02-26 16:54:20,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:54:20,7, GSM0: <- +CPMS: 1,40,1,40,1,40 OK 2010-02-26 16:54:20,6, GSM0: Checking if Modem is registered to the network 2010-02-26 16:54:20,7, GSM0: -> AT+CREG? 2010-02-26 16:54:20,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:54:20,7, GSM0: <- +CREG: 0,1 OK 2010-02-26 16:54:20,6, GSM0: Modem is registered to the network 2010-02-26 16:54:20,6, GSM0: Selecting PDU mode 2010-02-26 16:54:20,7, GSM0: -> AT+CMGF=0 2010-02-26 16:54:20,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:54:21,7, GSM0: <- OK 2010-02-26 16:54:21,6, GSM0: Querying IMSI 2010-02-26 16:54:21,7, GSM0: -> AT+CIMI 2010-02-26 16:54:21,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:54:21,7, GSM0: <- 460022104202573 OK 2010-02-26 16:54:21,6, GSM0: IMSI: 460022104202573 2010-02-26 16:54:21,6, GSM0: Checking memory size 2010-02-26 16:54:21,7, GSM0: -> AT+CPMS? 2010-02-26 16:54:21,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:54:22,7, GSM0: <- +CPMS: "SM",1,40,"SM",1,40,"SM",1,40 OK 2010-02-26 16:54:22,6, GSM0: Used memory is 1 of 40 2010-02-26 16:54:22,6, GSM0: Trying to get stored message 1 2010-02-26 16:54:22,7, GSM0: -> AT+CMGR=1 2010-02-26 16:54:22,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:54:22,7, GSM0: <- MODEM ERROR: 205 2010-02-26 16:54:22,6, GSM0: Trying to get stored message 2 2010-02-26 16:54:22,7, GSM0: -> AT+CMGR=2 2010-02-26 16:54:22,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:54:22,7, GSM0: <- MODEM ERROR: 205 2010-02-26 16:54:22,6, GSM0: Trying to get stored message 3 2010-02-26 16:54:22,7, GSM0: -> AT+CMGR=3 2010-02-26 16:54:22,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:54:23,7, GSM0: <- +CMGR:1,,23 0891683108100005F0000D91683124267935F900000120626144422303CEE012 OK 2010-02-26 16:54:23,6, GSM0: Trying to get stored message 4 2010-02-26 16:54:23,7, GSM0: -> AT+CMGR=4 2010-02-26 16:54:23,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:54:23,7, GSM0: <- MODEM ERROR: 205

new msg is received

2010-02-26 16:57:02,6, GSM0: Trying to get stored message 3 2010-02-26 16:57:02,7, GSM0: -> AT+CMGR=3 2010-02-26 16:57:02,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:57:02,7, GSM0: <- +CMGR:1,,23 0891683108100005F0000D91683124267935F900000120626144422303CEE012 OK 2010-02-26 16:57:02,6, GSM0: Trying to get stored message 4 2010-02-26 16:57:02,7, GSM0: -> AT+CMGR=4 2010-02-26 16:57:02,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:57:03,7, GSM0: <- +CMGR:1,,25 0891683108100005F0000D91683124267935F900000120626165702305CEE0122403 OK 2010-02-26 16:57:03,6, GSM0: Trying to get stored message 5 2010-02-26 16:57:03,7, GSM0: -> AT+CMGR=5 2010-02-26 16:57:03,7, GSM0: Command is sent, waiting for the answer 2010-02-26 16:57:03,7, GSM0: <- MODEM ERROR: 205 .... 2010-02-26 17:23:40,7, GSM0: -> AT+CMGR=40 2010-02-26 17:23:40,7, GSM0: Command is sent, waiting for the answer 2010-02-26 17:23:40,7, GSM0: <- MODEM ERROR: 205 2010-02-26 17:23:40,6, GSM0: No SMS received

# id smsd uid=114(smsd) gid=14(uucp) groups=14(uucp),116(smstools) context=root:system_r:unconfined_t:SystemLow-SystemHigh

# find /var/spool/sms -ls 426170 8 drwxr-x--- 7 smsd smstools 4096 Feb 26 10:13 /var/spool/sms 426187 8 drwxrwx--- 2 smsd smstools 4096 Feb 26 16:54 /var/spool/sms/outgoing 426186 8 drwxr-x--- 2 smsd smstools 4096 Feb 26 16:54 /var/spool/sms/incoming 426184 8 drwxr-x--- 2 smsd smstools 4096 Feb 26 16:54 /var/spool/sms/checked 426185 8 drwxr-x--- 2 smsd smstools 4096 Dec 20 2008 /var/spool/sms/failed 426188 8 drwxr-x--- 2 smsd smstools 4096 Dec 20 2008 /var/spool/sms/sent

SELinux is enabled, but nothing is showing up in the audit logs. Setting selinux to permissive does not change anything.

P.S. I use INIT of at+cpms="SM" because I don't want smsd sorting through 4096 empty mail slots in the phone's memory.

Thank's for your brief report.

As the answer from the modem seems to follow GSM 07.05 specification, I see no other reason than that the answer does not contain <CR> characters. There are <LF> characters, as the log has linefeeds shown. However, there should be both <CR> and <LF> as the definition says.

If my guess is correct, we have to change the code. I assume that the firmware of a modem cannot be altered.

Hopefully you can compile smsd from sources...

Download the latest version, 3.1.6 or 3.1.7beta and extract it into the /usr/local/src directory.

Go to the /usr/local/src/smstools3/src.

Edit smsd.c using some of your favourite editor.

Find "Trying to get stored message".

You will see the following piece of a code. Insert those lines which are colored to the place shown.


Save, make and test. Let me know about the results. I do not yet publish a new version, because this issue was not verified.

Hi keke,

No joy with 3.1.6. smstools aborts with or without the patch. I'll try 3.1.7Beta.

FYI: Here is what I got with 3.1.6....

2010-03-02 07:51:04,2, smsd: Smsd v3.1.6 started. 2010-03-02 07:51:04,2, smsd: Running as smsd:uucp. 2010-03-02 07:51:04,7, smsd: Running startup_check (shell): /tmp/smsd_script.DVpyMV /tmp/smsd_data.k76Uei 2010-03-02 07:51:04,7, smsd: Done: startup_check (shell), execution time 0 sec., status: 0 (0) 2010-03-02 07:51:04,4, smsd: File mode creation mask: 022 (0644, rw-r--r--). 2010-03-02 07:51:04,5, GSM0: Modem handler 0 has started. PID: 8863. 2010-03-02 07:51:04,5, smsd: Outgoing file checker has started. PID: 8862. 2010-03-02 07:51:04,5, GSM0: Using check_memory_method 1: CPMS is used. 2010-03-02 07:51:04,6, GSM0: Checking device for incoming SMS 2010-03-02 07:51:04,6, GSM0: Checking if modem is ready 2010-03-02 07:51:04,7, GSM0: -> AT 2010-03-02 07:51:04,7, GSM0: Command is sent, waiting for the answer 2010-03-02 07:51:04,7, GSM0: <- OK 2010-03-02 07:51:04,6, GSM0: Pre-initializing modem 2010-03-02 07:51:05,7, GSM0: -> ATE0+CMEE=1 2010-03-02 07:51:05,7, GSM0: Command is sent, waiting for the answer 2010-03-02 07:51:05,7, GSM0: <- OK 2010-03-02 07:51:05,6, GSM0: Checking if modem needs PIN 2010-03-02 07:51:05,7, GSM0: -> AT+CPIN? 2010-03-02 07:51:05,7, GSM0: Command is sent, waiting for the answer 2010-03-02 07:51:05,7, GSM0: <- +CPIN: "READY" OK 2010-03-02 07:51:05,2, GSM0: PIN handling: expected READY, modem answered +CPIN: "READY" OK 2010-03-02 07:51:05,2, GSM0: Modem handler 0 terminated abnormally. PID: 8863.

3.1.7Beta is equally unhappy. (no patch)

2010-03-02 08:04:49,2, smsd: Smsd v3.1.7beta started. 2010-03-02 08:04:49,2, smsd: Running as smsd:uucp. 2010-03-02 08:04:49,2, smsd: # You are running a beta version of SMS Server Tools 3. 2010-03-02 08:04:49,2, smsd: # All feedback is valuable. 2010-03-02 08:04:49,2, smsd: # Please provide you feedback on SMSTools3 Community. Thank you. 2010-03-02 08:04:49,7, smsd: Running startup_check (shell): /tmp/smsd_script.SnYSl2 /tmp/smsd_data.RdBvoj 2010-03-02 08:04:49,7, smsd: Done: startup_check (shell), execution time 0 sec., status: 0 (0) 2010-03-02 08:04:49,4, smsd: File mode creation mask: 022 (0644, rw-r--r--). 2010-03-02 08:04:49,5, GSM0: Modem handler 0 has started. PID: 9166. 2010-03-02 08:04:49,5, smsd: Outgoing file checker has started. PID: 9165. 2010-03-02 08:04:49,6, GSM0: Serial port /dev/ttyACM0 opened as 4, rtscts: 1, baudrate: 115200 2010-03-02 08:04:49,5, GSM0: Using check_memory_method 1: CPMS is used. 2010-03-02 08:04:49,6, GSM0: Checking device for incoming SMS 2010-03-02 08:04:49,6, GSM0: Checking if modem is ready 2010-03-02 08:04:49,7, GSM0: -> AT 2010-03-02 08:04:49,7, GSM0: Command is sent, waiting for the answer 2010-03-02 08:04:49,7, GSM0: <- OK 2010-03-02 08:04:49,6, GSM0: Pre-initializing modem 2010-03-02 08:04:49,7, GSM0: -> ATE0+CMEE=1 2010-03-02 08:04:49,7, GSM0: Command is sent, waiting for the answer 2010-03-02 08:04:50,7, GSM0: <- OK 2010-03-02 08:04:50,6, GSM0: Checking if modem needs PIN 2010-03-02 08:04:50,7, GSM0: -> AT+CPIN? 2010-03-02 08:04:50,7, GSM0: Command is sent, waiting for the answer 2010-03-02 08:04:50,7, GSM0: <- +CPIN: "READY" OK 2010-03-02 08:04:50,2, GSM0: PIN handling: expected READY, modem answered +CPIN: "READY" OK 2010-03-02 08:04:50,2, GSM0: Modem handler 0 terminated abnormally. PID: 9166.

Unfortunately, plugging the patch into 3.0.10 doesn't fix anything either.

Also, I inserted a printf into the patch and ran smsd -t , and the output is never seen.

Problem with a PIN is caused by the quotation marks which are received from a modem. This can be fixed in the modeminit.c:


However, better not to use a PIN while other issues are still unresolved...


I do not understand why your system does not accept incoming messages . It seems that there is nothing wrong in the answer from a modem, and the answer and PDU should be handled correctly by the smsd code.

Hopefully you can do one more test:

Stop the smsd if it's running.
Remove the smsd.log file.
Send an SMS to your device (while smsd is not running).
Start the smsd, use the original version 3.0.10.
When you can see from the log that a message was tried to handle, stop the smsd.
Now, do not alter smsd.log with any editor.
Create a dump of it: hexdump -C < /var/log/smsd.log
Show this dump here. It may be long, but I can make it shorted, if necessary, after I have seen what character there is actually in the log.

The removal of the double quotes fixed the modem init problem in 3.1.6. (I don't use a PIN anyway.)

This is from 3.0.10.
000016a0 3a 31 33 2c 37 2c 20 47 53 4d 30 3a 20 3c 2d 20 |:13,7, GSM0: <- | 000016b0 2b 43 4d 47 52 3a 31 2c 2c 39 36 0a 30 38 39 31 |+CMGR:1,,96.0891| 000016c0 36 38 33 31 30 38 31 30 30 30 30 35 46 30 30 30 |683108100005F000| 000016d0 30 35 38 31 30 31 38 30 46 36 30 30 30 38 30 31 |05810180F6000801| 000016e0 33 30 33 30 31 31 35 34 33 34 32 33 35 30 35 43 |303011543423505C| 000016f0 30 41 36 35 36 43 37 36 38 34 35 42 41 32 36 32 |0A656C76845BA262| 00001700 33 37 46 46 31 41 36 31 31 46 38 43 32 32 36 30 |37FF1A611F8C2260| 00001710 41 38 39 30 30 39 36 32 45 39 35 32 41 38 36 31 |A8900962E952A861| 00001720 31 46 35 37 33 30 35 45 32 36 46 46 30 31 36 37 |1F57305E26FF0167| 00001730 32 43 36 37 30 38 38 46 44 34 38 46 44 38 37 36 |2C67088FD48FD876| 00001740 38 34 30 30 33 31 30 30 33 30 35 31 34 33 38 42 |840031003051438B| 00001750 44 44 38 44 33 39 35 44 46 32 36 32 35 33 35 31 |DD8D395DF2625351| 00001760 36 35 36 30 41 38 37 36 38 34 38 44 32 36 36 32 |6560A876848D2662| 00001770 33 37 46 46 30 43 38 42 46 37 36 43 45 38 36 31 |37FF0C8BF76CE861| 00001780 30 46 36 37 45 35 36 35 33 36 33 30 30 32 0a 4f |0F67E565363002.O| 00001790 4b 0a 32 30 31 30 2d 30 33 2d 30 33 20 31 34 3a |K.2010-03-03 14:| 000017a0 31 31 3a 31 33 2c 36 2c 20 28 6e 75 6c 6c 29 3a |11:13,6, (null):| 000017b0 20 42 34 43 7c 0d 0a 2b 43 4d 47 52 3a 31 2c 2c | B4C|..+CMGR:1,,| 000017c0 39 36 0d 0a 0d 0a 30 38 39 31 36 38 33 31 30 38 |96....0891683108| 000017d0 31 30 30 30 30 35 46 30 30 30 30 35 38 31 30 31 |100005F000058101| 000017e0 38 30 46 36 30 30 30 38 30 31 33 30 33 30 31 31 |80F6000801303011| 000017f0 35 34 33 34 32 33 35 30 35 43 30 41 36 35 36 43 |543423505C0A656C| 00001800 37 36 38 34 35 42 41 32 36 32 33 37 46 46 31 41 |76845BA26237FF1A| 00001810 36 31 31 46 38 43 32 32 36 30 41 38 39 30 30 39 |611F8C2260A89009| 00001820 36 32 45 39 35 32 41 38 36 31 31 46 35 37 33 30 |62E952A8611F5730| 00001830 35 45 32 36 46 46 30 31 36 37 32 43 36 37 30 38 |5E26FF01672C6708| 00001840 38 46 44 34 38 46 44 38 37 36 38 34 30 30 33 31 |8FD48FD876840031| 00001850 30 30 33 30 35 31 34 33 38 42 44 44 38 44 33 39 |003051438BDD8D39| 00001860 35 44 46 32 36 32 35 33 35 31 36 35 36 30 41 38 |5DF26253516560A8| 00001870 37 36 38 34 38 44 32 36 36 32 33 37 46 46 30 43 |76848D266237FF0C| 00001880 38 42 46 37 36 43 45 38 36 31 30 46 36 37 45 35 |8BF76CE8610F67E5| 00001890 36 35 33 36 33 30 30 32 0d 0a 0d 0a 4f 4b 0d 0a |65363002....OK..| 000018a0 7c 0a 32 30 31 30 2d 30 33 2d 30 33 20 31 34 3a ||.2010-03-03 14:|

Just before the extra code you provided to convert 0x0a to 0x0d, I added a writelogfile(LOG_INFO, 0, "B4C|%s|",answer);



It shows there is a CR+LF at the end of each part. That might explain why the extra code didn't seem to do anything. But, it is also different from what is normally output to the log file, and that puzzles me.

CR+LF would obviously throw off the END2=BEGIN1+1 logic in the code after that.

Ah yes, that's it. I made this change in 3.1.0, and msgs start appearing in the incoming dir.

  begin1=strstr(answer,"+CMGR:");
if (begin1==0)
return -1;
end1=strstr(begin1,"\r");
if (end1==0)
return -1;

if ( strstr(begin1,"\r\n") ) {
begin2=end1+2;
} else {
begin2=end1+1;
}

end2=strstr(begin2+1,"\r");
if (end2==0)
return -1; 

Thanks for the information and the extra logging code. It shows that there is double line-ending used by the modem.

Your fix works, but I will include this kind of a fix in the next version: