Skip to content
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
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
3 changes: 3 additions & 0 deletions assemble/conf/log4j2-service.properties
Original file line number Diff line number Diff line change
Expand Up @@ -84,6 +84,9 @@ logger.accumulo.level = debug
#logger.audit.additivity = false
#logger.audit.appenderRef.audit.ref = AuditLogFiles

logger.cid.name = org.apache.accumulo.core.logging.CorrelationIdLogger

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Generically, "Correlation ID" is an ambiguous term, because it doesn't explain what two or more things it is correlating.

Calling it "Correlation ID" on the ScannerBase methods is fine, because the fact that it's on the Scanner API implies it's correlating scan information.

However, as a logger, we will need to ensure that log messages that use this CorrelationIdLogger include some context, so we know it's logging scan information. This could be a simple as (pseudo-code): Logger("CorrelationIdLogger").log("Scan <id> ..."). The fact that it shows up in the logs as part of the CorrelationIdLogger tells us that it's a log message to correlate information about something. But, the fact that it says it's a "scan" in the message tells us that the correlation ID that is being provided is one associated with a scan.

Presumably, other components than scans might also be able to log to the CorrelationIdLogger with their own context-specific IDs. If that's not the intent and this is intended only for scans, then it would be better to rename this logger to something that is scan-specific, and then we don't need to include "scan" in the message to add that important contextual information.

logger.cid.level = trace

rootLogger.level = info
rootLogger.appenderRef.console.ref = STDERR
rootLogger.appenderRef.rolling.ref = LogFiles
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -370,15 +370,15 @@ default void forEach(BiConsumer<? super Key,? super Value> keyValueConsumer) {
* @return consistency level
* @since 2.1.0
*/
public ConsistencyLevel getConsistencyLevel();
ConsistencyLevel getConsistencyLevel();

/**
* Set the desired consistency level for this scanner.
*
* @param level consistency level
* @since 2.1.0
*/
public void setConsistencyLevel(ConsistencyLevel level);
void setConsistencyLevel(ConsistencyLevel level);

/**
* Stream the Scanner results sequentially from this scanner's iterator
Expand All @@ -390,4 +390,21 @@ default Stream<Entry<Key,Value>> stream() {
return StreamSupport.stream(this.spliterator(), false);
}

/**
* Set correlationId on the Scanner. This data will be added to server side logs for correlation.
*
* @param correlationId meaningful data that applications can use to correlate server side
* information
* @since 3.0.0
*/
void setCorrelationId(String correlationId);

/**
* Get Scanner correlationId.
*
* @return correlationId
* @since 3.0.0
*/
String getCorrelationId();

}
Original file line number Diff line number Diff line change
Expand Up @@ -96,4 +96,13 @@ public abstract class ActiveScan {
* @since 1.5.0
*/
public abstract long getIdleTime();

/**
* Set user data set on the Scanner.
*
* @return correlationId meaningful data that applications can use to correlate server side
* information
* @since 3.0.0
*/
public abstract String getCorrelationId();
}
Original file line number Diff line number Diff line change
Expand Up @@ -55,6 +55,7 @@ public class ActiveScanImpl extends ActiveScan {
private Map<String,Map<String,String>> ssio;
private String user;
private Authorizations authorizations;
private String correlationId;

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Honestly, I think scanId is probably much more straight-forward than correlationId. Or even "scanLabel".

@EdColeman EdColeman Feb 10, 2023

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

scanLabel is attractive. scanId seems like it should be a UUID (like a FATE ID) that uniquely identifies the scan in the system for thing like killing it. This could be an UUID or maybe just a string that provided the caller / process

Another thought is if there is intent for a parent / child relationship then the name could reflect that.

@EdColeman EdColeman Feb 10, 2023

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

After reading correlationId I am more comfortable with correlationId because we can easily signal usage intent and reference other sources if additional clarification is needed.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The problem with correlationId, is that it doesn't clue you in to the context of what it is correlating. I can imagine half a dozen different correlationIds in Accumulo... for scans, compactions, RPC requests in general, writes, bulk ingest, etc. They can't all be called correlationId internally. They need to be scoped somehow to the context that says more about what they are correlating. That context can be given by the interface the method is attached to, the class the field is in, or additional information in the log message, or some other way. But I think it's important to think about and provide that context somehow, if it isn't present, because "correlationId" by itself is just too generic of a concept that applies to too many contexts.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If we migrate to using a specific logger like suggested, then the name of the logger could signal the context.

In a general sense, the correlationId as a general concept looks to want to apply to a more general usage than just a scan. Say that a client reads, possibly updates and then writes the modified or new data within the scope of one unit of work for the client. When logged consistently, the correlationId could be used to tie all of the log statements for that client operation, scan writes,... across servers and processes.

correlationId seems synonymous with transactionId in this context, without the implied atomic and rollback properties that are normally associated with transactions.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Right, in that sense it's not a scan correlationId, it's a client correlationId.

So I guess now I'm confused... which one are you going for here? I was under the impression you were going for a scan correlationId, but now I'm wondering if you are intending a client correlationId. If the latter, I would imagine we should focus on amending AccumuloClient.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Say that a client reads, possibly updates and then writes the modified or new data within the scope of one unit of work for the client. When logged consistently, the correlationId could be used to tie all of the log statements for that client operation, scan writes,... across servers and processes.
Right, in that sense it's not a scan correlationId, it's a client correlationId.

I was just saying that the same correlationId would be used by the client for those operations. I wasn't proposing a correlationId at the client.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Say that a client reads, possibly updates and then writes the modified or new data within the scope of one unit of work for the client. When logged consistently, the correlationId could be used to tie all of the log statements for that client operation, scan writes,... across servers and processes.
Right, in that sense it's not a scan correlationId, it's a client correlationId.

I was just saying that the same correlationId would be used by the client for those operations. I wasn't proposing a correlationId at the client.

I think I was proposing that, if that's the desired use case we're trying to support.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think a client correlationId should be the goal, this is a step that would not be incompatible with that.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think a client correlationId should be the goal, this is a step that would not be incompatible with that.

I think adding the APIs to ScannerBase would need to be rolled back if we're going to make it client-wide. It doesn't make sense to add it there if we're going to change it to be added to AccumuloClient later.


ActiveScanImpl(ClientContext context,
org.apache.accumulo.core.tabletscan.thrift.ActiveScan activeScan)
Expand All @@ -81,6 +82,7 @@ public class ActiveScanImpl extends ActiveScan {
this.ssiList.add(ii.iterName + "=" + ii.priority + "," + ii.className);
}
this.ssio = activeScan.ssio;
this.correlationId = activeScan.correlationId;
}

@Override
Expand Down Expand Up @@ -152,4 +154,10 @@ public Authorizations getAuthorizations() {
public long getIdleTime() {
return idle;
}

@Override
public String getCorrelationId() {
return correlationId;
}

}
Original file line number Diff line number Diff line change
Expand Up @@ -81,11 +81,12 @@ public class ScannerIterator implements Iterator<Entry<Key,Value>> {
range = range.bound(this.options.fetchedColumns.first(), this.options.fetchedColumns.last());
}

scanState = new ScanState(context, tableId, authorizations, new Range(range),
options.fetchedColumns, size, options.serverSideIteratorList,
options.serverSideIteratorOptions, isolated, readaheadThreshold,
options.getSamplerConfiguration(), options.batchTimeOut, options.classLoaderContext,
options.executionHints, options.getConsistencyLevel() == ConsistencyLevel.EVENTUAL);
scanState =
new ScanState(context, tableId, authorizations, new Range(range), options.fetchedColumns,
size, options.serverSideIteratorList, options.serverSideIteratorOptions, isolated,
readaheadThreshold, options.getSamplerConfiguration(), options.batchTimeOut,
options.classLoaderContext, options.executionHints,
options.getConsistencyLevel() == ConsistencyLevel.EVENTUAL, options.getCorrelationId());

// If we want to start readahead immediately, don't wait for hasNext to be called
if (readaheadThreshold == 0L) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -67,6 +67,8 @@ public class ScannerOptions implements ScannerBase {

private ConsistencyLevel consistencyLevel = ConsistencyLevel.IMMEDIATE;

private String correlationId = "";

protected ScannerOptions() {}

public ScannerOptions(ScannerOptions so) {
Expand Down Expand Up @@ -186,6 +188,7 @@ protected static void setOptions(ScannerOptions dst, ScannerOptions src) {
dst.executionHints = src.executionHints;

dst.consistencyLevel = src.consistencyLevel;
dst.correlationId = src.correlationId;
}
}
}
Expand Down Expand Up @@ -287,4 +290,14 @@ public void setConsistencyLevel(ConsistencyLevel level) {
this.consistencyLevel = Objects.requireNonNull(level);
}

@Override
public String getCorrelationId() {
return correlationId;
}

@Override
public void setCorrelationId(String correlationId) {
this.correlationId = Objects.requireNonNull(correlationId);
}

}
Original file line number Diff line number Diff line change
Expand Up @@ -621,6 +621,11 @@ public Collection<? extends ScanServerAttempt> getAttempts(TabletId tabletId) {
public Map<String,String> getHints() {
return options.executionHints;
}

@Override
public String getCorrelationId() {
return options.getCorrelationId();
}
};

var actions = ecsm.selectServers(params);
Expand Down Expand Up @@ -827,7 +832,8 @@ static void doLookup(ClientContext context, String server, Map<KeyExtent,List<Ra
options.serverSideIteratorList, options.serverSideIteratorOptions,
ByteBufferUtil.toByteBuffers(authorizations.getAuthorizations()), waitForWrites,
SamplerConfigurationImpl.toThrift(options.getSamplerConfiguration()),
options.batchTimeOut, options.classLoaderContext, execHints, busyTimeout);
options.batchTimeOut, options.classLoaderContext, execHints, busyTimeout,
options.getCorrelationId());
if (waitForWrites) {
ThriftScanner.serversWaitedForWrites.get(ttype).add(server.toString());
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -102,8 +102,8 @@ public static boolean getBatchFromServer(ClientContext context, Range range, Key
String server, SortedMap<Key,Value> results, SortedSet<Column> fetchedColumns,
List<IterInfo> serverSideIteratorList,
Map<String,Map<String,String>> serverSideIteratorOptions, int size,
Authorizations authorizations, long batchTimeOut, String classLoaderContext)
throws AccumuloException, AccumuloSecurityException {
Authorizations authorizations, long batchTimeOut, String classLoaderContext,
String correlationId) throws AccumuloException, AccumuloSecurityException {
if (server == null) {
throw new AccumuloException(new IOException());
}
Expand All @@ -119,7 +119,7 @@ public static boolean getBatchFromServer(ClientContext context, Range range, Key
ScanState scanState = new ScanState(context, extent.tableId(), authorizations, range,
fetchedColumns, size, serverSideIteratorList, serverSideIteratorOptions, false,
Constants.SCANNER_DEFAULT_READAHEAD_THRESHOLD, null, batchTimeOut, classLoaderContext,
null, false);
null, false, correlationId);

TabletType ttype = TabletType.type(extent);
boolean waitForWrites = !serversWaitedForWrites.get(ttype).contains(server);
Expand All @@ -129,7 +129,7 @@ public static boolean getBatchFromServer(ClientContext context, Range range, Key
scanState.size, scanState.serverSideIteratorList, scanState.serverSideIteratorOptions,
scanState.authorizations.getAuthorizationsBB(), waitForWrites, scanState.isolated,
scanState.readaheadThreshold, null, scanState.batchTimeOut, classLoaderContext,
scanState.executionHints, 0L);
scanState.executionHints, 0L, scanState.correlationId);
if (waitForWrites) {
serversWaitedForWrites.get(ttype).add(server);
}
Expand Down Expand Up @@ -196,6 +196,8 @@ public static class ScanState {

Duration busyTimeout;

String correlationId;

TabletLocation getErrorLocation() {
return prevLoc;
}
Expand All @@ -205,7 +207,8 @@ public ScanState(ClientContext context, TableId tableId, Authorizations authoriz
List<IterInfo> serverSideIteratorList,
Map<String,Map<String,String>> serverSideIteratorOptions, boolean isolated,
long readaheadThreshold, SamplerConfiguration samplerConfig, long batchTimeOut,
String classLoaderContext, Map<String,String> executionHints, boolean useScanServer) {
String classLoaderContext, Map<String,String> executionHints, boolean useScanServer,
String correlationId) {
this.context = context;
this.authorizations = authorizations;
this.classLoaderContext = classLoaderContext;
Expand Down Expand Up @@ -249,6 +252,8 @@ public ScanState(ClientContext context, TableId tableId, Authorizations authoriz
if (useScanServer) {
scanAttempts = new ScanServerAttemptsImpl();
}

this.correlationId = correlationId;
}
}

Expand Down Expand Up @@ -545,6 +550,11 @@ public Map<String,String> getHints() {
}
return scanState.executionHints;
}

@Override
public String getCorrelationId() {
return scanState.correlationId;
}
};

ScanServerSelections actions = context.getScanServerSelector().selectServers(params);
Expand Down Expand Up @@ -638,7 +648,8 @@ private static List<KeyValue> scanRpc(TabletLocation loc, ScanState scanState,
scanState.authorizations.getAuthorizationsBB(), waitForWrites, scanState.isolated,
scanState.readaheadThreshold,
SamplerConfigurationImpl.toThrift(scanState.samplerConfig), scanState.batchTimeOut,
scanState.classLoaderContext, scanState.executionHints, busyTimeout);
scanState.classLoaderContext, scanState.executionHints, busyTimeout,
scanState.correlationId);
if (waitForWrites) {
serversWaitedForWrites.get(ttype).add(loc.tablet_location);
}
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,55 @@
/*
* Licensed to the Apache Software Foundation (ASF) under one
* or more contributor license agreements. See the NOTICE file
* distributed with this work for additional information
* regarding copyright ownership. The ASF licenses this file
* to you under the Apache License, Version 2.0 (the
* "License"); you may not use this file except in compliance
* with the License. You may obtain a copy of the License at
*
* https://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing,
* software distributed under the License is distributed on an
* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
* KIND, either express or implied. See the License for the
* specific language governing permissions and limitations
* under the License.
*/
package org.apache.accumulo.core.logging;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.event.Level;

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm still a bit uncomfortable more tightly coupling ourselves to more SLF4J APIs, and have reservations about using Level here. Log4j's Level caused us a lot of problems removing it from our code, and although SLF4J's Level is maybe situated differently in its API, I can't help but anticipate the potential future problems we could have by using more of the logging framework's APIs in our code. I'd really prefer to avoid it. I also think that what I suggested before about having a logging lifecycle class, like what Keith did elsewhere would be better than adding this Logger class. I know Keith said that was out of scope for this PR... but I'm not so sure. If having that avoids this new class I think that's better than adding this class. If it needs to be done first, so it's a discrete task, that's fine... but I do think it's better than adding this class.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I do agree with removing the extra sl4j new dependencies - I think the proposed solution of using Keith's method is what we should be targeting.

As Christopher noted, the change in logging because of dependency changes took quite a while to unwind because we had basically painted ourselves into a corner, avoiding that happening again would be better.

I think those changes could happen first, or this can be committed with the understanding that it would be reworked before any release. Separate PRs would make the review easier and either way would set-up merge conflicts with this PR.


public class CorrelationIdLogger {

private static final Logger LOG = LoggerFactory.getLogger(CorrelationIdLogger.class);
private static final String FORMAT = "(%s) %s";

/**
* Utility method that will log the msg and args to the calling class' logger (classLogger) if the
* classLogger argument is supplied. The classLogger argument would be null in the case where we
* don't want to log the same thing twice.
*
* @param level slf4j log level
* @param classLogger calling class' slf4j logger
* @param correlationId meaningful data that applications can use to correlate server side
* information
* @param msg log message
* @param args log message arguments
*/
public static void log(Level level, Logger classLogger, String correlationId, String msg,
Object... args) {
if (classLogger != null && classLogger.isEnabledForLevel(level)) {
classLogger.atLevel(level).log(msg, args);
}
if (LOG.isEnabledForLevel(level)) {
if (args == null) {
LOG.atLevel(level).log(String.format(FORMAT, correlationId, msg));
} else {
LOG.atLevel(level).log(String.format(FORMAT, correlationId, msg), args);
}
}
Comment on lines +44 to +53

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Having two log messages seems excessive. I think if the original logger had the necessary information, you can correlate the logs without logging a second time.

I'm also thinking that the layers of formatting / interpolation here make this very confusing to understand/maintain.

}
}
Original file line number Diff line number Diff line change
Expand Up @@ -107,7 +107,8 @@ public TabletLocations lookupTablet(ClientContext context, TabletLocation src, T
Map<String,Map<String,String>> serverSideIteratorOptions = Collections.emptyMap();
boolean more = ThriftScanner.getBatchFromServer(context, range, src.tablet_extent,
src.tablet_location, encodedResults, locCols, serverSideIteratorList,
serverSideIteratorOptions, Constants.SCAN_BATCH_SIZE, Authorizations.EMPTY, 0L, null);
serverSideIteratorOptions, Constants.SCAN_BATCH_SIZE, Authorizations.EMPTY, 0L, null,
"metadata-location-obtainer");

decodeRows(encodedResults, results);

Expand All @@ -117,7 +118,8 @@ public TabletLocations lookupTablet(ClientContext context, TabletLocation src, T
encodedResults.clear();
ThriftScanner.getBatchFromServer(context, range, src.tablet_extent, src.tablet_location,
encodedResults, locCols, serverSideIteratorList, serverSideIteratorOptions,
Constants.SCAN_BATCH_SIZE, Authorizations.EMPTY, 0L, null);
Constants.SCAN_BATCH_SIZE, Authorizations.EMPTY, 0L, null,
"metadata-location-obtainer");

decodeRows(encodedResults, results);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,8 @@

import org.apache.accumulo.core.conf.ConfigurationTypeHelper;
import org.apache.accumulo.core.data.TabletId;
import org.apache.accumulo.core.logging.CorrelationIdLogger;
import org.slf4j.event.Level;

import com.google.common.base.Preconditions;
import com.google.common.base.Suppliers;
Expand Down Expand Up @@ -367,7 +369,8 @@ public Duration getBusyTimeout() {
(Math.abs(hashCode.asInt()) + RANDOM.nextInt(numServers)) % orderedScanServers.size();

serverToUse = orderedScanServers.get(serverIndex);

CorrelationIdLogger.log(Level.TRACE, null, params.getCorrelationId(),
"ScanServerSelector selected server {} for tablet {}", serverToUse, tablet);
serversToUse.put(tablet, serverToUse);
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -24,8 +24,10 @@
import java.util.Map;

import org.apache.accumulo.core.client.ScannerBase;
import org.apache.accumulo.core.logging.CorrelationIdLogger;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.event.Level;

/**
* When configured for a scan executor, this prioritizer allows scanners to set priorities as
Expand Down Expand Up @@ -80,6 +82,8 @@ private static int getPriority(ScanInfo si, int defaultPriority, HintProblemActi
String prio = si.getExecutionHints().get("priority");
if (prio != null) {
try {
CorrelationIdLogger.log(Level.TRACE, null, si.getCorrelationId(),
"HintScanPrioritizer - scan has priority: {}", prio);
return Integer.parseInt(prio);
} catch (NumberFormatException nfe) {
switch (hpa) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -125,4 +125,13 @@ enum Type {
* @return Hints set by a scanner using {@link ScannerBase#setExecutionHints(Map)}
*/
Map<String,String> getExecutionHints();

/**
* @return correlationId set by a scanner using {@link ScannerBase#setCorrelationId(String)}
*
* @since 3.0.0
*/
default String getCorrelationId() {
return "";
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -105,6 +105,14 @@ interface SelectorParameters {
* were set, an empty map is returned.
*/
Map<String,String> getHints();

/**
* @return correlationId set by a scanner using {@link ScannerBase#setCorrelationId(String)}
*
* @since 3.0.0
*/
String getCorrelationId();

}

/**
Expand Down
Loading