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
388 stars 304 forks source link

SMSC not available for a number of seconds after starting #10

Closed dauheeIRL closed 11 years ago

dauheeIRL commented 11 years ago

Apologies if I'm causing confusion I've opened up a fresh issue for what I've experienced. The code for stopping the SMSC from being wiped was perfect!

I was getting confused due to unplugging the modem sometimes, and also because self.smsc caching, changing versions of code, different timings because of me stepping through code in debug mode etc . . and most of all for me rushing!!

On first loading of this application, I still get a 330 no smsc error on the following line (175 of modem.py) of the latest code: currentSmscNumber = self.smsc

however on the second execution (while modem still connected) the error is not there. I believe this issue is due to an inital slowness of connection to the network, causing the SMSC not to be available for a few seconds. And because the AT+CSMP command needs the smsc somehow (and wipes it on me), the error was generating at that point for me.

So based on a possible timing issue, I tried the following grotesque test code after freshly plugging in the modem:

    starttime = time.time()
    print("start time %i"%(starttime))
    while True:
        try:
            self.write('AT+CSCA?') #won't reach next line if there is an error
            currentSmscNumber = self.smsc
            print('got smsc')
            break
        except:
            if ((time.time() - starttime) > 30):
                #raise error as no smsc is available
                print('timeout get smsc')
                break
            else:
                time.sleep(1)
                print('retry get smsc')
                pass
    print("took seconds: %i"%(time.time() - starttime))

    self.write('AT+CSMP=49,167,0,0', parseError=False) # Enable delivery reports

and got the following output: Initializing modem... start time 1367503949 retry get smsc retry get smsc retry get smsc retry get smsc retry get smsc retry get smsc retry get smsc retry get smsc retry get smsc got smsc took seconds: 9 Waiting for SMS and/or calls...

So it appears for my modem + network combination it is taking about 9-10 seconds for the SMSC to become available. By leaving in the modem, the next time I start the application, it takes 0 seconds - this means there will only be a delay for slower modem/networks and shouldn't impact other users of this code. I used the following at different points in the connect:

print("step 1 %s"%(self.write('AT+CSCA?', True, 5, False)))

and it proved that the SMSC just takes time to become available after the first execution, and is available from the start on the second execution.

So getting the currentSmscNumber before AT+CSMP and setting it afterwards was perfect. This has now moved onto another issue for me. You were totally right about the shotgun :)

Apologies I will leave you alone now and stop interfering :)

faucamp commented 11 years ago

Reposting most of my response from the previous thread :)

Thanks for the (very) thorough investigation! Your modem's behaviour in this regard is very strange; I've seen slow SIM cards and slow modems before, but it shouldn't give a 330 error if it is waiting for the SIM (or something else) - that's what the "_writeWait" attribute and automatic handling of CME 515 (device busy) and CME 14 (SIM busy) errors are for (in write()).

I'll try to come up with something that handles this in a similar fashion as the 515 and 14 errors, but for that I need more output from you (so that I can modify the modem profile I'm using for unit testing). Could you please modify that script you posted to print out the exact response from the modem instead of 'retry get smsc'? You'll need to change your while loop's condition as well. Try something along the lines of:

starttime = time.time()
print("start time %i"%(starttime))
while True:
    response = self.write('AT+CSCA?', parseError=False)
    print('response:',response)
    if response and response[-1] == 'OK':
        break
print('got smsc')
print("took seconds: %i"%(time.time() - starttime))
currentSmscNumber = self.smsc

Thanks (and thanks for your patience!)

dauheeIRL commented 11 years ago

Thank you very much for your patience, I'm hard work :)

The output I get is: Initializing modem... start time 1367509472 ('response:', ['ERROR']) . . . . . ... repeating entries deleted . . . . . ('response:', ['ERROR']) ('response:', ['ERROR']) ('response:', ['ERROR']) ('response:', ['ERROR']) ('response:', ['ERROR']) ('response:', ['ERROR']) ('response:', ['+CSCA: "+353857000000",145', 'OK']) got smsc took seconds: 8

faucamp commented 11 years ago

Thanks, but unfortunately we need slightly more info (it doesn't look like detailed error messages are turned on on that modem) - can you please add the following line right before the "while True" line:

print(self.write('AT+CMEE=1', parseError=False))

Thanks again.

dauheeIRL commented 11 years ago

OK great I put that in and a pause every second and getting the following: Initializing modem... ['OK'] start time 1367520960 ('response:', ['+CME ERROR: 14']) ('response:', ['+CME ERROR: 14']) ('response:', ['+CME ERROR: 14']) ('response:', ['+CME ERROR: 14']) ('response:', ['+CME ERROR: 14']) ('response:', ['+CME ERROR: 14']) ('response:', ['+CME ERROR: 14']) ('response:', ['+CME ERROR: 14']) ('response:', ['+CME ERROR: 14']) ('response:', ['+CME ERROR: 14']) ('response:', ['+CSCA: "+353857000000",145', 'OK']) got smsc took seconds: 10

faucamp commented 11 years ago

Hmm... we're missing something here. Those are "SIM busy" errors (which makes sense since the SMSC number is stored on the SIM card), but normally those errors are detected and handled automatically by the write() method (by slowing down the write call rate and retrying until the command succeeds). The addition of "parseError=False" to the write() bypasses this (which is why we are seeing the error).

What should be happening here is that your modem should appear to block for about 10 seconds during that "currentSmsc = self.smsc" call, but it should still work. My guess would be that the "AT+CMEE=1" call that happens earlier in connect() is somehow not handled properly by the modem (or is reset again at some point), causing the modem to not output that 14 error code - which would then be treated as an unknown error (i.e. it will cause a Python exception.

The only way to check for this is to enable full logging and run modem.connect(), and post the debug logs here. To enable logging, do something like this at the start of your script:

logging.basicConfig(format='%(levelname)s: %(message)s', level=logging.DEBUG)
dauheeIRL commented 11 years ago

Full debug output below hopefully it will show something up :) :

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="xxxxxxxxxxxxxxx" DEBUG: response: ['AT+CPIN="xxxxxxxxxxxxxx"\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+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+CMEE=1 DEBUG: response: ['OK'] ['OK'] start time 1367574867 DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14']('response:', ['+CME ERROR: 14']) DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14']('response:', ['+CME ERROR: 14']) DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14']('response:', ['+CME ERROR: 14']) DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14']('response:', ['+CME ERROR: 14']) DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14']('response:', ['+CME ERROR: 14']) 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']('response:', ['+CME ERROR: 14']) DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14']('response:', ['+CME ERROR: 14']) DEBUG: write: AT+CSCA? DEBUG: response: ['+CME ERROR: 14']('response:', ['+CME ERROR: 14']) DEBUG: write: AT+CSCA? DEBUG: response: ['+CSCA: "+353857000000",145', 'OK']('response:', ['+CSCA: "+353857000000",145', 'OK']) got smsc took seconds: 8 DEBUG: write: AT+CSCA? DEBUG: response: ['+CSCA: "+353857000000",145', 'OK'] 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"'] 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: 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"']

dauheeIRL commented 11 years ago

Just to comment, when I'm sending SMS after connect, I need to wait about 7 seconds because the unsolicited messages (seen after "Waiting for SMS and/or calls...") cause issues

faucamp commented 11 years ago

Thanks, this addresses one part of my assumption. The AT+CMEE is set before AT+CPIN and ATZ (in order to detect an incorrect PIN entry)... It might be that the ATZ is resetting it (especially since AT+CMEE is not set again afterwards). Ok, final request: could you please revert to the code from the repository (i.e. remove all the AT+CSCA? debug stuff we have added) and do a full debug log dump again? I'm expecting the code to fail exactly as you stated originally - I just want to see why the modem isn't auto-handling the CME 14 errors. Oh, and you might want to blank out the CPIN values from that code dump (I've done it already for your previous comment) ;-)

faucamp commented 11 years ago

Just to comment, when I'm sending SMS after connect, I need to wait about 7 seconds because the unsolicited messages (seen after "Waiting for SMS and/or calls...") cause issues

I'll investigate this - that modem of yours is quite chatty - but let's leave that for another ticket.

dauheeIRL commented 11 years ago

much appreciated for that. 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="xxxxx" DEBUG: response: ['AT+CPIN="xxxxxx"\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+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: ['ERROR'] Traceback (most recent call last): File "GSM2.py", line 67, in main() File "GSM2.py", line 39, in main modem.connect(PIN) File "c:\python27\lib\site-packages\gsmmodem\modem.py", line 176, in connect currentSmscNumber = self.smsc File "c:\python27\lib\site-packages\gsmmodem\modem.py", line 367, in smsc readSmsc = self.write('AT+CSCA?') File "c:\python27\lib\site-packages\gsmmodem\modem.py", line 277, in write raise CommandError(data) gsmmodem.exceptions.CommandError: AT+CSCA?

faucamp commented 11 years ago

That's it, thanks! :) The +CMEE setting is definitely being reset on your modem. This should be a simple fix, I'll apply it immediately.

faucamp commented 11 years ago

Ok, with the last update this should be fixed. Your connect() method should take a relatively long time to complete on the first execution (since it will wait for the SIM to become available before completing), but it should work. Please test it and close the issue if you are happy that it's fixed.

dauheeIRL commented 11 years ago

Ah fantastic that's it! Output enclosed below for reference:

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="xxxxxx" DEBUG: response: ['AT+CPIN="xxxxxx"\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: 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: 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"'] 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"'] DEBUG: Unhandled unsolicited modem notification: ['+ZDONR: "METEOR",272,3,"CS_ONLY","ROAM_OFF"'] DEBUG: notification: ['+ZPASR: "UMTS"'] DEBUG: Unhandled unsolicited modem notification: ['+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"']