Various error log improvements #100

Open
l1s5 wants to merge 6 commits from l1s5/out-of-your-element:log-improvements into main
5 changed files with 36 additions and 16 deletions

View file

@ -38,7 +38,10 @@ const storage = sync.remember(() => new class {
this.resolves.set(id, (this.resolves.get(id) || []).concat(resolve)) // add to list in map value
if (!this.timers.has(id)) {
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`)

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.
this.resolve(id, false)
}, 60 * 1000).unref()) // 1 minute
}
}

View file

@ -1,5 +1,6 @@
// @ts-check
const util = require("util")
const DiscordTypes = require("discord-api-types/v10")
const {Endpoints, SnowTransfer} = require("snowtransfer")
const {reg} = require("../matrix/read-registration")
@ -55,19 +56,21 @@ class DiscordClient {
this.guildChannelMap = new Map()
if (listen !== "no") {
this.cloud.on("event", message => {
discordPackets.onPacket(this, message, listen)
discordPackets.onPacket(this, message, listen).catch(e => {
console.error(`Unhandled error while processing Discord packet ${message.t}:\n${util.inspect(e, false, 4, false)}`)
})
})
}
const addEventLogger = (eventName, logName) => {
this.cloud.on(eventName, (...args) => {
const d = new Date().toISOString().slice(0, 19)
console.error(`[${d} Client ${logName}]`, ...args)
})
}
addEventLogger("error", "Error")
addEventLogger("disconnected", "Disconnected")

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.
if (CONNECTION_DEBUG) {
const addEventLogger = (eventName, logName) => {
this.cloud.on(eventName, (...args) => {
const d = new Date().toISOString().slice(0, 19)
console.error(`[${d} Client ${logName}]`, ...args)
})
}
addEventLogger("error", "Error")
addEventLogger("disconnected", "Disconnected")
addEventLogger("ready", "Ready")
}
}

View file

@ -1,6 +1,7 @@
// @ts-check
const assert = require("assert").strict
const util = require("util")
const {scheduler} = require("timers/promises")
const passthrough = require("../passthrough")
const {sync} = passthrough
@ -112,9 +113,10 @@ async function onPacket(client, message, listen) {
await eventDispatcher.checkMissedLeaves(client, message.d)
} catch (e) {
if (firstReady) {
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)

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.
}
console.error(e)
}
}
@ -216,7 +218,9 @@ async function onPacket(client, message, listen) {
const optionalEvents = ["TYPING_START"]
if (alwaysRealTimeEvents.includes(message.t) || homeserverStatus.homeserverStatus.isRealTime()) {
// real time
dispatchPacketToBridge(client, message)
dispatchPacketToBridge(client, message).catch(e => {
console.error(`Unhandled error while sending Discord packet ${message.t} to the bridge:\n${util.inspect(e, false, 4, false)}`)
})
} else if (optionalEvents.includes(message.t)) {
// when not real time, skip optional events
} else {

View file

@ -47,9 +47,7 @@ const {reg} = require("../matrix/read-registration")
const errorReportStatus = sync.remember(() => ({lastReportedEvent: 0}))
function printError(type, source, e, payload) {
console.error(`Error while processing a ${type} ${source} event:`)
console.error(e)
console.dir(payload, {depth: null})
console.error(`Error while processing a ${type} ${source} event:\n${util.inspect(e, false, 4, false)}\n${util.inspect(payload, false, 4, false)}`)
}
/** @param {string} stack */
@ -130,7 +128,14 @@ async function sendError(roomID, source, type, e, payload) {
|| (e instanceof mreq.MatrixServerError && [502, 503].includes(e.httpStatus) && e.errcode === "CX_SERVER_ERROR")
) {
// Matrix homeserver is down (reverse proxy indicated failure)
console.error([
`Matrix homeserver is down, queueing ${type} ${source} event.`,
`Couldn't send error report to ${roomID}:`,
util.inspect(e, false, 4, false),
].join("\n"))
homeserverStatus.homeserverStatus.setErrorWithPacket([source, payload])
} else {
console.error(`Couldn't send error report for a ${type} ${source} event to ${roomID}:\n${util.inspect(e, false, 4, false)}`)
}
}
}

View file

@ -8,6 +8,7 @@ process.title = "ooye"
require("temporal-polyfill-lite/global")
const fs = require("fs")
const util = require("util")
const sqlite = require("better-sqlite3")
const migrate = require("./src/db/migrate")
const HeatSync = require("heatsync")
@ -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 => {

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.
console.error(`Unhandled promise rejection:\n${util.inspect(e, false, 4, false)}`)
})
const sync = new HeatSync({
watchFunction(path, options, cb) {
return fs.watchFile(path, options, (curr, prev) => {