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`

ext/console/01_console.js

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

ext/cron/01_cron.ts

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

ext/http/00_serve.ts

@@ -584,8 +584,11 @@ function mapToCallback(context, callback, onError) {
         if (METRICS_ENABLED) {
           op_http_metric_handle_otel_error(req);
         }
-        // deno-lint-ignore no-console
+        import.meta.log(
-        console.error("Exception in onError while handling exception", error);
+          "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
+        import.meta.log(
-        console.error("Upgrade response was not returned from callback");
+          "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
+      import.meta.log("error", error);
-      console.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
+        import.meta.log("info", `Listening on ${path}`);
-        console.error(`Listening on ${path}`);
       }
     });
   }
@@ -820,8 +823,7 @@ function serve(arg1, arg2) {
     } else {
       const host = formatHostName(addr.hostname);
 
-      // deno-lint-ignore no-console
+      import.meta.log("info", `Listening on ${scheme}${host}:${addr.port}/`);
-      console.error(`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
+    import.meta.log(
-    console.error("Terminating Deno.serve loop due to unexpected error", error);
+      "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
+            import.meta.log(
-            console.error(
+              "info",
               `%cdeno serve%c: Listening on %chttp://${host}:${port}/%c${nThreads}`,
               "color: green",
               "color: inherit",

ext/kv/01_db.ts

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

ext/web/06_streams.js

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

runtime/js/99_main.js

@@ -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
+            import.meta.log(
-            console.error(
+              "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
+            import.meta.log(
-            console.error(
+              "error",
               `%cwarning: %cDetected %cexport default { fetch }%c, did you mean to run \"deno serve\"?`,
               "color: yellow;",
               "color: inherit;",

runtime/ops/runtime.rs

@@ -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);
+    }
+  }
+}

tests/specs/cli/otel_basic/http_propagators.out

@@ -237,10 +237,10 @@
     {
       "timeUnixNano": "[WILDCARD]",
       "observedTimeUnixNano": "[WILDCARD]",
-      "severityNumber": 17,
+      "severityNumber": 9,
-      "severityText": "ERROR",
+      "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,
+      "severityNumber": 9,
-      "severityText": "ERROR",
+      "severityText": "INFO",
       "body": {
-        "stringValue": "Listening on http://[WILDCARD]:8001/\n"
+        "stringValue": "Listening on http://[WILDCARD]:8001/"
       },
       "attributes": [],
       "droppedAttributesCount": 0,

tests/specs/run/045_proxy/proxy_test.ts.out

@@ -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

tests/specs/run/serve/__test__.jsonc

@@ -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"
+    }
+  }
+}

tests/specs/run/serve/ipv6_hostname.out

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

tests/specs/run/serve/ipv6_hostname.ts

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

tests/specs/run/serve/on_listen_default.out

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

tests/specs/run/serve/on_listen_default.ts

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

tests/unit/serve_test.ts

@@ -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(
     () =>