Universalmediaserver: Fully played when not able to play file

[pipin77]

When a video file could not be played with an error notice, the file is nevertheless marked as fully played.
Imo this was not the case before 7.0 .

[SubJunk]

Is this still happening?

[pipin77]

Yes, still the same error.

[SubJunk]

Can you please attach a trace log? I just checked and there is good logging there which should tell us what the fix should be

[pipin77]

Will do.

[SubJunk]

@pipin77 bump

[pipin77]

@pipin77 bump

Sorry, I'm pretty busy right now.
I will try to do a trace log.

[SubJunk]

I reproduced this just now and I can see our logging has this chain of events which ultimately seems like the renderer has done a wrong thing, but maybe that's not a full interpretation:

VLC asks for the file:

GET /get/280/file.mkv HTTP/1.1

HEADER:
  Host: 192.168.1.177:5001
  Accept: */*
  Accept-Language: en_US
  User-Agent: VLC/3.0.11.1 LibVLC/3.0.11.1
  Range: bytes=0-

We respond:

TRACE 2021-03-17 09:47:36.530 [HTTPv2 Request Worker 15] Transfer response sent to VLC for iOS:

HEADER:
  HTTP/1.1 206 Partial Content (non-chunked)
  Content-Type: video/x-matroska
  Content-Range: bytes 0-1399584989/1399584990
  Accept-Ranges: bytes
  Connection: keep-alive
  Server: Windows_10-amd64-10.0, UPnP/1.0 DLNADOC/1.50, UMS/10.3.1-SNAPSHOT
  Content-Length: 1399584990

VLC asks for the end of the file:

TRACE 2021-03-17 09:47:36.626 [HTTPv2 Request Worker 16] Received a nullrequest from VLC for iOS (192.168.1.174:49594):

GET /get/280/file.mkv HTTP/1.1

HEADER:
  Host: 192.168.1.177:5001
  Accept: */*
  Accept-Language: en_US
  User-Agent: VLC/3.0.11.1 LibVLC/3.0.11.1
  Range: bytes=1398656036-
.

We interpret that and send the remaining last chunk:

TRACE 2021-03-17 09:47:36.626 [HTTPv2 Request Worker 16] Asked stream chunk : ByteRange [start=1398656036, end=-1] of file.mkv and player null
TRACE 2021-03-17 09:47:36.626 [HTTPv2 Request Worker 16] Estimating seek position from byte range:
TRACE 2021-03-17 09:47:36.626 [HTTPv2 Request Worker 16]    media.getBitrate: 7802679
TRACE 2021-03-17 09:47:36.626 [HTTPv2 Request Worker 16]    low: 1398656036
TRACE 2021-03-17 09:47:36.626 [HTTPv2 Request Worker 16]    lastStartPosition: 1434.0264783416055
TRACE 2021-03-17 09:47:36.627 [HTTPv2 Request Worker 16] Did not send subtitle headers because dlna.getMediaSubtitle() is null
TRACE 2021-03-17 09:47:36.627 [HTTPv2 Request Worker 16] Sending 928954 bytes.
TRACE 2021-03-17 09:47:36.629 [HTTPv2 Request Worker 16] Transfer response sent to VLC for iOS:

HEADER:
  HTTP/1.1 206 Partial Content (non-chunked)
  Content-Type: video/x-matroska
  Content-Range: bytes 1398656036-1399584989/1399584990
  Accept-Ranges: bytes
  Connection: keep-alive
  Server: Windows_10-amd64-10.0, UPnP/1.0 DLNADOC/1.50, UMS/10.3.1-SNAPSHOT
  Content-Length: 928954

Then the renderer sends us a stop playing event and we get the last position, which was at the end, so we seem to be doing the correct thing at this point:

TRACE 2021-03-17 09:47:40.942 [StopPlaying Event] Fully Played feature logging:
TRACE 2021-03-17 09:47:40.942 [StopPlaying Event]    duration: 1434.979
TRACE 2021-03-17 09:47:40.943 [StopPlaying Event]    getLastStartPosition: 1434.0264783416055
TRACE 2021-03-17 09:47:40.943 [StopPlaying Event]    getStartTime: 1615927656533
TRACE 2021-03-17 09:47:40.943 [StopPlaying Event]    getLastStartSystemTime: 1.615927656627E12
TRACE 2021-03-17 09:47:40.943 [StopPlaying Event]    elapsed: 1438.3414783416056
TRACE 2021-03-17 09:47:40.943 [StopPlaying Event]    minimum play time needed: 1320.1806800000002

I'm not sure if we are doing something wrong to make VLC request the end of the file though, that seems really strange.

[Nadahar]

I guess that depends on how you see it. Would you say that starting a video, fast forwarding close to the end and watch parts of the credits before stopping should constitute "fully played"?

I actually don't see a "simple" way to get this right. You'd need to somehow map "what parts" of the video has been watched, and then mark it when a certain threshold was met. The question is of course, should this apply per renderer, per session, or how should this be handled? How should information about what parts have been played be stored between sessions?

Another problem is that UMS doesn't really know what the renderer plays if GetPositionInfo isn't implemented in the renderer. The current "logic" is to assume that whatever has been sent to the renderer has been played, but that could be very far from the truth if the renderer has a sizeable cache. While the PS3 for example seems to have a very small cache (so this holds somewhat true), this isn't always the case. Kodi seems to cache as much as it can, so it will generally transfer the entire media as fast as the server will provide it, and then handle playback locally. UMS will then assume that it is "fully played" even if you've just actually watched a couple of minutes.

I don't quite see how a proper logic that didn't make such mistakes could be implemented with the limited/varying information that is available.

[ExSport]

The behaviour seems like VLC is checking if file played is partially or fully downloaded so it can play correctly also files streamed/downloaded in the background (well known "feature" of VLC for a decade) up to the end (as the position of the end of file is changing).
If it is the reason then marking file as fully played is not the right decision but as you guys already wrote, it will need some more robust code to achieve satisfying behaviour :)
Btw. great you all are still working on this great UMS/DMS project🥇
Take care SubJunk, Valib, Nadar and others I didn't mention 👍

[SubJunk]

Yeah I agree with you guys it isn't perfect, and some renderers make it difficult for various reasons. However it works most of the time and the penalty for getting it wrong isn't huge - by default you get a little thumbnail overlay and are still able to continue playing that file. Some of the other non-default options would make that penalty worse though.

With regards to the behaviour I saw from VLC before, that only happens occasionally - I have not been able to reproduce it again, and the same file plays perfectly. So it is not the normal behaviour for VLC I think.

@ExSport great to see you and take care too :)

[Nadahar]

@SubJunk This is just a guess, but could it be related to MP4 files where some have the metadata at the end of the file? It would make sense if VLC requested the end if it determined that to be the case, to fully parse the file before starting playback.