Video playback crashing

Plex Media Server NAS & Devices
,
1

Server Version#: Version 1.22.0.4163 running on QNAP NAS as qpkg
Player Version#: apple tv - 7.14.1

I am experiencing random crashes playing back media on my apple tv from nas. All devices are hardwired to the network. no wifi involved. The app on apple tv crashes back to the apple tv main menu screen

I found this critical error in my server logs I have also attached the server log dump. I plan to update to the latest plex server version this evening (didnt realize I was behind)

2021-03-24 09:59:49,760 (7f8452e6b700) :  CRITICAL (agentservice:784) - Exception notifying the media server (most recent call last):
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Plug-ins-d8c4875dd/System.bundle/Contents/Code/agentservice.py", line 782, in notify_thread
    HTTP.Request(url, cacheTime=0, immediate=True, data=xml)
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Plug-ins-d8c4875dd/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/api/networkkit.py", line 194, in Request
    method=method,
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Plug-ins-d8c4875dd/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/api/networkkit.py", line 67, in _http_request
    req = self._core.networking.http_request(url, *args, **kwargs)
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Plug-ins-d8c4875dd/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/components/networking.py", line 346, in http_request
    return HTTPRequest(self._core, url, data, h, url_cache, encoding, errors, timeout, immediate, sleep, opener, follow_redirects, method)
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Plug-ins-d8c4875dd/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/components/networking.py", line 118, in __init__
    self.load()
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Plug-ins-d8c4875dd/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/components/networking.py", line 158, in load
    f = self._opener.open(req, timeout=self._timeout)
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Python/lib/python2.7/urllib2.py", line 429, in open
    response = self._open(req, data)
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Python/lib/python2.7/urllib2.py", line 447, in _open
    '_open', req)
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Python/lib/python2.7/urllib2.py", line 407, in _call_chain
    result = func(*args)
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Python/lib/python2.7/urllib2.py", line 1228, in http_open
    return self.do_open(httplib.HTTPConnection, req)
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Python/lib/python2.7/urllib2.py", line 1201, in do_open
    r = h.getresponse(buffering=True)
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Python/lib/python2.7/httplib.py", line 1148, in getresponse
    response.begin()
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Python/lib/python2.7/httplib.py", line 448, in begin
    version, status, reason = self._read_status()
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Python/lib/python2.7/httplib.py", line 404, in _read_status
    line = self.fp.readline(_MAXLINE + 1)
  File "/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources/Python/lib/python2.7/socket.py", line 480, in readline
    data = self._sock.recv(self._rbufsize)
timeout: timed out

Plex Media Server Logs_2021-03-24_19-31-28.zip (5.3 MB)

2

Thanks for the logs.

Unfortunately, because of all the playback/transcode/sync activity, whatever event caused it to crash has fallen off the end of the log buffer (itā€™s only 50 MB deep).

Is there any known way to replicate this happening?

3

no, it seems to be random.
I updated the server about an hour ago to the latest version qpkg and it just happened again so i pulled the logs before doing anything else.

Plex Media Server Logs_2021-03-24_21-20-14.zip (5.0 MB)

4

i also pulled down the apple tv log per instructions here Apple TV Logs | Plex Support

logging.zip (1.2 MB)

6

Did you issue the shutdown?

If not, what does the QNAP system logs show?

The server was commanded to shut down. This happens either by human intervention or by QTS being triggered.

Mar 24, 2021 20:11:16.805 [0x7f73f3735700] DEBUG - [CompanionProxy] player 1bhdq3zqmc3mtvfwemus7seg was last refreshed 30 seconds ago
Mar 24, 2021 20:11:21.174 [0x7f7489ca4700] DEBUG - Shutting down with signal 15 (Terminated)
Mar 24, 2021 20:11:21.174 [0x7f7489ca4700] DEBUG - Ordered to stop server.
Mar 24, 2021 20:11:21.174 [0x7f74929ec780] DEBUG - Stopping server...
Mar 24, 2021 20:11:21.174 [0x7f74929ec780] DEBUG - HttpServer: Stopping server.
Mar 24, 2021 20:11:21.174 [0x7f7467159700] DEBUG - TranscodeJobManager: [Running] onServerShutdown
Mar 24, 2021 20:11:21.174 [0x7f7467159700] DEBUG - TranscodeJobManager: [Running] -> [Shutdown]
Mar 24, 2021 20:11:21.174 [0x7f7467159700] DEBUG - MetadataItemClusterRequestHandler: a shutdown event has been received
Mar 24, 2021 20:11:21.259 [0x7f74929ec780] DEBUG - Server stopped.
Mar 24, 2021 20:11:21.259 [0x7f74929ec780] DEBUG - NetworkService: Stopping advertisement.
Mar 24, 2021 20:11:21.259 [0x7f74929ec780] DEBUG - Killing plug-ins.
Mar 24, 2021 20:11:21.259 [0x7f7467d11700] ERROR - Network Service: Error in advertiser handle read: 125 (Operation canceled) socket=-1
Mar 24, 2021 20:11:21.278 [0x7f74929ec780] DEBUG - [com.plexapp.system] Killing.
Mar 24, 2021 20:11:21.282 [0x7f7489ca4700] WARN - JobManager: Could not find job for handle 2252
Mar 24, 2021 20:11:21.283 [0x7f74929ec780] DEBUG - ChildProcessMonitor: Waiting for Plex Tuner Service to exit.
Mar 24, 2021 20:11:21.283 [0x7f74929ec780] DEBUG - [JobRunner] Signalling job ID 3439 with 2
Mar 24, 2021 20:11:21.359 [0x7f7467d11700] INFO - Network Service: Abandoning advertise socket, it was closed.
Mar 24, 2021 20:11:21.574 [0x7f7489ca4700] DEBUG - Jobs: '/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Plex Tuner Service' exit code for process 3439 is 0 (success)
Mar 24, 2021 20:11:21.574 [0x7f7467447700] DEBUG - [ChildProcessMonitor] Plex Tuner Service exited.
Mar 24, 2021 20:11:21.578 [0x7f74929ec780] INFO - Killing process: Plex EAE Service (pid: 25346)
Mar 24, 2021 20:11:21.578 [0x7f74929ec780] DEBUG - Killing job.
Mar 24, 2021 20:11:21.578 [0x7f74929ec780] DEBUG - Signalling job ID 25346 with 9
Mar 24, 2021 20:11:21.582 [0x7f7489ca4700] DEBUG - Jobs: '/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Library/Plex Media Server/Codecs/EasyAudioEncoder-1165-linux-x86_64/EasyAudioEncoder/EasyAudioEncoder' exit code for process 25346 is -9 (signal: Killed)
Mar 24, 2021 20:11:22.078 [0x7f74929ec780] DEBUG - Killing job.

If by QTS,

How much memory is in the machine? 4GB? 8GB ?

7

I issued that server shutdown to upgrade the server software to latest. The failure happened around 21:00 just before my last message with the media server logs.

The server has 16gb of ram. antivirus is running, along with several other things but it sits at about 30% cpu and 40% ram

8

Also, thank you for your help! Here is my server info.

SERVER INFO
SERVER INFO929Ɨ158 26.6 KB

9

Thank you.

What Iā€™m seeing is the player stopped (possible crash of the app) and dropped the connection.

Mar 24, 2021 21:18:41.754 [0x7f1911cd7700] DEBUG - Subscription: There are 0 active grabs at the end.
Mar 24, 2021 21:18:41.754 [0x7f1911cd7700] DEBUG - Activity: Ended activity 2abd8230-03ec-433f-8f9e-cf0309b410ad.
Mar 24, 2021 21:18:41.754 [0x7f1911cd7700] DEBUG - Subscription: Refreshed all content in 1 ms.
Mar 24, 2021 21:18:41.815 [0x7f19429c7700] DEBUG - Failed to stream media, client probably disconnected after 1426669568 bytes: 104 - Connection reset by peer
Mar 24, 2021 21:18:41.815 [0x7f19429c7700] DEBUG - Completed after connection close: [192.168.1.208:49273] 206 GET /library/parts/191987/1615212862/file.mkv (5 live) TLS 2443618ms 1426669568 bytes (range: bytes=6144-) 
Mar 24, 2021 21:18:43.646 [0x7f19426d9700] DEBUG - handleStreamWrite code 104: Connection reset by peer
Mar 24, 2021 21:18:43.646 [0x7f19426d9700] DEBUG - NotificationStream: Removing because of error
Mar 24, 2021 21:18:43.671 [0x7f19426d9700] DEBUG - Completed after connection close: [192.168.1.208:62665] 200 GET /:/eventsource/notifications (2 live) TLS GZIP 2570067ms 496294 bytes (pipelined: 1)
Mar 24, 2021 21:19:01.154 [0x7f19426d9700] DEBUG - Auth: authenticated user 1 as hansolosays

Looking at the player (AppleTV), I am NOT the best at understanding tvOS .

The closest time stamp I could find of any error is here.
Which makes more sense? Server log or player log ?

2021/03/24 19:29:19.124 (386 MB) (1131943) šŸ”§ PMKMPVVideoPlayer.m:896 | event: playback-restart
2021/03/24 19:29:19.124 (386 MB) (1131943) šŸ”§ PMKMPVClient.m:494 | [cplayer] v: playback restart complete @ 70.320000
2021/03/24 19:29:19.129 (387 MB) (1131785) šŸ”§ PMKAppEventMonitor.m:128 | [AppEventMonitor]: Playback First Frame did end 19:29:19,1290 | āš ļø This event ended before?, this shouldn't happenāš ļø
2021/03/24 19:29:19.146 (392 MB) (1132000) šŸ”§ PMKNetworkTask.m:220 | Completed [200]: 102: LOW_RIDER_NAS (a62ef04c37beca018713fbc99f2ad8ba429b0249): GET /:/timeline?bufferedTime=235&col=0&context=preplay&duration=2577568&key=/library/metadata/114889&location=lan&playQueueItemID=29896&playbackTime=0&ratingKey=114889&row=0&state=playing&time=70320&timeToFirstFrame=1
2021/03/24 19:29:19.146 (392 MB) (1131785) āž– PMKPlaybackEngine.m:650 | Received timeline response: <PMKServerTimelineResponse: 0x280cf8020>
2021/03/24 19:29:22.150 (459 MB) (1131849) šŸ”§ PMKNetworkTask.m:220 | Completed [0]: 103: LOW_RIDER_NAS (a62ef04c37beca018713fbc99f2ad8ba429b0249): GET /media/subscriptions/scheduled
2021/03/24 19:29:22.152 (459 MB) (1131948) šŸ”§ PMKNetworkTask.m:220 | Completed [0]: 104: LOW_RIDER_NAS (a62ef04c37beca018713fbc99f2ad8ba429b0249): GET /media/subscriptions?includeGrabs=1
2021/03/24 19:29:22.158 (459 MB) (1132000) šŸ”§ PMKNetworkTask.m:220 | Completed [200]: 105: LOW_RIDER_NAS (a62ef04c37beca018713fbc99f2ad8ba429b0249): GET /media/subscriptions/scheduled
2021/03/24 19:29:22.160 (459 MB) (1132005) šŸ”§ PMKNetworkTask.m:220 | Completed [200]: 106: LOW_RIDER_NAS (a62ef04c37beca018713fbc99f2ad8ba429b0249): GET /media/subscriptions?includeGrabs=1
2021/03/24 19:29:24.470 (460 MB) (1132035) šŸ”§ PMKNetworkTask.m:220 | Completed [200]: 107: LOW_RIDER_NAS (a62ef04c37beca018713fbc99f2ad8ba429b0249): GET /:/timeline?bufferedTime=435&col=0&context=preplay&duration=2577568&key=/library/metadata/114889&location=lan&playQueueItemID=29896&playbackTime=5327&ratingKey=114889&row=0&state=playing&time=75616
2021/03/24 19:29:24.471 (460 MB) (1131785) āž– PMKPlaybackEngine.m:650 | Received timeline response: <PMKServerTimelineResponse: 0x280ccb740>
10

The time stamp on the server log makes the most sense. I looked at my qnap logs as well and didnt see anything there other than my shutdown for upgrade

11

I need to get someone from the Apple team to look at this.
Iā€™m sorry that I donā€™t have the needed skills to see whatā€™s really going on and correlate that back to what the server is showing.

12

No worries. I am about to head to bed. I will check back tomorrow after work and can provide more info as needed. While the crash does not seem to be directly reproducible (certain file at certain time) it does happen regularly.

Thank you again for your help!

13

I hope they can look tomorrow but they are in a different time zone than me and I donā€™t know when theyā€™ll be making their rounds in the forum.

Iā€™ll do my best to ask them to take a look.

1 Like
14

@hansolosays

I woke to answers from both of the tvOS engineers. :slight_smile:

They have your logs and the uploaded crash reports.

The only information they ask, if itā€™s at all possible but not required,

Do you know about how long into the playback you were when it crashed?
From your logs, it didnā€™t seem like you were too far into it or am I mistaken?

15

it happened once early in playback. and it happened again maybe 40 minutes in?

16

if they can identify my device from the crash logs they will probably see many over the past few weeks as it seems to be happening more frequently

17

@hansolosays

They do have the crash reports.

In fact, they were commenting on what happened.

Reading that kind of comment is a 50/50 deal.

Either they were surprised but know how to fix it
-or-
Theyā€™re scratching their heads wondering HTH it happened in the first place.

I will try to find out. :slight_smile:

18

Ok. just let me know if there is any other info I can provide to help

19

Any updates?

20

I am having a similar issue with the latest release of plex 1.22.3.4392. Using my Apple TV causes my server to signal 15 and stop. I have a HDHomeRun and it appears to mainly crash when I watch live TV after about 30-45min. The DVR was the first library I added to this server before adding my other media files, this is a fresh server with about a day of life so far. I will try to remove the DVR guide and rebuild it to see if that stabilizes things.

I am running a Ubuntu 20.04 server VM (8c/8gb) with docker and using Linuxserver/plex for my container. My database and transcode drives are both located on SSDs as well. Everything is wired on the network.

Apr 24, 2021 09:36:15.248 [0x7f5c56623700] DEBUG - Shutting down with signal 15 (Terminated)
Apr 24, 2021 09:36:15.248 [0x7f5c56623700] DEBUG - Ordered to stop server.
Apr 24, 2021 09:36:15.248 [0x7f5c57915bc0] DEBUG - Stopping serverā€¦
Apr 24, 2021 09:36:15.248 [0x7f5c57915bc0] DEBUG - HttpServer: Stopping server.
Apr 24, 2021 09:36:15.249 [0x7f5c2f7fe700] DEBUG - TranscodeJobManager: [Running] onServerShutdown
Apr 24, 2021 09:36:15.249 [0x7f5c2f7fe700] DEBUG - TranscodeJobManager: [Running] ā†’ [Shutdown]
Apr 24, 2021 09:36:15.249 [0x7f5c2f7fe700] DEBUG - MetadataItemClusterRequestHandler: a shutdown event has been received
Apr 24, 2021 09:36:15.249 [0x7f5c57915bc0] DEBUG - Server stopped.
Apr 24, 2021 09:36:15.249 [0x7f5c57915bc0] DEBUG - NetworkService: Stopping advertisement.
Apr 24, 2021 09:36:15.249 [0x7f5c57915bc0] DEBUG - Killing plug-ins.
Apr 24, 2021 09:36:15.249 [0x7f5c2effd700] ERROR - Network Service: Error in advertiser handle read: 125 (Operation canceled) socket=-1
Apr 24, 2021 09:36:15.257 [0x7f5c57915bc0] DEBUG - [com.plexapp.agents.imdb] Killing.
Apr 24, 2021 09:36:15.261 [0x7f5c56623700] WARN - JobManager: Could not find job for handle 437
Apr 24, 2021 09:36:15.262 [0x7f5c57915bc0] DEBUG - [com.plexapp.system] Killing.
Apr 24, 2021 09:36:15.265 [0x7f5c57915bc0] DEBUG - ChildProcessMonitor: Waiting for Plex Tuner Service to exit.
Apr 24, 2021 09:36:15.265 [0x7f5c57915bc0] DEBUG - [JobRunner] Signalling job ID 388 with 2
Apr 24, 2021 09:36:15.265 [0x7f5c56623700] WARN - JobManager: Could not find job for handle 351
Apr 24, 2021 09:36:15.285 [0x7f5c56623700] DEBUG - Jobs: ā€˜/usr/lib/plexmediaserver/Plex Tuner Serviceā€™ exit code for process 388 is 0 (success)
Apr 24, 2021 09:36:15.285 [0x7f5c2e7fc700] DEBUG - [ChildProcessMonitor] Plex Tuner Service exited.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Database: Shutting down.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 0.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 1.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 2.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 3.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 4.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 5.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 6.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 7.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 8.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 9.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 10.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 11.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 12.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 13.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 14.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 15.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 16.
Apr 24, 2021 09:36:15.285 [0x7f5c57915bc0] DEBUG - Captured session 17.
Apr 24, 2021 09:36:15.349 [0x7f5c2effd700] INFO - Network Service: Abandoning advertise socket, it was closed.
Apr 24, 2021 09:36:17.954 [0x7f5c457fa700] DEBUG - Stopping file watcher for com.plexapp.system
Apr 24, 2021 09:36:19.786 [0x7f5bd97fa700] DEBUG - Stopping file watcher for com.plexapp.agents.imdb

21

Removing the DVR and adding it back did not help. Also this is now happening with local content as well. Same 30-45 min window before it crashes and I need to reboot.

Apr 24, 2021 17:33:38.126 [0x7f905fd85700] DEBUG - Shutting down with signal 15 (Terminated)

Apr 24, 2021 17:33:38.126 [0x7f905fd85700] DEBUG - Ordered to stop server.

Apr 24, 2021 17:33:38.126 [0x7f9061077bc0] DEBUG - Stopping serverā€¦

Apr 24, 2021 17:33:38.126 [0x7f9061077bc0] DEBUG - HttpServer: Stopping server.

Apr 24, 2021 17:33:38.126 [0x7f903f7fe700] DEBUG - TranscodeJobManager: [Running] onServerShutdown

Apr 24, 2021 17:33:38.126 [0x7f903f7fe700] DEBUG - TranscodeJobManager: [Running] ā†’ [Shutdown]

Apr 24, 2021 17:33:38.126 [0x7f903f7fe700] DEBUG - MetadataItemClusterRequestHandler: a shutdown event has been received

Apr 24, 2021 17:33:38.126 [0x7f9061077bc0] DEBUG - Server stopped.

Apr 24, 2021 17:33:38.126 [0x7f9061077bc0] DEBUG - NetworkService: Stopping advertisement.

Apr 24, 2021 17:33:38.126 [0x7f9061077bc0] DEBUG - Killing plug-ins.

Apr 24, 2021 17:33:38.126 [0x7f903ffff700] ERROR - Network Service: Error in advertiser handle read: 125 (Operation canceled) socket=-1

Apr 24, 2021 17:33:38.139 [0x7f9061077bc0] DEBUG - [com.plexapp.system] Killing.

Apr 24, 2021 17:33:38.142 [0x7f9061077bc0] DEBUG - ChildProcessMonitor: Waiting for Plex Tuner Service to exit.

Apr 24, 2021 17:33:38.142 [0x7f9061077bc0] DEBUG - [JobRunner] Signalling job ID 392 with 2

Apr 24, 2021 17:33:38.143 [0x7f905fd85700] WARN - JobManager: Could not find job for handle 352

Apr 24, 2021 17:33:38.161 [0x7f905fd85700] DEBUG - Jobs: ā€˜/usr/lib/plexmediaserver/Plex Tuner Serviceā€™ exit code for process 392 is 0 (success)

Apr 24, 2021 17:33:38.161 [0x7f9044ff9700] DEBUG - [ChildProcessMonitor] Plex Tuner Service exited.

Apr 24, 2021 17:33:38.161 [0x7f9061077bc0] INFO - Killing process: Plex EAE Service (pid: 605)

Apr 24, 2021 17:33:38.161 [0x7f9061077bc0] DEBUG - Killing job.

Apr 24, 2021 17:33:38.161 [0x7f9061077bc0] DEBUG - Signalling job ID 605 with 9

Apr 24, 2021 17:33:38.162 [0x7f9061077bc0] DEBUG - Database: Shutting down.

Apr 24, 2021 17:33:38.174 [0x7f905fd85700] DEBUG - Jobs: ā€˜/config/Library/Application Support/Plex Media Server/Codecs/EasyAudioEncoder-1165-linux-x86_64/EasyAudioEncoder/EasyAudioEncoderā€™ exit code for process 605 is -9 (signal: Killed)

Apr 24, 2021 17:33:38.226 [0x7f903ffff700] INFO - Network Service: Abandoning advertise socket, it was closed.

Apr 24, 2021 17:33:39.029 [0x7f9054ffb700] DEBUG - Stopping file watcher for com.plexapp.system