s4 dns_server Bind9: Log opertion durations
[samba.git] / source4 / dns_server / dlz_bind9.c
index 0e7fcfc2c2556c8b0baaf37a9ff6dce2dd59310f..5db1131e4dd9eb91d114192f4e68ded7bedef867 100644 (file)
@@ -82,6 +82,38 @@ static const char *zone_prefixes[] = {
        NULL
 };
 
+/*
+ * Get a printable string representation of an isc_result_t
+ */
+static const char *isc_result_str( const isc_result_t result) {
+       switch (result) {
+       case ISC_R_SUCCESS:
+               return "ISC_R_SUCCESS";
+       case ISC_R_NOMEMORY:
+               return "ISC_R_NOMEMORY";
+       case ISC_R_NOPERM:
+               return "ISC_R_NOPERM";
+       case ISC_R_NOSPACE:
+               return "ISC_R_NOSPACE";
+       case ISC_R_NOTFOUND:
+               return "ISC_R_NOTFOUND";
+       case ISC_R_FAILURE:
+               return "ISC_R_FAILURE";
+       case ISC_R_NOTIMPLEMENTED:
+               return "ISC_R_NOTIMPLEMENTED";
+       case ISC_R_NOMORE:
+               return "ISC_R_NOMORE";
+       case ISC_R_INVALIDFILE:
+               return "ISC_R_INVALIDFILE";
+       case ISC_R_UNEXPECTED:
+               return "ISC_R_UNEXPECTED";
+       case ISC_R_FILENOTFOUND:
+               return "ISC_R_FILENOTFOUND";
+       default:
+               return "UNKNOWN";
+       }
+}
+
 /*
   return the version of the API
  */
@@ -926,8 +958,18 @@ _PUBLIC_ isc_result_t dlz_findzonedb(void *dbdata, const char *name,
                                     dns_clientinfo_t *clientinfo)
 #endif
 {
+       struct timeval start = timeval_current();
        struct dlz_bind9_data *state = talloc_get_type_abort(dbdata, struct dlz_bind9_data);
-       return b9_find_zone_dn(state, name, NULL, NULL);
+       isc_result_t result = ISC_R_SUCCESS;
+
+       result = b9_find_zone_dn(state, name, NULL, NULL);
+        DNS_COMMON_LOG_OPERATION(
+               isc_result_str(result),
+               &start,
+               NULL,
+               name,
+               NULL);
+       return result;
 }
 
 
@@ -1040,7 +1082,18 @@ _PUBLIC_ isc_result_t dlz_lookup(const char *zone, const char *name,
 #endif
 {
        struct dlz_bind9_data *state = talloc_get_type_abort(dbdata, struct dlz_bind9_data);
-       return dlz_lookup_types(state, zone, name, lookup, NULL);
+       isc_result_t result = ISC_R_SUCCESS;
+       struct timeval start = timeval_current();
+
+       result = dlz_lookup_types(state, zone, name, lookup, NULL);
+       DNS_COMMON_LOG_OPERATION(
+               isc_result_str(result),
+               &start,
+               zone,
+               name,
+               NULL);
+
+       return result;
 }
 
 
@@ -1061,6 +1114,7 @@ _PUBLIC_ isc_result_t dlz_allowzonexfr(void *dbdata, const char *name, const cha
 _PUBLIC_ isc_result_t dlz_allnodes(const char *zone, void *dbdata,
                                   dns_sdlzallnodes_t *allnodes)
 {
+       struct timeval start = timeval_current();
        struct dlz_bind9_data *state = talloc_get_type_abort(dbdata, struct dlz_bind9_data);
        const char *attrs[] = { "dnsRecord", NULL };
        int ret = LDB_ERR_NO_SUCH_OBJECT;
@@ -1069,6 +1123,7 @@ _PUBLIC_ isc_result_t dlz_allnodes(const char *zone, void *dbdata,
        struct ldb_result *res;
        TALLOC_CTX *tmp_ctx = talloc_new(state);
        struct ldb_val zone_name_val = data_blob_string_const(zone);
+       isc_result_t result = ISC_R_SUCCESS;
 
        for (i=0; zone_prefixes[i]; i++) {
                const char *casefold;
@@ -1076,7 +1131,8 @@ _PUBLIC_ isc_result_t dlz_allnodes(const char *zone, void *dbdata,
                dn = ldb_dn_copy(tmp_ctx, ldb_get_default_basedn(state->samdb));
                if (dn == NULL) {
                        talloc_free(tmp_ctx);
-                       return ISC_R_NOMEMORY;
+                       result = ISC_R_NOMEMORY;
+                       goto exit;
                }
 
                /*
@@ -1089,7 +1145,8 @@ _PUBLIC_ isc_result_t dlz_allnodes(const char *zone, void *dbdata,
                                          "DC=X,%s",
                                          zone_prefixes[i])) {
                        talloc_free(tmp_ctx);
-                       return ISC_R_NOMEMORY;
+                       result = ISC_R_NOMEMORY;
+                       goto exit;
                }
 
                ret = ldb_dn_set_component(dn,
@@ -1098,7 +1155,8 @@ _PUBLIC_ isc_result_t dlz_allnodes(const char *zone, void *dbdata,
                                           zone_name_val);
                if (ret != LDB_SUCCESS) {
                        talloc_free(tmp_ctx);
-                       return ISC_R_NOMEMORY;
+                       result = ISC_R_NOMEMORY;
+                       goto exit;
                }
 
                /*
@@ -1109,7 +1167,8 @@ _PUBLIC_ isc_result_t dlz_allnodes(const char *zone, void *dbdata,
                casefold = ldb_dn_get_casefold(dn);
 
                if (casefold == NULL) {
-                       return ISC_R_NOTFOUND;
+                       result = ISC_R_NOTFOUND;
+                       goto exit;
                }
 
                ret = ldb_search(state->samdb, tmp_ctx, &res, dn, LDB_SCOPE_SUBTREE,
@@ -1120,7 +1179,8 @@ _PUBLIC_ isc_result_t dlz_allnodes(const char *zone, void *dbdata,
        }
        if (ret != LDB_SUCCESS || dn == NULL) {
                talloc_free(tmp_ctx);
-               return ISC_R_NOTFOUND;
+               result = ISC_R_NOTFOUND;
+               goto exit;
        }
 
        for (i=0; i<res->count; i++) {
@@ -1151,7 +1211,8 @@ _PUBLIC_ isc_result_t dlz_allnodes(const char *zone, void *dbdata,
                rdn = talloc_strndup(el_ctx, (char *)v->data, v->length);
                if (rdn == NULL) {
                        talloc_free(tmp_ctx);
-                       return ISC_R_NOMEMORY;
+                       result = ISC_R_NOMEMORY;
+                       goto exit;
                }
 
                if (strcmp(rdn, "@") == 0) {
@@ -1162,7 +1223,8 @@ _PUBLIC_ isc_result_t dlz_allnodes(const char *zone, void *dbdata,
                name = b9_format_fqdn(el_ctx, name);
                if (name == NULL) {
                        talloc_free(tmp_ctx);
-                       return ISC_R_NOMEMORY;
+                       result = ISC_R_NOMEMORY;
+                       goto exit;
                }
 
                werr = dns_common_extract(state->samdb, el, el_ctx, &recs, &num_recs);
@@ -1174,10 +1236,10 @@ _PUBLIC_ isc_result_t dlz_allnodes(const char *zone, void *dbdata,
                }
 
                for (j=0; j < num_recs; j++) {
-                       isc_result_t result;
+                       isc_result_t rc;
 
-                       result = b9_putnamedrr(state, allnodes, name, &recs[j]);
-                       if (result != ISC_R_SUCCESS) {
+                       rc = b9_putnamedrr(state, allnodes, name, &recs[j]);
+                       if (rc != ISC_R_SUCCESS) {
                                continue;
                        }
                }
@@ -1186,8 +1248,14 @@ _PUBLIC_ isc_result_t dlz_allnodes(const char *zone, void *dbdata,
        }
 
        talloc_free(tmp_ctx);
-
-       return ISC_R_SUCCESS;
+exit:
+       DNS_COMMON_LOG_OPERATION(
+               isc_result_str(result),
+               &start,
+               zone,
+               NULL,
+               NULL);
+       return result;
 }
 
 
@@ -1196,30 +1264,41 @@ _PUBLIC_ isc_result_t dlz_allnodes(const char *zone, void *dbdata,
  */
 _PUBLIC_ isc_result_t dlz_newversion(const char *zone, void *dbdata, void **versionp)
 {
+       struct timeval start = timeval_current();
        struct dlz_bind9_data *state = talloc_get_type_abort(dbdata, struct dlz_bind9_data);
+       isc_result_t result = ISC_R_SUCCESS;
 
        state->log(ISC_LOG_INFO, "samba_dlz: starting transaction on zone %s", zone);
 
        if (state->transaction_token != NULL) {
                state->log(ISC_LOG_INFO, "samba_dlz: transaction already started for zone %s", zone);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        state->transaction_token = talloc_zero(state, int);
        if (state->transaction_token == NULL) {
-               return ISC_R_NOMEMORY;
+               result = ISC_R_NOMEMORY;
+               goto exit;
        }
 
        if (ldb_transaction_start(state->samdb) != LDB_SUCCESS) {
                state->log(ISC_LOG_INFO, "samba_dlz: failed to start a transaction for zone %s", zone);
                talloc_free(state->transaction_token);
                state->transaction_token = NULL;
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        *versionp = (void *)state->transaction_token;
-
-       return ISC_R_SUCCESS;
+exit:
+       DNS_COMMON_LOG_OPERATION(
+               isc_result_str(result),
+               &start,
+               zone,
+               NULL,
+               NULL);
+       return result;
 }
 
 /*
@@ -1228,23 +1307,27 @@ _PUBLIC_ isc_result_t dlz_newversion(const char *zone, void *dbdata, void **vers
 _PUBLIC_ void dlz_closeversion(const char *zone, isc_boolean_t commit,
                               void *dbdata, void **versionp)
 {
+       struct timeval start = timeval_current();
        struct dlz_bind9_data *state = talloc_get_type_abort(dbdata, struct dlz_bind9_data);
+       const char *data = NULL;
+
+       data = commit ? "commit" : "cancel";
 
        if (state->transaction_token != (int *)*versionp) {
                state->log(ISC_LOG_INFO, "samba_dlz: transaction not started for zone %s", zone);
-               return;
+               goto exit;
        }
 
        if (commit) {
                if (ldb_transaction_commit(state->samdb) != LDB_SUCCESS) {
                        state->log(ISC_LOG_INFO, "samba_dlz: failed to commit a transaction for zone %s", zone);
-                       return;
+                       goto exit;
                }
                state->log(ISC_LOG_INFO, "samba_dlz: committed transaction on zone %s", zone);
        } else {
                if (ldb_transaction_cancel(state->samdb) != LDB_SUCCESS) {
                        state->log(ISC_LOG_INFO, "samba_dlz: failed to cancel a transaction for zone %s", zone);
-                       return;
+                       goto exit;
                }
                state->log(ISC_LOG_INFO, "samba_dlz: cancelling transaction on zone %s", zone);
        }
@@ -1252,6 +1335,14 @@ _PUBLIC_ void dlz_closeversion(const char *zone, isc_boolean_t commit,
        talloc_free(state->transaction_token);
        state->transaction_token = NULL;
        *versionp = NULL;
+
+exit:
+       DNS_COMMON_LOG_OPERATION(
+               isc_result_str(ISC_R_SUCCESS),
+               &start,
+               zone,
+               NULL,
+               data);
 }
 
 
@@ -1450,6 +1541,7 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
                                    const char *type, const char *key, uint32_t keydatalen, uint8_t *keydata,
                                    void *dbdata)
 {
+       struct timeval start = timeval_current();
        struct dlz_bind9_data *state = talloc_get_type_abort(dbdata, struct dlz_bind9_data);
        TALLOC_CTX *tmp_ctx;
        DATA_BLOB ap_req;
@@ -1462,13 +1554,14 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
        struct gensec_security *gensec_ctx;
        struct auth_session_info *session_info;
        struct ldb_dn *dn;
-       isc_result_t result;
+       isc_result_t rc;
        struct ldb_result *res;
        const char * attrs[] = { NULL };
        uint32_t access_mask;
        struct gensec_settings *settings = NULL;
        const struct gensec_security_ops **backends = NULL;
        size_t idx = 0;
+       isc_boolean_t result = ISC_FALSE;
 
        /* Remove cached credentials, if any */
        if (state->session_info) {
@@ -1483,7 +1576,8 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
        tmp_ctx = talloc_new(NULL);
        if (tmp_ctx == NULL) {
                state->log(ISC_LOG_ERROR, "samba_dlz: no memory");
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
 
        ap_req = data_blob_const(keydata, keydatalen);
@@ -1491,7 +1585,8 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
        if (!server_credentials) {
                state->log(ISC_LOG_ERROR, "samba_dlz: failed to init server credentials");
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
 
        cli_credentials_set_krb5_context(server_credentials, state->smb_krb5_ctx);
@@ -1503,7 +1598,8 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
        if (keytab_file == NULL) {
                state->log(ISC_LOG_ERROR, "samba_dlz: Out of memory!");
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
 
        if (!file_exist(keytab_file)) {
@@ -1513,7 +1609,8 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
                if (keytab_file == NULL) {
                        state->log(ISC_LOG_ERROR, "samba_dlz: Out of memory!");
                        talloc_free(tmp_ctx);
-                       return ISC_FALSE;
+                       result = ISC_FALSE;
+                       goto exit;
                }
        }
 
@@ -1521,7 +1618,8 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
        if (keytab_name == NULL) {
                state->log(ISC_LOG_ERROR, "samba_dlz: Out of memory!");
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
 
        ret = cli_credentials_set_keytab_name(server_credentials, state->lp, keytab_name,
@@ -1530,7 +1628,8 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
                state->log(ISC_LOG_ERROR, "samba_dlz: failed to obtain server credentials from %s",
                           keytab_name);
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
        talloc_free(keytab_name);
 
@@ -1538,14 +1637,16 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
        if (settings == NULL) {
                state->log(ISC_LOG_ERROR, "samba_dlz: lpcfg_gensec_settings failed");
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
        backends = talloc_zero_array(settings,
                                     const struct gensec_security_ops *, 3);
        if (backends == NULL) {
                state->log(ISC_LOG_ERROR, "samba_dlz: talloc_zero_array gensec_security_ops failed");
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
        settings->backends = backends;
 
@@ -1559,7 +1660,8 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
        if (!NT_STATUS_IS_OK(nt_status)) {
                state->log(ISC_LOG_ERROR, "samba_dlz: failed to start gensec server");
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
 
        gensec_set_credentials(gensec_ctx, server_credentials);
@@ -1568,7 +1670,8 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
        if (!NT_STATUS_IS_OK(nt_status)) {
                state->log(ISC_LOG_ERROR, "samba_dlz: failed to start spnego");
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
 
        /*
@@ -1587,22 +1690,25 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
        if (!NT_STATUS_IS_OK(nt_status)) {
                state->log(ISC_LOG_ERROR, "samba_dlz: spnego update failed");
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
 
        nt_status = gensec_session_info(gensec_ctx, tmp_ctx, &session_info);
        if (!NT_STATUS_IS_OK(nt_status)) {
                state->log(ISC_LOG_ERROR, "samba_dlz: failed to create session info");
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
 
        /* Get the DN from name */
-       result = b9_find_name_dn(state, name, tmp_ctx, &dn);
-       if (result != ISC_R_SUCCESS) {
+       rc = b9_find_name_dn(state, name, tmp_ctx, &dn);
+       if (rc != ISC_R_SUCCESS) {
                state->log(ISC_LOG_ERROR, "samba_dlz: failed to find name %s", name);
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
 
        /* make sure the dn exists, or find parent dn in case new object is being added */
@@ -1617,7 +1723,8 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
                talloc_free(res);
        } else {
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
 
        /* Do ACL check */
@@ -1629,7 +1736,8 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
                        "samba_dlz: disallowing update of signer=%s name=%s type=%s error=%s",
                        signer, name, type, ldb_strerror(ldb_ret));
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
 
        /* Cache session_info, so it can be used in the actual add/delete operation */
@@ -1637,7 +1745,8 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
        if (state->update_name == NULL) {
                state->log(ISC_LOG_ERROR, "samba_dlz: memory allocation error");
                talloc_free(tmp_ctx);
-               return ISC_FALSE;
+               result = ISC_FALSE;
+               goto exit;
        }
        state->session_info = talloc_steal(state, session_info);
 
@@ -1645,7 +1754,15 @@ _PUBLIC_ isc_boolean_t dlz_ssumatch(const char *signer, const char *name, const
                   signer, name, tcpaddr, type, key);
 
        talloc_free(tmp_ctx);
-       return ISC_TRUE;
+       result = ISC_TRUE;
+exit:
+       DNS_COMMON_LOG_OPERATION(
+               isc_result_str(result),
+               &start,
+               NULL,
+               name,
+               NULL);
+       return result;
 }
 
 /*
@@ -1775,10 +1892,11 @@ static void b9_reset_session_info(struct dlz_bind9_data *state)
  */
 _PUBLIC_ isc_result_t dlz_addrdataset(const char *name, const char *rdatastr, void *dbdata, void *version)
 {
+       struct timeval start = timeval_current();
        struct dlz_bind9_data *state = talloc_get_type_abort(dbdata, struct dlz_bind9_data);
        struct dnsp_DnssrvRpcRecord *rec;
        struct ldb_dn *dn;
-       isc_result_t result;
+       isc_result_t result = ISC_R_SUCCESS;
        bool tombstoned = false;
        bool needs_add = false;
        struct dnsp_DnssrvRpcRecord *recs = NULL;
@@ -1790,12 +1908,14 @@ _PUBLIC_ isc_result_t dlz_addrdataset(const char *name, const char *rdatastr, vo
 
        if (state->transaction_token != (void*)version) {
                state->log(ISC_LOG_INFO, "samba_dlz: bad transaction version");
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        rec = talloc_zero(state, struct dnsp_DnssrvRpcRecord);
        if (rec == NULL) {
-               return ISC_R_NOMEMORY;
+               result = ISC_R_NOMEMORY;
+               goto exit;
        }
 
        rec->rank        = DNS_RANK_ZONE;
@@ -1803,14 +1923,15 @@ _PUBLIC_ isc_result_t dlz_addrdataset(const char *name, const char *rdatastr, vo
        if (!b9_parse(state, rdatastr, rec)) {
                state->log(ISC_LOG_INFO, "samba_dlz: failed to parse rdataset '%s'", rdatastr);
                talloc_free(rec);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        /* find the DN of the record */
        result = b9_find_name_dn(state, name, rec, &dn);
        if (result != ISC_R_SUCCESS) {
                talloc_free(rec);
-               return result;
+               goto exit;
        }
 
        /* get any existing records */
@@ -1824,7 +1945,8 @@ _PUBLIC_ isc_result_t dlz_addrdataset(const char *name, const char *rdatastr, vo
                state->log(ISC_LOG_ERROR, "samba_dlz: failed to parse dnsRecord for %s, %s",
                           ldb_dn_get_linearized(dn), win_errstr(werr));
                talloc_free(rec);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        if (tombstoned) {
@@ -1847,7 +1969,8 @@ _PUBLIC_ isc_result_t dlz_addrdataset(const char *name, const char *rdatastr, vo
                state->log(ISC_LOG_ERROR, "samba_dlz: failed to already %u dnsRecord values for %s",
                           i, ldb_dn_get_linearized(dn));
                talloc_free(rec);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        if (i == num_recs) {
@@ -1857,7 +1980,8 @@ _PUBLIC_ isc_result_t dlz_addrdataset(const char *name, const char *rdatastr, vo
                                      num_recs + 1);
                if (recs == NULL) {
                        talloc_free(rec);
-                       return ISC_R_NOMEMORY;
+                       result = ISC_R_NOMEMORY;
+                       goto exit;
                }
                num_recs++;
 
@@ -1875,7 +1999,8 @@ _PUBLIC_ isc_result_t dlz_addrdataset(const char *name, const char *rdatastr, vo
 
        if (!b9_set_session_info(state, name)) {
                talloc_free(rec);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        /* modify the record */
@@ -1889,13 +2014,21 @@ _PUBLIC_ isc_result_t dlz_addrdataset(const char *name, const char *rdatastr, vo
                           needs_add ? "add" : "modify",
                           ldb_dn_get_linearized(dn), win_errstr(werr));
                talloc_free(rec);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        state->log(ISC_LOG_INFO, "samba_dlz: added rdataset %s '%s'", name, rdatastr);
 
        talloc_free(rec);
-       return ISC_R_SUCCESS;
+exit:
+       DNS_COMMON_LOG_OPERATION(
+               isc_result_str(result),
+               &start,
+               NULL,
+               name,
+               rdatastr);
+       return result;
 }
 
 /*
@@ -1903,10 +2036,11 @@ _PUBLIC_ isc_result_t dlz_addrdataset(const char *name, const char *rdatastr, vo
  */
 _PUBLIC_ isc_result_t dlz_subrdataset(const char *name, const char *rdatastr, void *dbdata, void *version)
 {
+       struct timeval start = timeval_current();
        struct dlz_bind9_data *state = talloc_get_type_abort(dbdata, struct dlz_bind9_data);
        struct dnsp_DnssrvRpcRecord *rec;
        struct ldb_dn *dn;
-       isc_result_t result;
+       isc_result_t result = ISC_R_SUCCESS;
        struct dnsp_DnssrvRpcRecord *recs = NULL;
        uint16_t num_recs = 0;
        uint16_t i;
@@ -1914,25 +2048,28 @@ _PUBLIC_ isc_result_t dlz_subrdataset(const char *name, const char *rdatastr, vo
 
        if (state->transaction_token != (void*)version) {
                state->log(ISC_LOG_ERROR, "samba_dlz: bad transaction version");
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        rec = talloc_zero(state, struct dnsp_DnssrvRpcRecord);
        if (rec == NULL) {
-               return ISC_R_NOMEMORY;
+               result = ISC_R_NOMEMORY;
+               goto exit;
        }
 
        if (!b9_parse(state, rdatastr, rec)) {
                state->log(ISC_LOG_ERROR, "samba_dlz: failed to parse rdataset '%s'", rdatastr);
                talloc_free(rec);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        /* find the DN of the record */
        result = b9_find_name_dn(state, name, rec, &dn);
        if (result != ISC_R_SUCCESS) {
                talloc_free(rec);
-               return result;
+               goto exit;
        }
 
        /* get the existing records */
@@ -1940,7 +2077,8 @@ _PUBLIC_ isc_result_t dlz_subrdataset(const char *name, const char *rdatastr, vo
                                 &recs, &num_recs, NULL);
        if (!W_ERROR_IS_OK(werr)) {
                talloc_free(rec);
-               return ISC_R_NOTFOUND;
+               result = ISC_R_NOTFOUND;
+               goto exit;
        }
 
        for (i=0; i < num_recs; i++) {
@@ -1953,12 +2091,14 @@ _PUBLIC_ isc_result_t dlz_subrdataset(const char *name, const char *rdatastr, vo
        }
        if (i == num_recs) {
                talloc_free(rec);
-               return ISC_R_NOTFOUND;
+               result = ISC_R_NOTFOUND;
+               goto exit;
        }
 
        if (!b9_set_session_info(state, name)) {
                talloc_free(rec);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        /* modify the record */
@@ -1971,13 +2111,21 @@ _PUBLIC_ isc_result_t dlz_subrdataset(const char *name, const char *rdatastr, vo
                state->log(ISC_LOG_ERROR, "samba_dlz: failed to modify %s - %s",
                           ldb_dn_get_linearized(dn), win_errstr(werr));
                talloc_free(rec);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        state->log(ISC_LOG_INFO, "samba_dlz: subtracted rdataset %s '%s'", name, rdatastr);
 
        talloc_free(rec);
-       return ISC_R_SUCCESS;
+exit:
+       DNS_COMMON_LOG_OPERATION(
+               isc_result_str(result),
+               &start,
+               NULL,
+               name,
+               rdatastr);
+       return result;
 }
 
 
@@ -1986,10 +2134,11 @@ _PUBLIC_ isc_result_t dlz_subrdataset(const char *name, const char *rdatastr, vo
  */
 _PUBLIC_ isc_result_t dlz_delrdataset(const char *name, const char *type, void *dbdata, void *version)
 {
+       struct timeval start = timeval_current();
        struct dlz_bind9_data *state = talloc_get_type_abort(dbdata, struct dlz_bind9_data);
        TALLOC_CTX *tmp_ctx;
        struct ldb_dn *dn;
-       isc_result_t result;
+       isc_result_t result = ISC_R_SUCCESS;
        enum dns_record_type dns_type;
        bool found = false;
        struct dnsp_DnssrvRpcRecord *recs = NULL;
@@ -1999,12 +2148,14 @@ _PUBLIC_ isc_result_t dlz_delrdataset(const char *name, const char *type, void *
 
        if (state->transaction_token != (void*)version) {
                state->log(ISC_LOG_ERROR, "samba_dlz: bad transaction version");
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        if (!b9_dns_type(type, &dns_type)) {
                state->log(ISC_LOG_ERROR, "samba_dlz: bad dns type %s in delete", type);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        tmp_ctx = talloc_new(state);
@@ -2013,7 +2164,7 @@ _PUBLIC_ isc_result_t dlz_delrdataset(const char *name, const char *type, void *
        result = b9_find_name_dn(state, name, tmp_ctx, &dn);
        if (result != ISC_R_SUCCESS) {
                talloc_free(tmp_ctx);
-               return result;
+               goto exit;
        }
 
        /* get the existing records */
@@ -2021,7 +2172,8 @@ _PUBLIC_ isc_result_t dlz_delrdataset(const char *name, const char *type, void *
                                 &recs, &num_recs, NULL);
        if (!W_ERROR_IS_OK(werr)) {
                talloc_free(tmp_ctx);
-               return ISC_R_NOTFOUND;
+               result = ISC_R_NOTFOUND;
+               goto exit;
        }
 
        for (ri=0; ri < num_recs; ri++) {
@@ -2037,12 +2189,14 @@ _PUBLIC_ isc_result_t dlz_delrdataset(const char *name, const char *type, void *
 
        if (!found) {
                talloc_free(tmp_ctx);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        if (!b9_set_session_info(state, name)) {
                talloc_free(tmp_ctx);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        /* modify the record */
@@ -2055,11 +2209,19 @@ _PUBLIC_ isc_result_t dlz_delrdataset(const char *name, const char *type, void *
                state->log(ISC_LOG_ERROR, "samba_dlz: failed to modify %s - %s",
                           ldb_dn_get_linearized(dn), win_errstr(werr));
                talloc_free(tmp_ctx);
-               return ISC_R_FAILURE;
+               result = ISC_R_FAILURE;
+               goto exit;
        }
 
        state->log(ISC_LOG_INFO, "samba_dlz: deleted rdataset %s of type %s", name, type);
 
        talloc_free(tmp_ctx);
-       return ISC_R_SUCCESS;
+exit:
+       DNS_COMMON_LOG_OPERATION(
+               isc_result_str(result),
+               &start,
+               NULL,
+               name,
+               type);
+       return result;
 }