samba - Jul 2023 - Bug 15346 - 2-3min delays at reconnect with smb2_validate_sequence_number: bad message_id 2 still on new 4.17.10

Hello to all,

I can confirm, that the bug, smb2_validate_sequence_number:
Jul 21 08:22:44 dom2 smbd[1908004]:   smb2_validate_sequence_number:
smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted 1, low
= 1, range = 1)
Jul 21 09:24:39 dom2 smbd[1908332]: [2023/07/21 09:24:39.140658,  0]
../../source3/smbd/smb2_server.c:677(smb2_validate_sequence_number)
Jul 21 09:24:39 dom2 smbd[1908332]:   smb2_validate_sequence_number:
smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted 1, low
= 1, range = 1)
Jul 21 09:25:54 dom2 smbd[1908342]: [2023/07/21 09:25:54.376344,  0]
../../source3/smbd/smb2_server.c:677(smb2_validate_sequence_number)
Jul 21 09:25:54 dom2 smbd[1908342]:   smb2_validate_sequence_number:
smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted 1, low
= 1, range = 1)
Jul 21 09:57:45 dom2 smbd[1908564]: [2023/07/21 09:57:45.419341,  0]
../../source3/smbd/smb2_server.c:677(smb2_validate_sequence_number)
Jul 21 09:57:45 dom2 smbd[1908564]:   smb2_validate_sequence_number:
smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted 1, low
= 1, range = 1)
Jul 21 10:02:29 dom2 smbd[1908588]: [2023/07/21 10:02:29.417950,  0]
../../source3/smbd/smb2_server.c:677(smb2_validate_sequence_number)
Jul 21 10:02:29 dom2 smbd[1908588]:   smb2_validate_sequence_number:
smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted 1, low
= 1, range = 1)

Is still on in new 4.17.10.
Is there a solution?

Greetings
Daniel

EDV Daniel M?ller

Leitung EDV
Tropenklinik Paul-Lechler-Krankenhaus
Paul-Lechler-Str. 24
72076 T?bingen

Hi Daniel,


Le 21/07/2023 ? 10:39, Daniel M?ller via samba a ?crit?:
> Hello to all,
> 
> I can confirm, that the bug, smb2_validate_sequence_number:
> Jul 21 08:22:44 dom2 smbd[1908004]:   smb2_validate_sequence_number:
> smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted
> 1, low = 1, range = 1)
> Jul 21 09:24:39 dom2 smbd[1908332]: [2023/07/21 09:24:39.140658,  0]
> ../../source3/smbd/smb2_server.c:677(smb2_validate_sequence_number)
> Jul 21 09:24:39 dom2 smbd[1908332]:   smb2_validate_sequence_number:
> smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted
> 1, low = 1, range = 1)
> Jul 21 09:25:54 dom2 smbd[1908342]: [2023/07/21 09:25:54.376344,  0]
> ../../source3/smbd/smb2_server.c:677(smb2_validate_sequence_number)
> Jul 21 09:25:54 dom2 smbd[1908342]:   smb2_validate_sequence_number:
> smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted
> 1, low = 1, range = 1)
> Jul 21 09:57:45 dom2 smbd[1908564]: [2023/07/21 09:57:45.419341,  0]
> ../../source3/smbd/smb2_server.c:677(smb2_validate_sequence_number)
> Jul 21 09:57:45 dom2 smbd[1908564]:   smb2_validate_sequence_number:
> smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted
> 1, low = 1, range = 1)
> Jul 21 10:02:29 dom2 smbd[1908588]: [2023/07/21 10:02:29.417950,  0]
> ../../source3/smbd/smb2_server.c:677(smb2_validate_sequence_number)
> Jul 21 10:02:29 dom2 smbd[1908588]:   smb2_validate_sequence_number:
> smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted
> 1, low = 1, range = 1)
> 
> Is still on in new 4.17.10 > Is there a solution
We have the same issue at one client site yesterday and we are 
investigating. We had the possibility for a short debug window with the 
client this morning and it seems the issue have poped-up between 4.17.5 
and 4.17.6. We have downgraded the Samba-AD to 4.16.11 to have a working 
setup with latest patch round in the mean time (no need to upgrade / 
downgrade the Samba file servers on the same site).

Like it was mentionned in the bugzilla entry, increasing the log level 
seems to decrease the probability to have the issue, so perhaps some 
timing / race condition issue. We have not been able to reproduce the 
issue internaly, neither seen this issue at others clients (up to now :-) )

Cheers,

Yohann?s and Denis



> 
> Greetings
> Daniel
> 
> EDV Daniel M?ller
> 
> Leitung EDV
> Tropenklinik Paul-Lechler-Krankenhaus
> Paul-Lechler-Str. 24
> 72076 T?bingen
> 
> 
> 
> 
> 
> 
>

Hi everybody,

Am 21.07.23 um 10:39 schrieb Daniel M?ller via samba:
> Hello to all,
> 
> I can confirm, that the bug, smb2_validate_sequence_number:
> Jul 21 08:22:44 dom2 smbd[1908004]:   smb2_validate_sequence_number:
> smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted
> 1, low = 1, range = 1)
> Jul 21 09:24:39 dom2 smbd[1908332]: [2023/07/21 09:24:39.140658,  0]
> ../../source3/smbd/smb2_server.c:677(smb2_validate_sequence_number)
> Jul 21 09:24:39 dom2 smbd[1908332]:   smb2_validate_sequence_number:
> smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted
> 1, low = 1, range = 1)
> Jul 21 09:25:54 dom2 smbd[1908342]: [2023/07/21 09:25:54.376344,  0]
> ../../source3/smbd/smb2_server.c:677(smb2_validate_sequence_number)
> Jul 21 09:25:54 dom2 smbd[1908342]:   smb2_validate_sequence_number:
> smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted
> 1, low = 1, range = 1)
> Jul 21 09:57:45 dom2 smbd[1908564]: [2023/07/21 09:57:45.419341,  0]
> ../../source3/smbd/smb2_server.c:677(smb2_validate_sequence_number)
> Jul 21 09:57:45 dom2 smbd[1908564]:   smb2_validate_sequence_number:
> smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted
> 1, low = 1, range = 1)
> Jul 21 10:02:29 dom2 smbd[1908588]: [2023/07/21 10:02:29.417950,  0]
> ../../source3/smbd/smb2_server.c:677(smb2_validate_sequence_number)
> Jul 21 10:02:29 dom2 smbd[1908588]:   smb2_validate_sequence_number:
> smb2_validate_sequence_number: bad message_id 2 (sequence id 2) (granted
> 1, low = 1, range = 1)
> 
> Is still on in new 4.17.10.
> Is there a solution?
> 
I can confirm I'm also seeing this after upgrading our AD DC servers 
from 4.16 to 4.17.10 in DC log. I noticed a delay in accessing AD 
objects from Windows ADUC tool. I haven't seen problems on fileservers 
(still 4.16) yet, but all this doesn't give me a very good feeling. 
Would be happy to see a solution/workaround/explanation.

Thanks,
Matthias