control/controlhttp: port 80 noise upgrade problem #4557
Description
Hey @danderson, @maisem, more controlv2 connection woes on port 80.
This is 1.24.1 on Windows:
(logID "d2796595a7110830caab2cb5cfd469abb69ad546b619c678736b515bf5d52b2f")
2022-04-28T09:37:30.359+08:00: Program starting: v1.24.1-t1a9302b1e-g1331ed583, Go 1.18.1-ts710a0d8610: []string{"C:\\Program Files\\Tailscale\\tailscaled.exe"}
2022-04-28T09:37:30.360+08:00: LogID: d2796595a7110830caab2cb5cfd469abb69ad546b619c678736b515bf5d52b2f
2022-04-28T09:37:30.360+08:00: logpolicy: using dir C:\ProgramData\Tailscale
2022-04-28T09:37:30.367+08:00: Running service...
2022-04-28T09:37:30.369+08:00: registry.OpenKey(SOFTWARE\Policies\Tailscale): The system cannot find the file specified.
2022-04-28T09:37:30.378+08:00: exec: "C:\\Program Files\\Tailscale\\tailscaled.exe" [/subproc d2796595a7110830caab2cb5cfd469abb69ad546b619c678736b515bf5d52b2f]
2022-04-28T09:37:30.430+08:00: Program starting: v1.24.1-t1a9302b1e-g1331ed583: []string{"C:\\Program Files\\Tailscale\\tailscaled.exe", "/subproc", "d2796595a7110830caab2cb5cfd469abb69ad546b619c678736b515bf5d52b2f"}
2022-04-28T09:37:30.430+08:00: subproc mode: logid=d2796595a7110830caab2cb5cfd469abb69ad546b619c678736b515bf5d52b2f
....
2022-04-28T09:37:49.021+08:00: control: [v1] TryLogin: register request: Post "https://controlplane.tailscale.com/machine/register": reading response header: read tcp 192.168.87.99:50582->52.29.8.43:80: i/o timeout
2022-04-28T09:37:49.022+08:00: control: [v1] sendStatus: authRoutine-report: state:authenticating
2022-04-28T09:37:49.022+08:00: Received error: register request: Post "https://controlplane.tailscale.com/machine/register": reading response header: read tcp 192.168.87.99:50582->52.29.8.43:80: i/o timeout
2022-04-28T09:37:49.022+08:00: control: authRoutine: [v1] backoff: 6 msec
2022-04-28T09:37:49.027+08:00: control: [v1] authRoutine: state:authenticating; wantLoggedIn=true
2022-04-28T09:37:49.027+08:00: control: [v1] direct.TryLogin(token=false, flags=0)
2022-04-28T09:37:49.027+08:00: control: doLogin(regen=false, hasUrl=false)
2022-04-28T09:37:49.027+08:00: control: RegisterReq: onode= node=[BLzve] fup=false
2022-04-28T09:37:59.028+08:00: control: [v1] TryLogin: register request: Post "https://controlplane.tailscale.com/machine/register": reading response header: read tcp 192.168.87.99:50587->52.29.8.43:80: i/o timeout
2022-04-28T09:37:59.030+08:00: control: [v1] sendStatus: authRoutine-report: state:authenticating
2022-04-28T09:37:59.030+08:00: Received error: register request: Post "https://controlplane.tailscale.com/machine/register": reading response header: read tcp 192.168.87.99:50587->52.29.8.43:80: i/o timeout
2022-04-28T09:37:59.030+08:00: control: authRoutine: [v1] backoff: 53 msec
2022-04-28T09:37:59.084+08:00: control: [v1] authRoutine: state:authenticating; wantLoggedIn=true
2022-04-28T09:37:59.084+08:00: control: [v1] direct.TryLogin(token=false, flags=0)
2022-04-28T09:37:59.084+08:00: control: doLogin(regen=false, hasUrl=false)
2022-04-28T09:37:59.084+08:00: control: RegisterReq: onode= node=[BLzve] fup=false
2022-04-28T09:38:09.084+08:00: control: [v1] TryLogin: register request: Post "https://controlplane.tailscale.com/machine/register": reading response header: read tcp 192.168.87.99:50591->52.29.8.43:80: i/o timeout
2022-04-28T09:38:09.084+08:00: control: [v1] sendStatus: authRoutine-report: state:authenticating
2022-04-28T09:38:09.084+08:00: Received error: register request: Post "https://controlplane.tailscale.com/machine/register": reading response header: read tcp 192.168.87.99:50591->52.29.8.43:80: i/o timeout
2022-04-28T09:38:09.085+08:00: control: authRoutine: [v1] backoff: 97 msec
2022-04-28T09:38:09.183+08:00: control: [v1] authRoutine: state:authenticating; wantLoggedIn=true
2022-04-28T09:38:09.183+08:00: control: [v1] direct.TryLogin(token=false, flags=0)
2022-04-28T09:38:09.183+08:00: control: doLogin(regen=false, hasUrl=false)
Note that the reading response header: read tcp 192.168.87.99:50591->52.29.8.43:80: i/o timeout comes from continueClientHandshake in control/controlbase)
So something's messing with port 80 but we connect enough to make control/controlhttp think the connection's good, but then the port 80 connection we get isn't usable. It times out, because there's probably some MITM software.
From #4538 (comment).
Hey @victpork, you have some anti-virus or firewall on that Windows machine?
In any case, we'll fix it to work around it.