Enhance Auditor #1683

reddycharan · 2018-09-18T02:51:23Z

Descriptions of the changes in this PR:

store last checkAllLedgers executed time in metadataserver.
use that value for determining the initialDelay of checkAllLedgers call
add dedicated metric for bookieCheck
add more log lines in Auditor

Motivation

In Auditor checkAllLedgers is scheduled to run for every ‘auditorPeriodicCheckInterval’ and with initial delay of ‘auditorPeriodicCheckInterval’. But the problem is if Auditor role keeps transforming to another AR process, it might not get chance to do ‘checkAllLedgers’ task. Considering default value for 'auditorPeriodicCheckInterval' is 1 week, it is not uncommon situation.

Changes

Thats why I'm planning to persist last successful checkAllLedgers execution ctime in ZK, so that next time when a new AR becomes Auditor, it would use that as reference to decide the initial delay value.

reddycharan · 2018-09-18T02:51:58Z

@pasha-kuznetsov fyi

eolivelli

I wonder if we should provide some tool to reset the new item on ZK.
Maybe it is not very useful

Overall this change looks good to me, I left some nits

eolivelli · 2018-09-18T16:18:03Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/replication/Auditor.java

@@ -184,6 +186,7 @@ private void submitShutdownTask() {
            executor.submit(new Runnable() {
                    public void run() {
                        synchronized (Auditor.this) {
+                            LOG.error("Shutting down Auditor's Executor");


changed it to info

eolivelli · 2018-09-18T16:21:44Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/replication/Auditor.java

+                } catch (UnavailableException ue) {
+                    LOG.error("Got UnavailableException while trying to get checkAllLedgersCTime", ue);
+                }
+                long durationSinceLastExecutionInSecs = (System.currentTimeMillis() - checkAllLedgersLastExecutedCTime)


This will be weird if checkAllLedgersLastExecutedCTime is -1

Btw it will work

it was intentional, but i see your concern there. I'll make adjustments to make it more sensible.

eolivelli

+1 awesome work

sijie · 2018-09-21T00:55:25Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/ZkLedgerUnderreplicationManager.java

+
+    @Override
+    public void setCheckAllLedgersCTime(long checkAllLedgersCTime) throws UnavailableException {
+        LOG.debug("setCheckAllLedgersCTime");


nit : add if (LOG.isDebugEnabled())

sijie · 2018-09-21T00:56:20Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/ZkLedgerUnderreplicationManager.java

+
+    @Override
+    public long getCheckAllLedgersCTime() throws UnavailableException {
+        LOG.debug("getCheckAllLedgersCTime");


nit : add if (LOG.isDebugEnabled())

sijie · 2018-09-21T00:58:44Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/ZkLedgerUnderreplicationManager.java

+        LOG.debug("setCheckAllLedgersCTime");
+        try {
+            if (zkc.exists(checkAllLedgersCtimeZnode, false) != null) {
+                zkc.setData(checkAllLedgersCtimeZnode, Long.toString(checkAllLedgersCTime).getBytes(UTF_8), -1);


can you make a util function for Long.toString(checkAllLedgersCTime).getBytes(UTF_8)? I see it is used multiple places.

regardless, shall we consider using a protobuf structure for future extensibility?

added protobuf

sijie · 2018-09-21T00:59:55Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/ZkLedgerUnderreplicationManager.java

+        LOG.debug("getCheckAllLedgersCTime");
+        try {
+            byte[] data = zkc.getData(checkAllLedgersCtimeZnode, false, null);
+            return Long.parseLong(new String(data, UTF_8));


Long.parseLong will throw NumberFormatException. Can you catch that and return -1?

added protobuf

sijie

overall looks good. just one general comment, shall we be using protobuf for serializing metadata for future extensibility?

eolivelli · 2018-09-21T05:38:55Z

@sijie the idea about protobuf is good.
Let's elaborate this idea please

jvrao · 2018-09-21T06:23:43Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/ZkLedgerUnderreplicationManager.java

+            return Long.parseLong(new String(data, UTF_8));
+        } catch (KeeperException.NoNodeException ne) {
+            LOG.warn("checkAllLedgersCtimeZnode is not yet available");
+            return -1;


Why not create the node on auditor startup with -1; So the node exists all the time.

users are even able to delete the znode from zk manually, it is better not to have this assumption in this case.

we are in a big soup if the user deletes whatever they want. I would rather get an alert/error if that happens.

okay, makes sense.
I was just saying that in this case we can be somehow tolerant to this simple case.
in general if the user alters zk contents manually a big mess will happen

so okay to fail

we don't want this to be part of cluster initialization stuff, this is kind of good to have information but not must have. It brings unnecessary burden for cluster initialization part. For all practical purposes if zNode is not existing / not yet created or if there is an issue in reading this zNode, then lets consider it as '-1' and move forward.

Okay @reddycharan you are right

jvrao · 2018-09-21T06:30:47Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/replication/Auditor.java

@@ -184,6 +186,7 @@ private void submitShutdownTask() {
            executor.submit(new Runnable() {
                    public void run() {
                        synchronized (Auditor.this) {
+                            LOG.info("Shutting down Auditor's Executor");


Can't we just say - Shutting down the Auditor? 'executor' adds any value?

there is separate Auditor.shutDown method, i don't want to mix them up.

Anyhow I feel some more logging is needed for this method Auditor.submitShutdownTask

jvrao · 2018-09-21T06:42:52Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/replication/Auditor.java

+                } else {
+                    durationSinceLastExecutionInSecs = (System.currentTimeMillis() - checkAllLedgersLastExecutedCTime)
+                            / 1000;
+                    initialDelay = durationSinceLastExecutionInSecs > interval ? 0


Shouldn't it be reversed? i.e (interval > durationSinceLastExecutionInSecs) ?

I missed 0 in there.

jvrao · 2018-09-21T06:43:51Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/replication/Auditor.java

+                    durationSinceLastExecutionInSecs = -1;
+                    initialDelay = 0;
+                } else {
+                    durationSinceLastExecutionInSecs = (System.currentTimeMillis() - checkAllLedgersLastExecutedCTime)


This may become -ve due to time skews between machines. Check for -ve value. Especially given that you are logging this info below.

will fix that

jvrao · 2018-09-21T06:45:09Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/replication/Auditor.java

                                checkAllLedgers();
+                                LOG.info("Completed checkAllLedgers");


Since you added log info; add more info if possible. At least the time it took and maybe how many ledgers it checked??

there is metric right below for 'checkAllLedgersTime' and if checkAllLedgers succeeded then it should have checked all the ledgers, so not sure if it is the right place to expect / log that info.

anyhow added log for duration of execution

jvrao · 2018-09-21T06:50:16Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/replication/Auditor.java

+            try {
+                ledgerUnderreplicationManager.setCheckAllLedgersCTime(System.currentTimeMillis());
+            } catch (UnavailableException ue) {
+                LOG.error("Got exception while trying to set checkAllLedgersCTime", ue);


Since there is a potential to fail this, why not cache this value. and the auditor reads the zk only if the local/cached value is -1. A minor optimization and also saves us from this kind of errors.

didn't get you completely. Also not sure how cache would work in all the scenarios here.

Anyhow frequency of checkAllLedgers is quite low (once a week), I don't see much value in this minor optimization and not sure if it is worth complicating logic.

eolivelli · 2018-09-22T07:45:13Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/ZkLedgerUnderreplicationManager.java

+            CheckAllLedgersFormat.Builder builder = CheckAllLedgersFormat.newBuilder();
+            builder.setCheckAllLedgersCTime(checkAllLedgersCTime);
+            if (zkc.exists(checkAllLedgersCtimeZnode, false) != null) {
+                zkc.setData(checkAllLedgersCtimeZnode, TextFormat.printToString(builder.build()).getBytes(UTF_8), -1);


What about using binary format? This is new stuff, better not to start with forward/backward compatibility problems

changing to binary format

eolivelli · 2018-09-22T07:45:31Z

bookkeeper-proto/src/main/proto/DataFormats.proto

@@ -95,3 +95,10 @@ message LockDataFormat {
 message AuditorVoteFormat {
    optional string bookieId = 1;
 }
+
+/**
+ * Debug information for checkAllLedgers


This is not debug actually

changing description

eolivelli · 2018-09-22T07:46:12Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/ZkLedgerUnderreplicationManager.java

+            return Long.parseLong(new String(data, UTF_8));
+        } catch (KeeperException.NoNodeException ne) {
+            LOG.warn("checkAllLedgersCtimeZnode is not yet available");
+            return -1;


Okay @reddycharan you are right

sijie · 2018-09-25T17:39:20Z

@reddycharan : I think @eolivelli has some more comments here.

reddycharan · 2018-09-26T00:52:36Z

@eolivelli @sijie changed it to binary format.

eolivelli

+1 lgtm

Nice work !

sijie · 2018-09-26T18:36:25Z

this might require rebasing to master, otherwise it should be ready to go.

- store last checkAllLedgers executed time in metadataserver. - use that value for determining the initialDelay of checkAllLedgers call - add dedicated metric for bookieCheck - add more log lines in Auditor

- fixing spotbugs errors and review comments

- added protobuf message for CheckAllLedgers - code review comments

- use binary format for CheckAllLedgers protobuf message

reddycharan · 2018-09-26T19:48:51Z

@sijie yes working on rebasing

- rebasing master

reddycharan · 2018-09-26T20:21:09Z

rebased

eolivelli

I have a last comment about zk ACLs.
Overall is ok

eolivelli · 2018-09-26T20:28:19Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/ZkLedgerUnderreplicationManager.java

+            if (zkc.exists(checkAllLedgersCtimeZnode, false) != null) {
+                zkc.setData(checkAllLedgersCtimeZnode, checkAllLedgersFormatByteArray, -1);
+            } else {
+                zkc.create(checkAllLedgersCtimeZnode, checkAllLedgersFormatByteArray, Ids.OPEN_ACL_UNSAFE,


One last note: we should apply ZK ACLs according to server configuration

- get zkacls from config

reddycharan · 2018-09-26T21:00:49Z

@eolivelli fixed zkAcls

eolivelli

+1 great

reddycharan · 2018-09-27T23:55:55Z

good to go ?

sijie · 2018-09-28T00:40:24Z

@reddycharan if @jvrao is good about this, it is ready to go

sijie · 2018-09-28T00:40:44Z

run bookkeeper-server bookie tests
run pr validation

sijie · 2018-09-28T19:07:08Z

@reddycharan there are some checkstyle violations. can you take a look?

[ERROR] /home/jenkins/jenkins-slave/workspace/bookkeeper_precommit_pullrequest_validation/bookkeeper-server/src/main/java/org/apache/bookkeeper/replication/Auditor.java:415: Trailing whitespace [RegexpSingleline]
[ERROR] /home/jenkins/jenkins-slave/workspace/bookkeeper_precommit_pullrequest_validation/bookkeeper-server/src/test/java/org/apache/bookkeeper/replication/TestLedgerUnderreplicationManager.java:33: Import java.nio.charset.Charset appears after other imports that it should precede [ImportOrder]
[ERROR] /home/jenkins/jenkins-slave/workspace/bookkeeper_precommit_pullrequest_validation/bookkeeper-server/src/test/java/org/apache/bookkeeper/replication/AuditorPeriodicCheckTest.java:73:8: Unused import: org.apache.bookkeeper.zookeeper.ZooKeeperClient. [UnusedImports]
[ERROR] /home/jenkins/jenkins-slave/workspace/bookkeeper_precommit_pullrequest_validation/bookkeeper-server/src/test/java/org/apache/bookkeeper/replication/AuditorPeriodicCheckTest.java:75:8: Unused import: org.apache.zookeeper.ZooKeeper. [UnusedImports]
[ERROR] /home/jenkins/jenkins-slave/workspace/bookkeeper_precommit_pullrequest_validation/bookkeeper-server/src/test/java/org/apache/bookkeeper/replication/AuditorPeriodicCheckTest.java:411:39: Should use uppercase 'L'. [UpperEll]
[ERROR] /home/jenkins/jenkins-slave/workspace/bookkeeper_precommit_pullrequest_validation/bookkeeper-server/src/test/java/org/apache/bookkeeper/replication/AuditorPeriodicCheckTest.java:421:91: Should use uppercase 'L'. [UpperEll]
[ERROR] /home/jenkins/jenkins-slave/workspace/bookkeeper_precommit_pullrequest_validation/bookkeeper-server/src/test/java/org/apache/bookkeeper/replication/AuditorPeriodicCheckTest.java:423:90: Should use uppercase 'L'. [UpperEll]

- checksum validation fixes

reddycharan · 2018-09-28T20:53:15Z

@sijie where did you find those failures? this was the only failure job https://travis-ci.org/apache/bookkeeper/jobs/433747876 and it didn't provide the details.

BTW, this is the correct mvn command to run to validate the fix right? - "mvn clean install -DskipTests apache-rat:check spotbugs:check" iirc, i had successful mvn run for that commit.

Anyhow pushed new commit with the fixes.

reddycharan · 2018-09-29T00:48:08Z

@sijie issue is with CUSTOM_JDK="oraclejdk9" / continuous-integration/travis-ci/pr, not sure if there is something I can do to fix it.

sijie · 2018-09-30T18:43:45Z

run integration tests

sijie · 2018-10-01T03:57:28Z

I have tried to compile using java9, it seems that I can't reproduce the error we are seen in travis. will try to look into it later again.

eolivelli · 2018-10-01T20:40:41Z

Seems a pernission error on Travis
home/travis/.m2/repository/org/apache/bookkeeper/tests/bookkeeper-server-compat420/4.7.0-SNAPSHOT/bookkeeper-server-compat420-4.7.0-SNAPSHOT.jar: Permission denied
/home/travis/.m2/repository/com/google/guava/guava/19.0/guava-19.0.jar: Permission denied

eolivelli · 2018-10-01T20:40:59Z

retest this please

reddycharan · 2018-10-02T00:30:24Z

@sijie is there anything we can do about it?

eolivelli · 2018-10-02T06:40:56Z

Maybe closing and reopening this pr will trigger a fresh new run of tests

sijie · 2018-10-02T17:37:59Z

run integration tests
rebuild java8

eolivelli · 2018-10-02T17:39:49Z

I have forced travis with the button in Travis UI

sijie · 2018-10-02T17:41:12Z

@eolivelli there is a problem with jdk9 that we need to look into. and you don't need to restart the whole build, you can just restart the jdk9 one.

sijie · 2018-10-02T17:41:42Z

run integration tests

sijie · 2018-10-02T20:43:17Z

@reddycharan I am not able to figure out why travis is failing with oraclejdk9/linux. I am disabling travis oraclejdk9/linux for this PR, so you can be unblocked.

sijie · 2018-10-02T22:01:07Z

run pr validation

eolivelli reviewed Sep 18, 2018

View reviewed changes

eolivelli approved these changes Sep 19, 2018

View reviewed changes

sijie reviewed Sep 21, 2018

View reviewed changes

jvrao reviewed Sep 21, 2018

View reviewed changes

eolivelli reviewed Sep 22, 2018

View reviewed changes

eolivelli approved these changes Sep 26, 2018

View reviewed changes

sijie approved these changes Sep 26, 2018

View reviewed changes

reddycharan added 4 commits September 26, 2018 12:43

Enhance Auditor

87ad971

- store last checkAllLedgers executed time in metadataserver. - use that value for determining the initialDelay of checkAllLedgers call - add dedicated metric for bookieCheck - add more log lines in Auditor

Enhance Auditor

b51a12f

- fixing spotbugs errors and review comments

Enhance Auditor

e74cdd6

- added protobuf message for CheckAllLedgers - code review comments

Enhance Auditor

9fec42d

- use binary format for CheckAllLedgers protobuf message

Enhance Auditor

0c61c86

- rebasing master

reddycharan force-pushed the auditormetricslogs branch from ab472f9 to 0c61c86 Compare September 26, 2018 20:16

eolivelli requested changes Sep 26, 2018

View reviewed changes

Enhance Auditor

02805ab

- get zkacls from config

eolivelli approved these changes Sep 26, 2018

View reviewed changes

Enhance Auditor

ad61f1a

- checksum validation fixes

Merge remote-tracking branch 'apache/master' into auditormetricslogs

1e1fd41

jvrao approved these changes Sep 30, 2018

View reviewed changes

eolivelli closed this Oct 2, 2018

eolivelli reopened this Oct 2, 2018

Disable oraclejdk9/linux build on travis

946d72c

sijie added this to the 4.9.0 milestone Oct 3, 2018

sijie added area/autorecovery release/4.9.0 type/improvement labels Oct 3, 2018

sijie assigned reddycharan Oct 3, 2018

sijie merged commit 4dac14b into apache:master Oct 3, 2018

Enhance Auditor #1683

Enhance Auditor #1683

Conversation

reddycharan commented Sep 18, 2018

Motivation

Changes

reddycharan commented Sep 18, 2018

eolivelli 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

eolivelli 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

sijie left a comment

Choose a reason for hiding this comment

eolivelli commented Sep 21, 2018

jvrao Sep 21, 2018 • edited

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

reddycharan Sep 21, 2018 • edited

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

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

sijie commented Sep 25, 2018

reddycharan commented Sep 26, 2018

eolivelli left a comment

Choose a reason for hiding this comment

sijie commented Sep 26, 2018

reddycharan commented Sep 26, 2018

reddycharan commented Sep 26, 2018

eolivelli left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

reddycharan commented Sep 26, 2018

eolivelli left a comment

Choose a reason for hiding this comment

reddycharan commented Sep 27, 2018

sijie commented Sep 28, 2018

sijie commented Sep 28, 2018

sijie commented Sep 28, 2018

reddycharan commented Sep 28, 2018 • edited

reddycharan commented Sep 29, 2018

sijie commented Sep 30, 2018

sijie commented Oct 1, 2018

eolivelli commented Oct 1, 2018

eolivelli commented Oct 1, 2018

reddycharan commented Oct 2, 2018

eolivelli commented Oct 2, 2018

sijie commented Oct 2, 2018

eolivelli commented Oct 2, 2018

sijie commented Oct 2, 2018

sijie commented Oct 2, 2018

sijie commented Oct 2, 2018

jvrao Sep 21, 2018 •

edited

reddycharan Sep 21, 2018 •

edited

reddycharan commented Sep 28, 2018 •

edited