Testing MrMC 3.9.7 - Apple TV

[amet]

nope, and debuglog was not enabled... nothing useful in the log

[snodrog742]

nope, and debuglog was not enabled... nothing useful in the log

I think was disabled from trying the other builds

[amet]

nope, and debuglog was not enabled... nothing useful in the log

I think was disabled from trying the other builds

I'll have another look in the morning, 2AM here, vut like i said... all is good here.

I wonder if your playback stutters and we report it as stopped for that reason... just a guess but the log would tell us. in the previous log, I only see one stopped report to emby server.

[snodrog742]

nope, and debuglog was not enabled... nothing useful in the log

I think was disabled from trying the other builds

I'll have another look in the morning, 2AM here, vut like i said... all is good here.

I wonder if your playback stutters and we report it as stopped for that reason... just a guess but the log would tell us. in the previous log, I only see one stopped report to emby server.

A3CA1.log - duplicated.

Only weird thing I see is it saying playback started twice and it definitely did not.

Code: Select all

2020-05-21 20:23:47.394 Info SessionManager: Playback start reported by app MrMC 3.9-7 playing Ruling Days. Started at 1000 ms

Code: Select all

2020-05-21 20:23:49.537 Info SessionManager: Playback stopped reported by app MrMC 3.9-7 playing Ruling Days. Stopped at 1000 ms

Code: Select all

2020-05-21 20:24:07.350 Info SessionManager: Playback start reported by app MrMC 3.9-7 playing Ruling Days. Started at 1000 ms

[amet]

hm, that specific timeline is user initiated start/stop... MrMC is 2 hours behind?


so here , you can see playback started at 18:23:47 and ended at 18:23:49 by user, we have exited the VideoFullScreen.xml and gone to home screen

Code: Select all

18:23:47.309 T:6171095040   DEBUG: CurlFile::Open(0x16fd36be0) https://xxxxxx:443/emby/Sessions/Playing?CanSeek=True&IsMuted=False&IsPaused=False&ItemId=93153&MediaSourceId=93153&PlayMethod=DirectPlay&PositionTicks=10000000&QueueableMediaTypes=Video
18:23:47.574 T:6188298240   DEBUG: CDVDClock::ErrorAdjust - CDVDPlayerAudio::OutputPacket - error:-22765.569364, adjusted:-22765.569364
18:23:49.001 T:6174535680   DEBUG: CGUIWindowManager::PreviousWindow: Deactivate
18:23:49.210 T:6174535680   DEBUG: ------ Window Deinit (VideoFullScreen.xml) ------
....... ## Removed some for clarity ####
18:23:49.327 T:6178549760   DEBUG: OnPlayBackStopped: play state was 2, starting 0
18:23:49.327 T:6178549760   DEBUG: CGUIWindowHome::Announce, type: 1, from xbmc, message OnStop
18:23:49.327 T:6178549760   DEBUG: CGUIWindowHome::SetupServices() - !g_application.IsCurrentThread()
18:23:49.327 T:6171668480   DEBUG: CurlFile::Open(0x16fdc2be0) https://xxxxxxx:443/emby/Sessions/Playing/Stopped?CanSeek=True&IsMuted=False&IsPaused=False&ItemId=93153&MediaSourceId=93153&PlayMethod=DirectPlay&PositionTicks=10000000&QueueableMediaTypes=Video

below, you opened Movie dialog for the same movie(ItemId=93153) and played from there until 19:23:03

Code: Select all

18:24:02.310 T:6174535680   DEBUG: ------ Window Init (DialogVideoInfo.xml) ------
....... ## Removed some for clarity ####
18:24:02.647 T:6173388800   DEBUG: CurlFile::Open(0x16ff648c0) https://xxxxxx:443/Users/a28e914c4ae240d99a6304ee4f05a94c/Items/Latest?Fields=DateCreated%2cPremiereDate%2cCriticRating%2cOfficialRating%2cCommunityRating%2cProductionYear%2cGenres%2cMediaStreams%2cMediaSources%2cOverview%2cShortOverview%2cPath%2cImageTags%2cBackdropImageTags%2cRecursiveItemCount%2cProviderIds&GroupItems=False&IncludeItemTypes=Movie&Limit=20&ParentId=f137a2dd21bbc1b99aa5c0f6bf02a805
18:24:03.005 T:6174535680   DEBUG: ------ Window Deinit (DialogVideoInfo.xml) ------
18:24:03.024 T:6174535680    INFO: easy_aquire - Created session to https://xxxxxx
18:24:03.112 T:6173388800   DEBUG: CurlFile::Open(0x16ff64960) https://xxxxxx:443//Shows/NextUp?Fields=DateCreated%2cPremiereDate%2cCriticRating%2cOfficialRating%2cCommunityRating%2cProductionYear%2cGenres%2cMediaStreams%2cMediaSources%2cOverview%2cShortOverview%2cPath%2cImageTags%2cBackdropImageTags%2cRecursiveItemCount&Limit=20&UserId=a28e914c4ae240d99a6304ee4f05a94c
18:24:04.119 T:6174535680   DEBUG: CCurlFile::GetMimeType - https://HOSTNAME:443/Videos/93153/stream?static=true|&X-MediaBrowser-Token=EMBYTOKEN -> video/x-matroska
....... ## Removed some for clarity ####
18:24:07.195 T:6173388800   DEBUG: CurlFile::Open(0x16ff66be0) https://xxxxxx:443/emby/Sessions/Playing?CanSeek=True&IsMuted=False&IsPaused=False&ItemId=93153&MediaSourceId=93153&PlayMethod=DirectPlay&PositionTicks=10000000&QueueableMediaTypes=Video
....... ## Removed some for clarity ####
19:23:03.871 T:6178549760   DEBUG: CGUIWindowHome::Announce, type: 1, from xbmc, message OnStop
19:23:03.871 T:6171668480   DEBUG: CurlFile::Open(0x16fdc2be0) https://xxxxxxx:443/emby/Sessions/Playing/Stopped?CanSeek=True&IsMuted=False&IsPaused=False&ItemId=93153&MediaSourceId=93153&PlayMethod=DirectPlay&PositionTicks=33350000000&QueueableMediaTypes=Video

this is definitely you start/stop/starting it but emby still shouldn't have "scrobbled" the movie after first stop as we reported stop ticks as 1sec. does emby log show setting watched status to trakt @ 2020-05-21 20:23:49.537 stop event?

[snodrog742]

hm, that specific timeline is user initiated start/stop... MrMC is 2 hours behind?


so here , you can see playback started at 18:23:47 and ended at 18:23:49 by user, we have exited the VideoFullScreen.xml and gone to home screen

Code: Select all

18:23:47.309 T:6171095040   DEBUG: CurlFile::Open(0x16fd36be0) https://xxxxxx:443/emby/Sessions/Playing?CanSeek=True&IsMuted=False&IsPaused=False&ItemId=93153&MediaSourceId=93153&PlayMethod=DirectPlay&PositionTicks=10000000&QueueableMediaTypes=Video
18:23:47.574 T:6188298240   DEBUG: CDVDClock::ErrorAdjust - CDVDPlayerAudio::OutputPacket - error:-22765.569364, adjusted:-22765.569364
18:23:49.001 T:6174535680   DEBUG: CGUIWindowManager::PreviousWindow: Deactivate
18:23:49.210 T:6174535680   DEBUG: ------ Window Deinit (VideoFullScreen.xml) ------
....... ## Removed some for clarity ####
18:23:49.327 T:6178549760   DEBUG: OnPlayBackStopped: play state was 2, starting 0
18:23:49.327 T:6178549760   DEBUG: CGUIWindowHome::Announce, type: 1, from xbmc, message OnStop
18:23:49.327 T:6178549760   DEBUG: CGUIWindowHome::SetupServices() - !g_application.IsCurrentThread()
18:23:49.327 T:6171668480   DEBUG: CurlFile::Open(0x16fdc2be0) https://xxxxxxx:443/emby/Sessions/Playing/Stopped?CanSeek=True&IsMuted=False&IsPaused=False&ItemId=93153&MediaSourceId=93153&PlayMethod=DirectPlay&PositionTicks=10000000&QueueableMediaTypes=Video

below, you opened Movie dialog for the same movie(ItemId=93153) and played from there until 19:23:03

Code: Select all

18:24:02.310 T:6174535680   DEBUG: ------ Window Init (DialogVideoInfo.xml) ------
....... ## Removed some for clarity ####
18:24:02.647 T:6173388800   DEBUG: CurlFile::Open(0x16ff648c0) https://xxxxxx:443/Users/a28e914c4ae240d99a6304ee4f05a94c/Items/Latest?Fields=DateCreated%2cPremiereDate%2cCriticRating%2cOfficialRating%2cCommunityRating%2cProductionYear%2cGenres%2cMediaStreams%2cMediaSources%2cOverview%2cShortOverview%2cPath%2cImageTags%2cBackdropImageTags%2cRecursiveItemCount%2cProviderIds&GroupItems=False&IncludeItemTypes=Movie&Limit=20&ParentId=f137a2dd21bbc1b99aa5c0f6bf02a805
18:24:03.005 T:6174535680   DEBUG: ------ Window Deinit (DialogVideoInfo.xml) ------
18:24:03.024 T:6174535680    INFO: easy_aquire - Created session to https://xxxxxx
18:24:03.112 T:6173388800   DEBUG: CurlFile::Open(0x16ff64960) https://xxxxxx:443//Shows/NextUp?Fields=DateCreated%2cPremiereDate%2cCriticRating%2cOfficialRating%2cCommunityRating%2cProductionYear%2cGenres%2cMediaStreams%2cMediaSources%2cOverview%2cShortOverview%2cPath%2cImageTags%2cBackdropImageTags%2cRecursiveItemCount&Limit=20&UserId=a28e914c4ae240d99a6304ee4f05a94c
18:24:04.119 T:6174535680   DEBUG: CCurlFile::GetMimeType - https://HOSTNAME:443/Videos/93153/stream?static=true|&X-MediaBrowser-Token=EMBYTOKEN -> video/x-matroska
....... ## Removed some for clarity ####
18:24:07.195 T:6173388800   DEBUG: CurlFile::Open(0x16ff66be0) https://xxxxxx:443/emby/Sessions/Playing?CanSeek=True&IsMuted=False&IsPaused=False&ItemId=93153&MediaSourceId=93153&PlayMethod=DirectPlay&PositionTicks=10000000&QueueableMediaTypes=Video
....... ## Removed some for clarity ####
19:23:03.871 T:6178549760   DEBUG: CGUIWindowHome::Announce, type: 1, from xbmc, message OnStop
19:23:03.871 T:6171668480   DEBUG: CurlFile::Open(0x16fdc2be0) https://xxxxxxx:443/emby/Sessions/Playing/Stopped?CanSeek=True&IsMuted=False&IsPaused=False&ItemId=93153&MediaSourceId=93153&PlayMethod=DirectPlay&PositionTicks=33350000000&QueueableMediaTypes=Video

this is definitely you start/stop/starting it but emby still shouldn't have "scrobbled" the movie after first stop as we reported stop ticks as 1sec. does emby log show setting watched status to trakt @ 2020-05-21 20:23:49.537 stop event?

I 100% never stopped. It reported the same for two more shows that night. Why would I stop everything I watch at 1 second and restart?

[davilla]

Double tap on play/pause button ?

[amet]

Hm, not sure what to say... I just read the log... wasn’t sitting next to you

Playback was started, stopped.. showed a brief info dialog and played again.

Do you have match rate enabled in Apple TV ? It might be that MrMC restarts due to the screen Frame rate change.

[snodrog742]

Hm, not sure what to say... I just read the log... wasn’t sitting next to you

Playback was started, stopped.. showed a brief info dialog and played again.

Do you have match rate enabled in Apple TV ? It might be that MrMC restarts due to the screen Frame rate change.

Yes

[snodrog742]

Double tap on play/pause button ?

Unfortunately, no.

@amet I totally get what logs say but that's why I'm trying to figure out why. I deal with facts of logs every day so totally understand but there has to be logic why.