Prevent mesh firmware checks from interrupting node updates - #601
Conversation
Fix a new bug identified and introduced by commit: bae3640 And PR: #539 This bug appears to be a concurrent firmware management collision, essentially a race while flashing a node while checking it for updates from the primary at the same time. I accidently ran into this, the seems to be that the node had prepared for the update, authenticated to its own WebUI, and was just about to hand the beta1 image to /upgrade.cgi When at that exact time, I started an upgrade from the primary, which logged into the node to check for updates, triggered start_webs_update, and resulted in putting the node’s ASUS firmware update system into a competing update/check state and ultimately MerlinAU rebooted the node without flashing any firmware. This may also be related to a report from JimbobJay here: https://www.snbforums.com/threads/merlinau-v1-6-8-the-ultimate-firmware-auto-updater.96306/post-999444
|
Have a look at this...
Exactly 4 seconds after the node entered that flashing stage, the primary logged into it, and invoked the firmware-check process as found below: When I checked the primary router MerlinAU logs for timestamps it confirms it:
After MerlinAU finished ejecting the USB device, and the flash attempt never moved on to the next step which is the normal ASUS upgrades path. (No calls to stop_upgrade or start_upgrade) |
Stop logging out early, allow _GetNodeInfo_ to logout
|
Actually... I'm testing another possibility/theory:
Hold tight... |
Tightening up the Flash Order Adjusting the flash order so we delete cron jobs before unloading Entware. (Incase a cron tries to fire for an entware script that is unloaded) This may also be related to a report from JimbobJay here: https://www.snbforums.com/threads/merlinau-v1-6-8-the-ultimate-firmware-auto-updater.96306/post-999444 Also adjusted the WebUI restart to be RIGHT before we login to the router to start the flash. The vulnerable window was the gap between the WebUI restart, unloading the USB, and flashing. Also adjusted the order so we say flashing right before we actually restart the WebUI and flash
|
Confirmed on my side, this is likely what happened. The primary is able to null the cookie of the node. That USB window can be anywhere from 10 seconds to 45 seconds+ based on the new USB unmount code. Unloading cron jobs just as long. Once that happens, the cookie is now null, and the flash fails. Also adjusting the flash order so we delete cron jobs before unloading Entware. This may also be related to a report from JimbobJay here: |
|
Unfortunately, because we previously never kept /tmp/upload_response.txt even though we generated it. It has to be one or the other...
This PR now attempts to address both. I tested it, and in case it does ever happen, we now should see this in the logs: |
|
That's a very interesting scenario, and a great catch, bud!! So, essentially, when the primary router logs into a node to check for F/W updates (which also triggers execution of the node's webs_update.sh script), it seems to "kick the node out" of its own login session by invalidating a previously obtained login cookie when/if the node happens to be in the middle of running a F/W update and is about to flash the image. This scenario creates a conflict between the primary router actions and the node's attempt to flash the F/W image because the primary router is completely unaware that the node is, in fact, in the middle of a F/W update. Unfortunately, I don't have a mesh setup in my home network, so I cannot help you test, debug, or validate any of the changes. But I'll take a look, review the code, do some sanity checks, and run the Linter tool after merging the PR. Give me until Friday evening to get to it (I'll be busy in the next couple of days). BTW, a friend of mine reported an issue where he's not able to do a simple 'Copy&Paste' operation when entering the password string on the CLI menu. I found the problem, so I'll fix it soon. Talk to you later, bud. |
Yeah, that makes sense. Good call!
In that case, the cron job would simply fail silently; but it's better to avoid such a scenario by changing the order. Good call.
In this case, the reported issue was that it failed to remove some cron job. This is independent of whether the cron job itself fails to execute. These are completely separate events. |
Not going to lie, to me, this is the most interesting thing that's come up for merlinAU in a while 😂 I had to investigate!!! Happened 2 days ago on the 15th early morning and then I spent whatever time I could until 2AM on the 16th trying to make sense of what happened to me.
Bingo, you got it. That seems like the most likely scenario to me anyways and I was able to independently reproduce that scenario. Unlike my initial firmware management collision theory. I initially thought it was a concurrent firmware management bug deeper in the firmware. (Because let's be honest, when a user normally starts a flash, it starts a spinning wheel and locks up the WebUI, people can't usually login a second time and trigger an update check which is essentially with the primary router did in this case) But the most likely scenario is the window between the WebUI restart and the actual flash is simply too large and allows for other things to login.
Ive tried to build in some "communication" between the two. It's rudimentary. We don't really have any real comms between them like SSH. But now the node sets a specific nvram value when it starts the critical flash process. The primary can then pull that nvram value using the same method it pulls all the other nodes values, if it finds that nvram value is set to 1, it says "node must be flashing, skip whatever I can for the node update check and trigger process"
No rush, this is extremely rare and uncommon. An "edge case" if I ever saw one 😉 My guess/assumption is between skipping as much as we can from the primary in an activate node flash, plus restarting the WebUI right up against the start of the flash, is the best way forwards to protect this window.
I see the PR! I'll replicate if I can and merge. |
Ah yes, funny enough I went back through past PRs and we had this discussion once before. I thought it rang a bell hearing you say that. Well this time that fact silently went over my head and I just changed the order so we limit that possibly anyways 😜
Fair enough! |
Martinski4GitHub
left a comment
There was a problem hiding this comment.
Looking good and approved!!
|
Sorry for the delayed response. Friday evening, my wife and I went out to dinner with a few friends and came back home a little bit past midnight. Anyway, I reviewed the code, and everything looks good. I'm going to merge it, but I'm already too tired to run it through the Linter tool. I'll do that tomorrow, Saturday evening. Enjoy the weekend and take care, bud!! |
| # so that the F/W Update can start without interruptions. | ||
| #------------------------------------------------------------# | ||
| "$isInteractive" && printf "\nRestarting web server... Please wait.\n" | ||
| /sbin/service restart_httpd >/dev/null 2>&1 & |
There was a problem hiding this comment.
This call to restart the HTTP daemon was invalidating the previously authenticated login session token/cookie, which would cause the call to flash the F/W to fail.
Fix a new bug identified and introduced by commit: bae3640
And PR: #539
This may also be related to a report from JimbobJay here:
https://www.snbforums.com/threads/merlinau-v1-6-8-the-ultimate-firmware-auto-updater.96306/post-999444
This bug appears to be a concurrent firmware management collision, essentially a race while flashing a node while checking it for updates from the primary at the same time.
I accidently ran into this, the issue seems to be that the node had prepared for the update, authenticated to its own WebUI, and was just about to hand the beta1 image to /upgrade.cgi
When at that exact time, I started an upgrade from the primary, which logged into the node to check for updates, triggered start_webs_update, and resulted in putting the node’s ASUS firmware update system into a competing update/check state and ultimately MerlinAU rebooted the node without flashing any firmware.