From d5b7d9110dd637a7f67ce9e430145314812a8df1 Mon Sep 17 00:00:00 2001 From: Chocobozzz Date: Mon, 26 Mar 2018 15:54:13 +0200 Subject: [PATCH] Fix error logging --- server.ts | 14 ++++++++++---- server/controllers/api/server/follows.ts | 6 +++--- server/controllers/api/videos/blacklist.ts | 2 +- server/controllers/api/videos/channel.ts | 4 ++-- server/helpers/database-utils.ts | 2 +- server/helpers/ffmpeg-utils.ts | 4 ++-- server/helpers/logger.ts | 16 +++++++++++++--- server/helpers/peertube-crypto.ts | 2 +- server/helpers/utils.ts | 2 +- server/initializers/installer.ts | 2 +- server/initializers/migrator.ts | 2 +- server/lib/activitypub/actor.ts | 8 ++++---- server/lib/activitypub/process/process-update.ts | 6 +++--- server/lib/activitypub/video-comments.ts | 2 +- server/lib/activitypub/videos.ts | 2 +- server/lib/emailer.ts | 2 +- server/lib/job-queue/job-queue.ts | 4 ++-- server/lib/redis.ts | 2 +- .../lib/schedulers/bad-actor-follow-scheduler.ts | 2 +- server/middlewares/activitypub.ts | 2 +- server/middlewares/validators/videos.ts | 2 +- server/models/activitypub/actor-follow.ts | 4 ++-- server/models/oauth/oauth-token.ts | 2 +- server/models/video/video.ts | 4 ++-- 24 files changed, 57 insertions(+), 41 deletions(-) diff --git a/server.ts b/server.ts index 56a4a0c44..f6794b897 100644 --- a/server.ts +++ b/server.ts @@ -27,13 +27,21 @@ const app = express() // ----------- Core checker ----------- import { checkMissedConfig, checkFFmpeg, checkConfig } from './server/initializers/checker' +// Do not use barrels because we don't want to load all modules here (we need to initialize database first) +import { logger } from './server/helpers/logger' +import { ACCEPT_HEADERS, API_VERSION, CONFIG, STATIC_PATHS } from './server/initializers/constants' + const missed = checkMissedConfig() if (missed.length !== 0) { - throw new Error('Your configuration files miss keys: ' + missed) + logger.error('Your configuration files miss keys: ' + missed) + process.exit(-1) } -import { ACCEPT_HEADERS, API_VERSION, CONFIG, STATIC_PATHS } from './server/initializers/constants' checkFFmpeg(CONFIG) + .catch(err => { + logger.error('Error in ffmpeg check.', { err }) + process.exit(-1) + }) const errorMessage = checkConfig() if (errorMessage !== null) { @@ -41,8 +49,6 @@ if (errorMessage !== null) { } // ----------- Database ----------- -// Do not use barrels because we don't want to load all modules here (we need to initialize database first) -import { logger } from './server/helpers/logger' // Initialize database and models import { initDatabaseModels } from './server/initializers/database' diff --git a/server/controllers/api/server/follows.ts b/server/controllers/api/server/follows.ts index 4a0a44cd3..bb0063473 100644 --- a/server/controllers/api/server/follows.ts +++ b/server/controllers/api/server/follows.ts @@ -93,14 +93,14 @@ async function followRetry (req: express.Request, res: express.Response, next: e return retryTransactionWrapper(follow, options) }) - .catch(err => logger.warn('Cannot follow server %s.', sanitizedHost, err)) + .catch(err => logger.warn('Cannot follow server %s.', sanitizedHost, { err })) tasks.push(p) } // Don't make the client wait the tasks Promise.all(tasks) - .catch(err => logger.error('Error in follow.', err)) + .catch(err => logger.error('Error in follow.', { err })) return res.status(204).end() } @@ -144,7 +144,7 @@ async function removeFollow (req: express.Request, res: express.Response, next: // This could be long so don't wait this task const following = follow.ActorFollowing following.destroy() - .catch(err => logger.error('Cannot destroy actor that we do not follow anymore %s.', following.url, err)) + .catch(err => logger.error('Cannot destroy actor that we do not follow anymore %s.', following.url, { err })) return res.status(204).end() } diff --git a/server/controllers/api/videos/blacklist.ts b/server/controllers/api/videos/blacklist.ts index 7eee460d4..8112b59b8 100644 --- a/server/controllers/api/videos/blacklist.ts +++ b/server/controllers/api/videos/blacklist.ts @@ -69,7 +69,7 @@ async function removeVideoFromBlacklistController (req: express.Request, res: ex return res.sendStatus(204) } catch (err) { - logger.error('Some error while removing video %s from blacklist.', res.locals.video.uuid, err) + logger.error('Some error while removing video %s from blacklist.', res.locals.video.uuid, { err }) throw err } } diff --git a/server/controllers/api/videos/channel.ts b/server/controllers/api/videos/channel.ts index fba5681de..e547d375f 100644 --- a/server/controllers/api/videos/channel.ts +++ b/server/controllers/api/videos/channel.ts @@ -98,7 +98,7 @@ async function addVideoChannel (req: express.Request, res: express.Response) { }) setAsyncActorKeys(videoChannelCreated.Actor) - .catch(err => logger.error('Cannot set async actor keys for account %s.', videoChannelCreated.Actor.uuid, err)) + .catch(err => logger.error('Cannot set async actor keys for account %s.', videoChannelCreated.Actor.uuid, { err })) logger.info('Video channel with uuid %s created.', videoChannelCreated.Actor.uuid) @@ -137,7 +137,7 @@ async function updateVideoChannel (req: express.Request, res: express.Response) logger.info('Video channel with name %s and uuid %s updated.', videoChannelInstance.name, videoChannelInstance.Actor.uuid) } catch (err) { - logger.debug('Cannot update the video channel.', err) + logger.debug('Cannot update the video channel.', { err }) // Force fields we want to update // If the transaction is retried, sequelize will think the object has not changed diff --git a/server/helpers/database-utils.ts b/server/helpers/database-utils.ts index d09b4b245..47a0abfd2 100644 --- a/server/helpers/database-utils.ts +++ b/server/helpers/database-utils.ts @@ -16,7 +16,7 @@ function retryTransactionWrapper ( .catch(err => callback(err)) }) .catch(err => { - logger.error(options.errorMessage, err) + logger.error(options.errorMessage, { err }) throw err }) } diff --git a/server/helpers/ffmpeg-utils.ts b/server/helpers/ffmpeg-utils.ts index 8f9a03c26..bfc942fa3 100644 --- a/server/helpers/ffmpeg-utils.ts +++ b/server/helpers/ffmpeg-utils.ts @@ -64,12 +64,12 @@ async function generateImageFromVideoFile (fromPath: string, folder: string, ima const destination = join(folder, imageName) await processImage({ path: pendingImagePath }, destination, size) } catch (err) { - logger.error('Cannot generate image from video %s.', fromPath, err) + logger.error('Cannot generate image from video %s.', fromPath, { err }) try { await unlinkPromise(pendingImagePath) } catch (err) { - logger.debug('Cannot remove pending image path after generation error.', err) + logger.debug('Cannot remove pending image path after generation error.', { err }) } } } diff --git a/server/helpers/logger.ts b/server/helpers/logger.ts index 7968b5ec9..d92381a2c 100644 --- a/server/helpers/logger.ts +++ b/server/helpers/logger.ts @@ -18,7 +18,11 @@ const excludedKeys = { label: true } function keysExcluder (key, value) { - return excludedKeys[key] === true ? undefined : value + if (excludedKeys[key] === true) return undefined + + if (key === 'err') return value.stack + + return value } const consoleLoggerFormat = winston.format.printf(info => { @@ -30,8 +34,14 @@ const consoleLoggerFormat = winston.format.printf(info => { return `[${info.label}] ${info.timestamp} ${info.level}: ${info.message}${additionalInfos}` }) -const jsonLoggerFormat = winston.format.printf(info => { - if (info.message && info.message.stack !== undefined) info.message = info.message.stack +const jsonLoggerFormat = winston.format.printf(infoArg => { + let info = infoArg.err + ? Object.assign({}, infoArg, { err: infoArg.err.stack }) + : infoArg + + if (infoArg.message && infoArg.message.stack !== undefined) { + info = Object.assign({}, info, { message: infoArg.message.stack }) + } return JSON.stringify(info) }) diff --git a/server/helpers/peertube-crypto.ts b/server/helpers/peertube-crypto.ts index 313c12e26..5c182961d 100644 --- a/server/helpers/peertube-crypto.ts +++ b/server/helpers/peertube-crypto.ts @@ -35,7 +35,7 @@ function isSignatureVerified (fromActor: ActorModel, signedDocument: object) { return jsig.promises.verify(signedDocument, options) .catch(err => { - logger.error('Cannot check signature.', err) + logger.error('Cannot check signature.', { err }) return false }) } diff --git a/server/helpers/utils.ts b/server/helpers/utils.ts index 3b618360b..c58117219 100644 --- a/server/helpers/utils.ts +++ b/server/helpers/utils.ts @@ -44,7 +44,7 @@ function createReqFiles ( try { randomString = await generateRandomString(16) } catch (err) { - logger.error('Cannot generate random string for file name.', err) + logger.error('Cannot generate random string for file name.', { err }) randomString = 'fake-random-string' } diff --git a/server/initializers/installer.ts b/server/initializers/installer.ts index 324a2c2e5..d2f6c7c8c 100644 --- a/server/initializers/installer.ts +++ b/server/initializers/installer.ts @@ -19,7 +19,7 @@ async function installApplication () { await createOAuthClientIfNotExist() await createOAuthAdminIfNotExist() } catch (err) { - logger.error('Cannot install application.', err) + logger.error('Cannot install application.', { err }) process.exit(-1) } } diff --git a/server/initializers/migrator.ts b/server/initializers/migrator.ts index c767acc83..466369729 100644 --- a/server/initializers/migrator.ts +++ b/server/initializers/migrator.ts @@ -35,7 +35,7 @@ async function migrate () { try { await executeMigration(actualVersion, migrationScript) } catch (err) { - logger.error('Cannot execute migration %s.', migrationScript.version, err) + logger.error('Cannot execute migration %s.', migrationScript.version, { err }) process.exit(-1) } } diff --git a/server/lib/activitypub/actor.ts b/server/lib/activitypub/actor.ts index fa31e71c7..b0cf9bb17 100644 --- a/server/lib/activitypub/actor.ts +++ b/server/lib/activitypub/actor.ts @@ -30,7 +30,7 @@ function setAsyncActorKeys (actor: ActorModel) { return actor.save() }) .catch(err => { - logger.error('Cannot set public/private keys of actor %d.', actor.uuid, err) + logger.error('Cannot set public/private keys of actor %d.', actor.uuid, { err }) return actor }) } @@ -117,7 +117,7 @@ async function updateActorAvatarInstance (actorInstance: ActorModel, avatarName: try { await actorInstance.Avatar.destroy({ transaction: t }) } catch (err) { - logger.error('Cannot remove old avatar of actor %s.', actorInstance.url, err) + logger.error('Cannot remove old avatar of actor %s.', actorInstance.url, { err }) } } @@ -144,7 +144,7 @@ async function fetchActorTotalItems (url: string) { const { body } = await doRequest(options) return body.totalItems ? body.totalItems : 0 } catch (err) { - logger.warn('Cannot fetch remote actor count %s.', url, err) + logger.warn('Cannot fetch remote actor count %s.', url, { err }) return 0 } } @@ -393,7 +393,7 @@ async function refreshActorIfNeeded (actor: ActorModel) { return actor }) } catch (err) { - logger.warn('Cannot refresh actor.', err) + logger.warn('Cannot refresh actor.', { err }) return actor } } diff --git a/server/lib/activitypub/process/process-update.ts b/server/lib/activitypub/process/process-update.ts index 24e5589d4..51e3cc4e3 100644 --- a/server/lib/activitypub/process/process-update.ts +++ b/server/lib/activitypub/process/process-update.ts @@ -92,7 +92,7 @@ async function updateRemoteVideo (actor: ActorModel, activity: ActivityUpdate) { // Don't block on request generateThumbnailFromUrl(videoInstance, videoAttributesToUpdate.icon) - .catch(err => logger.warn('Cannot generate thumbnail of %s.', videoAttributesToUpdate.id, err)) + .catch(err => logger.warn('Cannot generate thumbnail of %s.', videoAttributesToUpdate.id, { err })) // Remove old video files const videoFileDestroyTasks: Bluebird[] = [] @@ -117,7 +117,7 @@ async function updateRemoteVideo (actor: ActorModel, activity: ActivityUpdate) { } // This is just a debug because we will retry the insert - logger.debug('Cannot update the remote video.', err) + logger.debug('Cannot update the remote video.', { err }) throw err } } @@ -176,7 +176,7 @@ async function updateRemoteActor (actor: ActorModel, activity: ActivityUpdate) { } // This is just a debug because we will retry the insert - logger.debug('Cannot update the remote account.', err) + logger.debug('Cannot update the remote account.', { err }) throw err } } diff --git a/server/lib/activitypub/video-comments.ts b/server/lib/activitypub/video-comments.ts index b33ae27b1..8ab0cdba4 100644 --- a/server/lib/activitypub/video-comments.ts +++ b/server/lib/activitypub/video-comments.ts @@ -111,7 +111,7 @@ async function resolveThread (url: string, comments: VideoCommentModel[] = []) { return { video, parents: comments } } catch (err) { - logger.debug('Cannot get or create account and video and channel for reply %s, fetch comment', url, err) + logger.debug('Cannot get or create account and video and channel for reply %s, fetch comment', url, { err }) if (comments.length > ACTIVITY_PUB.MAX_RECURSION_COMMENTS) { throw new Error('Recursion limit reached when resolving a thread') diff --git a/server/lib/activitypub/videos.ts b/server/lib/activitypub/videos.ts index 2a6636625..ffba1570b 100644 --- a/server/lib/activitypub/videos.ts +++ b/server/lib/activitypub/videos.ts @@ -152,7 +152,7 @@ async function getOrCreateVideo (videoObject: VideoTorrentObject, channelActor: // Don't block on request generateThumbnailFromUrl(video, videoObject.icon) - .catch(err => logger.warn('Cannot generate thumbnail of %s.', videoObject.id, err)) + .catch(err => logger.warn('Cannot generate thumbnail of %s.', videoObject.id, { err })) const videoCreated = await video.save(sequelizeOptions) diff --git a/server/lib/emailer.ts b/server/lib/emailer.ts index f34d141ea..85cc725fa 100644 --- a/server/lib/emailer.ts +++ b/server/lib/emailer.ts @@ -119,7 +119,7 @@ class Emailer { } private dieOnConnectionFailure (err?: Error) { - logger.error('Failed to connect to SMTP %s:%d.', CONFIG.SMTP.HOSTNAME, CONFIG.SMTP.PORT, err) + logger.error('Failed to connect to SMTP %s:%d.', CONFIG.SMTP.HOSTNAME, CONFIG.SMTP.PORT, { err }) process.exit(-1) } diff --git a/server/lib/job-queue/job-queue.ts b/server/lib/job-queue/job-queue.ts index 66cced59a..1dc28755e 100644 --- a/server/lib/job-queue/job-queue.ts +++ b/server/lib/job-queue/job-queue.ts @@ -53,7 +53,7 @@ class JobQueue { this.jobQueue.setMaxListeners(15) this.jobQueue.on('error', err => { - logger.error('Error in job queue.', err) + logger.error('Error in job queue.', { err }) process.exit(-1) }) this.jobQueue.watchStuckJobs(5000) @@ -111,7 +111,7 @@ class JobQueue { const now = new Date().getTime() kue.Job.rangeByState('complete', 0, -1, 'asc', (err, jobs) => { if (err) { - logger.error('Cannot get jobs when removing old jobs.', err) + logger.error('Cannot get jobs when removing old jobs.', { err }) return } diff --git a/server/lib/redis.ts b/server/lib/redis.ts index 1fd366401..41f4c9869 100644 --- a/server/lib/redis.ts +++ b/server/lib/redis.ts @@ -23,7 +23,7 @@ class Redis { }) this.client.on('error', err => { - logger.error('Error in Redis client.', err) + logger.error('Error in Redis client.', { err }) process.exit(-1) }) diff --git a/server/lib/schedulers/bad-actor-follow-scheduler.ts b/server/lib/schedulers/bad-actor-follow-scheduler.ts index 9b9f9e17d..121f7145e 100644 --- a/server/lib/schedulers/bad-actor-follow-scheduler.ts +++ b/server/lib/schedulers/bad-actor-follow-scheduler.ts @@ -17,7 +17,7 @@ export class BadActorFollowScheduler extends AbstractScheduler { try { await ActorFollowModel.removeBadActorFollows() } catch (err) { - logger.error('Error in bad actor follows scheduler.', err) + logger.error('Error in bad actor follows scheduler.', { err }) } } diff --git a/server/middlewares/activitypub.ts b/server/middlewares/activitypub.ts index 1488b42ab..12d5c22c5 100644 --- a/server/middlewares/activitypub.ts +++ b/server/middlewares/activitypub.ts @@ -18,7 +18,7 @@ async function checkSignature (req: Request, res: Response, next: NextFunction) try { actor = await getOrCreateActorAndServerAndModel(creator) } catch (err) { - logger.error('Cannot create remote actor and check signature.', err) + logger.error('Cannot create remote actor and check signature.', { err }) return res.sendStatus(403) } diff --git a/server/middlewares/validators/videos.ts b/server/middlewares/validators/videos.ts index 1dc8429c8..e3543ef93 100644 --- a/server/middlewares/validators/videos.ts +++ b/server/middlewares/validators/videos.ts @@ -86,7 +86,7 @@ const videosAddValidator = [ try { duration = await getDurationFromVideoFile(videoFile.path) } catch (err) { - logger.error('Invalid input file in videosAddValidator.', err) + logger.error('Invalid input file in videosAddValidator.', { err }) res.status(400) .json({ error: 'Invalid input file.' }) .end() diff --git a/server/models/activitypub/actor-follow.ts b/server/models/activitypub/actor-follow.ts index d3c438626..c97f4cead 100644 --- a/server/models/activitypub/actor-follow.ts +++ b/server/models/activitypub/actor-follow.ts @@ -118,12 +118,12 @@ export class ActorFollowModel extends Model { if (goodInboxes.length !== 0) { ActorFollowModel.incrementScores(goodInboxes, ACTOR_FOLLOW_SCORE.BONUS, t) - .catch(err => logger.error('Cannot increment scores of good actor follows.', err)) + .catch(err => logger.error('Cannot increment scores of good actor follows.', { err })) } if (badInboxes.length !== 0) { ActorFollowModel.incrementScores(badInboxes, ACTOR_FOLLOW_SCORE.PENALTY, t) - .catch(err => logger.error('Cannot decrement scores of bad actor follows.', err)) + .catch(err => logger.error('Cannot decrement scores of bad actor follows.', { err })) } } diff --git a/server/models/oauth/oauth-token.ts b/server/models/oauth/oauth-token.ts index 528bb9587..759aa2779 100644 --- a/server/models/oauth/oauth-token.ts +++ b/server/models/oauth/oauth-token.ts @@ -125,7 +125,7 @@ export class OAuthTokenModel extends Model { } as OAuthTokenInfo }) .catch(err => { - logger.info('getRefreshToken error.', err) + logger.info('getRefreshToken error.', { err }) throw err }) } diff --git a/server/models/video/video.ts b/server/models/video/video.ts index f43b73e49..13bf0b6a2 100644 --- a/server/models/video/video.ts +++ b/server/models/video/video.ts @@ -473,7 +473,7 @@ export class VideoModel extends Model { return Promise.all(tasks) .catch(err => { - logger.error('Some errors when removing files of video %s in after destroy hook.', instance.uuid, err) + logger.error('Some errors when removing files of video %s in after destroy hook.', instance.uuid, { err }) }) } @@ -1213,7 +1213,7 @@ export class VideoModel extends Model { } catch (err) { // Auto destruction... - this.destroy().catch(err => logger.error('Cannot destruct video after transcoding failure.', err)) + this.destroy().catch(err => logger.error('Cannot destruct video after transcoding failure.', { err })) throw err } -- 2.25.1