VaultException Cannot renew lease Status 400 Bad Request lease not found during rotation of credentials

[fercam24]

Describe the bug
When using rotation of credentials I receive a

LeaseEventPublisher$LoggingErrorListener : [RequestedSecret [path='database/creds/datasource_dev-fallback_titan_titan-producer', mode=ROTATE]] Lease [leaseId='database/creds/datasource_dev-fallback_titan_titan-producer/7zukxovKwtAW1oQMpCqJl5Nk', leaseDuration=PT1M, renewable=true] Cannot renew lease: Status 400 Bad Requestlease not found; nested exception is org.springframework.vault.VaultException: Status 400 Bad Request: lease not found; nested exception is org.springframework.web.client.HttpClientErrorException$BadRequest: 400 Bad Request: [{"errors":["lease not found"]}

Actually the rotation happens (with some delay. Don't actually understand why) but I always get this exception.
Another thing is that I'm not sure to understand why the RequestedSecret has mode RENEW and when we ask for rotation we keep using mode ROTATION. Is there an impact on the behaviour?

If we look in the logs it starts with

Lease change for DB: (org.springframework.vault.core.lease.event.AfterSecretLeaseRenewedEvent[source=RequestedSecret [path='database/creds/datasource_dev-fallback_titan_titan-producer', mode=RENEW]]) : (Lease [leaseId='database/creds/datasource_dev-fallback_titan_titan-producer/Xxafr9a5kgeEOWxjUI94eL0o', leaseDuration=PT25S, renewable=true])

then it expires so we request a ROTATE

Lease change for DB: (org.springframework.vault.core.lease.event.SecretLeaseExpiredEvent[source=RequestedSecret [path='database/creds/datasource_dev-fallback_titan_titan-producer', mode=RENEW]]) : (Lease [leaseId='database/creds/datasource_dev-fallback_titan_titan-producer/Xxafr9a5kgeEOWxjUI94eL0o', leaseDuration=PT15S, renewable=true])
Database credentials lease expired. Replacing RENEW with ROTATE.

Right after we get a newly created lease with ROTATE mode and we update the database credentials

2020-12-17 16:22:47.531 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-1] c.l.t.p.vault.config.VaultConfiguration : Lease change for DB: (org.springframework.vault.core.lease.event.SecretLeaseCreatedEvent[source=RequestedSecret [path='database/creds/datasource_dev-fallback_titan_titan-producer', mode=ROTATE]]) : (Lease [leaseId='database/creds/datasource_dev-fallback_titan_titan-producer/7zukxovKwtAW1oQMpCqJl5Nk', leaseDuration=PT1M, renewable=true])
2020-12-17 16:22:47.532 WARN [titan-producer,,,] 1 --- [g-Cloud-Vault-1] c.l.t.p.vault.config.VaultConfiguration : Soft evicting database connections
2020-12-17 16:22:47.538 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-1] c.l.t.p.vault.config.VaultConfiguration : Updating database credentials
2020-12-17 16:22:47.740 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-2] o.s.v.a.LifecycleAwareSessionManager : Renewing token
2020-12-17 16:22:47.782 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-2] o.s.v.a.LifecycleAwareSessionManager : Token TTL (PT5S) exceeded validity TTL threshold (PT7S). Dropping token.

Then happens a renewal, and at the second one it has rotated the secrets again the secret (looking at leaseId)

Lease change for DB: (org.springframework.vault.core.lease.event.SecretLeaseCreatedEvent[source=RequestedSecret [path='database/creds/datasource_dev-fallback_titan_titan-producer', mode=ROTATE]]) : (Lease [leaseId='database/creds/datasource_dev-fallback_titan_titan-producer/ivyX0eR1q8Wr5TNbPeh9C1e7', leaseDuration=PT1M, renewable=true])

and then the previous one on renewal gets the exception. And it only happens after a rotation.

any idea?

Sample
Here is the Configuration I use for renewal
`
@flogger
@configuration
@ConditionalOnBean(SecretLeaseContainer.class)
@ConditionalOnProperty(
name = "titan.producer.scheduling.enabled",
havingValue = "true",
matchIfMissing = true)
public class VaultConfiguration {

@Autowired
private TitanProperties titanProperties;

@Autowired
private SecretLeaseContainer leaseContainer;

@Autowired
private ConfigurableApplicationContext applicationContext;

@Value("${spring.cloud.vault.database.role}")
private String databaseRole;

@Autowired
private RefreshScope refreshScope;

@Autowired
private HikariDataSource hikariDataSource;

@PostConstruct
private void configureApplicationRestartOnLeaseExpiration() {
    log.atInfo().log("Configuring application restart on lease expiration");

    String vaultCredsPath = String.format("database/creds/%s", databaseRole);

    leaseContainer.addLeaseListener(leaseEvent -> {
        RequestedSecret requestedSecret = leaseEvent.getSource();

        if (!requestedSecret.getPath().equals(vaultCredsPath)) {
            return;
        }

        log.atInfo().log("Lease change for DB: (%s) : (%s)", leaseEvent, leaseEvent.getLease());

        if (leaseEvent instanceof SecretLeaseExpiredEvent && requestedSecret.getMode().equals(RENEW)) {
            log.atInfo().log("Database credentials lease expired. Replacing RENEW with ROTATE.");
            leaseContainer.requestRotatingSecret(vaultCredsPath);
        }

        if (leaseEvent instanceof SecretLeaseCreatedEvent && requestedSecret.getMode().equals(ROTATE)) {
            SecretLeaseCreatedEvent event = (SecretLeaseCreatedEvent) leaseEvent;
            Credential credentials = getCredentials(event);
            if (credentials == null) {
                log.atSevere().log("Unable to get updated DB credentials. Shutting down.");
                applicationContext.close();
                return;
            }
            updateDatabaseConnection(credentials);
        }
    });
}

private void updateDatabaseConnection(Credential credentials) {
    updateDataSourceCredentialProperties(credentials);
    updateDataSource(credentials);
}

private void updateDataSourceCredentialProperties(Credential credentials) {
    System.setProperty("spring.datasource.username", credentials.getUser());
    System.setProperty("spring.datasource.password", credentials.getPassword());
}

private void updateDataSource(Credential credentials) {

    log.atWarning().log("Soft evicting database connections");
    HikariPoolMXBean dataSourcePoolBean = hikariDataSource.getHikariPoolMXBean();
    if (dataSourcePoolBean != null) {
        dataSourcePoolBean.softEvictConnections();
    }

    log.atInfo().log("Updating database credentials");
    HikariConfigMXBean dataSourceBean = hikariDataSource.getHikariConfigMXBean();
    dataSourceBean.setUsername(credentials.getUser());
    dataSourceBean.setPassword(credentials.getPassword());
}

private Credential getCredentials(SecretLeaseCreatedEvent createdEvent) {
    Map<String, Object> secrets = createdEvent.getSecrets();
    if (secrets.isEmpty()) {
        return null;
    }

    String username = (String) createdEvent.getSecrets().get("username");
    String password = (String) createdEvent.getSecrets().get("password");

    return new Credential(username, password);
}

}
`

my bootstrap.yml config
spring.cloud.vault: enabled: true discovery: enabled: false fail-fast: true authentication: APPROLE kv.enabled: false generic.enabled: false database: enabled: true role: datasource_${TITAN_PRODUCER_ENVKEY}-${TITAN_PRODUCER_GAMEKEY}_titan_${spring.application.name} username-property: spring.datasource.username password-property: spring.datasource.password config: order: -10 lifecycle: enabled: true lease-endpoints: SysLeases connection-timeout: 5000 read-timeout: 15000

The role in vault has a default_ttl of 60s and max_ttl of 6m (for testing purposes)

Debug logs

2020-12-17 16:22:37.202 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-2] c.l.t.p.vault.config.VaultConfiguration : Lease change for DB: (org.springframework.vault.core.lease.event.AfterSecretLeaseRenewedEvent[source=RequestedSecret [path='database/creds/datasource_dev-fallback_titan_titan-producer', mode=RENEW]]) : (Lease [leaseId='database/creds/datasource_dev-fallback_titan_titan-producer/Xxafr9a5kgeEOWxjUI94eL0o', leaseDuration=PT15S, renewable=true])
2020-12-17 16:22:47.202 DEBUG [titan-producer,,,] 1 --- [g-Cloud-Vault-1] cretLeaseContainer$LeaseRenewalScheduler : Renewing lease database/creds/datasource_dev-fallback_titan_titan-producer/Xxafr9a5kgeEOWxjUI94eL0o for secret database/creds/datasource_dev-fallback_titan_titan-producer
2020-12-17 16:22:47.367 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-1] c.l.t.p.vault.config.VaultConfiguration : Lease change for DB: (org.springframework.vault.core.lease.event.SecretLeaseExpiredEvent[source=RequestedSecret [path='database/creds/datasource_dev-fallback_titan_titan-producer', mode=RENEW]]) : (Lease [leaseId='database/creds/datasource_dev-fallback_titan_titan-producer/Xxafr9a5kgeEOWxjUI94eL0o', leaseDuration=PT15S, renewable=true])
2020-12-17 16:22:47.368 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-1] c.l.t.p.vault.config.VaultConfiguration : Database credentials lease expired. Replacing RENEW with ROTATE.
2020-12-17 16:22:47.529 DEBUG [titan-producer,,,] 1 --- [g-Cloud-Vault-1] o.s.v.core.lease.SecretLeaseContainer : Secret database/creds/datasource_dev-fallback_titan_titan-producer with Lease database/creds/datasource_dev-fallback_titan_titan-producer/7zukxovKwtAW1oQMpCqJl5Nk qualified for renewal
2020-12-17 16:22:47.530 DEBUG [titan-producer,,,] 1 --- [g-Cloud-Vault-1] cretLeaseContainer$LeaseRenewalScheduler : Scheduling renewal for secret database/creds/datasource_dev-fallback_titan_titan-producer with lease database/creds/datasource_dev-fallback_titan_titan-producer/7zukxovKwtAW1oQMpCqJl5Nk, lease duration 60
2020-12-17 16:22:47.531 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-1] c.l.t.p.vault.config.VaultConfiguration : Lease change for DB: (org.springframework.vault.core.lease.event.SecretLeaseCreatedEvent[source=RequestedSecret [path='database/creds/datasource_dev-fallback_titan_titan-producer', mode=ROTATE]]) : (Lease [leaseId='database/creds/datasource_dev-fallback_titan_titan-producer/7zukxovKwtAW1oQMpCqJl5Nk', leaseDuration=PT1M, renewable=true])
2020-12-17 16:22:47.532 WARN [titan-producer,,,] 1 --- [g-Cloud-Vault-1] c.l.t.p.vault.config.VaultConfiguration : Soft evicting database connections
2020-12-17 16:22:47.538 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-1] c.l.t.p.vault.config.VaultConfiguration : Updating database credentials
2020-12-17 16:22:47.740 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-2] o.s.v.a.LifecycleAwareSessionManager : Renewing token
2020-12-17 16:22:47.782 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-2] o.s.v.a.LifecycleAwareSessionManager : Token TTL (PT5S) exceeded validity TTL threshold (PT7S). Dropping token.
2020-12-17 16:22:57.531 DEBUG [titan-producer,,,] 1 --- [g-Cloud-Vault-1] cretLeaseContainer$LeaseRenewalScheduler : Renewing lease database/creds/datasource_dev-fallback_titan_titan-producer/7zukxovKwtAW1oQMpCqJl5Nk for secret database/creds/datasource_dev-fallback_titan_titan-producer
2020-12-17 16:22:57.623 DEBUG [titan-producer,,,] 1 --- [g-Cloud-Vault-1] o.s.v.a.AppRoleAuthentication : Login successful using AppRole authentication
2020-12-17 16:22:57.623 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-1] o.s.v.a.LifecycleAwareSessionManager : Scheduling Token renewal
2020-12-17 16:22:57.649 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-1] c.l.t.p.vault.config.VaultConfiguration : Lease change for DB: (org.springframework.vault.core.lease.event.SecretLeaseExpiredEvent[source=RequestedSecret [path='database/creds/datasource_dev-fallback_titan_titan-producer', mode=ROTATE]]) : (Lease [leaseId='database/creds/datasource_dev-fallback_titan_titan-producer/7zukxovKwtAW1oQMpCqJl5Nk', leaseDuration=PT1M, renewable=true])
2020-12-17 16:22:57.857 DEBUG [titan-producer,,,] 1 --- [g-Cloud-Vault-1] o.s.v.core.lease.SecretLeaseContainer : Secret database/creds/datasource_dev-fallback_titan_titan-producer with Lease database/creds/datasource_dev-fallback_titan_titan-producer/ivyX0eR1q8Wr5TNbPeh9C1e7 qualified for renewal
2020-12-17 16:22:57.857 DEBUG [titan-producer,,,] 1 --- [g-Cloud-Vault-1] cretLeaseContainer$LeaseRenewalScheduler : Scheduling renewal for secret database/creds/datasource_dev-fallback_titan_titan-producer with lease database/creds/datasource_dev-fallback_titan_titan-producer/ivyX0eR1q8Wr5TNbPeh9C1e7, lease duration 60
2020-12-17 16:22:57.858 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-1] c.l.t.p.vault.config.VaultConfiguration : Lease change for DB: (org.springframework.vault.core.lease.event.SecretLeaseCreatedEvent[source=RequestedSecret [path='database/creds/datasource_dev-fallback_titan_titan-producer', mode=ROTATE]]) : (Lease [leaseId='database/creds/datasource_dev-fallback_titan_titan-producer/ivyX0eR1q8Wr5TNbPeh9C1e7', leaseDuration=PT1M, renewable=true])
2020-12-17 16:22:57.858 WARN [titan-producer,,,] 1 --- [g-Cloud-Vault-1] c.l.t.p.vault.config.VaultConfiguration : Soft evicting database connections
2020-12-17 16:22:57.858 INFO [titan-producer,,,] 1 --- [g-Cloud-Vault-1] c.l.t.p.vault.config.VaultConfiguration : Updating database credentials
2020-12-17 16:22:57.863 WARN [titan-producer,,,] 1 --- [g-Cloud-Vault-1] LeaseEventPublisher$LoggingErrorListener : [RequestedSecret [path='database/creds/datasource_dev-fallback_titan_titan-producer', mode=ROTATE]] Lease [leaseId='database/creds/datasource_dev-fallback_titan_titan-producer/7zukxovKwtAW1oQMpCqJl5Nk', leaseDuration=PT1M, renewable=true] Cannot renew lease: Status 400 Bad Requestlease not found; nested exception is org.springframework.vault.VaultException: Status 400 Bad Request: lease not found; nested exception is org.springframework.web.client.HttpClientErrorException$BadRequest: 400 Bad Request: [{"errors":["lease not found"]}
]
org.springframework.vault.VaultException: Cannot renew lease: Status 400 Bad Requestlease not found; nested exception is org.springframework.vault.VaultException: Status 400 Bad Request: lease not found; nested exception is org.springframework.web.client.HttpClientErrorException$BadRequest: 400 Bad Request: [{"errors":["lease not found"]}
]
at org.springframework.vault.core.lease.SecretLeaseContainer.doRenewLease(SecretLeaseContainer.java:713)
at org.springframework.vault.core.lease.SecretLeaseContainer.renewAndSchedule(SecretLeaseContainer.java:589)
at org.springframework.vault.core.lease.SecretLeaseContainer.lambda$scheduleLeaseRenewal$0(SecretLeaseContainer.java:581)
at org.springframework.vault.core.lease.SecretLeaseContainer$LeaseRenewalScheduler$1.run(SecretLeaseContainer.java:891)
at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:93)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.base/java.lang.Thread.run(Unknown Source)
Caused by: org.springframework.vault.VaultException: Status 400 Bad Request: lease not found; nested exception is org.springframework.web.client.HttpClientErrorException$BadRequest: 400 Bad Request: [{"errors":["lease not found"]}
]
at org.springframework.vault.client.VaultResponses.buildException(VaultResponses.java:63)
at org.springframework.vault.core.VaultTemplate.doWithSession(VaultTemplate.java:469)
at org.springframework.vault.core.lease.SecretLeaseContainer.doRenew(SecretLeaseContainer.java:751)
at org.springframework.vault.core.lease.SecretLeaseContainer.doRenewLease(SecretLeaseContainer.java:688)
... 11 common frames omitted
Caused by: org.springframework.web.client.HttpClientErrorException$BadRequest: 400 Bad Request: [{"errors":["lease not found"]}
]
at org.springframework.web.client.HttpClientErrorException.create(HttpClientErrorException.java:101)
at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:184)
at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:125)
at org.springframework.web.client.ResponseErrorHandler.handleError(ResponseErrorHandler.java:63)
at org.springframework.web.client.RestTemplate.handleResponse(RestTemplate.java:780)
at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:738)
at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:672)
at org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:581)
at org.springframework.vault.core.lease.LeaseEndpoints$2.renew(LeaseEndpoints.java:88)
at org.springframework.vault.core.lease.SecretLeaseContainer.lambda$doRenew$2(SecretLeaseContainer.java:752)
at org.springframework.vault.core.VaultTemplate.doWithSession(VaultTemplate.java:466)
... 13 common frames omitted

[mp911de]

The sample above is a bit hard to understand. Can you provide a reproducer so we can look into the issue? Don't worry about the actual database. Having a Postgres or MySQL connector should be sufficient to let us the rest work out.

[mp911de]

Closing due to lack of requested feedback. If you would like us to look at this issue, please provide the requested information and we will re-open the issue.

[codergitcli]

@fercam24 Did you figure out what caused the "400 Bad Request: lease not found" exceptions? I am facing the same, although it gets printed as a WARN message. But it pollutes the logs with stacktraces.

[sullrich84]

see #256