The test “smb2.multichannel.bugs.bug_15346” frequently fails in CI. Typical output: [301(1956)/829 at 20m51s] samba3.smb2.multichannel(nt4_dc) Testing for BUG 15346 conn[0]: negprot done conn[2]: negprot done conn[3]: negprot done conn[0]: echo done conn[3]: echo done conn[5]: negprot done conn[5]: echo done conn[6]: negprot done conn[4]: negprot done conn[6]: echo done conn[4]: echo done conn[1]: negprot done conn[1]: echo done conn[8]: negprot done conn[8]: echo done conn[9]: negprot done conn[9]: echo done conn[7]: negprot done conn[7]: echo done conn[12]: negprot done conn[12]: echo done conn[10]: negprot done conn[10]: echo done conn[11]: negprot done conn[11]: echo done conn[13]: negprot done conn[13]: echo done conn[14]: negprot done conn[14]: echo done conn[18]: negprot done conn[18]: echo done conn[19]: negprot done conn[19]: echo done conn[16]: negprot done conn[16]: echo done conn[17]: negprot done conn[17]: echo done conn[15]: negprot done conn[15]: echo done conn[24]: negprot done conn[24]: echo done conn[25]: negprot done conn[25]: echo done conn[21]: negprot done conn[21]: echo done conn[20]: negprot done conn[20]: echo done conn[23]: negprot done conn[23]: echo done conn[29]: negprot done conn[29]: echo done conn[22]: negprot done conn[22]: echo done conn[28]: negprot done conn[28]: echo done conn[26]: negprot done conn[26]: echo done conn[30]: negprot done conn[30]: echo done conn[27]: negprot done conn[27]: echo done UNEXPECTED(failure): samba3.smb2.multichannel.bugs.bug_15346(nt4_dc) REASON: Exception: Exception: ../../source4/torture/smb2/multichannel.c:2428: status was NT_STATUS_IO_TIMEOUT, expected NT_STATUS_OK: smb2cli_echo_recv failed FAILED (1 failures, 0 errors and 0 unexpected successes in 0 testsuites) Notice the absence of a “conn[2]: echo done” line. It’s not always with connection 2 that we fail to receive an echo, though; I’ve observed it happening with 5 and 6, and other numbers as well.
This bug was referenced in samba master: e933fd2dadfabc04add3caed9f9496761fadba8c 46f0c2696582ab6561808dcfadcfc5cf9bc67a3a 9f54b94b52db2935affc6b1cb09b71c2907f2289
[299(1947)/828 at 20m33s] samba3.smb2.multichannel(nt4_dc) Testing for BUG 15346 2023-10-26T13:33:12.501749Z: conn[0]: negprot done 2023-10-26T13:33:12.501829Z: conn[2]: negprot done 2023-10-26T13:33:12.505714Z: conn[0]: echo done 2023-10-26T13:33:12.506592Z: conn[1]: negprot done 2023-10-26T13:33:12.508738Z: conn[1]: echo done 2023-10-26T13:33:12.509140Z: conn[3]: negprot done 2023-10-26T13:33:12.510461Z: conn[3]: echo done 2023-10-26T13:33:12.510826Z: conn[6]: negprot done 2023-10-26T13:33:12.512752Z: conn[6]: echo done 2023-10-26T13:33:12.514001Z: conn[5]: negprot done 2023-10-26T13:33:12.514494Z: conn[5]: echo done 2023-10-26T13:33:12.514846Z: conn[4]: negprot done 2023-10-26T13:33:12.516744Z: conn[4]: echo done 2023-10-26T13:33:12.518978Z: conn[7]: negprot done 2023-10-26T13:33:12.519783Z: conn[7]: echo done 2023-10-26T13:33:12.520424Z: conn[8]: negprot done 2023-10-26T13:33:12.520556Z: conn[8]: echo done 2023-10-26T13:33:12.528239Z: conn[9]: negprot done 2023-10-26T13:33:12.528436Z: conn[9]: echo done 2023-10-26T13:33:12.529606Z: conn[11]: negprot done 2023-10-26T13:33:12.529747Z: conn[11]: echo done 2023-10-26T13:33:12.530244Z: conn[10]: negprot done 2023-10-26T13:33:12.530366Z: conn[10]: echo done 2023-10-26T13:33:12.537396Z: conn[13]: negprot done 2023-10-26T13:33:12.537594Z: conn[13]: echo done 2023-10-26T13:33:12.538394Z: conn[12]: negprot done 2023-10-26T13:33:12.538512Z: conn[12]: echo done 2023-10-26T13:33:12.542679Z: conn[17]: negprot done 2023-10-26T13:33:12.542852Z: conn[17]: echo done 2023-10-26T13:33:12.543405Z: conn[15]: negprot done 2023-10-26T13:33:12.543550Z: conn[15]: echo done 2023-10-26T13:33:12.548583Z: conn[16]: negprot done 2023-10-26T13:33:12.548823Z: conn[16]: echo done 2023-10-26T13:33:12.551223Z: conn[19]: negprot done 2023-10-26T13:33:12.551464Z: conn[19]: echo done 2023-10-26T13:33:12.553199Z: conn[14]: negprot done 2023-10-26T13:33:12.553395Z: conn[14]: echo done 2023-10-26T13:33:12.554003Z: conn[18]: negprot done 2023-10-26T13:33:12.554146Z: conn[18]: echo done 2023-10-26T13:33:12.558421Z: conn[20]: negprot done 2023-10-26T13:33:12.558725Z: conn[20]: echo done 2023-10-26T13:33:12.561594Z: conn[21]: negprot done 2023-10-26T13:33:12.561861Z: conn[21]: echo done 2023-10-26T13:33:12.566443Z: conn[23]: negprot done 2023-10-26T13:33:12.566762Z: conn[23]: echo done 2023-10-26T13:33:12.568313Z: conn[22]: negprot done 2023-10-26T13:33:12.568478Z: conn[22]: echo done 2023-10-26T13:33:12.572248Z: conn[25]: negprot done 2023-10-26T13:33:12.572512Z: conn[25]: echo done 2023-10-26T13:33:12.574316Z: conn[24]: negprot done 2023-10-26T13:33:12.574498Z: conn[24]: echo done 2023-10-26T13:33:12.575453Z: conn[26]: negprot done 2023-10-26T13:33:12.575632Z: conn[26]: echo done 2023-10-26T13:33:12.578988Z: conn[29]: negprot done 2023-10-26T13:33:12.579237Z: conn[29]: echo done 2023-10-26T13:33:12.582451Z: conn[27]: negprot done 2023-10-26T13:33:12.582506Z: conn[30]: negprot done 2023-10-26T13:33:12.582757Z: conn[27]: echo done 2023-10-26T13:33:12.582774Z: conn[30]: echo done 2023-10-26T13:33:12.583327Z: conn[28]: negprot done 2023-10-26T13:33:12.583478Z: conn[28]: echo done 2023-10-26T13:34:45.576698Z: conn[2]: echo timed out UNEXPECTED(failure): samba3.smb2.multichannel.bugs.bug_15346(nt4_dc)
(In reply to Andreas Schneider from comment #2) > 2023-10-26T13:33:12.501749Z: conn[0]: negprot done > 2023-10-26T13:33:12.501829Z: conn[2]: negprot done The time elapsed between the first two connections completing protocol negotiation is only 80 microseconds. I wonder if the second connection getting stuck has anything to do with that delay being so short.
(In reply to Joseph Sutton from comment #3) Possibly not though, as the delay between connections 27 and 30 completing protocol negotiation is even shorter, and they both complete successfully.
This bug was referenced in samba master: b0a09a69cc8f44077363fe6ecbab8e237e769b13
(In reply to Samba QA Contact from comment #5) Note that the above is not a fix, just a marking of the test as flapping. We still need to fix this.
This is still causing pipelines to fail: https://gitlab.com/samba-team/devel/samba/-/jobs/6864603055 [90(532)/327 at 7m26s] samba3.smb2.multichannel(ad_dc) Testing for BUG 15346 2024-05-16T01:04:02.222702Z: conn[19]: negprot done 2024-05-16T01:04:02.260474Z: conn[4]: negprot done 2024-05-16T01:04:02.290986Z: conn[13]: negprot done 2024-05-16T01:04:02.291057Z: conn[19]: echo done 2024-05-16T01:04:02.306407Z: conn[11]: negprot done 2024-05-16T01:04:02.317536Z: conn[8]: negprot done 2024-05-16T01:04:02.317607Z: conn[13]: echo done 2024-05-16T01:04:02.324551Z: conn[6]: negprot done 2024-05-16T01:04:02.324613Z: conn[11]: echo done 2024-05-16T01:04:02.329075Z: conn[12]: negprot done 2024-05-16T01:04:02.329141Z: conn[8]: echo done 2024-05-16T01:04:02.333879Z: conn[9]: negprot done 2024-05-16T01:04:02.333940Z: conn[6]: echo done 2024-05-16T01:04:02.338496Z: conn[22]: negprot done 2024-05-16T01:04:02.338556Z: conn[12]: echo done 2024-05-16T01:04:02.343189Z: conn[17]: negprot done 2024-05-16T01:04:02.343253Z: conn[9]: echo done 2024-05-16T01:04:02.347971Z: conn[10]: negprot done 2024-05-16T01:04:02.348037Z: conn[22]: echo done 2024-05-16T01:04:02.352655Z: conn[23]: negprot done 2024-05-16T01:04:02.352824Z: conn[17]: echo done 2024-05-16T01:04:02.357504Z: conn[14]: negprot done 2024-05-16T01:04:02.357640Z: conn[10]: echo done 2024-05-16T01:04:02.357714Z: conn[23]: echo done 2024-05-16T01:04:02.369464Z: conn[0]: negprot done 2024-05-16T01:04:02.369607Z: conn[14]: echo done 2024-05-16T01:04:02.374333Z: conn[2]: negprot done 2024-05-16T01:04:02.374486Z: conn[0]: echo done 2024-05-16T01:04:02.387104Z: conn[21]: negprot done 2024-05-16T01:04:02.387185Z: conn[2]: echo done 2024-05-16T01:04:02.392334Z: conn[18]: negprot done 2024-05-16T01:04:02.397616Z: conn[26]: negprot done 2024-05-16T01:04:02.398032Z: conn[21]: echo done 2024-05-16T01:04:02.398241Z: conn[18]: echo done 2024-05-16T01:04:02.407486Z: conn[1]: negprot done 2024-05-16T01:04:02.407564Z: conn[26]: echo done 2024-05-16T01:04:02.412674Z: conn[7]: negprot done 2024-05-16T01:04:02.417497Z: conn[15]: negprot done 2024-05-16T01:04:02.417826Z: conn[1]: echo done 2024-05-16T01:04:02.418013Z: conn[7]: echo done 2024-05-16T01:04:02.422895Z: conn[20]: negprot done 2024-05-16T01:04:02.423181Z: conn[15]: echo done 2024-05-16T01:04:02.427995Z: conn[24]: negprot done 2024-05-16T01:04:02.428316Z: conn[20]: echo done 2024-05-16T01:04:02.433510Z: conn[5]: negprot done 2024-05-16T01:04:02.433954Z: conn[24]: echo done 2024-05-16T01:04:02.439079Z: conn[25]: negprot done 2024-05-16T01:04:02.439371Z: conn[5]: echo done 2024-05-16T01:04:02.444244Z: conn[3]: negprot done 2024-05-16T01:04:02.444497Z: conn[25]: echo done 2024-05-16T01:04:02.449098Z: conn[16]: negprot done 2024-05-16T01:04:02.449330Z: conn[3]: echo done 2024-05-16T01:04:02.454251Z: conn[29]: negprot done 2024-05-16T01:04:02.454500Z: conn[16]: echo done 2024-05-16T01:04:02.459148Z: conn[28]: negprot done 2024-05-16T01:04:02.459387Z: conn[29]: echo done 2024-05-16T01:04:02.471938Z: conn[30]: negprot done 2024-05-16T01:04:02.472318Z: conn[28]: echo done 2024-05-16T01:04:02.477411Z: conn[27]: negprot done 2024-05-16T01:04:02.477693Z: conn[30]: echo done 2024-05-16T01:04:02.477878Z: conn[27]: echo done 2024-05-16T01:05:04.322789Z: conn[4]: echo timed out UNEXPECTED(failure): samba3.smb2.multichannel.bugs.bug_15346(ad_dc) REASON: Exception: Exception: ../../source4/torture/smb2/multichannel.c:2474: status was NT_STATUS_IO_TIMEOUT, expected NT_STATUS_OK: smb2cli_echo_recv failed