Examples with TestLogging org.elasticsearch.test.junit.annotations.TestLogging used on opensource projects

Example 21 with TestLogging

use of org.elasticsearch.test.junit.annotations.TestLogging in project elasticsearch by elastic.

the class DiscoveryWithServiceDisruptionsIT method testStaleMasterNotHijackingMajority.

/**
     * Tests that emulates a frozen elected master node that unfreezes and pushes his cluster state to other nodes
     * that already are following another elected master node. These nodes should reject this cluster state and prevent
     * them from following the stale master.
     */
@TestLogging("_root:DEBUG,org.elasticsearch.cluster.service:TRACE,org.elasticsearch.test.disruption:TRACE")
public void testStaleMasterNotHijackingMajority() throws Exception {
    // 3 node cluster with unicast discovery and minimum_master_nodes set to 2:
    final List<String> nodes = startCluster(3, 2);
    // Save the current master node as old master node, because that node will get frozen
    final String oldMasterNode = internalCluster().getMasterName();
    for (String node : nodes) {
        ensureStableCluster(3, node);
    }
    assertMaster(oldMasterNode, nodes);
    // Simulating a painful gc by suspending all threads for a long time on the current elected master node.
    SingleNodeDisruption masterNodeDisruption = new LongGCDisruption(random(), oldMasterNode);
    // Save the majority side
    final List<String> majoritySide = new ArrayList<>(nodes);
    majoritySide.remove(oldMasterNode);
    // Keeps track of the previous and current master when a master node transition took place on each node on the majority side:
    final Map<String, List<Tuple<String, String>>> masters = Collections.synchronizedMap(new HashMap<String, List<Tuple<String, String>>>());
    for (final String node : majoritySide) {
        masters.put(node, new ArrayList<Tuple<String, String>>());
        internalCluster().getInstance(ClusterService.class, node).addListener(event -> {
            DiscoveryNode previousMaster = event.previousState().nodes().getMasterNode();
            DiscoveryNode currentMaster = event.state().nodes().getMasterNode();
            if (!Objects.equals(previousMaster, currentMaster)) {
                logger.info("node {} received new cluster state: {} \n and had previous cluster state: {}", node, event.state(), event.previousState());
                String previousMasterNodeName = previousMaster != null ? previousMaster.getName() : null;
                String currentMasterNodeName = currentMaster != null ? currentMaster.getName() : null;
                masters.get(node).add(new Tuple<>(previousMasterNodeName, currentMasterNodeName));
            }
        });
    }
    final CountDownLatch oldMasterNodeSteppedDown = new CountDownLatch(1);
    internalCluster().getInstance(ClusterService.class, oldMasterNode).addListener(event -> {
        if (event.state().nodes().getMasterNodeId() == null) {
            oldMasterNodeSteppedDown.countDown();
        }
    });
    internalCluster().setDisruptionScheme(masterNodeDisruption);
    logger.info("freezing node [{}]", oldMasterNode);
    masterNodeDisruption.startDisrupting();
    // Wait for the majority side to get stable
    assertDifferentMaster(majoritySide.get(0), oldMasterNode);
    assertDifferentMaster(majoritySide.get(1), oldMasterNode);
    // the test is periodically tripping on the following assertion. To find out which threads are blocking the nodes from making
    // progress we print a stack dump
    boolean failed = true;
    try {
        assertDiscoveryCompleted(majoritySide);
        failed = false;
    } finally {
        if (failed) {
            logger.error("discovery failed to complete, probably caused by a blocked thread: {}", new HotThreads().busiestThreads(Integer.MAX_VALUE).ignoreIdleThreads(false).detect());
        }
    }
    // The old master node is frozen, but here we submit a cluster state update task that doesn't get executed,
    // but will be queued and once the old master node un-freezes it gets executed.
    // The old master node will send this update + the cluster state where he is flagged as master to the other
    // nodes that follow the new master. These nodes should ignore this update.
    internalCluster().getInstance(ClusterService.class, oldMasterNode).submitStateUpdateTask("sneaky-update", new ClusterStateUpdateTask(Priority.IMMEDIATE) {

        @Override
        public ClusterState execute(ClusterState currentState) throws Exception {
            return ClusterState.builder(currentState).build();
        }

        @Override
        public void onFailure(String source, Exception e) {
            logger.warn((Supplier<?>) () -> new ParameterizedMessage("failure [{}]", source), e);
        }
    });
    // Save the new elected master node
    final String newMasterNode = internalCluster().getMasterName(majoritySide.get(0));
    logger.info("new detected master node [{}]", newMasterNode);
    // Stop disruption
    logger.info("Unfreeze node [{}]", oldMasterNode);
    masterNodeDisruption.stopDisrupting();
    oldMasterNodeSteppedDown.await(30, TimeUnit.SECONDS);
    // Make sure that the end state is consistent on all nodes:
    assertDiscoveryCompleted(nodes);
    assertMaster(newMasterNode, nodes);
    assertThat(masters.size(), equalTo(2));
    for (Map.Entry<String, List<Tuple<String, String>>> entry : masters.entrySet()) {
        String nodeName = entry.getKey();
        List<Tuple<String, String>> recordedMasterTransition = entry.getValue();
        assertThat("[" + nodeName + "] Each node should only record two master node transitions", recordedMasterTransition.size(), equalTo(2));
        assertThat("[" + nodeName + "] First transition's previous master should be [null]", recordedMasterTransition.get(0).v1(), equalTo(oldMasterNode));
        assertThat("[" + nodeName + "] First transition's current master should be [" + newMasterNode + "]", recordedMasterTransition.get(0).v2(), nullValue());
        assertThat("[" + nodeName + "] Second transition's previous master should be [null]", recordedMasterTransition.get(1).v1(), nullValue());
        assertThat("[" + nodeName + "] Second transition's current master should be [" + newMasterNode + "]", recordedMasterTransition.get(1).v2(), equalTo(newMasterNode));
    }
}

Example 22 with TestLogging

use of org.elasticsearch.test.junit.annotations.TestLogging in project elasticsearch by elastic.

the class IndexPrimaryRelocationIT method testPrimaryRelocationWhileIndexing.

@TestLogging("_root:DEBUG,org.elasticsearch.action.bulk:TRACE,org.elasticsearch.index.shard:TRACE,org.elasticsearch.cluster.service:TRACE")
public void testPrimaryRelocationWhileIndexing() throws Exception {
    internalCluster().ensureAtLeastNumDataNodes(randomIntBetween(2, 3));
    client().admin().indices().prepareCreate("test").setSettings(Settings.builder().put("index.number_of_shards", 1).put("index.number_of_replicas", 0)).addMapping("type", "field", "type=text").get();
    ensureGreen("test");
    AtomicInteger numAutoGenDocs = new AtomicInteger();
    final AtomicBoolean finished = new AtomicBoolean(false);
    Thread indexingThread = new Thread() {

        @Override
        public void run() {
            while (finished.get() == false) {
                IndexResponse indexResponse = client().prepareIndex("test", "type", "id").setSource("field", "value").get();
                assertEquals(DocWriteResponse.Result.CREATED, indexResponse.getResult());
                DeleteResponse deleteResponse = client().prepareDelete("test", "type", "id").get();
                assertEquals(DocWriteResponse.Result.DELETED, deleteResponse.getResult());
                client().prepareIndex("test", "type").setSource("auto", true).get();
                numAutoGenDocs.incrementAndGet();
            }
        }
    };
    indexingThread.start();
    ClusterState initialState = client().admin().cluster().prepareState().get().getState();
    DiscoveryNode[] dataNodes = initialState.getNodes().getDataNodes().values().toArray(DiscoveryNode.class);
    DiscoveryNode relocationSource = initialState.getNodes().getDataNodes().get(initialState.getRoutingTable().shardRoutingTable("test", 0).primaryShard().currentNodeId());
    for (int i = 0; i < RELOCATION_COUNT; i++) {
        DiscoveryNode relocationTarget = randomFrom(dataNodes);
        while (relocationTarget.equals(relocationSource)) {
            relocationTarget = randomFrom(dataNodes);
        }
        logger.info("--> [iteration {}] relocating from {} to {} ", i, relocationSource.getName(), relocationTarget.getName());
        client().admin().cluster().prepareReroute().add(new MoveAllocationCommand("test", 0, relocationSource.getId(), relocationTarget.getId())).execute().actionGet();
        ClusterHealthResponse clusterHealthResponse = client().admin().cluster().prepareHealth().setWaitForEvents(Priority.LANGUID).setWaitForNoRelocatingShards(true).execute().actionGet();
        assertThat(clusterHealthResponse.isTimedOut(), equalTo(false));
        logger.info("--> [iteration {}] relocation complete", i);
        relocationSource = relocationTarget;
        if (indexingThread.isAlive() == false) {
            // indexing process aborted early, no need for more relocations as test has already failed
            break;
        }
        if (i > 0 && i % 5 == 0) {
            logger.info("--> [iteration {}] flushing index", i);
            client().admin().indices().prepareFlush("test").get();
        }
    }
    finished.set(true);
    indexingThread.join();
    refresh("test");
    ElasticsearchAssertions.assertHitCount(client().prepareSearch("test").get(), numAutoGenDocs.get());
    ElasticsearchAssertions.assertHitCount(// extra paranoia ;)
    client().prepareSearch("test").setQuery(QueryBuilders.termQuery("auto", true)).get(), numAutoGenDocs.get());
}

Example 23 with TestLogging

use of org.elasticsearch.test.junit.annotations.TestLogging in project elasticsearch by elastic.

the class ClusterServiceTests method testLongClusterStateUpdateLogging.

// To ensure that we log cluster state events on WARN level
@TestLogging("org.elasticsearch.cluster.service:WARN")
public void testLongClusterStateUpdateLogging() throws Exception {
    MockLogAppender mockAppender = new MockLogAppender();
    mockAppender.start();
    mockAppender.addExpectation(new MockLogAppender.UnseenEventExpectation("test1 shouldn't see because setting is too low", "org.elasticsearch.cluster.service.ClusterServiceTests$TimedClusterService", Level.WARN, "*cluster state update task [test1] took [*] above the warn threshold of *"));
    mockAppender.addExpectation(new MockLogAppender.SeenEventExpectation("test2", "org.elasticsearch.cluster.service.ClusterServiceTests$TimedClusterService", Level.WARN, "*cluster state update task [test2] took [32s] above the warn threshold of *"));
    mockAppender.addExpectation(new MockLogAppender.SeenEventExpectation("test3", "org.elasticsearch.cluster.service.ClusterServiceTests$TimedClusterService", Level.WARN, "*cluster state update task [test3] took [33s] above the warn threshold of *"));
    mockAppender.addExpectation(new MockLogAppender.SeenEventExpectation("test4", "org.elasticsearch.cluster.service.ClusterServiceTests$TimedClusterService", Level.WARN, "*cluster state update task [test4] took [34s] above the warn threshold of *"));
    Logger clusterLogger = Loggers.getLogger("org.elasticsearch.cluster.service");
    Loggers.addAppender(clusterLogger, mockAppender);
    try {
        final CountDownLatch latch = new CountDownLatch(5);
        final CountDownLatch processedFirstTask = new CountDownLatch(1);
        clusterService.currentTimeOverride = System.nanoTime();
        clusterService.submitStateUpdateTask("test1", new ClusterStateUpdateTask() {

            @Override
            public ClusterState execute(ClusterState currentState) throws Exception {
                clusterService.currentTimeOverride += TimeValue.timeValueSeconds(1).nanos();
                return currentState;
            }

            @Override
            public void clusterStateProcessed(String source, ClusterState oldState, ClusterState newState) {
                latch.countDown();
                processedFirstTask.countDown();
            }

            @Override
            public void onFailure(String source, Exception e) {
                fail();
            }
        });
        processedFirstTask.await();
        clusterService.submitStateUpdateTask("test2", new ClusterStateUpdateTask() {

            @Override
            public ClusterState execute(ClusterState currentState) throws Exception {
                clusterService.currentTimeOverride += TimeValue.timeValueSeconds(32).nanos();
                throw new IllegalArgumentException("Testing handling of exceptions in the cluster state task");
            }

            @Override
            public void clusterStateProcessed(String source, ClusterState oldState, ClusterState newState) {
                fail();
            }

            @Override
            public void onFailure(String source, Exception e) {
                latch.countDown();
            }
        });
        clusterService.submitStateUpdateTask("test3", new ClusterStateUpdateTask() {

            @Override
            public ClusterState execute(ClusterState currentState) throws Exception {
                clusterService.currentTimeOverride += TimeValue.timeValueSeconds(33).nanos();
                return ClusterState.builder(currentState).incrementVersion().build();
            }

            @Override
            public void clusterStateProcessed(String source, ClusterState oldState, ClusterState newState) {
                latch.countDown();
            }

            @Override
            public void onFailure(String source, Exception e) {
                fail();
            }
        });
        clusterService.submitStateUpdateTask("test4", new ClusterStateUpdateTask() {

            @Override
            public ClusterState execute(ClusterState currentState) throws Exception {
                clusterService.currentTimeOverride += TimeValue.timeValueSeconds(34).nanos();
                return currentState;
            }

            @Override
            public void clusterStateProcessed(String source, ClusterState oldState, ClusterState newState) {
                latch.countDown();
            }

            @Override
            public void onFailure(String source, Exception e) {
                fail();
            }
        });
        // Additional update task to make sure all previous logging made it to the loggerName
        // We don't check logging for this on since there is no guarantee that it will occur before our check
        clusterService.submitStateUpdateTask("test5", new ClusterStateUpdateTask() {

            @Override
            public ClusterState execute(ClusterState currentState) {
                return currentState;
            }

            @Override
            public void clusterStateProcessed(String source, ClusterState oldState, ClusterState newState) {
                latch.countDown();
            }

            @Override
            public void onFailure(String source, Exception e) {
                fail();
            }
        });
        latch.await();
    } finally {
        Loggers.removeAppender(clusterLogger, mockAppender);
        mockAppender.stop();
    }
    mockAppender.assertAllExpectationsMatched();
}

Example 24 with TestLogging

use of org.elasticsearch.test.junit.annotations.TestLogging in project elasticsearch by elastic.

the class IndexActionIT method testAutoGenerateIdNoDuplicates.

/**
     * This test tries to simulate load while creating an index and indexing documents
     * while the index is being created.
     */
@TestLogging("_root:DEBUG,org.elasticsearch.index.shard.IndexShard:TRACE,org.elasticsearch.action.search:TRACE")
public void testAutoGenerateIdNoDuplicates() throws Exception {
    int numberOfIterations = scaledRandomIntBetween(10, 50);
    for (int i = 0; i < numberOfIterations; i++) {
        Exception firstError = null;
        createIndex("test");
        int numOfDocs = randomIntBetween(10, 100);
        logger.info("indexing [{}] docs", numOfDocs);
        List<IndexRequestBuilder> builders = new ArrayList<>(numOfDocs);
        for (int j = 0; j < numOfDocs; j++) {
            builders.add(client().prepareIndex("test", "type").setSource("field", "value_" + j));
        }
        indexRandom(true, builders);
        logger.info("verifying indexed content");
        int numOfChecks = randomIntBetween(8, 12);
        for (int j = 0; j < numOfChecks; j++) {
            try {
                logger.debug("running search with all types");
                SearchResponse response = client().prepareSearch("test").get();
                if (response.getHits().getTotalHits() != numOfDocs) {
                    final String message = "Count is " + response.getHits().getTotalHits() + " but " + numOfDocs + " was expected. " + ElasticsearchAssertions.formatShardStatus(response);
                    logger.error("{}. search response: \n{}", message, response);
                    fail(message);
                }
            } catch (Exception e) {
                logger.error("search for all docs types failed", e);
                if (firstError == null) {
                    firstError = e;
                }
            }
            try {
                logger.debug("running search with a specific type");
                SearchResponse response = client().prepareSearch("test").setTypes("type").get();
                if (response.getHits().getTotalHits() != numOfDocs) {
                    final String message = "Count is " + response.getHits().getTotalHits() + " but " + numOfDocs + " was expected. " + ElasticsearchAssertions.formatShardStatus(response);
                    logger.error("{}. search response: \n{}", message, response);
                    fail(message);
                }
            } catch (Exception e) {
                logger.error("search for all docs of a specific type failed", e);
                if (firstError == null) {
                    firstError = e;
                }
            }
        }
        if (firstError != null) {
            fail(firstError.getMessage());
        }
        internalCluster().wipeIndices("test");
    }
}