SoftwareSerial doesn't read data after a certain time being idle

[gutierrezps]

I was trying to use a RDM6300 RFID reader with the ESP8266, when I faced a weird issue: sometimes the ESP wasn't detecting that a tag was being read. Upon adding some debug code, I noticed the available() method from SoftwareSerial was returning false, even when there was data being sent constantly to the input pin. Upon further tests, I found out this problem always happened at a certain time after the last successful SoftwareSerial reading.

Then I was able to isolate the problem and make it reproducible, as follows.

Environment

• OS: Windows 7 x64
• IDE: Visual Studio Code + PlatformIO
• PlatformIO core version: 3.6.7
• Espressif 8266 platform version: 2.2.1
• ESP8266 Arduino core version: 2.5.2
• Board: Wemos D1 Mini v2.2.0

Circuit

ESP8266 firmware

#include <Arduino.h>
#include "SoftwareSerial.h"

const uint8_t pin_softSerialRx = D6;
const uint8_t pin_confirmation = D8;

SoftwareSerial softSerial(pin_softSerialRx, -1);

void setup()
{
    Serial.begin(115200);
    softSerial.begin(9600);

    pinMode(pin_confirmation, OUTPUT);
    digitalWrite(pin_confirmation, LOW);

    Serial.println("\n\nWaiting softSerial input");
}

void loop()
{
    static uint32_t lastSoftSerialInput = 0;
    static uint16_t lastSecondsPrinted = 0;

    if (softSerial.available()) {
        if (millis() - lastSoftSerialInput > 300) Serial.print(" # received: ");

        while (softSerial.available()) {
            Serial.print((char) softSerial.read());
            yield();
        }

        lastSoftSerialInput = millis();
        lastSecondsPrinted = 0;     // restart seconds count on Serial
    }

    // turn LED on for 100ms
    bool ledState = millis() - lastSoftSerialInput < 100;
    digitalWrite(pin_confirmation, ledState);

    uint16_t secondsSinceLastInput = (millis() - lastSoftSerialInput) / 1000;

    if (secondsSinceLastInput != lastSecondsPrinted) {
        lastSecondsPrinted = secondsSinceLastInput;
        if (secondsSinceLastInput == 1) Serial.println();
        Serial.print(secondsSinceLastInput, DEC);
        Serial.print(" ");
    }

    delay(10);
}

Arduino Nano Firmware

#include <Arduino.h>

// Available at: <https://github.com/PaulStoffregen/AltSoftSerial>
#include "AltSoftSerial.h"

AltSoftSerial altSerial;        // TX pin: 9 (fixed)

const uint8_t pin_confirmation = 4;

const uint32_t k_firstTestNo = 1;
const uint32_t k_delayBetweenTestsMs = 1000UL;
const uint32_t k_confirmationTimeoutMs = 100;

void setup()
{
    Serial.begin(115200);
    altSerial.begin(9600);

    Serial.println("EspSoftwareSerial test begin");
}

void loop()
{
    static uint32_t nextTestMillis = 0;
    static uint32_t testNo = k_firstTestNo;

    if (millis() < nextTestMillis) return;

    Serial.print("test no. ");
    Serial.print(testNo);
    Serial.print(": \t");

    altSerial.print(String(testNo));

    uint32_t start = millis();
    bool timeout = true;

    while (millis() - start < k_confirmationTimeoutMs) {
        if (digitalRead(pin_confirmation) == HIGH) {
            timeout = false;
            break;
        }
    }

    ++testNo;

    uint32_t incrementMs = 0;

    if (timeout) {
        Serial.print(" timeout");
        incrementMs = k_delayBetweenTestsMs;
    }
    else {
        Serial.print(" confirmed");
        incrementMs = testNo * k_delayBetweenTestsMs;
    }

    Serial.print("\tnext test in ");
    Serial.print(incrementMs);
    Serial.println("ms");
    
    nextTestMillis = millis() + incrementMs;
}

How it works

The Arduino sends data through Serial to the ESP8266, periodically at nextTestMillis (whose value is updated every test through incrementMs). When the ESP detects data, pin_confirmation goes high for 100ms. This ESP output is then read by the Arduino, and if it gets high after Arduino has sent data, incrementMs is increased in order to increase the ESP's idle time between tests. Otherwise, if the ESP doesn't confirm that it received data, a new test is scheduled to the minimum interval, k_delayBetweenTestsMs, until the ESP issues the confirmation signal.

Below are the test outputs (up to test no. 58).

Arduino Nano output

EspSoftwareSerial test begin
test no. 1:      confirmed      next test in 2000ms
test no. 2:      confirmed      next test in 3000ms
test no. 3:      confirmed      next test in 4000ms
test no. 4:      confirmed      next test in 5000ms
test no. 5:      confirmed      next test in 6000ms
test no. 6:      confirmed      next test in 7000ms
test no. 7:      confirmed      next test in 8000ms
test no. 8:      confirmed      next test in 9000ms
test no. 9:      confirmed      next test in 10000ms
test no. 10:     confirmed      next test in 11000ms
test no. 11:     confirmed      next test in 12000ms
test no. 12:     confirmed      next test in 13000ms
test no. 13:     confirmed      next test in 14000ms
test no. 14:     confirmed      next test in 15000ms
test no. 15:     confirmed      next test in 16000ms
test no. 16:     confirmed      next test in 17000ms
test no. 17:     confirmed      next test in 18000ms
test no. 18:     confirmed      next test in 19000ms
test no. 19:     confirmed      next test in 20000ms
test no. 20:     confirmed      next test in 21000ms
test no. 21:     confirmed      next test in 22000ms
test no. 22:     confirmed      next test in 23000ms
test no. 23:     confirmed      next test in 24000ms
test no. 24:     confirmed      next test in 25000ms
test no. 25:     confirmed      next test in 26000ms
test no. 26:     confirmed      next test in 27000ms
test no. 27:     timeout        next test in 1000ms
test no. 28:     timeout        next test in 1000ms
test no. 29:     timeout        next test in 1000ms
test no. 30:     timeout        next test in 1000ms
test no. 31:     timeout        next test in 1000ms
test no. 32:     timeout        next test in 1000ms
test no. 33:     timeout        next test in 1000ms
test no. 34:     timeout        next test in 1000ms
test no. 35:     timeout        next test in 1000ms
test no. 36:     timeout        next test in 1000ms
test no. 37:     timeout        next test in 1000ms
test no. 38:     timeout        next test in 1000ms
test no. 39:     timeout        next test in 1000ms
test no. 40:     timeout        next test in 1000ms
test no. 41:     timeout        next test in 1000ms
test no. 42:     timeout        next test in 1000ms
test no. 43:     timeout        next test in 1000ms
test no. 44:     timeout        next test in 1000ms
test no. 45:     timeout        next test in 1000ms
test no. 46:     timeout        next test in 1000ms
test no. 47:     timeout        next test in 1000ms
test no. 48:     timeout        next test in 1000ms
test no. 49:     timeout        next test in 1000ms
test no. 50:     timeout        next test in 1000ms
test no. 51:     timeout        next test in 1000ms
test no. 52:     confirmed      next test in 53000ms
test no. 53:     timeout        next test in 1000ms
test no. 54:     confirmed      next test in 55000ms
test no. 55:     confirmed      next test in 56000ms
test no. 56:     confirmed      next test in 57000ms
test no. 57:     confirmed      next test in 58000ms
test no. 58:     confirmed      next test in 59000ms

ESP8266 output

Waiting softSerial input

1  # received: 1
1 2  # received: 2
1 2  # received: 3
1 2 3  # received: 4
1 2 3 4  # received: 5
1 2 3 4 5  # received: 6
1 2 3 4 5 6  # received: 7
1 2 3 4 5 6 7  # received: 8
1 2 3 4 5 6 7 8  # received: 9
1 2 3 4 5 6 7 8 9  # received: 10
1 2 3 4 5 6 7 8 9 10  # received: 11
1 2 3 4 5 6 7 8 9 10 11  # received: 12
1 2 3 4 5 6 7 8 9 10 11 12  # received: 13
1 2 3 4 5 6 7 8 9 10 11 12 13  # received: 14
1 2 3 4 5 6 7 8 9 10 11 12 13 14  # received: 15
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15  # received: 16
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16  # received: 17
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17  # received: 18
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18  # received: 19
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19  # received: 20
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20  # received: 21
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21  # received: 22
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22  # received: 23
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23  # received: 24
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24  # received: 25
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25  # received: 26
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54  # received: 52
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54  # received: 54
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54  # received: 55
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55  # received: 56
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56  # received: 57
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57  # received: 58

Discussion

It can be seen that, after 27 seconds being idle, the ESP doesn't respond to any serial data until 54 seconds after the last successful reading (test no. 26).

The testing process can be fast-forwarded by changing k_firstTestNo to a previous known good value. Some values that precede fails (at least for me) are 26 (fail starts at 27 and goes up to 51, then 53 fails again), 80 (fails at 81 up to 105, then 107 again), 134 (fails 135-158, 160 and 161), 187 (fails 188-212 and 214), 241 (fails 242-266 and 268), 295 (fails 296-319, 321 and 322). I left it running overnight, and the fail log is abbreviated below:

EspSoftwareSerial test begin
test no. 1:      confirmed      next test in 2000ms
test no. 2:      confirmed      next test in 3000ms
...
test no. 25:     confirmed      next test in 26000ms
test no. 26:     confirmed      next test in 27000ms
test no. 27:     timeout        next test in 1000ms
test no. 28:     timeout        next test in 1000ms
...
test no. 50:     timeout        next test in 1000ms
test no. 51:     timeout        next test in 1000ms
test no. 52:     confirmed      next test in 53000ms
test no. 53:     timeout        next test in 1000ms
test no. 54:     confirmed      next test in 55000ms
test no. 55:     confirmed      next test in 56000ms
...
test no. 79:     confirmed      next test in 80000ms
test no. 80:     confirmed      next test in 81000ms
test no. 81:     timeout        next test in 1000ms
test no. 82:     timeout        next test in 1000ms
..
test no. 104:    timeout        next test in 1000ms
test no. 105:    timeout        next test in 1000ms
test no. 106:    confirmed      next test in 107000ms
test no. 107:    timeout        next test in 1000ms
test no. 108:    confirmed      next test in 109000ms
test no. 109:    confirmed      next test in 110000ms
...
test no. 133:    confirmed      next test in 134000ms
test no. 134:    confirmed      next test in 135000ms
test no. 135:    timeout        next test in 1000ms
test no. 136:    timeout        next test in 1000ms
...
test no. 157:    timeout        next test in 1000ms
test no. 158:    timeout        next test in 1000ms
test no. 159:    confirmed      next test in 160000ms
test no. 160:    timeout        next test in 1000ms
test no. 161:    timeout        next test in 1000ms
test no. 162:    confirmed      next test in 163000ms
test no. 163:    confirmed      next test in 164000ms
...
test no. 186:    confirmed      next test in 187000ms
test no. 187:    confirmed      next test in 188000ms
test no. 188:    timeout        next test in 1000ms
test no. 189:    timeout        next test in 1000ms
...
test no. 211:    timeout        next test in 1000ms
test no. 212:    timeout        next test in 1000ms
test no. 213:    confirmed      next test in 214000ms
test no. 214:    timeout        next test in 1000ms
test no. 215:    confirmed      next test in 216000ms
test no. 216:    confirmed      next test in 217000ms
...
test no. 240:    confirmed      next test in 241000ms
test no. 241:    confirmed      next test in 242000ms
test no. 242:    timeout        next test in 1000ms
test no. 243:    timeout        next test in 1000ms
...
test no. 265:    timeout        next test in 1000ms
test no. 266:    timeout        next test in 1000ms
test no. 267:    confirmed      next test in 268000ms
test no. 268:    timeout        next test in 1000ms
test no. 269:    confirmed      next test in 270000ms
test no. 270:    confirmed      next test in 271000ms
...
test no. 294:    confirmed      next test in 295000ms
test no. 295:    confirmed      next test in 296000ms
test no. 296:    timeout        next test in 1000ms
test no. 297:    timeout        next test in 1000ms
...
test no. 318:    timeout        next test in 1000ms
test no. 319:    timeout        next test in 1000ms
test no. 320:    confirmed      next test in 321000ms
test no. 321:    timeout        next test in 1000ms
test no. 322:    timeout        next test in 1000ms
test no. 323:    confirmed      next test in 324000ms
test no. 324:    confirmed      next test in 325000ms

I replaced the ESP8266, and also tried pins D6 (the main one for this issue), D5, D3 and D4, but the problem still happens. Can someone try to reproduce this issue? I am also open to suggestions to improve this testing procedure.

[dok-net]

Thank your for this extensive and enlightening issue report. I've superficially verified that there is in indeed a problem in all recent EspSoftwareSerial versions when there has been silence on the RX for just short of 27s, equaling 2^31 cycles at 80MHz ;-) ;-)
I will provide a fix ASAP - naturally for the latest version of EspSoftwareSerial, which unfortunately is pending a minor fix in the ESP8266 Arduino core. I am in active contact with the developers there. So either you'll have to wait for that, or if you are familiar with cobbling together different HEAD versions, you could kindly provide me early feedback for the fix.

[gutierrezps]

Thank you for the quick reply! Yes, I think I can apply your fix on the ESP8266 core and test SoftwareSerial on top of it. Tell me when you provide the SoftwareSerial fix and I'll test it as soon as I can.

[dok-net]

OK, I would like to ask you to clone this repo , including all submodules, into your workbook directory .../Arduino/hardware/esp8266com/esp8266 (moving aside the official ESP8266 Arduino tree). Please checkout the master branch - this contains all my pending PRs, so please don't use it for anything but this test, but it simply picks up my latest EspSoftwareSerial in [repo]/libraries/SoftwareSerial, too.

[gutierrezps]

The fix worked, thanks.

Now, since this is a potentially troublesome issue, do we really have to wait for your pull requests to be merged on ESP8266 core? Is it not possible to cherry pick the fix and release it as a new patch version?

[dok-net]

Not really, this would bind the same resources that are needed for the full update including the prerequisite PRs, as any release for the ESP8266 now happens via the submodule - at least for GitHub users. I've also done some more fixes for issues that I've found since then, that for the first time allow full-duplex at 38400bps software serial to software serial, in my tests.
And finally, I am not about to open that can of worms, I have just about only enough time for keeping one straight version graph alive. Please use the version from my development repo in the interim.

[gutierrezps]

I see. For now, I have already made a workaround when I noticed this issue, and I'm not needing this fix at the moment.

Anyway, I (and maybe others as well) would be grateful if you could add a comment here when the fix gets released.

[dok-net]

@gutierrezps The SDS011 air quality sensor behaves quite differently from the UARTs in both ESP8266 and ESP32, so I had to do a few tweaks to get that working again - I am sorry, could you please retest with the very latest head from my repo? Thanks!

[dok-net]

@arduino12 @gutierrezps @fredvik EspSoftwareSerial release 5.2.1 is out now for ESP8266 as integral library, once it's merged by the ESP8266 Arduino team, and immediately for both ESP8266 and ESP32 via all the manual methods that exist from https://github.com/plerup/espsoftwareserial/releases/tag/5.2.1 ;-)
Please mind the breaking change in initalization, the constructor now takes zero arguments, they have been moved to the begin() function.