refactor: internal logging utility (#28567)

`import.meta.log` enables basic log filtering through
`env_logger`/`DENO_LOG`. Log levels are supported, and filenames can
also be used. for example: `DENO_LOG=ext:deno_http::00_serve.ts=warn`
This commit is contained in:
snek 2025-03-21 12:17:50 +01:00 committed by GitHub
parent 94c9681385
commit 27363d389d
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
15 changed files with 116 additions and 98 deletions

View file

@ -3546,6 +3546,7 @@ export {
formatBigInt,
formatNumber,
formatValue,
getConsoleInspectOptions,
getDefaultInspectOptions,
getStderrNoColor,
getStdoutNoColor,

View file

@ -165,8 +165,7 @@ function cron(
const _res = isPromise(result) ? (await result) : result;
success = true;
} catch (error) {
// deno-lint-ignore no-console
console.error(`Exception in cron handler ${name}`, error);
import.meta.log("error", `Exception in cron handler ${name}`, error);
success = false;
}
}

View file

@ -584,8 +584,11 @@ function mapToCallback(context, callback, onError) {
if (METRICS_ENABLED) {
op_http_metric_handle_otel_error(req);
}
// deno-lint-ignore no-console
console.error("Exception in onError while handling exception", error);
import.meta.log(
"error",
"Exception in onError while handling exception",
error,
);
response = internalServerError();
}
}
@ -598,8 +601,10 @@ function mapToCallback(context, callback, onError) {
if (innerRequest?.[_upgraded]) {
// We're done here as the connection has been upgraded during the callback and no longer requires servicing.
if (response !== UPGRADE_RESPONSE_SENTINEL) {
// deno-lint-ignore no-console
console.error("Upgrade response was not returned from callback");
import.meta.log(
"error",
"Upgrade response was not returned from callback",
);
context.close();
}
innerRequest?.[_upgraded]();
@ -755,8 +760,7 @@ function serve(arg1, arg2) {
const signal = options.signal;
const onError = options.onError ??
function (error) {
// deno-lint-ignore no-console
console.error(error);
import.meta.log("error", error);
return internalServerError();
};
@ -771,8 +775,7 @@ function serve(arg1, arg2) {
if (options.onListen) {
options.onListen(listener.addr);
} else {
// deno-lint-ignore no-console
console.error(`Listening on ${path}`);
import.meta.log("info", `Listening on ${path}`);
}
});
}
@ -820,8 +823,7 @@ function serve(arg1, arg2) {
} else {
const host = formatHostName(addr.hostname);
// deno-lint-ignore no-console
console.error(`Listening on ${scheme}${host}:${addr.port}/`);
import.meta.log("info", `Listening on ${scheme}${host}:${addr.port}/`);
}
};
@ -866,8 +868,11 @@ function serveHttpOn(context, addr, callback) {
const promiseErrorHandler = (error) => {
// Abnormal exit
// deno-lint-ignore no-console
console.error("Terminating Deno.serve loop due to unexpected error", error);
import.meta.log(
"error",
"Terminating Deno.serve loop due to unexpected error",
error,
);
context.close();
};
@ -993,8 +998,8 @@ function registerDeclarativeServer(exports) {
: "";
const host = formatHostName(hostname);
// deno-lint-ignore no-console
console.error(
import.meta.log(
"info",
`%cdeno serve%c: Listening on %chttp://${host}:${port}/%c${nThreads}`,
"color: green",
"color: inherit",

View file

@ -324,8 +324,7 @@ class Kv {
const _res = isPromise(result) ? (await result) : result;
success = true;
} catch (error) {
// deno-lint-ignore no-console
console.error("Exception in queue handler", error);
import.meta.log("error", "Exception in queue handler", error);
} finally {
const promise: Promise<void> = op_kv_finish_dequeued_message(
handleId,

View file

@ -164,8 +164,7 @@ function resolvePromiseWith(value) {
function rethrowAssertionErrorRejection(e) {
if (e && ObjectPrototypeIsPrototypeOf(AssertionError.prototype, e)) {
queueMicrotask(() => {
// deno-lint-ignore no-console
console.error(`Internal Error: ${e.stack}`);
import.meta.log("error", `Internal Error: ${e.stack}`);
});
}
}

View file

@ -12,6 +12,8 @@ import {
op_bootstrap_pid,
op_bootstrap_stderr_no_color,
op_bootstrap_stdout_no_color,
op_get_ext_import_meta_proto,
op_internal_log,
op_main_module,
op_ppid,
op_set_format_exception_callback,
@ -59,6 +61,7 @@ import * as version from "ext:runtime/01_version.ts";
import * as os from "ext:deno_os/30_os.js";
import * as timers from "ext:deno_web/02_timers.js";
import {
getConsoleInspectOptions,
getDefaultInspectOptions,
getStderrNoColor,
inspectArgs,
@ -113,6 +116,24 @@ ObjectDefineProperties(Symbol, {
},
});
// https://docs.rs/log/latest/log/enum.Level.html
const LOG_LEVELS = {
error: 1,
warn: 2,
info: 3,
debug: 4,
trace: 5,
};
op_get_ext_import_meta_proto().log = function internalLog(levelStr, ...args) {
const level = LOG_LEVELS[levelStr];
const message = inspectArgs(
args,
getConsoleInspectOptions(getStderrNoColor()),
);
op_internal_log(this.url, level, message);
};
let windowIsClosing = false;
let globalThis_;
@ -819,8 +840,8 @@ function bootstrapMainRuntime(runtimeOptions, warmup = false) {
if (mode === executionModes.serve && !serve) {
if (serveIsMain) {
// Only error if main worker
// deno-lint-ignore no-console
console.error(
import.meta.log(
"error",
`%cerror: %cdeno serve requires %cexport default { fetch }%c in the main module, did you mean to run \"deno run\"?`,
"color: yellow;",
"color: inherit;",
@ -833,8 +854,8 @@ function bootstrapMainRuntime(runtimeOptions, warmup = false) {
if (serve) {
if (mode === executionModes.run) {
// deno-lint-ignore no-console
console.error(
import.meta.log(
"error",
`%cwarning: %cDetected %cexport default { fetch }%c, did you mean to run \"deno serve\"?`,
"color: yellow;",
"color: inherit;",

View file

@ -6,7 +6,7 @@ use deno_core::OpState;
deno_core::extension!(
deno_runtime,
ops = [op_main_module, op_ppid],
ops = [op_main_module, op_ppid, op_internal_log],
options = { main_module: ModuleSpecifier },
state = |state, options| {
state.put::<ModuleSpecifier>(options.main_module);
@ -86,3 +86,33 @@ pub fn op_ppid() -> i64 {
parent_id().into()
}
}
#[allow(clippy::match_single_binding)] // needed for temporary lifetime
#[op2(fast)]
fn op_internal_log(
#[string] url: &str,
#[smi] level: u32,
#[string] message: &str,
) {
let level = match level {
1 => log::Level::Error,
2 => log::Level::Warn,
3 => log::Level::Info,
4 => log::Level::Debug,
5 => log::Level::Trace,
_ => unreachable!(),
};
let target = url.replace('/', "::");
match format_args!("{message}") {
args => {
let record = log::Record::builder()
.file(Some(url))
.module_path(Some(url))
.target(&target)
.level(level)
.args(args)
.build();
log::logger().log(&record);
}
}
}

View file

@ -237,10 +237,10 @@
{
"timeUnixNano": "[WILDCARD]",
"observedTimeUnixNano": "[WILDCARD]",
"severityNumber": 17,
"severityText": "ERROR",
"severityNumber": 9,
"severityText": "INFO",
"body": {
"stringValue": "Listening on http://[WILDCARD]:8000/\n"
"stringValue": "Listening on http://[WILDCARD]:8000/"
},
"attributes": [],
"droppedAttributesCount": 0,
@ -251,10 +251,10 @@
{
"timeUnixNano": "[WILDCARD]",
"observedTimeUnixNano": "[WILDCARD]",
"severityNumber": 17,
"severityText": "ERROR",
"severityNumber": 9,
"severityText": "INFO",
"body": {
"stringValue": "Listening on http://[WILDCARD]:8001/\n"
"stringValue": "Listening on http://[WILDCARD]:8001/"
},
"attributes": [],
"droppedAttributesCount": 0,

View file

@ -1,4 +1,3 @@
Listening on [WILDCARD]
Proxy request to: http://localhost:4545/run/045_mod.ts
Proxy request to: http://localhost:4545/run/045_mod.ts
Proxy request to: http://localhost:4545/run/045_output.ts

View file

@ -0,0 +1,14 @@
{
"tests": {
"on_listen_default": {
"args": "run -A on_listen_default.ts",
"output": "on_listen_default.out",
"if": "unix"
},
"ipv6_hostname": {
"args": "run -A ipv6_hostname.ts",
"output": "ipv6_hostname.out",
"if": "unix"
}
}
}

View file

@ -0,0 +1 @@
Listening on http://[::1]:[WILDCARD]/

View file

@ -0,0 +1,6 @@
const server = Deno.serve({
handler: () => new Response(),
hostname: "::1",
port: 0,
});
await server.shutdown();

View file

@ -0,0 +1 @@
Listening on http://0.0.0.0:[WILDCARD]/

View file

@ -0,0 +1,9 @@
const server = Deno.serve({
handler() {
return new Response("Hello World");
},
hostname: "0.0.0.0",
port: 0,
});
await server.shutdown();

View file

@ -823,42 +823,6 @@ Deno.test({ permissions: { net: true } }, async function httpServerPort0() {
await server.finished;
});
Deno.test(
{ permissions: { net: true } },
async function httpServerDefaultOnListenCallback() {
const ac = new AbortController();
const consoleError = console.error;
console.error = (msg) => {
try {
const match = msg.match(
/Listening on http:\/\/(localhost|0\.0\.0\.0):(\d+)\//,
);
assert(!!match, `Didn't match ${msg}`);
const port = +match[2];
assert(port > 0 && port < 65536);
} finally {
ac.abort();
}
};
try {
await using server = Deno.serve({
handler() {
return new Response("Hello World");
},
hostname: "0.0.0.0",
port: 0,
signal: ac.signal,
});
await server.finished;
} finally {
console.error = consoleError;
}
},
);
// https://github.com/denoland/deno/issues/15107
Deno.test(
{ permissions: { net: true } },
@ -907,36 +871,6 @@ Deno.test({ permissions: { net: true } }, async function validPortString() {
await server.shutdown();
});
Deno.test({ permissions: { net: true } }, async function ipv6Hostname() {
const ac = new AbortController();
let url = "";
const consoleError = console.error;
console.error = (msg) => {
try {
const match = msg.match(/Listening on (http:\/\/(.*?):(\d+)\/)/);
assert(!!match, `Didn't match ${msg}`);
url = match[1];
} finally {
ac.abort();
}
};
try {
await using server = Deno.serve({
handler: () => new Response(),
hostname: "::1",
port: 0,
signal: ac.signal,
});
assertEquals(server.addr.transport, "tcp");
assert(new URL(url), `Not a valid URL "${url}"`);
await server.shutdown();
} finally {
console.error = consoleError;
}
});
Deno.test({ permissions: { net: true } }, function invalidPortFloat() {
assertThrows(
() =>