IGNITE-26330 Add logs for local snapshot creation steps (#12456)

Author: VolkodamovDaniil

modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/snapshot/IgniteSnapshotManager.java

@@ -779,6 +779,9 @@ private IgniteInternalFuture<SnapshotOperationResponse> initLocalSnapshotStartSt
         if (!CU.baselineNode(cctx.localNode(), cctx.kernalContext().state().clusterState()))
             return new GridFinishedFuture<>();
 
+        if (log.isInfoEnabled())
+            log.info("Starting local snapshot operation [req=" + req + ']');
+
         Set<UUID> leftNodes = new HashSet<>(req.nodes());
         leftNodes.removeAll(F.viewReadOnly(cctx.discovery().serverNodes(AffinityTopologyVersion.NONE), node2id()));
 
@@ -1279,8 +1282,14 @@ else if (!F.isEmpty(req.warnings())) {
                         enableIncrementalSnapshotsCreation(grpIds);
                     }
                 }
+
+                if (log.isInfoEnabled())
+                    log.info("Finishing local snapshot operation [req=" + req + ']');
             }
             catch (Exception e) {
+                log.error("Finishing local snapshot operation failed " +
+                    "[req=" + req + ", err=" + e + ']');
+
                 throw F.wrap(e);
             }
 

modules/core/src/test/java/org/apache/ignite/internal/processors/cache/persistence/snapshot/IgniteClusterSnapshotSelfTest.java

@@ -84,6 +84,8 @@
 import org.apache.ignite.metric.MetricRegistry;
 import org.apache.ignite.spi.metric.LongMetric;
 import org.apache.ignite.testframework.GridTestUtils;
+import org.apache.ignite.testframework.ListeningTestLogger;
+import org.apache.ignite.testframework.LogListener;
 import org.apache.ignite.transactions.Transaction;
 import org.jetbrains.annotations.Nullable;
 import org.junit.Before;
@@ -1311,6 +1313,116 @@ public void testClientHandlesSnapshotFailOnStartStage() throws Exception {
         assertSnapshotCacheKeys(cln.cache(dfltCacheCfg.getName()));
     }
 
+    /**
+     * Test snapshot operation logging for incremental snapshots.
+     */
+    @Test
+    public void testIncrementalSnapshotOperationLogging() throws Exception {
+        assumeFalse("https://issues.apache.org/jira/browse/IGNITE-17819", encryption);
+
+        int gridsCnt = 2;
+        ListeningTestLogger[] listeningLogs = new ListeningTestLogger[gridsCnt];
+        IgniteEx ignite = null;
+
+        for (int i = 0; i < gridsCnt; ++i) {
+            listeningLogs[i] = new ListeningTestLogger(log);
+
+            IgniteConfiguration cfg = getConfiguration(getTestIgniteInstanceName(i))
+                .setGridLogger(listeningLogs[i]);
+
+            if (ignite == null)
+                ignite = startGrid(cfg);
+            else
+                startGrid(cfg);
+        }
+        ignite.cluster().state(ACTIVE);
+
+        LogListener[] fullStartListeners = new LogListener[gridsCnt];
+        LogListener[] fullEndListeners = new LogListener[gridsCnt];
+
+        for (int i = 0; i < gridsCnt; ++i) {
+            fullStartListeners[i] = LogListener.matches("Starting local snapshot operation")
+                .andMatches("incremental=false")
+                .build();
+
+            fullEndListeners[i] = LogListener.matches("Finishing local snapshot operation")
+                .andMatches("err=null")
+                .andMatches("incremental=false")
+                .build();
+
+            listeningLogs[i].registerListener(fullStartListeners[i]);
+            listeningLogs[i].registerListener(fullEndListeners[i]);
+        }
+
+        ignite.snapshot().createSnapshot(SNAPSHOT_NAME).get(getTestTimeout());
+
+        for (int i = 0; i < gridsCnt; i++) {
+            assertTrue("Full snapshot start log not found on node " + i,
+                fullStartListeners[i].check());
+            assertTrue("Full snapshot end log not found on node " + i,
+                fullEndListeners[i].check());
+        }
+
+        LogListener[] incStartListeners = new LogListener[gridsCnt];
+        LogListener[] incEndListeners = new LogListener[gridsCnt];
+
+        for (int i = 0; i < gridsCnt; i++) {
+            incStartListeners[i] = LogListener.matches("Starting local snapshot operation")
+                .andMatches("incremental=true")
+                .andMatches("incIdx=1")
+                .build();
+
+            incEndListeners[i] = LogListener.matches("Finishing local snapshot operation")
+                .andMatches("err=null")
+                .andMatches("incremental=true")
+                .andMatches("incIdx=1")
+                .build();
+
+            listeningLogs[i].registerListener(incStartListeners[i]);
+            listeningLogs[i].registerListener(incEndListeners[i]);
+        }
+
+        ignite.snapshot().createIncrementalSnapshot(SNAPSHOT_NAME).get(getTestTimeout());
+
+        for (int i = 0; i < gridsCnt; i++) {
+            assertTrue("Incremental snapshot start log not found on node " + i,
+                incStartListeners[i].check());
+            assertTrue("Incremental snapshot end log not found on node " + i,
+                incEndListeners[i].check());
+        }
+
+        LogListener[] failureListeners = new LogListener[gridsCnt];
+
+        for (int i = 0; i < gridsCnt; i++) {
+            failureListeners[i] = LogListener.matches("Finishing local snapshot operation")
+                .andMatches("Snapshot process failure for testing")
+                .build();
+
+            listeningLogs[i].registerListener(failureListeners[i]);
+        }
+
+        snp(ignite).localSnapshotSenderFactory(sft -> {
+            throw new IgniteException("Snapshot process failure for testing");
+        });
+
+        try {
+            IgniteFuture<Void> fut = ignite.snapshot().createSnapshot("testSnp2");
+
+            fut.get();
+            fail("Should have failed");
+        }
+        catch (Exception e) {
+            // No-op.
+        }
+
+        stopAllGrids();
+
+        for (int i = 0; i < gridsCnt; i++) {
+            assertTrue("Failure snapshot log not found on node " + i,
+                failureListeners[i].check());
+        }
+    }
+
     /**
      * @param ignite Ignite instance.
      * @param started Latch will be released when delta partition processing starts.

modules/core/src/test/java/org/apache/ignite/internal/processors/cache/persistence/snapshot/IgniteSnapshotManagerSelfTest.java

@@ -617,10 +617,10 @@ public void testFullSnapshotCreationLog() throws Exception {
         LogListener matchFinish = LogListener.matches("Cluster-wide snapshot operation finished successfully: ").times(entriesCnt).build();
         listenLog.registerListener(matchFinish);
 
-        LogListener matchFullParams = LogListener.matches("incremental=false, incIdx=-1").times(2).build();
+        LogListener matchFullParams = LogListener.matches("incremental=false, incIdx=-1").times(4).build();
         listenLog.registerListener(matchFullParams);
 
-        LogListener matchIncParams = LogListener.matches("incremental=true").times(2 * (entriesCnt - 1)).build();
+        LogListener matchIncParams = LogListener.matches("incremental=true").times(4 * (entriesCnt - 1)).build();
         listenLog.registerListener(matchIncParams);
 
         LogListener noMatchParams = LogListener.matches("incremental=true, incIdx=-1").build();