Bug 9

Unbounded IPC debug logging made the test harness run out of memory

Status

Fixed

Symptom

Out of memory; worst effect seen: test failure only

Where seen

Bitcoin Core functional tests

Trigger

Writing log output

First reported

2019-07-09 (first report)

Fixed

2019-07-15

Fix

mp#3

Shipped to Bitcoin Core

bitcoin#18677

In released binaries

No

Defect ever on master

Yes

Summary

IPC debug logging wrote the full escaped text of every request and response to debug.log with no size limit, so on the multiprocess branch the log grew large enough that the functional test harness died with a Python MemoryError reading it. The node itself did not fail. This was in libmultiprocess's first weeks, before Bitcoin Core used the library, so no release was affected. Fixed in mp#3 by truncating logged messages to about 1000 characters.

What happened

• On the bitcoin#10102 branch, which splits Bitcoin Core into node, wallet and GUI processes, feature_block.py failed on Travis (job 558040257) with a MemoryError raised inside test_node.assert_debug_log while it read debug.log. The harness ran out of memory because the log file had grown too large to read.
• No comment on bitcoin#10102 mentions it; ryanofsky quoted the traceback in the fix commit (2019-07-09) and linked the job from the mp#3 description.

Root cause

LogEscape() in src/mp/util.cpp escaped and returned the full kj::StringTree text of every IPC request and response for the IPC client send/recv and IPC server recv/send debug lines, with no size cap. feature_block.py pushes many full-size blocks through the node, and with IPC logging on, each block's bytes were rendered into debug.log as escaped text on both sides of the connection.

The unbounded rendering was in the library's initial commit. Running Bitcoin Core's full functional test suite against the library, in bitcoin#10102's CI from June 2019, was the first time large binary payloads were logged at that scale.

The code

Quoted from 724d2f7fe35c^. clientInvoke (include/mp/proxy-types.h) logs every request and response as text, and the server side logs its params and results the same way:

proxy_client.m_connection->m_loop.logPlain()
    << "{" << invoke_context.thread_context.thread_name << "} IPC client send "
    << TypeName<typename Request::Params>() << " " << LogEscape(request.toString());

LogEscape (src/mp/util.cpp) escapes the whole message, however large:

std::string LogEscape(const kj::StringTree& string)
{
    std::string result;
    string.visit([&](const kj::ArrayPtr<const char>& piece) {
        for (char c : piece) {
            // ...
            } else if (c < 0x20 || c > 0x7e) {
                char escape[4];
                snprintf(escape, 4, "\\%02x", c);
                result.append(escape);
            } else {
                result.push_back(c);
            }
        }
    });
    return result;
}

The text form of a call that passes a block contains the whole serialized block, so every such call wrote at least the block's size to debug.log, on both sides of the connection. After feature_block.py sent many large blocks, the test framework's assert_debug_log read the log into memory and failed with MemoryError.

The fix stops escaping once the result passes 1000 characters and marks the cut with ... (724d2f7fe35c):

@@ -31,8 +31,10 @@ std::string ThreadName(const char* exe_name)
 std::string LogEscape(const kj::StringTree& string)
 {
+    const int MAX_SIZE = 1000;
     std::string result;
     string.visit([&](const kj::ArrayPtr<const char>& piece) {
+        if (result.size() > MAX_SIZE) return;
         for (char c : piece) {
@@ -43,6 +45,10 @@ std::string LogEscape(const kj::StringTree& string)
                 result.push_back(c);
             }
+            if (result.size() > MAX_SIZE) {
+                result += "...";
+                break;
+            }
         }

Each log line now holds at most about 1000 characters of message text, whatever the size of the message.

Fix

724d2f7fe35c adds a MAX_SIZE = 1000 limit to LogEscape(): it stops visiting further string pieces once the result exceeds the limit and appends ... (+6/-0).

Timeline

• 2019-06-25: unbounded logging since 06e1045baba0, the initial commit.
• 2019-07-09: Travis MemoryError on bitcoin#10102; fix committed.
• 2019-07-15: fix merged in mp#3.
• 2020-05-21: first reached Bitcoin Core with the libmultiprocess depends package in bitcoin#18677, which already contains the fix.
• Never in a release.

Notes

• An unrelated slip in the same function: LogEscape tested if ('c' == '\\'), which is always false, so backslashes were never escaped. It was fixed separately in 22afe27d1e9e (mp#45, 2021).
• The observable failure was a test harness running out of memory, not a node crash; the lasting effect of the defect would have been unbounded debug.log growth whenever IPC logging was enabled.

Classification

The survey's classification of this bug. The explorer charts these fields across all bugs; the method page explains them.