Audio Normalization Task

[Jamie Chapman]

Hey folks, I recently reset my Jellyfin to a clean install on a new box. 

Trcikplay is still cataloging: 4 days, 31% complete, so looks like the initial run will be close to two weeks. Sweet feature. I never knew about the old Jellyscrub plugin, so glad the feature was introduced. I had no idea what the heck trcikplay was until it was integrated in 10.9, then, as I usually do when something is new to me, I dug so I could understand it. Great tech, files are pretty small. I expect my metadata folder to grow about 30GB.

Anyway, the Audio Normalization scheduled task continues to fail. My guess on the reasoning for this is the trickplay task, but the log is not clear. Log snip of the failure event and surrounding events is below.

• [2024-06-17 20:27:51.680 -04:00] [ERR] [57] Emby.Server.Implementations.ScheduledTasks.TaskManager: Error executing Scheduled Task System.IO.IOException: The process cannot access the file 'C:\ProgramData\Jellyfin\Server\cache\transcodes\6bab25e2-5614-4b60-a3d7-735ccb7f6501.concat' because it is being used by another process.
  

•   at System.IO.FileSystem.DeleteFile(String fullPath)
  

•   at Emby.Server.Implementations.ScheduledTasks.Tasks.AudioNormalizationTask.ExecuteAsync(IProgress`1 progress, CancellationToken cancellationToken)
  

•   at Emby.Server.Implementations.ScheduledTasks.ScheduledTaskWorker.ExecuteInternal(TaskOptions options)
  

• [2024-06-17 20:27:51.974 -04:00] [INF] [57] Emby.Server.Implementations.ScheduledTasks.TaskManager: "Audio Normalization" Failed after 0 minute(s) and 10 seconds
  

Jellyfin 10.9.6
Windows Server (Win 11 Pro) running Jellyfin service
AMD Ryzen 9 7950X
64GB DDR5-4800 RAM
NVIDIA RTX 3060 12GB
OS Drive: Samsung 990 Pro 2TB
Media Drive (all libraries): QNAP TS-932PX NAS with 5 x Seagate Ironwolf Pro 16TB in RAID5 connected with 10Gbps iSCSI link

[Jamie Chapman]

Quick update. I stopped the trickplay task to test if this issue was related to it running, but the concat file is still locked. I understand the basics of concatenation, if that is, in fact, what the concat file is there for. Just trying to understand what it might have to do with the audio normalization routine, and how to resolve it. Here is the latest log snip. Same issue.

[2024-06-18 18:49:18.368 -04:00] [ERR] [113] Emby.Server.Implementations.ScheduledTasks.TaskManager: Error executing Scheduled Task
System.IO.IOException: The process cannot access the file 'C:\ProgramData\Jellyfin\Server\cache\transcodes\9cbab7c1-c9de-4bf9-bac5-375d176f962e.concat' because it is being used by another process.
at System.IO.FileSystem.DeleteFile(String fullPath)
at Emby.Server.Implementations.ScheduledTasks.Tasks.AudioNormalizationTask.ExecuteAsync(IProgress`1 progress, CancellationToken cancellationToken)
at Emby.Server.Implementations.ScheduledTasks.ScheduledTaskWorker.ExecuteInternal(TaskOptions options)
[2024-06-18 18:49:18.370 -04:00] [INF] [113] Emby.Server.Implementations.ScheduledTasks.TaskManager: "Audio Normalization" Failed after 0 minute(s) and 5 seconds

---

And I finally noticed that the concat file is being generated every time I run the audio normalization task (a new concat file every time, all of the same size, all with the same data in them).

So I decided to open it up in a text editor, and it's just a listing of the files in my music library, albeit a very short list, possibly the files that the task was processing when it hit the error.

Now I'm wondering if this might be a file permission problem on one of the libraries. I'm going to try that next and will post back if that is the issue.

[Jamie Chapman]

Definitely not a file or folder permission problem . Same issue. Reset permissions on the relevant folders and subs, restarted jellyfin, and same error. Going to check process explorer to see what process is locking the file. This appears to possibly be a bug.

[Jamie Chapman]

After a bit of digging, I cannot find what causes the file lock on the dynamically created .concat file. Rebooted numerous times, tried capturing what application process is locking the file, all to no avail. The task fails every time with the same error as noted above.

Any insight anyone may have would be greatly appreciated. Thanks.

[pcm]

I am guessing here. But, based on the log message.. it seems like the audio-normalization job creates a temp file in the cache and executes ffmpeg to normalize the audio of your album and then it tries to delete the temp file after it's done with the normalization calculations.
The schedule task spawns the ffmpeg process as a child process asynchronously (based on the github code).

I'm guessing that ffmpeg is not done doing it's normalization thingy and the scheduled task process moves on and attempts to delete the file which ffmpeg is still working on...

One thing you could do is turn on debug-logging temporarily and see what the log says when you kick off the audio normalization job and right before it fails... It might help understand the issue better.

But, I think, you might want to open an issue on github for this...

[TheDreadPirate]

Can you enable debug logged, replicate the problem, then post your server logs to pastebin?

https://jellyfin.org/docs/general/admini...ug-logging

[Jamie Chapman]

I am sure that it's me doing something wrong. Can someone take a look at the below logging.json configs and tell me where I'm off? I tried restarting the service, even though the instructions say this should not be needed, but there is still no debug logging showing up in the log file. Just the same standard INF, ERR and WRN log entries.

Default logging.json, located in C:\ProgramData\Jellyfin\Server\config

{
    "Serilog": {
        "MinimumLevel": {
            "Default": "Information",
            "Override": {
                "Microsoft": "Warning",
                "System": "Warning"
            }
        },
        "WriteTo": [
            {
                "Name": "Console",
                "Args": {
                    "outputTemplate": "[{Timestamp:HH:mm:ss}] [{Level:u3}] [{ThreadId}] {SourceContext}: {Message:lj}{NewLine}{Exception}"
                }
            },
            {
                "Name": "Async",
                "Args": {
                    "configure": [
                        {
                            "Name": "File",
                            "Args": {
                                "path": "%JELLYFIN_LOG_DIR%//log_.log",
                                "rollingInterval": "Day",
                                "retainedFileCountLimit": 3,
                                "rollOnFileSizeLimit": true,
                                "fileSizeLimitBytes": 100000000,
                                "outputTemplate": "[{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz}] [{Level:u3}] [{ThreadId}] {SourceContext}: {Message}{NewLine}{Exception}"
                            }
                        }
                    ]
                }
            }
        ],
        "Enrich": [ "FromLogContext", "WithThreadId" ]
    }
}


Modified logging.json from instructions found here: https://jellyfin.org/docs/general/admini...eshooting/

{
    "Serilog": {
        "MinimumLevel": {
            "Default": "Debug",
            "Override": {
                "": "Debug"
            }
        },
        "WriteTo": [
            {
                "Name": "Console",
                "Args": {
                    "outputTemplate": "[{Timestamp:HH:mm:ss}] [{Level:u3}] [{ThreadId}] {SourceContext}: {Message:lj}{NewLine}{Exception}"
                }
            },
            {
                "Name": "Async",
                "Args": {
                    "configure": [
                        {
                            "Name": "File",
                            "Args": {
                                "path": "%JELLYFIN_LOG_DIR%//log_.log",
                                "rollingInterval": "Day",
                                "retainedFileCountLimit": 3,
                                "rollOnFileSizeLimit": true,
                                "fileSizeLimitBytes": 100000000,
                                "outputTemplate": "[{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz}] [{Level:u3}] [{ThreadId}] {SourceContext}: {Message}{NewLine}{Exception}"
                            }
                        }
                    ]
                }
            }
        ],
        "Enrich": [ "FromLogContext", "WithThreadId" ]
    }
}

[TheDreadPirate]

For whatever reason, 10.9 doesn't label debug logs as such. But there are additional logs.

[Jamie Chapman]

Sounds good. I was looking for the DBG qualifier. Let me give it another go. Thanks for the insight.

[Jamie Chapman]

https://pastebin.com/a53KDFnG