pino-socket
pino-socket copied to clipboard
Data lost on reconnect even with recovery enabled
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.
Any thoughts on how I can fix this?
Sounds like a bug. Would you like to send a Pull Request to address this issue? Remember to add unit tests.
I could give it a shot. Any suggestions on where I might start?On Feb 28, 2023, at 6:16 PM, James Sumners @.***> wrote:
Any thoughts on how I can fix this?
Sounds like a bug. Would you like to send a Pull Request to address this issue? Remember to add unit tests.
—Reply to this email directly, view it on GitHub, or unsubscribe.You are receiving this because you authored the thread.Message ID: @.***>
I would start by looking at the code around the feature, and review the history of it (i.e. look at git blame
to find the PR and review the PR).