diff --git a/README.md b/README.md index 211fc40..f81c9ab 100644 --- a/README.md +++ b/README.md @@ -51,3 +51,15 @@ For a protocol-only test that does not create a window: Set `RKT_WEBVIEW_PRG` to test a backend executable outside the test program's directory. + +### Backend logging + +Diagnostics written through `utils.h` use one-line structured stderr records: + +```text +json:{"topic":"webview-backend","level":"info","elapsed":0.125,"message":"..."} +``` + +Stdout remains reserved for protocol messages. Unstructured stderr output from +Qt or third-party libraries may still occur and should be treated as diagnostic +text. diff --git a/STDIO-PROTOCOL.md b/STDIO-PROTOCOL.md index 75f03ab..49933aa 100644 --- a/STDIO-PROTOCOL.md +++ b/STDIO-PROTOCOL.md @@ -69,3 +69,18 @@ A normal shutdown sends `CMD_QUIT`, waits for its result, closes the child's stdin, and waits for the child process. If the Racket process terminates unexpectedly, the operating system closes the pipe; EOF on stdin makes the Qt backend close all windows and quit. + +## Structured stderr logging + +The backend writes diagnostic logging to stderr, never to stdout. Log entries +created through `utils.h` are emitted as one line beginning with `json:` followed +by a compact JSON object: + +```text +json:{"topic":"webview-backend","level":"debug","elapsed":1.234,"message":"..."} +``` + +Newlines and other control characters in the message are JSON escaped, so one +C++ log call always produces one physical stderr line. Consumers should also +accept unstructured stderr lines because Qt, Qt WebEngine, or another library +may write diagnostics directly. diff --git a/utils.cpp b/utils.cpp index a701588..4ad588f 100644 --- a/utils.cpp +++ b/utils.cpp @@ -1,17 +1,36 @@ - #include "utils.h" + +#include +#include +#include + #include +#include +#include +#include typedef struct { std::chrono::time_point start; } timer; - - static int _log_level = LOG_INFO; static timer *_timer = nullptr; +static QString formattedMessage(const char *format, va_list args) +{ + va_list countArgs; + va_copy(countArgs, args); + const int length = std::vsnprintf(nullptr, 0, format, countArgs); + va_end(countArgs); + if (length < 0) { + return QString::fromUtf8(format); + } + + std::vector buffer(static_cast(length) + 1); + std::vsnprintf(buffer.data(), buffer.size(), format, args); + return QString::fromUtf8(buffer.data(), length); +} extern "C" { int logLevel() @@ -27,27 +46,48 @@ void setLogLevel(int l) const char *logIndicator(int l) { switch(l) { - case LOG_ERROR: return "ERROR "; - case LOG_INFO: return "INFO "; - case LOG_DEBUG: return "DEBUG "; - case LOG_WARNING: return "WARNING"; + case LOG_ERROR: return "error"; + case LOG_INFO: return "info"; + case LOG_DEBUG: return "debug"; + case LOG_WARNING: return "warning"; } - return "UNKNOWN"; + return "unknown"; } -void logElapsed() +double logElapsedSeconds() { if (_timer == nullptr) { _timer = new timer; _timer->start = std::chrono::system_clock::now(); } - auto c = std::chrono::system_clock::now(); - auto duration = c - _timer->start; - auto milliseconds + const auto current = std::chrono::system_clock::now(); + const auto milliseconds = std::chrono::duration_cast( - duration) + current - _timer->start) .count(); - fprintf(stderr, "%8.3lf: ", milliseconds/ 1000.0); + return milliseconds / 1000.0; +} + +void logMessage(int level, const char *format, ...) +{ + if (logLevel() < level) { + return; + } + + va_list args; + va_start(args, format); + const QString message = formattedMessage(format, args); + va_end(args); + + QJsonObject object; + object.insert(QStringLiteral("topic"), QStringLiteral("webview-backend")); + object.insert(QStringLiteral("level"), QString::fromLatin1(logIndicator(level))); + object.insert(QStringLiteral("elapsed"), logElapsedSeconds()); + object.insert(QStringLiteral("message"), message); + + const QByteArray json = QJsonDocument(object).toJson(QJsonDocument::Compact); + std::fprintf(stderr, "json:%s\n", json.constData()); + std::fflush(stderr); } } diff --git a/utils.h b/utils.h index f8a0399..96df110 100644 --- a/utils.h +++ b/utils.h @@ -29,6 +29,7 @@ inline std::string basedir(const std::string &path) } return r; } + extern "C" { #ifdef RKTWEBVIEW_PRG_EXE #undef RKTWEBVIEW_EXPORT @@ -37,8 +38,9 @@ extern "C" { RKTWEBVIEW_EXPORT int logLevel(); RKTWEBVIEW_EXPORT void setLogLevel(int l); -RKTWEBVIEW_EXPORT void logElapsed(); +RKTWEBVIEW_EXPORT double logElapsedSeconds(); RKTWEBVIEW_EXPORT const char *logIndicator(int l); +RKTWEBVIEW_EXPORT void logMessage(int level, const char *format, ...); } #define LOG_ERROR 1 @@ -46,28 +48,22 @@ RKTWEBVIEW_EXPORT const char *logIndicator(int l); #define LOG_INFO 3 #define LOG_DEBUG 4 -#define MKLOGSTMT(level, code) if (logLevel() >= level) { fprintf(stderr, "%s: ", logIndicator(level));logElapsed();code;fflush(stderr); } -#define MKL0(level, msg) MKLOGSTMT(level, fprintf(stderr, msg)) -#define MKL1(level, msg, a) MKLOGSTMT(level, fprintf(stderr, msg, a)) -#define MKL2(level, msg, a, b) MKLOGSTMT(level, fprintf(stderr, msg, a, b)) -#define MKL3(level, msg, a, b, c) MKLOGSTMT(level, fprintf(stderr, msg, a, b, c)) +#define ERROR0(msg) logMessage(LOG_ERROR, msg) +#define WARN0(msg) logMessage(LOG_WARNING, msg) +#define INFO0(msg) logMessage(LOG_INFO, msg) +#define DEBUG0(msg) logMessage(LOG_DEBUG, msg) -#define ERROR0(msg) MKL0(LOG_ERROR, msg) -#define WARN0(msg) MKL0(LOG_WARNING, msg) -#define INFO0(msg) MKL0(LOG_INFO, msg) -#define DEBUG0(msg) MKL0(LOG_DEBUG, msg) +#define ERROR1(msg, a) logMessage(LOG_ERROR, msg, a) +#define WARN1(msg, a) logMessage(LOG_WARNING, msg, a) +#define INFO1(msg, a) logMessage(LOG_INFO, msg, a) +#define DEBUG1(msg, a) logMessage(LOG_DEBUG, msg, a) -#define ERROR1(msg, a) MKL1(LOG_ERROR, msg, a) -#define WARN1(msg, a) MKL1(LOG_WARNING, msg, a) -#define INFO1(msg, a) MKL1(LOG_INFO, msg, a) -#define DEBUG1(msg, a) MKL1(LOG_DEBUG, msg, a) +#define ERROR2(msg, a, b) logMessage(LOG_ERROR, msg, a, b) +#define WARN2(msg, a, b) logMessage(LOG_WARNING, msg, a, b) +#define INFO2(msg, a, b) logMessage(LOG_INFO, msg, a, b) +#define DEBUG2(msg, a, b) logMessage(LOG_DEBUG, msg, a, b) -#define ERROR2(msg, a, b) MKL2(LOG_ERROR, msg, a, b) -#define WARN2(msg, a, b) MKL2(LOG_WARNING, msg, a, b) -#define INFO2(msg, a, b) MKL2(LOG_INFO, msg, a, b) -#define DEBUG2(msg, a, b) MKL2(LOG_DEBUG, msg, a, b) - -#define INFO3(msg, a, b, c) MKL3(LOG_INFO, msg, a, b, c) +#define INFO3(msg, a, b, c) logMessage(LOG_INFO, msg, a, b, c) inline void do_free_data(rkt_data_t *d) {