🐞 [Bug]: Farmerbot fails to wake up my node, stays on "Waking up" state

[archit3kt]

What happened?

Hi,

I added node 338 on my testnet farm 23 and I'm trying to set up farmerbot on it

I must precise some context first

• farmerbot is hosted on a debian trixie VM A on subnet A
• node to wakeup is on subnet B
• wakeonlan "mac address of node NIC" sent from VM A is working correctly and wake up the node

The trick to make it work across subnets is to create a socat connection on the router (openwrt 2024.10.2)

socat -u UDP-RECVFROM:9,interface=(int for subnet A),fork UDP-DATAGRAM:(broadcast IP of subnet B):7,broadcast

Despite a working wakeonlan command, farmerbot doesn't seem to wake up my node. It's stuck in "waking up" state

Could you please tell me what command is sent by farmerbot to wake up the node ? It would help to explain why it is not working correctly.

I pinpointed the last waking up attempt to 20250921 5 PM CEST, log output provided here

If you need more info please don't hesitate

which network/s did you face the problem on?

Test

Twin ID/s

No response

Version

No response

Node ID/s

338

Farm ID/s

No response

Contract ID/s

No response

Relevant log output

ep 21 16:51:10 grafana farmerbot[158]: 4:51PM DBG connecting url=wss://tfchain.test.grid.tf/ws
Sep 21 16:51:10 grafana farmerbot[158]: 2025/09/21 16:51:10 Connecting to wss://tfchain.test.grid.tf/ws...
Sep 21 16:51:11 grafana farmerbot[158]: 4:51PM DBG Fetch nodes
Sep 21 16:51:11 grafana farmerbot[158]: 4:51PM DBG Add/update node nodeID=95
Sep 21 16:51:11 grafana farmerbot[158]: 4:51PM DBG Node is updated with latest changes successfully nodeID=95
Sep 21 16:51:11 grafana farmerbot[158]: 4:51PM DBG Add/update node nodeID=338
Sep 21 16:53:12 grafana farmerbot[158]: 4:53PM ERR error="failed to update node 338 with error: failed to get node 338 statistics from rmb with error: context deadline exceeded"
Sep 21 16:53:12 grafana farmerbot[158]: 4:53PM INF Too low resource usage, resources usage for online nodes: CRU:7%, SRU:20%, MRU:14%, HRU:0%
Sep 21 16:53:12 grafana farmerbot[158]: 4:53PM DBG Nothing to shutdown
Sep 21 16:53:12 grafana farmerbot[158]: 4:53PM DBG Nodes report
Sep 21 16:53:12 grafana farmerbot[158]: <E2><94><8C><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><AC><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><AC><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80>>
Sep 21 16:53:12 grafana farmerbot[158]: <E2><94><82>  ID <E2><94><82> STATE <E2><94><82> RENTED <E2><94><82> DEDICATED <E2><94><82> PUBLIC CONFIG <E2><94><82> USAGE            <E2><94><82> HAS ACTIVE NODE CONTRACTS <E2><94><82> RANDOM WAKE-UPS <E2><94><82> PERIODIC WAKE-UP <E2>  >
Sep 21 16:53:12 grafana farmerbot[158]: <E2><94><9C><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><BC><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><BC><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80>>
Sep 21 16:53:12 grafana farmerbot[158]: <E2><94><82>  95 <E2><94><82> ON    <E2><94><82> false  <E2><94><82> false     <E2><94><82> false         <E2><94><82> CRU:6%, SRU:19%, <E2><94><82> true                      <E2><94><82>               0 <E2><94><82> -                <E2>  >
Sep 21 16:53:12 grafana farmerbot[158]: <E2><94><82>     <E2><94><82>       <E2><94><82>        <E2><94><82>           <E2><94><82>               <E2><94><82> MRU:13%, HRU:0%  <E2><94><82>                           <E2><94><82>                 <E2><94><82>                  <E2>  >
Sep 21 16:53:12 grafana farmerbot[158]: <E2><94><9C><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><BC><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><BC><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80>>
Sep 21 16:53:12 grafana farmerbot[158]: <E2><94><82> 338 <E2><94><82> OFF   <E2><94><82> false  <E2><94><82> true      <E2><94><82> false         <E2><94><82> CRU:0%, SRU:1%,  <E2><94><82> false                     <E2><94><82>               0 <E2><94><82> -                <E2>  >
Sep 21 16:53:12 grafana farmerbot[158]: <E2><94><82>     <E2><94><82>       <E2><94><82>        <E2><94><82>           <E2><94><82>               <E2><94><82> MRU:9%, HRU:0%   <E2><94><82>                           <E2><94><82>                 <E2><94><82>                  <E2>  >
Sep 21 16:53:12 grafana farmerbot[158]: <E2><94><94><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><B4><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><B4><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80>>
Sep 21 16:58:12 grafana farmerbot[158]: 4:58PM DBG connecting url=wss://tfchain.test.grid.tf:443
Sep 21 16:58:12 grafana farmerbot[158]: 2025/09/21 16:58:12 Connecting to wss://tfchain.test.grid.tf:443...
Sep 21 16:58:12 grafana farmerbot[158]: 4:58PM DBG Fetch nodes
Sep 21 16:58:12 grafana farmerbot[158]: 4:58PM DBG Add/update node nodeID=95
Sep 21 16:58:13 grafana farmerbot[158]: 4:58PM DBG Node is updated with latest changes successfully nodeID=95
Sep 21 16:58:13 grafana farmerbot[158]: 4:58PM DBG Add/update node nodeID=338
Sep 21 17:00:13 grafana farmerbot[158]: 5:00PM ERR error="failed to update node 338 with error: failed to get node 338 statistics from rmb with error: context deadline exceeded"
Sep 21 17:00:13 grafana farmerbot[158]: 5:00PM INF Periodic wake up nodeID=338
Sep 21 17:00:13 grafana farmerbot[158]: 5:00PM INF POWER ON nodeID=338
Sep 21 17:00:18 grafana farmerbot[158]: 5:00PM INF Too low resource usage, resources usage for online nodes: CRU:5%, SRU:17%, MRU:13%, HRU:0%
Sep 21 17:00:18 grafana farmerbot[158]: 5:00PM DBG Nothing to shutdown
Sep 21 17:00:18 grafana farmerbot[158]: 5:00PM DBG Nodes report
Sep 21 17:00:18 grafana farmerbot[158]: <E2><94><8C><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><AC><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><AC><E2><94><80>>
Sep 21 17:00:18 grafana farmerbot[158]: <E2><94><82>  ID <E2><94><82> STATE     <E2><94><82> RENTED <E2><94><82> DEDICATED <E2><94><82> PUBLIC CONFIG <E2><94><82> USAGE            <E2><94><82> HAS ACTIVE NODE CONTRACTS <E2><94><82> RANDOM WAKE-UPS <E2><94><82> PERIODIC WAKE-UP   >
Sep 21 17:00:18 grafana farmerbot[158]: <E2><94><9C><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><BC><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><BC><E2><94><80>>
Sep 21 17:00:18 grafana farmerbot[158]: <E2><94><82>  95 <E2><94><82> ON        <E2><94><82> false  <E2><94><82> false     <E2><94><82> false         <E2><94><82> CRU:6%, SRU:19%, <E2><94><82> true                      <E2><94><82>               0 <E2><94><82> -                  >
Sep 21 17:00:18 grafana farmerbot[158]: <E2><94><82>     <E2><94><82>           <E2><94><82>        <E2><94><82>           <E2><94><82>               <E2><94><82> MRU:13%, HRU:0%  <E2><94><82>                           <E2><94><82>                 <E2><94><82>                    >
Sep 21 17:00:18 grafana farmerbot[158]: <E2><94><9C><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><BC><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><BC><E2><94><80>>
Sep 21 17:00:18 grafana farmerbot[158]: <E2><94><82> 338 <E2><94><82> Waking up <E2><94><82> false  <E2><94><82> true      <E2><94><82> false         <E2><94><82> CRU:0%, SRU:1%,  <E2><94><82> false                     <E2><94><82>               0 <E2><94><82> "05:00PM"          >
Sep 21 17:00:18 grafana farmerbot[158]: <E2><94><82>     <E2><94><82>           <E2><94><82>        <E2><94><82>           <E2><94><82>               <E2><94><82> MRU:9%, HRU:0%   <E2><94><82>                           <E2><94><82>                 <E2><94><82>                    >
Sep 21 17:00:18 grafana farmerbot[158]: <E2><94><94><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><B4><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><B4><E2><94><80>>
Sep 21 17:05:18 grafana farmerbot[158]: 5:05PM DBG connecting url=wss://tfchain.test.grid.tf/ws
Sep 21 17:05:18 grafana farmerbot[158]: 2025/09/21 17:05:18 Connecting to wss://tfchain.test.grid.tf/ws...
Sep 21 17:05:18 grafana farmerbot[158]: 5:05PM DBG Fetch nodes
Sep 21 17:05:18 grafana farmerbot[158]: 5:05PM DBG Add/update node nodeID=95
Sep 21 17:05:19 grafana farmerbot[158]: 5:05PM DBG Node is updated with latest changes successfully nodeID=95
Sep 21 17:05:19 grafana farmerbot[158]: 5:05PM DBG Add/update node nodeID=338
Sep 21 17:07:19 grafana farmerbot[158]: 5:07PM ERR error="failed to update node 338 with error: failed to get node 338 statistics from rmb with error: context deadline exceeded"
Sep 21 17:07:19 grafana farmerbot[158]: 5:07PM INF Too low resource usage, resources usage for online nodes: CRU:5%, SRU:17%, MRU:13%, HRU:0%
Sep 21 17:07:19 grafana farmerbot[158]: 5:07PM DBG Nothing to shutdown
Sep 21 17:07:19 grafana farmerbot[158]: 5:07PM DBG Nodes report
Sep 21 17:07:19 grafana farmerbot[158]: <E2><94><8C><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><AC><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><AC><E2><94><80>>
Sep 21 17:07:19 grafana farmerbot[158]: <E2><94><82>  ID <E2><94><82> STATE     <E2><94><82> RENTED <E2><94><82> DEDICATED <E2><94><82> PUBLIC CONFIG <E2><94><82> USAGE            <E2><94><82> HAS ACTIVE NODE CONTRACTS <E2><94><82> RANDOM WAKE-UPS <E2><94><82> PERIODIC WAKE-UP   >
Sep 21 17:07:19 grafana farmerbot[158]: <E2><94><9C><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><BC><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><BC><E2><94><80>>
Sep 21 17:07:19 grafana farmerbot[158]: <E2><94><82>  95 <E2><94><82> ON        <E2><94><82> false  <E2><94><82> false     <E2><94><82> false         <E2><94><82> CRU:6%, SRU:19%, <E2><94><82> true                      <E2><94><82>               0 <E2><94><82> -                  >
Sep 21 17:07:19 grafana farmerbot[158]: <E2><94><82>     <E2><94><82>           <E2><94><82>        <E2><94><82>           <E2><94><82>               <E2><94><82> MRU:13%, HRU:0%  <E2><94><82>                           <E2><94><82>                 <E2><94><82>                    >
Sep 21 17:07:19 grafana farmerbot[158]: <E2><94><9C><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><BC><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><BC><E2><94><80>>
Sep 21 17:07:19 grafana farmerbot[158]: <E2><94><82> 338 <E2><94><82> Waking up <E2><94><82> false  <E2><94><82> true      <E2><94><82> false         <E2><94><82> CRU:0%, SRU:1%,  <E2><94><82> false                     <E2><94><82>               0 <E2><94><82> "05:00PM"          >
Sep 21 17:07:19 grafana farmerbot[158]: <E2><94><82>     <E2><94><82>           <E2><94><82>        <E2><94><82>           <E2><94><82>               <E2><94><82> MRU:9%, HRU:0%   <E2><94><82>                           <E2><94><82>                 <E2><94><82>                    >
Sep 21 17:07:19 grafana farmerbot[158]: <E2><94><94><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><B4><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><80><E2><94><B4><E2><94><80>>

[TullysInc]

@xmonader - Please review and advise.

[xmonader]

Hi @archit3kt , the farmerbot just sets the state to wake up the node on tfchain, then zos farm nodes sends the wakeonlan sig https://github.com/threefoldtech/zosbase/blob/main/pkg/power/power.go#L149

[archit3kt]

Hi @xmonader, understood, the wol command is sent from a node.

My new plan is to host a virtual minimalistic node on my proxmox server which is on the same location, just for the purpose to send the wol command

Could you please tell me what are the minimal specs for a 3node to work ?

I tried 1 vCPU 2 Go RAM 500 GB SSD, but I've got an error "failed to register node: failed to create node on chain: failed to create node: InvalidMRUInput: registration failed"

Thanks for your help

[scottyeager]

InvalidMRUInput

This error is thrown from here: https://github.com/threefoldtech/tfchain/blob/8d32a808fb79443c5ed267a06e7481d640b89159/substrate-node/support/src/resources.rs#L60

Should be a minimum of 2 * 1024 * 1024 * 1024 bytes.

[archit3kt]

Upping node RAM to 2.25 GB is enough to get rid of the MRU error, but I pushed it to 3GB to get under the 80% MRU usage threshold. thanks for the input @scottyeager, dunno why I thought MRU was a network related problem (similar to MTU), I'm still not used to threefold terminology :)

So here's my farmerbot config :

farm_id: 23
included_nodes:
  - 338
  - 339
never_shutdown_nodes:
  - 339
power:
  periodic_wake_up_start: 03:00AM

The node was successfully shutdown, let's wait the next power on to see if it's working correctly, keep you updated before closing the issue

[archit3kt]

Well it hasn't been long

State node 338 OFF, 339 ON
Sep 26 11:43:48 grafana farmerbot[6771]: 11:43AM DBG connecting url=wss://tfchain.test.grid.tf/ws
Sep 26 11:43:48 grafana farmerbot[6771]: 2025/09/26 11:43:48 Connecting to wss://tfchain.test.grid.tf/ws...
Sep 26 11:43:48 grafana farmerbot[6771]: 11:43AM DBG Fetch nodes
Sep 26 11:43:48 grafana farmerbot[6771]: 11:43AM DBG Add/update node nodeID=338
Sep 26 11:45:49 grafana farmerbot[6771]: 11:45AM ERR error="failed to update node 338 with error: failed to get node 338 statistics from rmb with error: context deadline exceeded"
Sep 26 11:45:49 grafana farmerbot[6771]: 11:45AM INF Periodic wake up nodeID=338
Sep 26 11:45:49 grafana farmerbot[6771]: 11:45AM INF POWER ON nodeID=338
Sep 26 11:45:54 grafana farmerbot[6771]: 11:45AM DBG Add/update node nodeID=339
Sep 26 11:45:54 grafana farmerbot[6771]: 11:45AM DBG Node is updated with latest changes successfully nodeID=339
Sep 26 11:45:54 grafana farmerbot[6771]: 11:45AM INF Too low resource usage, resources usage for online nodes: CRU:0%, SRU:2%, MRU:13%, HRU:NaN%
Sep 26 11:45:54 grafana farmerbot[6771]: 11:45AM DBG Nothing to shutdown
Sep 26 11:45:54 grafana farmerbot[6771]: 11:45AM DBG Nodes report
Sep 26 11:45:54 grafana farmerbot[6771]: State node 338 Waking up, 339 ON
Sep 26 11:50:54 grafana farmerbot[6771]: 11:50AM DBG connecting url=wss://tfchain.test.grid.tf:443
Sep 26 11:50:54 grafana farmerbot[6771]: 2025/09/26 11:50:54 Connecting to wss://tfchain.test.grid.tf:443...
Sep 26 11:50:55 grafana farmerbot[6771]: 11:50AM DBG Fetch nodes
Sep 26 11:50:55 grafana farmerbot[6771]: 11:50AM DBG Add/update node nodeID=338
Sep 26 11:52:55 grafana farmerbot[6771]: 11:52AM ERR error="failed to update node 338 with error: failed to get node 338 statistics from rmb with error: context deadline exceeded"
Sep 26 11:52:55 grafana farmerbot[6771]: 11:52AM DBG Add/update node nodeID=339
Sep 26 11:52:56 grafana farmerbot[6771]: 11:52AM DBG Node is updated with latest changes successfully nodeID=339
Sep 26 11:52:56 grafana farmerbot[6771]: 11:52AM INF Too low resource usage, resources usage for online nodes: CRU:0%, SRU:2%, MRU:13%, HRU:NaN%
Sep 26 11:52:56 grafana farmerbot[6771]: 11:52AM DBG Nothing to shutdown
Sep 26 11:52:56 grafana farmerbot[6771]: 11:52AM DBG Nodes report
Sep 26 11:52:56 grafana farmerbot[6771]: State node 338 Waking up, 339 ON
Sep 26 11:57:56 grafana farmerbot[6771]: 11:57AM DBG connecting url=wss://tfchain.test.grid.tf/ws
Sep 26 11:57:56 grafana farmerbot[6771]: 2025/09/26 11:57:56 Connecting to wss://tfchain.test.grid.tf/ws...
Sep 26 11:57:56 grafana farmerbot[6771]: 11:57AM DBG Fetch nodes
Sep 26 11:57:56 grafana farmerbot[6771]: 11:57AM DBG Add/update node nodeID=338
Sep 26 11:59:56 grafana farmerbot[6771]: 11:59AM ERR error="failed to update node 338 with error: failed to get node 338 statistics from rmb with error: context deadline exceeded"
Sep 26 11:59:56 grafana farmerbot[6771]: 11:59AM DBG Add/update node nodeID=339
Sep 26 11:59:57 grafana farmerbot[6771]: 11:59AM DBG Node is updated with latest changes successfully nodeID=339
Sep 26 11:59:57 grafana farmerbot[6771]: 11:59AM INF Too low resource usage, resources usage for online nodes: CRU:0%, SRU:2%, MRU:13%, HRU:NaN%
Sep 26 11:59:57 grafana farmerbot[6771]: 11:59AM DBG Nothing to shutdown

Node is not booting

[scottyeager]

Here's a log snippet from node 339 (time is CEST):

This looks like normal behavior from a node that is waking up another node. Have you verified that a VM spawned in the same way as your Zos VM is able to get a WoL packet to the physical node?

[archit3kt]

Hi @scottyeager,

wakeonlan "mac address of node NIC" sent from VM A is working correctly and wake up the node
The trick to make it work across subnets is to create a socat connection on the router (openwrt 2024.10.2)

socat -u UDP-RECVFROM:9,interface=(int for subnet A),fork UDP-DATAGRAM:(broadcast IP of subnet B):7,broadcast

The zos VM is on the same subnet than the VM where the wakeonlan command is working properly. I tested one more VM from the same network and it's working fine.

Could you please show me the code part for the wol sending ? Maybe it's not done the same way as the wakeonlan command ?

Thanks for your help