Service unable to obtain a Vault Token after expiring

[nyameen]

Hello,

I am wondering if anyone has faced this issue and if there is a way to solve it without restarting multiple services manually. In secure mode, each service is given a Vault Token for communicating to Vault. This token is only valid for 1 hour and is supposed to be renewed every 30 minutes. If a service is stopped, and then restarted after 1 hour, it cannot start. For example, you can stop any device or app service, in this case, device-modbus

$ docker-compose up -d
$ docker stop edgex-device-modbus
# wait 1 hour...

$ docker start edgex-device-modbus

In the device-modbus logs you will see this repeatedly until secretstore-setup is manually restarted:

Mon Apr  8 10:52:40 EDT 2024 Executing waitFor with /device-modbus -cp=consul.http://edgex-core-consul:8500 --registry waiting on tcp://edgex-security-bootstrapper:54329
level=INFO ts=2024-04-08T14:52:40.081590107Z app=security-bootstrapper source=config.go:731 msg="Loading configuration file from /edgex-init/res/configuration.yaml"
level=INFO ts=2024-04-08T14:52:40.081832254Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'StageGate/BootStrapper/Host' by environment variable: STAGEGATE_BOOTSTRAPPER_HOST=edgex-security-bootstrapper"
level=INFO ts=2024-04-08T14:52:40.081856904Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'StageGate/Registry/ReadyPort' by environment variable: STAGEGATE_REGISTRY_READYPORT=54324"
level=INFO ts=2024-04-08T14:52:40.081862251Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'StageGate/SecretStoreSetup/Host' by environment variable: STAGEGATE_SECRETSTORESETUP_HOST=edgex-security-secretstore-setup"
level=INFO ts=2024-04-08T14:52:40.081865799Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'StageGate/Registry/Host' by environment variable: STAGEGATE_REGISTRY_HOST=edgex-core-consul"
level=INFO ts=2024-04-08T14:52:40.081869091Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'StageGate/Database/ReadyPort' by environment variable: STAGEGATE_DATABASE_READYPORT=6379"
level=INFO ts=2024-04-08T14:52:40.081873297Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'StageGate/Ready/ToRunPort' by environment variable: STAGEGATE_READY_TORUNPORT=54329"
level=INFO ts=2024-04-08T14:52:40.081876504Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'StageGate/Database/Host' by environment variable: STAGEGATE_DATABASE_HOST=edgex-redis"
level=INFO ts=2024-04-08T14:52:40.081879733Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'StageGate/Database/Port' by environment variable: STAGEGATE_DATABASE_PORT=6379"
level=INFO ts=2024-04-08T14:52:40.081883198Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'StageGate/BootStrapper/StartPort' by environment variable: STAGEGATE_BOOTSTRAPPER_STARTPORT=54321"
level=INFO ts=2024-04-08T14:52:40.081886628Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'SecretStore/Host' by environment variable: SECRETSTORE_HOST=edgex-vault"
level=INFO ts=2024-04-08T14:52:40.081900796Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'StageGate/WaitFor/Timeout' by environment variable: STAGEGATE_WAITFOR_TIMEOUT=60s"
level=INFO ts=2024-04-08T14:52:40.081906437Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'StageGate/SecretStoreSetup/Tokens/ReadyPort' by environment variable: STAGEGATE_SECRETSTORESETUP_TOKENS_READYPORT=54322"
level=INFO ts=2024-04-08T14:52:40.081920921Z app=security-bootstrapper source=variables.go:462 msg="Variables override of 'StageGate/Registry/Port' by environment variable: STAGEGATE_REGISTRY_PORT=8500"
level=INFO ts=2024-04-08T14:52:40.081926877Z app=security-bootstrapper source=config.go:251 msg="Private configuration loaded from file with 13 overrides applied"
level=INFO ts=2024-04-08T14:52:40.082088204Z app=security-bootstrapper source=command.go:119 msg="Security bootstrapper running waitFor"
level=INFO ts=2024-04-08T14:52:40.082142486Z app=security-bootstrapper source=command.go:144 msg="Waiting for: [tcp://edgex-security-bootstrapper:54329] with timeout: [1m0s]"
level=INFO ts=2024-04-08T14:52:40.084120904Z app=security-bootstrapper source=command.go:214 msg="Connected to tcp://edgex-security-bootstrapper:54329"
Mon Apr  8 10:52:40 EDT 2024 Starting /device-modbus -cp=consul.http://edgex-core-consul:8500 --registry ...
level=INFO ts=2024-04-08T14:52:40.09118069Z app=device-modbus source=secret.go:69 msg="Creating SecretClient"
level=INFO ts=2024-04-08T14:52:40.091349396Z app=device-modbus source=variables.go:462 msg="Variables override of 'SecretStore/Host' by environment variable: SECRETSTORE_HOST=edgex-vault"
level=INFO ts=2024-04-08T14:52:40.09176703Z app=device-modbus source=secret.go:172 msg="SecretStore information created with 1 overrides applied"
level=INFO ts=2024-04-08T14:52:40.091789455Z app=device-modbus source=secret.go:79 msg="Reading secret store configuration and authentication token"
level=INFO ts=2024-04-08T14:52:40.091815447Z app=device-modbus source=secret.go:216 msg="load token from file"
level=INFO ts=2024-04-08T14:52:40.0918817Z app=device-modbus source=secret.go:101 msg="Attempting to create secret client"
level=WARN ts=2024-04-08T14:52:40.093027985Z app=device-modbus source=secret.go:132 msg="Retryable failure while creating SecretClient: HTTP response with status code 403, message: failed to lookup token"
level=INFO ts=2024-04-08T14:52:41.093228648Z app=device-modbus source=secret.go:79 msg="Reading secret store configuration and authentication token"
level=INFO ts=2024-04-08T14:52:41.093283236Z app=device-modbus source=secret.go:216 msg="load token from file"
level=INFO ts=2024-04-08T14:52:41.093359875Z app=device-modbus source=secret.go:101 msg="Attempting to create secret client"
level=WARN ts=2024-04-08T14:52:41.094754752Z app=device-modbus source=secret.go:132 msg="Retryable failure while creating SecretClient: HTTP response with status code 403, message: failed to lookup token"
level=INFO ts=2024-04-08T14:52:42.094861604Z app=device-modbus source=secret.go:79 msg="Reading secret store configuration and authentication token"
level=INFO ts=2024-04-08T14:52:42.094927865Z app=device-modbus source=secret.go:216 msg="load token from file"
level=INFO ts=2024-04-08T14:52:42.0950129Z app=device-modbus source=secret.go:101 msg="Attempting to create secret client"
level=WARN ts=2024-04-08T14:52:42.096275804Z app=device-modbus source=secret.go:132 msg="Retryable failure while creating SecretClient: HTTP response with status code 403, message: failed to lookup token"
level=INFO ts=2024-04-08T14:52:43.096653098Z app=device-modbus source=secret.go:79 msg="Reading secret store configuration and authentication token"
level=INFO ts=2024-04-08T14:52:43.096769719Z app=device-modbus source=secret.go:216 msg="load token from file"
level=INFO ts=2024-04-08T14:52:43.096921259Z app=device-modbus source=secret.go:101 msg="Attempting to create secret client"

...

level=INFO ts=2024-04-08T14:53:39.254430923Z app=device-modbus source=secret.go:101 msg="Attempting to create secret client"
level=WARN ts=2024-04-08T14:53:39.255664552Z app=device-modbus source=secret.go:132 msg="Retryable failure while creating SecretClient: HTTP response with status code 403, message: failed to lookup token"
level=ERROR ts=2024-04-08T14:53:40.256126896Z app=device-modbus source=bootstrap.go:48 msg="failed to create SecretProvider: unable to create SecretClient: HTTP response with status code 403, message: failed to lookup token"

Is there a way I can successfully start device-modbus without having to restart the entire deployment?

[cloudxxx8]

can you resolve this by restarting secretstore-setup

[jrtitus]

Hi @cloudxxx8 - yes, we have seen that it is resolved when secretstore-setup is restarted, but the goal would be to not have to manually restart this service.

[cloudxxx8]

Another workaround is to extend the token TTL
You can add an environment variable here:
https://github.com/edgexfoundry/edgex-compose/blob/c25035d319c2721f419fa1864a28196a409b7fe8/docker-compose.yml#L1005

TOKENFILEPROVIDER_DEFAULTTOKENTTL: 720h
default is 1h
it depends on your security policy

[cloudxxx8]

Refer to: https://github.com/edgexfoundry/edgex-go/blob/971ded0da61705452274f4b577f848bc3eecf2cb/cmd/security-secretstore-setup/res-file-token-provider/configuration.yaml#L14

[jrtitus]

Thank you, @cloudxxx8. So, this particular TTL is associated with the Vault token that is used to renew the service-to-service JWT, while the DefaultJWTTTL is the amount of time that the service-to-service token produced by this renewal is good for. In that case if any of the service containers are down for longer than DefaultTokenTTL, there's no other option other than restarting the secretstore-setup container to generate a new Vault identity provider token and JWTs for all services.

Did I understand that correctly?

Does each service use its generated client_token to request a token refresh during its lifetime? So, if a service misses the DefaultTokenTTL window, or the Default token has already been refreshed (and thus the two tokens no longer have any relation), this would explain why there's nothing else that can be done other than regenerating the value in the secrets-token.json.

[cloudxxx8]

You can also refer to another approach
https://docs.edgexfoundry.org/3.1/security/Ch-DelayedStartServices/
https://docs.edgexfoundry.org/3.1/design/adr/security/0020-spiffe/

[teenccu]

@nyameen @jrtitus @cloudxxx8 As discussed during the meeting , if a service is missing the window of renewing its token the today there is no way that the service to retreive a new token from vault. Of course, restarting of secres-store setup can fix this but this cannot be a acceptable solution in production. Also forcing renewing a token with a expired token might introduce some vulneraibility. So may be the solution should be to introduce a way to manually approve with human intervention the workflow of regenerating a token for a service whose token is already expired. This can be though a new implemetation with new API. @cloudxxx8 dont hesiate to correct me or add any point I might have missed.

[teenccu]

@cloudxxx8 , today secret-store is responsible for generating the initial token and the services are responsible for renewing the future tokens subsequently. I was wondering if secret-store is modified to renew the token periodically , do you think the default behavior of the services for renewing the token will be impacted ?

[cloudxxx8]

There are two kinds of token in the system, one is the secret-store token (we called vault token before v3.1), and another one is the JWT for micro service authentication.
For the service behavior, it loads the secret-store token from the tmp file system when the service starts up and retrieve JWT from the secret store (Vault/OpenBao).
If the service is restarted, the secret-store token from the tmp file system usually has expired. If the secret-store-setup can renew the secret-store token in the tmp filesystem periodically, the behavior of the services should no be impacted, because they would still load the secret-store token from the tmp filesystem when they start up.
If the secret-store token expires, the services should just reload the file. If the JWT expires, the services should just re-retrieve the JWT from the secret store.

[teenccu]

@cloudxxx8 , I was having impression that services were actually renewing the secret store token and the JWT tokens are exchanged with the current token by the services. I was not aware that it is possible to continue to exchange JWT token with another JWT token even if the intial secret store token was expired. But if that is the case , the solution is ok for me.

[lamigue]

Hello @cloudxxx8, we also had another issue on changing the box time. For example, with this scenario:

First, can you confirm this scenario? What about the JWT token which is still working while the secret token is theorically expired?
Is the secret store token validated through a date and in this case, would your solution work (periodically renew token through secret store setup)?

[cloudxxx8]

@lamigue micro services retrieve JWT from the secret store via the secret store token. When JWT is expired, services will retrieve the new JWT from secret store again. If the secret store token is epxired, micro services can't retrieve JWT anymore. As Lindsey mentioned, micro services keep renewing the secret store token expireation time in the background. Thus, as long as the services are running, the token won't expire.

[lindseysimple]

Here's a summary in this discussion so far:

The service secret-store token's lease will be periodically renewed(every half of the TokenTTL duration) after the service starts.
However, if the service is stopped for a period of time and then restarted with an expired secret-store token , it will encounter a 403 failed to lookup token error from the secret-store.

Current workarounds:

1. Extend the DefaultTokenTTL and DefaultJWTTTL durations defined in /cmd/security-secretstore-setup/res-file-token-provider/configuration.yaml.
2. Run a script or a cron job periodically to restart the secretstore-setup service, ensuring it regenerates the service secret-store tokens if they have expired.

We are actively investigating looking at this issue and try to come up with a good solution with security is concerned.
@nyameen @jrtitus @teenccu Feel free to share any ideas you may have, thanks!

[lindseysimple]

@nyameen @jrtitus @teenccu

I've opened edgexfoundry/edgex-go#5065 to fix this issue.
It would be great if you could review the design and let me know if you have any suggestions, thanks.

[teenccu]

@cloudxxx8 and @lindseysimple

Could you please clarify in case the secretstore is restarted by any external procedure,, how does it impact a service for which the token is expired for any reason. The service is obviously in failure status as its token is not valid for the instant. Does the service will recover by itself as soon as the new token is regenerated by the secret-store ?

[lindseysimple]

@teenccu Based on your scenario, the answer is 'yes'! Once the secretstore-setup service is restarted, it would revoke all the secret-store token leases and re-generate the tokens for all services.

Here is the log showing device-virtual initially starting with an expired secret-store token. Shortly after, the secretstore-setup service was restarted, and device-virtual successfully loaded the newly generated secret-store token, allowing it to start successfully in the end.

level=INFO ts=2025-01-23T04:08:10.065203415Z app=device-virtual source=secret.go:77 msg="Reading secret store configuration and authentication token"                
level=INFO ts=2025-01-23T04:08:10.065248832Z app=device-virtual source=secret.go:214 msg="load token from file"                                                      
level=INFO ts=2025-01-23T04:08:10.065315833Z app=device-virtual source=secret.go:99 msg="Attempting to create secret client"                                         
level=WARN ts=2025-01-23T04:08:10.065884672Z app=device-virtual source=secret.go:130 msg="Retryable failure while creating SecretClient: HTTP response with status code 403, message: failed to lookup token"                                                                                                                             
level=INFO ts=2025-01-23T04:08:11.065989449Z app=device-virtual source=secret.go:77 msg="Reading secret store configuration and authentication token"                
level=INFO ts=2025-01-23T04:08:11.066051575Z app=device-virtual source=secret.go:214 msg="load token from file"
level=INFO ts=2025-01-23T04:08:11.066097283Z app=device-virtual source=secret.go:99 msg="Attempting to create secret client"                                         
level=WARN ts=2025-01-23T04:08:11.06709121Z app=device-virtual source=secret.go:130 msg="Retryable failure while creating SecretClient: HTTP response with status code 403, message: failed to lookup token"                                                                                                                              
level=INFO ts=2025-01-23T04:08:12.068370839Z app=device-virtual source=secret.go:77 msg="Reading secret store configuration and authentication token"
level=INFO ts=2025-01-23T04:08:12.068479382Z app=device-virtual source=secret.go:214 msg="load token from file"                                                      
level=INFO ts=2025-01-23T04:08:12.068577091Z app=device-virtual source=secret.go:99 msg="Attempting to create secret client"
level=INFO ts=2025-01-23T04:08:12.070610986Z app=device-virtual source=secret.go:110 msg="Created SecretClient"                                                      
level=INFO ts=2025-01-23T04:08:12.070641861Z app=device-virtual source=secret.go:115 msg="SecretsFile not set, skipping seeding of service secrets."                 
level=INFO ts=2025-01-23T04:08:12.070689404Z app=device-virtual source=config.go:723 msg="Using Configuration provider (keeper) from: http://edgex-core-keeper:59890 with base path of edgex/v4/core-common-config-bootstrapper/all-services
level=INFO ts=2025-01-23T04:08:12.070830363Z app=device-virtual source=secrets.go:215 msg="kick off token renewal with interval: 2m30s"                              
level=WARN ts=2025-01-23T04:08:12.077830266Z app=device-virtual source=config.go:1084 msg="waiting for Common Configuration to be available from config provider"    
level=WARN ts=2025-01-23T04:08:13.091818445Z app=device-virtual source=config.go:1084 msg="waiting for Common Configuration to be available from config provider"    
level=WARN ts=2025-01-23T04:08:14.103608984Z app=device-virtual source=config.go:1084 msg="waiting for Common Configuration to be available from config provider"    level=WARN ts=2025-01-23T04:08:15.116015121Z app=device-virtual source=config.go:1084 msg="waiting for Common Configuration to be available from config provider"    
level=WARN ts=2025-01-23T04:08:16.130228491Z app=device-virtual source=config.go:1084 msg="waiting for Common Configuration to be available from config provider"    
level=INFO ts=2025-01-23T04:08:17.169604076Z app=device-virtual source=config.go:462 msg="loading the common configuration for service type device-service"          
level=INFO ts=2025-01-23T04:08:17.169837787Z app=device-virtual source=config.go:723 msg="Using Configuration provider (keeper) from: http://edgex-core-keeper:59890 with base path of edgex/v4/core-common-config-bootstrapper/device-services"                                                                                          
level=INFO ts=2025-01-23T04:08:17.185445816Z app=device-virtual source=config.go:178 msg="Common configuration loaded from the Configuration Provider. No overrides applied"                                                                                                                                                              
level=INFO ts=2025-01-23T04:08:17.18549615Z app=device-virtual source=config.go:723 msg="Using Configuration provider (keeper) from: http://edgex-core-keeper:59890 with base path of edgex/v4/device-virtual"                                                                                                                            
level=INFO ts=2025-01-23T04:08:17.200111587Z app=device-virtual source=config.go:223 msg="Private configuration loaded from the Configuration Provider. No overrides applied"                                                                                                                                                             
level=INFO ts=2025-01-23T04:08:17.200148795Z app=device-virtual source=config.go:274 msg="listening for private config changes"                                      
level=INFO ts=2025-01-23T04:08:17.200154587Z app=device-virtual source=config.go:276 msg="listening for all services common config changes"                          
level=INFO ts=2025-01-23T04:08:17.200158837Z app=device-virtual source=config.go:283 msg="listening for device service common config changes"                        
level=INFO ts=2025-01-23T04:08:17.200166087Z app=device-virtual source=registry.go:64 msg="Using Registry (keeper) from http://edgex-core-keeper:59890"              
level=INFO ts=2025-01-23T04:08:17.208145583Z app=device-virtual source=httpserver.go:152 msg="Web server starting (edgex-device-virtual:59900)"                      
level=INFO ts=2025-01-23T04:08:17.208182667Z app=device-virtual source=messaging.go:66 msg="Setting options for secure MessageBus with AuthMode='usernamepassword' and SecretName='message-bus"                                                                                                                                           
level=INFO ts=2025-01-23T04:08:17.208259417Z app=device-virtual source=ziti.go:231 msg="listening on underlay network. ListenMode '' at edgex-device-virtual:59900"  
level=INFO ts=2025-01-23T04:08:17.210220728Z app=device-virtual source=messaging.go:104 msg="Connected to mqtt Message Bus @ mqtt://edgex-mqtt-broker:1883 with AuthMode='usernamepassword'"                                                                                                                                              
level=INFO ts=2025-01-23T04:08:17.210264437Z app=device-virtual source=command.go:36 msg="Subscribing to command requests on topic: edgex/device/command/request/device-virtual/#"                                                                                                                                                        
level=INFO ts=2025-01-23T04:08:17.210271854Z app=device-virtual source=command.go:40 msg="Responses to command requests will be published on topic: edgex/response/device-virtual/<requestId>"                                                                                                                                            
level=INFO ts=2025-01-23T04:08:17.210584857Z app=device-virtual source=callback.go:37 msg="Subscribing to System Events on topics: edgex/system-events/core-metadata/+/+/device-virtual/# and edgex/system-events/core-metadata/deviceprofile/delete/#"                                                                                   
level=INFO ts=2025-01-23T04:08:17.210857651Z app=device-virtual source=validation.go:31 msg="Subscribing to device validation requests on topic: edgex/device-virtual/validate/device"                                                                                                                                                    
level=INFO ts=2025-01-23T04:08:17.21087136Z app=device-virtual source=validation.go:35 msg="Responses to device validation requests will be published on topic: edgex/response/device-virtual/<requestId>"                                                                                                                                
level=INFO ts=2025-01-23T04:08:17.21122953Z app=device-virtual source=manager.go:128 msg="Metrics Manager started with a report interval of 30s"                     
level=INFO ts=2025-01-23T04:08:17.211261447Z app=device-virtual source=clients.go:90 msg="Using ClientBaseUrlFunc for 'security-proxy-auth' clients"                 
level=WARN ts=2025-01-23T04:08:17.21127178Z app=device-virtual source=secure.go:464 msg="refusing to override httpRoundTripper, already set"                         
level=WARN ts=2025-01-23T04:08:17.211292322Z app=device-virtual source=secure.go:476 msg="refusing to override fallbackDialer, already set"                          
level=INFO ts=2025-01-23T04:08:17.211303406Z app=device-virtual source=clients.go:90 msg="Using ClientBaseUrlFunc for 'core-metadata' clients"                       
level=INFO ts=2025-01-23T04:08:17.211348406Z app=device-virtual source=restrouter.go:55 msg="Registering routes..."                                                  
level=INFO ts=2025-01-23T04:08:17.21411685Z app=device-virtual source=init.go:170 msg="Check service 'core-metadata' availability succeeded"                         
level=INFO ts=2025-01-23T04:08:17.21659025Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"
level=INFO ts=2025-01-23T04:08:17.222770894Z app=device-virtual source=devices.go:75 msg="LastConnected-Random-UnsignedInteger-Device metric has been registered and will be reported (if enabled)"                                                                                                                                       
level=INFO ts=2025-01-23T04:08:17.222774186Z app=device-virtual source=devices.go:75 msg="LastConnected-Random-Float-Device metric has been registered and will be reported (if enabled)"                                                                                                                                                 
level=INFO ts=2025-01-23T04:08:17.222777436Z app=device-virtual source=devices.go:75 msg="LastConnected-Random-Binary-Device metric has been registered and will be reported (if enabled)"                                                                                                                                                
level=INFO ts=2025-01-23T04:08:17.225731799Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.232030236Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.238323757Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.244344192Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.249653536Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.254828004Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.260149306Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.262721415Z app=device-virtual source=service.go:320 msg="device service device-virtual exists, updating it"                        
level=INFO ts=2025-01-23T04:08:17.265352191Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.26955965Z app=device-virtual source=profiles.go:89 msg="Loading pre-defined Device Profiles from /res/profiles(5 files found)"     
level=INFO ts=2025-01-23T04:08:17.272201843Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.275088871Z app=device-virtual source=profiles.go:190 msg="Device Profile Random-Binary-Device exists, using the existing one"      
level=INFO ts=2025-01-23T04:08:17.277733689Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.280879095Z app=device-virtual source=profiles.go:190 msg="Device Profile Random-Boolean-Device exists, using the existing one"     
level=INFO ts=2025-01-23T04:08:17.28371429Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                   
level=INFO ts=2025-01-23T04:08:17.286369816Z app=device-virtual source=profiles.go:190 msg="Device Profile Random-Float-Device exists, using the existing one"       
level=INFO ts=2025-01-23T04:08:17.289364429Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.292206249Z app=device-virtual source=profiles.go:190 msg="Device Profile Random-Integer-Device exists, using the existing one"     
level=INFO ts=2025-01-23T04:08:17.295039986Z app=device-virtual source=clients.go:209 msg="Using registry for URL for 'core-metadata': http://edgex-core-metadata:59881"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.297758138Z app=device-virtual source=profiles.go:190 msg="Device Profile Random-UnsignedInteger-Device exists, using the existing one"                                                                                                                                                                  
level=INFO ts=2025-01-23T04:08:17.297823305Z app=device-virtual source=devices.go:107 msg="Loading pre-defined Devices from /res/devices(1 files found)"             
level=INFO ts=2025-01-23T04:08:17.298020932Z app=device-virtual source=devices.go:187 msg="Device Random-Boolean-Device exists, using the existing one"              
level=INFO ts=2025-01-23T04:08:17.298037307Z app=device-virtual source=devices.go:187 msg="Device Random-Integer-Device exists, using the existing one"              
level=INFO ts=2025-01-23T04:08:17.298040849Z app=device-virtual source=devices.go:187 msg="Device Random-UnsignedInteger-Device exists, using the existing one"      
level=INFO ts=2025-01-23T04:08:17.29804364Z app=device-virtual source=devices.go:187 msg="Device Random-Float-Device exists, using the existing one"                 
level=INFO ts=2025-01-23T04:08:17.29804614Z app=device-virtual source=devices.go:187 msg="Device Random-Binary-Device exists, using the existing one"                
level=INFO ts=2025-01-23T04:08:17.298087724Z app=device-virtual source=autodiscovery.go:32 msg="AutoDiscovery stopped: disabled by configuration"                    
level=INFO ts=2025-01-23T04:08:17.298101974Z app=device-virtual source=autodiscovery.go:40 msg="AutoDiscovery schedule is not started: interval <= 0"                
level=INFO ts=2025-01-23T04:08:17.298104724Z app=device-virtual source=message.go:50 msg="Service dependencies resolved..."                                          
level=INFO ts=2025-01-23T04:08:17.298118974Z app=device-virtual source=message.go:51 msg="Starting device-virtual 4.0.0-dev.12 "                                     
level=INFO ts=2025-01-23T04:08:17.298121516Z app=device-virtual source=message.go:55 msg="device virtual started"                                                    
level=INFO ts=2025-01-23T04:08:17.298124099Z app=device-virtual source=message.go:58 msg="Service started in: 52.564234632s"      

However, the restart of the secretstore-setup would temporarily affect Core-Keeper or other service which is continuously invoking the EdgeX service API, as the secret-store token was revoked and then re-generated by secretstore-setup. Here's the Core Keeper log for example:

level=ERROR ts=2025-01-23T04:08:12.077442137Z app=core-keeper source=auth_secretstore.go:24 msg="Error checking JWT validity by the secret provider: Error found on handling secrets from underlying data-store: Received a '403' response from the secret store "
level=ERROR ts=2025-01-23T04:08:13.090624433Z app=core-keeper source=auth_secretstore.go:24 msg="Error checking JWT validity by the secret provider: Error found on handling secrets from underlying data-store: Received a '403' response from the secret store "
level=ERROR ts=2025-01-23T04:08:14.102768309Z app=core-keeper source=auth_secretstore.go:24 msg="Error checking JWT validity by the secret provider: Error found on handling secrets from underlying data-store: Received a '403' response from the secret store "
level=ERROR ts=2025-01-23T04:08:15.115144945Z app=core-keeper source=auth_secretstore.go:24 msg="Error checking JWT validity by the secret provider: Error found on handling secrets from underlying data-store: Received a '403' response from the secret store "
level=ERROR ts=2025-01-23T04:08:16.129653985Z app=core-keeper source=auth_secretstore.go:24 msg="Error checking JWT validity by the secret provider: Error found on handling secrets from underlying data-store: Received a '403' response from the secret store "
level=INFO ts=2025-01-23T04:08:16.61133938Z app=core-keeper source=secrets.go:244 msg="auth token is replaced"

[teenccu]

Well my scenario was the service started well with a good token , gets paused for some reason resulting eventually failure to renew the token in the time frame and then its restarted. Now the secret-store might have renewed the token but does the failing service would look for this renewed token so that it can recover ?

[lindseysimple]

When a service is looking for a secret-store token, it will always check the shared docker volume /tmp/edgex/secrets/<service-name> where the secretstore-setup stores the tokens for each service. Therefore, after the secretstore-setup service is restarted, a new token will be generated in the same location (/tmp/edgex/secrets/<service-name>). The failing service can then retrieve this new token and start successfully.

[lindseysimple]

@nyameen @jrtitus @lamigue The issue has been improved in edgexfoundry/edgex-go#5065 and change included in the latest main. You might take a try when you have time, thanks!