Nest binding throwing pub/sub errors repeatedly

Add-ons Bindings
1

I installed the Nest binding last night with the goal of integrating my wired Nest doorbell.

I’m running 3.3 snapshot build #2860.

I made it through the SDM and Pub/Sub setup process without issues. I added the SDM account thing, and it discovered my doorbell. After adding the doorbell thing from the inbox, it seemed to run ok for a while, then I started getting authentication errors every 20-30 msec. It ran for several hours that way, and I fear it hammered the Google API with well over 50k pub/sub API calls. My logs contain 44,561 of these errors about 30 msec apart, and I believe a few log files already have rolled off the system. Here’s the error:

2022-05-05 15:05:34.237 [DEBUG] [rg.openhab.binding.nest.internal.sdm.api.PubSubAPI] - Pulling messages for 'openhab-nest-binding-pubsub' subscription
2022-05-05 15:05:34.242 [DEBUG] [rg.openhab.binding.nest.internal.sdm.api.PubSubAPI] - Posting JSON to: https://pubsub.googleapis.com/v1/projects/openhab-XXXXXXX/subscriptions/openhab-nest-binding-pubsub:pull
2022-05-05 15:05:34.269 [DEBUG] [rg.openhab.binding.nest.internal.sdm.api.PubSubAPI] - Response: {
  "error": {
    "code": 401,
    "message": "Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.",
    "status": "UNAUTHENTICATED",
    "details": [
      {
        "@type": "type.googleapis.com/google.rpc.ErrorInfo",
        "reason": "ACCESS_TOKEN_TYPE_UNSUPPORTED",
        "metadata": {
          "service": "pubsub.googleapis.com",
          "method": "google.pubsub.v1.Subscriber.Pull"
        }
      }
    ]
  }
}

I’m not quite sure what I should do next. @wborn would you suggest I start over from scratch by deleting the Nest things, as well as the Google OAuth configs.

2

One other thing I should mention…

The auth code that you copy from the Google URL in the browser’s address bar can contain encoded characters that must be decoded before pasting into the the auth code field in the SDM account bridge config. In my case, the auth code was this (note the %2F), which needed to be decoded (to /) before pasting into the SDM account bridge config.

4%2F0AX4XfWh5tcFCzN68oXsXXXXXXXvD6braYYYYYYYYY5JWYQDsZZZZZZZZytmsOPAHXTozw
3

Ok, so I deleted the SDM Account and Doorbell things.

Then I added an SDM Account thing, but did not do the Pub/Sub part.

I ran a scan, which discovered the Doorbell, which I added as a thing from the inbox.

All good so far. I was getting what look like OK responses in the DEBUG log every refresh interval.

2022-05-05 16:33:56.784 [DEBUG] [org.openhab.binding.nest.internal.sdm.api.SDMAPI  ] - Response: {
  "name": "enterprises/SNIP/devices/SNIP",
  "type": "sdm.devices.types.DOORBELL",
  "assignee": "enterprises/SNIP/structures/SNIP/rooms/SNIP",
  "traits": {
    "sdm.devices.traits.Info": {
      "customName": ""
    },
    "sdm.devices.traits.CameraLiveStream": {
      "maxVideoResolution": {
        "width": 640,
        "height": 480
      },
      "videoCodecs": [
        "H264"
      ],
      "audioCodecs": [
        "AAC"
      ],
      "supportedProtocols": [
        "RTSP"
      ]
    },
    "sdm.devices.traits.CameraImage": {
      "maxImageResolution": {
        "width": 1920,
        "height": 1200
      }
    },
    "sdm.devices.traits.CameraPerson": null,
    "sdm.devices.traits.CameraSound": null,
    "sdm.devices.traits.CameraMotion": {},
    "sdm.devices.traits.CameraEventImage": {},
    "sdm.devices.traits.DoorbellChime": {}
  },
  "parentRelations": [
    {
      "parent": "enterprises/SNIP/structures/SNIP/rooms/SNIP",
      "displayName": "Front Door"
    }
  ]
}

Then after almost exactly an hour I started getting this. And these repeat in pairs every refresh interval.

2022-05-05 17:34:02.307 [DEBUG] [org.openhab.binding.nest.internal.sdm.api.SDMAPI  ] - Getting device: SNIP
2022-05-05 17:34:02.308 [DEBUG] [org.openhab.binding.nest.internal.sdm.api.SDMAPI  ] - Getting JSON from: https://smartdevicemanagement.googleapis.com/v1/enterprises/SNIP
2022-05-05 17:34:02.510 [DEBUG] [org.openhab.binding.nest.internal.sdm.api.SDMAPI  ] - SDM API error: {
  "error": {
    "code": 401,
    "message": "Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.",
    "status": "UNAUTHENTICATED"
  }
}

2022-05-05 17:34:02.510 [WARN ] [org.openhab.binding.nest.internal.sdm.api.SDMAPI  ] - SDM API error: Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
2022-05-05 17:34:02.511 [DEBUG] [org.openhab.binding.nest.internal.sdm.api.SDMAPI  ] - Response: {
  "error": {
    "code": 401,
    "message": "Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.",
    "status": "UNAUTHENTICATED"
  }
}

Is it possible that the access token is expiring and not being refreshed?

4

Unfortunately I currently don’t have a lot of time to look into this @mhilbush. :frowning:

5

I had the feeling you were a little pressed for time. No worries.

Any suggestions on where I should look to do some additional troubleshooting?

I thought about turning on DEBUG/TRACE in the core OAuth bundle(s). Maybe that will give some insight into what’s going on?

6

Looking at the logs, it definitely looks like the access token is expiring and not being refreshed. The first failure occurred 1:00:06 after I entered the auth code into the SDM Account thing.

From the OAuth debug log, I see in the AccessTokenResponse that the access token expiresIn is set to 3526 sec (58:46), and from the JSONDB, the tokenExpiresInSeconds is 10 sec.

Perhaps more importantly, I don’t see a refreshToken in the AccessTokenResponse.

2022-05-06 09:45:04.124 [DEBUG] [lient.internal.OAuthStoreHandlerImpl] - Decrypting token: AccessTokenResponse [accessToken=SNIP, tokenType=Bearer, expiresIn=3526, refreshToken=null, scope=https://www.googleapis.com/auth/sdm.service https://www.googleapis.com/auth/pubsub, state=null, createdOn=2022-05-06T08:34:57.882061]

I don’t know how the OAuth core bundle works, but without a refreshToken, I don’t know how it can get a new accessToken.

Unfortunately, I didn’t turn on debug of the OAuth core bundle until after I entered the auth code into the SDN Account thing. For my next test, I’ll try to get a full OAuth debug log to see if there’s anything enlightening.

7

Interesting discussion here about Google only supplying the refresh token on the first authorization and only the first authorization. In my case, I’ve done multiple authorizations, so it would seem that the refresh token for my oauth credentials is lost forever. It’s not in the JSONDB, and I’ll never get it again from Google. So no matter how many times I reauthorize the SDM Account thing, I’ll never get another refresh token.

This would suggest that you’re screwed if you ever reauthorize. This is because on subsequent authorizations, the OH OAuth client will store the response from the authorization. And that response will not contain a refresh token.

I suppose if I start from scratch by deleting my oauth credentials, I’ll be able to get a new refresh token. But it’s unclear what will happen upon the first access token refresh if Google doesn’t return the refresh token. OTOH, I think I saw something in the OH oauth client that uses the existing refresh token if there’s not one in the access token response.

Yes, here it does use the last refresh token if it’s not in the response.

But, I don’t understand why I’m not seeing this exception in OAuthClientServiceImpl.refreshToken(), since in my current state, there’s no refresh token in my AccessTokenResponse. Perhaps there’s something that’s preventing refreshToken from being called.

I know you’re a bit short on time @wborn. But WDYT? Does my analysis make sense? And, do you have any thoughts on what could be done?

Edit: Ah, this explains why refreshToken() isn’t being called, hence the reason for not seeing the exception.

Edit 2: After sleeping on this, I think the most annoying issue is that reauthorizing gives you a false sense of security, because everything works fine for a hour (value of expiresIn), then fails when the access token needs to be refreshed.

8

Ok, @wborn, I have some thoughts on what we can do. Hopefully you’ll have enough time to review this short proposal. :wink:

First, adding &prompt=consent to the URL for requesting the authorization code will cause oAuthService.getAccessTokenResponseByAuthorizationCode to always result in a refresh token being returned from the Google OAuth API. This behavior is described in quite a few online discussions (although it appears Google still has not updated their documentation).

Second, I would propose we add a check for the existence of a refresh token in SDMAPI.getAuthorizationHeader and PubSubAPI.getAuthorizationHeader in order to defend against any edge case where a refresh token is missing. Those methods already check for a missing access token, so it seems logical to extend those methods to also check for a refresh token. This will cause an exception and will result in the Account thing going OFFLINE with a descriptive status message.

If you’re good with this, I can submit a PR.

9

Adding &prompt=consent to the pub/sub authorization code url as mentioned by mhilbush solved the problem for me.

Maybe that could be added to the binding’s README (pub/sub configuration parameters)? openhab-addons/README.md at main · openhab/openhab-addons · GitHub

10

But I did add it to the README. I added it to the URL…

Here

https://accounts.google.com/o/oauth2/v2/auth?scope=https://www.googleapis.com/auth/pubsub&access_type=offline&prompt=consent&include_granted_scopes=true&response_type=code&redirect_uri=https://www.google.com&client_id=<ClientID>

And here

https://accounts.google.com/o/oauth2/v2/auth?scope=https://www.googleapis.com/auth/pubsub&access_type=offline&prompt=consent&include_granted_scopes=true&response_type=code&redirect_uri=https://www.google.com&client_id=1046297811237-lg27h26kln6r1nbg54jpg6nfjg6h4b3n.apps.googleusercontent.com

11

Argh, you’re right. I used the stable release docs and didn’t double check if it’s already fixed in the upcoming release. Please excuse any inconveniences.

12

Sure, no worries.