Youtube ads neither skipped nor muted on CC with Google TV

[schumi4]

The ads don't show up in the log or mute/skip, skipping segments works though. Casting to Chromecast with Google TV (or Android TV, it also needs a Youtube API key). Older 'standard' Chromecasts on same network work fine.

[gabe565]

Interesting. I'm also using a Chromecast with Google TV and it worked last I checked...hopefully something didn't change in the Cast API. I'll see if I can replicate this!

Could you set CSS_LOG_LEVEL=debug to see if anything useful gets logged?

[schumi4]

Log only shows the continuous msg=Update device also during ads, nothing else gets logged. Segments get skipped as usual.

[gabe565]

Thanks, that's helpful. Sounds like ads aren't being detected for your device. Still planning to try to replicate!

[pengi]

I got the same issue when testing. This is the log I got (with actual video title removed though, but it was the title of the video I watched, so it detected it)

My comments inline for what I did

time=2023-10-02T20:30:57.493Z level=INFO msg="CastSponsorSkip v0.5.0 (73d1f7a)"
time=2023-10-02T20:30:57.494Z level=INFO msg="Searching for devices..."
time=2023-10-02T20:30:57.799Z level=INFO msg="Connected to cast device." device="Living Room TV"
time=2023-10-02T20:30:58.299Z level=DEBUG msg=Update device="Living Room TV"
time=2023-10-02T20:31:08.369Z level=DEBUG msg=Update device="Living Room TV"
time=2023-10-02T20:31:18.513Z level=DEBUG msg=Update device="Living Room TV"

Started video

time=2023-10-02T20:31:18.647Z level=INFO msg="Video ID not found. Searching for video on YouTube..." device="Living Room TV"
time=2023-10-02T20:31:18.647Z level=DEBUG msg="Searching for video ID" query="\"channelname\"+intitle:\"videotitle\""
time=2023-10-02T20:31:19.256Z level=DEBUG msg="Searching for video ID" query="\"channelname\"+intitle:\"videotitle\""
time=2023-10-02T20:31:20.297Z level=DEBUG msg="Searching for video ID" query="\"channelname\"+intitle:\"videotitle\""

Entered a segment of ads, nothing skipped

time=2023-10-02T20:31:22.339Z level=DEBUG msg="Searching for video ID" query="\"channelname\"+intitle:\"videotitle\""
time=2023-10-02T20:31:26.378Z level=DEBUG msg="Searching for video ID" query="\"channelname\"+intitle:\"videotitle\""

I'm testing with:

[Service]
Environment="CSS_PAUSED_INTERVAL=10s"
Environment="CSS_YOUTUBE_API_KEY=--api key--"
Environment="CSS_LOG_LEVEL=debug"

It also seems to not continue to log when changing to a new video, and the logging of "Searching for video ID " seems to be more seldom. So seems like it gets stuck somewhere

[gabe565]

I've been doing some testing and so far ad skip works reliably on a Chromecast Ultra and a Nest Hub. I don't think this is due to the device type, but I have another thought.

@pengi Thanks for the log and the extra info! Your log made me realize the retry logic for the YouTube search might be getting in the way of ad skip. When a video is found, it will log the video information, but that never happened here. Instead, it kept retrying the search. This is currently expected: if the YouTube search fails, it will pause the update cycle and retry up to 10 times with an exponential backoff. Could you let that search happen 10 times and see if an error is printed?

It seems like I should improve the retry logic, and I should also log the first error instead of waiting for the last. I may change it to just log every error. That could get chatty but I think more info would have more easily shown what's going on here.

[gabe565]

I just found a couple more bugs that could be contributing to this:

1. When the YouTube search fails, the update interval is changed to the slower "paused" interval. I originally added this before ad skip was supported. It is only causing issues now so I'll remove it.
2. If the YouTube search returns no videos, the log message is suppressed. This seemed to make sense at first, but I'd rather that get logged.

I'll fix all of this and release an update soon. Hopefully it helps 🤞

[pengi]

Yeah, it definitely looks like exponential backoff, and it seems to stop after 10 times. But no comment afterwards.

I'm trying to setup a go development environment here too to see if I can investigate a bit myself, but meanwhile, here is the log.

time=2023-10-03T06:45:24.116Z level=INFO msg="CastSponsorSkip v0.5.0 (73d1f7a)"
time=2023-10-03T06:45:24.117Z level=INFO msg="Searching for devices..."
time=2023-10-03T06:45:24.264Z level=INFO msg="Connected to cast device." device="Living Room TV"
time=2023-10-03T06:45:24.766Z level=DEBUG msg=Update device="Living Room TV"
time=2023-10-03T06:45:30.976Z level=DEBUG msg=Update device="Living Room TV"
time=2023-10-03T06:45:40.996Z level=DEBUG msg=Update device="Living Room TV"
time=2023-10-03T06:45:41.079Z level=INFO msg="Video ID not found. Searching for video on YouTube..." device="Living Room TV"
time=2023-10-03T06:45:41.079Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:45:41.706Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:45:42.745Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:45:44.783Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:45:48.810Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:45:56.880Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:46:12.948Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:46:45.009Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:47:49.048Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:49:57.091Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:50:24.329Z level=DEBUG msg="Ignoring device." device="Living Room TV" reason="Already connected"

I also have a run where the "ignoring device" happened before the last "searching for video id"

time=2023-10-03T06:40:41.894Z level=INFO msg="Video ID not found. Searching for video on YouTube..." device="Living Room TV"
time=2023-10-03T06:40:41.894Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:40:42.496Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:40:43.539Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:40:45.586Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:40:49.657Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:40:57.685Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:41:13.758Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:41:45.788Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:42:49.828Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""
time=2023-10-03T06:44:29.198Z level=DEBUG msg="Ignoring device." device="Living Room TV" reason="Already connected"
time=2023-10-03T06:44:57.901Z level=DEBUG msg="Searching for video ID" query="\"channel\"+intitle:\"video\""

In both runs, the retries was longer than the video clip itself, so had to scroll back a couple of times during playback, but that didn't seem to reset anything for what I could tell... but not sure.

[gabe565]

@pengi The "ignoring device" log is unrelated. That gets logged when a device is discovered that already has an active connection.

[pengi]

I got the go enviornment up and running and found the error.

Added some logging:

diff --git a/internal/youtube/youtube.go b/internal/youtube/youtube.go
index 7ad89fc..0dbf6b0 100644
--- a/internal/youtube/youtube.go
+++ b/internal/youtube/youtube.go
@@ -43,6 +43,7 @@ func QueryVideoId(ctx context.Context, artist, title string) (string, error) {
                Context(ctx).
                Do()
        if err != nil {
+               slog.Debug("error", "response", response, "err", err)
                return "", err
        }

and got:

level=DEBUG msg=error response=<nil> err="googleapi: Error 403: YouTube Data API v3 has not been used in project XXXX before or it is disabled. Enable it by visiting https://console.developers.google.com/apis/api/youtube.googleapis.com/overview?project=XXXX then retry. If you enabled this API recently, wait a few minutes for the action to propagate to our systems and retry.\nDetails:\n[\n  {\n    \"@type\": \"type.googleapis.com/google.rpc.Help\",\n    \"links\": [\n      {\n        \"description\": \"Google developers console API activation\",\n        \"url\": \"https://console.developers.google.com/apis/api/youtube.googleapis.com/overview?project=XXXX\"\n      }\n    ]\n  },\n  {\n    \"@type\": \"type.googleapis.com/google.rpc.ErrorInfo\",\n    \"domain\": \"googleapis.com\",\n    \"metadata\": {\n      \"consumer\": \"projects/XXXX\",\n      \"service\": \"youtube.googleapis.com\"\n    },\n    \"reason\": \"SERVICE_DISABLED\"\n  }\n]\n, accessNotConfigured"

Or slightly easier formatted:

googleapi: Error 403: YouTube Data API v3 has not been used in project XXXX before or it is disabled. Enable it by visiting https://console.developers.google.com/apis/api/youtube.googleapis.com/overview?project=XXXX then retry. If you enabled this API recently, wait a few minutes for the action to propagate to our systems and retry.
Details:
[
  {
    "@type": "type.googleapis.com/google.rpc.Help",
    "links": [
      {
        "description": "Google developers console API activation",
        "url": "https://console.developers.google.com/apis/api/youtube.googleapis.com/overview?project=XXXX"
      }
    ]
  },
  {
    "@type": "type.googleapis.com/google.rpc.ErrorInfo",
    "domain": "googleapis.com",
    "metadata": {
      "consumer": "projects/XXXX",
      "service": "youtube.googleapis.com"
    },
    "reason": "SERVICE_DISABLED"
  }
]
, accessNotConfigured

So when I simply enabled the YouTube v3 API for my API key it started working.

Think it's a case of error handling and reporting for API responses, to be helpful with outputs to point users towards how to fix it.

So now it works fine, thanks for the tool :)

[pengi]

@pengi The "ignoring device" log is unrelated. That gets logged when a device is discovered that already has an active connection.

Assumed so :) was thinking if if wasn't multitheaded, it could be helpful to know if the retry code had exited, or something similar

[gabe565]

I just pushed an update to run the YouTube search and the SponsorBlock queries concurrently so that ad skip doesn't get blocked. It isn't released yet, but it will be soon 🙂

This update will also improve YouTube API logging.

Assumed so :) was thinking if if wasn't multitheaded, it could be helpful to know if the retry code had exited, or something similar

It actually is multithreaded! Discovery and the update flow for each device all run independently of each other.