Videos not being marked "Fully Played"
Forum rules
Please make sure you follow the Problem Reporting Guidelines before posting if you want a reply
Please make sure you follow the Problem Reporting Guidelines before posting if you want a reply
Videos not being marked "Fully Played"
With the latest v15.5 build, many videos played to the end are not being marked "Fully Played."
The one video that was marked properly was 89 minutes. Others (five videos tested) that are less than 58 minutes are were not marked "Fully Played."
The function works, just not consistently. The log file shows the one video as Fully Played, and properly marked in the database. The log file also shows the other videos as "Stopped Playing" but not Fully Played, even though they were run until the video stopped at the end.
Is there a time limit on the newer release v15.5 that is not being reached?
I don't have a log file available at this time.
Thank you.
Update:
After the Media Server went to sleep for the night (at 23:36:00), upon waking up (07:21:00), UMS immediately marked the videos as Fully Played (over 8 hours later).
The video The.Pitt.S02E12.6PM.mkv actually finished about 22:18:00, but even though the UMS server was running until 23:36:00, UMS did not mark the video as Fully Played during this time. It had over an hour to mark it until the UMS server went to sleep.
--------
14:51:54 INFO Started playing Kung Fu The Movie (1986).mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
16:20:58 INFO IP Filter: Access allowed to 192.168.111.133
16:39:23 INFO Stopped playing Kung Fu The Movie (1986).mkv on BRAVIA KDL-55HX750
16:39:23 INFO Kung Fu The Movie (1986).mkv was fully played
21:26:24 INFO Started playing The.Pitt.S02E12.6PM.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
22:20:41 INFO Started playing Georgie.and.Mandys.First.Marriage.S02E12.The G Word and a Blaspheming Bimbo.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
22:21:57 INFO Started playing Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
22:21:58 INFO Stopped playing Georgie.and.Mandys.First.Marriage.S02E12.The G Word and a Blaspheming Bimbo.mkv on BRAVIA KDL-55HX750
22:42:27 INFO Started playing Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
22:42:47 INFO Started playing Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
22:43:41 INFO Started playing Georgie.and.Mandys.First.Marriage.S02E14.Three Angry Women and a Prophylactic.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
22:43:42 INFO Stopped playing Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv on BRAVIA KDL-55HX750
23:03:44 INFO Started playing Georgie.and.Mandys.First.Marriage.S02E15.A Stuffed Monkey and an Ex-Girlfriend.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
07:21:02 INFO Stopped playing The.Pitt.S02E12.6PM.mkv on BRAVIA KDL-55HX750
07:21:02 INFO The.Pitt.S02E12.6PM.mkv was fully played
07:21:02 INFO Stopped playing Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv on BRAVIA KDL-55HX750
07:21:02 INFO Stopped playing Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv on BRAVIA KDL-55HX750
07:21:02 INFO Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv was fully played
07:21:02 INFO Stopped playing Georgie.and.Mandys.First.Marriage.S02E14.Three Angry Women and a Prophylactic.mkv on BRAVIA KDL-55HX750
07:21:02 INFO Georgie.and.Mandys.First.Marriage.S02E14.Three Angry Women and a Prophylactic.mkv was fully played
07:21:02 INFO Stopped playing Georgie.and.Mandys.First.Marriage.S02E15.A Stuffed Monkey and an Ex-Girlfriend.mkv on BRAVIA KDL-55HX750
07:21:02 INFO Georgie.and.Mandys.First.Marriage.S02E15.A Stuffed Monkey and an Ex-Girlfriend.mkv was fully played
The one video that was marked properly was 89 minutes. Others (five videos tested) that are less than 58 minutes are were not marked "Fully Played."
The function works, just not consistently. The log file shows the one video as Fully Played, and properly marked in the database. The log file also shows the other videos as "Stopped Playing" but not Fully Played, even though they were run until the video stopped at the end.
Is there a time limit on the newer release v15.5 that is not being reached?
I don't have a log file available at this time.
Thank you.
Update:
After the Media Server went to sleep for the night (at 23:36:00), upon waking up (07:21:00), UMS immediately marked the videos as Fully Played (over 8 hours later).
The video The.Pitt.S02E12.6PM.mkv actually finished about 22:18:00, but even though the UMS server was running until 23:36:00, UMS did not mark the video as Fully Played during this time. It had over an hour to mark it until the UMS server went to sleep.
--------
14:51:54 INFO Started playing Kung Fu The Movie (1986).mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
16:20:58 INFO IP Filter: Access allowed to 192.168.111.133
16:39:23 INFO Stopped playing Kung Fu The Movie (1986).mkv on BRAVIA KDL-55HX750
16:39:23 INFO Kung Fu The Movie (1986).mkv was fully played
21:26:24 INFO Started playing The.Pitt.S02E12.6PM.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
22:20:41 INFO Started playing Georgie.and.Mandys.First.Marriage.S02E12.The G Word and a Blaspheming Bimbo.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
22:21:57 INFO Started playing Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
22:21:58 INFO Stopped playing Georgie.and.Mandys.First.Marriage.S02E12.The G Word and a Blaspheming Bimbo.mkv on BRAVIA KDL-55HX750
22:42:27 INFO Started playing Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
22:42:47 INFO Started playing Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
22:43:41 INFO Started playing Georgie.and.Mandys.First.Marriage.S02E14.Three Angry Women and a Prophylactic.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
22:43:42 INFO Stopped playing Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv on BRAVIA KDL-55HX750
23:03:44 INFO Started playing Georgie.and.Mandys.First.Marriage.S02E15.A Stuffed Monkey and an Ex-Girlfriend.mkv (FFmpeg Video) on your BRAVIA KDL-55HX750
07:21:02 INFO Stopped playing The.Pitt.S02E12.6PM.mkv on BRAVIA KDL-55HX750
07:21:02 INFO The.Pitt.S02E12.6PM.mkv was fully played
07:21:02 INFO Stopped playing Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv on BRAVIA KDL-55HX750
07:21:02 INFO Stopped playing Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv on BRAVIA KDL-55HX750
07:21:02 INFO Georgie.and.Mandys.First.Marriage.S02E13.A Big Birthday and Tequila Shots.mkv was fully played
07:21:02 INFO Stopped playing Georgie.and.Mandys.First.Marriage.S02E14.Three Angry Women and a Prophylactic.mkv on BRAVIA KDL-55HX750
07:21:02 INFO Georgie.and.Mandys.First.Marriage.S02E14.Three Angry Women and a Prophylactic.mkv was fully played
07:21:02 INFO Stopped playing Georgie.and.Mandys.First.Marriage.S02E15.A Stuffed Monkey and an Ex-Girlfriend.mkv on BRAVIA KDL-55HX750
07:21:02 INFO Georgie.and.Mandys.First.Marriage.S02E15.A Stuffed Monkey and an Ex-Girlfriend.mkv was fully played
Re: Videos not being marked "Fully Played"
If you have your logs in TRACE mode and search for "final decision:" it will tell you why something is not being marked as fully played.
In this case it may not have fully stopped playing when the computer went to sleep, so when it awoke it thought it was playing over 8 hours and then marked it as played.
IIRC there is also a certain percentage of the video that has to be played, if you stop before the end credits it may not count as fully played.
I can't remember if this is configurable ATM, I think it might be.
There have also been cases where UMS does not register that a video has stopped so the stop playing event is not triggered.
In this case it may not have fully stopped playing when the computer went to sleep, so when it awoke it thought it was playing over 8 hours and then marked it as played.
IIRC there is also a certain percentage of the video that has to be played, if you stop before the end credits it may not count as fully played.
I can't remember if this is configurable ATM, I think it might be.
There have also been cases where UMS does not register that a video has stopped so the stop playing event is not triggered.
Logs are important for us to help, Please follow This Link before asking for support. Just a forum cleaner, Will help if I can but no expert.
Re: Videos not being marked "Fully Played"
Still testing, but getting HUNDREDS of these messages in the log...
Large batches coming about every 7 minutes.
------
Update: Tested a video with length of 24 minutes 8 seconds. Ran it continuously until it ended.
The logs showed it started at 7:45:49 and ended at 8:04:10 (18 minutes 21 seconds). The minimum time to run to "completion" is 22 minutes 12 seconds. That is why it was not marked as Fully Played.
I will run the video again and note the exact time it runs. I don't see how a 24-minute video can finish in 18 minutes.
-----
Update #2: The log file shows that the video "Stopped Playing" 6 full minutes BEFORE the video ended playing on the TV. This is why it is not being marked as "Fully Played". But why does it show "Stopped Playing" when the video continues to be streamed to the TV for the final six minutes????
The video in question is: Herman's Head.S01E01.Pilot.mp4
-----
Following is a condensed log with the pertinent entries...
----------------------------------------------------------------------------------------------
Code: Select all
07:56:04 INFO [Fatal Error] :1:10: DOCTYPE is disallowed when the feature "http://apache.org/xml/features/disallow-doctype-decl" set to true.
------
Update: Tested a video with length of 24 minutes 8 seconds. Ran it continuously until it ended.
The logs showed it started at 7:45:49 and ended at 8:04:10 (18 minutes 21 seconds). The minimum time to run to "completion" is 22 minutes 12 seconds. That is why it was not marked as Fully Played.
I will run the video again and note the exact time it runs. I don't see how a 24-minute video can finish in 18 minutes.
-----
Update #2: The log file shows that the video "Stopped Playing" 6 full minutes BEFORE the video ended playing on the TV. This is why it is not being marked as "Fully Played". But why does it show "Stopped Playing" when the video continues to be streamed to the TV for the final six minutes????
The video in question is: Herman's Head.S01E01.Pilot.mp4
-----
Following is a condensed log with the pertinent entries...
----------------------------------------------------------------------------------------------
Code: Select all
TRACE 2026-04-20 07:46:02.140 [Windows Sleep Worker] net.pms.platform.windows.WindowsSleepWorker Calling SetThreadExecutionState ES_SYSTEM_REQUIRED to prevent Windows from going to sleep
INFO 2026-04-20 07:46:02.140 [StartPlaying Event] net.pms.store.StoreItem Started playing Herman's Head.S01E01.Pilot.mp4 (No transcoding) on your BRAVIA KDL-55HX750
DEBUG 2026-04-20 07:46:02.141 [StartPlaying Event] net.pms.store.StoreItem The full filename of which is: d:\0pending\Series\5Herman's Head (1991-94)\Season 1\Herman's Head.S01E01.Pilot.mp4 and the address of the renderer is: 192.168.111.178
TRACE 2026-04-20 07:46:03.128 [jupnp-stream-server-147] net.pms.network.UmsAsyncListener Stream Async progress: 6881280 bytes sent
TRACE 2026-04-20 07:46:04.132 [jupnp-stream-server-147] net.pms.network.UmsAsyncListener Stream Async progress: 17432576 bytes sent
DEBUG 2026-04-20 07:46:04.336 [jupnp-stream-server-147] net.pms.network.HttpServletHelper Sending stream with premature end: 19333120 bytes. Reason: An established connection was aborted by the software in your host machine
TRACE 2026-04-20 07:46:04.338 [jupnp-stream-server-147] net.pms.network.UmsAsyncListener Stream Async Premature end: An established connection was aborted by the software in your host machine, duration: 2215 ms, sent: 19333120 bytes
TRACE 2026-04-20 07:46:04.338 [StopPlaying Event Deferrer] net.pms.store.StoreItem Stop playing Herman's Head.S01E01.Pilot.mp4 on BRAVIA KDL-55HX750 if no request under 4000 ms
DEBUG 2026-04-20 07:46:04.338 [jupnp-stream-server-94] net.pms.network.HttpServletHelper Received a request from BRAVIA KDL-55HX750 [Sony Bravia HX] (192.168.111.178:41013):
============================= MEDIA HTTP SERVER REQUEST BEGIN ================================
GET /ums/media/00000000-0000-1010-8000-3C077113D470/1164/Herman-s-Head.S01E01.Pilot.mp4 HTTP/1.1
HEADER:
Range: bytes=239977-
getcontentFeatures.dlna.org: 1
Pragma: getIfoFileURI.dlna.org
X-AV-Physical-Unit-Info: pa="BRAVIA KDL-55HX750";
X-AV-Client-Info: av=5.0; cn="Sony Corporation"; mn="BRAVIA KDL-55HX750"; mv="1.7";
Host: 192.168.111.11:5001
============================= MEDIA HTTP SERVER REQUEST END ==================================
TRACE 2026-04-20 07:46:04.340 [jupnp-stream-server-94] net.pms.store.StoreItem Asked stream chunk: ByteRange [start=239977, end=67693485] of Herman's Head.S01E01.Pilot.mp4 and engine null
TRACE 2026-04-20 07:46:04.340 [jupnp-stream-server-94] net.pms.store.StoreItem Estimating seek position from byte range:
TRACE 2026-04-20 07:46:04.340 [jupnp-stream-server-94] net.pms.store.StoreItem media.getBitrate: 373974
TRACE 2026-04-20 07:46:04.340 [jupnp-stream-server-94] net.pms.store.StoreItem low: 239977
TRACE 2026-04-20 07:46:04.340 [jupnp-stream-server-94] net.pms.store.StoreItem lastStartPosition: 5.13355473909951
TRACE 2026-04-20 07:46:04.340 [jupnp-stream-server-94] net.pms.store.StoreItem Using size-limiting stream (67453509 bytes)
TRACE 2026-04-20 07:46:04.340 [jupnp-stream-server-94] net.pms.network.mediaserver.servlets.MediaServerServlet Did not send subtitle headers because item.getMediaSubtitle() is null
TRACE 2026-04-20 07:46:04.340 [jupnp-stream-server-94] net.pms.configuration.FormatConfiguration Format "mp4" failed to match supported line f:avi|divx v:mp4|divx|mjpeg a:mp3|lpcm|mpa|ac3 m:video/x-divx qpel:no gmc:0
TRACE 2026-04-20 07:46:04.340 [jupnp-stream-server-94] net.pms.configuration.FormatConfiguration Matched support line f:mp4 v:mp4|h264 a:ac3|aac-lc m:video/mp4
TRACE 2026-04-20 07:46:04.340 [jupnp-stream-server-94] net.pms.store.StoreItem File "Herman's Head.S01E01.Pilot.mp4" will be sent with MIME type "video/mp4"
TRACE 2026-04-20 07:46:04.341 [jupnp-stream-server-94] net.pms.network.mediaserver.servlets.MediaServerServlet Sending 67453509 bytes.
TRACE 2026-04-20 07:46:04.341 [jupnp-stream-server-94] net.pms.configuration.FormatConfiguration Format "mp4" failed to match supported line f:avi|divx v:mp4|divx|mjpeg a:mp3|lpcm|mpa|ac3 m:video/x-divx qpel:no gmc:0
TRACE 2026-04-20 07:46:04.341 [jupnp-stream-server-94] net.pms.configuration.FormatConfiguration Matched support line f:mp4 v:mp4|h264 a:ac3|aac-lc m:video/mp4
TRACE 2026-04-20 07:46:04.341 [jupnp-stream-server-94] net.pms.store.StoreItem File "Herman's Head.S01E01.Pilot.mp4" will be sent with MIME type "video/mp4"
DEBUG 2026-04-20 07:46:04.341 [jupnp-stream-server-94] net.pms.network.HttpServletHelper Transfer response sent to BRAVIA KDL-55HX750 [Sony Bravia HX] (192.168.111.178:41013):
============================= MEDIA HTTP SERVER RESPONSE BEGIN ===============================
HTTP/1.1 206 (non-chunked)
HEADER:
Server: Windows_11-amd64-10.0, UPnP/1.0 DLNADOC/1.50, UMS/15.5.0-SNAPSHOT
Date: Mon, 20 Apr 2026 11:46:04 GMT
Content-Type: video/mp4
Content-Range: bytes 239977-67693485/67693486
ContentFeatures.DLNA.ORG: DLNA.ORG_PN=AVC_MP4_BL;DLNA.ORG_OP=01;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=01700000000000000000000000000000
Accept-Ranges: bytes
Connection: keep-alive
Content-Length: 67453509
============================= MEDIA HTTP SERVER RESPONSE END =================================
TRACE 2026-04-20 08:03:38.089 [jupnp-sync-protocol 5423-1] net.pms.network.UmsAsyncListener Stream Async Complete, id: 902, uri: /dev/985ece06-78d6-4e66-aa77-12be46090fa4/svc/upnp-org/ConnectionManager/action, duration: 57 ms
TRACE 2026-04-20 08:03:38.090 [jupnp-sync-protocol 5423-1] net.pms.network.mediaserver.jupnp.transport.async.JakartaAsyncServletUpnpStream Completed asynchronous processing of HTTP request: oeje10s.ServletApiRequest@22e3fef4{oeje10s.ServletContextRequest@5a8bff64{POST@7260393a http://192.168.111.11:5001/dev/985ece06-78d6-4e66-aa77-12be46090fa4/svc/upnp-org/ConnectionManager/action HTTP/1.1}}
TRACE 2026-04-20 08:03:38.687 [jupnp-stream-server-91] net.pms.network.UmsAsyncListener Stream Async progress: 66191360 bytes sent
TRACE 2026-04-20 08:03:39.057 [NetworkConfiguration Watcher] net.pms.network.configuration.NetworkConfiguration Checking network configuration changes
TRACE 2026-04-20 08:03:43.687 [jupnp-stream-server-91] net.pms.network.UmsAsyncListener Stream Async progress: 66387968 bytes sent
TRACE 2026-04-20 08:03:44.500 [NetworkConfiguration Watcher] net.pms.network.configuration.NetworkConfiguration Checking network configuration changes
TRACE 2026-04-20 08:03:48.677 [jupnp-stream-server-91] net.pms.network.UmsAsyncListener Stream Async progress: 66650112 bytes sent
TRACE 2026-04-20 08:03:49.953 [NetworkConfiguration Watcher] net.pms.network.configuration.NetworkConfiguration Checking network configuration changes
TRACE 2026-04-20 08:03:53.717 [jupnp-stream-server-91] net.pms.network.UmsAsyncListener Stream Async progress: 66912256 bytes sent
TRACE 2026-04-20 08:03:55.442 [NetworkConfiguration Watcher] net.pms.network.configuration.NetworkConfiguration Checking network configuration changes
TRACE 2026-04-20 08:04:00.208 [jupnp-stream-server-91] net.pms.network.UmsAsyncListener Stream Async progress: 67108864 bytes sent
TRACE 2026-04-20 08:04:00.888 [NetworkConfiguration Watcher] net.pms.network.configuration.NetworkConfiguration Checking network configuration changes
TRACE 2026-04-20 08:04:06.217 [jupnp-stream-server-91] net.pms.network.UmsAsyncListener Stream Async progress: 67371008 bytes sent
TRACE 2026-04-20 08:04:06.297 [jupnp-stream-server-91] net.pms.network.HttpServletHelper Sending stream finished after: 67453509 bytes.
TRACE 2026-04-20 08:04:06.298 [jupnp-stream-server-91] net.pms.network.UmsAsyncListener Stream Async Complete, uri: /ums/media/00000000-0000-1010-8000-3C077113D470/1164/Herman-s-Head.S01E01.Pilot.mp4, duration: 1081956 ms, sent: 67453509 bytes
TRACE 2026-04-20 08:04:06.298 [StopPlaying Event Deferrer] net.pms.store.StoreItem Stop playing Herman's Head.S01E01.Pilot.mp4 on BRAVIA KDL-55HX750 if no request under 4000 ms
TRACE 2026-04-20 08:04:06.344 [NetworkConfiguration Watcher] net.pms.network.configuration.NetworkConfiguration Checking network configuration changes
TRACE 2026-04-20 08:04:07.318 [jupnp-stream-server-94] net.pms.network.mediaserver.jupnp.transport.async.JakartaAsyncServlet HttpServlet HttpServlet.service(): id: 903, request URI: /dev/985ece06-78d6-4e66-aa77-12be46090fa4/desc
TRACE 2026-04-20 08:04:07.318 [jupnp-stream-server-94] net.pms.network.mediaserver.jupnp.transport.async.JakartaAsyncServlet Handling Servlet request asynchronously: oeje10s.ServletApiRequest@6d3411b1{oeje10s.ServletContextRequest@1cc8a6{GET@1d507474 http://192.168.111.11:5001/dev/985ece06-78d6-4e66-aa77-12be46090fa4/desc HTTP/1.1}}
TRACE 2026-04-20 08:04:07.318 [jupnp-sync-protocol 5433-1] net.pms.network.mediaserver.jupnp.transport.impl.JakartaServletUpnpStream Processing HTTP request: GET /dev/985ece06-78d6-4e66-aa77-12be46090fa4/desc
TRACE 2026-04-20 08:04:07.318 [jupnp-sync-protocol 5433-1] net.pms.network.mediaserver.jupnp.transport.impl.JakartaServletUpnpStream Reading request body bytes: 0
TRACE 2026-04-20 08:04:07.318 [jupnp-sync-protocol 5433-1] net.pms.network.mediaserver.jupnp.transport.impl.JakartaServletUpnpStream Request did not contain entity body
TRACE 2026-04-20 08:04:07.318 [jupnp-sync-protocol 5433-1] net.pms.network.mediaserver.jupnp.transport.impl.JakartaServletUpnpStream Processing new request message: (StreamRequestMessage) GET /dev/985ece06-78d6-4e66-aa77-12be46090fa4/desc
DEBUG 2026-04-20 08:04:07.318 [jupnp-sync-protocol 5433-1] net.pms.network.HttpServletHelper Received a request from 192.168.111.178:
TRACE 2026-04-20 08:04:08.034 [jupnp-sync-protocol 5461-1] net.pms.network.UmsAsyncListener Stream Async Complete, id: 917, uri: /dev/985ece06-78d6-4e66-aa77-12be46090fa4/svc/upnp-org/ConnectionManager/action, duration: 70 ms
TRACE 2026-04-20 08:04:08.034 [jupnp-sync-protocol 5461-1] net.pms.network.mediaserver.jupnp.transport.async.JakartaAsyncServletUpnpStream Completed asynchronous processing of HTTP request: oeje10s.ServletApiRequest@363cefe3{oeje10s.ServletContextRequest@2183378e{POST@1e593d40 http://192.168.111.11:5001/dev/985ece06-78d6-4e66-aa77-12be46090fa4/svc/upnp-org/ConnectionManager/action HTTP/1.1}}
INFO 2026-04-20 08:04:10.302 [StopPlaying Event] net.pms.store.StoreItem Stopped playing Herman's Head.S01E01.Pilot.mp4 on BRAVIA KDL-55HX750
DEBUG 2026-04-20 08:04:10.303 [StopPlaying Event] net.pms.store.StoreItem The full filename of which is "d:\0pending\Series\5Herman's Head (1991-94)\Season 1\Herman's Head.S01E01.Pilot.mp4" and the address of the renderer is 192.168.111.178
DEBUG 2026-04-20 08:04:10.312 [StopPlaying Event] net.pms.store.ResumeObj Resume stop. This segment 1088166 new time 1088166
TRACE 2026-04-20 08:04:10.317 [StopPlaying Event] net.pms.store.container.MediaMonitor Fully Played feature logging:
TRACE 2026-04-20 08:04:10.318 [StopPlaying Event] net.pms.store.container.MediaMonitor duration: 1448.088
TRACE 2026-04-20 08:04:10.318 [StopPlaying Event] net.pms.store.container.MediaMonitor getLastStartPosition: 5.13355473909951
TRACE 2026-04-20 08:04:10.319 [StopPlaying Event] net.pms.store.container.MediaMonitor currentTime: 1776686650317
TRACE 2026-04-20 08:04:10.319 [StopPlaying Event] net.pms.store.container.MediaMonitor getLastStartSystemTime: 1776685562141
TRACE 2026-04-20 08:04:10.319 [StopPlaying Event] net.pms.store.container.MediaMonitor lastStartSystemTimeUser: 1776685562141
TRACE 2026-04-20 08:04:10.319 [StopPlaying Event] net.pms.store.container.MediaMonitor minimum play time: 30
TRACE 2026-04-20 08:04:10.319 [StopPlaying Event] net.pms.store.container.MediaMonitor triggered fully played time: 1332.24096
TRACE 2026-04-20 08:04:10.320 [StopPlaying Event] net.pms.store.container.MediaMonitor elapsed: 1093.3095547390994
TRACE 2026-04-20 08:04:10.320 [StopPlaying Event] net.pms.database.MediaTableFilesStatus Searching for file in FILES_STATUS with "HikariProxyPreparedStatement@610438341 wrapping prep5673: SELECT * FROM FILES_STATUS WHERE FILES_STATUS.FILENAME = ? AND FILES_STATUS.USERID = ? LIMIT 1 {1: 'd:\0pending\Series\5Herman''s Head (1991-94)\Season 1\Herman''s Head.S01E01.Pilot.mp4', 2: 0}" before setLastPlayed
TRACE 2026-04-20 08:04:10.325 [StopPlaying Event] net.pms.store.container.MediaMonitor final decision: not fully played
TRACE 2026-04-20 08:04:10.345 [jupnp-contentdirectory-service] net.pms.network.mediaserver.jupnp.support.contentdirectory.UmsContentDirectoryService Send event "SystemUpdateID" update from 1922 to 1924
TRACE 2026-04-20 08:04:37.373 [jupnp-stream-server-118] net.pms.network.mediaserver.jupnp.transport.async.JakartaAsyncServlet HttpServlet HttpServlet.service(): id: 918, request URI: /dev/985ece06-78d6-4e66-aa77-12be46090fa4/desc
TRACE 2026-04-20 08:04:37.373 [jupnp-stream-server-118] net.pms.network.mediaserver.jupnp.transport.async.JakartaAsyncServlet Handling Servlet request asynchronously: oeje10s.ServletApiRequest@52ae7ff{oeje10s.ServletContextRequest@5081b756{GET@65d88553 http://192.168.111.11:5001/dev/985ece06-78d6-4e66-aa77-12be46090fa4/desc HTTP/1.1}}
TRACE 2026-04-20 08:04:37.374 [jupnp-sync-protocol 5470-1] net.pms.network.mediaserver.jupnp.transport.impl.JakartaServletUpnpStream Processing HTTP request: GET /dev/985ece06-78d6-4e66-aa77-12be46090fa4/desc
TRACE 2026-04-20 08:04:37.374 [jupnp-sync-protocol 5470-1] net.pms.network.mediaserver.jupnp.transport.impl.JakartaServletUpnpStream Reading request body bytes: 0
TRACE 2026-04-20 08:04:37.374 [jupnp-sync-protocol 5470-1] net.pms.network.mediaserver.jupnp.transport.impl.JakartaServletUpnpStream Request did not contain entity body
TRACE 2026-04-20 08:04:37.374 [jupnp-sync-protocol 5470-1] net.pms.network.mediaserver.jupnp.transport.impl.JakartaServletUpnpStream Processing new request message: (StreamRequestMessage) GET /dev/985ece06-78d6-4e66-aa77-12be46090fa4/desc
DEBUG 2026-04-20 08:04:37.374 [jupnp-sync-protocol 5470-1] net.pms.network.HttpServletHelper Received a request from 192.168.111.178:- Attachments
-
- ums_dbg_2026-04-20-08-11 (UMS v15.5).zip
- Herman's Head.S01E01.Pilot.mp4
- (1.41 MiB) Downloaded 2076 times
Re: Videos not being marked "Fully Played"
I'm not sure about the fatal error message but it is not coming from UMS, it is the message sent from your Roku on 192.168.111.9
It might not actually be a Roku device as your UMS.conf has set this as the default renderer and the header mentions Microsoft.
I tried to figure out what this meant and is something about not allowing the DOCTYPE property in headers for security or simplicity.
Maybe there is something missing from the request so it interpreted as text that triggers that error
I think the UUID should be after "GET /upnphost/udhisapi.dll" like it says in the previous "Sending HTTP request:" line.
I don't know anything about how it calculates watch time but know it has been a problem before.
I can see that the video was being streamed. Maybe the TV is not correctly reporting its position.
This may be because that TV does not support a feature that would give an accurate reading
but should be able to give a good estimate depending on what data it has sent.
If you can reliably replicate this on many videos it might be worth opening an issue on Github.
It might not actually be a Roku device as your UMS.conf has set this as the default renderer and the header mentions Microsoft.
I tried to figure out what this meant and is something about not allowing the DOCTYPE property in headers for security or simplicity.
Code: Select all
Creating HTTP request. URI: 'http://192.168.111.9:2869/upnphost/udhisapi.dll?content=uuid:d92e123d-b2e4-4b86-aa03-ae87a8ce088f' method: 'GET'
Sending HTTP request: (StreamRequestMessage) GET http://192.168.111.9:2869/upnphost/udhisapi.dll?content=uuid:d92e123d-b2e4-4b86-aa03-ae87a8ce088f
Send a request to 192.168.111.9:
==================================== HTTPCLIENT REQUEST BEGIN ====================================
GET /upnphost/udhisapi.dll HTTP/1.1
HEADER:
User-agent: UMS/15.5.0-SNAPSHOT UPnP/1.0 DLNADOC/1.50 (Windows_11)
==================================== HTTPCLIENT REQUEST END ======================================
Received HTTP response: Bad Request
HTTP response message contains text entity
[Fatal Error] :1:10: DOCTYPE is disallowed when the feature "http://apache.org/xml/features/disallow-doctype-decl" set to true.
Received a response from 192.168.111.9:
==================================== HTTPCLIENT RESPONSE BEGIN ===================================
HTTP/1.1 400 Bad Request
HEADER:
Server: Microsoft-HTTPAPI/2.0
Connection: close
Date: Mon, 20 Apr 2026 11:11:34 GMT
Content-type: text/html; charset=us-ascii
Content-length: 339
CONTENT:
Content isn't valid XML, using text formatting: DOCTYPE is disallowed when the feature "http://apache.org/xml/features/disallow-doctype-decl" set to true.
<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN""http://www.w3.org/TR/html4/strict.dtd">
<HTML><HEAD><TITLE>Bad Request</TITLE>
<META HTTP-EQUIV="Content-Type" Content="text/html; charset=us-ascii"></HEAD>
<BODY><h2>Bad Request - Invalid Header</h2>
<hr><p>HTTP Error 400. The request has an invalid header name.</p>
</BODY></HTML>
==================================== HTTPCLIENT RESPONSE END =====================================
I think the UUID should be after "GET /upnphost/udhisapi.dll" like it says in the previous "Sending HTTP request:" line.
I don't know anything about how it calculates watch time but know it has been a problem before.
I can see that the video was being streamed. Maybe the TV is not correctly reporting its position.
This may be because that TV does not support a feature that would give an accurate reading
Code: Select all
The renderer BRAVIA KDL-55HX750 returns that the GetPositionInfo is not implemented. The UMS disabled this feature. If you can reliably replicate this on many videos it might be worth opening an issue on Github.
Logs are important for us to help, Please follow This Link before asking for support. Just a forum cleaner, Will help if I can but no expert.
Re: Videos not being marked "Fully Played"
Re: If you can reliably replicate this on many videos it might be worth opening an issue on Github.
Ans: I'm sure I can replicate on other videos. It has not been an issue in the past. And the TV reports the video location perfectly. When the TV shows it is near the end of the video, that is where it is.
I will run with more videos. Will you need further log file(s) to submit a problem to Github? I'm sure they will show similar results for all the videos it fails on.
Is this an issue with FFMPEG?
Ans: I'm sure I can replicate on other videos. It has not been an issue in the past. And the TV reports the video location perfectly. When the TV shows it is near the end of the video, that is where it is.
I will run with more videos. Will you need further log file(s) to submit a problem to Github? I'm sure they will show similar results for all the videos it fails on.
Is this an issue with FFMPEG?
Re: Videos not being marked "Fully Played"
No it was not FFmpeg as that video was being streamed and not transcoded.
I suspect videos that are transcoded would get correctly marked as UMS will know exactly how much has been played as it will know how much has been transcoded.
When streamed the file is sent unaltered to the TV and may be in large chunks so the TV could be playing any part of it.
UMS can only get a rough estimate based on the last requested chunk.
The TV itself knows where it is but does not support the GetPositionInfo request to tell UMS its position.
This is guesswork though as I don't know exactly how this works.
I suspect videos that are transcoded would get correctly marked as UMS will know exactly how much has been played as it will know how much has been transcoded.
When streamed the file is sent unaltered to the TV and may be in large chunks so the TV could be playing any part of it.
UMS can only get a rough estimate based on the last requested chunk.
The TV itself knows where it is but does not support the GetPositionInfo request to tell UMS its position.
This is guesswork though as I don't know exactly how this works.
Logs are important for us to help, Please follow This Link before asking for support. Just a forum cleaner, Will help if I can but no expert.
Re: Videos not being marked "Fully Played"
I have a recommendation that should fix this problem.
Can you change the "Fully Played" logic as follows???
If GetPositionInfo is not implemented Then
----Calculate Fully_Played_Time = Bytes_Sent_To_Player / Size_of_video_file * 100 * Duration
....If Fully_Played_Time > Triggered_Fully_Played_Time Then
........." Mark video as Fully Played
....End If
Else
...." Calculate Fully_Played_Time as is done currently. No change to existing method if GetPositionInfo is implemented.
End If
Let me know what you think.
Can you change the "Fully Played" logic as follows???
If GetPositionInfo is not implemented Then
----Calculate Fully_Played_Time = Bytes_Sent_To_Player / Size_of_video_file * 100 * Duration
....If Fully_Played_Time > Triggered_Fully_Played_Time Then
........." Mark video as Fully Played
....End If
Else
...." Calculate Fully_Played_Time as is done currently. No change to existing method if GetPositionInfo is implemented.
End If
Let me know what you think.
Re: Videos not being marked "Fully Played"
I don't think that would work.
The renderer might request X number of bytes from the start of the video then if seeking to the end it will request the last Y number of bytes.
however X+Y would only be a fraction of the total size of the video so you cannot work out the play duration from the data sent.
If the renderer had requested the data for a time Y then you could use that but not all renderers use seek by time and use seek by byte instead which is not as easy to work out as the bitrate may vary depending on the codec used.
There is probably a lot more to this than I know and it might actually be doing a similar test.
If you know anything about coding then maybe have a look at the source code for this to see how it works.
The renderer might request X number of bytes from the start of the video then if seeking to the end it will request the last Y number of bytes.
however X+Y would only be a fraction of the total size of the video so you cannot work out the play duration from the data sent.
If the renderer had requested the data for a time Y then you could use that but not all renderers use seek by time and use seek by byte instead which is not as easy to work out as the bitrate may vary depending on the codec used.
There is probably a lot more to this than I know and it might actually be doing a similar test.
If you know anything about coding then maybe have a look at the source code for this to see how it works.
Logs are important for us to help, Please follow This Link before asking for support. Just a forum cleaner, Will help if I can but no expert.
Re: Videos not being marked "Fully Played"
I'm trying to view the code in Eclipse. The README file says...
To import UMS into Eclipse as a project, go to:
File -> Import -> Maven -> Existing Maven Project
and browse to the root of the UMS git repository.
I don't see the "UMS git repository"...what directory is it in? What is the name of the directory?
I am using Windows.
To import UMS into Eclipse as a project, go to:
File -> Import -> Maven -> Existing Maven Project
and browse to the root of the UMS git repository.
I don't see the "UMS git repository"...what directory is it in? What is the name of the directory?
I am using Windows.
Re: Videos not being marked "Fully Played"
Sorry I have no idea about this.
I assume it will be in the directory you downloaded to.
I remember with Git installed you will need to be on the right branch to see the files, it will hide any files from other branches and previous versions but that is as much as I know.
I assume it will be in the directory you downloaded to.
I remember with Git installed you will need to be on the right branch to see the files, it will hide any files from other branches and previous versions but that is as much as I know.
Logs are important for us to help, Please follow This Link before asking for support. Just a forum cleaner, Will help if I can but no expert.