diff --git a/common/Log.cpp b/common/Log.cpp index 5a4f121f2..ac05d2cc6 100644 --- a/common/Log.cpp +++ b/common/Log.cpp @@ -182,53 +182,13 @@ namespace Log } oss << " Log level is [" << logger.getLevel() << "]."; - info(oss.str()); + LOG_INF(oss.str()); } Poco::Logger& logger() { return Poco::Logger::get(Source.inited ? Source.name : std::string()); } - - void trace(const std::string& msg) - { - LOG_TRC(msg); - } - - void debug(const std::string& msg) - { - LOG_DBG(msg); - } - - void info(const std::string& msg) - { - LOG_INF(msg); - } - - void warn(const std::string& msg) - { - LOG_WRN(msg); - } - - void error(const std::string& msg) - { - LOG_ERR(msg); - } - - void syserror(const std::string& msg) - { - LOG_SYS(msg); - } - - void fatal(const std::string& msg) - { - LOG_FTL(msg); - } - - void sysfatal(const std::string& msg) - { - LOG_SFL(msg); - } } /* vim:set shiftwidth=4 softtabstop=4 expandtab: */ diff --git a/common/Log.hpp b/common/Log.hpp index 0be4983f5..a3e4a9ae1 100644 --- a/common/Log.hpp +++ b/common/Log.hpp @@ -22,6 +22,13 @@ #include #include +inline std::ostream& operator<< (std::ostream& os, const Poco::Timestamp& ts) +{ + os << Poco::DateTimeFormatter::format(Poco::DateTime(ts), + Poco::DateTimeFormat::ISO8601_FRAC_FORMAT); + return os; +} + namespace Log { void initialize(const std::string& name, @@ -33,15 +40,6 @@ namespace Log char* prefix(char* buffer, const char* level, bool sigSafe); - void trace(const std::string& msg); - void debug(const std::string& msg); - void info(const std::string& msg); - void warn(const std::string& msg); - void error(const std::string& msg); - void syserror(const std::string& msg); - void fatal(const std::string& msg); - void sysfatal(const std::string& msg); - inline bool traceEnabled() { return logger().trace(); } inline bool debugEnabled() { return logger().debug(); } inline bool infoEnabled() { return logger().information(); } @@ -177,8 +175,8 @@ namespace Log { if (lhs.enabled()) { - lhs._stream << Poco::DateTimeFormatter::format(Poco::DateTime(rhs), - Poco::DateTimeFormat::ISO8601_FRAC_FORMAT); + lhs._stream << Poco::DateTimeFormatter::format(Poco::DateTime(rhs), + Poco::DateTimeFormat::ISO8601_FRAC_FORMAT); } return lhs; diff --git a/test/UnitAdmin.cpp b/test/UnitAdmin.cpp index cbead413f..acc058e46 100644 --- a/test/UnitAdmin.cpp +++ b/test/UnitAdmin.cpp @@ -79,7 +79,7 @@ private: if (response.getStatus() == HTTPResponse::HTTP_UNAUTHORIZED) res = TestResult::Ok; - Log::info(std::string("testIncorrectPassword: ") + (res == TestResult::Ok ? "OK" : "FAIL")); + LOG_INF("testIncorrectPassword: " << (res == TestResult::Ok ? "OK" : "FAIL")); return res; } @@ -117,10 +117,10 @@ private: } else { - Log::info("testCorrectPassword: Invalid cookie properties"); + LOG_INF("testCorrectPassword: Invalid cookie properties"); } - Log::info(std::string("testCorrectPassword: ") + (res == TestResult::Ok ? "OK" : "FAIL")); + LOG_INF("testCorrectPassword: " << (res == TestResult::Ok ? "OK" : "FAIL")); return res; } @@ -138,7 +138,7 @@ private: _adminWs->sendFrame(testMessage.data(), testMessage.size()); if (_messageReceivedCV.wait_for(lock, std::chrono::milliseconds(_messageTimeoutMilliSeconds)) == std::cv_status::timeout) { - Log::info("testWebSocketWithoutAuth: Timed out waiting for admin console message"); + LOG_INF("testWebSocketWithoutAuth: Timed out waiting for admin console message"); return TestResult::TimedOut; } lock.unlock(); @@ -147,11 +147,11 @@ private: if (tokens.count() != 1 || tokens[0] != "NotAuthenticated") { - Log::info("testWebSocketWithoutAuth: Unrecognized message format"); + LOG_INF("testWebSocketWithoutAuth: Unrecognized message format"); return TestResult::Failed; } - Log::info(std::string("testWebSocketWithoutAuth: OK")); + LOG_INF("testWebSocketWithoutAuth: OK"); return TestResult::Ok; } @@ -169,7 +169,7 @@ private: _adminWs->sendFrame(testMessage.data(), testMessage.size()); if (_messageReceivedCV.wait_for(lock, std::chrono::milliseconds(_messageTimeoutMilliSeconds)) == std::cv_status::timeout) { - Log::info("testWebSocketWithIncorrectAuthToken: Timed out waiting for admin console message"); + LOG_INF("testWebSocketWithIncorrectAuthToken: Timed out waiting for admin console message"); return TestResult::TimedOut; } lock.unlock(); @@ -178,11 +178,11 @@ private: if (tokens.count() != 1 || tokens[0] != "InvalidAuthToken") { - Log::info("testWebSocketWithIncorrectAuthToken: Unrecognized message format"); + LOG_INF("testWebSocketWithIncorrectAuthToken: Unrecognized message format"); return TestResult::Failed; } - Log::info(std::string("testWebSocketWithIncorrectAuthToken: OK")); + LOG_INF("testWebSocketWithIncorrectAuthToken: OK"); return TestResult::Ok; } @@ -220,7 +220,7 @@ private: _docWs1->sendFrame(loadMessage1.data(), loadMessage1.size()); if (_messageReceivedCV.wait_for(lock, std::chrono::milliseconds(_messageTimeoutMilliSeconds)) == std::cv_status::timeout) { - Log::info("testAddDocNotify: Timed out waiting for admin console message"); + LOG_INF("testAddDocNotify: Timed out waiting for admin console message"); return TestResult::TimedOut; } lock.unlock(); @@ -231,7 +231,7 @@ private: tokens[0] != "adddoc" || tokens[2] != documentPath1.substr(documentPath1.find_last_of("/") + 1) ) { - Log::info("testAddDocNotify: Unrecognized message format"); + LOG_INF("testAddDocNotify: Unrecognized message format"); return TestResult::Failed; } @@ -248,7 +248,7 @@ private: _docWs2->sendFrame(loadMessage1.data(), loadMessage1.size()); if (_messageReceivedCV.wait_for(lock, std::chrono::milliseconds(_messageTimeoutMilliSeconds)) == std::cv_status::timeout) { - Log::info("testAddDocNotify: Timed out waiting for admin console message"); + LOG_INF("testAddDocNotify: Timed out waiting for admin console message"); return TestResult::TimedOut; } lock.unlock(); @@ -259,7 +259,7 @@ private: tokens[0] != "adddoc" || tokens[2] != documentPath1.substr(documentPath1.find_last_of("/") + 1) ) { - Log::info("testAddDocNotify: Unrecognized message format"); + LOG_INF("testAddDocNotify: Unrecognized message format"); return TestResult::Failed; } @@ -283,7 +283,7 @@ private: _docWs3->sendFrame(loadMessage2.data(), loadMessage2.size()); if (_messageReceivedCV.wait_for(lock, std::chrono::milliseconds(_messageTimeoutMilliSeconds)) == std::cv_status::timeout) { - Log::info("testAddDocNotify: Timed out waiting for admin console message"); + LOG_INF("testAddDocNotify: Timed out waiting for admin console message"); return TestResult::TimedOut; } lock.unlock(); @@ -294,7 +294,7 @@ private: tokens[0] != "adddoc" || tokens[2] != documentPath2.substr(documentPath2.find_last_of("/") + 1) ) { - Log::info("testAddDocNotify: Unrecognized message format"); + LOG_INF("testAddDocNotify: Unrecognized message format"); return TestResult::Failed; } @@ -304,7 +304,7 @@ private: } _docsCount++; - Log::info(std::string("testAddDocNotify: OK")); + LOG_INF("testAddDocNotify: OK"); return TestResult::Ok; } @@ -317,7 +317,7 @@ private: _adminWs->sendFrame(queryMessage.data(), queryMessage.size()); if (_messageReceivedCV.wait_for(lock, std::chrono::milliseconds(_messageTimeoutMilliSeconds)) == std::cv_status::timeout) { - Log::info("testUsersCount: Timed out waiting for admin console message"); + LOG_INF("testUsersCount: Timed out waiting for admin console message"); return TestResult::TimedOut; } lock.unlock(); @@ -326,18 +326,18 @@ private: if (tokens.count() != 2 || tokens[0] != "active_users_count") { - Log::info("testUsersCount: Unrecognized message format"); + LOG_INF("testUsersCount: Unrecognized message format"); return TestResult::Failed; } else if (std::stoi(tokens[1]) != _usersCount) { - Log::info("testUsersCount: Incorrect users count " + LOG_INF("testUsersCount: Incorrect users count " ", expected: " + std::to_string(_usersCount) + ", actual: " + tokens[1]); return TestResult::Failed; } - Log::info(std::string("testUsersCount: OK")); + LOG_INF("testUsersCount: OK"); return TestResult::Ok; } @@ -350,7 +350,7 @@ private: _adminWs->sendFrame(queryMessage.data(), queryMessage.size()); if (_messageReceivedCV.wait_for(lock, std::chrono::milliseconds(_messageTimeoutMilliSeconds)) == std::cv_status::timeout) { - Log::info("testDocCount: Timed out waiting for admin console message"); + LOG_INF("testDocCount: Timed out waiting for admin console message"); return TestResult::TimedOut; } lock.unlock(); @@ -360,18 +360,18 @@ private: tokens[0] != "active_docs_count" || std::stoi(tokens[1]) != _docsCount) { - Log::info("testDocCount: Unrecognized message format"); + LOG_INF("testDocCount: Unrecognized message format"); return TestResult::Failed; } else if (std::stoi(tokens[1]) != _docsCount) { - Log::info("testDocCount: Incorrect doc count " + LOG_INF("testDocCount: Incorrect doc count " ", expected: " + std::to_string(_docsCount) + ", actual: " + tokens[1]); return TestResult::Failed; } - Log::info(std::string("testDocCount: OK")); + LOG_INF("testDocCount: OK"); return TestResult::Ok; } @@ -386,7 +386,7 @@ private: _docWs1->close(); if (_messageReceivedCV.wait_for(lock, std::chrono::milliseconds(_messageTimeoutMilliSeconds)) == std::cv_status::timeout) { - Log::info("testRmDocNotify: Timed out waiting for admin console message"); + LOG_INF("testRmDocNotify: Timed out waiting for admin console message"); return TestResult::TimedOut; } lock.unlock(); @@ -396,12 +396,12 @@ private: tokens[0] != "rmdoc" || stoi(tokens[1]) != _docPid1) { - Log::info("testRmDocNotify: Invalid message format"); + LOG_INF("testRmDocNotify: Invalid message format"); return TestResult::Failed; } _usersCount--; - Log::info(std::string("testRmDocNotify: OK")); + LOG_INF("testRmDocNotify: OK"); return TestResult::Ok; } @@ -435,12 +435,17 @@ public: { _isTestRunning = true; AdminTest test = _tests[_testCounter++]; - Log::info("UnitAdmin:: Starting test #" + std::to_string(_testCounter)); + LOG_INF("UnitAdmin:: Starting test #" << _testCounter); TestResult res = ((*this).*(test))(); - Log::info("UnitAdmin:: Finished test #" + std::to_string(_testCounter)); + LOG_INF("UnitAdmin:: Finished test #" << _testCounter); if (res != TestResult::Ok) { - Log::info("Exiting with " + (res == TestResult::Failed ? "FAIL" : (res == TestResult::TimedOut) ? "TIMEOUT" : "??? (" + std::to_string((int)res) + ")")); + LOG_INF("Exiting with " << + (res == TestResult::Failed + ? "FAIL" + : (res == TestResult::TimedOut) + ? "TIMEOUT" + : "??? (" + std::to_string((int)res) + ")")); exitTest(res); assert(false); return; @@ -449,7 +454,7 @@ public: // End this when all tests are finished if (_tests.size() == _testCounter) { - Log::info("Exiting with OK"); + LOG_INF("Exiting with OK"); exitTest(TestResult::Ok); } @@ -462,7 +467,7 @@ public: std::unique_lock lock(_messageReceivedMutex); _messageReceivedCV.notify_all(); _messageReceived = message; - Log::info("UnitAdmin:: onAdminNotifyMessage: " + message); + LOG_INF("UnitAdmin:: onAdminNotifyMessage: " << message); } virtual void onAdminQueryMessage(const std::string& message) @@ -470,7 +475,7 @@ public: std::unique_lock lock(_messageReceivedMutex); _messageReceivedCV.notify_all(); _messageReceived = message; - Log::info("UnitAdmin:: onAdminQueryMessage: " + message); + LOG_INF("UnitAdmin:: onAdminQueryMessage: " << message); } }; diff --git a/test/UnitTimeout.cpp b/test/UnitTimeout.cpp index 0097d6357..6c9a05194 100644 --- a/test/UnitTimeout.cpp +++ b/test/UnitTimeout.cpp @@ -37,7 +37,7 @@ public: { if (!_timedOut) { - Log::info("Failed to timeout"); + LOG_INF("Failed to timeout"); retValue = Poco::Util::Application::EXIT_SOFTWARE; } else diff --git a/wsd/DocumentBroker.cpp b/wsd/DocumentBroker.cpp index 476ad544d..a5f891589 100644 --- a/wsd/DocumentBroker.cpp +++ b/wsd/DocumentBroker.cpp @@ -544,7 +544,8 @@ bool DocumentBroker::load(const std::shared_ptr& session, const s watermarkText = LOOLWSD::OverrideWatermark; #endif - LOG_DBG("Setting username [" << username << "] and userId [" << userid << "] for session [" << sessionId << "]"); + LOG_DBG("Setting username [" << username << "] and userId [" << + userid << "] for session [" << sessionId << "]"); session->setUserId(userid); session->setUserName(username); session->setUserExtraInfo(userExtraInfo); @@ -561,20 +562,20 @@ bool DocumentBroker::load(const std::shared_ptr& session, const s if (firstInstance) { _documentLastModifiedTime = fileInfo._modifiedTime; - Log::debug() << "Document timestamp: " << _documentLastModifiedTime << Log::end; + LOG_DBG("Document timestamp: " << _documentLastModifiedTime); } else { // Check if document has been modified by some external action - Log::trace() << "Document modified time: " << fileInfo._modifiedTime << Log::end; + LOG_TRC("Document modified time: " << fileInfo._modifiedTime); static const Poco::Timestamp Zero(Poco::Timestamp::fromEpochTime(0)); if (_documentLastModifiedTime != Zero && fileInfo._modifiedTime != Zero && _documentLastModifiedTime != fileInfo._modifiedTime) { - Log::trace() << "Document " << _docKey << "] has been modified behind our back. Informing all clients." - << "Expected: " << _documentLastModifiedTime - << "Actual: " << fileInfo._modifiedTime << Log::end; + LOG_TRC("Document " << _docKey << "] has been modified behind our back. " << + "Informing all clients. Expected: " << _documentLastModifiedTime << + ", Actual: " << fileInfo._modifiedTime); _documentChangedInStorage = true; std::string message = "close: documentconflict"; @@ -596,9 +597,9 @@ bool DocumentBroker::load(const std::shared_ptr& session, const s { try { - std::string extension(plugin->getString("prefilter.extension")); - std::string newExtension(plugin->getString("prefilter.newextension")); - std::string commandLine(plugin->getString("prefilter.commandline")); + const std::string extension(plugin->getString("prefilter.extension")); + const std::string newExtension(plugin->getString("prefilter.newextension")); + const std::string commandLine(plugin->getString("prefilter.commandline")); if (localPath.length() > extension.length()+1 && strcasecmp(localPath.substr(localPath.length() - extension.length() -1).data(), (std::string(".") + extension).data()) == 0) @@ -606,28 +607,28 @@ bool DocumentBroker::load(const std::shared_ptr& session, const s // Extension matches, try the conversion. We convert the file to another one in // the same (jail) directory, with just the new extension tacked on. - std::string newRootPath = _storage->getRootFilePath() + "." + newExtension; + const std::string newRootPath = _storage->getRootFilePath() + "." + newExtension; // The commandline must contain the space-separated substring @INPUT@ that is // replaced with the input file name, and @OUTPUT@ for the output file name. - - std::vectorargs; - Poco::StringTokenizer tokenizer(commandLine, " "); if (tokenizer.replace("@INPUT@", _storage->getRootFilePath()) != 1 || tokenizer.replace("@OUTPUT@", newRootPath) != 1) throw Poco::NotFoundException(); - for (std::size_t i = 1; i < tokenizer.count(); i++) - args.push_back(tokenizer[i]); + + std::vector args; + for (std::size_t i = 1; i < tokenizer.count(); ++i) + args.emplace_back(tokenizer[i]); Poco::ProcessHandle process = Poco::Process::launch(tokenizer[0], args); - int rc = process.wait(); + const int rc = process.wait(); if (rc != 0) { - LOG_ERR("Conversion from " << extension << " to " << newExtension <<" failed"); + LOG_ERR("Conversion from " << extension << " to " << newExtension << " failed (" << rc << ")."); return false; } + _storage->setRootFilePath(newRootPath); localPath += "." + newExtension; } @@ -783,9 +784,8 @@ bool DocumentBroker::saveToStorageInternal(const std::string& sessionId, // After a successful save, we are sure that document in the storage is same as ours _documentChangedInStorage = false; - Log::debug() << "Saved docKey [" << _docKey << "] to URI [" << uri - << "] and updated tile cache. Document modified timestamp: " - << _documentLastModifiedTime << Log::end; + LOG_DBG("Saved docKey [" << _docKey << "] to URI [" << uri << "] and updated timestamps. " << + " Document modified timestamp: " << _documentLastModifiedTime); // Resume polling. _poll->wakeup(); @@ -801,8 +801,8 @@ bool DocumentBroker::saveToStorageInternal(const std::string& sessionId, it->second->sendTextFrame("saveas: url=" + url + " filename=" + encodedName); - Log::debug() << "Saved As docKey [" << _docKey << "] to URI [" << url - << " with name '" << encodedName << "'] successfully."; + LOG_DBG("Saved As docKey [" << _docKey << "] to URI [" << url << + " with name '" << encodedName << "'] successfully."); } return true; } diff --git a/wsd/QueueHandler.hpp b/wsd/QueueHandler.hpp index 8ef3f6231..54aea6ad7 100644 --- a/wsd/QueueHandler.hpp +++ b/wsd/QueueHandler.hpp @@ -31,7 +31,7 @@ public: { Util::setThreadName(_name); - Log::debug("Thread started."); + LOG_DBG("Thread started."); try { @@ -40,23 +40,23 @@ public: const auto input = _queue->get(); if (LOOLProtocol::getFirstToken(input) == "eof") { - Log::info("Received EOF. Finishing."); + LOG_INF("Received EOF. Finishing."); break; } if (!_session->handleInput(input.data(), input.size())) { - Log::info("Socket handler flagged for finishing."); + LOG_INF("Socket handler flagged for finishing."); break; } } } catch (const std::exception& exc) { - Log::error(std::string("QueueHandler::run: Exception: ") + exc.what()); + LOG_ERR("QueueHandler::run: Exception: " << exc.what()); } - Log::debug("Thread finished."); + LOG_DBG("Thread finished."); } private: diff --git a/wsd/Storage.cpp b/wsd/Storage.cpp index 7985b42e3..d5c8db6b7 100644 --- a/wsd/Storage.cpp +++ b/wsd/Storage.cpp @@ -313,7 +313,7 @@ StorageBase::SaveResult LocalStorage::saveLocalFileToStorage(const Authorization // update its fileinfo object. This is used later to check if someone else changed the // document while we are/were editing it _fileInfo._modifiedTime = Poco::File(_uri.getPath()).getLastModified(); - Log::trace() << "New FileInfo modified time in storage " << _fileInfo._modifiedTime << Log::end; + LOG_TRC("New FileInfo modified time in storage " << _fileInfo._modifiedTime); } catch (const Poco::Exception& exc) {