[SERVER-46333] Server log output is incorrectly truncated in certain test environments Created: 22/Feb/20  Updated: 29/Oct/23  Resolved: 25/Feb/20

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: 4.3.4
Fix Version/s: 4.3.4

Type: Bug Priority: Major - P3
Reporter: Ian Boros Assignee: Henrik Edin
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Operating System: ALL
Sprint: Dev Tools 2020-02-24
Participants:

 Description   

Certain test suites (like noPassthrough) are reponsible for starting their own mongods. As part of this, the shell started by resmoke is responsible for printing/redirecting the servers output. The logging mechanism responsible for this has truncation enabled by default, meaning a log line which is marked as "truncation disabled" (like below) may still ultimately get truncated when running under certain test suites.

LOGV2_OPTIONS(31431, {logv2::LogTruncation::Disabled}, "{bt}", "bt"_attr = obj); 

 

A quick way to reproduce this is to add an absurdly long log message somewhere in the server and exercise it in a noPassthrough test. Here's a patch which adds one to the $planCacheStats agg stage (not a common code path). Base rev 2b61edc505e45acc7927aee40e4e8abeb99420cd.

diff --git a/src/mongo/db/pipeline/document_source_plan_cache_stats.cpp b/src/mongo/db/pipeline/document_source_plan_cache_stats.cpp
index 1d871a9521..19c7fe3d20 100644
--- a/src/mongo/db/pipeline/document_source_plan_cache_stats.cpp
+++ b/src/mongo/db/pipeline/document_source_plan_cache_stats.cpp
@@ -27,9 +27,12 @@
  *    it in the license file.
  */
 
+#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kQuery
+
 #include "mongo/platform/basic.h"
 
 #include "mongo/db/pipeline/document_source_plan_cache_stats.h"
+#include "mongo/logv2/log.h"
 
 namespace mongo {
 
@@ -49,6 +52,15 @@ boost::intrusive_ptr<DocumentSource> DocumentSourcePlanCacheStats::createFromBso
                           << " parameters object must be empty. Found: " << typeName(spec.type()),
             spec.embeddedObject().isEmpty());
 
+    static constexpr char fmtBt[] = "message from me: {bt}";
+    std::string giantStr;
+    for (int i = 0; i < 10232; ++i) {
+        giantStr += 's';
+    }
+    giantStr += "remainder";
+
+    LOGV2_OPTIONS(99999, {logv2::LogTruncation::Disabled}, fmtBt, "bt"_attr = giantStr);
+
     return new DocumentSourcePlanCacheStats(pExpCtx);
 } 

 

Then run a test which exercises this code:

myresmoke --suites=no_passthrough jstests/noPassthrough/plan_cache_stats_agg_source.js 

One would expect the entire string to be printed (including the word "remainder"), but only a prefix is printed.

 

I am using the following fix locally (so that I can continue other work). It might actually make sense to commit this (or something similar), since I doubt we use the ProgramOutputMultiplexer for anything besides testing, and we can enforce that log lines are truncated on mongod/mongos separately.

diff --git a/src/mongo/shell/shell_utils_launcher.cpp b/src/mongo/shell/shell_utils_launcher.cpp
index 592eda259d..869c948712 100644
--- a/src/mongo/shell/shell_utils_launcher.cpp
+++ b/src/mongo/shell/shell_utils_launcher.cpp
@@ -251,6 +251,7 @@ void ProgramOutputMultiplexer::appendLine(int port,
     auto plainShellOutputDomain = logger::globalLogManager()->getNamedDomain("plainShellOutput");
     logger::LogstreamBuilder builder(
         plainShellOutputDomain, getThreadName(), logger::LogSeverity::Log());
+    builder.setIsTruncatable(false);
 
     sinkProgramOutput(_buffer);
     sinkProgramOutput(builder);



 Comments   
Comment by Githook User [ 24/Feb/20 ]

Author:

{'name': 'Henrik Edin', 'username': 'henrikedin', 'email': 'henrik.edin@mongodb.com'}

Message: SERVER-46333 Disable log truncation in the shell ProgramMultiplexer

Logs coming from mongod/mongos will be truncated already if they should be.
Branch: master
https://github.com/mongodb/mongo/commit/93a28d58c8c01a610aa6e60bc969699fa02007df

Comment by Ian Boros [ 22/Feb/20 ]

NOTE: The way I ran into this (without modifying the server) was to run an operation that causes a crash. The backtrace that gets printed from this is often massive and would be subject to truncation from the shell. If you're having difficulty debugging a test/crash because the stack trace was truncated (and thus, cannot be symbolized) I would suggest applying the patch to shell_utils_launcher.

Generated at Thu Feb 08 05:11:10 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.