Failed to authorize SDM client

I have two servers running openhab 4.0.4-2, and I had already set up a Nest SDM Account on one of the servers, and it works as expected. I am now trying to create a Nest SDM Account thing on the other server with the exact same project ID, Client ID and Client Secret. I get the one time authorization code following the instructions in the documentation, just as I did for the first server, but I always get the dreaded “Failed to authorize SDM client.” error. I changed the log level of org.openhab.binding.nest to TRACE in the console, but it does not show anything happening when I disable/enable the thing. When I do the same enable/disable on the first server, I can see openhab connecting to smartdevicemanagement.googleapis.com, and get the device list. I can also see traffic to smartdevicemanagement.googleapis.com with tcpdump, but there is no trafic on the second server.

I restarted openhab, rebooted the server, still looks like there is not even an attempt to communicate with smartdevicemanagement.googleapis.com.

Am I doing something wrong?

I am completely lost. I created a new SDM account, and it works perfectly on the first server, but not on the second. I even stopped openhab on both servers, then deployed as a container, and it is still the same. The same SDM account works on the openhab installation on the first server, but not on the other one. Even the operating system is the same on the two servers, which is Ubuntu 22.04 LTS, not to mention java, which is openjdk version “17.0.9” 2023-10-17.

I can only think of one difference. The second server is a new one, with a relatively new CPU (Intel Core i7 12th Gen Alder Lake), perhaps there is some new security feature in the CPU? Of course I hear myself how vague this is, but I really have got nothing.

Please, if anyone has an idea, any help would be greatly appreciated.

No, why should a CPU block any access and how should that be configured.
Both servers are in the same (v)LAN; use the same router and name server ? Kernel/Image is the same on both hosts ( it does not use something like SELinux on one of the boxes ). Router does not block one of the devices from accessing the internet ?

Yeah, I had a feeling that CPU “observation” was just a desperate attempt to find anything on my part … :-/

Both servers run the same OS (Ubuntu 22.04.3 LTS), but it seems the kernel is newer on the second server.

First server: 5.15.0-89-generic
Second server: 6.2.0-37-generic

SELinux is disabled on both.

Both servers are on the same subnet, and the ubuntu firewall (ufw) is disabled on both. I have both wide open on my firewall (OPNsense). After all it is only port 443 I have to let out, but I don’t think the firewall plays any role. As I mentioned, there is no traffic towards Google at all on the second server when I add the SDM account thing, while I can see packets going and coming on the first server.

name resolution and ping to google api works on both servers ?

Name resolution is good on both servers

root@ubuntu:~# host smartdevicemanagement.googleapis.com
smartdevicemanagement.googleapis.com has address 142.250.115.95
smartdevicemanagement.googleapis.com has address 142.250.114.95
smartdevicemanagement.googleapis.com has address 142.250.113.95
smartdevicemanagement.googleapis.com has address 142.251.116.95
smartdevicemanagement.googleapis.com has address 142.250.138.95
smartdevicemanagement.googleapis.com has IPv6 address 2607:f8b0:4023:1006::5f
smartdevicemanagement.googleapis.com has IPv6 address 2607:f8b0:4023:1004::5f
smartdevicemanagement.googleapis.com has IPv6 address 2607:f8b0:4023:1002::5f
smartdevicemanagement.googleapis.com has IPv6 address 2607:f8b0:4023:1000::5f


root@roki:~# host smartdevicemanagement.googleapis.com
smartdevicemanagement.googleapis.com has address 142.251.116.95
smartdevicemanagement.googleapis.com has address 142.250.138.95
smartdevicemanagement.googleapis.com has address 142.250.115.95
smartdevicemanagement.googleapis.com has address 142.250.114.95
smartdevicemanagement.googleapis.com has address 142.250.113.95
smartdevicemanagement.googleapis.com has IPv6 address 2607:f8b0:4023:1000::5f
smartdevicemanagement.googleapis.com has IPv6 address 2607:f8b0:4023:1006::5f
smartdevicemanagement.googleapis.com has IPv6 address 2607:f8b0:4023:1004::5f
smartdevicemanagement.googleapis.com has IPv6 address 2607:f8b0:4023:1002::5f

But ping does not work from either. I think it’s just that API server not doing ICMP. They both respond on port 443.

root@ubuntu:~# nc -vzw2 smartdevicemanagement.googleapis.com 443
Connection to smartdevicemanagement.googleapis.com (142.251.116.95) 443 port [tcp/https] succeeded!

root@roki:~# nc -vzw2 smartdevicemanagement.googleapis.com 443
Connection to smartdevicemanagement.googleapis.com (142.250.113.95) 443 port [tcp/https] succeeded!

Just in case it comes up later, “ubuntu” is the first server (the one that works), and “roki” is the second.

I stumbled upon this article, while trying to figure out why I cannot upgrade the kernel to 6.2 on the first server.

https://www.reddit.com/r/ubuntuserver/comments/15oo521/no_kernel_62_update_for_ubuntu_2204_lts/

So, could it be the kernel messing things up? Let me upgrade my first server to kernel 6.2, and see if it breaks the NEST SDM Account.

And then, I can start thinking how to downgrade the second server…

Adding a NEST SDM Account thing still works on the first server, even after the kernel upgrade to 6.2

I downgraded the kernel on the second server, and I still cannot create a NEST SDM Account thing.

This is still puzzling me. When I do a packet capture on the first server, while adding the NEST SDM Account thing, I see this.

root@ubuntu:~# tcpdump -nn -i any port 443
tcpdump: data link type LINUX_SLL2
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on any, link-type LINUX_SLL2 (Linux cooked v2), snapshot length 262144 bytes
02:11:39.837765 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [S], seq 2210076009, win 64240, options [mss 1460,sackOK,TS val 1736650415 ecr 0,nop,wscale 7], length 0
02:11:39.844136 enp0s25 In  IP 142.251.116.84.443 > 192.168.3.16.41396: Flags [S.], seq 1615980484, ack 2210076010, win 65535, options [mss 1412,sackOK,TS val 3103549364 ecr 1736650415,nop,wscale 8], length 0
02:11:39.844187 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [.], ack 1, win 502, options [nop,nop,TS val 1736650421 ecr 3103549364], length 0
02:11:39.848017 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [P.], seq 1:457, ack 1, win 502, options [nop,nop,TS val 1736650425 ecr 3103549364], length 456
02:11:39.854151 enp0s25 In  IP 142.251.116.84.443 > 192.168.3.16.41396: Flags [.], ack 457, win 261, options [nop,nop,TS val 3103549374 ecr 1736650425], length 0
02:11:39.854644 enp0s25 In  IP 142.251.116.84.443 > 192.168.3.16.41396: Flags [.], seq 1:1401, ack 457, win 261, options [nop,nop,TS val 3103549374 ecr 1736650425], length 1400
02:11:39.854667 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [.], ack 1401, win 501, options [nop,nop,TS val 1736650432 ecr 3103549374], length 0
02:11:39.854774 enp0s25 In  IP 142.251.116.84.443 > 192.168.3.16.41396: Flags [.], seq 1401:2801, ack 457, win 261, options [nop,nop,TS val 3103549374 ecr 1736650425], length 1400
02:11:39.854784 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [.], ack 2801, win 496, options [nop,nop,TS val 1736650432 ecr 3103549374], length 0
02:11:39.854897 enp0s25 In  IP 142.251.116.84.443 > 192.168.3.16.41396: Flags [P.], seq 2801:4328, ack 457, win 261, options [nop,nop,TS val 3103549374 ecr 1736650425], length 1527
02:11:39.854905 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [.], ack 4328, win 485, options [nop,nop,TS val 1736650432 ecr 3103549374], length 0
02:11:39.857396 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [P.], seq 457:463, ack 4328, win 501, options [nop,nop,TS val 1736650435 ecr 3103549374], length 6
02:11:39.866096 enp0s25 In  IP 142.251.116.84.443 > 192.168.3.16.41396: Flags [.], ack 463, win 261, options [nop,nop,TS val 3103549386 ecr 1736650435], length 0
02:11:39.867243 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [P.], seq 463:553, ack 4328, win 501, options [nop,nop,TS val 1736650444 ecr 3103549386], length 90
02:11:39.868072 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [P.], seq 553:1114, ack 4328, win 501, options [nop,nop,TS val 1736650445 ecr 3103549386], length 561
02:11:39.871125 enp0s25 In  IP 142.251.116.84.443 > 192.168.3.16.41396: Flags [.], ack 553, win 261, options [nop,nop,TS val 3103549391 ecr 1736650444], length 0
02:11:39.874368 enp0s25 In  IP 142.251.116.84.443 > 192.168.3.16.41396: Flags [.], ack 1114, win 265, options [nop,nop,TS val 3103549394 ecr 1736650445], length 0
02:11:39.975211 enp0s25 In  IP 142.251.116.84.443 > 192.168.3.16.41396: Flags [P.], seq 4328:6038, ack 1114, win 265, options [nop,nop,TS val 3103549495 ecr 1736650445], length 1710
02:11:39.975301 enp0s25 In  IP 142.251.116.84.443 > 192.168.3.16.41396: Flags [P.], seq 6038:6065, ack 1114, win 265, options [nop,nop,TS val 3103549495 ecr 1736650445], length 27
02:11:39.975528 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [.], ack 6065, win 501, options [nop,nop,TS val 1736650553 ecr 3103549495], length 0
02:11:39.977768 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [P.], seq 1114:1154, ack 6065, win 501, options [nop,nop,TS val 1736650555 ecr 3103549495], length 40
02:11:39.977798 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [F.], seq 1154, ack 6065, win 501, options [nop,nop,TS val 1736650555 ecr 3103549495], length 0
02:11:39.982113 enp0s25 In  IP 142.251.116.84.443 > 192.168.3.16.41396: Flags [.], ack 1154, win 265, options [nop,nop,TS val 3103549502 ecr 1736650555], length 0
02:11:39.983440 enp0s25 In  IP 142.251.116.84.443 > 192.168.3.16.41396: Flags [F.], seq 6065, ack 1155, win 265, options [nop,nop,TS val 3103549503 ecr 1736650555], length 0
02:11:39.983469 enp0s25 Out IP 192.168.3.16.41396 > 142.251.116.84.443: Flags [.], ack 6066, win 501, options [nop,nop,TS val 1736650561 ecr 3103549503], length 0

But when I do the same on the second server, there is not a single packet. Like there is not even an attempt to communicate with Google.

root@roki:/opt/openhab# tcpdump -nn -i any net 142.0.0.0/8
tcpdump: data link type LINUX_SLL2
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on any, link-type LINUX_SLL2 (Linux cooked v2), snapshot length 262144 bytes
^C
0 packets captured
6 packets received by filter
0 packets dropped by kernel

I enabled TRACE for everything, and captured the traces while adding the NEST SDM Account thing on both servers. What I see supports my observation, namely that there is no communication initiated on the second server towards Google. I attached the two trace files. I am not worried about the project and client ID and secret, this is a temporary SDM account, I will wipe it out later.

openstack-sdm-add-thing-roki.txt (17.8 KB)

openstack-sdm-add-thing-ubuntu.txt (22.0 KB)

And again, the operating systems, kernels, java, openhab, and addons versions are all the same on the two servers.

Whether it will work or not depends on authorization server strategy. Since you use same client id access token generated for second server might result in error (other token is active) or revoking of token for first server (principle of single active token per client).
I’ve seen all sorts of errors coming from pinning values with tokens issued by authorization servers. I don’t know if that’s the case with SDM, but my very first advice would be - try with another client id.

Again, what I am trying to point out is that it seems openhab doesn’t even talk to Google, so we don’t get as far as using the same account could pose a problem.

Also, for demonstrating it with the two trace files, I used the same account just so that the two files would look most alike. I had already tried creating a second account, but adding the thing failed nevertheless.

I got it! :slight_smile:

First of all, I created an excel sheet with both traces listed, and I tried to align them, so that I can see what the differences are. (what!? cannot attach MS excel? well, here’s a screen shot)

For starter, I have not seen any “OAuth” entries in the trace from the second server (roki). Then I noticed the last relevant looking entry, before the failure, was “creating http client for consumer OAuthConnector” in WebClientFactoryImpl.

So, I googled WebClientFactoryImpl, and found one promising article.

As a matter of fact, my second server has 20 cores. The simplest way to “reduce” the number of cores was to launch openhab in docker, with the --cpuset-cpus=“0-1” option, which menas the container will use CPUs 0 and 1 (two cores).

Lo and behold, adding NEST SDM Account now works!!! :slight_smile:

Is this a jetty bug? Can something be done in the nest binding?

Just adding a few lines here, so that I can mark this post as the solution.

Apart from reducing the number of CPUs of the container, one can also apply the solution from the github post above. I don’t know the exact meaning of those 4 variables, but this worked for me for my 20 thread CPU.

org.openhab.webclient:minThreadsShared=10
org.openhab.webclient:maxThreadsShared=40
org.openhab.webclient:minThreadsCustom=10
org.openhab.webclient:maxThreadsCustom=15

It had already been added to the latest openhab release.

One more thing. In one of my posts I said I enabled TRACE for everything, which is not true. I enabled TRACE for org.openhab, but the error message comes from org.eclipse.jetty. Have I enabled TRACE for that, I could have immediately see what the problem was.

19:38:36.187 [WARN ] [etty.util.component.AbstractLifeCycle] - FAILED HttpClientTransportOverHTTP@2b5187f0{FAILED}: java.lang.IllegalStateException: Insufficient configured threads: required=10 < max=10 for QueuedThreadPool[OH-httpClient-OAuthConnector]@6f238686{STOPPED,5<=0<=10,i=0,r=-1,q=0}[NO_TRY]
java.lang.IllegalStateException: Insufficient configured threads: required=10 < max=10 for QueuedThreadPool[OH-httpClient-OAuthConnector]@6f238686{STOPPED,5<=0<=10,i=0,r=-1,q=0}[NO_TRY]
        at org.eclipse.jetty.util.thread.ThreadPoolBudget.check(ThreadPoolBudget.java:165) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.util.thread.ThreadPoolBudget.leaseTo(ThreadPoolBudget.java:141) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.util.thread.ThreadPoolBudget.leaseFrom(ThreadPoolBudget.java:191) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.io.SelectorManager.doStart(SelectorManager.java:255) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117) ~[?:?]
        at org.eclipse.jetty.client.AbstractConnectorHttpClientTransport.doStart(AbstractConnectorHttpClientTransport.java:64) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117) ~[?:?]
        at org.eclipse.jetty.client.HttpClient.doStart(HttpClient.java:258) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.openhab.core.auth.oauth2client.internal.OAuthConnector.createHttpClient(OAuthConnector.java:352) ~[?:?]
        at org.openhab.core.auth.oauth2client.internal.OAuthConnector.grantTypeAuthorizationCode(OAuthConnector.java:216) ~[?:?]
        at org.openhab.core.auth.oauth2client.internal.OAuthClientServiceImpl.getAccessTokenResponseByAuthorizationCode(OAuthClientServiceImpl.java:218) ~[?:?]
        at org.openhab.binding.nest.internal.sdm.api.SDMAPI.authorizeClient(SDMAPI.java:115) ~[?:?]
        at org.openhab.binding.nest.internal.sdm.handler.SDMAccountHandler.initializeSDMAPI(SDMAccountHandler.java:196) ~[?:?]
        at org.openhab.binding.nest.internal.sdm.handler.SDMAccountHandler.lambda$0(SDMAccountHandler.java:181) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
        at java.lang.Thread.run(Thread.java:840) ~[?:?]

But I went the hard way… :wink:

1 Like

Updating the org.openhab.webclient config values in conf/services/runtime.cfg may help.

Indeed, although I am not sure what exactly those values mean, even after reading that post I was showing above, the below values worked for my 20 thread CPU.

org.openhab.webclient:minThreadsShared=10
org.openhab.webclient:maxThreadsShared=40
org.openhab.webclient:minThreadsCustom=10
org.openhab.webclient:maxThreadsCustom=15

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.