Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Default scenario logging does not show up in step notifications #2563

Closed
IgnasCi opened this issue Jun 6, 2022 · 4 comments Β· Fixed by #2573
Closed

Default scenario logging does not show up in step notifications #2563

IgnasCi opened this issue Jun 6, 2022 · 4 comments Β· Fixed by #2573
Labels
πŸ› bug Defect / Bug πŸ™ help wanted Help wanted - not prioritized by core team

Comments

@IgnasCi
Copy link

IgnasCi commented Jun 6, 2022

πŸ‘“ What did you see?

Scenario logs (scenario.log()) does not show up in step notifications. This started happening since 7.3.3 version.

βœ… What did you expect to see?

Logs should be shown in step notifications.

πŸ“¦ Which tool/library version are you using?

Maven project
Intellij 2022.1

πŸ”¬ How could we reproduce it?

Steps to reproduce the behavior:

  1. Clone project from https://github.com/IgnasCi/cucumberIssue.
  2. Try to run test runner (TestRunner.class)
  3. Check step notification (lest logging *), logs are not shown.
  4. Replace cucumber-java version to 7.3.2 in pom.xml, refresh maven project.
  5. Rerun project
  6. Select any step notification (test logging *) in console to check if logs are shown.

πŸ“š Any additional context?

7.3.2 7.3.4
image image

This text was originally generated from a template, then edited by hand. You can modify the template here.

@aslakhellesoy
Copy link
Contributor

aslakhellesoy commented Jun 6, 2022

Logs should be shown in step definitions.

I'm not sure I understand what you mean. A step definition is a Java method. What do you mean when you say logs should be shown in step definitions?

Do you mean they should be printed to STDOUT?

@aslakhellesoy
Copy link
Contributor

If it's about logs not being printed to STDOUT, it could be a regression introduced in #2541 where there were some changes about how output is flushed.

@IgnasCi IgnasCi changed the title Default scenario logging does not show up in step deffinitions Default scenario logging does not show up in step notifications Jun 6, 2022
@IgnasCi
Copy link
Author

IgnasCi commented Jun 6, 2022

Ah, sorry, I meant step notifications.... (check screenshots).

Do you mean they should be printed to STDOUT?

Partly yes - If i click on step notification (7.3.4), there are no logs flushed to STDOUT. However, at the same time if i click on scenario notification level, all logs in STDOUT are visible. 7.3.2 / or below - all good for both cases. So the problem is related only with step notifications feature, which is enabled via:

CucumberOptions -> stepNotifications = true.

image

@mpkorstanje
Copy link
Contributor

mpkorstanje commented Jun 7, 2022

The problem isn't a lack of flushing, the problem is too much buffering.

public PrettyFormatter(OutputStream out) {
this.out = new NiceAppendable(new UTF8OutputStreamWriter(out));
}

The UTF8OutputStreamWriter is a Writer which has a default buffer of 1KiB. If less then 1KiB is written, nothing is flushed until the end of the test execution when the stream is closed. When writing to System.out this buffer isn't necessary.

This buffer could be eliminated by adding support for a PrintStream argument in the PluginFactory. Plugins that were specified without an argument would receive System.out directly. For plugins that did specify an argument a PrintWriter with UTF-8 encoding would have to be created.

Once supported the PrettyFormatter could be declared as:

    public PrettyFormatter(PrintStream out) {
        this.out = new NiceAppendable(out);
    }

However note:

private PrintStream defaultOut = new PrintStream(System.out) {
@Override
public void close() {
// We have no intention to close System.out
}
};

To prevent closing System.out it is wrapped with a decorator. This adds another buffer to the chain. This would also have to be eliminated as well. Presumably by properly delegating all methods except .close() to System.out.

@mpkorstanje mpkorstanje added πŸ™ help wanted Help wanted - not prioritized by core team πŸ› bug Defect / Bug labels Jun 7, 2022
mpkorstanje added a commit that referenced this issue Jun 21, 2022
For the sake of efficiency and performance we write to buffered writers.
However, the pretty plugin is expected to print scenarios as they're started
and steps as they're finished.

This was initially resolved by flushing the `NiceAppendable` on every write.
This turned out to have performance impact (#2481) and interact poorly with
tools that expected (#2536) us to be better behaved.

By having `NiceAppendable` flush only when the underlying buffer was full these
problems were resolved (#2541) . However, because the underlying buffer is 8KiB
the pretty formatters output would effectively sit in a buffer until the writer
was closed.

So now we flush the pretty and progress output manually after each event. This
strikes a balance somewhere between the flush-everything-all-the-time and
flush-when-full approaches.

Fixes: #2563
mpkorstanje added a commit that referenced this issue Jun 21, 2022
For the sake of efficiency and performance we write to buffered writers.
However, the pretty plugin is expected to print scenarios as they're started
and steps as they're finished.

This was initially resolved by flushing the `NiceAppendable` on every write.
This turned out to have performance impact (#2481) and interact poorly with
tools that expected (#2536) us to be better behaved.

By having `NiceAppendable` flush only when the underlying buffer was full these
problems were resolved (#2541) . However, because the underlying buffer is 8KiB
the pretty formatters output would effectively sit in a buffer until the writer
was closed.

So now we flush the pretty and progress output manually after each event. This
strikes a balance somewhere between the flush-everything-all-the-time and
flush-when-full approaches.

Fixes: #2563
mpkorstanje added a commit that referenced this issue Jun 21, 2022
For the sake of efficiency and performance we write to buffered writers.
However, the pretty plugin is expected to print scenarios as they're started
and steps as they're finished.

This was initially resolved by flushing the `NiceAppendable` on every write.
This turned out to have performance impact (#2481) and interact poorly with
tools that expected (#2536) us to be better behaved.

By having `NiceAppendable` flush only when the underlying buffer was full these
problems were resolved (#2541) . However, because the underlying buffer is 8KiB
the pretty formatters output would effectively sit in a buffer until the writer
was closed.

So now we flush the pretty and progress output manually after each event. This
strikes a balance somewhere between the flush-everything-all-the-time and
flush-when-full approaches.

Fixes: #2563
mpkorstanje added a commit that referenced this issue Jun 21, 2022
For the sake of efficiency and performance we write to buffered writers.
However, the pretty plugin is expected to print scenarios as they're started
and steps as they're finished.

This was initially resolved by flushing the `NiceAppendable` on every write.
This turned out to have performance impact (#2481) and interact poorly with
tools that expected (#2536) us to be better behaved.

By having `NiceAppendable` flush only when the underlying buffer was full these
problems were resolved (#2541) . However, because the underlying buffer is 8KiB
the pretty formatters output would effectively sit in a buffer until the writer
was closed.

So now we flush the pretty and progress output manually after each event. This
strikes a balance somewhere between the flush-everything-all-the-time and
flush-when-full approaches.

Fixes: #2563
mpkorstanje added a commit that referenced this issue Jun 21, 2022
For the sake of efficiency and performance we write to buffered writers.
However, the pretty plugin is expected to print scenarios as they're started
and steps as they're finished.

This was initially resolved by flushing the `NiceAppendable` on every write.
This turned out to have performance impact (#2481) and interact poorly with
tools that expected (#2536) us to be better behaved.

By having `NiceAppendable` flush only when the underlying buffer was full these
problems were resolved (#2541) . However, because the underlying buffer is 8KiB
the pretty formatters output would effectively sit in a buffer until the writer
was closed.

So now we flush the pretty and progress output manually after each event. This
strikes a balance somewhere between the flush-everything-all-the-time and
flush-when-full approaches.

Fixes: #2563
mpkorstanje added a commit that referenced this issue Jun 21, 2022
For the sake of efficiency and performance we write to buffered writers.
However, the pretty plugin is expected to print scenarios as they're started
and steps as they're finished.

This was initially resolved by flushing the `NiceAppendable` on every write.
This turned out to have performance impact (#2481) and interact poorly with
tools that expected (#2536) us to be better behaved.

By having `NiceAppendable` flush only when the underlying buffer was full these
problems were resolved (#2541) . However, because the underlying buffer is 8KiB
the pretty formatters output would effectively sit in a buffer until the writer
was closed.

So now we flush the pretty and progress output manually after each event. This
strikes a balance somewhere between the flush-everything-all-the-time and
flush-when-full approaches.

Fixes: #2563
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
πŸ› bug Defect / Bug πŸ™ help wanted Help wanted - not prioritized by core team
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants