segmentation fault on changing the log level while a camera is streaming

[wout-vitestro]

This might be a very niche use of the realsense SDK, but we suppress some known warnings while setting up a second camera while the first camera is already streaming. We do this by changing the log level by using the rs2::log_to_console function. When doing this, we sometimes observe segmentation faults. Looking at the stack trace this seems to be due to a race condition in the logger.

SDK version: 2.56.5 (but looking at the code I believe this is present in all SDK versions)
Programming language: c++ (but this is likely not contained to c++ applications only)
OS: linux

Steps to reproduce:

• Start streaming
• Continuous change the log level while streaming (although it might also happen at stop/close, I'm not totally sure about that)
• Observe the crash happening after a while

To make it happen even faster you can change the log level on a different thread. Script which can reproduce the issue:

main.cc

#include <librealsense2/h/rs_types.h>
#include <librealsense2/hpp/rs_processing.hpp>
#include <librealsense2/hpp/rs_sensor.hpp>
#include <librealsense2/rs.hpp>

#include <iostream>
#include <ostream>
#include <string>
#include <thread>
#include <vector>

namespace {

void Close(rs2::sensor& sensor) {
  try {
    sensor.close();
  } catch (const std::exception& e) {
    std::cout << e.what() << "\n";
  }
}

void Stop(rs2::sensor& sensor) {
  try {
    sensor.stop();
  } catch (const std::exception& e) {
    std::cout << e.what() << "\n";
  }
}

std::string StreamProfile2String(const rs2::stream_profile& profile) {
  const auto video_stream_profile = profile.as<rs2::video_stream_profile>();
  std::ostringstream stream_format;
  stream_format << profile.stream_name() << " " << profile.format() << " "
                << std::to_string(video_stream_profile.height()) << " " << std::to_string(video_stream_profile.fps());
  return stream_format.str();
}

std::optional<std::size_t> GetStreamProfileIndex(const std::vector<rs2::stream_profile>& profiles,
                                                 const std::string& input_profile_string) {
  for (std::size_t i = 0; i < profiles.size(); i++) {
    if (StreamProfile2String(profiles[i]) == input_profile_string) {
      return i;
    }
  }
  return std::nullopt;
}

void realsense_log_level_changer() {
  while (true) {
    rs2::log_to_console(RS2_LOG_SEVERITY_FATAL);
    std::this_thread::sleep_for(std::chrono::milliseconds(1));
    rs2::log_to_console(RS2_LOG_SEVERITY_WARN);
    std::this_thread::sleep_for(std::chrono::milliseconds(1));
  }
}

}  // namespace

int main([[maybe_unused]] int argc, [[maybe_unused]] char* argv[]) {
  auto log_level_changer = std::thread(realsense_log_level_changer);

  rs2::context rs_context;
  rs2::sensor depth_sensor;
  rs2::syncer syncer;

  for (auto device : rs_context.query_devices()) {
    depth_sensor = device.first<rs2::depth_sensor>();
  }

  const auto depth_sensor_profiles = depth_sensor.get_stream_profiles();
  const auto depth_profile_index = GetStreamProfileIndex(depth_sensor_profiles, "Depth Z16 720 15");
  const auto& depth_profile = depth_sensor_profiles[depth_profile_index.value()];

  unsigned int loop_no = 0;
  while (true) {
    ++loop_no;

    Stop(depth_sensor);
    Close(depth_sensor);
    depth_sensor.open(depth_profile);
    Stop(depth_sensor);
    depth_sensor.start(syncer);

    rs2::frameset rs_frameset;
    if (syncer.try_wait_for_frames(&rs_frameset, 5000) && rs_frameset.size() >= 1) {
      std::cout << "frame received\n";
    } else {
      std::cout << "no frame received\n";
    }

    Stop(depth_sensor);
    Close(depth_sensor);
    std::cout << "=== completed loop " << loop_no << " ===\n";
  }
}

CMakeLists.txt

cmake_minimum_required(VERSION 3.29)
set(CMAKE_CXX_STANDARD 20)
set(CMAKE_RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}/build)

project(realsense_test_tool)
add_executable(${PROJECT_NAME})

find_package(realsense2 REQUIRED)

target_include_directories(${PROJECT_NAME} PRIVATE ${realsense_INCLUDE_DIR})
target_link_libraries(${PROJECT_NAME} PUBLIC ${realsense2_LIBRARY})
target_sources(${PROJECT_NAME} PRIVATE main.cc)

And the stack trace from the segmentation fault, note that you can observe two different stack traces depending on how the race condition manifests:

Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x000075ab49b15142 in ?? () from /opt/vitestro/0.1/sysroots/corei7-64-poky-linux/lib64/librealsense2.so.2.56
[Current thread is 1 (Thread 0x75ab40ff96c0 (LWP 2301436))]
(gdb) bt full
#0  0x000075ab49b15142 in ?? () from /opt/vitestro/0.1/sysroots/corei7-64-poky-linux/lib64/librealsense2.so.2.56
No symbol table info available.
#1  0x000075ab49b15297 in ?? () from /opt/vitestro/0.1/sysroots/corei7-64-poky-linux/lib64/librealsense2.so.2.56
No symbol table info available.
#2  0x000075ab49b193e9 in el::base::TypedConfigurations::enabled(el::Level) () from /opt/vitestro/0.1/sysroots/corei7-64-poky-linux/lib64/librealsense2.so.2.56
No symbol table info available.
#3  0x000075ab49ab3b5c in librealsense::log_callback_end(unsigned int, double, double, rs2_stream, unsigned long long) () from /opt/vitestro/0.1/sysroots/corei7-64-poky-linux/lib64/librealsense2.so.2.56
No symbol table info available.
#4  0x000075ab49ac6db8 in ?? () from /opt/vitestro/0.1/sysroots/corei7-64-poky-linux/lib64/librealsense2.so.2.56
No symbol table info available.
#5  0x000075ab49ac7d7d in ?? () from /opt/vitestro/0.1/sysroots/corei7-64-poky-linux/lib64/librealsense2.so.2.56
No symbol table info available.
#6  0x000075ab499e9a8f in librealsense::platform::v4l_uvc_device::upload_video_and_metadata_from_syncer(librealsense::platform::buffers_mgr&) () from /opt/vitestro/0.1/sysroots/corei7-64-poky-linux/lib64/librealsense2.so.2.56
No symbol table info available.
#7  0x000075ab499ee404 in librealsense::platform::v4l_uvc_device::poll() () from /opt/vitestro/0.1/sysroots/corei7-64-poky-linux/lib64/librealsense2.so.2.56
No symbol table info available.
#8  0x000075ab499efe68 in librealsense::platform::v4l_uvc_device::capture_loop() () from /opt/vitestro/0.1/sysroots/corei7-64-poky-linux/lib64/librealsense2.so.2.56
No symbol table info available.
#9  0x000075ab4928d2c3 in ?? () from /opt/vitestro/0.1/sysroots/corei7-64-poky-linux/lib64/libstdc++.so.6
No symbol table info available.
#10 0x000075ab48f51929 in start_thread (arg=<optimized out>) at pthread_create.c:447
        ret = <optimized out>
        pd = <optimized out>
        out = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {129378390349504, 8511239737464722635, -152, 22, 140729077840256, 129378381959168, -7112452041363548981, -7112469585494666037}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#11 0x000075ab48fc9e9c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

Plus the logs:

realsense_test_tool[2301108]: === completed loop 154 ===
realsense_test_tool[2301108]:  25/02 14:01:42,613 ERROR [129378522867200] (rs.cpp:256) [rs2_stop( sensor:0x5f518957b500 ) Wrong Api Call Sequence] stop_streaming() failed. UVC device is not streaming!
realsense_test_tool[2301108]: stop_streaming() failed. UVC device is not streaming!
realsense_test_tool[2301108]:  25/02 14:01:42,613 ERROR [129378522867200] (rs.cpp:256) [rs2_close( sensor:0x5f518957b500 ) Wrong Api Call Sequence] close() failed. UVC device was not opened!
realsense_test_tool[2301108]: close() failed. UVC device was not opened!
realsense_test_tool[2301108]:  25/02 14:01:42,618 ERROR [129378522867200] (rs.cpp:256) [rs2_stop( sensor:0x5f518957b500 ) Wrong Api Call Sequence] stop_streaming() failed. UVC device is not streaming!
realsense_test_tool[2301108]: stop_streaming() failed. UVC device is not streaming!
realsense_test_tool[2301108]: frame received
realsense_test_tool[2301108]: === completed loop 155 ===
realsense_test_tool[2301108]:  25/02 14:01:42,936 ERROR [129378522867200] (rs.cpp:256) [rs2_stop( sensor:0x5f518957b500 ) Wrong Api Call Sequence] stop_streaming() failed. UVC device is not streaming!
realsense_test_tool[2301108]: stop_streaming() failed. UVC device is not streaming!
realsense_test_tool[2301108]:  25/02 14:01:42,936 ERROR [129378522867200] (rs.cpp:256) [rs2_close( sensor:0x5f518957b500 ) Wrong Api Call Sequence] close() failed. UVC device was not opened!
systemd[1]: realsense_test_tool.service: Main process exited, code=dumped, status=11/SEGV
systemd[1]: realsense_test_tool.service: Failed with result 'core-dump'.
systemd[1]: realsense_test_tool.service: Consumed 8.419s CPU time.

I would expect that changing the log level would not result in a crash.

[MartyG-RealSense]

Hi @wout-vitestro It may be worth posting a comment about your issue at PR #14718 as development work was recently being done there regarding addressing segmentation faults.

[Nir-Az]

Thanks for the inputs,
We'll take a look