Introduce tags to the logger

That could help to filter unneeded logs and/or select particular
components

scripts/parse-log.ts

@@ -15,6 +15,8 @@ import { format as sqlFormat } from 'sql-formatter'
 program
   .option('-l, --level [level]', 'Level log (debug/info/warn/error)')
   .option('-f, --files [file...]', 'Files to parse. If not provided, the script will parse the latest log file from config)')
+  .option('-t, --tags [tags...]', 'Display only lines with these tags')
+  .option('-nt, --not-tags [tags...]', 'Donrt display lines containing these tags')
   .parse(process.argv)
 
 const options = program.opts()
@@ -24,6 +26,7 @@ const excludedKeys = {
   message: true,
   splat: true,
   timestamp: true,
+  tags: true,
   label: true,
   sql: true
 }
@@ -93,6 +96,14 @@ function run () {
       rl.on('line', line => {
         try {
           const log = JSON.parse(line)
+          if (options.tags && !containsTags(log.tags, options.tags)) {
+            return
+          }
+
+          if (options.notTags && containsTags(log.tags, options.notTags)) {
+            return
+          }
+
           // Don't know why but loggerFormat does not remove splat key
           Object.assign(log, { splat: undefined })
 
@@ -131,3 +142,15 @@ function toTimeFormat (time: string) {
 
   return new Date(timestamp).toISOString()
 }
+
+function containsTags (loggerTags: string[], optionsTags: string[]) {
+  if (!loggerTags) return false
+
+  for (const lt of loggerTags) {
+    for (const ot of optionsTags) {
+      if (lt === ot) return true
+    }
+  }
+
+  return false
+}

server.ts

@@ -160,7 +160,9 @@ morgan.token('user-agent', (req: express.Request) => {
   return req.get('user-agent')
 })
 app.use(morgan('combined', {
-  stream: { write: logger.info.bind(logger) },
+  stream: {
+    write: (str: string) => logger.info(str, { tags: [ 'http' ] })
+  },
   skip: req => CONFIG.LOG.LOG_PING_REQUESTS === false && req.originalUrl === '/api/v1/ping'
 }))
 

server/controllers/api/videos/index.ts

@@ -17,7 +17,7 @@ import { auditLoggerFactory, getAuditIdFromRes, VideoAuditView } from '../../../
 import { resetSequelizeInstance, retryTransactionWrapper } from '../../../helpers/database-utils'
 import { buildNSFWFilter, createReqFiles, getCountVideos } from '../../../helpers/express-utils'
 import { getMetadataFromFile, getVideoFileFPS, getVideoFileResolution } from '../../../helpers/ffprobe-utils'
-import { logger } from '../../../helpers/logger'
+import { logger, loggerTagsFactory } from '../../../helpers/logger'
 import { getFormattedObjects } from '../../../helpers/utils'
 import { CONFIG } from '../../../initializers/config'
 import {
@@ -67,6 +67,7 @@ import { ownershipVideoRouter } from './ownership'
 import { rateVideoRouter } from './rate'
 import { watchingRouter } from './watching'
 
+const lTags = loggerTagsFactory('api', 'video')
 const auditLogger = auditLoggerFactory('videos')
 const videosRouter = express.Router()
 
@@ -257,14 +258,14 @@ async function addVideo (req: express.Request, res: express.Response) {
     })
 
     auditLogger.create(getAuditIdFromRes(res), new VideoAuditView(videoCreated.toFormattedDetailsJSON()))
-    logger.info('Video with name %s and uuid %s created.', videoInfo.name, videoCreated.uuid)
+    logger.info('Video with name %s and uuid %s created.', videoInfo.name, videoCreated.uuid, lTags(videoCreated.uuid))
 
     return { videoCreated }
   })
 
   // Create the torrent file in async way because it could be long
   createTorrentAndSetInfoHashAsync(video, videoFile)
-    .catch(err => logger.error('Cannot create torrent file for video %s', video.url, { err }))
+    .catch(err => logger.error('Cannot create torrent file for video %s', video.url, { err, ...lTags(video.uuid) }))
     .then(() => VideoModel.loadAndPopulateAccountAndServerAndTags(video.id))
     .then(refreshedVideo => {
       if (!refreshedVideo) return
@@ -276,7 +277,7 @@ async function addVideo (req: express.Request, res: express.Response) {
         return sequelizeTypescript.transaction(t => federateVideoIfNeeded(refreshedVideo, true, t))
       })
     })
-    .catch(err => logger.error('Cannot federate or notify video creation %s', video.url, { err }))
+    .catch(err => logger.error('Cannot federate or notify video creation %s', video.url, { err, ...lTags(video.uuid) }))
 
   if (video.state === VideoState.TO_TRANSCODE) {
     await addOptimizeOrMergeAudioJob(videoCreated, videoFile, res.locals.oauth.token.User)
@@ -389,7 +390,7 @@ async function updateVideo (req: express.Request, res: express.Response) {
         new VideoAuditView(videoInstanceUpdated.toFormattedDetailsJSON()),
         oldVideoAuditView
       )
-      logger.info('Video with name %s and uuid %s updated.', videoInstance.name, videoInstance.uuid)
+      logger.info('Video with name %s and uuid %s updated.', videoInstance.name, videoInstance.uuid, lTags(videoInstance.uuid))
 
       return videoInstanceUpdated
     })

server/helpers/logger.ts

@@ -48,7 +48,7 @@ function getLoggerReplacer () {
 }
 
 const consoleLoggerFormat = winston.format.printf(info => {
-  const toOmit = [ 'label', 'timestamp', 'level', 'message', 'sql' ]
+  const toOmit = [ 'label', 'timestamp', 'level', 'message', 'sql', 'tags' ]
 
   const obj = omit(info, ...toOmit)
 
@@ -150,6 +150,13 @@ const bunyanLogger = {
   error: bunyanLogFactory('error'),
   fatal: bunyanLogFactory('error')
 }
+
+function loggerTagsFactory (...defaultTags: string[]) {
+  return (...tags: string[]) => {
+    return { tags: defaultTags.concat(tags) }
+  }
+}
+
 // ---------------------------------------------------------------------------
 
 export {
@@ -159,5 +166,6 @@ export {
   consoleLoggerFormat,
   jsonLoggerFormat,
   logger,
+  loggerTagsFactory,
   bunyanLogger
 }

server/initializers/database.ts

@@ -76,7 +76,7 @@ const sequelizeTypescript = new SequelizeTypescript({
       newMessage += ' in ' + benchmark + 'ms'
     }
 
-    logger.debug(newMessage, { sql: message })
+    logger.debug(newMessage, { sql: message, tags: [ 'sql' ] })
   }
 })
 

server/lib/activitypub/send/send-create.ts

@@ -4,7 +4,7 @@ import { VideoPrivacy } from '../../../../shared/models/videos'
 import { VideoCommentModel } from '../../../models/video/video-comment'
 import { broadcastToActors, broadcastToFollowers, sendVideoRelatedActivity, unicastTo } from './utils'
 import { audiencify, getActorsInvolvedInVideo, getAudience, getAudienceFromFollowersOf, getVideoCommentAudience } from '../audience'
-import { logger } from '../../../helpers/logger'
+import { logger, loggerTagsFactory } from '../../../helpers/logger'
 import { VideoPlaylistPrivacy } from '../../../../shared/models/videos/playlist/video-playlist-privacy.model'
 import {
   MActorLight,
@@ -18,10 +18,12 @@ import {
 import { getServerActor } from '@server/models/application/application'
 import { ContextType } from '@shared/models/activitypub/context'
 
+const lTags = loggerTagsFactory('ap', 'create')
+
 async function sendCreateVideo (video: MVideoAP, t: Transaction) {
   if (!video.hasPrivacyForFederation()) return undefined
 
-  logger.info('Creating job to send video creation of %s.', video.url)
+  logger.info('Creating job to send video creation of %s.', video.url, lTags(video.uuid))
 
   const byActor = video.VideoChannel.Account.Actor
   const videoObject = video.toActivityPubObject()
@@ -37,7 +39,7 @@ async function sendCreateCacheFile (
   video: MVideoAccountLight,
   fileRedundancy: MVideoRedundancyStreamingPlaylistVideo | MVideoRedundancyFileVideo
 ) {
-  logger.info('Creating job to send file cache of %s.', fileRedundancy.url)
+  logger.info('Creating job to send file cache of %s.', fileRedundancy.url, lTags(video.uuid))
 
   return sendVideoRelatedCreateActivity({
     byActor,
@@ -51,7 +53,7 @@ async function sendCreateCacheFile (
 async function sendCreateVideoPlaylist (playlist: MVideoPlaylistFull, t: Transaction) {
   if (playlist.privacy === VideoPlaylistPrivacy.PRIVATE) return undefined
 
-  logger.info('Creating job to send create video playlist of %s.', playlist.url)
+  logger.info('Creating job to send create video playlist of %s.', playlist.url, lTags(playlist.uuid))
 
   const byActor = playlist.OwnerAccount.Actor
   const audience = getAudience(byActor, playlist.privacy === VideoPlaylistPrivacy.PUBLIC)

server/lib/activitypub/share.ts

@@ -1,15 +1,17 @@
+import * as Bluebird from 'bluebird'
 import { Transaction } from 'sequelize'
+import { getServerActor } from '@server/models/application/application'
+import { checkUrlsSameHost, getAPId } from '../../helpers/activitypub'
+import { logger, loggerTagsFactory } from '../../helpers/logger'
+import { doRequest } from '../../helpers/requests'
+import { CRAWL_REQUEST_CONCURRENCY } from '../../initializers/constants'
 import { VideoShareModel } from '../../models/video/video-share'
+import { MChannelActorLight, MVideo, MVideoAccountLight, MVideoId } from '../../types/models/video'
+import { getOrCreateActorAndServerAndModel } from './actor'
 import { sendUndoAnnounce, sendVideoAnnounce } from './send'
 import { getLocalVideoAnnounceActivityPubUrl } from './url'
-import * as Bluebird from 'bluebird'
-import { doRequest } from '../../helpers/requests'
-import { getOrCreateActorAndServerAndModel } from './actor'
-import { logger } from '../../helpers/logger'
-import { CRAWL_REQUEST_CONCURRENCY } from '../../initializers/constants'
-import { checkUrlsSameHost, getAPId } from '../../helpers/activitypub'
-import { MChannelActorLight, MVideo, MVideoAccountLight, MVideoId } from '../../types/models/video'
-import { getServerActor } from '@server/models/application/application'
+
+const lTags = loggerTagsFactory('share')
 
 async function shareVideoByServerAndChannel (video: MVideoAccountLight, t: Transaction) {
   if (!video.hasPrivacyForFederation()) return undefined
@@ -25,7 +27,10 @@ async function changeVideoChannelShare (
   oldVideoChannel: MChannelActorLight,
   t: Transaction
 ) {
-  logger.info('Updating video channel of video %s: %s -> %s.', video.uuid, oldVideoChannel.name, video.VideoChannel.name)
+  logger.info(
+    'Updating video channel of video %s: %s -> %s.', video.uuid, oldVideoChannel.name, video.VideoChannel.name,
+    lTags(video.uuid)
+  )
 
   await undoShareByVideoChannel(video, oldVideoChannel, t)
 

server/lib/video-blacklist.ts

@@ -11,7 +11,7 @@ import {
 } from '@server/types/models'
 import { UserRight, VideoBlacklistCreate, VideoBlacklistType } from '../../shared/models'
 import { UserAdminFlag } from '../../shared/models/users/user-flag.model'
-import { logger } from '../helpers/logger'
+import { logger, loggerTagsFactory } from '../helpers/logger'
 import { CONFIG } from '../initializers/config'
 import { VideoBlacklistModel } from '../models/video/video-blacklist'
 import { sendDeleteVideo } from './activitypub/send'
@@ -20,6 +20,8 @@ import { LiveManager } from './live-manager'
 import { Notifier } from './notifier'
 import { Hooks } from './plugins/hooks'
 
+const lTags = loggerTagsFactory('blacklist')
+
 async function autoBlacklistVideoIfNeeded (parameters: {
   video: MVideoWithBlacklistLight
   user?: MUser
@@ -60,7 +62,7 @@ async function autoBlacklistVideoIfNeeded (parameters: {
     })
   }
 
-  logger.info('Video %s auto-blacklisted.', video.uuid)
+  logger.info('Video %s auto-blacklisted.', video.uuid, lTags(video.uuid))
 
   return true
 }