Fix logging #17064

gnossen · 2018-10-31T01:56:05Z

This PR addresses both #17017 and #16572. In #16378, we add calls to logging.basicConfig() in various modules, which added a handler to the root logger.

One potential solution to the problem is to by default configure each module-level logger with a NullHandler. This does two things:

avoids the pesky "No handlers could be found" message
doesn't mess with the user's own logging

Without explicit configuration of a handler for the root logger in application code, this change will result in no logging output from grpcio. To address this issue for tests, I have added a call to logging.basicConfig() in all unit tests and test utilities I could identify. It's entirely possible I've missed some places.

This reverts commit a20e207.

thelinuxfoundation · 2018-10-31T01:56:09Z

Thank you for your pull request. Before we can look at your contribution, we need to ensure all contributors are covered by a Contributor License Agreement.

After the following items are addressed, please respond with a new comment here, and the automated system will re-verify.

User @gnossen isn't covered by a CLA. They will need to complete the form at https://identity.linuxfoundation.org/projects/cncf

Regards,
CLA GitHub bot

gnossen · 2018-10-31T01:57:58Z

Agreed

srini100

Is it possible to add a test where app adds a handler and then imports grpcio. Would adding a NullHandler interfere with existing handler?

grpc-testing · 2018-10-31T18:41:50Z

Objective-C binary sizes
*****************STATIC******************
  New size                      Old size
 2,015,649      Total (=)      2,015,649

 No significant differences in binary sizes

***************FRAMEWORKS****************
  New size                      Old size
11,116,193      Total (<)     11,116,194

 No significant differences in binary sizes

gnossen · 2018-10-31T18:51:39Z

@srini100 No, I don't believe so. Handlers are added to particular loggers. So if the user configured a particular grpc module to have a handler (which I doubt would happen very often), then logging.getLogger(__name__).addHandler(logging.NullHandler) is still okay. We'll simply be adding another handler, which from the experience of the user is a no-op.

As for the additional test, sure! Sounds like a good idea.

grpc-testing · 2018-10-31T19:35:34Z

Objective-C binary sizes
*****************STATIC******************
  New size                      Old size
 2,015,649      Total (=)      2,015,649

 No significant differences in binary sizes

***************FRAMEWORKS****************
  New size                      Old size
11,116,197      Total (>)     11,116,196

 No significant differences in binary sizes

grpc-testing · 2018-11-01T00:33:47Z

Objective-C binary sizes
*****************STATIC******************
  New size                      Old size
 2,015,649      Total (=)      2,015,649

 No significant differences in binary sizes

***************FRAMEWORKS****************
  New size                      Old size
11,116,198      Total (<)     11,116,201

 No significant differences in binary sizes

grpc-testing · 2018-11-01T00:51:46Z

Objective-C binary sizes
*****************STATIC******************
  New size                      Old size
 2,015,649      Total (=)      2,015,649

 No significant differences in binary sizes

***************FRAMEWORKS****************
  New size                      Old size
11,116,194      Total (<)     11,116,195

 No significant differences in binary sizes

grpc-testing · 2018-11-01T01:06:32Z

Objective-C binary sizes
*****************STATIC******************
  New size                      Old size
 2,015,649      Total (=)      2,015,649

 No significant differences in binary sizes

***************FRAMEWORKS****************
  New size                      Old size
11,116,195      Total (>)     11,116,193

 No significant differences in binary sizes

grpc-testing · 2018-11-01T01:08:39Z

Objective-C binary sizes
*****************STATIC******************
  New size                      Old size
 2,015,649      Total (=)      2,015,649

 No significant differences in binary sizes

***************FRAMEWORKS****************
  New size                      Old size
11,116,187      Total (<)     11,116,197

 No significant differences in binary sizes

lidizheng

Looks great and discussed offline

lidizheng · 2018-11-01T20:21:07Z

src/python/grpcio_tests/tests/unit/_logging_test.py

+class LoggingTest(unittest.TestCase):
+
+    def test_logger_not_occupied(self):
+        self.assertEqual(0, len(logging.getLogger().handlers))


Discussed offline that if this test case run after the other two test cases, it will always success since the logging module is reloaded.

lidizheng · 2018-11-01T20:23:27Z

src/python/grpcio_tests/tests/unit/_logging_test.py

+            reload_module(logging)
+            reload_module(grpc)
+            self.assertFalse(
+                "No handlers could be found" in sys.stderr.getvalue())


optional: There is assertNotIn function in unit test. https://docs.python.org/2/library/unittest.html#unittest.TestCase.assertNotIn

grpc-testing · 2018-11-01T21:08:36Z

Objective-C binary sizes
*****************STATIC******************
  New size                      Old size
 2,015,578      Total (=)      2,015,578

 No significant differences in binary sizes

***************FRAMEWORKS****************
  New size                      Old size
11,116,200      Total (>)     11,116,196

 No significant differences in binary sizes

grpc-testing · 2018-11-01T21:13:57Z

Objective-C binary sizes
*****************STATIC******************
  New size                      Old size
 2,015,578      Total (=)      2,015,578

 No significant differences in binary sizes

***************FRAMEWORKS****************
  New size                      Old size
11,116,194      Total (>)     11,116,192

 No significant differences in binary sizes

grpc-testing · 2018-11-01T22:24:14Z

Objective-C binary sizes
*****************STATIC******************
  New size                      Old size
 2,015,578      Total (=)      2,015,578

 No significant differences in binary sizes

***************FRAMEWORKS****************
  New size                      Old size
11,116,195      Total (>)     11,116,187

 No significant differences in binary sizes

I was trying to get a feel for what the rest of the python ecosystem does with its logging, so I looked into the top few libraries on pypi: urllib3 maintains a logger for not quite every module, but for each one that does heavy lifting. The logger name is `__name__`, and no handlers are registered for any module-level loggers, including NullHandler. Their documentation spells out how to configure logging for the library. They explicitly configure a library root-level logger called `urllib3` to which they attach a `NullHandler`. This addresses the "no handlers could be found" problem. Their tests explicitly configure handlers, just like ours do. scrapy is more hands-on. It provides a configuration module for its logging and a whole document on how to handle logging with scrapy. It looks like log.py's whole reason for existence is making sure that a handler is attached to to the scrapy handler at startup. I think the extra complexity here is because scrapy also offers a CLI, so there has to be some way to configure logging without resorting to writing python, so I felt we didn't need to resort to this added complexity. --- Based on all of the libraries I've looked at, I think our current approach is reasonable. The one change I would make is to explicitly configure a `grpc` logger and to only attach a `NullHandler` to it instead of putting the burden on the author of each new module to configure it there. With this change, I have - Configured a logger in each module that cares about logging - Removed all NullHandlers attached to module-level loggers - Explicitly configured a `grpc` logger with a `NullHandler` attached Resolves: #16572 Related: #17064

gnossen added 6 commits October 30, 2018 17:51

Add failing unit test

ff1c31f

Revert "Configure module level loggers with basicConfig()"

1e05d48

This reverts commit a20e207.

Add NullHandler to avoid warnings about no handler

839722a

Add basicConfig handler to unit tests

240ca50

Add basicConfig handler to grpcio_testing

fb972c9

Fix various mind-numbing typos

4d086ef

srini100 added lang/Python release notes: yes Indicates if PR needs to be in release notes labels Oct 31, 2018

AspirinSJL requested a review from lidizheng October 31, 2018 17:41

AspirinSJL assigned lidizheng Oct 31, 2018

Add logging tests to tests.json

db1294d

srini100 reviewed Oct 31, 2018

View reviewed changes

Format code

a3ffca1

gnossen added 6 commits October 31, 2018 16:43

Add test for 'No handlers could be found' problem

b7335f5

Pull out function to patch stderr

79d0424

Format code

acc72c0

Fix splat

fec3765

Add explicit test that user can configure their own handler

78eae49

Appease the yapf gods

dc05e31

gnossen changed the title ~~WIP: Fix logging~~ Fix logging Nov 1, 2018

Isolate logging in all test cases

cf624a9

lidizheng requested changes Nov 1, 2018

View reviewed changes

Use custom assertions

18cc5f5

lidizheng approved these changes Nov 1, 2018

View reviewed changes

gnossen added the kokoro:force-run label Nov 1, 2018

kokoro-team removed the kokoro:force-run label Nov 1, 2018

gnossen merged commit b741454 into grpc:master Nov 1, 2018

gnossen deleted the fix-logging branch November 1, 2018 23:11

This was referenced Nov 2, 2018

grpc configures the root logger #17017

Closed

V1.16.x fix logging #17091

Merged

Adhere to logging best practices... after figuring them out #16572

Closed

lidizheng mentioned this pull request Nov 6, 2018

No handlers could be found for logger "grpc._plugin_wrapping" #16350

Closed

tseaver mentioned this pull request Nov 7, 2018

Firestore overrides logging level googleapis/google-cloud-python#6430

Closed

gnossen mentioned this pull request Nov 7, 2018

python: grpcio==1.16.0 adds a new logging handler for stderr #17135

Closed

tseaver mentioned this pull request Nov 12, 2018

Importing google.cloud.logging.Client adds StreamHandler to root googleapis/google-cloud-python#6477

Closed

lock bot locked as resolved and limited conversation to collaborators Jan 30, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix logging #17064

Fix logging #17064

gnossen commented Oct 31, 2018 •

edited

thelinuxfoundation commented Oct 31, 2018

gnossen commented Oct 31, 2018

srini100 left a comment

grpc-testing commented Oct 31, 2018

gnossen commented Oct 31, 2018

grpc-testing commented Oct 31, 2018

grpc-testing commented Nov 1, 2018

grpc-testing commented Nov 1, 2018

grpc-testing commented Nov 1, 2018

grpc-testing commented Nov 1, 2018

lidizheng left a comment

lidizheng Nov 1, 2018

lidizheng Nov 1, 2018

grpc-testing commented Nov 1, 2018

grpc-testing commented Nov 1, 2018

grpc-testing commented Nov 1, 2018

Fix logging #17064

Fix logging #17064

Conversation

gnossen commented Oct 31, 2018 • edited

thelinuxfoundation commented Oct 31, 2018

gnossen commented Oct 31, 2018

srini100 left a comment

Choose a reason for hiding this comment

grpc-testing commented Oct 31, 2018

gnossen commented Oct 31, 2018

grpc-testing commented Oct 31, 2018

grpc-testing commented Nov 1, 2018

grpc-testing commented Nov 1, 2018

grpc-testing commented Nov 1, 2018

grpc-testing commented Nov 1, 2018

lidizheng left a comment

Choose a reason for hiding this comment

lidizheng Nov 1, 2018

Choose a reason for hiding this comment

lidizheng Nov 1, 2018

Choose a reason for hiding this comment

grpc-testing commented Nov 1, 2018

grpc-testing commented Nov 1, 2018

grpc-testing commented Nov 1, 2018

gnossen commented Oct 31, 2018 •

edited