PowerDNS / pdns

PowerDNS Authoritative, PowerDNS Recursor, dnsdist
https://www.powerdns.com/
GNU General Public License v2.0
3.7k stars 908 forks source link

TSAN complains about strftime() calls #11640

Open omoerbeek opened 2 years ago

omoerbeek commented 2 years ago

TSAN reported an issue while working on the structured logging code. I solved that locally, but we might need to go for a common solution: providing a mutex protected strftime().

The underlying issue is that strftime() calls tzset(), this call is mandated by Posix. tzset() and strtime() are marked MT-Safe env locale in the Linux manual pages. tzset() is marked not thread safe by Posix. Both env and locale have this in attributes(7):

              We do not mark these functions as MT-Unsafe, however, because functions that modify the  locale  object  are
              marked  with const:locale and regarded as unsafe.  Being unsafe, the latter are not to be called when multi‐
              ple threads are running or asynchronous signals are enabled, and so the locale can be considered effectively
              constant in these contexts, which makes the former safe.

Still TSAN is not happy. log produced (note that the actual strftime() call is not there, even while compiled with -fno-inline -fno-omit-frame-pointer -O1

WARNING: ThreadSanitizer: data race (pid=41771)
  Write of size 8 at 0x7b0400000060 by main thread:
    #0 free <null> (pdns_recursor+0x158a98)
    #1 tzset_internal time/tzset.c:401:3 (libc.so.6+0xbba59)
    #2 loggerBackend(Logging::Entry const&) /home/otto/pdns/pdns/recursordist/rec-main.cc:858:32 (pdns_recursor+0x6a3702)
    #3 Logging::Logger::logMessage(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, Log
r::Priority, boost::optional<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const>) const /ho
me/otto/pdns/pdns/recursordist/logging.cc:73:3 (pdns_recursor+0x31ecf6)

  Previous write of size 8 at 0x7b0400000060 by thread T1:
    #0 malloc <null> (pdns_recursor+0x15847c)
    #1 strdup string/strdup.c:42:15 (libc.so.6+0x8de4a)
    #2 loggerBackend(Logging::Entry const&) /home/otto/pdns/pdns/recursordist/rec-main.cc:858:32 (pdns_recursor+0x6a3702)
    #3 Logging::Logger::logMessage(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, Log

The offending code assigns to a static char * that does not seem to be protected in any way: https://sourceware.org/git?p=glibc.git;f=time/tzset.c;hb=HEAD#l401

So TSAN is right I think. I also could reproduce this issue outside rec, see below.

So I'm wondering what to do? Ignore and add to suppression file? Or provide a safestrftime()` wrapper and use it everywhere?

Short description

Environment

Steps to reproduce

#include <time.h>
#include <thread>
#include <iostream>

void f()
{
        while (true) {
                struct tm tm;
                time_t t = time(nullptr);
                localtime_r(&t, &tm);
                char buf[30];
                strftime(buf, sizeof(buf), "%s", &tm);
                std::cout << buf << std::endl;
        }
}

int
main()
{
        std::thread t1(f);
        std::thread t2(f);
        t1.join();
        t2.join();
}
c++ -O2 x.cc -pthread -fsanitize=thread

and run: ./a.out > /dev/null

Expected behaviour

Actual behaviour

Other information

hhoffstaette commented 2 years ago

I know boost is everyone's favourite library :-), but maybe Boost.Date_Time? Usage looks straightforward enough and this says it's thread-safe. Not sure about the micro-benchmark performance though.