(DEPRECATED) Apache Flink User Mailing List archive.

Flink logging issue with logback

Classic

List

Threaded

11 messages Options

Bajaj, Abhinav

Flink logging issue with logback

Hi,

I am investigating a logging issue with Flink.

Setup

Using Flink-1.7.1 using logback as suggested in Flink documentation here.
Submitting the Flink job from the Flink dashboard.

Observations

Logs from main method(outside of job graph) do not show up in jobmanager logs.
Logs from the operators like map or custom operators do show up in the taskmanager logs.
Logs from main method do show up in jobmanager logs when using log4j in place of logback.

Has anyone else noticed similar behavior or is this a known issue with logback integration in Flink?

Any suggestions on potential workaround or fix?

Appreciate your time and help.

~ Abhinav Bajaj

Yang Wang

Re: Flink logging issue with logback

Hi Bajaj, Abhinav,

Could you share the start-command of jobmanager and taskmanager. If it is started correctly, we

will have a the following jvm options.

-Dlog.file=/path/of/taskmanager.log -Dlogback.configurationFile=file:///path/of/logback.xml

Best,

Yang

Bajaj, Abhinav <[hidden email]> 于2020年1月4日周六上午7:23写道：

Hi,

I am investigating a logging issue with Flink.

Setup

Using Flink-1.7.1 using logback as suggested in Flink documentation here.
Submitting the Flink job from the Flink dashboard.

Observations

Logs from main method(outside of job graph) do not show up in jobmanager logs.
Logs from the operators like map or custom operators do show up in the taskmanager logs.
Logs from main method do show up in jobmanager logs when using log4j in place of logback.

Has anyone else noticed similar behavior or is this a known issue with logback integration in Flink?

Any suggestions on potential workaround or fix?

Appreciate your time and help.

~ Abhinav Bajaj

vino yang

Re: Flink logging issue with logback

Hi Bajaj,

>> Logs from main method(outside of job graph) do not show up in jobmanager logs.

IMO, it's normal phenomena.

Other ideas, please check the JVM options mentioned by Yang.

Best,

Vino

Yang Wang <[hidden email]> 于2020年1月6日周一上午11:18写道：

Hi Bajaj, Abhinav,

Could you share the start-command of jobmanager and taskmanager. If it is started correctly, we
will have a the following jvm options.

-Dlog.file=/path/of/taskmanager.log -Dlogback.configurationFile=file:///path/of/logback.xml

Best,
Yang

Bajaj, Abhinav <[hidden email]> 于2020年1月4日周六上午7:23写道：

Hi,

I am investigating a logging issue with Flink.

Setup

Using Flink-1.7.1 using logback as suggested in Flink documentation here.
Submitting the Flink job from the Flink dashboard.

Observations

Logs from main method(outside of job graph) do not show up in jobmanager logs.
Logs from the operators like map or custom operators do show up in the taskmanager logs.
Logs from main method do show up in jobmanager logs when using log4j in place of logback.

Has anyone else noticed similar behavior or is this a known issue with logback integration in Flink?

Any suggestions on potential workaround or fix?

Appreciate your time and help.

~ Abhinav Bajaj

Dawid Wysakowicz-2

Re: Flink logging issue with logback

Hi Bajaj,

I am not entirely sure what is the actual issue you are seeking help, but let me comment on your observations.

Ad. 1

If you log to the console from the main method this is an expected behavior in both cases (log4j, logback). The std out is being overwritten for the execution of the main method

If you log to a file logs should work in both cases. I checked that myself and actually the logs appeared in the jobmanager logs as long as they are executed before the env.execute(). I observed though weird behavior of the Web UI, as it does not always update the logs that are displayed. How did you check the logs? If you checked through the Web UI could you try to check the file directly?

Ad. 2 Yes this is expected. Operators are executed on taskmanager and that's why they log there.

Ad. 3 See Ad. 1

Best,

Dawid

On 06/01/2020 07:07, vino yang wrote:

Hi Bajaj,

>> Logs from main method(outside of job graph) do not show up in jobmanager logs.

IMO, it's normal phenomena.

Other ideas, please check the JVM options mentioned by Yang.

Best,

Vino

Yang Wang <[hidden email]> 于2020年1月6日周一上午11:18写道：

Hi Bajaj, Abhinav,

Could you share the start-command of jobmanager and taskmanager. If it is started correctly, we

will have a the following jvm options.

-Dlog.file=/path/of/taskmanager.log -Dlogback.configurationFile=file:///path/of/logback.xml

Best,

Yang

Bajaj, Abhinav <[hidden email]> 于2020年1月4日周六上午7:23写道：

Hi,

I am investigating a logging issue with Flink.

Setup

Using Flink-1.7.1 using logback as suggested in Flink documentation here.

Submitting the Flink job from the Flink dashboard.

Observations

Logs from main method(outside of job graph) do not show up in jobmanager logs.

Logs from the operators like map or custom operators do show up in the taskmanager logs.

Logs from main method do show up in jobmanager logs when using log4j in place of logback.

Has anyone else noticed similar behavior or is this a known issue with logback integration in Flink?

Any suggestions on potential workaround or fix?

Appreciate your time and help.

~ Abhinav Bajaj

signature.asc (849 bytes) Download Attachment

Bajaj, Abhinav

Re: Flink logging issue with logback

Hi,

Thanks much for the responses.

Let me add some more details and clarify my question.

Setup

I used the WikipediaAnalysis example and added a log in main method.

……

public static void main(String[] args) throws Exception {
StreamExecutionEnvironment see = StreamExecutionEnvironment.getExecutionEnvironment();
LOG.info("Info log for test");

DataStream<WikipediaEditEvent> edits = see.addSource(new WikipediaEditsSource());

……

I am using the Flink 1.7.1 distribution and starting jobmanager and taskmanager locally using the below commands –

./bin/jobmanager.sh start-foreground
./bin/taskmanager.sh start-foreground
Both jobmanager and taskmanager log in the console now
JVM options are correctly set and verified from jobmanager & taskmanager logs

I submit the WikipediaAnalysis job from Flink dashboard and checked the jobmanager logs

Run 1: Flink is using the default log4j logging

Jobmanager logs the added info log from the job

2020-01-06 11:55:37,422 INFO wikiedits.WikipediaAnalysis - Info log for test

Run 2: Flink is setup to use logback as suggested in Flink documentation here

Jobmanger does not log the added info log from the job

So, it seems there is a logging behavior difference between using log4j & logback in Flink.

Is this expected or a known difference?

Thanks again,

Abhinav Bajaj

PS: Ahh. I see how my email was confusing the first time. Hopefully this one is better :P

From: Dawid Wysakowicz <[hidden email]>
Date: Monday, January 6, 2020 at 5:13 AM
Cc: "Bajaj, Abhinav" <[hidden email]>, "[hidden email]" <[hidden email]>
Subject: Re: Flink logging issue with logback

Hi Bajaj,

I am not entirely sure what is the actual issue you are seeking help, but let me comment on your observations.

Ad. 1

If you log to the console from the main method this is an expected behavior in both cases (log4j, logback). The std out is being overwritten for the execution of the main method

Ad. 2 Yes this is expected. Operators are executed on taskmanager and that's why they log there.

Ad. 3 See Ad. 1

Best,

Dawid

On 06/01/2020 07:07, vino yang wrote:

Hi Bajaj,

>> Logs from main method(outside of job graph) do not show up in jobmanager logs.

IMO, it's normal phenomena.

Other ideas, please check the JVM options mentioned by Yang.

Best,

Vino

Yang Wang <[hidden email]> 于2020年1月6日周一上午11:18写道：

Hi Bajaj, Abhinav,

Could you share the start-command of jobmanager and taskmanager. If it is started correctly, we

will have a the following jvm options.

-Dlog.file=/path/of/taskmanager.log -Dlogback.configurationFile=file:///path/of/logback.xml

Best,

Yang

Bajaj, Abhinav <[hidden email]> 于2020年1月4日周六上午7:23写道：

Hi,

I am investigating a logging issue with Flink.

Setup

Using Flink-1.7.1 using logback as suggested in Flink documentation here.
Submitting the Flink job from the Flink dashboard.

Observations

Logs from main method(outside of job graph) do not show up in jobmanager logs.
Logs from the operators like map or custom operators do show up in the taskmanager logs.
Logs from main method do show up in jobmanager logs when using log4j in place of logback.

Has anyone else noticed similar behavior or is this a known issue with logback integration in Flink?

Any suggestions on potential workaround or fix?

Appreciate your time and help.

~ Abhinav Bajaj

Yang Wang

Re: Flink logging issue with logback

Hi Bajaj,

I have tested just as you say, and find that the logs in the user class could not show up when

using ConsoleAppender. If using FileAppender instead, everything goes well.

It is so weird and i have no idea how to debug it.

Best,

Yang

Bajaj, Abhinav <[hidden email]> 于2020年1月7日周二上午4:28写道：

Hi,

Thanks much for the responses.

Let me add some more details and clarify my question.

Setup

I used the WikipediaAnalysis example and added a log in main method.

……

public static void main(String[] args) throws Exception {
StreamExecutionEnvironment see = StreamExecutionEnvironment.getExecutionEnvironment();
LOG.info("Info log for test");

DataStream<WikipediaEditEvent> edits = see.addSource(new WikipediaEditsSource());

……

I am using the Flink 1.7.1 distribution and starting jobmanager and taskmanager locally using the below commands –

./bin/jobmanager.sh start-foreground
./bin/taskmanager.sh start-foreground
Both jobmanager and taskmanager log in the console now
JVM options are correctly set and verified from jobmanager & taskmanager logs

I submit the WikipediaAnalysis job from Flink dashboard and checked the jobmanager logs

Run 1: Flink is using the default log4j logging

Jobmanager logs the added info log from the job

2020-01-06 11:55:37,422 INFO wikiedits.WikipediaAnalysis - Info log for test

Run 2: Flink is setup to use logback as suggested in Flink documentation here

Jobmanger does not log the added info log from the job

So, it seems there is a logging behavior difference between using log4j & logback in Flink.

Is this expected or a known difference?

Thanks again,

Abhinav Bajaj

PS: Ahh. I see how my email was confusing the first time. Hopefully this one is better :P

From: Dawid Wysakowicz <[hidden email]>
Date: Monday, January 6, 2020 at 5:13 AM
Cc: "Bajaj, Abhinav" <[hidden email]>, "[hidden email]" <[hidden email]>
Subject: Re: Flink logging issue with logback

Hi Bajaj,

I am not entirely sure what is the actual issue you are seeking help, but let me comment on your observations.

Ad. 1

If you log to the console from the main method this is an expected behavior in both cases (log4j, logback). The std out is being overwritten for the execution of the main method

If you log to a file logs should work in both cases. I checked that myself and actually the logs appeared in the jobmanager logs as long as they are executed before the env.execute(). I observed though weird behavior of the Web UI, as it does not always update the logs that are displayed. How did you check the logs? If you checked through the Web UI could you try to check the file directly?

Ad. 2 Yes this is expected. Operators are executed on taskmanager and that's why they log there.

Ad. 3 See Ad. 1

Best,

Dawid

On 06/01/2020 07:07, vino yang wrote:

Hi Bajaj,

>> Logs from main method(outside of job graph) do not show up in jobmanager logs.

IMO, it's normal phenomena.

Other ideas, please check the JVM options mentioned by Yang.

Best,

Vino

Yang Wang <[hidden email]> 于2020年1月6日周一上午11:18写道：

Hi Bajaj, Abhinav,

Could you share the start-command of jobmanager and taskmanager. If it is started correctly, we

will have a the following jvm options.

-Dlog.file=/path/of/taskmanager.log -Dlogback.configurationFile=file:///path/of/logback.xml

Best,

Yang

Bajaj, Abhinav <[hidden email]> 于2020年1月4日周六上午7:23写道：

Hi,

I am investigating a logging issue with Flink.

Setup

Using Flink-1.7.1 using logback as suggested in Flink documentation here.
Submitting the Flink job from the Flink dashboard.

Observations

Logs from main method(outside of job graph) do not show up in jobmanager logs.
Logs from the operators like map or custom operators do show up in the taskmanager logs.
Logs from main method do show up in jobmanager logs when using log4j in place of logback.

Has anyone else noticed similar behavior or is this a known issue with logback integration in Flink?

Any suggestions on potential workaround or fix?

Appreciate your time and help.

~ Abhinav Bajaj

Dawid Wysakowicz-2

Re: Flink logging issue with logback

Hi Bajaj,

I spent a bit more time on that and I figured out the difference. The cause is in the implementation of log4j's ConsoleAppender.

So first of all as I said before, the code path that submits a job through Web UI redirects the std.out and std.err to a memory buffer for the time of the "main" method execution. This is the expected behavior. That's why the logback does not log anything. Log4j implementation is slightly different as by default it does not follow changes to the System#setOut. It buffers the original System.out. It has an option though to also follow changes to the System.out: ConsoleAppender#follow (https://logging.apache.org/log4j/2.x/manual/appenders.html). If enabled the log4j behaves exactly the same way as logback. After a very brief check I could not find such property for logback (actually I like logback's approach better).

Hope it clarifies the difference.

Best,

Dawid

On 07/01/2020 07:17, Yang Wang wrote:

Hi Bajaj,

I have tested just as you say, and find that the logs in the user class could not show up when

using ConsoleAppender. If using FileAppender instead, everything goes well.

It is so weird and i have no idea how to debug it.
Best,
Yang
Bajaj, Abhinav <[hidden email]> 于2020年1月7日周二上午4:28写道：

Hi,

Thanks much for the responses.

Let me add some more details and clarify my question.

Setup

I used the WikipediaAnalysis example and added a log in main method.

……

public static void main(String[] args) throws Exception {
StreamExecutionEnvironment see = StreamExecutionEnvironment.getExecutionEnvironment();
LOG.info("Info log for test");

DataStream<WikipediaEditEvent> edits = see.addSource(new WikipediaEditsSource());

……

I am using the Flink 1.7.1 distribution and starting jobmanager and taskmanager locally using the below commands –

./bin/jobmanager.sh start-foreground

./bin/taskmanager.sh start-foreground

Both jobmanager and taskmanager log in the console now

JVM options are correctly set and verified from jobmanager & taskmanager logs

I submit the WikipediaAnalysis job from Flink dashboard and checked the jobmanager logs

Run 1: Flink is using the default log4j logging

Jobmanager logs the added info log from the job

2020-01-06 11:55:37,422 INFO wikiedits.WikipediaAnalysis - Info log for test

Run 2: Flink is setup to use logback as suggested in Flink documentation here

Jobmanger does not log the added info log from the job

So, it seems there is a logging behavior difference between using log4j & logback in Flink.

Is this expected or a known difference?

Thanks again,

Abhinav Bajaj

PS: Ahh. I see how my email was confusing the first time. Hopefully this one is better :P

From: Dawid Wysakowicz <[hidden email]>
Date: Monday, January 6, 2020 at 5:13 AM
Cc: "Bajaj, Abhinav" <[hidden email]>, "[hidden email]" <[hidden email]>
Subject: Re: Flink logging issue with logback

Hi Bajaj,

I am not entirely sure what is the actual issue you are seeking help, but let me comment on your observations.

Ad. 1

If you log to the console from the main method this is an expected behavior in both cases (log4j, logback). The std out is being overwritten for the execution of the main method

If you log to a file logs should work in both cases. I checked that myself and actually the logs appeared in the jobmanager logs as long as they are executed before the env.execute(). I observed though weird behavior of the Web UI, as it does not always update the logs that are displayed. How did you check the logs? If you checked through the Web UI could you try to check the file directly?

Ad. 2 Yes this is expected. Operators are executed on taskmanager and that's why they log there.

Ad. 3 See Ad. 1

Best,

Dawid

On 06/01/2020 07:07, vino yang wrote:

Hi Bajaj,

>> Logs from main method(outside of job graph) do not show up in jobmanager logs.

IMO, it's normal phenomena.

Other ideas, please check the JVM options mentioned by Yang.

Best,

Vino

Yang Wang <[hidden email]> 于2020年1月6日周一上午11:18写道：

Hi Bajaj, Abhinav,

Could you share the start-command of jobmanager and taskmanager. If it is started correctly, we

will have a the following jvm options.

-Dlog.file=/path/of/taskmanager.log -Dlogback.configurationFile=file:///path/of/logback.xml

Best,

Yang

Bajaj, Abhinav <[hidden email]> 于2020年1月4日周六上午7:23写道：

Hi,

I am investigating a logging issue with Flink.

Setup

Using Flink-1.7.1 using logback as suggested in Flink documentation here.

Submitting the Flink job from the Flink dashboard.

Observations

Logs from main method(outside of job graph) do not show up in jobmanager logs.

Logs from the operators like map or custom operators do show up in the taskmanager logs.

Logs from main method do show up in jobmanager logs when using log4j in place of logback.

Has anyone else noticed similar behavior or is this a known issue with logback integration in Flink?

Any suggestions on potential workaround or fix?

Appreciate your time and help.

~ Abhinav Bajaj

signature.asc (849 bytes) Download Attachment

Dawid Wysakowicz-2

Re: Flink logging issue with logback

In reply to this post by Yang Wang

A quick update. The suppression of stdout/stderr actually might soon be dropped, see: https://issues.apache.org/jira/browse/FLINK-15504

Best,

Dawid

On 07/01/2020 07:17, Yang Wang wrote:

Hi Bajaj,

I have tested just as you say, and find that the logs in the user class could not show up when

using ConsoleAppender. If using FileAppender instead, everything goes well.

It is so weird and i have no idea how to debug it.
Best,
Yang
Bajaj, Abhinav <[hidden email]> 于2020年1月7日周二上午4:28写道：

Hi,

Thanks much for the responses.

Let me add some more details and clarify my question.

Setup

I used the WikipediaAnalysis example and added a log in main method.

……

public static void main(String[] args) throws Exception {
StreamExecutionEnvironment see = StreamExecutionEnvironment.getExecutionEnvironment();
LOG.info("Info log for test");

DataStream<WikipediaEditEvent> edits = see.addSource(new WikipediaEditsSource());

……

I am using the Flink 1.7.1 distribution and starting jobmanager and taskmanager locally using the below commands –

./bin/jobmanager.sh start-foreground

./bin/taskmanager.sh start-foreground

Both jobmanager and taskmanager log in the console now

JVM options are correctly set and verified from jobmanager & taskmanager logs

I submit the WikipediaAnalysis job from Flink dashboard and checked the jobmanager logs

Run 1: Flink is using the default log4j logging

Jobmanager logs the added info log from the job

2020-01-06 11:55:37,422 INFO wikiedits.WikipediaAnalysis - Info log for test

Run 2: Flink is setup to use logback as suggested in Flink documentation here

Jobmanger does not log the added info log from the job

So, it seems there is a logging behavior difference between using log4j & logback in Flink.

Is this expected or a known difference?

Thanks again,

Abhinav Bajaj

PS: Ahh. I see how my email was confusing the first time. Hopefully this one is better :P

From: Dawid Wysakowicz <[hidden email]>
Date: Monday, January 6, 2020 at 5:13 AM
Cc: "Bajaj, Abhinav" <[hidden email]>, "[hidden email]" <[hidden email]>
Subject: Re: Flink logging issue with logback

Hi Bajaj,

I am not entirely sure what is the actual issue you are seeking help, but let me comment on your observations.

Ad. 1

If you log to the console from the main method this is an expected behavior in both cases (log4j, logback). The std out is being overwritten for the execution of the main method

If you log to a file logs should work in both cases. I checked that myself and actually the logs appeared in the jobmanager logs as long as they are executed before the env.execute(). I observed though weird behavior of the Web UI, as it does not always update the logs that are displayed. How did you check the logs? If you checked through the Web UI could you try to check the file directly?

Ad. 2 Yes this is expected. Operators are executed on taskmanager and that's why they log there.

Ad. 3 See Ad. 1

Best,

Dawid

On 06/01/2020 07:07, vino yang wrote:

Hi Bajaj,

>> Logs from main method(outside of job graph) do not show up in jobmanager logs.

IMO, it's normal phenomena.

Other ideas, please check the JVM options mentioned by Yang.

Best,

Vino

Yang Wang <[hidden email]> 于2020年1月6日周一上午11:18写道：

Hi Bajaj, Abhinav,

Could you share the start-command of jobmanager and taskmanager. If it is started correctly, we

will have a the following jvm options.

-Dlog.file=/path/of/taskmanager.log -Dlogback.configurationFile=file:///path/of/logback.xml

Best,

Yang

Bajaj, Abhinav <[hidden email]> 于2020年1月4日周六上午7:23写道：

Hi,

I am investigating a logging issue with Flink.

Setup

Using Flink-1.7.1 using logback as suggested in Flink documentation here.

Submitting the Flink job from the Flink dashboard.

Observations

Logs from main method(outside of job graph) do not show up in jobmanager logs.

Logs from the operators like map or custom operators do show up in the taskmanager logs.

Logs from main method do show up in jobmanager logs when using log4j in place of logback.

Has anyone else noticed similar behavior or is this a known issue with logback integration in Flink?

Any suggestions on potential workaround or fix?

Appreciate your time and help.

~ Abhinav Bajaj

signature.asc (849 bytes) Download Attachment

Maximilian Michels

Re: Flink logging issue with logback

Interesting that we came across this problem at the same time. We have
observed this with Lyft's K8s operator which uses the Rest API for job
submission, much like the Flink dashboard.

Note that you can restore the original stdout/stderr in your program:

private static void restoreStdOutAndStdErr() {
System.setOut(new PrintStream(
new FileOutputStream(FileDescriptor.out)));
System.setErr(new PrintStream(
new FileOutputStream(FileDescriptor.err)));
}

Just call restoreStdOutAndStdErr() before you start building the Flink
job. Of course, this is just meant to be a workaround.

I think an acceptable solution is to always print upon execution. For
the plan preview we may keep the existing behavior.

Cheers,
Max

On 07.01.20 17:39, Dawid Wysakowicz wrote:

> A quick update. The suppression of stdout/stderr actually might soon be
> dropped, see: https://issues.apache.org/jira/browse/FLINK-15504
>
> Best,
>
> Dawid
>
> On 07/01/2020 07:17, Yang Wang wrote:
>> Hi Bajaj,
>>
>> I have tested just as you say, and find that the logs in the user
>> class could not show up when
>> using ConsoleAppender. If using FileAppender instead, everything goes
>> well.
>>
>> It is so weird and i have no idea how to debug it.
>> Best,
>> Yang
>>
>> Bajaj, Abhinav <[hidden email]
>> <mailto:[hidden email]>> 于2020年1月7日周二上午4:28写道：
>>
>> Hi,
>>
>> Thanks much for the responses.
>>
>> Let me add some more details and clarify my question.
>>
>> _Setup_
>>
>> * I used the WikipediaAnalysis example and added a log in main
>> method.
>>
>> ……
>>
>> public static void main(String[] args) throws Exception {
>> StreamExecutionEnvironment see =
>> StreamExecutionEnvironment./getExecutionEnvironment/();
>> /LOG/.info("Info log for test");
>>
>> DataStream<WikipediaEditEvent> edits = see.addSource(new
>> WikipediaEditsSource());
>>
>> ……
>>
>> * I am using the Flink 1.7.1 distribution and starting
>> jobmanager and taskmanager locally using the below commands –
>> o ./bin/jobmanager.sh start-foreground
>> o ./bin/taskmanager.sh start-foreground
>> o Both jobmanager and taskmanager log in the console now
>> o JVM options are correctly set and verified from jobmanager
>> & taskmanager logs
>>
>> * I submit the WikipediaAnalysis job from Flink dashboard and
>> checked the jobmanager logs
>>
>> _Run 1_: Flink is using the default log4j logging
>>
>> * Jobmanager logs the added info log from the job
>> o 2020-01-06 11:55:37,422 INFO wikiedits.WikipediaAnalysis -
>> Info log for test
>>
>> _Run 2_: Flink is setup to use logback as suggested in Flink
>> documentation here
>> <https://ci.apache.org/projects/flink/flink-docs-stable/dev/best_practices.html#use-logback-when-running-flink-on-a-cluster>
>>
>> * Jobmanger does not log the added info log from the job
>>
>> So, it seems there is a logging behavior difference between using
>> log4j & logback in Flink.
>>
>> Is this expected or a known difference?
>>
>> Thanks again,
>>
>> Abhinav Bajaj
>>
>> _PS_: Ahh. I see how my email was confusing the first time.
>> Hopefully this one is better :P
>>
>> *From: *Dawid Wysakowicz <[hidden email]
>> <mailto:[hidden email]>>
>> *Date: *Monday, January 6, 2020 at 5:13 AM
>> *Cc: *"Bajaj, Abhinav" <[hidden email]
>> <mailto:[hidden email]>>, "[hidden email]
>> <mailto:[hidden email]>" <[hidden email]
>> <mailto:[hidden email]>>
>> *Subject: *Re: Flink logging issue with logback
>>
>> Hi Bajaj,
>>
>> I am not entirely sure what is the actual issue you are seeking
>> help, but let me comment on your observations.
>>
>> Ad. 1
>>
>> If you log to the console from the main method this is an expected
>> behavior in both cases (log4j, logback). The std out is being
>> overwritten for the execution of the main method
>>
>> If you log to a file logs should work in both cases. I checked
>> that myself and actually the logs appeared in the jobmanager logs
>> as long as they are executed before the env.execute(). I observed
>> though weird behavior of the Web UI, as it does not always update
>> the logs that are displayed. How did you check the logs? If you
>> checked through the Web UI could you try to check the file directly?
>>
>> Ad. 2 Yes this is expected. Operators are executed on taskmanager
>> and that's why they log there.
>>
>> Ad. 3 See Ad. 1
>>
>> Best,
>>
>> Dawid
>>
>> On 06/01/2020 07:07, vino yang wrote:
>>
>> Hi Bajaj,
>>
>> >> Logs from main method(outside of job graph) do not show up
>> in jobmanager logs.
>>
>> IMO, it's normal phenomena.
>>
>> Other ideas, please check the JVM options mentioned by Yang.
>>
>> Best,
>>
>> Vino
>>
>> Yang Wang <[hidden email]
>> <mailto:[hidden email]>> 于2020年1月6日周一上午11:18写道：
>>
>> Hi Bajaj, Abhinav,
>>
>> Could you share the start-command of jobmanager and
>> taskmanager. If it is started correctly, we
>>
>> will have a the following jvm options.
>>
>> -Dlog.file=/path/of/taskmanager.log
>> -Dlogback.configurationFile=file:///path/of/logback.xml
>>
>> Best,
>>
>> Yang
>>
>> Bajaj, Abhinav <[hidden email]
>> <mailto:[hidden email]>> 于2020年1月4日周六上午
>> 7:23写道：
>>
>> Hi,
>>
>> I am investigating a logging issue with Flink.
>>
>> _Setup_
>>
>> * Using Flink-1.7.1 using logback as suggested in
>> Flink documentation here
>> <https://ci.apache.org/projects/flink/flink-docs-stable/dev/best_practices.html#use-logback-when-running-flink-on-a-cluster>.
>> * Submitting the Flink job from the Flink dashboard.
>>
>> _Observations_
>>
>> * Logs from main method(outside of job graph) do not
>> show up in jobmanager logs.
>> * Logs from the operators like map or custom
>> operators do show up in the taskmanager logs.
>> * Logs from main method do show up in jobmanager
>> logs when using log4j in place of logback.
>>
>> Has anyone else noticed similar behavior or is this a
>> known issue with logback integration in Flink?
>>
>> Any suggestions on potential workaround or fix?
>>
>> Appreciate your time and help.
>>
>> ~ Abhinav Bajaj
>>

Bajaj, Abhinav

Re: Flink logging issue with logback

Thanks Dawid, Max and Yang for confirming the issue and providing potential workaround.

On 1/8/20, 3:24 AM, "Maximilian Michels" <[hidden email]> wrote:

Interesting that we came across this problem at the same time. We have
observed this with Lyft's K8s operator which uses the Rest API for job
submission, much like the Flink dashboard.

Note that you can restore the original stdout/stderr in your program:

private static void restoreStdOutAndStdErr() {
System.setOut(new PrintStream(
new FileOutputStream(FileDescriptor.out)));
System.setErr(new PrintStream(
new FileOutputStream(FileDescriptor.err)));
}

Just call restoreStdOutAndStdErr() before you start building the Flink
job. Of course, this is just meant to be a workaround.

I think an acceptable solution is to always print upon execution. For
the plan preview we may keep the existing behavior.

Cheers,
Max

On 07.01.20 17:39, Dawid Wysakowicz wrote:
> A quick update. The suppression of stdout/stderr actually might soon be
> dropped, see: https://eur02.safelinks.protection.outlook.com/?url=https%3A%2F%2Fissues.apache.org%2Fjira%2Fbrowse%2FFLINK-15504&data=01%7C01%7C%7Ce78cef33338e4589a72d08d7942d53eb%7C6d4034cd72254f72b85391feaea64919%7C1&sdata=a2dpid%2Fm1SN8%2F5sx09%2FbuVuk%2FI7UM%2BWMZtNALaYf8rU%3D&reserved=0
>
> Best,
>
> Dawid
>
> On 07/01/2020 07:17, Yang Wang wrote:
>> Hi Bajaj,
>>
>> I have tested just as you say, and find that the logs in the user
>> class could not show up when
>> using ConsoleAppender. If using FileAppender instead, everything goes
>> well.
>>
>> It is so weird and i have no idea how to debug it.
>> Best,
>> Yang
>>
>> Bajaj, Abhinav <[hidden email]
>> <mailto:[hidden email]>> 于2020年1月7日周二上午4:28写道：
>>
>> Hi,
>>
>> Thanks much for the responses.
>>
>> Let me add some more details and clarify my question.
>>
>> _Setup_
>>
>> * I used the WikipediaAnalysis example and added a log in main
>> method.
>>
>> ……
>>
>> public static void main(String[] args) throws Exception {
>> StreamExecutionEnvironment see =
>> StreamExecutionEnvironment./getExecutionEnvironment/();
>> /LOG/.info("Info log for test");
>>
>> DataStream<WikipediaEditEvent> edits = see.addSource(new
>> WikipediaEditsSource());
>>
>> ……
>>
>> * I am using the Flink 1.7.1 distribution and starting
>> jobmanager and taskmanager locally using the below commands –
>> o ./bin/jobmanager.sh start-foreground
>> o ./bin/taskmanager.sh start-foreground
>> o Both jobmanager and taskmanager log in the console now
>> o JVM options are correctly set and verified from jobmanager
>> & taskmanager logs
>>
>> * I submit the WikipediaAnalysis job from Flink dashboard and
>> checked the jobmanager logs
>>
>> _Run 1_: Flink is using the default log4j logging
>>
>> * Jobmanager logs the added info log from the job
>> o 2020-01-06 11:55:37,422 INFO wikiedits.WikipediaAnalysis -
>> Info log for test
>>
>> _Run 2_: Flink is setup to use logback as suggested in Flink
>> documentation here
>> <https://eur02.safelinks.protection.outlook.com/?url=https%3A%2F%2Fci.apache.org%2Fprojects%2Fflink%2Fflink-docs-stable%2Fdev%2Fbest_practices.html%23use-logback-when-running-flink-on-a-cluster&data=01%7C01%7C%7Ce78cef33338e4589a72d08d7942d53eb%7C6d4034cd72254f72b85391feaea64919%7C1&sdata=3heaNcREFAruHxyXCUjrySVKw14LIrHE8RKWV7gOpZU%3D&reserved=0>
>>
>> * Jobmanger does not log the added info log from the job
>>
>> So, it seems there is a logging behavior difference between using
>> log4j & logback in Flink.
>>
>> Is this expected or a known difference?
>>
>> Thanks again,
>>
>> Abhinav Bajaj
>>
>> _PS_: Ahh. I see how my email was confusing the first time.
>> Hopefully this one is better :P
>>
>> *From: *Dawid Wysakowicz <[hidden email]
>> <mailto:[hidden email]>>
>> *Date: *Monday, January 6, 2020 at 5:13 AM
>> *Cc: *"Bajaj, Abhinav" <[hidden email]
>> <mailto:[hidden email]>>, "[hidden email]
>> <mailto:[hidden email]>" <[hidden email]
>> <mailto:[hidden email]>>
>> *Subject: *Re: Flink logging issue with logback
>>
>> Hi Bajaj,
>>
>> I am not entirely sure what is the actual issue you are seeking
>> help, but let me comment on your observations.
>>
>> Ad. 1
>>
>> If you log to the console from the main method this is an expected
>> behavior in both cases (log4j, logback). The std out is being
>> overwritten for the execution of the main method
>>
>> If you log to a file logs should work in both cases. I checked
>> that myself and actually the logs appeared in the jobmanager logs
>> as long as they are executed before the env.execute(). I observed
>> though weird behavior of the Web UI, as it does not always update
>> the logs that are displayed. How did you check the logs? If you
>> checked through the Web UI could you try to check the file directly?
>>
>> Ad. 2 Yes this is expected. Operators are executed on taskmanager
>> and that's why they log there.
>>
>> Ad. 3 See Ad. 1
>>
>> Best,
>>
>> Dawid
>>
>> On 06/01/2020 07:07, vino yang wrote:
>>
>> Hi Bajaj,
>>
>> >> Logs from main method(outside of job graph) do not show up
>> in jobmanager logs.
>>
>> IMO, it's normal phenomena.
>>
>> Other ideas, please check the JVM options mentioned by Yang.
>>
>> Best,
>>
>> Vino
>>
>> Yang Wang <[hidden email]
>> <mailto:[hidden email]>> 于2020年1月6日周一上午11:18写道：
>>
>> Hi Bajaj, Abhinav,
>>
>> Could you share the start-command of jobmanager and
>> taskmanager. If it is started correctly, we
>>
>> will have a the following jvm options.
>>
>> -Dlog.file=/path/of/taskmanager.log
>> -Dlogback.configurationFile=file:///path/of/logback.xml
>>
>> Best,
>>
>> Yang
>>
>> Bajaj, Abhinav <[hidden email]
>> <mailto:[hidden email]>> 于2020年1月4日周六上午
>> 7:23写道：
>>
>> Hi,
>>
>> I am investigating a logging issue with Flink.
>>
>> _Setup_
>>
>> * Using Flink-1.7.1 using logback as suggested in
>> Flink documentation here
>> <https://eur02.safelinks.protection.outlook.com/?url=https%3A%2F%2Fci.apache.org%2Fprojects%2Fflink%2Fflink-docs-stable%2Fdev%2Fbest_practices.html%23use-logback-when-running-flink-on-a-cluster&data=01%7C01%7C%7Ce78cef33338e4589a72d08d7942d53eb%7C6d4034cd72254f72b85391feaea64919%7C1&sdata=3heaNcREFAruHxyXCUjrySVKw14LIrHE8RKWV7gOpZU%3D&reserved=0>.
>> * Submitting the Flink job from the Flink dashboard.
>>
>> _Observations_
>>
>> * Logs from main method(outside of job graph) do not
>> show up in jobmanager logs.
>> * Logs from the operators like map or custom
>> operators do show up in the taskmanager logs.
>> * Logs from main method do show up in jobmanager
>> logs when using log4j in place of logback.
>>
>> Has anyone else noticed similar behavior or is this a
>> known issue with logback integration in Flink?
>>
>> Any suggestions on potential workaround or fix?
>>
>> Appreciate your time and help.
>>
>> ~ Abhinav Bajaj
>>

Maximilian Michels

Re: Flink logging issue with logback

FYI, there is also a PR: https://github.com/apache/flink/pull/10811

On 09.01.20 01:53, Bajaj, Abhinav wrote:

> Thanks Dawid, Max and Yang for confirming the issue and providing potential workaround.
>
> On 1/8/20, 3:24 AM, "Maximilian Michels" <[hidden email]> wrote:
>
> Interesting that we came across this problem at the same time. We have
> observed this with Lyft's K8s operator which uses the Rest API for job
> submission, much like the Flink dashboard.
>
> Note that you can restore the original stdout/stderr in your program:
>
> private static void restoreStdOutAndStdErr() {
> System.setOut(new PrintStream(
> new FileOutputStream(FileDescriptor.out)));
> System.setErr(new PrintStream(
> new FileOutputStream(FileDescriptor.err)));
> }
>
> Just call restoreStdOutAndStdErr() before you start building the Flink
> job. Of course, this is just meant to be a workaround.
>
> I think an acceptable solution is to always print upon execution. For
> the plan preview we may keep the existing behavior.
>
> Cheers,
> Max
>
> On 07.01.20 17:39, Dawid Wysakowicz wrote:
> > A quick update. The suppression of stdout/stderr actually might soon be
> > dropped, see: https://eur02.safelinks.protection.outlook.com/?url=https%3A%2F%2Fissues.apache.org%2Fjira%2Fbrowse%2FFLINK-15504&data=01%7C01%7C%7Ce78cef33338e4589a72d08d7942d53eb%7C6d4034cd72254f72b85391feaea64919%7C1&sdata=a2dpid%2Fm1SN8%2F5sx09%2FbuVuk%2FI7UM%2BWMZtNALaYf8rU%3D&reserved=0
> >
> > Best,
> >
> > Dawid
> >
> > On 07/01/2020 07:17, Yang Wang wrote:
> >> Hi Bajaj,
> >>
> >> I have tested just as you say, and find that the logs in the user
> >> class could not show up when
> >> using ConsoleAppender. If using FileAppender instead, everything goes
> >> well.
> >>
> >> It is so weird and i have no idea how to debug it.
> >> Best,
> >> Yang
> >>
> >> Bajaj, Abhinav <[hidden email]
> >> <mailto:[hidden email]>> 于2020年1月7日周二上午4:28写道：
> >>
> >> Hi,
> >>
> >> Thanks much for the responses.
> >>
> >> Let me add some more details and clarify my question.
> >>
> >> _Setup_
> >>
> >> * I used the WikipediaAnalysis example and added a log in main
> >> method.
> >>
> >> ……
> >>
> >> public static void main(String[] args) throws Exception {
> >> StreamExecutionEnvironment see =
> >> StreamExecutionEnvironment./getExecutionEnvironment/();
> >> /LOG/.info("Info log for test");
> >>
> >> DataStream<WikipediaEditEvent> edits = see.addSource(new
> >> WikipediaEditsSource());
> >>
> >> ……
> >>
> >> * I am using the Flink 1.7.1 distribution and starting
> >> jobmanager and taskmanager locally using the below commands –
> >> o ./bin/jobmanager.sh start-foreground
> >> o ./bin/taskmanager.sh start-foreground
> >> o Both jobmanager and taskmanager log in the console now
> >> o JVM options are correctly set and verified from jobmanager
> >> & taskmanager logs
> >>
> >> * I submit the WikipediaAnalysis job from Flink dashboard and
> >> checked the jobmanager logs
> >>
> >> _Run 1_: Flink is using the default log4j logging
> >>
> >> * Jobmanager logs the added info log from the job
> >> o 2020-01-06 11:55:37,422 INFO wikiedits.WikipediaAnalysis -
> >> Info log for test
> >>
> >> _Run 2_: Flink is setup to use logback as suggested in Flink
> >> documentation here
> >> <https://eur02.safelinks.protection.outlook.com/?url=https%3A%2F%2Fci.apache.org%2Fprojects%2Fflink%2Fflink-docs-stable%2Fdev%2Fbest_practices.html%23use-logback-when-running-flink-on-a-cluster&data=01%7C01%7C%7Ce78cef33338e4589a72d08d7942d53eb%7C6d4034cd72254f72b85391feaea64919%7C1&sdata=3heaNcREFAruHxyXCUjrySVKw14LIrHE8RKWV7gOpZU%3D&reserved=0>
> >>
> >> * Jobmanger does not log the added info log from the job
> >>
> >> So, it seems there is a logging behavior difference between using
> >> log4j & logback in Flink.
> >>
> >> Is this expected or a known difference?
> >>
> >> Thanks again,
> >>
> >> Abhinav Bajaj
> >>
> >> _PS_: Ahh. I see how my email was confusing the first time.
> >> Hopefully this one is better :P
> >>
> >> *From: *Dawid Wysakowicz <[hidden email]
> >> <mailto:[hidden email]>>
> >> *Date: *Monday, January 6, 2020 at 5:13 AM
> >> *Cc: *"Bajaj, Abhinav" <[hidden email]
> >> <mailto:[hidden email]>>, "[hidden email]
> >> <mailto:[hidden email]>" <[hidden email]
> >> <mailto:[hidden email]>>
> >> *Subject: *Re: Flink logging issue with logback
> >>
> >> Hi Bajaj,
> >>
> >> I am not entirely sure what is the actual issue you are seeking
> >> help, but let me comment on your observations.
> >>
> >> Ad. 1
> >>
> >> If you log to the console from the main method this is an expected
> >> behavior in both cases (log4j, logback). The std out is being
> >> overwritten for the execution of the main method
> >>
> >> If you log to a file logs should work in both cases. I checked
> >> that myself and actually the logs appeared in the jobmanager logs
> >> as long as they are executed before the env.execute(). I observed
> >> though weird behavior of the Web UI, as it does not always update
> >> the logs that are displayed. How did you check the logs? If you
> >> checked through the Web UI could you try to check the file directly?
> >>
> >> Ad. 2 Yes this is expected. Operators are executed on taskmanager
> >> and that's why they log there.
> >>
> >> Ad. 3 See Ad. 1
> >>
> >> Best,
> >>
> >> Dawid
> >>
> >> On 06/01/2020 07:07, vino yang wrote:
> >>
> >> Hi Bajaj,
> >>
> >> >> Logs from main method(outside of job graph) do not show up
> >> in jobmanager logs.
> >>
> >> IMO, it's normal phenomena.
> >>
> >> Other ideas, please check the JVM options mentioned by Yang.
> >>
> >> Best,
> >>
> >> Vino
> >>
> >> Yang Wang <[hidden email]
> >> <mailto:[hidden email]>> 于2020年1月6日周一上午11:18写道：
> >>
> >> Hi Bajaj, Abhinav,
> >>
> >> Could you share the start-command of jobmanager and
> >> taskmanager. If it is started correctly, we
> >>
> >> will have a the following jvm options.
> >>
> >> -Dlog.file=/path/of/taskmanager.log
> >> -Dlogback.configurationFile=file:///path/of/logback.xml
> >>
> >> Best,
> >>
> >> Yang
> >>
> >> Bajaj, Abhinav <[hidden email]
> >> <mailto:[hidden email]>> 于2020年1月4日周六上午
> >> 7:23写道：
> >>
> >> Hi,
> >>
> >> I am investigating a logging issue with Flink.
> >>
> >> _Setup_
> >>
> >> * Using Flink-1.7.1 using logback as suggested in
> >> Flink documentation here
> >> <https://eur02.safelinks.protection.outlook.com/?url=https%3A%2F%2Fci.apache.org%2Fprojects%2Fflink%2Fflink-docs-stable%2Fdev%2Fbest_practices.html%23use-logback-when-running-flink-on-a-cluster&data=01%7C01%7C%7Ce78cef33338e4589a72d08d7942d53eb%7C6d4034cd72254f72b85391feaea64919%7C1&sdata=3heaNcREFAruHxyXCUjrySVKw14LIrHE8RKWV7gOpZU%3D&reserved=0>.
> >> * Submitting the Flink job from the Flink dashboard.
> >>
> >> _Observations_
> >>
> >> * Logs from main method(outside of job graph) do not
> >> show up in jobmanager logs.
> >> * Logs from the operators like map or custom
> >> operators do show up in the taskmanager logs.
> >> * Logs from main method do show up in jobmanager
> >> logs when using log4j in place of logback.
> >>
> >> Has anyone else noticed similar behavior or is this a
> >> known issue with logback integration in Flink?
> >>
> >> Any suggestions on potential workaround or fix?
> >>
> >> Appreciate your time and help.
> >>
> >> ~ Abhinav Bajaj
> >>
>
>