Improve handling of "Log entry with size X exceeds maximum size"

Hi,

Lib version: google-cloud-logging==1.15.0

I'm experiencing lots of errors like:

Traceback (most recent call last):
  File "/env/lib/python3.7/site-packages/google/cloud/logging/handlers/transports/background_thread.py", line 123, in _safely_commit_batch
    batch.commit()
  File "/env/lib/python3.7/site-packages/google/cloud/logging/logger.py", line 383, in commit
    client.logging_api.write_entries(entries, **kwargs)
  File "/env/lib/python3.7/site-packages/google/cloud/logging/_gapic.py", line 126, in write_entries
    partial_success=partial_success,
  File "/env/lib/python3.7/site-packages/google/cloud/logging_v2/gapic/logging_service_v2_client.py", line 477, in write_log_entries
    request, retry=retry, timeout=timeout, metadata=metadata
  File "/env/lib/python3.7/site-packages/google/api_core/gapic_v1/method.py", line 143, in __call__
    return wrapped_func(*args, **kwargs)
  File "/env/lib/python3.7/site-packages/google/api_core/retry.py", line 286, in retry_wrapped_func
    on_error=on_error,
  File "/env/lib/python3.7/site-packages/google/api_core/retry.py", line 184, in retry_target
    return target()
  File "/env/lib/python3.7/site-packages/google/api_core/timeout.py", line 214, in func_with_timeout
    return func(*args, **kwargs)
  File "/env/lib/python3.7/site-packages/google/api_core/grpc_helpers.py", line 59, in error_remapped_callable
    six.raise_from(exceptions.from_grpc_error(exc), exc)
  File "<string>", line 3, in raise_from
google.api_core.exceptions.InvalidArgument: 400 Log entry with size 256.6K exceeds maximum size of 256.0K

This traceback doesn't help me identify place where the offending line was logged (I'm using python logging), so I cannot fix it.

I can see at least 3 resolutions to this:

allow user to specify that log message can be cropped to max size before sending to Cloud Logging. This way, if someone is ok with it, everything will get (at least partially) logged
add to the traceback information where the offending log entry was logged (file name + line number). This way I may be able to identify and fix too long log lines - right now there's no such information.
verify the log message size eagerly when logging, i.e. throw exception from methods like logging.info when the message is too long and we won't be able to upload it (so rather than doing the verification in a background thread, do it immediately)

@rtshadow One possibility for identifying the offending line would be to switch (temporarily) from using BackgroundThreadTransport to using SyncTransport, so that the code creating the offending log entry waits for it to be sent.

@daniel-sanche

@daniel-sanche , I think that this issue is also related to 448

@daniel-sanche

Hi @daniel-sanche thanks for the quick response. I haven't been able to spot anywhere where I could log such enormous payload. I got even a message for 9Mb once. How can I try to spot the part of code that triggers that issue. I have read in some issues that sync transport could help identifying the specific log, but I worry for performance issue while doing that, as this is happening in a production system. Is there any other trick you got in mind?

In any case, the fact that at least someone else starting having that issue seems suspicious. Ofc both having a bug is still a possibility but I will try to rule that out by downgrading to 3.10.0 as last resort.

@chrisK824

@chrisK824 logs are aggregated and sent in batches, right? I expect that's where the larger sizes come from here, not that you ever emitted a single log that totaled eg 9MB.

@snarfed

@snarfed not sure about the exact mechanics of batching in the background transport but if that's the case that would happen all the time or at least much more often. Let alone if that's the case, it's an obvious bug. If a library does batches for optimisation then it should take care of the batches size or at least make it configurable by user. So I doubt that's the case here, but I ll double check as it seems a valid suspicion. Will dig the code more tomorrow.

@snarfed

@snarfed this specific bug is about an individual LogEntry, not the entire batch: google.api_core.exceptions.InvalidArgument: 400 Log entry with size 264.0K exceeds maximum size of 256.0K [ type_url: "type.googleapis.com/google.logging.v2.WriteLogEntriesPartialErrors" value: "\nA\010\000\022=\010\003\0229Log entry with size 264.0K exceeds maximum size of 256.0K" ]

Because partial_errors is enabled, the other logs are submitted, and only the overly large one is omitted

@chrisK824 can you show an example of how you're using the library? Are you using the logging standard library integration? How often is the issue occurring? Are you seeing the issue after upgrading to a specific version? (We've only had very minor changes in this library over the last 3 months, but I don't want to rule out a change in an update completely)

@daniel-sanche

Hi @daniel-sanche , I'm indeed using the standard library integration yes. 3.11.3 version in the system that the issue was raised.

I haven't seen the issue for two days in a row now. Also I noticed that I'm already using version 3.11.2 (only a minor patch behind) in another project and this has never suffered from this issue.

Both these make me suspicious that there is indeed a big payload somewhere in the project but haven't spotted it yet. Maybe it's caused by user input..

Is there a feasible way to reveal which log line causes the error without using the sync transport and fail the actual code when this happens just to debug logging? I saw previous notes on this issue and it was mentioned that log line and file had been added (?) in the traceback but I cannot see such thing?

Thanks for your time.

@daniel-sanche

Hi @daniel-sanche , I'm indeed using the standard library integration yes.

I haven't seen the issue for two days in a row now. Also I noticed that I'm already using version 3.11.2 (only a minor patch behind) in another project and this has never suffered from this issue.

Both these make me suspicious that there is indeed a big payload somewhere in the project but haven't spotted it yet. Maybe it's caused by user input..

Is there a feasible way to reveal which log line causes the error without using the sync transport and fail the actual code when this happens just to debug logging? I saw previous notes on this issue and it was mentioned that log line and file had been added (?) in the traceback but I cannot see such thing?

Thanks for your time.

Hey @snarfed, are you by any chance using the Google cloud appengine legacy bundle services in your project? This is the only major difference I can spot between a project of mine with no such issue ever for months now (at 3.11.2) and the problematic one (even if it is a patch later at 3.11.3).

I have seen some suspicious behaviour around a middleware sitting on top of legacy bundle middleware and I will dig it more tomorrow as it seems to me that registering my custom middleware before the legacy bundle instead of after it, seems to alleviate a memory leak I'm also seeing lately. That middleware exists in both mentioned projects as well others, so it doesn't seem to be the problem.

I'm suspicious that the excessive logs are related with that middleware issue somehow - maybe a monstrous log traceback after recursive middlewares failing? No idea. But it's a way to explore as I see no other place suspicious around this library.

@chrisK824

@chrisK824 interesting! Thanks for asking. Afaik I'm not using the legacy bundled services, whether for logging or anything else. Here's how I initialize logging:

# only relevant locally afaik
logging.basicConfig()
logging.getLogger().setLevel(logging.DEBUG)

# for GCP
import google.cloud.logging
logging_client = google.cloud.logging.Client()
logging_client.setup_logging(log_level=logging.DEBUG)

...however, I double checked the failures I'm seeing now, in a few different projects, and they're now timeouts, not the size limit. Stack trace below. Maybe related to #725? Probably not related to this issue any more, I can move to a different one.

Failed to submit 1 logs.
Traceback (most recent call last):
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/grpc_helpers.py", line 76, in error_remapped_callable
    return callable_(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/grpc/_channel.py", line 1181, in __call__
    return _end_unary_response_blocking(state, call, False, None)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/grpc/_channel.py", line 1006, in _end_unary_response_blocking
    raise _InactiveRpcError(state)  # pytype: disable=not-instantiable
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "UNKNOWN:Error received from peer  {grpc_message:"Deadline Exceeded", grpc_status:4, created_time:"2024-10-10T01:13:16.9670401+00:00"}"
>
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/retry/retry_unary.py", line 144, in retry_target
    result = target()
             ^^^^^^^^
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/timeout.py", line 120, in func_with_timeout
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/grpc_helpers.py", line 78, in error_remapped_callable
    raise exceptions.from_grpc_error(exc) from exc
google.api_core.exceptions.DeadlineExceeded: 504 Deadline Exceeded
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/cloud/logging_v2/handlers/transports/background_thread.py", line 115, in _safely_commit_batch
    batch.commit()
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/cloud/logging_v2/logger.py", line 468, in commit
    client.logging_api.write_entries(
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/cloud/logging_v2/_gapic.py", line 163, in write_entries
    self._gapic_api.write_log_entries(request=request)
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/cloud/logging_v2/services/logging_service_v2/client.py", line 966, in write_log_entries
    response = rpc(
               ^^^^
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/gapic_v1/method.py", line 131, in __call__
    return wrapped_func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/retry/retry_unary.py", line 293, in retry_wrapped_func
    return retry_target(
           ^^^^^^^^^^^^^
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/retry/retry_unary.py", line 153, in retry_target
    _retry_error_helper(
  File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/retry/retry_base.py", line 221, in _retry_error_helper

@snarfed

Hey @snarfed , nah, this is a different one, known for a while now. I have opened an issue here (on mobile now so can't easily refer to it but there aren't many open).

So there is no more size errors in your projects?

OK! Yeah looks like I haven't hit the size error for a while, at least the last 30d and probably much longer.

For the large logs issue, one thing you could try is to attach a custom LogFilter to drop large logs and give you more info about where they're coming from. Here's a quick example:

import logging
import sys

class LargeLogDetector(logging.Filter):

    def __init__(self, limit_size=200_000):
        self.limit = limit_size

    def filter(self, record):
        record_size = sys.getsizeof(record.msg)
        if record_size > self.limit:
            location = f"{record.filename}:{record.lineno}"
            print(f"dropping record from: {location}")
            return None
        return record

logging.getLogger().addFilter(LargeLogDetector())
logging.error("test")
logging.error("".join(["a" for _ in range(500_000)]))

Running this gives:

ERROR:root:test
dropping record from: large-log.py:19

@daniel-sanche

Thanks @daniel-sanche will try that!

@daniel-sanche

Hey @daniel-sanche , got some news back on it. I finally have seen that again in my prod system where this filter you proposed caught it and I saw the culprit. It was indeed a user payload after all, so false alarms here, sorry for that 😇

Meanwhile, I got a question before you can close this. Does this limit apply only on regular logger when it comes to app engine services (CloudLoggingHandler?) and not when using log_struct method? The exact same payload that got caught by the filter was logged normally with log_struct in a middleware of mine logging the requests payloads.

Also I would suggest this whole thing to take a place somewhere into docs for people to have in mind.

I actually don't know all the current implementation details around log limits since I'm no longer working in this area, but hopefully the docs should have some details.

If I can speculate though: when you use structured logging through stdout, the logs are captured and passed into Cloud Logging though a Logging Agent. If you're not seeing large payload error there, it may because the agent is automatically breaking up large logs into multiple ones using LogSplits. LogSplits are one way to handle large logs, but they aren't used by default in python-logging

Navigation Menu

Repository navigation

Improve handling of "Log entry with size X exceeds maximum size" #53

6 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Improve handling of "Log entry with size X exceeds maximum size" #53

Description

Activity

tseaver commented on Dec 14, 2020

losalex commented on Sep 13, 2022

6 remaining items

chrisK824 commented on Oct 24, 2024

snarfed commented on Oct 24, 2024

chrisK824 commented on Oct 24, 2024

daniel-sanche commented on Oct 24, 2024

chrisK824 commented on Oct 27, 2024

chrisK824 commented on Oct 28, 2024

snarfed commented on Oct 28, 2024

chrisK824 commented on Oct 28, 2024

snarfed commented on Oct 28, 2024

daniel-sanche commented on Oct 28, 2024

chrisK824 commented on Oct 29, 2024

chrisK824 commented on Nov 4, 2024

daniel-sanche commented on Nov 4, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions