From 298dec13e213826f0594f9543b9fb54e95c7ccd5 Mon Sep 17 00:00:00 2001 From: Rishabh Kumar Date: Fri, 24 Jan 2025 20:01:31 +0530 Subject: [PATCH] OAK-11401 : increased audit log level for VGC (#2024) Co-authored-by: Rishabh Kumar --- .../document/VersionGarbageCollector.java | 56 +++++++++---------- 1 file changed, 25 insertions(+), 31 deletions(-) diff --git a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java index 4182ea32d58..ad89f442ab8 100644 --- a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java +++ b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java @@ -1269,8 +1269,8 @@ private void combineInternalPropRemovals(final NodeDocument doc, final UpdateOp // update the deleted properties count Map to calculate the total no. of deleted properties int totalDeletedSystemPropsCount = deletedInternalPropsCountMap.merge(doc.getId(), deletedSystemPropsCount, Integer::sum); - if (AUDIT_LOG.isDebugEnabled() && totalDeletedSystemPropsCount > 0) { - AUDIT_LOG.debug(" [{}] internal prop revs in [{}] mode [{}]", totalDeletedSystemPropsCount, doc.getId(), fullGcMode); + if (AUDIT_LOG.isInfoEnabled() && totalDeletedSystemPropsCount > 0) { + AUDIT_LOG.info(" [{}] internal prop revs in [{}] mode [{}]", totalDeletedSystemPropsCount, doc.getId(), fullGcMode); } } } @@ -1348,9 +1348,7 @@ private boolean isDeletedOrOrphanedNode(final NodeState traversedState, final Pa orphanOrDeletedRemovalPathMap.put(doc.getId(), doc.getPath()); fullGCStats.candidateDocuments(GCPhase.FULL_GC_COLLECT_ORPHAN_NODES, 1); - if (AUDIT_LOG.isDebugEnabled()) { - AUDIT_LOG.debug(" [{}] orphaned node", doc.getId()); - } + AUDIT_LOG.info(" [{}] orphaned node in mode [{}]", doc.getId(), fullGcMode); phases.stop(GCPhase.FULL_GC_COLLECT_ORPHAN_NODES); return true; @@ -1388,8 +1386,8 @@ private void collectDeletedProperties(final NodeDocument doc, final GCPhases pha deletedPropsCountMap.put(doc.getId(), deletedPropsCount); fullGCStats.candidateProperties(GCPhase.FULL_GC_COLLECT_PROPS, deletedPropsCount); - if (AUDIT_LOG.isDebugEnabled() && deletedPropsCount > 0) { - AUDIT_LOG.debug(" [{}] deleted props in [{}]", deletedPropsCount, doc.getId()); + if (AUDIT_LOG.isInfoEnabled() && deletedPropsCount > 0) { + AUDIT_LOG.info(" [{}] deleted props in [{}]. Property Names [{}]", deletedPropsCount, doc.getId(), updateOp.getChanges().keySet()); } phases.stop(GCPhase.FULL_GC_COLLECT_PROPS); } @@ -1427,8 +1425,8 @@ private void collectUnmergedBranchCommits(final NodeDocument doc, final GCPhases olderUnmergedBranchCommits.forEach(bcRevision -> removeUnmergedBCRevision(bcRevision, doc, updateOp)); deletedUnmergedBCSet.addAll(olderUnmergedBranchCommits); - if (AUDIT_LOG.isDebugEnabled()) { - AUDIT_LOG.debug(" [{}] unmerged branch commits in [{}]", olderUnmergedBranchCommits.size(), doc.getId()); + if (AUDIT_LOG.isInfoEnabled()) { + AUDIT_LOG.info(" [{}] unmerged branch commits in [{}]", olderUnmergedBranchCommits.size(), doc.getId()); } // now for any of the handled system properties (the normal properties would @@ -1459,8 +1457,8 @@ private void collectUnmergedBranchCommits(final NodeDocument doc, final GCPhases int totalDeletedSystemPropsCount = deletedInternalPropsCountMap.merge(doc.getId(), deletedSystemPropsCount, Integer::sum); fullGCStats.candidateInternalRevisions(GCPhase.FULL_GC_COLLECT_UNMERGED_BC, totalDeletedSystemPropsCount); - if (AUDIT_LOG.isDebugEnabled() && totalDeletedSystemPropsCount > 0) { - AUDIT_LOG.debug(" [{}] internal prop revs in [{}] mode [{}]", totalDeletedSystemPropsCount, doc.getId(), fullGcMode); + if (AUDIT_LOG.isInfoEnabled() && totalDeletedSystemPropsCount > 0) { + AUDIT_LOG.info(" [{}] internal prop revs in [{}] mode [{}]", totalDeletedSystemPropsCount, doc.getId(), fullGcMode); } } phases.stop(GCPhase.FULL_GC_COLLECT_UNMERGED_BC); @@ -1619,8 +1617,8 @@ private void removeUnmergedBCRevision(final Revision unmergedBCRevision, final N fullGCStats.candidateRevisions(GCPhase.FULL_GC_COLLECT_UNMERGED_BC, revEntriesCount); fullGCStats.candidateInternalRevisions(GCPhase.FULL_GC_COLLECT_UNMERGED_BC, internalRevEntriesCount); - if (AUDIT_LOG.isDebugEnabled() && (revEntriesCount > 0 || internalRevEntriesCount > 0)) { - AUDIT_LOG.debug(" [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", revEntriesCount, internalRevEntriesCount, doc.getId(), fullGcMode); + if (AUDIT_LOG.isInfoEnabled() && (revEntriesCount > 0 || internalRevEntriesCount > 0)) { + AUDIT_LOG.info(" [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", revEntriesCount, internalRevEntriesCount, doc.getId(), fullGcMode); } } @@ -1640,8 +1638,8 @@ private void collectRevisionsOlderThan24hAndBetweenCheckpoints(final NodeDocumen if (intRevsDiff > 0) { deletedInternalPropRevsCountMap.merge(doc.getId(), intRevsDiff, Integer::sum); } - if (AUDIT_LOG.isDebugEnabled() && (revsDiff > 0 || intRevsDiff > 0)) { - AUDIT_LOG.debug(" [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", revsDiff, intRevsDiff, doc.getId(), fullGcMode); + if (AUDIT_LOG.isInfoEnabled() && (revsDiff > 0 || intRevsDiff > 0)) { + AUDIT_LOG.info(" [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", revsDiff, intRevsDiff, doc.getId(), fullGcMode); } fullGCStats.candidateRevisions(GCPhase.FULL_GC_COLLECT_OLD_REVS, revsDiff); fullGCStats.candidateInternalRevisions(GCPhase.FULL_GC_COLLECT_OLD_REVS, intRevsDiff); @@ -1690,8 +1688,8 @@ private void collectUnusedPropertyRevisions(final NodeDocument doc, deletedInternalPropRevsCountMap.merge(doc.getId(), deletedInternalRevsCount, Integer::sum); } - if (AUDIT_LOG.isDebugEnabled() && deletedTotalRevsCount > 0) { - AUDIT_LOG.debug(" [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", deletedUserRevsCount, deletedInternalRevsCount, doc.getId(), fullGcMode); + if (AUDIT_LOG.isInfoEnabled() && deletedTotalRevsCount > 0) { + AUDIT_LOG.info(" [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", deletedUserRevsCount, deletedInternalRevsCount, doc.getId(), fullGcMode); } fullGCStats.candidateRevisions(GCPhase.FULL_GC_COLLECT_OLD_REVS, deletedUserRevsCount); fullGCStats.candidateInternalRevisions(GCPhase.FULL_GC_COLLECT_OLD_REVS, deletedInternalRevsCount); @@ -1924,18 +1922,18 @@ public void close() { public void removeGarbage(final VersionGCStats stats) { if (updateOpList.isEmpty() && orphanOrDeletedRemovalMap.isEmpty()) { - if (log.isDebugEnabled() || isFullGCDryRun) { - log.debug("Skipping removal of Full garbage, cause no garbage detected"); + if (log.isInfoEnabled() || isFullGCDryRun) { + log.info("Skipping removal of Full garbage, cause no garbage detected"); } return; } monitor.info("Proceeding to update [{}] documents", updateOpList.size()); - if (AUDIT_LOG.isDebugEnabled() || isFullGCDryRun) { + if (AUDIT_LOG.isInfoEnabled() || isFullGCDryRun) { String updateIds = updateOpList.stream().map(UpdateOp::getId).collect(joining(", ")); String orphanIds = join(", ", orphanOrDeletedRemovalMap.keySet()); - log.debug("Performing batch update of ids [{}] and removal of orphan ids [{}]", updateIds, orphanIds); + AUDIT_LOG.info("Performing batch update of ids [{}] and removal of orphan ids [{}]", updateIds, orphanIds); } if (cancel.get()) { @@ -1969,9 +1967,7 @@ public void removeGarbage(final VersionGCStats stats) { if (!verifyViaTraversedState(traversedState, traversedParent, newDoc)) { // verification failure // let's skip this document - if (log.isDebugEnabled()) { - log.debug("removeGarbage.verify : verifyViaTraversedState failed for [{}]", newDoc.getId()); - } + log.warn("removeGarbage.verify : verifyViaTraversedState failed for [{}]", newDoc.getId()); it.remove(); stats.skippedFullGCDocsCount++; } @@ -1993,9 +1989,7 @@ public void removeGarbage(final VersionGCStats stats) { if (!verifyDeletion(traversedState)) { // verification failure // let's skip this document - if (log.isDebugEnabled()) { - log.debug("removeGarbage.verify : verifyDeletion failed for [{}]", e.getKey()); - } + log.warn("removeGarbage.verify : verifyDeletion failed for [{}]", e.getKey()); it.remove(); stats.skippedFullGCDocsCount++; } @@ -2016,8 +2010,8 @@ public void removeGarbage(final VersionGCStats stats) { stats.deletedDocGCCount += removedSize; stats.deletedOrphanNodesCount += removedSize; - if (AUDIT_LOG.isDebugEnabled()) { - AUDIT_LOG.debug(" [{}] documents (from intended {})", removedSize, orphanOrDeletedRemovalMap.size()); + if (AUDIT_LOG.isInfoEnabled()) { + AUDIT_LOG.info(" [{}] documents (from intended {})", removedSize, orphanOrDeletedRemovalMap.size()); } // save stats @@ -2044,8 +2038,8 @@ public void removeGarbage(final VersionGCStats stats) { stats.deletedInternalPropRevsCount += deletedInternalRevEntriesCount; stats.deletedUnmergedBCCount += deletedUnmergedBCSet.size(); - if (log.isDebugEnabled()) { - log.debug("Updated [{}] docs, deleted [{}] props, deleted [{}] unmergedBCs, deleted [{}] internal Props, deleted [{}] prop revs, deleted [{}] internal prop revs", + if (log.isInfoEnabled()) { + log.info("Updated [{}] docs, deleted [{}] props, deleted [{}] unmergedBCs, deleted [{}] internal Props, deleted [{}] prop revs, deleted [{}] internal prop revs", updatedDocs, deletedProps, deletedUnmergedBCSet.size(), deletedInternalProps, deletedRevEntriesCount, deletedInternalRevEntriesCount); }