Skip to content

Conversation

@ashgti
Copy link
Contributor

@ashgti ashgti commented Mar 18, 2025

I noticed this while debugging some unit tests that the logs occasionally would intersperse two log statements.

Previously, it was possible for a log statement to have two messages interspersed since the timestamp and log statement were two different writes to the log stream.

Instead, combine the logging into a single buffer first before printing.

…hunk.

Previously, it was possible for a log statement to have two messages interspersed since the timestamp and log statement were two different writes to the log stream.

Instead, combine the logging into a single buffer first before printing.
@llvmbot
Copy link
Member

llvmbot commented Mar 18, 2025

@llvm/pr-subscribers-lldb

Author: John Harrison (ashgti)

Changes

I noticed this while debugging some unit tests that the logs occasionally would intersperse two log statements.

Previously, it was possible for a log statement to have two messages interspersed since the timestamp and log statement were two different writes to the log stream.

Instead, combine the logging into a single buffer first before printing.


Full diff: https://github.com/llvm/llvm-project/pull/131916.diff

1 Files Affected:

  • (modified) lldb/tools/lldb-dap/DAPLog.h (+13-6)
diff --git a/lldb/tools/lldb-dap/DAPLog.h b/lldb/tools/lldb-dap/DAPLog.h
index 75a0a7d63a4f1..2574506739fea 100644
--- a/lldb/tools/lldb-dap/DAPLog.h
+++ b/lldb/tools/lldb-dap/DAPLog.h
@@ -23,8 +23,12 @@
     if (log_private) {                                                         \
       ::std::chrono::duration<double> now{                                     \
           ::std::chrono::system_clock::now().time_since_epoch()};              \
-      *log_private << ::llvm::formatv("{0:f9} ", now.count()).str()            \
-                   << ::llvm::formatv(__VA_ARGS__).str() << std::endl;         \
+      ::std::string out;                                                       \
+      ::llvm::raw_string_ostream os(out);                                      \
+      os << ::llvm::formatv("{0:f9} ", now.count()).str()                      \
+         << ::llvm::formatv(__VA_ARGS__).str() << "\n";                        \
+      *log_private << out;                                                     \
+      log_private->flush();                                                    \
     }                                                                          \
   } while (0)
 
@@ -37,10 +41,13 @@
     if (log_private && error_private) {                                        \
       ::std::chrono::duration<double> now{                                     \
           std::chrono::system_clock::now().time_since_epoch()};                \
-      *log_private << ::llvm::formatv("{0:f9} ", now.count()).str()            \
-                   << ::lldb_dap::FormatError(::std::move(error_private),      \
-                                              __VA_ARGS__)                     \
-                   << std::endl;                                               \
+      ::std::string out;                                                       \
+      ::llvm::raw_string_ostream os(out);                                      \
+      os << ::llvm::formatv("{0:f9} ", now.count()).str()                      \
+         << ::lldb_dap::FormatError(::std::move(error_private), __VA_ARGS__)   \
+         << "\n";                                                              \
+      *log_private << out;                                                     \
+      log_private->flush();                                                    \
     } else                                                                     \
       ::llvm::consumeError(::std::move(error_private));                        \
   } while (0)

Copy link
Member

@JDevlieghere JDevlieghere left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we just take a lock instead? I don't think this is all that much safer than what we had, depending on how buffering is implemented in std::ofstream.

@walter-erquinigo
Copy link
Member

walter-erquinigo commented Mar 18, 2025

You can't guarantee you are safe of print race conditions on all platforms just because you buffered the input to the stream writer and you have that manual flush. I'm pretty sure that now race conditions will be less frequent, but they can still happen.
The actual solution is to use a mutex + manual flush for all log writes. They can affect performance, but because logging is enabled in exceptional cases and there aren't that many logs per debug session, I imagine it will be fine.

@github-actions
Copy link

github-actions bot commented Mar 18, 2025

✅ With the latest revision this PR passed the C/C++ code formatter.

Copy link
Member

@JDevlieghere JDevlieghere left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🥳

@ashgti ashgti merged commit 7af0bfe into llvm:main Mar 19, 2025
6 of 9 checks passed
@ashgti ashgti deleted the lldb-dap-logs branch March 19, 2025 16:16
@llvm-ci
Copy link
Collaborator

llvm-ci commented Mar 19, 2025

LLVM Buildbot has detected a new failure on builder lldb-arm-ubuntu running on linaro-lldb-arm-ubuntu while building lldb at step 6 "test".

Full details are available at: https://lab.llvm.org/buildbot/#/builders/18/builds/13173

Here is the relevant piece of the build log for the reference
Step 6 (test) failure: build (failure)
...
PASS: lldb-api :: tools/lldb-dap/exception/TestDAP_exception.py (1157 of 2925)
UNSUPPORTED: lldb-api :: tools/lldb-dap/exception/objc/TestDAP_exception_objc.py (1158 of 2925)
UNSUPPORTED: lldb-api :: tools/lldb-dap/extendedStackTrace/TestDAP_extendedStackTrace.py (1159 of 2925)
PASS: lldb-api :: tools/lldb-dap/exception/cpp/TestDAP_exception_cpp.py (1160 of 2925)
PASS: lldb-api :: tools/lldb-dap/disconnect/TestDAP_disconnect.py (1161 of 2925)
PASS: lldb-api :: tools/lldb-dap/instruction-breakpoint/TestDAP_instruction_breakpoint.py (1162 of 2925)
PASS: lldb-api :: tools/lldb-dap/io/TestDAP_io.py (1163 of 2925)
PASS: lldb-api :: tools/lldb-dap/locations/TestDAP_locations.py (1164 of 2925)
PASS: lldb-api :: tools/lldb-dap/memory/TestDAP_memory.py (1165 of 2925)
PASS: lldb-api :: tools/lldb-dap/optimized/TestDAP_optimized.py (1166 of 2925)
FAIL: lldb-api :: tools/lldb-dap/output/TestDAP_output.py (1167 of 2925)
******************** TEST 'lldb-api :: tools/lldb-dap/output/TestDAP_output.py' FAILED ********************
Script:
--
/usr/bin/python3.10 /home/tcwg-buildbot/worker/lldb-arm-ubuntu/llvm-project/lldb/test/API/dotest.py -u CXXFLAGS -u CFLAGS --env LLVM_LIBS_DIR=/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./lib --env LLVM_INCLUDE_DIR=/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/include --env LLVM_TOOLS_DIR=/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./bin --arch armv8l --build-dir /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex --lldb-module-cache-dir /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex/module-cache-lldb/lldb-api --clang-module-cache-dir /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex/module-cache-clang/lldb-api --executable /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./bin/lldb --compiler /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./bin/clang --dsymutil /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./bin/dsymutil --make /usr/bin/gmake --llvm-tools-dir /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./bin --lldb-obj-root /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/tools/lldb --lldb-libs-dir /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./lib /home/tcwg-buildbot/worker/lldb-arm-ubuntu/llvm-project/lldb/test/API/tools/lldb-dap/output -p TestDAP_output.py
--
Exit Code: 1

Command Output (stdout):
--
lldb version 21.0.0git (https://github.com/llvm/llvm-project.git revision 7af0bfe62fff676c66a5394995b03030cf5baef4)
  clang revision 7af0bfe62fff676c66a5394995b03030cf5baef4
  llvm revision 7af0bfe62fff676c66a5394995b03030cf5baef4
Skipping the following test categories: ['libc++', 'dsym', 'gmodules', 'debugserver', 'objc']

--
Command Output (stderr):
--
========= DEBUG ADAPTER PROTOCOL LOGS =========
1742401981.689163923 --> (stdin/stdout) {"command":"initialize","type":"request","arguments":{"adapterID":"lldb-native","clientID":"vscode","columnsStartAt1":true,"linesStartAt1":true,"locale":"en-us","pathFormat":"path","supportsRunInTerminalRequest":true,"supportsVariablePaging":true,"supportsVariableType":true,"supportsStartDebuggingRequest":true,"sourceInitFile":false},"seq":1}
1742401981.692489147 <-- (stdin/stdout) {"body":{"__lldb":{"version":"lldb version 21.0.0git (https://github.com/llvm/llvm-project.git revision 7af0bfe62fff676c66a5394995b03030cf5baef4)\n  clang revision 7af0bfe62fff676c66a5394995b03030cf5baef4\n  llvm revision 7af0bfe62fff676c66a5394995b03030cf5baef4"},"completionTriggerCharacters":["."," ","\t"],"exceptionBreakpointFilters":[{"default":false,"filter":"cpp_catch","label":"C++ Catch"},{"default":false,"filter":"cpp_throw","label":"C++ Throw"},{"default":false,"filter":"objc_catch","label":"Objective-C Catch"},{"default":false,"filter":"objc_throw","label":"Objective-C Throw"}],"supportTerminateDebuggee":true,"supportsBreakpointLocationsRequest":true,"supportsCompletionsRequest":true,"supportsConditionalBreakpoints":true,"supportsConfigurationDoneRequest":true,"supportsDataBreakpoints":true,"supportsDelayedStackTraceLoading":true,"supportsDisassembleRequest":true,"supportsEvaluateForHovers":true,"supportsExceptionInfoRequest":true,"supportsExceptionOptions":true,"supportsFunctionBreakpoints":true,"supportsGotoTargetsRequest":false,"supportsHitConditionalBreakpoints":true,"supportsLoadedSourcesRequest":false,"supportsLogPoints":true,"supportsModulesRequest":true,"supportsProgressReporting":true,"supportsReadMemoryRequest":true,"supportsRestartFrame":false,"supportsRestartRequest":true,"supportsRunInTerminalRequest":true,"supportsSetVariable":true,"supportsStepBack":false,"supportsStepInTargetsRequest":true,"supportsSteppingGranularity":true,"supportsValueFormattingOptions":true},"command":"initialize","request_seq":1,"seq":0,"success":true,"type":"response"}
1742401981.692842484 --> (stdin/stdout) {"command":"launch","type":"request","arguments":{"program":"/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex/tools/lldb-dap/output/TestDAP_output.test_output/a.out","initCommands":["settings clear -all","settings set symbols.enable-external-lookup false","settings set target.inherit-tcc true","settings set target.disable-aslr false","settings set target.detach-on-error false","settings set target.auto-apply-fixits false","settings set plugin.process.gdb-remote.packet-timeout 60","settings set symbols.clang-modules-cache-path \"/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex/module-cache-lldb/lldb-api\"","settings set use-color false"],"exitCommands":["?script print('out\\0\\0', end='\\r\\n', file=sys.stdout)","?script print('err\\0\\0', end='\\r\\n', file=sys.stderr)"],"disableASLR":false,"enableAutoVariableSummaries":false,"enableSyntheticChildDebugging":false,"displayExtendedBacktrace":false,"commandEscapePrefix":null},"seq":2}
1742401981.693117380 <-- (stdin/stdout) {"body":{"category":"console","output":"Running initCommands:\n"},"event":"output","seq":0,"type":"event"}
1742401981.693140507 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings clear -all\n"},"event":"output","seq":0,"type":"event"}
1742401981.693151712 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set symbols.enable-external-lookup false\n"},"event":"output","seq":0,"type":"event"}
1742401981.693162203 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set target.inherit-tcc true\n"},"event":"output","seq":0,"type":"event"}
1742401981.693172932 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set target.disable-aslr false\n"},"event":"output","seq":0,"type":"event"}
1742401981.693183184 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set target.detach-on-error false\n"},"event":"output","seq":0,"type":"event"}
1742401981.693193913 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set target.auto-apply-fixits false\n"},"event":"output","seq":0,"type":"event"}
1742401981.693221569 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set plugin.process.gdb-remote.packet-timeout 60\n"},"event":"output","seq":0,"type":"event"}
1742401981.693233967 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set symbols.clang-modules-cache-path \"/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex/module-cache-lldb/lldb-api\"\n"},"event":"output","seq":0,"type":"event"}
1742401981.693244457 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set use-color false\n"},"event":"output","seq":0,"type":"event"}
1742401981.843765974 <-- (stdin/stdout) {"command":"launch","request_seq":2,"seq":0,"success":true,"type":"response"}
1742401981.843890429 <-- (stdin/stdout) {"body":{"isLocalProcess":true,"name":"/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex/tools/lldb-dap/output/TestDAP_output.test_output/a.out","startMethod":"launch","systemProcessId":1503894},"event":"process","seq":0,"type":"event"}
1742401981.843915224 <-- (stdin/stdout) {"event":"initialized","seq":0,"type":"event"}
1742401981.844311714 --> (stdin/stdout) {"command":"setBreakpoints","type":"request","arguments":{"source":{"name":"main.c","path":"main.c"},"sourceModified":false,"lines":[10],"breakpoints":[{"line":10}]},"seq":3}
1742401981.851707458 <-- (stdin/stdout) {"body":{"breakpoints":[{"column":3,"id":1,"instructionReference":"0x7FE6A8","line":10,"source":{"name":"main.c","path":"main.c"},"verified":true}]},"command":"setBreakpoints","request_seq":3,"seq":0,"success":true,"type":"response"}
1742401981.851858854 --> (stdin/stdout) {"command":"configurationDone","type":"request","arguments":{},"seq":4}
1742401981.851882935 <-- (stdin/stdout) {"command":"configurationDone","request_seq":4,"seq":0,"success":true,"type":"response"}

@llvm-ci
Copy link
Collaborator

llvm-ci commented Mar 19, 2025

LLVM Buildbot has detected a new failure on builder lldb-remote-linux-win running on as-builder-10 while building lldb at step 17 "test-check-lldb-api".

Full details are available at: https://lab.llvm.org/buildbot/#/builders/197/builds/2886

Here is the relevant piece of the build log for the reference
Step 17 (test-check-lldb-api) failure: Test just built components: check-lldb-api completed (failure)
******************** TEST 'lldb-api :: functionalities/thread/concurrent_events/TestConcurrentManyBreakpoints.py' FAILED ********************
Script:
--
C:/Python312/python.exe C:/buildbot/as-builder-10/lldb-x-aarch64/llvm-project/lldb\test\API\dotest.py -u CXXFLAGS -u CFLAGS --env LLVM_LIBS_DIR=C:/buildbot/as-builder-10/lldb-x-aarch64/build/./lib --env LLVM_INCLUDE_DIR=C:/buildbot/as-builder-10/lldb-x-aarch64/build/include --env LLVM_TOOLS_DIR=C:/buildbot/as-builder-10/lldb-x-aarch64/build/./bin --arch aarch64 --build-dir C:/buildbot/as-builder-10/lldb-x-aarch64/build/lldb-test-build.noindex --lldb-module-cache-dir C:/buildbot/as-builder-10/lldb-x-aarch64/build/lldb-test-build.noindex/module-cache-lldb\lldb-api --clang-module-cache-dir C:/buildbot/as-builder-10/lldb-x-aarch64/build/lldb-test-build.noindex/module-cache-clang\lldb-api --executable C:/buildbot/as-builder-10/lldb-x-aarch64/build/./bin/lldb.exe --compiler C:/buildbot/as-builder-10/lldb-x-aarch64/build/./bin/clang.exe --dsymutil C:/buildbot/as-builder-10/lldb-x-aarch64/build/./bin/dsymutil.exe --make C:/ninja/make.exe --llvm-tools-dir C:/buildbot/as-builder-10/lldb-x-aarch64/build/./bin --lldb-obj-root C:/buildbot/as-builder-10/lldb-x-aarch64/build/tools/lldb --lldb-libs-dir C:/buildbot/as-builder-10/lldb-x-aarch64/build/./lib --platform-url connect://jetson-agx-0086.lab.llvm.org:1234 --platform-working-dir /home/ubuntu/lldb-tests --sysroot c:/buildbot/fs/jetson-agx-ubuntu --env ARCH_CFLAGS=-mcpu=cortex-a78 --platform-name remote-linux --skip-category=lldb-server C:\buildbot\as-builder-10\lldb-x-aarch64\llvm-project\lldb\test\API\functionalities\thread\concurrent_events -p TestConcurrentManyBreakpoints.py
--
Exit Code: 1

Command Output (stdout):
--
lldb version 21.0.0git (https://github.com/llvm/llvm-project.git revision 7af0bfe62fff676c66a5394995b03030cf5baef4)
  clang revision 7af0bfe62fff676c66a5394995b03030cf5baef4
  llvm revision 7af0bfe62fff676c66a5394995b03030cf5baef4
Setting up remote platform 'remote-linux'

Connecting to remote platform 'remote-linux' at 'connect://jetson-agx-0086.lab.llvm.org:1234'...

Connected.

Setting remote platform working directory to '/home/ubuntu/lldb-tests'...

Skipping the following test categories: ['lldb-server', 'dsym', 'gmodules', 'debugserver', 'objc', 'lldb-dap']


--
Command Output (stderr):
--
FAIL: LLDB (C:\buildbot\as-builder-10\lldb-x-aarch64\build\bin\clang.exe-aarch64) :: test (TestConcurrentManyBreakpoints.ConcurrentManyBreakpoints.test)

======================================================================

FAIL: test (TestConcurrentManyBreakpoints.ConcurrentManyBreakpoints.test)

   Test 100 breakpoints from 100 threads.

----------------------------------------------------------------------

Traceback (most recent call last):

  File "C:\buildbot\as-builder-10\lldb-x-aarch64\llvm-project\lldb\packages\Python\lldbsuite\test\decorators.py", line 148, in wrapper

    return func(*args, **kwargs)

           ^^^^^^^^^^^^^^^^^^^^^

  File "C:\buildbot\as-builder-10\lldb-x-aarch64\llvm-project\lldb\test\API\functionalities\thread\concurrent_events\TestConcurrentManyBreakpoints.py", line 16, in test

    self.do_thread_actions(num_breakpoint_threads=100)

  File "C:\buildbot\as-builder-10\lldb-x-aarch64\llvm-project\lldb\packages\Python\lldbsuite\test\concurrent_base.py", line 225, in do_thread_actions

...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

6 participants