gRPC UDP port forwarding doesn't work

[brandonros]

Description

    # provision VM
    echo "provisioning VM"
    export LIMA_SSH_PORT_FORWARDER=false
    limactl start --tty=false --name debian-k3s ./deploy/vm/debian-k3s.yaml

portForwards:
- guestPort: 6443
  hostPort: 6443
  guestIP: "127.0.0.1"
  hostIP: "127.0.0.1"
  proto: tcp
- guestPort: 443
  hostPort: 443
  guestIP: "127.0.0.1"
  hostIP: "127.0.0.1"
  proto: tcp
- guestPort: 80
  hostPort: 80
  guestIP: "127.0.0.1"
  hostIP: "127.0.0.1"
  proto: tcp
- guestPort: 30000
  hostPort: 30000
  guestIP: "0.0.0.0"
  hostIP: "0.0.0.0"
  proto: udp

From host:

 while [ 1 ]; do   echo "test.metric:1|c" | nc -4u -v localhost 30000;   sleep 1; done

From guest:

brandon@lima-debian-k3s:~$ sudo tcpdump -i any -vv -n 'udp port 30000'
tcpdump: data link type LINUX_SLL2
tcpdump: listening on any, link-type LINUX_SLL2 (Linux cooked v2), snapshot length 262144 bytes
# traffic never arrives

I don't know if it's port collision because I was also trying to do this to fully "connect the chain"

apiVersion: v1
kind: Service
metadata:
  name: graphite-statsd
  namespace: graphite
spec:
  type: NodePort
  ports:
    - name: statsd
      port: 8125
      targetPort: 8125
      nodePort: 30000
      protocol: UDP
  selector:
    app.kubernetes.io/name: graphite
    app.kubernetes.io/instance: graphite

[nirs]

@brandonros can you share ~/.lima/debian-k3s/lima.yaml ?

Or include a lima.yaml that reproduce this issue on a developer machine?

[brandonros]

# vm type
vmType: vz

# images
images:
- location: "https://cloud.debian.org/images/cloud/bookworm/latest/debian-12-genericcloud-arm64.qcow2"
  arch: "aarch64"
  digest: "sha256:42911131556b610895360e3d28a2c3ec41c0bad85e8df9fc9374996509d1f256" # Wed, 15 Jan 2025 23:04:40 GMT

# memory
memory: "10GiB"

# cpus
cpus: 8

# cpu type (TODO: gets ignored by VZ?)
cpuType:
  aarch64: host

# disk
disk: "100GiB"

# port forwards
portForwards:
- guestPort: 6443
  hostPort: 6443
  guestIP: "127.0.0.1"
  hostIP: "127.0.0.1"
  proto: tcp
- guestPort: 443
  hostPort: 443
  guestIP: "127.0.0.1"
  hostIP: "127.0.0.1"
  proto: tcp
- guestPort: 80
  hostPort: 80
  guestIP: "127.0.0.1"
  hostIP: "127.0.0.1"
  proto: tcp
- guestPort: 30000
  hostPort: 30000
  guestIP: "0.0.0.0"
  hostIP: "0.0.0.0"
  proto: udp

# mounts
mounts: []

# containerd is managed by k3s, not by Lima, so the values are set to false here.
containerd:
  system: false
  user: false

# provision
provision:
- mode: system
  script: |
    #!/bin/sh
    if [ ! -d /var/lib/rancher/k3s ]; then
      # install k3s
      curl -sfL https://get.k3s.io | INSTALL_K3S_EXEC="server --write-kubeconfig-mode 644 --disable=traefik --disable=metrics-server" sh -

      # trust cluster ssl
      cp /var/lib/rancher/k3s/server/tls/server-ca.crt /usr/local/share/ca-certificates/
      update-ca-certificates

      # add coredns in the cluster to node dns resolution chain
      echo "DNS=10.43.0.10" | tee -a /etc/systemd/resolved.conf
      systemctl restart systemd-resolved
    fi

# probes
probes:
- script: |
    #!/bin/bash
    set -eux -o pipefail
    if ! timeout 30s bash -c "until test -f /etc/rancher/k3s/k3s.yaml; do sleep 3; done"; then
      echo >&2 "k3s is not running yet"
      exit 1
    fi
  hint: |
    The k3s kubeconfig file has not yet been created.
    Run "limactl shell k3s sudo journalctl -u k3s" to check the log.
    If that is still empty, check the bottom of the log at "/var/log/cloud-init-output.log".

# copyToHost
copyToHost:
- guest: "/etc/rancher/k3s/k3s.yaml"
  host: "{{.Dir}}/copied-from-guest/kubeconfig.yaml"
  deleteOnStop: true
- guest: "/var/lib/rancher/k3s/server/tls/server-ca.crt"
  host: "{{.Dir}}/copied-from-guest/server-ca.crt"
  deleteOnStop: true
- guest: "/var/lib/rancher/k3s/server/tls/server-ca.key"
  host: "{{.Dir}}/copied-from-guest/server-ca.key"
  deleteOnStop: true

# message
message: |
  To run `kubectl` on the host (assumes kubectl is installed), run the following commands:
  ------
  export KUBECONFIG="{{.Dir}}/copied-from-guest/kubeconfig.yaml"
  kubectl ...
  ------

# user
user:
  name: brandon

# operating system
os: Linux

[nirs]

@brandonros Which lima version/macOS version?

[nirs]

@brandonros your lima.yaml has bad digest. I remove the digest and cleaned it up a little bit (removed unneeded comments and setting).

Please check that it still reproduces the issue:
issue-3152.yaml.gz

[nirs]

Testing with lima 1.0.3 using the cleaned up file

limactl create issue-3152.yaml --tty=0
LIMA_SSH_PORT_FORWARDER=false limactl start issue-3152
limactl shell issue-3152

In the guest we see that nobody is listening to port 30000:

$ ss -lun
State         Recv-Q        Send-Q                   Local Address:Port                 Peer Address:Port        Process        
UNCONN        0             0                           127.0.0.54:53                        0.0.0.0:*                          
UNCONN        0             0                        127.0.0.53%lo:53                        0.0.0.0:*                          
UNCONN        0             0                    192.168.5.15%eth0:68                        0.0.0.0:*                          
UNCONN        0             0                              0.0.0.0:5355                      0.0.0.0:*                          
UNCONN        0             0                              0.0.0.0:8472                      0.0.0.0:*                          
UNCONN        0             0                                 [::]:5355                         [::]:*                          

Start nc, listning to port 30000

sudo apt-get update
sudo apt-get install netcat-openbsd
nc -l -u 30000

In hostagent log we can see that a port was added:

% tail ~/.lima/issue-3152/ha.stderr.log
...
{"level":"debug","msg":"guest agent event: local_ports_added:{protocol:\"udp\" ip:\"0.0.0.0\" port:30000}","time":"2025-01-27T01:17:28+02:00"}
{"level":"info","msg":"Forwarding UDP from 0.0.0.0:30000 to 0.0.0.0:30000","time":"2025-01-27T01:17:28+02:00"}

Checking port 30000 on the host:

% netstat -p udp | grep 30000
udp46      0      0  *.30000                *.*                               

Trying to send from the host:

% nc -u 127.0.0.1 30000
testing 1 2 3

On the guest we see the line:

nir@lima-issue-3152:~$ nc -l -u 30000
testing 1 2 3

So it seems to work.

[nirs]

So the first line worked, but after sending a second line the local port was closed:

Host:

echo testing 4 5 6 | nc -u 127.0.0.1 30000

Command terminated, nothing sent to guest.

Nobody listen to the port on the host now:

% netstat -p udp -n | grep 30000

In hostagent log we see that port forwarding was closed:

% tail ~/.lima/issue-3152/ha.stderr.log     
{"level":"info","msg":"Forwarding UDP from 0.0.0.0:30000 to 0.0.0.0:30000","time":"2025-01-27T01:17:28+02:00"}
{"level":"debug","msg":"Stopping udp proxy (read udp 194.0.5.123:123: i/o timeout)","time":"2025-01-27T01:18:13+02:00"}
{"level":"debug","msg":"Stopping udp proxy (read udp 194.0.5.123:123: i/o timeout)","time":"2025-01-27T01:18:46+02:00"}
{"level":"debug","msg":"guest agent event: local_ports_removed:{protocol:\"udp\" ip:\"0.0.0.0\" port:30000}","time":"2025-01-27T01:19:46+02:00"}
{"level":"debug","msg":"removing listener for hostAddress: 0.0.0.0:30000, guestAddress: 0.0.0.0:30000","time":"2025-01-27T01:19:46+02:00"}
{"level":"debug","msg":"Port forwarding closed proto:udp host:0.0.0.0:30000 guest:0.0.0.0:30000","time":"2025-01-27T01:19:46+02:00"}
{"level":"debug","msg":"removing listener for hostAddress: 0.0.0.0:30000, guestAddress: 0.0.0.0:30000","time":"2025-01-27T01:19:46+02:00"}

Seems that we have an issue in the guestagent, reporting that port was removed. This correctly stop forwarding on the host.

I stopped nc on the guest and started it again. This time I sent the instance yaml to the guest:

% nc -u 127.0.0.1 30000 < issue-3152.yaml

The guest received the entire yaml, and then we see again closing of the port formwarding:

% tail -f ~/.lima/issue-3152/ha.stderr.log
{"level":"info","msg":"Forwarding UDP from 0.0.0.0:30000 to 0.0.0.0:30000","time":"2025-01-27T01:17:28+02:00"}
{"level":"debug","msg":"Stopping udp proxy (read udp 194.0.5.123:123: i/o timeout)","time":"2025-01-27T01:18:13+02:00"}
{"level":"debug","msg":"Stopping udp proxy (read udp 194.0.5.123:123: i/o timeout)","time":"2025-01-27T01:18:46+02:00"}
{"level":"debug","msg":"guest agent event: local_ports_removed:{protocol:\"udp\" ip:\"0.0.0.0\" port:30000}","time":"2025-01-27T01:19:46+02:00"}
{"level":"debug","msg":"removing listener for hostAddress: 0.0.0.0:30000, guestAddress: 0.0.0.0:30000","time":"2025-01-27T01:19:46+02:00"}
{"level":"debug","msg":"Port forwarding closed proto:udp host:0.0.0.0:30000 guest:0.0.0.0:30000","time":"2025-01-27T01:19:46+02:00"}
{"level":"debug","msg":"removing listener for hostAddress: 0.0.0.0:30000, guestAddress: 0.0.0.0:30000","time":"2025-01-27T01:19:46+02:00"}
{"level":"debug","msg":"Stopping udp proxy (read udp 194.0.5.123:123: i/o timeout)","time":"2025-01-27T01:19:50+02:00"}
{"level":"debug","msg":"Stopping udp proxy (read udp 194.0.5.123:123: i/o timeout)","time":"2025-01-27T01:21:58+02:00"}
{"level":"debug","msg":"Stopping udp proxy (read udp 194.0.5.123:123: i/o timeout)","time":"2025-01-27T01:26:14+02:00"}
{"level":"debug","msg":"guest agent event: local_ports_added:{protocol:\"udp\" ip:\"0.0.0.0\" port:30000}","time":"2025-01-27T01:29:34+02:00"}
{"level":"info","msg":"Forwarding UDP from 0.0.0.0:30000 to 0.0.0.0:30000","time":"2025-01-27T01:29:34+02:00"}
{"level":"debug","msg":"guest agent event: local_ports_removed:{protocol:\"udp\" ip:\"0.0.0.0\" port:30000}","time":"2025-01-27T01:30:16+02:00"}
{"level":"debug","msg":"removing listener for hostAddress: 0.0.0.0:30000, guestAddress: 0.0.0.0:30000","time":"2025-01-27T01:30:16+02:00"}
{"level":"debug","msg":"removing listener for hostAddress: 0.0.0.0:30000, guestAddress: 0.0.0.0:30000","time":"2025-01-27T01:30:16+02:00"}
{"level":"debug","msg":"Port forwarding closed proto:udp host:0.0.0.0:30000 guest:0.0.0.0:30000","time":"2025-01-27T01:30:16+02:00"}

@balajiv113 any idea what can cause the guest to report that the port was removed?

[nirs]

No error in the lima-guestagent logs in the guest:

Jan 27 01:16:11 lima-issue-3152 systemd[1]: Started lima-guestagent.service - lima-guestagent.
Jan 27 01:16:11 lima-issue-3152 lima-guestagent[860]: time="2025-01-27T01:16:11+02:00" level=info msg="event tick: 3s"
Jan 27 01:16:11 lima-issue-3152 lima-guestagent[860]: time="2025-01-27T01:16:11+02:00" level=info msg="Auditing enabled (1)"
Jan 27 01:16:11 lima-issue-3152 lima-guestagent[860]: time="2025-01-27T01:16:11+02:00" level=info msg="serving the guest agent >
Jan 27 01:16:11 lima-issue-3152 lima-guestagent[860]: time="2025-01-27T01:16:11+02:00" level=info msg="Monitoring kubernetes se>
Jan 27 01:16:11 lima-issue-3152 lima-guestagent[860]: time="2025-01-27T01:16:11+02:00" level=info msg="fixSystemTimeSkew(): mon>

Maybe debug level will show more info.

[balajiv113]

@nirs As far as i remember, nc closes it after the first connect. With a proper udp server we should be able to send multiple messages

[nirs]

@nirs As far as i remember, nc closes it after the first connect. With a proper udp server we should be able to send multiple messages

nc does not terminate on the guest, why would it stop listening?

When using TCP this flow works without any issue.

But we can try again with a trivial python udp client and server to eliminate such issue.

[jandubois]

But we can try again with a trivial python udp client and server to eliminate such issue.

But then we have to install Python on each distro we want to test. It would be better if we could use simpler tools for testing.

[nirs]

But we can try again with a trivial python udp client and server to eliminate such issue.

But then we have to install Python on each distro we want to test. It would be better if we could use simpler tools for testing.

I suggest python as a quick way to debug this issue, not to add python to the automated tests.

[nirs]

After more digging I found the issue. netcat (at least the openbsd version I tested) tries to simulate a "connection" when using UDP.

When receiving the first packet it calls connect() with the peer address. This makes the socket ignore packets sent from other addresses:
https://github.com/openbsd/src/blob/e0a5400065cea17a7de6532c2ecb091c5f17622b/usr.bin/nc/netcat.c#L592

So once the client netcat command exit, the server is unlikely to receive packets from the next client, since new client use new local port.

Maybe when this happens we detect that the port is not listening any more. This may be a bug in the code detecting used ports in the guestagent.

To disable the "connection" behavior, we can use the -k option:

     -k      When a connection is completed, listen for another one.  Requires
             -l.  When used together with the -u option, the server socket is
             not connected and it can receive UDP datagrams from multiple
             hosts.

This option does not work on macOS, netcat version is probably too old.

We have another issue on the client - when nc finish to send a message read from stdin, it waits for replies from the peer and never exit. This breaks the example test in the description:

while [ 1 ]; do   echo "test.metric:1|c" | nc -4u -v localhost 30000;   sleep 1; done

This will send exactly one packet and wait forever for reply form the peer. The way to avoid this is to use the -w option:

     -w timeout
             Connections which cannot be established or are idle timeout after
             timeout seconds.  The -w flag has no effect on the -l option,
             i.e. nc will listen forever for a connection, with or without the
             -w flag.  The default is no timeout.

To send a packet every second, we can do:

while true; do echo "test.metric:1|c" | nc -u -w 1 localhost 30000; done

Testing both changes shows that UDP forwarding works:

Guest:

nir@lima-issue-3152:~$ nc -l -u -k 127.0.0.1 30000

Host:

% while true; do date | nc -u -w 1 127.0.0.1 30000; done

Guest:

nir@lima-issue-3152:~$ nc -l -u -k 127.0.0.1 30000
2025-01-28T22:55:08+02:00
2025-01-28T22:55:09+02:00
2025-01-28T22:55:10+02:00
2025-01-28T22:55:11+02:00
2025-01-28T22:55:12+02:00
2025-01-28T22:55:13+02:00
2025-01-28T22:55:14+02:00
2025-01-28T22:55:15+02:00
2025-01-28T22:55:16+02:00
2025-01-28T22:55:17+02:00
2025-01-28T22:55:18+02:00
2025-01-28T22:55:19+02:00
2025-01-28T22:55:20+02:00
2025-01-28T22:55:21+02:00
2025-01-28T22:55:22+02:00
2025-01-28T22:55:23+02:00

@brandonros your test was incorrect - we start port forwarding only when we detect a listening port on the guest. You tried to send packets when nobody listened to the port on the guest.

I think we can close this issue.

We can open another issue for the detection, we should not disable port forwarding when the guest listener calls connect() on the socket.