Windows client offline due to PollNetMap context canceled

[DentonGentry]

What is the issue?

Sometime between 2pm and 4:50pm Pacific time on November 11, 100.90.64.108 went offline because of a backend error PollNetMap: context canceled

Steps to reproduce

Windows device was not being actively used during this time, happened spontaneously.

Are there any recent changes that introduced the issue?

No response

OS

Windows

OS version

Windows 10.

Tailscale version

1.17.205

Bug report

No response

[DentonGentry]

From the frontend logs 9218572bb9f582d67ff91b1a6ad85cde4b238f5729fdab1ab5fd5124df7e4897, the failure occurred at 17:10:49:

2021-11-11 17:10:49.3389204 -0800 PST: backend error: PollNetMap: context canceled

The first sign of trouble in the frontend logs came over an hour before, when a continuous stream of wsasend errors started:

2021-11-11 15:50:10.6787964 -0800 PST: ui: UI still alive.
2021-11-11 15:50:25.6915764 -0800 PST: ui: UI still alive.
2021-11-11 15:50:40.6899231 -0800 PST: ui: UI still alive.
2021-11-11 15:50:55.6859518 -0800 PST: ui: UI still alive.
2021-11-11 15:51:10.6792512 -0800 PST: ui: UI still alive.
2021-11-11 15:51:25.681357 -0800 PST: ui: UI still alive.
2021-11-11 15:51:40.6913215 -0800 PST: ui: UI still alive.
2021-11-11 15:51:55.6896586 -0800 PST: ui: UI still alive.
2021-11-11 15:52:10.6821669 -0800 PST: ui: UI still alive.
2021-11-11 15:52:25.6917729 -0800 PST: ui: UI still alive.
2021-11-11 15:52:40.6821577 -0800 PST: ui: UI still alive.
2021-11-11 15:52:55.6836369 -0800 PST: ui: UI still alive.
2021-11-11 15:52:57.6869415 -0800 PST: ui: Failed to write message: write tcp 127.0.0.1:50782->127.0.0.1:41112: wsasend: An existing connection was forcibly closed by the remote host.
2021-11-11 15:52:59.6785468 -0800 PST: ui: Failed to write message: write tcp 127.0.0.1:50782->127.0.0.1:41112: wsasend: An existing connection was forcibly closed by the remote host.
2021-11-11 15:53:01.6898441 -0800 PST: ui: Failed to write message: write tcp 127.0.0.1:50782->127.0.0.1:41112: wsasend: An existing connection was forcibly closed by the remote host.
2021-11-11 15:53:03.7070131 -0800 PST: ui: Failed to write message: write tcp 127.0.0.1:50782->127.0.0.1:41112: wsasend: An existing connection was forcibly closed by the remote host.
2021-11-11 15:53:05.6886979 -0800 PST: ui: Failed to write message: write tcp 127.0.0.1:50782->127.0.0.1:41112: wsasend: An existing connection was forcibly closed by the remote host.
2021-11-11 15:53:07.6861489 -0800 PST: ui: Failed to write message: write tcp 127.0.0.1:50782->127.0.0.1:41112: wsasend: An existing connection was forcibly closed by the remote host.
2021-11-11 15:53:09.6832074 -0800 PST: ui: Failed to write message: write tcp 127.0.0.1:50782->127.0.0.1:41112: wsasend: An existing connection was forcibly closed by the remote host.
2021-11-11 15:53:10.6799425 -0800 PST: ui: UI still alive.

[DentonGentry]

The backend logs are 2646014839487dfcdbf94544078db3865f63fa7a9ce8cacd2b799d3b7c4c5570. at 15:52, several minutes after the frontend wsasend errors started, we see:

2021-11-11 15:52:56.7054553 -0800 PST: 2021/11/11 15:52:56 wgengine watchdog stacks:
2021-11-11 15:52:56.7059918 -0800 PST: goroutine profile: total 52
2021-11-11 15:52:56.7059918 -0800 PST: 4 @ 0xffc7d6 0x14c0b39 0x14c0b21 0x14c0c4e 0x14cf494 0x102b701
2021-11-11 15:52:56.7059918 -0800 PST: #        0x14c0b38       inet.af/netstack/sync.Gopark+0x78
                               inet.af/netstack@v0.0.0-20211101182044-1c1bcf452982/sync/runtime_unsafe.go:27
2021-11-11 15:52:56.7059918 -0800 PST: #        0x14c0b20       inet.af/netstack/sleep.(*Sleeper).nextWaker+0x60
                               inet.af/netstack@v0.0.0-20211101182044-1c1bcf452982/sleep/sleep_unsafe.go:181
2021-11-11 15:52:56.7059918 -0800 PST: #        0x14c0c4d       inet.af/netstack/sleep.(*Sleeper).Fetch+0x2d
                               inet.af/netstack@v0.0.0-20211101182044-1c1bcf452982/sleep/sleep_unsafe.go:228
2021-11-11 15:52:56.7075515 -0800 PST: #        0x14cf493       inet.af/netstack/tcpip/transport/tcp.(*processor).start+0x93
                               inet.af/netstack@v0.0.0-20211101182044-1c1bcf452982/tcpip/transport/tcp/dispatcher.go:97
2021-11-11 15:52:56.7090598 -0800 PST: 4 @ 0xffc7d6 0xfc768c 0xfc70f8 0x139ebc8 0x102b701
2021-11-11 15:52:56.7090598 -0800 PST: #        0x139ebc7       golang.zx2c4.com/wireguard/device.(*Device).RoutineDecryption+0x1a7
                               golang.zx2c4.com/wireguard@v0.0.0-20211020205005-82e0b734e5d2/device/receive.go:212
2021-11-11 15:52:56.7096076 -0800 PST: 4 @ 0xffc7d6 0xfc768c 0xfc70f8 0x139f01b 0x102b701
2021-11-11 15:52:56.7099009 -0800 PST: #        0x139f01a       golang.zx2c4.com/wireguard/device.(*Device).RoutineHandshake+0x19a
                               golang.zx2c4.com/wireguard@v0.0.0-20211020205005-82e0b734e5d2/device/receive.go:244
2021-11-11 15:52:56.710176 -0800 PST: 4 @ 0xffc7d6 0xfc768c 0xfc70f8 0x13a1f65 0x102b701
2021-11-11 15:52:56.7102815 -0800 PST: #        0x13a1f64       golang.zx2c4.com/wireguard/device.(*Device).RoutineEncryption+0x1c4     golang.zx2c4.com/wireguard@v0.0.0-20211020205005-82e0b734e5d2/device/send.go:376
2021-11-11 15:52:56.7104112 -0800 PST: 2 @ 0xffc7d6 0xfc768c 0xfc70f8 0x139fd05 0x102b701
2021-11-11 15:52:56.7104112 -0800 PST: #        0x139fd04       golang.zx2c4.com/wireguard/device.(*Peer).RoutineSequentialReceiver+0x144       golang.zx2c4.com/wireguard@v0.0.0-20211020205005-82e0b734e5d2/device/receive.go:406
2021-11-11 15:52:56.7104112 -0800 PST: 2 @ 0xffc7d6 0xfc768c 0xfc70f8 0x13a23da 0x102b701
2021-11-11 15:52:56.7112026 -0800 PST: #        0x13a23d9       golang.zx2c4.com/wireguard/device.(*Peer).RoutineSequentialSender+0x119 golang.zx2c4.com/wireguard@v0.0.0-20211020205005-82e0b734e5d2/device/send.go:418
...etc, etc...
2021-11-11 15:52:56.7289511 -0800 PST: 2021/11/11 15:52:56 wgengine: watchdog timeout on RequestStatus
2021-11-11 15:52:56.8484143 -0800 PST: subprocess exited: exit status 1
2021-11-11 15:52:56.8484143 -0800 PST: exec: "C:\\Program Files (x86)\\Tailscale IPN\\tailscaled.exe" [/subproc 2646014839487dfcdbf94544078db3865f63fa7a9ce8cacd2b799d3b7c4c5570]
2021-11-11 15:52:59.3899735 -0800 PST: 2021/11/11 15:52:59 Program starting: v1.17.186-tc467ed0b6-gc828502a7:[]string{"C:\\Program Files (x86)\\Tailscale IPN\\tailscaled.exe", "/subproc", "2646014839487dfcdbf94544078db3865f63fa7a9ce8cacd2b799d3b7c4c5570"}

The backend did not upload any logs around the time the frontend actually died, there are no logs between 15:53 and 18:52.

2021-11-11 15:53:31.1444533 -0800 PST: 2021/11/11 15:53:31 magicsock: starting endpoint update (link-change-minor)
2021-11-11 15:53:31.1704602 -0800 PST: 2021/11/11 15:53:31 magicsock: ignoring pre-DERP map, STUN-less endpoint update: [{24.4.62.176:41645 portmap} {10.1.10.81:41641 local} {[2602:248:7b4a:ff60::1226]:41641 local} {[2602:248:7b4a:ff60:df2:4aea:4959:52e]:41641 local} {[2602:248:7b4a:ff60:34dc:934b:4687:45b]:41641 local} {[2602:248:7b4a:ff60:c562:b4d4:5b3e:531e]:41641 local}]
2021-11-11 18:52:45.7102435 -0800 PST: 2021/11/11 18:52:45 monitor: got windows change event after 2h59m14.974s: evt=addr
2021-11-11 18:52:45.7107755 -0800 PST: 2021/11/11 18:52:45 monitor: got windows change event after 6ms: evt=route

[DentonGentry]

This isn't a regression after all: the first occurrence found so far was in 3/2021. Marking it as not a blocker of 1.18.

[bradfitz]

It wasn't running 1.17.205 as the top comment in this bug says.

In fact, it was never running that version. During the time in question, it was 1.17.186.

The backend logs say:

2021-11-11 15:52:59.3899735 -0800 PST: 2021/11/11 15:52:59 Program starting: v1.17.186-tc467ed0b6-gc828502a7: []string{"C:\\Program Files (x86)\\Tailscale IPN\\tailscaled.exe", "/subproc", "2646014839487dfcdbf94544078db3865f63fa7a9ce8cacd2b799d3b7c4c5570"}
...
2021-11-16 14:51:10.4238625 -0800 PST: Program starting: v1.17.232-t36b1df124-g4361435d5, Go 1.17.2-ts7037d3e: []string{"C:\\Program Files (x86)\\Tailscale IPN\\tailscaled.exe"}
2021-11-16 14:51:11.7592877 -0800 PST: 2021/11/16 14:51:11 Program starting: v1.17.232-t36b1df124-g4361435d5: []string{"C:\\Program Files (x86)\\Tailscale IPN\\tailscaled.exe", "/subproc", "2646014839487dfcdbf94544078db3865f63fa7a9ce8cacd2b799d3b7c4c5570"}
...
2021-11-17 19:53:52.0508242 -0800 PST: Program starting: v1.17.241-tb3d6704aa-g8dc7996e6, Go 1.17.2-ts7037d3ea51: []string{"C:\\Program Files (x86)\\Tailscale IPN\\tailscaled.exe"}
2021-11-17 19:53:53.15433 -0800 PST: 2021/11/17 19:53:53 Program starting: v1.17.241-tb3d6704aa-g8dc7996e6: []string{"C:\\Program Files (x86)\\Tailscale IPN\\tailscaled.exe", "/subproc", "2646014839487dfcdbf94544078db3865f63fa7a9ce8cacd2b799d3b7c4c5570"}

At 1.17.186, the Windows build was at oss commit c467ed0 which does not include the fix (337757a) in its history.

So I think this is fixed.

Auditing in both directions, but from the ways the UI can get that pop-up, and from where that error is generated, I don't see any way for this to happen anymore, including the old ways (from 3/2021, etc). It looks like 337757a also fixes them.

So I think this can be closed.

[DentonGentry]

Huh. Ok, another symptom of #3230