winston-cloudwatch icon indicating copy to clipboard operation
winston-cloudwatch copied to clipboard

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

Open wulfsolter opened this issue 2 years ago • 0 comments

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

wulfsolter avatar Jul 26 '22 06:07 wulfsolter