haraldwolff
/
collabora-online
mirror of https://github.com/CollaboraOnline/online.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Logging: annotate WebSocket, Admin and cleanup Forkit. 

Significantly calmer and less frenzied logging output.

Signed-off-by: Michael Meeks <michael.meeks@collabora.com>
Change-Id: I0f1782c0b8f10ac3427bac479ded2862f2b40b7a
pull/9054/head
Michael Meeks 2024-05-10 17:02:00 +01:00
parent 3746a51479
commit b95e4d8424
6 changed files with 33 additions and 37 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

5
kit/ForKit.cpp
View File

@ -283,9 +283,6 @@ static void cleanupChildren()
int status = 0;
int segFaultCount = 0;
LOG_TRC("cleanupChildren with " << childJails.size()
<< (childJails.size() == 1 ? " child" : " children"));
// Reap quickly without doing slow cleanup so WSD can spawn more rapidly.
while ((exitedChildPid = waitpid(-1, &status, WUNTRACED | WNOHANG)) > 0)
{
@ -321,7 +318,7 @@ static void cleanupChildren()
}
}
if (Log::traceEnabled())
if (Log::traceEnabled() && cleanupJailPaths.size() > 0)
{
std::ostringstream oss;
for (const auto& pair : childJails)

2
net/Socket.cpp
View File

@ -115,7 +115,7 @@ bool StreamSocket::simulateSocketError(bool read)
{
if ((socketErrorCount++ % 7) == 0)
{
LOG_TRC("Simulating socket error during " << (read ? "read." : "write."));
LOGA_TRC(Socket, "Simulating socket error during " << (read ? "read." : "write."));
errno = EAGAIN;
return true;
}

6
net/Socket.hpp
View File

@ -1462,9 +1462,9 @@ public:
if (len < 0 && last_errno != EAGAIN && last_errno != EWOULDBLOCK)
LOG_SYS_ERRNO(last_errno, "Socket write returned " << len);
else if (len <= 0) // Trace errno for debugging, even for "unspecified result."
LOG_TRC("Write failed, have " << _outBuffer.size() << " buffered bytes ("
<< Util::symbolicErrno(last_errno) << ": "
<< std::strerror(last_errno) << ')');
LOGA_TRC(Socket, "Write failed, have " << _outBuffer.size() << " buffered bytes ("
<< Util::symbolicErrno(last_errno) << ": "
<< std::strerror(last_errno) << ')');
else // Success.
LOGA_TRC(Socket, "Wrote " << len << " bytes of " << _outBuffer.size() << " buffered data"
#ifdef LOG_SOCKET_DATA

45
net/WebSocketHandler.hpp
View File

@ -137,7 +137,7 @@ public:
bool isSecure, SocketPoll& poll)
{
const std::string hostAndPort = host + ':' + port;
LOG_TRC("Web-Socket request: " << hostAndPort);
LOGA_TRC(WebSocket, "Web-Socket request: " << hostAndPort);
auto socket = net::connect(host, port, isSecure, shared_from_this());
if (!socket)
@ -176,7 +176,7 @@ protected:
_socket = socket;
setLogContext(socket->getFD());
LOG_TRC("Connected to WS Handler " << this);
LOGA_TRC(WebSocket, "Connected to WS Handler " << this);
}
/// Sends WS Close frame to the peer.
@ -200,8 +200,8 @@ protected:
// Don't send close-frame more than once.
if (!_shuttingDown)
{
LOG_TRC("Shutdown websocket, code: " << static_cast<unsigned>(statusCode)
<< ", message: " << statusMessage);
LOGA_TRC(WebSocket, "Shutdown websocket, code: "
<< static_cast<unsigned>(statusCode) << ", message: " << statusMessage);
_shuttingDown = true;
if (!Util::isMobileApp())
@ -244,7 +244,7 @@ public:
std::shared_ptr<StreamSocket> socket = _socket.lock();
if (socket)
{
LOG_TRC("Shutdown: Closing Connection");
LOGA_TRC(WebSocket, "Shutdown: Closing Connection");
if (!_shuttingDown)
sendCloseFrame(statusCode, statusMessage);
socket->closeConnection();
@ -285,7 +285,7 @@ private:
#if !MOBILEAPP
if (len < 2) // partial read
{
LOG_TRC("Still incomplete WebSocket message, have " << len << " bytes");
LOGA_TRC(WebSocket, "Still incomplete WebSocket message, have " << len << " bytes");
return false;
}
@ -302,7 +302,7 @@ private:
{
if (len < 2 + 2)
{
LOG_TRC("Still incomplete WebSocket message, have " << len << " bytes");
LOGA_TRC(WebSocket, "Still incomplete WebSocket message, have " << len << " bytes");
return false;
}
@ -313,7 +313,7 @@ private:
{
if (len < 2 + 8)
{
LOG_TRC("Still incomplete WebSocket message, have " << len << " bytes");
LOGA_TRC(WebSocket, "Still incomplete WebSocket message, have " << len << " bytes");
return false;
}
payloadLen = ((((uint64_t)p[9]) << 0) + (((uint64_t)p[8]) << 8) +
@ -334,7 +334,7 @@ private:
if (headerLen > len || payloadLen > len - headerLen)
{ // partial read wait for more data.
LOG_TRC("Still incomplete WebSocket frame, have "
LOGA_TRC(WebSocket, "Still incomplete WebSocket frame, have "
<< len << " bytes, frame is " << payloadLen + headerLen << " bytes");
return false;
}
@ -346,7 +346,7 @@ private:
return true;
}
LOG_TRC("Incoming WebSocket data of "
LOGA_TRC(WebSocket, "Incoming WebSocket data of "
<< len << " bytes: "
<< Util::stringifyHexLine(socket->getInBuffer(), 0, std::min((size_t)32, len)));
@ -360,7 +360,7 @@ private:
readPayload(data, payloadLen, mask, ctrlPayload);
socket->getInBuffer().eraseFirst(headerLen + payloadLen);
LOG_TRC("Incoming WebSocket frame code "
LOGA_TRC(WebSocket, "Incoming WebSocket frame code "
<< static_cast<unsigned>(code) << ", fin? " << fin << ", mask? " << hasMask
<< ", payload length: " << payloadLen
<< ", residual socket data: " << socket->getInBuffer().size() << " bytes");
@ -388,7 +388,7 @@ private:
_pingTimeUs = std::chrono::duration_cast<std::chrono::microseconds>
(std::chrono::steady_clock::now() - _lastPingSentTime).count();
LOG_TRC("Pong received: " << _pingTimeUs << " microseconds");
LOGA_TRC(WebSocket, "Pong received: " << _pingTimeUs << " microseconds");
gotPing(code, _pingTimeUs);
}
break;
@ -467,8 +467,7 @@ private:
#if !MOBILEAPP
LOG_TRC(
"Incoming WebSocket frame code "
LOGA_TRC(WebSocket, "Incoming WebSocket frame code "
<< static_cast<unsigned>(code) << ", fin? " << fin << ", mask? " << hasMask
<< ", payload length: " << payloadLen
<< ", residual socket data: " << socket->getInBuffer().size()
@ -597,7 +596,7 @@ private:
return;
}
LOG_TRC("Sending " << (const char*)(code == WSOpCode::Ping ? " ping" : "pong"));
LOGA_TRC(WebSocket, "Sending " << (const char*)(code == WSOpCode::Ping ? " ping" : "pong"));
// FIXME: allow an empty payload.
sendMessage(data, len, code, false);
_lastPingSentTime = now;
@ -796,9 +795,9 @@ protected:
ASSERT_CORRECT_SOCKET_THREAD(socket);
Buffer& out = socket->getOutBuffer();
LOG_TRC("WebSocketHandler: Writing " << len << " bytes to #" << socket->getFD()
<< " in addition to " << out.size()
<< " bytes buffered");
LOGA_TRC(WebSocket, "WebSocketHandler: Writing " << len << " bytes to #" << socket->getFD()
<< " in addition to " << out.size()
<< " bytes buffered");
#if ENABLE_DEBUG
if ((flags & 0xf) == (int)WSOpCode::Text) // utf8 validate
@ -956,7 +955,7 @@ protected:
[[maybe_unused]] const T& req)
{
assert(socket && "Must have a valid socket");
LOG_TRC("Upgrading to WebSocket");
LOGA_TRC(WebSocket, "Upgrading to WebSocket");
assert(!socket->isWebSocket());
assert(!_isClient && "Accepting upgrade requests are done by servers only.");
@ -978,7 +977,7 @@ protected:
httpResponse.set("Upgrade", "websocket");
httpResponse.set("Connection", "Upgrade");
httpResponse.set("Sec-WebSocket-Accept", computeAccept(wsKey));
LOG_TRC("Sending WS Upgrade response: " << httpResponse.header().toString());
LOGA_TRC(WebSocket, "Sending WS Upgrade response: " << httpResponse.header().toString());
socket->send(httpResponse);
#endif
setWebSocket(socket);
@ -993,8 +992,8 @@ protected:
Buffer& data = socket->getInBuffer();
LOG_TRC("Incoming client websocket upgrade response: " << std::string(data.data(),
data.size()));
LOGA_TRC(WebSocket, "Incoming client websocket upgrade response: "
<< std::string(data.data(), data.size()));
// Consume the incoming data by parsing and processing the body.
http::Response response(
@ -1005,7 +1004,7 @@ protected:
Util::iequal(response.get("Connection", ""), "Upgrade") &&
response.get("Sec-WebSocket-Accept", "") == computeAccept(_key))
{
LOG_TRC("Accepted incoming websocket response");
LOGA_TRC(WebSocket, "Accepted incoming websocket response");
setWebSocket(socket);
}
else

8
wsd/Admin.cpp
View File

@ -652,7 +652,7 @@ void Admin::pollingThread()
if (_lastRecvCount != recvCount || _lastSentCount != sentCount)
{
LOG_TRC("Total Data sent: " << sentCount << ", recv: " << recvCount);
LOGA_TRC(Admin, "Total Data sent: " << sentCount << ", recv: " << recvCount);
_lastRecvCount = recvCount;
_lastSentCount = sentCount;
}
@ -691,7 +691,7 @@ void Admin::pollingThread()
// Handle websockets & other work.
const auto timeout = std::chrono::milliseconds(capAndRoundInterval(
std::min(std::min(std::min(cpuWait, memWait), netWait), cleanupWait)));
LOG_TRC("Admin poll for " << timeout);
LOGA_TRC(Admin, "Admin poll for " << timeout);
poll(timeout); // continue with ms for admin, settings etc.
}
@ -969,12 +969,12 @@ void Admin::triggerMemoryCleanup(const size_t totalMem)
static const double memLimit = COOLWSD::getConfigValue<double>("memproportion", 0.0);
if (memLimit == 0.0 || _totalSysMemKb == 0)
{
LOG_TRC("Total memory consumed: " << totalMem <<
LOGA_TRC(Admin, "Total memory consumed: " << totalMem <<
" KB. Not configured to do memory cleanup. Skipping memory cleanup.");
return;
}
LOG_TRC("Total memory consumed: " << totalMem << " KB. Configured COOL memory proportion: " <<
LOGA_TRC(Admin, "Total memory consumed: " << totalMem << " KB. Configured COOL memory proportion: " <<
memLimit << "% (" << static_cast<size_t>(_totalSysMemKb * memLimit / 100.) << " KB).");
const double memToFreePercentage = (totalMem / static_cast<double>(_totalSysMemKb)) - memLimit / 100.;

4
wsd/AdminModel.cpp
View File

@ -301,8 +301,8 @@ unsigned AdminModel::getKitsMemoryUsage()
if (docs > 0)
{
LOG_TRC("Got total Kits memory of " << totalMem << " bytes for " << docs <<
" docs, avg: " << static_cast<double>(totalMem) / docs << " bytes / doc.");
LOGA_TRC(Admin, "Got total Kits memory of " << totalMem << " bytes for " << docs <<
" docs, avg: " << static_cast<double>(totalMem) / docs << " bytes / doc.");
}
return totalMem;