Short methods are overlapped with strange "debug info"

[wyhasany]

The short logs are overlapped in following way:

    ✔ 2.6 (748ms)0% EXECUTING [15s]
    ✔ 2.8 (776ms)0% EXECUTING [16s]

it seems like 0% EXECUTING [16s] comes from some other logger. You can override it adding additional white spaces up to 50th column. Then printed output would be clearer.

[wyhasany]

@JoseLion I can prepare a commit if you agree to overlap the end of output with extra whitespaces up to 80 columns (standard terminal width). Just let me know wdyt :)

[JoseLion]

@wyhasany sorry it took so long for me to answer, but I've been giving this a thought too. I've seen this could happen when something writes to "standard output" or "standard error", so it will also depend on the configuration of the test.testLogging closure.

I have pushed a fix so the plugin applies some default logging options to avoid some of this issue, can you give the latest version a try? However, test.testLogging can always be overridden in the project, so if you have custom configurations there, can you share them with me? 🙂

That being said, it looks like in your case the test runner itself is printing either to the lifecycle or to the "standard output". Which test framework are you using? I would like to be sure if the output is overlapping, or is just printed after the test description. Let's check that first and if there's no other option we could try the extra white spaces 😁

[wyhasany]

Hmm... It looks pretty the same with newest version:

  ✔ get  (868ms)90% EXECUTING [14s]
  ✔ get  (901ms)90% EXECUTING [17s]
<===========--> 90% EXECUTING [17s]
> :test > 6 tests completed
> :test > Executing test tech...propertyitems.PropertyItemsTest

It looks like the bar with progression left some lifecycle output which is normally overridden by the tests. Anyway I've created a PR #86 as there was an issue with configuring pretty-jupiter with build.gradle.kts. There is no issue when I call:

./gradlew test --console=plain

It seems that rich console somehow interact with logging.

[wyhasany]

Here you can find example project recreating this issue:
example-logs.zip

[wyhasany]

Here you can find related docs, but I don't see anything helpful:
https://docs.gradle.org/current/userguide/command_line_interface.html#sec:command_line_logging

[JoseLion]

@wyhasany yes, it seems like this is more related to the console output rather than the plugin's logging. I guess that's why it works correctly with --console=plain. I usually add the TERM=dumb env variable in CI environments to avoid this kind of issue.

In any case, I'll give the project you shared a try and get back to you. Maybe I find something there. 🙂

PS: Thanks for the PR for Kotlin interop 🎉

[JoseLion]

@wyhasany I tried the example you shared with me, and I think I found the issue. It seems you are using a Thread.sleep(200) in all your tests, so gradle assumes the process is idle and prints the progress to the output. If you reduce the sleep time to 50 (or less) you'll see the issue disapers (probably because Gradle has some threshold to consider a process idle).

IMO, this should not be an issue when running real tests. Even if a test is really expensive and takes an age to complete, it's not considered idle time since the thread is actually busy. 🙂

Let me know if this makes sense to you, or if you think this could still be an issue. I'm not sure if there's anything we can do from our side, but probably we can ask in https://discuss.gradle.org/ 😁

[wyhasany]

Hi! Thanks you a lot for your investigation. To be honest it's not an artificial issue as it looks like by my example 😅. Actually I see mixed logs in my integration tests. I think we can ask about it.

[wyhasany]

I've started a new topic in https://discuss.gradle.org/

[JoseLion]

@wyhasany thanks for starting the topic! I've also seen this happening while running other kinds of tasks, so I'll be checking the thread too 🙂