ZOOKEEPER-3083: Remove some redundant and noisy log lines #561

enixon · 2018-07-05T23:31:01Z

No description provided.

maoling · 2018-07-06T03:57:35Z

@enixon It seems that your IDE also makes some noises(grin)

enixon · 2018-07-06T18:10:25Z

Rolling back the unnecessary changes :)

The failing test was DisconnectedWatcherTest::testManyChildWatchersAutoReset. It is unrelated to my change and will not repro locally. Retrying with next commit.

hanm · 2018-07-07T05:01:34Z

src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java

@@ -754,7 +754,7 @@ public void finishSessionInit(ServerCnxn cnxn, boolean valid) {
            cnxn.sendBuffer(bb);

            if (valid) {
-                LOG.info("Established session 0x"
+                LOG.debug("Established session 0x"


This sounds pretty useful INFO level log. If we turn it into DEBUG level, are there any other equivalent INFO level logging where we can derive the session establishment details? If not, probably better to leave this as INFO?

I'd leave this one as INFO too.

i think this should go to debug. if you have thousands of clients that are reconnecting after a leader change the log fills with these. if you are really interested in this line you can add a log4j config that will show it. but this really creates a lot of noise in the log.

The attributes of an established connection don't appear in other INFO logs but remain accessible through jmx and through ServerCnxn::dumpConnectionInfo via 'cons'.

I'd agree with Ben that this is makes parsing the logs hard when the number of client connections is high and that it's better to isolate it via log level so it can be turned off in that scenario or turned on (via debug) if needed for low client-supporting ensembles.

anmolnar

Thanks for the cleanup initiative @enixon .
A few nitpicks from me.

anmolnar · 2018-07-09T12:35:46Z

src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java

-                    + cnxn.getRemoteSocketAddress());
-            createSession(cnxn, passwd, sessionTimeout);
+            long id = createSession(cnxn, passwd, sessionTimeout);
+            LOG.info("Client attempting to establish new session: session = 0x"


I like these ones. Would you please use the message formatter of the logging lib? e.g. "... {}... {}", a,b

shouldn't this also be debug like the other session messages?

anmolnar · 2018-07-09T12:36:25Z

src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java

@@ -754,7 +754,7 @@ public void finishSessionInit(ServerCnxn cnxn, boolean valid) {
            cnxn.sendBuffer(bb);

            if (valid) {
-                LOG.info("Established session 0x"
+                LOG.debug("Established session 0x"


I'd leave this one as INFO too.

anmolnar · 2018-07-09T12:43:10Z

src/java/main/org/apache/zookeeper/server/PrepRequestProcessor.java

-                                    + request.toString() + " aborting remaining multi ops."
-                                    + " Error Path:" + e.getPath()
-                                    + " Error:" + e.getMessage());
+                            if (e.code().intValue() > Code.APIERROR.intValue()) {


Does this mean that we don't want to log system errors at all?
Or I might be missing something here.

Additionally refactoring this one to use message formatter would be nice.

this one really seems like a debug level to me. the issue is that the client request tried to do something create a node that already exists. these are very normal cases that the client is probably expecting (in the case of leader election, for example). we shouldn't be logging this kind of expected behavior for common operations as INFO

I get the point - things will break when they are running at scale :) . I don't have strong opinion holding this as INFO. wondering how others think about this (I mentioned it's info as this log was my good friend before when I debugged some issues...).

BTW for similar use case (large scale of clients) - it looks like all client side related log should be silenced on server side. basically server side just keep server specific loggings on by default (which hopefully does not change regardless of the scale of clients). So all client cnx / session related logs need be silenced...

Exactly.

I'll fix up the format of this log line and the others as well.

anmolnar · 2018-07-09T12:43:28Z

src/java/main/org/apache/zookeeper/server/PrepRequestProcessor.java

-                    + " Error Path:" + e.getPath()
-                    + " Error:" + e.getMessage());
+
+            if (e.code().intValue() > Code.APIERROR.intValue()) {


i feel the same as above here.

breed

we have way to much log spam! thanx for doing this!

breed · 2018-07-10T11:09:13Z

src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java

@@ -754,7 +754,7 @@ public void finishSessionInit(ServerCnxn cnxn, boolean valid) {
            cnxn.sendBuffer(bb);

            if (valid) {
-                LOG.info("Established session 0x"
+                LOG.debug("Established session 0x"


i think this should go to debug. if you have thousands of clients that are reconnecting after a leader change the log fills with these. if you are really interested in this line you can add a log4j config that will show it. but this really creates a lot of noise in the log.

breed · 2018-07-10T11:10:14Z

src/java/main/org/apache/zookeeper/jmx/MBeanRegistry.java

-            if (LOG.isInfoEnabled()) {
-                LOG.info("Unregister MBean [{}]", objName);
-            }
+            LOG.debug("Unregister MBean [{}]", objName);


any idea why this was in an if clause before. i don't think it was needed, but just checking.

this sounds an optimization as with the if clause presence, if the log is not enabled the objName is not copied which might help if copying objName is expensive. sounds not a very big deal (and i noticed we have two inconsistent logging style in code base, with or without this if clause, might worth a clean up).

Right. And this where using log4j message formatter comes important: if one use string.format() instead and not putting it inside an if block, the string will be formatted every time no matter if the log level is enabled.

breed · 2018-07-10T11:14:52Z

src/java/main/org/apache/zookeeper/server/PrepRequestProcessor.java

-                                    + request.toString() + " aborting remaining multi ops."
-                                    + " Error Path:" + e.getPath()
-                                    + " Error:" + e.getMessage());
+                            if (e.code().intValue() > Code.APIERROR.intValue()) {


this one really seems like a debug level to me. the issue is that the client request tried to do something create a node that already exists. these are very normal cases that the client is probably expecting (in the case of leader election, for example). we shouldn't be logging this kind of expected behavior for common operations as INFO

breed · 2018-07-10T11:15:17Z

src/java/main/org/apache/zookeeper/server/PrepRequestProcessor.java

-                    + " Error Path:" + e.getPath()
-                    + " Error:" + e.getMessage());
+
+            if (e.code().intValue() > Code.APIERROR.intValue()) {


i feel the same as above here.

breed · 2018-07-10T11:15:54Z

src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java

-                    + cnxn.getRemoteSocketAddress());
-            createSession(cnxn, passwd, sessionTimeout);
+            long id = createSession(cnxn, passwd, sessionTimeout);
+            LOG.info("Client attempting to establish new session: session = 0x"


shouldn't this also be debug like the other session messages?

breed · 2018-07-10T11:16:45Z

src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java

        } else {
            long clientSessionId = connReq.getSessionId();
-            LOG.info("Client attempting to renew session 0x"
+            LOG.info("Client attempting to renew session: session = 0x"


i feel this should be debug as well.

enixon

Thanks for bearing with the delay, I'll make the formatting changes requested.

enixon · 2018-07-18T20:41:09Z

src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java

@@ -754,7 +754,7 @@ public void finishSessionInit(ServerCnxn cnxn, boolean valid) {
            cnxn.sendBuffer(bb);

            if (valid) {
-                LOG.info("Established session 0x"
+                LOG.debug("Established session 0x"


The attributes of an established connection don't appear in other INFO logs but remain accessible through jmx and through ServerCnxn::dumpConnectionInfo via 'cons'.

I'd agree with Ben that this is makes parsing the logs hard when the number of client connections is high and that it's better to isolate it via log level so it can be turned off in that scenario or turned on (via debug) if needed for low client-supporting ensembles.

enixon · 2018-07-18T20:42:42Z

src/java/main/org/apache/zookeeper/server/PrepRequestProcessor.java

-                                    + request.toString() + " aborting remaining multi ops."
-                                    + " Error Path:" + e.getPath()
-                                    + " Error:" + e.getMessage());
+                            if (e.code().intValue() > Code.APIERROR.intValue()) {


Exactly.

I'll fix up the format of this log line and the others as well.

Author: Brian Nixon <nixon@fb.com> Reviewers: Benjamin Reed <breed@apache.org>, Michael Han <hanm@apache.org>, Andor Molnar <andor@cloudera.com>, 毛蛤丝 <maoling199210191@sina.com> Closes #561 from enixon/ZOOKEEPER-3083 (cherry picked from commit f6bba09) Signed-off-by: Michael Han <hanm@apache.org>

hanm · 2018-07-19T04:00:51Z

Jenkins complained about a flaky test. LGTM overall. Committed.

Author: Brian Nixon <nixon@fb.com> Reviewers: Benjamin Reed <breed@apache.org>, Michael Han <hanm@apache.org>, Andor Molnar <andor@cloudera.com>, 毛蛤丝 <maoling199210191@sina.com> Closes apache#561 from enixon/ZOOKEEPER-3083

ZOOKEEPER-3083: Remove some redundant and noisy log lines

d995595

putting whitespace back

3a455b8

hanm reviewed Jul 7, 2018

View reviewed changes

anmolnar requested changes Jul 9, 2018

View reviewed changes

breed reviewed Jul 10, 2018

View reviewed changes

enixon commented Jul 18, 2018

View reviewed changes

use log4j message formatter for the changed log messages

6f9029d

hanm approved these changes Jul 19, 2018

View reviewed changes

asfgit closed this in f6bba09 Jul 19, 2018

enixon deleted the ZOOKEEPER-3083 branch July 19, 2018 18:53

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ZOOKEEPER-3083: Remove some redundant and noisy log lines #561

ZOOKEEPER-3083: Remove some redundant and noisy log lines #561

enixon commented Jul 5, 2018

maoling commented Jul 6, 2018

enixon commented Jul 6, 2018

hanm Jul 7, 2018

anmolnar Jul 9, 2018

breed Jul 10, 2018

enixon Jul 18, 2018

anmolnar left a comment

anmolnar Jul 9, 2018

breed Jul 10, 2018

anmolnar Jul 9, 2018

anmolnar Jul 9, 2018

anmolnar Jul 9, 2018

breed Jul 10, 2018

hanm Jul 10, 2018

enixon Jul 18, 2018

anmolnar Jul 9, 2018

breed Jul 10, 2018

breed left a comment

breed Jul 10, 2018

breed Jul 10, 2018

hanm Jul 10, 2018

anmolnar Jul 11, 2018

breed Jul 10, 2018

breed Jul 10, 2018

breed Jul 10, 2018

breed Jul 10, 2018

enixon left a comment

enixon Jul 18, 2018

enixon Jul 18, 2018

hanm commented Jul 19, 2018

ZOOKEEPER-3083: Remove some redundant and noisy log lines #561

ZOOKEEPER-3083: Remove some redundant and noisy log lines #561

Conversation

enixon commented Jul 5, 2018

maoling commented Jul 6, 2018

enixon commented Jul 6, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

anmolnar left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

breed left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

enixon left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hanm commented Jul 19, 2018