Skip to content

Commit 13ef687

Browse files
garrettjonesgooglegarrettjonesgoogle
committed
Preventing logging re-entrance at FINE level
Also: * Reducing the scope of synchronized blocks * Removing logger exclusions except for Http2FrameLogger
1 parent d1e1c85 commit 13ef687

File tree

4 files changed

+211
-108
lines changed

4 files changed

+211
-108
lines changed

‎google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java‎

Lines changed: 75 additions & 47 deletions
Original file line numberDiff line numberDiff line change
@@ -22,11 +22,8 @@
2222
import com.google.cloud.logging.Logging.WriteOption;
2323
import com.google.common.collect.ImmutableList;
2424
import com.google.common.collect.ImmutableMap;
25-
import com.google.common.collect.ImmutableSet;
26-
2725
import java.util.LinkedList;
2826
import java.util.List;
29-
import java.util.Set;
3027
import java.util.logging.ErrorManager;
3128
import java.util.logging.Filter;
3229
import java.util.logging.Formatter;
@@ -93,12 +90,12 @@ public class LoggingHandler extends Handler {
9390
private static final String HANDLERS_PROPERTY = "handlers";
9491
private static final String ROOT_LOGGER_NAME = "";
9592
private static final String[] NO_HANDLERS = new String[0];
96-
private static final Set<String> EXCLUDED_LOGGERS = ImmutableSet.of("io.grpc", "io.netty",
97-
"com.google.api.client.http", "sun.net.www.protocol.http");
93+
94+
private static final ThreadLocal<Boolean> inPublishCall = new ThreadLocal<>();
9895

9996
private final LoggingOptions options;
100-
private final List<LogEntry> buffer = new LinkedList<>();
10197
private final WriteOption[] writeOptions;
98+
private List<LogEntry> buffer = new LinkedList<>();
10299
private Logging logging;
103100
private Level flushLevel;
104101
private long flushSize;
@@ -148,31 +145,6 @@ public LoggingHandler(String log, LoggingOptions options, MonitoredResource moni
148145
String logName = firstNonNull(log, helper.getProperty(className + ".log", "java.log"));
149146
MonitoredResource resource = firstNonNull(monitoredResource, getDefaultResource());
150147
writeOptions = new WriteOption[]{WriteOption.logName(logName), WriteOption.resource(resource)};
151-
maskLoggers();
152-
}
153-
154-
private static void maskLoggers() {
155-
for (String loggerName : EXCLUDED_LOGGERS) {
156-
Logger logger = Logger.getLogger(loggerName);
157-
// We remove the Clould Logging handler if it has been registered for a logger that should be
158-
// masked
159-
List<LoggingHandler> loggingHandlers = getLoggingHandlers(logger);
160-
for (LoggingHandler loggingHandler : loggingHandlers) {
161-
logger.removeHandler(loggingHandler);
162-
}
163-
// We mask ancestors if they have a Stackdriver Logging Handler registered
164-
Logger currentLogger = logger;
165-
Logger ancestor = currentLogger.getParent();
166-
boolean masked = false;
167-
while (ancestor != null && !masked) {
168-
if (hasLoggingHandler(ancestor)) {
169-
currentLogger.setUseParentHandlers(false);
170-
masked = true;
171-
}
172-
currentLogger = ancestor;
173-
ancestor = ancestor.getParent();
174-
}
175-
}
176148
}
177149

178150
private static List<LoggingHandler> getLoggingHandlers(Logger logger) {
@@ -272,23 +244,55 @@ Formatter getFormatterProperty(String name, Formatter defaultValue) {
272244
*/
273245
Logging getLogging() {
274246
if (logging == null) {
275-
logging = options.getService();
247+
synchronized (this) {
248+
if (logging == null) {
249+
logging = options.getService();
250+
}
251+
}
276252
}
277253
return logging;
278254
}
279255

280256
@Override
281-
public synchronized void publish(LogRecord record) {
257+
public void publish(LogRecord record) {
282258
// check that the log record should be logged
283259
if (!isLoggable(record)) {
284260
return;
285261
}
286-
LogEntry entry = entryFor(record);
287-
if (entry != null) {
288-
buffer.add(entry);
262+
263+
// HACK warning: this logger doesn't work like normal loggers; the log calls are issued
264+
// from another class instead of by itself, so it can't be configured off like normal
265+
// loggers. We have to check the source class name instead.
266+
if ("io.netty.handler.codec.http2.Http2FrameLogger".equals(record.getSourceClassName())) {
267+
return;
289268
}
290-
if (buffer.size() >= flushSize || record.getLevel().intValue() >= flushLevel.intValue()) {
291-
flush();
269+
270+
if (inPublishCall.get() != null) {
271+
// ignore all logs generated in the course of logging through this handler
272+
return;
273+
}
274+
inPublishCall.set(true);
275+
276+
try {
277+
LogEntry entry = entryFor(record);
278+
279+
List<LogEntry> flushBuffer = null;
280+
WriteOption[] flushWriteOptions = null;
281+
282+
synchronized (this) {
283+
if (entry != null) {
284+
buffer.add(entry);
285+
}
286+
if (buffer.size() >= flushSize || record.getLevel().intValue() >= flushLevel.intValue()) {
287+
flushBuffer = buffer;
288+
flushWriteOptions = writeOptions;
289+
buffer = new LinkedList<>();
290+
}
291+
}
292+
293+
flush(flushBuffer, flushWriteOptions);
294+
} finally {
295+
inPublishCall.remove();
292296
}
293297
}
294298

@@ -350,34 +354,59 @@ private static Severity severityFor(Level level) {
350354
* how entries should be written.
351355
*/
352356
void write(List<LogEntry> entries, WriteOption... options) {
353-
getLogging().write(entries, options);
357+
getLogging().writeAsync(entries, options);
354358
}
355359

356360
@Override
357-
public synchronized void flush() {
361+
public void flush() {
362+
List<LogEntry> flushBuffer;
363+
WriteOption[] flushWriteOptions;
364+
365+
synchronized (this) {
366+
if (buffer.isEmpty()) {
367+
return;
368+
}
369+
flushBuffer = buffer;
370+
flushWriteOptions = writeOptions;
371+
buffer = new LinkedList<>();
372+
}
373+
374+
flush(flushBuffer, flushWriteOptions);
375+
}
376+
377+
private void flush(List<LogEntry> flushBuffer, WriteOption[] flushWriteOptions) {
378+
if (flushBuffer == null) {
379+
return;
380+
}
358381
try {
359-
write(buffer, writeOptions);
382+
write(flushBuffer, flushWriteOptions);
360383
} catch (Exception ex) {
361384
// writing can fail but we should not throw an exception, we report the error instead
362385
reportError(null, ex, ErrorManager.FLUSH_FAILURE);
363-
} finally {
364-
buffer.clear();
365386
}
366387
}
367388

368389
/**
369390
* Closes the handler and the associated {@link Logging} object.
370391
*/
371392
@Override
372-
public synchronized void close() throws SecurityException {
393+
public void close() throws SecurityException {
394+
Logging loggingToClose = null;
373395
if (logging != null) {
396+
synchronized (this) {
397+
if (logging != null) {
398+
loggingToClose = logging;
399+
logging = null;
400+
}
401+
}
402+
}
403+
if (loggingToClose != null) {
374404
try {
375-
logging.close();
405+
loggingToClose.close();
376406
} catch (Exception ex) {
377407
// ignore
378408
}
379409
}
380-
logging = null;
381410
}
382411

383412
/**
@@ -407,6 +436,5 @@ public synchronized long setFlushSize(long flushSize) {
407436
*/
408437
public static void addHandler(Logger logger, LoggingHandler handler) {
409438
logger.addHandler(handler);
410-
maskLoggers();
411439
}
412440
}

‎google-cloud-logging/src/main/java/com/google/cloud/logging/spi/v2/LoggingServiceV2Client.java‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -151,6 +151,9 @@ protected LoggingServiceV2Client(LoggingServiceV2Settings settings) throws IOExc
151151
UnaryCallable.create(settings.deleteLogSettings(), this.channel, this.executor);
152152
this.writeLogEntriesCallable =
153153
UnaryCallable.create(settings.writeLogEntriesSettings(), this.channel, this.executor);
154+
if (settings.writeLogEntriesSettings().getBundlerFactory() != null) {
155+
closeables.add(settings.writeLogEntriesSettings().getBundlerFactory());
156+
}
154157
this.listLogEntriesCallable =
155158
UnaryCallable.create(settings.listLogEntriesSettings(), this.channel, this.executor);
156159
this.listLogEntriesPagedCallable =

‎google-cloud-logging/src/main/java/com/google/cloud/logging/spi/v2/LoggingServiceV2Settings.java‎

Lines changed: 91 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,9 @@
2222
import com.google.api.MonitoredResourceDescriptor;
2323
import com.google.api.gax.core.GoogleCredentialsProvider;
2424
import com.google.api.gax.core.RetrySettings;
25+
import com.google.api.gax.grpc.BundlingCallSettings;
26+
import com.google.api.gax.grpc.BundlingDescriptor;
27+
import com.google.api.gax.grpc.BundlingSettings;
2528
import com.google.api.gax.grpc.CallContext;
2629
import com.google.api.gax.grpc.ChannelProvider;
2730
import com.google.api.gax.grpc.ClientSettings;
@@ -31,6 +34,7 @@
3134
import com.google.api.gax.grpc.PagedCallSettings;
3235
import com.google.api.gax.grpc.PagedListDescriptor;
3336
import com.google.api.gax.grpc.PagedListResponseFactory;
37+
import com.google.api.gax.grpc.RequestIssuer;
3438
import com.google.api.gax.grpc.SimpleCallSettings;
3539
import com.google.api.gax.grpc.UnaryCallSettings;
3640
import com.google.api.gax.grpc.UnaryCallable;
@@ -54,6 +58,9 @@
5458
import com.google.protobuf.ExperimentalApi;
5559
import io.grpc.Status;
5660
import java.io.IOException;
61+
import java.util.ArrayList;
62+
import java.util.Collection;
63+
import java.util.List;
5764
import javax.annotation.Generated;
5865
import org.joda.time.Duration;
5966

@@ -103,7 +110,7 @@ public class LoggingServiceV2Settings extends ClientSettings {
103110
.build();
104111

105112
private final SimpleCallSettings<DeleteLogRequest, Empty> deleteLogSettings;
106-
private final SimpleCallSettings<WriteLogEntriesRequest, WriteLogEntriesResponse>
113+
private final BundlingCallSettings<WriteLogEntriesRequest, WriteLogEntriesResponse>
107114
writeLogEntriesSettings;
108115
private final PagedCallSettings<
109116
ListLogEntriesRequest, ListLogEntriesResponse, ListLogEntriesPagedResponse>
@@ -121,7 +128,7 @@ public SimpleCallSettings<DeleteLogRequest, Empty> deleteLogSettings() {
121128
}
122129

123130
/** Returns the object with the settings used for calls to writeLogEntries. */
124-
public SimpleCallSettings<WriteLogEntriesRequest, WriteLogEntriesResponse>
131+
public BundlingCallSettings<WriteLogEntriesRequest, WriteLogEntriesResponse>
125132
writeLogEntriesSettings() {
126133
return writeLogEntriesSettings;
127134
}
@@ -368,12 +375,80 @@ public ListLogsPagedResponse createPagedListResponse(
368375
}
369376
};
370377

378+
private static final BundlingDescriptor<WriteLogEntriesRequest, WriteLogEntriesResponse>
379+
WRITE_LOG_ENTRIES_BUNDLING_DESC =
380+
new BundlingDescriptor<WriteLogEntriesRequest, WriteLogEntriesResponse>() {
381+
@Override
382+
public String getBundlePartitionKey(WriteLogEntriesRequest request) {
383+
return request.getLogName()
384+
+ "|"
385+
+ request.getResource()
386+
+ "|"
387+
+ request.getLabels()
388+
+ "|";
389+
}
390+
391+
@Override
392+
public WriteLogEntriesRequest mergeRequests(
393+
Collection<WriteLogEntriesRequest> requests) {
394+
WriteLogEntriesRequest firstRequest = requests.iterator().next();
395+
396+
List<LogEntry> elements = new ArrayList<>();
397+
for (WriteLogEntriesRequest request : requests) {
398+
elements.addAll(request.getEntriesList());
399+
}
400+
401+
WriteLogEntriesRequest bundleRequest =
402+
WriteLogEntriesRequest.newBuilder()
403+
.setLogName(firstRequest.getLogName())
404+
.setResource(firstRequest.getResource())
405+
.putAllLabels(firstRequest.getLabels())
406+
.addAllEntries(elements)
407+
.build();
408+
return bundleRequest;
409+
}
410+
411+
@Override
412+
public void splitResponse(
413+
WriteLogEntriesResponse bundleResponse,
414+
Collection<? extends RequestIssuer<WriteLogEntriesRequest, WriteLogEntriesResponse>>
415+
bundle) {
416+
int bundleMessageIndex = 0;
417+
for (RequestIssuer<WriteLogEntriesRequest, WriteLogEntriesResponse> responder :
418+
bundle) {
419+
WriteLogEntriesResponse response = WriteLogEntriesResponse.newBuilder().build();
420+
responder.setResponse(response);
421+
}
422+
}
423+
424+
@Override
425+
public void splitException(
426+
Throwable throwable,
427+
Collection<? extends RequestIssuer<WriteLogEntriesRequest, WriteLogEntriesResponse>>
428+
bundle) {
429+
for (RequestIssuer<WriteLogEntriesRequest, WriteLogEntriesResponse> responder :
430+
bundle) {
431+
responder.setException(throwable);
432+
}
433+
}
434+
435+
@Override
436+
public long countElements(WriteLogEntriesRequest request) {
437+
return request.getEntriesCount();
438+
}
439+
440+
@Override
441+
public long countBytes(WriteLogEntriesRequest request) {
442+
return request.getSerializedSize();
443+
}
444+
};
445+
371446
/** Builder for LoggingServiceV2Settings. */
372447
public static class Builder extends ClientSettings.Builder {
373448
private final ImmutableList<UnaryCallSettings.Builder> unaryMethodSettingsBuilders;
374449

375450
private final SimpleCallSettings.Builder<DeleteLogRequest, Empty> deleteLogSettings;
376-
private final SimpleCallSettings.Builder<WriteLogEntriesRequest, WriteLogEntriesResponse>
451+
private final BundlingCallSettings.Builder<WriteLogEntriesRequest, WriteLogEntriesResponse>
377452
writeLogEntriesSettings;
378453
private final PagedCallSettings.Builder<
379454
ListLogEntriesRequest, ListLogEntriesResponse, ListLogEntriesPagedResponse>
@@ -433,7 +508,9 @@ private Builder() {
433508
deleteLogSettings = SimpleCallSettings.newBuilder(LoggingServiceV2Grpc.METHOD_DELETE_LOG);
434509

435510
writeLogEntriesSettings =
436-
SimpleCallSettings.newBuilder(LoggingServiceV2Grpc.METHOD_WRITE_LOG_ENTRIES);
511+
BundlingCallSettings.newBuilder(
512+
LoggingServiceV2Grpc.METHOD_WRITE_LOG_ENTRIES, WRITE_LOG_ENTRIES_BUNDLING_DESC)
513+
.setBundlingSettingsBuilder(BundlingSettings.newBuilder());
437514

438515
listLogEntriesSettings =
439516
PagedCallSettings.newBuilder(
@@ -465,6 +542,15 @@ private static Builder createDefault() {
465542
.setRetryableCodes(RETRYABLE_CODE_DEFINITIONS.get("idempotent"))
466543
.setRetrySettingsBuilder(RETRY_PARAM_DEFINITIONS.get("default"));
467544

545+
builder
546+
.writeLogEntriesSettings()
547+
.getBundlingSettingsBuilder()
548+
.setElementCountThreshold(1)
549+
.setElementCountLimit(1000)
550+
.setRequestByteThreshold(1024)
551+
.setRequestByteLimit(10485760)
552+
.setDelayThreshold(Duration.millis(10))
553+
.setBlockingCallCountThreshold(1);
468554
builder
469555
.writeLogEntriesSettings()
470556
.setRetryableCodes(RETRYABLE_CODE_DEFINITIONS.get("non_idempotent"))
@@ -537,7 +623,7 @@ public SimpleCallSettings.Builder<DeleteLogRequest, Empty> deleteLogSettings() {
537623
}
538624

539625
/** Returns the builder for the settings used for calls to writeLogEntries. */
540-
public SimpleCallSettings.Builder<WriteLogEntriesRequest, WriteLogEntriesResponse>
626+
public BundlingCallSettings.Builder<WriteLogEntriesRequest, WriteLogEntriesResponse>
541627
writeLogEntriesSettings() {
542628
return writeLogEntriesSettings;
543629
}

0 commit comments

Comments
 (0)