Duplicate Log Lines

[QueenLinuxGlitch]

Using newest release, but has been long-running

2023/09/05 17:45:19 INFO Skipping to timestamp. device="Living Room TV" category=sponsor from=0s to=3s 2023/09/05 17:45:19 INFO Skipping to timestamp. device="Living Room TV" category=sponsor from=0s to=3s 2023/09/05 17:45:20 INFO Skipping to timestamp. device="Living Room TV" category=sponsor from=0s to=3s 2023/09/05 17:45:21 INFO Skipping to timestamp. device="Living Room TV" category=sponsor from=1s to=3s 2023/09/05 17:45:21 INFO Skipping to timestamp. device="Living Room TV" category=sponsor from=1s to=3s

Examples of log lines showing up multiple times, potentially more than one action.

Doesn't affect experience currently, but inconsistancy is the devil, in programatic terms.

Does not happen every time, but often

[gabe565]

I haven't seen this one. I'm glad it doesn't affect the experience, but I'd like to fix it. Do you know if this started in v0.4.0 or in v0.4.1? Also, could you try to replicate with CSS_LOG_LEVEL=debug?

[gabe565]

When this happens, does the sponsorship actually get skipped? After looking at your logs some more, it seems like the skip command fails for some reason causing it to try repeatedly. This is intended, but the sponsorship should either get skipped or an error should appear so I'm not sure why neither is happening. Is this on your Chromecast Ultra?

[QueenLinuxGlitch]

1. Started back in 3.0 actually, but generally skipped segments and was incredibly sporadic
2. Usually, the video ends up not having a sponsor segment anyway, and/or I never saw it, didn't watch the whole video e.g.
3. Yup, on my Chromecast Ultra w/ Google TV

On next run, will up log level to debug and report results

EDIT: Results good so far, just a few videos in, will have more results by tomorrow night

EDIT 2: time=2023-09-07T23:39:54.091-05:00 level=INFO msg="Video ID not found. Searching for video on YouTube..." device="Living Room TV" time=2023-09-07T23:39:54.091-05:00 level=DEBUG msg="Searching for video ID" query="\"TLDR Business\"+intitle:\"Is Going Woke Killing Disney... we ran the maths\"" time=2023-09-07T23:39:54.438-05:00 level=INFO msg="Detected video stream." device="Living Room TV" video_id=5SybR3KiBMw

I thought it was supposed to be Cast Metadata Detection then Channel + title query as failover, in my results I'm seeing both, not an issue, just a misunderstanding of logic

EDIT 3: time=2023-09-07T23:58:37.838-05:00 level=DEBUG msg=Update device="Living Room TV" time=2023-09-07T23:58:37.853-05:00 level=INFO msg="Skipping to timestamp." device="Living Room TV" category=sponsor from=14m19s to=15m20s time=2023-09-07T23:58:38.338-05:00 level=DEBUG msg=Update device="Living Room TV" time=2023-09-07T23:58:38.351-05:00 level=INFO msg="Skipping to timestamp." device="Living Room TV" category=sponsor from=14m20s to=15m20s

Duplicate Skip, everything worked fine on the TV end, but log shows double

[gabe565]

I thought it was supposed to be Cast Metadata Detection then Channel + title query as failover, in my results I'm seeing both, not an issue, just a misunderstanding of logic

No, that's correct. Most devices set the video ID in the metadata, but some don't. For the devices that don't, querying YouTube is the fallback.

Duplicate Skip, everything worked fine on the TV end, but log shows double

Thanks for posting that! It still seems like the initial skip is failing for some reason. Or maybe the device isn't returning the new timestamp immediately? Interesting either way.

[gabe565]

@QueenLinuxGlitch Are you still seeing this behavior? I have a feeling this is just due to the update interval being twice per second. It seems like it tries to skip twice before it actually gets an update back from the device. I could make it not try to skip the segment twice in a row, but I'd prefer to avoid doing that to keep the code simpler. What do you think?