Bug 15498 - Test smb2.multichannel.bugs.bug_15346 flaps
Summary: Test smb2.multichannel.bugs.bug_15346 flaps
Status: ASSIGNED
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: File services (show other bugs)
Version: 4.19.0rc2
Hardware: All All
: P5 normal (vote)
Target Milestone: ---
Assignee: Stefan Metzmacher
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on: 15346
Blocks:
  Show dependency treegraph
 
Reported: 2023-10-17 02:22 UTC by Jennifer Sutton
Modified: 2024-05-16 01:11 UTC (History)
2 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Jennifer Sutton 2023-10-17 02:22:50 UTC
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.
Comment 1 Samba QA Contact 2023-10-24 15:52:03 UTC
This bug was referenced in samba master:

e933fd2dadfabc04add3caed9f9496761fadba8c
46f0c2696582ab6561808dcfadcfc5cf9bc67a3a
9f54b94b52db2935affc6b1cb09b71c2907f2289
Comment 2 Andreas Schneider 2023-10-26 17:39:54 UTC
[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)
Comment 3 Jennifer Sutton 2023-10-27 02:57:40 UTC
(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.
Comment 4 Jennifer Sutton 2023-10-27 03:00:26 UTC
(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.
Comment 5 Samba QA Contact 2023-11-02 20:14:04 UTC
This bug was referenced in samba master:

b0a09a69cc8f44077363fe6ecbab8e237e769b13
Comment 6 Andrew Bartlett 2023-11-02 20:25:26 UTC
(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.
Comment 7 Jennifer Sutton 2024-05-16 01:11:44 UTC
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