feat: Added flushes/close functionality to logging handlers #917

gkevinzheng · 2024-07-10T19:57:57Z

For design doc see go/python-logging-background-thread

Fixes #<issue_number_goes_here> 🦕

daniel-sanche · 2024-08-05T21:35:15Z

google/cloud/logging_v2/handlers/handlers.py

+        if self.transport is None:
+            self.transport = self._transport_cls(
+                self.client, self.name, resource=self.resource
+            )


Wouldn't this mean the handler has been closed? Why not just raise an error, instead of re-creating the transport?

I based this off of some logging handlers I saw in the Python standard library, which will reopen a closed connection if that connection is closed.

Personally I think this adds extra complexity, so I'd prefer to keep them permanently closed if we can get away with that

But if you think this behavior would help us integrate with the standard library, it makes sense to keep it.

daniel-sanche · 2024-08-05T21:35:56Z

google/cloud/logging_v2/handlers/handlers.py

+    def close(self):
+        """Closes the log handler and cleans up all Transport objects used."""
+        self.transport.close()
+        self.transport = None


I don't like the idea of using transport == None as a way to check if the handler is closed. That makes the types quite a bit more complicated.

Can't we use a new flag for this?

daniel-sanche · 2024-08-05T21:45:02Z

google/cloud/logging_v2/handlers/transports/background_thread.py

+_CLOSE_THREAD_SHUTDOWN_ERROR_MSG = (
+    "CloudLoggingHandler shutting down, cannot send logs entries to Cloud Logging due to "
+    "inconsistent threading behavior at shutdown. To avoid this issue, flush the logging handler "
+    "manually or switch to StructuredLogHandler."


Maybe mention client.close or handler.close too?

daniel-sanche · 2024-08-05T21:46:37Z

google/cloud/logging_v2/handlers/transports/background_thread.py

        """Callback that attempts to send pending logs before termination."""
        if not self.is_alive:
            return

+        # Print different messages to the user depending on whether or not the
+        # program is shutting down. This is because this function now handles both
+        # the atexit handler and the regular close.


Can we decouple this? Maybe let the caller pass in a message or something?

otorreno · 2025-03-08T17:42:38Z

I am not fully sure this will solve #850 and #855. I see 2 possible scenarios:

A user calls flush on the logging client and then the program exit. That would call the _close function which would either attempt to send what is in the queue if the main thread has not terminated or it will just not send whatever is in the queue.
Even if a user would call flush and then close, nothing guarantees that between these 2 calls some message got to the queue. I think there will be similar outcomes to the previous point.

Have you considered flushing the queue at termination? Something like the following (conceptually):

Mark as shutting down (nothing else gets queued
Flush the queue
Mark as terminated

I wonder if the atexit hook should remain. I believe the main thread will be in a state where is_alive may return true, but underneath it would still error out because it can’t create new threads (this is a guess). What do you think about letting users explicitly calling the teardown/close?

snippet-bot · 2025-03-10T17:49:09Z

No region tags are edited in this PR.

This comment is generated by snippet-bot.
If you find problems with this result, please file an issue at:
https://github.com/googleapis/repo-automation-bots/issues.
To update this comment, add snippet-bot:force-run label or use the checkbox below:

Refresh this comment

See https://github.com/googleapis/repo-automation-bots/blob/main/packages/owl-bot/README.md

gkevinzheng · 2025-03-19T17:07:37Z

I am not fully sure this will solve #850 and #855. I see 2 possible scenarios:

A user calls flush on the logging client and then the program exit. That would call the _close function which would either attempt to send what is in the queue if the main thread has not terminated or it will just not send whatever is in the queue.

Even if a user would call flush and then close, nothing guarantees that between these 2 calls some message got to the queue. I think there will be similar outcomes to the previous point.

Have you considered flushing the queue at termination? Something like the following (conceptually):

Mark as shutting down (nothing else gets queued

Flush the queue

Mark as terminated

I wonder if the atexit hook should remain. I believe the main thread will be in a state where is_alive may return true, but underneath it would still error out because it can’t create new threads (this is a guess). What do you think about letting users explicitly calling the teardown/close?

Part of this PR is also adding functionality to explicitly let users call teardown/close for clients. Flushing the queue at termination is not an option because in order to send log entries over the wire to Cloud Logging, gRPC threads are needed, which we cannot create new ones at shutdown, causing the two bugs.

daniel-sanche · 2025-03-21T18:50:44Z

google/cloud/logging_v2/handlers/handlers.py

        self.transport = transport(client, name, resource=resource)
+        self.transport_open = True


Can this be made private?

See https://github.com/googleapis/repo-automation-bots/blob/main/packages/owl-bot/README.md

…pened There was a recent release (3.12.0) that included the changes introduced in googleapis#917. The newly introduced close method seems to be called by AppEngine Python runtime at shutdown, so if you would call it explicitly before the runtime does it, then the close function throws an exception because transport is None.

…pened (#990) There was a recent release (3.12.0) that included the changes introduced in #917. The newly introduced close method seems to be called by AppEngine Python runtime at shutdown, so if you would call it explicitly before the runtime does it, then the close function throws an exception because transport is None.

product-auto-label bot added size: l Pull request size is large. api: logging Issues related to the googleapis/python-logging API. labels Jul 10, 2024

gkevinzheng added the kokoro:force-run Add this label to force Kokoro to re-run the tests. label Aug 2, 2024

yoshi-kokoro removed the kokoro:force-run Add this label to force Kokoro to re-run the tests. label Aug 2, 2024

gkevinzheng marked this pull request as ready for review August 2, 2024 18:39

gkevinzheng requested review from a team as code owners August 2, 2024 18:39

gkevinzheng requested review from cindy-peng and removed request for a team August 2, 2024 18:39

daniel-sanche reviewed Aug 5, 2024

View reviewed changes

product-auto-label bot added the stale: old Pull request is old and needs attention. label Aug 10, 2024

product-auto-label bot added stale: extraold Pull request is critically old and needs prioritization. and removed stale: old Pull request is old and needs attention. labels Sep 9, 2024

gkevinzheng mentioned this pull request Mar 7, 2025

fix: make atexit registration conditional on background transport #978

Closed

gkevinzheng changed the base branch from experimental-v4 to main March 10, 2025 17:19

blunderbuss-gcf bot assigned danieljbruce Mar 10, 2025

gkevinzheng changed the base branch from main to experimental-v4 March 10, 2025 17:20

gkevinzheng added 5 commits March 10, 2025 17:48

feat: Added flushes/close functionality to logging handlers

9f85e57

Fixed unit test issues.

d725eff

linting

9ee7bae

more linting

ae3ece3

Addressed code review feedback

b46779e

gkevinzheng force-pushed the cloud-logging-handler-flush branch from db3be06 to b46779e Compare March 10, 2025 17:49

gkevinzheng requested a review from a team as a code owner March 10, 2025 17:49

gkevinzheng requested review from parthea and removed request for a team March 10, 2025 17:49

product-auto-label bot removed the size: l Pull request size is large. label Mar 10, 2025

product-auto-label bot added the size: xl Pull request size is extra large. label Mar 10, 2025

gkevinzheng changed the base branch from experimental-v4 to main March 10, 2025 17:49

danieljbruce assigned daniel-sanche and unassigned danieljbruce Mar 10, 2025

Refactored _close

1b037b6

product-auto-label bot added size: l Pull request size is large. and removed size: xl Pull request size is extra large. labels Mar 13, 2025

🦉 Updates from OwlBot post-processor

c1d1f3f

See https://github.com/googleapis/repo-automation-bots/blob/main/packages/owl-bot/README.md

daniel-sanche requested changes Mar 21, 2025

View reviewed changes

gkevinzheng and others added 3 commits March 31, 2025 18:13

Added system tests

da74511

make transport_open private

cc32e9b

🦉 Updates from OwlBot post-processor

72a8ff6

See https://github.com/googleapis/repo-automation-bots/blob/main/packages/owl-bot/README.md

daniel-sanche approved these changes Mar 31, 2025

View reviewed changes

Merge branch 'main' into cloud-logging-handler-flush

e04a188

gkevinzheng enabled auto-merge (squash) March 31, 2025 20:57

gkevinzheng merged commit d179304 into main Mar 31, 2025
15 checks passed

gkevinzheng deleted the cloud-logging-handler-flush branch March 31, 2025 21:23

release-please bot mentioned this pull request Mar 31, 2025

chore(main): release 3.12.0 #973

Merged

release-please bot mentioned this pull request Apr 16, 2025

chore(main): release 3.12.0 #986

Closed

This was referenced Apr 21, 2025

2 consecutive calls to CloudLoggingHandler.close throws an exception #989

Closed

fix: make logging handler close conditional to having the transport opened #990

Merged

gkevinzheng mentioned this pull request Apr 25, 2025

rpc errors only on Python 3.12 #855

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

feat: Added flushes/close functionality to logging handlers #917

feat: Added flushes/close functionality to logging handlers #917

Uh oh!

gkevinzheng commented Jul 10, 2024

Uh oh!

daniel-sanche Aug 5, 2024

Uh oh!

gkevinzheng Aug 8, 2024

Uh oh!

daniel-sanche Aug 9, 2024

Uh oh!

daniel-sanche Aug 5, 2024

Uh oh!

daniel-sanche Aug 5, 2024

Uh oh!

daniel-sanche Aug 5, 2024

Uh oh!

otorreno commented Mar 8, 2025

Uh oh!

snippet-bot bot commented Mar 10, 2025 •

edited

Loading

Uh oh!

gkevinzheng commented Mar 19, 2025

Uh oh!

daniel-sanche Mar 21, 2025

Uh oh!

gkevinzheng Mar 31, 2025

Uh oh!

Uh oh!

Uh oh!

		self.transport = transport(client, name, resource=resource)
		self.transport_open = True

feat: Added flushes/close functionality to logging handlers #917

feat: Added flushes/close functionality to logging handlers #917

Uh oh!

Conversation

gkevinzheng commented Jul 10, 2024

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

otorreno commented Mar 8, 2025

Uh oh!

snippet-bot bot commented Mar 10, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

No region tags are edited in this PR.

Uh oh!

gkevinzheng commented Mar 19, 2025

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

snippet-bot bot commented Mar 10, 2025 •

edited

Loading