WIP: Fix flaky `client_test.go/TestLoad` (!5) · Merge Requests · Kirill Smelkov / neo

WIP: Fix flaky `client_test.go/TestLoad`

Hello Kirill,

today I wanted to amend !2 (merged) by adding tests for its patches. So I was running client_test.go and realized TestLoad sometimes passes and sometimes fails.

I used

Debian 11
NEO/go commit 1c026f97
go version go1.15.15 linux/amd64 & go version go1.18.10 linux/amd64
Python 2.7.18

Did you already see these issues?

I thought maybe it's better to stabilize this first, before extending client tests for NEO cluster with more than one master node.

Best, Levin

levin@debian ~/n/n/g/neo ((1c026f97…))> go test -run TestLoad
2023/06/23 09:44:02 zodb: FIXME: open ../zodb/storage/fs1/testdata/1.fs: raw cache is not ready for invalidations -> NoCache forced
I: runneo.py: /tmp/neo172126318/1 !ssl: started master(s): 127.0.0.1:17167
I: runneo.py: /tmp/neo172126318/1 !ssl: terminated
I: runneo.py: /tmp/neo938026741/1 !ssl: started master(s): 127.0.0.1:17500
I: runneo.py: /tmp/neo938026741/1 !ssl: terminated
I: runneo.py: /tmp/neo938026741/1 !ssl: started master(s): 127.0.0.1:25655
I: runneo.py: /tmp/neo938026741/1 !ssl: terminated
E0623 09:44:13.345182  713219 master.go:962] M1: main: serve: serve C1: [::1]:37149 - [::1]:35318: accept: node link is down
I: runneo.py: /tmp/neo247550416/1 ssl: started master(s): 127.0.0.1:17363
I: runneo.py: /tmp/neo247550416/1 ssl: terminated
I: runneo.py: /tmp/neo002685679/1 ssl: started master(s): 127.0.0.1:19282
I: runneo.py: /tmp/neo002685679/1 ssl: terminated
I: runneo.py: /tmp/neo002685679/1 ssl: started master(s): 127.0.0.1:22599
I: runneo.py: /tmp/neo002685679/1 ssl: terminated
E0623 09:44:30.633918  713219 master.go:962] M1: main: serve: serve C1: [::1]:42895 - [::1]:54998: accept: node link is down
--- FAIL: TestLoad (28.47s)
    --- FAIL: TestLoad/py/ssl (11.39s)
        --- FAIL: TestLoad/py/ssl/enc=N(dialTryOrder=M,N) (6.20s)
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:17363/1: load 0285cbac258bf266:0000000000000000: dial S1: dial 127.0.0.1:44303 (STORAGE): 127.0.0.1:41892 - 127.0.0.1:44303: request identification: 127.0.0.1:41892 - 127.0.0.1:44303 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac258bf266
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned buf = nil
            xtesting.go:339: load 0285cbac258bf265:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:17363/1: load 0285cbac258bf265:0000000000000000: dial S1: dial 127.0.0.1:44303 (STORAGE): 127.0.0.1:41900 - 127.0.0.1:44303: request identification: 127.0.0.1:41900 - 127.0.0.1:44303 .1: recv: EOF
                want: neos://127.0.0.1:17363/1: load 0285cbac258bf265:0000000000000000: 0000000000000000: object was not yet created
FAIL
exit status 1
FAIL    lab.nexedi.com/kirr/neo/go/neo  28.497

levin@debian ~/n/n/g/neo ((1c026f97…)) [1]> go test -run TestLoad
2023/06/23 09:44:38 zodb: FIXME: open ../zodb/storage/fs1/testdata/1.fs: raw cache is not ready for invalidations -> NoCache forced
I: runneo.py: /tmp/neo784273489/1 !ssl: started master(s): 127.0.0.1:21889
I: runneo.py: /tmp/neo784273489/1 !ssl: terminated
I: runneo.py: /tmp/neo792498556/1 !ssl: started master(s): 127.0.0.1:23416
I: runneo.py: /tmp/neo792498556/1 !ssl: terminated
I: runneo.py: /tmp/neo792498556/1 !ssl: started master(s): 127.0.0.1:29387
I: runneo.py: /tmp/neo792498556/1 !ssl: terminated
E0623 09:44:47.573768  713414 master.go:962] M1: main: serve: serve C1: [::1]:40531 - [::1]:55046: accept: node link is down
I: runneo.py: /tmp/neo187340459/1 ssl: started master(s): 127.0.0.1:23463
I: runneo.py: /tmp/neo187340459/1 ssl: terminated
I: runneo.py: /tmp/neo833930254/1 ssl: started master(s): 127.0.0.1:23430
I: runneo.py: /tmp/neo833930254/1 ssl: terminated
I: runneo.py: /tmp/neo833930254/1 ssl: started master(s): 127.0.0.1:27259
I: runneo.py: /tmp/neo833930254/1 ssl: terminated
E0623 09:45:01.299879  713414 xio.go:78] M1: main: serve: serve C1: [::1]:40177 - [::1]:52334: close: write tcp [::1]:40177->[::1]:52334: write: broken pipe
E0623 09:45:01.300107  713414 master.go:962] M1: main: serve: serve C1: [::1]:40177 - [::1]:52334: accept: node link is down
E0623 09:45:01.300173  713414 xio.go:78] M1: [::1]:40177 - [::1]:52334: close: write tcp [::1]:40177->[::1]:52334: write: broken pipe
E0623 09:45:01.300289  713414 nodetab.go:219] M1: main: serve: [::1]:40177 - [::1]:52334: close: write tcp [::1]:40177->[::1]:52334: write: broken pipe
--- FAIL: TestLoad (23.07s)
    --- FAIL: TestLoad/py/ssl (7.88s)
        --- FAIL: TestLoad/py/ssl/enc=N(dialTryOrder=M,N) (4.20s)
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:23463/1: load 0285cbac258bf266:0000000000000000: dial S1: dial 127.0.0.1:35999 (STORAGE): 127.0.0.1:59906 - 127.0.0.1:35999: request identification: 127.0.0.1:59906 - 127.0.0.1:35999 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac258bf266
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned buf = nil
FAIL
exit status 1
FAIL    lab.nexedi.com/kirr/neo/go/neo  23.080s

levin@debian ~/n/n/g/neo ((1c026f97…))> /lib/go-1.18/bin/go test -run TestLoad
2023/06/23 10:08:39 zodb: FIXME: open ../zodb/storage/fs1/testdata/1.fs: raw cache is not ready for invalidations -> NoCache forced
I: runneo.py: /tmp/neo3334596047/1 !ssl: started master(s): 127.0.0.1:22186
I: runneo.py: /tmp/neo3334596047/1 !ssl: terminated
I: runneo.py: /tmp/neo1420152872/1 !ssl: started master(s): 127.0.0.1:23953
I: runneo.py: /tmp/neo1420152872/1 !ssl: terminated
I: runneo.py: /tmp/neo1420152872/1 !ssl: started master(s): 127.0.0.1:31149
I: runneo.py: /tmp/neo1420152872/1 !ssl: terminated
E0623 10:08:49.645352  725498 master.go:962] M1: main: serve: serve C1: [::1]:35335 - [::1]:45134: accept: node link is down
E0623 10:08:49.677909  725498 master.go:962] M1: main: serve: serve C2: [::1]:35335 - [::1]:45150: accept: node link is down
I: runneo.py: /tmp/neo511026990/1 ssl: started master(s): 127.0.0.1:30823
I: runneo.py: /tmp/neo511026990/1 ssl: terminated
I: runneo.py: /tmp/neo2983668233/1 ssl: started master(s): 127.0.0.1:22245
I: runneo.py: /tmp/neo2983668233/1 ssl: terminated
I: runneo.py: /tmp/neo2983668233/1 ssl: started master(s): 127.0.0.1:24578
I: runneo.py: /tmp/neo2983668233/1 ssl: terminated
E0623 10:09:17.087476  725498 xio.go:78] M1: main: serve: serve C1: [::1]:35031 - [::1]:40752: close: tls: failed to send closeNotify alert (but connection was closed anyway): write tcp [::1]:35031->[::1]:40752: write: broken pipe
E0623 10:09:17.087849  725498 master.go:962] M1: main: serve: serve C1: [::1]:35031 - [::1]:40752: accept: node link is down
E0623 10:09:17.087998  725498 xio.go:78] M1: [::1]:35031 - [::1]:40752: close: tls: failed to send closeNotify alert (but connection was closed anyway): write tcp [::1]:35031->[::1]:40752: write: broken pipe
E0623 10:09:17.088176  725498 nodetab.go:219] M1: main: serve: [::1]:35031 - [::1]:40752: close: tls: failed to send closeNotify alert (but connection was closed anyway): write tcp [::1]:35031->[::1]:40752: write: broken pipe
--- FAIL: TestLoad (38.10s)
    --- FAIL: TestLoad/py/ssl (21.13s)
        --- FAIL: TestLoad/py/ssl/enc=N(dialTryOrder=M,N) (17.38s)
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:30823/1: load 0285cbac258bf266:0000000000000000: dial S1: dial 127.0.0.1:46515 (STORAGE): 127.0.0.1:43962 - 127.0.0.1:46515: request identification: 127.0.0.1:43962 - 127.0.0.1:46515 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac258bf266
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned buf = nil
            xtesting.go:339: load 0285cbac258bf265:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:30823/1: load 0285cbac258bf265:0000000000000000: dial S1: dial 127.0.0.1:46515 (STORAGE): 127.0.0.1:43966 - 127.0.0.1:46515: request identification: 127.0.0.1:43966 - 127.0.0.1:46515 .1: recv: EOF
                want: neos://127.0.0.1:30823/1: load 0285cbac258bf265:0000000000000000: 0000000000000000: object was not yet created
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:30823/1: load 0285cbac3d0369e6:0000000000000000: dial S1: dial 127.0.0.1:46515 (STORAGE): 127.0.0.1:43982 - 127.0.0.1:46515: request identification: 127.0.0.1:43982 - 127.0.0.1:46515 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac3d0369e6
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000000: returned buf = nil
            xtesting.go:336: load 0285cbac3d0369e5:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:30823/1: load 0285cbac3d0369e5:0000000000000000: dial S1: dial 127.0.0.1:46515 (STORAGE): 127.0.0.1:50180 - 127.0.0.1:46515: request identification: 127.0.0.1:50180 - 127.0.0.1:46515 .1: recv: EOF
                want: nil
            xtesting.go:336: load 0285cbac3d0369e5:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac258bf266
            xtesting.go:336: load 0285cbac3d0369e5:0000000000000000: returned buf = nil
FAIL
exit status 1
FAIL    lab.nexedi.com/kirr/neo/go/neo  38.110s

levin@debian ~/n/n/g/neo ((1c026f97…)) [1]> /lib/go-1.18/bin/go test -run TestLoad
2023/06/23 10:10:19 zodb: FIXME: open ../zodb/storage/fs1/testdata/1.fs: raw cache is not ready for invalidations -> NoCache forced
I: runneo.py: /tmp/neo1087514255/1 !ssl: started master(s): 127.0.0.1:21145
I: runneo.py: /tmp/neo1087514255/1 !ssl: terminated
I: runneo.py: /tmp/neo821816103/1 !ssl: started master(s): 127.0.0.1:26352
I: runneo.py: /tmp/neo821816103/1 !ssl: terminated
I: runneo.py: /tmp/neo821816103/1 !ssl: started master(s): 127.0.0.1:22040
I: runneo.py: /tmp/neo821816103/1 !ssl: terminated
E0623 10:10:31.740509  726102 master.go:962] M1: main: serve: serve C1: [::1]:42583 - [::1]:40172: accept: node link is down
I: runneo.py: /tmp/neo1166413695/1 ssl: started master(s): 127.0.0.1:23876
I: runneo.py: /tmp/neo1166413695/1 ssl: terminated
I: runneo.py: /tmp/neo4117007582/1 ssl: started master(s): 127.0.0.1:31577
I: runneo.py: /tmp/neo4117007582/1 ssl: terminated
I: runneo.py: /tmp/neo4117007582/1 ssl: started master(s): 127.0.0.1:29934
I: runneo.py: /tmp/neo4117007582/1 ssl: terminated
E0623 10:11:00.540241  726102 xio.go:78] M1: main: serve: serve C1: [::1]:38445 - [::1]:59650: close: tls: failed to send closeNotify alert (but connection was closed anyway): write tcp [::1]:38445->[::1]:59650: write: broken pipe
E0623 10:11:00.540591  726102 master.go:962] M1: main: serve: serve C1: [::1]:38445 - [::1]:59650: accept: node link is down
E0623 10:11:00.540739  726102 xio.go:78] M1: [::1]:38445 - [::1]:59650: close: tls: failed to send closeNotify alert (but connection was closed anyway): write tcp [::1]:38445->[::1]:59650: write: broken pipe
E0623 10:11:00.540902  726102 nodetab.go:219] M1: main: serve: [::1]:38445 - [::1]:59650: close: tls: failed to send closeNotify alert (but connection was closed anyway): write tcp [::1]:38445->[::1]:59650: write: broken pipe
--- FAIL: TestLoad (41.38s)
    --- FAIL: TestLoad/py/ssl (23.97s)
        --- FAIL: TestLoad/py/ssl/enc=N(dialTryOrder=M,N) (19.30s)
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:23876/1: load 0285cbac258bf266:0000000000000000: dial S1: dial 127.0.0.1:46147 (STORAGE): 127.0.0.1:57216 - 127.0.0.1:46147: request identification: 127.0.0.1:57216 - 127.0.0.1:46147 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac258bf266
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned buf = nil
            xtesting.go:339: load 0285cbac258bf265:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:23876/1: load 0285cbac258bf265:0000000000000000: dial S1: dial 127.0.0.1:46147 (STORAGE): 127.0.0.1:57228 - 127.0.0.1:46147: request identification: 127.0.0.1:57228 - 127.0.0.1:46147 .1: recv: EOF
                want: neos://127.0.0.1:23876/1: load 0285cbac258bf265:0000000000000000: 0000000000000000: object was not yet created
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:23876/1: load 0285cbac3d0369e6:0000000000000000: dial S1: dial 127.0.0.1:46147 (STORAGE): 127.0.0.1:57236 - 127.0.0.1:46147: request identification: 127.0.0.1:57236 - 127.0.0.1:46147 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac3d0369e6
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000000: returned buf = nil
            xtesting.go:336: load 0285cbac3d0369e5:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:23876/1: load 0285cbac3d0369e5:0000000000000000: dial S1: dial 127.0.0.1:46147 (STORAGE): 127.0.0.1:57248 - 127.0.0.1:46147: request identification: 127.0.0.1:57248 - 127.0.0.1:46147 .1: recv: EOF
                want: nil
            xtesting.go:336: load 0285cbac3d0369e5:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac258bf266
            xtesting.go:336: load 0285cbac3d0369e5:0000000000000000: returned buf = nil
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000001: returned err unexpected:
                have: neos://127.0.0.1:23876/1: load 0285cbac3d0369e6:0000000000000001: dial S1: dial 127.0.0.1:46147 (STORAGE): 127.0.0.1:41126 - 127.0.0.1:46147: request identification: 127.0.0.1:41126 - 127.0.0.1:46147 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000001: returned tid unexpected: 0000000000000000  ; want: 0285cbac3d0369e6
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000001: returned buf = nil
            xtesting.go:339: load 0285cbac3d0369e5:0000000000000001: returned err unexpected:
                have: neos://127.0.0.1:23876/1: load 0285cbac3d0369e5:0000000000000001: dial S1: dial 127.0.0.1:46147 (STORAGE): 127.0.0.1:41134 - 127.0.0.1:46147: request identification: 127.0.0.1:41134 - 127.0.0.1:46147 .1: recv: EOF
                want: neos://127.0.0.1:23876/1: load 0285cbac3d0369e5:0000000000000001: 0000000000000001: object was not yet created
FAIL
exit status 1
FAIL    lab.nexedi.com/kirr/neo/go/neo  41.386s

Hello Kirill,

today I wanted to amend https://lab.nexedi.com/kirr/neo/merge_requests/2 by adding tests for its patches.
So I was running `client_test.go` and realized `TestLoad` sometimes passes and sometimes fails.

I used

- `Debian 11`
- NEO/go commit https://lab.nexedi.com/kirr/neo/commit/1c026f97c4302c5cb4b2205c1ca5247a0c1ce6d9
- `go version go1.15.15 linux/amd64` & `go version go1.18.10 linux/amd64`
- `Python 2.7.18`

Did you already see these issues?

I thought maybe it's better to stabilize this first, before extending client tests for NEO cluster with more than one master node.

Best, Levin

---

```
levin@debian ~/n/n/g/neo ((1c026f97…))> go test -run TestLoad
2023/06/23 09:44:02 zodb: FIXME: open ../zodb/storage/fs1/testdata/1.fs: raw cache is not ready for invalidations -> NoCache forced
I: runneo.py: /tmp/neo172126318/1 !ssl: started master(s): 127.0.0.1:17167
I: runneo.py: /tmp/neo172126318/1 !ssl: terminated
I: runneo.py: /tmp/neo938026741/1 !ssl: started master(s): 127.0.0.1:17500
I: runneo.py: /tmp/neo938026741/1 !ssl: terminated
I: runneo.py: /tmp/neo938026741/1 !ssl: started master(s): 127.0.0.1:25655
I: runneo.py: /tmp/neo938026741/1 !ssl: terminated
E0623 09:44:13.345182  713219 master.go:962] M1: main: serve: serve C1: [::1]:37149 - [::1]:35318: accept: node link is down
I: runneo.py: /tmp/neo247550416/1 ssl: started master(s): 127.0.0.1:17363
I: runneo.py: /tmp/neo247550416/1 ssl: terminated
I: runneo.py: /tmp/neo002685679/1 ssl: started master(s): 127.0.0.1:19282
I: runneo.py: /tmp/neo002685679/1 ssl: terminated
I: runneo.py: /tmp/neo002685679/1 ssl: started master(s): 127.0.0.1:22599
I: runneo.py: /tmp/neo002685679/1 ssl: terminated
E0623 09:44:30.633918  713219 master.go:962] M1: main: serve: serve C1: [::1]:42895 - [::1]:54998: accept: node link is down
--- FAIL: TestLoad (28.47s)
    --- FAIL: TestLoad/py/ssl (11.39s)
        --- FAIL: TestLoad/py/ssl/enc=N(dialTryOrder=M,N) (6.20s)
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:17363/1: load 0285cbac258bf266:0000000000000000: dial S1: dial 127.0.0.1:44303 (STORAGE): 127.0.0.1:41892 - 127.0.0.1:44303: request identification: 127.0.0.1:41892 - 127.0.0.1:44303 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac258bf266
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned buf = nil
            xtesting.go:339: load 0285cbac258bf265:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:17363/1: load 0285cbac258bf265:0000000000000000: dial S1: dial 127.0.0.1:44303 (STORAGE): 127.0.0.1:41900 - 127.0.0.1:44303: request identification: 127.0.0.1:41900 - 127.0.0.1:44303 .1: recv: EOF
                want: neos://127.0.0.1:17363/1: load 0285cbac258bf265:0000000000000000: 0000000000000000: object was not yet created
FAIL
exit status 1
FAIL    lab.nexedi.com/kirr/neo/go/neo  28.497
```

---

```
levin@debian ~/n/n/g/neo ((1c026f97…)) [1]> go test -run TestLoad
2023/06/23 09:44:38 zodb: FIXME: open ../zodb/storage/fs1/testdata/1.fs: raw cache is not ready for invalidations -> NoCache forced
I: runneo.py: /tmp/neo784273489/1 !ssl: started master(s): 127.0.0.1:21889
I: runneo.py: /tmp/neo784273489/1 !ssl: terminated
I: runneo.py: /tmp/neo792498556/1 !ssl: started master(s): 127.0.0.1:23416
I: runneo.py: /tmp/neo792498556/1 !ssl: terminated
I: runneo.py: /tmp/neo792498556/1 !ssl: started master(s): 127.0.0.1:29387
I: runneo.py: /tmp/neo792498556/1 !ssl: terminated
E0623 09:44:47.573768  713414 master.go:962] M1: main: serve: serve C1: [::1]:40531 - [::1]:55046: accept: node link is down
I: runneo.py: /tmp/neo187340459/1 ssl: started master(s): 127.0.0.1:23463
I: runneo.py: /tmp/neo187340459/1 ssl: terminated
I: runneo.py: /tmp/neo833930254/1 ssl: started master(s): 127.0.0.1:23430
I: runneo.py: /tmp/neo833930254/1 ssl: terminated
I: runneo.py: /tmp/neo833930254/1 ssl: started master(s): 127.0.0.1:27259
I: runneo.py: /tmp/neo833930254/1 ssl: terminated
E0623 09:45:01.299879  713414 xio.go:78] M1: main: serve: serve C1: [::1]:40177 - [::1]:52334: close: write tcp [::1]:40177->[::1]:52334: write: broken pipe
E0623 09:45:01.300107  713414 master.go:962] M1: main: serve: serve C1: [::1]:40177 - [::1]:52334: accept: node link is down
E0623 09:45:01.300173  713414 xio.go:78] M1: [::1]:40177 - [::1]:52334: close: write tcp [::1]:40177->[::1]:52334: write: broken pipe
E0623 09:45:01.300289  713414 nodetab.go:219] M1: main: serve: [::1]:40177 - [::1]:52334: close: write tcp [::1]:40177->[::1]:52334: write: broken pipe
--- FAIL: TestLoad (23.07s)
    --- FAIL: TestLoad/py/ssl (7.88s)
        --- FAIL: TestLoad/py/ssl/enc=N(dialTryOrder=M,N) (4.20s)
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:23463/1: load 0285cbac258bf266:0000000000000000: dial S1: dial 127.0.0.1:35999 (STORAGE): 127.0.0.1:59906 - 127.0.0.1:35999: request identification: 127.0.0.1:59906 - 127.0.0.1:35999 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac258bf266
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned buf = nil
FAIL
exit status 1
FAIL    lab.nexedi.com/kirr/neo/go/neo  23.080s
```

---

```
levin@debian ~/n/n/g/neo ((1c026f97…))> /lib/go-1.18/bin/go test -run TestLoad
2023/06/23 10:08:39 zodb: FIXME: open ../zodb/storage/fs1/testdata/1.fs: raw cache is not ready for invalidations -> NoCache forced
I: runneo.py: /tmp/neo3334596047/1 !ssl: started master(s): 127.0.0.1:22186
I: runneo.py: /tmp/neo3334596047/1 !ssl: terminated
I: runneo.py: /tmp/neo1420152872/1 !ssl: started master(s): 127.0.0.1:23953
I: runneo.py: /tmp/neo1420152872/1 !ssl: terminated
I: runneo.py: /tmp/neo1420152872/1 !ssl: started master(s): 127.0.0.1:31149
I: runneo.py: /tmp/neo1420152872/1 !ssl: terminated
E0623 10:08:49.645352  725498 master.go:962] M1: main: serve: serve C1: [::1]:35335 - [::1]:45134: accept: node link is down
E0623 10:08:49.677909  725498 master.go:962] M1: main: serve: serve C2: [::1]:35335 - [::1]:45150: accept: node link is down
I: runneo.py: /tmp/neo511026990/1 ssl: started master(s): 127.0.0.1:30823
I: runneo.py: /tmp/neo511026990/1 ssl: terminated
I: runneo.py: /tmp/neo2983668233/1 ssl: started master(s): 127.0.0.1:22245
I: runneo.py: /tmp/neo2983668233/1 ssl: terminated
I: runneo.py: /tmp/neo2983668233/1 ssl: started master(s): 127.0.0.1:24578
I: runneo.py: /tmp/neo2983668233/1 ssl: terminated
E0623 10:09:17.087476  725498 xio.go:78] M1: main: serve: serve C1: [::1]:35031 - [::1]:40752: close: tls: failed to send closeNotify alert (but connection was closed anyway): write tcp [::1]:35031->[::1]:40752: write: broken pipe
E0623 10:09:17.087849  725498 master.go:962] M1: main: serve: serve C1: [::1]:35031 - [::1]:40752: accept: node link is down
E0623 10:09:17.087998  725498 xio.go:78] M1: [::1]:35031 - [::1]:40752: close: tls: failed to send closeNotify alert (but connection was closed anyway): write tcp [::1]:35031->[::1]:40752: write: broken pipe
E0623 10:09:17.088176  725498 nodetab.go:219] M1: main: serve: [::1]:35031 - [::1]:40752: close: tls: failed to send closeNotify alert (but connection was closed anyway): write tcp [::1]:35031->[::1]:40752: write: broken pipe
--- FAIL: TestLoad (38.10s)
    --- FAIL: TestLoad/py/ssl (21.13s)
        --- FAIL: TestLoad/py/ssl/enc=N(dialTryOrder=M,N) (17.38s)
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:30823/1: load 0285cbac258bf266:0000000000000000: dial S1: dial 127.0.0.1:46515 (STORAGE): 127.0.0.1:43962 - 127.0.0.1:46515: request identification: 127.0.0.1:43962 - 127.0.0.1:46515 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac258bf266
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned buf = nil
            xtesting.go:339: load 0285cbac258bf265:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:30823/1: load 0285cbac258bf265:0000000000000000: dial S1: dial 127.0.0.1:46515 (STORAGE): 127.0.0.1:43966 - 127.0.0.1:46515: request identification: 127.0.0.1:43966 - 127.0.0.1:46515 .1: recv: EOF
                want: neos://127.0.0.1:30823/1: load 0285cbac258bf265:0000000000000000: 0000000000000000: object was not yet created
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:30823/1: load 0285cbac3d0369e6:0000000000000000: dial S1: dial 127.0.0.1:46515 (STORAGE): 127.0.0.1:43982 - 127.0.0.1:46515: request identification: 127.0.0.1:43982 - 127.0.0.1:46515 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac3d0369e6
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000000: returned buf = nil
            xtesting.go:336: load 0285cbac3d0369e5:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:30823/1: load 0285cbac3d0369e5:0000000000000000: dial S1: dial 127.0.0.1:46515 (STORAGE): 127.0.0.1:50180 - 127.0.0.1:46515: request identification: 127.0.0.1:50180 - 127.0.0.1:46515 .1: recv: EOF
                want: nil
            xtesting.go:336: load 0285cbac3d0369e5:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac258bf266
            xtesting.go:336: load 0285cbac3d0369e5:0000000000000000: returned buf = nil
FAIL
exit status 1
FAIL    lab.nexedi.com/kirr/neo/go/neo  38.110s
```

---

```
levin@debian ~/n/n/g/neo ((1c026f97…)) [1]> /lib/go-1.18/bin/go test -run TestLoad
2023/06/23 10:10:19 zodb: FIXME: open ../zodb/storage/fs1/testdata/1.fs: raw cache is not ready for invalidations -> NoCache forced
I: runneo.py: /tmp/neo1087514255/1 !ssl: started master(s): 127.0.0.1:21145
I: runneo.py: /tmp/neo1087514255/1 !ssl: terminated
I: runneo.py: /tmp/neo821816103/1 !ssl: started master(s): 127.0.0.1:26352
I: runneo.py: /tmp/neo821816103/1 !ssl: terminated
I: runneo.py: /tmp/neo821816103/1 !ssl: started master(s): 127.0.0.1:22040
I: runneo.py: /tmp/neo821816103/1 !ssl: terminated
E0623 10:10:31.740509  726102 master.go:962] M1: main: serve: serve C1: [::1]:42583 - [::1]:40172: accept: node link is down
I: runneo.py: /tmp/neo1166413695/1 ssl: started master(s): 127.0.0.1:23876
I: runneo.py: /tmp/neo1166413695/1 ssl: terminated
I: runneo.py: /tmp/neo4117007582/1 ssl: started master(s): 127.0.0.1:31577
I: runneo.py: /tmp/neo4117007582/1 ssl: terminated
I: runneo.py: /tmp/neo4117007582/1 ssl: started master(s): 127.0.0.1:29934
I: runneo.py: /tmp/neo4117007582/1 ssl: terminated
E0623 10:11:00.540241  726102 xio.go:78] M1: main: serve: serve C1: [::1]:38445 - [::1]:59650: close: tls: failed to send closeNotify alert (but connection was closed anyway): write tcp [::1]:38445->[::1]:59650: write: broken pipe
E0623 10:11:00.540591  726102 master.go:962] M1: main: serve: serve C1: [::1]:38445 - [::1]:59650: accept: node link is down
E0623 10:11:00.540739  726102 xio.go:78] M1: [::1]:38445 - [::1]:59650: close: tls: failed to send closeNotify alert (but connection was closed anyway): write tcp [::1]:38445->[::1]:59650: write: broken pipe
E0623 10:11:00.540902  726102 nodetab.go:219] M1: main: serve: [::1]:38445 - [::1]:59650: close: tls: failed to send closeNotify alert (but connection was closed anyway): write tcp [::1]:38445->[::1]:59650: write: broken pipe
--- FAIL: TestLoad (41.38s)
    --- FAIL: TestLoad/py/ssl (23.97s)
        --- FAIL: TestLoad/py/ssl/enc=N(dialTryOrder=M,N) (19.30s)
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:23876/1: load 0285cbac258bf266:0000000000000000: dial S1: dial 127.0.0.1:46147 (STORAGE): 127.0.0.1:57216 - 127.0.0.1:46147: request identification: 127.0.0.1:57216 - 127.0.0.1:46147 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac258bf266
            xtesting.go:330: load 0285cbac258bf266:0000000000000000: returned buf = nil
            xtesting.go:339: load 0285cbac258bf265:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:23876/1: load 0285cbac258bf265:0000000000000000: dial S1: dial 127.0.0.1:46147 (STORAGE): 127.0.0.1:57228 - 127.0.0.1:46147: request identification: 127.0.0.1:57228 - 127.0.0.1:46147 .1: recv: EOF
                want: neos://127.0.0.1:23876/1: load 0285cbac258bf265:0000000000000000: 0000000000000000: object was not yet created
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:23876/1: load 0285cbac3d0369e6:0000000000000000: dial S1: dial 127.0.0.1:46147 (STORAGE): 127.0.0.1:57236 - 127.0.0.1:46147: request identification: 127.0.0.1:57236 - 127.0.0.1:46147 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac3d0369e6
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000000: returned buf = nil
            xtesting.go:336: load 0285cbac3d0369e5:0000000000000000: returned err unexpected:
                have: neos://127.0.0.1:23876/1: load 0285cbac3d0369e5:0000000000000000: dial S1: dial 127.0.0.1:46147 (STORAGE): 127.0.0.1:57248 - 127.0.0.1:46147: request identification: 127.0.0.1:57248 - 127.0.0.1:46147 .1: recv: EOF
                want: nil
            xtesting.go:336: load 0285cbac3d0369e5:0000000000000000: returned tid unexpected: 0000000000000000  ; want: 0285cbac258bf266
            xtesting.go:336: load 0285cbac3d0369e5:0000000000000000: returned buf = nil
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000001: returned err unexpected:
                have: neos://127.0.0.1:23876/1: load 0285cbac3d0369e6:0000000000000001: dial S1: dial 127.0.0.1:46147 (STORAGE): 127.0.0.1:41126 - 127.0.0.1:46147: request identification: 127.0.0.1:41126 - 127.0.0.1:46147 .1: recv: EOF
                want: nil
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000001: returned tid unexpected: 0000000000000000  ; want: 0285cbac3d0369e6
            xtesting.go:330: load 0285cbac3d0369e6:0000000000000001: returned buf = nil
            xtesting.go:339: load 0285cbac3d0369e5:0000000000000001: returned err unexpected:
                have: neos://127.0.0.1:23876/1: load 0285cbac3d0369e5:0000000000000001: dial S1: dial 127.0.0.1:46147 (STORAGE): 127.0.0.1:41134 - 127.0.0.1:46147: request identification: 127.0.0.1:41134 - 127.0.0.1:46147 .1: recv: EOF
                want: neos://127.0.0.1:23876/1: load 0285cbac3d0369e5:0000000000000001: 0000000000000001: object was not yet created
FAIL
exit status 1
FAIL    lab.nexedi.com/kirr/neo/go/neo  41.386s
```

WIP: Fix flaky `client_test.go/TestLoad`

Check out, review, and merge locally

Revert this merge request

Cherry-pick this merge request