Better logs for redundancy

3 files changed, 51 insertions, 23 deletions

diff --git a/server/lib/redundancy.ts b/server/lib/redundancy.ts
index 2a9241249..2613d01be 100644
--- a/server/lib/redundancy.ts
+++ b/server/lib/redundancy.ts
@@ -1,5 +1,5 @@
 import { Transaction } from 'sequelize'
-import { logger } from '@server/helpers/logger'
+import { logger, loggerTagsFactory } from '@server/helpers/logger'
 import { CONFIG } from '@server/initializers/config'
 import { ActorFollowModel } from '@server/models/actor/actor-follow'
 import { getServerActor } from '@server/models/application/application'
@@ -8,6 +8,8 @@ import { Activity } from '@shared/models'
 import { VideoRedundancyModel } from '../models/redundancy/video-redundancy'
 import { sendUndoCacheFile } from './activitypub/send'
 
+const lTags = loggerTagsFactory('redundancy')
+
 async function removeVideoRedundancy (videoRedundancy: MVideoRedundancyVideo, t?: Transaction) {
   const serverActor = await getServerActor()
 
@@ -28,7 +30,7 @@ async function removeRedundanciesOfServer (serverId: number) {
 async function isRedundancyAccepted (activity: Activity, byActor: MActorSignature) {
   const configAcceptFrom = CONFIG.REMOTE_REDUNDANCY.VIDEOS.ACCEPT_FROM
   if (configAcceptFrom === 'nobody') {
-    logger.info('Do not accept remote redundancy %s due instance accept policy.', activity.id)
+    logger.info('Do not accept remote redundancy %s due instance accept policy.', activity.id, lTags())
     return false
   }
 
@@ -37,7 +39,10 @@ async function isRedundancyAccepted (activity: Activity, byActor: MActorSignatur
     const allowed = await ActorFollowModel.isFollowedBy(byActor.id, serverActor.id)
 
     if (allowed !== true) {
-      logger.info('Do not accept remote redundancy %s because actor %s is not followed by our instance.', activity.id, byActor.url)
+      logger.info(
+        'Do not accept remote redundancy %s because actor %s is not followed by our instance.',
+        activity.id, byActor.url, lTags()
+      )
       return false
     }
   }
diff --git a/server/lib/schedulers/videos-redundancy-scheduler.ts b/server/lib/schedulers/videos-redundancy-scheduler.ts
index ebfd015b5..d9988157d 100644
--- a/server/lib/schedulers/videos-redundancy-scheduler.ts
+++ b/server/lib/schedulers/videos-redundancy-scheduler.ts
@@ -14,7 +14,7 @@ import {
   MVideoWithAllFiles
 } from '@server/types/models'
 import { VideosRedundancyStrategy } from '../../../shared/models/redundancy'
-import { logger } from '../../helpers/logger'
+import { logger, loggerTagsFactory } from '../../helpers/logger'
 import { downloadWebTorrentVideo, generateMagnetUri } from '../../helpers/webtorrent'
 import { CONFIG } from '../../initializers/config'
 import { HLS_REDUNDANCY_DIRECTORY, REDUNDANCY, VIDEO_IMPORT_TIMEOUT } from '../../initializers/constants'
@@ -27,6 +27,8 @@ import { removeVideoRedundancy } from '../redundancy'
 import { generateHLSRedundancyUrl, generateWebTorrentRedundancyUrl } from '../video-urls'
 import { AbstractScheduler } from './abstract-scheduler'
 
+const lTags = loggerTagsFactory('redundancy')
+
 type CandidateToDuplicate = {
   redundancy: VideosRedundancyStrategy
   video: MVideoWithAllFiles
@@ -54,7 +56,7 @@ export class VideosRedundancyScheduler extends AbstractScheduler {
     const videoToDuplicate = await VideoModel.loadWithFiles(videoId)
 
     if (!videoToDuplicate) {
-      logger.warn('Video to manually duplicate %d does not exist anymore.', videoId)
+      logger.warn('Video to manually duplicate %d does not exist anymore.', videoId, lTags())
       return
     }
 
@@ -68,7 +70,7 @@ export class VideosRedundancyScheduler extends AbstractScheduler {
 
   protected async internalExecute () {
     for (const redundancyConfig of CONFIG.REDUNDANCY.VIDEOS.STRATEGIES) {
-      logger.info('Running redundancy scheduler for strategy %s.', redundancyConfig.strategy)
+      logger.info('Running redundancy scheduler for strategy %s.', redundancyConfig.strategy, lTags())
 
       try {
         const videoToDuplicate = await this.findVideoToDuplicate(redundancyConfig)
@@ -84,15 +86,18 @@ export class VideosRedundancyScheduler extends AbstractScheduler {
         await this.purgeCacheIfNeeded(candidateToDuplicate)
 
         if (await this.isTooHeavy(candidateToDuplicate)) {
-          logger.info('Video %s is too big for our cache, skipping.', videoToDuplicate.url)
+          logger.info('Video %s is too big for our cache, skipping.', videoToDuplicate.url, lTags(videoToDuplicate.uuid))
           continue
         }
 
-        logger.info('Will duplicate video %s in redundancy scheduler "%s".', videoToDuplicate.url, redundancyConfig.strategy)
+        logger.info(
+          'Will duplicate video %s in redundancy scheduler "%s".',
+          videoToDuplicate.url, redundancyConfig.strategy, lTags(videoToDuplicate.uuid)
+        )
 
         await this.createVideoRedundancies(candidateToDuplicate)
       } catch (err) {
-        logger.error('Cannot run videos redundancy %s.', redundancyConfig.strategy, { err })
+        logger.error('Cannot run videos redundancy %s.', redundancyConfig.strategy, { err, ...lTags() })
       }
     }
 
@@ -120,15 +125,19 @@ export class VideosRedundancyScheduler extends AbstractScheduler {
 
         // If the administrator disabled the redundancy or decreased the cache size, remove this redundancy instead of extending it
         if (!redundancyConfig || await this.isTooHeavy(candidate)) {
-          logger.info('Destroying redundancy %s because the cache size %s is too heavy.', redundancyModel.url, redundancyModel.strategy)
+          logger.info(
+            'Destroying redundancy %s because the cache size %s is too heavy.',
+            redundancyModel.url, redundancyModel.strategy, lTags(candidate.video.uuid)
+          )
+
           await removeVideoRedundancy(redundancyModel)
         } else {
           await this.extendsRedundancy(redundancyModel)
         }
       } catch (err) {
         logger.error(
-          'Cannot extend or remove expiration of %s video from our redundancy system.', this.buildEntryLogId(redundancyModel),
-          { err }
+          'Cannot extend or remove expiration of %s video from our redundancy system.',
+          this.buildEntryLogId(redundancyModel), { err, ...lTags(redundancyModel.getVideoUUID()) }
         )
       }
     }
@@ -152,7 +161,10 @@ export class VideosRedundancyScheduler extends AbstractScheduler {
       try {
         await removeVideoRedundancy(redundancyModel)
       } catch (err) {
-        logger.error('Cannot remove redundancy %s from our redundancy system.', this.buildEntryLogId(redundancyModel))
+        logger.error(
+          'Cannot remove redundancy %s from our redundancy system.',
+          this.buildEntryLogId(redundancyModel), lTags(redundancyModel.getVideoUUID())
+        )
       }
     }
   }
@@ -176,7 +188,7 @@ export class VideosRedundancyScheduler extends AbstractScheduler {
     const video = await this.loadAndRefreshVideo(data.video.url)
 
     if (!video) {
-      logger.info('Video %s we want to duplicate does not existing anymore, skipping.', data.video.url)
+      logger.info('Video %s we want to duplicate does not existing anymore, skipping.', data.video.url, lTags(data.video.uuid))
 
       return
     }
@@ -218,7 +230,7 @@ export class VideosRedundancyScheduler extends AbstractScheduler {
 
     const serverActor = await getServerActor()
 
-    logger.info('Duplicating %s - %d in videos redundancy with "%s" strategy.', video.url, file.resolution, strategy)
+    logger.info('Duplicating %s - %d in videos redundancy with "%s" strategy.', video.url, file.resolution, strategy, lTags(video.uuid))
 
     const trackerUrls = await TrackerModel.listUrlsByVideoId(video.id)
     const magnetUri = generateMagnetUri(video, file, trackerUrls)
@@ -241,7 +253,7 @@ export class VideosRedundancyScheduler extends AbstractScheduler {
 
     await sendCreateCacheFile(serverActor, video, createdModel)
 
-    logger.info('Duplicated %s - %d -> %s.', video.url, file.resolution, createdModel.url)
+    logger.info('Duplicated %s - %d -> %s.', video.url, file.resolution, createdModel.url, lTags(video.uuid))
   }
 
   private async createStreamingPlaylistRedundancy (
@@ -260,7 +272,7 @@ export class VideosRedundancyScheduler extends AbstractScheduler {
     const playlist = Object.assign(playlistArg, { Video: video })
     const serverActor = await getServerActor()
 
-    logger.info('Duplicating %s streaming playlist in videos redundancy with "%s" strategy.', video.url, strategy)
+    logger.info('Duplicating %s streaming playlist in videos redundancy with "%s" strategy.', video.url, strategy, lTags(video.uuid))
 
     const destDirectory = join(HLS_REDUNDANCY_DIRECTORY, video.uuid)
     const masterPlaylistUrl = playlist.getMasterPlaylistUrl(video)
@@ -282,11 +294,11 @@ export class VideosRedundancyScheduler extends AbstractScheduler {
 
     await sendCreateCacheFile(serverActor, video, createdModel)
 
-    logger.info('Duplicated playlist %s -> %s.', masterPlaylistUrl, createdModel.url)
+    logger.info('Duplicated playlist %s -> %s.', masterPlaylistUrl, createdModel.url, lTags(video.uuid))
   }
 
   private async extendsExpirationOf (redundancy: MVideoRedundancyVideo, expiresAfterMs: number) {
-    logger.info('Extending expiration of %s.', redundancy.url)
+    logger.info('Extending expiration of %s.', redundancy.url, lTags(redundancy.getVideoUUID()))
 
     const serverActor = await getServerActor()
 
@@ -317,10 +329,14 @@ export class VideosRedundancyScheduler extends AbstractScheduler {
   private async isTooHeavy (candidateToDuplicate: CandidateToDuplicate) {
     const maxSize = candidateToDuplicate.redundancy.size
 
-    const { totalUsed } = await VideoRedundancyModel.getStats(candidateToDuplicate.redundancy.strategy)
-    const totalWillDuplicate = totalUsed + this.getTotalFileSizes(candidateToDuplicate.files, candidateToDuplicate.streamingPlaylists)
+    const { totalUsed: used } = await VideoRedundancyModel.getStats(candidateToDuplicate.redundancy.strategy)
+
+    const videoSize = this.getTotalFileSizes(candidateToDuplicate.files, candidateToDuplicate.streamingPlaylists)
+    const total = used + videoSize
+
+    logger.debug('Checking candidate size.', { used, videoSize, total, ...lTags(candidateToDuplicate.video.uuid) })
 
-    return totalWillDuplicate > maxSize
+    return total > maxSize
   }
 
   private buildNewExpiration (expiresAfterMs: number) {
diff --git a/server/models/redundancy/video-redundancy.ts b/server/models/redundancy/video-redundancy.ts
index 44c17f8e5..529977924 100644
--- a/server/models/redundancy/video-redundancy.ts
+++ b/server/models/redundancy/video-redundancy.ts
@@ -411,7 +411,7 @@ export class VideoRedundancyModel extends Model<Partial<AttributesOnly<VideoRedu
     return VideoRedundancyModel.scope([ ScopeNames.WITH_VIDEO ]).findOne(query)
   }
 
-  static async listLocalExpired () {
+  static async listLocalExpired (): Promise<MVideoRedundancyVideo[]> {
     const actor = await getServerActor()
 
     const query = {
@@ -701,6 +701,13 @@ export class VideoRedundancyModel extends Model<Partial<AttributesOnly<VideoRedu
     return undefined
   }
 
+  getVideoUUID () {
+    const video = this.getVideo()
+    if (!video) return undefined
+
+    return video.uuid
+  }
+
   isOwned () {
     return !!this.strategy
   }