fix(logging): ensure callback executes even if Application Insights throws#791
fix(logging): ensure callback executes even if Application Insights throws#791yashkohli88 wants to merge 3 commits into
Conversation
…hrows Wrap Application Insights tracking calls in try/finally block to prevent Winston from hanging if the AI client throws an exception. Without this, a failed trackTrace or trackException call would skip the callback, causing Winston to stall. Addresses feedback from clearlydefined/service#1582
JamieMagee
left a comment
There was a problem hiding this comment.
finally makes sure the callback runs, but without a catch the exception from trackTrace / trackException still escapes through Winston into whoever called logger.info(). That swaps the silent hang for a crash on every failed telemetry call. Wrapping in try / catch / finally and dropping (or console.error-ing) the error in the catch fixes it.
Worth adding a test too: stub trackTrace to throw and assert that logger.info() doesn't throw and that the callback still fires. The current suite only hits the happy path, which is why this slipped through.
| logger.info('test message') | ||
| clock.runAll() | ||
| setImmediate(() => { | ||
| expect(trackTrace.callCount).to.equal(1) |
There was a problem hiding this comment.
This checks that trackTrace was called once, but it never checks that the Winston callback ran, which is the whole point of the PR. The done() on line 76 comes from the test's own setImmediate on line 73, so it isn't wired to the transport's callback at all.
I tried breaking the fix to see what these catch. If you skip callback() but don't throw synchronously (the actual hang this PR is about), the test still passes. The only reason it fails today when you revert the fix is that the throw escapes out of logger.info() under fake timers, which is a different failure from the one you care about.
ApplicationInsightsTransport isn't exported, so the cleanest way to assert the real guarantee is to export it and call it directly with a spy:
const cb = sinon.spy()
new ApplicationInsightsTransport({ aiClient }).log({ level: 'info', message: 'x' }, cb)
clock.runAll()
expect(cb.calledOnce).to.equal(true)Then the test fails if the callback ever stops running. Same idea for the trackException test below.
| logger.log({ level: 'error', message: 'boom', stack: 'Error: boom\n at test:1:1' }) | ||
| clock.runAll() | ||
| setImmediate(() => { | ||
| expect(trackException.callCount).to.equal(1) |
| clock.runAll() | ||
| setImmediate(() => { | ||
| expect(trackTrace.callCount).to.equal(1) | ||
| consoleError.restore() |
There was a problem hiding this comment.
consoleError.restore() runs after the expect on line 74, inside the faked setImmediate. If that assertion ever fails, it throws out of clock.runAll(), restore() never runs, and done() never fires. afterEach only restores the clock, so console.error stays stubbed as a no-op for the rest of the suite and later tests go quiet.
Putting the stub in a sinon sandbox and resetting it in afterEach keeps cleanup off the assertion's happy path.
| clock.runAll() | ||
| setImmediate(() => { | ||
| expect(trackException.callCount).to.equal(1) | ||
| consoleError.restore() |
Problem
ApplicationInsightsTransport.log() callback could be skipped if Application Insights client throws exception during trackTrace/trackException calls.
This would cause Winston to hang.
Solution
Wrap AI tracking calls in try/finally block to guarantee callback execution regardless of whether tracking succeeds or fails.
Context
Implements feedback from @JamieMagee on clearlydefined/service#1582 - same issue applies to crawler's ApplicationInsightsTransport implementation
added in #739 #740
Changes