Page MenuHomePhabricator

test: Fix wait_for_debug_log UnicodeDecodeError
ClosedPublic

Authored by PiRK on Nov 25 2022, 11:16.

Details

Reviewers
Fabien
Group Reviewers
Restricted Project
Commits
rABC9f3d2d181000: test: Fix wait_for_debug_log UnicodeDecodeError
Summary

Fix the intermittent UnicodeDecodeError when the debug log is truncated on an (multi-byte) unicode character by treating everything as bytes.

Also, remove the ignore_case option and there.search+re.escape wrap. All of this is unused and doesn't exist on raw byte strings.

This is a backport of core#25294

Depends on D12622

Note:
I added a typehint for expected_msgs because imo the parameter name is now misleading with regards to its type. This allowed the mypy linter to detect that a subsequent line defining print_log is now broken because log is now of type bytes and you cannot join bytes with str

Test Plan

ninja check-functional

Diff Detail

Event Timeline

PiRK requested review of this revision.Nov 25 2022, 11:16

Failed tests logs:

====== Bitcoin ABC functional tests: feature_abortnode.py ======

------- Stdout: -------
2022-11-25T11:20:48.265000Z TestFramework (INFO): Initializing test directory /work/abc-ci-builds/build-diff/test/tmp/test_runner_₿₵_  _20221125_112047/feature_abortnode_3
2022-11-25T11:21:28.783000Z TestFramework (ERROR): JSONRPC error
Traceback (most recent call last):
  File "/work/test/functional/test_framework/authproxy.py", line 187, in _get_response
    http_response = self.__conn.getresponse()
  File "/usr/lib/python3.9/http/client.py", line 1347, in getresponse
    response.begin()
  File "/usr/lib/python3.9/http/client.py", line 307, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.9/http/client.py", line 268, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/lib/python3.9/socket.py", line 704, in readinto
    return self._sock.recv_into(b)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/work/test/functional/test_framework/test_framework.py", line 132, in main
    self.setup()
  File "/work/test/functional/test_framework/test_framework.py", line 266, in setup
    self.setup_network()
  File "/work/test/functional/feature_abortnode.py", line 27, in setup_network
    self.setup_nodes()
  File "/work/test/functional/test_framework/test_framework.py", line 394, in setup_nodes
    self.import_deterministic_coinbase_privkeys()
  File "/work/test/functional/test_framework/test_framework.py", line 418, in import_deterministic_coinbase_privkeys
    n.createwallet(
  File "/work/test/functional/test_framework/test_node.py", line 949, in createwallet
    return self.__getattr__('createwallet')(
  File "/work/test/functional/test_framework/coverage.py", line 47, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
  File "/work/test/functional/test_framework/authproxy.py", line 160, in __call__
    response, status = self._request(
  File "/work/test/functional/test_framework/authproxy.py", line 117, in _request
    return self._get_response()
  File "/work/test/functional/test_framework/authproxy.py", line 189, in _get_response
    raise JSONRPCException({
test_framework.authproxy.JSONRPCException: 'createwallet' RPC took longer than 30 seconds. Consider using larger timeout for calls that take longer to return. (-344)
2022-11-25T11:21:28.839000Z TestFramework (INFO): Stopping nodes
2022-11-25T11:21:28.840000Z TestFramework.node0 (ERROR): Unable to stop node.
Traceback (most recent call last):
  File "/work/test/functional/test_framework/test_node.py", line 450, in stop_node
    self.stop(wait=wait)
  File "/work/test/functional/test_framework/coverage.py", line 47, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
  File "/work/test/functional/test_framework/authproxy.py", line 160, in __call__
    response, status = self._request(
  File "/work/test/functional/test_framework/authproxy.py", line 116, in _request
    self.__conn.request(method, path, postdata, headers)
  File "/usr/lib/python3.9/http/client.py", line 1255, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/usr/lib/python3.9/http/client.py", line 1266, in _send_request
    self.putrequest(method, url, **skips)
  File "/usr/lib/python3.9/http/client.py", line 1092, in putrequest
    raise CannotSendRequest(self.__state)
http.client.CannotSendRequest: Request-sent
2022-11-25T11:22:28.877000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
    def is_node_stopped(self):
        """Checks whether the node has stopped.

        Returns True if the node has stopped. False otherwise.
        This method is responsible for freeing resources (self.process)."""
        if not self.running:
            return True
        return_code = self.process.poll()
        if return_code is None:
            return False

        # process has stopped. Assert that it didn't return an error code.
        assert return_code == 0, self._node_msg(
            "Node returned non-zero exit code ({}) when stopping".format(return_code))
        self.running = False
        self.process = None
        self.rpc_connected = False
        self.rpc = None
        self.log.debug("Node stopped")
        return True
'''
[node 1] Cleaning up leftover process
[node 0] Cleaning up leftover process
------- Stderr: -------
Traceback (most recent call last):
  File "/work/test/functional/feature_abortnode.py", line 52, in <module>
    AbortNodeTest().main()
  File "/work/test/functional/test_framework/test_framework.py", line 153, in main
    exit_code = self.shutdown()
  File "/work/test/functional/test_framework/test_framework.py", line 281, in shutdown
    self.stop_nodes()
  File "/work/test/functional/test_framework/test_framework.py", line 521, in stop_nodes
    node.wait_until_stopped()
  File "/work/test/functional/test_framework/test_node.py", line 495, in wait_until_stopped
    wait_until_helper(
  File "/work/test/functional/test_framework/util.py", line 285, in wait_until_helper
    raise AssertionError(
AssertionError: Predicate ''''
    def is_node_stopped(self):
        """Checks whether the node has stopped.

        Returns True if the node has stopped. False otherwise.
        This method is responsible for freeing resources (self.process)."""
        if not self.running:
            return True
        return_code = self.process.poll()
        if return_code is None:
            return False

        # process has stopped. Assert that it didn't return an error code.
        assert return_code == 0, self._node_msg(
            "Node returned non-zero exit code ({}) when stopping".format(return_code))
        self.running = False
        self.process = None
        self.rpc_connected = False
        self.rpc = None
        self.log.debug("Node stopped")
        return True
''' not true after 60.0 seconds

Each failure log is accessible here:
Bitcoin ABC functional tests: feature_abortnode.py

Fabien requested changes to this revision.Nov 25 2022, 13:52
Fabien added a subscriber: Fabien.

back to your queue

This revision now requires changes to proceed.Nov 25 2022, 13:52

rebase.

Previous test failure is unrelated. I did not find any explanation for this failure. It could be a genuine timeout that happened on a slow server. The functional tests took 1663 seconds, when they usually take only about 1200 seconds on successful runs of build-diff (see for instance https://build.bitcoinabc.org/viewLog.html?buildId=470194&buildTypeId=BitcoinABC_BitcoinAbcStaging&tab=buildLog&_focus=112#_state=112)

This revision is now accepted and ready to land.Nov 25 2022, 15:19