Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

docker-mac-net-connect causes docker to crash #20

Open
kmahelona opened this issue Nov 22, 2022 · 3 comments
Open

docker-mac-net-connect causes docker to crash #20

kmahelona opened this issue Nov 22, 2022 · 3 comments

Comments

@kmahelona
Copy link

Summary

I've been experiencing random crashes and have tried to figure out what the cause was. I noticed the crash happens when I refresh my site. Since uninstalling docker-mac-net-connect the problem has gone away, but it's not fair to say it was indeed the culprit and I would appreciate some assistance to replicate and find the cause.

Logs

Logs were captured with,

pred='process matches ".*(ocker|vpnkit).*" || (process in {"taskgated-helper", "launchservicesd", "kernel"} && eventMessage contains[c] "docker")'
/usr/bin/log stream --style syslog --level=error --color=always --predicate "$pred"
2022-11-22 18:19:15.936205+1300  localhost docker-mac-net-connect[58147]: (libsystem_info.dylib) Created Activity ID: 0x3e350, Description: Retrieve User by ID
2022-11-22 18:19:25.968400+1300  localhost docker-mac-net-connect[58163]: (libsystem_info.dylib) Created Activity ID: 0x3e4b0, Description: Retrieve User by ID
2022-11-22 18:19:36.040428+1300  localhost docker-mac-net-connect[58181]: (libsystem_info.dylib) Created Activity ID: 0x3e520, Description: Retrieve User by ID
2022-11-22 18:19:46.067790+1300  localhost docker-mac-net-connect[58202]: (libsystem_info.dylib) Created Activity ID: 0x3e5f0, Description: Retrieve User by ID
2022-11-22 18:19:56.096402+1300  localhost docker-mac-net-connect[58212]: (libsystem_info.dylib) Created Activity ID: 0x3e780, Description: Retrieve User by ID
2022-11-22 18:19:58.802823+1300  localhost kernel[0]: process com.docker.virtu[56893] caught waking the CPU 45001 times over ~136 seconds, averaging 329 wakes / second and violating a limit of 45000 wakes over 300 seconds.
2022-11-22 18:20:06.125993+1300  localhost docker-mac-net-connect[58233]: (libsystem_info.dylib) Created Activity ID: 0x3e990, Description: Retrieve User by ID
2022-11-22 18:20:12.658992+1300  localhost Docker Desktop[56866]: (SharedFileList) Created Activity ID: 0x3c915, Description: #SFLAPI LSSharedFileListCopySnapshot
2022-11-22 18:20:16.155607+1300  localhost docker-mac-net-connect[58252]: (libsystem_info.dylib) Created Activity ID: 0x3eaa0, Description: Retrieve User by ID
2022-11-22 18:20:26.189182+1300  localhost docker-mac-net-connect[58268]: (libsystem_info.dylib) Created Activity ID: 0x3ed60, Description: Retrieve User by ID
2022-11-22 18:20:36.231122+1300  localhost docker-mac-net-connect[58291]: (libsystem_info.dylib) Created Activity ID: 0x3ef10, Description: Retrieve User by ID
2022-11-22 18:20:46.272531+1300  localhost docker-mac-net-connect[58311]: (libsystem_info.dylib) Created Activity ID: 0x3efb0, Description: Retrieve User by ID
2022-11-22 18:20:56.297009+1300  localhost docker-mac-net-connect[58322]: (libsystem_info.dylib) Created Activity ID: 0x3f010, Description: Retrieve User by ID
2022-11-22 18:21:06.326764+1300  localhost docker-mac-net-connect[58347]: (libsystem_info.dylib) Created Activity ID: 0x3f270, Description: Retrieve User by ID
2022-11-22 18:21:16.360662+1300  localhost docker-mac-net-connect[58367]: (libsystem_info.dylib) Created Activity ID: 0x3f5b0, Description: Retrieve User by ID
2022-11-22 18:21:26.413362+1300  localhost docker-mac-net-connect[58380]: (libsystem_info.dylib) Created Activity ID: 0x3f6c0, Description: Retrieve User by ID
2022-11-22 18:21:34.774691+1300  localhost Docker Desktop[56866]: (SharedFileList) Created Activity ID: 0x3c916, Description: #SFLAPI LSSharedFileListCopySnapshot
2022-11-22 18:21:36.465112+1300  localhost docker-mac-net-connect[58399]: (libsystem_info.dylib) Created Activity ID: 0x3f9a0, Description: Retrieve User by ID
2022-11-22 18:21:41.508277+1300  localhost Docker[56823]: (libquic.dylib) [com.apple.network:quic] quic_frame_write_CONNECTION_CLOSE [C1.1.1:2] [-d6d251cf16e1ae51] sending APPLICATION_CLOSE, code 0x100, reason <null>
2022-11-22 18:21:41.508403+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] [C2 E56ECD0D-A056-4943-B6A5-2F8E85176722 IPv4#cdd5f451:443 quic-connection, url hash: b389560b, tls, definite, attribution: developer] cancel
2022-11-22 18:21:41.508533+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] [C2 E56ECD0D-A056-4943-B6A5-2F8E85176722 IPv4#cdd5f451:443 quic-connection, url hash: b389560b, tls, definite, attribution: developer] cancelled
	[C2 C42BC433-DE1C-48A8-88B6-6D6CECF2D359 10.56.193.226:64252<->IPv4#cdd5f451:443]
	Connected Path: satisfied (Path is satisfied), viable, interface: en0, ipv4, dns
	Duration: 240.512s, QUIC @0.001s took 0.000s, TLS 1.3 took 0.101s
	bytes in/out: 7479/104105, packets in/out: 56/104, rtt: 0.046s, retransmitted bytes: 0, out-of-order bytes: 1131
2022-11-22 18:21:41.508600+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C2 IPv4#cdd5f451:443 cancelled channel-flow ((null))] Output protocol disconnected
2022-11-22 18:21:41.508627+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_connection_report_state_with_handler_on_nw_queue [C2] reporting state cancelled
2022-11-22 18:21:41.509045+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.509111+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.509689+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C2 IPv4#cdd5f451:443 cancelled channel-flow ((null))] Output protocol disconnected
2022-11-22 18:21:41.509873+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.509941+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.510029+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.510080+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.510148+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.510245+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.510294+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.510378+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C2 IPv4#cdd5f451:443 cancelled channel-flow ((null))] Output protocol disconnected
2022-11-22 18:21:41.510467+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.510533+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.510595+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.510647+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.510715+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 ready channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] Output protocol disconnected
2022-11-22 18:21:41.510774+1300  localhost Docker[56823]: (CFNetwork) Connection 1: cleaning up
2022-11-22 18:21:41.510830+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] [C1 17C1B211-8085-43B6-8268-57A2C0F8988F Hostname#92189e72:443 quic-connection, url hash: b389560b, definite, attribution: developer] cancel
2022-11-22 18:21:41.510912+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] [C1 17C1B211-8085-43B6-8268-57A2C0F8988F Hostname#92189e72:443 quic-connection, url hash: b389560b, definite, attribution: developer] cancelled
	[C1.1.1 C42BC433-DE1C-48A8-88B6-6D6CECF2D359 10.56.193.226:64252<->IPv4#cdd5f451:443]
	Connected Path: satisfied (Path is satisfied), viable, interface: en0, ipv4, dns
	Privacy Stance: Not Eligible
	Duration: 240.556s, DNS @0.000s took 0.039s, QUIC @0.041s took 0.103s
	bytes in/out: 7479/104105, packets in/out: 56/104, rtt: 0.046s, retransmitted bytes: 0, out-of-order bytes: 1131
2022-11-22 18:21:41.511039+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_flow_disconnected [C1.1.1 IPv4#cdd5f451:443 cancelled channel-flow ((null))] Output protocol disconnected
2022-11-22 18:21:41.511105+1300  localhost Docker[56823]: (libnetwork.dylib) [com.apple.network:connection] nw_connection_report_state_with_handler_on_nw_queue [C1] reporting state cancelled
2022-11-22 18:21:43.406774+1300  localhost com.docker.backend[56824]: HTTP 30 CONNECT desktop.docker.com:443: successful (5 active requests)
2022-11-22 18:21:43.418311+1300  localhost com.docker.backend[56824]: HTTP 22 CONNECT desktop.docker.com:443: successful (4 active requests)
2022-11-22 18:21:46.492893+1300  localhost docker-mac-net-connect[58437]: (libsystem_info.dylib) Created Activity ID: 0x3fcb0, Description: Retrieve User by ID
2022-11-22 18:21:56.541911+1300  localhost docker-mac-net-connect[58463]: (libsystem_info.dylib) Created Activity ID: 0x3ff10, Description: Retrieve User by ID
2022-11-22 18:22:06.597528+1300  localhost docker-mac-net-connect[58481]: (libsystem_info.dylib) Created Activity ID: 0x3ffd0, Description: Retrieve User by ID
2022-11-22 18:22:16.632752+1300  localhost docker-mac-net-connect[58499]: (libsystem_info.dylib) Created Activity ID: 0x40090, Description: Retrieve User by ID
2022-11-22 18:22:26.671357+1300  localhost docker-mac-net-connect[58509]: (libsystem_info.dylib) Created Activity ID: 0x400c0, Description: Retrieve User by ID
2022-11-22 18:22:36.708730+1300  localhost docker-mac-net-connect[58530]: (libsystem_info.dylib) Created Activity ID: 0x40200, Description: Retrieve User by ID
2022-11-22 18:22:39.729944+1300  localhost kernel[0]: (AppleMobileFileIntegrity) AMFI: Denying core dump for pid 56867 (com.docker.vpnki)
2022-11-22 18:22:39.729996+1300  localhost kernel[0]: com.docker.vpnkit[56867] Corpse allowed 1 of 5
2022-11-22 18:22:39.730947+1300  localhost com.docker.backend[56824]: shutting down 6 tasks
2022-11-22 18:22:39.730957+1300  localhost com.docker.backend[56824]: com.docker.vpnkit with pid: 56867 shutdown by signal: segmentation fault
2022-11-22 18:22:39.731233+1300  localhost com.docker.backend[56824]: shutdown group 0/2: [docker with pid: 56868 com.docker.extensions with pid: 56872 com.docker.dev-envs with pid: 56875]
2022-11-22 18:22:39.731620+1300  localhost com.docker.backend[56824]: sending signal terminated to docker with pid: 56868
2022-11-22 18:22:39.731937+1300  localhost com.docker.backend[56824]: sending signal terminated to com.docker.extensions with pid: 56872
2022-11-22 18:22:39.732146+1300  localhost com.docker.backend[56824]: sending signal terminated to com.docker.dev-envs with pid: 56875
2022-11-22 18:22:39.734043+1300  localhost com.docker.backend[56824]: docker with pid: 56868 shutdown cleanly
2022-11-22 18:22:39.734085+1300  localhost com.docker.backend[56824]: com.docker.dev-envs with pid: 56875 shutdown with exit code 1
2022-11-22 18:22:39.734601+1300  localhost com.docker.backend[56824]: com.docker.extensions with pid: 56872 shutdown cleanly
2022-11-22 18:22:39.833487+1300  localhost com.docker.backend[56824]: shutdown group 1/2: [com.docker.driver.amd64-linux with pid: 56870]
2022-11-22 18:22:39.833734+1300  localhost com.docker.backend[56824]: sending signal terminated to com.docker.driver.amd64-linux with pid: 56870
2022-11-22 18:22:39.834950+1300  localhost com.docker.backend[56824]: (17871a90) a362dc11-BackendAPI S<-C f5778ec1-DriverCMD POST /events[[STACK]]github.com/docker/pinata/common/pkg/backend.(*backendClient).PushEvent(0x14000617180, {0x1729d0a8af74b580, 0x0, {0x140003ca060, 0x21}, {0x100e61d87, 0x8}, {0x0, 0x0}, {0x0, ...}, ...})
	github.com/docker/pinata/common/pkg/backend/notify.go:27 +0x120
main.handleSystemCalls({0x10116d2b8, 0x1400006ee70})
	github.com/docker/pinata/mac/backend/cmd/com.docker.driver.amd64-linux/main.go:484 +0x18c
created by main.main
	github.com/docker/pinata/mac/backend/cmd/com.docker.driver.amd64-linux/main.go:86 +0x5a8
2022-11-22 18:22:39.835323+1300  localhost com.docker.backend[56824]: (17871a90) a362dc11-BackendAPI S<-C f5778ec1-DriverCMD bind: {"HasServerTimestamp":false,"content":"driver sent docker state stopping","docker":"stopping","timestamp":1669094559834224000}
2022-11-22 18:22:39.835600+1300  localhost com.docker.backend[56824]: a362dc11-BackendAPI /engine/state --> [2022-11-22T18:22:39.834224000+13:00] (8d9855bb) engine stopping : driver sent docker state stopping
2022-11-22 18:22:39.835679+1300  localhost com.docker.backend[56824]: (17871a90) a362dc11-BackendAPI S->C f5778ec1-DriverCMD POST /events (761.792µs): {"HasServerTimestamp":false,"content":"driver sent docker state stopping","docker":"stopping","timestamp":1669094559834224000}
2022-11-22 18:22:39.876757+1300  localhost com.docker.backend[56824]: disconnected data connection: multiplexer is offline
2022-11-22 18:22:39.876999+1300  localhost com.docker.backend[56824]: connection multiplexer has shutdown
2022-11-22 18:22:39.877177+1300  localhost com.docker.backend[56824]: established connection to vpnkit-forwarder
2022-11-22 18:22:39.877825+1300  localhost com.docker.backend[56824]: listening on unix:vpnkit.data.sock for data connection
2022-11-22 18:22:39.878500+1300  localhost com.docker.backend[56824]: c1960eac-PauseHDL /pause/events <-- [2022-11-22T18:22:39.878396000+13:00] (ede161f6) ipc disconnected : <nil>
2022-11-22 18:22:39.878886+1300  localhost com.docker.backend[56824]: Resyncer volumes/grpcfuse: while watching docker events: unexpected EOF
2022-11-22 18:22:39.879179+1300  localhost com.docker.backend[56824]: Resyncer ports: while watching docker events: unexpected EOF
2022-11-22 18:22:39.879376+1300  localhost com.docker.backend[56824]: NTP: disconnected connection
2022-11-22 18:22:41.882351+1300  localhost com.docker.backend[56824]: c1960eac-PauseHDL /pause/events <-- [2022-11-22T18:22:41.880893000+13:00] (788ce11b) ipc connecting : <nil>
2022-11-22 18:22:44.891570+1300  localhost com.docker.backend[56824]: (3c354267) a362dc11-BackendAPI S<-C f5778ec1-DriverCMD POST /usage[[STACK]]github.com/docker/pinata/common/pkg/backend.(*backendClient).UpdateUsage(0x14000617180, {{0x140000350b0, 0x14}, {0x0, 0x0}, {0x0, 0x0}, {0x0, 0x0}, 0x1})
	github.com/docker/pinata/common/pkg/backend/client.go:494 +0xbc
github.com/docker/pinata/common/pkg/proxy.(*BackendAnalytics).sendCommand(0x14000512480, {0x100e6290e, 0x9}, {0x100e5ebca, 0x6}, 0x1)
	github.com/docker/pinata/common/pkg/proxy/analytics.go:104 +0xb4
github.com/docker/pinata/common/pkg/proxy.(*BackendAnalytics).trackRouteForHTTPMethod(0x140006a1978?, 0x14000158200, 0x101166b98?, 0x10115c320)
	github.com/docker/pinata/common/pkg/proxy/analytics.go:97 +0xc8
github.com/docker/pinata/common/pkg/proxy.(*BackendAnalytics).Middleware.func1({0x1011661d0, 0x140002660e0}, 0x14000158200)
	github.com/docker/pinata/common/pkg/proxy/analytics.go:59 +0xa8
github.com/gorilla/mux.(*Router).ServeHTTP(0x140000ea000, {0x1011661d0, 0x140002660e0}, 0x140003ba000)
	gith<decode: missing data>
2022-11-22 18:22:44.891646+1300  localhost com.docker.backend[56824]: [...] ub.com/gorilla/[email protected]/mux.go:210 +0x19c
2022-11-22 18:22:44.892047+1300  localhost com.docker.backend[56824]: (3c354267) a362dc11-BackendAPI S<-C f5778ec1-DriverCMD bind: {"command":"imagePullOthersLinux","count":1}
2022-11-22 18:22:44.892319+1300  localhost com.docker.backend[56824]: (3c354267) a362dc11-BackendAPI S->C f5778ec1-DriverCMD POST /usage (1.139042ms): OK
2022-11-22 18:22:44.894113+1300  localhost com.docker.backend[56824]: (02dbb90d) a362dc11-BackendAPI S<-C 35ead4ae-ProxyPKG GET /registry/access[[STACK]]github.com/docker/pinata/common/pkg/backend.(*backendClient).GetAccess(0x140000301e0)
	github.com/docker/pinata/common/pkg/backend/client.go:336 +0x6c
github.com/docker/pinata/common/pkg/proxy.(*ramPullApprover).Approve(0x0?, {{0x140006524e0, 0x7}, {0x0, 0x0}, {0x140006524e8, 0x6}, {0x140006524ef, 0x1c}, {0x140000780ca, ...}})
	github.com/docker/pinata/common/pkg/proxy/pull.go:34 +0x50
github.com/docker/pinata/common/pkg/proxy.(*proxyPullRewriter).RequestRewrite(0x140003453b0, 0x14000158200)
	github.com/docker/pinata/common/pkg/proxy/pull.go:61 +0xc8
github.com/docker/pinata/common/pkg/proxy.(*passthrough).doHandleHTTP(0x140000312c0, {0x101ade000?, 0x1400000e0c8}, {0x1011661d0?, 0x140002660e0}, 0x2?, {0x2?, 0x14000424038?, 0x10167b3a0?})
	github.com/docker/pinata/common/pkg/proxy/passthrough.go:185 +0xc0
github.com/docker/pinata/common/pkg/proxy.(*passthrough).HandleHTTP(0x140000312c0, {0x1011661d0, 0x14<decode: missing data>
2022-11-22 18:22:44.894157+1300  localhost com.docker.backend[56824]: [...] 0002660e0}, 0x14000158200)
	github.com/docker/pinata/common/pkg/proxy/passthrough.go:120 +0x32c
github.com/docker/pinata/common/pkg/proxy.withError.func1({0x1011661d0, 0x140002660e0}, 0x140006a1538?)
	github.com/docker/pinata/common/pkg/proxy/routes.go:16 +0x40
github.com/docker/pinata/common/pkg/proxy.NewRouter.func2.1({0x1011661d0, 0x140002660e0}, 0x14000158200)
	github.com/docker/pinata/common/pkg/proxy/proxy.go:108 +0x2dc
github.com/docker/pinata/common/pkg/proxy.NewRouter.func1.1({0x1011661d0, 0x140002660e0}, 0x14000158200)
	github.com/docker/pinata/common/pkg/proxy/proxy.go:77 +0x134
github.com/docker/pinata/common/pkg/proxy.(*restrictions).Middleware.func1({0x1011661d0, 0x140002660e0}, 0x14000158200)
	github.com/docker/pinata/common/pkg/proxy/restrictions.go:73 +0x120
github.com/docker/pinata/common/pkg/proxy.(*BackendAnalytics).Middleware.func1({0x1011661d0, 0x140002660e0}, 0x14000158200)
	github.com/docker/pinata/common/pkg/proxy/analytics.go:61 +0xc4
github.com/gorilla/mu<…><decode: missing data>
2022-11-22 18:22:44.894168+1300  localhost com.docker.backend[56824]: [...] Router).ServeHTTP(0x140000ea000, {0x1011661d0, 0x140002660e0}, 0x140003ba000)
	github.com/gorilla/[email protected]/mux.go:210 +0x19c
2022-11-22 18:22:44.895686+1300  localhost com.docker.backend[56824]: (02dbb90d) a362dc11-BackendAPI S->C 35ead4ae-ProxyPKG GET /registry/access (808µs): {"allowed":[{"DNS":"","IP":{"IP":"0.0.0.0","Mask":"AAAAAA=="},"Type":1,"value":"0.0.0.0/0"},{"DNS":".","IP":{"IP":"","Mask":null},"Type":3,"value":"."},{"DNS":"","IP":{"IP":"","Mask":null},"Type":0,"value":"10.0.0.0/8"},{"DNS":"","IP":{"IP":"","Mask":null},"Type":0,"value":"172.16.0.0/12"},{"DNS":"","IP":{"IP":"","Mask":null},"Type":0,"value":"192.168.0.0/16"},{"DNS":"","IP":{"IP":"","Mask":null},"Type":0,"value":"127.0.0.0/8"}],"enabled":false,"refresh_after":"2022-11-23T06:22:44.89438+13:00","refresh_grace_period_ends":"2022-11-23T18:22:44.89438+13:00","refresh_grace_period_interval":3600000000000}
2022-11-22 18:22:46.734756+1300  localhost docker-mac-net-connect[58553]: (libsystem_info.dylib) Created Activity ID: 0x405b0, Description: Retrieve User by ID
2022-11-22 18:22:47.012463+1300  localhost com.docker.virtualization[56893]: The guest OS stopped the virtual machine.
2022-11-22 18:22:47.012719+1300  localhost com.docker.virtualization[56893]: VM shut down gracefully
2022-11-22 18:22:47.012981+1300  localhost com.docker.virtualization[56893]: (CoreAnalytics) [com.apple.CoreAnalytics:client] Entering exit handler.
2022-11-22 18:22:47.012995+1300  localhost com.docker.virtualization[56893]: (CoreAnalytics) [com.apple.CoreAnalytics:client] Exiting exit handler.
2022-11-22 18:22:47.015884+1300  localhost com.docker.backend[56824]: (ee60cda6) a362dc11-BackendAPI S<-C f5778ec1-DriverCMD POST /events[[STACK]]github.com/docker/pinata/common/pkg/backend.(*backendClient).PushEvent(0x14000617180, {0x1729d0aa5b7071e8, 0x0, {0x14000612d80, 0x20}, {0x100e60d1e, 0x7}, {0x0, 0x0}, {0x0, ...}, ...})
	github.com/docker/pinata/common/pkg/backend/notify.go:27 +0x120
main.runVMAndBreakableGoroutines(0x14000134c80)
	github.com/docker/pinata/mac/backend/cmd/com.docker.driver.amd64-linux/main.go:198 +0x508
main.main()
	github.com/docker/pinata/mac/backend/cmd/com.docker.driver.amd64-linux/main.go:117 +0x8f4
2022-11-22 18:22:47.016306+1300  localhost com.docker.backend[56824]: (ee60cda6) a362dc11-BackendAPI S<-C f5778ec1-DriverCMD bind: {"HasServerTimestamp":false,"content":"driver sent docker state stopped","docker":"stopped","timestamp":1669094567014593000}
2022-11-22 18:22:47.016676+1300  localhost com.docker.backend[56824]: (ee60cda6) a362dc11-BackendAPI S->C f5778ec1-DriverCMD POST /events (912.291µs): {"HasServerTimestamp":false,"content":"driver sent docker state stopped","docker":"stopped","timestamp":1669094567014593000}
2022-11-22 18:22:47.016679+1300  localhost com.docker.backend[56824]: a362dc11-BackendAPI /engine/state --> [2022-11-22T18:22:47.014593000+13:00] (9958485c) engine stopped : driver sent docker state stopped
2022-11-22 18:22:47.018393+1300  localhost com.docker.backend[56824]: com.docker.driver.amd64-linux with pid: 56870 shutdown cleanly
2022-11-22 18:22:47.113839+1300  localhost com.docker.backend[56824]: shutdown group 2/2: [com.docker.vpnkit with pid: 56867 vpnkit-bridge with pid: 56869]
2022-11-22 18:22:47.115152+1300  localhost com.docker.backend[56824]: sending signal terminated to vpnkit-bridge with pid: 56869
2022-11-22 18:22:47.133738+1300  localhost com.docker.backend[56824]: vpnkit-bridge with pid: 56869 shutdown cleanly
2022-11-22 18:22:47.218079+1300  localhost com.docker.backend[56824]: all 6 tasks shutdown
2022-11-22 18:22:47.219255+1300  localhost com.docker.backend[56824]: supervise running backend processes: supervising tasks: task com.docker.vpnkit with pid: 56867 failed
2022-11-22 18:22:56.773934+1300  localhost docker-mac-net-connect[59429]: (libsystem_info.dylib) Created Activity ID: 0x40b30, Description: Retrieve User by ID
2022-11-22 18:23:06.831355+1300  localhost docker-mac-net-connect[59445]: (libsystem_info.dylib) Created Activity ID: 0x40db0, Description: Retrieve User by ID
2022-11-22 18:23:11.950590+1300  localhost com.docker.backend[56824]: c1960eac-PauseHDL /pause/events server not replying: Get "http://ipc/pause/events": dial unix procd.sock: connect: no such file or directory
2022-11-22 18:23:16.875998+1300  localhost docker-mac-net-connect[59462]: (libsystem_info.dylib) Created Activity ID: 0x41060, Description: Retrieve User by ID
2022-11-22 18:23:26.931175+1300  localhost docker-mac-net-connect[60350]: (libsystem_info.dylib) Created Activity ID: 0x41160, Description: Retrieve User by ID
2022-11-22 18:23:36.972083+1300  localhost docker-mac-net-connect[60360]: (libsystem_info.dylib) Created Activity ID: 0x411a0, Description: Retrieve User by ID
2022-11-22 18:23:40.906527+1300  localhost Docker Desktop[56866]: (SharedFileList) Created Activity ID: 0x3c917, Description: #SFLAPI LSSharedFileListCopySnapshot
2022-11-22 18:23:42.001552+1300  localhost com.docker.backend[56824]: c1960eac-PauseHDL /pause/events server not replying: Get "http://ipc/pause/events": dial unix procd.sock: connect: no such file or directory
2022-11-22 18:23:47.023403+1300  localhost docker-mac-net-connect[60373]: (libsystem_info.dylib) Created Activity ID: 0x41250, Description: Retrieve User by ID
2022-11-22 18:23:57.069655+1300  localhost docker-mac-net-connect[61243]: (libsystem_info.dylib) Created Activity ID: 0x41330, Description: Retrieve User by ID
2022-11-22 18:24:07.140632+1300  localhost docker-mac-net-connect[61259]: (libsystem_info.dylib) Created Activity ID: 0x41500, Description: Retrieve User by ID
2022-11-22 18:24:12.056796+1300  localhost com.docker.backend[56824]: c1960eac-PauseHDL /pause/events server not replying: Get "http://ipc/pause/events": dial unix procd.sock: connect: no such file or directory
2022-11-22 18:24:17.189655+1300  localhost docker-mac-net-connect[61271]: (libsystem_info.dylib) Created Activity ID: 0x415c0, Description: Retrieve User by ID
2022-11-22 18:24:27.242278+1300  localhost docker-mac-net-connect[62148]: (libsystem_info.dylib) Created Activity ID: 0x41780, Description: Retrieve User by ID
2022-11-22 18:24:37.286440+1300  localhost docker-mac-net-connect[62159]: (libsystem_info.dylib) Created Activity ID: 0x418c0, Description: Retrieve User by ID
2022-11-22 18:24:42.110542+1300  localhost com.docker.backend[56824]: c1960eac-PauseHDL /pause/events server not replying: Get "http://ipc/pause/events": dial unix procd.sock: connect: no such file or directory
2022-11-22 18:24:47.330876+1300  localhost docker-mac-net-connect[62170]: (libsystem_info.dylib) Created Activity ID: 0x41920, Description: Retrieve User by ID
2022-11-22 18:24:54.004577+1300  localhost com.docker.backend[56824]: could not lookup OS process' name: EOF
2022-11-22 18:24:57.383929+1300  localhost docker-mac-net-connect[63033]: (libsystem_info.dylib) Created Activity ID: 0x419b0, Description: Retrieve User by ID

Discussion

When the crash occurs, this is the output I get around the same time,

2022-11-22 18:22:39.729944+1300  localhost kernel[0]: (AppleMobileFileIntegrity) AMFI: Denying core dump for pid 56867 (com.docker.vpnki)
2022-11-22 18:22:39.729996+1300  localhost kernel[0]: com.docker.vpnkit[56867] Corpse allowed 1 of 5

Earlier I thought this was the culprit but upon replicating the problem there wasn't a crash afte this (as seen in logs above),

2022-11-22 18:19:58.802823+1300  localhost kernel[0]: process com.docker.virtu[56893] caught waking the CPU 45001 times over ~136 seconds, averaging 329 wakes / second and violating a limit of 45000 wakes over 300 seconds.

I was wondering is it a memory or CPU issue... I've given docker 32GB ram and 8 CPUs so I can't see how that could be the problem. My setup I've modified /etc/hosts to point a domain name to a docker running nginx listening on port 80, 443, 8003. I then forward from nginx to other dockers, doing TLS termination etc.

upstream wsgi-server {
  server django-gunicorn:8000;
}

upstream asgi-server {
  server django-daphne:8000;
}

upstream vue-serve {
  server vue-serve:8003;
}

server {
    listen 80 default_server;
    server_name _;
    return 301 https://$host$request_uri;
}

server {
    listen 8000 default_server;
    listen 443 ssl;
    listen [::]:8000 default_server;
    listen [::]:443 ssl;
    server_name local.domainname.nz;

    ssl_certificate         /root/ssl/cert.pem;
    ssl_certificate_key     /root/ssl/key.pem;

    location /ws/ {
        proxy_pass http://asgi-server;

        proxy_read_timeout 86400;

        proxy_http_version 1.1;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection "upgrade";
        proxy_set_header Daphne-Root-Path "/ws";
        proxy_redirect off;
        proxy_set_header X-Real-IP $remote_addr;
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
        proxy_set_header X-Forwarded-Host $server_name;
        proxy_set_header X-Forwarded-Port 80;
    }

    client_max_body_size 5G;

    location /static/ {
        alias /static/;
    }

    location /media/ {
        alias /media/;
    }

    location / {
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
        proxy_set_header X-Forwarded-Host $server_name:$server_port;
        proxy_set_header X-Forwarded-Port $server_port;
        proxy_set_header X-Forwarded-Proto $scheme;
        proxy_pass http://wsgi-server;
    }

}

server {
    listen 8003 ssl;

    ssl_certificate         /root/ssl/cert.pem;
    ssl_certificate_key     /root/ssl/key.pem;

    location /sockjs-node/ {
        proxy_pass https://vue-serve;

        proxy_read_timeout 86400;

        proxy_http_version 1.1;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection "upgrade";
        proxy_redirect off;
        proxy_set_header X-Real-IP $remote_addr;
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
        proxy_set_header X-Forwarded-Host $server_name;
        proxy_set_header X-Forwarded-Port 8003;
    }

    location / {
        proxy_pass https://vue-serve;
    }
}

OS & Version
Docker 4.14.1 (91661)
MacOS Monterey 12.6

Being able to bind dockers to different IPs is a great feature for local development when you're working accross a number of different projects, so I very much appreciate this project!
@gregnr
Copy link
Member

gregnr commented Nov 22, 2022

Hi @kmahelona thanks for the details and sorry to hear you are experiencing this. Unfortunately my surface level research into this problem is coming up short. Some things that might help debug:

  • Have you always experienced this crash with this tool or is it more recent? Anything particular you have done differently recently that could help give hints?
  • Is the crash only reproducible when making requests through the nginx proxy? Can you reproduce when hitting the respective containers directly?
  • Any notably large number of requests being made during the crash? I noticed you have a WebSocket server. Any correlation between the crash and making connections to that?
  • Are you on an Intel based Mac or Apple silicon (M1, M2)?

@kmahelona
Copy link
Author

Have you always experienced this crash with this tool or is it more recent? Anything particular you have done differently recently that could help give hints?

I've only used the tool for this purpose.

Is the crash only reproducible when making requests through the nginx proxy? Can you reproduce when hitting the respective containers directly?

I don't seem to be getting crashes with nginx proxy without mac-docker-connect.

I've replicated the crashes taking nginx out of the loop, and connecting directly to the services. In my test the only static IP I connected to is the one associated with the docker running the web sockets.

Any notably large number of requests being made during the crash? I noticed you have a Web-socket server. Any correlation between the crash and making connections to that?

I manually make a lot of requests to a page that doesn't have web-socket connections, and I can't seem to crash Docker. Once I navigate to a page with web-sockets, the docker may crash. If it doesn't crash I keep refreshing until it does. I was suspecting that the container running the web-socket (vue hot reloading with an inspector plugin that uses web-sockets) was part of the problem and the test above further supports this.

Further testing I can confirm:

  • It is linked to a specific docker, changing OS and node versions doesn't resolve the problem
  • It's not a Vue plugin which makes ws connections to that docker
  • Whether we use TLS or not (for both https and wss) we can still cause a crash
  • Crashes only occur when I connect to that docker via a static IP enabled by docker-mac-connect

I should note that there is a request being returned from the docker that's about 28mb in size (a very large vendor js package) but that doesn't cause crashing without docker-mac-connect. Further investigation of this large file,

Without static IP my response times are 300ms
Screen Shot 2022-11-23 at 18 26 59

With the static IP my response times are 3s
Screen Shot 2022-11-23 at 18 26 47

And when I generated a crash, we can see that the large file didn't load... so that must be part of the problem!
Screen Shot 2022-11-23 at 18 28 29

I note that docker-mac-connect was running when I generated the snapshots above, so simply running in the background didn't cause a crash.

Are you on an Intel based Mac or Apple silicon (M1, M2)?

M1

@nikita2206
Copy link

Hey @gregnr great work you’ve done here with the tool and I learned a bunch from its implementation, thank you!

About this issue here, have you thought that it might be somehow related to the MTU size? I’m not sure how that would lead to a complete crash of the VM where docker is running though.
I assume that the way VPNKit is forwarding traffic (if you simply forward a port to host) ends up that the host OS gets the MTU size as if there’s no VPNKit in between (which is 64KB for loopback), but with WireGuard you’re at the default of 1420 bytes. Given that WireGuard client runs in the VM as a kernel module, that might make it more plausible that a crash in it would lead to a crash of the kernel? I assume that WireGuard is forced to split the TCP packet that it gets from the container and maybe its internal buffer isn’t able to handle that much? (could also very well be a bug in wg!)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@nikita2206 @gregnr @kmahelona