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

Example 1 with TestLogging

use of org.opensearch.test.junit.annotations.TestLogging in project OpenSearch by opensearch-project.

the class DiskThresholdMonitorTests method testDiskMonitorLogging.

@TestLogging(value = "org.opensearch.cluster.routing.allocation.DiskThresholdMonitor:INFO", reason = "testing INFO/WARN logging")
public void testDiskMonitorLogging() throws IllegalAccessException {
    final ClusterState clusterState = ClusterState.builder(ClusterName.CLUSTER_NAME_SETTING.getDefault(Settings.EMPTY)).nodes(DiscoveryNodes.builder().add(newNode("node1"))).build();
    final AtomicReference<ClusterState> clusterStateRef = new AtomicReference<>(clusterState);
    final AtomicBoolean advanceTime = new AtomicBoolean(randomBoolean());
    final LongSupplier timeSupplier = new LongSupplier() {

        long time;

        @Override
        public long getAsLong() {
            if (advanceTime.get()) {
                time += DiskThresholdSettings.CLUSTER_ROUTING_ALLOCATION_REROUTE_INTERVAL_SETTING.get(Settings.EMPTY).getMillis() + 1;
            }
            logger.info("time: [{}]", time);
            return time;
        }
    };
    final AtomicLong relocatingShardSizeRef = new AtomicLong();
    DiskThresholdMonitor monitor = new DiskThresholdMonitor(Settings.EMPTY, clusterStateRef::get, new ClusterSettings(Settings.EMPTY, ClusterSettings.BUILT_IN_CLUSTER_SETTINGS), null, timeSupplier, (reason, priority, listener) -> listener.onResponse(clusterStateRef.get())) {

        @Override
        protected void updateIndicesReadOnly(Set<String> indicesToMarkReadOnly, ActionListener<Void> listener, boolean readOnly) {
            listener.onResponse(null);
        }

        @Override
        long sizeOfRelocatingShards(RoutingNode routingNode, DiskUsage diskUsage, ClusterInfo info, ClusterState reroutedClusterState) {
            return relocatingShardSizeRef.get();
        }
    };
    final ImmutableOpenMap.Builder<String, DiskUsage> allDisksOkBuilder;
    allDisksOkBuilder = ImmutableOpenMap.builder();
    allDisksOkBuilder.put("node1", new DiskUsage("node1", "node1", "/foo/bar", 100, between(15, 100)));
    final ImmutableOpenMap<String, DiskUsage> allDisksOk = allDisksOkBuilder.build();
    final ImmutableOpenMap.Builder<String, DiskUsage> aboveLowWatermarkBuilder = ImmutableOpenMap.builder();
    aboveLowWatermarkBuilder.put("node1", new DiskUsage("node1", "node1", "/foo/bar", 100, between(10, 14)));
    final ImmutableOpenMap<String, DiskUsage> aboveLowWatermark = aboveLowWatermarkBuilder.build();
    final ImmutableOpenMap.Builder<String, DiskUsage> aboveHighWatermarkBuilder = ImmutableOpenMap.builder();
    aboveHighWatermarkBuilder.put("node1", new DiskUsage("node1", "node1", "/foo/bar", 100, between(5, 9)));
    final ImmutableOpenMap<String, DiskUsage> aboveHighWatermark = aboveHighWatermarkBuilder.build();
    final ImmutableOpenMap.Builder<String, DiskUsage> aboveFloodStageWatermarkBuilder = ImmutableOpenMap.builder();
    aboveFloodStageWatermarkBuilder.put("node1", new DiskUsage("node1", "node1", "/foo/bar", 100, between(0, 4)));
    final ImmutableOpenMap<String, DiskUsage> aboveFloodStageWatermark = aboveFloodStageWatermarkBuilder.build();
    assertNoLogging(monitor, allDisksOk);
    assertSingleInfoMessage(monitor, aboveLowWatermark, "low disk watermark [85%] exceeded on * replicas will not be assigned to this node");
    // will do one reroute and emit warnings, but subsequent reroutes and associated messages are delayed
    advanceTime.set(false);
    assertSingleWarningMessage(monitor, aboveHighWatermark, "high disk watermark [90%] exceeded on * shards will be relocated away from this node* " + "the node is expected to continue to exceed the high disk watermark when these relocations are complete");
    advanceTime.set(true);
    assertRepeatedWarningMessages(monitor, aboveHighWatermark, "high disk watermark [90%] exceeded on * shards will be relocated away from this node* " + "the node is expected to continue to exceed the high disk watermark when these relocations are complete");
    advanceTime.set(randomBoolean());
    assertRepeatedWarningMessages(monitor, aboveFloodStageWatermark, "flood stage disk watermark [95%] exceeded on * all indices on this node will be marked read-only");
    relocatingShardSizeRef.set(-5L);
    advanceTime.set(true);
    assertSingleInfoMessage(monitor, aboveHighWatermark, "high disk watermark [90%] exceeded on * shards will be relocated away from this node* " + "the node is expected to be below the high disk watermark when these relocations are complete");
    relocatingShardSizeRef.set(0L);
    // advance time long enough to do another reroute
    timeSupplier.getAsLong();
    // will do one reroute and emit warnings, but subsequent reroutes and associated messages are delayed
    advanceTime.set(false);
    assertSingleWarningMessage(monitor, aboveHighWatermark, "high disk watermark [90%] exceeded on * shards will be relocated away from this node* " + "the node is expected to continue to exceed the high disk watermark when these relocations are complete");
    advanceTime.set(true);
    assertRepeatedWarningMessages(monitor, aboveHighWatermark, "high disk watermark [90%] exceeded on * shards will be relocated away from this node* " + "the node is expected to continue to exceed the high disk watermark when these relocations are complete");
    advanceTime.set(randomBoolean());
    assertSingleInfoMessage(monitor, aboveLowWatermark, "high disk watermark [90%] no longer exceeded on * but low disk watermark [85%] is still exceeded");
    // only log about dropping below the low disk watermark on a reroute
    advanceTime.set(true);
    assertSingleInfoMessage(monitor, allDisksOk, "low disk watermark [85%] no longer exceeded on *");
    advanceTime.set(randomBoolean());
    assertRepeatedWarningMessages(monitor, aboveFloodStageWatermark, "flood stage disk watermark [95%] exceeded on * all indices on this node will be marked read-only");
    assertSingleInfoMessage(monitor, allDisksOk, "low disk watermark [85%] no longer exceeded on *");
    advanceTime.set(true);
    assertRepeatedWarningMessages(monitor, aboveHighWatermark, "high disk watermark [90%] exceeded on * shards will be relocated away from this node* " + "the node is expected to continue to exceed the high disk watermark when these relocations are complete");
    assertSingleInfoMessage(monitor, allDisksOk, "low disk watermark [85%] no longer exceeded on *");
    assertRepeatedWarningMessages(monitor, aboveFloodStageWatermark, "flood stage disk watermark [95%] exceeded on * all indices on this node will be marked read-only");
    assertSingleInfoMessage(monitor, aboveLowWatermark, "high disk watermark [90%] no longer exceeded on * but low disk watermark [85%] is still exceeded");
}

Example 2 with TestLogging

use of org.opensearch.test.junit.annotations.TestLogging in project OpenSearch by opensearch-project.

the class HandshakingTransportAddressConnectorTests method testLogsFullConnectionFailureAfterSuccessfulHandshake.

@TestLogging(reason = "ensure logging happens", value = "org.opensearch.discovery.HandshakingTransportAddressConnector:INFO")
public void testLogsFullConnectionFailureAfterSuccessfulHandshake() throws Exception {
    remoteNode = new DiscoveryNode("remote-node", buildNewFakeTransportAddress(), Version.CURRENT);
    remoteClusterName = "local-cluster";
    discoveryAddress = buildNewFakeTransportAddress();
    fullConnectionFailure = new ConnectTransportException(remoteNode, "simulated", new OpenSearchException("root cause"));
    FailureListener failureListener = new FailureListener();
    Logger targetLogger = LogManager.getLogger(HandshakingTransportAddressConnector.class);
    try (MockLogAppender mockAppender = MockLogAppender.createForLoggers(targetLogger)) {
        mockAppender.addExpectation(new MockLogAppender.SeenEventExpectation("message", HandshakingTransportAddressConnector.class.getCanonicalName(), Level.WARN, "*completed handshake with [*] but followup connection failed*"));
        handshakingTransportAddressConnector.connectToRemoteMasterNode(discoveryAddress, failureListener);
        failureListener.assertFailure();
        mockAppender.assertAllExpectationsMatched();
    }
}

Example 3 with TestLogging

use of org.opensearch.test.junit.annotations.TestLogging in project OpenSearch by opensearch-project.

the class NodeConnectionsServiceTests method testDebugLogging.

@TestLogging(reason = "testing that DEBUG-level logging is reasonable", value = "org.opensearch.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);
    }
    final Logger logger = LogManager.getLogger("org.opensearch.cluster.NodeConnectionsService");
    try (MockLogAppender appender = MockLogAppender.createForLoggers(logger)) {
        for (DiscoveryNode targetNode : targetNodes) {
            if (disconnectedNodes.contains(targetNode)) {
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("connecting to " + targetNode, "org.opensearch.cluster.NodeConnectionsService", Level.DEBUG, "connecting to " + targetNode));
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("connected to " + targetNode, "org.opensearch.cluster.NodeConnectionsService", Level.DEBUG, "connected to " + targetNode));
            } else {
                appender.addExpectation(new MockLogAppender.UnseenEventExpectation("connecting to " + targetNode, "org.opensearch.cluster.NodeConnectionsService", Level.DEBUG, "connecting to " + targetNode));
                appender.addExpectation(new MockLogAppender.UnseenEventExpectation("connected to " + targetNode, "org.opensearch.cluster.NodeConnectionsService", Level.DEBUG, "connected to " + targetNode));
            }
        }
        runTasksUntil(deterministicTaskQueue, CLUSTER_NODE_RECONNECT_INTERVAL_SETTING.get(Settings.EMPTY).millis());
        appender.assertAllExpectationsMatched();
    }
    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);
    }
    try (MockLogAppender appender = MockLogAppender.createForLoggers(logger)) {
        for (DiscoveryNode targetNode : targetNodes) {
            if (disconnectedNodes.contains(targetNode) && newTargetNodes.get(targetNode.getId()) != null) {
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("connecting to " + targetNode, "org.opensearch.cluster.NodeConnectionsService", Level.DEBUG, "connecting to " + targetNode));
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("connected to " + targetNode, "org.opensearch.cluster.NodeConnectionsService", Level.DEBUG, "connected to " + targetNode));
            } else {
                appender.addExpectation(new MockLogAppender.UnseenEventExpectation("connecting to " + targetNode, "org.opensearch.cluster.NodeConnectionsService", Level.DEBUG, "connecting to " + targetNode));
                appender.addExpectation(new MockLogAppender.UnseenEventExpectation("connected to " + targetNode, "org.opensearch.cluster.NodeConnectionsService", Level.DEBUG, "connected to " + targetNode));
            }
            if (newTargetNodes.get(targetNode.getId()) == null) {
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("disconnected from " + targetNode, "org.opensearch.cluster.NodeConnectionsService", Level.DEBUG, "disconnected from " + targetNode));
            }
        }
        for (DiscoveryNode targetNode : newTargetNodes) {
            appender.addExpectation(new MockLogAppender.UnseenEventExpectation("disconnected from " + targetNode, "org.opensearch.cluster.NodeConnectionsService", Level.DEBUG, "disconnected from " + targetNode));
            if (targetNodes.get(targetNode.getId()) == null) {
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("connecting to " + targetNode, "org.opensearch.cluster.NodeConnectionsService", Level.DEBUG, "connecting to " + targetNode));
                appender.addExpectation(new MockLogAppender.SeenEventExpectation("connected to " + targetNode, "org.opensearch.cluster.NodeConnectionsService", Level.DEBUG, "connected to " + targetNode));
            }
        }
        service.disconnectFromNodesExcept(newTargetNodes);
        service.connectToNodes(newTargetNodes, () -> {
        });
        deterministicTaskQueue.runAllRunnableTasks();
        appender.assertAllExpectationsMatched();
    }
}

Example 4 with TestLogging

use of org.opensearch.test.junit.annotations.TestLogging in project OpenSearch by opensearch-project.

the class SettingTests method testLogSettingUpdate.

@TestLogging(value = "org.opensearch.common.settings.IndexScopedSettings:INFO", reason = "to ensure we log INFO-level messages from IndexScopedSettings")
public void testLogSettingUpdate() throws Exception {
    final IndexMetadata metadata = newIndexMeta("index1", Settings.builder().put(IndexSettings.INDEX_REFRESH_INTERVAL_SETTING.getKey(), "20s").build());
    final IndexSettings settings = new IndexSettings(metadata, Settings.EMPTY);
    final Logger logger = LogManager.getLogger(IndexScopedSettings.class);
    try (MockLogAppender mockLogAppender = MockLogAppender.createForLoggers(logger)) {
        mockLogAppender.addExpectation(new MockLogAppender.SeenEventExpectation("message", "org.opensearch.common.settings.IndexScopedSettings", Level.INFO, "updating [index.refresh_interval] from [20s] to [10s]") {

            @Override
            public boolean innerMatch(LogEvent event) {
                return event.getMarker().getName().equals(" [index1]");
            }
        });
        settings.updateIndexMetadata(newIndexMeta("index1", Settings.builder().put(IndexSettings.INDEX_REFRESH_INTERVAL_SETTING.getKey(), "10s").build()));
        mockLogAppender.assertAllExpectationsMatched();
    }
}

Example 5 with TestLogging

use of org.opensearch.test.junit.annotations.TestLogging in project OpenSearch by opensearch-project.

the class FsHealthServiceTests method testLoggingOnHungIO.

@TestLogging(value = "org.opensearch.monitor.fs:WARN", reason = "to ensure that we log on hung IO at WARN level")
public void testLoggingOnHungIO() throws Exception {
    long slowLogThreshold = randomLongBetween(100, 200);
    final Settings settings = Settings.builder().put(FsHealthService.SLOW_PATH_LOGGING_THRESHOLD_SETTING.getKey(), slowLogThreshold + "ms").build();
    FileSystem fileSystem = PathUtils.getDefaultFileSystem();
    TestThreadPool testThreadPool = new TestThreadPool(getClass().getName(), settings);
    FileSystemFsyncHungProvider disruptFileSystemProvider = new FileSystemFsyncHungProvider(fileSystem, randomLongBetween(slowLogThreshold + 1, 400), testThreadPool);
    fileSystem = disruptFileSystemProvider.getFileSystem(null);
    PathUtilsForTesting.installMock(fileSystem);
    final ClusterSettings clusterSettings = new ClusterSettings(Settings.EMPTY, ClusterSettings.BUILT_IN_CLUSTER_SETTINGS);
    try (MockLogAppender mockAppender = MockLogAppender.createForLoggers(LogManager.getLogger(FsHealthService.class));
        NodeEnvironment env = newNodeEnvironment()) {
        FsHealthService fsHealthService = new FsHealthService(settings, clusterSettings, testThreadPool, env);
        int counter = 0;
        for (Path path : env.nodeDataPaths()) {
            mockAppender.addExpectation(new MockLogAppender.SeenEventExpectation("test" + ++counter, FsHealthService.class.getCanonicalName(), Level.WARN, "health check of [" + path + "] took [*ms] which is above the warn threshold*"));
        }
        // disrupt file system
        disruptFileSystemProvider.injectIODelay.set(true);
        fsHealthService.new FsHealthMonitor().run();
        assertEquals(env.nodeDataPaths().length, disruptFileSystemProvider.getInjectedPathCount());
        assertBusy(mockAppender::assertAllExpectationsMatched);
    } finally {
        PathUtilsForTesting.teardown();
        ThreadPool.terminate(testThreadPool, 500, TimeUnit.MILLISECONDS);
    }
}