lib/api tests unreliable, failing ~50% of the time on Fedora Linux #9455
Description
What happened?
I'm the package maintainer for syncthing on Fedora Linux (and for EPEL 9 and 8). We're running tests during package builds, and one of the tests (for the github.com/syncthing/syncthing/lib/api module) has been very unstable and unreliable. This started happening a few releases ago, but it is much worse with v1.27.4 now.
The errors I see most often happen on Linux x86_64. I have seen then occur with both Go 1.22 (Fedora Rawhide and Fedora 40) and Go 1.21 (Fedora 39). With v1.27.4, about half of my attempted builds fail with the log output included below (or output very similar to it).
I am building from the official "source" distribution that includes your vendored dependencies (i.e. not against Go packages that are packaged by the distribution), so there should be no mismatch between the sources and dependencies you use and the ones used for my builds.
Syncthing version
v1.27.4
Platform & operating system
Linux x86_64
Browser version
N/A
Relevant log output
$ go test -buildmode pie -compiler gc -ldflags ' -extldflags '\''-Wl,-z,relro -Wl,--as-needed -Wl,-z,pack-relative-relocs -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld-errors -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -Wl,--build-id=sha1 -specs=/usr/lib/rpm/redhat/redhat-package-notes '\''' github.com/syncthing/syncthing/lib/api
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:35601
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:45031
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:34027
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 INFO: GUI and API listening on [::]:45301
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http:///
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:44831
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:36359
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:43877
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:37173
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:39525
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:46203
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:46383
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 WARNING: Connection priority number for QUIC over WAN must be worse (higher) than QUIC over LAN. Correcting.
2024/03/07 13:01:39 WARNING: Connection priority number for TCP over WAN must be worse (higher) than TCP over LAN. Correcting.
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:37241
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:41315
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 WARNING: Decoding posted config: folder "foo": folder has duplicate ID
2024/03/07 13:01:39 INFO: GUI and API listening on 127.0.0.1:34627
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:39 INFO: GUI and API listening on [::]:33697
2024/03/07 13:01:39 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:40 INFO: GUI and API listening on [::1]:43443
2024/03/07 13:01:40 INFO: Access the GUI via the following URL: http://[::1]:0/
2024/03/07 13:01:40 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:34780
2024/03/07 13:01:40 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:34784
2024/03/07 13:01:40 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:51566
2024/03/07 13:01:40 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:51614
2024/03/07 13:01:40 INFO: GUI and API listening on 127.0.0.1:39313
2024/03/07 13:01:40 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:40 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:40874
2024/03/07 13:01:40 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:40872
2024/03/07 13:01:40 INFO: GUI and API listening on 127.0.0.1:41619
2024/03/07 13:01:40 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:40 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:34506
2024/03/07 13:01:40 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:34470
2024/03/07 13:01:41 INFO: GUI and API listening on 127.0.0.1:33699
2024/03/07 13:01:41 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:41 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:42548
2024/03/07 13:01:41 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:42564
--- FAIL: TestAPIServiceRequests (0.01s)
--- FAIL: TestAPIServiceRequests//rest/db/file?folder=default&file=something (1.00s)
api_test.go:464: Unexpected error requesting /rest/db/file?folder=default&file=something: Get "http://127.0.0.1:44831/rest/db/file?folder=default&file=something": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
--- FAIL: TestAPIServiceRequests//rest/db/need?folder=default (1.00s)
api_test.go:464: Unexpected error requesting /rest/db/need?folder=default: Get "http://127.0.0.1:44831/rest/db/need?folder=default": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
--- FAIL: TestAPIServiceRequests//rest/db/ignores?folder=default (1.00s)
api_test.go:464: Unexpected error requesting /rest/db/ignores?folder=default: Get "http://127.0.0.1:44831/rest/db/ignores?folder=default": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
--- FAIL: TestAPIServiceRequests//rest/system/log?since=0 (1.00s)
api_test.go:464: Unexpected error requesting /rest/system/log?since=0: Get "http://127.0.0.1:44831/rest/system/log?since=0": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
2024/03/07 13:01:41 INFO: GUI and API listening on 127.0.0.1:46033
2024/03/07 13:01:41 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:41 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:50216
2024/03/07 13:01:41 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:50174
2024/03/07 13:01:41 INFO: GUI and API listening on 127.0.0.1:36115
2024/03/07 13:01:41 INFO: Access the GUI via the following URL: http://127.0.0.1:0/
2024/03/07 13:01:41 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:33410
2024/03/07 13:01:41 INFO: Wrong credentials supplied during API authorization from 127.0.0.1:33422
FAIL
FAIL github.com/syncthing/syncthing/lib/api 2.284s
FAIL