[Python] Fix `GRPC_TRACE` not working when absl log initialized in cython by sreenithi · Pull Request #41814 · grpc/grpc

sreenithi · 2026-03-06T14:31:25Z

Follow up from #39779 that added the absl::InitializeLog() call in Cython. However this set the default STDERR level to error, hence disabling any GRPC_TRACE logs.

As discussed in abseil/abseil.github.io#467, the solution is to set the StderrThreshold to INFO to enable the GRPC_TRACE logs. This PR does the same.

In addition, a new test that checks for GRPC_TRACE logs is also added.

Related issue:

gRPC Python logging "All log messages before absl::InitializeLog() is called are written to STDERR" #38703

sreenithi · 2026-03-06T14:32:14Z

/gemini-review

sergiitk · 2026-03-07T00:30:43Z

/gemini review

gemini-code-assist

Code Review

This pull request correctly fixes an issue where GRPC_TRACE logs were being suppressed after absl::InitializeLog() was introduced. The approach of setting StderrThreshold to INFO before logger initialization is sound. The addition of a test case to verify GRPC_TRACE output is a great improvement. I have one suggestion to make this new test more robust by checking for specific log messages rather than a minimum line count, which can be brittle.

sergiitk

LGTM, thank you!

This reverts commit ee0253c.

sreenithi · 2026-03-10T12:07:16Z

Just for reference, posting the output of the test added in this PR to show that it actually fails without changes in #39779.

Test output using `grpc==1.78.0` (without changes in #39779)

GRPC_TRACE logs testcase succeeds as expected
absl::Initialize warning test fails as expected

$ python tests/unit/_absl_log_test.py 
test_grpc_trace_log (__main__.AbslLogTest.test_grpc_trace_log) ... ok
test_no_absl_log_warning (__main__.AbslLogTest.test_no_absl_log_warning) ... FAIL

======================================================================
FAIL: test_no_absl_log_warning (__main__.AbslLogTest.test_no_absl_log_warning)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/local/google/home/ssreenithi/my_forks/grpc/src/python/grpcio_tests/tests/unit/_absl_log_test.py", line 54, in test_no_absl_log_warning
    self.assertFalse(absl_warning in self.output, f"absl::InitializeLog() warning unexpectedly found in output:\n{self.output}")
AssertionError: True is not false : absl::InitializeLog() warning unexpectedly found in output:
Channel created
WARNING: All log messages before absl::InitializeLog() is called are written to STDERR
I0000 00:00:1773133738.783809   53948 trace.cc:91] gRPC Tracers: api
I0000 00:00:1773133738.784107   53948 init.cc:132] grpc_init(void)
I0000 00:00:1773133738.784155   53948 completion_queue.cc:574] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
I0000 00:00:1773133738.784177   53948 completion_queue.cc:574] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
I0000 00:00:1773133738.784196   53948 channel_create.cc:249] grpc_channel_create(target=localhost:1234, creds=0x563727b7a0e0, args=0x7f50de7ba230)
I0000 00:00:1773133738.787388   53948 init.cc:132] grpc_init(void)
I0000 00:00:1773133738.787427   53948 transport_credentials.cc:33] grpc_channel_credentials_release(creds=0x563727b7a0e0)
I0000 00:00:1773133738.787569   53948 completion_queue.cc:1420] grpc_completion_queue_shutdown(cq=0x563727b4e460)
I0000 00:00:1773133738.787585   53948 completion_queue.cc:1426] grpc_completion_queue_destroy(cq=0x563727b4e460)
I0000 00:00:1773133738.787590   53948 completion_queue.cc:1420] grpc_completion_queue_shutdown(cq=0x563727b4e460)
I0000 00:00:1773133738.787595   53948 completion_queue.cc:1420] grpc_completion_queue_shutdown(cq=0x563727982b00)
I0000 00:00:1773133738.787600   53948 completion_queue.cc:1426] grpc_completion_queue_destroy(cq=0x563727982b00)
I0000 00:00:1773133738.787604   53948 completion_queue.cc:1420] grpc_completion_queue_shutdown(cq=0x563727982b00)
I0000 00:00:1773133738.787609   53948 channel.cc:95] grpc_channel_destroy(channel=0x563727b05c60)
I0000 00:00:1773133738.787620   53948 init.cc:166] grpc_shutdown(void)
I0000 00:00:1773133738.790839   53951 init.cc:166] grpc_shutdown(void)
I0000 00:00:1773133738.791195   53967 init.cc:154] grpc_shutdown_from_cleanup_thread


----------------------------------------------------------------------
Ran 2 tests in 0.447s

FAILED (failures=1)

Test output using `grpc==1.78.1` (with changes in #39779)

GRPC_TRACE logs testcase fails as expected (regression)
absl::Initialize warning test succeeds as expected

$ python tests/unit/_absl_log_test.py 
test_grpc_trace_log (__main__.AbslLogTest.test_grpc_trace_log) ... FAIL
test_no_absl_log_warning (__main__.AbslLogTest.test_no_absl_log_warning) ... ok

======================================================================
FAIL: test_grpc_trace_log (__main__.AbslLogTest.test_grpc_trace_log)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/local/google/home/ssreenithi/my_forks/grpc/src/python/grpcio_tests/tests/unit/_absl_log_test.py", line 71, in test_grpc_trace_log
    self.assertTrue(
AssertionError: False is not true : Missing expected api trace(s) ['gRPC Tracers: api', 'grpc_init(', 'grpc_channel_create(', 'grpc_channel_destroy(', 'grpc_shutdown('], in output:
Channel created


----------------------------------------------------------------------
Ran 2 tests in 0.331s

FAILED (failures=1)

Test output with changes in this PR

GRPC_TRACE logs testcase passes
absl::Initialize warning test passes

$ python tests/unit/_absl_log_test.py 
test_grpc_trace_log (__main__.AbslLogTest.test_grpc_trace_log) ... ok
test_no_absl_log_warning (__main__.AbslLogTest.test_no_absl_log_warning) ... ok

----------------------------------------------------------------------
Ran 2 tests in 0.585s

OK

sergiitk · 2026-03-10T16:11:17Z

 #
 cdef _initialize_absl():
  if not _disable_absl_init_log:
+    SetStderrThreshold(LogSeverityAtLeast.kInfo)


Todo: confirm if it should be called before or after InitializeLog()

That's a good question. I checked it and it looks like there isn't a strict guideline for it. I searched across github and found examples doing both, however calling StdErrorThreshold before InitializeLog seems to be the pattern majority of the time.

Checking further with Gemini's help, here is the rationale behind that:

Continuity: Before absl::InitializeLog() is called, the library is in a "pre-initialization" state where all log messages are directed to stderr by default, regardless of the threshold.

Avoid a Logging Gap: Once absl::InitializeLog() is called, the library starts respecting the StderrThreshold (which defaults to kError). If you call InitializeLog() first, there will be a small window of time where INFO and WARNING logs are not sent to stderr until your subsequent call to SetStderrThreshold(absl::LogSeverityAtLeast::kInfo) completes.

Correctness: Calling SetStderrThreshold() before InitializeLog() ensures that as soon as the library transitions to its initialized state, it is already configured with your desired threshold, resulting in a seamless transition.

From Point 2, I think in this particular case, it's actually fine because we have the calls happening one after another, but in future if we were to have some other code coming in between the calls, it's probably better to have the StdErrThreshold call before InitializeLog to avoid that gap.

asheshvidyut · 2026-03-11T12:32:14Z

Do we need default info or that too could be made configurable using env var?

Maybe we could honor GRPC_VERBOSITY.

sreenithi · 2026-03-11T13:00:42Z

Do we need default info or that too could be made configurable using env var?

Maybe we could honor GRPC_VERBOSITY.

Thanks, good point. I also checked this after our discussion. First of all, GRPC_VERBOSITY is actually deprecated and we only want to support GRPC_TRACE which by default uses INFO level.

Secondly, for those who continue to use GRPC_VERBOSITY, they can still continue to use it as they already are. Setting to Info level here is not overriding that value. Just verified that by running the helloworld client by setting GRPC_VERBOSITY=error and GRPC_TRACE=api. Because verbosity is error, the trace logs shouldn't show up and that's what is happening, so I think we're good:

grpc/examples/python/helloworld$ GRPC_VERBOSITY=error GRPC_TRACE=api python greeter_client.py
Will try to greet world ...
Traceback (most recent call last):
  File "/usr/local/google/home/ssreenithi/my_forks/grpc/examples/python/helloworld/greeter_client.py", line 36, in <module>
    run()
  File "/usr/local/google/home/ssreenithi/my_forks/grpc/examples/python/helloworld/greeter_client.py", line 30, in run
    response = stub.SayHello(helloworld_pb2.HelloRequest(name="you"))
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/google/home/ssreenithi/.pyenv/versions/pyvenv_312/lib/python3.12/site-packages/grpc/_channel.py", line 1159, in __call__
    return _end_unary_response_blocking(state, call, False, None)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/google/home/ssreenithi/.pyenv/versions/pyvenv_312/lib/python3.12/site-packages/grpc/_channel.py", line 990, in _end_unary_response_blocking
    raise _InactiveRpcError(state)  # pytype: disable=not-instantiable
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:50051: Failed to connect to remote host: Connection refused"
        debug_error_string = "UNKNOWN:Error received from peer  {grpc_status:14, grpc_message:"failed to connect to all addresses; last error: UNKNOWN: ipv4:127.0.0.1:50051: Failed to connect to remote host: Connection refused"}"
>

asheshvidyut · 2026-03-11T13:25:26Z

Abseil Default level is Error

https://github.com/abseil/abseil-cpp/blob/04f3bc01d12cf58c90a1bb68990f087fa3c3ed19/absl/log/globals_test.cc#L37-L39

If some other library, imports grpc, will they not get flooded with info level logs?

sergiitk · 2026-03-12T22:49:43Z

Re: #41814 (comment): discussed IRL. We compile with -fvisibility=hidden, which ensures we have our private copies of absl symbols, with their own private global variables/state.

…nt (grpc#41814) Follow up from grpc#39779 that added the absl::InitializeLog() call in Cython. However this set the default STDERR level to error, hence disabling any GRPC_TRACE logs. As discussed in abseil/abseil.github.io#467, the solution is to set the StderrThreshold to INFO to enable the GRPC_TRACE logs. This PR does the same. In addition, a new test that checks for GRPC_TRACE logs is also added. This PR also potentially fixes grpc#41696 Closes grpc#41814 COPYBARA_INTEGRATE_REVIEW=grpc#41814 from sreenithi:absl_init_log_fix_trace 0a8a9cb PiperOrigin-RevId: 881977247

fix grpc_trace and add trace test

b1f9a85

github-actions Bot added the lang/Python label Mar 6, 2026

sreenithi added release notes: no Indicates if PR should not be in release notes and removed lang/Python labels Mar 6, 2026

sreenithi mentioned this pull request Mar 6, 2026

1.78.1: Error building Python wheel due to hardcoded dependency on vendored abseil #41696

Open

sreenithi requested a review from sergiitk March 6, 2026 19:48

gemini-code-assist Bot reviewed Mar 7, 2026

View reviewed changes

Comment thread src/python/grpcio_tests/tests/unit/_grpc_trace_log_test.py Outdated

fix sanity

fd4617b

github-actions Bot added the lang/Python label Mar 9, 2026

sergiitk added release notes: yes Indicates if PR needs to be in release notes and removed release notes: no Indicates if PR should not be in release notes labels Mar 10, 2026

sergiitk reviewed Mar 10, 2026

View reviewed changes

Comment thread src/python/grpcio_tests/tests/unit/_grpc_trace_log_test.py Outdated

sergiitk reviewed Mar 10, 2026

View reviewed changes

Comment thread setup.py Outdated

sergiitk reviewed Mar 10, 2026

View reviewed changes

Comment thread src/python/grpcio_tests/tests/unit/_grpc_trace_log_test.py Outdated

sergiitk reviewed Mar 10, 2026

View reviewed changes

Comment thread src/python/grpcio_tests/tests/unit/_grpc_trace_log_test.py Outdated

sergiitk reviewed Mar 10, 2026

View reviewed changes

Comment thread src/python/grpcio/grpc/_cython/_cygrpc/absl.pyx.pxi Outdated

sergiitk approved these changes Mar 10, 2026

View reviewed changes

sreenithi added 8 commits March 10, 2026 05:21

Merge branch 'master' into absl_init_log_fix_trace

cb35466

resolve review comments

9214db7

revert setup.py changes

4ed2108

revert setup.py remaining change

ee0253c

Revert "revert setup.py remaining change"

507d561

This reverts commit ee0253c.

revert setup.py correctly

67fd992

fix tests.json renamed class

9773db2

revert unwanted file

9f8446a

grpc-checks Bot added the bloat/none label Mar 10, 2026

sanity fix

ed3d1c3

sergiitk reviewed Mar 10, 2026

View reviewed changes

sreenithi added 2 commits March 11, 2026 06:12

fix order of stderrthreshold call

8e7718c

revert change order

0a8a9cb

copybara-service Bot closed this in 3ca09e4 Mar 11, 2026

sergiitk changed the title ~~[Python] Fix GRPC_TRACE and add test to check the GRPC_TRACE logs print~~ [Python] Fix GRPC_TRACE not working when absl log initialized in cython Mar 17, 2026

Conversation

sreenithi commented Mar 6, 2026 • edited by sergiitk Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

sreenithi commented Mar 6, 2026

Uh oh!

sergiitk commented Mar 7, 2026

Uh oh!

gemini-code-assist Bot left a comment

Choose a reason for hiding this comment

Code Review

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

sergiitk left a comment

Choose a reason for hiding this comment

Uh oh!

sreenithi commented Mar 10, 2026

Test output using grpc==1.78.0 (without changes in #39779)

Test output using grpc==1.78.1 (with changes in #39779)

Test output with changes in this PR

Uh oh!

sergiitk Mar 10, 2026

Choose a reason for hiding this comment

Uh oh!

sreenithi Mar 11, 2026

Choose a reason for hiding this comment

Uh oh!

asheshvidyut commented Mar 11, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

sreenithi commented Mar 11, 2026

Uh oh!

asheshvidyut commented Mar 11, 2026

Uh oh!

sergiitk commented Mar 12, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

sreenithi commented Mar 6, 2026 •

edited by sergiitk

Loading

Test output using `grpc==1.78.0` (without changes in #39779)

Test output using `grpc==1.78.1` (with changes in #39779)

asheshvidyut commented Mar 11, 2026 •

edited

Loading