Hover over the poster
You’ll see the ellipsis exposed in the lower right corner …
Click it
“Get Info”
“View XML” (left corner)
Hi chuck, didn’t want to leave you hanging.
I’m performing a massive I/O operation on my server that has taken about 30 hours so far.
Due to this, I cannot currently stream without heavy buffering, as my NAS is tied up.
I expect the operation to be done in in the next few hours, and I will be getting to your log request in the morning (about 9 hours from now)
Apologies for the delay
No rush.
I am just now recovering from a failed HDD in the QNAP.
Alright I have gotten this done.
-
XML of video (had to put in zip as xml is not authorized upload filetype)
3693.zip (1.7 KB) -
started video file, played for 2 minutes, paused, downloaded logs
Plex Media Server Logs_2021-03-05_17-25-37.zip (5.1 MB) -
Resumed until failure (happened at 22:53/26:28 of video length), downloaded logs
Plex Media Server Logs_2021-03-05_17-46-58.zip (5.1 MB) -
Went an extra step, restarted video right before the crash (22:50 was start point), continued until 23:25 when crashed again, downloaded those logs. (basically what I’ve sent before, was more for my own curiosity)
Plex Media Server Logs_2021-03-05_17-48-23.zip (5.1 MB)
All these log files seem larger than the ones I’ve sent before… im guessing its because I didn’t restart my server… In the troubleshooting page, Devs should add a "clear logs’ button to get a fresh log file lol.
I’m sorry, Your logs don’t contain those time stamps.
Are you running the system on UTC but thinking of local time?
Mar 04, 2021 22:05:03.316 [0x7fc0d77fe700] DEBUG - Subscription: Refreshed all content in 0 ms.
Mar 04, 2021 22:09:55.311 [0x7fc10a77b700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 22:14:55.312 [0x7fc10a77b700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 22:19:55.313 [0x7fc0d77fe700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 22:24:55.313 [0x7fc0d77fe700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 22:27:35.698 [0x7fc10bfff700] DEBUG - Request: [192.241.221.83:36736 (WAN)] GET / (4 live) TLS GZIP Signed-in
Mar 04, 2021 22:27:35.698 [0x7fc10bfff700] DEBUG - Completed: [192.241.221.83:36736] 401 GET / (4 live) TLS GZIP 0ms 435 bytes
Mar 04, 2021 22:29:53.485 [0x7fc10a77b700] DEBUG - Sync: uploadStatus
Mar 04, 2021 22:29:55.314 [0x7fc10a77b700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 22:30:04.128 [0x7fc06bfff700] DEBUG - Putting plug-in com.plexapp.agents.imdb to sleep.
Mar 04, 2021 22:30:04.128 [0x7fc06bfff700] DEBUG - Stopping [com.plexapp.agents.imdb].
Mar 04, 2021 22:30:04.128 [0x7fc06bfff700] DEBUG - [com.plexapp.agents.imdb] Killing.
Mar 04, 2021 22:30:04.131 [0x7fc113026700] WARN - JobManager: Could not find job for handle 81303
Mar 04, 2021 22:30:14.129 [0x7fc06bfff700] DEBUG - Stopping file watcher for com.plexapp.agents.imdb
Mar 04, 2021 22:34:55.314 [0x7fc10a77b700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 22:39:55.315 [0x7fc0d77fe700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 22:44:55.315 [0x7fc10a77b700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 22:49:55.316 [0x7fc0d77fe700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 22:54:55.316 [0x7fc0d77fe700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 22:59:53.485 [0x7fc0d77fe700] DEBUG - Sync: uploadStatus
Mar 04, 2021 22:59:55.317 [0x7fc0d77fe700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 22:59:59.576 [0x7fc0d77fe700] DEBUG - PublicAddressManager: Obtaining public address and mapping port.
Mar 04, 2021 22:59:59.576 [0x7fc10a77b700] DEBUG - PublicAddressManager: Obtaining public IP.
Mar 04, 2021 22:59:59.577 [0x7fc10a77b700] DEBUG - HTTP requesting GET http://plex.tv/pms/:/ip
Mar 04, 2021 22:59:59.853 [0x7fc10a77b700] DEBUG - HTTP 200 response from GET http://plex.tv/pms/:/ip
Mar 04, 2021 22:59:59.853 [0x7fc10a77b700] DEBUG - PublicAddressManager: Got public IP from http://plex.tv: 97.101.252.25
Mar 04, 2021 23:00:02.631 [0x7fc0d77fe700] DEBUG - Statistics: Flushing 2 expired bandwidth entries, 0 expired media entries.
Mar 04, 2021 23:00:07.913 [0x7fc10a77b700] DEBUG - NAT: UPnP, not an IGD: <http://192.168.1.1:5000/rootDesc.xml>.
Mar 04, 2021 23:00:07.913 [0x7fc10a77b700] DEBUG - NAT: UPnP, getPublicIP didn't find usable IGD.
Mar 04, 2021 23:00:08.163 [0x7fc10a77b700] WARN - NAT: PMP, got an error: Network Error.
Mar 04, 2021 23:00:08.164 [0x7fc10a77b700] DEBUG - HTTP requesting GET https://97-101-252-25.885a47b36d3c463fa73c21f034c140a9.plex.direct:32400/identity
Mar 04, 2021 23:00:08.165 [0x7fc10a77b700] ERROR - Error issuing curl_easy_perform(handle): 7
Mar 04, 2021 23:00:08.165 [0x7fc10a77b700] WARN - HTTP error requesting GET https://97-101-252-25.885a47b36d3c463fa73c21f034c140a9.plex.direct:32400/identity (7, Couldn't connect to server) (Failed to connect to 97-101-252-25.885a47b36d3c463fa73c21f034c140a9.plex.direct port 32400: Connection refused)
Mar 04, 2021 23:00:08.165 [0x7fc10a77b700] DEBUG - MyPlex: mapping state set to 'Mapped - Not Published'.
Mar 04, 2021 23:00:08.165 [0x7fc10a77b700] DEBUG - MyPlex: Last published value didn't change, we're done.
Mar 04, 2021 23:04:55.317 [0x7fc10a77b700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 23:09:55.318 [0x7fc0d77fe700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 23:14:55.318 [0x7fc10a77b700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 23:19:55.320 [0x7fc0d77fe700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 23:24:55.320 [0x7fc0d77fe700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 23:29:53.486 [0x7fc10a77b700] DEBUG - Sync: uploadStatus
Mar 04, 2021 23:29:55.321 [0x7fc10a77b700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 23:34:55.322 [0x7fc10a77b700] DEBUG - Checking if time for scheduled update
Mar 04, 2021 23:35:46.919 [0x7fc0ed7fa700] DEBUG - NetworkServiceBrowser: Parsing SSDP schema for http://192.168.1.157:9080
Mar 04, 2021 23:35:46.920 [0x7fc0ed7fa700] DEBUG - HTTP requesting GET http://192.168.1.157:9080
Mar 04, 2021 23:35:46.930 [0x7fc0ed7fa700] DEBUG - HTTP 200 response from GET http://192.168.1.157:9080
Mar 04, 2021 23:35:46.930 [0x7fc0ed7fa700] ERROR - XML: Entity: line 1:\00
I think I’m using UTC time, BUT the times i listed were actually the movie file times 
sorry for the confusion.
Which means what ?
I don’t know what time zone you’re in!
(we poor tech support types aren’t all that smart. help please? )
I get it, I’m engineering tech support myself haha.
I was trying to say that I wasn’t giving you times correlating to the logs. I don’t know what the log time was when the events happened.
I was saying that “The video crashed 22 minutes and 53 seconds into a 26 minute 28 second file”
and that I restarted the video 3 seconds before the ‘crash point’ 22 minutes 50 seconds into the video file, and then it crashed again at 23 minutes 25 seconds.
The log file is written with the machine’s local Date/Time stamp.
“26 minutes 30 seconds into a 27 minute 19 second video” means nothing to me.
I still don’t know where that when looking through 50 MB of logs spanning multiple days.
See my dilemma ?
When it fails, Look at the current time. THAT is helpful to me 
I can rerun the tests after work today if you want.
But I did do exactly as you instructed.
The log files were downloaded within 20 seconds of the crash.
Thanks. that’s enough of landmark.
I do hope you understand i’m light-heartedly joking a bit ?
It’s been a long frustrating week.
The only good thing to come of it was upgrading infrastructure so that I can handle 2.5 Gbps from my ISP (I get 1.44 Gbps now)
1 Like
Yes! I could tell, you’re good lol.
I definitely understand frustrating weeks lol. I’m on a business trip myself. The last 2 weeks was a forced quarantine on arrival, not allowed to leave my room at all. Just got out yesterday and can finally get some work done.
Also, that’s AWESOME. I get 500-600Mbps from my ISP, which is enough for my needs for now haha
I found where it occurs… SOME PEOPLE
Mar 05, 2021 17:47:54.113 [0x7f203ebbc700] DEBUG - Removed transcode data consumer, active count 1 => 0
Mar 05, 2021 17:47:54.831 [0x7f1fef7fe700] DEBUG - [Transcode] Transcoder segment range: 171 - 182 (182)
Mar 05, 2021 17:47:54.831 [0x7f1fee7fc700] DEBUG - [Transcode] Transcoder segment range: 171 - 183 (182)
Mar 05, 2021 17:47:56.525 [0x7f1fef7fe700] DEBUG - [Transcode] Transcoder segment range: 171 - 184 (183)
Mar 05, 2021 17:47:56.525 [0x7f1fee7fc700] DEBUG - [Transcode] Transcoder segment range: 171 - 184 (183)
Mar 05, 2021 17:47:58.230 [0x7f1fee7fc700] DEBUG - [Transcode] Transcoder segment range: 171 - 184 (184)
Mar 05, 2021 17:47:58.231 [0x7f1fef7fe700] DEBUG - [Transcode] Transcoder segment range: 171 - 185 (184)
Mar 05, 2021 17:47:59.949 [0x7f1feffff700] DEBUG - [Transcode] Transcoder segment range: 171 - 185 (185)
Mar 05, 2021 17:47:59.950 [0x7f1fef7fe700] DEBUG - [Transcode] Transcoder segment range: 171 - 186 (185)
Mar 05, 2021 17:48:01.158 [0x7f1fee7fc700] DEBUG - Request: [8.17.107.239:64832 (WAN)] GET /video/:/transcode/universal/session/v2tncnu1zk8alvstagtqpisp/base/00178.ts (6 live) TLS GZIP Signed-in
Mar 05, 2021 17:48:01.159 [0x7f1fee7fc700] DEBUG - [Transcode/v2tncnu1zk8alvstagtqpisp] Asked for segment 178 from session.
Mar 05, 2021 17:48:01.159 [0x7f1fee7fc700] DEBUG - [Transcode/v2tncnu1zk8alvstagtqpisp] Returning segment 178 from session
Mar 05, 2021 17:48:01.159 [0x7f1fee7fc700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-v2tncnu1zk8alvstagtqpisp-65f5d8b5-4793-4f6f-95a0-b397f2d28e70/media-00178.ts is 1313932 (of total: 1313932).
Mar 05, 2021 17:48:01.673 [0x7f1fef7fe700] DEBUG - [Transcode] Transcoder segment range: 171 - 186 (186)
Mar 05, 2021 17:48:01.673 [0x7f1feffff700] DEBUG - [Transcode] Transcoder segment range: 171 - 187 (186)
Mar 05, 2021 17:48:02.391 [0x7f203e3bb700] DEBUG - Auth: authenticated user 1 as seanmcg182
Mar 05, 2021 17:48:02.391 [0x7f1feffff700] DEBUG - Request: [8.17.107.239:64819 (WAN)] GET /:/timeline?ratingKey=3693&key=%2Flibrary%2Fmetadata%2F3693&playbackTime=26165&playQueueItemID=2242&state=playing&hasMDE=1&context=library%3Acontent.library&time=1395000&duration=1588000 (6 live) TLS GZIP Signed-in Token (seanmcg182)
Mar 05, 2021 17:48:02.392 [0x7f1feffff700] DEBUG - Client [46ydruqb31pc6n0cr1zx2gp7] reporting timeline state playing, progress of 1395000/1588000ms for guid=, playbackTime=26165ms ratingKey=3693 url=, key=/library/metadata/3693, containerKey=, metadataId=3693, source=
Mar 05, 2021 17:48:02.393 [0x7f1feffff700] DEBUG - Play progress on 3693 'Everyday Life when Rachnera Disappears' - got played 1395000 ms by account 1!
Mar 05, 2021 17:48:02.394 [0x7f1feffff700] DEBUG - [Now] User is seanmcg182 (ID: 1)
Mar 05, 2021 17:48:02.394 [0x7f1feffff700] DEBUG - [Now] Device is Chrome (Chrome).
Mar 05, 2021 17:48:02.394 [0x7f1feffff700] DEBUG - [Now] Profile is Web
Mar 05, 2021 17:48:02.394 [0x7f1feffff700] DEBUG - [Now] Updated play state for /library/metadata/3693.
Mar 05, 2021 17:48:02.394 [0x7f1feffff700] DEBUG - Statistics: (cu3hcgjxdnb63qeznqz48prw) Reporting active playback in state 0 of type 4 (scrobble: 0) for account 1
Mar 05, 2021 17:48:02.397 [0x7f203ebbc700] DEBUG - Completed: [8.17.107.239:64819] 200 GET /:/timeline?ratingKey=3693&key=%2Flibrary%2Fmetadata%2F3693&playbackTime=26165&playQueueItemID=2242&state=playing&hasMDE=1&context=library%3Acontent.library&time=1395000&duration=1588000 (6 live) TLS GZIP 6ms 848 bytes (pipelined: 14)
Mar 05, 2021 17:48:02.913 [0x7f203ebbc700] DEBUG - Completed: [8.17.107.239:64832] 200 GET /video/:/transcode/universal/session/v2tncnu1zk8alvstagtqpisp/base/00178.ts (6 live) TLS GZIP 1754ms 1313932 bytes (pipelined: 20)
Mar 05, 2021 17:48:02.913 [0x7f203ebbc700] DEBUG - Removed transcode data consumer, active count 1 => 0
Mar 05, 2021 17:48:03.431 [0x7f1fef7fe700] DEBUG - [Transcode] Transcoder segment range: 171 - 187 (187)
Mar 05, 2021 17:48:03.432 [0x7f1fee7fc700] DEBUG - [Transcode] Transcoder segment range: 171 - 188 (187)
Mar 05, 2021 17:48:05.102 [0x7f1fef7fe700] DEBUG - [Transcode] Transcoder segment range: 171 - 189 (188)
Mar 05, 2021 17:48:05.102 [0x7f1feffff700] DEBUG - [Transcode] Transcoder segment range: 171 - 189 (188)
Mar 05, 2021 17:48:08.898 [0x7f200effd700] DEBUG - NetworkServiceBrowser: Parsing SSDP schema for http://192.168.1.157:9080
Mar 05, 2021 17:48:08.933 [0x7f200effd700] DEBUG - HTTP requesting GET http://192.168.1.157:9080
Mar 05, 2021 17:48:08.972 [0x7f200effd700] DEBUG - HTTP 200 response from GET http://192.168.1.157:9080
Mar 05, 2021 17:48:08.978 [0x7f200effd700] ERROR - XML: Entity: line 1:\00
Mar 05, 2021 17:48:08.978 [0x7f200effd700] ERROR - XML: parser\00
Mar 05, 2021 17:48:08.978 [0x7f200effd700] ERROR - XML: error :\00
Mar 05, 2021 17:48:08.978 [0x7f200effd700] ERROR - XML: Start tag expected, '<' not found\00
Mar 05, 2021 17:48:08.978 [0x7f200effd700] ERROR - XML: status=ok\00
Mar 05, 2021 17:48:08.978 [0x7f200effd700] ERROR - XML: ^\00
Mar 05, 2021 17:48:08.978 [0x7f200effd700] ERROR - Error parsing content.
Mar 05, 2021 17:48:08.988 [0x7f200effd700] ERROR - Error parsing XML: Error parsing file.
Mar 05, 2021 17:48:08.988 [0x7f200effd700] ERROR - SSDP: Error parsing device schema for http://192.168.1.157:9080
Mar 05, 2021 17:48:09.190 [0x7f203f3bd700] DEBUG - Request: [8.17.107.239:64832 (WAN)] GET /video/:/transcode/universal/session/v2tncnu1zk8alvstagtqpisp/base/00179.ts (6 live) TLS GZIP Signed-in
Mar 05, 2021 17:48:09.196 [0x7f203f3bd700] DEBUG - [Transcode/v2tncnu1zk8alvstagtqpisp] Asked for segment 179 from session.
Mar 05, 2021 17:48:09.201 [0x7f203f3bd700] DEBUG - [Transcode/v2tncnu1zk8alvstagtqpisp] Returning segment 179 from session
Mar 05, 2021 17:48:09.207 [0x7f203f3bd700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-v2tncnu1zk8alvstagtqpisp-65f5d8b5-4793-4f6f-95a0-b397f2d28e70/media-00179.ts is 892060 (of total: 892060).
Mar 05, 2021 17:48:10.397 [0x7f203ebbc700] DEBUG - Completed: [8.17.107.239:64832] 200 GET /video/:/transcode/universal/session/v2tncnu1zk8alvstagtqpisp/base/00179.ts (6 live) TLS GZIP 1216ms 892060 bytes (pipelined: 21)
Mar 05, 2021 17:48:10.402 [0x7f203ebbc700] DEBUG - Removed transcode data consumer, active count 1 => 0
Mar 05, 2021 17:48:10.431 [0x7f2045678700] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 20407 is -9 (signal: Killed)
Mar 05, 2021 17:48:10.435 [0x7f202cff9700] DEBUG - Streaming Resource: Terminating session 0x7f1fd02d18b0:46ydruqb31pc6n0cr1zx2gp7 which is using 1981kbps of WAN bandwidth. Used is now 0kbps
Mar 05, 2021 17:48:10.435 [0x7f202cff9700] DEBUG - Streaming Resource: Terminating session 0x7f1fd02d18b0:46ydruqb31pc6n0cr1zx2gp7 which is using transcoder slot. Used slots is now 0
Mar 05, 2021 17:48:10.436 [0x7f202effd700] DEBUG - Killing job.
Mar 05, 2021 17:48:10.436 [0x7f202cff9700] DEBUG - Streaming Resource: Terminated session 0x7f1fd02d18b0:46ydruqb31pc6n0cr1zx2gp7 with reason Conversion failed. The transcoder exited due to an error.
Mar 05, 2021 17:48:10.436 [0x7f202effd700] DEBUG - Signalling job ID 20407 with 9
In the absence of more data, that looks like a bad video. it was streaming along, minding its own business when, WHAM, it got thrown under the bus.
Might I be able to get the video or at least +/- 5 minutes of that so I can watch it fail?
(ffmeg -c copy with skip & duration should do the job)
https://drive.google.com/file/d/1s-33JWnxT2VxpfMeie1IMpBAC44-DnTp/view?usp=sharing
Uploaded the video file to google drive.
This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.
