There was a problem playing this item

plex-web

#1

Video's won't play anymore via Plex Web App since update to PMS 1.5.2.3557 running on Ubuntu Linux 4.4.0-67-generic #88-Ubuntu SMP Wed Mar 8 16:34:45 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

When clicking on play after some time the error "There was a problem playing this item" appears.
Same content using iPhone, iPad, or android device runs fine.

In pmsserver log I see:

Mar 30, 2017 12:00:42.001 [0x7effaeffa700] ERROR - [Transcoder] [eac3_eae @ 0x229c6a0] EAE timeout! EAE not running, or wrong folder? Could not read '/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/EasyAudioEncoder/Convert to WAV (to 8ch or less)/265olkx393f7k3h9fi30vd3w_126565-1-7.wav'
Mar 30, 2017 12:00:42.002 [0x7effcfbff700] ERROR - [Transcoder] [eac3_eae @ 0x229c6a0] error reading output
Mar 30, 2017 12:00:42.002 [0x7effc13fe700] ERROR - [Transcoder] Error while decoding stream #0:1: Input/output error

Rights on that directory are 777 and rights on files are 666, user and group are plex which the pms also runs under.
The file "sksvncsaa1mtvw3husvqfkc1_125043-1-35.wav" doesn't exist.

Log:

Mar 30, 2017 12:00:39.772 [0x7effc13fe700] DEBUG - Request: [10.0.0.15:55971 (Allowed Network)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=1&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (13 live) TLS GZIP Signed-in Token (donald@flissinger.com)
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * Host => 10-0-0-32.cdf241c0276440a19c096ec69c251111.plex.direct:32400
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * Connection => keep-alive
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * Accept => text/plain, */*; q=0.01
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * Origin => https://app.plex.tv
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * Accept-Language => en
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * User-Agent => Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.110 Safari/537.36
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * DNT => 1
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * Referer => https://app.plex.tv/web/app
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * Accept-Encoding => gzip, deflate, sdch, br
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * X-Plex-Client-Identifier => 9fc63a10-87ee-47c5-8bf3-a264b97a9609
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * X-Plex-Device => Windows
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * X-Plex-Device-Name => Plex Web (Chrome)
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * X-Plex-Device-Screen-Resolution => 1920x974,1920x1080
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * X-Plex-Platform => Chrome
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * X-Plex-Platform-Version => 57.0
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * X-Plex-Product => Plex Web
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * X-Plex-Token => xxxxxxxxxxxxxxxxxxxx
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * X-Plex-Version => 3.2.0
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * deviceClass => pc
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * protocolCapabilities => timeline,playback,navigation,mirror,playqueues
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * protocolVersion => 1
Mar 30, 2017 12:00:39.772 [0x7effc13fe700] VERBOSE -  * timeout => 1
Mar 30, 2017 12:00:39.773 [0x7effc13fe700] VERBOSE - [IDLE] Adding (0->1) work item http_download - /player/proxy/poll?deviceClass=pc&protocolVersion=1&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1&X-Plex-Product=Plex%20Web&X-Plex-Version=3.2.0&X-Plex-Client-Identifier=9fc63a10-87ee-47c5-8bf3-a264b97a9609&X-Plex-Platform=Chrome&X-Plex-Platform-Version=57.0&X-Plex-Device=Windows&X-Plex-Device-Name=Plex%20Web%20%28Chrome%29&X-Plex-Device-Screen-Resolution=1920x974%2C1920x1080&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
Mar 30, 2017 12:00:39.773 [0x7effc13fe700] VERBOSE - [IDLE] * http_download - /player/proxy/poll?deviceClass=pc&protocolVersion=1&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1&X-Plex-Product=Plex%20Web&X-Plex-Version=3.1.1&X-Plex-Client-Identifier=5ljhuc826mcaq6pb63s628olxr&X-Plex-Platform=Chrome&X-Plex-Platform-Version=57.0&X-Plex-Device=Windows&X-Plex-Device-Name=Plex%20Web%20%28Chrome%29&X-Plex-Device-Screen-Resolution=1920x974%2C1920x1080&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx - 1 active item(s)
Mar 30, 2017 12:00:39.773 [0x7effc13fe700] VERBOSE - [IDLE] * http_download - /player/proxy/poll?deviceClass=pc&protocolVersion=1&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1&X-Plex-Product=Plex%20Web&X-Plex-Version=3.2.0&X-Plex-Client-Identifier=9fc63a10-87ee-47c5-8bf3-a264b97a9609&X-Plex-Platform=Chrome&X-Plex-Platform-Version=57.0&X-Plex-Device=Windows&X-Plex-Device-Name=Plex%20Web%20%28Chrome%29&X-Plex-Device-Screen-Resolution=1920x974%2C1920x1080&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx - 1 active item(s)
Mar 30, 2017 12:00:39.773 [0x7effc13fe700] VERBOSE - [IDLE] * http_download - /video/:/transcode/universal/start?hasMDE=1&path=%2Flibrary%2Fmetadata%2F264121&mediaIndex=0&partIndex=0&protocol=http&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=lan&session=265olkx393f7k3h9fi30vd3w&offset=0&subtitles=burn&copyts=1&Accept-Language=en&X-Plex-Session-Identifier=cmjqgr2d138co4xxw77kaa7i&X-Plex-Chunked=1&X-Plex-Product=Plex%20Web&X-Plex-Version=3.2.0&X-Plex-Client-Identifier=9fc63a10-87ee-47c5-8bf3-a264b97a9609&X-Plex-Platform=Chrome&X-Plex-Platform-Version=57.0&X-Plex-Device=Windows&X-Plex-Device-Name=Plex%20Web%20%28Chrome%29&X-Plex-Device-Screen-Resolution=1920x974%2C1920x1080&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx - 1 active item(s)
Mar 30, 2017 12:00:39.773 [0x7effc13fe700] VERBOSE - [IDLE] * transcoder - 265olkx393f7k3h9fi30vd3w - 1 active item(s)
Mar 30, 2017 12:00:39.773 [0x7effc13fe700] DEBUG - Beginning read from two-way stream.
Mar 30, 2017 12:00:39.847 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:39.947 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:40.047 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:40.147 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:40.248 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:40.348 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:40.448 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:40.548 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:40.649 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:40.749 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:40.849 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:40.949 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:41.049 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:41.149 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:41.250 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:41.350 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:41.450 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:41.550 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:41.650 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:41.751 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:41.851 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:41.951 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:42.001 [0x7effaeffa700] ERROR - [Transcoder] [eac3_eae @ 0x229c6a0] EAE timeout! EAE not running, or wrong folder? Could not read '/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/EasyAudioEncoder/Convert to WAV (to 8ch or less)/265olkx393f7k3h9fi30vd3w_126565-1-7.wav'
Mar 30, 2017 12:00:42.002 [0x7effcfbff700] ERROR - [Transcoder] [eac3_eae @ 0x229c6a0] error reading output
Mar 30, 2017 12:00:42.002 [0x7effc13fe700] ERROR - [Transcoder] Error while decoding stream #0:1: Input/output error
Mar 30, 2017 12:00:42.003 [0x7effd23fe700] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Mar 30, 2017 12:00:42.003 [0x7effd23fe700] DEBUG - Auth: Came in with the master token, authorization succeeded.
Mar 30, 2017 12:00:42.003 [0x7effaeffa700] DEBUG - Request: [127.0.0.1:56474 (Loopback)] PUT /video/:/transcode/session/265olkx393f7k3h9fi30vd3w/progress?progress=0.1&size=-22&speed=0.2&remaining=15464 (14 live) Signed-in Token (donald@flissinger.com)
Mar 30, 2017 12:00:42.003 [0x7effaeffa700] VERBOSE -  * User-Agent => Lavf/57.57.100
Mar 30, 2017 12:00:42.003 [0x7effaeffa700] VERBOSE -  * Accept => */*
Mar 30, 2017 12:00:42.003 [0x7effaeffa700] VERBOSE -  * Range => bytes=0-
Mar 30, 2017 12:00:42.003 [0x7effaeffa700] VERBOSE -  * Connection => close
Mar 30, 2017 12:00:42.003 [0x7effaeffa700] VERBOSE -  * Host => 127.0.0.1:32400
Mar 30, 2017 12:00:42.003 [0x7effaeffa700] VERBOSE -  * Icy-MetaData => 1
Mar 30, 2017 12:00:42.003 [0x7effaeffa700] VERBOSE -  * X-Plex-Token => xxxxxxxxxxxxxxxxxxxx
Mar 30, 2017 12:00:42.004 [0x7effaeffa700] VERBOSE -  * progress => 0.1
Mar 30, 2017 12:00:42.004 [0x7effaeffa700] VERBOSE -  * remaining => 15464
Mar 30, 2017 12:00:42.004 [0x7effaeffa700] VERBOSE -  * size => -22
Mar 30, 2017 12:00:42.004 [0x7effaeffa700] VERBOSE -  * speed => 0.2
Mar 30, 2017 12:00:42.005 [0x7effaeffa700] DEBUG - We want 60 seconds ahead, last returned was -1.000000 and max is -1.000000.
Mar 30, 2017 12:00:42.005 [0x7effaeffa700] DEBUG - It took 0.0 sec to serialize a list with 0 elements.
Mar 30, 2017 12:00:42.005 [0x7effd23fe700] DEBUG - Completed: [127.0.0.1:56474] 206 PUT /video/:/transcode/session/265olkx393f7k3h9fi30vd3w/progress?progress=0.1&size=-22&speed=0.2&remaining=15464 (14 live) 1ms 326 bytes
Mar 30, 2017 12:00:42.051 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:42.151 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:42.252 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:42.352 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:42.452 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:42.552 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:42.653 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:42.753 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:42.853 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:42.953 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:43.054 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:43.154 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:43.254 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:43.354 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:43.455 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:43.555 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:43.655 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:43.755 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:43.855 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:43.956 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:44.056 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:44.156 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:44.256 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:44.356 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:44.457 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:44.557 [0x7effd23fe700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...
Mar 30, 2017 12:00:44.657 [0x7effd2bff700] VERBOSE - [TranscodeOutputStream] Waiting 100ms for more data...

How to debug?

Regards,
Donald.


#2

Same here, Docker container on FreeNAS Corral.


#3

Same here. 1.5.1 and 1.5.2 on Docker container on FreeNAS Corral. Doesn’t seem to happen to everything. Only MKV files and only on Plex Web. I tried the phone app and it works fine. I also tried using handbrake to convert it from:
MKV with H.264 encoding and AC3 audio to an MP4 file with the same encoding and audio format. That fixed the problem as well.


#4

I found the answer to this question elsewhere in the forum. It has to do with transcoding on a network share, which is how docker containers mount the /transcode directly from a dataset. Here are some instructions for a workaround until 1.5.3 comes out where they (in theory) have fixed this.


#5

Thanks for your feedback, but I’m not running docker and I’m not transcoding on a Network Share, so I think I’m having another problem…


#6

I found my problem! Due to the huge amount of Movies, Pictures, Tvshows and Movies several other errors showed up in the pms.log which I never noticed:

ERROR - [Notify] Failed to add watch for /mnt/donald/Pictures/iPhoto Library.migratedphotolibrary/Database/Versions/2014/10/01/20141001-121115/INUoTXcWQTKpV7m7KfRApA (28: No space left on device)

But there was plenty space available.

I added fs.inotify.max_user_watches=100000 to /etc/sysctl.conf and problem seems to be fixed now.

So it had nothing to do with upgrade to 1.5.0 or 1.5.1, problem was always there, but noticed it since update.


#7

@donald@flissinger.com said:
I found my problem! Due to the huge amount of Movies, Pictures, Tvshows and Movies several other errors showed up in the pms.log which I never noticed:

ERROR - [Notify] Failed to add watch for /mnt/donald/Pictures/iPhoto Library.migratedphotolibrary/Database/Versions/2014/10/01/20141001-121115/INUoTXcWQTKpV7m7KfRApA (28: No space left on device)

But there was plenty space available.

I added fs.inotify.max_user_watches=100000 to /etc/sysctl.conf and problem seems to be fixed now.

So it had nothing to do with upgrade to 1.5.0 or 1.5.1, problem was always there, but noticed it since update.

Can’t thank you enough, I had this issue on a synology NAS and that solved it !


#8

@donald@flissinger.com said:
I found my problem! Due to the huge amount of Movies, Pictures, Tvshows and Movies several other errors showed up in the pms.log which I never noticed:

ERROR - [Notify] Failed to add watch for /mnt/donald/Pictures/iPhoto Library.migratedphotolibrary/Database/Versions/2014/10/01/20141001-121115/INUoTXcWQTKpV7m7KfRApA (28: No space left on device)

But there was plenty space available.

I added fs.inotify.max_user_watches=100000 to /etc/sysctl.conf and problem seems to be fixed now.

So it had nothing to do with upgrade to 1.5.0 or 1.5.1, problem was always there, but noticed it since update.

Great catch! Fixed my issue! Appreciate you sharing this answer with us!
B)


#9

BTW, FreeNAS corral is defunct. They’ve called of the devchain and you should revert back to 9.10.U2.

Care with premissions while you do it. Do not use Corral, unless you are happy with it all. Because it wont see any updates.

They will continue with FreeNAS 11 later this year.


#10

If anyone has trouble with getting the solution of adding fs.inotify.max_user_watches=10000 to /etc/sysctl.conf, try running sudo sysctl fs.inotify.max_user_watches=32768.


#11

This is still needed, which is no problem and I understand why plex can’t do anything about this (for people running outside of dockers that is). I was just wondering if this would be persistent accross docker updates? I would assume so considering it’s an os level file and not plex related.

Is there any chance we can increase this value in the official docker by default? Snooping around for a fix is an issue and I feel people less technologically minded would rather give up…