Server crashing semi-randomly (Imageprocessing-ConvertImageToLocal)

[Vitz 1]

Hi there,

I'm having a problem where Emby seems to be crashing randomly, but possibly only when transcoding (cryptic, I know). I simply don't know what's causing it. I've included the debug log that was made right before yesterday's crash, but it (and I am no expert in any way whatsoever) does not seem to show any details as to why. The only reason I'm blaming transcoding is because that seems to correlate to when people on my server are transcoding.

I'm running Emby through an Ubuntu 20.04 VM on Proxmox. It's got 24GB of memory, which I reckon should be more than enough. It's got 16 threads to work with which are never saturated, even when transcoding.

I feel like I need to add that the behaviour became a lot more rare when I told users to use maximum quality in their client, thus eliminating transcoding in a lot of cases. Also, I do not have a video card installed in the system so hardware acceleration is not enabled. The CPUs alone appear to be more than capable. 

Beside the Emby debug log I've included an ffmpeg log, but it seems to be many hours removed from Emby's regular log. I don't know how helpful that is because it doesn't represent the time at which Emby crashed.

Any help would be highly appreciated.

embyserver-63769566229.txt ffmpeg-transcode-da9ded3a-5010-4084-aaf9-ad13febe932a_1.txt

[Happy2Play 8309]

Dev will have to comment more as you log stops at what appears to be loop creating a playlist image "ConvertImageToLocal item 160690 - image url: emby://playlistcollage" almost 200 times.

 

Unrelated but you need to apply the inotify patch to your platform also.  Not limited to this library. 

2021-10-11 08:10:25.375 Error LibraryMonitor: Error in Directory watcher for: /smb/Movies1
	*** Error Report ***
	Version: 4.6.4.0
	Command line: /opt/emby-server/system/EmbyServer.dll -programdata /var/lib/emby -ffdetect /opt/emby-server/bin/ffdetect -ffmpeg /opt/emby-server/bin/ffmpeg -ffprobe /opt/emby-server/bin/ffprobe -restartexitcode 3 -updatepackage emby-server-deb_{version}_amd64.deb
	Operating system: Linux version 5.4.0-86-generic (buildd@lgw01-amd64-041) (gcc version 9.3.0 (Ubuntu 9.3.0-17ubuntu1~20.04)) #97-Ubuntu SMP Fri Sep 17 19:19:40 UTC 2021
	Framework: .NET Core 3.1.13
	OS/Process: x64/x64
	Runtime: opt/emby-server/system/System.Private.CoreLib.dll
	Processor count: 12
	Data path: /var/lib/emby
	Application path: /opt/emby-server/system
	System.IO.IOException: System.IO.IOException: The configured user limit (8192) on the number of inotify watches has been reached, or the operating system failed to allocate a required resource.
	Source: 
	TargetSite: 
	No Stack Trace Available

Don't know test platforms but this may help.

 

[Vitz 1]

2 hours ago, Happy2Play said:

Dev will have to comment more as you log stops at what appears to be loop creating a playlist image "ConvertImageToLocal item 160690 - image url: emby://playlistcollage" almost 200 times.

 

 

This puzzled me as well.

As for the inotify error, that's my bad. I left my libraries to utilise the real-time monitoring feature, which simply doesn't work with network shares coming from TrueNAS. I've disabled them so they won't litter future logs. That shouldn't be the source of the problem, though. I've enabled those options halfway through to see if they'd work for some reason and forgot to disable them.

[Happy2Play 8309]

I think there is a known issue (at least previously reported) but @Lukewould have to comment more if the issue was found.

Similar issue with boxsetcollage here

https://emby.media/community/index.php?/topic/100980-emby-server-crashing

 

[Vitz 1]

Thank you, but the issue you're referring to appears to be linked to "ConvertImageToLocal item" (which is probably for a different thread), and the person in that thread is running a Windows version. I mean, I could be mistaken but I don't think it's responsible for my crashing issue. There's a reason I waited some time to report this; the problem definitely appears more often, if not only, when users are transcoding.

[Carlo 4330]

Looking at your logs the ffmpeg shows the transcode finished so it's doubtful the crash was caused by transcoding (at least not that one).  However your server log stops with:

ConvertImageToLocal item 160690

Could you shutdown Emby Server, grab a copy of your library.db file and PM it to me?
I'd like to take a look to see what item 160690 is and what Emby is trying to do for that item.  This may give us clues to fixing this for you.

What is "playlistcollage"?  Does that mean anything to you?

Your inotify is working as @Happy2Play mentioned or you wouldn't be getting errors in the log.  RTM doesn't appear to be working because the host needs an adjustment to increase the number of watches it can handle. 8192 is just far too small for media environments and needs to be set to a higher number.  Once you do that, RTM will work for those folders.

[Vitz 1]

36 minutes ago, cayars said:

Looking at your logs the ffmpeg shows the transcode finished so it's doubtful the crash was caused by transcoding (at least not that one).  However your server log stops with:

ConvertImageToLocal item 160690

Could you shutdown Emby Server, grab a copy of your library.db file and PM it to me?
I'd like to take a look to see what item 160690 is and what Emby is trying to do for that item.  This may give us clues to fixing this for you.

What is "playlistcollage"?  Does that mean anything to you?

Your inotify is working as @Happy2Play mentioned or you wouldn't be getting errors in the log.  RTM doesn't appear to be working because the host needs an adjustment to increase the number of watches it can handle. 8192 is just far too small for media environments and needs to be set to a higher number.  Once you do that, RTM will work for those folders.

I believe item 160690 was one of the custom images I set up for one of my libraries. It no longer appears in any logs ever since I removed those (I'll attach yesterday's log for comparison).

"playlistcollage" doesn't mean anything to me, no. Could it be related to the Collections feature? In any case, I've gotten rid of those too.

As for inotify, what would be a recommended value for Emby? It would be awesome to get that working but it remains to be seen whether it's a good idea. I'm running my shares off TrueNAS SCALE, which is still an experimental version of TrueNAS running on Linux instead of BSD. The thing with TrueNAS is that they highly discourage any tinkering with the config files and instead do everything through their UI. inotify doesn't have any settings in the UI, as far as I'm aware. I'm not opposed to manually editing the config files but on BSD at least, TrueNAS actually caches its config files and resets them upon reboot unless they're applied through the UI. There's ways around that, but those are even more discouraged.

Edit: Decided to check out the inotify settings and the config file is just flat-out unwritable even with sudo. If I'm going to raise that number, I think I'll have to ask around the TrueNAS forums first.

embyserver-63769881600.txt

Edited October 15, 2021 by Vitz

[Vitz 1]

I can't seem to edit my post anymore but as it happens, changes to sysctl actually can be made through the TrueNAS UI (in SCALE, at least). So raising the inotify limit is trivial. I have no idea what to set it to, though. I don't just want to add two zeroes and have it hammer the system. What's a value I should aim for?

[Carlo 4330]

1 hour ago, Vitz said:

 I don't just want to add two zeroes and have it hammer the system. What's a value I should aim for?

Actually you do and your system will handle it just fine.  I would set up both instances and watches to these values and only raise them from there if you need to.
Mine are set higher then these.

fs.inotify.max_user_instances = 10000
fs.inotify.max_user_watches = 204800

[Vitz 1]

51 minutes ago, cayars said:

Actually you do and your system will handle it just fine.  I would set up both instances and watches to these values and only raise them from there if you need to.
Mine are set higher then these.

fs.inotify.max_user_instances = 10000
fs.inotify.max_user_watches = 204800

So far, no dice, I'm afraid. I added something ~thirty minutes ago and Emby hasn't picked it up yet. I validated the values and they're set correctly but I'm also reading that this is something that needs to be enabled at kernel level, and TrueNAS SCALE simply might not have that. I do have scripts in place that mitigate the lack of RTM, but it would be nice not having to rely on those and having it Just Work™. What are these values based on? Does my library size factor in? It is rather large.

[Happy2Play 8309]

OT:  @Lukehow do you get "/Items/undefined"?

2021-10-14 16:39:57.297 Info Server: http/1.1 GET http://[SERVER]/emby/Items/undefined/ThumbnailSet?Width=400&X-Emby-Client=Emby Web&X-Emby-Device-Name=Chrome&X-Emby-Device-Id=7902f9dc-64f9-4ccd-98ce-3c51e662ae2a&X-Emby-Client-Version=4.6.4.0. UserAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.81 Safari/537.36
2021-10-14 16:39:57.299 Error Server: Error processing request
	*** Error Report ***
	Version: 4.6.4.0
	Command line: /opt/emby-server/system/EmbyServer.dll -programdata /var/lib/emby -ffdetect /opt/emby-server/bin/ffdetect -ffmpeg /opt/emby-server/bin/ffmpeg -ffprobe /opt/emby-server/bin/ffprobe -restartexitcode 3 -updatepackage emby-server-deb_{version}_amd64.deb
	Operating system: Linux version 5.4.0-86-generic (buildd@lgw01-amd64-041) (gcc version 9.3.0 (Ubuntu 9.3.0-17ubuntu1~20.04)) #97-Ubuntu SMP Fri Sep 17 19:19:40 UTC 2021
	Framework: .NET Core 3.1.13
	OS/Process: x64/x64
	Runtime: opt/emby-server/system/System.Private.CoreLib.dll
	Processor count: 12
	Data path: /var/lib/emby
	Application path: /opt/emby-server/system
	System.FormatException: System.FormatException: Guid should contain 32 digits with 4 dashes (xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx).
	   at System.Guid.GuidResult.SetFailure(Boolean overflow, String failureMessageID)
	   at System.Guid.TryParseExactN(ReadOnlySpan`1 guidString, GuidResult& result)
	   at System.Guid.TryParseGuid(ReadOnlySpan`1 guidString, GuidResult& result)
	   at System.Guid..ctor(String g)
	   at MediaBrowser.Controller.Library.LibraryManagerExtensions.GetItemById(ILibraryManager manager, ReadOnlySpan`1 id)
	   at RokuMetadata.Api.BifService.Get(GetThumbnails request)
	   at Emby.Server.Implementations.Services.ServiceController.Execute(HttpListenerHost appHost, Object requestDto, IRequest req)
	   at Emby.Server.Implementations.Services.ServiceHandler.ProcessRequestAsync(HttpListenerHost appHost, IRequest httpReq, IResponse httpRes, RestPath restPath, String responseContentType, CancellationToken cancellationToken)
	   at Emby.Server.Implementations.HttpServer.HttpListenerHost.RequestHandler(IRequest httpReq, ReadOnlyMemory`1 urlString, ReadOnlyMemory`1 localPath, CancellationToken cancellationToken)
	Source: System.Private.CoreLib
	TargetSite: Void SetFailure(Boolean, System.String)
	
2021-10-14 16:39:57.299 Info Server: http/1.1 Response 500 to 2001:1c01:2ec2:6a00:9db0:510d:8a34:4d74. Time: 2ms. 

 

[Vitz 1]

Yeah, sorry for going off-topic. For the sake of functionality I've configured the Emby service to automatically restart so a crash wouldn't be that obvious. I've reverted that change so I'll have a log ready to go if it happens again.

[Carlo 4330]

54 minutes ago, Vitz said:

So far, no dice, I'm afraid. I added something ~thirty minutes ago and Emby hasn't picked it up yet. I validated the values and they're set correctly but I'm also reading that this is something that needs to be enabled at kernel level, and TrueNAS SCALE simply might not have that. I do have scripts in place that mitigate the lack of RTM, but it would be nice not having to rely on those and having it Just Work™. What are these values based on? Does my library size factor in? It is rather large.

Haven't really played with TrueNAS scale yet so I'm not sure but being Debian based you should be able to set this via SSH.

You could try this for a session only without adding it to any startup with this. On restart these would be gone.

sudo sysctl fs.inotify.max_user_watches=204800
sudo sysctl fs.inotify.max_user_instances=10000

Then turn on Real Time Monitoring in Emby again and test it.

Just curious, what do the scripts do?  You could also add or change the Scheduled Task for Scan Media Library to an Interval set at 2 hours (whatever) that would run a library scan.

[Vitz 1]

15 minutes ago, cayars said:

Haven't really played with TrueNAS scale yet so I'm not sure but being Debian based you should be able to set this via SSH.

You could try this for a session only without adding it to any startup with this. On restart these would be gone.

sudo sysctl fs.inotify.max_user_watches=204800
sudo sysctl fs.inotify.max_user_instances=10000

Then turn on Real Time Monitoring in Emby again and test it.

Just curious, what do the scripts do?  You could also add or change the Scheduled Task for Scan Media Library to an Interval set at 2 hours (whatever) that would run a library scan.

The values are already set. I've added them, restarted TrueNAS (it had to update anyway) and verified them. This makes me think inotify might just not be functional in SCALE. Either that or it's an SMB thing.

As for the scripts, I've got a webhook command running from Sonarr that echoes "1" to a file every time something is added, and then a cron job every fifteen minutes running a script that checks said file for "1", changes it back to "0" if true and proceeds to scan the TV Shows library only. If the first file remains at 0, nothing happens.

The reason I'm doing it like this is because my music library is simply too large to scan every fifteen minutes. It creates a completely unnecessary amount of overhead. Radarr also sends a webhook command, but that goes straight to scanning the Movies library instead of utilising scripts because it usually only involves a single file. The problem with using the webhook method for Sonarr was that it queues scans for every single episode, which Emby then executes consecutively. More unnecessary overhead.

Edited October 15, 2021 by Vitz

[Carlo 4330]

Don't know if you are aware but Sonarr (same with Radarr) can notify Emby directly that it just added media so it immediately scans in that media. No need for any scripts when using them.

[Vitz 1]

4 minutes ago, cayars said:

Don't know if you are aware but Sonarr (same with Radarr) can notify Emby directly that it just added media so it immediately scans in that media. No need for any scripts when using them.

Yep, I have that configured on both Sonarr and Radarr and neither of them work, despite the test button reporting success. I have no idea why.

[Carlo 4330]

Sounds like you can't catch a break.

[Vitz 1]

That's what I get for virtualising everything, I suppose!

[Vitz 1]

All right, I've got another crash, hot off the presses. This log is short because I rebooted the VM multiple times today. For some reason the dreaded item 160690 is back, despite it being absent from logs for days. I'm pretty much certain there were no people watching content on my server during the crash or before it, so it seems like I owe @Happy2Play an apology, as there could have been no transcoding.

@cayars Are you still interested in the library.db file?

embyserver-63769925461.txt

[Happy2Play 8309]

I am guessing it is a playlist since it is trying to make a playlistcollage.

2021-10-15 20:09:43.410 Info Server: http/1.1 GET http://vitzflix.home.lan:8096/emby/Items/160690/Images/Primary?maxWidth=80&tag=bb0f55b2ccff4f2cc871a64d285599a4&quality=90. UserAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:93.0) Gecko/20100101 Firefox/93.0

My guess it the what ever item 160690 need the image removed or it need completely removed from Emby and readded, if a playlist deleted and recreated.

And yes Cayars could look in the database to see exactly what 160690 is to assist if you can find it.  What does that url show you?

[Vitz 1]

10 minutes ago, Happy2Play said:

I am guessing it is a playlist since it is trying to make a playlistcollage.

2021-10-15 20:09:43.410 Info Server: http/1.1 GET http://vitzflix.home.lan:8096/emby/Items/160690/Images/Primary?maxWidth=80&tag=bb0f55b2ccff4f2cc871a64d285599a4&quality=90. UserAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:93.0) Gecko/20100101 Firefox/93.0

My guess it the what ever item 160690 need the image removed or it need completely removed from Emby and readded, if a playlist deleted and recreated.

And yes Cayars could look in the database to see exactly what 160690 is to assist if you can find it.  What does that url show you?

Heh...It shows nothing at all. It crashes Emby. I'm truly sorry. I shouldn't have been stubborn and I should have looked into your findings earlier. It's obviously the root of the problem. Thank you!

Now to find out what that item is. Is there an easily explainable method for me to find it on my own or should I wait for Cayars to respond?

Edited October 15, 2021 by Vitz

[Happy2Play 8309]

14 minutes ago, Vitz said:

Heh...It shows nothing at all. It crashes Emby. I'm truly sorry. I shouldn't have been stubborn and I should have looked into your findings earlier. It's obviously the root of the problem. Thank you!

Now to find out what that item is. Is there a method for me to find it on my own or should I wait for Cayars to respond?

Via the api or the database directly.  (Link is at the bottom of the Dashboard) The api is a little bit of a pain these days with the way browsers are require you to use https without adjusting browser flags.

how large is the database?

Edited October 15, 2021 by Happy2Play

[Vitz 1]

10 minutes ago, Happy2Play said:

Via the api or the database directly.  (Link is at the bottom of the Dashboard) The api is a little bit of a pain these days with the way browsers are require you to use https without adjusting browser flags.

how large is the database?

That API page looks a little out of my depth. The search bar doesn't return any results for 160690, in any case.

The database file is 372MB, which seems large to me but I don't have any frame of reference and there's a lot of stuff in there, so it might be normal.

[Happy2Play 8309]

8 minutes ago, Vitz said:

That API page looks a little out of my depth. The search bar doesn't return any results for 160690, in any case.

The database file is 372MB, which seems large to me but I don't have any frame of reference and there's a lot of stuff in there, so it might be normal.

In the api you can go to ItemsService and expand /items, click try out then scroll down to IDs and enter 160690 then scroll down and execute.  What results does it provide?

As for the database you would has to share it say one drive or other service like that.  But you could open it with any sqllite browser, go to mediaitems table and filter 160690 in the ID column.

Or possible PM cayars to do a remote session to assist you with this process.

[Vitz 1]

4 minutes ago, Happy2Play said:

In the api you can go to ItemsService and expand /items, click try out then scroll down to IDs and enter 160690 then scroll down and execute.  What results does it provide?

As for the database you would has to share it say one drive or other service like that.  But you could open it with any sqllite browser, go to mediaitems table and filter 160690 in the ID column.

Or possible PM cayars to do a remote session to assist you with this process.

Bingo. It refers me to an album I have, which contains an M3U file. I know this is a playlist file and 160690 explicitly refers to it as "Playlist". Can I safely assume this is the offender? I deleted it either way. It serves no purpose.