diff --git a/mythtv/libs/libmythbase/libmythbase.pro b/mythtv/libs/libmythbase/libmythbase.pro index 5fe8c5198af..4aba2c80f8a 100644 --- a/mythtv/libs/libmythbase/libmythbase.pro +++ b/mythtv/libs/libmythbase/libmythbase.pro @@ -6,6 +6,7 @@ TARGET = mythbase-$$LIBVERSION CONFIG += thread dll target.path = $${LIBDIR} INSTALLS = target +INCLUDEPATH += $$PREFIX/include QMAKE_CLEAN += $(TARGET) $(TARGETA) $(TARGETD) $(TARGET0) $(TARGET1) $(TARGET2) @@ -16,7 +17,7 @@ HEADERS += mythbaseexp.h mythdbcon.h mythdb.h mythdbparams.h oldsettings.h HEADERS += verbosedefs.h mythversion.h compat.h mythconfig.h HEADERS += mythobservable.h mythevent.h httpcomms.h mcodecs.h HEADERS += mythtimer.h mythsignalingtimer.h mythdirs.h exitcodes.h -HEADERS += lcddevice.h mythstorage.h remotefile.h logging.h +HEADERS += lcddevice.h mythstorage.h remotefile.h logging.h loggingserver.h HEADERS += mythcorecontext.h mythsystem.h mythlocale.h storagegroup.h HEADERS += mythcoreutil.h mythdownloadmanager.h mythtranslation.h HEADERS += unzip.h unzip_p.h zipentry_p.h iso639.h iso3166.h mythmedia.h @@ -36,7 +37,7 @@ SOURCES += mythcorecontext.cpp mythsystem.cpp mythlocale.cpp storagegroup.cpp SOURCES += mythcoreutil.cpp mythdownloadmanager.cpp mythtranslation.cpp SOURCES += unzip.cpp iso639.cpp iso3166.cpp mythmedia.cpp mythmiscutil.cpp SOURCES += mythhdd.cpp mythcdrom.cpp dbutil.cpp -SOURCES += mythhttppool.cpp mythhttphandler.cpp logging.cpp +SOURCES += mythhttppool.cpp mythhttphandler.cpp logging.cpp loggingserver.cpp SOURCES += referencecounter.cpp mythcommandlineparser.cpp SOURCES += filesysteminfo.cpp hardwareprofile.cpp serverpool.cpp SOURCES += plist.cpp @@ -60,7 +61,7 @@ inc.files += compat.h mythversion.h mythconfig.h mythconfig.mak version.h inc.files += mythobservable.h mythevent.h httpcomms.h mcodecs.h verbosedefs.h inc.files += mythtimer.h lcddevice.h exitcodes.h mythdirs.h mythstorage.h inc.files += mythsocket.h mythsocket_cb.h msocketdevice.h mythlogging.h -inc.files += mythcorecontext.h mythsystem.h storagegroup.h +inc.files += mythcorecontext.h mythsystem.h storagegroup.h loggingserver.h inc.files += mythcoreutil.h mythlocale.h mythdownloadmanager.h inc.files += mythtranslation.h iso639.h iso3166.h mythmedia.h mythmiscutil.h inc.files += mythcdrom.h autodeletedeque.h dbutil.h mythhttppool.h mythdeque.h @@ -123,4 +124,4 @@ QT += xml sql network include ( ../libs-targetfix.pro ) -LIBS += $$EXTRA_LIBS $$LATE_LIBS +LIBS += $$EXTRA_LIBS $$LATE_LIBS -lzmq diff --git a/mythtv/libs/libmythbase/logging.cpp b/mythtv/libs/libmythbase/logging.cpp index bc5004aee6c..6413df8f322 100644 --- a/mythtv/libs/libmythbase/logging.cpp +++ b/mythtv/libs/libmythbase/logging.cpp @@ -19,6 +19,7 @@ using namespace std; #include "mythconfig.h" #include "mythdb.h" #include "mythcorecontext.h" +#include "mythsystem.h" #include "dbutil.h" #include "exitcodes.h" #include "compat.h" @@ -52,8 +53,7 @@ extern "C" { #include #endif -QMutex loggerListMutex; -QList loggerList; +#include "nzmqt.hpp" QMutex logQueueMutex; QQueue logQueue; @@ -65,7 +65,6 @@ QHash logThreadHash; QMutex logThreadTidMutex; QHash logThreadTidHash; -LoggerThread *logThread = NULL; bool logThreadFinished = false; bool debugRegistration = false; @@ -122,636 +121,81 @@ void loglevelAdd(int value, QString name, char shortname); void verboseInit(void); void verboseHelp(void); -void LogTimeStamp( struct tm *tm, uint32_t *usec ); -char *getThreadName( LoggingItem *item ); -int64_t getThreadTid( LoggingItem *item ); -void setThreadTid( LoggingItem *item ); -static LoggingItem *createItem( - const char *, const char *, int, LogLevel_t, int); -static void deleteItem(LoggingItem *item); -#ifndef _WIN32 -void logSighup( int signum, siginfo_t *info, void *secret ); -#endif - -typedef enum { - kMessage = 0x01, - kRegistering = 0x02, - kDeregistering = 0x04, - kFlush = 0x08, - kStandardIO = 0x10, -} LoggingType; -class LoggingItem -{ - public: - LoggingItem(const char *_file, const char *_function, - int _line, LogLevel_t _level, int _type) : +LoggingItem::LoggingItem(const char *_file, const char *_function, + int _line, LogLevel_t _level, LoggingType _type) : threadId((uint64_t)(QThread::currentThreadId())), line(_line), type(_type), level(_level), file(_file), function(_function), threadName(NULL) - { - LogTimeStamp(&tm, &usec); - message[0]='\0'; - message[LOGLINE_MAX]='\0'; - setThreadTid(this); - refcount.ref(); - } - - QAtomicInt refcount; - uint64_t threadId; - uint32_t usec; - int line; - int type; - LogLevel_t level; - struct tm tm; - const char *file; - const char *function; - char *threadName; - char message[LOGLINE_MAX+1]; -}; - -/// \brief LoggerBase class constructor. Adds the new logger instance to the -/// loggerList. -/// \param string a C-string of the handle for this instance (NULL if unused) -/// \param number an integer for the handle for this instance -LoggerBase::LoggerBase(char *string, int number) -{ - QMutexLocker locker(&loggerListMutex); - if (string) - { - m_handle.string = strdup(string); - m_string = true; - } - else - { - m_handle.number = number; - m_string = false; - } - loggerList.append(this); -} - -/// \brief LoggerBase deconstructor. Removes the logger instance from the -/// loggerList. -LoggerBase::~LoggerBase() -{ - QMutexLocker locker(&loggerListMutex); - - QList::iterator it; - - for (it = loggerList.begin(); it != loggerList.end(); ++it) - { - if( *it == this ) - { - loggerList.erase(it); - break; - } - } - - if (m_string) - free(m_handle.string); -} - - -/// \brief FileLogger constructor -/// \param filename Filename of the logfile. "-" for console logging -/// \param progress Show only messages of LOG_ERR and more important, as the -/// console will be used for progress updates. Console only. -/// \param quiet Do not log to the console. Used for daemon mode. -/// Console only. -FileLogger::FileLogger(char *filename, bool progress, int quiet) : - LoggerBase(filename, 0), m_opened(false), m_fd(-1), - m_progress(progress), m_quiet(quiet) -{ - if( !strcmp(filename, "-") ) - { - m_opened = true; - m_fd = 1; - LOG(VB_GENERAL, LOG_INFO, "Added logging to the console"); - } - else - { - m_progress = false; - m_quiet = 0; - m_fd = open(filename, O_WRONLY|O_CREAT|O_APPEND, 0664); - m_opened = (m_fd != -1); - LOG(VB_GENERAL, LOG_INFO, QString("Added logging to %1") - .arg(filename)); - } -} - -/// \brief FileLogger deconstructor - close the logfile -FileLogger::~FileLogger() -{ - if( m_opened ) - { - if( m_fd != 1 ) - { - LOG(VB_GENERAL, LOG_INFO, QString("Removed logging to %1") - .arg(m_handle.string)); - close( m_fd ); - } - else - LOG(VB_GENERAL, LOG_INFO, "Removed logging to the console"); - } -} - -/// \brief Reopen the logfile after a SIGHUP. Log files only (no console). -/// This allows for logrollers to be used. -void FileLogger::reopen(void) -{ - char *filename = m_handle.string; - - // Skip console - if( !strcmp(filename, "-") ) - return; - - close(m_fd); - - m_fd = open(filename, O_WRONLY|O_CREAT|O_APPEND, 0664); - m_opened = (m_fd != -1); - LOG(VB_GENERAL, LOG_INFO, QString("Rolled logging on %1") - .arg(filename)); -} - -/// \brief Process a log message, writing to the logfile -/// \param item LoggingItem containing the log message to process -bool FileLogger::logmsg(LoggingItem *item) -{ - char line[MAX_STRING_LENGTH]; - char usPart[9]; - char timestamp[TIMESTAMP_MAX]; - char *threadName = NULL; - pid_t pid = getpid(); - - if (!m_opened || m_quiet || (m_progress && item->level > LOG_ERR)) - return false; - - item->refcount.ref(); - - strftime( timestamp, TIMESTAMP_MAX-8, "%Y-%m-%d %H:%M:%S", - (const struct tm *)&item->tm ); - snprintf( usPart, 9, ".%06d", (int)(item->usec) ); - strcat( timestamp, usPart ); - char shortname; - - { - QMutexLocker locker(&loglevelMapMutex); - LoglevelMap::iterator it = loglevelMap.find(item->level); - if (it == loglevelMap.end()) - shortname = '-'; - else - shortname = (*it)->shortname; - } - - if (item->type & kStandardIO) - { - snprintf( line, MAX_STRING_LENGTH, "%s", item->message ); - } - else if (m_fd == 1) - { - // Stdout - snprintf( line, MAX_STRING_LENGTH, "%s %c %s\n", timestamp, - shortname, item->message ); - } - else - { - threadName = getThreadName(item); - pid_t tid = getThreadTid(item); - - if( tid ) - snprintf( line, MAX_STRING_LENGTH, - "%s %c [%d/%d] %s %s:%d (%s) - %s\n", - timestamp, shortname, pid, tid, threadName, item->file, - item->line, item->function, item->message ); - else - snprintf( line, MAX_STRING_LENGTH, - "%s %c [%d] %s %s:%d (%s) - %s\n", - timestamp, shortname, pid, threadName, item->file, - item->line, item->function, item->message ); - } - - int fd = (item->type & kStandardIO) ? 1 : m_fd; - int result = write( fd, line, strlen(line) ); - - deleteItem(item); - - if( result == -1 ) - { - LOG(VB_GENERAL, LOG_ERR, - QString("Closed Log output on fd %1 due to errors").arg(m_fd)); - m_opened = false; - if( m_fd != 1 ) - close( m_fd ); - return false; - } - return true; -} - - -#ifndef _WIN32 -/// \brief SyslogLogger constructor -/// \param facility Syslog facility to use in logging -SyslogLogger::SyslogLogger(int facility) : LoggerBase(NULL, facility), - m_opened(false) -{ - CODE *name; - - m_application = strdup((char *)QCoreApplication::applicationName() - .toLocal8Bit().constData()); - - openlog( m_application, LOG_NDELAY | LOG_PID, facility ); - m_opened = true; - - for (name = &facilitynames[0]; - name->c_name && name->c_val != facility; name++); - - LOG(VB_GENERAL, LOG_INFO, QString("Added syslogging to facility %1") - .arg(name->c_name)); -} - -/// \brief SyslogLogger deconstructor. -SyslogLogger::~SyslogLogger() -{ - LOG(VB_GENERAL, LOG_INFO, "Removing syslogging"); - free(m_application); - closelog(); -} - - -/// \brief Process a log message, logging to syslog -/// \param item LoggingItem containing the log message to process -bool SyslogLogger::logmsg(LoggingItem *item) { - if (!m_opened) - return false; - - char shortname; - - { - QMutexLocker locker(&loglevelMapMutex); - LoglevelMap::iterator it = loglevelMap.find(item->level); - if (it == loglevelMap.end()) - shortname = '-'; - else - shortname = (*it)->shortname; - } - - char *threadName = getThreadName(item); - - syslog( item->level, "%c %s %s:%d (%s) %s", shortname, threadName, - item->file, item->line, item->function, item->message ); + time_t epoch; - return true; -} +#if HAVE_GETTIMEOFDAY + struct timeval tv; + gettimeofday(&tv, NULL); + epoch = tv.tv_sec; + usec = tv.tv_usec; +#else + /* Stupid system has no gettimeofday, use less precise QDateTime */ + QDateTime date = QDateTime::currentDateTime(); + QTime time = date.time(); + epoch = date.toTime_t(); + usec = time.msec() * 1000; #endif -const int DatabaseLogger::kMinDisabledTime = 1000; - -/// \brief DatabaseLogger constructor -/// \param table C-string of the database table to log to -DatabaseLogger::DatabaseLogger(char *table) : LoggerBase(table, 0), - m_opened(false), - m_loggingTableExists(false) -{ - m_query = QString( - "INSERT INTO %1 " - " (host, application, pid, tid, thread, filename, " - " line, function, msgtime, level, message) " - "VALUES (:HOST, :APP, :PID, :TID, :THREAD, :FILENAME, " - " :LINE, :FUNCTION, :MSGTIME, :LEVEL, :MESSAGE)") - .arg(m_handle.string); - - LOG(VB_GENERAL, LOG_INFO, QString("Added database logging to table %1") - .arg(m_handle.string)); - - m_thread = new DBLoggerThread(this); - m_thread->start(); - - m_opened = true; - m_disabled = false; -} - -/// \brief DatabaseLogger deconstructor -DatabaseLogger::~DatabaseLogger() -{ - LOG(VB_GENERAL, LOG_INFO, "Removing database logging"); - - stopDatabaseAccess(); -} - -/// \brief Stop logging to the database and wait for the thread to stop. -void DatabaseLogger::stopDatabaseAccess(void) -{ - if( m_thread ) - { - m_thread->stop(); - m_thread->wait(); - delete m_thread; - m_thread = NULL; - } -} - -/// \brief Process a log message, queuing it for logging to the database -/// \param item LoggingItem containing the log message to process -bool DatabaseLogger::logmsg(LoggingItem *item) -{ - if (!m_thread) - return false; - - if (!m_thread->isRunning()) - { - m_disabled = true; - m_disabledTime.start(); - } - - if (!m_disabled && m_thread->queueFull()) - { - m_disabled = true; - m_disabledTime.start(); - LOG(VB_GENERAL, LOG_CRIT, - "Disabling DB Logging: too many messages queued"); - return false; - } - - if (m_disabled && m_disabledTime.elapsed() > kMinDisabledTime) - { - if (isDatabaseReady() && !m_thread->queueFull()) - { - m_disabled = false; - LOG(VB_GENERAL, LOG_CRIT, "Reenabling DB Logging"); - } - } - - if (m_disabled) - return false; - - item->refcount.ref(); - m_thread->enqueue(item); - return true; -} - -/// \brief Actually insert a log message from the queue into the database -/// \param query The database insert query to use -/// \param item LoggingItem containing the log message to insert -bool DatabaseLogger::logqmsg(MSqlQuery &query, LoggingItem *item) -{ - char timestamp[TIMESTAMP_MAX]; - char *threadName = getThreadName(item); - pid_t tid = getThreadTid(item); - - strftime( timestamp, TIMESTAMP_MAX-8, "%Y-%m-%d %H:%M:%S", - (const struct tm *)&item->tm ); - - query.bindValue(":TID", tid); - query.bindValue(":THREAD", threadName); - query.bindValue(":FILENAME", item->file); - query.bindValue(":LINE", item->line); - query.bindValue(":FUNCTION", item->function); - query.bindValue(":MSGTIME", timestamp); - query.bindValue(":LEVEL", item->level); - query.bindValue(":MESSAGE", item->message); - - if (!query.exec()) - { - // Suppress Driver not loaded errors that occur at startup. - // and suppress additional errors for one second after the - // previous error (to avoid spamming the log). - QSqlError err = query.lastError(); - if ((err.type() != 1 || err.number() != -1) && - (!m_errorLoggingTime.isValid() || - (m_errorLoggingTime.elapsed() > 1000))) - { - MythDB::DBError("DBLogging", query); - m_errorLoggingTime.start(); - } - return false; - } - - deleteItem(item); - - return true; -} - -/// \brief Prepare the database query for use, and bind constant values to it. -/// \param query The database query to prepare -void DatabaseLogger::prepare(MSqlQuery &query) -{ - query.prepare(m_query); - query.bindValue(":HOST", gCoreContext->GetHostName()); - query.bindValue(":APP", QCoreApplication::applicationName()); - query.bindValue(":PID", getpid()); -} - -/// \brief Check if the database is ready for use -/// \return true when database is ready, false otherwise -bool DatabaseLogger::isDatabaseReady(void) -{ - bool ready = false; - MythDB *db = GetMythDB(); - - if ((db) && db->HaveValidDatabase()) - { - if ( !m_loggingTableExists ) - m_loggingTableExists = tableExists(m_handle.string); - - if ( m_loggingTableExists ) - ready = true; - } - - return ready; -} - -/// \brief Checks whether table exists and is ready for writing -/// \param table The name of the table to check (without schema name) -/// \return true if table exists in schema or false if not -bool DatabaseLogger::tableExists(const QString &table) -{ - bool result = false; - MSqlQuery query(MSqlQuery::InitCon()); - if (query.isConnected()) - { - QString sql = "SELECT INFORMATION_SCHEMA.COLUMNS.COLUMN_NAME " - " FROM INFORMATION_SCHEMA.COLUMNS " - " WHERE INFORMATION_SCHEMA.COLUMNS.TABLE_SCHEMA = " - " DATABASE() " - " AND INFORMATION_SCHEMA.COLUMNS.TABLE_NAME = " - " :TABLENAME " - " AND INFORMATION_SCHEMA.COLUMNS.COLUMN_NAME = " - " :COLUMNNAME;"; - if (query.prepare(sql)) - { - query.bindValue(":TABLENAME", table); - query.bindValue(":COLUMNNAME", "function"); - if (query.exec() && query.next()) - result = true; - } - } - return result; -} - + localtime_r(&epoch, &tm); -/// \brief DBLoggerThread constructor -/// \param logger DatabaseLogger instance that this thread belongs to -DBLoggerThread::DBLoggerThread(DatabaseLogger *logger) : - MThread("DBLogger"), - m_logger(logger), - m_queue(new QQueue), - m_wait(new QWaitCondition()), aborted(false) -{ + message[0]='\0'; + message[LOGLINE_MAX]='\0'; + setThreadTid(); + refcount.ref(); } -/// \brief DBLoggerThread deconstructor. Waits for the thread to finish, then -/// Empties what remains in the queue before deleting it. -DBLoggerThread::~DBLoggerThread() -{ - stop(); - wait(); - - QMutexLocker qLock(&m_queueMutex); - while (!m_queue->empty()) - deleteItem(m_queue->dequeue()); - delete m_queue; - delete m_wait; - m_queue = NULL; - m_wait = NULL; -} -/// \brief Start the thread. -void DBLoggerThread::run(void) +QByteArray LoggingItem::toByteArray(void) { - RunProlog(); + QByteArray out(""); - // Wait a bit before we start logging to the DB.. If we wait too long, - // then short-running tasks (like mythpreviewgen) will not log to the db - // at all, and that's undesirable. - while (true) - { - if ((aborted || (gCoreContext && m_logger->isDatabaseReady()))) - break; - - QMutexLocker locker(&m_queueMutex); - m_wait->wait(locker.mutex(), 100); - } - - if (!aborted) - { - // We want the query to be out of scope before the RunEpilog() so - // shutdown occurs correctly as otherwise the connection appears still - // in use, and we get a qWarning on shutdown. - MSqlQuery *query = new MSqlQuery(MSqlQuery::InitCon()); - m_logger->prepare(*query); - - QMutexLocker qLock(&m_queueMutex); - while (!aborted || !m_queue->isEmpty()) - { - if (m_queue->isEmpty()) - { - m_wait->wait(qLock.mutex(), 100); - continue; - } - - LoggingItem *item = m_queue->dequeue(); - if (!item) - continue; - - qLock.unlock(); - - if (item->message[0] != '\0') - { - if (!m_logger->logqmsg(*query, item)) - { - qLock.relock(); - m_queue->prepend(item); - m_wait->wait(qLock.mutex(), 100); - delete query; - query = new MSqlQuery(MSqlQuery::InitCon()); - m_logger->prepare(*query); - continue; - } - } - else - { - deleteItem(item); - } - - qLock.relock(); - } - - delete query; - - qLock.unlock(); - } - - RunEpilog(); -} - -/// \brief Tell the thread to stop by setting the aborted flag. -void DBLoggerThread::stop(void) -{ - QMutexLocker qLock(&m_queueMutex); - aborted = true; - m_wait->wakeAll(); + return out; } /// \brief Get the name of the thread that produced the LoggingItem -/// \param item the LoggingItem in question /// \return C-string of the thread name -char *getThreadName( LoggingItem *item ) +char *LoggingItem::getThreadName(void) { static const char *unknown = "thread_unknown"; - char *threadName; - if( !item ) - return( (char *)unknown ); + if( threadName ) + return threadName; - if( !item->threadName ) - { - QMutexLocker locker(&logThreadMutex); - if( logThreadHash.contains(item->threadId) ) - threadName = logThreadHash[item->threadId]; - else - threadName = (char *)unknown; - } - else - { - threadName = item->threadName; - } - - return( threadName ); + QMutexLocker locker(&logThreadMutex); + char *name = logThreadHash.value(threadId, (char *)unknown); + return name; } /// \brief Get the thread ID of the thread that produced the LoggingItem -/// \param item the LoggingItem in question /// \return Thread ID of the producing thread, cast to a 64-bit signed integer /// \notes In different platforms, the actual value returned here will vary. /// The intention is to get a thread ID that will map well to what is /// shown in gdb. -int64_t getThreadTid( LoggingItem *item ) +int64_t LoggingItem::getThreadTid(void) { - pid_t tid = 0; - - if( !item ) - return( 0 ); - QMutexLocker locker(&logThreadTidMutex); - if( logThreadTidHash.contains(item->threadId) ) - tid = logThreadTidHash[item->threadId]; - - return( tid ); + int64_t tid = logThreadTidHash.value(threadId, 0); + return tid; } /// \brief Set the thread ID of the thread that produced the LoggingItem. This /// code is actually run in the thread in question as part of the call /// to LOG() -/// \param item the LoggingItem in question /// \notes In different platforms, the actual value returned here will vary. /// The intention is to get a thread ID that will map well to what is /// shown in gdb. -void setThreadTid( LoggingItem *item ) +void LoggingItem::setThreadTid(void) { QMutexLocker locker(&logThreadTidMutex); - if( ! logThreadTidHash.contains(item->threadId) ) + if( !logThreadTidHash.contains(threadId) ) { int64_t tid = 0; @@ -765,18 +209,19 @@ void setThreadTid( LoggingItem *item ) #elif CONFIG_DARWIN tid = (int64_t)mach_thread_self(); #endif - logThreadTidHash[item->threadId] = tid; + logThreadTidHash[threadId] = tid; } } /// \brief LoggerThread constructor. Enables debugging of thread registration /// and deregistration if the VERBOSE_THREADS environment variable is /// set. -LoggerThread::LoggerThread() : +LoggerThread::LoggerThread(QString filename, bool progress, bool quiet) : MThread("Logger"), m_waitNotEmpty(new QWaitCondition()), m_waitEmpty(new QWaitCondition()), - aborted(false) + m_aborted(false), m_filename(filename), m_progress(progress), + m_quiet(quiet) { char *debug = getenv("VERBOSE_THREADS"); if (debug != NULL) @@ -793,15 +238,6 @@ LoggerThread::~LoggerThread() stop(); wait(); - QMutexLocker locker(&loggerListMutex); - - QList::iterator it; - - for (it = loggerList.begin(); it != loggerList.end(); ++it) - { - (*it)->deleteLater(); - } - delete m_waitNotEmpty; delete m_waitEmpty; } @@ -816,9 +252,50 @@ void LoggerThread::run(void) logThreadFinished = false; + LOG(VB_GENERAL, LOG_INFO, "Added logging to the console"); + + m_zmqContext = new nzmqt::PollingZMQContext(this, 4); + m_zmqContext->start(); + + m_zmqSocket = m_zmqContext->createSocket(nzmqt::ZMQSocket::TYP_DEALER); + m_zmqSocket->connectTo("tcp://127.0.0.1:35327"); + + connect(m_zmqSocket, SIGNAL(messageReceived(const QList&)), + this, SLOT(messageReceived(const QList&))); + + m_initialWaiting = true; + LoggingItem *item = LoggingItem::create(__FILE__, __FUNCTION__, + __LINE__, (LogLevel_t)LOG_DEBUG, + kInitializing); + if (item) + { + m_zmqSocket->sendMessage(item->toByteArray()); + item->deleteItem(); + } + + msleep(100); // wait up to 100ms for mythlogserver to respond + if (m_initialWaiting) + { + // Got no response from mythlogserver, let's assume it's dead and start + // it up + m_initialWaiting = false; + LOG(VB_GENERAL, LOG_INFO, "Starting mythlogserver"); + + MythSystemMask mask = MythSystemMask(kMSDontBlockInputDevs | + kMSDontDisableDrawing | + kMSRunBackground | kMSRunShell); + QStringList args; + args << "--daemon"; + + MythSystem ms("mythlogserver", args, mask); + ms.Run(); + } + + LOG(VB_GENERAL, LOG_INFO, "Added logging to mythlogserver at TCP:35327"); + QMutexLocker qLock(&logQueueMutex); - while (!aborted || !logQueue.isEmpty()) + while (!m_aborted || !logQueue.isEmpty()) { if (logQueue.isEmpty()) { @@ -831,11 +308,15 @@ void LoggerThread::run(void) qLock.unlock(); handleItem(item); - deleteItem(item); + logConsole(item); + item->deleteItem(); qLock.relock(); } + delete m_zmqSocket; + delete m_zmqContext; + logThreadFinished = true; qLock.unlock(); @@ -844,8 +325,25 @@ void LoggerThread::run(void) } -/// \brief Handles each LoggingItem, generally by handing it off to the -/// various running logger instances. There is a special case for +/// \brief Handles messages received back from mythlogserver via ZeroMQ. +/// This is particularly used to receive the acknowledgement of the +/// kInitializing message which contains the filename of the log to +/// create and whether to log to db and syslog. If this is not +/// received during startup, it is assumed that mythlogserver needs +/// to be started. +/// \param msg The message received (can be multi-part) +void LoggerThread::messageReceived(const QList &msg) +{ + if (m_initialWaiting) + { + m_initialWaiting = false; + return; + } +} + + +/// \brief Handles each LoggingItem, generally by handing it off to +/// mythlogserver via ZeroMQ. There is a special case for /// thread registration and deregistration which are also included in /// the logging queue to keep the thread names in sync with the log /// messages. @@ -854,7 +352,7 @@ void LoggerThread::handleItem(LoggingItem *item) { if (item->type & kRegistering) { - int64_t tid = getThreadTid(item); + int64_t tid = item->getThreadTid(); QMutexLocker locker(&logThreadMutex); logThreadHash[item->threadId] = strdup(item->threadName); @@ -901,21 +399,63 @@ void LoggerThread::handleItem(LoggingItem *item) if (item->message[0] != '\0') { - QMutexLocker locker(&loggerListMutex); + // Send it to mythlogserver + m_zmqSocket->sendMessage(item->toByteArray()); + } +} + +/// \brief Process a log message, writing to the console +/// \param item LoggingItem containing the log message to process +bool LoggerThread::logConsole(LoggingItem *item) +{ + char line[MAX_STRING_LENGTH]; + char usPart[9]; + char timestamp[TIMESTAMP_MAX]; + + if (m_quiet || (m_progress && item->level > LOG_ERR)) + return false; + + item->refcount.ref(); + + if (item->type & kStandardIO) + snprintf( line, MAX_STRING_LENGTH, "%s", item->message ); + else + { + strftime( timestamp, TIMESTAMP_MAX-8, "%Y-%m-%d %H:%M:%S", + (const struct tm *)&item->tm ); + snprintf( usPart, 9, ".%06d", (int)(item->usec) ); + strcat( timestamp, usPart ); + char shortname; + + { + QMutexLocker locker(&loglevelMapMutex); + LoglevelDef *lev = loglevelMap.value(item->level, NULL); + if (!lev) + shortname = '-'; + else + shortname = lev->shortname; + } - QList::iterator it; - for (it = loggerList.begin(); it != loggerList.end(); ++it) - (*it)->logmsg(item); + snprintf( line, MAX_STRING_LENGTH, "%s %c %s\n", timestamp, + shortname, item->message ); } + + int result = write( 1, line, strlen(line) ); + (void)result; + + item->deleteItem(); + + return true; } + /// \brief Stop the thread by setting the abort flag after waiting a second for /// the queue to be flushed. void LoggerThread::stop(void) { QMutexLocker qLock(&logQueueMutex); flush(1000); - aborted = true; + m_aborted = true; m_waitNotEmpty->wakeAll(); } @@ -926,7 +466,7 @@ bool LoggerThread::flush(int timeoutMS) { QTime t; t.start(); - while (!aborted && logQueue.isEmpty() && t.elapsed() < timeoutMS) + while (!m_aborted && logQueue.isEmpty() && t.elapsed() < timeoutMS) { m_waitNotEmpty->wakeAll(); int left = timeoutMS - t.elapsed(); @@ -936,7 +476,6 @@ bool LoggerThread::flush(int timeoutMS) return logQueue.isEmpty(); } -static QList item_recycler; static QAtomicInt item_count; static QAtomicInt malloc_count; @@ -953,8 +492,9 @@ static QTime memory_time; /// \param _level logging level of the message (LogLevel_t) /// \param _type type of logging message /// \return LoggingItem that was created -static LoggingItem *createItem(const char *_file, const char *_function, - int _line, LogLevel_t _level, int _type) +LoggingItem *LoggingItem::create(const char *_file, + const char *_function, + int _line, LogLevel_t _level, int _type) { LoggingItem *item = new LoggingItem(_file, _function, _line, _level, _type); @@ -981,49 +521,55 @@ static LoggingItem *createItem(const char *_file, const char *_function, return item; } -/// \brief Delete the LoggingItem once its reference count has run down -/// \param item LoggingItem to delete. -static void deleteItem(LoggingItem *item) +LoggingItem *LoggingItem::create(QByteArray &buf) { - if (!item) - return; + // Deserialize buffer - if (!item->refcount.deref()) - { - if (item->threadName) - free(item->threadName); - item_count.deref(); - delete item; - } -} + const char *_file = ""; + const char *_function = ""; + int _line = 0; + LogLevel_t _level = (LogLevel_t)LOG_DEBUG; + LoggingType _type = kMessage; -/// \brief Fill in the time structure from the current time to make a timestamp -/// for the log message. This is run as part of the LOG() call. -/// \param tm pointer to the time structure to fill in -/// \param usec pointer to a 32bit unsigned int to return the number of us -void LogTimeStamp( struct tm *tm, uint32_t *usec ) -{ - if( !usec || !tm ) - return; + LoggingItem *item = new LoggingItem(_file, _function, _line, _level, _type); - time_t epoch; + malloc_count.ref(); -#if HAVE_GETTIMEOFDAY - struct timeval tv; - gettimeofday(&tv, NULL); - epoch = tv.tv_sec; - *usec = tv.tv_usec; +#if DEBUG_MEMORY + int val = item_count.fetchAndAddRelaxed(1) + 1; + if (val == 0) + memory_time.start(); + max_count = (val > max_count) ? val : max_count; + if (memory_time.elapsed() > 1000) + { + cout<<"current memory usage: " + <deleteLater(); + } } + /// \brief Format and send a log message into the queue. This is called from /// the LOG() macro. The intention is minimal blocking of the caller. /// \param mask Verbosity mask of the message (VB_*) @@ -1046,7 +592,7 @@ void LogPrintLine( uint64_t mask, LogLevel_t level, const char *file, int line, int type = kMessage; type |= (mask & VB_FLUSH) ? kFlush : 0; type |= (mask & VB_STDIO) ? kStandardIO : 0; - LoggingItem *item = createItem(file, function, line, level, type); + LoggingItem *item = LoggingItem::create(file, function, line, level, type); if (!item) return; @@ -1075,7 +621,7 @@ void LogPrintLine( uint64_t mask, LogLevel_t level, const char *file, int line, item = logQueue.dequeue(); qLock.unlock(); logThread->handleItem(item); - deleteItem(item); + item->deleteItem(); qLock.relock(); } } @@ -1085,22 +631,6 @@ void LogPrintLine( uint64_t mask, LogLevel_t level, const char *file, int line, } } -#ifndef _WIN32 -/// \brief SIGHUP handler - reopen all open logfiles for logrollers -void logSighup( int signum, siginfo_t *info, void *secret ) -{ - LOG(VB_GENERAL, LOG_INFO, "SIGHUP received, rolling log files."); - - /* SIGHUP was sent. Close and reopen debug logfiles */ - QMutexLocker locker(&loggerListMutex); - - QList::iterator it; - for (it = loggerList.begin(); it != loggerList.end(); ++it) - { - (*it)->reopen(); - } -} -#endif /// \brief Generate the logPropagateArgs global with the latest logging /// level, mask, etc to propagate to all of the mythtv programs @@ -1160,15 +690,7 @@ bool logPropagateQuiet(void) void logStart(QString logfile, int progress, int quiet, int facility, LogLevel_t level, bool dblog, bool propagate) { - LoggerBase *logger; - - { - QMutexLocker qLock(&logQueueMutex); - if (!logThread) - logThread = new LoggerThread(); - } - - if (logThread->isRunning()) + if (logThread && logThread->isRunning()) return; logLevel = level; @@ -1189,38 +711,9 @@ void logStart(QString logfile, int progress, int quiet, int facility, logPropagateCalc(); - /* log to the console */ - logger = new FileLogger((char *)"-", progress, quiet); - - /* Debug logfile */ - if( !logfile.isEmpty() ) - logger = new FileLogger((char *)logfile.toLocal8Bit().constData(), - false, false); - -#ifndef _WIN32 - /* Syslog */ - if( facility == -1 ) - LOG(VB_GENERAL, LOG_CRIT, - "Syslogging facility unknown, disabling syslog output"); - else if( facility >= 0 ) - logger = new SyslogLogger(facility); -#endif - - /* Database */ - if( dblog ) - logger = new DatabaseLogger((char *)"logging"); - -#ifndef _WIN32 - /* Setup SIGHUP */ - LOG(VB_GENERAL, LOG_NOTICE, "Setting up SIGHUP handler"); - struct sigaction sa; - sa.sa_sigaction = logSighup; - sigemptyset( &sa.sa_mask ); - sa.sa_flags = SA_RESTART | SA_SIGINFO; - sigaction( SIGHUP, &sa, NULL ); -#endif - - (void)logger; + QMutexLocker qLock(&logQueueMutex); + if (!logThread) + logThread = new LoggerThread(logfile, progress, quiet); logThread->start(); } @@ -1233,21 +726,6 @@ void logStop(void) logThread->stop(); logThread->wait(); } - -#ifndef _WIN32 - /* Tear down SIGHUP */ - struct sigaction sa; - sa.sa_handler = SIG_DFL; - sigemptyset( &sa.sa_mask ); - sa.sa_flags = SA_RESTART; - sigaction( SIGHUP, &sa, NULL ); -#endif - - QList::iterator it; - for (it = loggerList.begin(); it != loggerList.end(); ++it) - { - (*it)->stopDatabaseAccess(); - } } /// \brief Register the current thread with the given name. This is triggered @@ -1261,8 +739,9 @@ void loggingRegisterThread(const QString &name) QMutexLocker qLock(&logQueueMutex); - LoggingItem *item = createItem(__FILE__, __FUNCTION__, __LINE__, - (LogLevel_t)LOG_DEBUG, kRegistering); + LoggingItem *item = LoggingItem::create(__FILE__, __FUNCTION__, + __LINE__, (LogLevel_t)LOG_DEBUG, + kRegistering); if (item) { item->threadName = strdup((char *)name.toLocal8Bit().constData()); @@ -1279,12 +758,14 @@ void loggingDeregisterThread(void) QMutexLocker qLock(&logQueueMutex); - LoggingItem *item = createItem(__FILE__, __FUNCTION__, __LINE__, - (LogLevel_t)LOG_DEBUG, kDeregistering); + LoggingItem *item = LoggingItem::create(__FILE__, __FUNCTION__, __LINE__, + (LogLevel_t)LOG_DEBUG, + kDeregistering); if (item) logQueue.enqueue(item); } + /// \brief Map a syslog facility name back to the enumerated value /// \param facility QString containing the facility name /// \return Syslog facility as enumerated type. Negative if not found. diff --git a/mythtv/libs/libmythbase/logging.h b/mythtv/libs/libmythbase/logging.h index 404477fb4e6..37190fcfb8f 100644 --- a/mythtv/libs/libmythbase/logging.h +++ b/mythtv/libs/libmythbase/logging.h @@ -13,6 +13,7 @@ #include "mythbaseexp.h" // MBASE_PUBLIC , etc. #include "verbosedefs.h" #include "mthread.h" +#include "nzmqt.hpp" #define LOGLINE_MAX (2048-120) @@ -23,157 +24,90 @@ class LoggingItem; void loggingRegisterThread(const QString &name); void loggingDeregisterThread(void); -/// \brief A semi-opaque handle that is used by the various loggers to indicate -/// which instance is being referenced. -typedef union { - char *string; - int number; -} LoggerHandle_t; +class QWaitCondition; -/// \brief Base class for the various logging mechanisms -class LoggerBase : public QObject { - Q_OBJECT +typedef enum { + kMessage = 0x01, + kRegistering = 0x02, + kDeregistering = 0x04, + kFlush = 0x08, + kStandardIO = 0x10, + kInitializing = 0x20, +} LoggingType; - public: - /// \brief LoggerBase Constructor - LoggerBase(char *string, int number); - /// \brief LoggerBase Deconstructor - virtual ~LoggerBase(); - /// \brief Process a log message for the logger instance - /// \param item LoggingItem containing the log message to process - virtual bool logmsg(LoggingItem *item) = 0; - /// \brief Reopen the log file to facilitate log rolling - virtual void reopen(void) = 0; - /// \brief Stop logging to the database - virtual void stopDatabaseAccess(void) { } - protected: - LoggerHandle_t m_handle; ///< semi-opaque handle for identifying instance - bool m_string; ///< true if m_handle.string valid, false otherwise -}; +class LoggerThread; -/// \brief File-based logger - used for logfiles and console -class FileLogger : public LoggerBase { - public: - FileLogger(char *filename, bool progress, int quiet); - ~FileLogger(); - bool logmsg(LoggingItem *item); - void reopen(void); - private: - bool m_opened; ///< true when the logfile is opened - int m_fd; ///< contains the file descriptor for the logfile - bool m_progress; ///< show only LOG_ERR and more important (console only) - int m_quiet; ///< silence the console (console only) -}; - -#ifndef _WIN32 -/// \brief Syslog-based logger (not available in Windows) -class SyslogLogger : public LoggerBase { - public: - SyslogLogger(int facility); - ~SyslogLogger(); - bool logmsg(LoggingItem *item); - /// \brief Unused for this logger. - void reopen(void) { }; - private: - char *m_application; ///< C-string of the application name - bool m_opened; ///< true when syslog channel open. -}; -#endif +/// \brief The logging items that are generated by LOG() and are sent to the +/// console and to mythlogserver via ZeroMQ +class LoggingItem: public QObject +{ + Q_OBJECT; -class DBLoggerThread; + friend class LoggerThread; + friend void LogPrintLine(uint64_t, LogLevel_t, const char *, int, + const char *, int, const char *, ... ); + friend void loggingRegisterThread(const QString &); -/// \brief Database logger - logs to the MythTV database -class DatabaseLogger : public LoggerBase { - friend class DBLoggerThread; public: - DatabaseLogger(char *table); - ~DatabaseLogger(); - bool logmsg(LoggingItem *item); - void reopen(void) { }; - virtual void stopDatabaseAccess(void); + char *getThreadName(void); + int64_t getThreadTid(void); + void setThreadTid(void); + static LoggingItem *create(const char *, const char *, int, LogLevel_t, + LoggingType); + static LoggingItem *create(QByteArray &buf); + void deleteItem(void); + QByteArray toByteArray(void); + protected: - bool logqmsg(MSqlQuery &query, LoggingItem *item); - void prepare(MSqlQuery &query); + QAtomicInt refcount; + uint64_t threadId; + uint32_t usec; + int line; + int type; + LogLevel_t level; + struct tm tm; + const char *file; + const char *function; + char *threadName; + char message[LOGLINE_MAX+1]; + private: - bool isDatabaseReady(void); - bool tableExists(const QString &table); - - DBLoggerThread *m_thread; ///< The database queue handling thread - QString m_query; ///< The database query to insert log messages - bool m_opened; ///< The database is opened - bool m_loggingTableExists; ///< The desired logging table exists - bool m_disabled; ///< DB logging is temporarily disabled - QTime m_disabledTime; ///< Time when the DB logging was disabled - QTime m_errorLoggingTime; ///< Time when DB error logging was last done - static const int kMinDisabledTime; ///< Minimum time to disable DB logging - /// (in ms) + LoggingItem(const char *_file, const char *_function, + int _line, LogLevel_t _level, int _type); }; -class QWaitCondition; - /// \brief The logging thread that consumes the logging queue and dispatches -/// each LoggingItem to each logger instance. -class LoggerThread : public MThread +/// each LoggingItem to mythlogserver via ZeroMQ +class LoggerThread : public QObject, public MThread { + Q_OBJECT public: - LoggerThread(); + LoggerThread(QString filename, bool progress, bool quiet); ~LoggerThread(); void run(void); void stop(void); bool flush(int timeoutMS = 200000); void handleItem(LoggingItem *item); private: + bool logConsole(LoggingItem *item); QWaitCondition *m_waitNotEmpty; ///< Condition variable for waiting /// for the queue to not be empty /// Protected by logQueueMutex QWaitCondition *m_waitEmpty; ///< Condition variable for waiting /// for the queue to be empty /// Protected by logQueueMutex - bool aborted; ///< Flag to abort the thread. + bool m_aborted; ///< Flag to abort the thread. /// Protected by logQueueMutex -}; - -#define MAX_QUEUE_LEN 1000 + bool m_initialWaiting; ///< Waiting for the initial response from + /// mythlogserver + QString m_filename; ///< Filename of debug logfile + bool m_progress; ///< show only LOG_ERR and more important (console only) + int m_quiet; ///< silence the console (console only) + nzmqt::PollingZMQContext *m_zmqContext; ///< ZeroMQ context to use in this logger + nzmqt::ZMQSocket *m_zmqSocket; ///< ZeroMQ socket to talk to mythlogserver -/// \brief Thread that manages the queueing of logging inserts for the database. -/// The database logging gets throttled if it gets overwhelmed, and also -/// during startup. Having a second queue allows the rest of the -/// logging to remain in sync and to allow for burstiness in the -/// database due to things like scheduler runs. -class DBLoggerThread : public MThread -{ - public: - DBLoggerThread(DatabaseLogger *logger); - ~DBLoggerThread(); - void run(void); - void stop(void); - /// \brief Enqueues a LoggingItem onto the queue for the thread to - /// consume. - bool enqueue(LoggingItem *item) - { - QMutexLocker qLock(&m_queueMutex); - if (!aborted) - m_queue->enqueue(item); - return true; - } - - /// \brief Indicates when the queue is full - /// \return true when the queue is full - bool queueFull(void) - { - QMutexLocker qLock(&m_queueMutex); - return (m_queue->size() >= MAX_QUEUE_LEN); - } - private: - DatabaseLogger *m_logger; ///< The associated logger instance - QMutex m_queueMutex; ///< Mutex for protecting the queue - QQueue *m_queue; ///< Queue of LoggingItems to insert - QWaitCondition *m_wait; ///< Wait condition used for waiting - /// for the queue to not be full. - /// Protected by m_queueMutex - volatile bool aborted; ///< Used during shutdown to indicate - /// that the thread should stop ASAP. - /// Protected by m_queueMutex + protected slots: + void messageReceived(const QList&); }; #endif diff --git a/mythtv/libs/libmythbase/loggingserver.cpp b/mythtv/libs/libmythbase/loggingserver.cpp new file mode 100644 index 00000000000..bf9a715b23b --- /dev/null +++ b/mythtv/libs/libmythbase/loggingserver.cpp @@ -0,0 +1,1413 @@ +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +using namespace std; + +#include "mythlogging.h" +#include "logging.h" +#include "loggingserver.h" +#include "mythconfig.h" +#include "mythdb.h" +#include "mythcorecontext.h" +#include "dbutil.h" +#include "exitcodes.h" +#include "compat.h" + +#include +#define SYSLOG_NAMES +#ifndef _WIN32 +#include +#endif +#include +#include +#include +#include +#include +#include +#include +#if HAVE_GETTIMEOFDAY +#include +#endif +#include + +// Various ways to get to thread's tid +#if defined(linux) +#include +#elif defined(__FreeBSD__) +extern "C" { +#include +#include +} +#elif CONFIG_DARWIN +#include +#endif + +QMutex loggerListMutex; +QList loggerList; + +QMutex logQueueMutex; +QQueue logQueue; +QRegExp logRegExp = QRegExp("[%]{1,2}"); + +QMutex logThreadMutex; +QHash logThreadHash; + +QMutex logThreadTidMutex; +QHash logThreadTidHash; + +LogServerThread *logThread = NULL; +bool logThreadFinished = false; +bool debugRegistration = false; + +typedef struct { + bool propagate; + int quiet; + int facility; + bool dblog; + QString path; +} LogPropagateOpts; + +LogPropagateOpts logPropagateOpts; +QString logPropagateArgs; + +#define TIMESTAMP_MAX 30 +#define MAX_STRING_LENGTH (LOGLINE_MAX+120) + +#ifndef _WIN32 +void logSighup( int signum, siginfo_t *info, void *secret ); +#endif + + +/// \brief LoggerBase class constructor. Adds the new logger instance to the +/// loggerList. +/// \param string a C-string of the handle for this instance (NULL if unused) +/// \param number an integer for the handle for this instance +LoggerBase::LoggerBase(char *string, int number) +{ + QMutexLocker locker(&loggerListMutex); + if (string) + { + m_handle.string = strdup(string); + m_string = true; + } + else + { + m_handle.number = number; + m_string = false; + } + loggerList.append(this); +} + +/// \brief LoggerBase deconstructor. Removes the logger instance from the +/// loggerList. +LoggerBase::~LoggerBase() +{ + QMutexLocker locker(&loggerListMutex); + loggerList.removeAll(this); + + if (m_string) + free(m_handle.string); +} + + +/// \brief FileLogger constructor +/// \param filename Filename of the logfile. +FileLogger::FileLogger(char *filename) : + LoggerBase(filename, 0), m_opened(false), m_fd(-1) +{ + m_fd = open(filename, O_WRONLY|O_CREAT|O_APPEND, 0664); + m_opened = (m_fd != -1); + LOG(VB_GENERAL, LOG_INFO, QString("Added logging to %1") + .arg(filename)); +} + +/// \brief FileLogger deconstructor - close the logfile +FileLogger::~FileLogger() +{ + if( m_opened ) + { + LOG(VB_GENERAL, LOG_INFO, "Removed logging to the console"); + } +} + +/// \brief Reopen the logfile after a SIGHUP. Log files only (no console). +/// This allows for logrollers to be used. +void FileLogger::reopen(void) +{ + char *filename = m_handle.string; + + close(m_fd); + + m_fd = open(filename, O_WRONLY|O_CREAT|O_APPEND, 0664); + m_opened = (m_fd != -1); + LOG(VB_GENERAL, LOG_INFO, QString("Rolled logging on %1") + .arg(filename)); +} + +/// \brief Process a log message, writing to the logfile +/// \param item LoggingItem containing the log message to process +bool FileLogger::logmsg(LoggingItem *item) +{ + char line[MAX_STRING_LENGTH]; + char usPart[9]; + char timestamp[TIMESTAMP_MAX]; + + if (!m_opened) + return false; + + item->refcount.ref(); + + strftime( timestamp, TIMESTAMP_MAX-8, "%Y-%m-%d %H:%M:%S", + (const struct tm *)&item->tm ); + snprintf( usPart, 9, ".%06d", (int)(item->usec) ); + strcat( timestamp, usPart ); + char shortname; + + { + QMutexLocker locker(&loglevelMapMutex); + LoglevelMap::iterator it = loglevelMap.find(item->level); + if (it == loglevelMap.end()) + shortname = '-'; + else + shortname = (*it)->shortname; + } + + if( item->tid ) + snprintf( line, MAX_STRING_LENGTH, + "%s %c [%d/%d] %s %s:%d (%s) - %s\n", + timestamp, shortname, item->pid, item->tid, item->threadName, + item->file, item->line, item->function, item->message ); + else + snprintf( line, MAX_STRING_LENGTH, + "%s %c [%d] %s %s:%d (%s) - %s\n", + timestamp, shortname, item->pid, item->threadName, item->file, + item->line, item->function, item->message ); + } + + int result = write( m_fd, line, strlen(line) ); + + deleteItem(item); + + if( result == -1 ) + { + LOG(VB_GENERAL, LOG_ERR, + QString("Closed Log output on fd %1 due to errors").arg(m_fd)); + m_opened = false; + close( m_fd ); + return false; + } + return true; +} + + +#ifndef _WIN32 +/// \brief SyslogLogger constructor +/// \param facility Syslog facility to use in logging +SyslogLogger::SyslogLogger() : LoggerBase(NULL, 0), m_opened(false) +{ + CODE *name; + + openlog(NULL, LOG_NDELAY, 0 ); + m_opened = true; + + LOG(VB_GENERAL, LOG_INFO, "Added syslogging"); +} + +/// \brief SyslogLogger deconstructor. +SyslogLogger::~SyslogLogger() +{ + LOG(VB_GENERAL, LOG_INFO, "Removing syslogging"); + closelog(); +} + + +/// \brief Process a log message, logging to syslog +/// \param item LoggingItem containing the log message to process +bool SyslogLogger::logmsg(LoggingItem *item) +{ + if (!m_opened) + return false; + + char shortname; + + { + QMutexLocker locker(&loglevelMapMutex); + LoglevelDef *lev = loglevelMap.value(item->level, NULL); + if (!lev) + shortname = '-'; + else + shortname = lev->shortname; + } + + syslog(item->level | item->facility, "%s[%d]: %c %s %s:%d (%s) %s", + item->appName, item->pid, shortname, item->threadName, item->file, + item->line, item->function, item->message); + + return true; +} +#endif + +const int DatabaseLogger::kMinDisabledTime = 1000; + +/// \brief DatabaseLogger constructor +/// \param table C-string of the database table to log to +DatabaseLogger::DatabaseLogger(char *table) : LoggerBase(table, 0), + m_opened(false), + m_loggingTableExists(false) +{ + m_query = QString( + "INSERT INTO %1 " + " (host, application, pid, tid, thread, filename, " + " line, function, msgtime, level, message) " + "VALUES (:HOST, :APP, :PID, :TID, :THREAD, :FILENAME, " + " :LINE, :FUNCTION, :MSGTIME, :LEVEL, :MESSAGE)") + .arg(m_handle.string); + + LOG(VB_GENERAL, LOG_INFO, QString("Added database logging to table %1") + .arg(m_handle.string)); + + m_thread = new DBLoggerThread(this); + m_thread->start(); + + m_opened = true; + m_disabled = false; +} + +/// \brief DatabaseLogger deconstructor +DatabaseLogger::~DatabaseLogger() +{ + LOG(VB_GENERAL, LOG_INFO, "Removing database logging"); + + stopDatabaseAccess(); +} + +/// \brief Stop logging to the database and wait for the thread to stop. +void DatabaseLogger::stopDatabaseAccess(void) +{ + if( m_thread ) + { + m_thread->stop(); + m_thread->wait(); + delete m_thread; + m_thread = NULL; + } +} + +/// \brief Process a log message, queuing it for logging to the database +/// \param item LoggingItem containing the log message to process +bool DatabaseLogger::logmsg(LoggingItem *item) +{ + if (!m_thread) + return false; + + if (!m_thread->isRunning()) + { + m_disabled = true; + m_disabledTime.start(); + } + + if (!m_disabled && m_thread->queueFull()) + { + m_disabled = true; + m_disabledTime.start(); + LOG(VB_GENERAL, LOG_CRIT, + "Disabling DB Logging: too many messages queued"); + return false; + } + + if (m_disabled && m_disabledTime.elapsed() > kMinDisabledTime) + { + if (isDatabaseReady() && !m_thread->queueFull()) + { + m_disabled = false; + LOG(VB_GENERAL, LOG_CRIT, "Reenabling DB Logging"); + } + } + + if (m_disabled) + return false; + + item->refcount.ref(); + m_thread->enqueue(item); + return true; +} + +/// \brief Actually insert a log message from the queue into the database +/// \param query The database insert query to use +/// \param item LoggingItem containing the log message to insert +bool DatabaseLogger::logqmsg(MSqlQuery &query, LoggingItem *item) +{ + char timestamp[TIMESTAMP_MAX]; + char *threadName = getThreadName(item); + pid_t tid = getThreadTid(item); + + strftime( timestamp, TIMESTAMP_MAX-8, "%Y-%m-%d %H:%M:%S", + (const struct tm *)&item->tm ); + + query.bindValue(":TID", tid); + query.bindValue(":THREAD", threadName); + query.bindValue(":FILENAME", item->file); + query.bindValue(":LINE", item->line); + query.bindValue(":FUNCTION", item->function); + query.bindValue(":MSGTIME", timestamp); + query.bindValue(":LEVEL", item->level); + query.bindValue(":MESSAGE", item->message); + + if (!query.exec()) + { + // Suppress Driver not loaded errors that occur at startup. + // and suppress additional errors for one second after the + // previous error (to avoid spamming the log). + QSqlError err = query.lastError(); + if ((err.type() != 1 || err.number() != -1) && + (!m_errorLoggingTime.isValid() || + (m_errorLoggingTime.elapsed() > 1000))) + { + MythDB::DBError("DBLogging", query); + m_errorLoggingTime.start(); + } + return false; + } + + deleteItem(item); + + return true; +} + +/// \brief Prepare the database query for use, and bind constant values to it. +/// \param query The database query to prepare +void DatabaseLogger::prepare(MSqlQuery &query) +{ + query.prepare(m_query); + query.bindValue(":HOST", gCoreContext->GetHostName()); + query.bindValue(":APP", QCoreApplication::applicationName()); + query.bindValue(":PID", getpid()); +} + +/// \brief Check if the database is ready for use +/// \return true when database is ready, false otherwise +bool DatabaseLogger::isDatabaseReady(void) +{ + bool ready = false; + MythDB *db = GetMythDB(); + + if ((db) && db->HaveValidDatabase()) + { + if ( !m_loggingTableExists ) + m_loggingTableExists = tableExists(m_handle.string); + + if ( m_loggingTableExists ) + ready = true; + } + + return ready; +} + +/// \brief Checks whether table exists and is ready for writing +/// \param table The name of the table to check (without schema name) +/// \return true if table exists in schema or false if not +bool DatabaseLogger::tableExists(const QString &table) +{ + bool result = false; + MSqlQuery query(MSqlQuery::InitCon()); + if (query.isConnected()) + { + QString sql = "SELECT INFORMATION_SCHEMA.COLUMNS.COLUMN_NAME " + " FROM INFORMATION_SCHEMA.COLUMNS " + " WHERE INFORMATION_SCHEMA.COLUMNS.TABLE_SCHEMA = " + " DATABASE() " + " AND INFORMATION_SCHEMA.COLUMNS.TABLE_NAME = " + " :TABLENAME " + " AND INFORMATION_SCHEMA.COLUMNS.COLUMN_NAME = " + " :COLUMNNAME;"; + if (query.prepare(sql)) + { + query.bindValue(":TABLENAME", table); + query.bindValue(":COLUMNNAME", "function"); + if (query.exec() && query.next()) + result = true; + } + } + return result; +} + + +/// \brief DBLoggerThread constructor +/// \param logger DatabaseLogger instance that this thread belongs to +DBLoggerThread::DBLoggerThread(DatabaseLogger *logger) : + MThread("DBLogger"), + m_logger(logger), + m_queue(new QQueue), + m_wait(new QWaitCondition()), aborted(false) +{ +} + +/// \brief DBLoggerThread deconstructor. Waits for the thread to finish, then +/// Empties what remains in the queue before deleting it. +DBLoggerThread::~DBLoggerThread() +{ + stop(); + wait(); + + QMutexLocker qLock(&m_queueMutex); + while (!m_queue->empty()) + deleteItem(m_queue->dequeue()); + delete m_queue; + delete m_wait; + m_queue = NULL; + m_wait = NULL; +} + +/// \brief Start the thread. +void DBLoggerThread::run(void) +{ + RunProlog(); + + // Wait a bit before we start logging to the DB.. If we wait too long, + // then short-running tasks (like mythpreviewgen) will not log to the db + // at all, and that's undesirable. + while (true) + { + if ((aborted || (gCoreContext && m_logger->isDatabaseReady()))) + break; + + QMutexLocker locker(&m_queueMutex); + m_wait->wait(locker.mutex(), 100); + } + + if (!aborted) + { + // We want the query to be out of scope before the RunEpilog() so + // shutdown occurs correctly as otherwise the connection appears still + // in use, and we get a qWarning on shutdown. + MSqlQuery *query = new MSqlQuery(MSqlQuery::InitCon()); + m_logger->prepare(*query); + + QMutexLocker qLock(&m_queueMutex); + while (!aborted || !m_queue->isEmpty()) + { + if (m_queue->isEmpty()) + { + m_wait->wait(qLock.mutex(), 100); + continue; + } + + LoggingItem *item = m_queue->dequeue(); + if (!item) + continue; + + qLock.unlock(); + + if (item->message[0] != '\0') + { + if (!m_logger->logqmsg(*query, item)) + { + qLock.relock(); + m_queue->prepend(item); + m_wait->wait(qLock.mutex(), 100); + delete query; + query = new MSqlQuery(MSqlQuery::InitCon()); + m_logger->prepare(*query); + continue; + } + } + else + { + deleteItem(item); + } + + qLock.relock(); + } + + delete query; + + qLock.unlock(); + } + + RunEpilog(); +} + +/// \brief Tell the thread to stop by setting the aborted flag. +void DBLoggerThread::stop(void) +{ + QMutexLocker qLock(&m_queueMutex); + aborted = true; + m_wait->wakeAll(); +} + +/// \brief Get the name of the thread that produced the LoggingItem +/// \param item the LoggingItem in question +/// \return C-string of the thread name +char *getThreadName( LoggingItem *item ) +{ + static const char *unknown = "thread_unknown"; + char *threadName; + + if( !item ) + return( (char *)unknown ); + + if( !item->threadName ) + { + QMutexLocker locker(&logThreadMutex); + if( logThreadHash.contains(item->threadId) ) + threadName = logThreadHash[item->threadId]; + else + threadName = (char *)unknown; + } + else + { + threadName = item->threadName; + } + + return( threadName ); +} + +/// \brief Get the thread ID of the thread that produced the LoggingItem +/// \param item the LoggingItem in question +/// \return Thread ID of the producing thread, cast to a 64-bit signed integer +/// \notes In different platforms, the actual value returned here will vary. +/// The intention is to get a thread ID that will map well to what is +/// shown in gdb. +int64_t getThreadTid( LoggingItem *item ) +{ + pid_t tid = 0; + + if( !item ) + return( 0 ); + + QMutexLocker locker(&logThreadTidMutex); + if( logThreadTidHash.contains(item->threadId) ) + tid = logThreadTidHash[item->threadId]; + + return( tid ); +} + +/// \brief Set the thread ID of the thread that produced the LoggingItem. This +/// code is actually run in the thread in question as part of the call +/// to LOG() +/// \param item the LoggingItem in question +/// \notes In different platforms, the actual value returned here will vary. +/// The intention is to get a thread ID that will map well to what is +/// shown in gdb. +void setThreadTid( LoggingItem *item ) +{ + QMutexLocker locker(&logThreadTidMutex); + + if( ! logThreadTidHash.contains(item->threadId) ) + { + int64_t tid = 0; + +#if defined(linux) + tid = (int64_t)syscall(SYS_gettid); +#elif defined(__FreeBSD__) + long lwpid; + int dummy = thr_self( &lwpid ); + (void)dummy; + tid = (int64_t)lwpid; +#elif CONFIG_DARWIN + tid = (int64_t)mach_thread_self(); +#endif + logThreadTidHash[item->threadId] = tid; + } +} + +/// \brief LogServerThread constructor. +LogServerThread::LogServerThread() : + MThread("LogServer"), m_aborted(false) +{ +} + +/// \brief LogServerThread destructor. +LogServerThread::~LogServerThread() +{ + stop(); + wait(); +} + +/// \brief Run the logging thread. This thread reads from ZeroMQ (TCP:35327) +/// and handles distributing the LoggingItems to each logger instance +/// vi ZeroMQ (inproc). +void LogServerThread::run(void) +{ + RunProlog(); + + logThreadFinished = false; + + m_zmqContext = new nzmqt::PollingZMQContext(this, 4); + m_zmqContext->start(); + + m_zmqInSock = m_zmqContext->createSocket(nzmqt::ZMQSocket::TYP_ROUTER); + connect(m_zmqInSocket, SIGNAL(messageReceived(const QList&)), + this, SLOT(messageReceived(const QList&))); + m_zmqInSock->bindTo("tcp://127.0.0.1:35327"); + + m_zmqPubSock = m_zmqContext->createSocket(nzmqt::ZMQSocket::TYP_PUB); + m_zmqPubSock->bindTo("inproc://loggers"); + + while (!m_aborted) + { + msleep(1000); + // handle heartbeat... + } + + logThreadFinished = true; + + delete m_zmqPubSock; + delete m_zmqInSock; + delete m_zmqContext; + + RunEpilog(); +} + +/// \brief Handles messages received from logging clients +/// \param msg The message received (can be multi-part) +void LoggerThread::messageReceived(const QList &msg) +{ + m_zmqPubSock->sendMessage(msg); +} + + + +/// \brief Handles each LoggingItem, generally by handing it off to the +/// various running logger instances. There is a special case for +/// thread registration and deregistration which are also included in +/// the logging queue to keep the thread names in sync with the log +/// messages. +/// \param item The LoggingItem to be handled +void LoggerThread::handleItem(LoggingItem *item) +{ + if (item->type & kRegistering) + { + int64_t tid = getThreadTid(item); + + QMutexLocker locker(&logThreadMutex); + logThreadHash[item->threadId] = strdup(item->threadName); + + if (debugRegistration) + { + snprintf(item->message, LOGLINE_MAX, + "Thread 0x%" PREFIX64 "X (%" PREFIX64 + "d) registered as \'%s\'", + (long long unsigned int)item->threadId, + (long long int)tid, + logThreadHash[item->threadId]); + } + } + else if (item->type & kDeregistering) + { + int64_t tid = 0; + + { + QMutexLocker locker(&logThreadTidMutex); + if( logThreadTidHash.contains(item->threadId) ) + { + tid = logThreadTidHash[item->threadId]; + logThreadTidHash.remove(item->threadId); + } + } + + QMutexLocker locker(&logThreadMutex); + if (logThreadHash.contains(item->threadId)) + { + if (debugRegistration) + { + snprintf(item->message, LOGLINE_MAX, + "Thread 0x%" PREFIX64 "X (%" PREFIX64 + "d) deregistered as \'%s\'", + (long long unsigned int)item->threadId, + (long long int)tid, + logThreadHash[item->threadId]); + } + item->threadName = logThreadHash[item->threadId]; + logThreadHash.remove(item->threadId); + } + } + + if (item->message[0] != '\0') + { + QMutexLocker locker(&loggerListMutex); + + QList::iterator it; + for (it = loggerList.begin(); it != loggerList.end(); ++it) + (*it)->logmsg(item); + } +} + +/// \brief Stop the thread by setting the abort flag after waiting a second for +/// the queue to be flushed. +void LoggerThread::stop(void) +{ + QMutexLocker qLock(&logQueueMutex); + flush(1000); + aborted = true; + m_waitNotEmpty->wakeAll(); +} + +/// \brief Wait for the queue to be flushed (up to a timeout) +/// \param timeoutMS The number of ms to wait for the queue to flush +/// \return true if the queue is empty, false otherwise +bool LoggerThread::flush(int timeoutMS) +{ + QTime t; + t.start(); + while (!aborted && logQueue.isEmpty() && t.elapsed() < timeoutMS) + { + m_waitNotEmpty->wakeAll(); + int left = timeoutMS - t.elapsed(); + if (left > 0) + m_waitEmpty->wait(&logQueueMutex, left); + } + return logQueue.isEmpty(); +} + +static QList item_recycler; +static QAtomicInt item_count; +static QAtomicInt malloc_count; + +#define DEBUG_MEMORY 0 +#if DEBUG_MEMORY +static int max_count = 0; +static QTime memory_time; +#endif + +/// \brief Create a new LoggingItem +/// \param _file filename of the source file where the log message is from +/// \param _function source function where the log message is from +/// \param _line line number in the source where the log message is from +/// \param _level logging level of the message (LogLevel_t) +/// \param _type type of logging message +/// \return LoggingItem that was created +static LoggingItem *createItem(const char *_file, const char *_function, + int _line, LogLevel_t _level, int _type) +{ + LoggingItem *item = new LoggingItem(_file, _function, _line, _level, _type); + + malloc_count.ref(); + +#if DEBUG_MEMORY + int val = item_count.fetchAndAddRelaxed(1) + 1; + if (val == 0) + memory_time.start(); + max_count = (val > max_count) ? val : max_count; + if (memory_time.elapsed() > 1000) + { + cout<<"current memory usage: " + <refcount.deref()) + { + if (item->threadName) + free(item->threadName); + item_count.deref(); + delete item; + } +} + +/// \brief Fill in the time structure from the current time to make a timestamp +/// for the log message. This is run as part of the LOG() call. +/// \param tm pointer to the time structure to fill in +/// \param usec pointer to a 32bit unsigned int to return the number of us +void LogTimeStamp( struct tm *tm, uint32_t *usec ) +{ + if( !usec || !tm ) + return; + + time_t epoch; + +#if HAVE_GETTIMEOFDAY + struct timeval tv; + gettimeofday(&tv, NULL); + epoch = tv.tv_sec; + *usec = tv.tv_usec; +#else + /* Stupid system has no gettimeofday, use less precise QDateTime */ + QDateTime date = QDateTime::currentDateTime(); + QTime time = date.time(); + epoch = date.toTime_t(); + *usec = time.msec() * 1000; +#endif + + localtime_r(&epoch, tm); +} + +/// \brief Format and send a log message into the queue. This is called from +/// the LOG() macro. The intention is minimal blocking of the caller. +/// \param mask Verbosity mask of the message (VB_*) +/// \param level Log level of this message (LOG_* - matching syslog levels) +/// \param file Filename of source code logging the message +/// \param line Line number within the source of log message source +/// \param function Function name of the log message source +/// \param fromQString true if this message originated from QString +/// \param format printf format string (when not from QString), log message +/// (when from QString) +/// \param ... printf arguments (when not from QString) +void LogPrintLine( uint64_t mask, LogLevel_t level, const char *file, int line, + const char *function, int fromQString, + const char *format, ... ) +{ + va_list arguments; + + QMutexLocker qLock(&logQueueMutex); + + int type = kMessage; + type |= (mask & VB_FLUSH) ? kFlush : 0; + type |= (mask & VB_STDIO) ? kStandardIO : 0; + LoggingItem *item = createItem(file, function, line, level, type); + if (!item) + return; + + char *formatcopy = NULL; + if( fromQString && strchr(format, '%') ) + { + QString string(format); + format = strdup(string.replace(logRegExp, "%%").toLocal8Bit() + .constData()); + formatcopy = (char *)format; + } + + va_start(arguments, format); + vsnprintf(item->message, LOGLINE_MAX, format, arguments); + va_end(arguments); + + if (formatcopy) + free(formatcopy); + + logQueue.enqueue(item); + + if (logThread && logThreadFinished && !logThread->isRunning()) + { + while (!logQueue.isEmpty()) + { + item = logQueue.dequeue(); + qLock.unlock(); + logThread->handleItem(item); + deleteItem(item); + qLock.relock(); + } + } + else if (logThread && !logThreadFinished && (type & kFlush)) + { + logThread->flush(); + } +} + +#ifndef _WIN32 +/// \brief SIGHUP handler - reopen all open logfiles for logrollers +void logSighup( int signum, siginfo_t *info, void *secret ) +{ + LOG(VB_GENERAL, LOG_INFO, "SIGHUP received, rolling log files."); + + /* SIGHUP was sent. Close and reopen debug logfiles */ + QMutexLocker locker(&loggerListMutex); + + QList::iterator it; + for (it = loggerList.begin(); it != loggerList.end(); ++it) + { + (*it)->reopen(); + } +} +#endif + +/// \brief Generate the logPropagateArgs global with the latest logging +/// level, mask, etc to propagate to all of the mythtv programs +/// spawned from this one. +void logPropagateCalc(void) +{ + QString mask = verboseString.trimmed(); + mask.replace(QRegExp(" "), ","); + mask.remove(QRegExp("^,")); + logPropagateArgs = " --verbose " + mask; + + if (logPropagateOpts.propagate) + logPropagateArgs += " --logpath " + logPropagateOpts.path; + + QString name = logLevelGetName(logLevel); + logPropagateArgs += " --loglevel " + name; + + for (int i = 0; i < logPropagateOpts.quiet; i++) + logPropagateArgs += " --quiet"; + + if (!logPropagateOpts.dblog) + logPropagateArgs += " --nodblog"; + +#ifndef _WIN32 + if (logPropagateOpts.facility >= 0) + { + CODE *syslogname; + + for (syslogname = &facilitynames[0]; + (syslogname->c_name && + syslogname->c_val != logPropagateOpts.facility); syslogname++); + + logPropagateArgs += QString(" --syslog %1").arg(syslogname->c_name); + } +#endif +} + +/// \brief Check if we are propagating a "--quiet" +/// \return true if --quiet is being propagated +bool logPropagateQuiet(void) +{ + return logPropagateOpts.quiet; +} + +/// \brief Entry point to start logging for the application. This will +/// start up all of the threads needed. +/// \param logfile Filename of the logfile to create. Empty if no file. +/// \param progress non-zero if progress output will be sent to the console. +/// This squelches all messages less important than LOG_ERR +/// on the console +/// \param quiet quiet level requested (squelches all console output) +/// \param facility Syslog facility to use. -1 to disable syslog output +/// \param level Minimum logging level to put into the logs +/// \param dblog true if database logging is requested +/// \param propagate true if the logfile path needs to be propagated to child +/// processes. +void logStart(QString logfile, int progress, int quiet, int facility, + LogLevel_t level, bool dblog, bool propagate) +{ + LoggerBase *logger; + + { + QMutexLocker qLock(&logQueueMutex); + if (!logThread) + logThread = new LoggerThread(); + } + + if (logThread->isRunning()) + return; + + logLevel = level; + LOG(VB_GENERAL, LOG_NOTICE, QString("Setting Log Level to LOG_%1") + .arg(logLevelGetName(logLevel).toUpper())); + + logPropagateOpts.propagate = propagate; + logPropagateOpts.quiet = quiet; + logPropagateOpts.facility = facility; + logPropagateOpts.dblog = dblog; + + if (propagate) + { + QFileInfo finfo(logfile); + QString path = finfo.path(); + logPropagateOpts.path = path; + } + + logPropagateCalc(); + + /* log to the console */ + logger = new FileLogger((char *)"-", progress, quiet); + + /* Debug logfile */ + if( !logfile.isEmpty() ) + logger = new FileLogger((char *)logfile.toLocal8Bit().constData(), + false, false); + +#ifndef _WIN32 + /* Syslog */ + if( facility == -1 ) + LOG(VB_GENERAL, LOG_CRIT, + "Syslogging facility unknown, disabling syslog output"); + else if( facility >= 0 ) + logger = new SyslogLogger(facility); +#endif + + /* Database */ + if( dblog ) + logger = new DatabaseLogger((char *)"logging"); + +#ifndef _WIN32 + /* Setup SIGHUP */ + LOG(VB_GENERAL, LOG_NOTICE, "Setting up SIGHUP handler"); + struct sigaction sa; + sa.sa_sigaction = logSighup; + sigemptyset( &sa.sa_mask ); + sa.sa_flags = SA_RESTART | SA_SIGINFO; + sigaction( SIGHUP, &sa, NULL ); +#endif + + (void)logger; + + logThread->start(); +} + +/// \brief Entry point for stopping logging for an application +void logStop(void) +{ + if (logThread) + { + logThread->stop(); + logThread->wait(); + } + +#ifndef _WIN32 + /* Tear down SIGHUP */ + struct sigaction sa; + sa.sa_handler = SIG_DFL; + sigemptyset( &sa.sa_mask ); + sa.sa_flags = SA_RESTART; + sigaction( SIGHUP, &sa, NULL ); +#endif + + QList::iterator it; + for (it = loggerList.begin(); it != loggerList.end(); ++it) + { + (*it)->stopDatabaseAccess(); + } +} + +/// \brief Register the current thread with the given name. This is triggered +/// by the RunProlog() call in each thread. +/// \param name the name of the thread being registered. This is used for +/// indicating the thread each log message is coming from. +void loggingRegisterThread(const QString &name) +{ + if (logThreadFinished) + return; + + QMutexLocker qLock(&logQueueMutex); + + LoggingItem *item = createItem(__FILE__, __FUNCTION__, __LINE__, + (LogLevel_t)LOG_DEBUG, kRegistering); + if (item) + { + item->threadName = strdup((char *)name.toLocal8Bit().constData()); + logQueue.enqueue(item); + } +} + +/// \brief Deregister the current thread's name. This is triggered by the +/// RunEpilog() call in each thread. +void loggingDeregisterThread(void) +{ + if (logThreadFinished) + return; + + QMutexLocker qLock(&logQueueMutex); + + LoggingItem *item = createItem(__FILE__, __FUNCTION__, __LINE__, + (LogLevel_t)LOG_DEBUG, kDeregistering); + if (item) + logQueue.enqueue(item); +} + +/// \brief Map a syslog facility name back to the enumerated value +/// \param facility QString containing the facility name +/// \return Syslog facility as enumerated type. Negative if not found. +int syslogGetFacility(QString facility) +{ +#ifdef _WIN32 + LOG(VB_GENERAL, LOG_NOTICE, + "Windows does not support syslog, disabling" ); + return( -2 ); +#else + CODE *name; + int i; + QByteArray ba = facility.toLocal8Bit(); + char *string = (char *)ba.constData(); + + for (i = 0, name = &facilitynames[0]; + name->c_name && strcmp(name->c_name, string); i++, name++); + + return( name->c_val ); +#endif +} + +/// \brief Map a log level name back to the enumerated value +/// \param level QString containing the log level name +/// \return Log level as enumerated type. LOG_UNKNOWN if not found. +LogLevel_t logLevelGet(QString level) +{ + QMutexLocker locker(&loglevelMapMutex); + if (!verboseInitialized) + { + locker.unlock(); + verboseInit(); + locker.relock(); + } + + for (LoglevelMap::iterator it = loglevelMap.begin(); + it != loglevelMap.end(); ++it) + { + LoglevelDef *item = (*it); + if ( item->name == level.toLower() ) + return (LogLevel_t)item->value; + } + + return LOG_UNKNOWN; +} + +/// \brief Map a log level enumerated value back to the name +/// \param level Enumerated value of the log level +/// \return Log level name. "unknown" if not found. +QString logLevelGetName(LogLevel_t level) +{ + QMutexLocker locker(&loglevelMapMutex); + if (!verboseInitialized) + { + locker.unlock(); + verboseInit(); + locker.relock(); + } + LoglevelMap::iterator it = loglevelMap.find((int)level); + + if ( it == loglevelMap.end() ) + return QString("unknown"); + + return (*it)->name; +} + +/// \brief Add a verbose level to the verboseMap. Done at initialization. +/// \param mask verbose mask (VB_*) +/// \param name name of the verbosity level +/// \param additive true if this is to be ORed with other masks. false if +/// is will clear the other bits. +/// \param helptext Descriptive text for --verbose help output +void verboseAdd(uint64_t mask, QString name, bool additive, QString helptext) +{ + VerboseDef *item = new VerboseDef; + + item->mask = mask; + name.detach(); + // VB_GENERAL -> general + name.remove(0, 3); + name = name.toLower(); + item->name = name; + item->additive = additive; + helptext.detach(); + item->helpText = helptext; + + verboseMap.insert(name, item); +} + +/// \brief Add a log level to the logLevelMap. Done at initialization. +/// \param value log level enumerated value (LOG_*) - matches syslog +/// levels +/// \param name name of the log level +/// \param shortname one-letter short name for output into logs +void loglevelAdd(int value, QString name, char shortname) +{ + LoglevelDef *item = new LoglevelDef; + + item->value = value; + name.detach(); + // LOG_CRIT -> crit + name.remove(0, 4); + name = name.toLower(); + item->name = name; + item->shortname = shortname; + + loglevelMap.insert(value, item); +} + +/// \brief Initialize the logging levels and verbose levels. +void verboseInit(void) +{ + QMutexLocker locker(&verboseMapMutex); + QMutexLocker locker2(&loglevelMapMutex); + verboseMap.clear(); + loglevelMap.clear(); + + // This looks funky, so I'll put some explanation here. The verbosedefs.h + // file gets included as part of the mythlogging.h include, and at that + // time, the normal (without _IMPLEMENT_VERBOSE defined) code case will + // define the VerboseMask enum. At this point, we force it to allow us + // to include the file again, but with _IMPLEMENT_VERBOSE set so that the + // single definition of the VB_* values can be shared to define also the + // contents of verboseMap, via repeated calls to verboseAdd() + +#undef VERBOSEDEFS_H_ +#define _IMPLEMENT_VERBOSE +#include "verbosedefs.h" + + verboseInitialized = true; +} + + +/// \brief Outputs the Verbose levels and their descriptions +/// (for --verbose help) +void verboseHelp(void) +{ + QString m_verbose = verboseString.trimmed(); + m_verbose.replace(QRegExp(" "), ","); + m_verbose.remove(QRegExp("^,")); + + cerr << "Verbose debug levels.\n" + "Accepts any combination (separated by comma) of:\n\n"; + + for (VerboseMap::Iterator vit = verboseMap.begin(); + vit != verboseMap.end(); ++vit ) + { + VerboseDef *item = vit.value(); + QString name = QString(" %1").arg(item->name, -15, ' '); + if (item->helpText.isEmpty()) + continue; + cerr << name.toLocal8Bit().constData() << " - " << + item->helpText.toLocal8Bit().constData() << endl; + } + + cerr << endl << + "The default for this program appears to be: '-v " << + m_verbose.toLocal8Bit().constData() << "'\n\n" + "Most options are additive except for 'none' and 'all'.\n" + "These two are semi-exclusive and take precedence over any\n" + "other options. However, you may use something like\n" + "'-v none,jobqueue' to receive only JobQueue related messages\n" + "and override the default verbosity level.\n\n" + "Additive options may also be subtracted from 'all' by\n" + "prefixing them with 'no', so you may use '-v all,nodatabase'\n" + "to view all but database debug messages.\n\n" + "Some debug levels may not apply to this program.\n\n"; +} + +/// \brief Parse the --verbose commandline argument and set the verbose level +/// \param arg the commandline argument following "--verbose" +/// \return an exit code. GENERIC_EXIT_OK if all is well. +int verboseArgParse(QString arg) +{ + QString option; + + if (!verboseInitialized) + verboseInit(); + + QMutexLocker locker(&verboseMapMutex); + + verboseMask = verboseDefaultInt; + verboseString = QString(verboseDefaultStr); + + if (arg.startsWith('-')) + { + cerr << "Invalid or missing argument to -v/--verbose option\n"; + return GENERIC_EXIT_INVALID_CMDLINE; + } + + QStringList verboseOpts = arg.split(QRegExp("\\W+")); + for (QStringList::Iterator it = verboseOpts.begin(); + it != verboseOpts.end(); ++it ) + { + option = (*it).toLower(); + bool reverseOption = false; + + if (option != "none" && option.left(2) == "no") + { + reverseOption = true; + option = option.right(option.length() - 2); + } + + if (option == "help") + { + verboseHelp(); + return GENERIC_EXIT_INVALID_CMDLINE; + } + else if (option == "important") + { + cerr << "The \"important\" log mask is no longer valid.\n"; + } + else if (option == "extra") + { + cerr << "The \"extra\" log mask is no longer valid. Please try " + "--loglevel debug instead.\n"; + } + else if (option == "default") + { + if (haveUserDefaultValues) + { + verboseMask = userDefaultValueInt; + verboseString = userDefaultValueStr; + } + else + { + verboseMask = verboseDefaultInt; + verboseString = QString(verboseDefaultStr); + } + } + else + { + VerboseDef *item = verboseMap.value(option); + + if (item) + { + if (reverseOption) + { + verboseMask &= ~(item->mask); + verboseString = verboseString.remove(' ' + item->name); + verboseString += " no" + item->name; + } + else + { + if (item->additive) + { + if (!(verboseMask & item->mask)) + { + verboseMask |= item->mask; + verboseString += ' ' + item->name; + } + } + else + { + verboseMask = item->mask; + verboseString = item->name; + } + } + } + else + { + cerr << "Unknown argument for -v/--verbose: " << + option.toLocal8Bit().constData() << endl;; + return GENERIC_EXIT_INVALID_CMDLINE; + } + } + } + + if (!haveUserDefaultValues) + { + haveUserDefaultValues = true; + userDefaultValueInt = verboseMask; + userDefaultValueStr = verboseString; + } + + return GENERIC_EXIT_OK; +} + +/// \brief Verbose helper function for ENO macro. +/// \param errnum system errno value +/// \return QString containing the string version of the errno value, plus the +/// errno value itself. +QString logStrerror(int errnum) +{ + return QString("%1 (%2)").arg(strerror(errnum)).arg(errnum); +} + + +/* + * vim:ts=4:sw=4:ai:et:si:sts=4 + */ diff --git a/mythtv/libs/libmythbase/loggingserver.h b/mythtv/libs/libmythbase/loggingserver.h new file mode 100644 index 00000000000..a8827a5d08d --- /dev/null +++ b/mythtv/libs/libmythbase/loggingserver.h @@ -0,0 +1,210 @@ +#ifndef LOGGINGSERVER_H_ +#define LOGGINGSERVER_H_ + +#include +#include +#include +#include + +#include +#include +#include + +#include "mythbaseexp.h" // MBASE_PUBLIC , etc. +#include "verbosedefs.h" +#include "mthread.h" +#include "nzmqt.hpp" + +#define LOGLINE_MAX (2048-120) + +class QString; +class MSqlQuery; +class LoggingItem; + +/// \brief Base class for the various logging mechanisms +class LoggerBase : public QObject { + Q_OBJECT + + public: + /// \brief LoggerBase Constructor + LoggerBase(char *string, int number); + /// \brief LoggerBase Deconstructor + virtual ~LoggerBase(); + /// \brief Process a log message for the logger instance + /// \param item LoggingItem containing the log message to process + virtual bool logmsg(LoggingItem *item) = 0; + /// \brief Reopen the log file to facilitate log rolling + virtual void reopen(void) = 0; + /// \brief Stop logging to the database + virtual void stopDatabaseAccess(void) { } + /// \brief Deal with an incoming log message + virtual void messageReceived(const QList&) = 0; + protected: + LoggerHandle_t m_handle; ///< semi-opaque handle for identifying instance + bool m_string; ///< true if m_handle.string valid, false otherwise +}; + +/// \brief File-based logger - used for logfiles and console +class FileLogger : public LoggerBase { + public: + FileLogger(char *filename); + ~FileLogger(); + bool logmsg(LoggingItem *item); + void reopen(void); + void messageReceived(const QList&); + private: + bool m_opened; ///< true when the logfile is opened + int m_fd; ///< contains the file descriptor for the logfile +}; + +#ifndef _WIN32 +/// \brief Syslog-based logger (not available in Windows) +class SyslogLogger : public LoggerBase { + public: + SyslogLogger(int facility, char *application); + ~SyslogLogger(); + bool logmsg(LoggingItem *item); + /// \brief Unused for this logger. + void reopen(void) { }; + void messageReceived(const QList&); + private: + char *m_application; ///< C-string of the application name + bool m_opened; ///< true when syslog channel open. +}; +#endif + +class DBLoggerThread; + +/// \brief Database logger - logs to the MythTV database +class DatabaseLogger : public LoggerBase { + friend class DBLoggerThread; + public: + DatabaseLogger(char *table); + ~DatabaseLogger(); + bool logmsg(LoggingItem *item); + void reopen(void) { }; + virtual void stopDatabaseAccess(void); + void messageReceived(const QList&); + protected: + bool logqmsg(MSqlQuery &query, LoggingItem *item); + void prepare(MSqlQuery &query); + private: + bool isDatabaseReady(void); + bool tableExists(const QString &table); + + DBLoggerThread *m_thread; ///< The database queue handling thread + QString m_query; ///< The database query to insert log messages + bool m_opened; ///< The database is opened + bool m_loggingTableExists; ///< The desired logging table exists + bool m_disabled; ///< DB logging is temporarily disabled + QTime m_disabledTime; ///< Time when the DB logging was disabled + QTime m_errorLoggingTime; ///< Time when DB error logging was last done + static const int kMinDisabledTime; ///< Minimum time to disable DB logging + /// (in ms) +}; + + +/// \brief The logging thread that received the messages from the clients via +/// ZeroMQ and dispatches each LoggingItem to each logger instance via +/// ZeroMQ. +class LogServerThread : public QObject, public MThread +{ + Q_OBJECT; + public: + LogServerThread(); + ~LogServerThread(); + void run(void); + void stop(void); + private: + bool m_aborted; ///< Flag to abort the thread. + nzmqt::PollingZMQContext *m_zmqContext; ///< ZeroMQ context + nzmqt::ZMQSocket *m_zmqInSock; ///< ZeroMQ feeding socket + nzmqt::ZMQSocket *m_zmqPubSock; ///< ZeroMQ publishing socket + protected slots: + void messageReceived(const QList&); +}; + +/// \brief Thread that manages the queueing of logging inserts for the database. +/// The database logging gets throttled if it gets overwhelmed, and also +/// during startup. Having a second queue allows the rest of the +/// logging to remain in sync and to allow for burstiness in the +/// database due to things like scheduler runs. +class DBLoggerThread : public MThread +{ + public: + DBLoggerThread(DatabaseLogger *logger); + ~DBLoggerThread(); + void run(void); + void stop(void); + /// \brief Enqueues a LoggingItem onto the queue for the thread to + /// consume. + bool enqueue(LoggingItem *item) + { + QMutexLocker qLock(&m_queueMutex); + if (!aborted) + m_queue->enqueue(item); + return true; + } + + /// \brief Indicates when the queue is full + /// \return true when the queue is full + bool queueFull(void) + { + QMutexLocker qLock(&m_queueMutex); + return (m_queue->size() >= MAX_QUEUE_LEN); + } + private: + DatabaseLogger *m_logger; ///< The associated logger instance + QMutex m_queueMutex; ///< Mutex for protecting the queue + QQueue *m_queue; ///< Queue of LoggingItems to insert + QWaitCondition *m_wait; ///< Wait condition used for waiting + /// for the queue to not be full. + /// Protected by m_queueMutex + volatile bool aborted; ///< Used during shutdown to indicate + /// that the thread should stop ASAP. + /// Protected by m_queueMutex +}; + +/// \brief Thread that manages the queueing of logging inserts to mythlogserver, +/// and dealing with any messages sent back. +class ZeroMQLoggerThread : public MThread +{ + public: + ZeroMQLoggerThread(ZeroMQLogger *logger); + ~ZeroMQLoggerThread(); + void run(void); + void stop(void); + /// \brief Enqueues a LoggingItem onto the queue for the thread to + /// consume. + bool enqueue(LoggingItem *item) + { + QMutexLocker qLock(&m_queueMutex); + if (!aborted) + m_queue->enqueue(item); + return true; + } + + /// \brief Indicates when the queue is full + /// \return true when the queue is full + bool queueFull(void) + { + QMutexLocker qLock(&m_queueMutex); + return (m_queue->size() >= MAX_QUEUE_LEN); + } + private: + ZeroMQLogger *m_logger; ///< The associated logger instance + QMutex m_queueMutex; ///< Mutex for protecting the queue + QQueue *m_queue; ///< Queue of LoggingItems to insert + QWaitCondition *m_wait; ///< Wait condition used for waiting + /// for the queue to not be full. + /// Protected by m_queueMutex + volatile bool aborted; ///< Used during shutdown to indicate + /// that the thread should stop ASAP. + /// Protected by m_queueMutex +}; + +#endif + +/* + * vim:ts=4:sw=4:ai:et:si:sts=4 + */