#584

100% CPU usage on macOS on sleep

Opensteinybotopened 10mo ago

Hi,

A few users of podman are experiencing an issue where gvproxy is consuming 100% CPU on one or more threads on macOS. This typically happens after sleep and may be related to network proxies or vpns. The issue was first raised here https://github.com/containers/podman/issues/27279.

What I was seeing is that after sleep I would unlock my MacBook and see that the CPU usage for gvproxy was up at 1200% percent.

Podman runs gvproxy with these arguments:

/opt/homebrew/Cellar/podman/5.6.2/libexec/podman/gvproxy -mtu 1500 -ssh-port 63695 -listen-vfkit unixgram:///var/folders/p1/tbxygbp918l6xpk3q9cx_9xm0000gp/T/podman/podman-machine-default-gvproxy.sock -forward-dest /run/podman/podman.sock -forward-user root -forward-identity /Users/jason.pickens/.local/share/containers/podman/machine/machine -forward-sock /var/folders/p1/tbxygbp918l6xpk3q9cx_9xm0000gp/T/podman/podman-machine-default-api.sock -pid-file /var/folders/p1/tbxygbp918l6xpk3q9cx_9xm0000gp/T/podman/gvproxy.pid -log-file /var/folders/p1/tbxygbp918l6xpk3q9cx_9xm0000gp/T/podman/gvproxy.log

I checked the log and it contained:

❯ less /var/folders/p1/tbxygbp918l6xpk3q9cx_9xm0000gp/T/podman/gvproxy.log
time="2025-12-03T10:45:52+13:00" level=info msg="gvproxy version v0.8.7"
time="2025-12-03T10:45:52+13:00" level=info msg="waiting for clients..."
time="2025-12-03T14:01:56+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 192.36.143.130:123: connect: network is unreachable\n"
time="2025-12-03T14:39:10+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 45.231.168.6:123: connect: network is unreachable\n"
time="2025-12-03T14:39:13+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 132.248.30.3:123: connect: network is unreachable\n"
time="2025-12-03T15:12:01+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 192.36.143.130:123: connect: network is unreachable\n"
time="2025-12-03T15:13:10+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 192.36.143.130:123: connect: network is unreachable\n"
time="2025-12-03T15:46:16+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 192.36.143.130:123: connect: network is unreachable\n"
time="2025-12-03T15:46:27+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 45.231.168.6:123: connect: network is unreachable\n"
time="2025-12-03T15:46:29+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 132.248.30.3:123: connect: network is unreachable\n"
time="2025-12-03T16:03:09+13:00" level=error msg="Can't proxy a datagram to udp: write udp 10.10.10.10:0->6.6.1.85:123: write: broken pipe\n"
time="2025-12-03T16:20:31+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 192.36.143.130:123: connect: network is unreachable\n"
time="2025-12-03T16:20:42+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 45.231.168.6:123: connect: network is unreachable\n"
time="2025-12-03T16:20:43+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 132.248.30.3:123: connect: network is unreachable\n"
time="2025-12-03T18:13:38+13:00" level=error msg="Can't proxy a datagram to udp: write udp 10.10.10.10:54288->6.6.1.85:123: write: broken pipe\n"
time="2025-12-03T21:01:56+13:00" level=error msg="Can't proxy a datagram to udp: write udp 10.10.10.10:65025->6.6.1.85:123: write: broken pipe\n"

The log does not always contain this so these errors could be a red herring but they are likely related given that it is port 123.

I would then see multiple NTP connections for the gvproxy process that would never close. The number correlated to the number of threads stuck at 100%.

❯ lsof -p 51681 | grep ntp
gvproxy 51681 jason.pickens    8u     IPv4 0xa4e2cacb93e95b33      0t0                 UDP 10.10.10.10:58733->6.6.1.85:ntp
gvproxy 51681 jason.pickens   14u     IPv4 0x4cf04fffe9df7795      0t0                 UDP 10.10.10.10:63616->6.6.1.85:ntp
gvproxy 51681 jason.pickens   16u     IPv4 0xa4eb936652186552      0t0                 UDP 10.10.10.10:63070->6.6.1.85:ntp
gvproxy 51681 jason.pickens   17u     IPv4 0xd0e3ee15924321e5      0t0                 UDP 10.10.10.10:56963->6.6.1.85:ntp
gvproxy 51681 jason.pickens   19u     IPv4 0xb38d5af81d62af45      0t0                 UDP 10.10.10.10:56892->6.6.1.85:ntp
gvproxy 51681 jason.pickens   22u     IPv4 0xef4d7ec6694531db      0t0                 UDP 10.10.10.10:49352->6.6.1.85:ntp
gvproxy 51681 jason.pickens   25u     IPv4 0xbe76200e2d8dc14a      0t0                 UDP 10.10.10.10:49346->6.6.1.85:ntp
gvproxy 51681 jason.pickens   26u     IPv4 0xf7cd0c551a9ba292      0t0                 UDP 10.10.10.10:56741->6.6.1.85:ntp
gvproxy 51681 jason.pickens   27u     IPv4  0x86f9115ffd7bb48      0t0                 UDP 10.10.10.10:61083->6.6.1.85:ntp
gvproxy 51681 jason.pickens   28u     IPv4 0x7481d656ca8cb8a9      0t0                 UDP 10.10.10.10:52968->6.6.1.85:ntp
gvproxy 51681 jason.pickens   29u     IPv4 0xa4fe5ddfa423def2      0t0                 UDP 10.10.10.10:59627->6.6.1.85:ntp
gvproxy 51681 jason.pickens   30u     IPv4 0x1c9b8708b817e8d9      0t0                 UDP 10.10.10.10:53673->6.6.1.85:ntp
gvproxy 51681 jason.pickens   31u     IPv4 0x1a54d41666ab044a      0t0                 UDP 10.10.10.10:57939->6.6.1.85:ntp
gvproxy 51681 jason.pickens   32u     IPv4 0x437cebf62ab2f961      0t0                 UDP 10.10.10.10:65130->6.6.1.85:ntp
gvproxy 51681 jason.pickens   33u     IPv4  0xcea711337797a9a      0t0                 UDP 10.10.10.10:60839->6.6.1.85:ntp
gvproxy 51681 jason.pickens   35u     IPv4 0x91c3530bde6e5fc7      0t0                 UDP 10.10.10.10:58305->6.6.1.85:ntp

It seems that something related to the sleeps and/or proxies/vpns are disturbing the NTP association in such a way that cause gvproxy to get into a bad state and spin the thread.

Activity

17
steinybot9mo ago

AI Investigation:

⏺ Based on my investigation using sequential thinking, I've identified the root cause of the 100% CPU bug in gvproxy on macOS.

Root Cause

The bug is in the replyLoop method in pkg/services/forwarder/udp_proxy.go, specifically in the ECONNREFUSED error handling (lines 83-89).

The Problem

When macOS wakes from sleep, network state changes cause UDP connections to fail. The code has special handling for ECONNREFUSED errors:

  if err, ok := err.(*net.OpError); ok && err.Err == syscall.ECONNREFUSED {
      // retry indefinitely
      goto again
  }

This creates an infinite tight loop when:

  1. Mac wakes from sleep with changed network state (proxy/VPN changes)
  2. VM sends NTP packets to time servers
  3. gvproxy creates UDP connections that fail due to network changes
  4. ICMP "port unreachable" messages get queued in the kernel for these sockets
  5. proxyConn.Read() immediately returns ECONNREFUSED (doesn't block)
  6. Code jumps to again and retries immediately
  7. ICMP error persists, Read() returns ECONNREFUSED again instantly
  8. Infinite loop at 100% CPU with no blocking or delays

Why Multiple Threads

Each NTP server connection creates a separate replyLoop goroutine (line 129). Multiple NTP servers = multiple spinning goroutines = multiple CPU cores pegged at 100%.

Evidence Match

✅ Happens after sleep - network state changes cause connection failures ✅ Related to proxies/VPNs - routing changes trigger ICMP errors ✅ Multiple threads spinning - one replyLoop per NTP connection ✅ Thread count = NTP connection count - each replyLoop is independent ✅ Connections never close - replyLoop stuck in infinite loop ✅ NTP port 123 specifically - UDP where ICMP errors are common

The Fix

Add safeguards to prevent infinite retry loops:

  // Option 1: Limit consecutive retries
  retryCount := 0
  maxRetries := 10
  again:
  read, err := proxyConn.Read(readBuf)
  if err != nil {
      if err, ok := err.(*net.OpError); ok && err.Err == syscall.ECONNREFUSED {
          retryCount++
          if retryCount < maxRetries {
              time.Sleep(10 * time.Millisecond) // prevent tight loop
              goto again
          }
      }
      return
  }
  retryCount = 0 // reset on successful read

Or more simply, just remove the goto and let ECONNREFUSED errors terminate the connection like other errors, since the 90-second timeout should be sufficient for transient errors.

steinybot9mo ago

AI Investigation:

⏺ Based on my investigation using sequential thinking, I've identified the root cause of the 100% CPU bug in gvproxy on macOS.

Root Cause

The bug is in the replyLoop method in pkg/services/forwarder/udp_proxy.go, specifically in the ECONNREFUSED error handling (lines 83-89).

The Problem

When macOS wakes from sleep, network state changes cause UDP connections to fail. The code has special handling for ECONNREFUSED errors:

  if err, ok := err.(*net.OpError); ok && err.Err == syscall.ECONNREFUSED {
      // retry indefinitely
      goto again
  }

This creates an infinite tight loop when:

  1. Mac wakes from sleep with changed network state (proxy/VPN changes)
  2. VM sends NTP packets to time servers
  3. gvproxy creates UDP connections that fail due to network changes
  4. ICMP "port unreachable" messages get queued in the kernel for these sockets
  5. proxyConn.Read() immediately returns ECONNREFUSED (doesn't block)
  6. Code jumps to again and retries immediately
  7. ICMP error persists, Read() returns ECONNREFUSED again instantly
  8. Infinite loop at 100% CPU with no blocking or delays

Why Multiple Threads

Each NTP server connection creates a separate replyLoop goroutine (line 129). Multiple NTP servers = multiple spinning goroutines = multiple CPU cores pegged at 100%.

Evidence Match

✅ Happens after sleep - network state changes cause connection failures ✅ Related to proxies/VPNs - routing changes trigger ICMP errors ✅ Multiple threads spinning - one replyLoop per NTP connection ✅ Thread count = NTP connection count - each replyLoop is independent ✅ Connections never close - replyLoop stuck in infinite loop ✅ NTP port 123 specifically - UDP where ICMP errors are common

The Fix

Add safeguards to prevent infinite retry loops:

  // Option 1: Limit consecutive retries
  retryCount := 0
  maxRetries := 10
  again:
  read, err := proxyConn.Read(readBuf)
  if err != nil {
      if err, ok := err.(*net.OpError); ok && err.Err == syscall.ECONNREFUSED {
          retryCount++
          if retryCount < maxRetries {
              time.Sleep(10 * time.Millisecond) // prevent tight loop
              goto again
          }
      }
      return
  }
  retryCount = 0 // reset on successful read

Or more simply, just remove the goto and let ECONNREFUSED errors terminate the connection like other errors, since the 90-second timeout should be sufficient for transient errors.

steinybot9mo ago

AI Investigation:

⏺ Based on my investigation using sequential thinking, I've identified the root cause of the 100% CPU bug in gvproxy on macOS.

Root Cause

The bug is in the replyLoop method in pkg/services/forwarder/udp_proxy.go, specifically in the ECONNREFUSED error handling (lines 83-89).

The Problem

When macOS wakes from sleep, network state changes cause UDP connections to fail. The code has special handling for ECONNREFUSED errors:

  if err, ok := err.(*net.OpError); ok && err.Err == syscall.ECONNREFUSED {
      // retry indefinitely
      goto again
  }

This creates an infinite tight loop when:

  1. Mac wakes from sleep with changed network state (proxy/VPN changes)
  2. VM sends NTP packets to time servers
  3. gvproxy creates UDP connections that fail due to network changes
  4. ICMP "port unreachable" messages get queued in the kernel for these sockets
  5. proxyConn.Read() immediately returns ECONNREFUSED (doesn't block)
  6. Code jumps to again and retries immediately
  7. ICMP error persists, Read() returns ECONNREFUSED again instantly
  8. Infinite loop at 100% CPU with no blocking or delays

Why Multiple Threads

Each NTP server connection creates a separate replyLoop goroutine (line 129). Multiple NTP servers = multiple spinning goroutines = multiple CPU cores pegged at 100%.

Evidence Match

✅ Happens after sleep - network state changes cause connection failures ✅ Related to proxies/VPNs - routing changes trigger ICMP errors ✅ Multiple threads spinning - one replyLoop per NTP connection ✅ Thread count = NTP connection count - each replyLoop is independent ✅ Connections never close - replyLoop stuck in infinite loop ✅ NTP port 123 specifically - UDP where ICMP errors are common

The Fix

Add safeguards to prevent infinite retry loops:

  // Option 1: Limit consecutive retries
  retryCount := 0
  maxRetries := 10
  again:
  read, err := proxyConn.Read(readBuf)
  if err != nil {
      if err, ok := err.(*net.OpError); ok && err.Err == syscall.ECONNREFUSED {
          retryCount++
          if retryCount < maxRetries {
              time.Sleep(10 * time.Millisecond) // prevent tight loop
              goto again
          }
      }
      return
  }
  retryCount = 0 // reset on successful read

Or more simply, just remove the goto and let ECONNREFUSED errors terminate the connection like other errors, since the 90-second timeout should be sufficient for transient errors.

cfergeau9mo ago

Mac wakes from sleep with changed network state (proxy/VPN changes)

Is this true on your setup when you reproduce this issue?

cfergeau9mo ago

Mac wakes from sleep with changed network state (proxy/VPN changes)

Is this true on your setup when you reproduce this issue?

cfergeau9mo ago

Mac wakes from sleep with changed network state (proxy/VPN changes)

Is this true on your setup when you reproduce this issue?

cfergeau9mo ago

I’ve tried to reproduce this by disabling wifi, and using a wired connection on my mac. Then I put it to sleep and unplug the wired connection, and wake it up. I’ve seen several logs similar to time="2025-12-03T14:39:13+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 132.248.30.3:123: connect: network is unreachable\n" , but I don’t hit 100% CPU, nor do I see worrying threads in lsof. Looks like there is more to it than just connection refused.

I’m working on a way to get a dump of the state of all the go routines when gvproxy gets to 100% CPU, but you will need a modified gvproxy binary.

cfergeau9mo ago

I’ve tried to reproduce this by disabling wifi, and using a wired connection on my mac. Then I put it to sleep and unplug the wired connection, and wake it up. I’ve seen several logs similar to time="2025-12-03T14:39:13+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 132.248.30.3:123: connect: network is unreachable\n" , but I don’t hit 100% CPU, nor do I see worrying threads in lsof. Looks like there is more to it than just connection refused.

I’m working on a way to get a dump of the state of all the go routines when gvproxy gets to 100% CPU, but you will need a modified gvproxy binary.

cfergeau9mo ago

I’ve tried to reproduce this by disabling wifi, and using a wired connection on my mac. Then I put it to sleep and unplug the wired connection, and wake it up. I’ve seen several logs similar to time="2025-12-03T14:39:13+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 132.248.30.3:123: connect: network is unreachable\n" , but I don’t hit 100% CPU, nor do I see worrying threads in lsof. Looks like there is more to it than just connection refused.

I’m working on a way to get a dump of the state of all the go routines when gvproxy gets to 100% CPU, but you will need a modified gvproxy binary.

steinybot8mo ago

Mac wakes from sleep with changed network state (proxy/VPN changes)

Is this true on your setup when you reproduce this issue?

I'm not entirely sure. I do use Global Secure Access. It's possible that it disconnects when sleeping and then reconnects after waking up.

steinybot8mo ago

Mac wakes from sleep with changed network state (proxy/VPN changes)

Is this true on your setup when you reproduce this issue?

I'm not entirely sure. I do use Global Secure Access. It's possible that it disconnects when sleeping and then reconnects after waking up.

steinybot8mo ago

Mac wakes from sleep with changed network state (proxy/VPN changes)

Is this true on your setup when you reproduce this issue?

I'm not entirely sure. I do use Global Secure Access. It's possible that it disconnects when sleeping and then reconnects after waking up.

hugoprudente3mo ago

Hi team,

Do we have any date for having the 8e7b605e as part of a release, as v0.8.9 do not include it.

cfergeau3mo ago

Do we have any date for having the 8e7b605 as part of a release, as v0.8.9 do not include it.

This was backported to v0.8.9 as https://github.com/containers/gvisor-tap-vsock/commit/828122235c704e5a6016712edece182fcf43af1c Are you still seeing this issue with v0.8.9?

hugoprudente3mo ago

@cfergeau the versions that my homebrew are getting are not getting version v0.8.9 :( .

I have built myself and replaced the binary and it works :)

(I'm used to gerrit way of checking, so the tag contains didn't found the commit as it's not the same commit.