s4:dns_server: Add some more debugging in order to find problems with level 10 logs

We had customer problems where level 10 logs were not good enough in
order to find the reason for failing dns updates.

With the new debug message there's at least a chance to
find out what the problem could be.

Signed-off-by: Stefan Metzmacher <metze@samba.org>
Reviewed-by: Andreas Schneider <asn@samba.org>
Reviewed-by: Ralph Boehme <slow@samba.org>

diff --git a/source4/dns_server/dns_crypto.c b/source4/dns_server/dns_crypto.c
index b38eb8b13bb2bdae22dd80f279867d5b75ee9904..be79a4e87b75e085d107f7afbe49f2c4540486ec 100644 (file)
--- a/source4/dns_server/dns_crypto.c
+++ b/source4/dns_server/dns_crypto.c
@@ -128,6 +128,7 @@ WERROR dns_verify_tsig(struct dns_server *dns,
 
        /* We got a TSIG, so we need to sign our reply */
        state->sign = true;
+       DBG_DEBUG("Got TSIG\n");
 
        state->tsig = talloc_zero(state->mem_ctx, struct dns_res_rec);
        if (state->tsig == NULL) {
@@ -144,6 +145,7 @@ WERROR dns_verify_tsig(struct dns_server *dns,
 
        tkey = dns_find_tkey(dns->tkeys, state->tsig->name);
        if (tkey == NULL) {
+               DBG_DEBUG("dns_find_tkey() => NOTAUTH / DNS_RCODE_BADKEY\n");
                /*
                 * We must save the name for use in the TSIG error
                 * response and have no choice here but to save the
@@ -157,6 +159,7 @@ WERROR dns_verify_tsig(struct dns_server *dns,
                state->tsig_error = DNS_RCODE_BADKEY;
                return DNS_ERR(NOTAUTH);
        }
+       DBG_DEBUG("dns_find_tkey() => found\n");
 
        /*
         * Remember the keyname that found an existing tkey, used
@@ -232,17 +235,23 @@ WERROR dns_verify_tsig(struct dns_server *dns,
        status = gensec_check_packet(tkey->gensec, buffer, buffer_len,
                                    buffer, buffer_len, &sig);
        if (NT_STATUS_EQUAL(NT_STATUS_ACCESS_DENIED, status)) {
+               dump_data_dbgc(DBGC_DNS, 8, sig.data, sig.length);
+               dump_data_dbgc(DBGC_DNS, 8, buffer, buffer_len);
+               DBG_NOTICE("Verifying tsig failed: %s\n", nt_errstr(status));
                state->tsig_error = DNS_RCODE_BADSIG;
                return DNS_ERR(NOTAUTH);
        }
 
        if (!NT_STATUS_IS_OK(status)) {
+               dump_data_dbgc(DBGC_DNS, 8, sig.data, sig.length);
+               dump_data_dbgc(DBGC_DNS, 8, buffer, buffer_len);
                DEBUG(1, ("Verifying tsig failed: %s\n", nt_errstr(status)));
                return ntstatus_to_werror(status);
        }
 
        state->authenticated = true;
 
+       DBG_DEBUG("AUTHENTICATED\n");
        return WERR_OK;
 }
 
@@ -373,11 +382,13 @@ WERROR dns_sign_tsig(struct dns_server *dns,
                struct dns_server_tkey *tkey = dns_find_tkey(
                        dns->tkeys, state->key_name);
                if (tkey == NULL) {
+                       DBG_WARNING("dns_find_tkey() => NULL)\n");
                        return DNS_ERR(SERVER_FAILURE);
                }
 
                werror = dns_tsig_compute_mac(mem_ctx, state, packet,
                                              tkey, current_time, &sig);
+               DBG_DEBUG("dns_tsig_compute_mac() => %s\n", win_errstr(werror));
                if (!W_ERROR_IS_OK(werror)) {
                        return werror;
                }
@@ -410,6 +421,8 @@ WERROR dns_sign_tsig(struct dns_server *dns,
                }
        }
 
+       DBG_DEBUG("sig.length=%zu\n", sig.length);
+
        if (packet->arcount == 0) {
                packet->additional = talloc_zero(mem_ctx, struct dns_res_rec);
                if (packet->additional == NULL) {
@@ -425,6 +438,7 @@ WERROR dns_sign_tsig(struct dns_server *dns,
 
        werror = dns_copy_tsig(mem_ctx, tsig,
                               &packet->additional[packet->arcount]);
+       DBG_DEBUG("dns_copy_tsig() => %s\n", win_errstr(werror));
        if (!W_ERROR_IS_OK(werror)) {
                return werror;
        }

diff --git a/source4/dns_server/dns_server.c b/source4/dns_server/dns_server.c
index e73c5415d01f84a173e939a1433c5807a1c1e184..ccb8babc4f4297e1d87388a7233223268be8e14e 100644 (file)
--- a/source4/dns_server/dns_server.c
+++ b/source4/dns_server/dns_server.c
@@ -146,6 +146,8 @@ static struct tevent_req *dns_process_send(TALLOC_CTX *mem_ctx,
                (ndr_pull_flags_fn_t)ndr_pull_dns_name_packet);
 
        if (!NDR_ERR_CODE_IS_SUCCESS(ndr_err)) {
+               DBG_NOTICE("ndr_pull_dns_name_packet() failed with %s\n",
+                          ndr_map_error2string(ndr_err));
                state->dns_err = DNS_ERR(FORMAT_ERROR);
                tevent_req_done(req);
                return tevent_req_post(req, ev);
@@ -155,7 +157,7 @@ static struct tevent_req *dns_process_send(TALLOC_CTX *mem_ctx,
        }
 
        if (state->in_packet.operation & DNS_FLAG_REPLY) {
-               DEBUG(1, ("Won't reply to replies.\n"));
+               DBG_INFO("Won't reply to replies.\n");
                tevent_req_werror(req, WERR_INVALID_PARAMETER);
                return tevent_req_post(req, ev);
        }
@@ -175,6 +177,8 @@ static struct tevent_req *dns_process_send(TALLOC_CTX *mem_ctx,
        ret = dns_verify_tsig(dns, state, &state->state,
                              &state->out_packet, in);
        if (!W_ERROR_IS_OK(ret)) {
+               DBG_INFO("dns_verify_tsig() failed with %s\n",
+                        win_errstr(ret));
                state->dns_err = ret;
                tevent_req_done(req);
                return tevent_req_post(req, ev);
@@ -197,9 +201,14 @@ static struct tevent_req *dns_process_send(TALLOC_CTX *mem_ctx,
                        &state->out_packet.nsrecs,  &state->out_packet.nscount,
                        &state->out_packet.additional,
                        &state->out_packet.arcount);
+               DBG_DEBUG("dns_server_process_update(): %s\n",
+                         win_errstr(ret));
                break;
        default:
                ret = WERR_DNS_ERROR_RCODE_NOT_IMPLEMENTED;
+               DBG_NOTICE("OPCODE[0x%x]: %s\n",
+                          (state->in_packet.operation & DNS_OPCODE),
+                          win_errstr(ret));
        }
        state->dns_err = ret;
        tevent_req_done(req);
@@ -221,6 +230,8 @@ static void dns_process_done(struct tevent_req *subreq)
                &state->out_packet.additional, &state->out_packet.arcount);
        TALLOC_FREE(subreq);
 
+       DBG_DEBUG("dns_server_process_query_recv(): %s\n",
+                 win_errstr(ret));
        state->dns_err = ret;
        tevent_req_done(req);
 }
@@ -235,6 +246,8 @@ static WERROR dns_process_recv(struct tevent_req *req, TALLOC_CTX *mem_ctx,
        WERROR ret;
 
        if (tevent_req_is_werror(req, &ret)) {
+               DBG_NOTICE("ERROR: %s from %s\n", win_errstr(ret),
+                          tevent_req_print(state, req));
                return ret;
        }
        dns_err = werr_to_dns_err(state->dns_err);
@@ -242,10 +255,19 @@ static WERROR dns_process_recv(struct tevent_req *req, TALLOC_CTX *mem_ctx,
            (dns_err != DNS_RCODE_NXDOMAIN) &&
            (dns_err != DNS_RCODE_NOTAUTH))
        {
+               DBG_INFO("FAILURE: %s from %s\n",
+                        win_errstr(state->dns_err),
+                        tevent_req_print(state, req));
                goto drop;
        }
        if (dns_err != DNS_RCODE_OK) {
+               DBG_DEBUG("INFO: %s from %s\n",
+                         win_errstr(state->dns_err),
+                         tevent_req_print(state, req));
                state->out_packet.operation |= dns_err;
+       } else {
+               DBG_DEBUG("OK: %s\n",
+                         tevent_req_print(state, req));
        }
        state->out_packet.operation |= state->state.flags;
 
@@ -253,6 +275,8 @@ static WERROR dns_process_recv(struct tevent_req *req, TALLOC_CTX *mem_ctx,
                ret = dns_sign_tsig(state->dns, mem_ctx, &state->state,
                                    &state->out_packet, 0);
                if (!W_ERROR_IS_OK(ret)) {
+                       DBG_WARNING("dns_sign_tsig() failed %s\n",
+                                   win_errstr(ret));
                        dns_err = DNS_RCODE_SERVFAIL;
                        goto drop;
                }
@@ -266,8 +290,8 @@ static WERROR dns_process_recv(struct tevent_req *req, TALLOC_CTX *mem_ctx,
                out, mem_ctx, &state->out_packet,
                (ndr_push_flags_fn_t)ndr_push_dns_name_packet);
        if (!NDR_ERR_CODE_IS_SUCCESS(ndr_err)) {
-               DEBUG(1, ("Failed to push packet: %s!\n",
-                         ndr_errstr(ndr_err)));
+               DBG_WARNING("Failed to push packet: %s!\n",
+                           ndr_errstr(ndr_err));
                dns_err = DNS_RCODE_SERVFAIL;
                goto drop;
        }

diff --git a/source4/dns_server/dns_update.c b/source4/dns_server/dns_update.c
index 2caebd5b2af88b270dffbf168f829a21b40a8ffb..3cc26952353a0b6a1f79b7c8b97d6728a83af810 100644 (file)
--- a/source4/dns_server/dns_update.c
+++ b/source4/dns_server/dns_update.c
@@ -418,10 +418,12 @@ static WERROR handle_one_update(struct dns_server *dns,
        }
 
        werror = dns_name2dn(dns, mem_ctx, update->name, &dn);
+       DBG_DEBUG("dns_name2dn(): %s\n", win_errstr(werror));
        W_ERROR_NOT_OK_RETURN(werror);
 
        werror = dns_common_lookup(dns->samdb, mem_ctx, dn,
                                   &recs, &rcount, &tombstoned);
+       DBG_DEBUG("dns_common_lookup(): %s\n", win_errstr(werror));
        if (W_ERROR_EQUAL(werror, WERR_DNS_ERROR_NAME_DOES_NOT_EXIST)) {
                needs_add = true;
                werror = WERR_OK;
@@ -473,11 +475,13 @@ static WERROR handle_one_update(struct dns_server *dns,
 
                        werror = dns_rr_to_dnsp(
                            recs, update, &recs[rcount], name_is_static);
+                       DBG_DEBUG("dns_rr_to_dnsp(CNAME): %s\n", win_errstr(werror));
                        W_ERROR_NOT_OK_RETURN(werror);
                        rcount += 1;
 
                        werror = dns_replace_records(dns, mem_ctx, dn,
                                                     needs_add, recs, rcount);
+                       DBG_DEBUG("dns_replace_records(CNAME): %s\n", win_errstr(werror));
                        W_ERROR_NOT_OK_RETURN(werror);
 
                        return WERR_OK;
@@ -526,6 +530,7 @@ static WERROR handle_one_update(struct dns_server *dns,
 
                        werror = dns_rr_to_dnsp(
                            mem_ctx, update, &recs[i], name_is_static);
+                       DBG_DEBUG("dns_rr_to_dnsp(SOA): %s\n", win_errstr(werror));
                        W_ERROR_NOT_OK_RETURN(werror);
 
                        /*
@@ -549,6 +554,7 @@ static WERROR handle_one_update(struct dns_server *dns,
 
                        werror = dns_replace_records(dns, mem_ctx, dn,
                                                     needs_add, recs, rcount);
+                       DBG_DEBUG("dns_replace_records(SOA): %s\n", win_errstr(werror));
                        W_ERROR_NOT_OK_RETURN(werror);
 
                        return WERR_OK;
@@ -560,6 +566,7 @@ static WERROR handle_one_update(struct dns_server *dns,
 
                werror =
                    dns_rr_to_dnsp(recs, update, &recs[rcount], name_is_static);
+               DBG_DEBUG("dns_rr_to_dnsp(GENERIC): %s\n", win_errstr(werror));
                W_ERROR_NOT_OK_RETURN(werror);
 
                for (i = first; i < rcount; i++) {
@@ -575,6 +582,7 @@ static WERROR handle_one_update(struct dns_server *dns,
                        recs[i].flags = 0;
                        werror = dns_replace_records(dns, mem_ctx, dn,
                                                     needs_add, recs, rcount);
+                       DBG_DEBUG("dns_replace_records(REPLACE): %s\n", win_errstr(werror));
                        W_ERROR_NOT_OK_RETURN(werror);
 
                        return WERR_OK;
@@ -582,6 +590,7 @@ static WERROR handle_one_update(struct dns_server *dns,
                /* we did not find a matching record. This is new. */
                werror = dns_replace_records(dns, mem_ctx, dn,
                                             needs_add, recs, rcount+1);
+               DBG_DEBUG("dns_replace_records(ADD): %s\n", win_errstr(werror));
                W_ERROR_NOT_OK_RETURN(werror);
 
                return WERR_OK;
@@ -636,6 +645,7 @@ static WERROR handle_one_update(struct dns_server *dns,
 
                werror = dns_replace_records(dns, mem_ctx, dn,
                                             needs_add, recs, rcount);
+               DBG_DEBUG("dns_replace_records(DELETE-ANY): %s\n", win_errstr(werror));
                W_ERROR_NOT_OK_RETURN(werror);
 
                return WERR_OK;
@@ -654,6 +664,7 @@ static WERROR handle_one_update(struct dns_server *dns,
 
                        werror = dns_rr_to_dnsp(
                            ns_rec, update, ns_rec, name_is_static);
+                       DBG_DEBUG("dns_rr_to_dnsp(NS): %s\n", win_errstr(werror));
                        W_ERROR_NOT_OK_RETURN(werror);
 
                        for (i = first; i < rcount; i++) {
@@ -672,6 +683,7 @@ static WERROR handle_one_update(struct dns_server *dns,
 
                werror =
                    dns_rr_to_dnsp(del_rec, update, del_rec, name_is_static);
+               DBG_DEBUG("dns_rr_to_dnsp(DELETE-NONE): %s\n", win_errstr(werror));
                W_ERROR_NOT_OK_RETURN(werror);
 
                for (i = first; i < rcount; i++) {
@@ -684,6 +696,7 @@ static WERROR handle_one_update(struct dns_server *dns,
 
                werror = dns_replace_records(dns, mem_ctx, dn,
                                             needs_add, recs, rcount);
+               DBG_DEBUG("dns_replace_records(DELETE-NONE): %s\n", win_errstr(werror));
                W_ERROR_NOT_OK_RETURN(werror);
        }
 
@@ -716,6 +729,7 @@ static WERROR handle_updates(struct dns_server *dns,
        }
 
        werror = dns_name2dn(dns, tmp_ctx, zone->name, &zone_dn);
+       DBG_DEBUG("dns_name2dn(): %s\n", win_errstr(werror));
        W_ERROR_NOT_OK_GOTO(werror, failed);
 
        ret = ldb_transaction_start(dns->samdb);
@@ -732,6 +746,8 @@ static WERROR handle_updates(struct dns_server *dns,
        for (ri = 0; ri < upd_count; ri++) {
                werror = handle_one_update(dns, tmp_ctx, zone,
                                           &updates[ri], tkey);
+               DBG_DEBUG("handle_one_update(%u): %s\n",
+                         ri, win_errstr(werror));
                W_ERROR_NOT_OK_GOTO(werror, failed);
        }
 
@@ -856,10 +872,12 @@ WERROR dns_server_process_update(struct dns_server *dns,
        *update_count = in->nscount;
        *updates = in->nsrecs;
        werror = update_prescan(in->questions, *updates, *update_count);
+       DBG_DEBUG("update_prescan(): %s\n", win_errstr(werror));
        W_ERROR_NOT_OK_RETURN(werror);
 
        werror = handle_updates(dns, mem_ctx, in->questions, *prereqs,
                                *prereq_count, *updates, *update_count, tkey);
+       DBG_DEBUG("handle_updates(): %s\n", win_errstr(werror));
        W_ERROR_NOT_OK_RETURN(werror);
 
        return werror;