chore(core): improved error logging

This commit is contained in:
alina 🌸 2024-07-12 17:54:52 +03:00
parent 1ca3348dc6
commit d4d3f1becc
Signed by: teidesu
SSH key fingerprint: SHA256:uNeCpw6aTSU4aIObXLvHfLkDa82HWH9EiOj9AXOIRpI
11 changed files with 76 additions and 23 deletions

View file

@ -176,7 +176,7 @@ export async function* downloadAsIterable(
let error: unknown = undefined let error: unknown = undefined
void Promise.all(Array.from({ length: Math.min(poolSize * REQUESTS_PER_CONNECTION, numChunks) }, downloadChunk)) void Promise.all(Array.from({ length: Math.min(poolSize * REQUESTS_PER_CONNECTION, numChunks) }, downloadChunk))
.catch((e) => { .catch((e) => {
client.log.debug('download workers errored: %s', e.message) client.log.debug('download workers errored: %e', e)
error = e error = e
aborted = true // not really aborted, but we dont want to download more chunks aborted = true // not really aborted, but we dont want to download more chunks
nextChunkCv.notify() nextChunkCv.notify()

View file

@ -104,7 +104,7 @@ export async function resolvePeerMany(
let error: unknown = undefined let error: unknown = undefined
void Promise.all(Array.from({ length: limit }, (_, i) => fetchNext(i))).catch((e) => { void Promise.all(Array.from({ length: limit }, (_, i) => fetchNext(i))).catch((e) => {
client.log.debug('resolvePeerMany errored: %s', e.message) client.log.debug('resolvePeerMany errored: %e', e)
error = e error = e
cv.notify() cv.notify()
}) })

View file

@ -959,7 +959,7 @@ export class UpdatesManager {
channelId, channelId,
this._fetchChannelDifference(channelId, fallbackPts) this._fetchChannelDifference(channelId, fallbackPts)
.catch((err) => { .catch((err) => {
this.log.warn('error fetching difference for %d: %s', channelId, err) this.log.warn('error fetching difference for %d: %e', channelId, err)
}) })
.then((ok) => { .then((ok) => {
requestedDiff.delete(channelId) requestedDiff.delete(channelId)
@ -1092,7 +1092,7 @@ export class UpdatesManager {
return return
} }
this.log.warn('error fetching common difference: %s', err) this.log.warn('error fetching common difference: %e', err)
if (tl.RpcError.is(err, 'PERSISTENT_TIMESTAMP_INVALID')) { if (tl.RpcError.is(err, 'PERSISTENT_TIMESTAMP_INVALID')) {
// this function never throws // this function never throws
@ -1285,7 +1285,7 @@ export class UpdatesManager {
log.warn('cannot fetch full peer %d - unknown peer type %s', id, peer._) log.warn('cannot fetch full peer %d - unknown peer type %s', id, peer._)
}) })
.catch((err) => { .catch((err) => {
log.warn('error fetching full peer %d: %s', id, err) log.warn('error fetching full peer %d: %e', id, err)
}) })
} }
} }

View file

@ -117,7 +117,7 @@ export class MultiSessionConnection extends EventEmitter {
for (let i = this._connections.length - 1; i >= this._count; i--) { for (let i = this._connections.length - 1; i >= this._count; i--) {
this._connections[i].removeAllListeners() this._connections[i].removeAllListeners()
this._connections[i].destroy().catch((err) => { this._connections[i].destroy().catch((err) => {
this._log.warn('error destroying connection: %s', err) this._log.warn('error destroying connection: %e', err)
}) })
} }

View file

@ -321,7 +321,7 @@ export class DcConnectionManager {
this.downloadSmall.notifyKeyChange() this.downloadSmall.notifyKeyChange()
}) })
.catch((e: Error) => { .catch((e: Error) => {
this.manager._log.warn('failed to save auth key for dc %d: %s', this.dcId, e) this.manager._log.warn('failed to save auth key for dc %d: %e', this.dcId, e)
this.manager.params.emitError(e) this.manager.params.emitError(e)
}) })
}) })
@ -346,7 +346,7 @@ export class DcConnectionManager {
this.downloadSmall.notifyKeyChange() this.downloadSmall.notifyKeyChange()
}) })
.catch((e: Error) => { .catch((e: Error) => {
this.manager._log.warn('failed to save temp auth key %d for dc %d: %s', idx, this.dcId, e) this.manager._log.warn('failed to save temp auth key %d for dc %d: %e', idx, this.dcId, e)
this.manager.params.emitError(e) this.manager.params.emitError(e)
}) })
}) })

View file

@ -70,7 +70,7 @@ export abstract class PersistentConnection extends EventEmitter {
changeTransport(factory: TransportFactory): void { changeTransport(factory: TransportFactory): void {
if (this._transport) { if (this._transport) {
Promise.resolve(this._transport.close()).catch((err) => { Promise.resolve(this._transport.close()).catch((err) => {
this.log.warn('error closing previous transport: %s', err) this.log.warn('error closing previous transport: %e', err)
}) })
} }
@ -98,7 +98,7 @@ export abstract class PersistentConnection extends EventEmitter {
.send(data) .send(data)
.then(sendNext) .then(sendNext)
.catch((err) => { .catch((err) => {
this.log.error('error sending queued data: %s', err) this.log.error('error sending queued data: %e', err)
this._sendOnceConnected.unshift(data) this._sendOnceConnected.unshift(data)
}) })
} }
@ -152,7 +152,7 @@ export abstract class PersistentConnection extends EventEmitter {
if (wait === false) { if (wait === false) {
this.destroy().catch((err) => { this.destroy().catch((err) => {
this.log.warn('error destroying connection: %s', err) this.log.warn('error destroying connection: %e', err)
}) })
return return
@ -197,7 +197,7 @@ export abstract class PersistentConnection extends EventEmitter {
if (this.isConnected) { if (this.isConnected) {
this._shouldReconnectImmediately = true this._shouldReconnectImmediately = true
Promise.resolve(this._transport.close()).catch((err) => { Promise.resolve(this._transport.close()).catch((err) => {
this.log.error('error closing transport: %s', err) this.log.error('error closing transport: %e', err)
}) })
return return
@ -236,7 +236,7 @@ export abstract class PersistentConnection extends EventEmitter {
this._inactive = true this._inactive = true
this._inactivityTimeout = null this._inactivityTimeout = null
Promise.resolve(this._transport.close()).catch((err) => { Promise.resolve(this._transport.close()).catch((err) => {
this.log.warn('error closing transport: %s', err) this.log.warn('error closing transport: %e', err)
}) })
} }

View file

@ -264,7 +264,7 @@ export class SessionConnection extends PersistentConnection {
// it will send us updates // it will send us updates
this.sendRpc({ _: 'updates.getState' }).catch((err: any) => { this.sendRpc({ _: 'updates.getState' }).catch((err: any) => {
if (this._destroyed || tl.RpcError.is(err, 'AUTH_KEY_UNREGISTERED')) return // silently fail if (this._destroyed || tl.RpcError.is(err, 'AUTH_KEY_UNREGISTERED')) return // silently fail
this.log.warn('failed to send updates.getState: %s', err.text || err.message) this.log.warn('failed to send updates.getState: %e', err)
}) })
} }
@ -308,7 +308,7 @@ export class SessionConnection extends PersistentConnection {
.catch((err: Error) => { .catch((err: Error) => {
this._session.authorizationPending = false this._session.authorizationPending = false
if (this._destroyed) return if (this._destroyed) return
this.log.error('Authorization error: %s', err.message) this.log.error('Authorization error: %e', err)
this.onError(err) this.onError(err)
this.reconnect() this.reconnect()
}) })
@ -476,7 +476,7 @@ export class SessionConnection extends PersistentConnection {
}) })
.catch((err: Error) => { .catch((err: Error) => {
if (this._destroyed) return if (this._destroyed) return
this.log.error('PFS Authorization error: %s', err.message) this.log.error('PFS Authorization error: %e', err)
if (this._isPfsBindingPendingInBackground) { if (this._isPfsBindingPendingInBackground) {
this._isPfsBindingPendingInBackground = false this._isPfsBindingPendingInBackground = false
@ -820,7 +820,7 @@ export class SessionConnection extends PersistentConnection {
this.log.debug('additional help.getNearestDc for initConnection ok') this.log.debug('additional help.getNearestDc for initConnection ok')
}) })
.catch((err) => { .catch((err) => {
this.log.debug('additional help.getNearestDc for initConnection error: %s', err) this.log.debug('additional help.getNearestDc for initConnection error: %e', err)
}) })
return return
@ -1456,7 +1456,7 @@ export class SessionConnection extends PersistentConnection {
this.reconnect() this.reconnect()
} else { } else {
this.disconnectManual().catch((err) => { this.disconnectManual().catch((err) => {
this.log.warn('error while disconnecting: %s', err) this.log.warn('error while disconnecting: %e', err)
}) })
} }
} }
@ -2000,7 +2000,7 @@ export class SessionConnection extends PersistentConnection {
const enc = this._session.encryptMessage(result) const enc = this._session.encryptMessage(result)
const promise = this.send(enc).catch((err: Error) => { const promise = this.send(enc).catch((err: Error) => {
this.log.error('error while sending pending messages (root msg_id = %l): %s', rootMsgId, err.stack) this.log.error('error while sending pending messages (root msg_id = %l): %e', rootMsgId, err)
// put acks in the front so they are the first to be sent // put acks in the front so they are the first to be sent
if (ackMsgIds) { if (ackMsgIds) {

View file

@ -71,7 +71,7 @@ export class StorageManager {
if (this.options.cleanup ?? true) { if (this.options.cleanup ?? true) {
this._cleanupRestore = getPlatform().beforeExit(() => { this._cleanupRestore = getPlatform().beforeExit(() => {
this._destroy().catch((err) => this.log.error('cleanup error: %s', err)) this._destroy().catch((err) => this.log.error('cleanup error: %e', err))
}) })
} }

View file

@ -18,6 +18,6 @@ export function reportUnknownError(log: Logger, error: tl.RpcError, method: stri
} }
}) })
.catch((e) => { .catch((e) => {
log.debug('failed to report error %s to telerpc: %s', error.text, e) log.debug('failed to report error %s to telerpc: %e', error.text, e)
}) })
} }

View file

@ -1,6 +1,8 @@
import Long from 'long' import Long from 'long'
import { describe, expect, it, vi } from 'vitest' import { describe, expect, it, vi } from 'vitest'
import { tl } from '@mtcute/tl'
import { LogManager } from './logger.js' import { LogManager } from './logger.js'
describe('logger', () => { describe('logger', () => {
@ -190,5 +192,40 @@ describe('logger', () => {
expect(spy).toHaveBeenCalledWith(3, 3, 'base', 'test n/a', []) expect(spy).toHaveBeenCalledWith(3, 3, 'base', 'test n/a', [])
}) })
}) })
describe('%e', () => {
it('should format mt_rpc_error', () => {
const [mgr, spy] = createManager()
mgr.info('test %e', { _: 'mt_rpc_error', errorCode: 400, errorMessage: 'FLOOD_WAIT_42' })
expect(spy).toHaveBeenCalledWith(3, 3, 'base', 'test 400 FLOOD_WAIT_42', [])
})
it('should format RpcError', () => {
const [mgr, spy] = createManager()
mgr.info('test %e', tl.RpcError.create(400, 'FLOOD_WAIT_42'))
expect(spy).toHaveBeenCalledWith(3, 3, 'base', 'test 400 FLOOD_WAIT_42', [])
})
it('should format errors', () => {
const [mgr, spy] = createManager()
const err = new Error('test error')
mgr.info('test %e', err)
expect(spy).toHaveBeenCalledWith(3, 3, 'base', `test ${err.stack}`, [])
})
it('should format everything else as strings', () => {
const [mgr, spy] = createManager()
mgr.info('test %e', 'test')
expect(spy).toHaveBeenCalledWith(3, 3, 'base', 'test test', [])
})
})
}) })
}) })

View file

@ -1,4 +1,7 @@
import { tl } from '@mtcute/tl'
import { getPlatform } from '../platform.js' import { getPlatform } from '../platform.js'
import { isTlRpcError } from './type-assertions.js'
const DEFAULT_LOG_LEVEL = 2 const DEFAULT_LOG_LEVEL = 2
const FORMATTER_RE = /%[a-zA-Z]/g const FORMATTER_RE = /%[a-zA-Z]/g
@ -52,11 +55,12 @@ export class Logger {
fmt.includes('%j') || fmt.includes('%j') ||
fmt.includes('%J') || fmt.includes('%J') ||
fmt.includes('%l') || fmt.includes('%l') ||
fmt.includes('%L') fmt.includes('%L') ||
fmt.includes('%e')
) { ) {
let idx = 0 let idx = 0
fmt = fmt.replace(FORMATTER_RE, (m) => { fmt = fmt.replace(FORMATTER_RE, (m) => {
if (m === '%h' || m === '%b' || m === '%j' || m === '%J' || m === '%l' || m === '%L') { if (m === '%h' || m === '%b' || m === '%j' || m === '%J' || m === '%l' || m === '%L' || m === '%e') {
let val = args[idx] let val = args[idx]
args.splice(idx, 1) args.splice(idx, 1)
@ -100,6 +104,18 @@ export class Logger {
return `[${(val as unknown[]).map(String).join(', ')}]` return `[${(val as unknown[]).map(String).join(', ')}]`
} }
if (m === '%e') {
if (isTlRpcError(val)) {
return `${val.errorCode} ${val.errorMessage}`
}
if (tl.RpcError.is(val)) {
return `${val.code} ${val.text}`
}
return val && typeof val === 'object' ? (val as Error).stack || (val as Error).message : String(val)
}
} }
idx++ idx++