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 this.resolves.set(id, (this.resolves.get(id) || []).concat(resolve)) // add to list in map value
if (!this.timers.has(id)) { if (!this.timers.has(id)) {
debugRetrigger(`[retrigger] SET TIMER id = ${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 // @ts-check
const util = require("util")
const DiscordTypes = require("discord-api-types/v10") const DiscordTypes = require("discord-api-types/v10")
const {Endpoints, SnowTransfer} = require("snowtransfer") const {Endpoints, SnowTransfer} = require("snowtransfer")
const {reg} = require("../matrix/read-registration") const {reg} = require("../matrix/read-registration")
@ -55,19 +56,21 @@ class DiscordClient {
this.guildChannelMap = new Map() this.guildChannelMap = new Map()
if (listen !== "no") { if (listen !== "no") {
this.cloud.on("event", message => { 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) { 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") addEventLogger("ready", "Ready")
} }
} }

View file

@ -1,6 +1,7 @@
// @ts-check // @ts-check
const assert = require("assert").strict const assert = require("assert").strict
const util = require("util")
const {scheduler} = require("timers/promises") const {scheduler} = require("timers/promises")
const passthrough = require("../passthrough") const passthrough = require("../passthrough")
const {sync} = passthrough const {sync} = passthrough
@ -112,9 +113,10 @@ async function onPacket(client, message, listen) {
await eventDispatcher.checkMissedLeaves(client, message.d) await eventDispatcher.checkMissedLeaves(client, message.d)
} catch (e) { } catch (e) {
if (firstReady) { 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"] const optionalEvents = ["TYPING_START"]
if (alwaysRealTimeEvents.includes(message.t) || homeserverStatus.homeserverStatus.isRealTime()) { if (alwaysRealTimeEvents.includes(message.t) || homeserverStatus.homeserverStatus.isRealTime()) {
// real time // 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)) { } else if (optionalEvents.includes(message.t)) {
// when not real time, skip optional events // when not real time, skip optional events
} else { } else {

View file

@ -47,9 +47,7 @@ const {reg} = require("../matrix/read-registration")
const errorReportStatus = sync.remember(() => ({lastReportedEvent: 0})) const errorReportStatus = sync.remember(() => ({lastReportedEvent: 0}))
function printError(type, source, e, payload) { function printError(type, source, e, payload) {
console.error(`Error while processing a ${type} ${source} event:`) console.error(`Error while processing a ${type} ${source} event:\n${util.inspect(e, false, 4, false)}\n${util.inspect(payload, false, 4, false)}`)
console.error(e)
console.dir(payload, {depth: null})
} }
/** @param {string} stack */ /** @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") || (e instanceof mreq.MatrixServerError && [502, 503].includes(e.httpStatus) && e.errcode === "CX_SERVER_ERROR")
) { ) {
// Matrix homeserver is down (reverse proxy indicated failure) // 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]) 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") require("temporal-polyfill-lite/global")
const fs = require("fs") const fs = require("fs")
const util = require("util")
const sqlite = require("better-sqlite3") const sqlite = require("better-sqlite3")
const migrate = require("./src/db/migrate") const migrate = require("./src/db/migrate")
const HeatSync = require("heatsync") const HeatSync = require("heatsync")
@ -16,6 +17,10 @@ const {reg} = require("./src/matrix/read-registration")
const passthrough = require("./src/passthrough") const passthrough = require("./src/passthrough")
const db = new sqlite("ooye.db") 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({ const sync = new HeatSync({
watchFunction(path, options, cb) { watchFunction(path, options, cb) {
return fs.watchFile(path, options, (curr, prev) => { return fs.watchFile(path, options, (curr, prev) => {