Open laurentsenta opened 2 years ago
First attempt, getting a 404 on some lib: (commit: 9430dde797e65b06bb56827a7ab23b2ce59ce1fb)
Step 13/23 : RUN echo "Using go proxy: ${GO_PROXY}" && cd ${PLAN_DIR} && go env -w GOPROXY="${GO_PROXY}" && go mod download
---> Running in 9026992102ac
Using go proxy: http://testground-goproxy:8081
go mod download: github.com/francoispqt/gojay@v1.2.13 requires
cloud.google.com/go@v0.37.0 requires
go.opencensus.io@v0.18.0 requires
google.golang.org/api@v0.0.0-20180910000450-7ca32eb868bf: reading http://testground-goproxy:8081/google.golang.org/api/@v/v0.0.0-20180910000450-7ca32eb868bf.mod: 404 Not Found
server response:
go mod download -json google.golang.org/api@v0.0.0-20180910000450-7ca32eb868bf:
{
"Path": "google.golang.org/api",
"Version": "v0.0.0-20180910000450-7ca32eb868bf",
[Truncated: too long.]
Apr 25 15:40:31.057450 INFO build failed {"plan": "ping", "groups": ["single"], "builder": "docker:go", "error": "docker build failed: The command '/bin/sh -c echo \"Using go proxy: ${GO_PROXY}\" && cd ${PLAN_DIR} && go env -w GOPROXY=\"${GO_PROXY}\" && go mod download' returned a non-zero code: 1"}
Doing a go get -u to move from libp2p 0.17 to 0.19.
Second attempt: (twice with a docker clear in between)
Step 13/23 : RUN echo "Using go proxy: ${GO_PROXY}" && cd ${PLAN_DIR} && go env -w GOPROXY="${GO_PROXY}" && go mod download
---> Running in fb620caf842b
Using go proxy: http://testground-goproxy:8081
go mod download: github.com/fsnotify/fsnotify@v1.5.3: verifying go.mod: checksum mismatch
downloaded: h1:EOpbeAJhdpekq8sZhpAlwLODDoZNgN3BMRphsKZMJfU=
sum.golang.org: h1:T3375wBYaZdLLcVNkcVbzGHY7f1l/uK5T5Ai1i3InKU=
SECURITY ERROR
This download does NOT match the one reported by the checksum server.
The bits may have been replaced on the origin server, or an attacker may
have intercepted the download attempt.
For more information, see 'go help module-auth'.
Tried using a clean modcache, not working, Moving to fsnotify v1.5.1 solved the issue,
Error (on Ubuntu)
Apr 25 17:53:21.619781 [34mINFO[0m 3.9745s [30;47m MESSAGE[0m [33m<< version-b[000] (30755c) >>[0m Dial peer: QmXrzArCEHAQs8opBRKQrehJv5YTjhjmULWaYFXoVTZj8u
Apr 25 17:53:21.619850 [34mINFO[0m 3.9746s [30;47m MESSAGE[0m [32m<< version-a[000] (df8144) >>[0m done dialling my peers
Apr 25 17:53:21.621953 [34mINFO[0m 3.9770s [37;41m ERROR[0m [33m<< version-b[000] (30755c) >>[0m panic: send on closed channel
Apr 25 17:53:21.621985 [34mINFO[0m 3.9771s [37;41m ERROR[0m [33m<< version-b[000] (30755c) >>[0m
Apr 25 17:53:21.622011 [34mINFO[0m 3.9771s [37;41m ERROR[0m [33m<< version-b[000] (30755c) >>[0m goroutine 27 [running]:
Apr 25 17:53:21.622029 [34mINFO[0m 3.9771s [37;41m ERROR[0m [33m<< version-b[000] (30755c) >>[0m github.com/testground/sdk-go/sync.(*DefaultClient).responsesWorker(0xc000304150)
Apr 25 17:53:21.622054 [34mINFO[0m 3.9771s [37;41m ERROR[0m [33m<< version-b[000] (30755c) >>[0m /go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/sync/client_conn.go:43 +0x285
Apr 25 17:53:21.622076 [34mINFO[0m 3.9772s [37;41m ERROR[0m [33m<< version-b[000] (30755c) >>[0m created by github.com/testground/sdk-go/sync.newClient
Apr 25 17:53:21.622094 [34mINFO[0m 3.9772s [37;41m ERROR[0m [33m<< version-b[000] (30755c) >>[0m /go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/sync/client.go:118 +0x1e7
Apr 25 17:53:21.705462 [34mINFO[0m 4.0605s [37;101mINCOMPLETE[0m [33m<< version-b[000] (30755c) >>[0m
Apr 25 17:58:21.406298 [34mINFO[0m 303.7601s [37;101m CRASH[0m [32m<< version-a[000] (df8144) >>[0m goroutine 13 [running]:
runtime/debug.Stack()
/usr/local/go/src/runtime/debug/stack.go:24 +0x65
github.com/testground/sdk-go/run.HandlePanics()
/go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/run/panic.go:23 +0x39
panic({0xd79ce0, 0xc002139090})
/usr/local/go/src/runtime/panic.go:1038 +0x215
github.com/testground/sdk-go/sync.(*sugarOperations).MustSignalAndWait(0x2, {0x12bf2a0, 0xc000c4e240}, {0xed9558, 0xd9be60}, 0xc0007e2100)
/go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/sync/client_sugar.go:104 +0x48
main.runPing(0xc000262d00, 0xc001f90d50)
/plan/main.go:236 +0xd8d
github.com/testground/sdk-go/run.invoke.func4()
/go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/run/invoker.go:173 +0x194
created by github.com/testground/sdk-go/run.invoke
/go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/run/invoker.go:162 +0x551
goroutine 1 [running]:
runtime/debug.Stack()
/usr/local/go/src/runtime/debug/stack.go:24 +0x65
github.com/testground/sdk-go/runtime.(*RunEnv).RecordCrash(0xc000262d00, {0xd4afe0, 0xc0007fc050})
/go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/runtime/runenv_events.go:246 +0x7b
github.com/testground/sdk-go/run.invoke(0xc000262d00, {0xd6d680, 0x1182148})
/go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/run/invoker.go:190 +0x6b4
github.com/testground/sdk-go/run.InvokeMap(0xc0000001a0)
/go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/run/invoker.go:77 +0x94
main.main()
/plan/main.go:53 +0x25
Apr 25 17:58:21.471147 [34mINFO[0m 303.8253s [37;101m CRASH[0m [32m<< version-a[000] (df8144) >>[0m channel closed before getting responsegoroutine 1 [running]:
runtime/debug.Stack()
/usr/local/go/src/runtime/debug/stack.go:24 +0x65
github.com/testground/sdk-go/runtime.(*RunEnv).RecordCrash(0xc000262d00, {0xd79ce0, 0xc002139090})
/go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/runtime/runenv_events.go:246 +0x7b
github.com/testground/sdk-go/run.invoke.func3()
/go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/run/invoker.go:147 +0x4a
panic({0xd79ce0, 0xc002139090})
/usr/local/go/src/runtime/panic.go:1038 +0x215
github.com/testground/sdk-go/run.invoke(0xc000262d00, {0xd6d680, 0x1182148})
/go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/run/invoker.go:191 +0x6c6
github.com/testground/sdk-go/run.InvokeMap(0xc0000001a0)
/go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/run/invoker.go:77 +0x94
main.main()
/plan/main.go:53 +0x25
Apr 25 17:58:21.529130 [34mINFO[0m 303.8842s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m channel closed before getting response
Apr 25 17:58:21.529319 [34mINFO[0m 303.8844s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m goroutine 1 [running]:
Apr 25 17:58:21.529435 [34mINFO[0m 303.8845s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m runtime/debug.Stack()
Apr 25 17:58:21.529492 [34mINFO[0m 303.8846s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m /usr/local/go/src/runtime/debug/stack.go:24 +0x65
Apr 25 17:58:21.529582 [34mINFO[0m 303.8847s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m runtime/debug.PrintStack()
Apr 25 17:58:21.529634 [34mINFO[0m 303.8847s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m /usr/local/go/src/runtime/debug/stack.go:16 +0x19
Apr 25 17:58:21.529676 [34mINFO[0m 303.8848s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m github.com/testground/sdk-go/run.invoke.func3()
Apr 25 17:58:21.529724 [34mINFO[0m 303.8848s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m /go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/run/invoker.go:151 +0x8a
Apr 25 17:58:21.529781 [34mINFO[0m 303.8849s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m panic({0xd79ce0, 0xc002139090})
Apr 25 17:58:21.529850 [34mINFO[0m 303.8849s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m /usr/local/go/src/runtime/panic.go:1038 +0x215
Apr 25 17:58:21.529904 [34mINFO[0m 303.8850s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m github.com/testground/sdk-go/run.invoke(0xc000262d00, {0xd6d680, 0x1182148})
Apr 25 17:58:21.529955 [34mINFO[0m 303.8850s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m /go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/run/invoker.go:191 +0x6c6
Apr 25 17:58:21.530004 [34mINFO[0m 303.8851s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m github.com/testground/sdk-go/run.InvokeMap(0xc0000001a0)
Apr 25 17:58:21.530055 [34mINFO[0m 303.8851s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m /go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/run/invoker.go:77 +0x94
Apr 25 17:58:21.530106 [34mINFO[0m 303.8852s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m main.main()
Apr 25 17:58:21.530199 [34mINFO[0m 303.8852s [37;41m ERROR[0m [32m<< version-a[000] (df8144) >>[0m /plan/main.go:53 +0x25
Apr 25 17:58:22.933314 [34mINFO[0m deleting containers {"runner": "local:docker", "run_id": "c9je02iel22qnuhs299g", "ids": ["df8144ca01ee0a66f283c2a16905949bf2d53154fbc14bb898f132fa4c2d185b", "30755c0d1e7dbe4c6ecc2c694d2709db28a4f241e38194ed755c20bd552c15e4"]}
Apr 25 17:58:22.933372 [34mINFO[0m deleting container {"runner": "local:docker", "run_id": "c9je02iel22qnuhs299g", "id": "30755c0d1e7dbe4c6ecc2c694d2709db28a4f241e38194ed755c20bd552c15e4"}
Apr 25 17:58:22.933376 [34mINFO[0m deleting container {"runner": "local:docker", "run_id": "c9je02iel22qnuhs299g", "id": "df8144ca01ee0a66f283c2a16905949bf2d53154fbc14bb898f132fa4c2d185b"}
Apr 25 17:58:25.258212 [33mWARN[0m run finished in error {"run_id": "c9je02iel22qnuhs299g", "plan": "ping", "case": "ping", "runner": "local:docker", "instances": 2, "error": "2 nodes failed"}
And now the previous test doesn't work anymore:
Apr 25 17:59:39.280529 [34mINFO[0m 2.9656s [30;47m MESSAGE[0m [31m<< sidecar >>[0m InfluxDB unavailable; no metrics will be dispatched: no InfluxDB URL in $INFLUXDB_URL env var
Apr 25 17:59:39.281065 [34mINFO[0m 2.9663s [37;45m OTHER[0m [31m<< sidecar >>[0m Apr 25 17:59:39.280938 [34mINFO[0m successfully resolved route to host {"container_id": "da23ab83fa478cc555af232c2d29341567329f261decc49a5e79a30cf3087ac5"}
Apr 25 17:59:39.281321 [34mINFO[0m 2.9666s [37;45m OTHER[0m [31m<< sidecar >>[0m Apr 25 17:59:39.281182 [34mINFO[0m external routing disabled
Apr 25 17:59:39.281347 [34mINFO[0m 2.9666s [37;45m OTHER[0m [31m<< sidecar >>[0m Apr 25 17:59:39.281224 [34mINFO[0m waiting for all networks to be ready {"sidecar": true, "run_id": "c9je31ael22qnuhs29a0"}
Apr 25 17:59:39.281626 [34mINFO[0m 2.9669s [37;45m OTHER[0m [31m<< sidecar >>[0m Apr 25 17:59:39.281481 [34mINFO[0m all networks ready {"sidecar": true, "run_id": "c9je31ael22qnuhs29a0"}
Apr 25 17:59:39.281812 [34mINFO[0m 2.9671s [37;45m OTHER[0m [31m<< sidecar >>[0m Apr 25 17:59:39.281672 [34mINFO[0m all networks ready {"sidecar": true, "run_id": "c9je31ael22qnuhs29a0"}
Apr 25 17:59:39.635766 [34mINFO[0m 3.3204s [30;47m MESSAGE[0m [33m<< version-a[001] (da23ab) >>[0m waiting for network to initialize
Apr 25 17:59:39.638145 [34mINFO[0m 3.3228s [30;47m MESSAGE[0m [33m<< version-a[001] (da23ab) >>[0m network initialisation successful
Apr 25 17:59:39.639142 [34mINFO[0m 3.3237s [30;47m MESSAGE[0m [33m<< version-a[001] (da23ab) >>[0m network initialization complete
Apr 25 17:59:39.640647 [34mINFO[0m 3.3253s [30;47m MESSAGE[0m [33m<< version-a[001] (da23ab) >>[0m claimed sequence numbers; global=1, group(version-a)=1
Apr 25 17:59:39.640827 [34mINFO[0m 3.3254s [30;47m MESSAGE[0m [33m<< version-a[001] (da23ab) >>[0m started test instance; params: secure_channel=noise, max_latency_ms=1000, iterations=5
Apr 25 17:59:39.768672 [34mINFO[0m 3.4532s [30;47m MESSAGE[0m [32m<< version-a[000] (9e9705) >>[0m waiting for network to initialize
Apr 25 17:59:39.771061 [34mINFO[0m 3.4556s [30;47m MESSAGE[0m [32m<< version-a[000] (9e9705) >>[0m network initialisation successful
Apr 25 17:59:39.771837 [34mINFO[0m 3.4565s [30;47m MESSAGE[0m [32m<< version-a[000] (9e9705) >>[0m network initialization complete
Apr 25 17:59:39.773309 [34mINFO[0m 3.4578s [30;47m MESSAGE[0m [33m<< version-a[001] (da23ab) >>[0m 127.0.0.1 not in data subnet 16.0.0.0/16, ignoring
Apr 25 17:59:39.773551 [34mINFO[0m 3.4579s [30;47m MESSAGE[0m [33m<< version-a[001] (da23ab) >>[0m 192.18.0.8 not in data subnet 16.0.0.0/16, ignoring
Apr 25 17:59:39.773583 [34mINFO[0m 3.4582s [30;47m MESSAGE[0m [32m<< version-a[000] (9e9705) >>[0m claimed sequence numbers; global=2, group(version-a)=2
Apr 25 17:59:39.773732 [34mINFO[0m 3.4581s [30;47m MESSAGE[0m [33m<< version-a[001] (da23ab) >>[0m detected data network IP: 16.0.0.3/16
Apr 25 17:59:39.773755 [34mINFO[0m 3.4583s [30;47m MESSAGE[0m [32m<< version-a[000] (9e9705) >>[0m started test instance; params: secure_channel=noise, max_latency_ms=1000, iterations=5
Apr 25 17:59:39.775023 [34mINFO[0m 3.4596s [30;47m MESSAGE[0m [32m<< version-a[000] (9e9705) >>[0m 127.0.0.1 not in data subnet 16.0.0.0/16, ignoring
Apr 25 17:59:39.775168 [34mINFO[0m 3.4598s [30;47m MESSAGE[0m [32m<< version-a[000] (9e9705) >>[0m 192.18.0.7 not in data subnet 16.0.0.0/16, ignoring
Apr 25 17:59:39.775274 [34mINFO[0m 3.4600s [30;47m MESSAGE[0m [32m<< version-a[000] (9e9705) >>[0m detected data network IP: 16.0.0.2/16
Apr 25 17:59:39.911443 [34mINFO[0m 3.5964s [30;47m MESSAGE[0m [32m<< version-a[000] (9e9705) >>[0m my listen addrs: [/ip4/16.0.0.2/tcp/44859]
Apr 25 17:59:39.944059 [34mINFO[0m 3.6292s [30;47m MESSAGE[0m [33m<< version-a[001] (da23ab) >>[0m my listen addrs: [/ip4/16.0.0.3/tcp/37409]
Apr 25 17:59:40.014207 [34mINFO[0m 3.6986s [30;47m MESSAGE[0m [33m<< version-a[001] (da23ab) >>[0m Dial peer: QmV8fEQB5bjWH2frqAwtuRtR5mpGTZzndx1JCJTrK5rAaH
Apr 25 17:59:40.014261 [34mINFO[0m 3.6988s [30;47m MESSAGE[0m [32m<< version-a[000] (9e9705) >>[0m done dialling my peers
Apr 25 17:59:40.016462 [34mINFO[0m 3.7017s [37;41m ERROR[0m [33m<< version-a[001] (da23ab) >>[0m panic: send on closed channel
Apr 25 17:59:40.016615 [34mINFO[0m 3.7019s [37;41m ERROR[0m [33m<< version-a[001] (da23ab) >>[0m
Apr 25 17:59:40.016808 [34mINFO[0m 3.7021s [37;41m ERROR[0m [33m<< version-a[001] (da23ab) >>[0m goroutine 99 [running]:
Apr 25 17:59:40.016980 [34mINFO[0m 3.7022s [37;41m ERROR[0m [33m<< version-a[001] (da23ab) >>[0m github.com/testground/sdk-go/sync.(*DefaultClient).responsesWorker(0xc00074a000)
Apr 25 17:59:40.017116 [34mINFO[0m 3.7024s [37;41m ERROR[0m [33m<< version-a[001] (da23ab) >>[0m /go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/sync/client_conn.go:43 +0x285
Apr 25 17:59:40.017250 [34mINFO[0m 3.7025s [37;41m ERROR[0m [33m<< version-a[001] (da23ab) >>[0m created by github.com/testground/sdk-go/sync.newClient
Apr 25 17:59:40.017388 [34mINFO[0m 3.7027s [37;41m ERROR[0m [33m<< version-a[001] (da23ab) >>[0m /go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/sync/client.go:118 +0x1e7
Apr 25 17:59:40.085384 [34mINFO[0m 3.7706s [37;101mINCOMPLETE[0m [33m<< version-a[001] (da23ab) >>[0m
Next actions:
PR: https://github.com/libp2p/test-plans/pull/23/commits/3dfd289e316a7e0f0ef8921bae24f9e6d482ca3e
Started a run on CI to test the current state: https://github.com/laurentsenta/pl-github/actions/runs/2225579698 (edit: failed with context deadline) trying again with a goproxy that has seen another libp2p build before: https://github.com/laurentsenta/pl-github/actions/runs/2225833468
Still getting the panic on dedicated server:
Apr 26 08:32:38.157543 INFO 3.1306s MESSAGE << single[000] (67bead) >> 127.0.0.1 not in data subnet 16.0.0.0/16, ignoring
Apr 26 08:32:38.157717 INFO 3.1308s MESSAGE << single[000] (67bead) >> 192.18.0.7 not in data subnet 16.0.0.0/16, ignoring
Apr 26 08:32:38.158526 INFO 3.1310s MESSAGE << single[000] (67bead) >> detected data network IP: 16.0.0.2/16
Apr 26 08:32:38.158587 INFO 3.1320s MESSAGE << single[001] (2c2ad7) >> 127.0.0.1 not in data subnet 16.0.0.0/16, ignoring
Apr 26 08:32:38.158733 INFO 3.1321s MESSAGE << single[001] (2c2ad7) >> 192.18.0.8 not in data subnet 16.0.0.0/16, ignoring
Apr 26 08:32:38.158912 INFO 3.1322s MESSAGE << single[001] (2c2ad7) >> detected data network IP: 16.0.0.3/16
Apr 26 08:32:38.281460 INFO 3.2554s MESSAGE << single[000] (67bead) >> my listen addrs: [/ip4/16.0.0.2/tcp/37491]
Apr 26 08:32:38.287380 INFO 3.2614s MESSAGE << single[001] (2c2ad7) >> my listen addrs: [/ip4/16.0.0.3/tcp/45209]
Apr 26 08:32:38.383203 INFO 3.3565s MESSAGE << single[001] (2c2ad7) >> Dial peer: QmVH1M1shpuUR6bXjzDqxeoFBdxUgC2MGqvA74ekCr988p
Apr 26 08:32:38.383258 INFO 3.3568s MESSAGE << single[000] (67bead) >> done dialling my peers
Apr 26 08:32:38.385192 INFO 3.3593s ERROR << single[001] (2c2ad7) >> panic: send on closed channel
Apr 26 08:32:38.385300 INFO 3.3595s ERROR << single[001] (2c2ad7) >>
Apr 26 08:32:38.385351 INFO 3.3595s ERROR << single[001] (2c2ad7) >> goroutine 89 [running]:
Apr 26 08:32:38.385401 INFO 3.3596s ERROR << single[001] (2c2ad7) >> github.com/testground/sdk-go/sync.(*DefaultClient).responsesWorker(0xc000012000)
Apr 26 08:32:38.385450 INFO 3.3596s ERROR << single[001] (2c2ad7) >> /go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/sync/client_conn.go:43 +0x285
Apr 26 08:32:38.385527 INFO 3.3597s ERROR << single[001] (2c2ad7) >> created by github.com/testground/sdk-go/sync.newClient
Apr 26 08:32:38.385597 INFO 3.3598s ERROR << single[001] (2c2ad7) >> /go/pkg/mod/github.com/testground/sdk-go@v0.3.1-0.20211012114808-49c90fa75405/sync/client.go:118 +0x1e7
Apr 26 08:32:38.481532 INFO 3.4557s INCOMPLETE << single[001] (2c2ad7) >>
W
in GARDEN22:~/dev/plabs/testground/testground on master
› docker logs testground-sync-service ☺
Apr 26 08:32:24.304730 INFO sync service listening {"addr": "[::]:5050"}
Apr 26 08:32:38.429731 WARN websocket closed unexpectedly: failed to read JSON message: failed to get reader: failed to read frame header: EOF