pino-socket icon indicating copy to clipboard operation
pino-socket copied to clipboard

Data lost on reconnect even with recovery enabled

Open pocketcolin opened this issue 1 year ago • 3 comments

Hello! I'm using pino-socket to transport data to Logstash and everything works great except it seems to disconnect after about 15 minutes of no use. Enabling reconnect fixed the issue of needing to reconnect after the 15 minutes, but it seems that the first message that triggers the reconnect never gets retried and never makes it to logstash. Any thoughts on how I can fix this?

pino v8.11.0
pino-socket v7.3.0

Pino Transport Config

const logstashTransport = pino.transport({
    target: 'pino-socket',
    options: {
        address: lsHost,
        port: lsPort,
        mode: 'tcp',
        reconnect: true,
        recovery: true,
    },
})

logstashTransport.on('socketError', (err: Error) => {
    console.log('socketError', err)
})
logstashTransport.on('socketClose', (err: Error) => {
    console.log('socketClose', err)
})
logstashTransport.on('open', (address: string) => {
    console.log('open', address)
})

Logs

Feb 28 02:43:31 PM      message: "END: [POST] /api/functions/example"
Feb 28 03:17:33 PM  socketError Error: read ECONNRESET
Feb 28 03:17:33 PM      at TCP.onStreamRead (node:internal/stream_base_commons:217:20)
Feb 28 03:17:33 PM  socketClose Error: read ECONNRESET
Feb 28 03:17:33 PM      at TCP.onStreamRead (node:internal/stream_base_commons:217:20)
Feb 28 03:17:33 PM  open { address: 'some.ip.addr', family: 'IPv4', port: 43230 }
Feb 28 03:17:33 PM      log.level: "info"
Feb 28 03:17:33 PM      @timestamp: "2023-02-28T20:17:32.881Z"
Feb 28 03:17:33 PM      process: {
Feb 28 03:17:33 PM        "pid": 81
Feb 28 03:17:33 PM      }
Feb 28 03:17:33 PM      host: {
Feb 28 03:17:33 PM        "hostname": "srv-123"
Feb 28 03:17:33 PM      }
Feb 28 03:17:33 PM      ecs: {
Feb 28 03:17:33 PM        "version": "1.6.0"
Feb 28 03:17:33 PM      }
Feb 28 03:17:33 PM      service: {
Feb 28 03:17:33 PM        "name": "render-server"
Feb 28 03:17:33 PM      }
Feb 28 03:17:33 PM      event: {
Feb 28 03:17:33 PM        "dataset": "render-server.log"
Feb 28 03:17:33 PM      }
Feb 28 03:17:33 PM      trace: {
Feb 28 03:17:33 PM        "id": "0b3fdd23de1b96bd9b0ef9b07dcd319c"
Feb 28 03:17:33 PM      }
Feb 28 03:17:33 PM      transaction: {
Feb 28 03:17:33 PM        "id": "bf0b2258bb3dc3f0"
Feb 28 03:17:33 PM      }
Feb 28 03:17:33 PM      message: "START: [POST] /api/functions/example"
Feb 28 03:17:34 PM      log.level: "info"
Feb 28 03:17:34 PM      @timestamp: "2023-02-28T20:17:34.022Z"
Feb 28 03:17:34 PM      process: {
Feb 28 03:17:34 PM        "pid": 81
Feb 28 03:17:34 PM      }
Feb 28 03:17:34 PM      host: {
Feb 28 03:17:34 PM        "hostname": "srv-123"
Feb 28 03:17:34 PM      }
Feb 28 03:17:34 PM      ecs: {
Feb 28 03:17:34 PM        "version": "1.6.0"
Feb 28 03:17:34 PM      }
Feb 28 03:17:34 PM      service: {
Feb 28 03:17:34 PM        "name": "render-server"
Feb 28 03:17:34 PM      }
Feb 28 03:17:34 PM      event: {
Feb 28 03:17:34 PM        "dataset": "render-server.log"
Feb 28 03:17:34 PM      }
Feb 28 03:17:34 PM      trace: {
Feb 28 03:17:34 PM        "id": "0b3fdd23de1b96bd9b0ef9b07dcd319c"
Feb 28 03:17:34 PM      }
Feb 28 03:17:34 PM      transaction: {
Feb 28 03:17:34 PM        "id": "bf0b2258bb3dc3f0"
Feb 28 03:17:34 PM      }
Feb 28 03:17:34 PM      message: "END: [POST] /api/functions/example"

NOTE: The line after open never makes it to Logstash but the next message (starting at Feb 28 03:17:34 PM) does.

pocketcolin avatar Feb 28 '23 20:02 pocketcolin