This commit is contained in:
2026-08-04 13:00:56 +02:00
parent d9af82d230
commit a1a56cd08c
4 changed files with 97 additions and 34 deletions
+12
View File
@@ -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 Set `RKT_WEBVIEW_PRG` to test a backend executable outside the test program's
directory. 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.
+15
View File
@@ -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 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 unexpectedly, the operating system closes the pipe; EOF on stdin makes the Qt
backend close all windows and quit. 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.
+54 -14
View File
@@ -1,17 +1,36 @@
#include "utils.h" #include "utils.h"
#include <QJsonDocument>
#include <QJsonObject>
#include <QString>
#include <chrono> #include <chrono>
#include <cstdarg>
#include <cstdio>
#include <vector>
typedef struct { typedef struct {
std::chrono::time_point<std::chrono::system_clock> start; std::chrono::time_point<std::chrono::system_clock> start;
} timer; } timer;
static int _log_level = LOG_INFO; static int _log_level = LOG_INFO;
static timer *_timer = nullptr; 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<char> buffer(static_cast<size_t>(length) + 1);
std::vsnprintf(buffer.data(), buffer.size(), format, args);
return QString::fromUtf8(buffer.data(), length);
}
extern "C" { extern "C" {
int logLevel() int logLevel()
@@ -27,27 +46,48 @@ void setLogLevel(int l)
const char *logIndicator(int l) const char *logIndicator(int l)
{ {
switch(l) { switch(l) {
case LOG_ERROR: return "ERROR "; case LOG_ERROR: return "error";
case LOG_INFO: return "INFO "; case LOG_INFO: return "info";
case LOG_DEBUG: return "DEBUG "; case LOG_DEBUG: return "debug";
case LOG_WARNING: return "WARNING"; case LOG_WARNING: return "warning";
} }
return "UNKNOWN"; return "unknown";
} }
void logElapsed() double logElapsedSeconds()
{ {
if (_timer == nullptr) { if (_timer == nullptr) {
_timer = new timer; _timer = new timer;
_timer->start = std::chrono::system_clock::now(); _timer->start = std::chrono::system_clock::now();
} }
auto c = std::chrono::system_clock::now(); const auto current = std::chrono::system_clock::now();
auto duration = c - _timer->start; const auto milliseconds
auto milliseconds
= std::chrono::duration_cast<std::chrono::milliseconds>( = std::chrono::duration_cast<std::chrono::milliseconds>(
duration) current - _timer->start)
.count(); .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);
} }
} }
+16 -20
View File
@@ -29,6 +29,7 @@ inline std::string basedir(const std::string &path)
} }
return r; return r;
} }
extern "C" { extern "C" {
#ifdef RKTWEBVIEW_PRG_EXE #ifdef RKTWEBVIEW_PRG_EXE
#undef RKTWEBVIEW_EXPORT #undef RKTWEBVIEW_EXPORT
@@ -37,8 +38,9 @@ extern "C" {
RKTWEBVIEW_EXPORT int logLevel(); RKTWEBVIEW_EXPORT int logLevel();
RKTWEBVIEW_EXPORT void setLogLevel(int l); RKTWEBVIEW_EXPORT void setLogLevel(int l);
RKTWEBVIEW_EXPORT void logElapsed(); RKTWEBVIEW_EXPORT double logElapsedSeconds();
RKTWEBVIEW_EXPORT const char *logIndicator(int l); RKTWEBVIEW_EXPORT const char *logIndicator(int l);
RKTWEBVIEW_EXPORT void logMessage(int level, const char *format, ...);
} }
#define LOG_ERROR 1 #define LOG_ERROR 1
@@ -46,28 +48,22 @@ RKTWEBVIEW_EXPORT const char *logIndicator(int l);
#define LOG_INFO 3 #define LOG_INFO 3
#define LOG_DEBUG 4 #define LOG_DEBUG 4
#define MKLOGSTMT(level, code) if (logLevel() >= level) { fprintf(stderr, "%s: ", logIndicator(level));logElapsed();code;fflush(stderr); } #define ERROR0(msg) logMessage(LOG_ERROR, msg)
#define MKL0(level, msg) MKLOGSTMT(level, fprintf(stderr, msg)) #define WARN0(msg) logMessage(LOG_WARNING, msg)
#define MKL1(level, msg, a) MKLOGSTMT(level, fprintf(stderr, msg, a)) #define INFO0(msg) logMessage(LOG_INFO, msg)
#define MKL2(level, msg, a, b) MKLOGSTMT(level, fprintf(stderr, msg, a, b)) #define DEBUG0(msg) logMessage(LOG_DEBUG, msg)
#define MKL3(level, msg, a, b, c) MKLOGSTMT(level, fprintf(stderr, msg, a, b, c))
#define ERROR0(msg) MKL0(LOG_ERROR, msg) #define ERROR1(msg, a) logMessage(LOG_ERROR, msg, a)
#define WARN0(msg) MKL0(LOG_WARNING, msg) #define WARN1(msg, a) logMessage(LOG_WARNING, msg, a)
#define INFO0(msg) MKL0(LOG_INFO, msg) #define INFO1(msg, a) logMessage(LOG_INFO, msg, a)
#define DEBUG0(msg) MKL0(LOG_DEBUG, msg) #define DEBUG1(msg, a) logMessage(LOG_DEBUG, msg, a)
#define ERROR1(msg, a) MKL1(LOG_ERROR, msg, a) #define ERROR2(msg, a, b) logMessage(LOG_ERROR, msg, a, b)
#define WARN1(msg, a) MKL1(LOG_WARNING, msg, a) #define WARN2(msg, a, b) logMessage(LOG_WARNING, msg, a, b)
#define INFO1(msg, a) MKL1(LOG_INFO, msg, a) #define INFO2(msg, a, b) logMessage(LOG_INFO, msg, a, b)
#define DEBUG1(msg, a) MKL1(LOG_DEBUG, msg, a) #define DEBUG2(msg, a, b) logMessage(LOG_DEBUG, msg, a, b)
#define ERROR2(msg, a, b) MKL2(LOG_ERROR, msg, a, b) #define INFO3(msg, a, b, c) logMessage(LOG_INFO, msg, a, b, c)
#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)
inline void do_free_data(rkt_data_t *d) inline void do_free_data(rkt_data_t *d)
{ {