Device-os: Photon stuck indefinitely in breathing green LED mode following wifi reconnection

[karlhenricksen]

Description:

I left my device running online running a simple script to repeatedly send commands over the weekend and saw what looked to be wifi flakiness the first night - 16 wifi disconnects with 15 successful reconnects. On the 16th disconnect however, the Photon failed to get back online - instead, it had become stuck in the mode of breathing green LED. When I returned 3 days later, it was still in this mode and I was forced to reset in order to recover. We have seen this in the past with Manual mode, but now using Semi-Automatic mode and multi-threading, we thought it would be non-existent.

NOTE this is not 100% reproducible - it's only happened when running scripts to continually send simple updates and/or when our wifi is slow or possibly flaky/intermittent - I havent' been able to reproduce by pulling/restoring internet repeatedly as I'd hoped either with or without the messaging.

Steps to Reproduce:

1. Ensure Photon is connected to wifi and cloud with correct router credentials (breathing cyan)
2. Run some script to repeatedly make simple changes
3. Leave running overnight with periods of slow/flaky internet
   

   Video:

Video below shows the described behavior, of the breathing green LED.

https://www.youtube.com/watch?v=Csc-nLxfNyA

Photon Info:

System version 0.4.7
Multi-thread enabled
Semi-Auto mode

[m-mcgowan]

Thanks for this report. We'll investigate what might be causing the device to not automatically reconnect to the cloud once the Wi-Fi connection has been re-established.

[karlhenricksen]

Thanks @m-mcgowan - FYI we tried to work around this by initiating a wifi reset (see below) every 30s that we're not connected to the cloud. We check whether we’re connected to the cloud by checking the handshake result from Particle.syncTime().

Unfortunately the workaround does not help this problem and I reproduced the issue by leaving online last night, again with a script that is making simple calls on and off throughout the night. We could see many resets being made but the breathing green state persisted.

void ResetWiFiConnection()
{
  Serial.println("Beginning WiFi reset #" + String(++numWiFiResets) );
  WiFi.off();
  delay(10);
  WiFi.on();
  WiFi.connect();
  Particle.connect();
}

[m-mcgowan]

Thanks for this extra info - very useful. I was going to suggest that Particle.connect()should re-initialize the cloud connection.

Are you sure there aren't delays in your code that block the main loop()? To be sure you could add a loop to call Particle.process() several times from within your ResetWiFiConnection.

e.g.

for (int i=0; i<10; i++) {
   Particle.process();
}

The LED will breathe green if the device hasn't ran the background loop for 10 seconds, since the server side will disconnect the device without a regular heartbeat.

I hope that helps!

[karlhenricksen]

We call Particle.process() every 10ms within the main loop (as measured by millis()) and we are running in SYSTEM_THREAD(ENABLED)

[m-mcgowan]

Understood. fyi, with threading enabled you don't need to call Particle.process() it's a no-op. So doesn't do any harm, but doesn't do anything good either! (Update: in 0.4.7 this was changed to pump application events, and in 0.4.9 delay() will do the same.)

If I'm able to reproduce this then of course I'll dive in deeper, but I hope you don't mind doing some experimenting for me in the meantime!

Could you add a System.memory() print to your Wi-Fi reset function to check on memory health.

I'm wondering if somehow the system thread is being permanently blocked by a function that stalls? I've seen other reports recently of WICED sockets blocking indefinitely after returning a timeout error. You won't notice this since all the functions being called WiFi.off()/WiFi.on()/Particle.connect() are asynchronous - they don't wait for the system thread.

One function that is synchronous is WiFi.hasCredentials() - you could try calling that and printing the value. If the value never appears then we know the system thread has become blocked.

[karlhenricksen]

Great thanks, we're trying that out now, will report back if I find anything interesting.

[karlhenricksen]

@m-mcgowan it looks like you are right - we see the system thread being permanently blocked and following the Wifi.hasCredentials() the user thread is stuck waiting for a return.

Right before that stall, we printed System.freeMemory() and it returned 29788.

Right before the system crash, the function we were calling was Time.zone(), in case that is relevant.

[karlhenricksen]

FYI, the function repeatedly called OTA is basically

int SetTZ(String offset)
{
  Time.zone( offset.toInt() );
  return 1; 
}

We have reproduced this same issue every night by interleaving calls to SetTZ as a Particle.function() every few seconds with gets of our swVersion. We leave this on for a couple hours and have had 100% success.

[karlhenricksen]

@m-mcgowan I believe I'm seeing this same issue, but it's now looking like the repeated messages are the trigger rather than wifi reconnect. I've reproduced this twice when running a simple test to set and get different user settings repeatedly. Wifi reconnects did not appear to be an issue since there were only a couple through the night.

• 1st night, I left out any wait time between setting and getting, and came back to a fully crashed user program while system was in breathing green
• 2nd night, I put in a more reasonable wait time, and returned the next day to see user pgm working fine, but system was not fully functioning and breathing green. I was unable to set the Photon into listening mode either via serial or via holding the setup button. When I attempted to enter listening via setup button, LED turned to solid green and was unresponsive.

Right before that stall, we printed System.freeMemory() and it returned 54176. 2min after going to breathing green, we see our process getting totally starved by the system thread - our loop time (measure of how long it takes us to return to the same point in our user process loop) grew exponentially. 1 hour later, the loop time dropped back to the normal time.

Is there anything else you'd need to help reproduce this issue? Does this seem reasonable that what I described would be caused by repeated OTA calls?

System v 0.4.9
Multi-thread enabled
Semi-Auto mode

[karlhenricksen]

@m-mcgowan I've also now seen user and system crash (doing similar many-call and many-get loops) where the Photon goes to fast-blinking cyan. Could this at all be related to or a duplicate of #852 ? Similar to #804, I am unable to enter listening and either gets stuck on cyan or off (depending on where it is in the blink cycle). We're going to try to get a simpler user pgm to send to you that can still reproduce this, but it would be good to know if you have any instinct of what's happening here.

[harmeetsingh-work]

Hi, facing the same issue, works fine with my router but with my partner's router which takes time to connect to internet if restarted photon gets stuck in fast green blinking and blocks user code, if I try to call WiFi.off or WiFi.disconnect using SparkIntervalTimer it has no effect.

Please fix this as our production is blocked due to this. :)

[m-mcgowan]

If you can help me reproduce the issue with a test program, I'll glady look into this as a high priority issue.

[harmeetsingh-work]

Ok I create one.

[lzrd]

Are you suffering from bufferbloat? (http://www.bufferbloat.net/)
My home network went from unusable with ASUS router stock firmware to one
with no problems when I switched it to https://advancedtomato.com/ (a fork
of Tomato by Shibby) and enabled appropriate bandwidth management.

See http://www.chizang.net/alex/2012/07/24/bufferbloat-for-the-impatient/

On Mon, Jan 11, 2016 at 12:42 PM, karlhenricksen [email protected]
wrote:

Description:

I left my device running online over the weekend and saw that there was
some wifi flakiness the first night - 16 wifi disconnects with 15
successful reconnects. On the 16th disconnect however, the Photon failed to
get back online, even though internet was restored - instead, it had become
stuck in the mode of breathing green LED. When I returned 3 days later, it
was still in this mode and I was forced to reset in order to recover. We
have seen this in the past with Manual mode, but now using Semi-Automatic
mode and multi-threading, we thought it would be non-existent.

NOTE this is not 100% reproducible - it's only happened naturally, when
our wifi is slow or possibly flaky/intermittent - I havent' been able to
reproduce by pulling/restoring internet repeatedly as I'd hoped.
Steps to Reproduce:

1. Ensure Photon is connected to wifi and cloud with correct router
   credentials (breathing cyan)
2. Leave running overnight with periods of slow/flaky internet

Video:

Video below shows the described behavior, of the breathing green LED.

https://www.youtube.com/watch?v=Csc-nLxfNyA
Photon Info:

System version 0.4.7
Multi-thread enabled
Semi-Auto mode

—
Reply to this email directly or view it on GitHub
https://github.com/spark/firmware/issues/804.

[karlhenricksen]

Alright @m-mcgowan, we've spent some good time reproducing this, narrowing down and retesting and believe we have simplest version of this issue.

Notes:

• Just to reiterate, this issue has been observed during normal operation, the procedure below is just to accelerate the failure and make it easily reproducible.
• It seems the crash is likely related to the short period when a Photon is re-connecting to the cloud.
• We could not re-create this crash using SYSTEM_MODE(MANUAL) UPDATE: this is reproducible in Manual mode
• The issue name is a bit of a misnomer, as when this system crash occurs, it stalls all processes except the RGB LED, which just remains in whatever state it was previously in. We have seen breathing green, blinking cyan, or solid cyan. In any case, the system and user code are no longer running, and the photon must be manually reset.

Requirements for Test:

• Some way to power cycle your router.

We have this hydroponics timer which works great, highly recommend picking a few of these up for internal regression testing of flaky routers/internet:

Titan Repeat Cycle Timer
You can buy one HERE

• Simple user program: (included at the end)

Steps to Reproduce:

1. Connect your test router power to the Repeat Cycle Timer and set on-time to max for setup
2. Ensure Photon is successfully connected to test router (breathing cyan)
3. Setup Repeat Cycle Timer so that it stays on long enough for router to power on and Photon to consistently connect: for our router, this was 1.5 min ON. OFF time was set to minimum (5s)
4. Let the router repeatedly power-cycle until the Photon LED stops disconnecting/connecting --> _for us this usually occurs within 20-30 minutes. Up to a day may be necessary though._

Our Setup:

Router - Netgear WNDR3800
Photon v0.4.9
AC timer: Titan Controls Spartan Series Repeat Cycle Timer

User Program to Reproduce:

#include "application.h"

SYSTEM_MODE(SEMI_AUTOMATIC);
SYSTEM_THREAD(ENABLED);

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

  WiFi.on();
  WiFi.connect();
  Particle.connect();
  
  Serial.println("Very simple example program with publishes");
}

static bool myState = false;
static unsigned long lastTimeWeAnnouncedLoopTime = 0;
static unsigned long lastLoopTime = 0;
static unsigned long millisOfLastPublish = 0;

void loop()
{
  Particle.process();

  myState = random(2); //modify our state

  //anounce loop time every so often, just to print something...
  //Value is irrelevant 
  if( (millis() - lastTimeWeAnnouncedLoopTime) > random( 10, 500 ) )
  {
    lastTimeWeAnnouncedLoopTime = millis(); 
    Serial.println("loop time: " + String( millis() - lastLoopTime ) );
  }

  lastLoopTime = millis(); //record last time we were here

  //if we're connected, publish every so often
  if( Particle.connected() )
  {
    if( ( millis() - millisOfLastPublish ) > random(500, 1500) )
    {
      millisOfLastPublish = millis();
      Serial.println("Publishing junk....");
      //involve some states in our junk publish...
      Particle.publish("junk", String(myState) + " fjksdas " + String(millisOfLastPublish) + String(myState) );
    }
  }
}

[harmeetsingh-work]

Hi, After testing few days, we fixed the issue

ISSUE: When reset router, photon gets in infinite fast green blinking.

We tracked that this was due to when router turned off, our MQTT client tries reconnection and locks tcp client and it remains there for ever.

if (mqttHandler.isConnected()) {
        mqttHandler.loop();
} else{
  if(Particle.connected()){
    if((millis() - timeMqttRetry) >= 10000){
        timeMqttRetry = millis();
        mqttConnect();
    }
    }
  }

Actually when router disconnects, out mqtt client comes to know immediately and retries as the above condition Particle.connected() returns true, might Particle.connected() takes a little to refresh its status and thus the photon gets stuck to infinite fast green blinking.

SOLUTION:
Mode is AUTOMATIC SYSTEM_THREAD(ENABLED);
DO NOT RETRY TCP OR UDP retry just after disconnect.

if (mqttHandler.isConnected()) {
        timeMqttRetry = millis();
        mqttHandler.loop();
    } else{
        if(WiFi.ready() && Particle.connected()){
        if((millis() - timeMqttRetry) >= 10000){
            timeMqttRetry = millis();
            mqttConnect();
            }
        }
    }

[m-mcgowan]

Many thanks for taking the time to troubleshoot this @karlhenricksen, @blackadmin. It will take me a little while to get the necessary pieces to setup the same test fixture.

I made a PR here - https://github.com/spark/firmware/pull/898 - that attempts to disconnect the device when connection to wifi takes too long. Would you mind trying that with your current setup to see if it helps with the stall?

[karlhenricksen]

@m-mcgowan today we're checking that PR against the simple pgm we sent, so will get back to you with any results. But yes, would definitely recommend and appreciate if you add that router reset-timer to your tests, should hopefully help catch any similar issues going forward on your end

[karlhenricksen]

@m-mcgowan this does look to be something Semi-Auto related (we were unable to reproduce when in MANUAL mode with the same steps.)

Results from last night:
We were able to reproduce last night however with the same user pgm against the latest Develop version + the PR you made. This looks very easy to reproduce - just a simple timer to force multiple wifi reconnects should do it quickly (within 30min to a few hours of just sitting and reconnecting).

[pomplesiegel]

Just reproduced this (Breathing Green + stopped user application and our threads) using the tip of develop (as of yesterday) + SYSTEM_MODE(MANUAL). It appears to take longer to reproduce using MANUAL, rather than SEMI_AUTOMATIC. Reproduced using the exact same test conditions (router repeatedly power-cycled using the mechanical outlet timer).

[pomplesiegel]

@monkbroc, any update on this for 0.5.0? Consistently able to reproduce this, even with the tip of develop, with that simple app or our actual application under normal wavering WiFi conditions.

[monkbroc]

I haven't had the chance to dive in to the root cause yet. It's my next thing to do.

[pomplesiegel]

Great, thanks for the update.

Sent from my iPhone

On Apr 1, 2016, at 11:35 AM, Julien Vanier [email protected] wrote:

I haven't had the chance to dive in to the root cause yet. It's my next thing to do.

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

[monkbroc]

I've been running the test program above for 3 hours on a Photon with the tip of develop, cycling the AP off for 5 seconds and on for 30 seconds. So far the Photon always manages to reconnect. I'll let it run longer.

Do you have particularities in the WiFi setup I should try? What WiFi security are you using? How strong is the signal?

[karlhenricksen]

@monkbroc Wifi is very strong (2 ft from Photon), Wifi Security is WPA2. It's possible the 30sec on period is not enough - to mimic our setup here, you could try 90s on, 5 sec off. And sometimes it just takes time to see the issue.

We have also just set up a test with the tip of dev to make sure we're still able to reproduce consistently and we're on the same page as you, so we'll update with anything we see here. Thanks

[monkbroc]

I see your published messages mixed in with mine. I'll increase the off time to 90s and run this overnight.

[monkbroc]

I haven't been able to reproduce this problem. The Photon ran your test program for 12 hours with a 90s on / 5s off cycle for the Wi-Fi access point with WPA2. It kept reconnecting and publishing to the cloud.

Is there any information you can provide to narrow in on this issue? Can you dump the entire firmware of your Photon so I can try again with the same binary. @pomplesiegel can send me the file through Slack.

dfu-util -d 2b04:d006 -a 0 -s 0x8000000:0x100000 -U photon_dump.bin
xxd -o 0x8000000 photon_dump.bin > photon_dump.hex

[pomplesiegel]

Hello @monkbroc, thanks for doing this test.

Our photon crashed overnight using the same code. FYI, this shows itself as

1. The photon no longer re-connecting or disconnecting.
2. The photon no longer executing the user thread, which means no messages are published.

However, the RGB LED still displays the most recent pattern. Ours is stuck in blinking green.

I don't currently see your messages on the firehouse, assuming you're using the same name. Ours has stopped publishing as well.

particle subscribe | grep "junk"

FYI, our actual product's application crashed in the exact same way overnight, using SYSTEM_MODE(MANUAL). It's alternating between flashing green and FAST flashing green, but our user thread and swTimers have permanently stopped executing.

I'll get you that binary now. Thanks!

[pomplesiegel]

Successfully reproduced, even when sitting alone within a breadboard. Sent the exact test setup off to @monkbroc, so looking forward to this one getting unraveled! We've seen this occur within our product recently off of a few different routers, even without any power cycling.

[karlhenricksen]

@monkbroc FYI I reran the same test with another timer (90s on, 5s off), Photon with the same binary @pomplesiegel shared in a breadboard - failure (solid cyan) occurred less than an hour later. Router used was the classic clunker Linksys WRT54GL, WPA2. So unless there's some other factor we haven't accounted for, you should be able to reproduce with the setup sent to you pretty easily.

[pomplesiegel]

Just reproduced this using the same procedure and code in a totally different test environment, using a different router. This time crashed on static cyan. Compiled against and running with 0.5.0-rc1.

[m-mcgowan]

The crash on static cyan is now understood - the details in #877. This is almost certainly a different issue from the device continually breathing green, as indicated in the title of the thread.

[monkbroc]

@pomplesiegel @karlhenricksen Since the breathing green issue #904 was fixed have you seen this particular issue crop back up? The symptoms look very similar. I'll keep running the Photon with the router connected to the on/off mechanical timer. So far the breathing green issue is not showing up anymore.

[pomplesiegel]

HI @monkbroc, this issue title is a bit of a misnomer: in the end this issue ended up covering mainly the static cyan issue, which we have not seen again. Since we also fixed #904, i feel comfortable that this issue is done. The mechanical timer is always a super useful way to test for weirdness. 👍 Thanks for your help!

[pomplesiegel]

@karlhenricksen, can you close this?

[karlhenricksen]

Yes, this is safe to close, we've done hundreds of router resets using a timer since the fix with no return of the breathing green following those hundreds of resets.

[monkbroc]

Thanks for your help tracking down these issues folks!