docker-mac-net-connect
docker-mac-net-connect copied to clipboard
chipmk
docker-mac-net-connect causes docker to crash
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!
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)?
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
With the static IP my response times are 3s
And when I generated a crash, we can see that the large file didn't load... so that must be part of the problem!
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
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!)
