Skip to content

Commit 808d523

Browse files
guybedfordguybedford
committed
process stdio log prefixing on console.log
1 parent 658acf6 commit 808d523

15 files changed

+204
-117
lines changed

‎src/workerd/api/node/tests/process-stdio-fs-nodejs-test.expected_stderr

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1 +0,0 @@
1-
Direct writeSync to stderr

‎src/workerd/api/node/tests/process-stdio-fs-nodejs-test.expected_stdout

Lines changed: 7 additions & 6 deletions
Large diffs are not rendered by default.

‎src/workerd/api/node/tests/process-stdio-fs-nodejs-test.wd-test

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -16,4 +16,8 @@ const unitTests :Workerd.Config = (
1616
)
1717
),
1818
],
19+
logging = (
20+
stdoutPrefix = ">",
21+
stderrPrefix = ""
22+
)
1923
);

‎src/workerd/api/node/tests/process-stdio-nodejs-test.expected_stderr

Lines changed: 0 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -1,20 +1,2 @@
1-
Error Line 1
2-
Error Line 2
3-
Error Line 3
4-
Error First
5-
6-
Error Second with empty line
7-
Error with trailing newlines
8-
9-
10-
Error Start
11-
Error Mid1
12-
Error Mid2
13-
Error End
14-
Test string write to stderr
15-
Test buffer write
16-
Hello
171
console.error
182
console.error interleaves
19-
24
20-
😀

‎src/workerd/api/node/tests/process-stdio-nodejs-test.expected_stdout

Lines changed: 46 additions & 28 deletions
Large diffs are not rendered by default.

‎src/workerd/api/node/tests/process-stdio-nodejs-test.wd-test

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -14,5 +14,5 @@ const unitTests :Workerd.Config = (
1414
],
1515
)
1616
),
17-
],
17+
]
1818
);

‎src/workerd/api/node/tests/test_process_stdio.sh

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -19,7 +19,7 @@ trap "rm -f $ACTUAL_STDOUT $ACTUAL_STDERR $FILTERED_STDOUT $FILTERED_STDERR" EXI
1919
"$WORKERD_BINARY" test "$TEST_CONFIG" --experimental >"$ACTUAL_STDOUT" 2>"$ACTUAL_STDERR"
2020

2121
# Remove [ PASS ] [ TEST ] [ FAIL ] lines from stderr
22-
grep -vE "\[ PASS \]|\[ FAIL \]|\[ TEST \]" "$ACTUAL_STDERR" > "$FILTERED_STDERR"
22+
grep -vE "\[ PASS \]|\[ FAIL \]|\[ TEST \]" "$ACTUAL_STDERR" > "$FILTERED_STDERR" || true
2323

2424
# Compare with expected output (normalize line endings for cross-platform compatibility)
2525
echo "Comparing stdout..."

‎src/workerd/io/worker-fs.c++

Lines changed: 17 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -1755,17 +1755,29 @@ class DevRandomFile final: public File, public kj::EnableAddRefToThis<DevRandomF
17551755
void writeStdio(jsg::Lock& js, VirtualFileSystem::Stdio type, kj::ArrayPtr<const kj::byte> bytes) {
17561756
auto chars = bytes.asChars();
17571757
size_t endPos = chars.size();
1758-
if (chars[endPos - 1] == '\n') endPos--;
1758+
if (endPos > 0 && chars[endPos - 1] == '\n') endPos--;
17591759

17601760
KJ_IF_SOME(console, js.global().get(js, "console"_kj).tryCast<jsg::JsObject>()) {
1761-
auto method = console.get(js, type == VirtualFileSystem::Stdio::OUT ? "log"_kj : "error"_kj);
1761+
auto method = console.get(js, "log"_kj);
17621762
if (method.isFunction()) {
17631763
v8::Local<v8::Value> methodVal(method);
1764-
auto methodFunc = methodVal.As<v8::Function>();
1765-
v8::Local<v8::Value> args[] = {js.str(chars.first(endPos))};
1766-
jsg::check(methodFunc->Call(js.v8Context(), console, 1, args));
1764+
auto methodFunc = jsg::JsFunction(methodVal.As<v8::Function>());
1765+
1766+
kj::String outputStr;
1767+
auto isolate = &Worker::Isolate::from(js);
1768+
auto prefix = type == VirtualFileSystem::Stdio::OUT ? isolate->getStdoutPrefix()
1769+
: isolate->getStderrPrefix();
1770+
if (endPos == 0) {
1771+
methodFunc.call(js, console, js.str(prefix));
1772+
} else if (prefix.size() > 0) {
1773+
methodFunc.call(js, console, js.str(kj::str(prefix, " "_kj, chars.first(endPos))));
1774+
} else {
1775+
methodFunc.call(js, console, js.str(chars.first(endPos)));
1776+
}
1777+
return;
17671778
}
17681779
}
1780+
KJ_LOG(WARNING, "No console.log implementation available for stdio logging");
17691781
}
17701782

17711783
// An StdioFile is a special file implementation used to represent stdin,

‎src/workerd/io/worker.c++

Lines changed: 15 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -575,8 +575,7 @@ struct Worker::Isolate::Impl {
575575
progressCounter(impl.lockSuccessCount),
576576
oldCurrentApi(currentApi),
577577
limitEnforcer(isolate.getLimitEnforcer()),
578-
consoleMode(isolate.consoleMode),
579-
structuredLogging(isolate.structuredLogging),
578+
loggingOptions(isolate.loggingOptions),
580579
lock(isolate.api->lock(stackScope)) {
581580
WarnAboutIsolateLockScope::maybeWarn();
582581

@@ -624,7 +623,7 @@ struct Worker::Isolate::Impl {
624623
i.get()->contextCreated(
625624
v8_inspector::V8ContextInfo(context, 1, jsg::toInspectorStringView("Worker")));
626625
}
627-
Worker::setupContext(*lock, context, consoleMode, structuredLogging);
626+
Worker::setupContext(*lock, context, loggingOptions);
628627
}
629628

630629
void disposeContext(jsg::JsContext<api::ServiceWorkerGlobalScope> context) {
@@ -659,11 +658,9 @@ struct Worker::Isolate::Impl {
659658

660659
const IsolateLimitEnforcer& limitEnforcer; // only so we can call getIsolateStats()
661660

662-
ConsoleMode consoleMode;
663-
664661
// When structuredLogging is YES AND consoleMode is STDOUT js logs will be emitted to STDOUT
665-
// as newline separated json objects.
666-
StructuredLogging structuredLogging;
662+
// as newline separated json objects
663+
LoggingOptions loggingOptions;
667664

668665
public:
669666
kj::Own<jsg::Lock> lock;
@@ -1019,14 +1016,12 @@ Worker::Isolate::Isolate(kj::Own<Api> apiParam,
10191016
kj::StringPtr id,
10201017
kj::Own<IsolateLimitEnforcer> limitEnforcerParam,
10211018
InspectorPolicy inspectorPolicy,
1022-
ConsoleMode consoleMode,
1023-
StructuredLogging structuredLogging)
1019+
LoggingOptions loggingOptions)
10241020
: metrics(kj::mv(metricsParam)),
10251021
id(kj::str(id)),
10261022
limitEnforcer(kj::mv(limitEnforcerParam)),
10271023
api(kj::mv(apiParam)),
1028-
consoleMode(consoleMode),
1029-
structuredLogging(structuredLogging),
1024+
loggingOptions(loggingOptions),
10301025
featureFlagsForFl(makeCompatJson(decompileCompatibilityFlagsForFl(api->getFeatureFlags()))),
10311026
impl(kj::heap<Impl>(*api, *metrics, *limitEnforcer, inspectorPolicy)),
10321027
weakIsolateRef(WeakIsolateRef::wrap(this)),
@@ -1510,10 +1505,8 @@ void setWebAssemblyModuleHasInstance(jsg::Lock& lock, v8::Local<v8::Context> con
15101505
module->DefineOwnProperty(context, v8::Symbol::GetHasInstance(lock.v8Isolate), function));
15111506
}
15121507

1513-
void Worker::setupContext(jsg::Lock& lock,
1514-
v8::Local<v8::Context> context,
1515-
Worker::ConsoleMode consoleMode,
1516-
StructuredLogging structuredLogging) {
1508+
void Worker::setupContext(
1509+
jsg::Lock& lock, v8::Local<v8::Context> context, const LoggingOptions& loggingOptions) {
15171510
// Set WebAssembly.Module @@HasInstance
15181511
setWebAssemblyModuleHasInstance(lock, context);
15191512

@@ -1529,9 +1522,9 @@ void Worker::setupContext(jsg::Lock& lock,
15291522
lock.v8Isolate, jsg::check(console->Get(context, methodStr)).As<v8::Function>());
15301523

15311524
auto f = lock.wrapSimpleFunction(context,
1532-
[consoleMode, level, structuredLogging, original = kj::mv(original)](
1525+
[loggingOptions, level, original = kj::mv(original)](
15331526
jsg::Lock& js, const v8::FunctionCallbackInfo<v8::Value>& info) {
1534-
handleLog(js, consoleMode, level, structuredLogging, original, info);
1527+
handleLog(js, loggingOptions, level, original, info);
15351528
});
15361529
jsg::check(console->Set(context, methodStr, f));
15371530
};
@@ -1846,9 +1839,8 @@ void Worker::processEntrypointClass(jsg::Lock& js,
18461839
}
18471840

18481841
void Worker::handleLog(jsg::Lock& js,
1849-
ConsoleMode consoleMode,
1842+
const LoggingOptions& loggingOptions,
18501843
LogLevel level,
1851-
StructuredLogging structuredLogging,
18521844
const v8::Global<v8::Function>& original,
18531845
const v8::FunctionCallbackInfo<v8::Value>& info) {
18541846
// Call original V8 implementation so messages sent to connected inspector if any
@@ -1945,7 +1937,7 @@ void Worker::handleLog(jsg::Lock& js,
19451937
}
19461938
}
19471939

1948-
if (consoleMode == ConsoleMode::INSPECTOR_ONLY) {
1940+
if (loggingOptions.consoleMode == Worker::ConsoleMode::INSPECTOR_ONLY) {
19491941
// Lets us dump console.log()s to stdout when running test-runner with --verbose flag, to make
19501942
// it easier to debug tests. Note that when --verbose is not passed, KJ_LOG(INFO, ...) will
19511943
// not even evaluate its arguments, so `message()` will not be called at all.
@@ -1964,7 +1956,7 @@ void Worker::handleLog(jsg::Lock& js,
19641956

19651957
// Log warnings and errors to stderr
19661958
// Always log to stdout when structuredLogging is enabled.
1967-
auto useStderr = level >= LogLevel::WARN && !structuredLogging;
1959+
auto useStderr = level >= LogLevel::WARN && !loggingOptions.structuredLogging;
19681960
auto fd = useStderr ? stderr : stdout;
19691961
auto tty = useStderr ? STDERR_TTY : STDOUT_TTY;
19701962
auto colors =
@@ -1978,7 +1970,7 @@ void Worker::handleLog(jsg::Lock& js,
19781970

19791971
auto levelStr = logLevelToString(level);
19801972
args[length] = v8::Boolean::New(js.v8Isolate, colors);
1981-
args[length + 1] = v8::Boolean::New(js.v8Isolate, bool(structuredLogging));
1973+
args[length + 1] = v8::Boolean::New(js.v8Isolate, bool(loggingOptions.structuredLogging));
19821974
args[length + 2] = jsg::v8StrIntern(js.v8Isolate, levelStr);
19831975
auto formatted = js.toString(
19841976
jsg::check(formatLog->Call(context, js.v8Undefined(), length + 3, args.data())));
@@ -3252,7 +3244,7 @@ void Worker::Isolate::logWarning(kj::StringPtr description, Lock& lock) {
32523244
});
32533245
}
32543246

3255-
if (consoleMode == ConsoleMode::INSPECTOR_ONLY) {
3247+
if (loggingOptions.consoleMode == Worker::ConsoleMode::INSPECTOR_ONLY) {
32563248
// Run with --verbose to log JS exceptions to stderr. Useful when running tests.
32573249
KJ_LOG(INFO, "console warning", description);
32583250
} else {

‎src/workerd/io/worker.h

Lines changed: 45 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,7 @@ class Isolate;
3535
namespace workerd {
3636

3737
WD_STRONG_BOOL(StructuredLogging);
38+
WD_STRONG_BOOL(ProcessStdioPrefixed);
3839

3940
namespace api {
4041
class DurableObjectState;
@@ -120,6 +121,36 @@ class Worker: public kj::AtomicRefcounted {
120121
STDOUT,
121122
};
122123

124+
struct LoggingOptions {
125+
ConsoleMode consoleMode = Worker::ConsoleMode::INSPECTOR_ONLY;
126+
StructuredLogging structuredLogging = StructuredLogging::NO;
127+
ProcessStdioPrefixed processStdioPrefixed = ProcessStdioPrefixed::YES;
128+
kj::String stdoutPrefix = kj::str("stdout:"_kj);
129+
kj::String stderrPrefix = kj::str("stderr:"_kj);
130+
131+
LoggingOptions() = default;
132+
LoggingOptions(LoggingOptions&&) = default;
133+
LoggingOptions& operator=(LoggingOptions&&) = default;
134+
135+
explicit LoggingOptions(ConsoleMode mode): consoleMode(mode) {}
136+
137+
LoggingOptions(const LoggingOptions& other)
138+
: consoleMode(other.consoleMode),
139+
structuredLogging(other.structuredLogging),
140+
processStdioPrefixed(other.processStdioPrefixed),
141+
stdoutPrefix(kj::str(other.stdoutPrefix)),
142+
stderrPrefix(kj::str(other.stderrPrefix)) {}
143+
144+
LoggingOptions& operator=(const LoggingOptions& other) {
145+
consoleMode = other.consoleMode;
146+
structuredLogging = other.structuredLogging;
147+
processStdioPrefixed = other.processStdioPrefixed;
148+
stdoutPrefix = kj::str(other.stdoutPrefix);
149+
stderrPrefix = kj::str(other.stderrPrefix);
150+
return *this;
151+
}
152+
};
153+
123154
explicit Worker(kj::Own<const Script> script,
124155
kj::Own<WorkerObserver> metrics,
125156
kj::FunctionParam<void(jsg::Lock& lock,
@@ -185,10 +216,8 @@ class Worker: public kj::AtomicRefcounted {
185216
void setConnectOverride(kj::String networkAddress, ConnectFn connectFn);
186217
kj::Maybe<ConnectFn&> getConnectOverride(kj::StringPtr networkAddress);
187218

188-
static void setupContext(jsg::Lock& lock,
189-
v8::Local<v8::Context> context,
190-
Worker::ConsoleMode consoleMode,
191-
StructuredLogging structuredLogging);
219+
static void setupContext(
220+
jsg::Lock& lock, v8::Local<v8::Context> context, const LoggingOptions& loggingOptions);
192221

193222
private:
194223
kj::Own<const Script> script;
@@ -214,9 +243,8 @@ class Worker: public kj::AtomicRefcounted {
214243
friend constexpr bool _kj_internal_isPolymorphic(AsyncWaiter*);
215244

216245
static void handleLog(jsg::Lock& js,
217-
ConsoleMode mode,
246+
const LoggingOptions& loggingOptions,
218247
LogLevel level,
219-
StructuredLogging structuredLogging,
220248
const v8::Global<v8::Function>& original,
221249
const v8::FunctionCallbackInfo<v8::Value>& info);
222250

@@ -334,8 +362,7 @@ class Worker::Isolate: public kj::AtomicRefcounted {
334362
kj::StringPtr id,
335363
kj::Own<IsolateLimitEnforcer> limitEnforcer,
336364
InspectorPolicy inspectorPolicy,
337-
ConsoleMode consoleMode = ConsoleMode::INSPECTOR_ONLY,
338-
StructuredLogging structuredLogging = StructuredLogging::NO);
365+
LoggingOptions loggingOptions = {});
339366

340367
~Isolate() noexcept(false);
341368
KJ_DISALLOW_COPY_AND_MOVE(Isolate);
@@ -451,6 +478,15 @@ class Worker::Isolate: public kj::AtomicRefcounted {
451478

452479
bool isInspectorEnabled() const;
453480

481+
// Get the process stdio prefixed setting from logging options
482+
inline kj::StringPtr getStdoutPrefix() const {
483+
return loggingOptions.stdoutPrefix;
484+
}
485+
486+
inline kj::StringPtr getStderrPrefix() const {
487+
return loggingOptions.stderrPrefix;
488+
}
489+
454490
// Represents a weak reference back to the isolate that code within the isolate can use as an
455491
// indirect pointer when they want to be able to race destruction safely. A caller wishing to
456492
// use a weak reference to the isolate should acquire a strong reference to weakIsolateRef.
@@ -479,8 +515,7 @@ class Worker::Isolate: public kj::AtomicRefcounted {
479515
kj::String id;
480516
kj::Own<IsolateLimitEnforcer> limitEnforcer;
481517
kj::Own<Api> api;
482-
ConsoleMode consoleMode;
483-
StructuredLogging structuredLogging;
518+
LoggingOptions loggingOptions;
484519

485520
// If non-null, a serialized JSON object with a single "flags" property, which is a list of
486521
// compatibility enable-flags that are relevant to FL.

0 commit comments

Comments
 (0)