Skip to content

Commit

Permalink
Preventing logging re-entrance at FINE level
Browse files Browse the repository at this point in the history 
Also:
* Reducing the scope of synchronized blocks
* Removing logger exclusions except for Http2FrameLogger
  • Loading branch information
@garrettjonesgoogle
garrettjonesgoogle committed Jan 11, 2017
1 parent d1e1c85 commit 13ef687
Show file tree
Hide file tree
Showing 4 changed files with 211 additions and 108 deletions.
122 changes: 75 additions & 47 deletions google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,11 +22,8 @@
import com.google.cloud.logging.Logging.WriteOption;
import com.google.common.collect.ImmutableList;
import com.google.common.collect.ImmutableMap;
import com.google.common.collect.ImmutableSet;

import java.util.LinkedList;
import java.util.List;
import java.util.Set;
import java.util.logging.ErrorManager;
import java.util.logging.Filter;
import java.util.logging.Formatter;
Expand Down Expand Up @@ -93,12 +90,12 @@ public class LoggingHandler extends Handler {
private static final String HANDLERS_PROPERTY = "handlers";
private static final String ROOT_LOGGER_NAME = "";
private static final String[] NO_HANDLERS = new String[0];
private static final Set<String> EXCLUDED_LOGGERS = ImmutableSet.of("io.grpc", "io.netty",
"com.google.api.client.http", "sun.net.www.protocol.http");

private static final ThreadLocal<Boolean> inPublishCall = new ThreadLocal<>();

private final LoggingOptions options;
private final List<LogEntry> buffer = new LinkedList<>();
private final WriteOption[] writeOptions;
private List<LogEntry> buffer = new LinkedList<>();
private Logging logging;
private Level flushLevel;
private long flushSize;
Expand Down Expand Up @@ -148,31 +145,6 @@ public LoggingHandler(String log, LoggingOptions options, MonitoredResource moni
String logName = firstNonNull(log, helper.getProperty(className + ".log", "java.log"));
MonitoredResource resource = firstNonNull(monitoredResource, getDefaultResource());
writeOptions = new WriteOption[]{WriteOption.logName(logName), WriteOption.resource(resource)};
maskLoggers();
}

private static void maskLoggers() {
for (String loggerName : EXCLUDED_LOGGERS) {
Logger logger = Logger.getLogger(loggerName);
// We remove the Clould Logging handler if it has been registered for a logger that should be
// masked
List<LoggingHandler> loggingHandlers = getLoggingHandlers(logger);
for (LoggingHandler loggingHandler : loggingHandlers) {
logger.removeHandler(loggingHandler);
}
// We mask ancestors if they have a Stackdriver Logging Handler registered
Logger currentLogger = logger;
Logger ancestor = currentLogger.getParent();
boolean masked = false;
while (ancestor != null && !masked) {
if (hasLoggingHandler(ancestor)) {
currentLogger.setUseParentHandlers(false);
masked = true;
}
currentLogger = ancestor;
ancestor = ancestor.getParent();
}
}
}

private static List<LoggingHandler> getLoggingHandlers(Logger logger) {
Expand Down Expand Up @@ -272,23 +244,55 @@ Formatter getFormatterProperty(String name, Formatter defaultValue) {
*/
Logging getLogging() {
if (logging == null) {
logging = options.getService();
synchronized (this) {
if (logging == null) {
logging = options.getService();
}
}
}
return logging;
}

@Override
public synchronized void publish(LogRecord record) {
public void publish(LogRecord record) {
// check that the log record should be logged
if (!isLoggable(record)) {
return;
}
LogEntry entry = entryFor(record);
if (entry != null) {
buffer.add(entry);

// HACK warning: this logger doesn't work like normal loggers; the log calls are issued
// from another class instead of by itself, so it can't be configured off like normal
// loggers. We have to check the source class name instead.
if ("io.netty.handler.codec.http2.Http2FrameLogger".equals(record.getSourceClassName())) {
return;
}
if (buffer.size() >= flushSize || record.getLevel().intValue() >= flushLevel.intValue()) {
flush();

if (inPublishCall.get() != null) {
// ignore all logs generated in the course of logging through this handler
return;
}
inPublishCall.set(true);

try {
LogEntry entry = entryFor(record);

List<LogEntry> flushBuffer = null;
WriteOption[] flushWriteOptions = null;

synchronized (this) {
if (entry != null) {
buffer.add(entry);
}
if (buffer.size() >= flushSize || record.getLevel().intValue() >= flushLevel.intValue()) {
flushBuffer = buffer;
flushWriteOptions = writeOptions;
buffer = new LinkedList<>();
}
}

flush(flushBuffer, flushWriteOptions);
} finally {
inPublishCall.remove();
}
}

Expand Down Expand Up @@ -350,34 +354,59 @@ private static Severity severityFor(Level level) {
* how entries should be written.
*/
void write(List<LogEntry> entries, WriteOption... options) {
getLogging().write(entries, options);
getLogging().writeAsync(entries, options);
}

@Override
public synchronized void flush() {
public void flush() {
List<LogEntry> flushBuffer;
WriteOption[] flushWriteOptions;

synchronized (this) {
if (buffer.isEmpty()) {
return;
}
flushBuffer = buffer;
flushWriteOptions = writeOptions;
buffer = new LinkedList<>();
}

flush(flushBuffer, flushWriteOptions);
}

private void flush(List<LogEntry> flushBuffer, WriteOption[] flushWriteOptions) {
if (flushBuffer == null) {
return;
}
try {
write(buffer, writeOptions);
write(flushBuffer, flushWriteOptions);
} catch (Exception ex) {
// writing can fail but we should not throw an exception, we report the error instead
reportError(null, ex, ErrorManager.FLUSH_FAILURE);
} finally {
buffer.clear();
}
}

/**
* Closes the handler and the associated {@link Logging} object.
*/
@Override
public synchronized void close() throws SecurityException {
public void close() throws SecurityException {
Logging loggingToClose = null;
if (logging != null) {
synchronized (this) {
if (logging != null) {
loggingToClose = logging;
logging = null;
}
}
}
if (loggingToClose != null) {
try {
logging.close();
loggingToClose.close();
} catch (Exception ex) {
// ignore
}
}
logging = null;
}

/**
Expand Down Expand Up @@ -407,6 +436,5 @@ public synchronized long setFlushSize(long flushSize) {
*/
public static void addHandler(Logger logger, LoggingHandler handler) {
logger.addHandler(handler);
maskLoggers();
}
}
3 changes: 3 additions & 0 deletions ...e-cloud-logging/src/main/java/com/google/cloud/logging/spi/v2/LoggingServiceV2Client.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -151,6 +151,9 @@ protected LoggingServiceV2Client(LoggingServiceV2Settings settings) throws IOExc
UnaryCallable.create(settings.deleteLogSettings(), this.channel, this.executor);
this.writeLogEntriesCallable =
UnaryCallable.create(settings.writeLogEntriesSettings(), this.channel, this.executor);
if (settings.writeLogEntriesSettings().getBundlerFactory() != null) {
closeables.add(settings.writeLogEntriesSettings().getBundlerFactory());
}
this.listLogEntriesCallable =
UnaryCallable.create(settings.listLogEntriesSettings(), this.channel, this.executor);
this.listLogEntriesPagedCallable =
Expand Down
96 changes: 91 additions & 5 deletions ...cloud-logging/src/main/java/com/google/cloud/logging/spi/v2/LoggingServiceV2Settings.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,9 @@
import com.google.api.MonitoredResourceDescriptor;
import com.google.api.gax.core.GoogleCredentialsProvider;
import com.google.api.gax.core.RetrySettings;
import com.google.api.gax.grpc.BundlingCallSettings;
import com.google.api.gax.grpc.BundlingDescriptor;
import com.google.api.gax.grpc.BundlingSettings;
import com.google.api.gax.grpc.CallContext;
import com.google.api.gax.grpc.ChannelProvider;
import com.google.api.gax.grpc.ClientSettings;
Expand All @@ -31,6 +34,7 @@
import com.google.api.gax.grpc.PagedCallSettings;
import com.google.api.gax.grpc.PagedListDescriptor;
import com.google.api.gax.grpc.PagedListResponseFactory;
import com.google.api.gax.grpc.RequestIssuer;
import com.google.api.gax.grpc.SimpleCallSettings;
import com.google.api.gax.grpc.UnaryCallSettings;
import com.google.api.gax.grpc.UnaryCallable;
Expand All @@ -54,6 +58,9 @@
import com.google.protobuf.ExperimentalApi;
import io.grpc.Status;
import java.io.IOException;
import java.util.ArrayList;
import java.util.Collection;
import java.util.List;
import javax.annotation.Generated;
import org.joda.time.Duration;

Expand Down Expand Up @@ -103,7 +110,7 @@ public class LoggingServiceV2Settings extends ClientSettings {
.build();

private final SimpleCallSettings<DeleteLogRequest, Empty> deleteLogSettings;
private final SimpleCallSettings<WriteLogEntriesRequest, WriteLogEntriesResponse>
private final BundlingCallSettings<WriteLogEntriesRequest, WriteLogEntriesResponse>
writeLogEntriesSettings;
private final PagedCallSettings<
ListLogEntriesRequest, ListLogEntriesResponse, ListLogEntriesPagedResponse>
Expand All @@ -121,7 +128,7 @@ public SimpleCallSettings<DeleteLogRequest, Empty> deleteLogSettings() {
}

/** Returns the object with the settings used for calls to writeLogEntries. */
public SimpleCallSettings<WriteLogEntriesRequest, WriteLogEntriesResponse>
public BundlingCallSettings<WriteLogEntriesRequest, WriteLogEntriesResponse>
writeLogEntriesSettings() {
return writeLogEntriesSettings;
}
Expand Down Expand Up @@ -368,12 +375,80 @@ public ListLogsPagedResponse createPagedListResponse(
}
};

private static final BundlingDescriptor<WriteLogEntriesRequest, WriteLogEntriesResponse>
WRITE_LOG_ENTRIES_BUNDLING_DESC =
new BundlingDescriptor<WriteLogEntriesRequest, WriteLogEntriesResponse>() {
@Override
public String getBundlePartitionKey(WriteLogEntriesRequest request) {
return request.getLogName()
+ "|"
+ request.getResource()
+ "|"
+ request.getLabels()
+ "|";
}

@Override
public WriteLogEntriesRequest mergeRequests(
Collection<WriteLogEntriesRequest> requests) {
WriteLogEntriesRequest firstRequest = requests.iterator().next();

List<LogEntry> elements = new ArrayList<>();
for (WriteLogEntriesRequest request : requests) {
elements.addAll(request.getEntriesList());
}

WriteLogEntriesRequest bundleRequest =
WriteLogEntriesRequest.newBuilder()
.setLogName(firstRequest.getLogName())
.setResource(firstRequest.getResource())
.putAllLabels(firstRequest.getLabels())
.addAllEntries(elements)
.build();
return bundleRequest;
}

@Override
public void splitResponse(
WriteLogEntriesResponse bundleResponse,
Collection<? extends RequestIssuer<WriteLogEntriesRequest, WriteLogEntriesResponse>>
bundle) {
int bundleMessageIndex = 0;
for (RequestIssuer<WriteLogEntriesRequest, WriteLogEntriesResponse> responder :
bundle) {
WriteLogEntriesResponse response = WriteLogEntriesResponse.newBuilder().build();
responder.setResponse(response);
}
}

@Override
public void splitException(
Throwable throwable,
Collection<? extends RequestIssuer<WriteLogEntriesRequest, WriteLogEntriesResponse>>
bundle) {
for (RequestIssuer<WriteLogEntriesRequest, WriteLogEntriesResponse> responder :
bundle) {
responder.setException(throwable);
}
}

@Override
public long countElements(WriteLogEntriesRequest request) {
return request.getEntriesCount();
}

@Override
public long countBytes(WriteLogEntriesRequest request) {
return request.getSerializedSize();
}
};

/** Builder for LoggingServiceV2Settings. */
public static class Builder extends ClientSettings.Builder {
private final ImmutableList<UnaryCallSettings.Builder> unaryMethodSettingsBuilders;

private final SimpleCallSettings.Builder<DeleteLogRequest, Empty> deleteLogSettings;
private final SimpleCallSettings.Builder<WriteLogEntriesRequest, WriteLogEntriesResponse>
private final BundlingCallSettings.Builder<WriteLogEntriesRequest, WriteLogEntriesResponse>
writeLogEntriesSettings;
private final PagedCallSettings.Builder<
ListLogEntriesRequest, ListLogEntriesResponse, ListLogEntriesPagedResponse>
Expand Down Expand Up @@ -433,7 +508,9 @@ private Builder() {
deleteLogSettings = SimpleCallSettings.newBuilder(LoggingServiceV2Grpc.METHOD_DELETE_LOG);

writeLogEntriesSettings =
SimpleCallSettings.newBuilder(LoggingServiceV2Grpc.METHOD_WRITE_LOG_ENTRIES);
BundlingCallSettings.newBuilder(
LoggingServiceV2Grpc.METHOD_WRITE_LOG_ENTRIES, WRITE_LOG_ENTRIES_BUNDLING_DESC)
.setBundlingSettingsBuilder(BundlingSettings.newBuilder());

listLogEntriesSettings =
PagedCallSettings.newBuilder(
Expand Down Expand Up @@ -465,6 +542,15 @@ private static Builder createDefault() {
.setRetryableCodes(RETRYABLE_CODE_DEFINITIONS.get("idempotent"))
.setRetrySettingsBuilder(RETRY_PARAM_DEFINITIONS.get("default"));

builder
.writeLogEntriesSettings()
.getBundlingSettingsBuilder()
.setElementCountThreshold(1)
.setElementCountLimit(1000)
.setRequestByteThreshold(1024)
.setRequestByteLimit(10485760)
.setDelayThreshold(Duration.millis(10))
.setBlockingCallCountThreshold(1);
builder
.writeLogEntriesSettings()
.setRetryableCodes(RETRYABLE_CODE_DEFINITIONS.get("non_idempotent"))
Expand Down Expand Up @@ -537,7 +623,7 @@ public SimpleCallSettings.Builder<DeleteLogRequest, Empty> deleteLogSettings() {
}

/** Returns the builder for the settings used for calls to writeLogEntries. */
public SimpleCallSettings.Builder<WriteLogEntriesRequest, WriteLogEntriesResponse>
public BundlingCallSettings.Builder<WriteLogEntriesRequest, WriteLogEntriesResponse>
writeLogEntriesSettings() {
return writeLogEntriesSettings;
}
Expand Down
Loading

0 comments on commit 13ef687

Please sign in to comment.