Marking media played entirely #3947

Fredo1650 · 2023-06-17T01:20:18Z

Hello, since the 13.4.0 update the fully played media are no longer marked, software bug? , Can you help me ?

Mik-S-UMS · 2023-06-17T17:44:40Z

Could you post your logs? See here for instructions.

Fredo1650 · 2023-06-18T00:33:41Z

Hello, attached the UMS logs
ums_dbg_2023-06-18-02-26.zip

Mik-S-UMS · 2023-06-18T02:53:26Z

Nothing was playing when you created the logs so could not see anything.

Could you try again but fully watch something from your renderer so I can see what UMS does. It may be enough to skip to near the end of the video.

Fredo1650 · 2023-06-18T12:48:37Z

Hello, I played some video until the next video loaded, but they are still marked as fully played.
attached the UMS logs
_ums_dbg_2023-06-18-14-41.zip

Mik-S-UMS · 2023-06-18T14:09:47Z

Not sue what is going on. I see the fully played logging and from what I understand it should be marking them as played but is not.

I tried to see if it was a configuration problem but I see you don't have the advanced options enabled so you would not have changed anything. I have mine set to move fully played videos to another folder and it still works for me.

Go into settings and enable Show advanced options
In the Navigation Settings tab under General settings is the option Fully played action:
Set this to Mark media and save.

If this now works then the default option must have changed somehow, maybe on accident or due to a bug (possibly related to #3948)

Fredo1650 · 2023-06-18T14:51:43Z

I have already reinstalled the software with all the default settings (Clean install), after a test the media was still not marked.
Only the Media Library Folder, Recently Played, TRANSCODE parameters are disabled, but that did not change anything when it was enabled by default I had already tried it.

In link some images of the general parameters of UMS:

Mik-S-UMS · 2023-06-18T19:49:21Z

Since you did a clean install could you do some more logs with your new settings?

Fredo1650 · 2023-06-18T20:04:15Z

The last logs that I provided to you were made after the new installation (Clean install), I just deactivated the Media Library virtual folder, Played recently, TRANSCODE, I had done another test without touching any parameters (UMS By default), the media played entirely was not marked
The images and the last logs I published are the current settings I use with the new installation

Mik-S-UMS · 2023-06-19T22:09:45Z

I tried to replicate this on my system using your settings and at first I could not reproduce this behaviour, then it stopped marking.

I messed around with the settings to enable and disable cache, marking, and media library by editing your conf to add those options. The results were random, sometimes working and other not and I could not pin it down to anything specific. I also tried with videos streamed and transcoded.

An example of this happening is

TRACE 2023-06-19 22:19:57.724 [StartPlaying Event] Matched media renderer "PlayStation 4" based on address 192.168.1.67
INFO  2023-06-19 22:19:57.724 [StartPlaying Event] Started playing Anotlkjgjjh Life 2019 S01E02.mkv on your PlayStation 4
DEBUG 2023-06-19 22:19:57.724 [StartPlaying Event] The full filename of which is: D:\Users\Mik\Downloads\Video\Anotlkjgjjh Life 2019 S01E02.mkv and the address of the renderer is: 192.168.1.67
TRACE 2023-06-19 22:20:15.772 [StopPlaying Event] Matched media renderer "PlayStation 4" based on address 192.168.1.67
INFO  2023-06-19 22:20:15.772 [StopPlaying Event] Stopped playing Anotlkjgjjh Life 2019 S01E02.mkv on PlayStation 4
DEBUG 2023-06-19 22:20:15.772 [StopPlaying Event] The full filename of which is "D:\Users\Mik\Downloads\Video\Anotlkjgjjh Life 2019 S01E02.mkv" and the address of the renderer is 192.168.1.67
TRACE 2023-06-19 22:20:15.772 [StopPlaying Event] Fully Played feature logging:
TRACE 2023-06-19 22:20:15.772 [StopPlaying Event]    duration: 2675.125
TRACE 2023-06-19 22:20:15.772 [StopPlaying Event]    getLastStartPosition: 2674.64858214109
TRACE 2023-06-19 22:20:15.772 [StopPlaying Event]    getStartTime: 1687209597724
TRACE 2023-06-19 22:20:15.772 [StopPlaying Event]    getLastStartSystemTime: 1.68720961177E12
TRACE 2023-06-19 22:20:15.772 [StopPlaying Event]    elapsed: 2678.65058214109
TRACE 2023-06-19 22:20:15.773 [StopPlaying Event]    minimum play time needed: 2461.1150000000002
TRACE 2023-06-19 22:20:32.593 [StartPlaying Event] Matched media renderer "PlayStation 4" based on address 192.168.1.67

While this is when it works (set to move on fully played)

INFO  2023-06-19 22:20:32.593 [StartPlaying Event] Started playing Another Life 2019 S01E03.mkv on your PlayStation 4
DEBUG 2023-06-19 22:20:32.593 [StartPlaying Event] The full filename of which is: D:\Users\Mik\Downloads\Video\Another Life 2019 S01E03.mkv and the address of the renderer is: 192.168.1.67
TRACE 2023-06-19 22:20:52.851 [StopPlaying Event] Matched media renderer "PlayStation 4" based on address 192.168.1.67
INFO  2023-06-19 22:20:52.851 [StopPlaying Event] Stopped playing Another Life 2019 S01E03.mkv on PlayStation 4
DEBUG 2023-06-19 22:20:52.851 [StopPlaying Event] The full filename of which is "D:\Users\Mik\Downloads\Video\Another Life 2019 S01E03.mkv" and the address of the renderer is 192.168.1.67
TRACE 2023-06-19 22:20:52.851 [StopPlaying Event] Fully Played feature logging:
TRACE 2023-06-19 22:20:52.851 [StopPlaying Event]    duration: 2841.301
TRACE 2023-06-19 22:20:52.851 [StopPlaying Event]    getLastStartPosition: 2839.2262705918392
TRACE 2023-06-19 22:20:52.851 [StopPlaying Event]    getStartTime: 1687209632593
TRACE 2023-06-19 22:20:52.851 [StopPlaying Event]    getLastStartSystemTime: 1.687209648845E12
TRACE 2023-06-19 22:20:52.851 [StopPlaying Event]    elapsed: 2843.232270591839
TRACE 2023-06-19 22:20:52.851 [StopPlaying Event]    minimum play time needed: 2613.99692
TRACE 2023-06-19 22:20:52.852 [StopPlaying Event] Searching for file in FILES_STATUS with "HikariProxyPreparedStatement@92686285 wrapping prep265089: SELECT * FROM FILES_STATUS WHERE FILES_STATUS.FILENAME = ? LIMIT 1 {1: 'D:\Users\Mik\Downloads\Video\Another Life 2019 S01E03.mkv'}" before setFullyPlayed
TRACE 2023-06-19 22:20:52.852 [StopPlaying Event] File entry "D:\Users\Mik\Downloads\Video\Another Life 2019 S01E03.mkv" not found in FILES_STATUS, inserting new row with ISFULLYPLAYED set to true
TRACE 2023-06-19 22:20:52.852 [StopPlaying Event] Searching for file in FILES_STATUS with "HikariProxyPreparedStatement@188852493 wrapping prep265091: SELECT * FROM FILES_STATUS WHERE FILES_STATUS.FILENAME = ? LIMIT 1 {1: 'D:\Users\Mik\Downloads\Video\Another Life 2019 S01E03.mkv'}" before setLastPlayed
DEBUG 2023-06-19 22:20:52.854 [StopPlaying Event] Moved Another Life 2019 S01E03.mkv because it has been fully played
...

...
INFO  2023-06-19 22:20:53.011 [StopPlaying Event] New file Another Life 2019 S01E03.mkv was detected and added to the Media Library
TRACE 2023-06-19 22:20:53.064 [StopPlaying Event] Searching for file in FILES_STATUS with "HikariProxyPreparedStatement@1799826941 wrapping prep265147: SELECT * FROM FILES_STATUS WHERE FILES_STATUS.FILENAME = ? LIMIT 1 {1: 'D:\Users\Mik\Downloads\Video\Watched\Another Life 2019 S01E03.mkv'}" before setFullyPlayed
TRACE 2023-06-19 22:20:53.064 [StopPlaying Event] File entry "D:\Users\Mik\Downloads\Video\Watched\Another Life 2019 S01E03.mkv" not found in FILES_STATUS, inserting new row with ISFULLYPLAYED set to true
TRACE 2023-06-19 22:20:53.065 [StopPlaying Event] Searching for file in FILES_STATUS with "HikariProxyPreparedStatement@1905819306 wrapping prep265149: SELECT * FROM FILES_STATUS WHERE FILES_STATUS.FILENAME = ? LIMIT 1 {1: 'D:\Users\Mik\Downloads\Video\Watched\Another Life 2019 S01E03.mkv'}" before setLastPlayed
INFO  2023-06-19 22:20:53.065 [StopPlaying Event] Another Life 2019 S01E03.mkv marked as fully played

Odd thing is when I restored my original conf I had one file that I was testing with to refuse to mark. This suggests that there could be something wrong with the data for that file in the database. Once I removed that file from the shared folder then re-added it it worked as normal. This would make sense as the entry in the database will be remade.

@SubJunk in the fully played logging there the message final decision: not fully played but there is none for when it is fully played. Could you add the message for final decision: fully played. I know it does have marked as fully played further down but it would be easier to find the result by doing a search on final decision:. This also might help you to track what is causing this as it seems to be something to do with this decision, or updating the database.

Fredo1650 · 2023-08-03T00:41:38Z

Hello, UMS 13.5.0 still does not mark the media fully played, the problem still persists to this day, attached the UMS log
Best regards Fredo
_ums_dbg_2023-08-03-02-28.zip

SubJunk · 2023-08-03T04:47:13Z

@Fredo1650 hi, I can see in your logs that the video was stopped too soon for us to consider it full played. You stopped it at 2977 seconds, but the minimum needed was 3007 seconds, which is 92% of the total duration of 3268 seconds.
You can change the 92% part to anything you want by setting the resume_back property in UMS.conf, e.g.
resume_back = 80
I hope that helps

Fredo1650 · 2023-08-20T21:10:57Z

Hello, I followed your @SubJunk advice and thank you, but that didn't change the problem, the media are still not marked.
I did a clean reinstall with default settings.
I launched the media until the end and the launch of the other episode, full duration 00:41:54
I also noticed that UMS marks that the media stop a few minutes before the end when the film is not yet finished. (UMS Start 21:54:30 End 22:34:18) End of episode 22:36:24
I attach the log of UMS 13.5.0

TRACE 2023-08-20 22:34:18.876 [StopPlaying Event] net.pms.dlna.MediaMonitor Fully Played feature logging:
TRACE 2023-08-20 22:34:18.876 [StopPlaying Event] net.pms.dlna.MediaMonitor duration: 2514.984
TRACE 2023-08-20 22:34:18.876 [StopPlaying Event] net.pms.dlna.MediaMonitor getLastStartPosition: 2514.9837761986455
TRACE 2023-08-20 22:34:18.876 [StopPlaying Event] net.pms.dlna.MediaMonitor getStartTime: 1692561270390
TRACE 2023-08-20 22:34:18.876 [StopPlaying Event] net.pms.dlna.MediaMonitor getLastStartSystemTime: 1.692563654871E12
TRACE 2023-08-20 22:34:18.877 [StopPlaying Event] net.pms.dlna.MediaMonitor elapsed: 2518.9887761986456
TRACE 2023-08-20 22:34:18.877 [StopPlaying Event] net.pms.dlna.MediaMonitor minimum play time needed: 2313.78528
TRACE 2023-08-20 22:34:18.877 [StopPlaying Event] net.pms.dlna.MediaMonitor final decision: not legitimate playback
ums_dbg_2023-08-20-22-37.zip

Fredo1650 · 2023-08-25T19:50:25Z

Hello, in this photo attached a description of the problem on another series, the episodes are fully played passing one after the other, there were no stops, only 3 episodes are marked.

Can you help me fix this untagged multimedia bug?

Episode 4:
TRACE 2023-08-25 20:04:15.967 [StopPlaying Event] net.pms.dlna.MediaMonitor Fully Played feature logging:
TRACE 2023-08-25 20:04:15.967 [StopPlaying Event] net.pms.dlna.MediaMonitor duration: 2611.56
TRACE 2023-08-25 20:04:15.967 [StopPlaying Event] net.pms.dlna.MediaMonitor getLastStartPosition: 2611.5604874653322
TRACE 2023-08-25 20:04:15.967 [StopPlaying Event] net.pms.dlna.MediaMonitor getStartTime: 1692984095801
TRACE 2023-08-25 20:04:15.967 [StopPlaying Event] net.pms.dlna.MediaMonitor getLastStartSystemTime: 1.692986651963E12
TRACE 2023-08-25 20:04:15.967 [StopPlaying Event] net.pms.dlna.MediaMonitor elapsed: 2615.564487465332
TRACE 2023-08-25 20:04:15.967 [StopPlaying Event] net.pms.dlna.MediaMonitor minimum play time needed: 2402.6352
TRACE 2023-08-25 20:04:15.967 [StopPlaying Event] net.pms.dlna.MediaMonitor final decision: not legitimate playback

Episode 5:
TRACE 2023-08-25 20:49:15.390 [StopPlaying Event] net.pms.dlna.MediaMonitor Fully Played feature logging:
TRACE 2023-08-25 20:49:15.390 [StopPlaying Event] net.pms.dlna.MediaMonitor duration: 2685.4
TRACE 2023-08-25 20:49:15.390 [StopPlaying Event] net.pms.dlna.MediaMonitor getLastStartPosition: 2685.39982457398
TRACE 2023-08-25 20:49:15.390 [StopPlaying Event] net.pms.dlna.MediaMonitor getStartTime: 1692986710199
TRACE 2023-08-25 20:49:15.390 [StopPlaying Event] net.pms.dlna.MediaMonitor getLastStartSystemTime: 1.692989351385E12
TRACE 2023-08-25 20:49:15.390 [StopPlaying Event] net.pms.dlna.MediaMonitor elapsed: 2689.40482457398
TRACE 2023-08-25 20:49:15.390 [StopPlaying Event] net.pms.dlna.MediaMonitor minimum play time needed: 2470.568
TRACE 2023-08-25 20:49:15.390 [StopPlaying Event] net.pms.dlna.MediaMonitor final decision: not legitimate playback

ums_dbg_2023-08-25-20-51.zip

SubJunk · 2023-08-25T21:28:07Z

I see what is happening. In the background, the TV is sending a request for the end of the video before it is finished. From the logs, there are 4 requests for that video that happen:

1:

GET /get/61/Fear+The+Walking+Dead+S05E04.mkv HTTP/1.0

HEADER:
  Range: bytes=0-
  getcontentFeatures.dlna.org: 1
  transferMode.dlna.org: Streaming
  getMediaInfo.sec: 1
  Host: 192.168.1.31:5001

2:

GET /get/61/Fear+The+Walking+Dead+S05E04.mkv HTTP/1.0

HEADER:
  Range: bytes=842282369-
  getcontentFeatures.dlna.org: 1
  transferMode.dlna.org: Streaming
  Host: 192.168.1.31:5001

3:

GET /get/61/Fear+The+Walking+Dead+S05E04.mkv HTTP/1.0

HEADER:
  Range: bytes=1986-
  getcontentFeatures.dlna.org: 1
  transferMode.dlna.org: Streaming
  Host: 192.168.1.31:5001

4:

GET /get/61/Fear+The+Walking+Dead+S05E04.mkv HTTP/1.0

HEADER:
  Range: bytes=842294852-
  getcontentFeatures.dlna.org: 1
  transferMode.dlna.org: Streaming
  Host: 192.168.1.31:5001

which is annoying because it breaks my logic for another fix. I'll have to think about how to fix this

SubJunk · 2023-08-27T05:43:51Z

I have a possible fix, can you please test it?
https://www.universalmediaserver.com/uploads/UMS-3947-Fredo1650.exe

Fredo1650 · 2023-08-27T20:21:36Z

Hello @SubJunk I have just read several episodes, it works correctly for the moment with the version that you modified on the previous post, the episodes have all been marked.
Can you integrate it into the next UMS update, thank you for this very good work and this very good software.

Below the latest UMS logs after the correction
ums_dbg_2023-08-27-14-56 Episode 4 .zip
ums_dbg_2023-08-27-21-36 Episode 5 et 6.zip

SubJunk · 2023-08-28T04:54:02Z

@Fredo1650 thank you for the fast testing, and for reporting the bug. Yes this will make it into the release after 13.6.0

SurfaceS mentioned this issue Jun 29, 2023

log more fully played #3962

Merged

SubJunk closed this as completed Aug 28, 2023

SubJunk mentioned this issue Aug 28, 2023

Attempt to store the last legitimate playback time for a resource #4049

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Marking media played entirely #3947

Marking media played entirely #3947

Fredo1650 commented Jun 17, 2023

Mik-S-UMS commented Jun 17, 2023

Fredo1650 commented Jun 18, 2023

Mik-S-UMS commented Jun 18, 2023

Fredo1650 commented Jun 18, 2023

Mik-S-UMS commented Jun 18, 2023

Fredo1650 commented Jun 18, 2023

Mik-S-UMS commented Jun 18, 2023

Fredo1650 commented Jun 18, 2023 •

edited

Mik-S-UMS commented Jun 19, 2023

Fredo1650 commented Aug 3, 2023

SubJunk commented Aug 3, 2023

Fredo1650 commented Aug 20, 2023 •

edited

Fredo1650 commented Aug 25, 2023 •

edited

SubJunk commented Aug 25, 2023

SubJunk commented Aug 27, 2023

Fredo1650 commented Aug 27, 2023

SubJunk commented Aug 28, 2023

Marking media played entirely #3947

Marking media played entirely #3947

Comments

Fredo1650 commented Jun 17, 2023

Mik-S-UMS commented Jun 17, 2023

Fredo1650 commented Jun 18, 2023

Mik-S-UMS commented Jun 18, 2023

Fredo1650 commented Jun 18, 2023

Mik-S-UMS commented Jun 18, 2023

Fredo1650 commented Jun 18, 2023

Mik-S-UMS commented Jun 18, 2023

Fredo1650 commented Jun 18, 2023 • edited

Mik-S-UMS commented Jun 19, 2023

Fredo1650 commented Aug 3, 2023

SubJunk commented Aug 3, 2023

Fredo1650 commented Aug 20, 2023 • edited

Fredo1650 commented Aug 25, 2023 • edited

SubJunk commented Aug 25, 2023

SubJunk commented Aug 27, 2023

Fredo1650 commented Aug 27, 2023

SubJunk commented Aug 28, 2023

Fredo1650 commented Jun 18, 2023 •

edited

Fredo1650 commented Aug 20, 2023 •

edited

Fredo1650 commented Aug 25, 2023 •

edited