Skip to content

OAK-11401 : increased audit log level for VGC #2024

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
rishabhdaim merged 1 commit into from
Jan 24, 2025
Merged

OAK-11401 : increased audit log level for VGC #2024

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
56 changes: 25 additions & 31 deletions ...ent/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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("<Collected> [{}] internal prop revs in [{}] mode [{}]", totalDeletedSystemPropsCount, doc.getId(), fullGcMode);
if (AUDIT_LOG.isInfoEnabled() && totalDeletedSystemPropsCount > 0) {
AUDIT_LOG.info("<Collected> [{}] internal prop revs in [{}] mode [{}]", totalDeletedSystemPropsCount, doc.getId(), fullGcMode);
}
}
}
Expand Down Expand Up @@ -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("<Collected> [{}] orphaned node", doc.getId());
}
AUDIT_LOG.info("<Collected> [{}] orphaned node in mode [{}]", doc.getId(), fullGcMode);

phases.stop(GCPhase.FULL_GC_COLLECT_ORPHAN_NODES);
return true;
Expand Down Expand Up @@ -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("<Collected> [{}] deleted props in [{}]", deletedPropsCount, doc.getId());
if (AUDIT_LOG.isInfoEnabled() && deletedPropsCount > 0) {
AUDIT_LOG.info("<Collected> [{}] deleted props in [{}]. Property Names [{}]", deletedPropsCount, doc.getId(), updateOp.getChanges().keySet());
}
phases.stop(GCPhase.FULL_GC_COLLECT_PROPS);
}
Expand Down Expand Up @@ -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("<Collected> [{}] unmerged branch commits in [{}]", olderUnmergedBranchCommits.size(), doc.getId());
if (AUDIT_LOG.isInfoEnabled()) {
AUDIT_LOG.info("<Collected> [{}] unmerged branch commits in [{}]", olderUnmergedBranchCommits.size(), doc.getId());
}

// now for any of the handled system properties (the normal properties would
Expand Down Expand Up @@ -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("<Collected> [{}] internal prop revs in [{}] mode [{}]", totalDeletedSystemPropsCount, doc.getId(), fullGcMode);
if (AUDIT_LOG.isInfoEnabled() && totalDeletedSystemPropsCount > 0) {
AUDIT_LOG.info("<Collected> [{}] internal prop revs in [{}] mode [{}]", totalDeletedSystemPropsCount, doc.getId(), fullGcMode);
}
}
phases.stop(GCPhase.FULL_GC_COLLECT_UNMERGED_BC);
Expand Down Expand Up @@ -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("<Collected> [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", revEntriesCount, internalRevEntriesCount, doc.getId(), fullGcMode);
if (AUDIT_LOG.isInfoEnabled() && (revEntriesCount > 0 || internalRevEntriesCount > 0)) {
AUDIT_LOG.info("<Collected> [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", revEntriesCount, internalRevEntriesCount, doc.getId(), fullGcMode);
}

}
Expand All @@ -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("<Collected> [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", revsDiff, intRevsDiff, doc.getId(), fullGcMode);
if (AUDIT_LOG.isInfoEnabled() && (revsDiff > 0 || intRevsDiff > 0)) {
AUDIT_LOG.info("<Collected> [{}] 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);
Expand Down Expand Up @@ -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("<Collected> [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", deletedUserRevsCount, deletedInternalRevsCount, doc.getId(), fullGcMode);
if (AUDIT_LOG.isInfoEnabled() && deletedTotalRevsCount > 0) {
AUDIT_LOG.info("<Collected> [{}] 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);
Expand Down Expand Up @@ -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()) {
Expand Down Expand Up @@ -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++;
}
Expand All @@ -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++;
}
Expand All @@ -2016,8 +2010,8 @@ public void removeGarbage(final VersionGCStats stats) {
stats.deletedDocGCCount += removedSize;
stats.deletedOrphanNodesCount += removedSize;

if (AUDIT_LOG.isDebugEnabled()) {
AUDIT_LOG.debug("<delete> [{}] documents (from intended {})", removedSize, orphanOrDeletedRemovalMap.size());
if (AUDIT_LOG.isInfoEnabled()) {
AUDIT_LOG.info("<delete> [{}] documents (from intended {})", removedSize, orphanOrDeletedRemovalMap.size());
}

// save stats
Expand All @@ -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);
}

Expand Down
Loading