-
Notifications
You must be signed in to change notification settings - Fork 2.3k
Description
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.
