2

I raised an issue at my employer concerning our gigantic heaps of testing logs. I raised the issue because I was spending well over a minute to find the relevant logs and stack-trace.

I stated we should change the logging level of tests to either warning or error. Not debug or info which they currently are.

Two of my colleagues were adamant on using the debugging log level. They stated that it is possible the failure originated earlier in the code and you'd need information about that specific part of code.

I said those logs were completely irrelevant because you want to see errors when testing. Not to mention that you have a reproducible situation at the push of a button and you don't need the debug logs at all. You need debug logs in production to reproduce a situation, not for a test.

I don't want to see entire debug logs of successful tests. I want to see the logs of failing tests and errors. Personally I truly cannot fathom why you'd log entire queries during your tests when you can just check for failing tests and use a debugger locally to find the cause.

Base on the above, I would like to know what the proper logging level is for tests.

Improve this question
3
  • For testing, you could redirect all logging to a special log handler which stores the messages for the current test case. Then, after each test case, the handler checks the test result. If the test succeeded, the handler prints only warnings and errors. If the test failed, the handler prints all messages. Commented Sep 26, 2019 at 11:45
  • Why is this a fixed choice? If you're getting too much output, change the log level and run the tests again. Commented Sep 27, 2019 at 18:28
  • @RobertHarvey They're fixed because it concerns CI pipelines. The test-suites themselves run for over 9 minutes so redoing the entire pipeline for the logs is what my colleagues are worried about. Which makes no sense because we can run the failing tests again locally. Commented Sep 27, 2019 at 21:44

3 Answers 3

Reset to default
2

I don't want to see entire debug logs of successful tests. I want to see the logs of failing tests and errors.

Yup. This. Different test runners will handle this differently. But, it sounds like you're running on the CLI. So, I think ideally you'd want to see this:

test_001() : PASSED
test_002() : PASSED
...
test_028() : FAILED
  <DEBUG LEVEL LOGGING + STDOUT>

test_029() : PASSED

Or this:

test_001() : PASSED
test_002() : PASSED
...
test_028() : FAILED
test_029() : PASSED

< much later >

test_028() CAPTURED OUTPUT:
  <DEBUG LEVEL LOGGING + STDOUT>

If your colleagues are insistent on having DEBUG level logging everywhere, two things:

  • Firstly, just write yourself a quick little parser to extract logging info from only the failed tests. Unless your testing output is garbage, this is a ~30 minute task, right??? (If not, find/buy/build a better test runner.)
  • Secondly, fix your tests. Tests shouldn't depend on each other. If your colleagues want to see DEBUG logs from all tests, your tests are broken. Fix them. (1)

1. The caveat is that if your tests are broken, you need to be able to flip a switch to make your test runner print everything as DocBrown noted.

Improve this answer
2
  • All of our integration tests put together run for about 9 minutes in total. Only a few at a time will fail so lets say depending on which ones it's at most a minute of waiting time to retreive the debugging logs you need. We can enable or disable debugging logs easily and we have a stacktrace so we can kind of judge where the error is coming from without the debug logs. To me the point to keep the debugging-leve for our testing logs was nonsensical. Commented Sep 27, 2019 at 21:44
  • I've marked this as the answer due to your indication of the tests being broken if you need debug logs for successful tests. Commented Sep 27, 2019 at 21:50
3

Debug logs for successful tests are quite useless, that should be pretty obvious.

But in case a test fails, a full log may be helpful for finding the root cause of certain kinds of bugs, sometimes even more helpful than a debugger. So if your tests as default would only produce a minimal log, this leads to the question how much time and effort your team requires to reproduce a full log (ideally for one specific test case) in case they need one:

  • if reproducing a full log is just a matter of changing a config switch and running the tests locally again in less than a minute, producing always a full log is pretty nonsensical.

  • but if your team notices certain kind of failures only to happen on the build server from time to time, and for producing a full log, one has to wait two hours or more for the next server based build/test cycle, then having the log immediately at hand is probably a good idea.

So don't argue with

those logs were completely irrelevant

instead, check if you can argue with "we can produce these logs if required in a blink of an eye". If you can't, you colleagues have a point.

Improve this answer
3
  • Well I recently made sure that we could reproduce everything locally with ease. Reproduction is more along the lines of 30-40 seconds rather than 20. But it's much easier now than it used to be. Commented Sep 27, 2019 at 20:09
  • 1
    @Byebye: that is the point - you "recently made this sure". So this was not the case before. Now you just have to convince your colleagues that this new solution works fine. Commented Sep 27, 2019 at 20:13
  • I really tried to get them to see that running locally is equivalent to running on our CI server. They just kept on digging their heels in about having to see the logs in our CI jobs. Commented Sep 27, 2019 at 21:46
1

I suspect your logging framework isn't really helping you here (assuming you have one) as it shouldn't be a case of either/or.

Any logging framework worth its salt will allow you to redirect different log level to different types of output e.g. error to file and warning to screen or whatever. Even if it doesn't and everything is spooled to one huge file, it should be easy to mine the data based on tag. This will vary from framework to framework but typically we have [ERROR] for errors and [DEBUG] for debug etc.

As well as this a good framework will rollup logs based on day/file size and (optionally) compress them so there is less to look through when things go wrong.

All this aside, what you should be logged can be contentious (as you've already seen!). Some developers prefer only very high level operations to be logged while others want detailed information all of the time. The ideal is that you log everything that may be useful (a topic in itself) so you can minimise problem investigation time. However, this isn't always practical for a variety of reasons (speed, disk space, network traffic, noise etc).

Improve this answer
7
  • 2
    I understand your point. However, to me, logs are meant as a method to track what happened right before a failure. The logs then are meant for situations that are not yet reproducible. For a test this does not apply. Tests are meant to be reproducible. If it were a production situation I would happily log everything because I don't know if it might be interesting. In this case, I know which logs are interesting because I have a predefined situation. Hence my contention with the debug log-level for tests. Commented Sep 26, 2019 at 12:52
  • Ok, so you’re talking about unit test logs here? Commented Sep 26, 2019 at 12:55
  • Correct. We're creating huge amounts of testing logs in our CI pipelines. To such a degree that the webbrowser is struggling to open the raw logging files. Commented Sep 26, 2019 at 12:56
  • Ah, OK - that is a slightly different question then. Can't you track the failures in the assertions? Commented Sep 26, 2019 at 13:01
  • 1
    Also, could you please edit the question to make it clear that it is about unit tests? Other readers may not see your earlier comment - especially if this question attracts lots of answers. Commented Sep 26, 2019 at 13:04

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.