PS4 Plex App responds with "video did not start playing in time" for videos.

Plex Players Gaming Consoles
1

Plex Media Server v0.9.12.8 (current)

Playback to PS4 works fine for some videos, not for others. The latest failed play attempt from PS4 produced the following log file. I can stream this same video file fine to the IoS Plex App (v4.0). Please help me.

Plex Media Server.log extract for failed PS4 play attempt:

Aug 12, 2015 14:54:07:552 [10656] DEBUG - Request: [192.168.1.6:59872] OPTIONS /playQueues?type=video&uri=library%3A%2F%2F92828136-ba6d-42ea-a495-bf5e432a9db3%2Fitem%2F%252Flibrary%252Fmetadata%252F371&shuffle=0&X-Plex-No-Cache=14394069371703252 (3 live) GZIP
Aug 12, 2015 14:54:07:554 [6256] DEBUG - Completed: [192.168.1.6:59872] OPTIONS /playQueues?type=video&uri=library%3A%2F%2F92828136-ba6d-42ea-a495-bf5e432a9db3%2Fitem%2F%252Flibrary%252Fmetadata%252F371&shuffle=0 (3 live) GZIP 3ms 541 bytes 200
Aug 12, 2015 14:54:07:579 [6468] DEBUG - Request: [192.168.1.6:50284] POST /playQueues?type=video&uri=library%3A%2F%2F92828136-ba6d-42ea-a495-bf5e432a9db3%2Fitem%2F%252Flibrary%252Fmetadata%252F371&shuffle=0&X-Plex-No-Cache=14394069371703252 (3 live) GZIP
Aug 12, 2015 14:54:07:581 [6468] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 12, 2015 14:54:07:581 [6468] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 12, 2015 14:54:07:586 [6468] DEBUG - PlayQueue: 0 generated IDs compressed down to a 2 byte blob.
Aug 12, 2015 14:54:07:595 [6468] DEBUG - PlayQueue: Start index: 0 End index: 0 Count: 1
Aug 12, 2015 14:54:07:598 [6468] DEBUG - PlayQueue: 1 generated IDs compressed down to a 24 byte blob.
Aug 12, 2015 14:54:07:602 [6468] DEBUG - PlayQueue: Added 1 items in 0.0 sec.
Aug 12, 2015 14:54:07:614 [6468] DEBUG - We’re going to try to auto-select an audio stream for account 1.
Aug 12, 2015 14:54:07:614 [6468] DEBUG - Selecting best audio stream for part ID 1113 (autoselect: 0 language: en)
Aug 12, 2015 14:54:07:614 [6468] DEBUG - Audio Stream: 2193, Subtitle Stream: -1
Aug 12, 2015 14:54:07:615 [6468] DEBUG - It took 0.0 sec to serialize a list with 1 elements.
Aug 12, 2015 14:54:07:616 [6256] DEBUG - Completed: [192.168.1.6:50284] POST /playQueues?type=video&uri=library%3A%2F%2F92828136-ba6d-42ea-a495-bf5e432a9db3%2Fitem%2F%252Flibrary%252Fmetadata%252F371&shuffle=0 (3 live) GZIP 37ms 2208 bytes 200
Aug 12, 2015 14:54:07:681 [10656] DEBUG - Request: [192.168.1.6:50284] OPTIONS /playQueues/53?X-Plex-No-Cache=14394069373393257 (3 live) GZIP
Aug 12, 2015 14:54:07:682 [6260] DEBUG - Completed: [192.168.1.6:50284] OPTIONS /playQueues/53 (3 live) GZIP 0ms 541 bytes 200 (pipelined: 2)
Aug 12, 2015 14:54:07:788 [6468] DEBUG - Request: [192.168.1.6:57054] GET /playQueues/53?X-Plex-No-Cache=14394069373393257 (3 live) GZIP
Aug 12, 2015 14:54:07:789 [6468] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 12, 2015 14:54:07:790 [6468] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 12, 2015 14:54:07:792 [6468] DEBUG - PlayQueue: total generated: 1, before cursor: 0, after cursor: 0
Aug 12, 2015 14:54:07:792 [6468] DEBUG - PlayQueue: No need to refresh, active window is operational.
Aug 12, 2015 14:54:07:806 [6468] DEBUG - We’re going to try to auto-select an audio stream for account 1.
Aug 12, 2015 14:54:07:807 [6468] DEBUG - Selecting best audio stream for part ID 1113 (autoselect: 0 language: en)
Aug 12, 2015 14:54:07:808 [6468] DEBUG - Audio Stream: 2193, Subtitle Stream: -1
Aug 12, 2015 14:54:07:808 [6468] DEBUG - It took 0.0 sec to serialize a list with 1 elements.
Aug 12, 2015 14:54:07:810 [6256] DEBUG - Completed: [192.168.1.6:57054] GET /playQueues/53 (3 live) GZIP 22ms 2208 bytes 200
Aug 12, 2015 14:54:07:886 [10656] DEBUG - Request: [192.168.1.6:57054] GET /photo/:/transcode?url=http%3A%2F%2F127.0.0.1%3A32400%2Flibrary%2Fmetadata%2F371%2Fthumb%2F1439163577%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx&width=150&height=225&minSize=1&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx (3 live) GZIP
Aug 12, 2015 14:54:07:888 [10656] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 12, 2015 14:54:07:888 [10656] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 12, 2015 14:54:07:890 [10656] DEBUG - Photo transcoder: Request for url [127.0.0.1:32400/library/metadata/371/thumb/1439163577?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx] (is local: 1 upscaled: 0)
Aug 12, 2015 14:54:07:893 [10656] DEBUG - Content-Length of C:\Users\pkavitz\AppData\Local\Plex Media Server\Cache\PhotoTranscoder\3e\3e2bdc288b7d3480ac6b03da18704a682371c13c.jpg is 11414.
Aug 12, 2015 14:54:07:893 [6468] DEBUG - Request: [192.168.1.6:59296] OPTIONS /library/metadata/371?X-Plex-No-Cache=14394069375613280&checkFiles=1 (4 live) GZIP
Aug 12, 2015 14:54:07:895 [6256] DEBUG - Completed: [192.168.1.6:59296] OPTIONS /library/metadata/371 (4 live) GZIP 1ms 541 bytes 200
Aug 12, 2015 14:54:07:895 [6260] DEBUG - Completed: [192.168.1.6:57054] GET /photo/:/transcode?url=http%3A%2F%2F127.0.0.1%3A32400%2Flibrary%2Fmetadata%2F371%2Fthumb%2F1439163577%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx&width=150&height=225&minSize=1 (4 live) GZIP 8ms 11414 bytes 200 (pipelined: 2)
Aug 12, 2015 14:54:07:988 [12056] DEBUG - Request: [192.168.1.6:57054] GET /photo/:/transcode?url=http%3A%2F%2F127.0.0.1%3A32400%2Flibrary%2Fmetadata%2F371%2Fthumb%2F1439163577%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx&width=150&height=225&minSize=1&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx (3 live) GZIP
Aug 12, 2015 14:54:07:989 [12056] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 12, 2015 14:54:07:990 [12056] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 12, 2015 14:54:07:991 [12056] DEBUG - Photo transcoder: Request for url [127.0.0.1:32400/library/metadata/371/thumb/1439163577?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx] (is local: 1 upscaled: 0)
Aug 12, 2015 14:54:07:994 [6468] DEBUG - Request: [192.168.1.6:52203] GET /library/metadata/371?X-Plex-No-Cache=14394069375613280&checkFiles=1 (4 live) GZIP
Aug 12, 2015 14:54:07:994 [12056] DEBUG - Content-Length of C:\Users\pkavitz\AppData\Local\Plex Media Server\Cache\PhotoTranscoder\3e\3e2bdc288b7d3480ac6b03da18704a682371c13c.jpg is 11414.
Aug 12, 2015 14:54:07:995 [6468] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 12, 2015 14:54:07:995 [6468] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 12, 2015 14:54:07:997 [6256] DEBUG - Completed: [192.168.1.6:57054] GET /photo/:/transcode?url=http%3A%2F%2F127.0.0.1%3A32400%2Flibrary%2Fmetadata%2F371%2Fthumb%2F1439163577%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx&width=150&height=225&minSize=1 (4 live) GZIP 9ms 11414 bytes 200 (pipelined: 3)
Aug 12, 2015 14:54:08:112 [6468] DEBUG - We’re going to try to auto-select an audio stream for account 1.
Aug 12, 2015 14:54:08:112 [6468] DEBUG - Selecting best audio stream for part ID 1113 (autoselect: 0 language: en)
Aug 12, 2015 14:54:08:112 [6468] DEBUG - Audio Stream: 2193, Subtitle Stream: -1
Aug 12, 2015 14:54:08:113 [6468] DEBUG - It took 0.0 sec to serialize a list with 1 elements.
Aug 12, 2015 14:54:08:114 [6256] DEBUG - Completed: [192.168.1.6:52203] GET /library/metadata/371 (4 live) GZIP 120ms 2227 bytes 200
Aug 12, 2015 14:54:08:198 [10656] DEBUG - Request: [192.168.1.6:52254] HEAD /library/parts/1113/file.m4v?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx (5 live)
Aug 12, 2015 14:54:08:199 [10656] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 12, 2015 14:54:08:199 [10656] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 12, 2015 14:54:08:234 [10656] DEBUG - Content-Length of Y:\Media\StoryPlex\Movies\Return of the King.m4v is 3808514033.
Aug 12, 2015 14:54:08:234 [10656] DEBUG - Completed: [192.168.1.6:52254] HEAD /library/parts/1113/file.m4v (5 live) 37ms 0 bytes 200
Aug 12, 2015 14:54:08:347 [12056] DEBUG - Request: [192.168.1.6:57997] GET /library/parts/1113/file.m4v?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx (5 live)
Aug 12, 2015 14:54:08:348 [12056] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 12, 2015 14:54:08:349 [12056] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 12, 2015 14:54:08:350 [12056] DEBUG - Request range: 0 to 2621439
Aug 12, 2015 14:54:08:380 [12056] DEBUG - Content-Length of Y:\Media\StoryPlex\Movies\Return of the King.m4v is 3808514033.
Aug 12, 2015 14:54:12:338 [6260] DEBUG - Completed: [192.168.1.6:57997] GET /library/parts/1113/file.m4v (5 live) 3995ms 2621440 bytes 200
Aug 12, 2015 14:54:12:604 [10656] DEBUG - Request: [192.168.1.6:65133] HEAD /library/parts/1113/file.m4v?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx (6 live)
Aug 12, 2015 14:54:12:605 [10656] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 12, 2015 14:54:12:605 [10656] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 12, 2015 14:54:12:650 [10656] DEBUG - Content-Length of Y:\Media\StoryPlex\Movies\Return of the King.m4v is 3808514033.
Aug 12, 2015 14:54:12:650 [10656] DEBUG - Completed: [192.168.1.6:65133] HEAD /library/parts/1113/file.m4v (6 live) 47ms 0 bytes 200
Aug 12, 2015 14:54:12:770 [6468] DEBUG - Request: [192.168.1.6:58325] GET /library/parts/1113/file.m4v?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx (6 live)
Aug 12, 2015 14:54:12:771 [6468] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 12, 2015 14:54:12:771 [6468] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 12, 2015 14:54:12:773 [6468] DEBUG - Request range: 0 to 2621439
Aug 12, 2015 14:54:12:855 [6468] DEBUG - Content-Length of Y:\Media\StoryPlex\Movies\Return of the King.m4v is 3808514033.
Aug 12, 2015 14:54:15:731 [6260] DEBUG - Completed: [192.168.1.6:58325] GET /library/parts/1113/file.m4v (6 live) 2964ms 2621440 bytes 200
Aug 12, 2015 14:54:39:640 [12056] DEBUG - Request: [192.168.1.6:52475] OPTIONS /:/timeline?ratingKey=371&key=%2Flibrary%2Fmetadata%2F371&state=stopped&playQueueItemID=53&time=0&duration=12057045&X-Plex-No-Cache=14394069693233287 (4 live) GZIP
Aug 12, 2015 14:54:39:641 [10860] DEBUG - Request: [192.168.1.6:50257] OPTIONS /:/timeline?ratingKey=371&key=%2Flibrary%2Fmetadata%2F371&state=error&playQueueItemID=53&time=0&duration=12057045&X-Plex-No-Cache=14394069693133282 (4 live) GZIP
Aug 12, 2015 14:54:39:642 [6256] DEBUG - Completed: [192.168.1.6:52475] OPTIONS /:/timeline?ratingKey=371&key=%2Flibrary%2Fmetadata%2F371&state=stopped&playQueueItemID=53&time=0&duration=12057045 (4 live) GZIP 2ms 541 bytes 200
Aug 12, 2015 14:54:39:642 [6260] DEBUG - Completed: [192.168.1.6:50257] OPTIONS /:/timeline?ratingKey=371&key=%2Flibrary%2Fmetadata%2F371&state=error&playQueueItemID=53&time=0&duration=12057045 (4 live) GZIP 1ms 541 bytes 200
Aug 12, 2015 14:54:39:727 [10860] DEBUG - Request: [192.168.1.6:64716] GET /:/timeline?ratingKey=371&key=%2Flibrary%2Fmetadata%2F371&state=error&playQueueItemID=53&time=0&duration=12057045&X-Plex-No-Cache=14394069693133282 (5 live) GZIP
Aug 12, 2015 14:54:39:728 [10860] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 12, 2015 14:54:39:728 [10860] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 12, 2015 14:54:39:729 [9884] DEBUG - Request: [192.168.1.6:51170] GET /:/timeline?ratingKey=371&key=%2Flibrary%2Fmetadata%2F371&state=stopped&playQueueItemID=53&time=0&duration=12057045&X-Plex-No-Cache=14394069693233287 (4 live) GZIP
Aug 12, 2015 14:54:39:729 [10860] DEBUG - Client [6r0xws0vdhv] reporting timeline state error, progress of 0/12057045ms for guid=, ratingKey=371 url=, key=/library/metadata/371, containerKey=, metadataId=371
Aug 12, 2015 14:54:39:730 [10860] DEBUG - [Now] User is pkavitz (ID: 1)
Aug 12, 2015 14:54:39:730 [10860] DEBUG - [Now] Device is Mystery 4 (Plex for Sony (PlayStation 4 01.17)).
Aug 12, 2015 14:54:39:730 [10860] DEBUG - [Now] Updated play state for /library/metadata/371.
Aug 12, 2015 14:54:39:730 [9884] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 12, 2015 14:54:39:730 [9884] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 12, 2015 14:54:39:730 [10248] DEBUG - Downloading document http://127.0.0.1:32400/library/metadata/371
Aug 12, 2015 14:54:39:731 [6256] DEBUG - Completed: [192.168.1.6:64716] GET /:/timeline?ratingKey=371&key=%2Flibrary%2Fmetadata%2F371&state=error&playQueueItemID=53&time=0&duration=12057045 (4 live) GZIP 4ms 231 bytes 200
Aug 12, 2015 14:54:39:731 [10248] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 12, 2015 14:54:39:731 [10248] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Aug 12, 2015 14:54:39:732 [9884] DEBUG - Client [6r0xws0vdhv] reporting timeline state stopped, progress of 0/12057045ms for guid=, ratingKey=371 url=, key=/library/metadata/371, containerKey=, metadataId=371
Aug 12, 2015 14:54:39:732 [9884] DEBUG - [Now] User is pkavitz (ID: 1)
Aug 12, 2015 14:54:39:732 [9884] DEBUG - [Now] Device is Mystery 4 (Plex for Sony (PlayStation 4 01.17)).
Aug 12, 2015 14:54:39:732 [9884] DEBUG - [Now] Updated play state for /library/metadata/371.
Aug 12, 2015 14:54:39:733 [6256] DEBUG - Completed: [192.168.1.6:51170] GET /:/timeline?ratingKey=371&key=%2Flibrary%2Fmetadata%2F371&state=stopped&playQueueItemID=53&time=0&duration=12057045 (4 live) GZIP 8ms 231 bytes 200
Aug 12, 2015 14:54:39:772 [10248] DEBUG - It took 0.0 sec to serialize a list with 1 elements.
Aug 12, 2015 14:54:39:773 [10248] DEBUG - Caching document http://127.0.0.1:32400/library/metadata/371 as ea4158edc5639c9916e6ae2ed472e2c8b6d1c3be

2

Okay, so it looks like you’re direct playing an M4V:
Aug 12, 2015 14:54:08:198 [10656] DEBUG - Request: [192.168.1.6:52254] HEAD /library/parts/1113/file.m4v?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx (5 live)

Then after about 30s (that’s our playback start timeout) the server is notified of an error:
Aug 12, 2015 14:54:39:731 [6256] DEBUG - Completed: [192.168.1.6:64716] GET /:/timeline?ratingKey=371&key=%2Flibrary%2Fmetadata%2F371&state=error&playQueueItemID=53&time=0&duration=12057045 (4 live) GZIP 4ms 231 bytes 200

So the app is trying to play a video but the device’s playback system isn’t starting playback within 30s. This is unusual but not entirely unusual. We run into videos with certain characteristics that interrupt otherwise successful PS3/4 playbacks someone routinely.

Can you post one of the M4V files which should direct play but isn’t and PM me a link? I’ll download and look at the behavior directly.

3

OK, PM link sent. Thanks for prelim diagnosis. Hope you can help.

4

@mattseeley any luck?

5

I facing this issue too. Only happen when i invite outside user into my local account. After remove than okay. Issue is certain movie unable to play, screen blank only sound could be hear.

6

@mattselley Ping! Please let me know if you can access the example video encoding I placed on Dropbox for you (link via Private Message). This remains and issue that prevents me from leveraging the Premium membership I paid for.

7

Neither resolution nor response for a week. Can I at least get a status update?

8

Same issue here - trying to play 480p .mp4 videos ripped from DVD. Got a couple to play last night by skipping ahead 30sec which seemed to get the movie going, however that does not work today.

Just set up the server last night so I could have missed some settings. My gaming PC is the host and I’m trying to stream over Wifi for now.

9

Sorry for the delay @pkavitz. Thank you for the message. I’ll test it out this week to try to hopefully recreate and understand the issue.

10

The file certainly doesn’t play on my PS4 either. While trying to generate a sample file from your video I ran into some weird output which suggests the primary video stream is encoded using the mpeg4 codec, not the h264 codec Plex Media Server reports.

The PS4 cannot play mpeg4 video codecs directly while it is configured to play some videos with h264 codecs directly. I’m following up with my transcoder colleague for help.

Also, I’m unable to the video in MediaInfo. It could be that this video is somehow encoded incorrectly, or with characteristics unexpected by some devices. This failure in particular is interesting to me as this app is usually has no issues opening similar files.

When I cause this video to transcode it plays fine. Another option is to re-encode it and make doubly sure the selected video codec is h624.

11

Wired mine direct and that fixed my issue. Must not have had enough wifi to maintain the signal.

12

@mattseeley, thanks for the insight. I will try re-encoding the video confirming h264 and retry.

13

I seem to be running into the same or similar issue. I have tested that mp4 files that are a gig or less play fine and when they start getting larger it takes longer for the movie to load or it times out.

14

Problem solution:

  • Error recurred with many different movie files with different encoding formats, so encoding was not the general issue creating the error.

Changed my PS4 network connection from 2.4Ghz Wifi to wired Ethernet and the problem vanished completely with an otherwise identical configuration… Network latency seems to masquerade as a server issue in this case.

15

Thanks to everyone who helped.