Thanks Rowland for the ping.
On 8/04/24 22:17, Rowland Penny via samba wrote:> On Mon, 08 Apr 2024 11:46:39 +0200
> Bart?omiej Kami?ski via samba <samba at lists.samba.org> wrote:
>
>> Hi,
>>
>> after update Samba on DCs to 4.20 logs are fulfilled with messages
>> like this:
>>
>>> [2024/04/08 10:02:19.491146, 0]
>>> source4/dns_server/dnsserver_common.c:1038(dns_common_replace)
>>> dns_common_replace: tombstone record has 1 neighbour records.
>>
>
> That is coming from here:
>
> source4/dns_server/dnsserver_common.c
>
> 1012 for (i = 0; i < rec_count; i++) {
> 1013 struct ldb_val *v =
&el->values[el->num_values];
> 1014 enum ndr_err_code ndr_err;
> 1015
> 1016 if (records[i].wType == DNS_TYPE_TOMBSTONE) {
> 1017 /*
> 1018 * There are two things that could be going on
here.
> 1019 *
> 1020 * 1. We use a tombstone with EntombedTime ==
0 for
> 1021 * passing deletion messages through the
stack, and
> 1022 * this is the place we filter them out to
perform
> 1023 * that deletion.
> 1024 *
> 1025 * 2. This node is tombstoned, with no records
except
> 1026 * for a single tombstone, and it is just
waiting to
> 1027 * disappear. In this case, unless the caller
has
> 1028 * added a record, rec_count should be 1, and
> 1029 * el->num_values will end up at 0, and we
will make
> 1030 * no changes. But if the caller has added a
record,
> 1031 * we need to un-tombstone the node.
> 1032 *
> 1033 * It is not possible to add an explicit
tombstone
> 1034 * record.
> 1035 */
> 1036 if (records[i].data.EntombedTime != 0) {
> 1037 if (rec_count != 1) {
> 1038 DBG_ERR("tombstone record
has %u neighbour "
> 1039
"records.\n",
> 1040 rec_count - 1);
> 1041 }
> 1042 was_tombstoned = true;
> 1043 }
> 1044 continue;
> 1045 }
>
> It was added with this:
>
>
https://git.samba.org/?p=samba.git;a=commit;h=ffdd9ddeaeada92fec3baf2046a4e03810f26286
>
> The commit message says this:
>
> s4:dns_server: loudly warn when a tombstone record has other records
>
> This shouldn't happen -- that is, there should never be non-tombstone
> records in conjunction with a tombstone record -- and if it does, the
> situation should resolve itself here. But the flow is confusing and
> strange things sometimes happen often enough that it would be helpful
> to know if this ever occurs.
>
> So Douglas, it has occurred, now what ?
Good question. Actually, I think the logic behind that commit was wrong. There
can be a tombstone and another record if the record has recently been deleted
and is now being revived. The revival will resolve to the proper state, removing
the tombstone.
Bartek: in the log, are the MASKED names the same as each other?
Bart?omiej Kami?ski wrote:>> [2024/04/08 10:27:09.942141, 2]
source4/dns_server/dns_update.c:834(dns_server_process_update)
>> Got a dns update request.
>> [2024/04/08 10:27:09.942273, 2]
source4/dns_server/dns_update.c:791(dns_update_allowed)
>> Update not allowed for unsigned packet.
>> [2024/04/08 10:27:09.955219, 3]
lib/ldb-samba/ldb_wrap.c:332(ldb_wrap_connect)
>> ldb_wrap open of privilege.ldb
>> [2024/04/08 10:27:09.959169, 3]
source4/samba/service_stream.c:67(stream_terminate_connection)
>> stream_terminate_connection: Terminating connection -
'dns_tcp_call_loop: tstream_read_pdu_blob_recv() -
NT_STATUS_CONNECTION_RESET'
I'm guessing that one update attempt ends at this point.
Then from here, the client sends 3 updates in one request.
My guess is they are all for one name.
The DNS_QCLASS_ANY requests delete all IPv6 and IPv4 records, respectively.
The DNS_QCLASS_IN adds back an IPv4 record.
The new IPv4 record ends up beside a tombstone, which is removed
later in dns_common_replace(). That would be the end of the story,
except the client will come back soon and do the whole thing again.
The actual flow of the code is correct, but this debug message is
wrong, because it expected a plain update, not a delete-and-update.
>> [2024/04/08 10:27:09.960597, 2]
source4/dns_server/dns_update.c:834(dns_server_process_update)
>> Got a dns update request.
>> [2024/04/08 10:27:09.961275, 3]
source4/dns_server/dns_update.c:397(handle_one_update)
>> handle_one_update: Looking at record:
>> [2024/04/08 10:27:09.961295, 1]
source4/dns_server/dns_update.c:399(handle_one_update)
>> discard_const(update): struct dns_res_rec
>> name : MASKED
>> rr_type : DNS_QTYPE_AAAA (0x1C)
>> rr_class : DNS_QCLASS_ANY (0xFF)
>> ttl : 0x00000000 (0)
>> length : 0x0000 (0)
>> rdata : union dns_rdata(case 0x1C)
>> ipv6_record : (null)
>> unexpected : DATA_BLOB length=0
>> [2024/04/08 10:27:09.961947, 3]
source4/dns_server/dns_update.c:397(handle_one_update)
>> handle_one_update: Looking at record:
>> [2024/04/08 10:27:09.961967, 1]
source4/dns_server/dns_update.c:399(handle_one_update)
>> discard_const(update): struct dns_res_rec
>> name : MASKED
>> rr_type : DNS_QTYPE_A (0x1)
>> rr_class : DNS_QCLASS_ANY (0xFF)
>> ttl : 0x00000000 (0)
>> length : 0x0000 (0)
>> rdata : union dns_rdata(case 0x1)
>> ipv4_record : (null)
>> unexpected : DATA_BLOB length=0
>> [2024/04/08 10:27:09.962646, 3]
source4/dns_server/dns_update.c:397(handle_one_update)
>> handle_one_update: Looking at record:
>> [2024/04/08 10:27:09.962666, 1]
source4/dns_server/dns_update.c:399(handle_one_update)
>> discard_const(update): struct dns_res_rec
>> name : MASKED
>> rr_type : DNS_QTYPE_A (0x1)
>> rr_class : DNS_QCLASS_IN (0x1)
>> ttl : 0x000004b0 (1200)
>> length : 0x0004 (4)
>> rdata : union dns_rdata(case 0x1)
>> ipv4_record : MASKED
>> unexpected : DATA_BLOB length=0
>> [2024/04/08 10:27:09.962838, 0]
source4/dns_server/dnsserver_common.c:1038(dns_common_replace)
>> dns_common_replace: tombstone record has 1 neighbour records.
> The record seems to be updated properly.
Yes, I think everything is working properly, except for my debug message.
I added that to catch some circumstance that I can't quite remember now
(the CC'd people might recall it).
> Can someone give some advice how to check what causes this and how to
resolve it?
My advice is to ignore these messages and wait for an update that turns down
the urgency of this message.
Sorry for the log noise.
Douglas