Various error log improvements #100
|
|
@ -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`)
|
||||
|
|
||||
this.resolve(id, false)
|
||||
}, 60 * 1000).unref()) // 1 minute
|
||||
}
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -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")
|
||||
|
cadence
commented
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")
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
cadence
commented
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 {
|
||||
|
|
|
|||
|
|
@ -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)}`)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
|
|
|||
5
start.js
|
|
@ -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 => {
|
||||
|
cadence
commented
I don't want to apply the This is incomplete at the goal of preventing crashes anyway because you need to deal with 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) => {
|
||||
|
|
|
|||
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.