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

sending SMS directly after connect() #11

Closed dauheeIRL closed 11 years ago

dauheeIRL commented 11 years ago

There is an easy workaround for me here. Simply timer.sleep(7) after connect() and before sendSms. Just sending this on if is of interest - error output below:

Initializing modem... INFO: Connecting to modem on port COM9 at 115200bps DEBUG: write: ATZ DEBUG: response: ['ATZ\r', 'ERROR'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['AT+CMEE=1\r', 'OK'] DEBUG: write: AT+CPIN? DEBUG: response: ['AT+CPIN?\r', '+CPIN: SIM PIN', 'OK'] DEBUG: write: AT+CPIN="xxxxx" DEBUG: response: ['AT+CPIN="xxxxx"\r', 'OK'] DEBUG: write: ATZ DEBUG: response: ['ATZ\r', 'OK'] DEBUG: write: ATE0 DEBUG: response: ['ATE0\r', 'OK'] DEBUG: write: AT+CFUN? DEBUG: response: ['+CFUN: 0', 'OK'] DEBUG: write: AT+CFUN=1 DEBUG: response: ['OK'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['OK'] DEBUG: write: AT+CLAC DEBUG: response: ['ERROR'] DEBUG: write: AT+WIND? DEBUG: response: ['ERROR'] DEBUG: write: AT+CGMI DEBUG: response: ['QUALCOMM INCORPORATED', 'OK'] INFO: Unknown modem type - will use polling for call state updates DEBUG: write: AT+COPS=3,0 DEBUG: response: ['OK'] DEBUG: write: AT+CMGF=1 DEBUG: response: ['OK'] DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 0s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 0s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 0s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 0s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 1s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: notification: ['+ZDONR: "Not Found"', '+ZPASR: "No Service"'] DEBUG: Unhandled unsolicited modem notification: ['+ZDONR: "Not Found"', '+ZPASR: "No Service"'] DEBUG: 515 error detected; self._writeWait adjusted to 1s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 1s DEBUG: write: AT+CSCA? DEBUG: response: ['+CSCA: "+353857000000",145', 'OK'] DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: write: AT+CSMP=49,167,0,0 DEBUG: response: ['OK'] DEBUG: write: AT+CSCA? DEBUG: response: ['+CSCA: "+353857000000",145', '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: 1,100,1,100,1,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 and/or calls... DEBUG: write: AT+CMGS="087111111" DEBUG: response: ['> '] DEBUG: write: test message DEBUG: response: ['+CMS ERROR: 500'] Traceback (most recent call last): File "GSM2.py", line 65, in main() File "GSM2.py", line 50, in main sms = modem.sendSms('087111111', 'test message', waitForDeliveryReport=False) File "c:\python27\lib\site-packages\gsmmodem\modem.py", line 417, in sendSms result = self.write(text, timeout=15, writeTerm=chr(26))[0] File "c:\python27\lib\site-packages\gsmmodem\modem.py", line 266, in write raise CmsError(data, int(errorCode)) gsmmodem.exceptions.CmsError: CMS 500

However when I put in the sleep, I works successfully as below:

Initializing modem... INFO: Connecting to modem on port COM9 at 115200bps DEBUG: write: ATZ DEBUG: response: ['ATZ\r', 'ERROR'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['AT+CMEE=1\r', 'OK'] DEBUG: write: AT+CPIN? DEBUG: response: ['AT+CPIN?\r', '+CPIN: SIM PIN', 'OK'] DEBUG: write: AT+CPIN="xxx" DEBUG: response: ['AT+CPIN="xxx"\r', 'OK'] DEBUG: write: ATZ DEBUG: response: ['ATZ\r', 'OK'] DEBUG: write: ATE0 DEBUG: response: ['ATE0\r', 'OK'] DEBUG: write: AT+CFUN? DEBUG: response: ['+CFUN: 0', 'OK'] DEBUG: write: AT+CFUN=1 DEBUG: response: ['OK'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['OK'] DEBUG: write: AT+CLAC DEBUG: response: ['ERROR'] DEBUG: write: AT+WIND? DEBUG: response: ['ERROR'] DEBUG: write: AT+CGMI DEBUG: response: ['QUALCOMM INCORPORATED', 'OK'] INFO: Unknown modem type - will use polling for call state updates DEBUG: write: AT+COPS=3,0 DEBUG: response: ['OK'] DEBUG: write: AT+CMGF=1 DEBUG: response: ['OK'] DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 0s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 0s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 0s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 0s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 1s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: notification: ['+ZDONR: "Not Found"', '+ZPASR: "No Service"'] DEBUG: Unhandled unsolicited modem notification: ['+ZDONR: "Not Found"', '+ZPASR: "No Service"'] DEBUG: 515 error detected; self._writeWait adjusted to 1s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 1s DEBUG: write: AT+CSCA? DEBUG: response: ['+CSCA: "+353857000000",145', 'OK'] DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: write: AT+CSMP=49,167,0,0 DEBUG: response: ['OK'] DEBUG: write: AT+CSCA? DEBUG: response: ['+CSCA: "+353857000000",145', '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: 1,100,1,100,1,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 and/or calls... DEBUG: notification: ['+ZDONR: "METEOR",272,3,"CS_ONLY","ROAM_OFF"', '+ZPASR: "UMTS"', '+ZDONR: "METEOR",272,3,"CS_ONLY","ROAM_OFF"', '+ZPASR: "UMTS"'] DEBUG: Unhandled unsolicited modem notification: ['+ZDONR: "METEOR",272,3,"CS_ONLY","ROAM_OFF"', '+ZPASR: "UMTS"', '+ZDONR: "METEOR",272,3,"CS_ONLY","ROAM_OFF"' , '+ZPASR: "UMTS"'] DEBUG: notification: ['+ZDONR: "METEOR",272,3,"CS_PS","ROAM_OFF"', '+ZPASR: "UMTS"'] DEBUG: Unhandled unsolicited modem notification: ['+ZDONR: "METEOR",272,3,"CS_PS","ROAM_OFF"', '+ZPASR: "UMTS"'] DEBUG: write: AT+CMGS="0871111111" DEBUG: response: ['> '] DEBUG: write: test message DEBUG: response: ['+CMGS: 61', 'OK'] Message sent. DEBUG: notification: ['+CDSI: "SR",50'] DEBUG: SMS status report received DEBUG: write: AT+CPMS="SR" DEBUG: response: ['+CPMS: 1,100,2,100,2,100', 'OK'] DEBUG: write: AT+CMGR=50 DEBUG: response: ['+CMGR: ,6,61,"0871111111",129,"13/05/03,14:56:00+04","13/05/03,14:56:00+04",0', 'OK'] DEBUG: write: AT+CMGD=50 DEBUG: response: ['OK']

forgot to say, that you so so much for all the excellent work on this. Its greatly appreciated!

faucamp commented 11 years ago

This modem appears to be a ZTE modem of some sort, based on a few Google searches (I can't seem to find tangible information on this modem based on the the "Qualcomm M6280" identifier it returned from identify-modem.py, but those +ZDONR and +ZPASR notifications stand out). Anyway, these modems seem to send unsolicited +ZDONR updates every time the mobile network conditions change - in this case your modem is only just connecting to the network.

That said, the GsmModem.waitForNetworkCoverage() method should work for you - it was designed to handle exactly this type of scenario (even though the GsmModem class ignores those modem-specific update messages).

To use it in the sms_handler_demo.py script (I am assuming this is what you are using for the above output), replace the print('Waiting for SMS message...') line with the following:

print('Waiting for network coverage...')
modem.waitForNetworkCoverage(30)
print('Waiting for SMS message...')

Please add that to your script and see if it works? Otherwise, try sending an SMS using the sendsms.py script?

faucamp commented 11 years ago

Aah sorry, I see now that you are using your own script - I wasn't reading properly. Just replace your "sleep" call with the modem.waitForNetworkCoverage() call.

dauheeIRL commented 11 years ago

I was using your script with a little modification :) I have a very troublesome modem - output now is:

Initializing modem... INFO: Connecting to modem on port COM9 at 115200bps DEBUG: write: ATZ DEBUG: response: ['ATZ\r', 'ERROR'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['AT+CMEE=1\r', 'OK'] DEBUG: write: AT+CPIN? DEBUG: response: ['AT+CPIN?\r', '+CPIN: SIM PIN', 'OK'] DEBUG: write: AT+CPIN="1111" DEBUG: response: ['AT+CPIN="1111"\r', 'OK'] DEBUG: write: ATZ DEBUG: response: ['ATZ\r', 'OK'] DEBUG: write: ATE0 DEBUG: response: ['ATE0\r', 'OK'] DEBUG: write: AT+CFUN? DEBUG: response: ['+CFUN: 0', 'OK'] DEBUG: write: AT+CFUN=1 DEBUG: response: ['OK'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['OK'] DEBUG: write: AT+CLAC DEBUG: response: ['ERROR'] DEBUG: write: AT+WIND? DEBUG: response: ['ERROR'] DEBUG: write: AT+CGMI DEBUG: response: ['QUALCOMM INCORPORATED', 'OK'] INFO: Unknown modem type - will use polling for call state updates DEBUG: write: AT+COPS=3,0 DEBUG: response: ['OK'] DEBUG: write: AT+CMGF=1 DEBUG: response: ['OK'] DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 0s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 0s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 0s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 0s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 1s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: notification: ['+ZDONR: "Not Found"', '+ZPASR: "No Service"'] DEBUG: Unhandled unsolicited modem notification: ['+ZDONR: "Not Found"', '+ZPASR: "No Service"'] DEBUG: 515 error detected; self._writeWait adjusted to 1s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: 515 error detected; self._writeWait adjusted to 1s DEBUG: write: AT+CSCA? DEBUG: response: ['+CSCA: "+353857000000",145', 'OK'] DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: self_writeWait set to 0.1 because of recovering from 515 error DEBUG: write: AT+CSMP=49,167,0,0 DEBUG: response: ['OK'] DEBUG: write: AT+CSCA? DEBUG: response: ['+CSCA: "+353857000000",145', '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: 1,100,1,100,1,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 network coverage... DEBUG: write: AT+CSQ DEBUG: response: ['+CSQ: 0,99', 'OK'] DEBUG: write: AT+CSQ DEBUG: response: ['+CSQ: 0,99', 'OK'] DEBUG: write: AT+CSQ DEBUG: response: ['+CSQ: 0,99', 'OK'] DEBUG: write: AT+CSQ DEBUG: response: ['+CSQ: 21,99', 'OK'] Waiting for SMS message... DEBUG: write: AT+CMGS="087111111" DEBUG: response: ['+ZDONR: "METEOR",272,3,"CS_ONLY","ROAM_OFF"', '+ZPASR: "UMTS"', '> '] DEBUG: write: test message DEBUG: response: ['+ZDONR: "METEOR",272,3,"CS_ONLY","ROAM_OFF"', '+ZPASR: "UMTS"', '+ZDONR: "METEOR",272,3,"CS_PS","ROAM_OFF"', '+ZPASR: "UMTS"', '+CMGS: 62', ' OK'] Traceback (most recent call last): File "GSM2.py", line 66, in main() File "GSM2.py", line 51, in main sms = modem.sendSms('087111111', 'test message', waitForDeliveryReport=False) File "c:\python27\lib\site-packages\gsmmodem\modem.py", line 426, in sendSms reference = int(result[7:]) ValueError: invalid literal for int() with base 10: '"METEOR",272,3,"CS_ONLY","ROAM_OFF"'

faucamp commented 11 years ago

Thanks for that - it helps a lot. What's happening now is that the modem's "response" to the AT+CMGS command includes those unsolicited messages as well, simply because of realllllly unfortunate timing (you can see the expected '> ' sequence right at the end of the "AT+CMGS" command, and the "+GMGS: 62" response after the "write: test message" bit.

This, fortunately, should be easily fixable - the command is still being executed without problems; I'll just filter the response and look for the expected result ("+CMGS: xx") instead of assuming that no other "garbage" messages are included along with it.

dauheeIRL commented 11 years ago

Ah that's great. An easy fix is music to my ears :)

On Fri, May 3, 2013 at 3:33 PM, Francois Aucamp notifications@github.comwrote:

Thanks for that - it helps a lot. What's happening now is that the modem's "response" to the AT+CMGS command includes those unsolicited messages as well, simply because of realllllly unfortunate timing (you can see the expected '> ' sequence right at the end of the "AT+CMGS" command, and the "+GMGS: 62" response after the "write: test message" bit.

This, fortunately, should be easily fixable - the command is still being executed without problems; I'll just filter the response and look for the expected result ("+CMGS: xx") instead of assuming that no other "garbage" messages are included along with it.

— Reply to this email directly or view it on GitHubhttps://github.com/faucamp/python-gsmmodem/issues/11#issuecomment-17397230 .

faucamp commented 11 years ago

Right, that should fix it. Kindly test it again and close the issue if this is OK? If it solves your problem, I'll add the filter to other commands in the code as well, for safety. Thanks!

dauheeIRL commented 11 years ago

No luck unfortunately. I tried twice just in case. It might be a need for the network to fully connect (unsolicited messages etc).

Initializing modem... INFO: Connecting to modem on port COM9 at 115200bps DEBUG: write: ATZ DEBUG: response: ['ATZ\r', 'ERROR'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['AT+CMEE=1\r', 'OK'] DEBUG: write: AT+CPIN? DEBUG: response: ['AT+CPIN?\r', '+CPIN: SIM PIN', 'OK'] DEBUG: write: AT+CPIN="xxxxx" DEBUG: response: ['AT+CPIN="xxxxx"\r', 'OK'] DEBUG: write: ATZ DEBUG: response: ['ATZ\r', 'OK'] DEBUG: write: ATE0 DEBUG: response: ['ATE0\r', 'OK'] DEBUG: write: AT+CFUN? DEBUG: response: ['+CFUN: 0', 'OK'] DEBUG: write: AT+CFUN=1 DEBUG: response: ['OK'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['OK'] DEBUG: write: AT+CLAC DEBUG: response: ['ERROR'] DEBUG: write: AT+WIND? DEBUG: response: ['ERROR'] DEBUG: write: AT+CGMI DEBUG: response: ['QUALCOMM INCORPORATED', 'OK'] INFO: Unknown modem type - will use polling for call state updates DEBUG: write: AT+COPS=3,0 DEBUG: response: ['OK'] DEBUG: write: AT+CMGF=1 DEBUG: response: ['OK'] DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 0.200000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 0.400000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 0.600000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 0.800000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 1.000000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: notification: ['+ZDONR: "Not Found"', '+ZPASR: "No Service"'] DEBUG: Unhandled unsolicited modem notification: ['+ZDONR: "Not Found"', '+ZPASR: "No Service"'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 1.200000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 1.400000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CSCA: "+353857000000",145', 'OK'] DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: write: AT+CSMP=49,167,0,0 DEBUG: response: ['OK'] DEBUG: write: AT+CSCA? DEBUG: response: ['+CSCA: "+353857000000",145', '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: 1,100,1,100,1,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 network coverage... DEBUG: write: AT+CSQ DEBUG: response: ['+CSQ: 8,99', 'OK'] Waiting for SMS message... DEBUG: write: AT+CMGS="087111111" DEBUG: response: ['> '] DEBUG: write: test message DEBUG: response: ['+CMS ERROR: 500'] Traceback (most recent call last): File "GSM2.py", line 66, in main() File "GSM2.py", line 51, in main sms = modem.sendSms('087111111', 'test message', waitForDeliveryReport=False) File "c:\python27\lib\site-packages\gsmmodem\modem.py", line 417, in sendSms result = lineStartingWith('+CMGS:', self.write(text, timeout=15, writeTerm=chr(26))) File "c:\python27\lib\site-packages\gsmmodem\modem.py", line 266, in write raise CmsError(data, int(errorCode)) gsmmodem.exceptions.CmsError: CMS 500

faucamp commented 11 years ago

Hmm.. This is not the same error as the previous comment (but it is the same as the original report) - previously the unsolicited notifications were interfering with parsing command responses (which is what I addressed in the patch), but now the modem actually sent the initial unsolicted notifications far earlier (during connect() - you can see them at the end of the AT+CSCA? wait cycle).

The error you're getting now (CMS 500) is a proper error from the modem in response to that command, so python-gsmmodem is doing the right thing by throwing an exception. Sadly CMS 500 means "Unknown error" according to most modem specs, which does not help us at all. :( The part that bugs me is that the network coverage checks are OK (you have weak-ish signal, but enough) and there are no unsolicited notifications being issued by the modem at this point that might have interfered, so it should have worked... but I think you are correct about the modem not being "fully" connected yet (despite what it reports its signal strength to be).

What I'll do is add a handler for those +ZDONR and +ZPASR notifications from the modem, and use the information provided by them in conjunction with the current signal levels checks to improve the waitForNetworkCoverage() method. Thanks (as always) for your detailed report!

Some background info (for others that might find this bug report due to a Google search or whatnot):

I have only ever gotten a CMS 500 error in response to the AT+CMGS command for the following scenarios:

Neither of these scenarios match your case.

faucamp commented 11 years ago

I might have a more generic solution; could you please modify your script to do the following:

modem.connect()
modem.write('AT+CREG?', parseError=False)
time.sleep(8)
modem.write('AT+CREG?', parseError=False)

i.e. remove the waitForNetworkCoverage() and sendSms() calls for now and replace them with the sleep and +creg calls? The output of that might solve this completely.

dauheeIRL commented 11 years ago

Excellent stuff! OK I had to give a 10 second wait inbetween the CREG (7 used to work previously, network must be going slow tonight!). I left in the sendSMS just for good measure to ensure the second CREG was taken from a time that was good. Output is below:

Initializing modem... INFO: Connecting to modem on port COM9 at 115200bps DEBUG: write: ATZ DEBUG: response: ['ATZ\r', 'ERROR'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['AT+CMEE=1\r', 'OK'] DEBUG: write: AT+CPIN? DEBUG: response: ['AT+CPIN?\r', '+CPIN: SIM PIN', 'OK'] DEBUG: write: AT+CPIN="xxxx" DEBUG: response: ['AT+CPIN="xxxx"\r', 'OK'] DEBUG: write: ATZ DEBUG: response: ['ATZ\r', 'OK'] DEBUG: write: ATE0 DEBUG: response: ['ATE0\r', 'OK'] DEBUG: write: AT+CFUN? DEBUG: response: ['+CFUN: 0', 'OK'] DEBUG: write: AT+CFUN=1 DEBUG: response: ['OK'] DEBUG: write: AT+CMEE=1 DEBUG: response: ['OK'] DEBUG: write: AT+CLAC DEBUG: response: ['ERROR'] DEBUG: write: AT+WIND? DEBUG: response: ['ERROR'] DEBUG: write: AT+CGMI DEBUG: response: ['QUALCOMM INCORPORATED', 'OK'] INFO: Unknown modem type - will use polling for call state updates DEBUG: write: AT+COPS=3,0 DEBUG: response: ['OK'] DEBUG: write: AT+CMGF=1 DEBUG: response: ['OK'] DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 0.200000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 0.400000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 0.600000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 0.800000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 1.000000s DEBUG: notification: ['+ZDONR: "Not Found"', '+ZPASR: "No Service"'] DEBUG: Unhandled unsolicited modem notification: ['+ZDONR: "Not Found"', '+ZPASR: "No Service"'] DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 1.200000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14'] DEBUG: Device/SIM busy error detected; self._writeWait adjusted to 1.400000s DEBUG: write: AT+CSCA? DEBUG: response: ['+CSCA: "+353857000000",145', 'OK'] DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: self_writeWait set to 0.1 because of recovering from device busy (515) error DEBUG: write: AT+CSMP=49,167,0,0 DEBUG: response: ['OK'] DEBUG: write: AT+CSCA? DEBUG: response: ['+CSCA: "+353857000000",145', '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: 1,100,1,100,1,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'] Processing CREG commands after connect... DEBUG: write: AT+CREG? DEBUG: response: ['+CREG: 0,2', 'OK'] DEBUG: notification: ['+ZDONR: "METEOR",272,3,"CS_ONLY","ROAM_OFF"', '+ZPASR: "UMTS"'] DEBUG: Unhandled unsolicited modem notification: ['+ZDONR: "METEOR",272,3,"CS_ONLY","ROAM_OFF"', '+ZPASR: "UMTS"'] DEBUG: notification: ['+ZDONR: "METEOR",272,3,"CS_ONLY","ROAM_OFF"', '+ZPASR: "UMTS"'] DEBUG: Unhandled unsolicited modem notification: ['+ZDONR: "METEOR",272,3,"CS_ONLY","ROAM_OFF"', '+ZPASR: "UMTS"'] DEBUG: write: AT+CREG? DEBUG: response: ['+CREG: 0,1', 'OK'] DEBUG: write: AT+CMGS="0871111111" DEBUG: response: ['> '] DEBUG: write: test message DEBUG: response: ['+ZDONR: "METEOR",272,3,"CS_PS","ROAM_OFF"', '+ZPASR: "UMTS"', '+CMGS: 64', 'OK'] Message sent. DEBUG: notification: ['+CDSI: "SR",50'] DEBUG: SMS status report received DEBUG: write: AT+CPMS="SR" DEBUG: response: ['+CPMS: 1,100,2,100,2,100', 'OK'] DEBUG: write: AT+CMGR=50 DEBUG: response: ['+CMGR: ,6,64,"0871111111",129,"13/05/07,20:16:00+04","13/05/07,20:16:00+04",0', 'OK'] DEBUG: write: AT+CMGD=50 DEBUG: response: ['OK']

So when the sleep was too short (or not there at all), the second CREG was the same as the first one i.e. ['+CREG: 0,2', 'OK']

faucamp commented 11 years ago

Thanks a lot for the thorough testing! I've committed a patch that takes the CREG result into account. You should now be able to simply use waitForNetworkCoverage() after connect() as expected. When you have time, please check this let me know if this works?

dauheeIRL commented 11 years ago

OK getting so close now! When its not ready to send, the CREG value is: ['+CREG: 0,2', 'OK']

When it is ready to send, the CREG changes to: ['+CREG: 0,1', 'OK']

Hopefully this value isn't the complete opposite of other modem types

On Wed, May 8, 2013 at 9:55 AM, Francois Aucamp notifications@github.comwrote:

Thanks a lot for the thorough testing! I've committed a patch that takes the CREG result into account. You should now be able to simply use waitForNetworkCoverage() after connect() as expected. When you have time, please check this let me know if this works?

— Reply to this email directly or view it on GitHubhttps://github.com/faucamp/python-gsmmodem/issues/11#issuecomment-17593740 .

faucamp commented 11 years ago

Well I feel stupid. :/ Sorry about that - I had read the specs but somehow managed to put exactly the wrong value in the unit tests (and thus the implementation as well). Thanks!

dauheeIRL commented 11 years ago

not at all. I've been bombarding you with debug logs and multiple re-editing the same comment (which other users won't see) just to complicate things further!

On Wed, May 8, 2013 at 10:23 AM, Francois Aucamp notifications@github.comwrote:

Well I feel stupid. :/ Sorry about that - I had read the specs but somehow managed to put exactly the wrong value in the unit tests (and thus the implementation as well). Thanks!

— Reply to this email directly or view it on GitHubhttps://github.com/faucamp/python-gsmmodem/issues/11#issuecomment-17594849 .

dauheeIRL commented 11 years ago

Success! Thank you so much for this. Fantastic work as ever!