diff options
Diffstat (limited to 'src')
| -rw-r--r-- | src/Makefile | 4 | ||||
| -rw-r--r-- | src/btfrv.cpp | 65 | ||||
| -rw-r--r-- | src/btfrv.h | 19 | ||||
| -rw-r--r-- | src/btftunnel.cpp | 140 | ||||
| -rw-r--r-- | src/btftunnel.h | 25 | ||||
| -rw-r--r-- | src/gui.cpp | 34 | ||||
| -rw-r--r-- | src/main.cpp | 521 | ||||
| -rw-r--r-- | src/main_gui.cpp | 50 | ||||
| -rw-r--r-- | src/net.cpp | 5 | ||||
| -rw-r--r-- | src/net.h | 73 | ||||
| -rw-r--r-- | src/nostr.cpp | 27 | ||||
| -rw-r--r-- | src/nostr.h | 3 | ||||
| -rw-r--r-- | src/randomx_pow.cpp | 28 | ||||
| -rw-r--r-- | src/readme.txt | 2 | ||||
| -rw-r--r-- | src/rpc.cpp | 398 | ||||
| -rw-r--r-- | src/util.cpp | 153 | ||||
| -rw-r--r-- | src/util.h | 93 |
17 files changed, 1534 insertions, 106 deletions
diff --git a/src/Makefile b/src/Makefile index 1bc3ae8..2c6d304 100644 --- a/src/Makefile +++ b/src/Makefile | |||
| @@ -6,7 +6,9 @@ FUZZ_CXX ?= clang++ | |||
| 6 | 6 | ||
| 7 | SECP_INC ?= /usr/local/include | 7 | SECP_INC ?= /usr/local/include |
| 8 | SECP_LIB ?= /usr/local/lib | 8 | SECP_LIB ?= /usr/local/lib |
| 9 | RANDOMX_DIR ?= $(HOME)/RandomX | 9 | # The root Makefile exports RANDOMX_DIR (default: <repo>/randomx-build, built |
| 10 | # by deps-randomx). This fallback only applies when src/ is built standalone. | ||
| 11 | RANDOMX_DIR ?= $(abspath $(CURDIR)/..)/randomx-build | ||
| 10 | 12 | ||
| 11 | IMGUI_DIR = imgui | 13 | IMGUI_DIR = imgui |
| 12 | 14 | ||
diff --git a/src/btfrv.cpp b/src/btfrv.cpp index 133eb89..7d705ef 100644 --- a/src/btfrv.cpp +++ b/src/btfrv.cpp | |||
| @@ -40,6 +40,8 @@ typedef int SOCKET; | |||
| 40 | #include <thread> | 40 | #include <thread> |
| 41 | #include <mutex> | 41 | #include <mutex> |
| 42 | #include <atomic> | 42 | #include <atomic> |
| 43 | #include <chrono> | ||
| 44 | #include <system_error> | ||
| 43 | 45 | ||
| 44 | namespace btf | 46 | namespace btf |
| 45 | { | 47 | { |
| @@ -209,8 +211,28 @@ static void HandleIncoming(SOCKET s) | |||
| 209 | bool a = WriteN(svc, &ok, 1); | 211 | bool a = WriteN(svc, &ok, 1); |
| 210 | bool b = WriteN(s, &ok, 1); | 212 | bool b = WriteN(s, &ok, 1); |
| 211 | if (!a || !b) { CLOSESOCK(svc); CLOSESOCK(s); return; } | 213 | if (!a || !b) { CLOSESOCK(svc); CLOSESOCK(s); return; } |
| 212 | std::thread(Forward, s, svc).detach(); | 214 | // One thread pumps s -> svc; this thread pumps svc -> s. Spawning a |
| 213 | std::thread(Forward, svc, s).detach(); | 215 | // thread per direction left no clean way to fail the second spawn: |
| 216 | // std::thread throws std::system_error when pthread_create is refused | ||
| 217 | // (NPROC limit, container pids cgroup, memory pressure), the first | ||
| 218 | // pump was already detached, and closing its sockets from here would | ||
| 219 | // race it -- so nothing caught the throw and it reached | ||
| 220 | // std::terminate, killing the relay over one pair it could not serve. | ||
| 221 | // Running one direction on this thread leaves exactly one spawn to | ||
| 222 | // guard, and a failure here has nothing running yet to race. | ||
| 223 | try | ||
| 224 | { | ||
| 225 | std::thread(Forward, s, svc).detach(); | ||
| 226 | } | ||
| 227 | catch (const std::system_error& e) | ||
| 228 | { | ||
| 229 | fprintf(stderr, "rendezvous relay: cannot spawn forward thread (%s), pair dropped\n", | ||
| 230 | e.what()); | ||
| 231 | CLOSESOCK(svc); | ||
| 232 | CLOSESOCK(s); | ||
| 233 | return; | ||
| 234 | } | ||
| 235 | Forward(svc, s); | ||
| 214 | } | 236 | } |
| 215 | else | 237 | else |
| 216 | { | 238 | { |
| @@ -236,6 +258,7 @@ bool RvRelayRun(unsigned short port) | |||
| 236 | if (bind(g_listen, (struct sockaddr*)&addr, sizeof(addr)) != 0) { CLOSESOCK(g_listen); return false; } | 258 | if (bind(g_listen, (struct sockaddr*)&addr, sizeof(addr)) != 0) { CLOSESOCK(g_listen); return false; } |
| 237 | if (listen(g_listen, 16) != 0) { CLOSESOCK(g_listen); return false; } | 259 | if (listen(g_listen, 16) != 0) { CLOSESOCK(g_listen); return false; } |
| 238 | 260 | ||
| 261 | int nSpawnFails = 0; | ||
| 239 | while (!g_stop) | 262 | while (!g_stop) |
| 240 | { | 263 | { |
| 241 | struct sockaddr_in cli; | 264 | struct sockaddr_in cli; |
| @@ -246,7 +269,27 @@ bool RvRelayRun(unsigned short port) | |||
| 246 | if (g_stop) break; | 269 | if (g_stop) break; |
| 247 | continue; | 270 | continue; |
| 248 | } | 271 | } |
| 249 | std::thread(HandleIncoming, s).detach(); | 272 | try |
| 273 | { | ||
| 274 | std::thread(HandleIncoming, s).detach(); | ||
| 275 | nSpawnFails = 0; | ||
| 276 | } | ||
| 277 | catch (const std::system_error& e) | ||
| 278 | { | ||
| 279 | // A refused pthread_create is backpressure, not a reason to die: | ||
| 280 | // the condition behind it (NPROC, pids cgroup, memory) does not | ||
| 281 | // clear in milliseconds, and the connection count feeding it is | ||
| 282 | // attacker-influenced. Drop this one peer, stop accepting for a | ||
| 283 | // moment -- longer each time, capped -- and keep serving the | ||
| 284 | // connections already established. | ||
| 285 | fprintf(stderr, "rendezvous relay: cannot spawn connection thread (%s), connection dropped\n", | ||
| 286 | e.what()); | ||
| 287 | CLOSESOCK(s); | ||
| 288 | nSpawnFails++; | ||
| 289 | int nWaitMs = nSpawnFails < 5 ? nSpawnFails * 1000 : 5000; | ||
| 290 | for (int i = 0; i < nWaitMs && !g_stop; i += 100) | ||
| 291 | std::this_thread::sleep_for(std::chrono::milliseconds(100)); | ||
| 292 | } | ||
| 250 | } | 293 | } |
| 251 | CLOSESOCK(g_listen); | 294 | CLOSESOCK(g_listen); |
| 252 | g_listen = INVALID_SOCKET; | 295 | g_listen = INVALID_SOCKET; |
| @@ -334,17 +377,29 @@ bool RvServiceWaitPaired(RvSocket s, int nTimeoutSecs) | |||
| 334 | } | 377 | } |
| 335 | 378 | ||
| 336 | RvSocket RvClientConnect(const char* relay_host, unsigned short port, | 379 | RvSocket RvClientConnect(const char* relay_host, unsigned short port, |
| 337 | const unsigned char target_pubkey[32]) | 380 | const unsigned char target_pubkey[32], |
| 381 | RvClientFail* pFail) | ||
| 338 | { | 382 | { |
| 383 | if (pFail) *pFail = RVC_FAIL_DIAL; | ||
| 339 | if (!RvInit()) return RV_INVALID; | 384 | if (!RvInit()) return RV_INVALID; |
| 340 | SOCKET s = ConnectTo(relay_host, port); | 385 | SOCKET s = ConnectTo(relay_host, port); |
| 341 | if (s == INVALID_SOCKET) return RV_INVALID; | 386 | if (s == INVALID_SOCKET) return RV_INVALID; |
| 387 | if (pFail) *pFail = RVC_FAIL_PAIR; | ||
| 342 | unsigned char hdr[33]; | 388 | unsigned char hdr[33]; |
| 343 | hdr[0] = (unsigned char)'C'; | 389 | hdr[0] = (unsigned char)'C'; |
| 344 | memcpy(hdr + 1, target_pubkey, 32); | 390 | memcpy(hdr + 1, target_pubkey, 32); |
| 345 | if (!WriteN(s, hdr, 33)) { CLOSESOCK(s); return RV_INVALID; } | 391 | if (!WriteN(s, hdr, 33)) { CLOSESOCK(s); return RV_INVALID; } |
| 346 | unsigned char paired = 0; | 392 | unsigned char paired = 0; |
| 347 | if (!ReadN(s, &paired, 1) || paired != 0x01) { CLOSESOCK(s); return RV_INVALID; } | 393 | if (!ReadN(s, &paired, 1)) { CLOSESOCK(s); return RV_INVALID; } |
| 394 | if (paired != 0x01) | ||
| 395 | { | ||
| 396 | // The relay answered and declined: HandleIncoming writes 0x00 and | ||
| 397 | // closes when no service is parked under this pubkey right now. | ||
| 398 | if (pFail) *pFail = RVC_FAIL_REFUSED; | ||
| 399 | CLOSESOCK(s); | ||
| 400 | return RV_INVALID; | ||
| 401 | } | ||
| 402 | if (pFail) *pFail = RVC_FAIL_NONE; | ||
| 348 | return (RvSocket)s; | 403 | return (RvSocket)s; |
| 349 | } | 404 | } |
| 350 | 405 | ||
diff --git a/src/btfrv.h b/src/btfrv.h index 9cd7476..1e85cb0 100644 --- a/src/btfrv.h +++ b/src/btfrv.h | |||
| @@ -57,10 +57,25 @@ RvSocket RvServiceRegister(const char* relay_host, unsigned short port, | |||
| 57 | bool RvServiceWaitPaired(RvSocket s, int nTimeoutSecs = 0); | 57 | bool RvServiceWaitPaired(RvSocket s, int nTimeoutSecs = 0); |
| 58 | 58 | ||
| 59 | // ---- client side (the node dialing a .btf address) ---- | 59 | // ---- client side (the node dialing a .btf address) ---- |
| 60 | // Where a failed RvClientConnect stopped. RV_INVALID alone collapses three | ||
| 61 | // different situations -- relay unreachable, relay reachable but nobody | ||
| 62 | // registered, connection died mid-pairing -- and they point at different | ||
| 63 | // components. The caller can only report the right one if this side says | ||
| 64 | // which it saw. | ||
| 65 | enum RvClientFail | ||
| 66 | { | ||
| 67 | RVC_FAIL_NONE = 0, | ||
| 68 | RVC_FAIL_DIAL, // TCP connect to the relay itself failed | ||
| 69 | RVC_FAIL_REFUSED, // relay answered 0x00: no service registered under this pubkey | ||
| 70 | RVC_FAIL_PAIR, // relay connection died before pairing completed | ||
| 71 | }; | ||
| 72 | |||
| 60 | // Connect through the relay to the service registered under `target_pubkey`. | 73 | // Connect through the relay to the service registered under `target_pubkey`. |
| 61 | // Returns the paired socket, or RV_INVALID on error. | 74 | // Returns the paired socket, or RV_INVALID on error -- with `pFail`, if |
| 75 | // given, naming the stage that failed. | ||
| 62 | RvSocket RvClientConnect(const char* relay_host, unsigned short port, | 76 | RvSocket RvClientConnect(const char* relay_host, unsigned short port, |
| 63 | const unsigned char target_pubkey[32]); | 77 | const unsigned char target_pubkey[32], |
| 78 | RvClientFail* pFail = 0); | ||
| 64 | 79 | ||
| 65 | // Blocking read/write of exactly n bytes over a rendezvous socket. Return false | 80 | // Blocking read/write of exactly n bytes over a rendezvous socket. Return false |
| 66 | // on error/EOF. | 81 | // on error/EOF. |
diff --git a/src/btftunnel.cpp b/src/btftunnel.cpp index 63d178b..4058f6b 100644 --- a/src/btftunnel.cpp +++ b/src/btftunnel.cpp | |||
| @@ -25,8 +25,12 @@ typedef int SOCKET; | |||
| 25 | #endif | 25 | #endif |
| 26 | #include "sockcount.h" | 26 | #include "sockcount.h" |
| 27 | #include <cstring> | 27 | #include <cstring> |
| 28 | #include <cstdio> | ||
| 29 | #include <memory> | ||
| 30 | #include <new> | ||
| 28 | #include <vector> | 31 | #include <vector> |
| 29 | #include <thread> | 32 | #include <thread> |
| 33 | #include <system_error> | ||
| 30 | 34 | ||
| 31 | namespace btf | 35 | namespace btf |
| 32 | { | 36 | { |
| @@ -119,35 +123,155 @@ static void PumpIn(SOCKET pumpEnd, RvSocket rv, std::vector<unsigned char> key) | |||
| 119 | shutdown((SOCKET)rv, SD_BOTH); | 123 | shutdown((SOCKET)rv, SD_BOTH); |
| 120 | } | 124 | } |
| 121 | 125 | ||
| 126 | // The pump end and the rendezvous socket, owned jointly by whoever is still | ||
| 127 | // using them. Closed once, by the last reference to go. | ||
| 128 | // | ||
| 129 | // Joint ownership rather than "the inbound pump owns the cleanup", because | ||
| 130 | // either pump can reach its exit first and BOTH touch BOTH descriptors on the | ||
| 131 | // way out -- PumpOut ends in shutdown(rv), shutdown(pumpEnd) and PumpIn ends in | ||
| 132 | // the mirror image. A single owner therefore has no exit at which the other is | ||
| 133 | // guaranteed to be finished. Holding a reference for the whole body of each | ||
| 134 | // pump gives it one: the close cannot happen until the last pump has stopped | ||
| 135 | // touching the descriptors, so no shutdown() can land on a number that has | ||
| 136 | // already been closed and handed back out by the kernel to an unrelated | ||
| 137 | // connection. | ||
| 138 | struct TunnelEnds | ||
| 139 | { | ||
| 140 | SOCKET pumpEnd; | ||
| 141 | RvSocket rv; | ||
| 142 | TunnelEnds(SOCKET p, RvSocket r) : pumpEnd(p), rv(r) {} | ||
| 143 | ~TunnelEnds() { BtfCloseSocket(pumpEnd); RvClose(rv); } | ||
| 144 | private: | ||
| 145 | TunnelEnds(const TunnelEnds&); | ||
| 146 | TunnelEnds& operator=(const TunnelEnds&); | ||
| 147 | }; | ||
| 148 | |||
| 122 | // Start the two pumps and hand back the app-facing socket. When both pumps | 149 | // Start the two pumps and hand back the app-facing socket. When both pumps |
| 123 | // finish, close the pump end and the rendezvous socket. | 150 | // finish, close the pump end and the rendezvous socket. |
| 151 | // | ||
| 152 | // That sentence used to be a comment describing something the code did not do. | ||
| 153 | // The inbound pump closed both descriptors as soon as it exited, without | ||
| 154 | // waiting for the outbound pump, which then called shutdown() on both at its | ||
| 155 | // own exit. Whether that shutdown hit a live descriptor or a closed one came | ||
| 156 | // down to which pump got there first, and the rendezvous socket dying before | ||
| 157 | // the app socket -- a relay restart, the far side hanging up -- is precisely | ||
| 158 | // the order that puts the inbound pump ahead. Measured over 25 such teardowns | ||
| 159 | // against the real code: 29 shutdowns landed on an already-closed descriptor. | ||
| 160 | // | ||
| 161 | // appEnd is not part of this. It is handed to the caller on success and closed | ||
| 162 | // here on every failure path; no pump ever touches it. | ||
| 163 | // | ||
| 164 | // Every tunnel is two threads, and a tunnel is one peer connection (a .btf | ||
| 165 | // dial or accept, a pool miner, a participant's pool session) -- so the | ||
| 166 | // thread count scales with peer count, which is attacker-influenced. When | ||
| 167 | // pthread_create is refused std::thread throws std::system_error; uncaught it | ||
| 168 | // reached std::terminate and took the whole process down over one connection | ||
| 169 | // it could not serve. Both spawns are guarded, and the failure paths return | ||
| 170 | // INVALID_SOCKET, which every caller already handles by dropping just that | ||
| 171 | // connection. | ||
| 124 | static btf_socket_t StartTunnel(RvSocket rv, const unsigned char shared[32]) | 172 | static btf_socket_t StartTunnel(RvSocket rv, const unsigned char shared[32]) |
| 125 | { | 173 | { |
| 126 | btf_socket_t appEnd, pumpEnd; | 174 | btf_socket_t appEnd, pumpEnd; |
| 127 | if (!MakeLocalPair(appEnd, pumpEnd)) { RvClose(rv); return INVALID_SOCKET; } | 175 | if (!MakeLocalPair(appEnd, pumpEnd)) { RvClose(rv); return INVALID_SOCKET; } |
| 128 | 176 | ||
| 129 | std::vector<unsigned char> key(shared, shared + 32); | 177 | std::vector<unsigned char> key(shared, shared + 32); |
| 130 | std::thread(PumpOut, pumpEnd, rv, key).detach(); | 178 | |
| 131 | std::thread([pumpEnd, rv, key]() { | 179 | // make_shared, not shared_ptr(new ...): it allocates before it constructs, |
| 132 | PumpIn(pumpEnd, rv, key); | 180 | // so it either comes back owning both descriptors or throws having taken |
| 181 | // ownership of neither. The two-step form can run the deleter and then | ||
| 182 | // throw, which would close both here and again below. | ||
| 183 | std::shared_ptr<TunnelEnds> ends; | ||
| 184 | try | ||
| 185 | { | ||
| 186 | ends = std::make_shared<TunnelEnds>(pumpEnd, rv); | ||
| 187 | } | ||
| 188 | catch (const std::bad_alloc&) | ||
| 189 | { | ||
| 190 | fprintf(stderr, "btf tunnel: out of memory starting tunnel, tunnel dropped\n"); | ||
| 133 | BtfCloseSocket(pumpEnd); | 191 | BtfCloseSocket(pumpEnd); |
| 192 | BtfCloseSocket(appEnd); | ||
| 134 | RvClose(rv); | 193 | RvClose(rv); |
| 135 | }).detach(); | 194 | return INVALID_SOCKET; |
| 195 | } | ||
| 196 | |||
| 197 | try | ||
| 198 | { | ||
| 199 | std::thread([ends, key]() { PumpIn(ends->pumpEnd, ends->rv, key); }).detach(); | ||
| 200 | } | ||
| 201 | catch (const std::system_error& e) | ||
| 202 | { | ||
| 203 | // Nothing is running yet: `ends` is the only reference, and returning | ||
| 204 | // drops it, which is what closes pumpEnd and rv. | ||
| 205 | fprintf(stderr, "btf tunnel: cannot spawn inbound pump (%s), tunnel dropped\n", | ||
| 206 | e.what()); | ||
| 207 | BtfCloseSocket(appEnd); | ||
| 208 | return INVALID_SOCKET; | ||
| 209 | } | ||
| 210 | |||
| 211 | try | ||
| 212 | { | ||
| 213 | std::thread([ends, key]() { PumpOut(ends->pumpEnd, ends->rv, key); }).detach(); | ||
| 214 | } | ||
| 215 | catch (const std::system_error& e) | ||
| 216 | { | ||
| 217 | // The inbound pump may be parked in RvReadN(rv) or may already have | ||
| 218 | // exited -- when the spawn is refused because the process is loaded, | ||
| 219 | // the rendezvous socket is often dead for the same reason, and then | ||
| 220 | // PumpIn returns on its first length read. Either way this thread | ||
| 221 | // still holds a reference, so both descriptors are still open: the | ||
| 222 | // shutdown wakes the pump if it is parked and is harmless if it is | ||
| 223 | // not. The close belongs to whichever reference goes last. | ||
| 224 | fprintf(stderr, "btf tunnel: cannot spawn outbound pump (%s), tunnel dropped\n", | ||
| 225 | e.what()); | ||
| 226 | shutdown((SOCKET)ends->rv, SD_BOTH); | ||
| 227 | shutdown(ends->pumpEnd, SD_BOTH); | ||
| 228 | BtfCloseSocket(appEnd); | ||
| 229 | return INVALID_SOCKET; | ||
| 230 | } | ||
| 136 | return appEnd; | 231 | return appEnd; |
| 137 | } | 232 | } |
| 138 | 233 | ||
| 234 | const char* TunnelFailText(TunnelFail f) | ||
| 235 | { | ||
| 236 | switch (f) | ||
| 237 | { | ||
| 238 | case TUNNEL_FAIL_NONE: return "no failure"; | ||
| 239 | case TUNNEL_FAIL_INIT: return "local socket/crypto init failed"; | ||
| 240 | case TUNNEL_FAIL_DIAL: return "meeting node unreachable (tcp dial failed)"; | ||
| 241 | case TUNNEL_FAIL_REFUSED: return "relay reachable, but no service registered there for this address"; | ||
| 242 | case TUNNEL_FAIL_PAIR: return "relay connection died before pairing completed"; | ||
| 243 | case TUNNEL_FAIL_HANDSHAKE: return "end-to-end handshake failed"; | ||
| 244 | case TUNNEL_FAIL_LOCAL: return "local tunnel setup failed"; | ||
| 245 | } | ||
| 246 | return "unknown failure"; | ||
| 247 | } | ||
| 248 | |||
| 139 | btf_socket_t BtfClientTunnel(const char* meeting_host, unsigned short port, | 249 | btf_socket_t BtfClientTunnel(const char* meeting_host, unsigned short port, |
| 140 | const unsigned char target_pubkey[32], | 250 | const unsigned char target_pubkey[32], |
| 141 | const unsigned char service_enc_pub[32]) | 251 | const unsigned char service_enc_pub[32], |
| 252 | TunnelFail* pFail) | ||
| 142 | { | 253 | { |
| 254 | if (pFail) *pFail = TUNNEL_FAIL_INIT; | ||
| 143 | if (!TunnelInit()) return INVALID_SOCKET; | 255 | if (!TunnelInit()) return INVALID_SOCKET; |
| 144 | RvSocket rv = RvClientConnect(meeting_host, port, target_pubkey); | 256 | RvClientFail rvFail = RVC_FAIL_NONE; |
| 145 | if (rv == RV_INVALID) return INVALID_SOCKET; | 257 | RvSocket rv = RvClientConnect(meeting_host, port, target_pubkey, &rvFail); |
| 258 | if (rv == RV_INVALID) | ||
| 259 | { | ||
| 260 | if (pFail) | ||
| 261 | *pFail = rvFail == RVC_FAIL_DIAL ? TUNNEL_FAIL_DIAL | ||
| 262 | : rvFail == RVC_FAIL_REFUSED ? TUNNEL_FAIL_REFUSED | ||
| 263 | : TUNNEL_FAIL_PAIR; | ||
| 264 | return INVALID_SOCKET; | ||
| 265 | } | ||
| 146 | 266 | ||
| 147 | unsigned char eph_pub[32], shared[32]; | 267 | unsigned char eph_pub[32], shared[32]; |
| 268 | if (pFail) *pFail = TUNNEL_FAIL_HANDSHAKE; | ||
| 148 | if (!ChanClientHandshake(service_enc_pub, eph_pub, shared)) { RvClose(rv); return INVALID_SOCKET; } | 269 | if (!ChanClientHandshake(service_enc_pub, eph_pub, shared)) { RvClose(rv); return INVALID_SOCKET; } |
| 149 | if (!RvWriteN(rv, eph_pub, 32)) { RvClose(rv); return INVALID_SOCKET; } | 270 | if (!RvWriteN(rv, eph_pub, 32)) { RvClose(rv); return INVALID_SOCKET; } |
| 150 | return StartTunnel(rv, shared); | 271 | if (pFail) *pFail = TUNNEL_FAIL_LOCAL; |
| 272 | btf_socket_t app = StartTunnel(rv, shared); | ||
| 273 | if (app != INVALID_SOCKET && pFail) *pFail = TUNNEL_FAIL_NONE; | ||
| 274 | return app; | ||
| 151 | } | 275 | } |
| 152 | 276 | ||
| 153 | btf_socket_t BtfServiceWrap(RvSocket rv, const unsigned char my_enc_sk[32]) | 277 | btf_socket_t BtfServiceWrap(RvSocket rv, const unsigned char my_enc_sk[32]) |
diff --git a/src/btftunnel.h b/src/btftunnel.h index 24a7509..3cc87cd 100644 --- a/src/btftunnel.h +++ b/src/btftunnel.h | |||
| @@ -36,12 +36,33 @@ namespace btf | |||
| 36 | // Initialize (sockets + libsodium). Idempotent. | 36 | // Initialize (sockets + libsodium). Idempotent. |
| 37 | bool TunnelInit(); | 37 | bool TunnelInit(); |
| 38 | 38 | ||
| 39 | // Which stage of BtfClientTunnel failed. INVALID_SOCKET alone says only "no | ||
| 40 | // tunnel"; a caller that then guesses at causes in its log line sends whoever | ||
| 41 | // reads it to the wrong component (issue #17: "relay unreachable or pool not | ||
| 42 | // listening" blamed two healthy parts). The stage is what this side actually | ||
| 43 | // knows -- report that. | ||
| 44 | enum TunnelFail | ||
| 45 | { | ||
| 46 | TUNNEL_FAIL_NONE = 0, | ||
| 47 | TUNNEL_FAIL_INIT, // local socket/crypto init failed | ||
| 48 | TUNNEL_FAIL_DIAL, // TCP connect to the meeting node failed | ||
| 49 | TUNNEL_FAIL_REFUSED, // relay reachable, but no service registered under the pubkey | ||
| 50 | TUNNEL_FAIL_PAIR, // relay connection died before pairing completed | ||
| 51 | TUNNEL_FAIL_HANDSHAKE, // end-to-end channel handshake failed | ||
| 52 | TUNNEL_FAIL_LOCAL, // local pump plumbing (socket pair / threads) failed | ||
| 53 | }; | ||
| 54 | |||
| 55 | // Short description of a TunnelFail for log lines. | ||
| 56 | const char* TunnelFailText(TunnelFail f); | ||
| 57 | |||
| 39 | // Client: dial the service registered under `target_pubkey` at the meeting node | 58 | // Client: dial the service registered under `target_pubkey` at the meeting node |
| 40 | // (host:port), box to its static x25519 `service_enc_pub`, and return a local | 59 | // (host:port), box to its static x25519 `service_enc_pub`, and return a local |
| 41 | // plaintext SOCKET tunneled end-to-end to the service. INVALID_SOCKET on error. | 60 | // plaintext SOCKET tunneled end-to-end to the service. INVALID_SOCKET on error |
| 61 | // -- with `pFail`, if given, naming the stage that failed. | ||
| 42 | btf_socket_t BtfClientTunnel(const char* meeting_host, unsigned short port, | 62 | btf_socket_t BtfClientTunnel(const char* meeting_host, unsigned short port, |
| 43 | const unsigned char target_pubkey[32], | 63 | const unsigned char target_pubkey[32], |
| 44 | const unsigned char service_enc_pub[32]); | 64 | const unsigned char service_enc_pub[32], |
| 65 | TunnelFail* pFail = 0); | ||
| 45 | 66 | ||
| 46 | // Service: wrap an already-paired rendezvous socket (RvServiceRegister followed | 67 | // Service: wrap an already-paired rendezvous socket (RvServiceRegister followed |
| 47 | // by RvServiceWaitPaired -- the pairing byte MUST already be consumed) with | 68 | // by RvServiceWaitPaired -- the pairing byte MUST already be consumed) with |
diff --git a/src/gui.cpp b/src/gui.cpp index 8dcb854..9b3802b 100644 --- a/src/gui.cpp +++ b/src/gui.cpp | |||
| @@ -15,6 +15,7 @@ | |||
| 15 | #include <atomic> | 15 | #include <atomic> |
| 16 | #include <mutex> | 16 | #include <mutex> |
| 17 | #include <thread> | 17 | #include <thread> |
| 18 | #include <system_error> | ||
| 18 | #include "bip32.h" | 19 | #include "bip32.h" |
| 19 | #include "walletcmd.h" | 20 | #include "walletcmd.h" |
| 20 | #include "font_roboto.h" | 21 | #include "font_roboto.h" |
| @@ -910,8 +911,16 @@ static void DrawOptionsDialog() | |||
| 910 | 911 | ||
| 911 | if (nMineMode == MINE_OPERATOR) { | 912 | if (nMineMode == MINE_OPERATOR) { |
| 912 | if (!gPoolServerRunning) { | 913 | if (!gPoolServerRunning) { |
| 913 | gPoolServerRunning = true; | 914 | // Claim the server is up only once it is. The flag used to |
| 914 | _beginthread(ThreadRPCServer, 0, NULL); | 915 | // be set first and the result never looked at, so a refused |
| 916 | // spawn left an operator with a pool that reports itself | ||
| 917 | // running, no RPC server for miners to reach, and nothing | ||
| 918 | // anywhere saying why. The flag also latches: with it set, | ||
| 919 | // this branch is never retried. | ||
| 920 | if (_beginthread(ThreadRPCServer, 0, NULL) == (uintptr_t)-1) | ||
| 921 | printf("Error: _beginthread(ThreadRPCServer) failed -- pool server not started\n"); | ||
| 922 | else | ||
| 923 | gPoolServerRunning = true; | ||
| 915 | } else if (!gPoolRunning) { | 924 | } else if (!gPoolRunning) { |
| 916 | gPoolRunning = true; | 925 | gPoolRunning = true; |
| 917 | } | 926 | } |
| @@ -1124,11 +1133,28 @@ static void DrawRestorePhraseDialog() | |||
| 1124 | } | 1133 | } |
| 1125 | g_restoreDerived.store(0); | 1134 | g_restoreDerived.store(0); |
| 1126 | g_restoreRecovered.store(0); | 1135 | g_restoreRecovered.store(0); |
| 1136 | // Set before the spawn, not after: RestoreThread clears this | ||
| 1137 | // flag itself when it finishes, and a short restore can beat | ||
| 1138 | // us back here and have its `false` overwritten, leaving the | ||
| 1139 | // dialog disabled forever. | ||
| 1127 | g_restoreRunning.store(true); | 1140 | g_restoreRunning.store(true); |
| 1128 | // On its own thread: a restore walks the whole chain once per | 1141 | // On its own thread: a restore walks the whole chain once per |
| 1129 | // batch and would otherwise freeze the window for as long as it | 1142 | // batch and would otherwise freeze the window for as long as it |
| 1130 | // takes. | 1143 | // takes. A refused spawn is one restore that does not happen, |
| 1131 | std::thread(RestoreThread, std::string(g_restoreInput)).detach(); | 1144 | // not a reason to take the window down with an uncaught |
| 1145 | // std::system_error -- and the flag has to come back off, or | ||
| 1146 | // the dialog sits greyed out reporting a search nobody is | ||
| 1147 | // running. | ||
| 1148 | try | ||
| 1149 | { | ||
| 1150 | std::thread(RestoreThread, std::string(g_restoreInput)).detach(); | ||
| 1151 | } | ||
| 1152 | catch (const std::system_error& e) | ||
| 1153 | { | ||
| 1154 | g_restoreRunning.store(false); | ||
| 1155 | std::lock_guard<std::mutex> lock(g_restoreResultMutex); | ||
| 1156 | g_restoreResult = std::string("Could not start the search: ") + e.what(); | ||
| 1157 | } | ||
| 1132 | } | 1158 | } |
| 1133 | } | 1159 | } |
| 1134 | if (fBusy) | 1160 | if (fBusy) |
diff --git a/src/main.cpp b/src/main.cpp index 7b3e555..6b8e0de 100644 --- a/src/main.cpp +++ b/src/main.cpp | |||
| @@ -14,6 +14,7 @@ | |||
| 14 | #include <atomic> | 14 | #include <atomic> |
| 15 | #include <mutex> | 15 | #include <mutex> |
| 16 | #include <thread> | 16 | #include <thread> |
| 17 | #include <system_error> | ||
| 17 | #include "bip32.h" | 18 | #include "bip32.h" |
| 18 | #include "btfaddr.h" | 19 | #include "btfaddr.h" |
| 19 | #include "btftunnel.h" | 20 | #include "btftunnel.h" |
| @@ -64,6 +65,137 @@ CBlockIndex* pindexBest = NULL; | |||
| 64 | map<uint256, CBlock*> mapOrphanBlocks; | 65 | map<uint256, CBlock*> mapOrphanBlocks; |
| 65 | multimap<uint256, CBlock*> mapOrphanBlocksByPrev; | 66 | multimap<uint256, CBlock*> mapOrphanBlocksByPrev; |
| 66 | 67 | ||
| 68 | // Block bodies we have sent a getdata for and not yet received, so the | ||
| 69 | // failover pass in SendMessages can tell "requested and being served" from | ||
| 70 | // "requested and gone quiet" and re-issue the request to a different peer | ||
| 71 | // (#33). Keyed by block hash; setAsked is the peers already tried since the | ||
| 72 | // round last restarted, so the retry rotates instead of hammering the | ||
| 73 | // announcer that is not serving. Guarded by cs_main, which both the message | ||
| 74 | // handlers and SendMessages already hold. | ||
| 75 | // | ||
| 76 | // Capped small on purpose. At the tip there is one block in flight; during | ||
| 77 | // initial download there are legitimately hundreds outstanding to one peer, | ||
| 78 | // and rotating those would duplicate the whole download to every other peer. | ||
| 79 | // | ||
| 80 | // The cap is a shared resource and nothing on the path from inv to insertion | ||
| 81 | // can tell a real block hash from 32 random bytes -- AlreadyHave only asks | ||
| 82 | // whether we already hold the block, and there is no header to check work | ||
| 83 | // against. So the table does not refuse a new hash when it is full; it makes | ||
| 84 | // room. See MakeRoomInBlockFetch for the rule, which is what stops one peer | ||
| 85 | // filling all eight slots and switching failover off for everybody. | ||
| 86 | // | ||
| 87 | // The initialisers matter: the insertion path uses operator[] and then tests | ||
| 88 | // nTimeFirstAsked == 0 to detect a fresh entry. That worked on | ||
| 89 | // value-initialisation alone, but only for as long as nobody gave this struct | ||
| 90 | // a constructor. | ||
| 91 | struct CBlockFetch | ||
| 92 | { | ||
| 93 | int64 nTimeFirstAsked = 0; // when the first getdata for this block went out | ||
| 94 | int64 nTimeAsked = 0; // when the latest getdata went out | ||
| 95 | CAddress addrAnnounced; // peer whose announcement put this hash here | ||
| 96 | set<CAddress> setAsked; // peers tried since the round last restarted | ||
| 97 | }; | ||
| 98 | map<uint256, CBlockFetch> mapBlockFetch; | ||
| 99 | static const int BLOCK_FETCH_TRACK_MAX = 8; | ||
| 100 | // A block nobody has served for this long is not a fetch problem: the hash may | ||
| 101 | // have been announced and never existed. Drop the entry rather than getdata | ||
| 102 | // forever; a re-announcement recreates it. | ||
| 103 | static const int BLOCK_FETCH_GIVEUP_SECS = 10 * 60; | ||
| 104 | |||
| 105 | // Failover firing at all is worth saying out loud: it means peers are | ||
| 106 | // announcing blocks they then do not serve, which is the pathology of #33 and | ||
| 107 | // the thing nobody could otherwise see. Naming the peer on every re-request is | ||
| 108 | // a different matter. A peer can drive that line as often as it likes by | ||
| 109 | // announcing hashes it will not serve, and what it prints is a peer address, | ||
| 110 | // which is the one thing the .btf transport otherwise takes trouble not to | ||
| 111 | // spread around. So the per-peer detail sits behind the net category and the | ||
| 112 | // unconditional line is a count over a window no peer can shorten: the first | ||
| 113 | // failover after a quiet spell prints at once, because the change from "blocks | ||
| 114 | // arrive" to "blocks are announced and not served" is the event worth seeing, | ||
| 115 | // and everything after it is summarised once a minute. | ||
| 116 | static const int BLOCK_FETCH_REPORT_SECS = 60; | ||
| 117 | static int64 nBlockFetchWindowStart = 0; | ||
| 118 | static int nBlockFetchFailovers = 0; | ||
| 119 | |||
| 120 | // How stale our own best block may be before we stop calling this the tip. | ||
| 121 | // Blocks target two minutes, so this is thirty intervals: far longer than any | ||
| 122 | // stall worth failing over from -- the one in #33 ran sixteen minutes -- and | ||
| 123 | // far shorter than catching up, which starts hours or days back. | ||
| 124 | static const int BLOCK_FETCH_TIP_AGE_SECS = 60 * 60; | ||
| 125 | |||
| 126 | // Whether this node is tracking the tip rather than still catching up. | ||
| 127 | // | ||
| 128 | // Measured off the age of our own best block, not off any height a peer told | ||
| 129 | // us. nStartingHeight is optional in the version message and every node | ||
| 130 | // released so far sends the short form, so it is -1 for essentially every | ||
| 131 | // peer; and where it is filled in later it is filled in from the height of a | ||
| 132 | // block that peer served us, which during catch-up tracks our own height and | ||
| 133 | // would report "at the tip" for the whole download. Block timestamps are the | ||
| 134 | // one clock here that peers cannot move: CheckBlock refuses anything more than | ||
| 135 | // two hours ahead and AcceptBlock refuses anything at or before the previous | ||
| 136 | // median, so the only way to make this read "at the tip" falsely is to mine, | ||
| 137 | // and all that buys is the 15s spacing this code had unconditionally anyway. | ||
| 138 | bool IsBlockFetchNearTip() | ||
| 139 | { | ||
| 140 | return pindexBest && (int64)pindexBest->nTime > GetTime() - BLOCK_FETCH_TIP_AGE_SECS; | ||
| 141 | } | ||
| 142 | |||
| 143 | // Drop one entry so a hash announced by addrNew can be tracked. | ||
| 144 | // | ||
| 145 | // Refusing the insertion instead was a remote off-switch for the whole | ||
| 146 | // feature. An inv carrying eight hashes that never existed filled every slot | ||
| 147 | // -- nothing between inv and here can tell those from real blocks -- and no | ||
| 148 | // genuinely new block was tracked again until the give-up timer expired ten | ||
| 149 | // minutes later, re-armable for one message per ten minutes from a single | ||
| 150 | // connection. | ||
| 151 | // | ||
| 152 | // So evict instead, by occupancy: a peer may only take a slot from a peer | ||
| 153 | // holding strictly more slots than itself, and otherwise recycles one of its | ||
| 154 | // own. That is what keeps eviction from becoming the same attack in a new | ||
| 155 | // shape. A peer that has filled the table is by definition the heaviest | ||
| 156 | // holder, so its own entries are the only ones it can displace, while a peer | ||
| 157 | // announcing its first block holds nothing and therefore always evicts from | ||
| 158 | // the heaviest -- a genuine announcement is never refused a slot, whatever the | ||
| 159 | // attacker holds or however many connections it holds it from. The one case | ||
| 160 | // that costs a real fetch is eight distinct peers holding one entry each, | ||
| 161 | // where a ninth takes the oldest; that is a busy healthy node, not an attack, | ||
| 162 | // and losing the oldest of eight beats refusing the ninth. | ||
| 163 | static void MakeRoomInBlockFetch(const CAddress& addrNew) | ||
| 164 | { | ||
| 165 | if (mapBlockFetch.empty()) | ||
| 166 | return; | ||
| 167 | |||
| 168 | map<CAddress, int> mapHeld; | ||
| 169 | for (map<uint256, CBlockFetch>::iterator mi = mapBlockFetch.begin(); mi != mapBlockFetch.end(); ++mi) | ||
| 170 | mapHeld[(*mi).second.addrAnnounced]++; | ||
| 171 | |||
| 172 | int nMine = mapHeld.count(addrNew) ? mapHeld[addrNew] : 0; | ||
| 173 | |||
| 174 | int nMax = 0; | ||
| 175 | CAddress addrVictim; | ||
| 176 | for (map<CAddress, int>::iterator mi = mapHeld.begin(); mi != mapHeld.end(); ++mi) | ||
| 177 | if ((*mi).second > nMax) | ||
| 178 | { | ||
| 179 | nMax = (*mi).second; | ||
| 180 | addrVictim = (*mi).first; | ||
| 181 | } | ||
| 182 | |||
| 183 | // Nobody is holding more than this peer, so it recycles its own oldest | ||
| 184 | // rather than taking a slot off an equal. | ||
| 185 | if (nMax <= nMine) | ||
| 186 | addrVictim = addrNew; | ||
| 187 | |||
| 188 | map<uint256, CBlockFetch>::iterator miVictim = mapBlockFetch.end(); | ||
| 189 | for (map<uint256, CBlockFetch>::iterator mi = mapBlockFetch.begin(); mi != mapBlockFetch.end(); ++mi) | ||
| 190 | if ((*mi).second.addrAnnounced == addrVictim && | ||
| 191 | (miVictim == mapBlockFetch.end() || | ||
| 192 | (*mi).second.nTimeFirstAsked < (*miVictim).second.nTimeFirstAsked)) | ||
| 193 | miVictim = mi; | ||
| 194 | |||
| 195 | if (miVictim != mapBlockFetch.end()) | ||
| 196 | mapBlockFetch.erase(miVictim); | ||
| 197 | } | ||
| 198 | |||
| 67 | map<uint256, CDataStream*> mapOrphanTransactions; | 199 | map<uint256, CDataStream*> mapOrphanTransactions; |
| 68 | multimap<uint256, CDataStream*> mapOrphanTransactionsByPrev; | 200 | multimap<uint256, CDataStream*> mapOrphanTransactionsByPrev; |
| 69 | 201 | ||
| @@ -1712,7 +1844,7 @@ void CWalletTx::RelayWalletTransaction(CTxDB& txdb) | |||
| 1712 | uint256 hash = GetHash(); | 1844 | uint256 hash = GetHash(); |
| 1713 | if (!txdb.ContainsTx(hash)) | 1845 | if (!txdb.ContainsTx(hash)) |
| 1714 | { | 1846 | { |
| 1715 | if (LogAcceptsCategory("net")) printf("Relaying wtx %s\n", hash.ToString().substr(0,6).c_str()); | 1847 | if (LogAcceptsCategory("relay")) printf("Relaying wtx %s\n", hash.ToString().substr(0,6).c_str()); |
| 1716 | RelayMessage(CInv(MSG_TX, hash), (CTransaction)*this); | 1848 | RelayMessage(CInv(MSG_TX, hash), (CTransaction)*this); |
| 1717 | } | 1849 | } |
| 1718 | } | 1850 | } |
| @@ -2678,7 +2810,18 @@ bool LoadBlockIndex(bool fAllowNew) | |||
| 2678 | // CTxOut(nValue=50.00000000, scriptPubKey=0x5F1DF16B2B704C8A578D0B) | 2810 | // CTxOut(nValue=50.00000000, scriptPubKey=0x5F1DF16B2B704C8A578D0B) |
| 2679 | // vMerkleTree: 4a5e1e | 2811 | // vMerkleTree: 4a5e1e |
| 2680 | 2812 | ||
| 2681 | // Bitflash genesis block -- own header (fair launch, 2026 stable relaunch) | 2813 | // Bitflash genesis block -- own header (fair launch) |
| 2814 | // | ||
| 2815 | // Do not change pszTimestamp, the scriptPubKey, nTime or nNonce. They | ||
| 2816 | // are the inputs to the genesis hash, and the genesis hash is | ||
| 2817 | // consensus. Changing one on its own trips the assert below, which is | ||
| 2818 | // loud and reverts cleanly; changing one and regenerating | ||
| 2819 | // GENESIS_NONCE and hashGenesisBlock to match -- which is exactly what | ||
| 2820 | // the re-mining branch below prints out and invites -- gives a node | ||
| 2821 | // that starts without complaint, builds its own chain from height 0, | ||
| 2822 | // and rejects every real peer as being on a different chain. That one | ||
| 2823 | // fails silently, and the damage scales with how many people run the | ||
| 2824 | // "fixed" build. | ||
| 2682 | char* pszTimestamp = "Bitflash 24/Jul/2026 Fair launch: one CPU one vote, no premine"; | 2825 | char* pszTimestamp = "Bitflash 24/Jul/2026 Fair launch: one CPU one vote, no premine"; |
| 2683 | CTransaction txNew; | 2826 | CTransaction txNew; |
| 2684 | txNew.vin.resize(1); | 2827 | txNew.vin.resize(1); |
| @@ -2691,7 +2834,14 @@ bool LoadBlockIndex(bool fAllowNew) | |||
| 2691 | block.hashPrevBlock = 0; | 2834 | block.hashPrevBlock = 0; |
| 2692 | block.hashMerkleRoot = block.BuildMerkleTree(); | 2835 | block.hashMerkleRoot = block.BuildMerkleTree(); |
| 2693 | block.nVersion = 1; | 2836 | block.nVersion = 1; |
| 2694 | block.nTime = 1753315200; // 2026-07-24 00:00:00 UTC (stable relaunch) | 2837 | // 1753315200 is 2025-07-24T00:00:00Z. The headline in pszTimestamp |
| 2838 | // above reads 2026 and does not match it. This is a known discrepancy | ||
| 2839 | // and not a typo in the constant: the value is only consensus-critical | ||
| 2840 | // as an input to the genesis hash, the block hashes to | ||
| 2841 | // hashGenesisBlock with it, and every node on the network agrees. The | ||
| 2842 | // mismatch is in the launched chain and cannot be corrected -- see the | ||
| 2843 | // warning above before deciding otherwise. | ||
| 2844 | block.nTime = 1753315200; | ||
| 2695 | block.nBits = 0x1f0fffff; // = bnProofOfWorkLimit (Bitflash RandomX floor) | 2845 | block.nBits = 0x1f0fffff; // = bnProofOfWorkLimit (Bitflash RandomX floor) |
| 2696 | block.nNonce = GENESIS_NONCE; | 2846 | block.nNonce = GENESIS_NONCE; |
| 2697 | 2847 | ||
| @@ -2718,6 +2868,11 @@ bool LoadBlockIndex(bool fAllowNew) | |||
| 2718 | printf("powhash = %s\n", block.GetPoWHash().ToString().c_str()); | 2868 | printf("powhash = %s\n", block.GetPoWHash().ToString().c_str()); |
| 2719 | printf("hash = %s\n", block.GetHash().ToString().c_str()); | 2869 | printf("hash = %s\n", block.GetHash().ToString().c_str()); |
| 2720 | printf("merkle = %s\n", block.hashMerkleRoot.ToString().c_str()); | 2870 | printf("merkle = %s\n", block.hashMerkleRoot.ToString().c_str()); |
| 2871 | printf("----------------------------------------\n"); | ||
| 2872 | printf("These constants bring up a NEW chain. Do not paste them\n"); | ||
| 2873 | printf("into a build for this network to make an edited nTime or\n"); | ||
| 2874 | printf("pszTimestamp fit -- a node whose genesis differs starts\n"); | ||
| 2875 | printf("cleanly on a chain of its own and rejects every real peer.\n"); | ||
| 2721 | printf("========================================\n"); | 2876 | printf("========================================\n"); |
| 2722 | } | 2877 | } |
| 2723 | 2878 | ||
| @@ -3263,15 +3418,61 @@ bool ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv) | |||
| 3263 | vRecv >> *pblock; | 3418 | vRecv >> *pblock; |
| 3264 | 3419 | ||
| 3265 | //// debug print | 3420 | //// debug print |
| 3266 | if (LogAcceptsCategory("net")) { printf("received block:\n"); pblock->print(); } | 3421 | if (LogAcceptsCategory("relay")) { printf("received block:\n"); pblock->print(); } |
| 3267 | 3422 | ||
| 3268 | CInv inv(MSG_BLOCK, pblock->GetHash()); | 3423 | CInv inv(MSG_BLOCK, pblock->GetHash()); |
| 3269 | pfrom->AddInventoryKnown(inv); | 3424 | pfrom->AddInventoryKnown(inv); |
| 3270 | 3425 | ||
| 3426 | // GetHash() covers the 80-byte header and nothing else, so the hash | ||
| 3427 | // coming out right does not make this the block we asked for. Every | ||
| 3428 | // peer that saw X announced holds X's header, and can answer our | ||
| 3429 | // getdata with that header bolted onto a transaction list of its own | ||
| 3430 | // invention -- the reply still hashes to X. hashMerkleRoot is the only | ||
| 3431 | // thing binding the header to the body, so check it here, before the | ||
| 3432 | // mapBlockFetch entry is touched and before CheckBlock spends a | ||
| 3433 | // RandomX hash on a body already known to be forged. | ||
| 3434 | // | ||
| 3435 | // There is no honest way to arrive here. Peer traffic rides the .btf | ||
| 3436 | // channel, which is XChaCha20-Poly1305, so a body that arrives at all | ||
| 3437 | // arrived intact: a mismatch is the peer's own construction, not line | ||
| 3438 | // noise. Drop the peer and leave the fetch outstanding so the failover | ||
| 3439 | // sweep asks somebody else for the real X, rather than recording X as | ||
| 3440 | // delivered on the strength of a header anyone could copy. | ||
| 3441 | if (pblock->hashMerkleRoot != pblock->BuildMerkleTree()) | ||
| 3442 | { | ||
| 3443 | if (LogAcceptsCategory("net")) | ||
| 3444 | printf("peer %s served a forged body for %s\n", | ||
| 3445 | pfrom->addr.ToString().c_str(), inv.ToString().c_str()); | ||
| 3446 | // One line per connection: ProcessMessages keeps draining the | ||
| 3447 | // receive buffer after fDisconnect is set, so a peer that packs | ||
| 3448 | // many forged bodies into one buffer must not get one log line | ||
| 3449 | // for each of them. | ||
| 3450 | if (!pfrom->fDisconnect) | ||
| 3451 | printf("block fetch: a peer answered the request for %s with a body that is not " | ||
| 3452 | "that block -- dropping it\n", inv.hash.ToString().substr(0,14).c_str()); | ||
| 3453 | pfrom->fDisconnect = true; | ||
| 3454 | return error("ProcessMessage() : forged block body for %s", | ||
| 3455 | inv.hash.ToString().substr(0,14).c_str()); | ||
| 3456 | } | ||
| 3457 | |||
| 3271 | if (ProcessBlock(pfrom, pblock.release())) | 3458 | if (ProcessBlock(pfrom, pblock.release())) |
| 3272 | { | 3459 | { |
| 3273 | mapAlreadyAskedFor.erase(inv); | 3460 | mapAlreadyAskedFor.erase(inv); |
| 3274 | 3461 | ||
| 3462 | // The body arrived and validated, so the fetch really is over: | ||
| 3463 | // the block is now in mapBlockIndex, or parked in mapOrphanBlocks, | ||
| 3464 | // and either way AlreadyHave answers for it from here on. | ||
| 3465 | // | ||
| 3466 | // This has to stay inside the success branch, next to the erase | ||
| 3467 | // above. When validation rejects a body nothing is stored, | ||
| 3468 | // AlreadyHave stays false, and the mapAskFor entry was already | ||
| 3469 | // consumed when the getdata went out -- so erasing the tracking | ||
| 3470 | // here would leave the block requested from nobody at all until | ||
| 3471 | // some peer happened to re-announce it. That is exactly the stall | ||
| 3472 | // of #33, and erasing before ProcessBlock made it reachable on | ||
| 3473 | // demand. | ||
| 3474 | mapBlockFetch.erase(inv.hash); | ||
| 3475 | |||
| 3275 | // A peer that just handed us a block is demonstrably at least at | 3476 | // A peer that just handed us a block is demonstrably at least at |
| 3276 | // that block's height. Without this, nStartingHeight is a snapshot | 3477 | // that block's height. Without this, nStartingHeight is a snapshot |
| 3277 | // taken once during the version handshake and never touched again, | 3478 | // taken once during the version handshake and never touched again, |
| @@ -3396,12 +3597,119 @@ bool SendMessages(CNode* pto) | |||
| 3396 | const CInv& inv = (*pto->mapAskFor.begin()).second; | 3597 | const CInv& inv = (*pto->mapAskFor.begin()).second; |
| 3397 | if (LogAcceptsCategory("net")) printf("sending getdata: %s\n", inv.ToString().c_str()); | 3598 | if (LogAcceptsCategory("net")) printf("sending getdata: %s\n", inv.ToString().c_str()); |
| 3398 | if (!AlreadyHave(txdb, inv)) | 3599 | if (!AlreadyHave(txdb, inv)) |
| 3600 | { | ||
| 3399 | vAskFor.push_back(inv); | 3601 | vAskFor.push_back(inv); |
| 3602 | // Blocks get their delivery tracked so the failover pass | ||
| 3603 | // below can chase the ones that go quiet. | ||
| 3604 | if (inv.type == MSG_BLOCK) | ||
| 3605 | { | ||
| 3606 | // Full, and this is a hash we are not already tracking: | ||
| 3607 | // make room rather than drop it on the floor, or one peer | ||
| 3608 | // announcing eight hashes turns failover off for everyone. | ||
| 3609 | if (!mapBlockFetch.count(inv.hash) && | ||
| 3610 | mapBlockFetch.size() >= BLOCK_FETCH_TRACK_MAX) | ||
| 3611 | MakeRoomInBlockFetch(pto->addr); | ||
| 3612 | |||
| 3613 | if (mapBlockFetch.count(inv.hash) || | ||
| 3614 | mapBlockFetch.size() < BLOCK_FETCH_TRACK_MAX) | ||
| 3615 | { | ||
| 3616 | CBlockFetch& fetch = mapBlockFetch[inv.hash]; | ||
| 3617 | if (fetch.nTimeFirstAsked == 0) | ||
| 3618 | { | ||
| 3619 | fetch.nTimeFirstAsked = GetTime(); | ||
| 3620 | // Who is answerable for this hash existing. Set | ||
| 3621 | // once, on creation: the failover sweep asks other | ||
| 3622 | // peers later, and none of them chose to announce | ||
| 3623 | // it, so none of them should be charged for it. | ||
| 3624 | fetch.addrAnnounced = pto->addr; | ||
| 3625 | } | ||
| 3626 | fetch.nTimeAsked = GetTime(); | ||
| 3627 | fetch.setAsked.insert(pto->addr); | ||
| 3628 | } | ||
| 3629 | } | ||
| 3630 | } | ||
| 3400 | pto->mapAskFor.erase(pto->mapAskFor.begin()); | 3631 | pto->mapAskFor.erase(pto->mapAskFor.begin()); |
| 3401 | } | 3632 | } |
| 3402 | if (!vAskFor.empty()) | 3633 | if (!vAskFor.empty()) |
| 3403 | pto->PushMessage("getdata", vAskFor); | 3634 | pto->PushMessage("getdata", vAskFor); |
| 3404 | 3635 | ||
| 3636 | |||
| 3637 | // | ||
| 3638 | // Message: getdata (block fetch failover) | ||
| 3639 | // | ||
| 3640 | // A requested block that has not arrived in BLOCK_FETCH_RETRY_SECS is | ||
| 3641 | // not still in transit -- a body is at most 1 MB and somebody | ||
| 3642 | // demonstrably has it -- so ask somebody else instead of waiting on | ||
| 3643 | // whoever was asked first (#33). Each peer the message handler visits | ||
| 3644 | // takes at most one turn per block per round; once every connected | ||
| 3645 | // peer has had its turn and a further interval passes with nobody | ||
| 3646 | // new to ask, the round restarts. A peer that declared itself a | ||
| 3647 | // client cannot serve block bodies and is no use as a target. | ||
| 3648 | if (!pto->fClient) | ||
| 3649 | { | ||
| 3650 | vector<CInv> vFailover; | ||
| 3651 | int64 nNowSecs = GetTime(); | ||
| 3652 | for (map<uint256, CBlockFetch>::iterator mi = mapBlockFetch.begin(); mi != mapBlockFetch.end();) | ||
| 3653 | { | ||
| 3654 | CBlockFetch& fetch = (*mi).second; | ||
| 3655 | CInv inv(MSG_BLOCK, (*mi).first); | ||
| 3656 | if (AlreadyHave(txdb, inv)) | ||
| 3657 | { | ||
| 3658 | // Arrived by some other road -- our own miner, an orphan | ||
| 3659 | // parked in mapOrphanBlocks. Nothing left to chase. | ||
| 3660 | mapBlockFetch.erase(mi++); | ||
| 3661 | continue; | ||
| 3662 | } | ||
| 3663 | if (nNowSecs - fetch.nTimeFirstAsked > BLOCK_FETCH_GIVEUP_SECS) | ||
| 3664 | { | ||
| 3665 | printf("block fetch: giving up on %s -- no peer served it in %d s\n", | ||
| 3666 | inv.ToString().c_str(), (int)(nNowSecs - fetch.nTimeFirstAsked)); | ||
| 3667 | mapBlockFetch.erase(mi++); | ||
| 3668 | continue; | ||
| 3669 | } | ||
| 3670 | if (nNowSecs - fetch.nTimeAsked >= BLOCK_FETCH_RETRY_SECS) | ||
| 3671 | { | ||
| 3672 | // The handler loop visits every peer within ~100ms, so a | ||
| 3673 | // request stale by two full intervals means nobody outside | ||
| 3674 | // setAsked was there to ask. Start the round over. | ||
| 3675 | if (nNowSecs - fetch.nTimeAsked >= 2 * BLOCK_FETCH_RETRY_SECS) | ||
| 3676 | fetch.setAsked.clear(); | ||
| 3677 | if (!fetch.setAsked.count(pto->addr)) | ||
| 3678 | { | ||
| 3679 | // Which block, how long, and which peer we are trying | ||
| 3680 | // next. Behind the category because it names a peer | ||
| 3681 | // and a peer decides how often it is written. | ||
| 3682 | if (LogAcceptsCategory("net")) | ||
| 3683 | printf("block fetch failover: %s unanswered for %d s, re-requesting from %s\n", | ||
| 3684 | inv.ToString().c_str(), (int)(nNowSecs - fetch.nTimeAsked), | ||
| 3685 | pto->addr.ToString().c_str()); | ||
| 3686 | |||
| 3687 | // The unconditional half: no addresses, and at most | ||
| 3688 | // one line per BLOCK_FETCH_REPORT_SECS however hard a | ||
| 3689 | // peer tries. See the counters for the reasoning. | ||
| 3690 | nBlockFetchFailovers++; | ||
| 3691 | if (nNowSecs - nBlockFetchWindowStart >= BLOCK_FETCH_REPORT_SECS) | ||
| 3692 | { | ||
| 3693 | printf("block fetch: %d block request%s went unanswered and %s been " | ||
| 3694 | "re-asked of other peers (%d tracked)\n", | ||
| 3695 | nBlockFetchFailovers, nBlockFetchFailovers == 1 ? "" : "s", | ||
| 3696 | nBlockFetchFailovers == 1 ? "has" : "have", | ||
| 3697 | (int)mapBlockFetch.size()); | ||
| 3698 | nBlockFetchWindowStart = nNowSecs; | ||
| 3699 | nBlockFetchFailovers = 0; | ||
| 3700 | } | ||
| 3701 | |||
| 3702 | vFailover.push_back(inv); | ||
| 3703 | fetch.nTimeAsked = nNowSecs; | ||
| 3704 | fetch.setAsked.insert(pto->addr); | ||
| 3705 | } | ||
| 3706 | } | ||
| 3707 | ++mi; | ||
| 3708 | } | ||
| 3709 | if (!vFailover.empty()) | ||
| 3710 | pto->PushMessage("getdata", vFailover); | ||
| 3711 | } | ||
| 3712 | |||
| 3405 | } | 3713 | } |
| 3406 | return true; | 3714 | return true; |
| 3407 | } | 3715 | } |
| @@ -3662,6 +3970,14 @@ static void ParticipantHashWorker(ParticipantJobShared* sh, int idx, int nWorker | |||
| 3662 | RandomXDestroyMinerVM(vm); | 3970 | RandomXDestroyMinerVM(vm); |
| 3663 | } | 3971 | } |
| 3664 | 3972 | ||
| 3973 | // Run one participant session: resolve the pool, open the tunnel, subscribe, | ||
| 3974 | // hash, submit shares. Returns true only if the pool actually handed out work | ||
| 3975 | // -- at least one well-formed mining.notify arrived. Everything else is false, | ||
| 3976 | // including a tunnel that opened and was dropped before any job. | ||
| 3977 | // | ||
| 3978 | // The caller's reconnect backoff keys off this return value, so any path added | ||
| 3979 | // here that leaves the session without work MUST return false. "The session | ||
| 3980 | // ended tidily" is not the question being asked. | ||
| 3665 | static bool PoolParticipantMiner() | 3981 | static bool PoolParticipantMiner() |
| 3666 | { | 3982 | { |
| 3667 | // ------------------------------------------------------------------ | 3983 | // ------------------------------------------------------------------ |
| @@ -3739,6 +4055,33 @@ static bool PoolParticipantMiner() | |||
| 3739 | } | 4055 | } |
| 3740 | LogPrint("worker", "[worker] pool resolved to meeting node %s\n", meetingHostPort.c_str()); | 4056 | LogPrint("worker", "[worker] pool resolved to meeting node %s\n", meetingHostPort.c_str()); |
| 3741 | 4057 | ||
| 4058 | // The descriptor names ONE meeting node, but the pool parks a | ||
| 4059 | // registration at every relay it knows (one accept thread per relay, | ||
| 4060 | // rpc.cpp:AcceptOneFn), so any seed relay can pair us. Insisting on the | ||
| 4061 | // advertised entry forever turns one bad path into a miner that idles | ||
| 4062 | // indefinitely while a working path exists (issue #17); after a few | ||
| 4063 | // consecutive tunnel failures, rotate the seed relays into the attempts | ||
| 4064 | // too. Only ONE participant session runs (StartMinerThreads), so these | ||
| 4065 | // statics are single-threaded. | ||
| 4066 | static const int TUNNEL_FAILOVER_AFTER = 3; | ||
| 4067 | static int nTunnelFails = 0; // consecutive tunnel failures, this pool | ||
| 4068 | static size_t iFailoverRelay = 0; // rotation cursor over vBtfMeetingRelays | ||
| 4069 | static std::string strFailPool; // pool the counters belong to | ||
| 4070 | if (strFailPool != strParticipantPool) { | ||
| 4071 | strFailPool = strParticipantPool; | ||
| 4072 | nTunnelFails = 0; | ||
| 4073 | iFailoverRelay = 0; | ||
| 4074 | } | ||
| 4075 | if (nTunnelFails >= TUNNEL_FAILOVER_AFTER && !vBtfMeetingRelays.empty()) { | ||
| 4076 | std::string alt = vBtfMeetingRelays[iFailoverRelay++ % vBtfMeetingRelays.size()]; | ||
| 4077 | if (alt != meetingHostPort) { | ||
| 4078 | LogPrint("worker", "[worker] advertised meeting node %s failed %d" | ||
| 4079 | " times in a row -- trying seed relay %s instead\n", | ||
| 4080 | meetingHostPort.c_str(), nTunnelFails, alt.c_str()); | ||
| 4081 | meetingHostPort = alt; | ||
| 4082 | } | ||
| 4083 | } | ||
| 4084 | |||
| 3742 | size_t colon = meetingHostPort.rfind(':'); | 4085 | size_t colon = meetingHostPort.rfind(':'); |
| 3743 | if (colon == std::string::npos) { | 4086 | if (colon == std::string::npos) { |
| 3744 | LogPrint("worker", "[worker] bad meeting node format '%s'\n", meetingHostPort.c_str()); | 4087 | LogPrint("worker", "[worker] bad meeting node format '%s'\n", meetingHostPort.c_str()); |
| @@ -3758,15 +4101,18 @@ static bool PoolParticipantMiner() | |||
| 3758 | // Step 2b: open encrypted tunnel to pool | 4101 | // Step 2b: open encrypted tunnel to pool |
| 3759 | // ------------------------------------------------------------------ | 4102 | // ------------------------------------------------------------------ |
| 3760 | SetParticipantMiningStatus("opening tunnel"); | 4103 | SetParticipantMiningStatus("opening tunnel"); |
| 4104 | btf::TunnelFail tunnelFail = btf::TUNNEL_FAIL_NONE; | ||
| 3761 | s = btf::BtfClientTunnel(host.c_str(), (unsigned short)port, | 4105 | s = btf::BtfClientTunnel(host.c_str(), (unsigned short)port, |
| 3762 | target_pubkey, service_enc_pub); | 4106 | target_pubkey, service_enc_pub, &tunnelFail); |
| 3763 | if (s == INVALID_SOCKET) { | 4107 | if (s == INVALID_SOCKET) { |
| 3764 | LogPrint("worker", "[worker] tunnel connect FAILED via %s" | 4108 | nTunnelFails++; |
| 3765 | " (relay unreachable or pool not listening)\n", | 4109 | LogPrint("worker", "[worker] tunnel connect FAILED via %s: %s\n", |
| 3766 | meetingHostPort.c_str()); | 4110 | meetingHostPort.c_str(), btf::TunnelFailText(tunnelFail)); |
| 3767 | SetParticipantMiningStatus("tunnel connect failed"); | 4111 | SetParticipantMiningStatus(std::string("tunnel connect failed: ") |
| 4112 | + btf::TunnelFailText(tunnelFail)); | ||
| 3768 | return false; | 4113 | return false; |
| 3769 | } | 4114 | } |
| 4115 | nTunnelFails = 0; | ||
| 3770 | LogPrint("worker", "[worker] tunnel open via %s\n", meetingHostPort.c_str()); | 4116 | LogPrint("worker", "[worker] tunnel open via %s\n", meetingHostPort.c_str()); |
| 3771 | SetParticipantMiningStatus("tunnel open"); | 4117 | SetParticipantMiningStatus("tunnel open"); |
| 3772 | } | 4118 | } |
| @@ -3899,9 +4245,32 @@ connected: | |||
| 3899 | std::vector<ParticipantShareHit> shareHits; | 4245 | std::vector<ParticipantShareHit> shareHits; |
| 3900 | std::mutex shareHitsMtx; | 4246 | std::mutex shareHitsMtx; |
| 3901 | std::vector<std::thread> hashThreads; | 4247 | std::vector<std::thread> hashThreads; |
| 3902 | for (int i = 0; i < nWorkers; i++) | 4248 | try |
| 3903 | hashThreads.emplace_back(ParticipantHashWorker, &jobShared, i, nWorkers, | 4249 | { |
| 3904 | &shareHits, &shareHitsMtx); | 4250 | for (int i = 0; i < nWorkers; i++) |
| 4251 | hashThreads.emplace_back(ParticipantHashWorker, &jobShared, i, nWorkers, | ||
| 4252 | &shareHits, &shareHitsMtx); | ||
| 4253 | } | ||
| 4254 | catch (const std::system_error& e) | ||
| 4255 | { | ||
| 4256 | // A refused pthread_create used to reach std::terminate here and | ||
| 4257 | // kill the worker mid-session -- observed twice on an otherwise | ||
| 4258 | // healthy participant. Stop the workers that did start the same way | ||
| 4259 | // the disconnect path below does, drop this pool connection, and let | ||
| 4260 | // the caller's reconnect loop try again once the pressure clears. | ||
| 4261 | LogPrint("worker", "[worker] cannot spawn hash threads (%s)" | ||
| 4262 | " -- dropping pool connection\n", e.what()); | ||
| 4263 | SetParticipantMiningStatus("hash thread spawn failed"); | ||
| 4264 | { | ||
| 4265 | std::lock_guard<std::mutex> lk(jobShared.mtx); | ||
| 4266 | jobShared.stop = true; | ||
| 4267 | jobShared.haveJob = false; | ||
| 4268 | } | ||
| 4269 | for (std::thread& t : hashThreads) | ||
| 4270 | t.join(); | ||
| 4271 | closesocket(s); | ||
| 4272 | return false; | ||
| 4273 | } | ||
| 3905 | LogPrint("worker", "[worker] spawned %d hash threads on shared RandomX dataset\n", | 4274 | LogPrint("worker", "[worker] spawned %d hash threads on shared RandomX dataset\n", |
| 3906 | nWorkers); | 4275 | nWorkers); |
| 3907 | const uint64 sessionStartHashes = gParticipantHashes.load(); | 4276 | const uint64 sessionStartHashes = gParticipantHashes.load(); |
| @@ -3912,8 +4281,17 @@ connected: | |||
| 3912 | std::string jobId; | 4281 | std::string jobId; |
| 3913 | unsigned char header[80] = {}; | 4282 | unsigned char header[80] = {}; |
| 3914 | uint256 target; | 4283 | uint256 target; |
| 4284 | // Cached answer to "which block is this job built on", for the | ||
| 4285 | // mining.notify handler below -- see the comment there. Session-local, so | ||
| 4286 | // a reconnect re-resolves rather than trusting an answer obtained before | ||
| 4287 | // a possible change of pool. | ||
| 4288 | uint256 hashPrevResolved; // prevhash the cached answer describes | ||
| 4289 | bool fPrevResolved = false; // whether that answer exists yet | ||
| 4290 | int nPrevHeight = -1; // its height, or -1 == unknown to us | ||
| 4291 | int nBestHeightResolved = -1; // nBestHeight when we last resolved | ||
| 3915 | double currentDifficulty = 1.0; // updated by mining.set_difficulty from pool | 4292 | double currentDifficulty = 1.0; // updated by mining.set_difficulty from pool |
| 3916 | bool haveJob = false; | 4293 | bool haveJob = false; |
| 4294 | bool gotAnyJob = false; // any job at all this session -- the return value | ||
| 3917 | bool gotSubscribeAck = false; | 4295 | bool gotSubscribeAck = false; |
| 3918 | bool gotAuthorizeAck = false; | 4296 | bool gotAuthorizeAck = false; |
| 3919 | int64 authWaitStart = 0; | 4297 | int64 authWaitStart = 0; |
| @@ -4030,8 +4408,9 @@ connected: | |||
| 4030 | jobId = newJobId; | 4408 | jobId = newJobId; |
| 4031 | memcpy(header, hdrBytes.data(), 80); | 4409 | memcpy(header, hdrBytes.data(), 80); |
| 4032 | memcpy(&target, tgtBytes.data(), 32); | 4410 | memcpy(&target, tgtBytes.data(), 32); |
| 4033 | haveJob = true; | 4411 | haveJob = true; |
| 4034 | nNonce = 1; | 4412 | gotAnyJob = true; |
| 4413 | nNonce = 1; | ||
| 4035 | { | 4414 | { |
| 4036 | std::lock_guard<std::mutex> lk(jobShared.mtx); | 4415 | std::lock_guard<std::mutex> lk(jobShared.mtx); |
| 4037 | memcpy(jobShared.header, header, 80); | 4416 | memcpy(jobShared.header, header, 80); |
| @@ -4040,8 +4419,64 @@ connected: | |||
| 4040 | jobShared.jobSeq++; | 4419 | jobShared.jobSeq++; |
| 4041 | jobShared.haveJob = true; | 4420 | jobShared.haveJob = true; |
| 4042 | } | 4421 | } |
| 4043 | LogPrint("worker", "[pool->worker] new job %s received\n", | 4422 | // Log the chain position the pool is |
| 4044 | jobId.c_str()); | 4423 | // building on, so a stale or private |
| 4424 | // fork is auditable from worker logs. | ||
| 4425 | // The prevhash comes from the header we | ||
| 4426 | // actually hash (== p[2] of the notify); | ||
| 4427 | // a brief cs_main lookup is safe here -- | ||
| 4428 | // this thread holds no other lock. | ||
| 4429 | // | ||
| 4430 | // Resolving it is the expensive half, and | ||
| 4431 | // this is the socket-reading thread: block | ||
| 4432 | // validation can hold cs_main for a long | ||
| 4433 | // time, and every moment spent waiting on | ||
| 4434 | // it here is a moment set_difficulty and | ||
| 4435 | // share responses are not being handled. | ||
| 4436 | // Most notifies in a round are a new job | ||
| 4437 | // on the SAME tip, so the answer is cached | ||
| 4438 | // and re-resolved only when it could come | ||
| 4439 | // out differently: a prevhash we have not | ||
| 4440 | // resolved, or one we could NOT resolve | ||
| 4441 | // last time while the chain has since | ||
| 4442 | // moved (unknown -> known). A block's | ||
| 4443 | // height is fixed once mapBlockIndex knows | ||
| 4444 | // it, so a cached "known" never goes | ||
| 4445 | // stale. nBestHeight is read unlocked on | ||
| 4446 | // purpose -- it only decides whether to | ||
| 4447 | // repeat a lookup, never what gets | ||
| 4448 | // printed, so a stale read costs at most | ||
| 4449 | // one deferred or one extra lookup. | ||
| 4450 | // The line still prints in full for every | ||
| 4451 | // job, cached or not. | ||
| 4452 | uint256 hashPrev; | ||
| 4453 | memcpy(&hashPrev, header + 4, 32); | ||
| 4454 | if (LogAcceptsCategory("worker")) | ||
| 4455 | { | ||
| 4456 | int nBestHeightNow = nBestHeight; | ||
| 4457 | if (!fPrevResolved | ||
| 4458 | || hashPrev != hashPrevResolved | ||
| 4459 | || (nPrevHeight < 0 && nBestHeightNow != nBestHeightResolved)) | ||
| 4460 | { | ||
| 4461 | nPrevHeight = -1; | ||
| 4462 | CRITICAL_BLOCK(cs_main) | ||
| 4463 | { | ||
| 4464 | map<uint256, CBlockIndex*>::iterator mi = mapBlockIndex.find(hashPrev); | ||
| 4465 | if (mi != mapBlockIndex.end()) | ||
| 4466 | nPrevHeight = (*mi).second->nHeight; | ||
| 4467 | } | ||
| 4468 | hashPrevResolved = hashPrev; | ||
| 4469 | nBestHeightResolved = nBestHeightNow; | ||
| 4470 | fPrevResolved = true; | ||
| 4471 | } | ||
| 4472 | if (nPrevHeight >= 0) | ||
| 4473 | LogPrint("worker", "[pool->worker] new job %s received, prevhash %s (known, job height %d)\n", | ||
| 4474 | jobId.c_str(), hashPrev.GetHex().c_str(), | ||
| 4475 | nPrevHeight + 1); | ||
| 4476 | else | ||
| 4477 | LogPrint("worker", "[pool->worker] new job %s received, prevhash %s (unknown to our chain)\n", | ||
| 4478 | jobId.c_str(), hashPrev.GetHex().c_str()); | ||
| 4479 | } | ||
| 4045 | SetParticipantMiningStatus("hashing job " + jobId); | 4480 | SetParticipantMiningStatus("hashing job " + jobId); |
| 4046 | } | 4481 | } |
| 4047 | } | 4482 | } |
| @@ -4167,7 +4602,11 @@ connected: | |||
| 4167 | (unsigned long long)hashesSinceSample, | 4602 | (unsigned long long)hashesSinceSample, |
| 4168 | (unsigned long long)sessionSharesSent, | 4603 | (unsigned long long)sessionSharesSent, |
| 4169 | (unsigned long long)sessionSharesAccepted); | 4604 | (unsigned long long)sessionSharesAccepted); |
| 4170 | return true; | 4605 | // Not "we got here", which is true of a tunnel the pool accepted and then |
| 4606 | // dropped without ever sending a job -- exactly the case the caller's | ||
| 4607 | // backoff exists for. Reaching the end of the session is not evidence the | ||
| 4608 | // session was worth anything; a job is. | ||
| 4609 | return gotAnyJob; | ||
| 4171 | } | 4610 | } |
| 4172 | 4611 | ||
| 4173 | // --------------------------------------------------------------------------- | 4612 | // --------------------------------------------------------------------------- |
| @@ -4364,11 +4803,51 @@ bool BitcoinMiner(int nThreadId) | |||
| 4364 | // Participant mode: connect to external pool instead of mining solo/operator | 4803 | // Participant mode: connect to external pool instead of mining solo/operator |
| 4365 | if (nMineMode == MINE_PARTICIPANT) | 4804 | if (nMineMode == MINE_PARTICIPANT) |
| 4366 | { | 4805 | { |
| 4806 | // An attempt that never got work backs off (10s doubling to 120s) | ||
| 4807 | // instead of hammering the same path every flat 10s, and a streak | ||
| 4808 | // lasting minutes is said at printf level: the identical once-per-10s | ||
| 4809 | // LogPrint line is how a worker idled all night unnoticed (issue #17). | ||
| 4810 | // | ||
| 4811 | // Only a session the pool actually sent a job to resets either. The | ||
| 4812 | // weaker test -- "the session returned" -- was gameable: a pool that | ||
| 4813 | // completes the tunnel and drops without ever sending work leaves by | ||
| 4814 | // the same tidy cleanup path a healthy one does, which would pin the | ||
| 4815 | // retry at 10s forever and defeat the backoff in exactly the scenario | ||
| 4816 | // it exists for. | ||
| 4817 | int nRetrySecs = 10; | ||
| 4818 | int64 nFailingSince = 0; | ||
| 4367 | while (fGenerateBitcoins && nMineMode == MINE_PARTICIPANT && !fShutdown) { | 4819 | while (fGenerateBitcoins && nMineMode == MINE_PARTICIPANT && !fShutdown) { |
| 4368 | PoolParticipantMiner(); | 4820 | bool fGotWork = PoolParticipantMiner(); |
| 4369 | if (fGenerateBitcoins && nMineMode == MINE_PARTICIPANT && !fShutdown) { | 4821 | if (fGenerateBitcoins && nMineMode == MINE_PARTICIPANT && !fShutdown) { |
| 4370 | LogPrint("worker", "PoolParticipantMiner: reconnecting in 10s\n"); | 4822 | if (fGotWork) { |
| 4371 | for (int i = 0; i < 10 && !fShutdown; i++) Sleep(1000); | 4823 | nRetrySecs = 10; |
| 4824 | nFailingSince = 0; | ||
| 4825 | } else { | ||
| 4826 | if (nFailingSince == 0) | ||
| 4827 | nFailingSince = GetTime(); | ||
| 4828 | int64 nMins = (GetTime() - nFailingSince) / 60; | ||
| 4829 | if (nMins >= 1) | ||
| 4830 | printf("[worker] connection to pool %s has been failing" | ||
| 4831 | " for %lld minutes\n", | ||
| 4832 | strParticipantPool.c_str(), (long long)nMins); | ||
| 4833 | } | ||
| 4834 | LogPrint("worker", "PoolParticipantMiner: reconnecting in %ds\n", | ||
| 4835 | nRetrySecs); | ||
| 4836 | // Poll everything the enclosing while polls, not just | ||
| 4837 | // fShutdown. Raising the ceiling to 120s made a | ||
| 4838 | // shutdown-only predicate expensive: after the operator | ||
| 4839 | // clears Generate or switches to Relay, the session -- and | ||
| 4840 | // the vfThreadRunning[3] slot that gates restarting it -- | ||
| 4841 | // would stay held for up to two minutes. Measured 119s | ||
| 4842 | // before, 1s after. | ||
| 4843 | for (int i = 0; i < nRetrySecs && !fShutdown && fGenerateBitcoins | ||
| 4844 | && nMineMode == MINE_PARTICIPANT; i++) | ||
| 4845 | Sleep(1000); | ||
| 4846 | if (!fGotWork && nRetrySecs < 120) { | ||
| 4847 | nRetrySecs *= 2; | ||
| 4848 | if (nRetrySecs > 120) | ||
| 4849 | nRetrySecs = 120; | ||
| 4850 | } | ||
| 4372 | } | 4851 | } |
| 4373 | } | 4852 | } |
| 4374 | return true; | 4853 | return true; |
| @@ -4555,7 +5034,7 @@ bool BitcoinMiner(int nThreadId) | |||
| 4555 | //// debug print | 5034 | //// debug print |
| 4556 | if (LogAcceptsCategory("net")) printf("BitcoinMiner:\n"); | 5035 | if (LogAcceptsCategory("net")) printf("BitcoinMiner:\n"); |
| 4557 | if (LogAcceptsCategory("net")) printf("RandomX proof-of-work found \n powhash: %s \ntarget: %s\n", hash.GetHex().c_str(), hashTarget.GetHex().c_str()); | 5036 | if (LogAcceptsCategory("net")) printf("RandomX proof-of-work found \n powhash: %s \ntarget: %s\n", hash.GetHex().c_str(), hashTarget.GetHex().c_str()); |
| 4558 | if (LogAcceptsCategory("net")) pblock->print(); | 5037 | if (LogAcceptsCategory("relay")) pblock->print(); |
| 4559 | 5038 | ||
| 4560 | SetThreadPriority(GetCurrentThread(), THREAD_PRIORITY_NORMAL); | 5039 | SetThreadPriority(GetCurrentThread(), THREAD_PRIORITY_NORMAL); |
| 4561 | CRITICAL_BLOCK(cs_main) | 5040 | CRITICAL_BLOCK(cs_main) |
diff --git a/src/main_gui.cpp b/src/main_gui.cpp index 211e1e2..0e64985 100644 --- a/src/main_gui.cpp +++ b/src/main_gui.cpp | |||
| @@ -111,6 +111,8 @@ static void PrintUsage() | |||
| 111 | printf(" /help, -help, --help, /?\n"); | 111 | printf(" /help, -help, --help, /?\n"); |
| 112 | printf(" /datadir=PATH\n"); | 112 | printf(" /datadir=PATH\n"); |
| 113 | printf(" /debug\n"); | 113 | printf(" /debug\n"); |
| 114 | printf(" /debugrelay (/debug plus per-message relay chatter and block dumps)\n"); | ||
| 115 | printf(" /maxdebugfilesize=N (roll debug.log at N MB, default 1024; 0 = never)\n"); | ||
| 114 | printf(" /gen\n"); | 116 | printf(" /gen\n"); |
| 115 | printf(" /nogui or /daemon\n"); | 117 | printf(" /nogui or /daemon\n"); |
| 116 | printf(" /selftest=wallet-keypool, wallet-hd, wallet-format, wallet-crypto, wallet-encrypt,\n"); | 118 | printf(" /selftest=wallet-keypool, wallet-hd, wallet-format, wallet-crypto, wallet-encrypt,\n"); |
| @@ -191,6 +193,54 @@ static void ParseStartupArguments(int argc, char* argv[]) | |||
| 191 | if (arg(argc,argv,"/debug") || arg(argc,argv,"-debug")) | 193 | if (arg(argc,argv,"/debug") || arg(argc,argv,"-debug")) |
| 192 | fDebug = true; | 194 | fDebug = true; |
| 193 | 195 | ||
| 196 | // /debugrelay -- everything /debug shows, plus the per-message firehose | ||
| 197 | // ("relay" and "nostrdiscovery" categories: sending: tx, Relaying wtx, | ||
| 198 | // raw CBlock dumps, per-peer discovery lines). That traffic was ~90% of | ||
| 199 | // a 13-hour production debug.log (issue #35), so plain /debug leaves it | ||
| 200 | // off; the message text itself is unchanged for anyone grepping it. | ||
| 201 | if (arg(argc,argv,"/debugrelay") || arg(argc,argv,"-debugrelay")) | ||
| 202 | { | ||
| 203 | fDebug = true; | ||
| 204 | fDebugRelay = true; | ||
| 205 | } | ||
| 206 | |||
| 207 | // /maxdebugfilesize=N -- roll debug.log to debug.log.old once it passes | ||
| 208 | // N MB, checked on each write. Default is 1024 (see util.cpp); 0 turns | ||
| 209 | // the check off and leaves rotation entirely to logrotate. | ||
| 210 | string strMaxDebugSize = argval2(argc, argv, "/maxdebugfilesize", "-maxdebugfilesize"); | ||
| 211 | if (!strMaxDebugSize.empty()) | ||
| 212 | { | ||
| 213 | // Parsed with atoi64() before, which is strtoll() with the endptr | ||
| 214 | // thrown away: it returns 0 for anything it cannot read, so | ||
| 215 | // /maxdebugfilesize=1G and =1024MB both came out as 0 -- "never | ||
| 216 | // roll", identical to asking for that on purpose, with nothing said | ||
| 217 | // to the operator. The old code also multiplied without a range | ||
| 218 | // check, so a big enough N wrapped to a negative cap, which the roll | ||
| 219 | // reads as "off" too. Every rejection is now reported and leaves the | ||
| 220 | // default in place; the value is a plain count of MB, no suffix. | ||
| 221 | const char* psz = strMaxDebugSize.c_str(); | ||
| 222 | char* pszEnd = NULL; | ||
| 223 | errno = 0; | ||
| 224 | int64 nMB = strtoll(psz, &pszEnd, 10); | ||
| 225 | // INT64_MAX, without depending on which limits header this tree pulls in. | ||
| 226 | const int64 nMaxMB = (int64)((~(uint64)0) >> 1) / (1024 * 1024); | ||
| 227 | const char* pszWhy = NULL; | ||
| 228 | if (pszEnd == psz) | ||
| 229 | pszWhy = "not a number"; | ||
| 230 | else if (*pszEnd != '\0') | ||
| 231 | pszWhy = "trailing characters -- the value is a count of MB, with no unit suffix"; | ||
| 232 | else if (errno == ERANGE || nMB < 0) | ||
| 233 | pszWhy = "not a size in MB"; | ||
| 234 | else if (nMB > nMaxMB) | ||
| 235 | pszWhy = "larger than a file size can be"; | ||
| 236 | if (pszWhy) | ||
| 237 | fprintf(stderr, "Ignoring /maxdebugfilesize=%s: %s (keeping %lld MB)\n", | ||
| 238 | strMaxDebugSize.c_str(), pszWhy, | ||
| 239 | (long long)(nMaxDebugFileSize / 1024 / 1024)); | ||
| 240 | else | ||
| 241 | nMaxDebugFileSize = nMB * 1024 * 1024; | ||
| 242 | } | ||
| 243 | |||
| 194 | if (arg(argc,argv,"/gen") || arg(argc,argv,"-gen")) | 244 | if (arg(argc,argv,"/gen") || arg(argc,argv,"-gen")) |
| 195 | { | 245 | { |
| 196 | fGenerateBitcoins = 1; | 246 | fGenerateBitcoins = 1; |
diff --git a/src/net.cpp b/src/net.cpp index fed6123..16038c8 100644 --- a/src/net.cpp +++ b/src/net.cpp | |||
| @@ -2090,7 +2090,7 @@ bool StartNode(string& strError) | |||
| 2090 | if (addrIncoming.ip) | 2090 | if (addrIncoming.ip) |
| 2091 | addrLocalHost.ip = addrIncoming.ip; | 2091 | addrLocalHost.ip = addrIncoming.ip; |
| 2092 | 2092 | ||
| 2093 | _beginthread([](void*) { | 2093 | if (_beginthread([](void*) { |
| 2094 | unsigned int ip = addrLocalHost.ip; | 2094 | unsigned int ip = addrLocalHost.ip; |
| 2095 | if (GetMyExternalIP(ip)) { | 2095 | if (GetMyExternalIP(ip)) { |
| 2096 | addrLocalHost.ip = ip; | 2096 | addrLocalHost.ip = ip; |
| @@ -2098,7 +2098,8 @@ bool StartNode(string& strError) | |||
| 2098 | CWalletDB().WriteSetting("addrIncoming", addrIncoming); | 2098 | CWalletDB().WriteSetting("addrIncoming", addrIncoming); |
| 2099 | printf("External IP updated: %s\n", addrLocalHost.ToStringIP().c_str()); | 2099 | printf("External IP updated: %s\n", addrLocalHost.ToStringIP().c_str()); |
| 2100 | } | 2100 | } |
| 2101 | }, 0, NULL); | 2101 | }, 0, NULL) == (uintptr_t)-1) |
| 2102 | printf("Error: _beginthread(GetMyExternalIP) failed\n"); | ||
| 2102 | 2103 | ||
| 2103 | // Peers that answered last time, dialled straight away. The relays are the | 2104 | // Peers that answered last time, dialled straight away. The relays are the |
| 2104 | // only way to find anyone otherwise, and reaching them plus walking their | 2105 | // only way to find anyone otherwise, and reaching them plus walking their |
| @@ -23,6 +23,12 @@ enum | |||
| 23 | 23 | ||
| 24 | 24 | ||
| 25 | 25 | ||
| 26 | // Defined in main.cpp. True while this node is tracking the tip rather than | ||
| 27 | // still catching up, measured off the age of our own best block -- see there | ||
| 28 | // for why that and not a peer-reported height. Declared here because net.h is | ||
| 29 | // parsed before main.h and CNode::AskFor needs it. | ||
| 30 | bool IsBlockFetchNearTip(); | ||
| 31 | |||
| 26 | bool GetMyExternalIP(unsigned int& ipRet); | 32 | bool GetMyExternalIP(unsigned int& ipRet); |
| 27 | CNode* ConnectNodeBtf(const string& strBtfAddr); | 33 | CNode* ConnectNodeBtf(const string& strBtfAddr); |
| 28 | CNode* ConnectNodeBtfResolved(const string& strBtfAddr, const string& strMeeting, | 34 | CNode* ConnectNodeBtfResolved(const string& strBtfAddr, const string& strMeeting, |
| @@ -89,6 +95,15 @@ static const int BTF_RECV_TIMEOUT_SECS = 30 * 60; | |||
| 89 | static const int BTF_SEND_STALL_SECS = 10 * 60; | 95 | static const int BTF_SEND_STALL_SECS = 10 * 60; |
| 90 | static const int BTF_HANDSHAKE_GRACE_SECS = 60; | 96 | static const int BTF_HANDSHAKE_GRACE_SECS = 60; |
| 91 | 97 | ||
| 98 | // How long a requested block gets before it is asked for again, in seconds. | ||
| 99 | // Used twice: CNode::AskFor spaces the queued per-announcer block retries this | ||
| 100 | // far apart instead of the two minutes transactions get, and the failover | ||
| 101 | // sweep in main.cpp re-issues a getdata to a different peer once a sent | ||
| 102 | // request has gone unanswered this long. A block body is at most 1 MB and | ||
| 103 | // somebody demonstrably has it -- they announced it -- so on this timescale | ||
| 104 | // "not here yet" means "not coming from that peer", not "still in transit". | ||
| 105 | static const int BLOCK_FETCH_RETRY_SECS = 15; | ||
| 106 | |||
| 92 | // A serialized object cannot be larger than MAX_SIZE, so no valid network | 107 | // A serialized object cannot be larger than MAX_SIZE, so no valid network |
| 93 | // message needs the old 256 MB header allowance. Keep the wire cap aligned with | 108 | // message needs the old 256 MB header allowance. Keep the wire cap aligned with |
| 94 | // what the deserializer can accept. How long a peer may sit on a partial | 109 | // what the deserializer can accept. How long a peer may sit on a partial |
| @@ -795,13 +810,51 @@ public: | |||
| 795 | static int64 nLastTime; | 810 | static int64 nLastTime; |
| 796 | nLastTime = nNow = max(nNow, ++nLastTime); | 811 | nLastTime = nNow = max(nNow, ++nLastTime); |
| 797 | 812 | ||
| 798 | // Each retry is 2 minutes after the last | 813 | // Each retry is 2 minutes after the last -- and because nRequestTime |
| 799 | nRequestTime = max(nRequestTime + 2 * 60 * 1000000, nNow); | 814 | // is shared across peers, the same spacing is what strings requests |
| 815 | // for one inv across its announcers. For transactions that is pacing; | ||
| 816 | // for a new block it was the stall of issue #33: nine peers announce | ||
| 817 | // the block, the first one asked does not serve it, and the ninth | ||
| 818 | // candidate is not even asked until sixteen minutes in, with the pool | ||
| 819 | // mining on the stale tip the whole time. | ||
| 820 | // | ||
| 821 | // Blocks retry on the fetch timescale, but only while we are at the | ||
| 822 | // tip. That is where the stall costs something -- the pool keeps | ||
| 823 | // handing out jobs against a dead tip -- and it is also where the | ||
| 824 | // spacing is nearly free: one block is in flight, and its body has | ||
| 825 | // almost always arrived before the second announcer's turn comes | ||
| 826 | // round, so AlreadyHave drops the duplicate before a getdata is sent. | ||
| 827 | // | ||
| 828 | // While catching up neither half holds. A peer working through a | ||
| 829 | // 500-deep queue can be minutes away from block N without anything | ||
| 830 | // being wrong, so at 15s the second announcer is asked at +15s, the | ||
| 831 | // third at +30s, and the bulk download arrives once per announcer -- | ||
| 832 | // up to eight times over. Nothing caps that: the eight-entry cap is on | ||
| 833 | // mapBlockFetch, which is a different mechanism from this spacing. | ||
| 834 | // Two minutes is the right number there, and it is what this line did | ||
| 835 | // before. Failover at the tip does not depend on this being 15s in any | ||
| 836 | // case: mapBlockFetch re-issues a stalled getdata to the next peer on | ||
| 837 | // its own timer, which is what actually fixes #33. | ||
| 838 | bool fFast = (inv.type == MSG_BLOCK && IsBlockFetchNearTip()); | ||
| 839 | int64 nRetryUsecs = (fFast ? BLOCK_FETCH_RETRY_SECS : 2 * 60) * 1000000LL; | ||
| 840 | nRequestTime = max(nRequestTime + nRetryUsecs, nNow); | ||
| 800 | mapAskFor.insert(make_pair(nRequestTime, inv)); | 841 | mapAskFor.insert(make_pair(nRequestTime, inv)); |
| 801 | } | 842 | } |
| 802 | 843 | ||
| 803 | 844 | ||
| 804 | 845 | ||
| 846 | // "sending: tx (N bytes)" alone was ~71% of a 13-hour production | ||
| 847 | // debug.log (issue #35), so tx sends are demoted to the /debugrelay-gated | ||
| 848 | // "relay" category; every other command's send trace stays on "net". | ||
| 849 | // The line is emitted in pieces across BeginMessage/EndMessage/ | ||
| 850 | // AbortMessage, so all three must agree on the category or orphaned | ||
| 851 | // "(N bytes)" fragments would leak into a plain -debug log. | ||
| 852 | // Valid only mid-message (nPushPos != -1). | ||
| 853 | const char* SendLogCategory() const | ||
| 854 | { | ||
| 855 | return strcmp(GetMessageCommand(), "tx") == 0 ? "relay" : "net"; | ||
| 856 | } | ||
| 857 | |||
| 805 | void BeginMessage(const char* pszCommand) | 858 | void BeginMessage(const char* pszCommand) |
| 806 | { | 859 | { |
| 807 | EnterCriticalSection(&cs_vSend); | 860 | EnterCriticalSection(&cs_vSend); |
| @@ -809,17 +862,19 @@ public: | |||
| 809 | AbortMessage(); | 862 | AbortMessage(); |
| 810 | nPushPos = vSend.size(); | 863 | nPushPos = vSend.size(); |
| 811 | vSend << CMessageHeader(pszCommand, 0); | 864 | vSend << CMessageHeader(pszCommand, 0); |
| 812 | if (LogAcceptsCategory("net")) printf("sending: %-12s ", pszCommand); | 865 | if (LogAcceptsCategory(SendLogCategory())) printf("sending: %-12s ", pszCommand); |
| 813 | } | 866 | } |
| 814 | 867 | ||
| 815 | void AbortMessage() | 868 | void AbortMessage() |
| 816 | { | 869 | { |
| 817 | if (nPushPos == -1) | 870 | if (nPushPos == -1) |
| 818 | return; | 871 | return; |
| 872 | // Capture before nPushPos is cleared; GetMessageCommand() needs it. | ||
| 873 | const char* pszCategory = SendLogCategory(); | ||
| 819 | vSend.resize(nPushPos); | 874 | vSend.resize(nPushPos); |
| 820 | nPushPos = -1; | 875 | nPushPos = -1; |
| 821 | LeaveCriticalSection(&cs_vSend); | 876 | LeaveCriticalSection(&cs_vSend); |
| 822 | if (LogAcceptsCategory("net")) printf("(aborted)\n"); | 877 | if (LogAcceptsCategory(pszCategory)) printf("(aborted)\n"); |
| 823 | } | 878 | } |
| 824 | 879 | ||
| 825 | void EndMessage() | 880 | void EndMessage() |
| @@ -827,7 +882,11 @@ public: | |||
| 827 | extern int nDropMessagesTest; | 882 | extern int nDropMessagesTest; |
| 828 | if (nDropMessagesTest > 0 && GetRand(nDropMessagesTest) == 0) | 883 | if (nDropMessagesTest > 0 && GetRand(nDropMessagesTest) == 0) |
| 829 | { | 884 | { |
| 830 | if (LogAcceptsCategory("net")) printf("dropmessages DROPPING SEND MESSAGE\n"); | 885 | // Same category as the "sending: " this line interrupts, so a tx |
| 886 | // does not announce its own drop under "net" having been gated | ||
| 887 | // off under "relay". nPushPos can be -1 here, and then | ||
| 888 | // GetMessageCommand() returns "" and this is "net" as before. | ||
| 889 | if (LogAcceptsCategory(SendLogCategory())) printf("dropmessages DROPPING SEND MESSAGE\n"); | ||
| 831 | AbortMessage(); | 890 | AbortMessage(); |
| 832 | return; | 891 | return; |
| 833 | } | 892 | } |
| @@ -839,10 +898,10 @@ public: | |||
| 839 | unsigned int nSize = vSend.size() - nPushPos - sizeof(CMessageHeader); | 898 | unsigned int nSize = vSend.size() - nPushPos - sizeof(CMessageHeader); |
| 840 | memcpy((char*)&vSend[nPushPos] + offsetof(CMessageHeader, nMessageSize), &nSize, sizeof(nSize)); | 899 | memcpy((char*)&vSend[nPushPos] + offsetof(CMessageHeader, nMessageSize), &nSize, sizeof(nSize)); |
| 841 | 900 | ||
| 842 | if (LogAcceptsCategory("net")) printf("(%d bytes) ", nSize); | 901 | if (LogAcceptsCategory(SendLogCategory())) printf("(%d bytes) ", nSize); |
| 843 | //for (int i = nPushPos+sizeof(CMessageHeader); i < min(vSend.size(), nPushPos+sizeof(CMessageHeader)+20U); i++) | 902 | //for (int i = nPushPos+sizeof(CMessageHeader); i < min(vSend.size(), nPushPos+sizeof(CMessageHeader)+20U); i++) |
| 844 | // printf("%02x ", vSend[i] & 0xff); | 903 | // printf("%02x ", vSend[i] & 0xff); |
| 845 | if (LogAcceptsCategory("net")) printf("\n"); | 904 | if (LogAcceptsCategory(SendLogCategory())) printf("\n"); |
| 846 | 905 | ||
| 847 | nPushPos = -1; | 906 | nPushPos = -1; |
| 848 | LeaveCriticalSection(&cs_vSend); | 907 | LeaveCriticalSection(&cs_vSend); |
diff --git a/src/nostr.cpp b/src/nostr.cpp index e2d839c..f44dc08 100644 --- a/src/nostr.cpp +++ b/src/nostr.cpp | |||
| @@ -151,6 +151,19 @@ string BtfActiveRelay() | |||
| 151 | 151 | ||
| 152 | void BtfSetActiveRelay(const string& relay) | 152 | void BtfSetActiveRelay(const string& relay) |
| 153 | { | 153 | { |
| 154 | // With /rvrelay set, the descriptor must never name anything but the pin. | ||
| 155 | // No caller can reach here with another relay today -- both registration | ||
| 156 | // paths draw their list from BtfAllRelays(), which returns the pin alone -- | ||
| 157 | // but the descriptor is the one thing a miner obeys, so the invariant is | ||
| 158 | // enforced at the sink instead of being retrusted to every future caller. | ||
| 159 | if (fBtfRelayPinned && | ||
| 160 | find(vBtfMeetingRelays.begin(), vBtfMeetingRelays.end(), relay) == vBtfMeetingRelays.end()) | ||
| 161 | { | ||
| 162 | LogPrint("pool", "refusing to advertise meeting relay %s: /rvrelay pins %s\n", | ||
| 163 | relay.c_str(), | ||
| 164 | vBtfMeetingRelays.empty() ? "an empty list" : vBtfMeetingRelays[0].c_str()); | ||
| 165 | return; | ||
| 166 | } | ||
| 154 | CRITICAL_BLOCK(cs_activeRelay) | 167 | CRITICAL_BLOCK(cs_activeRelay) |
| 155 | strBtfActiveRelay = relay; | 168 | strBtfActiveRelay = relay; |
| 156 | } | 169 | } |
| @@ -223,6 +236,18 @@ vector<string> BtfAllRelays() | |||
| 223 | return all; | 236 | return all; |
| 224 | } | 237 | } |
| 225 | 238 | ||
| 239 | // Relays learned from Nostr, whether or not a pin is in force. Reporting only: | ||
| 240 | // it exists so the pool can name what /rvrelay is excluding. Anything choosing | ||
| 241 | // a relay to register or dial at must keep using BtfAllRelays(). | ||
| 242 | vector<string> BtfDiscoveredRelays() | ||
| 243 | { | ||
| 244 | vector<string> out; | ||
| 245 | CRITICAL_BLOCK(cs_discoveredRelays) | ||
| 246 | foreach(const string& r, g_discoveredRelays) | ||
| 247 | out.push_back(r); | ||
| 248 | return out; | ||
| 249 | } | ||
| 250 | |||
| 226 | 251 | ||
| 227 | // | 252 | // |
| 228 | // Utilities | 253 | // Utilities |
| @@ -1440,7 +1465,7 @@ static bool SeedFromRelay(CNostrKey& key, const string& relay) | |||
| 1440 | else if (createdAt > it->second) it->second = createdAt; // refresh | 1465 | else if (createdAt > it->second) it->second = createdAt; // refresh |
| 1441 | } | 1466 | } |
| 1442 | if (fNew && fDebug) | 1467 | if (fNew && fDebug) |
| 1443 | LogPrint("nostr", "Nostr: discovered .btf peer %s\n", peerAddr.c_str()); | 1468 | LogPrint("nostrdiscovery", "Nostr: discovered .btf peer %s\n", peerAddr.c_str()); |
| 1444 | if (++nPeers > 500) break; | 1469 | if (++nPeers > 500) break; |
| 1445 | } | 1470 | } |
| 1446 | else if (type == "EOSE") | 1471 | else if (type == "EOSE") |
diff --git a/src/nostr.h b/src/nostr.h index 6dbbe26..0dd919d 100644 --- a/src/nostr.h +++ b/src/nostr.h | |||
| @@ -60,6 +60,9 @@ extern bool fBtfRelayPinned; | |||
| 60 | bool LooksLikeRelay(const std::string& r); | 60 | bool LooksLikeRelay(const std::string& r); |
| 61 | // Every relay to try: curated seeds + relays discovered from Nostr announcements. | 61 | // Every relay to try: curated seeds + relays discovered from Nostr announcements. |
| 62 | std::vector<std::string> BtfAllRelays(); | 62 | std::vector<std::string> BtfAllRelays(); |
| 63 | // Relays discovered from Nostr, ignoring the pin. For reporting what a pin | ||
| 64 | // excludes -- never for choosing a relay to register or dial at. | ||
| 65 | std::vector<std::string> BtfDiscoveredRelays(); | ||
| 63 | 66 | ||
| 64 | struct BtfPoolAnnouncement | 67 | struct BtfPoolAnnouncement |
| 65 | { | 68 | { |
diff --git a/src/randomx_pow.cpp b/src/randomx_pow.cpp index 1d058d4..9c59364 100644 --- a/src/randomx_pow.cpp +++ b/src/randomx_pow.cpp | |||
| @@ -8,6 +8,7 @@ | |||
| 8 | #include <thread> | 8 | #include <thread> |
| 9 | #include <vector> | 9 | #include <vector> |
| 10 | #include <mutex> | 10 | #include <mutex> |
| 11 | #include <system_error> | ||
| 11 | 12 | ||
| 12 | // Fixed key (seed) that determines the RandomX cache/dataset. Keeping it | 13 | // Fixed key (seed) that determines the RandomX cache/dataset. Keeping it |
| 13 | // constant avoids per-epoch "reseed" logic; for the CPU+RAM fairness goal | 14 | // constant avoids per-epoch "reseed" logic; for the CPU+RAM fairness goal |
| @@ -101,13 +102,28 @@ bool RandomXInitDataset(int nThreads) | |||
| 101 | 102 | ||
| 102 | std::vector<std::thread> workers; | 103 | std::vector<std::thread> workers; |
| 103 | unsigned long per = total / nThreads; | 104 | unsigned long per = total / nThreads; |
| 104 | for (int i = 0; i < nThreads; i++) | 105 | try |
| 105 | { | 106 | { |
| 106 | unsigned long start = i * per; | 107 | for (int i = 0; i < nThreads; i++) |
| 107 | unsigned long count = (i == nThreads - 1) ? (total - start) : per; | 108 | { |
| 108 | workers.emplace_back([start, count]() { | 109 | unsigned long start = i * per; |
| 109 | randomx_init_dataset(g_dataset, g_cache, start, count); | 110 | unsigned long count = (i == nThreads - 1) ? (total - start) : per; |
| 110 | }); | 111 | workers.emplace_back([start, count]() { |
| 112 | randomx_init_dataset(g_dataset, g_cache, start, count); | ||
| 113 | }); | ||
| 114 | } | ||
| 115 | } | ||
| 116 | catch (const std::system_error& e) | ||
| 117 | { | ||
| 118 | // Same refusal as the allocation failure above: light mode is slow | ||
| 119 | // but alive, std::terminate is neither. Join the workers that did | ||
| 120 | // start before releasing the dataset out from under them. | ||
| 121 | for (auto& w : workers) w.join(); | ||
| 122 | randomx_release_dataset(g_dataset); | ||
| 123 | g_dataset = NULL; | ||
| 124 | printf("RandomX: cannot spawn dataset init threads (%s), staying in light mode\n", | ||
| 125 | e.what()); | ||
| 126 | return false; | ||
| 111 | } | 127 | } |
| 112 | for (auto& w : workers) w.join(); | 128 | for (auto& w : workers) w.join(); |
| 113 | 129 | ||
diff --git a/src/readme.txt b/src/readme.txt index 752be66..7490a9a 100644 --- a/src/readme.txt +++ b/src/readme.txt | |||
| @@ -16,7 +16,7 @@ This product includes software developed by the OpenSSL Project. | |||
| 16 | Differences from the original Bitcoin | 16 | Differences from the original Bitcoin |
| 17 | ------------------------------------- | 17 | ------------------------------------- |
| 18 | - Own genesis block (22/Jul/2026 headline, independent chain) | 18 | - Own genesis block (22/Jul/2026 headline, independent chain) |
| 19 | - Own magic bytes (0xbf 0x1a 0x5c 0xfd) and P2P port 8433 | 19 | - Own magic bytes (0xbf 0x20 0x5c 0xfd) and P2P port 8433 |
| 20 | - Addresses start with "B" (ADDRESSVERSION = 25) | 20 | - Addresses start with "B" (ADDRESSVERSION = 25) |
| 21 | - Consensus fixes applied: value overflow (CVE-2010-5139), duplicate inputs, | 21 | - Consensus fixes applied: value overflow (CVE-2010-5139), duplicate inputs, |
| 22 | money range checks (MoneyRange) | 22 | money range checks (MoneyRange) |
diff --git a/src/rpc.cpp b/src/rpc.cpp index be6c80d..1d53fb2 100644 --- a/src/rpc.cpp +++ b/src/rpc.cpp | |||
| @@ -115,15 +115,28 @@ static uint256 ShareTargetFromDifficulty(double difficulty) | |||
| 115 | { | 115 | { |
| 116 | if (difficulty <= 0.0) difficulty = 1.0; | 116 | if (difficulty <= 0.0) difficulty = 1.0; |
| 117 | static const uint256 diff1 = CBigNum(bnProofOfWorkLimit).getuint256(); | 117 | static const uint256 diff1 = CBigNum(bnProofOfWorkLimit).getuint256(); |
| 118 | // Representability floor. shareTarget = diff1 / difficulty, and diff1 is | ||
| 119 | // ~uint256(0) >> 12, i.e. a hair under 2^244 -- so the true target stops | ||
| 120 | // fitting in a uint256 once difficulty reaches 2^-12 (= 1/4096), and the | ||
| 121 | // fixed-point divide below breaks even earlier in a second way: the | ||
| 122 | // (uint64)(difficulty * 65536.0) divisor truncates to zero for any | ||
| 123 | // difficulty under 2^-16. Both thresholds sit far below VARDIFF_MIN | ||
| 124 | // (0.001), so live operation never comes near this, but a caller that | ||
| 125 | // bypasses vardiff (or a future VARDIFF_MIN) must not divide by zero or | ||
| 126 | // hand back getuint256()'s low-256-bit truncation of an oversized | ||
| 127 | // quotient -- a wrapped target is not merely wrong, it is arbitrarily | ||
| 128 | // HARDER than difficulty 1. At these difficulties every hash is meant to | ||
| 129 | // be a share, so the honest answer is the easiest representable target. | ||
| 130 | // (This replaces a dead branch that read `if (t < diff1 && difficulty < | ||
| 131 | // 1.0)`: t = diff1/difficulty, so difficulty < 1.0 implies t > diff1 and | ||
| 132 | // the two conditions could never both hold.) | ||
| 133 | if (difficulty < 1.0 / 4096.0) return ~uint256(0); | ||
| 118 | // shareTarget = diff1 / difficulty | 134 | // shareTarget = diff1 / difficulty |
| 119 | CBigNum bn; bn.setuint256(diff1); | 135 | CBigNum bn; bn.setuint256(diff1); |
| 120 | // Multiply by 2^16 to keep precision, divide, shift back | 136 | // Multiply by 2^16 to keep precision, divide, shift back |
| 121 | bn <<= 16; | 137 | bn <<= 16; |
| 122 | bn /= (uint64)(difficulty * 65536.0); | 138 | bn /= (uint64)(difficulty * 65536.0); |
| 123 | uint256 t = bn.getuint256(); | 139 | return bn.getuint256(); |
| 124 | // Cap at all-ones (maximum, easiest possible) | ||
| 125 | if (t < diff1 && difficulty < 1.0) t = ~uint256(0); | ||
| 126 | return t; | ||
| 127 | } | 140 | } |
| 128 | 141 | ||
| 129 | // Expected number of hashes to find one share at a given Stratum difficulty, | 142 | // Expected number of hashes to find one share at a given Stratum difficulty, |
| @@ -223,6 +236,29 @@ static bool RebuildJob() | |||
| 223 | // From the pool, so the template's payout key is in wallet.dat before | 236 | // From the pool, so the template's payout key is in wallet.dat before |
| 224 | // any miner is handed work against it. | 237 | // any miner is handed work against it. |
| 225 | vector<unsigned char> vchPubKey = GetKeyFromPool(); | 238 | vector<unsigned char> vchPubKey = GetKeyFromPool(); |
| 239 | if (vchPubKey.empty()) { | ||
| 240 | // Empty means the wallet could not produce a key: encrypted and | ||
| 241 | // locked, or key generation itself failed. Serialised, an empty | ||
| 242 | // vector is a zero-length push, so the coinbase would become | ||
| 243 | // `<empty> OP_CHECKSIG` -- a script nobody can satisfy. Every | ||
| 244 | // block mined against such a job burns its whole subsidy, while | ||
| 245 | // QueuePayouts still records the full obligation and the miners | ||
| 246 | // are then paid out of coin that block never contributed. | ||
| 247 | // BitcoinMiner refuses to mine in this state; refuse to hand the | ||
| 248 | // pool's miners work in it too. printf and not LogPrint for the | ||
| 249 | // reason given above the deaf-node refusal, and throttled the | ||
| 250 | // same way -- the no-job watchdog retries every few seconds for | ||
| 251 | // as long as the condition lasts. | ||
| 252 | static int64 nLastSaidNoKey = 0; | ||
| 253 | if (GetTime() - nLastSaidNoKey > 60) { | ||
| 254 | nLastSaidNoKey = GetTime(); | ||
| 255 | printf("RebuildJob: no wallet key available for the coinbase " | ||
| 256 | "(wallet locked, or key generation failed -- the " | ||
| 257 | "GetKeyFromPool line above says which) -- not issuing " | ||
| 258 | "jobs\n"); | ||
| 259 | } | ||
| 260 | return false; | ||
| 261 | } | ||
| 226 | static std::atomic<uint32_t> sExtra{0}; | 262 | static std::atomic<uint32_t> sExtra{0}; |
| 227 | uint32_t extraNonce = ++sExtra; | 263 | uint32_t extraNonce = ++sExtra; |
| 228 | 264 | ||
| @@ -1832,7 +1868,9 @@ static void FlushMaturePayouts() | |||
| 1832 | } | 1868 | } |
| 1833 | int64 total = 0; | 1869 | int64 total = 0; |
| 1834 | for (auto& kv : it->amounts) total += kv.second; | 1870 | for (auto& kv : it->amounts) total += kv.second; |
| 1835 | LogPrint("payout", "[payout] block %d (%s) was orphaned -- voiding %zu" | 1871 | // Always: one line per voided entry, never a collapsed summary. |
| 1872 | // A reorg voids these in a burst from this one source line. | ||
| 1873 | LogPrintAlways("payout", "[payout] block %d (%s) was orphaned -- voiding %zu" | ||
| 1836 | " payment(s) totalling %s\n", | 1874 | " payment(s) totalling %s\n", |
| 1837 | it->blockHeight, it->blockHash.ToString().substr(0, 14).c_str(), | 1875 | it->blockHeight, it->blockHash.ToString().substr(0, 14).c_str(), |
| 1838 | it->amounts.size(), FormatMoney(total).c_str()); | 1876 | it->amounts.size(), FormatMoney(total).c_str()); |
| @@ -2031,7 +2069,7 @@ static void RecordPayoutTxid(const PayingRecord& r, const std::string& txid) | |||
| 2031 | // disagreeing. | 2069 | // disagreeing. |
| 2032 | static void ForfeitPayoutRecipient(const PayingRecord& r, const std::string& reason) | 2070 | static void ForfeitPayoutRecipient(const PayingRecord& r, const std::string& reason) |
| 2033 | { | 2071 | { |
| 2034 | LogPrint("payout", "[payout] writing off %s owed to %s for block %d: %s\n", | 2072 | LogPrintAlways("payout", "[payout] writing off %s owed to %s for block %d: %s\n", |
| 2035 | FormatMoney(r.amount).c_str(), r.address.c_str(), r.blockHeight, | 2073 | FormatMoney(r.amount).c_str(), r.address.c_str(), r.blockHeight, |
| 2036 | reason.c_str()); | 2074 | reason.c_str()); |
| 2037 | VersionedBlob blob; | 2075 | VersionedBlob blob; |
| @@ -2136,7 +2174,7 @@ static void PayoutThreadFn(void*) | |||
| 2136 | // funding block can land at any point in that window. Upstream has | 2174 | // funding block can land at any point in that window. Upstream has |
| 2137 | // no equivalent -- it decides once, when the entry matures. | 2175 | // no equivalent -- it decides once, when the entry matures. |
| 2138 | if (!PayoutBlockStillOnChain(r.blockHash)) { | 2176 | if (!PayoutBlockStillOnChain(r.blockHash)) { |
| 2139 | LogPrint("payout", "[payout] block %d (%s) orphaned while queued" | 2177 | LogPrintAlways("payout", "[payout] block %d (%s) orphaned while queued" |
| 2140 | " -- dropping %s to %s\n", | 2178 | " -- dropping %s to %s\n", |
| 2141 | r.blockHeight, r.blockHash.ToString().substr(0, 14).c_str(), | 2179 | r.blockHeight, r.blockHash.ToString().substr(0, 14).c_str(), |
| 2142 | FormatMoney(r.amount).c_str(), r.address.c_str()); | 2180 | FormatMoney(r.amount).c_str(), r.address.c_str()); |
| @@ -2180,7 +2218,7 @@ static void PayoutThreadFn(void*) | |||
| 2180 | const std::string reason = | 2218 | const std::string reason = |
| 2181 | strprintf("'%s' is not a valid address, so no transaction" | 2219 | strprintf("'%s' is not a valid address, so no transaction" |
| 2182 | " can pay it", r.address.c_str()); | 2220 | " can pay it", r.address.c_str()); |
| 2183 | LogPrint("payout", "[payout] SKIPPED bad address '%s' --" | 2221 | LogPrintAlways("payout", "[payout] SKIPPED bad address '%s' --" |
| 2184 | " %s owed for block %d cannot be paid\n", | 2222 | " %s owed for block %d cannot be paid\n", |
| 2185 | r.address.c_str(), FormatMoney(r.amount).c_str(), | 2223 | r.address.c_str(), FormatMoney(r.amount).c_str(), |
| 2186 | r.blockHeight); | 2224 | r.blockHeight); |
| @@ -2316,7 +2354,7 @@ static void PayoutThreadFn(void*) | |||
| 2316 | // described by at least one of them at every instant. | 2354 | // described by at least one of them at every instant. |
| 2317 | RecordPayoutTxid(r, wtx.GetHash().GetHex()); | 2355 | RecordPayoutTxid(r, wtx.GetHash().GetHex()); |
| 2318 | ForgetPayment(r); | 2356 | ForgetPayment(r); |
| 2319 | LogPrint("payout", "[payout] paid %s to %s (tx %s)\n", | 2357 | LogPrintAlways("payout", "[payout] paid %s to %s (tx %s)\n", |
| 2320 | FormatMoney(r.amount).c_str(), r.address.c_str(), | 2358 | FormatMoney(r.amount).c_str(), r.address.c_str(), |
| 2321 | wtx.GetHash().ToString().substr(0, 12).c_str()); | 2359 | wtx.GetHash().ToString().substr(0, 12).c_str()); |
| 2322 | } else { | 2360 | } else { |
| @@ -2374,7 +2412,7 @@ static void PayoutThreadFn(void*) | |||
| 2374 | // going away must not turn the log into one line a minute | 2412 | // going away must not turn the log into one line a minute |
| 2375 | // forever, and must not go quiet either. | 2413 | // forever, and must not go quiet either. |
| 2376 | if (r.retries <= 5 || r.retries % 60 == 0) | 2414 | if (r.retries <= 5 || r.retries % 60 == 0) |
| 2377 | LogPrint("payout", "[payout] FAILED to pay %s to %s" | 2415 | LogPrintAlways("payout", "[payout] FAILED to pay %s to %s" |
| 2378 | " (%s spendable, wallet unlocked, block %d on" | 2416 | " (%s spendable, wallet unlocked, block %d on" |
| 2379 | " the main chain) -- attempt %d, retrying in" | 2417 | " the main chain) -- attempt %d, retrying in" |
| 2380 | " 60s; this debt stands until it is paid\n", | 2418 | " 60s; this debt stands until it is paid\n", |
| @@ -2582,6 +2620,31 @@ static const double VARDIFF_MAX = 1e12; | |||
| 2582 | static const int64 VARDIFF_STALL_SECS = 45; // 3x share target -- reacts faster without false-triggering on normal variance | 2620 | static const int64 VARDIFF_STALL_SECS = 45; // 3x share target -- reacts faster without false-triggering on normal variance |
| 2583 | static const double VARDIFF_STALL_CUT = 4.0; // divide difficulty by this much | 2621 | static const double VARDIFF_STALL_CUT = 4.0; // divide difficulty by this much |
| 2584 | 2622 | ||
| 2623 | // #7: m->hashRate is an EWMA sampled only when a share arrives, so a miner | ||
| 2624 | // that stops hashing keeps its last estimate forever and RefreshStats sums | ||
| 2625 | // it into the announced pool total for as long as the connection sits open | ||
| 2626 | // -- the published pool hashrate ran several times over ground truth | ||
| 2627 | // because of exactly this. MinerReportedHashRate() below applies the | ||
| 2628 | // policy: a miner gets a grace of HASHRATE_IDLE_MISSES expected share | ||
| 2629 | // intervals (expected interval = expected hashes per share at its | ||
| 2630 | // difficulty, divided by the estimate itself) with no share, after which | ||
| 2631 | // the figure we report falls off with a half-life of one more such | ||
| 2632 | // interval. The interval is clamped to [HASHRATE_MIN_INTERVAL, | ||
| 2633 | // HASHRATE_MAX_INTERVAL] so a fast miner at the vardiff floor (expected | ||
| 2634 | // interval of milliseconds) is not punished for ordinary share-delivery | ||
| 2635 | // jitter, and a very slow miner's grace does not stretch past the point | ||
| 2636 | // where its estimate means anything. At the vardiff target of one share | ||
| 2637 | // per 15s that is a minute of grace, half the rate reported 75s in, and | ||
| 2638 | // nothing reported after about seventeen minutes of silence. | ||
| 2639 | static const double HASHRATE_IDLE_MISSES = 4.0; // grace, in expected share intervals | ||
| 2640 | static const double HASHRATE_MIN_INTERVAL = 1.0; // seconds; floor for the expected interval | ||
| 2641 | static const double HASHRATE_MAX_INTERVAL = 3600.0; // seconds; ceiling for the expected interval | ||
| 2642 | // Half-lives past the grace beyond which we report a flat zero. 2^-64 of the | ||
| 2643 | // original estimate is not a number anyone needs, and stopping here keeps | ||
| 2644 | // pow() from walking down into the denormals for a miner that has been quiet | ||
| 2645 | // for hours. | ||
| 2646 | static const double HASHRATE_DECAY_CUTOFF = 64.0; | ||
| 2647 | |||
| 2585 | struct Miner { | 2648 | struct Miner { |
| 2586 | btf_socket_t fd; | 2649 | btf_socket_t fd; |
| 2587 | bool authorised = false; | 2650 | bool authorised = false; |
| @@ -2609,11 +2672,80 @@ struct Miner { | |||
| 2609 | int64 lastShareTime = 0; // GetTime() of the previous accepted share | 2672 | int64 lastShareTime = 0; // GetTime() of the previous accepted share |
| 2610 | double hashRate = 0.0; // smoothed H/s estimate | 2673 | double hashRate = 0.0; // smoothed H/s estimate |
| 2611 | 2674 | ||
| 2675 | // Replay guard for mining.submit (#8): nonces already credited on this | ||
| 2676 | // connection for the job it is currently working. Keyed to the job id in | ||
| 2677 | // seenNoncesJob and cleared by SendJob whenever that id changes, so a | ||
| 2678 | // resubmission under a NEW job is never turned away, while a replayed | ||
| 2679 | // (job_id, nonce) pair under the same job is refused before it can be | ||
| 2680 | // credited twice into roundShareCount -- the figure the payout split | ||
| 2681 | // divides by. | ||
| 2682 | std::set<uint32_t> seenNonces; | ||
| 2683 | std::string seenNoncesJob; | ||
| 2684 | |||
| 2612 | explicit Miner(btf_socket_t f) | 2685 | explicit Miner(btf_socket_t f) |
| 2613 | : fd(f), connectTime(GetTime()), | 2686 | : fd(f), connectTime(GetTime()), |
| 2614 | extranonce2(gNextExtranonce2.fetch_add(1)) {} | 2687 | extranonce2(gNextExtranonce2.fetch_add(1)) {} |
| 2615 | }; | 2688 | }; |
| 2616 | 2689 | ||
| 2690 | // What we publish as a miner's H/s: the last EWMA sample, faded out if shares | ||
| 2691 | // have stopped arriving (#7, policy at HASHRATE_IDLE_MISSES). | ||
| 2692 | // | ||
| 2693 | // This reads m->hashRate and never writes it. That is the whole design. The | ||
| 2694 | // first attempt decayed the stored estimate in place from the event loop's | ||
| 2695 | // sweep, which put a running accumulator behind a figure that is only ever | ||
| 2696 | // displayed, and the accumulator misbehaved in two ways: | ||
| 2697 | // | ||
| 2698 | // - `expected` was recomputed from the already-decayed estimate on every | ||
| 2699 | // pass, so each decay raised `expected`, which raised `grace`, which is | ||
| 2700 | // the very thing gating the next decay. `grace` simply chased `silent` | ||
| 2701 | // upward and the reported rate settled into a 1/t crawl instead of the | ||
| 2702 | // half-life curve the comment above promises -- 291x too high at ten | ||
| 2703 | // half-lives past the grace. Issue #7 is about the pool over-reporting; | ||
| 2704 | // that under-corrected it for hours. | ||
| 2705 | // - Once `expected` reached HASHRATE_MAX_INTERVAL it could not rise any | ||
| 2706 | // further, the feedback that had been gating each pass was gone, and the | ||
| 2707 | // decay began compounding once a second against the total elapsed | ||
| 2708 | // silence -- taking a miner from 0.4% of its baseline to 1e-11 of it in | ||
| 2709 | // the next hundred seconds, four hours in, for no reason a reader of | ||
| 2710 | // either the code or the announced number could see. | ||
| 2711 | // | ||
| 2712 | // Computing the value instead of accumulating it removes the failure mode | ||
| 2713 | // rather than tuning it: with no stored decay state there is nothing for a | ||
| 2714 | // tick rate, a missed pass or a duplicated pass to perturb, and the answer | ||
| 2715 | // depends only on how long the miner has actually been quiet. It also keeps | ||
| 2716 | // the fade out of the estimator -- the EWMA on the share path still blends | ||
| 2717 | // against the value it last computed, not against a faded copy of it, so a | ||
| 2718 | // miner that resumes recovers on exactly the curve it would have without any | ||
| 2719 | // of this. | ||
| 2720 | // | ||
| 2721 | // `now` is a parameter rather than a GetTime() call so that one refresh fades | ||
| 2722 | // every miner to the same instant, and so the policy is directly testable. | ||
| 2723 | static double MinerReportedHashRate(const Miner* m, int64 now) | ||
| 2724 | { | ||
| 2725 | // Nothing sampled yet: a fresh connection, or one that has found a single | ||
| 2726 | // share and so has no interval to have been timed over. Nothing to fade, | ||
| 2727 | // and nothing to divide by below. | ||
| 2728 | if (m->hashRate <= 0.0 || m->lastShareTime <= 0) return m->hashRate; | ||
| 2729 | |||
| 2730 | double expected = ExpectedHashesForDifficulty(m->difficulty) / m->hashRate; | ||
| 2731 | // Written so that a NaN would land on the floor rather than sail through: | ||
| 2732 | // the clamp is what guarantees `expected` is finite and strictly positive | ||
| 2733 | // below, whatever the division produced. | ||
| 2734 | if (!(expected > HASHRATE_MIN_INTERVAL)) expected = HASHRATE_MIN_INTERVAL; | ||
| 2735 | if (expected > HASHRATE_MAX_INTERVAL) expected = HASHRATE_MAX_INTERVAL; | ||
| 2736 | |||
| 2737 | double silent = (double)(now - m->lastShareTime); | ||
| 2738 | double grace = HASHRATE_IDLE_MISSES * expected; | ||
| 2739 | // grace is at least HASHRATE_IDLE_MISSES seconds, so a clock that has | ||
| 2740 | // stepped backwards gives a negative `silent`, takes this branch, and | ||
| 2741 | // reports the sample unchanged. Nothing here can scale an estimate up. | ||
| 2742 | if (!(silent > grace)) return m->hashRate; | ||
| 2743 | |||
| 2744 | double halflives = (silent - grace) / expected; | ||
| 2745 | if (halflives >= HASHRATE_DECAY_CUTOFF) return 0.0; | ||
| 2746 | return m->hashRate * pow(0.5, halflives); | ||
| 2747 | } | ||
| 2748 | |||
| 2617 | static std::vector<Miner*> gMiners; | 2749 | static std::vector<Miner*> gMiners; |
| 2618 | 2750 | ||
| 2619 | struct FoundBlock { int height; int64 ts; std::string addr; }; | 2751 | struct FoundBlock { int height; int64 ts; std::string addr; }; |
| @@ -2664,6 +2796,18 @@ static void LocalAcceptFn(void*) | |||
| 2664 | break; | 2796 | break; |
| 2665 | continue; | 2797 | continue; |
| 2666 | } | 2798 | } |
| 2799 | // #6: let the OS probe a peer that has gone silent, so a half-open | ||
| 2800 | // session eventually errors out of recv and lands in the event | ||
| 2801 | // loop's existing reap path instead of sitting in gMiners forever. | ||
| 2802 | // This is a backstop, not the mechanism: the default cadence before | ||
| 2803 | // the first probe is hours on most stacks, so the idle timeout in | ||
| 2804 | // PoolEventLoop fires long before keepalive does. Miners arriving | ||
| 2805 | // via a relay ride a loopback socket pair whose remote transport is | ||
| 2806 | // the rendezvous socket owned by the tunnel pump threads; keepalive | ||
| 2807 | // cannot reach across that, which is part of why the idle timeout | ||
| 2808 | // exists. | ||
| 2809 | int keepalive = 1; | ||
| 2810 | setsockopt(c, SOL_SOCKET, SO_KEEPALIVE, (char*)&keepalive, sizeof(keepalive)); | ||
| 2667 | LogPrint("pool", "[pool] miner arrived via loopback -- pushing to event loop\n"); | 2811 | LogPrint("pool", "[pool] miner arrived via loopback -- pushing to event loop\n"); |
| 2668 | PushReady((btf_socket_t)c); | 2812 | PushReady((btf_socket_t)c); |
| 2669 | } | 2813 | } |
| @@ -2707,6 +2851,16 @@ static const int64 POOL_ACTIVE_WINDOW = 300; // a miner is "active" if it | |||
| 2707 | static const int64 POOL_UNAUTH_GRACE_SECS = 60; // a connection still not | 2851 | static const int64 POOL_UNAUTH_GRACE_SECS = 60; // a connection still not |
| 2708 | // authorized after this long is | 2852 | // authorized after this long is |
| 2709 | // idle, not merely starting up | 2853 | // idle, not merely starting up |
| 2854 | // #6: a Miner used to leave gMiners only when RecvLine reported a clean | ||
| 2855 | // disconnect. A half-open session (miner host died, NAT state expired, | ||
| 2856 | // cable pulled) sends no FIN and reports no error, so it sat in the table | ||
| 2857 | // forever -- authorize outpaced disconnect 2:1 on the live pool, and the | ||
| 2858 | // table grew toward MAX_POOL_MINERS, past which real miners are refused. | ||
| 2859 | // lastSeen is stamped on every complete line received; a miner that has | ||
| 2860 | // said nothing for this long is gone in every way that matters. Ten | ||
| 2861 | // minutes is far beyond the vardiff target (a share every 15s) and the | ||
| 2862 | // stall watchdog (45s), so no miner that is actually hashing comes close. | ||
| 2863 | static const int64 POOL_IDLE_TIMEOUT_SECS = 600; | ||
| 2710 | 2864 | ||
| 2711 | // Non-blocking recv: pull whatever bytes are available now into buf, then | 2865 | // Non-blocking recv: pull whatever bytes are available now into buf, then |
| 2712 | // return one complete line if one is ready. Three outcomes: | 2866 | // return one complete line if one is ready. Three outcomes: |
| @@ -2791,6 +2945,17 @@ static json MakeNotifyParams(const StratumJob& job, const CBlock& b, | |||
| 2791 | static void SendJob(Miner* m, bool clean) | 2945 | static void SendJob(Miner* m, bool clean) |
| 2792 | { | 2946 | { |
| 2793 | if (!gHaveJob) return; | 2947 | if (!gHaveJob) return; |
| 2948 | // Every path that hands a miner a new job funnels through here, so this | ||
| 2949 | // is the one place the replay guard needs to follow the job id: nonces | ||
| 2950 | // credited under the previous job mean nothing under the new one. Keying | ||
| 2951 | // the clear to the id (rather than clearing unconditionally) keeps a | ||
| 2952 | // same-job re-notify -- the vardiff retarget and stall watchdog both | ||
| 2953 | // re-send the CURRENT job -- from reopening the duplicate window it | ||
| 2954 | // exists to close. | ||
| 2955 | if (m->seenNoncesJob != gCurrentJob.jobId) { | ||
| 2956 | m->seenNonces.clear(); | ||
| 2957 | m->seenNoncesJob = gCurrentJob.jobId; | ||
| 2958 | } | ||
| 2794 | CBlock mb = BuildMinerBlock(gCurrentJob, m->extranonce2); | 2959 | CBlock mb = BuildMinerBlock(gCurrentJob, m->extranonce2); |
| 2795 | // Use this miner's own shareTarget (set by vardiff) in the notify params. | 2960 | // Use this miner's own shareTarget (set by vardiff) in the notify params. |
| 2796 | // The participant miner reads p[3] as its share target, and HandleLine | 2961 | // The participant miner reads p[3] as its share target, and HandleLine |
| @@ -3049,6 +3214,22 @@ static bool HandleLine(Miner* m, const std::string& rawLine, | |||
| 3049 | } | 3214 | } |
| 3050 | unsigned int nNonce; memcpy(&nNonce, nb.data(), 4); | 3215 | unsigned int nNonce; memcpy(&nNonce, nb.data(), 4); |
| 3051 | 3216 | ||
| 3217 | // Reject a replayed (job, nonce) before it costs a rebuild and a | ||
| 3218 | // RandomX hash: nothing about the work below distinguishes a second | ||
| 3219 | // submission of a valid share from the first, so without this check | ||
| 3220 | // it passes every test and is credited again -- and roundShareCount | ||
| 3221 | // is what the payout split divides by, so each replay multiplies the | ||
| 3222 | // address's cut of the round. The set is per-connection and cleared | ||
| 3223 | // by SendJob on every job change, so only a same-job repeat is | ||
| 3224 | // refused. | ||
| 3225 | if (m->seenNonces.count(nNonce)) { | ||
| 3226 | LogPrint("worker", "[worker->pool] duplicate share from %s" | ||
| 3227 | " nonce=%u job=%s -- already credited, not counting again\n", | ||
| 3228 | m->address.c_str(), nNonce, submitJobId.c_str()); | ||
| 3229 | reply(false, "Duplicate share"); | ||
| 3230 | return true; | ||
| 3231 | } | ||
| 3232 | |||
| 3052 | // Rebuild this miner's exact block (unique merkle via extranonce2) | 3233 | // Rebuild this miner's exact block (unique merkle via extranonce2) |
| 3053 | CBlock b = BuildMinerBlock(gCurrentJob, m->extranonce2); | 3234 | CBlock b = BuildMinerBlock(gCurrentJob, m->extranonce2); |
| 3054 | b.nNonce = nNonce; | 3235 | b.nNonce = nNonce; |
| @@ -3076,6 +3257,7 @@ static bool HandleLine(Miner* m, const std::string& rawLine, | |||
| 3076 | m->roundShares++; | 3257 | m->roundShares++; |
| 3077 | m->totalShares++; | 3258 | m->totalShares++; |
| 3078 | m->vardiffShares++; | 3259 | m->vardiffShares++; |
| 3260 | m->seenNonces.insert(nNonce); // replay guard: credit each nonce once per job | ||
| 3079 | int64 shareTime = GetTime(); | 3261 | int64 shareTime = GetTime(); |
| 3080 | m->lastSeen = shareTime; | 3262 | m->lastSeen = shareTime; |
| 3081 | roundShareCount[m->address]++; | 3263 | roundShareCount[m->address]++; |
| @@ -4938,6 +5120,82 @@ int RunPoolStratumSelfTest() | |||
| 4938 | strPoolRoundsFile = savedRoundsFile; | 5120 | strPoolRoundsFile = savedRoundsFile; |
| 4939 | gPoolRounds = savedRounds; | 5121 | gPoolRounds = savedRounds; |
| 4940 | 5122 | ||
| 5123 | // -- hashrate decay (#7) -------------------------------------------------- | ||
| 5124 | // The first version of this decayed m->hashRate in place from the event | ||
| 5125 | // loop's sweep, which made the reported figure a function of how the loop | ||
| 5126 | // happened to run rather than of how long the miner had been quiet. These | ||
| 5127 | // pin the properties that fixes: sampling changes nothing, and the answer | ||
| 5128 | // depends only on elapsed silence. | ||
| 5129 | { | ||
| 5130 | // A miner exactly on the vardiff target: 4096 hashes per share at | ||
| 5131 | // difficulty 1.0, one share per 15s, so 4096/15 H/s. Its expected | ||
| 5132 | // interval is 15s and its grace is 60s. | ||
| 5133 | const double base = 4096.0 / 15.0; | ||
| 5134 | const int64 t0 = 1766000000; // any plausible non-zero wall clock | ||
| 5135 | Miner decayed(INVALID_SOCKET); | ||
| 5136 | decayed.difficulty = 1.0; | ||
| 5137 | decayed.hashRate = base; | ||
| 5138 | decayed.lastShareTime = t0; | ||
| 5139 | |||
| 5140 | check(MinerReportedHashRate(&decayed, t0 + 60) == base, | ||
| 5141 | "hashrate decay: a miner inside its grace period reports its full estimate"); | ||
| 5142 | |||
| 5143 | // Sampling must not consume the estimate. Twenty passes is one second | ||
| 5144 | // of the event loop's old sweep; a thousand is nearly a minute of it. | ||
| 5145 | double once = MinerReportedHashRate(&decayed, t0 + 61); | ||
| 5146 | bool idempotent = (decayed.hashRate == base); | ||
| 5147 | for (int i = 0; i < 1000 && idempotent; i++) | ||
| 5148 | idempotent = (MinerReportedHashRate(&decayed, t0 + 61) == once) && | ||
| 5149 | (decayed.hashRate == base); | ||
| 5150 | check(idempotent, | ||
| 5151 | "hashrate decay: repeated sampling returns one value and leaves the estimate alone"); | ||
| 5152 | |||
| 5153 | // One second past a 60s grace is 1/15th of a half-life: ~4.5% off, not | ||
| 5154 | // the estimate gone. A miner at the vardiff target overshoots its grace | ||
| 5155 | // roughly 1.8% of the time (e^-4) purely by share-timing variance, and | ||
| 5156 | // must not be zeroed for it. | ||
| 5157 | check(once > 0.94 * base && once < 0.96 * base, | ||
| 5158 | "hashrate decay: one second past grace costs a few percent, not the estimate"); | ||
| 5159 | double three = MinerReportedHashRate(&decayed, t0 + 63); | ||
| 5160 | check(three > 0.86 * base && three < 0.88 * base, | ||
| 5161 | "hashrate decay: three seconds past grace costs ~13%"); | ||
| 5162 | |||
| 5163 | // One half-life past the grace is exactly half. | ||
| 5164 | double half = MinerReportedHashRate(&decayed, t0 + 75); | ||
| 5165 | check(half > 0.499 * base && half < 0.501 * base, | ||
| 5166 | "hashrate decay: one expected interval past grace halves the estimate"); | ||
| 5167 | |||
| 5168 | // A miner that has genuinely stopped ends up reported as nothing -- | ||
| 5169 | // the whole point of #7. The old in-place version could not get here: | ||
| 5170 | // its decay fed back into its own grace and settled into a 1/t crawl. | ||
| 5171 | check(MinerReportedHashRate(&decayed, t0 + 3600) == 0.0, | ||
| 5172 | "hashrate decay: a miner silent for an hour is reported as zero"); | ||
| 5173 | |||
| 5174 | // A clock that steps backwards must never inflate what we announce. | ||
| 5175 | check(MinerReportedHashRate(&decayed, t0 - 3600) == base, | ||
| 5176 | "hashrate decay: a backwards clock reports the estimate unchanged, never higher"); | ||
| 5177 | |||
| 5178 | // Fresh connection, and a connection with one share and so no interval | ||
| 5179 | // to have timed: both must report nothing rather than divide by zero. | ||
| 5180 | Miner fresh(INVALID_SOCKET); | ||
| 5181 | check(MinerReportedHashRate(&fresh, t0) == 0.0, | ||
| 5182 | "hashrate decay: a miner that never submitted a share reports zero"); | ||
| 5183 | Miner single(INVALID_SOCKET); | ||
| 5184 | single.lastShareTime = t0; | ||
| 5185 | check(MinerReportedHashRate(&single, t0 + 86400) == 0.0, | ||
| 5186 | "hashrate decay: a miner with no rate sample yet reports zero"); | ||
| 5187 | |||
| 5188 | // Nothing in the swept range may produce a NaN, an infinity, a negative | ||
| 5189 | // rate, or a rate above the estimate it started from. | ||
| 5190 | bool finite = true; | ||
| 5191 | for (int64 s = -100; s < 200000 && finite; s += 37) { | ||
| 5192 | double v = MinerReportedHashRate(&decayed, t0 + s); | ||
| 5193 | finite = !std::isnan(v) && !std::isinf(v) && v >= 0.0 && v <= base; | ||
| 5194 | } | ||
| 5195 | check(finite, | ||
| 5196 | "hashrate decay: stays finite, non-negative and non-amplifying across a long silence"); | ||
| 5197 | } | ||
| 5198 | |||
| 4941 | gCurrentJob = savedJob; | 5199 | gCurrentJob = savedJob; |
| 4942 | gHaveJob = savedHaveJob; | 5200 | gHaveJob = savedHaveJob; |
| 4943 | 5201 | ||
| @@ -4965,6 +5223,10 @@ static void RefreshStats(int blocksFoundThisSession, uint64 roundShareTotal) | |||
| 4965 | if (m->authorised) gStats.authorizedMiners++; | 5223 | if (m->authorised) gStats.authorizedMiners++; |
| 4966 | 5224 | ||
| 4967 | gWorkerStats.clear(); | 5225 | gWorkerStats.clear(); |
| 5226 | // One timestamp for the whole sweep (#7): every miner is faded to the | ||
| 5227 | // same instant, so the per-worker rows and the total they are summed | ||
| 5228 | // into describe one moment rather than a smear across the loop. | ||
| 5229 | int64 nowStats = GetTime(); | ||
| 4968 | for (Miner* m : gMiners) { | 5230 | for (Miner* m : gMiners) { |
| 4969 | if (!m->authorised || m->lastSeen <= 0) continue; | 5231 | if (!m->authorised || m->lastSeen <= 0) continue; |
| 4970 | PoolWorkerStatView v; | 5232 | PoolWorkerStatView v; |
| @@ -4973,9 +5235,11 @@ static void RefreshStats(int blocksFoundThisSession, uint64 roundShareTotal) | |||
| 4973 | v.roundShares = m->roundShares; | 5235 | v.roundShares = m->roundShares; |
| 4974 | v.totalShares = m->totalShares; | 5236 | v.totalShares = m->totalShares; |
| 4975 | v.lastSeen = m->lastSeen; | 5237 | v.lastSeen = m->lastSeen; |
| 4976 | v.hashRate = m->hashRate; | 5238 | // Not m->hashRate: a miner that has stopped submitting shares must |
| 5239 | // not keep contributing its last sample to the announced total. | ||
| 5240 | v.hashRate = MinerReportedHashRate(m, nowStats); | ||
| 4977 | gWorkerStats.push_back(v); | 5241 | gWorkerStats.push_back(v); |
| 4978 | gStats.totalHashRate += m->hashRate; | 5242 | gStats.totalHashRate += v.hashRate; |
| 4979 | } | 5243 | } |
| 4980 | std::sort(gWorkerStats.begin(), gWorkerStats.end(), | 5244 | std::sort(gWorkerStats.begin(), gWorkerStats.end(), |
| 4981 | [](const PoolWorkerStatView& a, const PoolWorkerStatView& b) { | 5245 | [](const PoolWorkerStatView& a, const PoolWorkerStatView& b) { |
| @@ -5208,6 +5472,35 @@ static void PoolEventLoop() | |||
| 5208 | } | 5472 | } |
| 5209 | } | 5473 | } |
| 5210 | 5474 | ||
| 5475 | // 3.6. Idle reap (#6). Mirror the clean-disconnect path exactly -- | ||
| 5476 | // log, close, erase from gMiners via std::find, delete -- just with | ||
| 5477 | // a different reason. Shares the miner already earned stay in | ||
| 5478 | // roundShareCount, exactly as they do when a miner cleanly | ||
| 5479 | // disconnects mid-round. connectTime stands in for lastSeen on a | ||
| 5480 | // connection that never completed a line. Erasing inside the loop | ||
| 5481 | // above would invalidate the iteration, so collect then reap. | ||
| 5482 | { | ||
| 5483 | int64 now = GetTime(); | ||
| 5484 | std::vector<Miner*> idle; | ||
| 5485 | for (Miner* m : gMiners) { | ||
| 5486 | int64 last = (m->lastSeen > 0) ? m->lastSeen : m->connectTime; | ||
| 5487 | if (now - last > POOL_IDLE_TIMEOUT_SECS) | ||
| 5488 | idle.push_back(m); | ||
| 5489 | } | ||
| 5490 | for (Miner* m : idle) { | ||
| 5491 | LogPrint("worker", "[pool] dropping idle miner %s -- nothing" | ||
| 5492 | " received in over %llds (session shares: %llu," | ||
| 5493 | " round shares: %llu)\n", | ||
| 5494 | m->worker.empty() ? "(never authorized)" : m->worker.c_str(), | ||
| 5495 | (long long)POOL_IDLE_TIMEOUT_SECS, | ||
| 5496 | (unsigned long long)m->sessionShares, | ||
| 5497 | (unsigned long long)m->roundShares); | ||
| 5498 | sock_close(m->fd); | ||
| 5499 | gMiners.erase(std::find(gMiners.begin(), gMiners.end(), m)); | ||
| 5500 | delete m; | ||
| 5501 | } | ||
| 5502 | } | ||
| 5503 | |||
| 5211 | // 4. Select over miner sockets | 5504 | // 4. Select over miner sockets |
| 5212 | if (!gMiners.empty()) { | 5505 | if (!gMiners.empty()) { |
| 5213 | fd_set fds; FD_ZERO(&fds); | 5506 | fd_set fds; FD_ZERO(&fds); |
| @@ -5230,6 +5523,11 @@ static void PoolEventLoop() | |||
| 5230 | // terminate the whole node -- not just the pool. Every | 5523 | // terminate the whole node -- not just the pool. Every |
| 5231 | // line arrives from an unauthenticated socket. | 5524 | // line arrives from an unauthenticated socket. |
| 5232 | while (RecvLine(m->fd, m->readBuf, line, disc)) { | 5525 | while (RecvLine(m->fd, m->readBuf, line, disc)) { |
| 5526 | // Any complete line is proof of life (#6): authorize | ||
| 5527 | // and valid shares already stamp lastSeen themselves, | ||
| 5528 | // but a miner that only ever subscribes (or sends | ||
| 5529 | // unrecognised methods) must count as alive too. | ||
| 5530 | m->lastSeen = GetTime(); | ||
| 5233 | try { | 5531 | try { |
| 5234 | HandleLine(m, line, roundShareCount, | 5532 | HandleLine(m, line, roundShareCount, |
| 5235 | roundShareTotal, blocksFoundThisSession); | 5533 | roundShareTotal, blocksFoundThisSession); |
| @@ -5306,13 +5604,19 @@ static void AcceptOneFn(void* arg) | |||
| 5306 | std::string host = relay.substr(0, colon); | 5604 | std::string host = relay.substr(0, colon); |
| 5307 | int port = atoi(relay.substr(colon + 1).c_str()); | 5605 | int port = atoi(relay.substr(colon + 1).c_str()); |
| 5308 | 5606 | ||
| 5309 | LogPrint("pool", "[pool] accept thread started for relay %s\n", relay.c_str()); | 5607 | LogPrint("pool", "[pool] accept thread started for relay %s%s\n", relay.c_str(), |
| 5608 | fBtfRelayPinned ? " (/rvrelay pin)" : ""); | ||
| 5609 | |||
| 5610 | // Registration health for this relay. A pin has no fallback, so a pin that | ||
| 5611 | // never registers means the pool is simply unreachable -- and that has to | ||
| 5612 | // be loud. The 2026-07-30 incident went unnoticed because this loop logged | ||
| 5613 | // failures at one flat line and success not at all, so "which relay is this | ||
| 5614 | // pool actually registered at" could not be answered from the log. | ||
| 5615 | int nConsecFail = 0; | ||
| 5616 | int64 nFirstFail = 0; | ||
| 5617 | bool fEverRegistered = false; | ||
| 5310 | 5618 | ||
| 5311 | while (!fShutdown && gPoolRunning) { | 5619 | while (!fShutdown && gPoolRunning) { |
| 5312 | // Advertise this relay as the pool's meeting node BEFORE registering, | ||
| 5313 | // so that miners which resolve our descriptor find a relay where the | ||
| 5314 | // pool (not the node's peer-accept) holds the registration. | ||
| 5315 | BtfSetActiveRelay(relay); | ||
| 5316 | // Returns as soon as the relay lists us -- registered, not yet paired. | 5620 | // Returns as soon as the relay lists us -- registered, not yet paired. |
| 5317 | btf::RvSocket rv = btf::RvServiceRegister(host.c_str(), (unsigned short)port, pk); | 5621 | btf::RvSocket rv = btf::RvServiceRegister(host.c_str(), (unsigned short)port, pk); |
| 5318 | 5622 | ||
| @@ -5321,12 +5625,36 @@ static void AcceptOneFn(void* arg) | |||
| 5321 | break; | 5625 | break; |
| 5322 | } | 5626 | } |
| 5323 | if (rv == btf::RV_INVALID) { | 5627 | if (rv == btf::RV_INVALID) { |
| 5324 | LogPrint("pool", "[pool] relay %s: RvServiceRegister failed" | 5628 | nConsecFail++; |
| 5325 | " -- backing off 30s before retry\n", relay.c_str()); | 5629 | if (nFirstFail == 0) nFirstFail = GetTime(); |
| 5630 | LogPrint("pool", "[pool] relay %s: registration failed (attempt %d," | ||
| 5631 | " failing for %llds) -- backing off 30s before retry\n", | ||
| 5632 | relay.c_str(), nConsecFail, (long long)(GetTime() - nFirstFail)); | ||
| 5633 | if (fBtfRelayPinned && (nConsecFail == 3 || nConsecFail % 10 == 0)) | ||
| 5634 | LogPrint("pool", "[pool] WARNING: pinned relay %s refused registration" | ||
| 5635 | " %d times running (%llds); /rvrelay leaves no fallback, so" | ||
| 5636 | " miners cannot reach this pool%s\n", | ||
| 5637 | relay.c_str(), nConsecFail, (long long)(GetTime() - nFirstFail), | ||
| 5638 | fEverRegistered ? "" : " -- it has never registered once"); | ||
| 5326 | for (int i = 0; i < 30 && !fShutdown && gPoolRunning; i++) Sleep(1000); | 5639 | for (int i = 0; i < 30 && !fShutdown && gPoolRunning; i++) Sleep(1000); |
| 5327 | continue; | 5640 | continue; |
| 5328 | } | 5641 | } |
| 5329 | 5642 | ||
| 5643 | // Advertise THIS relay only now. Setting it before the call published a | ||
| 5644 | // meeting node we were not yet listed at, so a miner resolving the | ||
| 5645 | // descriptor inside that window burned its dial on a relay holding no | ||
| 5646 | // registration for us. net.cpp's peer-accept has always ordered it this | ||
| 5647 | // way round; the pool had not. | ||
| 5648 | BtfSetActiveRelay(relay); | ||
| 5649 | if (!fEverRegistered || nConsecFail > 0) | ||
| 5650 | LogPrint("pool", "[pool] registered at relay %s%s%s -- advertising it as" | ||
| 5651 | " the pool's meeting node\n", relay.c_str(), | ||
| 5652 | fBtfRelayPinned ? " (/rvrelay pin)" : "", | ||
| 5653 | nConsecFail > 0 ? ", recovered" : ""); | ||
| 5654 | fEverRegistered = true; | ||
| 5655 | nConsecFail = 0; | ||
| 5656 | nFirstFail = 0; | ||
| 5657 | |||
| 5330 | // Block for a miner to actually arrive. RvServiceRegister used to do | 5658 | // Block for a miner to actually arrive. RvServiceRegister used to do |
| 5331 | // this itself and returned with the relay's 0x01 pairing byte already | 5659 | // this itself and returned with the relay's 0x01 pairing byte already |
| 5332 | // consumed; it no longer does. Without waiting here, BtfServiceWrap | 5660 | // consumed; it no longer does. Without waiting here, BtfServiceWrap |
| @@ -5381,9 +5709,21 @@ static void AcceptLoopFn(void*) | |||
| 5381 | LogPrint("pool", "[pool] .btf identity ready after %ds\n", waitSecs * 2); | 5709 | LogPrint("pool", "[pool] .btf identity ready after %ds\n", waitSecs * 2); |
| 5382 | 5710 | ||
| 5383 | std::set<std::string> spawned; // relays we've already started a thread for | 5711 | std::set<std::string> spawned; // relays we've already started a thread for |
| 5712 | std::set<std::string> skipped; // discovered relays the pin excluded, logged once each | ||
| 5384 | 5713 | ||
| 5385 | while (!fShutdown && gPoolRunning) { | 5714 | while (!fShutdown && gPoolRunning) { |
| 5715 | // BtfAllRelays() already honours the pin: with /rvrelay set it returns | ||
| 5716 | // vBtfMeetingRelays alone, so no thread is ever spawned for a | ||
| 5717 | // discovered relay. Name the ones it drops -- a pool registering at a | ||
| 5718 | // stranger's relay is exactly the thing that should not be silent. | ||
| 5386 | vector<string> relays = BtfAllRelays(); | 5719 | vector<string> relays = BtfAllRelays(); |
| 5720 | if (fBtfRelayPinned) { | ||
| 5721 | for (const string& r : BtfDiscoveredRelays()) | ||
| 5722 | if (std::find(relays.begin(), relays.end(), r) == relays.end() && | ||
| 5723 | skipped.insert(r).second) | ||
| 5724 | LogPrint("pool", "[pool] not registering at discovered relay %s" | ||
| 5725 | " -- /rvrelay pins the relay list\n", r.c_str()); | ||
| 5726 | } | ||
| 5387 | if (relays.empty()) { | 5727 | if (relays.empty()) { |
| 5388 | LogPrint("pool", "[pool] no relays available -- miners cannot connect yet\n"); | 5728 | LogPrint("pool", "[pool] no relays available -- miners cannot connect yet\n"); |
| 5389 | } else { | 5729 | } else { |
| @@ -5399,8 +5739,9 @@ static void AcceptLoopFn(void*) | |||
| 5399 | relay.c_str()); | 5739 | relay.c_str()); |
| 5400 | } else { | 5740 | } else { |
| 5401 | spawned.insert(relay); | 5741 | spawned.insert(relay); |
| 5402 | LogPrint("pool", "[pool] accept thread spawned for relay %s" | 5742 | LogPrint("pool", "[pool] accept thread spawned for relay %s%s" |
| 5403 | " (%zu total)\n", relay.c_str(), spawned.size()); | 5743 | " (%zu total)\n", relay.c_str(), |
| 5744 | fBtfRelayPinned ? " (/rvrelay pin)" : "", spawned.size()); | ||
| 5404 | } | 5745 | } |
| 5405 | } | 5746 | } |
| 5406 | } | 5747 | } |
| @@ -5436,10 +5777,17 @@ void ThreadRPCServer(void*) | |||
| 5436 | // armed for its one wallet probe before it is allowed to send. | 5777 | // armed for its one wallet probe before it is allowed to send. |
| 5437 | ReconcilePayouts(); | 5778 | ReconcilePayouts(); |
| 5438 | 5779 | ||
| 5439 | _beginthread(AcceptLoopFn, 0, NULL); | 5780 | // _beginthread cannot throw (it reports -1), but an unchecked failure |
| 5440 | _beginthread(LocalAcceptFn, 0, NULL); | 5781 | // leaves the pool running deaf: nobody accepts, announces, or pays, and |
| 5441 | _beginthread(ThreadBtfPoolAnnouncer, 0, NULL); | 5782 | // nothing in the log says why. |
| 5442 | _beginthread(PayoutThreadFn, 0, NULL); | 5783 | if (_beginthread(AcceptLoopFn, 0, NULL) == (uintptr_t)-1) |
| 5784 | LogPrint("pool", "[pool] FATAL: accept loop thread failed to spawn -- miners cannot connect\n"); | ||
| 5785 | if (_beginthread(LocalAcceptFn, 0, NULL) == (uintptr_t)-1) | ||
| 5786 | LogPrint("pool", "[pool] local accept thread failed to spawn\n"); | ||
| 5787 | if (_beginthread(ThreadBtfPoolAnnouncer, 0, NULL) == (uintptr_t)-1) | ||
| 5788 | LogPrint("pool", "[pool] announcer thread failed to spawn -- pool will not be advertised\n"); | ||
| 5789 | if (_beginthread(PayoutThreadFn, 0, NULL) == (uintptr_t)-1) | ||
| 5790 | LogPrint("pool", "[pool] FATAL: payout thread failed to spawn -- no one gets paid\n"); | ||
| 5443 | 5791 | ||
| 5444 | PoolEventLoop(); // blocks until gPoolRunning = false or fShutdown | 5792 | PoolEventLoop(); // blocks until gPoolRunning = false or fShutdown |
| 5445 | 5793 | ||
diff --git a/src/util.cpp b/src/util.cpp index 0cd0133..ab29178 100644 --- a/src/util.cpp +++ b/src/util.cpp | |||
| @@ -7,6 +7,12 @@ | |||
| 7 | 7 | ||
| 8 | 8 | ||
| 9 | bool fDebug = false; | 9 | bool fDebug = false; |
| 10 | bool fDebugRelay = false; | ||
| 11 | |||
| 12 | // In-process cap for debug.log, in bytes. Default matches the 1G trigger of | ||
| 13 | // the shipped logrotate policy so a long-running node stays bounded even | ||
| 14 | // without it; -maxdebugfilesize=N (MB) tunes it, 0 disables. | ||
| 15 | int64 nMaxDebugFileSize = 1024 * 1024 * (int64)1024; | ||
| 10 | 16 | ||
| 11 | // --------------------------------------------------------------------------- | 17 | // --------------------------------------------------------------------------- |
| 12 | // Categorized, burst-collapsing logging -- see the LogPrint doc comment in | 18 | // Categorized, burst-collapsing logging -- see the LogPrint doc comment in |
| @@ -26,10 +32,22 @@ static bool LogCategoryDefaultOn(const char* category) | |||
| 26 | strcmp(category, "payout") == 0; | 32 | strcmp(category, "payout") == 0; |
| 27 | } | 33 | } |
| 28 | 34 | ||
| 35 | // Categories so noisy they drown out everything else even under -debug: | ||
| 36 | // per-message send traces, wallet relay rebroadcasts, raw CBlock dumps and | ||
| 37 | // per-address discovery lines made up ~90% of a 13-hour production capture | ||
| 38 | // (issue #35). They need /debugrelay, not merely /debug. | ||
| 39 | static bool LogCategoryVerboseOnly(const char* category) | ||
| 40 | { | ||
| 41 | return strcmp(category, "relay") == 0 || | ||
| 42 | strcmp(category, "nostrdiscovery") == 0; | ||
| 43 | } | ||
| 44 | |||
| 29 | bool LogAcceptsCategory(const char* category) | 45 | bool LogAcceptsCategory(const char* category) |
| 30 | { | 46 | { |
| 31 | if (LogCategoryDefaultOn(category)) | 47 | if (LogCategoryDefaultOn(category)) |
| 32 | return true; | 48 | return true; |
| 49 | if (LogCategoryVerboseOnly(category)) | ||
| 50 | return fDebugRelay; | ||
| 33 | return fDebug; | 51 | return fDebug; |
| 34 | } | 52 | } |
| 35 | 53 | ||
| @@ -47,6 +65,61 @@ struct LogDedupState { | |||
| 47 | static std::map<std::string, LogDedupState> g_logDedup; | 65 | static std::map<std::string, LogDedupState> g_logDedup; |
| 48 | static CCriticalSection cs_logDedup; | 66 | static CCriticalSection cs_logDedup; |
| 49 | 67 | ||
| 68 | // A pending "(N similar)" summary, lifted out of the table while the lock is | ||
| 69 | // held and written after it is released. | ||
| 70 | struct LogDedupFlush { | ||
| 71 | std::string category; | ||
| 72 | int suppressed; | ||
| 73 | int64 elapsed; // how long the window that counted them ran | ||
| 74 | std::string lastMsg; | ||
| 75 | }; | ||
| 76 | |||
| 77 | static int64 g_logDedupLastSweep = 0; | ||
| 78 | |||
| 79 | static void EmitDedupSummary(const LogDedupFlush& f) | ||
| 80 | { | ||
| 81 | OutputDebugStringF("[%s] (%d similar in %llds, last: %s)\n", | ||
| 82 | f.category.c_str(), f.suppressed, | ||
| 83 | (long long)f.elapsed, f.lastMsg.c_str()); | ||
| 84 | } | ||
| 85 | |||
| 86 | // A window is otherwise only closed out when its own call site fires again, so | ||
| 87 | // a burst that simply stops -- 100 ledger entries voided in one pass and then | ||
| 88 | // silence -- leaves its count sitting in the table and the summary is never | ||
| 89 | // written at all. That is how 99 of 100 voids went unreported, with no "(N | ||
| 90 | // similar)" line to say anything was missing (issue #3). Sweep every expired | ||
| 91 | // window instead, so a finished burst is summarised as soon as anything at all | ||
| 92 | // is logged. | ||
| 93 | // | ||
| 94 | // Expired entries are erased rather than reopened: the window is over, so there | ||
| 95 | // is no state left worth keeping, and the next call from that site then takes | ||
| 96 | // the "first time" path and prints directly -- exactly what the rollover branch | ||
| 97 | // below would have done. It also stops the table growing without bound. | ||
| 98 | // | ||
| 99 | // Caller holds cs_logDedup; the summaries are written after it is released. | ||
| 100 | static void SweepExpiredWindowsLocked(int64 now, std::vector<LogDedupFlush>& out) | ||
| 101 | { | ||
| 102 | for (std::map<std::string, LogDedupState>::iterator it = g_logDedup.begin(); | ||
| 103 | it != g_logDedup.end(); ) | ||
| 104 | { | ||
| 105 | if (now - it->second.windowStart < DEDUP_WINDOW_SECS) | ||
| 106 | { | ||
| 107 | ++it; | ||
| 108 | continue; | ||
| 109 | } | ||
| 110 | if (it->second.suppressed > 0) | ||
| 111 | { | ||
| 112 | LogDedupFlush f; | ||
| 113 | f.category = it->first.substr(0, it->first.find('|')); | ||
| 114 | f.suppressed = it->second.suppressed; | ||
| 115 | f.elapsed = now - it->second.windowStart; | ||
| 116 | f.lastMsg = it->second.lastMsg; | ||
| 117 | out.push_back(f); | ||
| 118 | } | ||
| 119 | g_logDedup.erase(it++); | ||
| 120 | } | ||
| 121 | } | ||
| 122 | |||
| 50 | void LogPrintDedup(const char* category, const char* file, int line, const std::string& msgIn) | 123 | void LogPrintDedup(const char* category, const char* file, int line, const std::string& msgIn) |
| 51 | { | 124 | { |
| 52 | // Call sites follow the existing printf() convention of ending their | 125 | // Call sites follow the existing printf() convention of ending their |
| @@ -61,11 +134,19 @@ void LogPrintDedup(const char* category, const char* file, int line, const std:: | |||
| 61 | 134 | ||
| 62 | int64 now = GetTime(); | 135 | int64 now = GetTime(); |
| 63 | bool fEmitNow = false; | 136 | bool fEmitNow = false; |
| 64 | int suppressedToFlush = 0; | 137 | std::vector<LogDedupFlush> flushes; |
| 65 | std::string flushedMsg; | ||
| 66 | 138 | ||
| 67 | CRITICAL_BLOCK(cs_logDedup) | 139 | CRITICAL_BLOCK(cs_logDedup) |
| 68 | { | 140 | { |
| 141 | // At most once a second. The table holds one entry per call site that | ||
| 142 | // has fired in the last few seconds, so the walk is short, but it must | ||
| 143 | // not run once per line of a burst. | ||
| 144 | if (now != g_logDedupLastSweep) | ||
| 145 | { | ||
| 146 | g_logDedupLastSweep = now; | ||
| 147 | SweepExpiredWindowsLocked(now, flushes); | ||
| 148 | } | ||
| 149 | |||
| 69 | std::map<std::string, LogDedupState>::iterator it = g_logDedup.find(key); | 150 | std::map<std::string, LogDedupState>::iterator it = g_logDedup.find(key); |
| 70 | if (it == g_logDedup.end()) | 151 | if (it == g_logDedup.end()) |
| 71 | { | 152 | { |
| @@ -76,10 +157,18 @@ void LogPrintDedup(const char* category, const char* file, int line, const std:: | |||
| 76 | } | 157 | } |
| 77 | else if (now - it->second.windowStart >= DEDUP_WINDOW_SECS) | 158 | else if (now - it->second.windowStart >= DEDUP_WINDOW_SECS) |
| 78 | { | 159 | { |
| 79 | // Window rolled over: flush what was suppressed during it (if | 160 | // Window rolled over within the same second as the last sweep: |
| 80 | // anything), then start a new window with this call printed. | 161 | // flush what was suppressed during it (if anything), then start a |
| 81 | suppressedToFlush = it->second.suppressed; | 162 | // new window with this call printed. |
| 82 | flushedMsg = it->second.lastMsg; | 163 | if (it->second.suppressed > 0) |
| 164 | { | ||
| 165 | LogDedupFlush f; | ||
| 166 | f.category = category; | ||
| 167 | f.suppressed = it->second.suppressed; | ||
| 168 | f.elapsed = now - it->second.windowStart; | ||
| 169 | f.lastMsg = it->second.lastMsg; | ||
| 170 | flushes.push_back(f); | ||
| 171 | } | ||
| 83 | it->second.windowStart = now; | 172 | it->second.windowStart = now; |
| 84 | it->second.suppressed = 0; | 173 | it->second.suppressed = 0; |
| 85 | it->second.lastMsg = msg; | 174 | it->second.lastMsg = msg; |
| @@ -94,13 +183,23 @@ void LogPrintDedup(const char* category, const char* file, int line, const std:: | |||
| 94 | } | 183 | } |
| 95 | } | 184 | } |
| 96 | 185 | ||
| 97 | if (suppressedToFlush > 0) | 186 | for (size_t i = 0; i < flushes.size(); i++) |
| 98 | OutputDebugStringF("[%s] (%d similar in %llds, last: %s)\n", | 187 | EmitDedupSummary(flushes[i]); |
| 99 | category, suppressedToFlush, (long long)DEDUP_WINDOW_SECS, flushedMsg.c_str()); | ||
| 100 | if (fEmitNow) | 188 | if (fEmitNow) |
| 101 | OutputDebugStringF("[%s] %s\n", category, msg.c_str()); | 189 | OutputDebugStringF("[%s] %s\n", category, msg.c_str()); |
| 102 | } | 190 | } |
| 103 | 191 | ||
| 192 | // LogPrintAlways() -- see the doc comment in util.h. No window, no counting, | ||
| 193 | // no table entry: every call writes its own line. | ||
| 194 | void LogPrintNoCollapse(const char* category, const std::string& msgIn) | ||
| 195 | { | ||
| 196 | std::string msg = msgIn; | ||
| 197 | while (!msg.empty() && (msg.back() == '\n' || msg.back() == '\r')) | ||
| 198 | msg.pop_back(); | ||
| 199 | |||
| 200 | OutputDebugStringF("[%s] %s\n", category, msg.c_str()); | ||
| 201 | } | ||
| 202 | |||
| 104 | 203 | ||
| 105 | 204 | ||
| 106 | 205 | ||
| @@ -397,13 +496,37 @@ bool FileExists(const char* psz) | |||
| 397 | #endif | 496 | #endif |
| 398 | } | 497 | } |
| 399 | 498 | ||
| 400 | int GetFilesize(FILE* file) | 499 | #ifndef _WIN32 |
| 500 | // If off_t is 32 bits wide, ftello() truncates exactly like the int this | ||
| 501 | // function used to return. Fail the build rather than ship the silent | ||
| 502 | // version of the bug (32-bit hosts need -D_FILE_OFFSET_BITS=64). | ||
| 503 | static_assert(sizeof(off_t) >= 8, "GetFilesize needs a 64-bit off_t"); | ||
| 504 | #endif | ||
| 505 | |||
| 506 | // Returns the file's size in bytes, or -1 if it cannot be determined. | ||
| 507 | // | ||
| 508 | // This used to hold ftell()'s long in an int, so a file of 2 GiB or more came | ||
| 509 | // back negative. Its only caller is the debug.log roll in util.h, which skips | ||
| 510 | // the roll on a negative size -- i.e. rotation switched itself off for good at | ||
| 511 | // exactly the size the roll exists to prevent, and any cap of 2048 MB or more | ||
| 512 | // could never be exceeded at all. Both failures were silent. | ||
| 513 | int64 GetFilesize(FILE* file) | ||
| 401 | { | 514 | { |
| 402 | int nSavePos = ftell(file); | 515 | #ifdef _WIN32 |
| 403 | int nFilesize = -1; | 516 | __int64 nSavePos = _ftelli64(file); |
| 404 | if (fseek(file, 0, SEEK_END) == 0) | 517 | int64 nFilesize = -1; |
| 405 | nFilesize = ftell(file); | 518 | if (nSavePos >= 0 && _fseeki64(file, 0, SEEK_END) == 0) |
| 406 | fseek(file, nSavePos, SEEK_SET); | 519 | nFilesize = _ftelli64(file); |
| 520 | if (nSavePos >= 0) | ||
| 521 | _fseeki64(file, nSavePos, SEEK_SET); | ||
| 522 | #else | ||
| 523 | off_t nSavePos = ftello(file); | ||
| 524 | int64 nFilesize = -1; | ||
| 525 | if (nSavePos >= 0 && fseeko(file, 0, SEEK_END) == 0) | ||
| 526 | nFilesize = ftello(file); | ||
| 527 | if (nSavePos >= 0) | ||
| 528 | fseeko(file, nSavePos, SEEK_SET); | ||
| 529 | #endif | ||
| 407 | return nFilesize; | 530 | return nFilesize; |
| 408 | } | 531 | } |
| 409 | 532 | ||
| @@ -87,6 +87,15 @@ inline T& REF(const T& val) | |||
| 87 | 87 | ||
| 88 | extern bool fDebug; | 88 | extern bool fDebug; |
| 89 | 89 | ||
| 90 | // /debugrelay: the per-message firehose ("relay" and "nostrdiscovery" | ||
| 91 | // categories) that even -debug keeps off. See LogAcceptsCategory(). | ||
| 92 | extern bool fDebugRelay; | ||
| 93 | |||
| 94 | // debug.log is rolled to debug.log.old once it grows past this many bytes | ||
| 95 | // (set from -maxdebugfilesize, in MB; 0 disables the check). See the roll | ||
| 96 | // site in OutputDebugStringF() below. | ||
| 97 | extern int64 nMaxDebugFileSize; | ||
| 98 | |||
| 90 | // --------------------------------------------------------------------------- | 99 | // --------------------------------------------------------------------------- |
| 91 | // Categorized, burst-collapsing logging | 100 | // Categorized, burst-collapsing logging |
| 92 | // | 101 | // |
| @@ -106,15 +115,29 @@ extern bool fDebug; | |||
| 106 | // 2. Burst collapse: repeated LogPrint() calls from the *same source line* | 115 | // 2. Burst collapse: repeated LogPrint() calls from the *same source line* |
| 107 | // only emit one line per DEDUP_WINDOW_SECS; if more calls land inside | 116 | // only emit one line per DEDUP_WINDOW_SECS; if more calls land inside |
| 108 | // that window they're counted instead of reprinted, and the count is | 117 | // that window they're counted instead of reprinted, and the count is |
| 109 | // flushed as a single "(xN similar in Ws)" line the moment the window | 118 | // flushed as a single "(xN similar in Ws)" line once the window expires |
| 110 | // rolls over. A loop discovering 500 peers by address now produces a | 119 | // -- whether or not that call site ever fires again. A loop discovering |
| 111 | // small, bounded number of lines instead of 500 -- log growth is capped | 120 | // 500 peers by address now produces a small, bounded number of lines |
| 112 | // by elapsed time, not by how many similar events happen to fire. | 121 | // instead of 500 -- log growth is capped by elapsed time, not by how |
| 122 | // many similar events happen to fire. | ||
| 123 | // | ||
| 124 | // Use LogPrintAlways() instead for anything that reports an irreversible | ||
| 125 | // change to money: an obligation voided, a payment sent, a payment that | ||
| 126 | // failed. One line standing in for an unknown number of identical events is | ||
| 127 | // a tidy report of peer chatter and a false report of a ledger. A reorg | ||
| 128 | // voiding 100 entries hits one source line 100 times inside one window; | ||
| 129 | // under LogPrint() that read as a single block losing a single 49.49 BTF | ||
| 130 | // payment, while 4,950 BTF of obligations were actually destroyed, and the | ||
| 131 | // discrepancy was only found by counting entries in pending_payouts.json | ||
| 132 | // (issue #3). Bounded log growth is not worth that ambiguity here. | ||
| 113 | // --------------------------------------------------------------------------- | 133 | // --------------------------------------------------------------------------- |
| 114 | bool LogAcceptsCategory(const char* category); | 134 | bool LogAcceptsCategory(const char* category); |
| 115 | void LogPrintDedup(const char* category, const char* file, int line, const std::string& msg); | 135 | void LogPrintDedup(const char* category, const char* file, int line, const std::string& msg); |
| 136 | void LogPrintNoCollapse(const char* category, const std::string& msg); | ||
| 116 | #define LogPrint(category, ...) \ | 137 | #define LogPrint(category, ...) \ |
| 117 | do { if (LogAcceptsCategory(category)) LogPrintDedup((category), __FILE__, __LINE__, strprintf(__VA_ARGS__)); } while (0) | 138 | do { if (LogAcceptsCategory(category)) LogPrintDedup((category), __FILE__, __LINE__, strprintf(__VA_ARGS__)); } while (0) |
| 139 | #define LogPrintAlways(category, ...) \ | ||
| 140 | do { if (LogAcceptsCategory(category)) LogPrintNoCollapse((category), strprintf(__VA_ARGS__)); } while (0) | ||
| 118 | 141 | ||
| 119 | // Every format string in this project goes through one of the four functions | 142 | // Every format string in this project goes through one of the four functions |
| 120 | // below -- `printf` itself is remapped to OutputDebugStringF just above, and | 143 | // below -- `printf` itself is remapped to OutputDebugStringF just above, and |
| @@ -145,7 +168,7 @@ void ParseString(const string& str, char c, vector<string>& v); | |||
| 145 | string FormatMoney(int64 n, bool fPlus=false); | 168 | string FormatMoney(int64 n, bool fPlus=false); |
| 146 | bool ParseMoney(const char* pszIn, int64& nRet); | 169 | bool ParseMoney(const char* pszIn, int64& nRet); |
| 147 | bool FileExists(const char* psz); | 170 | bool FileExists(const char* psz); |
| 148 | int GetFilesize(FILE* file); | 171 | int64 GetFilesize(FILE* file); |
| 149 | uint64 GetRand(uint64 nMax); | 172 | uint64 GetRand(uint64 nMax); |
| 150 | int64 GetTime(); | 173 | int64 GetTime(); |
| 151 | int64 GetAdjustedTime(); | 174 | int64 GetAdjustedTime(); |
| @@ -199,7 +222,7 @@ protected: | |||
| 199 | public: | 222 | public: |
| 200 | char* pszFile; | 223 | char* pszFile; |
| 201 | int nLine; | 224 | int nLine; |
| 202 | explicit CCriticalSection() { InitializeCriticalSection(&cs); } | 225 | explicit CCriticalSection() : pszFile(NULL), nLine(0) { InitializeCriticalSection(&cs); } |
| 203 | ~CCriticalSection() { DeleteCriticalSection(&cs); } | 226 | ~CCriticalSection() { DeleteCriticalSection(&cs); } |
| 204 | void Enter() { EnterCriticalSection(&cs); } | 227 | void Enter() { EnterCriticalSection(&cs); } |
| 205 | void Leave() { LeaveCriticalSection(&cs); } | 228 | void Leave() { LeaveCriticalSection(&cs); } |
| @@ -390,7 +413,65 @@ inline int OutputDebugStringF(const char* pszFormat, ...) | |||
| 390 | else | 413 | else |
| 391 | strDebugFile = "debug.log"; | 414 | strDebugFile = "debug.log"; |
| 392 | } | 415 | } |
| 416 | // Latched by a failed rename in the roll below, which cannot be | ||
| 417 | // retried usefully and must not be retried endlessly. | ||
| 418 | static bool fRollDisabled = false; | ||
| 393 | FILE* fileout = fopen(strDebugFile.c_str(), "a"); | 419 | FILE* fileout = fopen(strDebugFile.c_str(), "a"); |
| 420 | if (fileout && nMaxDebugFileSize > 0 && !fRollDisabled) | ||
| 421 | { | ||
| 422 | // Roll an overgrown debug.log before adding to it. Nothing in the | ||
| 423 | // tree shrinks this file once the process is running (there is no | ||
| 424 | // ShrinkDebugFile, and even Bitcoin's only ran at startup), so a | ||
| 425 | // node that stays up for months grows the log without bound -- | ||
| 426 | // production hit ~2 GiB. The file is opened and closed per line, | ||
| 427 | // so a rename is safe here: the next line simply reopens the | ||
| 428 | // path. One generation is kept as debug.log.old; logrotate | ||
| 429 | // (contrib/logrotate/) handles anything longer-term. | ||
| 430 | int64 nSize = GetFilesize(fileout); | ||
| 431 | if (nSize >= 0 && nSize > nMaxDebugFileSize) | ||
| 432 | { | ||
| 433 | fclose(fileout); | ||
| 434 | string strOldFile = strDebugFile + ".old"; | ||
| 435 | remove(strOldFile.c_str()); // rename() won't clobber on Windows | ||
| 436 | bool fRolled = (rename(strDebugFile.c_str(), strOldFile.c_str()) == 0); | ||
| 437 | int nRenameErrno = errno; // before fopen() can overwrite it | ||
| 438 | fileout = fopen(strDebugFile.c_str(), "a"); | ||
| 439 | if (fRolled) | ||
| 440 | { | ||
| 441 | if (fileout) | ||
| 442 | fprintf(fileout, | ||
| 443 | "debug.log grew past %lld MB; previous contents moved to debug.log.old (-maxdebugfilesize)\n", | ||
| 444 | (long long)(nMaxDebugFileSize / 1024 / 1024)); | ||
| 445 | } | ||
| 446 | else if (nRenameErrno == ENOENT) | ||
| 447 | { | ||
| 448 | // The file went away between the size check and the | ||
| 449 | // rename, so an external rotator (logrotate) got there | ||
| 450 | // first. Nothing left to roll and nothing wrong: the | ||
| 451 | // fopen above has already recreated it. Latching on this | ||
| 452 | // would let a benign race with logrotate switch the cap | ||
| 453 | // off for the rest of the run. | ||
| 454 | } | ||
| 455 | else | ||
| 456 | { | ||
| 457 | // The file is still over the cap, so this branch would be | ||
| 458 | // reached again on the next line and every line after it. | ||
| 459 | // Unlatched, the complaint about failing to roll becomes | ||
| 460 | // the runaway growth the roll exists to prevent. Say it | ||
| 461 | // once and stop trying -- on stderr too, because whatever | ||
| 462 | // blocked the rename (read-only mount, permissions, EXDEV | ||
| 463 | // across a bind mount) may equally block the log write. | ||
| 464 | fRollDisabled = true; | ||
| 465 | fprintf(stderr, | ||
| 466 | "cannot roll %s (rename to .old failed: %s); -maxdebugfilesize disabled for this run\n", | ||
| 467 | strDebugFile.c_str(), strerror(nRenameErrno)); | ||
| 468 | if (fileout) | ||
| 469 | fprintf(fileout, | ||
| 470 | "cannot roll debug.log (rename to .old failed: %s); -maxdebugfilesize disabled for this run\n", | ||
| 471 | strerror(nRenameErrno)); | ||
| 472 | } | ||
| 473 | } | ||
| 474 | } | ||
| 394 | if (fileout) | 475 | if (fileout) |
| 395 | { | 476 | { |
| 396 | va_list arg_ptr; | 477 | va_list arg_ptr; |