deno icon indicating copy to clipboard operation
deno copied to clipboard

Issue with Pino's transport on Windows using Deno 2 and TypeScript - no output is written to the log file

Open marvinhagemeister opened this issue 1 year ago • 3 comments

Discussed in https://github.com/denoland/deno/discussions/26150

Originally posted by cvermeer579 October 11, 2024 I raised the problem with Pino, but they replied: "Thank you for the report. This project targets the Node.js runtime. Please file issues with the runtime if you are not using Node.js".

I’m using Deno 2 with TypeScript on Windows, and I've encountered an issue when trying to log with Pino using a transport. The following code works perfectly and logs to the debug console as expected:

import { pino } from 'pino';
export const logger = pino();

However, when I introduce the transport to log to a file, no output appears, and the log file is not created:

import { pino } from 'pino';
const transport = pino.transport({
    level: 'trace',
    target: 'pino/file',
    options: { destination: '.\\log.txt' },  // Using Windows path
});
export const logger = pino(transport);

No errors are thrown, but the expected log file doesn't appear, and no logging is written.

I am running Deno with the --allow-write flag, and Deno’s internal logger is correctly logging output. Is there any known issue with using Pino's transport functionality on Deno or Windows, or is there something specific I might be missing in my configuration?

Warm regards Corrie

marvinhagemeister avatar Oct 11 '24 13:10 marvinhagemeister

It seems like we have a bug with the Atomics API. Under the hood pino shells out to the thread-stream package which uses this code where Deno is stuck:

https://github.com/pinojs/thread-stream/blob/57e34022ee0b9dd6ed249fe1c0f3ca08be6cc3af/index.js#L428-L442

stream.flushSync()

let readIndex = Atomics.load(stream[kImpl].state, READ_INDEX)
Atomics.store(stream[kImpl].state, WRITE_INDEX, -1)
Atomics.notify(stream[kImpl].state, WRITE_INDEX)

// Wait for the process to complete
let spins = 0
while (readIndex !== -1) {
  Atomics.wait(stream[kImpl].state, READ_INDEX, readIndex, 1000)
  readIndex = Atomics.load(stream[kImpl].state, READ_INDEX)

  if (readIndex === -2) {
    destroy(stream, new Error('end() failed'))
    return
  }

  if (++spins === 10) {
    destroy(stream, new Error('end() took too long (10s)'))
    return
  }
}

marvinhagemeister avatar Oct 11 '24 13:10 marvinhagemeister

Odd, I know we have a bug with Atomics.waitAsync, but Atomics.wait should work. I can take a look on monday

nathanwhit avatar Oct 12 '24 18:10 nathanwhit

I am observing this issue as well. No logs are being outputted to the console. On Ubuntu OS.

my settings:

const loggerModule = LoggerModule.forRootAsync({
  imports: [ConfigModule],
  inject: [ConfigService],
  useFactory: (configService: ConfigService) => ({
    pinoHttp: {
      level: configService.get('NODE_ENV') === 'development' ? 'debug' : 'warn',
      transport:
        configService.get('NODE_ENV') === 'development'
          ? {
              target: 'pino-pretty',
              options: {
                singleLine: true
              }
            }
          : undefined
    }
  })
});

smith558 avatar Oct 21 '24 21:10 smith558

Same issue here, also randomly some logs don't show up in the console.

I am using it for a Hono API based on this repo (https://github.com/w3cj/hono-open-api-starter) that has pino as the logger.

Most logs do work, but there are instances where Pino just does not output to the console. Can't really tell when it happens and when it does not.

pablog12 avatar Nov 20 '24 15:11 pablog12

Looked into this further and I found that this dynamic import call never returns nor throws.

https://github.com/pinojs/thread-stream/blob/a08e354782ea9254b6c7bff67a0a744381eca6d1/lib/worker.js#L33

(That causes the SharedArrayBuffer untouched from worker threads, and makes Atomics.wait call always be timed out.)

I tried to reproduce similar situation, and the following setup reproduced that issue.

main.mjs

import { Worker } from "node:worker_threads";
const worker = new Worker("./worker.cjs");

worker.cjs

console.log("worker.cjs");
import("./foo.cjs");

foo.cjs

const a = "a".repeat(10**7)
console.log(a.length);
// This script needs to be somehow more complex than trivial hello world to reproduce the issue

and this executes like:

$ deno -A main.mjs
worker.cjs
$ node main.mjs 
worker.cjs
10000000

So import("./foo.cjs") part only works in Node.js.

By the way, if I change foo.cjs contents to something simpler (like console.log("foo"), then it occasionally works in Deno

BTW I'm not sure this is directly related to this issue, but if I change worker.cjs to the below:

worker.cjs

console.log("worker.cjs");
setTimeout(() => {
  console.log("100ms passed");
}, 100);

Then it executes like:

$ deno -A main.mjs
worker.cjs
$ node main.mjs 
worker.cjs
100ms passed

It looks like timers in worker threads in Deno are not working. I guess something is wrong with event loop of worker threads.

kt3k avatar Dec 13 '24 14:12 kt3k

Probably related to #23061

kt3k avatar Dec 16 '24 03:12 kt3k

related https://github.com/pinojs/pino/issues/2060

kt3k avatar Dec 18 '24 04:12 kt3k