search

vshymanskyy / TinyGSM

A small Arduino library for GSM modules, that just works
GNU Lesser General Public License v3.0
1.95k stars 723 forks source link

[SIM800] read() stuck forever #111

Open hubaksis opened 6 years ago

hubaksis commented 6 years ago

Hi, I've faced an issue trying to connect to a website using HTTPS. Not sure how to reproduce it. It just happens once a few hours of every minute requests.

I am using a code from the example folder for HTTPS. Issue happens (not often) when I try to read response statuse code in this line: int status = http.responseStatusCode();

I added extra logging to the read function in the TinyGsmClientSIM800.h like this:

while (cnt < size) {
       //dbg
      Serial.print(cnt); Serial.print(" < "); Serial.println(size);
      size_t chunk = TinyGsmMin(size-cnt, rx.size());
      //dbg
      Serial.println(chunk);
      if (chunk > 0) {
        rx.get(buf, chunk);
        buf += chunk;
        cnt += chunk;
        continue;
      }
      //dbg
      Serial.println(F("read 3"));
      // TODO: Read directly into user buffer?
      at->maintain();
      Serial.println(F("read 4"));
      if (sock_available > 0) {
          Serial.println(F("read 5"));
        at->modemRead(rx.free(), mux);
      } else {
        break;
      }
      Serial.println(F("read 6"));
    }

And got the following log:

HTTP GET request completed 

read 1
read 2
0 < 1
0
read 3
read 4
read 5
AT+CIPRXGET=2,1,199

ERROR
read 6
0 < 1
0
read 3
read 4
read 5
AT+CIPRXGET=2,1,199

ERROR
read 6
0 < 1
0
read 3
read 4
read 5
AT+CIPRXGET=2,1,199

ERROR
read 6
0 < 1
0
read 3
read 4
read 5
AT+CIPRXGET=2,1,199

forever.

The only thing I thought of is to add a counter and stop the cycle if this thing happens like:

int tries = 0;

    while (cnt < size && tries < 1000) {
       //dbg
      Serial.print(cnt); Serial.print(" < "); Serial.println(size);
      size_t chunk = TinyGsmMin(size-cnt, rx.size());
      //dbg
      Serial.println(chunk);
      if (chunk > 0) {
        rx.get(buf, chunk);
        buf += chunk;
        cnt += chunk;
        continue;
      }
      //dbg
      Serial.println(F("read 3"));
      // TODO: Read directly into user buffer?
      at->maintain();
      Serial.println(F("read 4"));
      if (sock_available > 0) {
          Serial.println(F("read 5"));
        at->modemRead(rx.free(), mux);
      } else {
        break;
      }
      Serial.println(F("read 6"));
      tries++;
    }

Do you know what causes this issue and how to avoid it in a more civilized manner?

Thanks.

dawidcieszynski commented 6 years ago

I had some time problems with device hanging and not restarting. There was missing timeout handling, this fixed issue https://github.com/vshymanskyy/TinyGSM/pull/101. Maybe it will help you too.

hubaksis commented 6 years ago

Thank you, I'll check it. I added your fix to my code.

The issue is somewhere deeper as my workaround (with 1000 tries, then fail as I described earlier) didn't work: after the issue happened again - no success requests were made. All of them where halted by my threshold.

I added another step in the main cycle: if I have more then 10 bad requests - restart modem. Will see whether it will help.

lathoub commented 6 years ago

I appears that the issue is in modemRead

The +CIPRXGET response indicates the amount of bytes that are ready to be read (the 3rd parameter). modemreadassumes that indeed these amout of characters CAN be read. This turns out not to be case. Sometimes stream.readreturns -1before the expected number of characters are read!

I suggest to alter modemRead from:

      while (!stream.available()) { TINY_GSM_YIELD(); }
      char c = stream.read();

to:

      //while (!stream.available()) { TINY_GSM_YIELD(); }
      int8_t c = stream.read();
      if (c == -1)
          return i;

I tested it on a Adafruit FONA 32U4 (SIM800L) using the HttpClientexample on server: arduino.ccand resource: /asciilogo.txt(Arduino IDE 1.8.5)

Can someone confirm my fix?

118

ta2edchimp commented 6 years ago

I just had a similar issue (modemRead being randomly stuck for anything between five minutes to hours!), but fixed it using a timedRead approach.
IMO this approach has the following advantages:

In modemRead:

  size_t modemRead( size_t size, uint8_t mux ) {
    // ...

    for ( size_t i = 0; i < len; i++ ) {
      // ...

     int8_t c = streamTimedRead();
     if ( c == - 1) {
        return i;
     }

      sockets[ mux ]->rx.put( c );
    }

    waitResponse();

    return len;
  }

calling streamTimedRead:

  int8_t streamTimedRead() {
    uint32_t timeout = 1000;
    uint32_t startMillis = millis();
    int8_t c;

    do {
      c = stream.read();
      if ( c >= 0 ) {
        return c;
      }
    } while ( millis() - startMillis < timeout );

    return -1;
  }
Mark-Wills commented 6 years ago

I can't confirm 100%, but this sounds/looks like heap fragmentation. After a while the heap (there's only 2K of RAM in the ATMEGA328P) is too fragmented, and calls to malloc() inside the Arduino String class start to fail.

lafbrazil commented 6 years ago

@ta2edchimp @Mark-Wills

Hi Mark and Andreas,

I am using :

TinyGSM version: v.0.3.5 Modem: SIM808 R14.18 ATmega2560

Sketch uses 70062 bytes (27%) of program storage space. Maximum is 253952 bytes. Global variables use 4678 bytes (57%) of dynamic memory, leaving 3514 bytes for local variables. Maximum is 8192 bytes

-- The issue remain the same... after running per 4 hours and 30 minutes the PCB is freezing and an physical reset is required.

Previous issues:

119 - [SIM800] Get request over HTTPS fires only once for SIM808

111 - [SIM800] read() stuck forever

69 - [SIM800] Looping with ERROR AT+CIPRXGET=2,1,63

65 - Remove recursive call to waitResponse() that removes unprocessed data…

62 - [SIM868] library doesn't receive "1, CLOSED" message from modem

21 - [SIM900/SIM800] ERROR LOOP after a short time

4 - [SIM900/SIM800] Freeze after about 15 Minutes

LOG

[13:16:05.450] AT+CSQ ....... working fine...... [17:41:55.605] Modem inittialized [17:41:55.625] [17:46:17.527] AT+CSQ [17:46:17.545] Call Ready [17:46:17.564] [17:46:17.564] SMS Ready [17:46:17.591] [17:46:17.591] +CSQ: 20,0 [17:46:17.591] [17:46:17.591] OK [17:46:17.607] Sending data throguh GPRS [17:46:17.623] AT+CGATT? [17:46:17.644] [17:46:17.703] +CGATT: 1 [17:46:17.724] [17:46:17.724] OK [17:46:17.751] AT+CIFSR;E0 [17:46:17.751] [17:46:17.751] ERROR [17:46:17.767] Waiting for network...AT+CREG? [17:46:17.803] [17:46:17.803] +CREG: 0,5 [17:46:17.831] [17:46:17.831] OK [17:46:17.831] OK [17:46:17.847] smartgaas.algar.brAT+CIPSHUT [17:46:17.883] [17:46:17.883] SHUT OK [17:46:17.911] AT+CGATT=0 [17:46:17.911] [17:46:18.744] [17:46:18.744] OK [17:46:18.765] AT+SAPBR=3,1,"Contype","GPRS" [17:46:18.803] [17:46:18.844] OK [17:46:18.844] AT+SAPBR=3,1,"APN","smartgaas.algar.br" [17:46:18.894] [17:46:18.937] OK [17:46:18.954] AT+SAPBR=3,1,"USER","XXXX" [17:46:18.994] [17:46:19.035] OK [17:46:19.035] AT+SAPBR=3,1,"PWD","XXXX" [17:46:19.065] [17:46:19.097] OK [17:46:19.114] AT+CGDCONT=1,"IP","smartgaas.algar.br" [17:46:19.161] [17:46:19.209] OK [17:46:19.225] AT+CGACT=1,1 [17:46:19.244] [17:46:25.713] [17:46:25.713] OK [17:46:25.713] AT+SAPBR=1,1 [17:46:25.734] [17:46:26.530] [17:46:26.530] OK [17:46:26.530] AT+SAPBR=2,1 [17:46:26.546] [17:46:26.578] +SAPBR: 1,1,"100.89.162.11" [17:46:26.722] [17:46:26.722] OK [17:46:26.722] AT+CGATT=1 [17:46:26.743] [17:46:26.763] OK [17:46:26.763] AT+CIPMUX=1 [17:46:26.783] [17:46:26.807] OK [17:46:26.807] AT+CIPQSEND=1 [17:46:26.824] [17:46:26.851] OK [17:46:26.873] AT+CIPRXGET=1 [17:46:26.899] OK [17:46:26.915] AT+CSTT="smartgaas.algar.br","XXXX","XXXX" [17:46:26.973] [17:46:27.027] OK [17:46:27.027] AT+ [17:46:27.043] CIICR [17:46:27.043] [17:46:27.083] OK [17:46:27.083] AT+CIFSR;E0 [17:46:27.101] [17:46:27.139] 100.89.162.11 [17:46:27.155] [17:46:27.155] OK [17:46:27.155] AT+CDNSCFG="8.8.8.8","8.8.4.4" [17:46:27.192] [17:46:27.235] OK [17:46:27.253] Connected [17:46:27.274] ---Incoming Data start ... Connection 1 [17:46:27.303] Connection already open [17:46:27.347] Connected [17:46:27.347] AT+CIPSEND=1,3 [17:46:27.363] [17:46:27.363] ERROR [17:46:27.363] AT+CIPSEND=1,1 [17:46:27.383] [17:46:27.383] ERROR [17:46:27.403] AT+CIPSEND=1,36 [17:46:27.423] [17:46:27.443] ERROR [17:46:27.468] AT+CIPSEND=1,9 [17:46:27.483] [17:46:27.507] ERROR [17:46:27.523] AT+CIPSEND=1,2 [17:46:27.543] [17:46:27.572] [17:46:27.572] ERROR [17:46:27.594] GET /apis/device/01B26A/1.24/13.00/14.48 HTTP/1.1 [17:46:27.636] AT+CIPSEND=1,6 [17:46:27.655] [17:46:27.700] ERROR [17:46:27.716] AT+CIPSEND=1,17 [17:46:27.734] [17:46:27.780] ERROR [17:46:27.780] AT+CIPSEND=1,1 [17:46:27.796] [17:46:27.833] ERROR [17:46:27.833] AT+CIPSEND=1,3 [17:46:27.851] [17:46:27.876] ERROR [17:46:27.893] AT+CIPSEND=1,2 [17:46:27.913] [17:46:27.940] ERROR [17:46:27.956] AT+CIPSEND=1,10 [17:46:27.973] [17:46:28.004] ERROR [17:46:28.025] AT+CIPSEND=1,2 [17:46:28.048] [17:46:28.068] ERR [17:46:28.084] OR [17:46:28.084] AT+CIPSEND=1,13 [17:46:28.104] [17:46:28.132] ERROR [17:46:28.153] AT+CIPSEND=1,2 [17:46:28.173] [17:46:28.196] ERROR [17:46:28.213] AT+CIPSEND=1,2 [17:46:28.234] [17:46:28.260] ERROR [17:46:28.276]

arihantdaga commented 5 years ago

I am also stuck with a similar problem, i am not sure if this is due to exact same issue, but its important to fix this - I am using Sim800 Module. In my case modem always returns data in response to AT+CIPRXGET. While that should have been 0. This is my log

+CIPRXGET: 4,1,2871

OK
AT+CIPRXGET=2,1,63

+CIPRXGET: 2,1,63,2808
ng/s=a:KU/864287038236863/ping/s<a:KU/864287038236863/p
OK
[1575571] [MQTT] Received  KU/864287038236863/ping/s
AT+CSQ

+CSQ: 9,0

OK
[1575583] [MQTT] Sending Message on  KU/864287038236863/ping/g
AT+CIPSEND=1,67
>0AKU/864287038236863/ping/g{"NW":9,"AP":1,"PE":1,"HS":1,"RS":[1]} 
1, SEND FAIL
[1576598] ### Unhandled: 1, SEND FAIL
AT+CIPSEND=1,4

>@= 
1, SEND FAIL
[1577602] ### Unhandled: 1, SEND FAIL
AT+CSQ

+CSQ: 9,0

OK
[1577606] [MQTT] Sending Message on  KU/864287038236863/ping/g
AT+CIPSEND=1,96

>0^KU/864287038236863/ping/g{"NW":9,"AP":1,"switch":{"relays":[1]},"other":{"health":1,"pe":1}} 
1, SEND FAIL
[1578621] ### Unhandled: 1, SEND FAIL
AT+CMGL="REC UNREAD",1

OK
[1583623] ### Unhandled: OK
[1584623] [MQTT] Received  KU/864287038236863/ping/s
AT+CSQ

+CSQ: 11,0

OK
[1584635] [MQTT] Sending Message on  KU/864287038236863/ping/g
AT+CIPSEND=1,68

>0BKU/864287038236863/ping/g{"NW":11,"AP":1,"PE":1,"HS":1,"RS":[1]} 
1, SEND FAIL
[1585649] ### Unhandled: 1, SEND FAIL
AT+CIPSEND=1,4

>@< 
1, SEND FAIL
[1586653] ### Unhandled: 1, SEND FAIL
AT+CSQ

+CSQ: 11,0

OK
[1586657] [MQTT] Sending Message on  KU/864287038236863/ping/g
AT+CIPSEND=1,97

>0_KU/864287038236863/ping/g{"NW":11,"AP":1,"switch":{"relays":[1]},"other":{"health":1,"pe":1}} 
1, SEND FAIL
[1587672] ### Unhandled: 1, SEND FAIL
AT+CMGL="REC UNREAD",1

OK
[1592674] ### Unhandled: OK
AT+CIPRXGET=4,1

+CIPRXGET: 4,1,2808

OK
AT+CIPRXGET=2,1,63

+CIPRXGET: 2,1,63,2745
ing/s;a:KU/864287038236863/ping/sXa:KU/864287038236863/
OK
[1593692] [MQTT] Received  KU/864287038236863/ping/s
AT+CSQ

+CSQ: 7,0

OK
[1593705] [MQTT] Sending Message on  KU/864287038236863/ping/g
AT+CIPSEND=1,67

>0AKU/864287038236863/ping/g{"NW":7,"AP":1,"PE":1,"HS":1,"RS":[1]} 
1, SEND FAIL
[1594719] ### Unhandled: 1, SEND FAIL
AT+CIPSEND=1,4

>@; 
1, SEND FAIL
[1595723] ### Unhandled: 1, SEND FAIL
AT+CSQ

+CSQ: 7,0

OK
[1595727] [MQTT] Sending Message on  KU/864287038236863/ping/g
AT+CIPSEND=1,96

>0^KU/864287038236863/ping/g{"NW":7,"AP":1,"switch":{"relays":[1]},"other":{"health":1,"pe":1}} 
1, SEND FAIL
[1596742] ### Unhandled: 1, SEND FAIL
AT+CMGL="REC UNREAD",1

OK
[1601744] ### Unhandled: OK
[1602744] [MQTT] Received  KU/864287038236863/ping/s
AT+CSQ

+CSQ: 9,0

OK
[1602756] [MQTT] Sending Message on  KU/864287038236863/ping/g
AT+CIPSEND=1,67

>0AKU/864287038236863/ping/g{"NW":9,"AP":1,"PE":1,"HS":1,"RS":[1]} 
1, SEND FAIL
[1603770] ### Unhandled: 1, SEND FAIL
AT+CIPSEND=1,4

>@X 
1, SEND FAIL
[1604774] ### Unhandled: 1, SEND FAIL
AT+CSQ

+CSQ: 9,0

OK
[1604778] [MQTT] Sending Message on  KU/864287038236863/ping/g
AT+CIPSEND=1,96

>0^KU/864287038236863/ping/g{"NW":9,"AP":1,"switch":{"relays":[1]},"other":{"health":1,"pe":1}} 
1, SEND FAIL
[1605793] ### Unhandled: 1, SEND FAIL
AT+CMGL="REC UNREAD",1

OK
[1610795] ### Unhandled: OK
AT+CIPRXGET=4,1

+CIPRXGET: 4,1,2745

OK
AT+CIPRXGET=2,1,63

+CIPRXGET: 2,1,63,2682

Note this - 

AT+CIPRXGET=4,1

+CIPRXGET: 4,1,2745

OK
AT+CIPRXGET=2,1,63

+CIPRXGET: 2,1,63,2682

In response to AT+CIPRXGET=4,1 it's returning 2745 bytes of data, but actually there is no data. and it seems to just keep growing and module is always stuck in this loop...

lafbrazil commented 5 years ago

Use baud rate 4800;

Sent from my iPhone LAF - Luís Augusto Ferreira lafbrazil2050@gmail.com (55) 11 99230 8535

Em 8 de fev de 2019, à(s) 08:58, arihant daga notifications@github.com escreveu:

I am also stuck with a similar problem, i am not sure if this is due to exact same issue, but its important to fix this - I am using Sim800 Module. In my case modem always returns data in response to AT+CIPRXGET. While that should have been 0. This is my log

+CIPRXGET: 4,1,2871

OK AT+CIPRXGET=2,1,63

+CIPRXGET: 2,1,63,2808 ng/s�=a:���KU/864287038236863/ping/s�<a:���KU/864287038236863/p OK [1575571] [MQTT] Received KU/864287038236863/ping/s AT+CSQ

+CSQ: 9,0

OK [1575583] [MQTT] Sending Message on KU/864287038236863/ping/g AT+CIPSEND=1,67

0A��KU/864287038236863/ping/g{"NW":9,"AP":1,"PE":1,"HS":1,"RS":[1]} 1, SEND FAIL [1576598] ### Unhandled: 1, SEND FAIL AT+CIPSEND=1,4

@��= 1, SEND FAIL [1577602] ### Unhandled: 1, SEND FAIL AT+CSQ

+CSQ: 9,0

OK [1577606] [MQTT] Sending Message on KU/864287038236863/ping/g AT+CIPSEND=1,96

0^��KU/864287038236863/ping/g{"NW":9,"AP":1,"switch":{"relays":[1]},"other":{"health":1,"pe":1}} 1, SEND FAIL [1578621] ### Unhandled: 1, SEND FAIL AT+CMGL="REC UNREAD",1

OK [1583623] ### Unhandled: OK [1584623] [MQTT] Received KU/864287038236863/ping/s AT+CSQ

+CSQ: 11,0

OK [1584635] [MQTT] Sending Message on KU/864287038236863/ping/g AT+CIPSEND=1,68

0B��KU/864287038236863/ping/g{"NW":11,"AP":1,"PE":1,"HS":1,"RS":[1]} 1, SEND FAIL [1585649] ### Unhandled: 1, SEND FAIL AT+CIPSEND=1,4

@��< 1, SEND FAIL [1586653] ### Unhandled: 1, SEND FAIL AT+CSQ

+CSQ: 11,0

OK [1586657] [MQTT] Sending Message on KU/864287038236863/ping/g AT+CIPSEND=1,97

0_��KU/864287038236863/ping/g{"NW":11,"AP":1,"switch":{"relays":[1]},"other":{"health":1,"pe":1}} 1, SEND FAIL [1587672] ### Unhandled: 1, SEND FAIL AT+CMGL="REC UNREAD",1

OK [1592674] ### Unhandled: OK AT+CIPRXGET=4,1

+CIPRXGET: 4,1,2808

OK AT+CIPRXGET=2,1,63

+CIPRXGET: 2,1,63,2745 ing/s�;a:���KU/864287038236863/ping/s�Xa:���KU/864287038236863/ OK [1593692] [MQTT] Received KU/864287038236863/ping/s AT+CSQ

+CSQ: 7,0

OK [1593705] [MQTT] Sending Message on KU/864287038236863/ping/g AT+CIPSEND=1,67

0A��KU/864287038236863/ping/g{"NW":7,"AP":1,"PE":1,"HS":1,"RS":[1]} 1, SEND FAIL [1594719] ### Unhandled: 1, SEND FAIL AT+CIPSEND=1,4

@��; 1, SEND FAIL [1595723] ### Unhandled: 1, SEND FAIL AT+CSQ

+CSQ: 7,0

OK [1595727] [MQTT] Sending Message on KU/864287038236863/ping/g AT+CIPSEND=1,96

0^��KU/864287038236863/ping/g{"NW":7,"AP":1,"switch":{"relays":[1]},"other":{"health":1,"pe":1}} 1, SEND FAIL [1596742] ### Unhandled: 1, SEND FAIL AT+CMGL="REC UNREAD",1

OK [1601744] ### Unhandled: OK [1602744] [MQTT] Received KU/864287038236863/ping/s AT+CSQ

+CSQ: 9,0

OK [1602756] [MQTT] Sending Message on KU/864287038236863/ping/g AT+CIPSEND=1,67

0A��KU/864287038236863/ping/g{"NW":9,"AP":1,"PE":1,"HS":1,"RS":[1]} 1, SEND FAIL [1603770] ### Unhandled: 1, SEND FAIL AT+CIPSEND=1,4

@��X 1, SEND FAIL [1604774] ### Unhandled: 1, SEND FAIL AT+CSQ

+CSQ: 9,0

OK [1604778] [MQTT] Sending Message on KU/864287038236863/ping/g AT+CIPSEND=1,96

0^��KU/864287038236863/ping/g{"NW":9,"AP":1,"switch":{"relays":[1]},"other":{"health":1,"pe":1}} 1, SEND FAIL [1605793] ### Unhandled: 1, SEND FAIL AT+CMGL="REC UNREAD",1

OK [1610795] ### Unhandled: OK AT+CIPRXGET=4,1

+CIPRXGET: 4,1,2745

OK AT+CIPRXGET=2,1,63

+CIPRXGET: 2,1,63,2682 Note this -

AT+CIPRXGET=4,1

+CIPRXGET: 4,1,2745

OK AT+CIPRXGET=2,1,63

+CIPRXGET: 2,1,63,2682 In response to AT+CIPRXGET=4,1 it's returning 2745 bytes of data, but actually there is no data. and it seems to just keep growing and module is always stuck in this loop...

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub, or mute the thread.

arihantdaga commented 5 years ago

Hi @lafbrazil, Thank you for helping out, but 4800 will be very low and how is baud rate related to available data in network buffer.

felipeas commented 5 years ago

Any changes on this matter? I'm getting this very same issue.

I'm currently using somewhat of workaround that counts a very long timer in the TINY_GSM_YIELD func, and restarts the device if it gets too high;

SRGDamia1 commented 4 years ago

Have any of you had issues with this more recently?

semajoel commented 2 years ago

solution from @ta2edchimp seems to work fine