UDP Proxy device crashes

[dang-khoa-tran]

Required information

• Distribution: Ubuntu (server)
• Distribution version: 18.04.1 LTS
• The output of "lxc info" or if that fails:
• lxc info output with certificate and addresses removed config: {} api_extensions:
  • storage_zfs_remove_snapshots
  • container_host_shutdown_timeout
  • container_stop_priority
  • container_syscall_filtering
  • auth_pki
  • container_last_used_at
  • etag
  • patch
  • usb_devices
  • https_allowed_credentials
  • image_compression_algorithm
  • directory_manipulation
  • container_cpu_time
  • storage_zfs_use_refquota
  • storage_lvm_mount_options
  • network
  • profile_usedby
  • container_push
  • container_exec_recording
  • certificate_update
  • container_exec_signal_handling
  • gpu_devices
  • container_image_properties
  • migration_progress
  • id_map
  • network_firewall_filtering
  • network_routes
  • storage
  • file_delete
  • file_append
  • network_dhcp_expiry
  • storage_lvm_vg_rename
  • storage_lvm_thinpool_rename
  • network_vlan
  • image_create_aliases
  • container_stateless_copy
  • container_only_migration
  • storage_zfs_clone_copy
  • unix_device_rename
  • storage_lvm_use_thinpool
  • storage_rsync_bwlimit
  • network_vxlan_interface
  • storage_btrfs_mount_options
  • entity_description
  • image_force_refresh
  • storage_lvm_lv_resizing
  • id_map_base
  • file_symlinks
  • container_push_target
  • network_vlan_physical
  • storage_images_delete
  • container_edit_metadata
  • container_snapshot_stateful_migration
  • storage_driver_ceph
  • storage_ceph_user_name
  • resource_limits
  • storage_volatile_initial_source
  • storage_ceph_force_osd_reuse
  • storage_block_filesystem_btrfs
  • resources
  • kernel_limits
  • storage_api_volume_rename
  • macaroon_authentication
  • network_sriov
  • console
  • restrict_devlxd
  • migration_pre_copy
  • infiniband
  • maas_network
  • devlxd_events
  • proxy
  • network_dhcp_gateway
  • file_get_symlink
  • network_leases
  • unix_device_hotplug
  • storage_api_local_volume_handling
  • operation_description
  • clustering
  • event_lifecycle
  • storage_api_remote_volume_handling
  • nvidia_runtime
  • container_mount_propagation
  • container_backup
  • devlxd_images
  • container_local_cross_pool_handling
  • proxy_unix
  • proxy_udp
  • clustering_join
  • proxy_tcp_udp_multi_port_handling
  • network_state
  • proxy_unix_dac_properties
  • container_protection_delete
  • unix_priv_drop
  • pprof_http
  • proxy_haproxy_protocol
  • network_hwaddr
  • proxy_nat
  • network_nat_order
  • container_full
  • candid_authentication
  • backup_compression
  • candid_config
  • nvidia_runtime_config
  • storage_api_volume_snapshots
  • storage_unmapped
  • projects
  • candid_config_key
  • network_vxlan_ttl
  • container_incremental_copy
  • usb_optional_vendorid
  • snapshot_scheduling
  • container_copy_project
  • clustering_server_address
  • clustering_image_replication
  • container_protection_shift
  • snapshot_expiry
  • container_backup_override_pool api_status: stable api_version: "1.0" auth: trusted public: false auth_methods:
  • tls environment: architectures:
  • x86_64
  • i686 driver: lxc driver_version: 3.1.0 kernel: Linux kernel_architecture: x86_64 kernel_version: 4.15.0-45-generic server: lxd server_pid: 85189 server_version: "3.10" storage: btrfs storage_version: "4.4" server_clustered: false server_name: homeserver project: default

Issue description

Trying to host a teamspeak server on container. To do that I added a UDP proxy device to forward the port, and after a uncertain amount of time the proxy seems to crash. lsof -i -n | grep 9987 returns nothing

and the proxys log files contains following message: `panic: runtime error: racy use of timers

goroutine 36 [running]: time.startTimer(0xc0001c42d8) /build/lxd/parts/go/build/src/runtime/time.go:114 +0x2b time.(*Timer).Reset(0xc0001c42d0, 0x1a3185c5000, 0xc0001b6c00) /build/lxd/parts/go/build/src/time/sleep.go:130 +0x81 main.proxyCopy(0x1379ee0, 0xc00000e030, 0x1379ee0, 0xc0001ba028, 0x0, 0x0) /build/lxd/parts/lxd/go/src/github.com/lxc/lxd/lxd/main_forkproxy.go:778 +0x68b created by main.proxyCopy /build/lxd/parts/lxd/go/src/github.com/lxc/lxd/lxd/main_forkproxy.go:733 +0xb9e`

Steps to reproduce

Not sure how to reproduce. Installed and configured Teamspeak3 on the container, added the proxy devices and then connected with multiple clients on to the server. After some time it just disconnects.

Information to attach

• [ ] Any relevant kernel output (dmesg)
• [ ] Container log (lxc info NAME --show-log)

Name: teamspeak Location: none Remote: unix:// Architecture: x86_64 Created: 2019/01/27 19:05 UTC Status: Running Type: persistent Profiles: default Pid: 63900 Ips: lo: inet 127.0.0.1 lo: inet6 ::1 eth0: inet 192.168.0.116 vethQT39LV eth0: inet6 fd42:3b06:828a:7517:216:3eff:fe16:a6be vethQT39LV eth0: inet6 fe80::216:3eff:fe16:a6be vethQT39LV Resources: Processes: 41 CPU usage: CPU usage (in seconds): 224 Memory usage: Memory (current): 95.78MB Memory (peak): 109.88MB Network usage: eth0: Bytes received: 6.12MB Bytes sent: 116.36kB Packets received: 56089 Packets sent: 1463 lo: Bytes received: 25.99MB Bytes sent: 25.99MB Packets received: 238899 Packets sent: 238899

Log:

lxc teamspeak 20190211163957.970 WARN conf - conf.c:lxc_map_ids:2970 - newuidmap binary is missing lxc teamspeak 20190211163957.970 WARN conf - conf.c:lxc_map_ids:2976 - newgidmap binary is missing lxc teamspeak 20190211163958.298 WARN conf - conf.c:lxc_map_ids:2970 - newuidmap binary is missing lxc teamspeak 20190211163958.298 WARN conf - conf.c:lxc_map_ids:2976 - newgidmap binary is missing lxc teamspeak 20190211163958.413 WARN conf - conf.c:lxc_setup_devpts:1641 - Invalid argument - Failed to unmount old devpts instance

• [ ] Container configuration (lxc config show NAME --expanded)

architecture: x86_64 config: boot.autostart: "1" image.architecture: amd64 image.build: "20181129_07:43" image.description: Ubuntu bionic amd64 (20181129_07:43) image.distribution: ubuntu image.name: ubuntu-bionic-amd64-default-20181129_07:43 image.os: ubuntu image.release: bionic image.serial: "20181129_07:43" image.variant: default limits.cpu.allowance: 10% limits.memory: 1024MB limits.memory.enforce: hard volatile.base_image: 1bae1c087cedd4f169f5e3cd9e0a088116460a0bc0f2ea25741a6bf997634171 volatile.eth0.hwaddr: 00:16:3e:16:a6:be volatile.idmap.base: "0" volatile.idmap.next: '[{"Isuid":true,"Isgid":false,"Hostid":100000,"Nsid":0,"Maprange":65536},{"Isuid":false,"Isgid":true,"Hostid":100000,"Nsid":0,"Maprange":65536}]' volatile.last_state.idmap: '[{"Isuid":true,"Isgid":false,"Hostid":100000,"Nsid":0,"Maprange":65536},{"Isuid":false,"Isgid":true,"Hostid":100000,"Nsid":0,"Maprange":65536}]' volatile.last_state.power: RUNNING devices: FileTransfer: connect: tcp:192.168.0.116:30033 listen: tcp:192.168.178.138:30033 type: proxy ServerQuery: connect: tcp:192.168.0.116:10011 listen: tcp:192.168.178.138:10011 type: proxy Voice: connect: udp:192.168.0.116:9987 listen: udp:192.168.178.138:9987 type: proxy eth0: name: eth0 nictype: bridged parent: lxdbr0 type: nic root: path: / pool: default type: disk ephemeral: false profiles:

• default stateful: false description: ""

  • [ ] Main daemon log (at /var/log/lxd/lxd.log or /var/snap/lxd/common/lxd/logs/lxd.log) t=2019-02-12T02:13:01+0000 lvl=info msg="LXD 3.10 is starting in normal mode" path=/var/snap/lxd/common/lxd t=2019-02-12T02:13:01+0000 lvl=info msg="Kernel uid/gid map:" t=2019-02-12T02:13:01+0000 lvl=info msg=" - u 0 0 4294967295" t=2019-02-12T02:13:01+0000 lvl=info msg=" - g 0 0 4294967295" t=2019-02-12T02:13:01+0000 lvl=info msg="Configured LXD uid/gid map:" t=2019-02-12T02:13:01+0000 lvl=info msg=" - u 0 1000000 1000000000" t=2019-02-12T02:13:01+0000 lvl=info msg=" - g 0 1000000 1000000000" t=2019-02-12T02:13:01+0000 lvl=warn msg="CGroup memory swap accounting is disabled, swap limits will be ignored." t=2019-02-12T02:13:01+0000 lvl=info msg="Kernel features:" t=2019-02-12T02:13:01+0000 lvl=info msg=" - netnsid-based network retrieval: no" t=2019-02-12T02:13:01+0000 lvl=info msg=" - uevent injection: no" t=2019-02-12T02:13:01+0000 lvl=info msg=" - unprivileged file capabilities: yes" t=2019-02-12T02:13:01+0000 lvl=info msg="Initializing local database" t=2019-02-12T02:13:01+0000 lvl=info msg="Starting /dev/lxd handler:" t=2019-02-12T02:13:01+0000 lvl=info msg=" - binding devlxd socket" socket=/var/snap/lxd/common/lxd/devlxd/sock t=2019-02-12T02:13:01+0000 lvl=info msg="REST API daemon:" t=2019-02-12T02:13:01+0000 lvl=info msg=" - binding Unix socket" inherited=true socket=/var/snap/lxd/common/lxd/unix.socket t=2019-02-12T02:13:01+0000 lvl=info msg="Initializing global database" t=2019-02-12T02:13:01+0000 lvl=info msg="Updating the LXD global schema. Backup made as \"global.bak\"" t=2019-02-12T02:13:01+0000 lvl=info msg="Initializing storage pools" t=2019-02-12T02:13:01+0000 lvl=info msg="Initializing networks" t=2019-02-12T02:13:02+0000 lvl=info msg="Pruning leftover image files" t=2019-02-12T02:13:02+0000 lvl=info msg="Done pruning leftover image files" t=2019-02-12T02:13:02+0000 lvl=info msg="Loading daemon configuration" t=2019-02-12T02:13:02+0000 lvl=info msg="Pruning expired images" t=2019-02-12T02:13:02+0000 lvl=info msg="Done pruning expired images" t=2019-02-12T02:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T02:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T02:13:02+0000 lvl=info msg="Expiring log files" t=2019-02-12T02:13:02+0000 lvl=info msg="Done expiring log files" t=2019-02-12T02:13:02+0000 lvl=info msg="Updating images" t=2019-02-12T02:13:02+0000 lvl=info msg="Done updating images" t=2019-02-12T02:13:02+0000 lvl=info msg="Updating instance types" t=2019-02-12T02:13:02+0000 lvl=info msg="Done updating instance types" t=2019-02-12T03:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T03:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T04:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T04:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T05:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T05:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T06:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T06:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T07:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T07:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T08:13:02+0000 lvl=info msg="Updating images" t=2019-02-12T08:13:02+0000 lvl=info msg="Done updating images" t=2019-02-12T08:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T08:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T09:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T09:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T10:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T10:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T11:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T11:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T12:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T12:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T13:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T13:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T14:13:02+0000 lvl=info msg="Updating images" t=2019-02-12T14:13:02+0000 lvl=info msg="Done updating images" t=2019-02-12T14:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T14:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T15:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T15:13:02+0000 lvl=info msg="Done pruning expired container backups" t=2019-02-12T16:13:02+0000 lvl=info msg="Pruning expired container backups" t=2019-02-12T16:13:02+0000 lvl=info msg="Done pruning expired container backups"

  • [ ] Output of the client with --debug

  • [ ] Output of the daemon with --debug (alternatively output of lxc monitor while reproducing the issue)

[stgraber]

and the proxys log files contains following message:
`panic: runtime error: racy use of timers

goroutine 36 [running]:
time.startTimer(0xc0001c42d8)
/build/lxd/parts/go/build/src/runtime/time.go:114 +0x2b
time.(*Timer).Reset(0xc0001c42d0, 0x1a3185c5000, 0xc0001b6c00)
/build/lxd/parts/go/build/src/time/sleep.go:130 +0x81
main.proxyCopy(0x1379ee0, 0xc00000e030, 0x1379ee0, 0xc0001ba028, 0x0, 0x0)
/build/lxd/parts/lxd/go/src/github.com/lxc/lxd/lxd/main_forkproxy.go:778 +0x68b
created by main.proxyCopy
/build/lxd/parts/lxd/go/src/github.com/lxc/lxd/lxd/main_forkproxy.go:733 +0xb9e`

@brauner apparently that timer stuff is your code, any idea what's going on?

[alexpmorris]

I may be having a similar problem with UDP in a container as this (lxd 3.10 via snap, ubuntu 18.04).

If I use socat as follows, the UDP connection seems to be rock solid: socat UDP-LISTEN:6050,fork UDP:10.120.31.34:6050

However, if I use the UDP proxy via LXD, as follows: lxc config device add mycontainer udp6050 proxy listen=udp:0.0.0.0:6050 connect=udp:127.0.0.1:6050 bind=host

While it works fine at first (albeit with a few more "request timed out" on ping requests) than socat, eventually the proxy fails completely and the only way I can get it going again is by removing and adding it back again. Unfortunately, I could not seem to find any appropriate log file entries to share in this case, but I will keep an eye out and add any relevant entries if I find some.

lxc config device remove mycontainer udp6050
lxc config device add mycontainer udp6050 proxy listen=udp:0.0.0.0:6050 connect=udp:127.0.0.1:6050 bind=host