Plex server randomly stops responding even thought it shows as still running (Ubuntu 14.04 LTS)

General Discussions
1

I am running Plex 1.2.3.2914 (although this problem has been going on for some time now). I am running it on Ubuntu 14.04 LTS with a couple of other applications dedicated to media for Plex. The server down nothing else.

For well over a year the plex server has been rock solid, never needing any maintenance other then the plex server software upgrades and the occasional apt-get update/upgrade. A couple of months ago I started to get complaints that the server was offline. When I logged into the server and issued a service plexmediaserver status It would show that it was running. A ps aux showed this to be the case, but any attempts to connect to it (directly or via plex.tv) would fail.

The only way to get the server back online was to shut it down and restart the plexmedia service itself. It is now to the point where it happens once every couple of days, sometimes just minutes after a restart of the service, sometimes a day or two will pass, but definitely more and more often now. My media does not reside on the plex media server but is server from an attached NAS. I was going to write a script to detect when it went offline and restart it, but a service check always shows it up and running and the plex media server process is still running, just not responding to requests.

I have looked at the logs, but frankly nothing sticks out at all, it just seems that for some reason Plex stops responding to requests even though it is still running on the server. I am really starting to pull my hair out on this one.

If anyone has any suggestions where to looks, I would be very grateful!

2

The next time it stops responding, shut it down normally, and grab all the log files for everything in and below “Logs” (tar.gz or zip are fine)… Without seeing your logs, there is no way of knowing whether a plug-in or something else is causing it to not respond.

The most common reasons for it to not respond are “SLOW QUERY” in the logs (which cause time-outs) and an ill-behaving plug-in monopolizing the API. If your problem(s) began right after you upgraded to a specific version and/or upgraded a plug-in , the plug-in / API scenario is more likely.

Examining your logs will show us what’s happening.

You may attach your logs to your next post using the document icon along the top of your reply.

3

ChuckPa -

Will Do.

Thanks

4

ChuckPa -

Just happened again. Was watching TV with maybe 4 or 5 streams going and all-of-a-sudden it just stops. I shut plex down normally (service plexmediaserver stop) then copied all of the logs as suggested. I have attached them here.

The other thing that I noticed before I shut down the server was that a netstat (also attached here) showed a ton of connections that appeared to be hanging. I am thinking this must be clients coming in via plex.tv trying to talk to the server (which by then is not responding).

Any help would be greatly appreciated.

Thanks

5

I see that (netstat) Thank you! That explains a lot. It ran out of sockets (which is very difficult to do btw)

What I also see, which is far more disturbing, is the spamming of transcoder errors. There is something about the video it was playing that it did NOT like. I need to pin down what it was trying to play at the time.

I need to see all the rollover versions too please. I only see the streaming of errors and not what was actually being played. If you have them, and can show what items were being played please attach them in a tarball.

The hour is late here (02:00) I’ll update again in the morning.

6

Thanks ChuckPa -

I have attached all of the logs including the rollover logs here. I thought it was weird with all of the sockets open as well which is why I figured I would send the netstat! Not sure if it matters but here is a little more about my setup:

We have a cox fiber connection and I have one of my IP addresses statically mapped to my Plex server via my firewall. The only allowed port is 32400. All other management is completed via VPN. I have NZBGet, CP and Sonaar running as well. The server is dedicate to Plex/CP/Sonaar and runs an i7-5960 running at 3Ghz with 32GB of memory and 2 x 1T system drives (primary and rsynce’d backup). I am connected via 10GB ethernet to my NAS server (plexnas) running FreeNAS (FreeNAS-9.10.1-U2 (f045a8b)) This is dedicated to Plex and has 45TB of attached drive space, about 25TB of that in use. I have a standard gigabit ethernet from the Plex server to my cisco switch via a dedicated vlan for my media stuff.

I think (at most) I have had 8 streams but most of the time around 4. None of them local to the server, all going through plex.tv. I also have 8MB set as the max under Server => Remote Access => Limit remote stream bitrate. This is so I don’t get my connection too saturated with just Plex.

Not sure if you need any other info, if so please ask!

7

If you pull open your log Plex Media Server.1.log, look at the AAC errors.

Can you find that file and get the first 10 MB of it? We need to figure out what’s happening. I suspect that is causing the transcoder to crash in a very ugly way, leaving all those sockets dangling. When that happens, with most linux distros having a limit of < 256 sockets open at any one instant, PMS ‘hangs’ waiting for a free socket to open.

We can test that theory if you like by granting more sockets at the system level (adjust the runtime, not the perm config)

8

Do me a favor please. Optimize the Database.

Oct 29, 2016 21:32:08.005 [0x7fc830bff700] INFO - Time value greater than duration
Oct 29, 2016 21:33:08.581 [0x7fc82cbff700] WARN - Waited one whole second for a busy database.
Oct 29, 2016 21:33:16.555 [0x7fc80abfb700] INFO - It's been 16572729 seconds, so we're starting scheduled library update for section 1 (Movies)```

I don't think the database is slow but want to be certain it's perfect.   This usually indicates something else is in the DB and has it locked while doing something.  I suspect the XB-1 is the culprit but need to start narrowing down the variables.
9

@ChuckPa said:
If you pull open your log Plex Media Server.1.log, look at the AAC errors.

Can you find that file and get the first 10 MB of it? We need to figure out what’s happening. I suspect that is causing the transcoder to crash in a very ugly way, leaving all those sockets dangling. When that happens, with most linux distros having a limit of < 256 sockets open at any one instant, PMS ‘hangs’ waiting for a free socket to open.

We can test that theory if you like by granting more sockets at the system level (adjust the runtime, not the perm config)

Thanks ChuckPa -

Not sure which file I am supposed to get. I see those (what appears to be thousands) or errors, but I don’t see a file name anywhere telling me what file is causing the errors!

Per your second post, I went ahead and ran the database optimization.

10

Do you have any possible clue as to which file(s) might be causing it? What was most recently played? It is coming from the XB-1.

I’m asking because that error does happen when a MKV is renamed to be MP4 or otherwise changed without analysis having been updated. The transcoder expects one thing but gets another .

11

humm…no idea at all. I have plexwatch installed and I see absolutely nothing being played on an XB-1. All of my kids have Roku’s (3s and 4s) and the one person with an xbox one was not watching anything last night when it happened. So I am at a total loss as to what that might have been.

Out of curiosity How can you tell it was an xbox one?

Thanks

12

Also, I am tailing my logs now and I am seeing more errors, could these be related or something different:

Oct 30, 2016 09:53:22.180 [0x7fc8093f8700] WARN - Got a request to stop a transcode session without a session GUID (or with an invalid one).
Oct 30, 2016 09:53:25.226 [0x7fc8093f8700] WARN - Got a request to stop a transcode session without a session GUID (or with an invalid one).
Oct 30, 2016 09:59:39.210 [0x7fc819ffd700] WARN - Waited one whole second for a busy database.
Oct 30, 2016 09:59:40.220 [0x7fc819ffd700] ERROR - Failed to begin transaction (…/Statistics/StatisticsManager.h:183) (tries=1): Cannot begin transaction. database is locked
Oct 30, 2016 09:59:41.711 [0x7fc819ffd700] WARN - Waited one whole second for a busy database.
Oct 30, 2016 09:59:42.721 [0x7fc819ffd700] ERROR - Failed to begin transaction (…/Statistics/StatisticsManager.h:183) (tries=2): Cannot begin transaction. database is locked

13

That’s what I"m trying to find. THAT one. What was playing / trying to be played.

14

This is what I see. This contains the ID numbers to the media being played as well.

Oct 29, 2016 20:49:43.630 [0x7fc830bff700] WARN - [Plex for Xbox One] [Connections] cinaplex is unavailable at https://10-0-7-1.cbe8776fe7694611904bc906997e8a7e.plex.direct:32400/ (Status 0)
Oct 29, 2016 20:49:44.793 [0x7fc8053f0700] INFO - [Plex for Xbox One] [MDE] Augmented profile: { "directPlay": { "mp4": { "video": { "codecs": { "h264": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 }, "hevc": { "maxWidth": 4096, "maxHeight": 2160, "maxBitDepth": 10 }, "wmv3": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 }, "vc1": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 }, "mpeg4": { "maxWidth": 4096, "maxHeight": 2160, "maxBitDepth": 10 } } }, "audio": { "codecs": { "aac": { "maxChannels": 6 }, "ac3": { "maxChannels": 6 }, "eac3": { "maxChannels": 6 }, "mp3": { "maxChannels": 2 } } } }, "mkv": { "video": { "codecs": { "h264": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 }, "hevc": { "maxWidth": 4096, "maxHeight": 2160, "maxBitDepth": 10 }, "wmv3": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 }, "vc1": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 }, "mpeg4": { "maxWidth": 4096, "maxHeight": 2160, "maxBitDepth": 10 } } }, "audio": { "codecs": { "aac": { "maxChannels": 6 }, "ac3": { "maxChannels": 6 }, "eac3": { "maxChannels": 6 }, "mp3": { "maxChannels": 2 }, "flac": { "maxChannels": 6 }, "alac": { "maxChannels": 6 } } } }, "mpegts": { "video": { "codecs": { "h264": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 }, "mpeg2video": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 } } }, "audio": { "codecs": { "aac": { "maxChannels": 6 }, "ac3": { "maxChannels": 6 }, "mp2": { "maxChannels": 6 } } } }, "avi": { "video": { "codecs": { "wmv3": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 }, "vc1": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 }, "mpeg4": { "maxWidth": 4096, "maxHeight": 2160, "maxBitDepth": 10 }, "msmpeg4": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 } } }, "audio": { "codecs": { "aac": { "maxChannels": 6 }, "ac3": { "maxChannels": 6 }, "mp3": { "maxChannels": 2 } } } }, "mov": { "video": { "codecs": { "h264": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 } } }, "audio": { "codecs": { "aac": { "maxChannels": 6 } } } } }, "directStream": { "video": { "codecs": { "h264": { "maxWidth": 1920, "maxHeight": 1080, "maxBitDepth": 8 }, "hevc": { "maxWidth": 4096, "maxHeight": 2160, "maxBitDepth": 10 } } }, "audio": { "codecs": { "aac": { "maxChannels": 6 }, "ac3": { "maxChannels": 6 }, "eac3": { "maxChannels": 6 } } } } }
Oct 29, 2016 20:49:44.895 [0x7fc828bff700] INFO - [Plex for Xbox One] [MDE] Starting analysis of 720 (mkv, h264, aac, 31, high)
Oct 29, 2016 20:49:45.511 [0x7fc828bff700] INFO - [Plex for Xbox One] [MDE] Finished analysis of 720 (mkv, h264, aac, 31, high)
Oct 29, 2016 20:49:45.641 [0x7fc82cbff700] INFO - [Plex for Xbox One]   canPlay: true
Oct 29, 2016 20:49:45.762 [0x7fc82abff700] INFO - [Plex for Xbox One]   canDirectPlay: true
Oct 29, 2016 20:49:45.882 [0x7fc82bbff700] INFO - [Plex for Xbox One]   canDirectStreamVideo: true
Oct 29, 2016 20:49:46.011 [0x7fc8053f0700] INFO - [Plex for Xbox One]   canDirectStreamAudio: true
Oct 29, 2016 20:49:46.127 [0x7fc828bff700] INFO - [Plex for Xbox One]   bitrate: 3298
Oct 29, 2016 20:49:46.234 [0x7fc82cbff700] INFO - [Plex for Xbox One]   videoResolution: 720
Oct 29, 2016 20:49:46.353 [0x7fc82abff700] INFO - [Plex for Xbox One] [PDE] Player decision
Oct 29, 2016 20:49:46.491 [0x7fc82bbff700] INFO - [Plex for Xbox One]   Player: html
Oct 29, 2016 20:49:46.609 [0x7fc829bff700] INFO - [Plex for Xbox One]   Protocol: http
Oct 29, 2016 20:49:46.735 [0x7fc828bff700] INFO - [Plex for Xbox One]   Direct Play: true
Oct 29, 2016 20:49:49.847 [0x7fc82bbff700] INFO - [Plex for Xbox One] [Transcoder] Video (decision) options
Oct 29, 2016 20:49:49.964 [0x7fc828bff700] INFO - [Plex for Xbox One]   hasMDE: 1
Oct 29, 2016 20:49:50.089 [0x7fc82fbff700] INFO - [Plex for Xbox One]   path: http://127.0.0.1:32400/library/metadata/386804
Oct 29, 2016 20:49:50.264 [0x7fc82dbff700] INFO - [Plex for Xbox One]   mediaIndex: 0
Oct 29, 2016 20:49:50.406 [0x7fc82bbff700] INFO - [Plex for Xbox One]   partIndex: 0
Oct 29, 2016 20:49:50.595 [0x7fc827bff700] INFO - [Plex for Xbox One]   protocol: hls
Oct 29, 2016 20:49:50.982 [0x7fc830bff700] INFO - [Plex for Xbox One]   offset: 0
Oct 29, 2016 20:49:51.408 [0x7fc82cbff700] INFO - [Plex for Xbox One]   fastSeek: 1
Oct 29, 2016 20:49:51.586 [0x7fc827bff700] INFO - [Plex for Xbox One]   directPlay: 1
Oct 29, 2016 20:49:51.835 [0x7fc82cbff700] INFO - [Plex for Xbox One]   directStream: 1
Oct 29, 2016 20:49:51.968 [0x7fc82abff700] INFO - [Plex for Xbox One]   subtitleSize: 100
Oct 29, 2016 20:49:52.077 [0x7fc82ebff700] INFO - [Plex for Xbox One]   audioBoost: 100
Oct 29, 2016 20:49:52.213 [0x7fc8053f0700] INFO - [Plex for Xbox One]   location: wan
Oct 29, 2016 20:49:52.356 [0x7fc82bbff700] INFO - [Plex for Xbox One]   session: i483scoqj8id
Oct 29, 2016 20:49:52.471 [0x7fc828bff700] INFO - [Plex for Xbox One]   X-Plex-Session-Identifier: 98oo3hqfsj88
Oct 29, 2016 20:49:52.585 [0x7fc82dbff700] INFO - [Plex for Xbox One]   subtitles: burn
Oct 29, 2016 20:49:52.700 [0x7fc82dbff700] INFO - [Plex for Xbox One] [Player] Load
Oct 29, 2016 20:49:52.838 [0x7fc82bbff700] INFO - [Plex for Xbox One]   URL: https://98-173-155-67.cbe8776fe7694611904bc906997e8a7e.plex.direct:32400/library/parts/943571/1375845488/file.mkv?X-Plex-Session-Identifier=98oo3hqfsj88&X-Plex-Client-Identifier=%22h49llertiudi%22&X-Plex-Product=Plex%20for%20Xbox%20One&X-Plex-Device=Xbox%20One&X-Plex-Platform=Xbox%20One&X-Plex-Platform-Version=10.0&X-Plex-Version=1.8.0&X-Plex-Device-Name=XboxOne&X-Plex-Provides=player&X-Plex-Client-Capabilities=videoDecoders%3Dh264%7Bprofile%3Ahigh%26resolution%3A1080%7D%3BaudioDecoders%3Daac%7Bchannels%3A6%7D%2Cac3%7Bchannels%3A6%7D%2Ceac3%7Bchannels%3A6%7D&X-Plex-Accept-Language=en&X-Plex-Token=xxxxxxxx
Oct 29, 2016 20:49:52.931 [0x7fc8053f0700] INFO - [Plex for Xbox One]   Autoplay: true
Oct 29, 2016 20:49:53.032 [0x7fc827bff700] INFO - [Plex for Xbox One]   Offset: 0
Oct 29, 2016 20:49:53.136 [0x7fc82abff700] INFO - [Plex for Xbox One] [Player] setting src attribute https://XX-XXX-XXX-67.cbe8776fe7694611904bc906997e8a7e.plex.direct:32400/library/parts/943571/1375845488/file.mkv?X-Plex-Session-Identifier=98oo3hqfsj88&X-Plex-Client-Identifier=%22h49llertiudi%22&X-Plex-Product=Plex%20for%20Xbox%20One&X-Plex-Device=Xbox%20One&X-Plex-Platform=Xbox%20One&X-Plex-Platform-Version=10.0&X-Plex-Version=1.8.0&X-Plex-Device-Name=XboxOne&X-Plex-Provides=player&X-Plex-Client-Capabilities=videoDecoders%3Dh264%7Bprofile%3Ahigh%26resolution%3A1080%7D%3BaudioDecoders%3Daac%7Bchannels%3A6%7D%2Cac3%7Bchannels%3A6%7D%2Ceac3%7Bchannels%3A6%7D&X-Plex-Accept-Language=en&X-Plex-Token=xxxxxxxx
Oct 29, 2016 20:49:53.254 [0x7fc829bff700] INFO - [Plex for Xbox One] [Player] Playback is ready

Here’s what to go get http://127.0.0.1:32400/library/metadata/386804?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx

It’s all contained in the list line (library/parts/137584......./file.mkv)

15

This is what I get:

<MediaContainer size="1" allowSync="1" identifier="com.plexapp.plugins.library" librarySectionID="2" librarySectionTitle="TV Shows" librarySectionUUID="407bd660-687b-45f6-916f-822d01f88ffa" mediaTagPrefix="/system/bundle/media/flags/" mediaTagVersion="1477343825"> <Video ratingKey="386804" key="/library/metadata/386804" parentRatingKey="386706" grandparentRatingKey="386705" guid="com.plexapp.agents.thetvdb://259972/1/9?lang=en" librarySectionID="2" type="episode" title="The Time Traveler's Pig" titleSort="Time Traveler's Pig" grandparentKey="/library/metadata/386705" parentKey="/library/metadata/386706" grandparentTitle="Gravity Falls" contentRating="TV-Y7" summary="Dipper wants to correct a mistake he made in the past with assistance from a time machine. Mabel is overjoyed when she wins a pet pig at a fair." index="9" parentIndex="1" rating="9.0" year="2012" thumb="/library/metadata/386804/thumb/1471835237" art="/library/metadata/386705/art/1471835239" parentThumb="/library/metadata/386706/thumb/1471835239" grandparentThumb="/library/metadata/386705/thumb/1471835239" grandparentArt="/library/metadata/386705/art/1471835239" grandparentTheme="/library/metadata/386705/theme/1471835239" duration="1358869" originallyAvailableAt="2012-08-24" addedAt="1471833387" updatedAt="1471835237" chapterSource=""> <Media videoResolution="720" id="941506" duration="1358869" bitrate="3298" width="1280" height="718" aspectRatio="1.78" audioChannels="2" audioCodec="aac" videoCodec="h264" container="mkv" videoFrameRate="24p" audioProfile="lc" videoProfile="high"> <Part id="943571" key="/library/parts/943571/1375845488/file.mkv" duration="1358869" file="/mount/media/TV Shows/Gravity Falls/Season 1/Gravity Falls - S01E09 - The Time Traveler's Pig WEBDL-720p.mkv" size="560151844" audioProfile="lc" container="mkv" deepAnalysisVersion="1" requiredBandwidths="4818,3872,3601,3601,3601,3601,3601,3601" videoProfile="high"> <Stream id="1860301" streamType="1" default="1" codec="h264" index="1" bitrate="3298" language="English" languageCode="eng" bitDepth="8" cabac="0" chromaSubsampling="4:2:0" codecID="V_MPEG4/ISO/AVC" colorRange="tv" colorSpace="bt709" duration="1358859" frameRate="23.976" frameRateMode="cfr" hasScalingMatrix="1" height="718" level="31" pixelFormat="yuv420p" profile="high" refFrames="2" requiredBandwidths="4656,3713,3456,3456,3456,3456,3456,3456" scanType="progressive" width="1280"/> <Stream id="1860300" streamType="2" selected="1" default="1" codec="aac" index="0" channels="2" language="English" languageCode="eng" audioChannelLayout="stereo" codecID="A_AAC" duration="1358869" profile="lc" requiredBandwidths="152,152,152,152,152,152,152,152" samplingRate="48000"/> </Part> </Media> <Director id="71933" tag="Joe Pitt"/> <Director id="71941" tag="Aaron Springer"/> <Writer id="71935" tag="Aury Wallington"/> <Writer id="71857" tag="Alex Hirsch"/> </Video> </MediaContainer>

16

When I play Gravity Falls Episode 9 referenced above, it plays just fine on (plex chrome) at least.

17

Also, that shows at 8:49pm last night but the errors were all around midnight. It also looks like they watched the full thing:

18

Do you have the time to clear the logs and play it again? See if you can create the log file entries? If they are just spamming the log, that’s one thing and I’ll get that taken care of right away.

19

Yes, I can clear the logs and play it again no problem. I did talk to the person that was watching it and she said it played all the way through with no problems at all.

As a side note, I just found out that on that login (locally managed user) they were watching multiple things. Would that cause a problem?

Also, do I need to play it on an XB-1 or anything?

20

Watching multiple things won’t be a problem provided they didn’t bounce around through 60+ different things within a 2-minute window (default linux socket connection close time)

I would like to rule out the XB-1. If it can be ruled out, then we’ve reduced this to the XB-1 - PMS communications as the reason for the lockup (it was monopolizing the PMS framework and database)

Where I’m headed in my diagnosis is what I think is a race condition or ‘handshake of death’ (both grab hold and neither lets go). I need to figure out which it is.