Syslog logs not flushed until app exits, and multiples are concatenated?

[quantropi-cmckenzie]

Hi.

I'm finding that logs are not sent to my syslog server until after my app exits. I setup a straight Winston syslog config (with a Console transport added for good measure, which outputs the logs immediately), write a log and nothing appears in my syslog server until I Ctrl+C the app, then all 4 logs I wrote appear as a single syslog entry.

log_transports.push(new transports.Syslog(
{
                host: '127.0.0.1', // defaults to localhost
                port: 514, // defaults to syslog port 514
                protocol: 'tcp', // pick tcp4, udp4, tls4 etc,,,
                facility: 'user',
                app_name: 'Admin',
            }
))
...
const logger = createLogger({
    level: config.logger.logging.level,
    transports: log_transports
})

Here's the syslog message that gets written when exiting:

Apr 20 22:20:30 localhost Admin[799677]: {"message":"skipping static hosting: ../frontend/dist","level":"info"}<14>Apr 20 22:20:30 localhost Admin[799677]: {"message":"test1","level":"info"}<11>Apr 20 22:20:30 localhost Admin[799677]: {"message":"test3","level":"error"}<14>Apr 20 22:20:31 localhost Admin[799677]: {"message":"Server is listening on port 5002","level":"info"}

Is it that the logs aren't flushing? Why are all 4 bulk concatenated and not written as separate logs? Am I missing a log string terminator like newline (I don't see anything like this in the example usage)?

Thanks.

[quantropi-cmckenzie]

Ok, strange. I was looking at your source for any flush related code and decided to try switching to UDP. It works as expected now:

Apr 21 12:47:44 localhost QiSpace_Admin[801634]: {"message":"skipping static hosting: ../frontend/dist","level":"info"}
Apr 21 12:47:44 localhost QiSpace_Admin[801634]: {"message":"test1","level":"info"}
Apr 21 12:47:44 localhost QiSpace_Admin[801634]: {"message":"test3","level":"error"}
Apr 21 12:47:44 localhost QiSpace_Admin[801634]: {"message":"Server is listening on port 5002","level":"info"}

Is there a reason TCP is misbehaving? Am I mis-using the TCP protocol support? Or is this normal and my understanding of syslog has missed some more recent change? Thanks.

[tgirotto]

having the same problem.

[Tej13]

We also have the same issue, seems there is even no api to flush the logs while using TCP. Can somebody from contributors check this?

[NightWatchman]

I'm having this problem or something similar. I run this code in an AWS lambda function, and my syslog events don't make it through when I use protocol: 'tls4'. The error handler never fires, and it fails silently. When I let it use the default udp protocol it works.

I'm using winston v3.7.2 and winston-syslog v2.5.0

const log = winston.createLogger({
    levels: winston.config.syslog.levels,
    transports: [
      new winstonTransports.Console(),
      new winstonTransports.Syslog({
        level: 'debug',
        host: process.env.LOG_HOST,
        port: Number(process.env.LOG_PORT),
        // protocol: 'tls4'
        type: 'RFC5424',
        localhost: 'lhost',
        app_name: app,
        facility: 'user',
        format: winston.format.printf(logEvent =>
          `${logEvent.message} ${JSON.stringify(logEvent)}`),
        eol: '\n'
      })
    ]
  });
  process.on('exit', () => {
    console.debug('process exiting');
  });
  log.on('error', err => {
    console.error('log error: %s', err);
  });
  log.on('finish', () => {
    console.debug('done logging');
  });
  log.info('I have logged');
  log.end();

[jhleao]

I am also running into this issue on serverless functions. Is there any way to reliably wait for full flush?

[jhleao]

For anyone having similar issues to that of OP, double check if you have your eol set to '\n'. This fixed it for me.

new Syslog({
  host,
  port,
  protocol,
  app_name,
  localhost,
  level,
  eol: '\n', // <- This line
})

Other than that, I've been having similar issues that of @NightWatchman . My serverless functions exit before logs finish sending. Switching to UDP makes them arrive but most times out of order.

After trying several ways using winston or winston-syslog events and supported methods with no luck, I worked around this by snooping into winston-syslog's internal queue state:

const syslog = new Syslog({...}) as typeof Syslog & { queue: unknown[] }
const logger = new Winston.createLogger({..., transports: [syslog]})

async function flushSyslog(timeoutMs: number): Promise<boolean> => {
  return new Promise<boolean>(resolve => {
    let interval: NodeJS.Timeout
    let timeout: NodeJS.Timeout

    const finish = (result: boolean) => {
      if (timeout) clearTimeout(timeout)
      if (interval) clearInterval(interval)
      resolve(result)
    }

    interval = setInterval(() => {
      if (syslog.queue.length !== 0) return
      finish(true)
    }, 10)

    timeout = setTimeout(() => {
      finish(false)
    }, timeoutMs)
  })
}

Just need to call this before finishing serverless functions and logs will arrive at destination.

async function handler() {
  try {
    // code
  } finally {
    await flushSyslog(1000);
  }
}