CCloud auth expiration doesn't disconnect cleanly

[shouples]

Seen after hitting the 8-hour session expiration, where it looks like we only got an INVALID_TOKEN status:

2025-02-28 04:16:55.645 [info] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.RefreshCCloudTokensBean] Refreshed tokens of connection with ID=vscode-confluent-cloud-connection.
2025-02-28 04:17:29.312 [debug] [Confluent] [docker.eventListener] stream ended: Body Timeout Error
2025-02-28 04:17:29.817 [debug] [Confluent] [docker.configs] docker ping response: OK
2025-02-28 04:17:29.817 [debug] [Confluent] [docker.eventListener] dockerAvailable: true
2025-02-28 04:17:29.821 [debug] [Confluent] [docker.eventListener] reading from stream...
2025-02-28 04:21:55.598 [info] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.RefreshCCloudTokensBean] Refreshed tokens of connection with ID=vscode-confluent-cloud-connection.
2025-02-28 04:22:29.947 [debug] [Confluent] [docker.eventListener] stream ended: Body Timeout Error
2025-02-28 04:22:30.452 [debug] [Confluent] [docker.configs] docker ping response: OK
2025-02-28 04:22:30.452 [debug] [Confluent] [docker.eventListener] dockerAvailable: true
2025-02-28 04:22:30.455 [debug] [Confluent] [docker.eventListener] reading from stream...
2025-02-28 04:26:55.612 [info] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.RefreshCCloudTokensBean] Refreshed tokens of connection with ID=vscode-confluent-cloud-connection.
2025-02-28 04:27:30.884 [debug] [Confluent] [docker.eventListener] stream ended: Body Timeout Error
2025-02-28 04:27:31.095 [debug] [Confluent] [docker.configs] docker ping response: OK
2025-02-28 04:27:31.095 [debug] [Confluent] [docker.eventListener] dockerAvailable: true
2025-02-28 04:27:31.096 [debug] [Confluent] [docker.eventListener] reading from stream...
2025-02-28 04:32:00.040 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}
2025-02-28 04:32:00.041 [info] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.connections.ConnectionState] Updated status for connection ID=vscode-confluent-cloud-connection. Original spec: ConnectionStatus[ccloud=CCloudStatus[state=SUCCESS, requiresAuthenticationAt=2025-02-28T09:29:06.499129Z, user=UserInfo[...], errors=null], kafkaCluster=null, schemaRegistry=null], Updated spec: ConnectionStatus[ccloud=CCloudStatus[state=EXPIRED, requiresAuthenticationAt=null, user=null, errors=null], kafkaCluster=null, schemaRegistry=null], Last updated: 2025-02-28T09:32:00.039801Z
2025-02-28 04:32:00.041 [info] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.cache.ClusterCache] Disconnected ConnectionSpec[id=vscode-confluent-cloud-connection, name=Confluent Cloud, type=CCLOUD, ccloudConfig=CCloudConfig[organizationId=null, ideAuthCallbackUri=vscode://confluentinc.vscode-confluent/authCallback], localConfig=null, kafkaClusterConfig=null, schemaRegistryConfig=null]
2025-02-28 04:32:00.041 [debug] [Confluent] [sidecar.connections.watcher] ConnectionStateWatcher: received DISCONNECTED event for connection id vscode-confluent-cloud-connection
2025-02-28 04:32:00.041 [debug] [Confluent] [sidecar.connections.statusUtils] connectionEventHandler: ccloud connection update received, passing to reactToCCloudAuthState()
2025-02-28 04:32:00.041 [debug] [Confluent] [authn.ccloudStateHandling] received update to CCloud connection {"status":"INVALID_TOKEN"}
2025-02-28 04:32:00.064 [debug] [Confluent] [authn.ccloudProvider] authProvider: secrets.onDidChange event {"key":"ccloudAuthStatus"}
2025-02-28 04:32:05.037 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}
2025-02-28 04:32:10.038 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}
2025-02-28 04:32:15.050 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}
2025-02-28 04:32:20.041 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}
2025-02-28 04:32:25.049 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}
2025-02-28 04:32:30.045 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}
2025-02-28 04:32:31.221 [debug] [Confluent] [docker.eventListener] stream ended: Body Timeout Error
2025-02-28 04:32:31.691 [debug] [Confluent] [docker.configs] docker ping response: OK
2025-02-28 04:32:31.691 [debug] [Confluent] [docker.eventListener] dockerAvailable: true
2025-02-28 04:32:31.694 [debug] [Confluent] [docker.eventListener] reading from stream...
2025-02-28 04:32:35.053 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}
2025-02-28 04:32:40.033 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}
2025-02-28 04:32:45.040 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}
2025-02-28 04:32:50.041 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}
2025-02-28 04:32:55.046 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}
2025-02-28 04:33:00.047 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}

[shouples]

@flippingbits since we also see 2025-02-28 04:32:00.041 [info] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.connections.ConnectionState] ... Updated spec: ConnectionStatus[ccloud=CCloudStatus[state=EXPIRED, requiresAuthenticationAt=null, user=null, errors=null], kafkaCluster=null, schemaRegistry=null] from the sidecar logs, would handling #855 take care of this issue?

I'm surprised we don't get any other websocket events aside from 2025-02-28 04:32:00.041 [debug] [Confluent] [authn.ccloudStateHandling] received update to CCloud connection {"status":"INVALID_TOKEN"}

[flippingbits]

Thanks for reporting it and looping me in, @shouples!

I don't think #855 would handle this issue, as the status.ccloud's EXPIRED status equals the status.authentications INVALID_TOKEN status (see here).

From reading the logs, the sidecar seems to report that the CCloud control plane token is invalid after consulting the CCloud API: 2025-02-28 04:32:00.040 [error] [Confluent (Sidecar)] [io.confluent.idesidecar.restapi.auth.CCloudOAuthContext] Error in CCloud response while verifying the auth status of this connection: {"code":401,"message":"token is expired","error_code":"token_expired"}.

It looks like the absolute lifetime of the refresh token ended at 2025-02-28T09:29:06.499129Z, which is why the sidecar stopped refreshing the control plane token (the next refresh would have been performed at 2025-02-28T09:31:55Z).

Unfortunately, the sidecar doesn't report a non-transient error in this case, which would let the VS Code extension prompt the user to re-authenticate, but assumes that the VS Code extension has noted the requiresAuthenticationAt timestamp earlier. IIRC, the extension prompts the user to reauthenticate shortly before the end of the 8-hour window?

I feel we should fix this on the sidecar side and let it reset the CCloud connection (and set its status to the initial NONE/NO_TOKEN status), once the CCloud connection's refresh token has hit the end of its absolute lifetime, assuming this doesn't cause any weird experience/behavior on the extension side. WDYT? We can also chat about it over Zoom later today if you like.

[shouples]

I feel we should fix this on the sidecar side and let it reset the CCloud connection (and set its status to the initial NONE/NO_TOKEN status), once the CCloud connection's refresh token has hit the end of its absolute lifetime, assuming this doesn't cause any weird experience/behavior on the extension side.

@flippingbits thanks for the info here! Currently the extension blocks any CCloud-related requests via its middleware when we see the INVALID_TOKEN state, so having a follow-on event to reset the connection state makes sense to me. 👍

And yep, we should be floating CCloud auth expiration warning notifications as soon as the session has <1hr before the 8hr window.