Various error log improvements #100

Open
l1s5 wants to merge 6 commits from l1s5/out-of-your-element:log-improvements into main
Contributor

Hi!

This PR consists mostly of new console.error statements, with one commit moving some error logs out of a guard and another combining separate invocations to make it easier to read in a log ingester (loki in our case).

These have helped us discover various things to fix (some coming in future PRs), and will hopefully lead to future bug reports from others being easier to analyze as well.

Note that some of these have a side effect of not crashing ooye where the previous implementation would have. I'm guessing a lot of people are running the bridge on auto-restart anyway, so it might not be a big deal (and it haven't been for us so far), but you probably know better than me whether it could put the bridge in a weird state.

Hi! This PR consists mostly of new `console.error` statements, with one commit moving some error logs out of a guard and another combining separate invocations to make it easier to read in a log ingester (loki in our case). These have helped us discover various things to fix (some coming in future PRs), and will hopefully lead to future bug reports from others being easier to analyze as well. Note that some of these have a side effect of not crashing ooye where the previous implementation would have. I'm guessing a lot of people are running the bridge on auto-restart anyway, so it *might* not be a big deal (and it haven't been for us so far), but you probably know better than me whether it could put the bridge in a weird state.
Note that this also means that unhandled rejections now longer crashes
the program, it just logs the error and continues as usual.
Getting 2 log events for every error made them a bit hard to both read
and query for in a log ingester.
Whenever `sendError` fails (the function responsible for sending reports
about failed m2d bridging back to the matrix room), the error was
silently dropped. We now log it as an error to the console.
These logs are useful in production environments, when investigating
unexpected downtime and incidents.
cadence left a comment

See comments on diffs.

If any of this logging helped you fix an actual error, then I'd like to see the fix, to demonstrate that logging that part is useful in the real world.

See comments on diffs. If any of this logging helped you fix an actual error, then I'd like to see the fix, to demonstrate that logging that part is useful in the real world.
@ -40,2 +40,3 @@
debugRetrigger(`[retrigger] SET TIMER id = ${id}`)
this.timers.set(id, setTimeout(() => this.resolve(id, false), 60 * 1000).unref()) // 1 minute
this.timers.set(id, setTimeout(() => {
console.warn(`[retrigger] gave up waiting for ${id} to finish bridging after 1 minute, skipping ${this.resolves.get(id)?.length ?? 0} pending changes`)
Owner

I don't want to print retrigger mismatches since these are expected in normal operation. Logging this is noisy and wouldn't help to solve actual problems in retrigger. The complete logging from DEBUG_RETRIGGER is necessary for that.

I don't want to print retrigger mismatches since these are expected in normal operation. Logging this is noisy and wouldn't help to solve actual problems in retrigger. The complete logging from DEBUG_RETRIGGER is necessary for that.
@ -62,0 +69,4 @@
})
}
addEventLogger("error", "Error")
addEventLogger("disconnected", "Disconnected")
Owner

I don't want to move these outside of the CONNECTION_DEBUG filter because printing "disconnected" and not printing anything after it comes back online makes the situation look bad when there was actually no issue.

If there are actually any connection reliability issues in Cloudstorm (which I think we've dealt with, because I haven't seen any in many months) then more logging is needed to diagnose those anyway.

I don't want to move these outside of the CONNECTION_DEBUG filter because printing "disconnected" and _not printing anything after it comes back online_ makes the situation look bad when there was actually no issue. If there are actually any connection reliability issues in Cloudstorm (which I think we've dealt with, because I haven't seen any in many months) then more logging is needed to diagnose those anyway.
@ -115,1 +116,3 @@
console.error("Failed to sync missed events. To retry, please fix this error and restart OOYE:")
console.error("Failed to sync missed events. To retry, please fix this error and restart OOYE:", e)
} else {
console.error(e)
Owner

Errors in this branch are caused by internet outage. Logging it is noise because it can error from just checking if anything needed to be done, even if nothing actually took place. That's why I moved this into an if branch.

Errors in this branch are caused by internet outage. Logging it is noise because it can error from just checking if anything needed to be done, even if nothing actually took place. That's why I moved this into an if branch.
@ -16,6 +17,10 @@ const {reg} = require("./src/matrix/read-registration")
const passthrough = require("./src/passthrough")
const db = new sqlite("ooye.db")
process.on("unhandledRejection", e => {
Owner

I don't want to apply the unhandledRejection change because the process dying has helped me notice a few bugs that I wouldn't have noticed otherwise. If there's an error, I want to fix it at the source, not suppress it and pretend everything's okay. Auto-restart is a great choice for everyone else.

This is incomplete at the goal of preventing crashes anyway because you need to deal with error events too.

I don't want to apply the `unhandledRejection` change because the process dying has helped me notice a few bugs that I wouldn't have noticed otherwise. If there's an error, I want to fix it at the source, not suppress it and pretend everything's okay. Auto-restart is a great choice for everyone else. This is incomplete at the goal of preventing crashes anyway because you need to deal with `error` events too.
This pull request can be merged automatically.
This branch is out-of-date with the base branch
You are not authorized to merge this pull request.
View command line instructions

Checkout

From your project repository, check out a new branch and test the changes.
git fetch -u log-improvements:l1s5-log-improvements
git switch l1s5-log-improvements

Merge

Merge the changes and update on Forgejo.

Warning: The "Autodetect manual merge" setting is not enabled for this repository, you will have to mark this pull request as manually merged afterwards.

git switch main
git merge --no-ff l1s5-log-improvements
git switch l1s5-log-improvements
git rebase main
git switch main
git merge --ff-only l1s5-log-improvements
git switch l1s5-log-improvements
git rebase main
git switch main
git merge --no-ff l1s5-log-improvements
git switch main
git merge --squash l1s5-log-improvements
git switch main
git merge --ff-only l1s5-log-improvements
git switch main
git merge l1s5-log-improvements
git push origin main
Sign in to join this conversation.
No description provided.