From 52b1fd15fa9e2cc04873ad606e789929579483f2 Mon Sep 17 00:00:00 2001 From: Chocobozzz Date: Thu, 26 Aug 2021 11:01:59 +0200 Subject: Better logs for redundancy --- server/lib/redundancy.ts | 11 +++-- .../lib/schedulers/videos-redundancy-scheduler.ts | 54 ++++++++++++++-------- server/models/redundancy/video-redundancy.ts | 9 +++- 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 { const actor = await getServerActor() const query = { @@ -701,6 +701,13 @@ export class VideoRedundancyModel extends Model