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

[cli] Write to stdout/stderr, allow redirection #207

Merged
merged 3 commits into from
Jun 7, 2018

Conversation

jimschubert
Copy link
Member

@jimschubert jimschubert commented Jun 3, 2018

Previously, slf4j-simple from generator core was being used. This writes
to only a single stream (STDERR) and is confusing from a CLI tooling
perspective.

This consumes logback in CLI, and excludes core's slf4j-simple
dependency. This allows us to define multiple appenders, one for STDOUT
and one for STDERR.

WARN messages and lower are written to STDOUT. ERROR is written to
STDERR.

See #186

PR checklist

  • Read the contribution guidelines.
  • Ran the shell script under ./bin/ to update Petstore sample so that CIs can verify the change. (For instance, only need to run ./bin/{LANG}-petstore.sh and ./bin/security/{LANG}-petstore.sh if updating the {LANG} (e.g. php, ruby, python, etc) code generator or {LANG} client's mustache templates). Windows batch files can be found in .\bin\windows\.
  • Filed the PR against the correct branch: Default: master.
  • Copied the technical committee to review the pull request if your PR is targeting a particular programming language.

Previously, slf4j-simple from generator core was being used. This writes
to only a single stream (STDERR) and is confusing from a CLI tooling
perspective.

This consumes logback in CLI, and excludes core's slf4j-simple
dependency. This allows us to define multiple appenders, one for STDOUT
and one for STDERR.

WARN messages and lower are written to STDOUT. ERROR is written to
STDERR.
@jimschubert
Copy link
Member Author

/cc @jmini @wing328

@wing328
Copy link
Member

wing328 commented Jun 3, 2018

@jimschubert thanks for the PR. I'll review shortly.

@wing328
Copy link
Member

wing328 commented Jun 3, 2018

I did a test with ./bin/ruby-petstore.sh and found that there are a lot more additional output than before:

User@LAPTOP-NTDC2CBM MINGW64 ~/Code/3.0/openapi-generator (jimschubert-cli-redirection)
$ ./bin/ruby-petstore.sh
# START SCRIPT: ./bin/ruby-petstore.sh
00:20:34,297 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
00:20:34,297 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
00:20:34,297 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/C:/Users/User/Code/3.0/openapi-generator/modules/openapi-generator-cli/target/openapi-generator-cli.jar!/logback.xml]
00:20:34,359 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@2a3046da - URL [jar:file:/C:/Users/User/Code/3.0/openapi-generator/modules/openapi-generator-cli/target/openapi-generator-cli.jar!/logback.xml] is not of type file
00:20:34,547 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
00:20:34,578 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
00:20:34,609 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
00:20:34,797 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - This appender no longer admits a layout as a sub-component, set an encoder instead.
00:20:34,797 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
00:20:34,797 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
00:20:34,812 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
00:20:34,812 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDERR]
00:20:34,812 |-WARN in ch.qos.logback.core.ConsoleAppender[STDERR] - This appender no longer admits a layout as a sub-component, set an encoder instead.
00:20:34,812 |-WARN in ch.qos.logback.core.ConsoleAppender[STDERR] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
00:20:34,812 |-WARN in ch.qos.logback.core.ConsoleAppender[STDERR] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
00:20:34,828 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.swagger] to DEBUG
00:20:34,828 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[io.swagger]
00:20:34,828 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDERR] to Logger[io.swagger]
00:20:34,828 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
00:20:34,828 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
00:20:34,828 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDERR] to Logger[ROOT]
00:20:34,828 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
00:20:34,828 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@2a098129 - Registering current configuration as safe fallback point

[main] DEBUG io.swagger.v3.parser.OpenAPIV3Parser - Loaded raw data: swagger: '2.0'
info:
  description: "This spec is mainly for testing Petstore server and contains fake endpoints, models. Please do not use this for any other purpose. Special characters: \" \\"
  version: 1.0.0
  title: OpenAPI Petstore
  license:

Would it be possible to change the log level to restore the previous output? We can then document which file to change to enable more output.

@jimschubert
Copy link
Member Author

@wing328 I'll look at the default levels. Previously, they were whatever the simple plugin defaulted to, not what was in logback.xml (which isn't really in use in the core package).

@jimschubert
Copy link
Member Author

@wing328 I've fixed this. The previous root logger was INFO, which wasn't ideal. The ch.qos.logback.classic.* logs occurred because we had layout rather than encoder. Layout is deprecated (https://logback.qos.ch/codes.html#layoutInsteadOfEncoder) and caused those logs.

@jmini
Copy link
Member

jmini commented Jun 4, 2018

Does it make sense to have slf4j-simple as compile scope dependency in the org.openapitools:openapi-generator ?

In my opinion the core should only depend from the slf4j api and let consumers (cli, other...) define the implementation they want to use (logback, slf4j-simple, ...).

@jimschubert
Copy link
Member Author

Should I just remove it? We can't run core on it's own, and without it we would have the noop logger.

I also think the logback.xml in the core project can be removed. It's a little presumptuous that the consumer will use logback, and if they're creating a fat jar it most likely needs to be removed anyway.

@jmini
Copy link
Member

jmini commented Jun 4, 2018

I did not look in details into it, I have the feeling that the unit tests from the core might need to have a logger. We might just need to change the scope of slf4j-simple to test.

@jimschubert
Copy link
Member Author

@jmini When you say tests "might need to have a logger" do you mean that some tests may be instantiating a logger and outputting logs rather than doing a println? I think we can just change those to println rather than pulling in an additional dependency. After all, logging isn't really a common thing to do in tests. slf4j doesn't need a binding defined in a module (it defaults to NOPLogger there no-operation logger if no binding is found on the classpath). This could improve build times a little if we remove all unnecessary dependencies.

I think later this evening, I'll remove the extra dependency and check tests for use of loggers.

@jimschubert
Copy link
Member Author

@jmini I've removed slf4j-simple from the core project completely. There was a single test which instantiated (but did not use) a logger.

This removal results in a single warning in log output as I'd expect:

Running TestSuite
objc[28394]: Class JavaLaunchHelper is implemented in both /Library/Java/JavaVirtualMachines/jdk1.8.0_151.jdk/Contents/Home/jre/bin/java (0x1060f24c0) and /Library/Java/JavaVirtualMachines/jdk1.8.0_151.jdk/Contents/Home/jre/lib/libinstrument.dylib (0x10b1c24e0). One of the two will be used. Which one is undefined.
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
Tests run: 374, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 13.911 sec - in TestSuite

This is acceptable as it doesn't pull an unnecessary artifact, and doesn't open us to the potential of having conflicting logger implementations for additional tools moving forward. I've left the exclusion of slf4j-simple in the dependency declaration in openapi-generator-cli so we'd have record of this exclusion in the master branch.

@@ -78,6 +77,12 @@
<groupId>org.openapitools</groupId>
<artifactId>openapi-generator</artifactId>
<version>${project.version}</version>
<exclusions>
<exclusion>
<groupId>org.slf4j</groupId>
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@jimschubert:

I've left the exclusion of slf4j-simple in the dependency declaration in openapi-generator-cli so we'd have record of this exclusion in the master branch.

For me this is similar to unnecessary or commented code, it will be very difficult to understand from the outside or for us in few weeks or months. I would remove those lines.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If we remove this, it can result in a transient dependency pulling in the simple binding, and a warning.

@jmini
Copy link
Member

jmini commented Jun 5, 2018

I've removed slf4j-simple from the core project completely. There was a single test which instantiated (but did not use) a logger.

I consider this change as not really user friendly.

Personally, when I run a unit test, I do not use the log output to debug or understand what is happening. But I have the feeling that other developers in this project do use logs.

The logger is used when a unit test is executed, not inside src/test/java but inside src/main/java.
I would have let a test scope for slf4j-simple because this way:

  • you do not have a logger implementation when you reuse the openapi-generator core library in an other projects (I did this yesterday and I excluded slf4j-simple because we are using logback)
  • you have one when you run the tests (inside an IDE or using maven).

But we can also do it your way: remove it completely and restore it when developers complains about not seeing the logs and some SLF4J warnings when they run unit tests.

<version>${slf4j-version}</version>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>1.0.13</version>
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there a reason why you have picked version 1.0.13 for logback-classic?

It seems to me that this is an implementation for org.slf4j:slf4j-api:1.7.5 maybe it is compatible with the version 1.7.12 that we have defined (I guess also without any good reason)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I used the version documented as the native implementation on slf4j: https://www.slf4j.org/manual.html

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This page seems outdated to me... See: https://logback.qos.ch/download.html

Or on maven central:
http://mvnrepository.com/artifact/ch.qos.logback/logback-classic

Do we want to update to:
logback-classic version 1.2.3 and slf4j to it corresponding version 1.7.25. This way we will be in sync with swagger-core.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@jmini this won't necessarily work. SLF4J's site is current.

Let me explain how slf4j works, as there seems to be some confusion.

slf4j provides an abstraction atop common logging frameworks. It does this via bindings that just need to exist in your classpath. It natively includes bindings to logback. This is why you don't have to add a binding jar, only the logback implementation. The logback usage is locked to logback 1.0.13 (see https://github.com/qos-ch/slf4j/blob/master/pom.xml) because it uses interfaces specific to that version. If you upgrade to a newer version of logback, you'd have to check if it is ABI compatible with 1.0.13. If it isn't, you can have exceptions thrown when code is JIT'd. That's obviously not ideal. It might just work with some luck, but I see no reason to chance it.

Similarly, if we don't exclude the simple logger binding explicitly, it opens us to the possibility of pulling this in as a transitive dependency. This simple logging package is the only one I've found that writes to stderr only, so allowing that to be included would result in a regression in this bug.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you a lot for the explanations... 1.0.13 seems to be the version that we need to use.

@jimschubert
Copy link
Member Author

@jmini if you run tests on this branch, you should still see a lot of logs. It seems that most of what people would use during testing is output using println. This PR doesn't clean those up, but we should do that at some point.

My assumptions with testing are that people are unit testing, and are therefore focusing on a small amount of code. If things are so complex that a contributor has to rely on log messages to understand the code flow during that test, I think it's on us to reduce that complexity rather than focus on logging as a use case for testing.

Enabling the simple logger binding for the test scope would be hiding that issue. I'm not against it, just very cautious about the reasoning.

@jmini
Copy link
Member

jmini commented Jun 5, 2018

About logger implementation in tests, I am OK with the fact that we do not provide one.

Personally I do not need it. I just consider that having one is more user friendly than having this when a unit test is executed:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

As @wing328 told, this is something we can document:

previously i put down https://github.com/OpenAPITools/openapi-generator/wiki/FAQ#how-to-debug-openapi-generator. given that the community has grown a lot in size, we can create a new page/section on how to debug openapi-generator. how to setup dev environment, how to test locally , etc

@wing328
Copy link
Member

wing328 commented Jun 6, 2018

I did anther test with ./bin/ruby-petstore.sh and the result looks good.

If no more feedback/question, I'll merge this PR tomorrow (Thur)

@wing328 wing328 added this to the 3.0.1 milestone Jun 7, 2018
@wing328 wing328 merged commit f4c66d9 into OpenAPITools:master Jun 7, 2018
jimschubert added a commit to jimschubert/openapi-generator that referenced this pull request Jun 8, 2018
* master:
  Add 'unblu inc.' to company list (OpenAPITools#246)
  put company list in alphabetical order (OpenAPITools#244)
  [jaxrs-spec] generate spec file (yaml) correctly (OpenAPITools#243)
  [C++] Adjust the names (script, sample folder, generator) to lang option (OpenAPITools#220)
  Add GMO Pepabo to company list (OpenAPITools#242)
  [Spring] Add apiFirst option (OpenAPITools#184)
  [cli] Write to stdout/stderr, allow redirection (OpenAPITools#207)
  [JAVA][Client] New object instead of null for empty POST request (OpenAPITools#98)
  Make yaml serialization deterministic (OpenAPITools#233)
  Add syntax highlighting to migration guide (OpenAPITools#237)
  Fix shippable badge (OpenAPITools#232)
  update company list (OpenAPITools#227)
  Fix OpenAPITools#210: [Ada] Update the code generator for required and optional parameters (OpenAPITools#211)
  Delete unused methods in DefaultCodegen (OpenAPITools#209)
  add note about maven plugins (OpenAPITools#216)
  add raiffeisen to company list (OpenAPITools#223)
  add a remark about homebrew installatio (OpenAPITools#217)
devplayer0 added a commit to devplayer0/openapi-generator that referenced this pull request Aug 17, 2018
It makes sense that error messages should be written to STDERR and
all others should be written to STDOUT (as shown in OpenAPITools#207). However, it
would be convenient to parse the debugging output when the relevant
flags are set.

This change will disable logging to STDOUT and redirect all log messages
to STDERR when any of the debug flags are set. (Resolves OpenAPITools#473)
jimschubert pushed a commit that referenced this pull request Aug 20, 2018
It makes sense that error messages should be written to STDERR and
all others should be written to STDOUT (as shown in #207). However, it
would be convenient to parse the debugging output when the relevant
flags are set.

This change will disable logging to STDOUT and redirect all log messages
to STDERR when any of the debug flags are set. (Resolves #473)
A-Joshi pushed a commit to ihsmarkitoss/openapi-generator that referenced this pull request Feb 27, 2019
It makes sense that error messages should be written to STDERR and
all others should be written to STDOUT (as shown in OpenAPITools#207). However, it
would be convenient to parse the debugging output when the relevant
flags are set.

This change will disable logging to STDOUT and redirect all log messages
to STDERR when any of the debug flags are set. (Resolves OpenAPITools#473)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants