Is it possible to change log level after deployment?

[chuncheng...@gmail.com]

Hi,

Is it possible to change log level after the CDAP application has been deployed? For example, change the preference?

It seems that slf4j doesn't provide this function.

So I tried to use logback logger instead:

import org.slf4j.LoggerFactory;

import ch.qos.logback.classic.Level;

import ch.qos.logback.classic.Logger;

private static Logger logger = (Logger)LoggerFactory.getLogger(GreetingHandler.class);

logger.setLevel(Level.WARN);

But when I try to create app in CDAP, I got below error message:

Error: ch.qos.logback.classic.Logger cannot be cast to ch.qos.logback.classic.Logger

Which cause my GreetingHandler class doesn't initialized correctly.

Any suggestions?

Thanks.

[yao...@cask.co]

Hi Chuncheng,

Changing log levels after the deploy of CDAP application is supported in distributed mode. 

To change the log level before the application starts, you can add the logger name as the key and log level as the value in the preferences. The logger name should be prefixed with "system.log.level". For example, if you want to change the log level of HelloWorld class to DEBUG, you can use "system.log.level.co.cask.cdap.examples.helloworld.HelloWorld" as the key and "DEBUG" as the value. This can be applied to any package and any classes. If logger name is omitted, it will change the log level of ROOT.

To change the log level of a program dynamically(for worker, flow, and service which are running), please refer to http://docs.cask.co/cdap/4.1.0/en/reference-manual/http-restful-api/logging.html#changing-program-log-levels. You can change the log level at run level of a worker, flow and service.

Changing log levels for applications in sdk is not supported. You have to either modify the logback.xml or provide a logback.xml for your application. 

If you want to change log levels in code, please do:

LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();

Logger logger = loggerContext.getLogger(loggerName);

logger.setLevel(Level.WARN);

Thanks and regards,

Yaojie Feng

[chuncheng...@gmail.com]

Hi Yaojie,

Thanks for looking into this.

The way to change log level you mentioned above is available in CDAP 4.0.0 or later. Is it right?

Thanks,

Chuncheng

[yao...@cask.co]

Hi Chuncheng,

Yes. It is available in 4.0.0 or later version of CDAP.

Regards,

Yaojie Feng

[chuncheng...@gmail.com]

Hi Yaojie,

I have another question. I configured my root logger to ERROR level as below, but still I can see a lot of INFO level logs. Do you know why and how can I make them disappear? Thanks.

<?xml version="1.0" encoding="UTF-8"?>

<configuration>

<appender name="Console" class="ch.qos.logback.core.ConsoleAppender">

<encoder>

<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{5} - %msg%n

</pattern>

</encoder>

</appender>

<root level="ERROR">

<appender-ref ref="Console" />

</root>

</configuration>

Logs I can see:

2017-03-15 02:11:54,031 - INFO  [NettyHttpService STARTING:c.c.h.NettyHttpService@257] - Starting WorkflowDriver http service on address ejv-cask-005.amers3.cis.trcloud/10.51.24.150:0...

2017-03-15 02:11:54,206 - INFO  [NettyHttpService STARTING:c.c.h.NettyHttpService@262] - Started WorkflowDriver http service on address /10.51.24.150:59370

2017-03-15 02:11:55,243 - INFO  [WorkflowDriver:o.a.t.d.AbstractClientProvider@112] - Service discovered at ejv-cask-005.amers3.cis.trcloud:50332

2017-03-15 02:11:55,245 - INFO  [WorkflowDriver:o.a.t.d.AbstractClientProvider@120] - Attempting to connect to tx service at ejv-cask-005.amers3.cis.trcloud:50332 with timeout 30000 ms.

2017-03-15 02:11:55,269 - INFO  [WorkflowDriver:o.a.t.d.AbstractClientProvider@134] - Connected to tx service at ejv-cask-005.amers3.cis.trcloud:50332

2017-03-15 02:11:55,460 - INFO  [WorkflowDriver:c.c.c.i.a.r.w.WorkflowProgramController@78] - Workflow service workflow.M0116501.BIMBQMExceptionArchiveSpark.ExceptionArchiveWorkflow.b68fa9a6-0924-11e7-bd59-fa163ed746b2 announced at /10.51.24.150:59370

2017-03-15 02:11:55,462 - INFO  [WorkflowDriver:c.c.c.i.a.r.w.WorkflowDriver@554] - Start workflow execution for ExceptionArchiveWorkflow

2017-03-15 02:11:55,549 - INFO  [action-ExceptionArchiveSpark-0:c.c.c.c.g.LocationRuntimeModule@100] - HDFS namespace is /cdap

2017-03-15 02:11:55,647 - INFO  [action-ExceptionArchiveSpark-0:c.c.c.i.w.ProgramWorkflowAction@62] - Starting Program for workflow action: ExceptionArchiveSpark

2017-03-15 02:11:55,704 - INFO  [action-ExceptionArchiveSpark-0:c.c.c.a.r.s.SparkProgramRunner@197] - Starting Spark Job: SparkRuntimeContext{id=program:M0116501.BIMBQMExceptionArchiveSpark.-SNAPSHOT.spark.ExceptionArchiveSpark, runId=c331e871-0924-11e7-84a7-fa163e8e3c1c}

2017-03-15 02:12:04,785 - INFO  [NettyHttpService STARTING:c.c.h.NettyHttpService@257] - Starting SparkExecutionService http service on address ejv-cask-005.amers3.cis.trcloud/10.51.24.150:0...

2017-03-15 02:12:04,790 - INFO  [NettyHttpService STARTING:c.c.h.NettyHttpService@262] - Started SparkExecutionService http service on address /10.51.24.150:47349

2017-03-15 02:12:04,940 - INFO  [spark-submitter-ExceptionArchiveSpark-c331e871-0924-11e7-84a7-fa163e8e3c1c:o.a.s.u.MutableURLClassLoader@40] - MutableURLClassLoader intercepted

2017-03-15 02:12:06,042 - INFO  [spark-submitter-ExceptionArchiveSpark-c331e871-0924-11e7-84a7-fa163e8e3c1c:o.a.s.d.y.Client@59] - Requesting a new application from cluster with 4 NodeManagers

2017-03-15 02:12:06,081 - INFO  [spark-submitter-ExceptionArchiveSpark-c331e871-0924-11e7-84a7-fa163e8e3c1c:o.a.s.d.y.Client@59] - Verifying our application has not requested more than the maximum memory capability of the cluster (24576 MB per container)

2017-03-15 02:12:06,082 - INFO  [spark-submitter-ExceptionArchiveSpark-c331e871-0924-11e7-84a7-fa163e8e3c1c:o.a.s.d.y.Client@59] - Will allocate AM container, with 896 MB memory including 384 MB overhead

2017-03-15 02:12:06,084 - INFO  [spark-submitter-ExceptionArchiveSpark-c331e871-0924-11e7-84a7-fa163e8e3c1c:o.a.s.d.y.Client@59] - Setting up container launch context for our AM

2017-03-15 02:12:06,085 - INFO  [spark-submitter-ExceptionArchiveSpark-c331e871-0924-11e7-84a7-fa163e8e3c1c:o.a.s.d.y.Client@59] - Setting up the launch environment for our AM container

2017-03-15 02:12:06,109 - INFO  [spark-submitter-ExceptionArchiveSpark-c331e871-0924-11e7-84a7-fa163e8e3c1c:o.a.s.d.y.Client@59] - Preparing resources for our AM container

2017-03-15 02:12:06,259 - INFO  [spark-submitter-ExceptionArchiveSpark-c331e871-0924-11e7-84a7-fa163e8e3c1c:o.a.s.d.y.Client@59] - Uploading resource file:/storage/yarn/nm/usercache/cdap/appcache/application_1487639244741_0992/container_1487639244741_0992_01_000002/spark-assembly.jar -&gt; hdfs://ejv-cask-001.amers3.cis.trcloud:8020/user/cdap/.sparkStaging/application_1487639244741_0993/spark-assembly.jar

2017-03-15 02:12:07,474 - INFO  [spark-submitter-ExceptionArchiveSpark-c331e871-0924-11e7-84a7-fa163e8e3c1c:o.a.s.d.y.Client@59] - Uploading resource file:/storage/yarn/nm/usercache/cdap/appcache/application_1487639244741_0992/container_1487639244741_0992_01_000002/data/tmp/1489543915787-0/emptyJob.jar -&gt; hdfs://ejv-cask-001.amers3.cis.trcloud:8020/user/cdap/.sparkStaging/application_1487639244741_0993/emptyJob.jar

..........

[yao...@cask.co]

Hi Chuncheng,

Did you put your logback.xml under src/main/resources of your application? You will need to do that to configure the log level of your application. 

Thank you and regards,

Yaojie Feng

[chuncheng...@gmail.com]

Hi Yaojie,

Yes, I've put the logback.xml under src/main/resources. And in distribution mode.

Thanks,

Chuncheng

[yao...@cask.co]

Hi Chuncheng,

For your problem that the logback.xml is not working, this is a bug about https://issues.apache.org/jira/browse/TWILL-222. The root log level is always assumed to INFO regardless of what is in the logback.xml. Other logger works fine. The fix will be coming in next release. 

The current workaround is to set the root log level using preferences. Put "system.log.level" as key and "ERROR" as value, and then start the program. The preferences will override the default value and make the ROOT log level be ERROR. Hope this solves your problem.

Best and regards,

Yaojie Feng

[chuncheng...@gmail.com]

Hi Yaojie,

Currently our CDAP version is 3.5.4, so I can't use preference.

1) I find that not only root logger doesn't work, I find others don't work, too.

For example, I added below config in logback.xml:

<logger name="co.cask.cdap" level="ERROR" />

<logger name="akka.event.slf4j" level="ERROR" />

<logger name="org.apache.spark" level="ERROR" />

I can still see log messages whose level is lower than ERROR from these loggers, such as:

2017-03-17 08:58:31,904 - INFO  [WorkflowDriver:c.c.c.i.a.r.w.WorkflowDriver@554] - Start workflow execution for ExceptionArchiveWorkflow

2017-03-17 08:59:05,889 - INFO  [sparkDriver-akka.actor.default-dispatcher-3:a.e.s.Slf4jLogger@80] - Slf4jLogger started

2017-03-17 08:59:06,838 - WARN  [Driver:o.a.s.m.MetricsSystem@71] - Using default name DAGScheduler for source because spark.app.id is not set.

2) I find another issue that the log message contains another entire original message, for example:

2017-03-17 08:59:25,253 - WARN  [Executor task launch worker-0:o.a.s.e.CoarseGrainedExecutorBackend@91] - 17/03/17 08:59:25 INFO zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x6ffdfc2 connecting to ZooKeeper ensemble=c321shu.int.westgroup.com:2181,c149jub.int.westgroup.com:2181,c167rvm.int.westgroup.com:2181

Do you know why and how to solve or work around these 2 problems?

Thanks,

Chuncheng

[yao...@cask.co]

Hi Chuncheng,

I tested your logback.xml for an application on a cluster using cdap version 3.5.4 and it is working fine. To make your customized logback work, please do the following:

1. Make sure you put it under src/main/resources in your app directory, and after you build your app, check the jar file of the app contains the logback.xml file.

2. Once your app jar has the logback.xml, you need to delete your original app, artifact and redeploy it on cdap, otherwise your logback.xml will not get picked up.

3. It is recommended that you use the similar configuration in logback-container.xml under /etc/cdap/conf.dist/. It will generate program.log for your program and make it easier for you to see logs.

For your second problem, I am not able to reproduce. Can you please tell us more about the problem, like what spark version you used and more about the logs? Thank you!

Best and regards,

Yaojie Feng

[chuncheng...@gmail.com]

Hi Yaojie,

Just sent you an email with attachment, please have a look.

Thanks,

Chuncheng

[yao...@cask.co]

Hi Chuncheng,

I tested your application on a 3.5.4 cluster and the logs worked fine. So can you make sure: 1). No other logback.xml is in your app's classpath which try to override your logback.xml, 2) stop your application, stop your schedule for your workflow and redeploy the application to let cdap pick up your changes in logback.xml, 3) in your pom.xml, I noticed there are two dependencies which I cannot resolve dependency on my laptop, can you remove these two dependencies and the use of them and then try out if the logback.xml works, thank you!: 

        <dependency>

<groupId>com.trgr.cobalt.infrastructure</groupId>

<artifactId>ServiceRegistry</artifactId>

<version>34.1.0</version>

</dependency>

<dependency>

<groupId>com.trgr.cobalt.infrastructure</groupId>

<artifactId>loglayout</artifactId>

<version>34.1.0</version>

</dependency>

Best and regards,

Yaojie Feng

[Terence Yim]

Hi ChunCheng,

Would you mind sharing the content of your application jar as well? You can get the content by "jar -tf <app.jar>"

Terence

--
You received this message because you are subscribed to the Google Groups "CDAP User" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cdap-user+...@googlegroups.com.
To post to this group, send email to cdap...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/cdap-user/a4684ba8-f68e-441c-ad61-d91b853c3a0b%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[chuncheng...@gmail.com]

Hi Terence,

I've replied your email yesterday. Would you please take a look?

Thanks,

Chuncheng

[Terence Yim]

Hi,

Your jar file layout looks correct. However, due to the bug that Yaojie mentioned earlier that the root log level is always info, turning individual logger to higher level is not enough. Logback logger by default has additively set to true, meaning it will always goes up the logger hierarchy to call log appenders. Hence, even you suppressed with <logger name=“co.cask.cdap” level=“ERROR/>, logback will still go up the hierarchy and eventually reached the root logger, which log as INFO level, hence the logs get emitted. One quick way to workaround it is to have

<logger name="co.cask.cdap" level="ERROR" additivity="false" />

Terence

--
You received this message because you are subscribed to the Google Groups "CDAP User" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cdap-user+...@googlegroups.com.
To post to this group, send email to cdap...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/cdap-user/0c670ce2-468f-4a28-ac19-5f5d531a9fa0%40googlegroups.com.

[chuncheng...@gmail.com]

Hi Terence,

Adding additivity="false" doesn't work...

Below is my new logback.xml and I can still see these logs.

<?xml version="1.0" encoding="UTF-8"?>

<!-- Logback used by containers that run in YARN eg. Flows, MR, Explore -->

<configuration>

<!-- Disabling some chatty loggers. -->

<logger name="org.apache.commons.beanutils" level="ERROR" additivity="false"/>

<logger name="org.apache.zookeeper.server" level="ERROR" additivity="false"/>

<logger name="org.apache.zookeeper" level="ERROR" additivity="false"/>

<logger name="com.ning" level="WARN" additivity="false"/>

<logger name="org.apache.spark" level="ERROR" additivity="false"/>

<logger name="org.spark-project" level="WARN" additivity="false"/>

<logger name="org.apache.hadoop" level="WARN" additivity="false"/>

<logger name="org.apache.hive" level="WARN" additivity="false"/>

<logger name="org.quartz.core" level="WARN" additivity="false"/>

<logger name="org.eclipse.jetty" level="WARN" additivity="false"/>

<logger name="io.netty.util.internal" level="WARN" additivity="false"/>

<logger name="org.apache.twill" level="WARN" additivity="false"/>

<logger name="co.cask.cdap" level="ERROR" additivity="false"/>

<logger name="com.ccliu.test" level="INFO" additivity="false"/>

<logger name="akka.event.slf4j" level="ERROR" additivity="false"/>

<appender name="Console" class="ch.qos.logback.core.ConsoleAppender">

<encoder>

<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{5} - %msg%n

</pattern>

</encoder>

</appender>

<root level="INFO">

[yao...@cask.co]

Hi Chuncheng,

I tried your application on a 3.5 cluster by removing these two dependencies since I cannot build your app with them: 

<dependency>

        <groupId>com.trgr.cobalt.infrastructure</groupId>

        <artifactId>ServiceRegistry</artifactId>

<version>34.1.0</version>

</dependency>

<dependency>

<groupId>com.trgr.cobalt.infrastructure</groupId>

<artifactId>loglayout</artifactId>

<version>34.1.0</version>

</dependency>

And here is the log I see for the spark driver:

Launch class org.apache.spark.deploy.yarn.ApplicationMaster by calling co.cask.cdap.app.runtime.spark.distributed.SparkContainerLauncher.launch
LOGBACK: No context given for co.cask.cdap.logging.appender.kafka.KafkaLogAppender[KafkaLogAppender]
19:32:41.207 [main] WARN  o.a.h.u.NativeCodeLoader - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
19:32:43.417 [NettyHttpService STARTING] INFO  c.c.h.NettyHttpService - Starting SparkTransactionService http service on address logtestforuser20522-1000.dev.continuuity.net/10.128.0.23:0...
19:32:43.510 [NettyHttpService STARTING] INFO  c.c.h.NettyHttpService - Started SparkTransactionService http service on address /10.128.0.23:33414
19:32:44.403 [sparkDriver-akka.actor.default-dispatcher-2] INFO  Remoting - Starting remoting
19:32:44.559 [sparkDriver-akka.actor.default-dispatcher-2] INFO  Remoting - Remoting started; listening on addresses :[akka.tcp://spark...@10.128.0.23:42620]
19:33:07.502 [Driver] INFO  c.c.t.s.ExceptionArchive - Hello world. - info
19:33:07.503 [Driver] WARN  c.c.t.s.ExceptionArchive - Hello world. - warn
19:33:07.797 [sparkDriver-akka.actor.default-dispatcher-3] INFO  a.r.RemoteActorRefProvider$RemotingTerminator - Shutting down remote daemon.
19:33:07.800 [sparkDriver-akka.actor.default-dispatcher-3] INFO  a.r.RemoteActorRefProvider$RemotingTerminator - Remote daemon shut down; proceeding with flushing remote transports.
19:33:07.829 [NettyHttpService STOPPING] INFO  c.c.h.NettyHttpService - Stopping SparkTransactionService http service on address /10.128.0.23:33414...
19:33:07.842 [NettyHttpService STOPPING] INFO  c.c.h.NettyHttpService - Stopped SparkTransactionService http service on address /10.128.0.23:33414
19:33:07.846 [sparkDriver-akka.actor.default-dispatcher-3] INFO  a.r.RemoteActorRefProvider$RemotingTerminator - Remoting shut down.
Shutting SparkClassLoader services
SparkClassLoader services shutdown completed: [com.google.common.util.concurrent.AbstractService$Transition@352e4515, com.google.common.util.concurrent.AbstractService$Transition@70b980f9, com.google.common.util.concurrent.AbstractService$Transition@22c29540, com.google.common.util.concurrent.AbstractService$Transition@14d4ae94, com.google.common.util.concurrent.AbstractService$Transition@7e3b5451, com.google.common.util.concurrent.AbstractService$Transition@691cd295]

In the logs I did not any logs on co.cask.cdap and org.apache.spark show up, can you try to remove the dependencies mentioned above and try again to see if the logback is working?

Thank you!

Yaojie Feng

[chuncheng...@gmail.com]

Hi Yaojie,

Thanks for your information. I will do more test on this.

Best regards,

Chuncheng