lazywithclass / winston-cloudwatch

Send logs to Amazon Cloudwatch using Winston.
MIT License
258 stars 104 forks source link

InvalidParameterException: Log events in a single PutLogEvents request must be in chronological order. #197

Closed wulfsolter closed 2 years ago

wulfsolter commented 2 years ago

In heavily async tasks, where many async methods are being run in parallel, we occasionally get

InvalidParameterException: Log events in a single PutLogEvents request must be in chronological order.
    at Request.extractError (/backend/node_modules/aws-sdk/lib/protocol/json.js:52:27)
    at Request.callListeners (/backend/node_modules/aws-sdk/lib/sequential_executor.js:106:20)
    at Request.emit (/backend/node_modules/aws-sdk/lib/sequential_executor.js:78:10)
    at Request.emit (/backend/node_modules/aws-sdk/lib/request.js:686:14)
    at Request.transition (/backend/node_modules/aws-sdk/lib/request.js:22:10)
    at AcceptorStateMachine.runTo (/backend/node_modules/aws-sdk/lib/state_machine.js:14:12)
    at /backend/node_modules/aws-sdk/lib/state_machine.js:26:10
    at Request.<anonymous> (/backend/node_modules/aws-sdk/lib/request.js:38:9)
    at Request.<anonymous> (/backend/node_modules/aws-sdk/lib/request.js:688:12)
    at Request.callListeners (/backend/node_modules/aws-sdk/lib/sequential_executor.js:116:18)
    at Request.emit (/backend/node_modules/aws-sdk/lib/sequential_executor.js:78:10)
    at Request.emit (/backend/node_modules/aws-sdk/lib/request.js:686:14)
    at Request.transition (/backend/node_modules/aws-sdk/lib/request.js:22:10)
    at AcceptorStateMachine.runTo (/backend/node_modules/aws-sdk/lib/state_machine.js:14:12)
    at /backend/node_modules/aws-sdk/lib/state_machine.js:26:10
    at Request.<anonymous> (/backend/node_modules/aws-sdk/lib/request.js:38:9)
    at Request.<anonymous> (/backend/node_modules/aws-sdk/lib/request.js:688:12)
    at Request.callListeners (/backend/node_modules/aws-sdk/lib/sequential_executor.js:116:18)
    at callNextListener (/backend/node_modules/aws-sdk/lib/sequential_executor.js:96:12)
    at IncomingMessage.onEnd (/backend/node_modules/aws-sdk/lib/event_listeners.js:363:13)
    at IncomingMessage.emit (node:events:539:35)
    at IncomingMessage.emit (node:domain:475:12)
    at endReadableNT (node:internal/streams/readable:1345:12)
    at processTicksAndRejections (node:internal/process/task_queues:83:21) {
  code: 'InvalidParameterException',
  time: 2022-07-25T04:51:11.307Z,
  requestId: 'b5b2368a-2423-4f3e-8d93-607754c62e99',
  statusCode: 400,
  retryable: false,
  retryDelay: 68.5605990689063
}

As for replicating error above in a clean manner is less easy, its things like

await Promise.all(new Array(1000).fill().map(() => asyncMethodThatLogs(params)));

where asyncMethodThatLogs() makes one or more logging calls, that cause the issue - occasionally. Sometimes on a fast dev machine I can get away with 5000 "parallel" promises being resolved without issue, sometimes on slow CI machines it might be as low as 100 that falls over.

Have patched (by sorting this.logEvents when uploading) in PR #198. Hopefully PR is obvious enough