wsd: test: better logging

Change-Id: I3d17afb2e76f1d4b2b27182a6419482801342e8c
Signed-off-by: Ashod Nakashian <ashod.nakashian@collabora.co.uk>
This commit is contained in:
Ashod Nakashian 2021-03-08 21:59:33 -05:00 committed by Ashod Nakashian
parent 89a587a695
commit 95bb52d945
5 changed files with 37 additions and 26 deletions

View file

@ -7,6 +7,8 @@
#pragma once
#include <test/testlog.hpp>
#include <cstdlib>
#include <mutex>
#include <thread>
@ -47,20 +49,20 @@ public:
/// or -1 if no "interesting" (not PING or PONG) frame was actually received).
/// Should we also factor out the handling of non-final and continuation frames into this?
int receiveFrame(char* buffer, const int length, int& flags)
int receiveFrame(char* buffer, const int length, int& flags,
const std::string& testname = std::string())
{
// Timeout is in microseconds. We don't need this, except to yield the cpu.
static const Poco::Timespan waitTime(POLL_TIMEOUT_MICRO_S / 10);
static const Poco::Timespan waitZero(0);
while (poll(waitTime, Poco::Net::Socket::SELECT_READ))
{
const int n = Poco::Net::WebSocket::receiveFrame(buffer, length, flags);
if (n <= 0)
LOG_TRC("Got nothing (" << n << ')');
TST_LOG("Got nothing (" << n << ')');
else
LOG_TRC("Got frame: " << getAbbreviatedFrameDump(buffer, n, flags));
TST_LOG("Got frame: " << getAbbreviatedFrameDump(buffer, n, flags));
if ((flags & WebSocket::FRAME_OP_BITMASK) == WebSocket::FRAME_OP_CLOSE)
{
@ -71,9 +73,12 @@ public:
if ((flags & WebSocket::FRAME_OP_BITMASK) == WebSocket::FRAME_OP_PING)
{
// Echo back the ping message.
if (Poco::Net::WebSocket::sendFrame(buffer, n, static_cast<int>(WebSocket::FRAME_FLAG_FIN) | WebSocket::FRAME_OP_PONG) != n)
if (Poco::Net::WebSocket::sendFrame(buffer, n,
static_cast<int>(WebSocket::FRAME_FLAG_FIN)
| WebSocket::FRAME_OP_PONG)
!= n)
{
LOG_WRN("Sending Pong failed.");
TST_LOG("WARN: Sending Pong failed.");
return -1;
}
}
@ -92,20 +97,20 @@ public:
}
/// Wrapper for Poco::Net::WebSocket::sendFrame() that handles large frames.
int sendFrame(const char* buffer, const int length, const int flags = FRAME_TEXT)
int sendFrame(const char* buffer, const int length, const int flags = FRAME_TEXT,
const std::string& testname = std::string())
{
static const Poco::Timespan waitZero(0);
const int result = Poco::Net::WebSocket::sendFrame(buffer, length, flags);
if (result != length)
{
LOG_ERR("Sent incomplete message, expected " << length << " bytes but sent " << result <<
" for: " << getAbbreviatedFrameDump(buffer, length, flags));
TST_LOG("ERROR: Sent incomplete message, expected "
<< length << " bytes but sent " << result
<< " for: " << getAbbreviatedFrameDump(buffer, length, flags));
}
else
{
LOG_TRC("Sent frame: " << getAbbreviatedFrameDump(buffer, length, flags));
TST_LOG("Sent frame: " << getAbbreviatedFrameDump(buffer, length, flags));
}
return result;
@ -113,14 +118,15 @@ public:
/// Safe shutdown by sending a normal close frame, if socket is not in error,
/// or, otherwise, close the socket without sending close frame, if it is.
void shutdown()
void shutdown(const std::string& testname = std::string())
{
shutdown(Poco::Net::WebSocket::StatusCodes::WS_NORMAL_CLOSE);
shutdown(Poco::Net::WebSocket::StatusCodes::WS_NORMAL_CLOSE, testname);
}
/// Safe shutdown by sending a specific close frame, if socket is not in error,
/// or, otherwise, close the socket without sending close frame, if it is.
void shutdown(Poco::UInt16 statusCode, const std::string& statusMessage = "")
void shutdown(Poco::UInt16 statusCode, const std::string& statusMessage = std::string(),
const std::string& testname = std::string())
{
try
{
@ -138,8 +144,9 @@ public:
}
catch (const Poco::Exception& exc)
{
LOG_WRN("LOOLWebSocket::shutdown: Exception: " << exc.displayText() <<
(exc.nested() ? " (" + exc.nested()->displayText() + ')' : ""));
TST_LOG("WARN: LOOLWebSocket::shutdown: Exception: "
<< exc.displayText()
<< (exc.nested() ? " (" + exc.nested()->displayText() + ')' : ""));
// Just close it.
try

View file

@ -304,8 +304,8 @@ public:
return;
LOG_TST("Close sockets:");
socket->shutdown();
socket2->shutdown();
socket->shutdown(testname);
socket2->shutdown(testname);
sleep(1); // paranoia.

View file

@ -238,7 +238,7 @@ int getErrorCode(LOOLWebSocket& ws, std::string& message, const std::string& tes
do
{
// Read next WS frame and log it.
bytes = ws.receiveFrame(buffer.begin(), READ_BUFFER_SIZE, flags);
bytes = ws.receiveFrame(buffer.begin(), READ_BUFFER_SIZE, flags, testname);
std::this_thread::sleep_for(std::chrono::milliseconds(50));
}
while (bytes > 0 && (flags & Poco::Net::WebSocket::FRAME_OP_BITMASK) != Poco::Net::WebSocket::FRAME_OP_CLOSE);
@ -288,7 +288,7 @@ std::vector<char> getResponseMessage(LOOLWebSocket& ws, const std::string& prefi
if (ws.poll(Poco::Timespan(waitTimeUs), Poco::Net::Socket::SELECT_READ))
{
response.resize(READ_BUFFER_SIZE * 8);
const int bytes = ws.receiveFrame(response.data(), response.size(), flags);
const int bytes = ws.receiveFrame(response.data(), response.size(), flags, testname);
response.resize(std::max(bytes, 0));
const auto message = LOOLProtocol::getFirstLine(response);
if (bytes > 0 && (flags & Poco::Net::WebSocket::FRAME_OP_BITMASK) != Poco::Net::WebSocket::FRAME_OP_CLOSE)
@ -512,7 +512,7 @@ void SocketProcessor(const std::string& testname,
break;
}
n = socket->receiveFrame(buffer, sizeof(buffer), flags);
n = socket->receiveFrame(buffer, sizeof(buffer), flags, testname);
TST_LOG("Got " << LOOLWebSocket::getAbbreviatedFrameDump(buffer, n, flags));
if (n > 0 && (flags & Poco::Net::WebSocket::FRAME_OP_BITMASK) != Poco::Net::WebSocket::FRAME_OP_CLOSE)
{

View file

@ -150,7 +150,7 @@ void HTTPCrashTest::testCrashKit()
// respond close frame
TST_LOG("Shutting down socket.");
socket->shutdown();
socket->shutdown(testname);
TST_LOG("Reading after shutdown.");
@ -223,7 +223,7 @@ void HTTPCrashTest::testCrashForkit()
assertResponseString(socket, "status:", testname);
// respond close frame
socket->shutdown();
socket->shutdown(testname);
TST_LOG("Killing loolkit.");
killLoKitProcesses();

View file

@ -59,6 +59,8 @@ using Poco::Util::Application;
static bool closeExpected = false;
static std::mutex coutMutex;
constexpr auto Name = "connect ";
/// Prints incoming data from a LOOLWebSocket.
class Output : public Runnable
{
@ -77,7 +79,7 @@ public:
do
{
char buffer[100000];
n = _ws.receiveFrame(buffer, sizeof(buffer), flags);
n = _ws.receiveFrame(buffer, sizeof(buffer), flags, Name);
if (n > 0 && (flags & WebSocket::FRAME_OP_BITMASK) != WebSocket::FRAME_OP_CLOSE)
{
{
@ -209,6 +211,7 @@ protected:
std::unique_lock<std::mutex> lock(coutMutex);
std::cout << "Sending: '" << line << '\'' << std::endl;
}
ws.sendFrame(line.c_str(), line.size());
}
}
@ -217,8 +220,9 @@ protected:
std::unique_lock<std::mutex> lock(coutMutex);
std::cout << "Shutting down websocket" << std::endl;
}
closeExpected = true;
ws.shutdown();
ws.shutdown(Name);
thread.join();
return EX_OK;