From: Stefan Metzmacher Date: Thu, 14 Jul 2022 10:00:51 +0000 (+0200) Subject: s4:dns_server: Add some more debugging in order to find problems with level 10 logs X-Git-Tag: ldb-2.8.0~90 X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=40fb810de39c681c647b9003fe7472d9fb010667;p=thirdparty%2Fsamba.git 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 Reviewed-by: Andreas Schneider Reviewed-by: Ralph Boehme --- diff --git a/source4/dns_server/dns_crypto.c b/source4/dns_server/dns_crypto.c index b38eb8b13bb..be79a4e87b7 100644 --- 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 e73c5415d01..ccb8babc4f4 100644 --- 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 2caebd5b2af..3cc26952353 100644 --- 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;