You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@drill.apache.org by Jean-Claude Cote <jc...@gmail.com> on 2018/11/03 19:17:01 UTC
logging in test cases produces two outputs
I'm using the LogFixture
LogFixtureBuilder logBuilder = LogFixture.builder()
// Log to the console for debugging convenience
.toConsole().logger("org.apache.drill.exec.store.msgpack", Level.DEBUG);
try (LogFixture logs = logBuilder.build()) {
Basice logback.xml file is
<configuration>
<root>
<level value="error" />
</root>
</configuration>
However when I do so I get two outputs. The LogFixtureBuilder seems to
install the appender twice. When I step into the logback code I saw that
the appender was found on "org.apache.drill" and on the ROOT Logger. Which
is why I get two outputs.
I'm using the API correctly?
thanks
jc
Re: logging in test cases produces two outputs
Posted by Paul Rogers <pa...@yahoo.com.INVALID>.
Hi JC,
Logback will look for logback-test.xml. If not found, it looks for logback.xml. Each search is on the class path. When Logback finds more than one, it picks one at random, then dumps warning messages about the problem.
Drill used to have an issue with an excess of logback config files. There were copies in multiple class path locations, leading to confusion. Last I checked, we had one for production (logback.xml, copied into $DRILL_HOME/conf at build time), and another for test: logback-test.xml.
When I test, I rely on the logback-test.xml file, augmented with any LogFixture setting needed for a specific ad-hoc test.
As soon as you add another file, that one may or may not take precedence over the existing one.
When you were getting three copies of output, I'd guess it is because somewhere you ended up with multiple console appenders, each configured at the Debug or Info levels.
The goal is to have two console appenders. The one defined in logback-test.xml set to ERROR, another added ad-hoc by LogFixture for one class or package, set to a lower level.
Debugging Logback setup is tedious. I think you can use the APIs shown in LogFixture to poke around and runtime to find what Logback thinks it is doing.
You mention "your personal project." I wonder, how is your code organized? Did you add it to Drill's own source tree, say under the contrib module? If so, then you should rely on logback-test.xml, plus LogFixture.
The other way to organize the code is to put it in a separate Maven project, separate from Drill, with Drill as a dependency. This works, but is not a well tested or smooth path. (Charles Givre, for example, builds his plugins this way.) Even here, you need to use the logback-test.xml because there is no way to tell Logback to use your own. This is, perhaps, an enhancement we could make to better support plugin development: exclude logback-test.xml from the exported dependencies.
Thanks,
- Paul
On Sunday, November 4, 2018, 5:19:23 AM PST, Jean-Claude Cote <jc...@gmail.com> wrote:
The problem is with the toConsole(). I've removed it and now I get only one
output (I'm logging at debug level). I've modified my logback.xml so the
console definition is in the file.
<configuration>
<appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
<!-- encoders are assigned the type
ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
<encoder>
<pattern>====> %msg%n</pattern>
</encoder>
</appender>
<root>
<level value="error" />
<appender-ref ref="Console"/>
</root>
</configuration>
Removed the .toConsole(),
LogFixtureBuilder logBuilder = LogFixture.builder()
// Log to the console for debugging convenience
.logger("org.apache.drill.exec.store.msgpack", Level.DEBUG);
try (LogFixture logs = logBuilder.build()) {
Also another issue I was having is that I was getting 3 outputs initially.
I was picking up this logback file because logback tries to load
logback-test.xml before logback.xml.
https://github.com/apache/drill/blob/7b0c9034753a8c5035fd1c0f1f84a37b376e6748/common/src/test/resources/logback-test.xml
Should I be using a logback-text.xml in my personal project or should that
common logback-test.xml be removed ?
Thanks Paul
jc
On Sat, Nov 3, 2018 at 3:39 PM Paul Rogers <pa...@yahoo.com.invalid>
wrote:
> Hi JC,
>
> Your code looks fine. I usually start with the default log level (ERROR),
> then turn on DEBUG for specific modules, as you do. I then see my INFO or
> DEBUG messages. My code looks like yours, so I'm not sure why you are
> seeing two messages. Perhaps you are logging ERROR level messages?
>
> If you look at the LogFixture code, you'll see that it works by creating a
> new console appender, then enabling only the logging you request. This
> works if the default appender logs only errors and you want to see INFO or
> DEBUG. I suppose it might cause double reporting if you log ERROR messages.
>
> All this leads to a suggestion: if you want to visualize ERROR messages,
> you have two choices. First, don't use the LogFixture since the default
> logging already does what you want. Second, perhaps modify your default
> file has to turn off console logging completely, so that only the
> LogFixture controls the console.
>
> Thanks,
> - Paul
>
>
>
> On Saturday, November 3, 2018, 12:17:28 PM PDT, Jean-Claude Cote <
> jccote@gmail.com> wrote:
>
> I'm using the LogFixture
>
> LogFixtureBuilder logBuilder = LogFixture.builder()
> // Log to the console for debugging convenience
> .toConsole().logger("org.apache.drill.exec.store.msgpack", Level.DEBUG);
> try (LogFixture logs = logBuilder.build()) {
>
>
> Basice logback.xml file is
>
> <configuration>
>
> <root>
> <level value="error" />
> </root>
>
> </configuration>
>
>
> However when I do so I get two outputs. The LogFixtureBuilder seems to
> install the appender twice. When I step into the logback code I saw that
> the appender was found on "org.apache.drill" and on the ROOT Logger. Which
> is why I get two outputs.
>
> I'm using the API correctly?
> thanks
> jc
>
Re: logging in test cases produces two outputs
Posted by Jean-Claude Cote <jc...@gmail.com>.
The problem is with the toConsole(). I've removed it and now I get only one
output (I'm logging at debug level). I've modified my logback.xml so the
console definition is in the file.
<configuration>
<appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
<!-- encoders are assigned the type
ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
<encoder>
<pattern>====> %msg%n</pattern>
</encoder>
</appender>
<root>
<level value="error" />
<appender-ref ref="Console"/>
</root>
</configuration>
Removed the .toConsole(),
LogFixtureBuilder logBuilder = LogFixture.builder()
// Log to the console for debugging convenience
.logger("org.apache.drill.exec.store.msgpack", Level.DEBUG);
try (LogFixture logs = logBuilder.build()) {
Also another issue I was having is that I was getting 3 outputs initially.
I was picking up this logback file because logback tries to load
logback-test.xml before logback.xml.
https://github.com/apache/drill/blob/7b0c9034753a8c5035fd1c0f1f84a37b376e6748/common/src/test/resources/logback-test.xml
Should I be using a logback-text.xml in my personal project or should that
common logback-test.xml be removed ?
Thanks Paul
jc
On Sat, Nov 3, 2018 at 3:39 PM Paul Rogers <pa...@yahoo.com.invalid>
wrote:
> Hi JC,
>
> Your code looks fine. I usually start with the default log level (ERROR),
> then turn on DEBUG for specific modules, as you do. I then see my INFO or
> DEBUG messages. My code looks like yours, so I'm not sure why you are
> seeing two messages. Perhaps you are logging ERROR level messages?
>
> If you look at the LogFixture code, you'll see that it works by creating a
> new console appender, then enabling only the logging you request. This
> works if the default appender logs only errors and you want to see INFO or
> DEBUG. I suppose it might cause double reporting if you log ERROR messages.
>
> All this leads to a suggestion: if you want to visualize ERROR messages,
> you have two choices. First, don't use the LogFixture since the default
> logging already does what you want. Second, perhaps modify your default
> file has to turn off console logging completely, so that only the
> LogFixture controls the console.
>
> Thanks,
> - Paul
>
>
>
> On Saturday, November 3, 2018, 12:17:28 PM PDT, Jean-Claude Cote <
> jccote@gmail.com> wrote:
>
> I'm using the LogFixture
>
> LogFixtureBuilder logBuilder = LogFixture.builder()
> // Log to the console for debugging convenience
> .toConsole().logger("org.apache.drill.exec.store.msgpack", Level.DEBUG);
> try (LogFixture logs = logBuilder.build()) {
>
>
> Basice logback.xml file is
>
> <configuration>
>
> <root>
> <level value="error" />
> </root>
>
> </configuration>
>
>
> However when I do so I get two outputs. The LogFixtureBuilder seems to
> install the appender twice. When I step into the logback code I saw that
> the appender was found on "org.apache.drill" and on the ROOT Logger. Which
> is why I get two outputs.
>
> I'm using the API correctly?
> thanks
> jc
>
Re: logging in test cases produces two outputs
Posted by Paul Rogers <pa...@yahoo.com.INVALID>.
Hi JC,
Your code looks fine. I usually start with the default log level (ERROR), then turn on DEBUG for specific modules, as you do. I then see my INFO or DEBUG messages. My code looks like yours, so I'm not sure why you are seeing two messages. Perhaps you are logging ERROR level messages?
If you look at the LogFixture code, you'll see that it works by creating a new console appender, then enabling only the logging you request. This works if the default appender logs only errors and you want to see INFO or DEBUG. I suppose it might cause double reporting if you log ERROR messages.
All this leads to a suggestion: if you want to visualize ERROR messages, you have two choices. First, don't use the LogFixture since the default logging already does what you want. Second, perhaps modify your default file has to turn off console logging completely, so that only the LogFixture controls the console.
Thanks,
- Paul
On Saturday, November 3, 2018, 12:17:28 PM PDT, Jean-Claude Cote <jc...@gmail.com> wrote:
I'm using the LogFixture
LogFixtureBuilder logBuilder = LogFixture.builder()
// Log to the console for debugging convenience
.toConsole().logger("org.apache.drill.exec.store.msgpack", Level.DEBUG);
try (LogFixture logs = logBuilder.build()) {
Basice logback.xml file is
<configuration>
<root>
<level value="error" />
</root>
</configuration>
However when I do so I get two outputs. The LogFixtureBuilder seems to
install the appender twice. When I step into the logback code I saw that
the appender was found on "org.apache.drill" and on the ROOT Logger. Which
is why I get two outputs.
I'm using the API correctly?
thanks
jc