Examples with MockLogAppender org.elasticsearch.test.MockLogAppender used on opensource projects

Example 11 with MockLogAppender

use of org.elasticsearch.test.MockLogAppender in project crate by crate.

the class NodeConnectionsServiceTests method testDebugLogging.

@TestLogging(value = "org.elasticsearch.cluster.NodeConnectionsService:DEBUG")
public void testDebugLogging() throws IllegalAccessException {
    final DeterministicTaskQueue deterministicTaskQueue = new DeterministicTaskQueue(builder().put(NODE_NAME_SETTING.getKey(), "node").build(), random());
    MockTransport transport = new MockTransport(deterministicTaskQueue.getThreadPool());
    TestTransportService transportService = new TestTransportService(transport, deterministicTaskQueue.getThreadPool());
    transportService.start();
    transportService.acceptIncomingRequests();
    final NodeConnectionsService service = new NodeConnectionsService(Settings.EMPTY, deterministicTaskQueue.getThreadPool(), transportService);
    service.start();
    final List<DiscoveryNode> allNodes = generateNodes();
    final DiscoveryNodes targetNodes = discoveryNodesFromList(randomSubsetOf(allNodes));
    service.connectToNodes(targetNodes, () -> {
    });
    deterministicTaskQueue.runAllRunnableTasks();
    // periodic reconnections to unexpectedly-disconnected nodes are logged
    final Set<DiscoveryNode> disconnectedNodes = new HashSet<>(randomSubsetOf(allNodes));
    for (DiscoveryNode disconnectedNode : disconnectedNodes) {
        transportService.disconnectFromNode(disconnectedNode);
    }
    MockLogAppender appender = new MockLogAppender();
    try {
        appender.start();
        Loggers.addAppender(LogManager.getLogger("org.elasticsearch.cluster.NodeConnectionsService"), appender);
        for (DiscoveryNode targetNode : targetNodes) {
            if (disconnectedNodes.contains(targetNode)) {
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("connecting to " + targetNode, "org.elasticsearch.cluster.NodeConnectionsService", Level.DEBUG, "connecting to " + targetNode));
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("connected to " + targetNode, "org.elasticsearch.cluster.NodeConnectionsService", Level.DEBUG, "connected to " + targetNode));
            } else {
                appender.addExpectation(new MockLogAppender.UnseenEventExpectation("connecting to " + targetNode, "org.elasticsearch.cluster.NodeConnectionsService", Level.DEBUG, "connecting to " + targetNode));
                appender.addExpectation(new MockLogAppender.UnseenEventExpectation("connected to " + targetNode, "org.elasticsearch.cluster.NodeConnectionsService", Level.DEBUG, "connected to " + targetNode));
            }
        }
        runTasksUntil(deterministicTaskQueue, CLUSTER_NODE_RECONNECT_INTERVAL_SETTING.get(Settings.EMPTY).millis());
        appender.assertAllExpectationsMatched();
    } finally {
        Loggers.removeAppender(LogManager.getLogger("org.elasticsearch.cluster.NodeConnectionsService"), appender);
        appender.stop();
    }
    for (DiscoveryNode disconnectedNode : disconnectedNodes) {
        transportService.disconnectFromNode(disconnectedNode);
    }
    // changes to the expected set of nodes are logged, including reconnections to any unexpectedly-disconnected nodes
    final DiscoveryNodes newTargetNodes = discoveryNodesFromList(randomSubsetOf(allNodes));
    for (DiscoveryNode disconnectedNode : disconnectedNodes) {
        transportService.disconnectFromNode(disconnectedNode);
    }
    appender = new MockLogAppender();
    try {
        appender.start();
        Loggers.addAppender(LogManager.getLogger("org.elasticsearch.cluster.NodeConnectionsService"), appender);
        for (DiscoveryNode targetNode : targetNodes) {
            if (disconnectedNodes.contains(targetNode) && newTargetNodes.get(targetNode.getId()) != null) {
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("connecting to " + targetNode, "org.elasticsearch.cluster.NodeConnectionsService", Level.DEBUG, "connecting to " + targetNode));
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("connected to " + targetNode, "org.elasticsearch.cluster.NodeConnectionsService", Level.DEBUG, "connected to " + targetNode));
            } else {
                appender.addExpectation(new MockLogAppender.UnseenEventExpectation("connecting to " + targetNode, "org.elasticsearch.cluster.NodeConnectionsService", Level.DEBUG, "connecting to " + targetNode));
                appender.addExpectation(new MockLogAppender.UnseenEventExpectation("connected to " + targetNode, "org.elasticsearch.cluster.NodeConnectionsService", Level.DEBUG, "connected to " + targetNode));
            }
            if (newTargetNodes.get(targetNode.getId()) == null) {
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("disconnected from " + targetNode, "org.elasticsearch.cluster.NodeConnectionsService", Level.DEBUG, "disconnected from " + targetNode));
            }
        }
        for (DiscoveryNode targetNode : newTargetNodes) {
            appender.addExpectation(new MockLogAppender.UnseenEventExpectation("disconnected from " + targetNode, "org.elasticsearch.cluster.NodeConnectionsService", Level.DEBUG, "disconnected from " + targetNode));
            if (targetNodes.get(targetNode.getId()) == null) {
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("connecting to " + targetNode, "org.elasticsearch.cluster.NodeConnectionsService", Level.DEBUG, "connecting to " + targetNode));
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("connected to " + targetNode, "org.elasticsearch.cluster.NodeConnectionsService", Level.DEBUG, "connected to " + targetNode));
            }
        }
        service.disconnectFromNodesExcept(newTargetNodes);
        service.connectToNodes(newTargetNodes, () -> {
        });
        deterministicTaskQueue.runAllRunnableTasks();
        appender.assertAllExpectationsMatched();
    } finally {
        Loggers.removeAppender(LogManager.getLogger("org.elasticsearch.cluster.NodeConnectionsService"), appender);
        appender.stop();
    }
}

Example 12 with MockLogAppender

use of org.elasticsearch.test.MockLogAppender in project crate by crate.

the class MasterServiceTests 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 log because it was fast enough", MasterService.class.getCanonicalName(), Level.WARN, "*took*test1*"));
    mockAppender.addExpectation(new MockLogAppender.SeenEventExpectation("test2", MasterService.class.getCanonicalName(), Level.WARN, "*took [*], which is over [10s], to compute cluster state update for [test2]"));
    mockAppender.addExpectation(new MockLogAppender.SeenEventExpectation("test3", MasterService.class.getCanonicalName(), Level.WARN, "*took [*], which is over [10s], to compute cluster state update for [test3]"));
    mockAppender.addExpectation(new MockLogAppender.SeenEventExpectation("test4", MasterService.class.getCanonicalName(), Level.WARN, "*took [*], which is over [10s], to compute cluster state update for [test4]"));
    mockAppender.addExpectation(new MockLogAppender.UnseenEventExpectation("test5 should not log despite publishing slowly", MasterService.class.getCanonicalName(), Level.WARN, "*took*test5*"));
    mockAppender.addExpectation(new MockLogAppender.SeenEventExpectation("test6 should log due to slow and failing publication", MasterService.class.getCanonicalName(), Level.WARN, "took [*] and then failed to publish updated cluster state (version: *, uuid: *) for [test6]:*"));
    Logger clusterLogger = LogManager.getLogger(MasterService.class);
    Loggers.addAppender(clusterLogger, mockAppender);
    try (MasterService masterService = new MasterService(Settings.builder().put(ClusterName.CLUSTER_NAME_SETTING.getKey(), MasterServiceTests.class.getSimpleName()).put(Node.NODE_NAME_SETTING.getKey(), "test_node").build(), new ClusterSettings(Settings.EMPTY, ClusterSettings.BUILT_IN_CLUSTER_SETTINGS), threadPool)) {
        final DiscoveryNode localNode = new DiscoveryNode("node1", buildNewFakeTransportAddress(), emptyMap(), emptySet(), Version.CURRENT);
        final ClusterState initialClusterState = ClusterState.builder(new ClusterName(MasterServiceTests.class.getSimpleName())).nodes(DiscoveryNodes.builder().add(localNode).localNodeId(localNode.getId()).masterNodeId(localNode.getId())).blocks(ClusterBlocks.EMPTY_CLUSTER_BLOCK).build();
        final AtomicReference<ClusterState> clusterStateRef = new AtomicReference<>(initialClusterState);
        masterService.setClusterStatePublisher((event, publishListener, ackListener) -> {
            if (event.source().contains("test5")) {
                relativeTimeInMillis += MasterService.MASTER_SERVICE_SLOW_TASK_LOGGING_THRESHOLD_SETTING.get(Settings.EMPTY).millis() + randomLongBetween(1, 1000000);
            }
            if (event.source().contains("test6")) {
                relativeTimeInMillis += MasterService.MASTER_SERVICE_SLOW_TASK_LOGGING_THRESHOLD_SETTING.get(Settings.EMPTY).millis() + randomLongBetween(1, 1000000);
                throw new ElasticsearchException("simulated error during slow publication which should trigger logging");
            }
            clusterStateRef.set(event.state());
            publishListener.onResponse(null);
        });
        masterService.setClusterStateSupplier(clusterStateRef::get);
        masterService.start();
        final CountDownLatch latch = new CountDownLatch(6);
        final CountDownLatch processedFirstTask = new CountDownLatch(1);
        masterService.submitStateUpdateTask("test1", new ClusterStateUpdateTask() {

            @Override
            public ClusterState execute(ClusterState currentState) {
                relativeTimeInMillis += randomLongBetween(0L, MasterService.MASTER_SERVICE_SLOW_TASK_LOGGING_THRESHOLD_SETTING.get(Settings.EMPTY).millis());
                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();
        masterService.submitStateUpdateTask("test2", new ClusterStateUpdateTask() {

            @Override
            public ClusterState execute(ClusterState currentState) {
                relativeTimeInMillis += MasterService.MASTER_SERVICE_SLOW_TASK_LOGGING_THRESHOLD_SETTING.get(Settings.EMPTY).millis() + randomLongBetween(1, 1000000);
                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();
            }
        });
        masterService.submitStateUpdateTask("test3", new ClusterStateUpdateTask() {

            @Override
            public ClusterState execute(ClusterState currentState) {
                relativeTimeInMillis += MasterService.MASTER_SERVICE_SLOW_TASK_LOGGING_THRESHOLD_SETTING.get(Settings.EMPTY).millis() + randomLongBetween(1, 1000000);
                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();
            }
        });
        masterService.submitStateUpdateTask("test4", new ClusterStateUpdateTask() {

            @Override
            public ClusterState execute(ClusterState currentState) {
                relativeTimeInMillis += MasterService.MASTER_SERVICE_SLOW_TASK_LOGGING_THRESHOLD_SETTING.get(Settings.EMPTY).millis() + randomLongBetween(1, 1000000);
                return currentState;
            }

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

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

            @Override
            public ClusterState execute(ClusterState currentState) {
                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();
            }
        });
        masterService.submitStateUpdateTask("test6", new ClusterStateUpdateTask() {

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

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

            @Override
            public void onFailure(String source, Exception e) {
                // maybe we should notify here?
                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
        masterService.submitStateUpdateTask("test7", 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 13 with MockLogAppender

use of org.elasticsearch.test.MockLogAppender in project crate by crate.

the class SettingsFilterTests method assertExpectedLogMessages.

private void assertExpectedLogMessages(Consumer<Logger> consumer, MockLogAppender.LoggingExpectation... expectations) throws IllegalAccessException {
    Logger testLogger = LogManager.getLogger("org.elasticsearch.test");
    MockLogAppender appender = new MockLogAppender();
    Loggers.addAppender(testLogger, appender);
    try {
        appender.start();
        Arrays.stream(expectations).forEach(appender::addExpectation);
        consumer.accept(testLogger);
        appender.assertAllExpectationsMatched();
    } finally {
        Loggers.removeAppender(testLogger, appender);
    }
}

Example 14 with MockLogAppender

use of org.elasticsearch.test.MockLogAppender in project crate by crate.

the class TcpTransportTests method testExceptionHandling.

private void testExceptionHandling(boolean startTransport, Exception exception, boolean expectClosed, MockLogAppender.LoggingExpectation... expectations) throws IllegalAccessException {
    final TestThreadPool testThreadPool = new TestThreadPool("test");
    MockLogAppender appender = new MockLogAppender();
    try {
        appender.start();
        Loggers.addAppender(LogManager.getLogger(TcpTransport.class), appender);
        for (MockLogAppender.LoggingExpectation expectation : expectations) {
            appender.addExpectation(expectation);
        }
        final Lifecycle lifecycle = new Lifecycle();
        if (startTransport) {
            lifecycle.moveToStarted();
        }
        final FakeTcpChannel channel = new FakeTcpChannel();
        final PlainActionFuture<Void> listener = new PlainActionFuture<>();
        channel.addCloseListener(listener);
        var logger = Loggers.getLogger(TcpTransport.class);
        TcpTransport.handleException(logger, channel, exception, lifecycle, new OutboundHandler(randomAlphaOfLength(10), Version.CURRENT, new StatsTracker(), testThreadPool, BigArrays.NON_RECYCLING_INSTANCE));
        if (expectClosed) {
            assertTrue(listener.isDone());
            assertThat(listener.actionGet(), nullValue());
        } else {
            assertFalse(listener.isDone());
        }
        appender.assertAllExpectationsMatched();
    } finally {
        Loggers.removeAppender(LogManager.getLogger(TcpTransport.class), appender);
        appender.stop();
        ThreadPool.terminate(testThreadPool, 30, TimeUnit.SECONDS);
    }
}