loss of coverage of logging paths

[mattklein123]

One thing I noticed in looking at our current coverage report is that due to #2751 we are now missing coverage of a bunch of logging paths because we don't evaluate the log unless we are at a sufficient logging level.

This is good for performance, but it's kind of bad from a test perspective because we might now have crashing issues that we don't know about until someone turns on more verbose logging.

It's not completely clear to me how to fix this. We might need to think about how we do logging in tests. For example, maybe we always "log" at trace level but don't actually print logs unless the user has asked to see them at a certain level. This needs some thinking.

@jmarantz given your recent work on log testing, are you interested in tackling this?

cc @cpakulski

[ggreenway]

How about by default, log to a file at trace level (somewhere in the sandbox). Then it doesn't clutter stdout/stderr.

[mattklein123]

@ggreenway that's definitely an option.

[jmarantz]

I have the converse concern with a remedy to this: I would worry that if you don't test production behavior, you might grow a dependency on a side effect in a log expression that you don't notice until you go to production.

WDYT of a solution where we just do another test-run in CI with "--loglevel trace" so that we get coverage with both paths? Re-executing the testsuite without needing to recompile is going to be reasonably fast.

What I don't know is how easy it is to pipe --loglevel into all the integration tests (e.g shell tests like hotrestart's integration test).

[cpakulski]

My first reaction to this was to redefine LOG macros when running in test mode, but tests usually just link with precompiled modules, so it will not help. Looks like we have to lower severity to trace at the beginning of each test sequence (maybe based on --loglevel argument) or hijack spdlog::level method to always return "trace".

[mattklein123]

@jmarantz @cpakulski @ggreenway what if we just run logging at trace level for the coverage build only, and point the logs to somewhere on the filesystem per @ggreenway to avoid epic noise in the default test logs? I think this would make everyone happy?

Effectively as long as we don't do this on the release test build I think we make everyone happy?

[cpakulski]

Sounds good! I do not know how coverage report is created though. I assume that it operates on final binary, I mean it does not take unit tests into account. In that case the solution is great. The only thing which came to my mind is to derive a logger class from spdlog class and overwrite constructor in such way that if a specific OS env variable is defined, it will set level to trace and prohibit changing level (set_level method). Actually, we can even pretend that logger's level is trace so all parameters will be evaluated but spdlog will later on drop the message.

[jmarantz]

@cpakulski I think "--loglevel trace" can applied to the unit test binary. Will have to plumb that through to invocations of envoy-static in integration test scripts as well, perhaps based on an env var exported in the coverage script.

No spdlog overrides or any other C++ changes are required for this, AFAICT.

The coverage report is generated by running all the tests, but the report excludes test code in the coverage calculation.

[mattklein123]

I think all that is needed is to basically add --test_arg="-l trace" here: https://github.com/envoyproxy/envoy/blob/master/test/run_envoy_bazel_coverage.sh#L36.

I think there might be a bit more work to do if we want the logger to log to a file (probably /dev/null), but I think that is basically just replicating https://github.com/envoyproxy/envoy/blob/master/source/server/server.cc#L57 here: https://github.com/envoyproxy/envoy/blob/master/test/test_runner.h#L31

If someone feels like taking a crack at this, please go for it.

[jmarantz]

I was wondering how much logging would actually be there with tracing enabled...would it really be that bad for the coverage run? E.g. would it exceed circleci resources or make the file unloadable?

I don't have any objection to redirecting to a file for tests...i was just wondering how bad it would be just to set the loglevel.

[cpakulski]

@jmarantz - thank you for explaining how it works. @mattklein123 - ok, my changes caused this issue, so I will take this task.

[mattklein123]

@jmarantz @cpakulski we can definitely try just turning on trace logging on the coverage build and seeing if it works. I would give that a shot first since it's a trivial change. If we need to /dev/null the logs I think it's only a very small incremental amount of work.

[ggreenway]

Logging to /dev/null should just be one more command-line argument. Except if we support any platform that doesn't have /dev/null (like windows).

[jmarantz]

In windows you can use "NUL":
https://stackoverflow.com/questions/313111/dev-null-in-windows

[mattklein123]

Logging to /dev/null should just be one more command-line argument. Except if we support any platform that doesn't have /dev/null (like windows).

The issue is the test harness currently doesn't support that CLI arg. It would be a trivial change (see my code links above).

[cpakulski]

I am trying to find out how adding --test_arg="-l trace" to https://github.com/envoyproxy/envoy/blob/master/test/run_envoy_bazel_coverage.sh#L36 would initialize spdlog for each unit test. I see a handler for "-l" in https://github.com/envoyproxy/envoy/blob/master/source/server/options_impl.cc#L67-L69, but this is for main binary, not unit tests.

[mattklein123]

@cpakulski see the links in #3012 (comment). Specifically test_runner.h

[cpakulski]

Implemented as we discussed above. The only problem was that logger files are not opened directly, but by access_log_manager. I used MockAccessLogManager, which uses FileSystem::MockFile, which is no-op and does not really write anything into a real file. What it means is that it does not matter what is specified in --log-path option. It just needs to be present. Changes are here:master...cpakulski:issue/3012. The real AccessLogManager seems to be hard to setup as it requires few params: https://github.com/envoyproxy/envoy/blob/master/source/common/access_log/access_log_manager_impl.h#L14. What currently is implemented is dropping logs at MockFile, not at /dev/null. If dumping logs to real file is required, more work is needed.

[mattklein123]

@cpakulski looks very reasonable to me. Can you open a PR?

[cpakulski]

@mattklein123 #3065