weird "time out" problems when waiting for sms or sending with report #84

ChristianSch · 2020-01-31T13:53:55Z

Hi there,

I have the problem that when sending an sms, that in case of waitForDeliveryReport=True I get a time out, even with the sendsms script:

 (sms) λ sudo python sendsms.py -i /dev/ttyUSB0 -d "+49redacted" "test"
Connecting to GSM modem on /dev/ttyUSB0...
Checking for network coverage...

Sending SMS and waiting for delivery report...
Failed to send message: the send operation timed out

the sms_handler_demo.py "fails" with the following (I added the hanging_threads model to see where it hangs:

Initializing modem...
INFO: Connecting to modem on port /dev/ttyUSB0 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: ['+CLAC:&C,&D,&E,&F,&S,&V,&W,E,I,L,M,Q,V,X,Z,T,P,\\Q,\\S,\\V,%V,D,A,H,O,S0,S2,S3,S4,S5,S6,S7,S8,S9,S10,S11,S30,S103,S104,+FCLASS,+ICF,+IFC,+IPR,+GMI,+GMM,+GMR,+GCAP,+GSN,+DR,+DS,+WS46,+CLAC,+CCLK,+CBST,+CRLP,+CV120,+CHSN,+CSSN,+CREG,+CGREG,+CFUN,+GCAP,+CSCS,+CSTA,+CR,+CEER,+CRC,+CMEE,+CGDCONT,+CGDSCONT,+CGTFT,+CGEQREQ,+CGEQMIN,+CGQREQ,+CGQMIN,+CGEQNEG,+CGEREP,+CGPADDR,+CGCLASS,+CGSMS,+CSMS,+CMGF,+CSAS,+CRES,+CSCA,+CSMP,+CSDH,+CSCB,+FDD,+FAR,+FCL,+FIT,+ES,+ESA,+CMOD,+CVHU,+CGDATA,+CSQ,+CBC,+CPAS,+CPIN,+CMEC,+CKPD,+CGATT,+CGACT,+CGCMOD,+CPBS,+CPBR,+CPBF,+CPBW,+CPMS,+CNMI,+CMGL,+CMGR,+CMGS,+CMSS,+CMGW,+CMGD,+CMGC,+CNMA,+CMMS,+FTS,+FRS,+FTH,+FRH,+FTM,+FRM,+CHUP,+CCFC,+CCUG,+COPS,+CLCK,+CPWD,+CUSD,+CAOC,+CACM,+CAMM,+CPUC,+CCWA,+CHLD,+CIMI,+CGMI,+CGMM,+CGMR,+CGSN,+CNUM,+CSIM,+CRSM,+CCLK,+CLVL,+CMUT,+CLCC,+COPN,+CPOL,+CPLS,+CTZR,+CTZU,+CLAC,+CLIP,+COLP,+CDIP,+CTFR,+CLIR,$QCSIMSTAT,$QCCNMI,$QCCLR,$QCDMG,$QCDMR,$QCDNSP,$QCDNSS,$QCTER,$QCSLOT,$QCPINSTAT,$QCPDPP,$QCPDPLT,$QCPWRDN,$QCDGEN,$BREW,$QCSYSMODE,^STSF,^STGI,^STGR,^IMSICHG,^SYSINFO,^SYSCFG,^SYSCONFIG,^HS,^DTMF,^CPBR,^CPBW,^HWVER,^HVER,^DSFLOWCLR,^DSFLOWQRY,^DSFLOWRPT,^SPN,^PORTSEL,^CPIN,^SN,^EARST,^CARDLOCK,^CARDUNLOCK,^ATRECORD,^CDUR,^BOOT,^FHVER,^CURC,^FREQLOCK,^FREQPREF,^HSDPA,^CARDMODE,^U2DIAG,^PAD,^PCSCINFO,^CQI,^GETPORTMODE,^CVOICE,^DDSETEX,^pcmrecord,^PCMBUFFER,^CSNR,^CMSR,^CMMT,^CMGI,^PNN,^OPL,^CPNN,^ADCTEMP,^RDCUST,^SETPID,^DIALMODE,^YJCX,^NDISDUP,^DHCP,^AUTHDATA,^CRPN,^ICCID,', 'OK']
DEBUG: write: AT^CVOICE=0
DEBUG: response: ['OK']
INFO: Loading Huawei call state update table
DEBUG: write: AT+COPS=3,0
DEBUG: response: ['OK']
DEBUG: write: AT+CMGF=0
DEBUG: response: ['OK']
DEBUG: write: AT+CSCA?
DEBUG: response: ['+CSCA: "+provider service number",145', 'OK']
DEBUG: write: AT+CSMP=49,167,0,0
DEBUG: response: ['OK']
DEBUG: write: AT+CSCA?
DEBUG: response: ['+CSCA: "+provider service number",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,23,1,23,1,23', '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...
----------Thread 140217586341632 "Thread-2" hangs ----------
        File "/usr/lib64/python3.8/threading.py", line 890, in _bootstrap
                self._bootstrap_inner()
        File "/usr/lib64/python3.8/threading.py", line 932, in _bootstrap_inner
                self.run()
        File "/usr/lib64/python3.8/threading.py", line 870, in run
                self._target(*self._args, **self._kwargs)
        File "/home/redacted/.virtualenvs/sms/lib/python3.8/site-packages/gsmmodem/serial_comms.py", line 97, in _readLoop
                data = self.serial.read(1)
        File "/home/redacted/.virtualenvs/sms/lib/python3.8/site-packages/serial/serialposix.py", line 483, in read
                ready, _, _ = select.select([self.fd, self.pipe_abort_read_r], [], [], timeout.time_left())
---------Thread 140217601791808 "MainThread" hangs ---------
        File "sms_handler_demo.py", line 43, in <module>
                main()
        File "sms_handler_demo.py", line 38, in main
                modem.rxThread.join(2**31) # Specify a (huge) timeout so that it essentially blocks indefinitely, but still receives CTRL+C interrupt signal
        File "/usr/lib64/python3.8/threading.py", line 1015, in join
                self._wait_for_tstate_lock(timeout=max(timeout, 0))
        File "/usr/lib64/python3

Looks ok, but it never actually reads something. I can read sms when using modem.listStoredSms though. This fails as well, when I request a report (and no message is sent aswell). I can't compare to the older version, but I suspect the modem waits for some kind of terminator or something? My code worked perfectly in the old version but I had to port it to python 3 after 4 years now. Any advice is appreciated. Let me know if you need something.

The following is a log of my code (after the log) of the case when processing stored messages with a report:

(sms) λ sudo GSM_MODEM_TTY="/dev/ttyUSB0" python index.py
INFO: Connecting to modem on port /dev/ttyUSB0 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: ['+CLAC:&C,&D,&E,&F,&S,&V,&W,E,I,L,M,Q,V,X,Z,T,P,\\Q,\\S,\\V,%V,D,A,H,O,S0,S2,S3,S4,S5,S6,S7,S8,S9,S10,S11,S30,S103,S104,+FCLASS,+ICF,+IFC,+IPR,+GMI,+GMM,+GMR,+GCAP,+GSN,+DR,+DS,+WS46,+CLAC,+CCLK,+CBST,+CRLP,+CV120,+CHSN,+CSSN,+CREG,+CGREG,+CFUN,+GCAP,+CSCS,+CSTA,+CR,+CEER,+CRC,+CMEE,+CGDCONT,+CGDSCONT,+CGTFT,+CGEQREQ,+CGEQMIN,+CGQREQ,+CGQMIN,+CGEQNEG,+CGEREP,+CGPADDR,+CGCLASS,+CGSMS,+CSMS,+CMGF,+CSAS,+CRES,+CSCA,+CSMP,+CSDH,+CSCB,+FDD,+FAR,+FCL,+FIT,+ES,+ESA,+CMOD,+CVHU,+CGDATA,+CSQ,+CBC,+CPAS,+CPIN,+CMEC,+CKPD,+CGATT,+CGACT,+CGCMOD,+CPBS,+CPBR,+CPBF,+CPBW,+CPMS,+CNMI,+CMGL,+CMGR,+CMGS,+CMSS,+CMGW,+CMGD,+CMGC,+CNMA,+CMMS,+FTS,+FRS,+FTH,+FRH,+FTM,+FRM,+CHUP,+CCFC,+CCUG,+COPS,+CLCK,+CPWD,+CUSD,+CAOC,+CACM,+CAMM,+CPUC,+CCWA,+CHLD,+CIMI,+CGMI,+CGMM,+CGMR,+CGSN,+CNUM,+CSIM,+CRSM,+CCLK,+CLVL,+CMUT,+CLCC,+COPN,+CPOL,+CPLS,+CTZR,+CTZU,+CLAC,+CLIP,+COLP,+CDIP,+CTFR,+CLIR,$QCSIMSTAT,$QCCNMI,$QCCLR,$QCDMG,$QCDMR,$QCDNSP,$QCDNSS,$QCTER,$QCSLOT,$QCPINSTAT,$QCPDPP,$QCPDPLT,$QCPWRDN,$QCDGEN,$BREW,$QCSYSMODE,^STSF,^STGI,^STGR,^IMSICHG,^SYSINFO,^SYSCFG,^SYSCONFIG,^HS,^DTMF,^CPBR,^CPBW,^HWVER,^HVER,^DSFLOWCLR,^DSFLOWQRY,^DSFLOWRPT,^SPN,^PORTSEL,^CPIN,^SN,^EARST,^CARDLOCK,^CARDUNLOCK,^ATRECORD,^CDUR,^BOOT,^FHVER,^CURC,^FREQLOCK,^FREQPREF,^HSDPA,^CARDMODE,^U2DIAG,^PAD,^PCSCINFO,^CQI,^GETPORTMODE,^CVOICE,^DDSETEX,^pcmrecord,^PCMBUFFER,^CSNR,^CMSR,^CMMT,^CMGI,^PNN,^OPL,^CPNN,^ADCTEMP,^RDCUST,^SETPID,^DIALMODE,^YJCX,^NDISDUP,^DHCP,^AUTHDATA,^CRPN,^ICCID,', 'OK']
DEBUG: write: AT^CVOICE=0
DEBUG: response: ['OK']
INFO: Loading Huawei call state update table
DEBUG: write: AT+COPS=3,0
DEBUG: response: ['OK']
DEBUG: write: AT+CMGF=0
DEBUG: response: ['OK']
DEBUG: write: AT+CSCA?
DEBUG: response: ['+CSCA: "+49 provider service number",145', 'OK']
DEBUG: write: AT+CSMP=49,167,0,0
DEBUG: response: ['OK']
DEBUG: write: AT+CSCA?
DEBUG: response: ['+CSCA: "+49  provider service number145', '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,23,1,23,1,23', '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']
DEBUG: write: AT+CGMM
DEBUG: response: ['E1550', 'OK']
DEBUG: write: AT+CGSN
DEBUG: response: ['351911047523090', 'OK']
DEBUG: connected to modem:      model: E1550 (IMEI: redacted)
INFO: waiting for network coverage ...
DEBUG: write: AT+CREG?
DEBUG: response: ['+CREG: 0,1', 'OK']
DEBUG: write: AT+CSQ
DEBUG: response: ['+CSQ: 19,99', 'OK']
INFO: network coverage suffices, waiting for incoming notifications
DEBUG: processing stored messages
DEBUG: write: AT+CMGL=4
DEBUG: response: ['+CMGL: 0,0,,27', 'redacted', '+CMGL: 1,0,,34', 'redacted E4E9301', 'OK']
DEBUG: write: AT+CMGD=1,4
DEBUG: response: ['OK']
INFO:   +49 external number redacted says `redacted`
DEBUG: write: AT+CSCS=?
DEBUG: response: ['+CSCS: ("IRA","GSM","UCS2")', 'OK']
DEBUG: write: AT+CSCS="GSM"
DEBUG: response: ['OK']
DEBUG: write: AT+CMGS=85
DEBUG: response: ['> ']
DEBUG: write: redacted
DEBUG: response: ['+CMGS: 76', 'OK']
WARNING: /!\ SMS read/reply failed.
ERROR: None
INFO:   +49 external number redacted says `redacted`
DEBUG: write: AT+CSCS="GSM"
DEBUG: response: ['OK']
DEBUG: write: AT+CMGS=85
DEBUG: response: ['> ']
DEBUG: write: redacted
DEBUG: response: ['+CMGS: 77', 'OK']
----------Thread 139785630054144 "Thread-1" hangs ----------
        File "/usr/lib64/python3.8/threading.py", line 890, in _bootstrap
                self._bootstrap_inner()
        File "/usr/lib64/python3.8/threading.py", line 932, in _bootstrap_inner
                self.run()
        File "/usr/lib64/python3.8/threading.py", line 870, in run
                self._target(*self._args, **self._kwargs)
        File "/home/redacted/.virtualenvs/sms/lib/python3.8/site-packages/gsmmodem/serial_comms.py", line 97, in _readLoop
                data = self.serial.read(1)
        File "/home/redactedvirtualenvs/sms/lib/python3.8/site-packages/serial/serialposix.py", line 483, in read
                ready, _, _ = select.select([self.fd, self.pipe_abort_read_r], [], [], timeout.time_left())
WARNING: /!\ SMS read/reply failed.
ERROR: None
DEBUG: finished processing stored messages, waiting for new ones
---------Thread 139785641441088 "MainThread" hangs ---------
        File "index.py", line 135, in <module>
                modem.rxThread.join()
        File "/usr/lib64/python3.8/threading.py", line 1011, in join
                self._wait_for_tstate_lock()
        File "/usr/lib64/python3.8/threading.py", line 1027, in _wait_for_tstate_lock
                elif lock.acquire(block, timeout):

my (essential) code:


import logging
import sys
import os
from gsmmodem.modem import GsmModem
from hanging_threads import start_monitoring

BAUDRATE = 115200
PIN = None  # SIM card PIN (if any)

def handle_msg(sms):
    try:
        logger.info('\t{0} says `{1}`'.format(sms.number, sms.text))

        if customer:
            rec_msg = # some message

            msg = rec_msg.format(sms.number)

            out_sms = modem.sendSms(customer['telephone'],
                                    msg,
                                    # waitForDeliveryReport=False)
                                    waitForDeliveryReport=True)

            logger.debug('\tsent message `{0}` to customer ({1})'.format(msg, customer['telephone']))

            reply = # some reply

            if out_sms.report:
                logger.info('\t{0}'.format(out_sms.report))
        else:
            logger.debug('\t/!\ no customer found')
            msg = # some error message
            reply = msg.format(sms.text)

        # either confirmation or error message
        logger.debug('\treplying with: "%s" to %s' % (reply, sms.number))
        sms.reply(reply)

    except Exception as e:
        logger.warning("/!\\ SMS read/reply failed.")
        logger.error(e)

if __name__ == "__main__":
    # logging setup removed for brevity
    modem = GsmModem(os.getenv('GSM_MODEM_TTY'),
                     BAUDRATE,
                     smsReceivedCallbackFunc=handle_msg)
    modem.smsTextMode = False
    modem.connect(PIN)

    logger.debug('connected to modem:\tmodel: %s (IMEI: %s)' % (modem.model, modem.imei))
    logger.info('waiting for network coverage ...')

    try:
        modem.waitForNetworkCoverage(5)
        logger.info('network coverage suffices, waiting for incoming notifications')
    except TimeoutException:
        logger.warning('network signal strength is not sufficient, please'
                       ' adjust modem position/antenna and try again.')
        modem.close()
        sys.exit(1)

    monitoring_thread = start_monitoring(seconds_frozen=30)
    logger.debug('processing stored messages')
    for sms in modem.listStoredSms(delete=True):
        handle_msg(sms)
    logger.debug('finished processing stored messages, waiting for new ones')

    try:
        modem.rxThread.join() # note no 2**31, but also fails the same with this value
    finally:
        modem.close()

The text was updated successfully, but these errors were encountered:

tomchy · 2021-02-12T17:20:28Z

Hi @ChristianSch !
Does the issue is reproduced if you use destination number, that does not contain letters?

ChristianSch · 2021-02-25T22:50:14Z

Hi @tomchy, I'm afraid I can't really check it anymore.

lcnittl · 2021-11-03T00:48:58Z

Should we close this, as it is not reproducible/check-able anymore?

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

weird "time out" problems when waiting for sms or sending with report #84

weird "time out" problems when waiting for sms or sending with report #84

ChristianSch commented Jan 31, 2020 •

edited

tomchy commented Feb 12, 2021

ChristianSch commented Feb 25, 2021

lcnittl commented Nov 3, 2021

weird "time out" problems when waiting for sms or sending with report #84

weird "time out" problems when waiting for sms or sending with report #84

Comments

ChristianSch commented Jan 31, 2020 • edited

tomchy commented Feb 12, 2021

ChristianSch commented Feb 25, 2021

lcnittl commented Nov 3, 2021

ChristianSch commented Jan 31, 2020 •

edited