server: Create a mocking infrastructure for logging, by delegating the log-sinks #2930

jmarantz · 2018-03-29T02:41:35Z

Signed-off-by: Joshua Marantz [email protected]

Description:
This is a fork of #2912, including only the logs mocking, and new tests for existing logging behavior in admin.

Risk Level: Low

Testing: //test/...

Docs Changes: N/A

Release Notes: N/A

…nks. Add testing in admin_test.cc that no logs get emitted, most of the time, except for one test where an unwriteable output filename is named. Signed-off-by: Joshua Marantz <[email protected]>

jmarantz · 2018-03-29T02:44:08Z

@greenway comments from #2912:

file_logger_.reset(nullptr) --> nullptr is the default value; envoy convention is to omit it as an arg at the callsite.
DelegatingLogSink() {}  --> DelegatingLogSink() = default;
inlined initialize() --> I have a minor preference for putting this in the .cc file because nearly every file has to parse this header.

Thanks for the comments, Greg. All done in this PR.

…rence to it. Signed-off-by: Joshua Marantz <[email protected]>

mattklein123

This is cool. I had one comment about setting log level/format tests that I think needs some thought. My other comment is that it took me a while to understand the various relationships between the classes and how things get set. (In particular the basic stderr init case). If you have time for more comments I think that would help, especially on how init works.

mattklein123 · 2018-03-29T04:49:45Z

test/server/http/admin_test.cc

    EXPECT_EQ(std::chrono::milliseconds(100), admin_.drainTimeout());
    admin_.tracingStats().random_sampling_.inc();
    EXPECT_TRUE(admin_.setCurrentClientCertDetails().empty());
+    Logger::Registry::setLogLevel(Logger::Logger::warn);


I commented on this in a recent @zuercher PR, but I don't think this plays well with when someone sets the log level on the CLI for a test (via --test_arg). a) it will overwrite what they set, which I guess might be OK, but b) I think it will leave it set for all tests in the same binary. Should this level be somehow stackable also such that you could potentially just set up your delegate with level and then have everything be restored? (logger/level/format)

On other option, as food for thought: I believe spdlog supports multiple sinks. If not, instead of a delegation system we could actually allow a list system, with independent formatting/level. This might be a safer way of doing this type of testing. Basically, just add the mock logger to the end of the list of already existing loggers.

Ah, good catch about the test resetting. I had glanced at test_runner.h, which resets the logging system, but now I see it only does it once for the binary, not once per testcase. I was thinking that was the hook you had mentioned to me about totally resetting all singleton state between each test. Now I'm not sure where such a between-test-global-reset is supposed to occur. I think this issue is somewhat orthogonal to mocking the logs, but I can add a similar RAII mechanism to this PR, which can restore the config mechanisms on destruction. I think this can be independent.

spdlog does support mulitple sinks in 2 ways, from my re-reading:

You can use a dist_sink, which contains a vector and exposes an add/remove of individual sinks. Note that if we use this, we'll take an extra mutex in the spdlog system on each
log or flush, beyond what we have in our code.

You can specify a list of sinks up front when you create the logger, which I don't think helps us.

I had seen the list-of-sinks-up-front option when designing this solution, but missed the dist_sink, which could be made to work.

However, I still slightly prefer the RAII solution I have here because:

I kind of think the tests shouldn't be noisy, and the mocked logging should replace the actual logging so the test output is not noisy. OTOH that makes the actual logging code path untested by code that uses it; of course it would still be tested by its own tests.

the RAII approach to stacking the mock feels right to me, and that's annoying to do with
spdylog sinks which are all shared_ptr.

If that's OK with you, then I'll work on adding some more comments.

I kind of think the tests shouldn't be noisy, and the mocked logging should replace the actual logging so the test output is not noisy. OTOH that makes the actual logging code path untested by code that uses it; of course it would still be tested by its own tests.

The issue is that sometimes you need the logging to debug the test. ;)

I agre in this trivial example it doesn't matter that much, but what about more complex examples?

In general I don't have any objection to this approach, I just want to make sure that it doesn't regress dev/test/debug flow. Thoughts?

You are right; it's better to have noisy tests than ones you can't debug, or have to do code tweaks to debug. I changed the behavior to chain to the previous delegate, renaming MockLogSink to LogRecordingSink. Functionally this addressses that issue, though you still can't mess with the delegates during threaded operation.

I added an RAII level-saving class as well and use that rather than just globally stomping on the level. PTAL

… be seen. Signed-off-by: Joshua Marantz <[email protected]>

…nary when tweaking flags. Signed-off-by: Joshua Marantz <[email protected]>

mattklein123

I like where this is going. Some more questions/comments. Would love to get thoughts from @ggreenway and @zuercher also.

mattklein123 · 2018-03-29T23:14:57Z

test/server/http/admin_test.cc

+    }
+  }
+
+  std::string log0() {


nit: instead of log0 maybe recordedLog()? Same below?

ok, commit coming.

mattklein123 · 2018-03-29T23:23:45Z

test/server/http/admin_test.cc

@@ -31,16 +34,21 @@ class AdminFilterTest : public testing::TestWithParam<Network::Address::IpVersio
 public:
  // TODO(mattklein123): Switch to mocks and do not bind to a real port.
  AdminFilterTest()
-      : admin_("/dev/null", TestEnvironment::temporaryPath("envoy.prof"),
+      : log_level_setter_(spdlog::level::warn),


I love where this going, but won't this still set all logs to warn for this test? What if I want to see debug logs while I'm debugging this test? Would I come in and change this?

Ideas:

Perhaps somehow just set log level to warn unless log level if already less than warn?

Maybe filter in the recorder somehow that I only want warn logs?

IIUC the setting here doesn't alter what the level of a generated message is. It alters the severity threshold required for the log to pass through spdlog. E.g. in the #2912 if I set the loglevel to 'error' rather than 'warn', it won't change the "mutation needs POST" message into an 'error' - that message is hard-coded to a warning, and it just won't show it, causing the test to fail.

I'll clarify in the comments in logging.h and logger.h

Sorry that's not what I meant. What I meant is that if I want to run this test and see trace/debug/info trace messages, I can't. I have to go and change this code. This is one of the issues I was originally concerned about.

I see -- you have a practice of running the test-binary with a command-line flag to override the loglevel to an even more permissive value than what I had set it to in this test, and you don't want to lose the ability to see all that when running tests manually. Got it.

Maybe the model of what I'm trying to do needs to be adjusted so I don't mess that up. You might actually want to set a lower permissiveness, or a higher permissiveness, than what's configured. And what you really want is for the LogRecorder to catch all the messages, regardless of what the loglevel is set to, and for the loglevel to affect what's printed to the screen.

Maybe I need to put the record/delegate hooks at the Logger* level rather than the spdlog::sink level, so that it's loglevel independent. WDTY?

Yup exactly. Yeah I think we need to hook things in such a way that you can record logs independently somehow from the main logger, which is why I had suggested potentially allowing for multiple sinks, or multiple loggers, or something like that. (TBH I'm not really sure what the best way of accomplishing this is.)

Also, just to be clear, I think the delegate stuff is cool and makes the file logging cleaner, but I think we shouldn't lose the ability to dynamically change log levels during debugging.

Do we need to catch all messages? It seems for most test purposes, you just need a narrow window around at most a few statements where you want to do modify the logging. See my other comment on EXPECT_LOG.

Signed-off-by: Joshua Marantz <[email protected]>

htuch

This is very cool, I think this will make testing much saner for those cases where the behavior is logging.

htuch · 2018-03-30T10:12:12Z

STYLE.md

@@ -109,6 +109,8 @@ A few general notes on our error handling philosophy:
  that there is complete test coverage for the degraded case.** Additionally, the user should be
  aware of the degraded state minimally via an error log of level warn or greater and via the
  increment of a stat.
+* If you do need to log a non-fatal warning or error, you can unit-test it by instantiating a 
+  MockLogSink from test/mocks/common.h.


Can we add some statement along the lines of "It's generally bad practice to test by depending on log messages unless the actual behavior being validated is logging. It's preferable to export statistics to enable consumption by external monitoring for any behavior that should be externally consumed or to introduce appropriate internal interfaces such as mocks for internal behavior.".

I'm somewhat worried about it becoming too easy to depend on logging in tests now that we have a great facility for it ;)

htuch · 2018-03-30T10:16:24Z

test/server/http/admin_test.cc

+    return "";
+  }
+
+  bool recordedLogContains(absl::string_view substr) {


Would it be possible to get a model similar to EXPECT_CALL, e.g. EXPECT_LOG('Some log message") with this new infra?

Excellent idea -- I think this simplifies a lot of things. Done. @mattklein123 does this address your concerns about having the command-line flags mostly work, except in the context of EXPECT_LOG_CONTAINS?

Sure it's definitely better, though I honestly still would prefer some type of forking logger that can be used during tests.

If a spdlog logger has multiple sinks, can the level be set independently on each sink? Just wondering if for test code we could install a forking logger, and then independently set the forked logger to warn and greater only, which realistically I think is all we are ever going to test?

If we think this is the best we can do I can live with it, but it still seems mildly hacky IMHO.

spdlog::logger contains the level, not the sinks, unfortunately.

But in a sink we can get the level, right? https://github.com/gabime/spdlog/blob/master/include/spdlog/details/log_msg.h#L16

I guess I'm just thinking of a solution that looks like:

Forking logger in tests.

If a test wants to test logging, it says the log level it wants to test at.

We set actual log level at logger to min<CLI, requested>

Enforce log level in the test sinks?

htuch · 2018-03-30T10:17:36Z

test/server/http/admin_test.cc

@@ -31,16 +34,21 @@ class AdminFilterTest : public testing::TestWithParam<Network::Address::IpVersio
 public:
  // TODO(mattklein123): Switch to mocks and do not bind to a real port.
  AdminFilterTest()
-      : admin_("/dev/null", TestEnvironment::temporaryPath("envoy.prof"),
+      : log_level_setter_(spdlog::level::warn),


Do we need to catch all messages? It seems for most test purposes, you just need a narrow window around at most a few statements where you want to do modify the logging. See my other comment on EXPECT_LOG.

…rides. Signed-off-by: Joshua Marantz <[email protected]>

…s/mocks to verify functionality. Signed-off-by: Joshua Marantz <[email protected]>

Signed-off-by: Joshua Marantz <[email protected]>

jmarantz · 2018-03-30T20:12:20Z

per IMs -- I think @mattklein123 is OK with temporarily changing the loglevel to 'tracing' which is what this does.

Any other comments?

mattklein123

Nice, sorry, did not fully understand the newest approach. LGTM. Will defer to @htuch to see if he has any further comments.

Signed-off-by: Joshua Marantz <[email protected]>

htuch

This is super awesome. This will make some types of testing so much better. A couple of minor comments, definitely ready to ship when they are addressed.

htuch · 2018-04-02T18:20:40Z

STYLE.md

@@ -109,6 +109,11 @@ A few general notes on our error handling philosophy:
  that there is complete test coverage for the degraded case.** Additionally, the user should be
  aware of the degraded state minimally via an error log of level warn or greater and via the
  increment of a stat.
+* If you do need to log a non-fatal warning or error, you can unit-test it with EXPECT_LOG_CONTAINS or
+  EXPECT_NO_LOGS from test/test_common/logging.h. It's generally bad practice to test by depending on


Could use a GH link here, https://blog.github.com/2013-01-31-relative-links-in-markup-files/

htuch · 2018-04-02T18:41:49Z

test/server/http/admin_test.cc

@@ -78,7 +79,9 @@ class AdminInstanceTest : public testing::TestWithParam<Network::Address::IpVers
        cpu_profile_path_(TestEnvironment::temporaryPath("envoy.prof")),
        admin_("/dev/null", cpu_profile_path_, address_out_path_,
               Network::Test::getCanonicalLoopbackAddress(GetParam()), server_,
-               listener_scope_.createScope("listener.admin.")) {
+               listener_scope_.createScope("listener.admin.")),
+        expect_no_logs_(true) {


Where is this used?

The past. It was used in the past :) Removed.

htuch · 2018-04-02T18:44:55Z

test/test_common/logging.h

+};
+
+// Validates that when stmt is executed, exactly one log message containing substr will be emitted.
+#define EXPECT_LOG_CONTAINS(substr, stmt)                                                          \


Might we want to specify what log level we're expecting the string to appear at as well, e.g. if the documented behavior is we log at "warn", then we should test at "warn" rather than trace.

OK, ptal. Not sure if this is the best way to do this, given I've hooked in after the string has been constructed.

…g check. Signed-off-by: Joshua Marantz <[email protected]>

Signed-off-by: Joshua Marantz <[email protected]>

zuercher · 2018-04-02T20:05:50Z

This looks great. Thanks.

Signed-off-by: Joshua Marantz <[email protected]>

akonradi · 2018-04-03T17:34:57Z

Uh, this adds a build rule referencing test/test_common/lua_wrappers.h but doesn't actually include the file.

jmarantz · 2018-04-03T17:37:16Z

Must be some kind of merge conflict...in fact this PR had nothing to do with Lua. I'll remove it.

Create a mocking infrastructure for logging, by delegating the log-si…

62d724a

…nks. Add testing in admin_test.cc that no logs get emitted, most of the time, except for one test where an unwriteable output filename is named. Signed-off-by: Joshua Marantz <[email protected]>

jmarantz mentioned this pull request Mar 29, 2018

server: warn on admin mutations, GET requests, add mocking of messages #2912

Closed

Re-arrange the temps so we don't drop the string while holding a refe…

b4f417f

…rence to it. Signed-off-by: Joshua Marantz <[email protected]>

mattklein123 reviewed Mar 29, 2018

View reviewed changes

alyssawilk assigned mattklein123 Mar 29, 2018

jmarantz added 2 commits March 29, 2018 16:38

Rename MockLogSink to LogRecordingSink, and have it chain so logs can…

892b4c3

… be seen. Signed-off-by: Joshua Marantz <[email protected]>

Add RAII log-level set/restore, so we don't affect the rest of the bi…

0382c7e

…nary when tweaking flags. Signed-off-by: Joshua Marantz <[email protected]>

mattklein123 reviewed Mar 29, 2018

View reviewed changes

jmarantz added 2 commits March 29, 2018 19:36

remove extraneous includes.

9b944c9

Signed-off-by: Joshua Marantz <[email protected]>

Add commentary explaining loglevel semantics.

e6dfa6b

Signed-off-by: Joshua Marantz <[email protected]>

htuch reviewed Mar 30, 2018

View reviewed changes

htuch self-assigned this Mar 30, 2018

jmarantz added 4 commits March 30, 2018 09:22

Add testing macros to bound the scope of logging mocks and level over…

3b512d9

…rides. Signed-off-by: Joshua Marantz <[email protected]>

Update style note and add commentary from htuch about preferring stat…

300f65f

…s/mocks to verify functionality. Signed-off-by: Joshua Marantz <[email protected]>

fix comment typo.

6d6d39a

Signed-off-by: Joshua Marantz <[email protected]>

Show all the logs on an EXPECT_NO_LOGS failure, not just the first one.

7de2f1f

Signed-off-by: Joshua Marantz <[email protected]>

gsagula mentioned this pull request Mar 30, 2018

xds_rate_limit: implemented xds rate-limit and alerts #2783

Merged

mattklein123 previously approved these changes Mar 30, 2018

View reviewed changes

Merge branch 'master' into delegating-log-sinks

99e0449

Signed-off-by: Joshua Marantz <[email protected]>

htuch suggested changes Apr 2, 2018

View reviewed changes

EXPECT_LOG_CONTAINS compares loglevel as well as the overall substrin…

f9dc581

…g check. Signed-off-by: Joshua Marantz <[email protected]>

jmarantz dismissed mattklein123’s stale review via f9dc581 April 2, 2018 19:20

Add comment indicating what's being parsed with the the StrSplit.

a0a5cb5

Signed-off-by: Joshua Marantz <[email protected]>

Merge branch 'master' into delegating-log-sinks

5a6a2f2

Signed-off-by: Joshua Marantz <[email protected]>

htuch approved these changes Apr 2, 2018

View reviewed changes

htuch merged commit 2a2a658 into envoyproxy:master Apr 2, 2018

jmarantz deleted the delegating-log-sinks branch April 2, 2018 22:42

jmarantz mentioned this pull request Apr 3, 2018

server: Warn in logs on admin mutations via GET. Mutations should be POSTed. #2971

Merged

server: Create a mocking infrastructure for logging, by delegating the log-sinks #2930

server: Create a mocking infrastructure for logging, by delegating the log-sinks #2930

Conversation

jmarantz commented Mar 29, 2018

jmarantz commented Mar 29, 2018 • edited Loading

mattklein123 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mattklein123 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

htuch left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jmarantz commented Mar 30, 2018

mattklein123 left a comment

Choose a reason for hiding this comment

htuch left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

zuercher commented Apr 2, 2018

akonradi commented Apr 3, 2018

jmarantz commented Apr 3, 2018

jmarantz commented Mar 29, 2018 •

edited

Loading