Re: Flink logging issue with logback

Posted by Maximilian Michels on
URL: http://deprecated-apache-flink-user-mailing-list-archive.369.s1.nabble.com/Flink-logging-issue-with-logback-tp31928p32048.html

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&amp;data=01%7C01%7C%7Ce78cef33338e4589a72d08d7942d53eb%7C6d4034cd72254f72b85391feaea64919%7C1&amp;sdata=a2dpid%2Fm1SN8%2F5sx09%2FbuVuk%2FI7UM%2BWMZtNALaYf8rU%3D&amp;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&amp;data=01%7C01%7C%7Ce78cef33338e4589a72d08d7942d53eb%7C6d4034cd72254f72b85391feaea64919%7C1&amp;sdata=3heaNcREFAruHxyXCUjrySVKw14LIrHE8RKWV7gOpZU%3D&amp;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&amp;data=01%7C01%7C%7Ce78cef33338e4589a72d08d7942d53eb%7C6d4034cd72254f72b85391feaea64919%7C1&amp;sdata=3heaNcREFAruHxyXCUjrySVKw14LIrHE8RKWV7gOpZU%3D&amp;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
>      >>
>      
>