[Bug] Workflow logs not propagated unless telemetryOptions.logging.filter is DEBUG or TRACE

[antlai-temporal]

Describe the bug

Using sample https://github.com/temporalio/samples-typescript/tree/main/custom-logger unless the worker
configures core logging filter to DEBUG or TRACE, workflow application logging, i.e., using log.info in workflow code, will not show up in the logs.

This is confusing because it would be expected if telemetryOptions.logging.filter is set to INFO, a log.info in workflow code will be reflected in the logs

Minimal Reproduction

Change line https://github.com/temporalio/samples-typescript/blob/main/custom-logger/src/worker.ts#L33 to

filter: makeTelemetryFilterString({ core: 'INFO' }),

and the log.info in
https://github.com/temporalio/samples-typescript/blob/main/custom-logger/src/workflows/index.ts#L10

does not show up in the logs

Environment/Versions

Latest TS SDK 1.12.1

[mjameswh]

Ehh? That's a very surprising situation.

This is confusing because it would be expected if telemetryOptions.logging.filter is set to INFO, a log.info in workflow code will be reflected in the logs

Not only that, but more importantly, the value of telemetryOptions.logging.filter is only ever passed to Core (i.e. to control verbosity of log messages emitted by core), which is not involved in collecting log messages coming from Workflows (that one is implemented using sinks).

One thing that comes to my mind… When core's logs are forwarded to lang, log messages get buffered for a few miliseconds through the NativeLogCollector class, which ensures proper ordering of messages. The thing is that this class only flushes buffered messages when it receives a log message from Core. It could be that if core is configured at INFO, we get very few messages from Core, and so the buffer rarely gets flushed. But I would still expect the log message to eventually get flushed at some point; in the worst case, that would be on Worker shutdown. Does that matches your observation?

[antlai-temporal]

I don't see the messages with graceful worker shutdown. I added a console.log("Worker gracefully shutdown" after await worker.run(); and then use kill -TERM ... to trigger worker shutdown. It prints the "Worker gracefully..." message but not the info logs from the workflow...
However, it is true that there are no more core messages after the workflow starts (with info), even after shutdown, so it could be that we need to guarantee to always flush the collector during shutdown...
Frankly, there are very few core log messages with info+, so relying on them for flushing workflow logs is a bad idea...

[tatejones]

Come to think of it, I believe it maybe related to the flush as I would see them during a shutdown phase.

[Nielsvanbree]

One thing that comes to my mind… When core's logs are forwarded to lang, log messages get buffered for a few miliseconds through the NativeLogCollector class, which ensures proper ordering of messages. The thing is that this class only flushes buffered messages when it receives a log message from Core. It could be that if core is configured at INFO, we get very few messages from Core, and so the buffer rarely gets flushed. But I would still expect the log message to eventually get flushed at some point; in the worst case, that would be on Worker shutdown. Does that matches your observation?

This looks like the core problem for what our team also experiences. After upgrading to Temporal 1.12.x we don't see any of our worker logs until we redeploy the worker: in that moment, all past logs are written in 1 go. Even if we don't deploy for a few days, the logs don't get written until we redeploy.

Setting the filter to DEBUG like @antlai-temporal showed resolved the issue for us, even though we expect it to work with INFO (which it was set to for months without issues).

[SamuelMS]

Yep, I can confirm this, or something similar – our activity logs get suppressed when we use makeTelemetryFilterString at INFO, and DEBUG/TRACE are too noisy for production use. Removing the option surfaces the missing logs (which were emitted at INFO). We were stumped as to why our worker entrypoint was logging just fine but activities were failing until we found this issue.

[saniul]

Same, can confirm this too. We've had to downgrade to 1.11.8 to ensure we can see our workflow logs in production without enabling DEBUG logs from the Core.

[geuben]

Also seeing this.

My workflow logs do get emitted when the worker process receives a SIGTERM but that's not acceptable behaviour.

[SamuelMS]

@mjameswh Given @geuben's comment above, maybe your guess that something's going awry with log flushing is correct?