Skip to content
This repository has been archived by the owner on Jan 6, 2023. It is now read-only.

Token expiring after 70 minutes. #99

Closed
thiagolc3 opened this issue Mar 23, 2019 · 5 comments
Closed

Token expiring after 70 minutes. #99

thiagolc3 opened this issue Mar 23, 2019 · 5 comments

Comments

@thiagolc3
Copy link

Hi Gus.
6 months ago I was trying to use the mqtt examples for ESP32, but I stopped at the token expiration problem. Now I saw that you changed the examples a lot, it was easier to understand, this more didactic, but I still found the token expiration problem after 70 minutes. Now I'm using ESP8266, I can only refresh the token if I reset the device, where am I going wrong?

Thanks for attention.

@gguuss
Copy link
Contributor

gguuss commented Mar 25, 2019

The 70 minutes is probably coming from a combination of the 60 minute token expiration set in the JWT payload combined with the 20 minutes of clock drift allowed by the authentication backend. If you're using the new examples, they should refresh the JWT token when it expires and subsequently re-authenticates the MQTT connection. Can you share any additional debugging information, as described in the support issue?

@gguuss
Copy link
Contributor

gguuss commented Mar 25, 2019

I'm able to repro the issue:



12:21:40.114 -> connecting...
12:21:40.777 -> connected!
incoming: /devices/arduino-taste/config - 1
12:21:40.843 -> incoming: /devices/arduino-taste/config - 1
incoming: /devices/arduino-taste/config - 1
incoming: /devices/arduino-taste/commands - test
incoming: /devices/arduino-taste/config - 1
incoming: /devices/arduino-taste/config - 0

12:56:16.156 -> connecting...
12:56:22.821 -> connected!
incoming: /devices/arduino-taste/config - 0
12:56:22.920 -> incoming: /devices/arduino-taste/config - 0
incoming: /devices/arduino-taste/commands - 123

13:25:43.999 -> connecting...Refreshing JWT
-10
13:25:54.012 -> LWMQTT_CONNECTION_DENIED
13:25:54.012 -> 5
13:25:54.012 -> LWMQTT_NOT_AUTHORIZED
13:25:54.012 -> Delaying 2120ms
-10
13:25:56.765 -> LWMQTT_CONNECTION_DENIED
13:25:56.765 -> 5
13:25:56.765 -> LWMQTT_NOT_AUTHORIZED
13:25:56.765 -> Delaying 4387ms
-10
13:26:01.772 -> LWMQTT_CONNECTION_DENIED
13:26:01.772 -> 5
13:26:01.772 -> LWMQTT_NOT_AUTHORIZED
13:26:01.772 -> Delaying 8864ms
-10
13:26:11.223 -> LWMQTT_CONNECTION_DENIED
13:26:11.223 -> 5
13:26:11.223 -> LWMQTT_NOT_AUTHORIZED
13:26:11.223 -> Delaying 18193ms
-10
13:26:30.055 -> LWMQTT_CONNECTION_DENIED
13:26:30.055 -> 5
13:26:30.055 -> LWMQTT_NOT_AUTHORIZED
13:26:30.055 -> Delaying 36681ms
-10
13:27:07.689 -> LWMQTT_CONNECTION_DENIED
13:27:07.689 -> 5
13:27:07.689 -> LWMQTT_NOT_AUTHORIZED
13:27:07.689 -> Delaying 60000ms
-10
13:28:08.296 -> LWMQTT_CONNECTION_DENIED
13:28:08.296 -> 5
13:28:08.296 -> LWMQTT_NOT_AUTHORIZED
13:28:08.296 -> Delaying 60000ms
-10
13:29:08.910 -> LWMQTT_CONNECTION_DENIED
13:29:08.910 -> 5
13:29:08.910 -> LWMQTT_NOT_AUTHORIZED
13:29:08.910 -> Delaying 60000ms
-10
13:30:09.491 -> LWMQTT_CONNECTION_DENIED
13:30:09.491 -> 5
13:30:09.491 -> LWMQTT_NOT_AUTHORIZED
13:30:09.491 -> Delaying 60000ms
-10
13:31:10.273 -> LWMQTT_CONNECTION_DENIED
13:31:10.273 -> 5
13:31:10.273 -> LWMQTT_NOT_AUTHORIZED
13:31:10.273 -> Delaying 60000ms
-10
13:32:10.926 -> LWMQTT_CONNECTION_DENIED
13:32:10.926 -> 5
13:32:10.926 -> LWMQTT_NOT_AUTHORIZED
13:32:10.926 -> Delaying 60000ms
-10
13:33:11.543 -> LWMQTT_CONNECTION_DENIED
13:33:11.543 -> 5
13:33:11.543 -> LWMQTT_NOT_AUTHORIZED
13:33:11.543 -> Delaying 60000ms
-10
13:34:12.160 -> LWMQTT_CONNECTION_DENIED
13:34:12.160 -> 5
13:34:12.160 -> LWMQTT_NOT_AUTHORIZED
13:34:12.160 -> Delaying 60000ms
-10
13:35:12.772 -> LWMQTT_CONNECTION_DENIED
13:35:12.772 -> 5
13:35:12.772 -> LWMQTT_NOT_AUTHORIZED
13:35:12.772 -> Delaying 60000ms
-10
13:36:13.387 -> LWMQTT_CONNECTION_DENIED
13:36:13.387 -> 5
13:36:13.387 -> LWMQTT_NOT_AUTHORIZED
13:36:13.387 -> Delaying 60000ms
-5
13:37:15.202 -> LWMQTT_NETWORK_FAILED_READ
13:37:15.202 -> 6
13:37:15.202 -> LWMQTT_UNKNOWN_RETURN_CODE
13:37:15.202 -> Delaying 60000ms
-10
13:38:15.889 -> LWMQTT_CONNECTION_DENIED
13:38:15.889 -> 5
13:38:15.889 -> LWMQTT_NOT_AUTHORIZED
13:38:15.889 -> Delaying 60000ms
-10
13:39:16.475 -> LWMQTT_CONNECTION_DENIED
13:39:16.475 -> 5
13:39:16.475 -> LWMQTT_NOT_AUTHORIZED
13:39:16.475 -> Delaying 60000ms
-10
13:40:17.055 -> LWMQTT_CONNECTION_DENIED
13:40:17.055 -> 5
13:40:17.055 -> LWMQTT_NOT_AUTHORIZED
13:40:17.055 -> Delaying 60000ms
-10
13:41:17.801 -> LWMQTT_CONNECTION_DENIED
13:41:17.801 -> 5
13:41:17.801 -> LWMQTT_NOT_AUTHORIZED
13:41:17.801 -> Delaying 60000ms
-10
13:42:18.416 -> LWMQTT_CONNECTION_DENIED
13:42:18.416 -> 5
13:42:18.416 -> LWMQTT_NOT_AUTHORIZED
13:42:18.416 -> Delaying 60000ms
-10
13:43:19.016 -> LWMQTT_CONNECTION_DENIED
13:43:19.016 -> 5
13:43:19.016 -> LWMQTT_NOT_AUTHORIZED
13:43:19.016 -> Delaying 60000ms
-10
13:44:19.966 -> LWMQTT_CONNECTION_DENIED
13:44:19.966 -> 5
13:44:19.966 -> LWMQTT_NOT_AUTHORIZED
13:44:19.966 -> Delaying 60000ms
-10
13:45:20.554 -> LWMQTT_CONNECTION_DENIED
13:45:20.554 -> 5
13:45:20.554 -> LWMQTT_NOT_AUTHORIZED
13:45:20.554 -> Delaying 60000ms
-10
13:46:21.209 -> LWMQTT_CONNECTION_DENIED
13:46:21.209 -> 5
13:46:21.209 -> LWMQTT_NOT_AUTHORIZED
13:46:21.209 -> Delaying 60000ms
-10
13:47:21.895 -> LWMQTT_CONNECTION_DENIED
13:47:21.895 -> 5
13:47:21.895 -> LWMQTT_NOT_AUTHORIZED
13:47:21.895 -> Delaying 60000ms
-10
13:48:22.545 -> LWMQTT_CONNECTION_DENIED
13:48:22.545 -> 5
13:48:22.545 -> LWMQTT_NOT_AUTHORIZED
13:48:22.545 -> Delaying 60000ms
-10
13:49:23.162 -> LWMQTT_CONNECTION_DENIED
13:49:23.162 -> 5
13:49:23.162 -> LWMQTT_NOT_AUTHORIZED
13:49:23.162 -> Delaying 60000ms
-10
13:50:23.744 -> LWMQTT_CONNECTION_DENIED
13:50:23.744 -> 5
13:50:23.744 -> LWMQTT_NOT_AUTHORIZED
13:50:23.744 -> Delaying 60000ms
-10
13:51:24.426 -> LWMQTT_CONNECTION_DENIED
13:51:24.426 -> 5
13:51:24.426 -> LWMQTT_NOT_AUTHORIZED
13:51:24.426 -> Delaying 60000ms
-10
13:52:25.013 -> LWMQTT_CONNECTION_DENIED
13:52:25.013 -> 5
13:52:25.013 -> LWMQTT_NOT_AUTHORIZED
13:52:25.013 -> Delaying 60000ms
-10
13:53:25.628 -> LWMQTT_CONNECTION_DENIED
13:53:25.628 -> 5
13:53:25.628 -> LWMQTT_NOT_AUTHORIZED
13:53:25.628 -> Delaying 60000ms
-10
13:54:26.181 -> LWMQTT_CONNECTION_DENIED
13:54:26.181 -> 5
13:54:26.181 -> LWMQTT_NOT_AUTHORIZED
13:54:26.181 -> Delaying 60000ms
-10
13:55:26.866 -> LWMQTT_CONNECTION_DENIED
13:55:26.866 -> 5
13:55:26.866 -> LWMQTT_NOT_AUTHORIZED
13:55:26.866 -> Delaying 60000ms
-10
13:56:27.478 -> LWMQTT_CONNECTION_DENIED
13:56:27.478 -> 5
13:56:27.478 -> LWMQTT_NOT_AUTHORIZED
13:56:27.478 -> Delaying 60000ms
-10
13:57:28.089 -> LWMQTT_CONNECTION_DENIED
13:57:28.089 -> 5
13:57:28.089 -> LWMQTT_NOT_AUTHORIZED
13:57:28.089 -> Delaying 60000ms
-10
13:58:28.714 -> LWMQTT_CONNECTION_DENIED
13:58:28.714 -> 5
13:58:28.714 -> LWMQTT_NOT_AUTHORIZED
13:58:28.714 -> Delaying 60000ms
-10
13:59:29.298 -> LWMQTT_CONNECTION_DENIED
13:59:29.298 -> 5
13:59:29.298 -> LWMQTT_NOT_AUTHORIZED
13:59:29.298 -> Delaying 60000ms
-10
14:00:29.848 -> LWMQTT_CONNECTION_DENIED
14:00:29.848 -> 5
14:00:29.848 -> LWMQTT_NOT_AUTHORIZED
14:00:29.848 -> Delaying 60000ms
-10
14:01:30.483 -> LWMQTT_CONNECTION_DENIED
14:01:30.483 -> 5
14:01:30.483 -> LWMQTT_NOT_AUTHORIZED
14:01:30.483 -> Delaying 60000ms
-10
14:02:31.092 -> LWMQTT_CONNECTION_DENIED
14:02:31.092 -> 5
14:02:31.092 -> LWMQTT_NOT_AUTHORIZED
14:02:31.092 -> Delaying 60000ms
-10
14:03:31.673 -> LWMQTT_CONNECTION_DENIED
14:03:31.673 -> 5
14:03:31.673 -> LWMQTT_NOT_AUTHORIZED
14:03:31.673 -> Delaying 60000ms
-10
14:04:32.245 -> LWMQTT_CONNECTION_DENIED
14:04:32.245 -> 5
14:04:32.245 -> LWMQTT_NOT_AUTHORIZED
14:04:32.245 -> Delaying 60000ms
-10
14:05:32.823 -> LWMQTT_CONNECTION_DENIED
14:05:32.823 -> 5
14:05:32.857 -> LWMQTT_NOT_AUTHORIZED
14:05:32.857 -> Delaying 60000ms
-10
14:06:33.432 -> LWMQTT_CONNECTION_DENIED
14:06:33.432 -> 5
14:06:33.432 -> LWMQTT_NOT_AUTHORIZED
14:06:33.432 -> Delaying 60000ms
-10
14:07:34.016 -> LWMQTT_CONNECTION_DENIED
14:07:34.016 -> 5
14:07:34.049 -> LWMQTT_NOT_AUTHORIZED
14:07:34.049 -> Delaying 60000ms
-10
14:08:34.626 -> LWMQTT_CONNECTION_DENIED
14:08:34.626 -> 5
14:08:34.626 -> LWMQTT_NOT_AUTHORIZED
14:08:34.626 -> Delaying 60000ms
-10
14:09:35.204 -> LWMQTT_CONNECTION_DENIED
14:09:35.204 -> 5
14:09:35.204 -> LWMQTT_NOT_AUTHORIZED
14:09:35.204 -> Delaying 60000ms
-10
14:10:35.778 -> LWMQTT_CONNECTION_DENIED
14:10:35.778 -> 5
14:10:35.778 -> LWMQTT_NOT_AUTHORIZED
14:10:35.778 -> Delaying 60000ms
-10
14:11:36.387 -> LWMQTT_CONNECTION_DENIED
14:11:36.387 -> 5
14:11:36.387 -> LWMQTT_NOT_AUTHORIZED
14:11:36.387 -> Delaying 60000ms
-10
14:12:36.930 -> LWMQTT_CONNECTION_DENIED
14:12:36.930 -> 5
14:12:36.930 -> LWMQTT_NOT_AUTHORIZED
14:12:36.930 -> Delaying 60000ms
-10
14:13:37.511 -> LWMQTT_CONNECTION_DENIED
14:13:37.511 -> 5
14:13:37.511 -> LWMQTT_NOT_AUTHORIZED
14:13:37.511 -> Delaying 60000ms
-10
14:14:38.089 -> LWMQTT_CONNECTION_DENIED
14:14:38.089 -> 5
14:14:38.089 -> LWMQTT_NOT_AUTHORIZED
14:14:38.089 -> Delaying 60000ms
-10
14:15:38.699 -> LWMQTT_CONNECTION_DENIED
14:15:38.699 -> 5
14:15:38.699 -> LWMQTT_NOT_AUTHORIZED
14:15:38.699 -> Delaying 60000ms
-10
14:16:39.359 -> LWMQTT_CONNECTION_DENIED
14:16:39.359 -> 5
14:16:39.359 -> LWMQTT_NOT_AUTHORIZED
14:16:39.359 -> Delaying 60000ms
-10
14:17:39.942 -> LWMQTT_CONNECTION_DENIED
14:17:39.942 -> 5
14:17:39.942 -> LWMQTT_NOT_AUTHORIZED
14:17:39.942 -> Delaying 60000ms
-10
14:18:40.554 -> LWMQTT_CONNECTION_DENIED
14:18:40.554 -> 5
14:18:40.554 -> LWMQTT_NOT_AUTHORIZED
14:18:40.554 -> Delaying 60000ms
-10
14:19:41.105 -> LWMQTT_CONNECTION_DENIED
14:19:41.105 -> 5
14:19:41.105 -> LWMQTT_NOT_AUTHORIZED
14:19:41.105 -> Delaying 60000ms
-10
14:20:41.690 -> LWMQTT_CONNECTION_DENIED
14:20:41.690 -> 5
14:20:41.690 -> LWMQTT_NOT_AUTHORIZED
14:20:41.690 -> Delaying 60000ms
-10
14:21:42.297 -> LWMQTT_CONNECTION_DENIED
14:21:42.297 -> 5
14:21:42.297 -> LWMQTT_NOT_AUTHORIZED
14:21:42.297 -> Delaying 60000ms
-10
14:22:42.876 -> LWMQTT_CONNECTION_DENIED
14:22:42.876 -> 5
14:22:42.909 -> LWMQTT_NOT_AUTHORIZED
14:22:42.909 -> Delaying 60000ms
-10
14:23:43.522 -> LWMQTT_CONNECTION_DENIED
14:23:43.522 -> 5
14:23:43.522 -> LWMQTT_NOT_AUTHORIZED
14:23:43.522 -> Delaying 60000ms
-10
14:24:44.135 -> LWMQTT_CONNECTION_DENIED
14:24:44.135 -> 5
14:24:44.135 -> LWMQTT_NOT_AUTHORIZED
14:24:44.135 -> Delaying 60000ms
-10
14:25:45.078 -> LWMQTT_CONNECTION_DENIED
14:25:45.078 -> 5
14:25:45.078 -> LWMQTT_NOT_AUTHORIZED
14:25:45.078 -> Delaying 60000ms
Refreshing JWT

14:26:49.069 -> connected!
incoming: /devices/arduino-taste/config - 0
14:26:49.135 -> incoming: /devices/arduino-taste/config - 0

15:02:00.689 -> connecting...
15:02:08.249 -> connected!
incoming: /devices/arduino-taste/config - 0
15:02:08.316 -> incoming: /devices/arduino-taste/config - 0

However, you'll notice that the connection eventually corrects itself. I'll see if I can get the connection to properly drop / resetart after the JWT expires.

@Gior80
Copy link

Gior80 commented Mar 25, 2019

Hi Man,

had this problem for while and destroy my head on. If can help this seems direct connect in some way to MQTT protocol. looks like need to fully reset the connection ( or go to a timeout.... ) to reconnect, in fact if you reset also wifi cons and reopen full wifi + ssl + iot core this work good ( a workaround could do to set a 24 Expiry and do that 1 time a day). It would be SO useful to have acces to MQTT log ( I suppose ( I repeat I suppose....) IOT core is a layer on standard IBM MQTT) to verifiy what's happening on server side. Do you have ability to have a look with you google internal super power? ✌️

@gguuss
Copy link
Contributor

gguuss commented Mar 26, 2019

It looks to me that the current issue is that getJwt in each example is independently keeping state for the JWT issuance. I was able to successfully refresh the JWT and reconnect the client with the following change in ESP8266:

String getJwt() {
  if (iss == 0 || time(nullptr) - iss > 60) {  // TODO: exp in device
    // Disable software watchdog as these operations can take a while.
    ESP.wdtDisable();
    iss = time(nullptr);
    Serial.println("Refreshing JWT");
    jwt = device->createJWT(iss, 60); // TODO: fix force expiration
    ESP.wdtEnable(0);
  }
  return jwt;
}

There will be more refactoring necessary for making these less decoupled but I do believe that refresh is working, just out of sync with the token issue.

@gguuss
Copy link
Contributor

gguuss commented Mar 26, 2019

I found the bug -- the getJWT code was hardcoded to guard against refreshing the JWT too frequently.

This fix has been pushed to master and has been tested. This should release later this week.

I'll close the issue now, please reopen if you're still seeing the JWTs expire and not refresh after installing the latest library from the master branch.

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

No branches or pull requests

3 participants