strepsirrhini/libreoffice-online
3
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

wsd: cleanup logging and remove unused helpers

Browse source 
Now all logging is done after checking if the
level in question is enabled or not (thanks to
the macros LOG_XXX), which saves unnecessary
conversions and stringification when said level
is disabled.

Change-Id: Icde31e067f60269563896f04f8b0d65643720766
Reviewed-on: https://gerrit.libreoffice.org/47885
Reviewed-by: Michael Meeks <michael.meeks@collabora.com>
Tested-by: Michael Meeks <michael.meeks@collabora.com>
This commit is contained in:
Ashod Nakashian 2018-01-14 20:39:06 -05:00 committed by Ashod Nakashian
parent 13e2868601
commit c06376cc1d
7 changed files with 77 additions and 114 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

42
common/Log.cpp
View file

@ -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: */

20
common/Log.hpp
View file

@ -22,6 +22,13 @@
#include <Poco/DateTimeFormatter.h>
#include <Poco/Logger.h>
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;

71
test/UnitAdmin.cpp
View file

@ -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<std::mutex> 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<std::mutex> lock(_messageReceivedMutex);
_messageReceivedCV.notify_all();
_messageReceived = message;
Log::info("UnitAdmin:: onAdminQueryMessage: " + message);
LOG_INF("UnitAdmin:: onAdminQueryMessage: " << message);
}
};

2
test/UnitTimeout.cpp
View file

@ -37,7 +37,7 @@ public:
{
if (!_timedOut)
{
Log::info("Failed to timeout");
LOG_INF("Failed to timeout");
retValue = Poco::Util::Application::EXIT_SOFTWARE;
}
else

44
wsd/DocumentBroker.cpp
View file

@ -544,7 +544,8 @@ bool DocumentBroker::load(const std::shared_ptr<ClientSession>& 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<ClientSession>& 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<ClientSession>& 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<ClientSession>& 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::vector<std::string>args;
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<std::string> 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;
}

10
wsd/QueueHandler.hpp
View file

@ -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:

2
wsd/Storage.cpp
View file

@ -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)
{