pinojs / pino

🌲 super fast, all natural json logger
http://getpino.io
MIT License
14.21k stars 875 forks source link

On demand log flushing? #488

Closed thomasmichaelwallace closed 6 years ago

thomasmichaelwallace commented 6 years ago

Hi!

I'm trying to use pino (not in extreme mode, just the default destination) with AWS Lambda.

With Lambda AWS freezes the process after the (handler) function has completed and then might thaw it later.

Periodically this causes a problem that pino doesn't write the log until after the process is unfrozen, or even loses logs if the process is killed after freezing.

I've seen some discussions- but I couldn't work out if there's a method for me to explicitly make pino (destination(1)) flush that I could then call at the end of the function.

Apologies if this is documented- I'm not that experienced with node streams.

mcollina commented 6 years ago

What is very interesting is that it does not happen with node streams. They do very similar buffering, but maybe AWS lambda does something special that we are sidestepping.

pino.destination() has a flush method. It’s an instance of https://github.com/mcollina/sonic-boom.

By any chance, can you confirm that pino@4 worked ok?

Also, can you do a console.log(process.stdout) and paste what’s in there?

thomasmichaelwallace commented 6 years ago

So here's the output from console.log(process.stdout) which I did just before returning (freezing) on a function that 'lost' two lines of logging:


connecting: false,
_hadError: false,
_handle: 
Pipe {
writeQueueSize: 0,
owner: [Circular],
onread: [Function: onread] },
_parent: null,
_host: null,
_readableState: 
ReadableState {
objectMode: false,
highWaterMark: 16384,
buffer: BufferList { head: null, tail: null, length: 0 },
length: 0,
pipes: null,
pipesCount: 0,
flowing: null,
ended: false,
endEmitted: false,
reading: false,
sync: true,
needReadable: false,
emittedReadable: false,
readableListening: false,
resumeScheduled: false,
destroyed: false,
defaultEncoding: 'utf8',
awaitDrain: 0,
readingMore: false,
decoder: null,
encoding: null },
readable: false,
domain: null,
_events: 
{ end: { [Function: bound onceWrapper] listener: [Function: onend] },
finish: [Function: onSocketFinish],
_socketEnd: [Function: onSocketEnd] },
_eventsCount: 3,
_maxListeners: undefined,
_writableState: 
WritableState {
objectMode: false,
highWaterMark: 16384,
finalCalled: false,
needDrain: false,
ending: false,
ended: false,
finished: false,
destroyed: false,
decodeStrings: false,
defaultEncoding: 'utf8',
length: 0,
writing: false,
corked: 0,
sync: true,
bufferProcessing: false,
onwrite: [Function: bound onwrite],
writecb: null,
writelen: 0,
bufferedRequest: null,
lastBufferedRequest: null,
pendingcb: 0,
prefinished: false,
errorEmitted: false,
bufferedRequestCount: 0,
corkedRequestsFree: 
{ next: null,
entry: null,
finish: [Function: bound onCorkedFinish] } },
writable: true,
allowHalfOpen: false,
_bytesDispatched: 0,
_sockname: null,
_pendingData: null,
_pendingEncoding: '',
server: null,
_server: null,
_type: 'pipe',
fd: 1,
_isStdio: true,
destroySoon: [Function: destroy],
_destroy: [Function],
[Symbol(asyncId)]: 3,
[Symbol(bytesRead)]: 0 }```
thomasmichaelwallace commented 6 years ago

I'm using pino@5, so I'll check out pino@4 and see if I can figure flushing the destination

thomasmichaelwallace commented 6 years ago

OK- having downgraded to pino@4.17.6 everything works as expected- which is a good enough work around for me.

Thanks for the guidance @mcollina - I'm happy to keep trying / providing information for pino@5 though.

mcollina commented 6 years ago

Thanks for helping with this. I know exactly what the problem is: if the output is redirect to a pipe, Node.js creates stdout as a net.Socket. While our approach works anyway, this is substantially different from a file and it is somehow conflicting with AWS Lambda process-freezing.

How are you creating the pino@5 instance? Are you creating a custom destination, or just relying on the default?

jsumners commented 6 years ago

I am very interested in this being solved. I want to start using Pino in AWS.

mcollina commented 6 years ago

@jsumners this is specific to AWS lambda.

thomasmichaelwallace commented 6 years ago

@mcollina I'm just relying on the default (please excuse the es6!):

import pino from 'pino';
import { level } from '../config';

const logger = pino({ name: 'Module', level });

And @jsumners - we use it on EC2 and ElasticBeanstalk fine. It's just lambda (and even then, for now, downgrading to 4.17.6, works perfectly!)

ofer-papaya commented 5 years ago

Trying to use version 5.12.2 and unable to use pino.destination is it the same issue?

mcollina commented 5 years ago

likely not, you should open a new one.

github-actions[bot] commented 2 years ago

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.