Repeated Crashes

General Discussions
1

Been running plex for almost 2 years no major dramas.

System: FreeNAS 9.10, with 16GB RAM

A couple of days ago, plex crashed (rare but not miles out of the ordinary) I rebooted FreeNAS, and next time I looked (about an hour later) it was down again.

Now, I had around that time gone from 9.3 to 9.10 FreeNAS, so assumed that must have something to do with it, I rebuilt all of my jails (had been meaning to anyway) and rebuilt plex using (inside a freshly created jail):
portsnap fetch extract
cd /usr/ports/multimedia/plexmediaserver-plexpass/ && make install clean
That’s fine - I restored the back up meta data and rebooted the jail. Plex came up all working - lasted only about 5 minutes before crashing again.

I had previously been running from the plugin on FreeNAS rather than building it, and I had the auto update script, which would have updated it around the time it first crashed. And the new jail obviously has the most current plex pass version. So that could be a factor.

However - in my logs I get this:
(the last few lines from the plex media server log)

Apr 23, 2016 17:12:12 [0x80b486400] WARN - NetworkServiceBrowser: Error sending out discover packet: send_to: Can't assign requested address
Apr 23, 2016 17:12:17 [0x80b486400] WARN - NetworkServiceBrowser: Error sending out discover packet: send_to: Can't assign requested address
Apr 23, 2016 17:12:17 [0x80b486400] WARN - NetworkServiceBrowser: Error sending out discover packet: send_to: Can't assign requested address
Apr 23, 2016 17:12:20 [0x80d0cd800] ERROR - Had trouble breaking X-Plex-Token
Apr 23, 2016 17:12:20 [0x80d0cd800] ERROR - ERROR: Parsing request failed.
Apr 23, 2016 17:12:20 [0x80d0cd800] DEBUG - Request: [31.127.111.255:59767] GET /photo/:/transcode?width=1024&height=1024&url=http%3A%2F%2F127.0.0.1%3A32400%2Flibrary%2Fmetadata%2F481892%2Fart%2F1454527866%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx&minSize=0&X-Plex-Token (4 live) TLS

the last few lines from the com.plexapp.agents.imdb

2016-04-23 17:10:10,145 (802406400) :  INFO (core:611) - Started plug-in
2016-04-23 17:10:10,145 (802406400) :  DEBUG (socketinterface:160) - Starting socket server
2016-04-23 17:10:10,145 (802406400) :  DEBUG (runtime:1117) - Created a thread named 'start'
2016-04-23 17:10:10,146 (802406400) :  INFO (socketinterface:184) - Socket server started on port 42313
2016-04-23 17:10:10,146 (802406400) :  INFO (pipeinterface:25) - Entering run loop
2016-04-23 17:10:10,146 (802406400) :  DEBUG (runtime:717) - Handling request GET /:/prefixes
2016-04-23 17:10:10,147 (802406400) :  DEBUG (runtime:814) - Found route matching /:/prefixes
2016-04-23 17:10:10,147 (802406400) :  DEBUG (runtime:924) - Response: [200] MediaContainer, 148 bytes
2016-04-23 17:10:10,224 (80b04c400) :  DEBUG (runtime:717) - Handling request GET /:/plugins/com.plexapp.agents.imdb/prefs
2016-04-23 17:10:10,233 (80b04c400) :  DEBUG (runtime:814) - Found route matching /:/plugins/com.plexapp.agents.imdb/prefs
2016-04-23 17:10:10,234 (80b04c400) :  WARNING (data:179) - Error decoding with simplejson, using demjson instead (this will cause a performance hit) - Expecting value: line 83 column 1 (char 1580)
2016-04-23 17:10:10,238 (80b04c400) :  DEBUG (preferences:258) - Loaded preferences from DefaultPrefs.json
2016-04-23 17:10:10,238 (80b04c400) :  DEBUG (preferences:178) - Loaded the user preferences for com.plexapp.agents.imdb
2016-04-23 17:10:10,241 (80b04c400) :  DEBUG (runtime:924) - Response: [200] MediaContainer, 1287 bytes
2016-04-23 17:12:20,930 (802406400) :  INFO (pipeinterface:87) - Stopping plug-in

and the final lines from com.plexapp.system

2016-04-23 17:11:27,033 (80b096800) :  DEBUG (networking:166) - Requesting 'http://192.168.1.53:32400/library/sections'
2016-04-23 17:11:27,037 (80b096800) :  DEBUG (networking:166) - Requesting 'http://192.168.1.53:32400/channels/all'
2016-04-23 17:11:27,039 (80f474400) :  DEBUG (peerservice:163) - Background-refreshing remote servers
2016-04-23 17:11:27,039 (80b096800) :  DEBUG (runtime:1117) - Created a thread named 'background_refresh'
2016-04-23 17:11:27,039 (80f474400) :  DEBUG (peerservice:171) - Updating servers (False/True True/True/True)
2016-04-23 17:11:27,040 (80f474400) :  DEBUG (peerservice:180) - Found 1 servers
2016-04-23 17:12:20,930 (802406400) :  INFO (pipeinterface:87) - Stopping plug-in
2016-04-23 17:15:08,504 (80d827800) :  DEBUG (runtime:1156) - Starting timed thread named 'auto_update_thread'
2016-04-23 17:15:08,545 (80d827800) :  INFO (storeservice:351) - Starting automatic update check
2016-04-23 17:15:08,545 (80d827800) :  DEBUG (runtime:1117) - Created a thread named 'remove_unavailable_agents'
2016-04-23 17:15:08,600 (80d827800) :  DEBUG (networking:166) - Requesting 'https://nine.plugins.plexapp.com/apps/all.json?frameworkVersion=2.6.3&machineIdentifier=89057bad53c55323879476f1c38e2c270f2a17fb&os=FreeBSD&osVersion=10.3-RELEASE%20%28FreeBSD%2010.3-RELEASE%20%230%201b72f49%28HEAD%29%3A%20Wed%20Apr%2013%2023%3A35%3A10%20PDT%202016%20%20%20%20%20root%40build.ixsystems.com%3A/tank/home/nightlies/CVE910/_BE/objs/tank/home/nightlies/CVE910/_BE/trueos/sys/FreeNAS.amd64%29&cpu=i386&serverVersion=0.9.16.5.1966-81a3bf0&systemRevision=81a3bf0'
2016-04-23 17:15:09,304 (80d827800) :  INFO (storeservice:490) - No beta plugins.
2016-04-23 17:15:09,310 (80d827800) :  INFO (storeservice:526) - 'WebManager' plug-in [com.plexapp.plugins.webmanager] is up to date (402fcf6e4d1ee8b4153d404708f02a2afa47ab8c)
2016-04-23 17:15:09,310 (80d827800) :  INFO (storeservice:357) - All plug-ins are up to date
2016-04-23 17:15:09,311 (80d827800) :  DEBUG (runtime:1150) - Scheduled a timed thread named 'auto_update_thread'
2016-04-23 17:15:13,590 (806193400) :  INFO (datakit:131) - Saved the dictionary file

Any guide on fixing this? As I can’t seem to make it last more than a few minutes before plex crashes again

2

Still suffering from this, plex has gone from being rock stable for me to unusable

3

why only pasting parts of logs ?
Should always attach full logs. You can zip the logs folder and attach the zip or attach the individual logs but after restarting the server to get fresh logs and recreating the problem

Would like to see what thread with identifier 0x80d0cd800 was doing prior to the token processing error - for example. The warnings on discovery packets are normal and do arise on FreeNAS. Only may impact GDM and SSDP discovery

and what time was the crash and is there a crash dmp file to go with the Plex Media Server.log for the crash

4

Sorry for the slow reply - certainly, attached is the logs folder zipped.

So for background for the logs - I re-installed today. Steps I took:

New jail (with the new jail template) on the latest FreeNAS, then the following from SSH into the jail:

pkg update && pkg upgrade -y
pkg install multimedia/plexmediaserver-plexpass
echo plexmediaserver_plexpass_enable="YES" >> /etc/rc.conf
# restarted the jail at this point
service plexmediaserver_plexpass stop
rm -Rf /mnt/Family/Jails/Plex/usr/local/plexdata-plexpass/Plex\ Media\ Server/
cp -Rip 'backuplocation' /mnt/Family/Jails/Plex/usr/local/plexdata-plexpass/Plex\ Media\ Server/
# last two lines were to copy over the data I had from my old installation - I then used ls -l to confirm the permissions were the same as before.
#I then attached the storage from FreeNAS for the media directory, as I had before
pw groupadd Family -g 1001
pw usermod plex -G Family
#Last two were to make sure plex had access to the media folder (and was what I had set it to before)
# confirmed this with tail /etc/group
#I then restarted the jail

So, i then went to plex.tv/web/ And whola Plex appeared, as before with everything I had previously, all watched unwatched etc remembered. Files were playable, all looking good.

I closed the app, informed some one else to confirm they could get on - they could, then immediately text back saying they couldn’t

Apr 26 20:09:15 freenas kernel: pid 89300 (Plex Media Server), uid 972: exited on signal 11.

I had that in my FreeNAS session, plex this time apparently lasted all of one or two minutes. Memory usage (from the reporting section of FreeNAS) had 4.4GB inactive, throughout the whole event, with some more free. No Swap space was used. And as previously mentioned plex has run very well on this system for a substantial period of time.

I am tearing my hair out a little, as I am completely clueless on diagnosing this and my Google voodoo is failing me.

5

@George51 said:
Sorry for the slow reply - certainly, attached is the logs folder zipped.

So for background for the logs - I re-installed today. Steps I took:

New jail (with the new jail template) on the latest FreeNAS, then the following from SSH into the jail:

pkg update && pkg upgrade -y
pkg install multimedia/plexmediaserver-plexpass
echo plexmediaserver_plexpass_enable="YES" >> /etc/rc.conf
# restarted the jail at this point
service plexmediaserver_plexpass stop
rm -Rf /mnt/Family/Jails/Plex/usr/local/plexdata-plexpass/Plex\ Media\ Server/
cp -Rip 'backuplocation' /mnt/Family/Jails/Plex/usr/local/plexdata-plexpass/Plex\ Media\ Server/
# last two lines were to copy over the data I had from my old installation - I then used ls -l to confirm the permissions were the same as before.
#I then attached the storage from FreeNAS for the media directory, as I had before
pw groupadd Family -g 1001
pw usermod plex -G Family
#Last two were to make sure plex had access to the media folder (and was what I had set it to before)
# confirmed this with tail /etc/group
#I then restarted the jail

So, i then went to plex.tv/web/ And whola Plex appeared, as before with everything I had previously, all watched unwatched etc remembered. Files were playable, all looking good.

I closed the app, informed some one else to confirm they could get on - they could, then immediately text back saying they couldn’t

Apr 26 20:09:15 freenas kernel: pid 89300 (Plex Media Server), uid 972: exited on signal 11.

I had that in my FreeNAS session, plex this time apparently lasted all of one or two minutes. Memory usage (from the reporting section of FreeNAS) had 4.4GB inactive, throughout the whole event, with some more free. No Swap space was used. And as previously mentioned plex has run very well on this system for a substantial period of time.

I am tearing my hair out a little, as I am completely clueless on diagnosing this and my Google voodoo is failing me.

A device / app is sending an invalid request and it is crashing the server. The tojen processing appears relevant

Apr 26, 2016 20:09:15 [0x80c03b400] ERROR - Had trouble breaking X-Plex-Toke
Apr 26, 2016 20:09:15 [0x80c03b400] ERROR - ERROR: Parsing request failed.
Apr 26, 2016 20:09:15 [0x80c03b400] DEBUG - Request: [192.168.1.1:38356] GET /photo/:/transcode?width=1024&height=1024&url=http%3A%2F%2F127.0.0.1%3A32400%2Flibrary%2Fmetadata%2F651454%2Fthumb%2F1460214490%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx&minSize=0&X-Plex-Toke (9 live) TLS

Can’t tell which device / app / plugin it is. We know it is using secure connections and came through the public IP as it appears as coming through the router gateway 192.168.1.1
It was trying to load the image for this (you could try this on the server and see what it is)
http://192.168.1.53:32400/library/metadata/651454/thumb1460214490
Media info can be seen in xml from
http://192.168.1.53:32400/library/metadata/651454
Perhaps you know who was connecting at 20:09:15 ?
The syntax of the request is wrong having X-Plex-Token and then X-Plex-Toke

Actually last time round we know it was from IP 31.127.111.255 so may be you know who that could be
Other possibility is messages being truncated on route - and I do not know about jail setup to give help with troubleshooting that. This time the request ended with X-Plex-Toke. Last time with X-Plex-Token but no token.

6

Do you have remote Roku? There were some changes recently to the token inclusion specifically for FreeNAS

7

It seems to be definitely truncation of requests and buffer size issue somewhere - because the logs also had this request

Apr 22, 2016 21:21:45 [0x80d928800] ERROR - Had trouble breaking X-Plex-Tok
Apr 22, 2016 21:21:45 [0x80d928800] ERROR - ERROR: Parsing request failed.
Apr 22, 2016 21:21:45 [0x80d928800] DEBUG - Request: [192.168.1.1:12324] GET /photo/:/transcode?width=1024&height=1024&url=http%3A%2F%2F127.0.0.1%3A32400%2Flibrary%2Fmetadata%2F651454%2Fthumb%2F1460214490%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx&minSize=0&X-Plex-Tok (11 live) TLS

So we have request ending with X-Plex-Toke and X-Plex-Tok and X-Plex-Token without the =token-string

The only time we had an IP address logged was the first one you had in your first post (31.127.111.255) . All other requests appearing as 192.168.1.1 which is the gateway address

The very last failure - the one at 20:09:15, just before this two devices were active on IPs
90.205.21.90 and 89.195.123.253. Do not know if relevant

8

@George51 The crash of Plex Media Server has now been fixed and will get included in a future release of Plex Media Server. I do not know at this stage which version it will be released in

What is needed now is to identify what is sending the malformed requests or if they are generated correctly, what is truncating them before reaching the Plex Media Server

9

@sa2000 Okay. Thank you very much for your assistance so far. So based on what you said about it possibly being a device/app with an invalid request. And what I had tried to connect after resetting the server.
I reset it, disconnect all of my devices from the server setting page, and then also disconnected the server. Then accessed plex via the ip address, reconnected it to my account, signed out on my android app, signed back in. And so far, it has been connected and stable for a couple of hours. I am away from my computer so done this on my phone and via openvpn, haven’t tested watching anything yet. But so far so good!

Pleased to see such a fast response and that a fix will be put into PMS, not sure what caused the invalid request, but I am leaning that way as the cause. Because disconnecting and reconnecting has (apparently, touch wood) fixed the issue.

10

@George51 said:
@sa2000 Okay. Thank you very much for your assistance so far. So based on what you said about it possibly being a device/app with an invalid request. And what I had tried to connect after resetting the server.
I reset it, disconnect all of my devices from the server setting page, and then also disconnected the server. Then accessed plex via the ip address, reconnected it to my account, signed out on my android app, signed back in. And so far, it has been connected and stable for a couple of hours. I am away from my computer so done this on my phone and via openvpn, haven’t tested watching anything yet. But so far so good!

Pleased to see such a fast response and that a fix will be put into PMS, not sure what caused the invalid request, but I am leaning that way as the cause. Because disconnecting and reconnecting has (apparently, touch wood) fixed the issue.

What we know is that they were from remote devices and not within the local network
If more than one device causing it then it would be some buffer truncating messages - but I don’t know anything about jail and freenas setup to say more.

11

@sa2000 So it’s been nearly 6 hours since I last restarted it. The most time by far that Plex hasn’t crashed in, I’ve tweaked the old Plex Plugin script to update Plex pass for a generic jail installation, that works, Plex seems stable again. I look forward to having the fix you mentioned included so it doesn’t crash PMS if it were to re occur. But I think we can marked this as solved, and if not I will update this thread. Thank you again.

12

I’m having the exact same issue as well!

Attached are my logs files. The error that I saw most recently is:

Apr 27, 2016 20:35:32:349 [4488] ERROR - Had trouble breaking X-Plex-Toke
Apr 27, 2016 20:35:32:349 [4488] ERROR - ERROR: Parsing request failed.
Apr 27, 2016 20:35:32:349 [4488] DEBUG - Request: [192.168.1.162:52834] GET /photo/:/transcode?width=1024&height=1024&url=http%3A%2F%2F127.0.0.1%3A32400%2Flibrary%2Fmetadata%2F147373%2Fthumb%2F1461709186%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx&minSize=0&X-Plex-Toke (4 live) TLS

Now 192.168.1.162 is my Nokia Lumia 640 XL Windows Phone. I’ve been having the server shutdown afer about 10 minutes since I applied the most recent Media Server update. I’m going to shutdown the phone and see if the crash stops.

Hope this helps! Glad to contribute to such an amazing piece of software!!

13

@SpazShark said:
I’m having the exact same issue as well!

Attached are my logs files. The error that I saw most recently is:

Apr 27, 2016 20:35:32:349 [4488] ERROR - Had trouble breaking X-Plex-Toke
Apr 27, 2016 20:35:32:349 [4488] ERROR - ERROR: Parsing request failed.
Apr 27, 2016 20:35:32:349 [4488] DEBUG - Request: [192.168.1.162:52834] GET /photo/:/transcode?width=1024&height=1024&url=http%3A%2F%2F127.0.0.1%3A32400%2Flibrary%2Fmetadata%2F147373%2Fthumb%2F1461709186%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx&minSize=0&X-Plex-Toke (4 live) TLS

Now 192.168.1.162 is my Nokia Lumia 640 XL Windows Phone. I’ve been having the server shutdown afer about 10 minutes since I applied the most recent Media Server update. I’m going to shutdown the phone and see if the crash stops.

Hope this helps! Glad to contribute to such an amazing piece of software!!

Thank you - that is good to know - that it is a windows phone. It is almost 3am where I am so going to bed but would love is the Plex for Windows app debug log file for the time when this happens together with the corresponding server log - hopefully you will find out from the Plex for Windows Phone forum how to do that

14

Thank you - that is good to know - that it is a windows phone. It is almost 3am where I am so going to bed but would love is the Plex for Windows app debug log file for the time when this happens together with the corresponding server log - hopefully you will find out from the Plex for Windows Phone forum how to do that

Ok I uninstalled Plex on the phone but will re-install tomorrow if the issue ceases to occur. I saw that the Windows Phone app was updated a few days ago so perhaps a new issue was introduced.

15

I’m having issues with my server crashing on mac has happen 3 times

16

@SpazShark said:

Thank you - that is good to know - that it is a windows phone. It is almost 3am where I am so going to bed but would love is the Plex for Windows app debug log file for the time when this happens together with the corresponding server log - hopefully you will find out from the Plex for Windows Phone forum how to do that

Ok I uninstalled Plex on the phone but will re-install tomorrow if the issue ceases to occur. I saw that the Windows Phone app was updated a few days ago so perhaps a new issue was introduced.

Do you know what version you had at the time?

17

@cutehis23satx said:
I’m having issues with my server crashing on mac has happen 3 times

Will need the crash report file and associated log - but please log a separate forum topic in the mac server forum here or the preview forum if PlexPASS Preview release - it may be different issue

see
https://support.plex.tv/hc/en-us/articles/201643703-Reporting-issues-with-Plex-Media-Server
https://support.plex.tv/hc/en-us/articles/200250417-Plex-Media-Server-Log-Files
https://support.plex.tv/hc/en-us/articles/201455336

18

Re the X-Plex-Token parsing error, the development team are unable to reproduce the problem. If either of you could enable diagnostics on the phone app and email the logs to yourself and try and get the crash and provide the logs from the phone app and the server - that would be much appreciated

See this support page for enabling Plex for Windows Phone diagnostics and emailing logs to yourself before uploading here with the server Plex Media Server.log at time of crash

https://support.plex.tv/hc/en-us/articles/202533096-Windows-Phone-Logs

19

In case tokens are showing in the plex for Windows phone logs please zip and send to me by private message and I wil to the developer

20

@sa2000 said:
Re the X-Plex-Token parsing error, the development team are unable to reproduce the problem. If either of you could enable diagnostics on the phone app and email the logs to yourself and try and get the crash and provide the logs from the phone app and the server - that would be much appreciated

See this support page for enabling Plex for Windows Phone diagnostics and emailing logs to yourself before uploading here with the server Plex Media Server.log at time of crash

https://support.plex.tv/hc/en-us/articles/202533096-Windows-Phone-Logs

Ok I’m going to see if I can get at this tonight. I was using the latest version of the phone client (can’t verify what it was as I uninstalled it but I saw the update occurred a few days ago). The issue started occurring after I took the most recent Plex Media Server update about 24 hours ago.

FYI: Every crash message that I saw (ERROR - ERROR: Parsing request failed) always involved the IP address of that phone. Since I uninstalled Plex from the Windows Phone about 16 hours ago, I haven’t had a single crash. And it was happening every 20 mins or so. So it definitely has something to do with the phone interacting with PMS specifically.

I’ll try to send the logs tonight.