Emby Server hangs daily (Ubuntu)

[ChrisD 0]

Hi,

I moved over to Emby a few months back partly because of the added support for the HDHomeRun but also because in general I liked the software - unfortunately it hasn't really been working out for me. Let me briefly explain my setup:

* Latest Emby Server 3.0.5781.2 running on a Ubuntu 14.04 server (an HP Gen 8 micro server with a low-power Xeon and 16Gb RAM) which is regularly updated via apt

* 3 x NowTV (Roku) boxes running Emby (MediaBrowser) app

* A few Android 4.4 tablets running Emby app

 

I don't believe that what the clients are running matters, the problem is this: Initially after starting Emby server, the clients talk to Emby server and all is well. Typically though, a day later I will attempt to connect - usually via one of the NowTv/Rok boxes but sometimes via a tablet - and the client will stall waiting to buffer/play a video. It just won't play anything. If I then immediately restart Emby server and retry to play the video on the client, it works again (so I don't believe the client matters here). And it will continue to work until maybe the next day or the day after that, when it needs restarted again (note that we only play a few videos each day so generally it isn't doing much before it stops working again).

 

Unfortunately there is nothing in the server-*.txt logs - the last thing logged was many hours earlier (scheduled tasks but nothing unusual I can see in the logs) and the next thing after that is when the server is restarted. There are transcode-*.txt files for the times that the video failed to play though and these look exactly the same as when the video played successfully. But nothing in the server-*.txt logs. 

 

Usually I know when the video isn't going to play because the client interface isn't right - a top-level category doesn't show up or there are a lot of spinners as it cannot get the images for some thumbnails. Sometimes the client interface doesn't display any categories so I can't even attempt to play a video as nothing shows up. Again, a restart sorts it all out. 

 

Any ideas on where I can go from here? I added a cron job to restart the server each day (early morning) but it didn't help. Should I enable debugging? 

 

One last query, I see a lot (thousands) of these in the server-*.txt logs:

2015-11-21 06:06:28.4214 Info - App: HttpClientManager POST: http://192.168.2.231:9000/plugins/UPnP/MediaRenderer/RenderingControl/control?player=00%3A04%3A20%3A18%3A21%3Abb

This IP:Port is a VM running an instance of Logitech Media Server which services a Logitech Squeezebox. There are actually two set up identically but the logs only report this for one of them. What does it mean - is LMS sending the POST?

 

Thanks.

 

Chris.

Edited November 21, 2015 by ChrisD

[Luke 37010]

Hi, sorry to hear this. The best thing to do is provide some server logs from when the issue occurs so that we can take a look

 

http://emby.media/community/index.php?/topic/739-how-to-report-a-problem/

 

If you're seeing the log fill with dlna related info you could also try disabling some features under Dlna and seeing if that makes a difference.

 

Thanks.

[ChrisD 0]

Ok, so what I've done is zip up the previous two server logs plus the one after it was restarted. Also included is the successful and unsuccessful transcode logs and a readme that explains what the files are and gives a directory listing that shows the original file timestamps. Let me know if you need anything else or I haven't explained anything properly - note that I haven't tried enabling debugging yet.

 

Thanks for looking.

report.tar.gz

[Luke 37010]

the transcodes actually all look fine. what's happening with the first two is that your settings indicated you wanted subtitles to be played. what we do here is extract the subtitles on the fly and deliver them to the video player in text format in order to avoid having to burn them into the video. this exaction happens once per video and the result is cached is cached for future playback.

 

the first video took 19 seconds to extract, the second took 90 seconds, which is on the high side and not typical. so i think the real issue is that we need to provide feedback in the UI about what is going on so that you don't assume there's been a failure. 

 

a previous server release, 5781.0 actually removed the extraction and just resorted to burning them in and that did not go very well as there were numerous reports of poor transcoding performance.

 

unfortunately it's just a situation where we have to pick our poison - the client can't direct play with the internal subs so we have to choose between two imperfect options. that's why external text-based subtitles are always the most efficient. but as mentioned, this only happens once per subtitle and the next time you play the same thing, it's instantaneous.

[ChrisD 0]

Hi Luke, thanks for checking it out. If the generation of subtitles could be causing the problem, can I disable this for a while to see if it helps? I am not sure if it is a server or client setting (I would guess client) - I will have a look later at the MediaBrowser client to see if it can be switched off there. For my own interest, how did you determine this information about how long the subtitle extraction took, from the transcode logs?

[Luke 37010]

at the time of playback there are ffmpeg.exe command lines both for transcoding and for extraction. then later there's a log message about subtitle extraction completed. you can click the user icon in the top right -> settings -> playback, and set your subtitle preference to no subtitles by default.

[ChrisD 0]

Are both command lines for transcoding and extraction to be found in the same transcode*.txt file? I can't see where this is in any of the files I attached, can you point me to the lines that contain this information about subtitle processing?

 

Tonight the NowTV (Roku w/MediaBrowser) failed to play any videos that I tried, it had played the same videos previously. The videos did play via the Emby Android app. I took a look at the transcode logs and have included one here, there are a lot of these:

[aac @ 0x4a1c940] element type mismatch 3 != 0    
Last message repeated 147 times

Any idea what that might indicate?

 

I noticed that when I played a video on the Emby Android app (the same one that failed on the NowTV) that there is no transcode log which I guess is because there is no transcoding required. But there is also no logging in the server-*.txt logs, in fact the last message logged to one of these files was at 01:53 (about 21 hours ago). This doesn't seem right. The last time I watched a video on the NowTV there was no transcode log but there was a lot of logging in the server-*.txt log, so I would assume there should always be logging in the server-*.txt log when doing anything on Emby, is that correct? It isn't a disk space issue, there is 9Gb free on that partition.

 

So just to be clear, nothing has been logged in the server-*.txt logs for 21 hours, despite me browsing and playing on Android and browsing on Roku (but playing failed). The same problem can be observed in the tar of files I previously attached - server-63583671975.txt is timestamped 06:10 (the last time something was written to it) but nothing more was logged until I restarted the server at 20:07.

 

transcode-7bf0dc40-d59a-43b4-8474-7159a723f937.txt

[Luke 37010]

Check the regular server log not the transcoding log for the entries that i mentioned.

[ChrisD 0]

Hi Luke,

I mustn't be explaining this properly - there is no server logging for the period when the issue occurred. Take a look at the readme.txt in the report.tar.gz, the first two transcodes that failed occur at 20:05 and 20:06 - the server stopped logging at 06:10 that morning (see server-63583671975.txt) and didn't log anything again until when it was restarted at 20:07 (see server-63583733245.txt). It was then after the server was restarted that I successfully played a video (the third transcode, which has a log timestamped at 20:08). 

 

In my update about this yesterday, again I am reporting seeing that the server stopped logging earlier in the day - at 01:53 - and when I try to play a video on the NowTV it fails. I haven't restarted Emby Server since then (just to see what happens) and there hasn't been a single line logged - so at the time of writing that is almost two days. Normally there is quite a lot of activity in the logs with all the periodic events. So there is definitely something wrong with logging (and as I said it isn't a disk space issue, restarting Emby fixes it). I have no idea if it is connected to the inability to play videos but on any of the occasions when I have been unable to play videos and I have restarted Emby to fix the problem, there has not been any logging for the period before I restarted it. So I cannot analyse it any further myself as there is nothing logged. 

 

Can you help me get to the bottom of what could be wrong here? I noticed that there are a lot of error reports / stack traces on startup on Emby Server - there are 51 in server-63583733245.txt - are these relevant? Is it possible to take a useful stack trace from Emby when there is a problem? I am not familiar with Mono/.NET or how Emby is architected but I can have a go at trying to collect some useful info, if you think that is possible or helpful.

 

Thanks.

 

Chris.

[ChrisD 0]

Tonight I started the Emby app (NowTV) and it didn't show any media, only the Sign Out / Preferences section. I checked the Emby logs and nothing had been logged for the previous hour, so again it looks like there is a connection between logging stopping and not being about to browse or play media. 

 

I also have a HDHomeRun and scheduling setup with Emby - I have now removed them so that there is one less piece of functionality that could go wrong.

 

Any ideas or thoughts about what I can do here? I can't keep restarting Emby server every time I want to use it. 

[ChrisD 0]

Me again.

 

I thought I had got somewhere with it - after disabling HDHomeRun and SchedulesDirect it worked fine for three days (that's more than usual) but the same problems occurred again last night: server logging had stopped working many hours earlier; each time I attempt to play a video a transcode log is created and that looks ok; the media player does not play anything though (either NowTV or web browser). There is definitely a connection with there being no server logging. One other thing I noticed this time is that no scheduled tasks have been run for 3 days, basically since it was last restarted. I haven't changed anything else apart from removing HDHomeRun/SchedulesDirect.

 

Can anyone help me out here please? I am guessing that no help is available because there are no logs to provide useful information - if it were something I understood I could delve into the application in more detail but from what I have read it isn't easy to take a stack dump like it would be with Java (or to use pstack on a binary).

 

Anybody?

[ChrisD 0]

So here I am again hoping that someone who understands Emby can help me - it's the same problem:

 

I connect to Emby via the Web UI (I haven't used Emby in a couple of days) and it isn't showing any media libraries - the administration UI is working but the browsing/playing part seems to have 'lost' all the media libraries that are normally displayed. If I hover over the Home label in the top left-hand corner, it just displays Home and Metadata manager. Looking at the server logs, the last message was logged a couple of days ago:

 

2015-12-01 09:48:35.9613 Info - App: Scan media library Completed after 1 minute(s) and 25 seconds

 

Looking at the scheduled tasks, nothing has been run in 3 days. That's about since when I last restarted it. So what am I to do, I've spent 90 dollars supporting Emby as I thought it was a great alternative to Plex and I liked the support for HDHomeRun but it isn't working and there doesn't appear to be anyone who can answer my request for help. I can provide any information that might be useful if someone can tell me what would help us get to the bottom of the problem. I have a pretty plain Ubuntu 14.04 installation with Samba and some VMs running via KVM, that's about it. I can provide more details on exactly what is running etc. on the machine if that would help.

 

I am currently running 3.0.5781.4.

[hurricanehrndz 149]

@@ChrisD, I'm sorry you feel like your not getting the support you deserve and being a supporter to us is greatly appreciated. I'm currently in the process of doing a massive upgrades to the packages. Once I'm done I will be more than happy to give your issues a more indepth look. In the meantime ChrisD may I ask where exactly are you looking for the logs? And I will have a look over your logs soon. 

 

Please be patient with us, as we try and make emby the best experience for everyone. 

Edited December 3, 2015 by hurricanehrndz

[ChrisD 0]

I am not expecting special treatment, I was just getting a little frustrated that I'd been talking to myself here  

I am prepared to dig in and try to help get to the bottom of the issue, so any guidance you can give on where I should look would be helpful (I have no experience of Mono/.NET). 

 

I have been consulting the logs in /var/lib/emby-server/logs. Before I restarted Emby server this afternoon (Dec 3rd), this is what I could see:

 

$ ls -alrt

total 14120

drwxr-xr-x 13 chris root      4096 Aug 27 19:31 ../

-rw-r--r--  1 chris users    21022 Nov 30 21:51 server-63584517073.txt

-rw-r--r--  1 chris users    54948 Nov 30 22:15 transcode-44e9f6a6-3c49-4df3-8a69-3c14b750ba71.txt

-rw-r--r--  1 chris users    13800 Nov 30 22:34 transcode-21d91396-739b-4b11-b8ce-cbe516a48356.txt

-rw-r--r--  1 chris users     8611 Nov 30 22:37 transcode-10cde1bd-aa9b-4c94-b8ad-6968efac243d.txt

-rw-r--r--  1 chris users  2316002 Nov 30 23:59 server-63584517111.txt

-rw-r--r--  1 chris users 11529781 Dec  1 09:48 server-63584524800.txt

 

There have been no log updates since Dec 1st, the last line logged is something fairly benign:

 

2015-12-01 09:48:35.9613 Info - App: Scan media library Completed after 1 minute(s) and 25 seconds

 

Every time I restart Emby, within a day or two logging stops and media playback fails. The two don't happen at the same time, I will notice playback isn't working and when I log in, there has been no server logging for hours (or maybe days). So the core problem is that media playback / library browsing fails every day or two and when I go to investigate, there has been no server logging for some time (the last line logged isn't the same each time). This has occurred dozens of times. 

 

Disk space and memory are all good:

 

/var/lib/emby-server/logs$ df -h .

Filesystem      Size  Used Avail Use% Mounted on

/dev/sda1        30G  7.9G   20G  29% /

 

$ free

             total       used       free     shared    buffers     cached

Mem:      16390856   12971680    3419176      39328    1431432    2473724

-/+ buffers/cache:    9066524    7324332

Swap:     15625212      11020   15614192

 

Note that I use zfs which uses up a lot of free memory but gives it back to the OS when required.

 

Whenever you are free and get a chance to read over this issue, if there is any information I can collect or anything I can run then just let me know. I understand you have your own workstack and that you are all busy making Emby even better, so I appreciate any help anyone can give me.

 

Thanks.

[hurricanehrndz 149]

 

I am not expecting special treatment, I was just getting a little frustrated that I'd been talking to myself here

I am prepared to dig in and try to help get to the bottom of the issue, so any guidance you can give on where I should look would be helpful (I have no experience of Mono/.NET). 

 

I have been consulting the logs in /var/lib/emby-server/logs. Before I restarted Emby server this afternoon (Dec 3rd), this is what I could see:

 

$ ls -alrt

total 14120

drwxr-xr-x 13 chris root      4096 Aug 27 19:31 ../

-rw-r--r--  1 chris users    21022 Nov 30 21:51 server-63584517073.txt

-rw-r--r--  1 chris users    54948 Nov 30 22:15 transcode-44e9f6a6-3c49-4df3-8a69-3c14b750ba71.txt

-rw-r--r--  1 chris users    13800 Nov 30 22:34 transcode-21d91396-739b-4b11-b8ce-cbe516a48356.txt

-rw-r--r--  1 chris users     8611 Nov 30 22:37 transcode-10cde1bd-aa9b-4c94-b8ad-6968efac243d.txt

-rw-r--r--  1 chris users  2316002 Nov 30 23:59 server-63584517111.txt

-rw-r--r--  1 chris users 11529781 Dec  1 09:48 server-63584524800.txt

 

There have been no log updates since Dec 1st, the last line logged is something fairly benign:

 

2015-12-01 09:48:35.9613 Info - App: Scan media library Completed after 1 minute(s) and 25 seconds

 

Every time I restart Emby, within a day or two logging stops and media playback fails. The two don't happen at the same time, I will notice playback isn't working and when I log in, there has been no server logging for hours (or maybe days). So the core problem is that media playback / library browsing fails every day or two and when I go to investigate, there has been no server logging for some time (the last line logged isn't the same each time). This has occurred dozens of times. 

 

Disk space and memory are all good:

 

/var/lib/emby-server/logs$ df -h .

Filesystem      Size  Used Avail Use% Mounted on

/dev/sda1        30G  7.9G   20G  29% /

 

$ free

             total       used       free     shared    buffers     cached

Mem:      16390856   12971680    3419176      39328    1431432    2473724

-/+ buffers/cache:    9066524    7324332

Swap:     15625212      11020   15614192

 

Note that I use zfs which uses up a lot of free memory but gives it back to the OS when required.

 

Whenever you are free and get a chance to read over this issue, if there is any information I can collect or anything I can run then just let me know. I understand you have your own workstack and that you are all busy making Emby even better, so I appreciate any help anyone can give me.

 

Thanks.

 

If this is vm, can you please provide with an export? Dropbox? You can clean it a little.

[Luke 37010]

And I apologize for not responding either. I think I was just a little stumped also. I would try turning off all of the dlna features just to reduce the amount of work the server is doing. that might help isolate the problem.

[ChrisD 0]

No problem, being stumped is fine, I just didn't know that  

 

Unfortunately Emby is running on the bare metal (the VMs are used for other services) so I couldn't supply an export - although if I can't get to the bottom of the problem I think I might just install Emby in a new VM and if the problem persists there, I can then export it for you. And if it I don't see the problem in the VM then it is fixed... 

 

In the meantime I have switched off the DLNA features to see if that makes any difference. If that doesn't help and there are no other suggestions, I will stick it in a new VM and see what happens.

 

Thanks.

[hurricanehrndz 149]

What are you doing for ZFS, are you compiling the kernel yourself?

[ChrisD 0]

No it's the stock Ubuntu kernel with the zfs module installed via ppa:zfs-native/stable.

[hurricanehrndz 149]

Any updates ChrisD? Is emby still crashing on you daily? PS I would love to see your syslogs around the time emby stops responding.

Edited December 7, 2015 by hurricanehrndz

[ChrisD 0]

Well I was waiting for a bit longer before saying anything but so far it hasn't crashed / stopped working since I turned off all the DLNA features. Since it doesn't usually last 3 days it looks like that may have fixed it - although I'd maybe want to give it a few more days to be sure. 

 

I don't require any of the DLNA functionality but I can re-enable it for a while if you need me to collect anything to help identify what the problem was - just let me know.

 

If you open the report.tar.gz that I attached earlier in the thread, there is a readme that shows the original directory listing for the included files - the file server-63583671975.txt was last written to at 06:10 that morning but that evening I tried to play some videos (which didn't work) and no further logging was performed until I restarted the server. So that file shows what was going on before the server stopped logging. Looks like one of my Logitech Sequeezeboxes was pretty active - I have two Logitech Media Servers running (192.168.2.130 and 192.168.2.131) which are run in VMs and should be pretty much identical in terms of configuration. There are two hardware players but one is switched off most of the time, the other one being "Squeezebox SL" which is mentioned at the top of the log. 

 

Thanks.

[Luke 37010]

Interesting. yea it was a hunch based on the amount of traffic that was showing up. Thanks for the info.

[ChrisD 0]

Update: All is still well on my system. It's never been this stable before, must be about 9 days since it was restarted and everything still works when required. Awesome stuff. I had kind of given up using Emby to watch TV through the HDHomeRun due to the reliability issues but now it is a good option. 

 

Cheers.

[hurricanehrndz 149]

@@ChrisD Happy to hear, and congrats.