ZOOKEEPER-1260:Audit logging in ZooKeeper servers. by arshadmohammad · Pull Request #338 · apache/zookeeper

arshadmohammad · 2017-08-21T19:15:06Z

Audit logging in ZooKeeper Servers.

hanm · 2017-08-22T04:28:59Z

      <jmx   label="JMX"                    href="zookeeperJMX.html" />
      <observers label="Observers Guide" href="zookeeperObservers.html" />
      <reconfig label="Dynamic Reconfiguration" href="zookeeperReconfig.html" />
+      <reconfig label="Audit Logging" href="zookeeperAuditLogs.html" />


Shouldn't this be something like <audit label="Audit Logging" href="zookeeperAuditLogs.html" /> rather than <reconfig ?

yes it should be <audit. Corrected it

hanm

Nice work. Some quick comments. Also please fix FindBug warnings as they are legitimate.

hanm · 2017-08-22T04:29:28Z

+                    <emphasis role="bold">zookeeper.audit.enabled</emphasis>)
+                </para>
+                <para>
+                    <emphasis role="bold">New in 3.5.3:</emphasis>


This should be 3.5.4 at least. We've shipped 3.5.3 already :)

corrected it

hanm · 2017-08-22T04:30:12Z

+        </imageobject>
+    </mediaobject>
+    <para>The audit log captures the detailed information for the operations that are selected to be audited. The audit
+    information is written as a set of key=value pairs for the following keys</para>


Nit: missing full stop after following keys

Corrected it

afine · 2017-08-25T20:13:22Z

+audit.logger=INFO, RFAAUDIT
+log4j.logger.org.apache.zookeeper.audit.ZKAuditLogger=${audit.logger}
+log4j.additivity.org.apache.zookeeper.audit.ZKAuditLogger=false
+log4j.appender.RFAAUDIT=org.apache.log4j.RollingFileAppender


I'm sure this is a very dumb question, why is this called RFAAUDIT?

It is very valid question. By RFAAUDIT i meant Rolling File Audit. Also one A is extra by mistake. I think it is better to change the name to AUDITFILE.

afine · 2017-08-25T20:13:53Z

+log4j.appender.RFAAUDIT=org.apache.log4j.RollingFileAppender
+log4j.appender.RFAAUDIT.File=${zookeeper.log.dir}/${zookeeper.auditlog.file}
+log4j.appender.RFAAUDIT.layout=org.apache.log4j.PatternLayout
+log4j.appender.RFAAUDIT.layout.ConversionPattern=%d{ISO8601} %p %c{2}: %m%n


Why don't we use the same conversion pattern as the other log types?

Logging is done only from one class, which thread is logging is not important. so only required parameters are logged.

afine · 2017-08-25T20:14:35Z

      <li><a href="zookeeperHierarchicalQuorums.html">Hierarchical quorums</a></li>
      <li><a href="zookeeperObservers.html">Observers</a> - non-voting ensemble members that easily improve ZooKeeper's scalability</li>
      <li><a href="zookeeperReconfig.html">Dynamic Reconfiguration</a> - a guide on how to use dynamic reconfiguration in ZooKeeper</li>
+      <li><a href="zookeeperAuditLogs.html">Audit Logging</a> - a guide on how to configure audit logs in ZooKeeper Server and what contents are logged.</li>


nit: I don't think we need the "and what contents are logged."

afine · 2017-08-25T20:15:37Z

+                </para>
+                <para>
+                    <emphasis role="bold">New in 3.5.4:</emphasis>
+                    By default audit logs are disabled. Set to "true" to enable this feature. Default is "false". See


nit: We don't need to tell the user what the default is twice.

afine · 2017-08-25T20:16:13Z

+  </articleinfo>
+  <section id="ch_auditLogs">
+    <title>ZooKeeper Audit Logs</title>
+    <para>Apache ZooKeeper supports audit logs form version 3.5.4. By default audit logs are disabled. To enable audit


"from version"

afine · 2017-08-25T22:00:57Z

        return request.cnxn == null;
    }

+    private String getHostAddress(ServerCnxn cnxn) {


perhaps we could do this logic in ServerCnxn?

afine · 2017-08-25T22:06:58Z

     */
    static final ByteBuffer closeConn = ByteBuffer.allocate(0);

+    private static String loginUser = System.getProperty("user.name", "<NA>");


Not sure I understand what this represents

loginUser is the user who started zk server.

Perhaps this can be renamed? Maybe "serverUser" or something to clarify this is not the same thing as the user "logged in" on the client. Or at least a comment.

changed to serverUser

afine · 2017-08-25T22:08:07Z

+ */
+package org.apache.zookeeper.server.util;
+
+import static org.junit.Assert.*;


nit: avoid * imports

afine · 2017-08-25T22:08:33Z

+
+    @Test
+    public void testGetUserFromAllAuthenticationScheme() {
+        System.setProperty("zookeeper.authProvider.sasl",


Do we have/need a test for custom authentication schemes?

only digest authentication is different, rest all are same. That is why not needed.

afine · 2017-08-25T22:15:58Z

+    private ZooKeeper zk;
+
+    @Test
+    public void testAuditLogs() throws Exception {


I really like this integration test. I think it would be great if it was a little more rigorous.

Would it be possible to use multiple auth providers oruse multiple servers and make sure logs are only appearing on the correct server?

Authentication provider make difference only for user attribute, rest all audit log attributes will remain same.
Test is already running on 3 node cluster. It is validating number of audit entries but in total. Not on which server. In all the cases expected number of entry is either 1 or three. In case of 1 entry test case currently not checking on which specific server entry is expected. But I think it is fine.

arshadmohammad · 2017-09-04T19:58:09Z

Thanks @hanm @afine for reviewing this feature. I have addressed all the comments, Please have a look.

hanm · 2017-09-11T20:19:28Z

+zookeeper.auditlog.threshold=INFO
+audit.logger=INFO, AUDITFILE
+log4j.logger.org.apache.zookeeper.audit.ZKAuditLogger=${audit.logger}
+log4j.additivity.org.apache.zookeeper.audit.ZKAuditLogger=false


I think something like this would be better here (see how HDFS defines audit log properties for example).
log4j.additivity.org.apache.zookeeper.audit = false
or
log4j.additivity.org.apache.zookeeper.audit.enabled = false

log4j.additivity.org.apache.zookeeper.audit = false is superset configuration of log4j.additivity.org.apache.zookeeper.audit.ZKAuditLogger=false
As all the all audit logging is done through ZKAuditLogger it is ok to configure only this

hanm · 2017-09-11T20:21:27Z

+audit.logger=INFO, AUDITFILE
+log4j.logger.org.apache.zookeeper.audit.ZKAuditLogger=${audit.logger}
+log4j.additivity.org.apache.zookeeper.audit.ZKAuditLogger=false
+log4j.appender.AUDITFILE=org.apache.log4j.RollingFileAppender


How is the rolling of the audit log file defined? Is it controlled by the log4j.appender.AUDITFILE.Threshold property?

Should we also add something like DailyRollingFileAppender and a date pattern property as another alternative for rolling logs?

rolling of the audit log file is defined by following properties
log4j.appender.RFAAUDIT=org.apache.log4j.RollingFileAppender

Max log file size of 10MB

log4j.appender.RFAAUDIT.MaxFileSize=10MB
log4j.appender.RFAAUDIT.MaxBackupIndex=10

hanm · 2017-09-11T20:27:03Z

+    public static final String KEY_VAL_SEPARATOR = "=";
+    public static final char PAIR_SEPARATOR = '\t';
+
+    public static final String OP_START = "serverStart";


I think we should not expose the internal op codes, etc to end users, through API or through the public constant definition included in this patch. We can get rid of the constants definitions here and instead, whenever we want to audit log something we create the operation string on site and directly pass the string to the audit event function call. Something like:
case OpCode.create: subResult = new CreateResult(subTxnResult.path); addSuccessAudit(request, cnxn, "create", subTxnResult.path); break;
This approach seems make the maintain overhead low as we don't have to worry about the correlations between various op codes definitions and the only catch is we might have to duplicate the op code string in different places if we audit logging same thing in different places - but in this case it seems the cost of duplication is low comparing to maintaining explicit op constants.

I also checked HDFS code base and it took a similar approach.

hanm · 2017-09-11T20:33:06Z

@arshadmohammad Audit logging, when enabled, will for sure degrade performance as it adds additional IO cost. Have you done any sort of performance evaluation so we can roughly get an idea of what kind of performance expectation we should have when audit logging is enabled?

Depends on how the performance degraded on different use cases, you might want to consider adding an async version of audit logging otherwise this feature might not be usable (note I am just guessing on the perf numbers here). Similar case happened on HDFS where an async audit logging was added to avoid degrading performance on hotspots.

pmoust · 2018-04-23T11:54:50Z

@arshadmohammad I'd also be curious as to the perf implications of this, have you run a load test-suite against this?

anmolnar

This would be a very great addition to 3.5 version. I only have a few nitpick and I think it'd also very useful to get some insight into the performance implications of this patch.

anmolnar · 2018-04-23T15:07:58Z

+     *            ACL permissions
+     * @return string representation of permissions
+     */
+    public static String getPermString(int perms) {


Have you considered caching these values in some way?
I see 2 options to make this faster:

dynamic caching of already generated values,

static caching of all possible values in a static hashmap (32 possible values if I'm not mistaken)

Good suggestion
selecting dynamic caching

anmolnar · 2018-04-23T15:14:00Z

+     */
+    public static String createLog(String user, String operation, String znode, String acl, String session, String ip,
+            String status) {
+        ZKAuditLogFormatter fmt = new ZKAuditLogFormatter();


If I got it right, this is the only place where you use ZKAuditLogFormatter. Why don't you just use String.format() instead of a custom formatter?

ZKAuditLogFormatter is not putting info for which value is null. I think we can not do with String.format()

anmolnar · 2018-04-23T15:16:18Z

                lastOp = "SETA";
                rsp = new SetACLResponse(rc.stat);
                err = Code.get(rc.err);
+                addAuditLog(request, cnxn, AuditConstants.OP_SETACL, rc.path, getACLs(request),


I believe this approach has some performance impact even if audit logging is disabled. The flag gets checked within the method, therefore getACLs() will be evaluated even if there's no need for the result.
Passing only request and calling getACLs() from addAuditLog() would be slightly faster.

corrected, added one more check at the before making audit log itself
if (ZKAuditLogger.isAuditEnabled()) {
addAuditLog(request, cnxn, AuditConstants.OP_SETACL, rc.path, getACLs(request), err);
}

anmolnar · 2018-04-23T15:21:17Z

+        return ZKUtil.aclToString(setACLRequest.getAcl());
+    }
+
+    private void addFailedTxnAduitLog(Request request) {


anmolnar · 2018-04-23T15:22:38Z

+            case OpCode.delete:
+            case OpCode.deleteContainer:
+                op = AuditConstants.OP_DELETE;
+                //path = new String(request.request.array());


Please the commented line.

anmolnar · 2018-06-25T15:12:50Z

@arshadmohammad Can we move on with this great new feature?

arshadmohammad · 2018-09-17T13:54:14Z

Hi all, please find performance impact analysis in jira comments.

pmoust · 2018-09-17T14:04:51Z

@arshadmohammad hm - there don't seem to be any(?)

arshadmohammad · 2018-09-17T17:50:37Z

@pmoust I was pointing to comments: 1, 2 and 3

s4s0l · 2019-09-03T20:21:51Z

What is the status of this MR?

hanm reviewed Aug 22, 2017

View reviewed changes

hanm requested changes Aug 22, 2017

View reviewed changes

afine requested changes Aug 25, 2017

View reviewed changes

hanm requested changes Sep 11, 2017

View reviewed changes

anmolnar requested changes Apr 23, 2018

View reviewed changes

ZOOKEEPER-1260:Audit logging in ZooKeeper Servers.

ee25bc0

ZOOKEEPER-1260: Review comment fix

e0528ff

arshadmohammad closed this Sep 22, 2019

arshadmohammad mentioned this pull request Oct 2, 2019

ZOOKEEPER-1260:Audit logging in ZooKeeper servers. #1105

Closed

Uh oh!

Conversation

arshadmohammad commented Aug 21, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

hanm left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

arshadmohammad commented Sep 4, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Max log file size of 10MB

Uh oh!

Choose a reason for hiding this comment

Uh oh!

hanm commented Sep 11, 2017

Uh oh!

pmoust commented Apr 23, 2018

Uh oh!