search

faucamp / python-gsmmodem

Python module to control a GSM modem attached to the system: send/receive SMS messages, handle calls, etc
GNU Lesser General Public License v3.0
386 stars 304 forks source link

error on SMS received #6

Closed dauheeIRL closed 11 years ago

dauheeIRL commented 11 years ago

last one I promise!

I get an error using the SMS demo example. When a SMS is received I get the following error:

Initializing modem... Waiting for SMS message... Exception in thread Thread-2: Traceback (most recent call last): File "C:\Python27\lib\threading.py", line 551, in bootstrap_inner self.run() File "C:\Python27\lib\threading.py", line 504, in run self.__target(_self.args, *_self.kwargs) File "C:\Python27\lib\site-packages\gsmmodem\modem.py", line 444, in threadedHandleModemNotification self._handleSmsReceived(line) File "C:\Python27\lib\site-packages\gsmmodem\modem.py", line 534, in _handleSmsReceived sms = self._readStoredSmsMessage(msgIndex) File "C:\Python27\lib\site-packages\gsmmodem\modem.py", line 583, in _readStoredSmsMessage raise CommandError('Failed to parse the SMS message +CMGR response: {0}'.format(msgData)) CommandError

Again this could be particular to my GSM dongle and/or my telecoms carrier and nothing to do with the gsmmodem project.

Thanks.

faucamp commented 11 years ago

Yes, the CMGR command output sadly tends to vary quite a bit between modems when using text mode. The immediate workaround is to use PDU mode - this is the default mode for python-gsmmodem (or should be, anyhow...).

However, to fix the error, would you please post the output of a AT+CMGR command from gsmterm? (you can replace the phone numbers and message with random characters to maintain privacy) I'll use this output to modify the regex accordingly.

dauheeIRL commented 11 years ago

Hi faucamp,

I'm thinking this is totally a feature request as the environment is different for me in Ireland on the Meteor network. I tried modem.smsTextMode both True and False.

Apologies I didn't get anything other than the following when running gsmterm after sending a SMS:

C:\Per\Tools\raspberry pi\backup_Dev\scripts-dev>c:\python27\python gsmterm.py COM9

GSMTerm connected to COM9 at 115200bps. Press CTRL+] or CTRL+D to exit.

←[1;33mCLOSING TERMINAL...←[0m

I did get the following when querying the port directly:

+CMGR: "REC UNREAD","+353870000000",,"13/04/20,20:22:27+04" My message

faucamp commented 11 years ago

This is very strange. The +CMGR output you provided is a pretty standard response for a modem in text mode - and it works fine on my side (the regular expression matches against that input string if I do it manually). I've also added the message details to the test cases which also pass. I'll add a few more tests dedicated to simply parsing these messages; maybe there is some obscure difference in the way Windows handles regular expressions.

Worst is: PDU mode should have worked fine. I've improved the error-handling code to output more useful errors - could you please update your code and post the errors you are getting? (the output from the SMS handler demo should be enough)

dauheeIRL commented 11 years ago

I ran the sms_handler.py (smsTextMode = False) and got the following output if its of any benefit:

C:\Per\Tools\raspberry pi\backup_Dev\scripts-dev>c:\python27\python sms_handler.py Initializing modem... INFO: Connecting to modem on port COM9 at 115200bps DEBUG: write: ATZ DEBUG: response: ['OK'] DEBUG: write: ATE0 DEBUG: response: ['ATE0\r', 'OK'] DEBUG: write: AT+CFUN? DEBUG: response: ['+CFUN: 1', 'OK'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['OK'] DEBUG: write: AT+CPIN? DEBUG: response: ['+CPIN: READY', 'OK'] DEBUG: write: AT+CLAC DEBUG: response: ['ERROR'] DEBUG: write: AT+WIND? DEBUG: response: ['ERROR'] INFO: Loading Huawei call update table DEBUG: write: AT+COPS=3,0 DEBUG: response: ['OK'] DEBUG: write: AT+CMGF=0 DEBUG: response: ['OK'] DEBUG: write: AT+CSMP=49,167,0,0 DEBUG: response: ['OK'] DEBUG: write: AT+CPMS=? DEBUG: response: ['+CPMS: ("ME","MT","SM","SR"),("ME","MT","SM","SR"),("ME","MT","SM","SR")', 'OK'] DEBUG: write: AT+CPMS="SM","SM","SR" DEBUG: response: ['+CPMS: 0,30,0,30,0,100', 'OK'] DEBUG: write: AT+CNMI=2,1,0,2 DEBUG: response: ['OK'] DEBUG: write: AT+CLIP=1 DEBUG: response: ['OK'] DEBUG: write: AT+CRC=1 DEBUG: response: ['OK'] DEBUG: write: AT+CVHU=0 DEBUG: response: ['OK'] Waiting for SMS message... DEBUG: notification: ['+CMTI: "ME",3'] DEBUG: SMS message received DEBUG: write: AT+CMGR=3 DEBUG: response: ['OK'] Exception in thread Thread-2: Traceback (most recent call last): File "c:\python27\lib\threading.py", line 551, in bootstrap_inner self.run() File "c:\python27\lib\threading.py", line 504, in run self.__target(_self.args, *_self.kwargs) File "c:\python27\lib\site-packages\gsmmodem\modem.py", line 475, in threadedHandleModemNotification self._handleSmsReceived(line) File "c:\python27\lib\site-packages\gsmmodem\modem.py", line 565, in _handleSmsReceived sms = self._readStoredSmsMessage(msgIndex) File "c:\python27\lib\site-packages\gsmmodem\modem.py", line 618, in _readStoredSmsMessage raise CommandError('Failed to parse the SMS message +CMGR response: {0}'.format(msgData)) CommandError: Failed to parse the SMS message +CMGR response: ['OK']

dauheeIRL commented 11 years ago

I am separated from my beloved RPi until Friday, so can run it on that in just case there is some windows regex problem as you mentioned

I reran gsmterm again, I think I wasn't getting full debug info the last time. This is output from 1 text and 1 call:

C:\Per\Tools\raspberry pi\backup_Dev\scripts-dev>c:\python27\python gsmterm.py COM9

GSMTerm connected to COM9 at 115200bps. Press CTRL+] or CTRL+D to exit.

←[1;36m+CMTI: "ME",6←[0m ←[1;36m+CRING: VOICE +CLIP: "0872216345",128,,,,0←[0m ←[1;36mSTOPRING←[0m ←[1;32mGSM> ←[0m

faucamp commented 11 years ago

DEBUG: notification: ['+CMTI: "ME",3'] DEBUG: SMS message received DEBUG: write: AT+CMGR=3 DEBUG: response: ['OK']

Great, that's the problem right there: the AT+CMGR=3 command seems to get a response of only "OK" instead of the expected "+CMGR " followed by "OK". Since you've already shown that the modem does however give the correct response, something must be going wrong with the serial_comms read

My guess would be that this is a timing-related issue, meaning the "OK" that is currently read is actually still part of the "+CMTI" message announcement, but that the GsmModem class issues the +CMGR before that OK has been read, causing it to believe that the "OK" was sent in response to to the +CMGR. In other words, the actual +CMGR response will be picked up a moment later as an unsolicited notification from the modem (but in this case the program has already crashed, so we never see it).

Sadly I cannot replicate this issue on my modems, as the notification-reading code picks up multi-line notifications just fine (by querying the serial buffer to see if any more data is pending) - this is not working properly on your side, obviously - I suspect your PC might just be muuuuuch faster than mine ;). Could you please help me confirm the issue by editing the "_handleSmsReceived()" method in the GsmModem class and wrapping the affected into a try-except block? i.e. change the method to:

def _handleSmsReceived(self, notificationLine):
        """ Handler for "new SMS" unsolicited notification line """
        self.log.debug('SMS message received')
        cmtiMatch = self.CMTI_REGEX.match(notificationLine)
        if cmtiMatch:
            msgIndex = cmtiMatch.group(2)
            try:
                sms = self._readStoredSmsMessage(msgIndex)
                self._deleteStoredMessage(msgIndex)
                self.smsReceivedCallback(sms)
            except Exception as ex:
                self.log.warning('Caught exception', ex)

...and test it again. If my assumption is correct you should see some lines like "Unhandled unsolicited modem notification" after the "Caught exception" log message. Could you post these last log messages?

Thanks for all your help making this project better, I truly appreciate it.

dauheeIRL commented 11 years ago

am delighted to be of service, this is a great library. Please don't hesitate with further requests. I got the following output below:

C:\Per\Tools\raspberry pi\backup_Dev\scripts-dev>c:\python27\python sms_handler.py Initializing modem... INFO: Connecting to modem on port COM9 at 115200bps DEBUG: write: ATZ DEBUG: response: ['OK'] DEBUG: write: ATE0 DEBUG: response: ['ATE0\r', 'OK'] DEBUG: write: AT+CFUN? DEBUG: response: ['+CFUN: 1', 'OK'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['OK'] DEBUG: write: AT+CPIN? DEBUG: response: ['+CPIN: READY', 'OK'] DEBUG: write: AT+CLAC DEBUG: response: ['ERROR'] DEBUG: write: AT+WIND? DEBUG: response: ['ERROR'] INFO: Loading Huawei call update table DEBUG: write: AT+COPS=3,0 DEBUG: response: ['OK'] DEBUG: write: AT+CMGF=0 DEBUG: response: ['OK'] DEBUG: write: AT+CSMP=49,167,0,0 DEBUG: response: ['OK'] DEBUG: write: AT+CPMS=? DEBUG: response: ['+CPMS: ("ME","MT","SM","SR"),("ME","MT","SM","SR"),("ME","MT","SM","SR")', 'OK'] DEBUG: write: AT+CPMS="SM","SM","SR" DEBUG: response: ['+CPMS: 0,30,0,30,0,100', 'OK'] DEBUG: write: AT+CNMI=2,1,0,2 DEBUG: response: ['OK'] DEBUG: write: AT+CLIP=1 DEBUG: response: ['OK'] DEBUG: write: AT+CRC=1 DEBUG: response: ['OK'] DEBUG: write: AT+CVHU=0 DEBUG: response: ['OK'] Waiting for SMS message... DEBUG: notification: ['+CMTI: "ME",7'] DEBUG: SMS message received DEBUG: write: AT+CMGR=7 DEBUG: response: ['OK'] Traceback (most recent call last): File "c:\python27\lib\logginginit.py", line 846, in emit msg = self.format(record) File "c:\python27\lib\logginginit.py", line 723, in format return fmt.format(record) File "c:\python27\lib\logginginit.py", line 464, in format record.message = record.getMessage() File "c:\python27\lib\logginginit.py", line 328, in getMessage msg = msg % self.args TypeError: not all arguments converted during string formatting Logged from file modem.py, line 580

dauheeIRL commented 11 years ago

On a hunch, I changed AT+CPMS= to ME, ME, ME in connect() and got the following output with the message now being delivered but now getting an error further on - I will need to determine if its because I don't have credit to send sms on receiving sim which is quite possible. So it looks like we are in business :)

C:\Per\Tools\raspberry pi\backup_Dev\scripts-dev>c:\python27\python sms_handler.py Initializing modem... INFO: Connecting to modem on port COM9 at 115200bps DEBUG: write: ATZ DEBUG: response: ['OK'] DEBUG: write: ATE0 DEBUG: response: ['ATE0\r', 'OK'] DEBUG: write: AT+CFUN? DEBUG: response: ['+CFUN: 1', 'OK'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['OK'] DEBUG: write: AT+CPIN? DEBUG: response: ['+CPIN: READY', 'OK'] DEBUG: write: AT+CLAC DEBUG: response: ['ERROR'] DEBUG: write: AT+WIND? DEBUG: response: ['ERROR'] INFO: Loading Huawei call update table DEBUG: write: AT+COPS=3,0 DEBUG: response: ['OK'] DEBUG: write: AT+CMGF=0 DEBUG: response: ['OK'] DEBUG: write: AT+CSMP=49,167,0,0 DEBUG: response: ['OK'] DEBUG: write: AT+CPMS=? DEBUG: response: ['+CPMS: ("ME","MT","SM","SR"),("ME","MT","SM","SR"),("ME","MT","SM","SR")', 'OK'] DEBUG: write: AT+CPMS="ME","ME","ME" DEBUG: response: ['+CPMS: 8,100,8,100,8,100', 'OK'] DEBUG: write: AT+CNMI=2,1,0,2 DEBUG: response: ['OK'] DEBUG: write: AT+CLIP=1 DEBUG: response: ['OK'] DEBUG: write: AT+CRC=1 DEBUG: response: ['OK'] DEBUG: write: AT+CVHU=0 DEBUG: response: ['OK'] Waiting for SMS message... DEBUG: notification: ['+CMTI: "ME",8'] DEBUG: SMS message received DEBUG: write: AT+CMGR=8 DEBUG: response: ['+CMGR: 0,,24', '0791538386000200040C9153832712365400003140328190234005C8329BFD06', 'OK'] DEBUG: write: AT+CMGD=8 DEBUG: response: ['OK'] == SMS message received == From: +3538700000000 Time: 2013-04-23 18:09:32+01:00 Message: Hello

Replying to SMS... DEBUG: write: AT+CMGS=32 DEBUG: response: ['> '] DEBUG: write: 0021000C91538327123654000015D3E614242F8FCB697B99AC0389906536FB2D02 DEBUG: response: ['+CMS ERROR: 330'] Traceback (most recent call last): File "c:\python27\lib\logginginit.py", line 846, in emit msg = self.format(record) File "c:\python27\lib\logginginit.py", line 723, in format return fmt.format(record) File "c:\python27\lib\logginginit.py", line 464, in format record.message = record.getMessage() File "c:\python27\lib\logginginit.py", line 328, in getMessage msg = msg % self.args TypeError: not all arguments converted during string formatting Logged from file modem.py, line 581

faucamp commented 11 years ago

Good catch! It was right in front of us the whole time: Your new message notification specified "ME" from the beginning:

DEBUG: notification: ['+CMTI: "ME",7']

...but since the GsmModem class uses the preferred message storage setting for reads (set via +CPMS) it would have attempted to read index 7 from the "SM" memory (which would obviously not return anything).

I'll update the code to actually take note of what memory the indication is using - this was a very, very nasty oversight on my part.

As for the TypeError you're getting from the logging module: I'm not sure where that is coming from (your code is different from what's in the repository at the moment), so I am going to ignore that for now, but please open a ticket if this isn't fixed after the update.

Finally, a +CMS 330 error (the error you're getting on sending an SMS) indicates that the SMSC number has not been set. You should have gotten a "SmscNumberUnknownError" exception, but due to the above logging error you are not seeing this. You can use the GsmModem.smsc property to set the default SMSC number; I'll also be adding a "smsc" parameter to sendSms to allow users to override the default SMSC number.

faucamp commented 11 years ago

Fixed in fd88b5080f6e6e54e4cc15e6614ef794979ab9a3

Please update to the latest codebase and check that everything is working for you. If not, feel free to re-open this ticket :)

dauheeIRL commented 11 years ago

Ah fantastic thats working now with the ME location.

It seems to be wiping the SMSC number on each connect with the return value of modem.smsc(): +10787132000000000000000000000000000000000 I can set the SMSC after connect and set it manually each time so its not a show-stopper. I'm not sure if this behaviour was there for me previously as have only started trying to send SMS.