Failed response.json() call in _helpers.response_log() causes response object's state to change

[anarkiwi]

Hello,

In v2.40, new helpers were introduced that can log various requests and responses.

One such helper, response_log() tries to jsonify a response instance (https://github.com/googleapis/google-auth-library-python/blob/56b4d3b3bfd6f935411130c8828cdeea90aa69f1/google/auth/_helpers.py#L477) and use the result to log.

The issue with this is it causes the response instance state to change. Called via https://github.com/psf/requests/blob/c65c780849563c891f35ffc98d3198b71011c012/src/requests/models.py#L965, we can retrieve content which causes _content_consumed to change to True, even though the JSON decode failed.

This means it isn't safe to call json() on the response and keep the response unchanged. I can see the argument that this is a bug in requests, but for the moment there is now a subtle side effect introduced just by attempting logging - the implicit assumption is response won't change. I can imagine a less than ideal option would be to copy the response before trying to json()?

[ohmayr]

@anarkiwi Copying the response for logging purposes isn't resource efficient. If a response.json() call results in a JSONDecodeError, any subsequent calls will also produce the same error. The same is the case for a success call where the cached content is returned for any subsequent calls.

[anarkiwi]

Totally agree there, my point is attempting to call .json() at all causes the response instance to change state (the logging action has side effects). The implicit assumption is calling .json() has no side effects.

[ohmayr]

@anarkiwi I see what you mean. The state of the response does change once we read the response. Can you provide some sample code which breaks the end user?

[anarkiwi]

@anarkiwi I see what you mean. The state of the response does change once we read the response. Can you provide some sample code which breaks the end user?

I'm working on that (I have a breakage in a non public codebase). In summary the changed response object causes google-cloud-storage to attempt gzip transcoding which in turn breaks due to a hash mismatch error. Removing the call to the json logger fixes the problem. I'll try to reproduce it with entirely open source code.

[ohmayr]

There's already a known issue where reading the response early on results in streaming API calls to fail. googleapis/google-auth-library-python#1761 addresses this issue by removing the call to response log for API calls.

However, we're still logging response logs for other requests (e.g. fetching credentials). https://github.com/googleapis/google-auth-library-python/blob/56b4d3b3bfd6f935411130c8828cdeea90aa69f1/google/auth/transport/requests.py#L190.

I'm assuming the issue that you're experiencing should be fixed once we release v2.40.2. Feel free to test against a development version (i.e. the linked PR) or wait until we release v2.40.2 and let me know if you still see an issue with the storage library.

[ohmayr]

@anarkiwi can you confirm if you're still experiencing the issue with the latest release of google-auth i.e. https://github.com/googleapis/google-auth-library-python/releases/tag/v2.40.2?

[parthea]

Transferring to google-cloud-python as the code for google-auth-library-python will be migrated there in 1-3 weeks.