Better logs for redundancy

pull/4360/head
Chocobozzz 2021-08-26 11:01:59 +02:00
parent 7b6cf83e33
commit 52b1fd15fa
No known key found for this signature in database
GPG Key ID: 583A612D890159BE
3 changed files with 51 additions and 23 deletions

View File

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

View File

@ -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)
return totalWillDuplicate > maxSize
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 total > maxSize
}
private buildNewExpiration (expiresAfterMs: number) {

View File

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