🐞 [Bug]: Farmerbot tries to shutdown nodes that are already asleep, doesn't shutdown awake node

[scottyeager]

What happened?

Farmer noticed that during a random wakeup, the Farmerbot hadn't put the node back to sleep after about 1 hour and 20 minutes. Upon inspecting the logs, I noticed that Farmerbot is attempting to put nodes to sleep which are already off, but not putting the node to sleep that actually woke up.

The node in question here is 1983. Note that the farmer changed the power target to Down manually eventually, toward the end of this log file.

farmerbot-3703.log

which network/s did you face the problem on?

Main

Node ID/s

1983

Farm ID/s

3073

Relevant log output

Here's a snippet of the log file showing an example. Farmerbot is attempting to shutdown node 3400, which is already off, rather than powering down node 1983.

┌──────┬───────┬────────┬───────────┬───────────────┬───────┬─────────────────┬──────────────────┬─────────────────────────┬─────────────────────┬───────────────────────────┐
│   ID │ STATE │ RENTED │ DEDICATED │ PUBLIC CONFIG │ USAGE │ RANDOM WAKE-UPS │ PERIODIC WAKE-UP │ LAST TIME STATE CHANGED │     LAST TIME AWAKE │ CLAIMED RESOURCES TIMEOUT │
├──────┼───────┼────────┼───────────┼───────────────┼───────┼─────────────────┼──────────────────┼─────────────────────────┼─────────────────────┼───────────────────────────┤
│ 3402 │ OFF   │ false  │ false     │ false         │ 0%    │               0 │ "09:02AM"        │       12h36m40.5766559s │ 13h16m16.369202278s │                        0s │
├──────┼───────┼────────┼───────────┼───────────────┼───────┼─────────────────┼──────────────────┼─────────────────────────┼─────────────────────┼───────────────────────────┤
│ 3410 │ OFF   │ false  │ false     │ false         │ 0%    │               0 │ "09:09AM"        │     12h31m35.047112151s │  13h9m10.364912262s │                        0s │
├──────┼───────┼────────┼───────────┼───────────────┼───────┼─────────────────┼──────────────────┼─────────────────────────┼─────────────────────┼───────────────────────────┤
│ 1983 │ ON    │ false  │ false     │ false         │ 0%    │               1 │ "09:16AM"        │      1h20m32.692315141s │  1h20m32.692315291s │                        0s │
├──────┼───────┼────────┼───────────┼───────────────┼───────┼─────────────────┼──────────────────┼─────────────────────────┼─────────────────────┼───────────────────────────┤
│  642 │ ON    │ false  │ false     │ false         │ 0%    │               0 │ -                │                      0s │                  0s │                        0s │
├──────┼───────┼────────┼───────────┼───────────────┼───────┼─────────────────┼──────────────────┼─────────────────────────┼─────────────────────┼───────────────────────────┤
│ 3423 │ OFF   │ false  │ false     │ false         │ 0%    │               0 │ "08:33AM"        │      13h1m59.652884122s │ 13h37m34.817366132s │                        0s │
├──────┼───────┼────────┼───────────┼───────────────┼───────┼─────────────────┼──────────────────┼─────────────────────────┼─────────────────────┼───────────────────────────┤
│ 3400 │ OFF   │ false  │ false     │ false         │ 0%    │               1 │ "08:40AM"        │      13h1m59.556269723s │ 13h37m34.504749446s │                        0s │
├──────┼───────┼────────┼───────────┼───────────────┼───────┼─────────────────┼──────────────────┼─────────────────────────┼─────────────────────┼───────────────────────────┤
│ 3406 │ OFF   │ false  │ false     │ false         │ 0%    │               0 │ "08:48AM"        │     12h51m53.206844651s │  13h30m28.44214988s │                        0s │
├──────┼───────┼────────┼───────────┼───────────────┼───────┼─────────────────┼──────────────────┼─────────────────────────┼─────────────────────┼───────────────────────────┤
│ 3403 │ OFF   │ false  │ false     │ false         │ 0%    │               0 │ "08:55AM"        │     12h46m47.184476729s │ 13h23m22.534957809s │                        0s │
└──────┴───────┴────────┴───────────┴───────────────┴───────┴─────────────────┴──────────────────┴─────────────────────────┴─────────────────────┴───────────────────────────┘
10:36PM DBG connecting url=wss://tfchain.grid.tf/ws
2024/02/02 22:36:12 Connecting to wss://tfchain.grid.tf/ws...
10:36PM DBG Fetch nodes
10:36PM DBG Add/update node nodeID=642
10:36PM ERR error="failed to update node 642 with error: failed to get node 642 statistics from rmb with error: e2e error: invalid cipher data"
10:36PM DBG Add/update node nodeID=3423
10:36PM WRN Node is off, will skip rmb calls nodeID=3423
10:36PM DBG Node is updated with latest changes successfully nodeID=3423
10:36PM DBG Add/update node nodeID=3400
10:36PM WRN Node is off, will skip rmb calls nodeID=3400
10:36PM DBG Node is updated with latest changes successfully nodeID=3400
10:36PM DBG Add/update node nodeID=3406
10:36PM WRN Node is off, will skip rmb calls nodeID=3406
10:36PM DBG Node is updated with latest changes successfully nodeID=3406
10:36PM DBG Add/update node nodeID=3403
10:36PM WRN Node is off, will skip rmb calls nodeID=3403
10:36PM DBG Node is updated with latest changes successfully nodeID=3403
10:36PM DBG Add/update node nodeID=3402
10:36PM WRN Node is off, will skip rmb calls nodeID=3402
10:36PM DBG Node is updated with latest changes successfully nodeID=3402
10:36PM DBG Add/update node nodeID=3410
10:36PM WRN Node is off, will skip rmb calls nodeID=3410
10:36PM DBG Node is updated with latest changes successfully nodeID=3410
10:36PM DBG Add/update node nodeID=1983
10:36PM ERR error="failed to update node 1983 with error: failed to get node 1983 statistics from rmb with error: e2e error: invalid cipher data"
10:36PM INF Too low resource usage resources usage=0
10:36PM INF Resource usage too low. Turning off unused node nodeID=3400 resources usage=0
10:36PM INF POWER OFF nodeID=3400

[scottyeager]

Update from the farmer on this one. I asked to wait longer to see if node 1983 goes to sleep. Farmer reports that it does eventually, but it takes much longer than the other nodes:

Okay node 1983 just needs 150 min every time until it falls asleep, maybe the devs can public some Informations why it is like that. With the old fb it was just 45 min like all the other nodes
The HP needs twice the time to boot, but also that's just 15 min more...

Is this expected behavior under the current implementation?

[rawdaGastan]

I fixed it. You need to use the latest version

[scottyeager]

Thanks @rawdaGastan. I'll ask farmer to try the latest version.