Fix error logging

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'

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()
 }

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
   }
 }

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

server/helpers/database-utils.ts

@@ -16,7 +16,7 @@ function retryTransactionWrapper <T> (
         .catch(err => callback(err))
   })
   .catch(err => {
-    logger.error(options.errorMessage, err)
+    logger.error(options.errorMessage, { err })
     throw err
   })
 }

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 })
     }
   }
 }

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)
 })

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
     })
 }

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'
       }
 

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)
   }
 }

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)
     }
   }

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
   }
 }

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<void>[] = []
@@ -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
   }
 }

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')

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)
 

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)
   }
 

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
       }
 

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)
     })
 

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 })
     }
   }
 

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)
   }
 

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()

server/models/activitypub/actor-follow.ts

@@ -118,12 +118,12 @@ export class ActorFollowModel extends Model<ActorFollowModel> {
 
     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 }))
     }
   }
 

server/models/oauth/oauth-token.ts

@@ -125,7 +125,7 @@ export class OAuthTokenModel extends Model<OAuthTokenModel> {
         } as OAuthTokenInfo
       })
       .catch(err => {
-        logger.info('getRefreshToken error.', err)
+        logger.info('getRefreshToken error.', { err })
         throw err
       })
   }

server/models/video/video.ts

@@ -473,7 +473,7 @@ export class VideoModel extends Model<VideoModel> {
 
     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<VideoModel> {
 
     } 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
     }