Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[oauth] Error fetching access token. Invalid oauth code? Please generate a new one. #3447

Closed
Mark-VG opened this issue Mar 12, 2023 · 33 comments · Fixed by #3449
Closed

[oauth] Error fetching access token. Invalid oauth code? Please generate a new one. #3447

Mark-VG opened this issue Mar 12, 2023 · 33 comments · Fixed by #3449

Comments

@Mark-VG
Copy link

Mark-VG commented Mar 12, 2023

I am running on a Windows 10 PC:

Operating system: Windows 10/10.0 (amd64)
Java Runtime: Azul Systems, Inc. 17.0.6 (Zulu17.40+19-CA)

Since upgrading from 3.4.2 to 4.0.0-SNAPSHOT and now 4.0.0.M1 I am getting errors trying to authenticate for Google TTS:

Error fetching access token. Invalid oauth code? Please generate a new one.

When logged using TRACE logging:

log:set TRACE org.openhab.voice.googletts
log:set TRACE org.openhab.core.auth.oauth2client

I get:

11:22:33.943 [DEBUG] [e.googletts.internal.GoogleTTSService] - bundle org.openhab.voice.googletts:4.0.0.M1 (257)[org.openhab.voice.googletts.internal.GoogleTTSService(336)] : ConfigurableComponentHolder configuration updated for pid org.openhab.voice.googletts with change count 61
11:22:33.944 [DEBUG] [e.googletts.internal.GoogleTTSService] - bundle org.openhab.voice.googletts:4.0.0.M1 (257)[org.openhab.voice.googletts.internal.GoogleTTSService(336)] : Querying state active
11:22:33.945 [DEBUG] [e.googletts.internal.GoogleTTSService] - bundle org.openhab.voice.googletts:4.0.0.M1 (257)[org.openhab.voice.googletts.internal.GoogleTTSService(336)] : Querying state active
11:22:33.945 [DEBUG] [e.googletts.internal.GoogleTTSService] - bundle org.openhab.voice.googletts:4.0.0.M1 (257)[org.openhab.voice.googletts.internal.GoogleTTSService(336)] : invoking modified: updateConfig: parameters [org.apache.felix.scr.impl.helper.ReadOnlyDictionary]
11:22:33.946 [DEBUG] [e.googletts.internal.GoogleTTSService] - Updating configuration
11:22:33.946 [TRACE] [e.googletts.internal.GoogleTTSService] - New configuration: GoogleTTSConfig{pitch=0.0, speakingRate=1.0, volumeGainDb=0.0, purgeCache=true}
11:22:33.947 [DEBUG] [ice.googletts.internal.GoogleCloudAPI] - Trying to get access and refresh tokens.
11:22:34.122 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter grant_type, value authorization_code
11:22:34.123 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter code, value <REDACT>
11:22:34.124 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter redirect_uri, value https://www.google.com
11:22:34.124 [DEBUG] [.oauth2client.internal.OAuthConnector] - Setting authentication for clientId <REDACT> Using basic auth false
11:22:35.564 [DEBUG] [ice.googletts.internal.GoogleCloudAPI] - Error fetching access token: Exception in oauth communication, grant type authorization_code
org.openhab.core.auth.client.oauth2.OAuthException: Exception in oauth communication, grant type authorization_code
        at org.openhab.core.auth.oauth2client.internal.OAuthConnector.doRequest(OAuthConnector.java:331) ~[?:?]
        at org.openhab.core.auth.oauth2client.internal.OAuthConnector.grantTypeAuthorizationCode(OAuthConnector.java:220) ~[?:?]
        at org.openhab.core.auth.oauth2client.internal.OAuthClientServiceImpl.getAccessTokenResponseByAuthorizationCode(OAuthClientServiceImpl.java:211) ~[?:?]
        at org.openhab.voice.googletts.internal.GoogleCloudAPI.getAccessToken(GoogleCloudAPI.java:192) ~[?:?]
        at org.openhab.voice.googletts.internal.GoogleCloudAPI.setConfig(GoogleCloudAPI.java:154) ~[?:?]
        at org.openhab.voice.googletts.internal.GoogleTTSService.updateConfig(GoogleTTSService.java:240) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:245) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:687) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:531) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:317) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:307) ~[?:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeModifiedMethod(SingleComponentManager.java:856) ~[?:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.modify(SingleComponentManager.java:810) ~[?:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.reconfigure(SingleComponentManager.java:725) ~[?:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.reconfigure(SingleComponentManager.java:686) ~[?:?]
        at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.configurationUpdated(ConfigurableComponentHolder.java:440) ~[?:?]
        at org.apache.felix.scr.impl.manager.RegionConfigurationSupport.configurationEvent(RegionConfigurationSupport.java:347) ~[?:?]
        at org.apache.felix.scr.impl.manager.RegionConfigurationSupport$2.configurationEvent(RegionConfigurationSupport.java:115) ~[?:?]
        at org.apache.felix.cm.impl.ConfigurationManager$FireConfigurationEvent.sendEvent(ConfigurationManager.java:1723) ~[?:?]
        at org.apache.felix.cm.impl.ConfigurationManager$FireConfigurationEvent.run(ConfigurationManager.java:1664) ~[?:?]
        at org.apache.felix.cm.impl.UpdateThread.run0(UpdateThread.java:122) ~[?:?]
        at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:84) ~[?:?]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: com.google.gson.JsonIOException: Failed making field 'java.time.Instant#seconds' accessible; either change its visibility or write a custom TypeAdapter for its declaring type
        at com.google.gson.internal.reflect.ReflectionHelper.makeAccessible(ReflectionHelper.java:23) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory.getBoundFields(ReflectiveTypeAdapterFactory.java:203) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory.create(ReflectiveTypeAdapterFactory.java:112) ~[?:?]
        at com.google.gson.Gson.getAdapter(Gson.java:531) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory.createBoundField(ReflectiveTypeAdapterFactory.java:137) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory.getBoundFields(ReflectiveTypeAdapterFactory.java:211) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory.create(ReflectiveTypeAdapterFactory.java:112) ~[?:?]
        at com.google.gson.Gson.getAdapter(Gson.java:531) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:1057) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:1016) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:959) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:927) ~[?:?]
        at org.openhab.core.auth.oauth2client.internal.OAuthConnector.doRequest(OAuthConnector.java:308) ~[?:?]
        ... 27 more
Caused by: java.lang.reflect.InaccessibleObjectException: Unable to make field private final long java.time.Instant.seconds accessible: module java.base does not "opens java.time" to unnamed module @72d10ef7
        at java.lang.reflect.AccessibleObject.checkCanSetAccessible(AccessibleObject.java:354) ~[?:?]
        at java.lang.reflect.AccessibleObject.checkCanSetAccessible(AccessibleObject.java:297) ~[?:?]
        at java.lang.reflect.Field.checkCanSetAccessible(Field.java:178) ~[?:?]
        at java.lang.reflect.Field.setAccessible(Field.java:172) ~[?:?]
        at com.google.gson.internal.reflect.ReflectionHelper.makeAccessible(ReflectionHelper.java:20) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory.getBoundFields(ReflectiveTypeAdapterFactory.java:203) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory.create(ReflectiveTypeAdapterFactory.java:112) ~[?:?]
        at com.google.gson.Gson.getAdapter(Gson.java:531) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory.createBoundField(ReflectiveTypeAdapterFactory.java:137) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory.getBoundFields(ReflectiveTypeAdapterFactory.java:211) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory.create(ReflectiveTypeAdapterFactory.java:112) ~[?:?]
        at com.google.gson.Gson.getAdapter(Gson.java:531) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:1057) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:1016) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:959) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:927) ~[?:?]
        at org.openhab.core.auth.oauth2client.internal.OAuthConnector.doRequest(OAuthConnector.java:308) ~[?:?]
        ... 27 more
11:22:35.574 [WARN ] [ice.googletts.internal.GoogleCloudAPI] - Error initializing Google Cloud TTS service: Error fetching access token. Invalid authcode? Please generate a new one.
11:22:35.575 [DEBUG] [ice.googletts.internal.GoogleCloudAPI] - Cache purged.
11:22:35.576 [DEBUG] [e.googletts.internal.GoogleTTSService] - bundle org.openhab.voice.googletts:4.0.0.M1 (257)[org.openhab.voice.googletts.internal.GoogleTTSService(336)] : invoked modified: updateConfig
11:22:35.577 [DEBUG] [e.googletts.internal.GoogleTTSService] - bundle org.openhab.voice.googletts:4.0.0.M1 (257)[org.openhab.voice.googletts.internal.GoogleTTSService(336)] : No change in target property for dependency $000: currently registered: true
11:22:35.577 [DEBUG] [e.googletts.internal.GoogleTTSService] - bundle org.openhab.voice.googletts:4.0.0.M1 (257)[org.openhab.voice.googletts.internal.GoogleTTSService(336)] : No change in target property for dependency $001: currently registered: true
11:22:35.578 [DEBUG] [e.googletts.internal.GoogleTTSService] - bundle org.openhab.voice.googletts:4.0.0.M1 (257)[org.openhab.voice.googletts.internal.GoogleTTSService(336)] : No change in target property for dependency osgi.ds.satisfying.condition: currently registered: true
11:22:35.578 [DEBUG] [e.googletts.internal.GoogleTTSService] - bundle org.openhab.voice.googletts:4.0.0.M1 (257)[org.openhab.voice.googletts.internal.GoogleTTSService(336)] : Querying state active
11:22:35.580 [DEBUG] [e.googletts.internal.GoogleTTSService] - bundle org.openhab.voice.googletts:4.0.0.M1 (257)[org.openhab.voice.googletts.internal.GoogleTTSService(336)] : ImmediateComponentHolder Finished configuring the dependency managers for component for pid org.openhab.voice.googletts
11:22:35.581 [DEBUG] [e.googletts.internal.GoogleTTSService] - bundle org.openhab.voice.googletts:4.0.0.M1 (257)[org.openhab.voice.googletts.internal.GoogleTTSService(336)] : ImmediateComponentHolder Will not enable component for pid org.openhab.voice.googletts: holder enabled state: true, metadata enabled: true

I have retested with 3.4.2 (Java 11) and with a CLEAN 4.0.0-SNAPSHOT (only Google TTS installed) and both work fine.

Any assistance would be appreciated.

@openhab-bot
Copy link
Collaborator

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/oh4-0-0-snapshot-and-m1-google-tts-exception/145046/15

@jlaur
Copy link
Contributor

jlaur commented Mar 12, 2023

I have this reproduced in a unit test now, I'll start working on a fix.

@jlaur
Copy link
Contributor

jlaur commented Mar 12, 2023

I believe this is a regression from the Java 17 upgrade, because JDK internals are now strongly encapsulated.

@jlaur
Copy link
Contributor

jlaur commented Mar 12, 2023

Please note, the call stack reported in the forum post is not the same as in the PR description:

[ERROR] [e.googlestt.internal.GoogleSTTService] - bundle org.openhab.voice.googlestt:4.0.0.M1 (258)[org.openhab.voice.googlestt.internal.GoogleSTTService(338)] : The modified method has thrown an exception
com.google.gson.JsonIOException: Failed making field 'java.time.LocalDateTime#date' accessible; either change its visibility or write a custom TypeAdapter for its declaring type
        at com.google.gson.internal.reflect.ReflectionHelper.makeAccessible(ReflectionHelper.java:23) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory.getBoundFields(ReflectiveTypeAdapterFactory.java:203) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory.create(ReflectiveTypeAdapterFactory.java:112) ~[?:?]
        at com.google.gson.Gson.getAdapter(Gson.java:531) ~[?:?]
        at com.google.gson.Gson.toJson(Gson.java:778) ~[?:?]
        at com.google.gson.Gson.toJson(Gson.java:756) ~[?:?]
        at com.google.gson.Gson.toJson(Gson.java:711) ~[?:?]
        at com.google.gson.Gson.toJson(Gson.java:691) ~[?:?]
        at org.openhab.core.auth.oauth2client.internal.OAuthStoreHandlerImpl$StorageFacade.put(OAuthStoreHandlerImpl.java:366) ~[?:?]
        at org.openhab.core.auth.oauth2client.internal.OAuthStoreHandlerImpl.savePersistedParams(OAuthStoreHandlerImpl.java:164) ~[?:?]
        at org.openhab.core.auth.oauth2client.internal.OAuthClientServiceImpl.createInstance(OAuthClientServiceImpl.java:131) ~[?:?]
        at org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl.createOAuthClientService(OAuthFactoryImpl.java:83) ~[?:?]
        at org.openhab.voice.googlestt.internal.GoogleSTTService.updateConfig(GoogleSTTService.java:163) ~[?:?]
        at org.openhab.voice.googlestt.internal.GoogleSTTService.modified(GoogleSTTService.java:117) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:245) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:687) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:531) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:317) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:307) ~[?:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeModifiedMethod(SingleComponentManager.java:856) ~[?:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.modify(SingleComponentManager.java:810) ~[?:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.reconfigure(SingleComponentManager.java:725) ~[?:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.reconfigure(SingleComponentManager.java:686) ~[?:?]
        at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.configurationUpdated(ConfigurableComponentHolder.java:440) ~[?:?]
        at org.apache.felix.scr.impl.manager.RegionConfigurationSupport.configurationEvent(RegionConfigurationSupport.java:347) ~[?:?]
        at org.apache.felix.scr.impl.manager.RegionConfigurationSupport$2.configurationEvent(RegionConfigurationSupport.java:115) ~[?:?]
        at org.apache.felix.cm.impl.ConfigurationManager$FireConfigurationEvent.sendEvent(ConfigurationManager.java:1723) ~[?:?]
        at org.apache.felix.cm.impl.ConfigurationManager$FireConfigurationEvent.run(ConfigurationManager.java:1664) ~[?:?]
        at org.apache.felix.cm.impl.UpdateThread.run0(UpdateThread.java:122) ~[?:?]
        at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:84) ~[?:?]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: java.lang.reflect.InaccessibleObjectException: Unable to make field private final java.time.LocalDate java.time.LocalDateTime.date accessible: module java.base does not "opens java.time" to unnamed module @72d10ef7
        at java.lang.reflect.AccessibleObject.checkCanSetAccessible(AccessibleObject.java:354) ~[?:?]
        at java.lang.reflect.AccessibleObject.checkCanSetAccessible(AccessibleObject.java:297) ~[?:?]
        at java.lang.reflect.Field.checkCanSetAccessible(Field.java:178) ~[?:?]
        at java.lang.reflect.Field.setAccessible(Field.java:172) ~[?:?]
        at com.google.gson.internal.reflect.ReflectionHelper.makeAccessible(ReflectionHelper.java:20) ~[?:?]
        ... 35 more

@Mark-VG
Copy link
Author

Mark-VG commented Mar 12, 2023

I got a 2nd error after re-installing the addon.
Is there anything I can do to get a more accurate trace for you?

@jlaur
Copy link
Contributor

jlaur commented Mar 12, 2023

No, this issue now has everything needed, just wanted to mention for difference for completeness, since it's relevant for the fix.

@Mark-VG
Copy link
Author

Mark-VG commented Mar 12, 2023

After re-installing I only get:

15:24:09.239 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter grant_type, value authorization_code
15:24:09.240 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter code, value <REDACT>
15:24:09.241 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter redirect_uri, value https://www.google.com
15:24:09.242 [DEBUG] [.oauth2client.internal.OAuthConnector] - Setting authentication for clientId <REDACT>. Using basic auth false
15:24:09.813 [WARN ] [e.googlestt.internal.GoogleSTTService] - Error fetching access token. Invalid oauth code? Please generate a new one.

Will reboot and report back

EDIT: No change after restart

@jlaur
Copy link
Contributor

jlaur commented Mar 12, 2023

@Mark-VG - can you try this:

bundle:uninstall org.openhab.core.auth.oauth2client

and then drop this JAR in you addons directory: org.openhab.core.auth.oauth2client-4.0.0-SNAPSHOT.jar

@Mark-VG
Copy link
Author

Mark-VG commented Mar 13, 2023

@jlaur Thank you. Tried the new JAR and get the same authn error (no exception though):

07:01:10.654 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter grant_type, value authorization_code
07:01:10.655 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter code, value <REDACT>&scope=https://www.googleapis.com/auth/cloud-platform
07:01:10.656 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter redirect_uri, value https://www.google.com
07:01:10.656 [DEBUG] [.oauth2client.internal.OAuthConnector] - Setting authentication for clientId <REDACT>. Using basic auth false
07:01:11.143 [WARN ] [e.googlestt.internal.GoogleSTTService] - Error fetching access token. Invalid oauth code? Please generate a new one.

@jlaur
Copy link
Contributor

jlaur commented Mar 13, 2023

@Mark-VG - do you still have TRACE logging enabled for org.openhab.core.auth.oauth2client? What happens if you reauthorize after installing this version? I will have another look, but probably need to set up a Google TTS account to reproduce.

@Mark-VG
Copy link
Author

Mark-VG commented Mar 13, 2023

@jlaur Yes, I do:

org.openhab.core.auth.oauth2client                 │ TRACE
org.openhab.voice.googletts                        │ TRACE

Tried again too:

11:51:01.843 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter grant_type, value authorization_code
11:51:01.844 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter code, value <REDACT>&scope=https://www.googleapis.com/auth/cloud-platform
11:51:01.844 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter redirect_uri, value https://www.google.com
11:51:01.845 [DEBUG] [.oauth2client.internal.OAuthConnector] - Setting authentication for clientId <REDACT>. Using basic auth false
11:51:02.318 [WARN ] [e.googlestt.internal.GoogleSTTService] - Error fetching access token. Invalid oauth code? Please generate a new one.

@jlaur
Copy link
Contributor

jlaur commented Mar 13, 2023

@Mark-VG - I have uploaded a new version with an additional fix that should be targeting the exception from the stack trace in the description. The JAR can be downloaded using the same link as previously. Can you try that one too? I have been struggling with unit tests (so far unsuccessfully) so haven't had time to set up Google TTS yet for manual testing.

@Mark-VG
Copy link
Author

Mark-VG commented Mar 14, 2023

@jlaur Thank you. Tried the new one and get:

07:30:48.865 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter grant_type, value authorization_code
07:30:48.865 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter code, value <REDACT>&scope=https://www.googleapis.com/auth/cloud-platform
07:30:48.866 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter redirect_uri, value https://www.google.com
07:30:48.866 [DEBUG] [.oauth2client.internal.OAuthConnector] - Setting authentication for clientId <REDACT> Using basic auth false
07:30:49.310 [DEBUG] [.oauth2client.internal.OAuthConnector] - grant type authorization_code to URL https://accounts.google.com/o/oauth2/token success

I noticed that I did not get the log:

07:34:20.342 [WARN ] [e.googlestt.internal.GoogleSTTService] - Error fetching access token. Invalid oauth code? Please generate a new one.

This only happened if I tried to use the same code again?

The authorization still failed though - the setting are not saved and the Google TTS is still not available.

@jlaur
Copy link
Contributor

jlaur commented Mar 14, 2023

@mhilbush - if you are still using the Google TTS, perhaps you could assist? I saw you did openhab/openhab-addons#13042, so you probably know your way around this?

@Mark-VG - can you check the file /var/lib/openhab/jsondb/StorageHandler.For.OAuthClientService.json and see if it contains anything that seems related?

@mhilbush
Copy link
Contributor

Sorry, I've actually never used Google TTS (I use VoiceRSS). But I do have a Nest doorbell, and that binding had the same problem. So I ended up fixing it in both bindings.

@jlaur
Copy link
Contributor

jlaur commented Mar 14, 2023

@mhilbush - is Nest doorbell working for you with 4.0? If no, is it working in combination with this: org.openhab.core.auth.oauth2client-4.0.0-SNAPSHOT.jar?

@mhilbush
Copy link
Contributor

It's working fine for me. I'm on build 3357 without that jar.

Is there something you want me to check? It's in another house, but I have a VPN connection to that location.

@jlaur
Copy link
Contributor

jlaur commented Mar 14, 2023

@mhilbush - if it's working, I think there's nothing more I can ask you to check. 🙂 Thanks!

@Mark-VG
Copy link
Author

Mark-VG commented Mar 15, 2023

can you check the file /var/lib/openhab/jsondb/StorageHandler.For.OAuthClientService.json and see if it contains anything that seems related?

Hi
Tried again after renaming the StorageHandler.For.OAuthClientService.json file

09:32:05.733 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter grant_type, value authorization_code
09:32:05.734 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter code, value <REDACT>&scope=https://www.googleapis.com/auth/cloud-platform
09:32:05.734 [DEBUG] [.oauth2client.internal.OAuthConnector] - Oauth request parameter redirect_uri, value https://www.google.com
09:32:05.735 [DEBUG] [.oauth2client.internal.OAuthConnector] - Setting authentication for clientId <REDACT>.apps.googleusercontent.com. Using basic auth false
09:32:06.369 [DEBUG] [.oauth2client.internal.OAuthConnector] - grant type authorization_code to URL https://accounts.google.com/o/oauth2/token success

The file was recreated and no error generated, however Google TTS is still offline. The redacted new file is as follows:
StorageHandler.For.OAuthClientService.json.txt

I did notice that org.openhab.voice.googletts.ServiceConfiguration is listed twice?

@jlaur
Copy link
Contributor

jlaur commented Mar 15, 2023

Thanks. I notice also some duplication between two different namespaces:

  • org.openhab.voice.googlestt
  • org.openhab.voice.googletts

And the newest one is for the stt namespace:

  "org.openhab.voice.googlestt.LastUsed": {
    "class": "java.lang.String",
    "value": "\"2023-03-15T07:32:06.379005900Z\""
  },

This is the next thing to check.

@Mark-VG
Copy link
Author

Mark-VG commented Mar 15, 2023

Sorry, did not pick up TTS vs STT.

@jlaur
Copy link
Contributor

jlaur commented Mar 15, 2023

@Mark-VG - I assume it's TTS you are still having issues with.

@Mark-VG
Copy link
Author

Mark-VG commented Mar 15, 2023

I assume it's TTS you are still having issues with.

Yes, I actually don't use STT at all.

@Mark-VG
Copy link
Author

Mark-VG commented Mar 15, 2023

Saw an article suggestion to delete the backup file sfro JSON as well, which I have now tried. This time the StorageHandler.For.OAuthClientService.json got created, but still no access.

@jlaur
Copy link
Contributor

jlaur commented Mar 15, 2023

@Mark-VG - what does the file contain after it was recreated? Can you also describe the steps you are going through when trying to authorize? The remaining problem might be specific for the Google TTS add-on, since it works for me with Miele Cloud and for @mhilbush with Nest.

@jlaur
Copy link
Contributor

jlaur commented Mar 15, 2023

@Mark-VG - in the meantime I'll add some more logging in the Google TTS add-on to try to better pinpoint the problem.

@jlaur
Copy link
Contributor

jlaur commented Mar 15, 2023

@Mark-VG - with trace logging enabled for org.openhab.voice.googletts, can you post what it currently logs when you restart it, i.e. bundle:restart org.openhab.voice.googletts (combined with the org.openhab.core.auth.oauth2client log entries)?

@Mark-VG
Copy link
Author

Mark-VG commented Mar 15, 2023

@jlaur
I follow these steps - which are the same as the documentation - just a bit more detailed:

https://community.openhab.org/t/oh3-google-tts-error-grant-type-authorization-code/112549/44

The generated JSON is as follows (Redacted).

StorageHandler.For.OAuthClientService.json.txt

org.openhab.core.auth.oauth2client                 │ TRACE
org.openhab.voice.googletts                        │ TRACE

258 │ Active │  80 │ 4.0.0.M1               │ openHAB Add-ons :: Bundles :: Voice :: Google Cloud Speech to Text

bundle:restart 258

Gives:

21:27:14.008 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : Querying state active
21:27:14.008 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : getting deactivate: deactivate
21:27:14.008 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : Locating method deactivate in class org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl
21:27:14.009 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : Declared Method org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl.deactivate([interface org.osgi.service.component.ComponentContext]) not found
21:27:14.009 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : Found deactivate method: public void org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl.deactivate()
21:27:14.009 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : invoking deactivate: deactivate: parameters []
21:27:14.009 [DEBUG] [lient.internal.OAuthClientServiceImpl] - closing oauth client, handle: org.openhab.voice.googlestt
21:27:14.009 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : invoked deactivate: deactivate
21:27:14.009 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : DependencyManager: osgi.ds.satisfying.condition close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@7279969a at tracking count 2 refpairs: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
21:27:14.009 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : DependencyManager: $001 close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@7279969a at tracking count 3 refpairs: [[RefPair: ref: [{org.openhab.core.auth.oauth2client.internal.OAuthStoreHandler}={service.id=504, service.bundleid=261, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), CIPHER_TARGET=SymmetricKeyCipher, component.name=org.openhab.core.auth.oauth2client.internal.OAuthStoreHandlerImpl, component.id=335}] service: [org.openhab.core.auth.oauth2client.internal.OAuthStoreHandlerImpl@516e7c4b]]]
21:27:14.010 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : DependencyManager: $000 close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@7279969a at tracking count 1 refpairs: [[RefPair: ref: [{org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=272, service.bundleid=165, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=143}] service: [org.openhab.core.io.net.http.internal.WebClientFactoryImpl@6ed0d74]]]
21:27:14.010 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : Unset and deconfigured implementation object for component in deleteComponent for reason Unspecified
21:27:14.010 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : Changed state from active to satisfied
21:27:14.017 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : This thread collected dependencies
21:27:14.017 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : getService (single component manager) dependencies collected.
21:27:14.017 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : Querying state satisfied
21:27:14.017 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : Querying state satisfied
21:27:14.017 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=272, service.bundleid=165, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=143}] service: [org.openhab.core.io.net.http.internal.WebClientFactoryImpl@6ed0d74]]]
21:27:14.017 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : For dependency $001, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.auth.oauth2client.internal.OAuthStoreHandler}={service.id=504, service.bundleid=261, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), CIPHER_TARGET=SymmetricKeyCipher, component.name=org.openhab.core.auth.oauth2client.internal.OAuthStoreHandlerImpl, component.id=335}] service: [org.openhab.core.auth.oauth2client.internal.OAuthStoreHandlerImpl@516e7c4b]]]
21:27:14.017 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
21:27:14.019 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : Set implementation object for component
21:27:14.019 [DEBUG] [auth2client.internal.OAuthFactoryImpl] - bundle org.openhab.core.auth.oauth2client:4.0.0.202303132040 (261)[org.openhab.core.auth.oauth2client.internal.OAuthFactoryImpl(334)] : Changed state from satisfied to active

Also

openhab> bundle:restart org.openhab.voice.googletts
No bundles specified.

Hence the use of the number

@jlaur
Copy link
Contributor

jlaur commented Mar 15, 2023

258 │ Active │ 80 │ 4.0.0.M1 │ openHAB Add-ons :: Bundles :: Voice :: Google Cloud Speech to Text

This should be "Google Cloud Text-to-Speech". The bundle you mentioned is STT, not TTS. This is probably also why you can't restart it. Can you check if you have TTS correctly installed? In the logs above not a single log line is from this add-on, so something is missing.

@Mark-VG
Copy link
Author

Mark-VG commented Mar 16, 2023

I am so sorry!

When trying to test I uninstalled Google TTS and "reinstalled". Turns out I installed STT instead. Really a rookie move!

I can confirm now that your fixed org.openhab.core.auth.oauth2client-4.0.0-SNAPSHOT - the latest one, has resolved my issue and I have managed to log in to Google TTS successfully.

I retested with the M1 version and the error occurs - so your fix is definitely the solution. I also do not see the exceptions anymore.

Can you confirm that once your fixes are merged I would have to:

  • remove the .JAR file from Addons
  • run bundle:install org.openhab.core.auth.oauth2client

Again, thank you so much for taking the time to look at this and help me

@jlaur
Copy link
Contributor

jlaur commented Mar 16, 2023

I can confirm now that your fixed org.openhab.core.auth.oauth2client-4.0.0-SNAPSHOT - the latest one, has resolved my issue and I have managed to log in to Google TTS successfully.

Thanks for the feedback, I'm glad that it finally worked out, and to have confirmation that the fix is working. 🙂

Can you confirm that once your fixes are merged I would have to:

I will have a look in the evening (CET) and try to get my test system reverted to the bundled version. Then will let you know which steps are needed. The fix has now been merged, so it will be included with the next snapshot.

@jlaur
Copy link
Contributor

jlaur commented Mar 16, 2023

I will have a look in the evening (CET) and try to get my test system reverted to the bundled version. Then will let you know which steps are needed.

I'm not 100% sure, but it seems that after removing the JAR from the addons directory, you can simply bundle:restart org.openhab.core.auth.oauth2client.

@Mark-VG
Copy link
Author

Mark-VG commented Mar 17, 2023

I'm not 100% sure, but it seems that after removing the JAR from the addons directory, you can simply bundle:restart org.openhab.core.auth.oauth2client.

Yes, I just restarted openHAB and it changed from WAITING. Thanks for all the help

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants