Repository: bitcoin/bitcoin (language: cpp)

Issue:
ci: ConnectionRefusedError: [WinError 10061] No connection could be made because the target machine actively refused it
Usually they come with a follow-up error of `Unable to connect to bitcoind after 2400s` (or similar).

This is a tracking issue, because all tests are affected.


Discussion / hints:
Given that no one has reproduced this locally yet, this may be an issue limited to GHA.
Seen recently here (`wallet_bumpfee.py --descriptors`) https://github.com/bitcoin/bitcoin/actions/runs/9863555844/job/27236587622#step:27:12496:
```bash
                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\test_node.py", line 188, in _raise_assertion_error
                                       raise AssertionError(self._node_msg(msg))
                                   AssertionError: [node 1] Unable to connect to bitcoind after 2400s
 test  2024-07-09T21:07:49.462000Z TestFramework (DEBUG): Closing down network thread 
```
Would something like this be useful in helping approach the root cause of this?

(Edit: updated diff based off [1](https://github.com/bitcoin/bitcoin/issues/30390#issuecomment-2311591619) [2](https://github.com/bitcoin/bitcoin/issues/30390#issuecomment-2311697202))
```diff
--- a/test/functional/test_framework/test_node.py
+++ b/test/functional/test_framework/test_node.py
@@ -5,6 +5,7 @@
 """Class for bitcoind node under test"""
 
 import contextlib
+from collections import Counter
 import decimal
 import errno
 from enum import Enum
@@ -260,6 +261,7 @@ class TestNode():
         """Sets up an RPC connection to the bitcoind process. Returns False if unable to connect."""
         # Poll at a rate of four times per second
         poll_per_s = 4
+        ignored_errors = Counter()
         for _ in range(poll_per_s * self.rpc_timeout):
             if self.process.poll() is not None:
                 # Attach abrupt shutdown error/s to the exception message
@@ -308,25 +310,32 @@ class TestNode():
                 return
             except JSONRPCException as e:  # Initialization phase
                 # -28 RPC in warmup
+                if e.error['code'] == -28:
+                    ignored_errors["JSONRPCException -28"] += 1
                 # -342 Service unavailable, RPC server started but is shutting down due to error
-                if e.error['code'] != -28 and e.error['code'] != -342:
+                # - Ignore the exception to properly raise the FailedToStartError.
+                elif e.error['code'] == -342:
+                    ignored_errors["JSONRPCException -342"] += 1
+                else:
                     raise  # unknown JSON RPC exception
-            except ConnectionResetError:
-                # This might happen when the RPC server is in warmup, but shut down before the call to getblockcount
-                # succeeds. Try again to properly raise the FailedToStartError
-                pass
             except OSError as e:
-                if e.errno == errno.ETIMEDOUT:
-                    pass  # Treat identical to ConnectionResetError
+                if e.errno == errno.ECONNRESET:
+                    # This might happen when the RPC server is in warmup, but shut down before the call to getblockcount
+                    # succeeds. Try again to properly raise the FailedToStartError
+                    ignored_errors["OSError.ECONNRESET"] += 1
+                elif e.errno == errno.ETIMEDOUT:
+                    ignored_errors["OSError.ETIMEDOUT"] += 1 # Treat identical to ECONNRESET
                 elif e.errno == errno.ECONNREFUSED:
-                    pass  # Port not yet open?
+                    ignored_errors["OSError.ECONNREFUSED"] += 1 # Port not yet open?
                 else:
                     raise  # unknown OS error
             except ValueError as e:  # cookie file not found and no rpcuser or rpcpassword; bitcoind is still starting
-                if "No RPC credentials" not in str(e):
+                if "No RPC credentials" in str(e):
+                    ignored_errors["missing_credentials"] += 1
+                else:
                     raise
             time.sleep(1.0 / poll_per_s)
-        self._raise_assertion_error("Unable to connect to bitcoind after {}s".format(self.rpc_timeout))
+        self._raise_assertion_error("Unable to connect to bitcoind after {}s (ignored_errors: {})".format(self.rpc_timeout, str(dict(ignored_errors))))
 
     def wait_for_cookie_credentials(self):
         """Ensures auth cookie credentials can be read, e.g. for testing CLI with -rpcwait before RPC connection is up."""
```
Not sure if patches like this could be applied to some subset of CI to help debug CI-only issues, slightly unclean, but maybe you've done similar things before?

~**Notable**: I removed the case for "-342 Service unavailable, RPC server started but is shutting down due to error". Seems like we should be failing if the server is shutting down instead of *silently ignoring it*.~
> **Notable**: I removed the case for "-342 Service unavailable, RPC server started but is shutting down due to error". Seems like we should be failing if the server is shutting down instead of _silently ignoring it_.

That'd revert 62c304ea481d474bc87d950e21907b8b05134fe7 and thus break existing tests, no?
For reference: You can use `git log -S "unique_code_blob"` to see when (and hopefully why) a piece of code was added. In this case it would be something like:

```
$ git log -S ' != -342' 
commit 62c304ea481d474bc87d950e21907b8b05134fe7
Date:   Sat Oct 6 13:42:11 2018 +0800

    tests: Allow closed http server in assert_start_raises_init_error

Other than that the patch 

> Seen recently here (`wallet_bumpfee.py --descriptors`) https://github.com/bitcoin/bitcoin/actions/runs/9863555844/job/27236587622#step:27:12496:

This one looks different, because `node1` never actually starts to start up. It doesn't even get to emit an `10061` error.
As for the ignored_errors counter, I presume it will just count `errno.ECONNREFUSED` for WinError 10061?
Thanks, I should have searched for why the -342 check was introduced before I suggested removing it. :facepalm: And my git-fu could do with some leveling up, that's impressive how it can single out the right commit.

Updated my [suggested diff](https://github.com/bitcoin/bitcoin/issues/30390#issuecomment-2311170636), bringing back the -342 check.

> As for the ignored_errors counter, I presume it will just count errno.ECONNREFUSED for WinError 10061?

Yes, that's what [ConnectionRefusedError seems to contain](https://docs.python.org/3/library/exceptions.html#ConnectionRefusedError). Also corrected & updated that part of the diff.
> Other than that the patch
> 
> > Seen recently here (`wallet_bumpfee.py --descriptors`) https://github.com/bitcoin/bitcoin/actions/runs/9863555844/job/27236587622#step:27:12496:
> 
> This one looks different, because `node1` never actually starts to start up. It doesn't even get to emit an `10061` error.

The linked log has:
```
 node1 2024-07-09T20:27:21.198248Z [shutoff] [D:\a\bitcoin\bitcoin\src\init.cpp:386] [Shutdown] Shutdown: done 
 test  2024-07-09T20:27:21.233000Z TestFramework.node1 (DEBUG): Node stopped 
 test  2024-07-09T20:27:21.233000Z TestFramework.node1 (DEBUG): bitcoind started, waiting for RPC to come up 
 node0 2024-07-09T20:27:52.439635Z [scheduler] [D:\a\bitcoin\bitcoin\src\net.cpp:2365] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers 
 node0 2024-07-09T20:42:07.454184Z [scheduler] [D:\a\bitcoin\bitcoin\src\net.cpp:2328] [DumpAddresses] [net] Flushed 0 addresses to peers.dat  1ms 
 node0 2024-07-09T20:57:07.475871Z [scheduler] [D:\a\bitcoin\bitcoin\src\net.cpp:2328] [DumpAddresses] [net] Flushed 0 addresses to peers.dat  1ms 
 test  2024-07-09T21:07:49.462000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\test_framework.py", line 132, in main
                                       self.run_test()
                                     File "D:\a\bitcoin\bitcoin/test/functional/wallet_bumpfee.py", line 99, in run_test
                                       test_bumpfee_with_abandoned_descendant_succeeds(self, rbf_node, rbf_node_address, dest_address)
                                     File "D:\a\bitcoin\bitcoin/test/functional/wallet_bumpfee.py", line 451, in test_bumpfee_with_abandoned_descendant_succeeds
                                       self.restart_node(1, ['-minrelaytxfee=0.00005'] + self.extra_args[1])
                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\test_framework.py", line 602, in restart_node
                                       self.start_node(i, extra_args)
                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\test_framework.py", line 554, in start_node
                                       node.wait_for_rpc_connection()
                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\test_node.py", line 314, in wait_for_rpc_connection
                                       self._raise_assertion_error("Unable to connect to bitcoind after {}s".format(self.rpc_timeout))
                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\test_node.py", line 188, in _raise_assertion_error
                                       raise AssertionError(self._node_msg(msg))
                                   AssertionError: [node 1] Unable to connect to bitcoind after 2400s
```
The first 2 lines in the excerpt show how node 1 is shutting down right before starting. This made me think of issues reusing TCP ports when restarting a process (stackoverflow [1](https://stackoverflow.com/questions/22549044/why-is-port-not-immediately-released-after-the-socket-closes) [2](https://stackoverflow.com/questions/3229860/what-is-the-meaning-of-so-reuseaddr-setsockopt-option-linux)).

Maybe it would be better for the test nodes to use new port numbers upon restart, especially for tests like `wallet_bumpfee.py` that use `restart_node`?

This could potentially be an issue between two different tests as well, if they shut down/start up quickly enough to still be within the TCP `TIME_WAIT` period.

Edit: I guess `TIME_WAIT` does not directly explain why connection still fails after *2400s*. But it could be a contributing factor.
(Btw, b22529529823c0cb5916ac318c8536e9107b7e78 did touch code raising `JSONRPCException` `-342` in the beginning of June. Don't see how that change would cause issues, but if it correlates with when you started seeing this, maybe it could be?)
> This could potentially be an issue between two different tests as well, if they shut down/start up quickly enough to still be within the TCP `TIME_WAIT` period.

I don't think different tests affect each other, because the test_runner assigns non-overlapping spans of ports for each test case (rpc, p2p, ...).

> Edit: I guess TIME_WAIT does not directly explain why connection still fails after 2400s. But it could be a contributing factor.

I don't think Bitcoin Core will re-try to start the HTTP RPC server, so if it fails once, it should fail always?

However, it looks like the node is never started at all. Same in https://github.com/bitcoin/bitcoin/actions/runs/9789643429/job/27029722411?pr=30356




> > This could potentially be an issue between two different tests as well, if they shut down/start up quickly enough to still be within the TCP `TIME_WAIT` period.
> 
> I don't think different tests affect each other, because the test_runner assigns non-overlapping spans of ports for each test case (rpc, p2p, ...).

Yes, different tests would get different PIDs, which feed into `p2p_port` etc, so port collisions between tests should not happen *unless PIDs are reused within a too short timeperiod*.

> > Edit: I guess TIME_WAIT does not directly explain why connection still fails after 2400s. But it could be a contributing factor.
> 
> I don't think Bitcoin Core will re-try to start the HTTP RPC server, so if it fails once, it should fail always?

That is my assumption too.

> However, it looks like the node is never started at all. Same in https://github.com/bitcoin/bitcoin/actions/runs/9789643429/job/27029722411?pr=30356

Yup, it sure is mysterious. At least having counters for the silent failures could provide some clues. Do you think I should create a PR for https://github.com/bitcoin/bitcoin/issues/30390#issuecomment-2311170636?

Something definitely seems to be causing bitcoind to keep running but stall somewhere for 2400s without returning an exit code from `.poll()`. Or as you say, Python Popen may be having issues in even starting the process for some reason.

Tangent: In another project, I once saw issues with subprocesses stalling on writing to `stdout` due to the parent process not reading from it quickly enough, so the OS buffer in between the processes would fill up. It was solved by spinning up a dedicated thread in the parent process which continuously read `stdout` from the child. But in our case we seem to mostly be writing subprocess `stdout` & `stderr` to a file, so only running out of disk would potentially cause it to block in a similar fashion to the other project. But running out of disk would hopefully spawn other errors too, making the issue clear.
Read through the docs on [Python Popen](https://docs.python.org/3/library/subprocess.html#subprocess.Popen) and didn't find anything suspicious. Would assume that `Popen` would raise an exception immediately if it fails to start `bitcoind`. Seems more likely that `bitcoind` has gone into an infinite loop/blocked for some reason early during startup.

Might be helpful if we could log the callstack(s) from the `bitcoind` process when hitting the 2400s timeout.
Also https://github.com/bitcoin/bitcoin/pull/28509.
> Also #28509.

Ah nice! I forgot about it. I guess it also underlines that the issue lies in starting the process.

Maybe GHA has some kind of "Anti-Virus" software that may block some processes?

> > > This could potentially be an issue between two different tests as well, if they shut down/start up quickly enough to still be within the TCP `TIME_WAIT` period.
> > 
> > 
> > I don't think different tests affect each other, because the test_runner assigns non-overlapping spans of ports for each test case (rpc, p2p, ...).
> 
> Yes, different tests would get different PIDs, which feed into `p2p_port` etc, so port collisions between tests should not happen _unless PIDs are reused within a too short timeperiod_.

Probably unrelated to this issue at this point, but the test_runner provides the `--portseed`, so no PID is used.
> Also #28509.

Thanks for the added context @hebasto! ~There seems to be some agreement that upgrading to Python 3.12 would [fix](https://github.com/bitcoin/bitcoin/pull/28509#issuecomment-1726482147) the issue. However, I was unable to find a documented fix, do you have a link? Your [comment](https://github.com/bitcoin/bitcoin/issues/28411#issuecomment-1724233900) links to an issue with `subprocess.run` but it's a higher-level function implemented on top of `subprocess.Popen` which we use.~

> Maybe GHA has some kind of "Anti-Virus" software that may block some processes?

Little experience with GHA, but yeah, those kind of things slowing down CI is not unheard of.

> Probably unrelated to this issue at this point, but the test_runner provides the `--portseed`, so no PID is used.

Thanks for pointing that out!
```python
test = self.test_list.pop(0)
portseed = len(self.test_list)
portseed_arg = ["--portseed={}".format(portseed)]
```
..that should indeed circumvent possible port-reuse issues stemming from OS PID reuse choices.

Given..
```python
def p2p_port(n):
    return PORT_MIN + n + (MAX_NODES * PortSeed.n) % (PORT_RANGE - 1 - MAX_NODES)
    # Constants: 11000 + n + (12 * PortSeed.n) % (5000 - 1 - 12)
    #          = 11000 + n + (12 * PortSeed.n) % (4987)
```
..we should be able to have 415 tests (4987 / 12) before tests at the beginning of the `test_list` risk colliding ports with tests at the end. From what I can see in **test/functional/test_runner.py** we have ~300 tests. :+1: 
> There seems to some agreement that upgrading to Python 3.12 would [fix](https://github.com/bitcoin/bitcoin/pull/28509#issuecomment-1726482147) the issue. However, I was unable to find a documented fix, do you have a link?

This was just a wrong comment by myself. See https://github.com/bitcoin/bitcoin/pull/28509#issuecomment-1727885738
Regarding process start issues, would there be any support for me attempting to integrate [Microsoft SysInternals ProcDump](https://learn.microsoft.com/en-us/sysinternals/downloads/procdump) into CI & test framework to be able to call `procdump -mm <PID>` on the `bitcoind.exe` process and hopefully figure out where the process is stalling?
Seems fine to integrate in a pull request and then keep the pull request unmerged, and only merge the pull request in the GHA CI, as that is the only place where it reproduces. Adding temporary test test-only code for everyone else may be a bit too much.
Alright, I can live with having it a pending PR until it has proven itself useful on CI. :)

Will see if I can get a Windows/Wine environment going locally and study how to integrate it into GHA.
Seen in https://github.com/bitcoin/bitcoin/actions/runs/10851531017/job/30115514734?pr=24123#step:12:242:
```bash
   File "C:\hostedtoolcache\windows\Python\3.12.5\x64\Lib\socket.py", line 850, in create_connection

    sock.connect(sa)

ConnectionRefusedError: [WinError 10061] No connection could be made because the target machine actively refused it
```
https://github.com/bitcoin/bitcoin/actions/runs/10907936867/job/30272762595?pr=30918#step:12:226
https://github.com/bitcoin/bitcoin/actions/runs/11164991068/job/31035622913?pr=30982#step:12:242
https://github.com/bitcoin/bitcoin/actions/runs/11265108219/job/31326367933#step:12:228

Fix patch:
diff --git a/src/random.cpp b/src/random.cpp
index 163112585ac4e..4d871d30bdee8 100644
--- a/src/random.cpp
+++ b/src/random.cpp
@@ -599,7 +599,7 @@ void SeedPeriodic(CSHA512& hasher, RNGState& rng) noexcept
     // Add the events hasher into the mix
     rng.SeedEvents(hasher);
 
-    // Dynamic environment data (performance monitoring, ...)
+    // Dynamic environment data (clocks, resource usage, ...)
     auto old_size = hasher.Size();
     RandAddDynamicEnv(hasher);
     LogDebug(BCLog::RAND, "Feeding %i bytes of dynamic environment data into RNG\n", hasher.Size() - old_size);
@@ -616,7 +616,7 @@ void SeedStartup(CSHA512& hasher, RNGState& rng) noexcept
     // Everything that the 'slow' seeder includes.
     SeedSlow(hasher, rng);
 
-    // Dynamic environment data (performance monitoring, ...)
+    // Dynamic environment data (clocks, resource usage, ...)
     auto old_size = hasher.Size();
     RandAddDynamicEnv(hasher);
 
diff --git a/src/random.h b/src/random.h
index 536e697ccaf01..2a26ca986be47 100644
--- a/src/random.h
+++ b/src/random.h
@@ -49,7 +49,7 @@
  *
  * - RandAddPeriodic() seeds everything that fast seeding includes, but additionally:
  *   - A high-precision timestamp
- *   - Dynamic environment data (performance monitoring, ...)
+ *   - Dynamic environment data (clocks, resource usage, ...)
  *   - Strengthen the entropy for 10 ms using repeated SHA512.
  *   This is run once every minute.
  *
diff --git a/src/randomenv.cpp b/src/randomenv.cpp
index dee48481c5a47..7a46a5109bce2 100644
--- a/src/randomenv.cpp
+++ b/src/randomenv.cpp
@@ -28,7 +28,6 @@
 
 #ifdef WIN32
 #include <windows.h>
-#include <winreg.h>
 #else
 #include <fcntl.h>
 #include <netinet/in.h>
@@ -64,45 +63,6 @@ extern char** environ; // NOLINT(readability-redundant-declaration): Necessary o
 
 namespace {
 
-void RandAddSeedPerfmon(CSHA512& hasher)
-{
-#ifdef WIN32
-    // Seed with the entire set of perfmon data
-
-    // This can take up to 2 seconds, so only do it every 10 minutes.
-    // Initialize last_perfmon to 0 seconds, we don't skip the first call.
-    static std::atomic<SteadyClock::time_point> last_perfmon{SteadyClock::time_point{0s}};
-    auto last_time = last_perfmon.load();
-    auto current_time = SteadyClock::now();
-    if (current_time < last_time + 10min) return;
-    last_perfmon = current_time;
-
-    std::vector<unsigned char> vData(250000, 0);
-    long ret = 0;
-    unsigned long nSize = 0;
-    const size_t nMaxSize = 10000000; // Bail out at more than 10MB of performance data
-    while (true) {
-        nSize = vData.size();
-        ret = RegQueryValueExA(HKEY_PERFORMANCE_DATA, "Global", nullptr, nullptr, vData.data(), &nSize);
-        if (ret != ERROR_MORE_DATA || vData.size() >= nMaxSize)
-            break;
-        vData.resize(std::min((vData.size() * 3) / 2, nMaxSize)); // Grow size of buffer exponentially
-    }
-    RegCloseKey(HKEY_PERFORMANCE_DATA);
-    if (ret == ERROR_SUCCESS) {
-        hasher.Write(vData.data(), nSize);
-        memory_cleanse(vData.data(), nSize);
-    } else {
-        // Performance data is only a best-effort attempt at improving the
-        // situation when the OS randomness (and other sources) aren't
-        // adequate. As a result, failure to read it is isn't considered critical,
-        // so we don't call RandFailure().
-        // TODO: Add logging when the logger is made functional before global
-        // constructors have been invoked.
-    }
-#endif
-}
-
 /** Helper to easily feed data into a CSHA512.
  *
  * Note that this does not serialize the passed object (like stream.h's << operators do).
@@ -227,8 +187,6 @@ void AddAllCPUID(CSHA512& hasher)
 
 void RandAddDynamicEnv(CSHA512& hasher)
 {
-    RandAddSeedPerfmon(hasher);
-
     // Various clocks
 #ifdef WIN32
     FILETIME ftime;


Test patch: