Test: update TokenAuthIntegTests to modify document to test expiration

This change modifies how we test the deletion of expired documents to be in line with elastic/x-pack-elasticsearch#3468 and
also adds debugging output in case the failures in CI continue.

Relates elastic/x-pack-elasticsearch#2253

Original commit: elastic/x-pack-elasticsearch@979b5357f5

plugin/src/main/java/org/elasticsearch/xpack/security/authc/ExpiredTokenRemover.java

@@ -6,7 +6,9 @@
 package org.elasticsearch.xpack.security.authc;
 
 import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.message.ParameterizedMessage;
 import org.elasticsearch.action.ActionListener;
+import org.elasticsearch.action.bulk.BulkItemResponse;
 import org.elasticsearch.action.search.SearchRequest;
 import org.elasticsearch.client.Client;
 import org.elasticsearch.common.logging.Loggers;
@@ -14,8 +16,10 @@ import org.elasticsearch.common.settings.Settings;
 import org.elasticsearch.common.unit.TimeValue;
 import org.elasticsearch.common.util.concurrent.AbstractRunnable;
 import org.elasticsearch.index.query.QueryBuilders;
+import org.elasticsearch.index.reindex.BulkByScrollResponse;
 import org.elasticsearch.index.reindex.DeleteByQueryAction;
 import org.elasticsearch.index.reindex.DeleteByQueryRequest;
+import org.elasticsearch.index.reindex.ScrollableHitSource;
 import org.elasticsearch.threadpool.ThreadPool;
 import org.elasticsearch.threadpool.ThreadPool.Names;
 import org.elasticsearch.xpack.security.SecurityLifecycleService;
@@ -56,8 +60,10 @@ final class ExpiredTokenRemover extends AbstractRunnable {
                         .filter(QueryBuilders.termQuery("doc_type", TokenService.DOC_TYPE))
                         .filter(QueryBuilders.rangeQuery("expiration_time").lte(Instant.now().toEpochMilli())));
         executeAsyncWithOrigin(client, SECURITY_ORIGIN, DeleteByQueryAction.INSTANCE, dbq,
-                ActionListener.wrap(r -> markComplete(),
+                ActionListener.wrap(r -> {
-                    e -> {
+                    debugDbqResponse(r);
+                    markComplete();
+                }, e -> {
                         if (isShardNotAvailableException(e) == false) {
                             logger.error("failed to delete expired tokens", e);
                         }
@@ -71,6 +77,21 @@ final class ExpiredTokenRemover extends AbstractRunnable {
         }
     }
 
+    private void debugDbqResponse(BulkByScrollResponse response) {
+        if (logger.isDebugEnabled()) {
+            logger.debug("delete by query of tokens finished with [{}] deletions, [{}] bulk failures, [{}] search failures",
+                    response.getDeleted(), response.getBulkFailures().size(), response.getSearchFailures().size());
+            for (BulkItemResponse.Failure failure : response.getBulkFailures()) {
+                logger.debug(new ParameterizedMessage("deletion failed for index [{}], type [{}], id [{}]",
+                        failure.getIndex(), failure.getType(), failure.getId()), failure.getCause());
+            }
+            for (ScrollableHitSource.SearchFailure failure : response.getSearchFailures()) {
+                logger.debug(new ParameterizedMessage("search failed for index [{}], shard [{}] on node [{}]",
+                        failure.getIndex(), failure.getShardId(), failure.getNodeId()), failure.getReason());
+            }
+        }
+    }
+
     boolean isExpirationInProgress() {
         return inProgress.get();
     }

plugin/src/test/java/org/elasticsearch/xpack/security/authc/TokenAuthIntegTests.java

@@ -9,6 +9,7 @@ import org.elasticsearch.ElasticsearchSecurityException;
 import org.elasticsearch.action.admin.cluster.state.ClusterStateResponse;
 import org.elasticsearch.action.search.SearchResponse;
 import org.elasticsearch.action.support.PlainActionFuture;
+import org.elasticsearch.action.support.WriteRequest;
 import org.elasticsearch.client.Client;
 import org.elasticsearch.cluster.ack.ClusterStateUpdateResponse;
 import org.elasticsearch.common.settings.SecureString;
@@ -18,6 +19,7 @@ import org.elasticsearch.index.query.QueryBuilders;
 import org.elasticsearch.search.builder.SearchSourceBuilder;
 import org.elasticsearch.test.SecurityIntegTestCase;
 import org.elasticsearch.test.SecuritySettingsSource;
+import org.elasticsearch.test.junit.annotations.TestLogging;
 import org.elasticsearch.xpack.XPackSettings;
 import org.elasticsearch.xpack.security.SecurityLifecycleService;
 import org.elasticsearch.xpack.security.action.token.CreateTokenResponse;
@@ -30,9 +32,11 @@ import org.junit.Before;
 import java.io.IOException;
 import java.io.UncheckedIOException;
 import java.time.Instant;
+import java.time.temporal.ChronoUnit;
 import java.util.Collections;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.concurrent.atomic.AtomicReference;
 
 import static org.hamcrest.Matchers.equalTo;
 import static org.hamcrest.Matchers.greaterThan;
@@ -43,8 +47,7 @@ public class TokenAuthIntegTests extends SecurityIntegTestCase {
     public Settings nodeSettings(int nodeOrdinal) {
         return Settings.builder()
                 .put(super.nodeSettings(nodeOrdinal))
-                // turn down token expiration interval and crank up the deletion interval
+                // crank up the deletion interval and set timeout for delete requests
-                .put(TokenService.TOKEN_EXPIRATION.getKey(), TimeValue.timeValueSeconds(1L))
                 .put(TokenService.DELETE_INTERVAL.getKey(), TimeValue.timeValueSeconds(1L))
                 .put(TokenService.DELETE_TIMEOUT.getKey(), TimeValue.timeValueSeconds(2L))
                 .put(XPackSettings.TOKEN_SERVICE_ENABLED_SETTING.getKey(), true)
@@ -117,6 +120,7 @@ public class TokenAuthIntegTests extends SecurityIntegTestCase {
         }
     }
 
+    @TestLogging("org.elasticsearch.xpack.security.authc:DEBUG")
     public void testExpiredTokensDeletedAfterExpiration() throws Exception {
         final Client client = client().filterWithHeader(Collections.singletonMap("Authorization",
                 UsernamePasswordToken.basicAuthHeaderValue(SecuritySettingsSource.TEST_SUPERUSER,
@@ -132,15 +136,25 @@ public class TokenAuthIntegTests extends SecurityIntegTestCase {
 
         InvalidateTokenResponse invalidateResponse = securityClient.prepareInvalidateToken(response.getTokenString()).get();
         assertTrue(invalidateResponse.isCreated());
+        AtomicReference<String> docId = new AtomicReference<>();
         assertBusy(() -> {
             SearchResponse searchResponse = client.prepareSearch(SecurityLifecycleService.SECURITY_INDEX_NAME)
                     .setSource(SearchSourceBuilder.searchSource().query(QueryBuilders.termQuery("doc_type", TokenService.DOC_TYPE)))
-                    .setSize(0)
+                    .setSize(1)
                     .setTerminateAfter(1)
                     .get();
-            assertThat(searchResponse.getHits().getTotalHits(), greaterThan(0L));
+            assertThat(searchResponse.getHits().getTotalHits(), equalTo(1L));
+            docId.set(searchResponse.getHits().getAt(0).getId());
         });
 
+        // hack doc to modify the time to the day before
+        Instant dayBefore = created.minus(1L, ChronoUnit.DAYS);
+        assertTrue(Instant.now().isAfter(dayBefore));
+        client.prepareUpdate(SecurityLifecycleService.SECURITY_INDEX_NAME, "doc", docId.get())
+                .setDoc("expiration_time", dayBefore.toEpochMilli())
+                .setRefreshPolicy(WriteRequest.RefreshPolicy.IMMEDIATE)
+                .get();
+
         AtomicBoolean deleteTriggered = new AtomicBoolean(false);
         assertBusy(() -> {
             assertTrue(Instant.now().isAfter(created.plusSeconds(1L).plusMillis(500L)));