Static FastMutex fails to lock when issued from another thread on linux

[JoKre17]

Hello,
as the title says, we are getting an error and undefined behavior after logging 2-3 messages when using the LoggingConfigurator with the following logging properties file:

logging.formatters.pretty.class = PatternFormatter
logging.formatters.pretty.pattern = %Y-%m-%d %H:%M:%S.%i [%z] [%p] %s: %t
logging.formatters.pretty.times = local

logging.channels.console.class = ColorConsoleChannel
logging.channels.console.formatter = pretty

logging.channels.file.class = FileChannel
logging.channels.file.formatter = pretty
logging.channels.file.path = my_logging_file.log

logging.channels.splitter.class = SplitterChannel
logging.channels.splitter.channel = console,file

logging.channels.async.class = AsyncChannel
logging.channels.async.channel = splitter

logging.loggers.root.channel = async
logging.loggers.root.level = debug

We are using the AsyncChannel which runs another Thread. Further down the logging channel chain we are reaching the channel named "console" which is wrapped with the formatter named "pretty" which is calling PatternFormatter::format.
As we include "[%z]" in the format, the function in return calls Timezone::utcOffset().

Under linux the Timezone implementation contains the following (I've stripped out the unrelevant parts):

class TZInfo {
 public:
  TZInfo() { tzset(); }

  int timeZone() {
    Poco::FastMutex::ScopedLock lock(_mutex);  // <-- HERE we are getting an exception/undefined behavior

    tzset();
    return -timezone;
  }

 private:
  Poco::FastMutex _mutex;
};
static TZInfo tzInfo;

int Timezone::utcOffset() { return tzInfo.timeZone(); }

As TZInfo tzInfo including the FastMutex member is static, it will be created by the main thread. Now the logging contains an AsyncChannel running on a different thread which then fails to lock the FastMutex. (Line 27 in Foundation/src/Timezone_UNIX.cpp)

The code running pthread_mutex_lock (in this case MutexImpl::lockImpl) throws an exception without any catch handler which is likely the cause for the process hanging.
It seems on pthread_mutex_lock(&_mutex) we are getting the error code for EINVAL indicating that our logging thread has a higher priority than the main thread or the mutex handle _mutex is invalid.

Linux documentation says:

EINVAL
The mutex was created with the protocol attribute having the value PTHREAD_PRIO_PROTECT and the calling thread's priority is
higher than the mutex's current priority ceiling.
[...]
EINVAL
The value specified by mutex does not refer to an initialized mutex object.

The latter error is unlikely as we checked the mutex lock/unlock after initialization and dumped the pthread_mutex_t object showing no modification between construction and later after the error by lockImpl.

After debugging it seems weird to get this error as per default Poco does not set the protocol attribute (therefore it's PTHREAD_PRIO_NONE) and Poco seems to only creates threads with the schedule policy SCHED_OTHER (meaning no real time threads) and thus the priority must be 0.

For threads scheduled under one of the normal scheduling policies (SCHED_OTHER, SCHED_IDLE, SCHED_BATCH), sched_priority is not used in scheduling decisions (it must be specified as 0).
(Source)

After all of this I checked the implementation of tzset() to see if it's not already thread safely implemented.
And indeed, as discussed on Stack Overflow here, the tzset function already uses a lock as one can see here (glib.c) in line 562.

Therefore potential fixes for the issues with TZInfo in Poco could be solved by either removing the usage of Poco::FastMutex or to switch to a native mutex from stdlib or to use a Poco::SpinlockMutex.

Here is a minimal example to reproduce the bug:

#include "Poco/AsyncChannel.h"
#include "Poco/ConsoleChannel.h"
#include "Poco/FormattingChannel.h"
#include "Poco/Logger.h"
#include "Poco/PatternFormatter.h"

using namespace Poco;

int main() {
  AutoPtr<ConsoleChannel> pConsoleChannel(new ConsoleChannel);

  AutoPtr<PatternFormatter> pPatternFormatter(new PatternFormatter("[%z] %t"));
  pPatternFormatter->setProperty("times", "local");
  AutoPtr<FormattingChannel> pFormattingChannel(
      new FormattingChannel(pPatternFormatter));
  pFormattingChannel->setChannel(pConsoleChannel);

  AutoPtr<AsyncChannel> pAsyncChannel(new AsyncChannel());
  pAsyncChannel->setChannel(pFormattingChannel);

  Logger& rootLogger = Logger::root();
  rootLogger.setChannel(pAsyncChannel);

  rootLogger.information("Test 1");
  rootLogger.information("Test 2");
}

The following screenshot with two example executions shows the undefined behavior.

[aleks-f]

thank you @JoKre17

[JoKre17]

Thanks for fixing this particular occurrence of the issue regarding Poco::Mutex.
I believe the exact same issue can occur as well in any other case where Mutex or FastMutex are being used statically.

Here is a quick grep to find some more occurrences which don't even include cases where a Mutex/FastMutex is a member of another static object:

Crypto/include/Poco/Crypto/OpenSSLInitializer.h:91:     static Poco::FastMutex* _mutexes;
Foundation/include/Poco/ConsoleChannel.h:62:    static FastMutex _mutex;
Foundation/include/Poco/ConsoleChannel.h:181:   static FastMutex _mutex;
Foundation/include/Poco/Environment_UNIX.h:49:  static FastMutex _mutex;
Foundation/include/Poco/Environment_VX.h:49:    static FastMutex _mutex;
Foundation/include/Poco/ErrorHandler.h:104:     static FastMutex     _mutex;
Foundation/include/Poco/SharedLibrary_HPUX.h:45:        static FastMutex _mutex;
Foundation/include/Poco/SharedLibrary_UNIX.h:50:        static FastMutex _mutex;
Foundation/include/Poco/SharedLibrary_VX.h:45:  static FastMutex _mutex;
Foundation/include/Poco/SharedLibrary_WIN32U.h:44:      static FastMutex _mutex;
Foundation/samples/NotificationQueue/src/NotificationQueue.cpp:91:      static FastMutex   _mutex;
Foundation/src/Base32Decoder.cpp:31:    static FastMutex mutex;
Foundation/src/Base64Decoder.cpp:32:    static FastMutex mutex;
Foundation/src/TemporaryFile.cpp:137:   static FastMutex mutex;
Net/include/Poco/Net/HTTPDigestCredentials.h:173:       static Poco::FastMutex _nonceMutex;
Net/include/Poco/Net/NetworkInterface.h:322:    static Poco::FastMutex _mutex;
Net/samples/HTTPLoadTest/src/HTTPLoadTest.cpp:159:      static FastMutex _mutex;
Net/testsuite/src/ICMPClientTest.h:46:  static Poco::FastMutex _mutex;
NetSSL_Win/include/Poco/Net/Utility.h:43:       static Poco::FastMutex _mutex;
SevenZip/src/Archive.cpp:290:   static Poco::FastMutex _initMutex;

As described in this issue I was not able to exactly identify the cause of the bug. In our case I replaced all usages of Mutex and FastMutex with std::mutex which then behave as expected.