s4 dns_server Bind9: Log opertion durations

Add duration debug logging to the samba bind9 dlz driver and the
dnsserver_common routines.  This should aid future diagnosis of
performance issues, and could be used to monitor DNS performance.

The logs are currently Human readable text only, i.e. no JSON formatted
output.

Log lines are of the form:

<function>: DNS timing: result: [<result>] \
duration: (<duration>) zone: [<zone>] name: [<name>] \
data: [<data>]

e.g.

dns_common_wildcard_lookup: DNS timing: result: [WERR_OK] \
duration: (111) zone: [] \
name: [DC=_ldap._tcp.Default-First-Site-Name._sites.ForestDnsZones,\
DC=chgdcpassword.samba.example.com,CN=MicrosoftDNS,DC=DomainDnsZones,\
DC=chgdcpassword,DC=samba,DC=example,DC=com] data: []

Enabled by setting log level to "dns:10"

durations are in microseconds.

Signed-off-by: Gary Lockyer <gary@catalyst.net.nz>
Reviewed-by: Andrew Bartlett <abartlet@samba.org>

Autobuild-User(master): Andrew Bartlett <abartlet@samba.org>
Autobuild-Date(master): Tue May  7 05:03:26 UTC 2019 on sn-devel-184

3 files changed, 366 insertions, 108 deletions

diff --git a/source4/dns_server/dlz_bind9.c b/source4/dns_server/dlz_bind9.c
index 0e7fcfc2c25..5db1131e4dd 100644
--- a/source4/dns_server/dlz_bind9.c
+++ b/source4/dns_server/dlz_bind9.c
@@ -83,6 +83,38 @@ static const char *zone_prefixes[] = {
 };
 
 /*
+ * 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
  */
 _PUBLIC_ int dlz_version(unsigned int *flags)
@@ -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;
 }
diff --git a/source4/dns_server/dnsserver_common.c b/source4/dns_server/dnsserver_common.c
index e0849713604..ab8079a7296 100644
--- a/source4/dns_server/dnsserver_common.c
+++ b/source4/dns_server/dnsserver_common.c
@@ -145,13 +145,14 @@ WERROR dns_common_lookup(struct ldb_context *samdb,
 			 uint16_t *num_records,
 			 bool *tombstoned)
 {
+	const struct timeval start = timeval_current();
 	static const char * const attrs[] = {
 		"dnsRecord",
 		"dNSTombstoned",
 		NULL
 	};
 	int ret;
-	WERROR werr;
+	WERROR werr = WERR_OK;
 	struct ldb_message *msg = NULL;
 	struct ldb_message_element *el;
 
@@ -169,12 +170,14 @@ WERROR dns_common_lookup(struct ldb_context *samdb,
 			"(&(objectClass=dnsNode)(!(dNSTombstoned=TRUE)))");
 	}
 	if (ret == LDB_ERR_NO_SUCH_OBJECT) {
-		return WERR_DNS_ERROR_NAME_DOES_NOT_EXIST;
+		werr = WERR_DNS_ERROR_NAME_DOES_NOT_EXIST;
+		goto exit;
 	}
 	if (ret != LDB_SUCCESS) {
 		/* TODO: we need to check if there's a glue record we need to
 		 * create a referral to */
-		return DNS_ERR(NAME_ERROR);
+		werr = DNS_ERR(NAME_ERROR);
+		goto exit;
 	}
 
 	if (tombstoned != NULL) {
@@ -198,7 +201,8 @@ WERROR dns_common_lookup(struct ldb_context *samdb,
 					    struct dnsp_DnssrvRpcRecord,
 					    1);
 			if (recs == NULL) {
-				return WERR_NOT_ENOUGH_MEMORY;
+				werr = WERR_NOT_ENOUGH_MEMORY;
+				goto exit;
 			}
 			recs[0] = (struct dnsp_DnssrvRpcRecord) {
 				.wType = DNS_TYPE_TOMBSTONE,
@@ -214,24 +218,34 @@ WERROR dns_common_lookup(struct ldb_context *samdb,
 			*tombstoned = true;
 			*records = recs;
 			*num_records = 1;
-			return WERR_OK;
+			werr = WERR_OK;
+			goto exit;
 		} else {
 			/*
 			 * Because we are not looking for a tombstone
 			 * in this codepath, we just pretend it does
 			 * not exist at all.
 			 */
-			return WERR_DNS_ERROR_NAME_DOES_NOT_EXIST;
+			werr = WERR_DNS_ERROR_NAME_DOES_NOT_EXIST;
+			goto exit;
 		}
 	}
 
 	werr = dns_common_extract(samdb, el, mem_ctx, records, num_records);
 	TALLOC_FREE(msg);
 	if (!W_ERROR_IS_OK(werr)) {
-		return werr;
+		goto exit;
 	}
 
-	return WERR_OK;
+	werr = WERR_OK;
+exit:
+	DNS_COMMON_LOG_OPERATION(
+		win_errstr(werr),
+		&start,
+		NULL,
+		dn == NULL ? NULL : ldb_dn_get_linearized(dn),
+		NULL);
+	return werr;
 }
 
 /*
@@ -533,8 +547,9 @@ WERROR dns_common_wildcard_lookup(struct ldb_context *samdb,
 				  struct dnsp_DnssrvRpcRecord **records,
 				  uint16_t *num_records)
 {
+	const struct timeval start = timeval_current();
 	int ret;
-	WERROR werr;
+	WERROR werr = WERR_OK;
 	struct ldb_message *msg = NULL;
 	struct ldb_message_element *el = NULL;
 	const struct ldb_val *name = NULL;
@@ -545,16 +560,18 @@ WERROR dns_common_wildcard_lookup(struct ldb_context *samdb,
 	name = ldb_dn_get_rdn_val(dn);
 	if (name == NULL) {
 		return DNS_ERR(NAME_ERROR);
+		goto exit;
 	}
 
 	/* Don't look for a wildcard for @ */
 	if (name->length == 1 && name->data[0] == '@') {
-		return dns_common_lookup(samdb,
+		werr = dns_common_lookup(samdb,
 					 mem_ctx,
 					 dn,
 					 records,
 					 num_records,
 					 NULL);
+		goto exit;
 	}
 
 	werr =  dns_name_check(
@@ -562,7 +579,7 @@ WERROR dns_common_wildcard_lookup(struct ldb_context *samdb,
 			strlen((const char*)name->data),
 			(const char*) name->data);
 	if (!W_ERROR_IS_OK(werr)) {
-		return werr;
+		goto exit;
 	}
 
 	/*
@@ -576,29 +593,41 @@ WERROR dns_common_wildcard_lookup(struct ldb_context *samdb,
 				 num_records,
 				 NULL);
 	if (!W_ERROR_EQUAL(werr, WERR_DNS_ERROR_NAME_DOES_NOT_EXIST)) {
-		return werr;
+		goto exit;
 	}
 
 	ret = dns_wildcard_lookup(samdb, mem_ctx, dn, &msg);
 	if (ret == LDB_ERR_OPERATIONS_ERROR) {
-		return DNS_ERR(SERVER_FAILURE);
+		werr = DNS_ERR(SERVER_FAILURE);
+		goto exit;
 	}
 	if (ret != LDB_SUCCESS) {
-		return DNS_ERR(NAME_ERROR);
+		werr = DNS_ERR(NAME_ERROR);
+		goto exit;
 	}
 
 	el = ldb_msg_find_element(msg, "dnsRecord");
 	if (el == NULL) {
-		return WERR_DNS_ERROR_NAME_DOES_NOT_EXIST;
+		werr = WERR_DNS_ERROR_NAME_DOES_NOT_EXIST;
+		goto exit;
 	}
 
 	werr = dns_common_extract(samdb, el, mem_ctx, records, num_records);
 	TALLOC_FREE(msg);
 	if (!W_ERROR_IS_OK(werr)) {
 		return werr;
+		goto exit;
 	}
 
-	return WERR_OK;
+	werr = WERR_OK;
+exit:
+	DNS_COMMON_LOG_OPERATION(
+		win_errstr(werr),
+		&start,
+		NULL,
+		dn == NULL ? NULL : ldb_dn_get_linearized(dn),
+		NULL);
+	return werr;
 }
 
 static int rec_cmp(const struct dnsp_DnssrvRpcRecord *r1,
@@ -894,6 +923,7 @@ WERROR dns_common_replace(struct ldb_context *samdb,
 			  struct dnsp_DnssrvRpcRecord *records,
 			  uint16_t rec_count)
 {
+	const struct timeval start = timeval_current();
 	struct ldb_message_element *el;
 	uint16_t i;
 	int ret;
@@ -912,14 +942,17 @@ WERROR dns_common_replace(struct ldb_context *samdb,
 
 	zone_dn = ldb_dn_copy(mem_ctx, dn);
 	if (zone_dn == NULL) {
-		return WERR_NOT_ENOUGH_MEMORY;
+		werr = WERR_NOT_ENOUGH_MEMORY;
+		goto exit;
 	}
 	if (!ldb_dn_remove_child_components(zone_dn, 1)) {
-		return DNS_ERR(SERVER_FAILURE);
+		werr = DNS_ERR(SERVER_FAILURE);
+		goto exit;
 	}
 	zoneinfo = talloc(mem_ctx, struct dnsserver_zoneinfo);
 	if (zoneinfo == NULL) {
-		return WERR_NOT_ENOUGH_MEMORY;
+		werr = WERR_NOT_ENOUGH_MEMORY;
+		goto exit;
 	}
 	werr = dns_get_zone_properties(samdb, mem_ctx, zone_dn, zoneinfo);
 	if (W_ERROR_EQUAL(DNS_ERR(NOTZONE), werr)) {
@@ -929,17 +962,18 @@ WERROR dns_common_replace(struct ldb_context *samdb,
 		 */
 		zoneinfo->fAging = 0;
 	} else if (!W_ERROR_IS_OK(werr)) {
-		return werr;
+		goto exit;
 	}
 
 	werr = check_name_list(mem_ctx, rec_count, records);
 	if (!W_ERROR_IS_OK(werr)) {
-		return werr;
+		goto exit;
 	}
 
 	ret = ldb_msg_add_empty(msg, "dnsRecord", LDB_FLAG_MOD_REPLACE, &el);
 	if (ret != LDB_SUCCESS) {
-		return DNS_ERR(SERVER_FAILURE);
+		werr = DNS_ERR(SERVER_FAILURE);
+		goto exit;
 	}
 
 	/*
@@ -948,7 +982,10 @@ WERROR dns_common_replace(struct ldb_context *samdb,
 	 */
 	el->values = talloc_zero_array(el, struct ldb_val, MAX(1, rec_count));
 	if (rec_count > 0) {
-		W_ERROR_HAVE_NO_MEMORY(el->values);
+		if (el->values == NULL) {
+			werr = WERR_NOT_ENOUGH_MEMORY;
+			goto exit;
+		}
 
 		/*
 		 * We store a sorted list with the high wType values first
@@ -984,27 +1021,32 @@ WERROR dns_common_replace(struct ldb_context *samdb,
 				(ndr_push_flags_fn_t)ndr_push_dnsp_DnssrvRpcRecord);
 		if (!NDR_ERR_CODE_IS_SUCCESS(ndr_err)) {
 			DEBUG(0, ("Failed to push dnsp_DnssrvRpcRecord\n"));
-			return DNS_ERR(SERVER_FAILURE);
+			werr = DNS_ERR(SERVER_FAILURE);
+			goto exit;
 		}
 		el->num_values++;
 	}
 
 	if (needs_add) {
 		if (el->num_values == 0) {
-			return WERR_OK;
+			werr = WERR_OK;
+			goto exit;
 		}
 
 		ret = ldb_msg_add_string(msg, "objectClass", "dnsNode");
 		if (ret != LDB_SUCCESS) {
-			return DNS_ERR(SERVER_FAILURE);
+			werr = DNS_ERR(SERVER_FAILURE);
+			goto exit;
 		}
 
 		ret = ldb_add(samdb, msg);
 		if (ret != LDB_SUCCESS) {
-			return DNS_ERR(SERVER_FAILURE);
+			werr = DNS_ERR(SERVER_FAILURE);
+			goto exit;
 		}
 
 		return WERR_OK;
+		goto exit;
 	}
 
 	if (el->num_values == 0) {
@@ -1018,7 +1060,8 @@ WERROR dns_common_replace(struct ldb_context *samdb,
 			 * This is already a tombstoned object.
 			 * Just leave it instead of updating the time stamp.
 			 */
-			return WERR_OK;
+			werr = WERR_OK;
+			goto exit;
 		}
 
 		tv = timeval_current();
@@ -1032,7 +1075,8 @@ WERROR dns_common_replace(struct ldb_context *samdb,
 				(ndr_push_flags_fn_t)ndr_push_dnsp_DnssrvRpcRecord);
 		if (!NDR_ERR_CODE_IS_SUCCESS(ndr_err)) {
 			DEBUG(0, ("Failed to push dnsp_DnssrvRpcRecord\n"));
-			return DNS_ERR(SERVER_FAILURE);
+			werr = DNS_ERR(SERVER_FAILURE);
+			goto exit;
 		}
 		el->num_values++;
 
@@ -1043,23 +1087,34 @@ WERROR dns_common_replace(struct ldb_context *samdb,
 		ret = ldb_msg_add_empty(msg, "dNSTombstoned",
 					LDB_FLAG_MOD_REPLACE, NULL);
 		if (ret != LDB_SUCCESS) {
-			return DNS_ERR(SERVER_FAILURE);
+			werr = DNS_ERR(SERVER_FAILURE);
+			goto exit;
 		}
 
 		ret = ldb_msg_add_fmt(msg, "dNSTombstoned", "%s",
 				      become_tombstoned ? "TRUE" : "FALSE");
 		if (ret != LDB_SUCCESS) {
-			return DNS_ERR(SERVER_FAILURE);
+			werr = DNS_ERR(SERVER_FAILURE);
+			goto exit;
 		}
 	}
 
 	ret = ldb_modify(samdb, msg);
 	if (ret != LDB_SUCCESS) {
 		NTSTATUS nt = dsdb_ldb_err_to_ntstatus(ret);
-		return ntstatus_to_werror(nt);
+		werr = ntstatus_to_werror(nt);
+		goto exit;
 	}
 
-	return WERR_OK;
+	werr = WERR_OK;
+exit:
+	DNS_COMMON_LOG_OPERATION(
+		win_errstr(werr),
+		&start,
+		NULL,
+		dn == NULL ? NULL : ldb_dn_get_linearized(dn),
+		NULL);
+	return werr;
 }
 
 bool dns_name_match(const char *zone, const char *name, size_t *host_part_len)
@@ -1231,12 +1286,14 @@ NTSTATUS dns_common_zones(struct ldb_context *samdb,
 			  struct ldb_dn *base_dn,
 			  struct dns_server_zone **zones_ret)
 {
+	const struct timeval start = timeval_current();
 	int ret;
 	static const char * const attrs[] = { "name", NULL};
 	struct ldb_result *res;
 	int i;
 	struct dns_server_zone *new_list = NULL;
 	TALLOC_CTX *frame = talloc_stackframe();
+	NTSTATUS result = NT_STATUS_OK;
 
 	if (base_dn) {
 		/* This search will work against windows */
@@ -1253,7 +1310,8 @@ NTSTATUS dns_common_zones(struct ldb_context *samdb,
 	}
 	if (ret != LDB_SUCCESS) {
 		TALLOC_FREE(frame);
-		return NT_STATUS_INTERNAL_DB_CORRUPTION;
+		result = NT_STATUS_INTERNAL_DB_CORRUPTION;
+		goto exit;
 	}
 
 	TYPESAFE_QSORT(res->msgs, res->count, dns_common_sort_zones);
@@ -1264,7 +1322,8 @@ NTSTATUS dns_common_zones(struct ldb_context *samdb,
 		z = talloc_zero(mem_ctx, struct dns_server_zone);
 		if (z == NULL) {
 			TALLOC_FREE(frame);
-			return NT_STATUS_NO_MEMORY;
+			result = NT_STATUS_NO_MEMORY;
+			goto exit;
 		}
 
 		z->name = ldb_msg_find_attr_as_string(res->msgs[i], "name", NULL);
@@ -1289,7 +1348,15 @@ NTSTATUS dns_common_zones(struct ldb_context *samdb,
 
 	*zones_ret = new_list;
 	TALLOC_FREE(frame);
-	return NT_STATUS_OK;
+	result = NT_STATUS_OK;
+exit:
+	DNS_COMMON_LOG_OPERATION(
+		nt_errstr(result),
+		&start,
+		NULL,
+		base_dn == NULL ? NULL : ldb_dn_get_linearized(base_dn),
+		NULL);
+	return result;
 }
 
 /*
diff --git a/source4/dns_server/dnsserver_common.h b/source4/dns_server/dnsserver_common.h
index 60ecde4fa91..9d634fc1b7d 100644
--- a/source4/dns_server/dnsserver_common.h
+++ b/source4/dns_server/dnsserver_common.h
@@ -90,4 +90,33 @@ NTSTATUS dns_common_zones(struct ldb_context *samdb,
 
 bool dns_zoneinfo_load_zone_property(struct dnsserver_zoneinfo *zoneinfo,
 				     struct dnsp_DnsProperty *prop);
+/*
+ * Log a DNS operation along with it's duration
+ * Enabled by setting a log level of "dns:10"
+ *
+ * const char *operation
+ * const char *result
+ * const struct timeval *start
+ * const char *zone
+ * const char *name
+ * const char *data
+ */
+#define DNS_COMMON_LOG_OPERATION(result, start, zone, name, data) \
+	if (CHECK_DEBUGLVLC(DBGC_DNS, DBGLVL_DEBUG)) { \
+		struct timeval now = timeval_current(); \
+		uint64_t duration = usec_time_diff(&now, (start));\
+		const char *re = (result);\
+		const char *zn = (zone); \
+		const char *nm = (name); \
+		const char *dt = (data); \
+		DBG_DEBUG( \
+			"DNS timing: result: [%s] duration: (%" PRIi64 ") " \
+			"zone: [%s] name: [%s] data: [%s]\n", \
+			re == NULL ? "" : re, \
+			duration, \
+			zn == NULL ? "" : zn, \
+			nm == NULL ? "" : nm, \
+			dt == NULL ? "" : dt); \
+	}
+
 #endif /* __DNSSERVER_COMMON_H__ */