[BUG] 'Empty reply from server' error when start/stop CRC with daemon HTTP API

[evidolob]

General information

• OS: macOS
• Hypervisor: hyperkit
• Did you run crc setup before starting it (Yes/No)? Yes
• Running CRC on: Laptop

CRC version

CRC version: 2.16.0+4f183e5
OpenShift version: 4.12.9
Podman version: 4.4.1

Host Operating System

ProductName:		macOS
ProductVersion:		13.3.1
BuildVersion:		22E261

Steps to reproduce

Start cluster with curl -GET -i --unix-socket <home>/.crc/crc-http.sock http://localhost/api/start

Stop cluster with curl -GET -i --unix-socket <home>/.crc/crc-http.sock http://localhost/api/stop

Expected

No errors

Actual

Start result:

curl: (52) Empty reply from server

Stop result:

curl: (52) Empty reply from server

Logs

Start daemon log:

INFO listening /Users/yevhen/.crc/tap.sock
INFO listening /Users/yevhen/.crc/crc-http.sock
INFO Checking if running as non-root
INFO Checking if crc-admin-helper executable is cached
INFO Checking if running on a supported CPU architecture
INFO Checking minimum RAM requirements
INFO Checking if crc executable symlink exists
INFO Checking if running emulated on a M1 CPU
INFO Checking if vfkit is installed
INFO Checking if old launchd config for tray and/or daemon exists
INFO Checking if crc daemon plist file is present and loaded
 - - [13/Apr/2023:14:12:29 +0300] "GET /api/version HTTP/1.1" 200 97
INFO Loading bundle: crc_vfkit_4.12.9_amd64...
INFO Starting CRC VM for openshift 4.12.9...
 - - [13/Apr/2023:14:12:29 +0300] "GET /network/services/forwarder/all HTTP/1.1" 200 3
 - - [13/Apr/2023:14:12:29 +0300] "POST /network/services/forwarder/expose HTTP/1.1" 200 0
 - - [13/Apr/2023:14:12:29 +0300] "POST /network/services/forwarder/expose HTTP/1.1" 200 0
 - - [13/Apr/2023:14:12:29 +0300] "POST /network/services/forwarder/expose HTTP/1.1" 200 0
 - - [13/Apr/2023:14:12:29 +0300] "POST /network/services/forwarder/expose HTTP/1.1" 200 0
INFO CRC instance is running with IP 127.0.0.1
2023/04/13 14:12:33 tcpproxy: for incoming conn 127.0.0.1:63835, error dialing "192.168.127.2:22": connect tcp 192.168.127.2:22: no route to host
2023/04/13 14:12:37 tcpproxy: for incoming conn 127.0.0.1:63836, error dialing "192.168.127.2:22": connect tcp 192.168.127.2:22: no route to host
2023/04/13 14:12:41 tcpproxy: for incoming conn 127.0.0.1:63837, error dialing "192.168.127.2:22": connect tcp 192.168.127.2:22: no route to host
2023/04/13 14:12:45 tcpproxy: for incoming conn 127.0.0.1:63839, error dialing "192.168.127.2:22": connect tcp 192.168.127.2:22: no route to host
2023/04/13 14:12:49 tcpproxy: for incoming conn 127.0.0.1:63841, error dialing "192.168.127.2:22": connect tcp 192.168.127.2:22: no route to host
2023/04/13 14:12:53 tcpproxy: for incoming conn 127.0.0.1:63844, error dialing "192.168.127.2:22": connect tcp 192.168.127.2:22: no route to host
2023/04/13 14:12:57 tcpproxy: for incoming conn 127.0.0.1:63845, error dialing "192.168.127.2:22": connect tcp 192.168.127.2:22: no route to host
2023/04/13 14:13:01 tcpproxy: for incoming conn 127.0.0.1:63846, error dialing "192.168.127.2:22": connect tcp 192.168.127.2:22: no route to host
2023/04/13 14:13:05 tcpproxy: for incoming conn 127.0.0.1:63847, error dialing "192.168.127.2:22": connect tcp 192.168.127.2:22: no route to host
INFO new connection from  to /Users/yevhen/.crc/tap.sock
INFO CRC VM is running
INFO Configuring shared directories
INFO Check internal and public DNS query...
INFO Check DNS query from host...
INFO Verifying validity of the kubelet certificates...
INFO Starting kubelet service
INFO Waiting for kube-apiserver availability... [takes around 2min]
INFO Waiting until the user's pull secret is written to the instance disk...
INFO Starting openshift instance... [waiting for the cluster to stabilize]
INFO 2 operators are progressing: authentication, operator-lifecycle-manager-packageserver
INFO 2 operators are progressing: authentication, operator-lifecycle-manager-packageserver
192.168.127.2 - - [13/Apr/2023:14:14:34 +0300] "POST /hosts/add HTTP/1.1" 200 0
192.168.127.2 - - [13/Apr/2023:14:14:34 +0300] "POST /hosts/add HTTP/1.1" 200 0
192.168.127.2 - - [13/Apr/2023:14:14:34 +0300] "POST /hosts/add HTTP/1.1" 200 0
INFO 2 operators are progressing: authentication, ingress
W0413 14:14:46.535606   48387 gonet.go:457] ep.GetRemoteAddress() failed: endpoint not connected
W0413 14:14:47.009571   48387 gonet.go:457] ep.GetRemoteAddress() failed: endpoint not connected
W0413 14:14:49.365461   48387 gonet.go:457] ep.GetRemoteAddress() failed: endpoint not connected
W0413 14:14:50.888306   48387 gonet.go:457] ep.GetRemoteAddress() failed: endpoint not connected
W0413 14:14:51.597940   48387 gonet.go:457] ep.GetRemoteAddress() failed: endpoint not connected
INFO Operator authentication is progressing
INFO Operator authentication is progressing
INFO Operator authentication is progressing
INFO Operator authentication is progressing
INFO Operator authentication is progressing
INFO Operator authentication is progressing
INFO Operator authentication is progressing
INFO Operator authentication is degraded
INFO All operators are available. Ensuring stability...
INFO Operators are stable (2/3)...
INFO Operators are stable (3/3)...
INFO Adding crc-admin and crc-developer contexts to kubeconfig...
ERRO Failed to send response: write unix /Users/yevhen/.crc/crc-http.sock->: i/o timeout
 - - [13/Apr/2023:14:12:28 +0300] "GET /api/start HTTP/1.1" 200 3965

Stop daemon log:

INFO Stopping kubelet and all containers...
INFO Updating kernel args...
INFO Stopping the instance, this may take a few minutes...
ERRO cannot receive packets from , disconnecting: cannot read size from socket: EOF
 - - [13/Apr/2023:14:34:15 +0300] "GET /api/stop HTTP/1.1" 200 0

Please consider posting the output of crc start --log-level debug on http://gist.github.com/ and post the link in the issue.

[evidolob]

cc @gbraad

[anjannath]

in go 1.20 there's a ResponseController with the ability to change the timeout from within the handlers, https://pkg.go.dev/net/http#ResponseController but we are on go1.19

[gbraad]

We had changed behaviour by introducing timeouts, as this was instructed by golint as an issue; the possibility to have connections block the server. Originally we did not enforce a timeout, and we have re-introduced this for now; but prevent partial requests by requiring headers.