WriteLogEntriesRequest API is called per a log entry

[ikenox]

Hi, I use this library in my GCP project App Engine application, and I found that the quota Log ingestion requests is easily exhausted when load testing.

When a log entry is appended, the log is wrapped as singleton list, and it is passed to google-cloud-logging library.
https://github.com/googleapis/java-logging-logback/blob/master/src/main/java/com/google/cloud/logging/logback/LoggingAppender.java#L232

Finally the singleton list seems to be converted to one WriteLogEntriesRequest.
This means one log entry causes one WriteLogEntriesRequest API call.
https://github.com/googleapis/java-logging/blob/8cbf0af1c63dd14392bd819c9a33e0141d7aad2f/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingImpl.java#L510

I think it's better to support batch send option in order to reduce request number and save Log ingestion requests quota.
Is my idea correct?

[0xSage]

This library doesn't support explicit batch logic (e.g. setting your own thresholds, deciding what logs to batch). Though, I can see an implementation down the line to allow batching, where we:

1. Override append() to instead store logs in a ConcurrentHashMap.
2. Introduce LIMIT variables, that can be reset to allow batching up to n unit* at a time.
3. And once FLUSHLEVEL or LIMITs are reached, we can simply call logging.write(buffered_logs, ...).

*The main challenge would be creating the various limits to stay compliant to API thresholds. i.e. we may need limits on total log entry byte size, log entry count, and more similar to go

This would be a breaking change, so marking this feature request as a P3 for now.

In the meantime, @ikenox you may have an easier time:

1. Raising flushLevel so there are less critical logs that need to be frequently flushed.
2. Directly using the java-logging library. The benefit is that you can batch write logs (instructions) as well as set your own timestamps (maybe use your system time rather than api call time), which gives you more granularity during load testing.

[daniel-sanche]

Building off of what Nicole said, logs will only be sent in individual API calls if their severity is at or above the flushLevel (which defaults to ERROR). Anything below the flush level will be internally batched (assuming writeSynchronicity is ASYNC). As of v0.120.0, you should be able to set flushLevel=OFF to prevent instant-flushing entirely.

I'm going to close this as a duplicate of #133, but feel free to re-open if you want to discuss this further!

[hwellmann]

Please reopen, this is not a duplicate of #133.

WIth #133, you can prevent flushing, but you still can't batch log entries and reduce the Log ingestion requests.

The instructions link in #134 (comment) is broken, see Write structured logs instead.

[artemptushkin]

@daniel-sanche @nicoleczhu I'd like to join @hwellmann this is still a viable request. With the suggestion to adjust flushing we just postpone set of requests but it does one by one.

I would expect: if it sends on flush then merge all the entries into a single one, but it looks like it doesn't work like this.
See the screenshot, it's always one entry when I sent 1000 in a loop, and Stackdriver logs prove it

Just to make it clear, by batching on logback side I'd like to see call like this https://cloud.google.com/logging/docs/reference/libraries#logging_write_log_entry-java with Logging #write(Iterable<LogEntry>) in use.

Would really appreciate it if you can implement this, it burns the quote

[minherz]

The provided comments include somewhat different situations. I would like to try and summarize the use cases in order to identify the expected behavior.

As it was mentioned the way the log entry writing is implemented depends on the way the logger synchronization is configured. If synchronization is set to Synchronicity.SYNC the collection of log entries is sent synchronously when LoggingImpl.write() is invoked. Given each call sends a single or few log entries in an event of the load test it is easy to exhaust the quota for the API calls. The referenced appender code clearly sends only one log entry.
@ikenox, can you please confirm that the application does not explicitly configure synchronous logging? If it does, can you change (or remove) this configuration and see if you still has a problem with API call quota?

@artemptushkin and @hwellmann , reading your comments I could not understand what is a problem you report. Unless it is the same as in the issue description, can you provide a use case and reproducing steps please?

[artemptushkin]

There is the common problem relatively to logback in the issue description, but I think the reason is deeper.

---

Consider N calls of LoggingAppender #append(ILoggingEvent e), it causes to:

• SYNC: calls immediately N requests with 1 single log entry each here - exhausting calls
• ASYNC: creates N suspended calls with 1 single log entry each here. Then on flush it calls N times each ILoggingEvent that has been written - exhausting calls

I'd expect that either:

1. [This issue description] Appender should aggregate logs entry and batch it, weird as it doesn't have this mechanism and doesn't look as one supposed to be
2. LoggingImpl should merge pendingWrites into the batch on flush as this looks rational to call a single request when it's possible

I see that LoggingImpl is in java-logging project, should we move the issue there? @minherz

[minherz]

@artemptushkin you are correct for SYNC case. However, for ASYNC case the log entries will be batched following the batching configuration in gax library. It does not happened on a call to flush. The name is misleading. The flush speeds up sending collected log entries as soon as possible by the gax batching logic.

For SYNC case I do not see how log aggregation can be possible. If you request SYNC but you ask to send single log entry, there is no place for aggregation. The single entry is sent as requested.

Logging library and appender have the synchronization flag set to ASYNC by default. Setting it to SYNC means that a caller explicitly asked to send all log entries they provided to the logger (or appender) immediately on the call. A developer has to decide what is desired: \1 a promised API call on invocation of the logger or \2 implicit background sending which leaves places to aggregation and other optimizations.

So the expectations for SYNC behavior when a single log entry is provided do not match the configured functionality.

[artemptushkin]

Sync is clear, it's just an example. Certainly, ASYNC is expected to be updated.

I stand on the fact that I had behavior A on production then I debugged and found this, code confirms. Could you refer to that gax usage you're writing about?

by the gax batching logic.

then gax must merge log entries but I didn't see this before sending.

Or, please, check the code I refer to point where I'm wrong

[minherz]

The code referenced in your comments 1 and 2 shows the direct call up to the depth of 3. It does not show that asynchronous operation does not batch multiple log entries.
I am not sure to what you reference as "behavior A", but you can look at GrpcLoggingRpc constructor for batching and transport channel configuration. All asynchronous calls are further handled by gax library. The batching for logging is configured in the LoggingServiceV2StubSettings.java.

If you are still convinced that batching in asynchronous mode does not work, please compose a minimal application that, for your opinion, demonstrates this.

Thank you.

[artemptushkin]

Seems like it's enabled by default here com.google.api.gax.batching.BatchingSettings #newBuilder

For the history, the reference is: com.google.cloud.logging.spi.v2.GrpcLoggingRpc #write calls com.google.api.gax.rpc.BatchingCallable futureCall(RequestT request, ApiCallContext context) the latter depends on enabling of the property, which is true be default and never changes to false.

It's hard to debug async code, so I rely on the code and your @minherz statement. Sorry, I might was wrong with assumptions.

At least this discussion satisfies the problem: there is batching that is used by grpc in gax library. I think, that it makes no sense then to update Logback with additional batching logic.

As I see it's documented as well https://cloud.google.com/logging/docs/setup/java#defaults without details, but sufficient.

The ticket can be closed for me so far till any other issues/evidences.