search

pgj / freebsd-wifibox

wifibox: Use Linux to drive your wireless card on FreeBSD
BSD 2-Clause "Simplified" License
159 stars 12 forks source link

WPA pass-through doesn't work with wpa_gui till manual restart of both wifibox and netif services #16

Closed patovm04 closed 2 years ago

patovm04 commented 2 years ago

First of all, thank you very much for this project! I've been successfully using it with my Intel Wireless-AC 9560 card for some time, but recently I gave WPA pass-through a shot and found that wpa_gui doesn't work right away, unless I do the following:

service netif stop wifibox0 ;
service wifibox restart &&
service netif start wifibox0

I need to do this once after boot up, every time. But then it seems to work just fine. Also noticed wpactrl* sockets don't get created under /tmp directory until issuing commands above...

pgj commented 2 years ago

I am glad that you find Wifibox useful. I would need more information for reproducing this issue. Please include the relevant parts of the following configuration files: wpa_supplicant.conf, wpa_ctrl.conf, rc.conf , as well as the output of wifibox version.

Note that the control sockets shall be created under /var/run/wpa_supplicant on the host (unless configured otherwise). You can find logs for the guest under /var/run/wifibox/appliance/log to see what is actually going on. There the file named messages can tell us more about the wpa_passthru service that is responsible for the implementation on the guest's side, e.g.

cat /var/run/wifibox/appliance/log/message | fgrep wpa_passthru

On the host, the log level may be changed in core.conf, e.g. to info, therefore it can be checked in the resulting /var/log/wifibox.log file how the implementation behaves on the host's side at the same time.

cat /var/log/wifibox.log
patovm04 commented 2 years ago

Ok, I changed core.conf to set loglevel=info. Here is the info you requested:

/usr/local/etc/wifibox/wpa_supplicant/wpa_supplicant.conf

ctrl_interface=/var/run/wpa_supplicant
ctrl_interface_group=0
eapol_version=2
update_config=1

network={
    ssid="myssid"
    psk="mypsk"
    proto=RSN
    key_mgmt=WPA-PSK
    pairwise=CCMP
    auth_alg=OPEN
}

/usr/local/etc/wifibox/wpa_ctrl.conf

enabled=yes
network=10.0.0.1:255.255.255.0
wlan0_port=1200
p2p_dev_wlan0_port=1201

/etc/rc.conf

devmatch_blacklist="if_iwlwifi"
wifibox_enable="YES"
ifconfig_wifibox0="WPA SYNCDHCP"
background_dhclient_wifibox0="YES"
defaultroute_delay="0"
defaultroute_carrier_delay="0"

wifibox version

wifibox version 0.8.1
Disk image checksum: 49452bd58f610d58b2a04f9450c3eeecf0f5958bd0a0c94334edfc8b2a0545d4

NOTE: The following commands are before using the workaround of restarting wifibox and netif:

cat /var/run/wifibox/appliance/log/messages | fgrep wpa_passthru

Apr  3 16:46:32 wifibox daemon.info supervise-daemon[1632]: Supervisor command line: supervise-daemon wpa_passthru --start /sbin/wpa_passthru -- 
Apr  3 16:46:32 wifibox daemon.info supervise-daemon[1635]: Child command line: /sbin/wpa_passthru 
Apr  3 16:46:32 wifibox daemon.debug wpa_passthru[1635]: Configuration: enabled=yes, network=10.0.0.1:255.255.255.0, wlan devs=[p2p_dev_wlan0 wlan0]
Apr  3 16:46:32 wifibox daemon.info wpa_passthru[1635]: Associating 10.0.0.1:1201 (10.0.0.1:255.255.255.0) with /var/run/wpa_supplicant/p2p-dev-wlan0 (/tmp/tmp.keijbp/p2p-dev-wlan0)
Apr  3 16:46:32 wifibox daemon.info wpa_passthru[1635]: Associating 10.0.0.1:1200 (10.0.0.1:255.255.255.0) with /var/run/wpa_supplicant/wlan0 (/tmp/tmp.keijbp/wlan0)

cat /var/log/wifibox.log

2022-04-03T12:46:25-0400 INFO  Begin: wifibox start
2022-04-03T12:46:25-0400 INFO  vmm.ko is expected at path: vmm.ko
2022-04-03T12:46:25-0400 INFO  vmm.ko is found at path: /boot/kernel/vmm.ko
2022-04-03T12:46:25-0400 INFO  Creating bridge interface: wifibox0
2022-04-03T12:46:25-0400 INFO  Linking tap interface to wifibox0: tap0
2022-04-03T12:46:25-0400 INFO  Gathering necessary configuration files for launching the guest
2022-04-03T12:46:25-0400 INFO  Pulling bhyve options from configuration file
2022-04-03T12:46:25-0400 INFO  Guest console is not configured to use
2022-04-03T12:46:25-0400 INFO  Passthru device is configured: 0/20/3
2022-04-03T12:46:25-0400 INFO  PPT driver is configured for pci0:20:3 device
2022-04-03T12:46:25-0400 INFO  tap interface is configured: tap0
2022-04-03T12:46:25-0400 INFO  Pulling WPA Supplicant control options from configuration file
2022-04-03T12:46:25-0400 INFO  wpa_supplicant.conf will be mounted writable
2022-04-03T12:46:25-0400 INFO  Lauching guest wifibox with grub-bhyve
2022-04-03T12:46:25-0400 INFO  Launching guest wifibox with bhyve
2022-04-03T12:46:25-0400 INFO  Waiting for bhyve to start up
2022-04-03T12:46:26-0400 INFO  Guest wifibox has started up
2022-04-03T12:46:26-0400 INFO  Bringing up WPA pass-through
2022-04-03T12:46:26-0400 INFO  Control interface: /var/run/wpa_supplicant
2022-04-03T12:46:26-0400 INFO  Found guest IP address: 10.0.0.1
2022-04-03T12:46:26-0400 INFO  Control interface group: 0
2022-04-03T12:46:26-0400 INFO  WLAN devices: [p2p_dev_wlan0
wlan0]
2022-04-03T12:46:26-0400 INFO  Hooking up 10.0.0.1:1201 as /var/run/wpa_supplicant/p2p-dev-wlan0
2022-04-03T12:46:26-0400 INFO  Hooking up 10.0.0.1:1200 as /var/run/wpa_supplicant/wlan0
2022-04-03T12:46:26-0400 INFO  End: wifibox start
2022-04-03T13:01:56-0400 INFO  Begin: wifibox version
2022-04-03T13:01:57-0400 INFO  End: wifibox version
pgj commented 2 years ago

Everything looks okay to me. Do you have UNIX domain sockets created under /var/run/wpa_supplicant, right? What is the exact problem you are experiencing with wpa_gui?

patovm04 commented 2 years ago

Well, the thing is /var/run/wpa_supplicant/ is actually empty until I restart wifibox and netif, I don't know why. wpa_gui remains mostly blank (no icon, almost no info) and only says: _"Status: Could not get status from wpasupplicant"

Also restarting wpa_gui doesn't help.

After I do:

service netif stop wifibox0 ;
service wifibox restart &&
service netif start wifibox0

both p2p-dev-wlan0 and wlan0 get created under /var/run/wpa_supplicant/ and also 2 files named wpa_ctrl_* appear in /tmp directory. And wpa_gui starts working alright...

pgj commented 2 years ago

This must be due to a problem with socat on the host's side. I guess wpa_ctrl_* will not be created until wpa_gui establishes a connnection with the wpa_supplicant through the socket.

Could you please switch to debug level? It shall record if socat has emitted any error on launch. It would be good to see if there happened any related message. It should appear after the Hooking up ... info message.

patovm04 commented 2 years ago

Sure. I set loglevel=debug and rebooted. This is the content of /var/log/wifibox.log since:

2022-04-03T16:45:35-0400 DEBUG Program started as /usr/local/sbin/wifibox, with arguments: start
2022-04-03T16:45:35-0400 INFO  Begin: wifibox start
2022-04-03T16:45:35-0400 INFO  vmm.ko is expected at path: vmm.ko
2022-04-03T16:45:35-0400 INFO  vmm.ko is found at path: /boot/kernel/vmm.ko
2022-04-03T16:45:35-0400 DEBUG assert loaded: kmod=vmm, kmod_file=vmm.ko
2022-04-03T16:45:35-0400 DEBUG Kernel module vmm is not loaded
2022-04-03T16:45:35-0400 DEBUG Kernel module vmm was loaded successfully
2022-04-03T16:45:35-0400 DEBUG assert hardware support present: iommu=1, amdvi=0
2022-04-03T16:45:35-0400 DEBUG Backends reported by bhyve:
2022-04-03T16:45:35-0400 DEBUG [bhyve] ahci
2022-04-03T16:45:35-0400 DEBUG [bhyve] ahci-hd
2022-04-03T16:45:35-0400 DEBUG [bhyve] ahci-cd
2022-04-03T16:45:35-0400 DEBUG [bhyve] e1000
2022-04-03T16:45:35-0400 DEBUG [bhyve] dummy
2022-04-03T16:45:35-0400 DEBUG [bhyve] hda
2022-04-03T16:45:35-0400 DEBUG [bhyve] fbuf
2022-04-03T16:45:35-0400 DEBUG [bhyve] amd_hostbridge
2022-04-03T16:45:35-0400 DEBUG [bhyve] hostbridge
2022-04-03T16:45:35-0400 DEBUG [bhyve] lpc
2022-04-03T16:45:35-0400 DEBUG [bhyve] nvme
2022-04-03T16:45:35-0400 DEBUG [bhyve] passthru
2022-04-03T16:45:35-0400 DEBUG [bhyve] virtio-9p
2022-04-03T16:45:35-0400 DEBUG [bhyve] virtio-blk
2022-04-03T16:45:35-0400 DEBUG [bhyve] virtio-console
2022-04-03T16:45:35-0400 DEBUG [bhyve] virtio-net
2022-04-03T16:45:35-0400 DEBUG [bhyve] virtio-rnd
2022-04-03T16:45:35-0400 DEBUG [bhyve] virtio-scsi
2022-04-03T16:45:35-0400 DEBUG [bhyve] uart
2022-04-03T16:45:35-0400 DEBUG [bhyve] xhci
2022-04-03T16:45:35-0400 INFO  Creating bridge interface: wifibox0
2022-04-03T16:45:35-0400 DEBUG [ifconfig] wifibox0
2022-04-03T16:45:35-0400 INFO  Linking tap interface to wifibox0: tap0
2022-04-03T16:45:35-0400 INFO  Gathering necessary configuration files for launching the guest
2022-04-03T16:45:35-0400 INFO  Pulling bhyve options from configuration file
2022-04-03T16:45:35-0400 DEBUG cpus=1, memory=90M, passthru=0/20/3, console=no
2022-04-03T16:45:35-0400 INFO  Guest console is not configured to use
2022-04-03T16:45:35-0400 INFO  Passthru device is configured: 0/20/3
2022-04-03T16:45:35-0400 INFO  PPT driver is configured for pci0:20:3 device
2022-04-03T16:45:35-0400 INFO  tap interface is configured: tap0
2022-04-03T16:45:35-0400 INFO  Pulling WPA Supplicant control options from configuration file
2022-04-03T16:45:35-0400 DEBUG wpa_ctrl.enabled=yes
2022-04-03T16:45:35-0400 INFO  wpa_supplicant.conf will be mounted writable
2022-04-03T16:45:35-0400 INFO  Lauching guest wifibox with grub-bhyve
2022-04-03T16:45:35-0400 DEBUG Arguments:  -S -M 90M -r host  -m /usr/local/share/wifibox/device.map -d /usr/local/share/wifibox wifibox
2022-04-03T16:45:35-0400 INFO  Launching guest wifibox with bhyve
2022-04-03T16:45:35-0400 DEBUG Arguments:  -c 1 -m 90M -AHP -u -S  -s 0,hostbridge -s 31,lpc -s 4:0,virtio-blk,/usr/local/share/wifibox/disk.img -s 4:1,virtio-9p,config=/usr/local/etc/wifibox,ro -s 4:2,virtio-9p,wpa_config=/usr/local/etc/wifibox/wpa_supplicant -s 4:3,virtio-9p,var=/var/run/wifibox/appliance -s 5:0,e1000,tap0 -s 6:0,passthru,0/20/3 wifibox
2022-04-03T16:45:35-0400 INFO  Waiting for bhyve to start up
2022-04-03T16:45:36-0400 DEBUG [bhyve] rdmsr to register 0x140 on vcpu 0
2022-04-03T16:45:36-0400 DEBUG [bhyve] rdmsr to register 0x64e on vcpu 0
2022-04-03T16:45:36-0400 DEBUG [bhyve] rdmsr to register 0x34 on vcpu 0
2022-04-03T16:45:36-0400 DEBUG Guest is backed by PID 1775
2022-04-03T16:45:36-0400 INFO  Guest wifibox has started up
2022-04-03T16:45:36-0400 INFO  Bringing up WPA pass-through
2022-04-03T16:45:36-0400 INFO  Control interface: /var/run/wpa_supplicant
2022-04-03T16:45:36-0400 INFO  Found guest IP address: 10.0.0.1
2022-04-03T16:45:36-0400 INFO  Control interface group: 0
2022-04-03T16:45:36-0400 INFO  WLAN devices: [p2p_dev_wlan0
wlan0]
2022-04-03T16:45:36-0400 INFO  Hooking up 10.0.0.1:1201 as /var/run/wpa_supplicant/p2p-dev-wlan0
2022-04-03T16:45:36-0400 INFO  Hooking up 10.0.0.1:1200 as /var/run/wpa_supplicant/wlan0
2022-04-03T16:45:36-0400 INFO  End: wifibox start

As you can see, there's nothing about socat in there. If I restart wifibox and netif, this is the new info that appears in /var/log/wifibox.log :

2022-04-03T16:53:43-0400 DEBUG Program started as /usr/local/sbin/wifibox, with arguments: stop
2022-04-03T16:53:43-0400 INFO  Begin: wifibox stop
2022-04-03T16:53:43-0400 DEBUG assert guest runs: pid=1775
2022-04-03T16:53:43-0400 INFO  Tearing down WPA pass-through
2022-04-03T16:53:43-0400 INFO  socat processes found: []
2022-04-03T16:53:43-0400 INFO  Stopping guest wifibox, backed by PID 1775
2022-04-03T16:53:43-0400 INFO  Waiting 3 seconds for the guest to stop
2022-04-03T16:53:46-0400 INFO  Forcing shutdown of guest wifibox
2022-04-03T16:53:46-0400 INFO  Destroying guest wifibox
2022-04-03T16:53:47-0400 INFO  Destroying bhyve PPT device: pci0:20:3
2022-04-03T16:53:47-0400 DEBUG [devctl] devctl: Failed to clear pci0:20:3 driver: Device not configured
2022-04-03T16:53:47-0400 WARN  The PPT device could not be destroyed
2022-04-03T16:53:47-0400 INFO  Removing null-modem devices
2022-04-03T16:53:47-0400 INFO  Null-modem devices are removed
2022-04-03T16:53:47-0400 INFO  Destroying bridge interface: wifibox0
2022-04-03T16:53:47-0400 INFO  Destroying linked tap interface: tap0
2022-04-03T16:53:47-0400 INFO  End: wifibox stop
2022-04-03T16:53:47-0400 DEBUG Program started as /usr/local/sbin/wifibox, with arguments: start
2022-04-03T16:53:47-0400 INFO  Begin: wifibox start
2022-04-03T16:53:47-0400 INFO  vmm.ko is expected at path: vmm.ko
2022-04-03T16:53:47-0400 INFO  vmm.ko is found at path: /boot/kernel/vmm.ko
2022-04-03T16:53:47-0400 DEBUG assert loaded: kmod=vmm, kmod_file=vmm.ko
2022-04-03T16:53:47-0400 DEBUG Kernel module vmm is not loaded
2022-04-03T16:53:47-0400 DEBUG Kernel module vmm was loaded successfully
2022-04-03T16:53:47-0400 DEBUG assert hardware support present: iommu=1, amdvi=0
2022-04-03T16:53:47-0400 DEBUG Backends reported by bhyve:
2022-04-03T16:53:47-0400 DEBUG [bhyve] ahci
2022-04-03T16:53:47-0400 DEBUG [bhyve] ahci-hd
2022-04-03T16:53:47-0400 DEBUG [bhyve] ahci-cd
2022-04-03T16:53:47-0400 DEBUG [bhyve] e1000
2022-04-03T16:53:47-0400 DEBUG [bhyve] dummy
2022-04-03T16:53:47-0400 DEBUG [bhyve] hda
2022-04-03T16:53:47-0400 DEBUG [bhyve] fbuf
2022-04-03T16:53:47-0400 DEBUG [bhyve] amd_hostbridge
2022-04-03T16:53:47-0400 DEBUG [bhyve] hostbridge
2022-04-03T16:53:47-0400 DEBUG [bhyve] lpc
2022-04-03T16:53:47-0400 DEBUG [bhyve] nvme
2022-04-03T16:53:47-0400 DEBUG [bhyve] passthru
2022-04-03T16:53:47-0400 DEBUG [bhyve] virtio-9p
2022-04-03T16:53:47-0400 DEBUG [bhyve] virtio-blk
2022-04-03T16:53:47-0400 DEBUG [bhyve] virtio-console
2022-04-03T16:53:47-0400 DEBUG [bhyve] virtio-net
2022-04-03T16:53:47-0400 DEBUG [bhyve] virtio-rnd
2022-04-03T16:53:47-0400 DEBUG [bhyve] virtio-scsi
2022-04-03T16:53:47-0400 DEBUG [bhyve] uart
2022-04-03T16:53:47-0400 DEBUG [bhyve] xhci
2022-04-03T16:53:47-0400 INFO  Creating bridge interface: wifibox0
2022-04-03T16:53:47-0400 DEBUG [ifconfig] wifibox0
2022-04-03T16:53:47-0400 INFO  Linking tap interface to wifibox0: tap0
2022-04-03T16:53:47-0400 INFO  Gathering necessary configuration files for launching the guest
2022-04-03T16:53:47-0400 INFO  Pulling bhyve options from configuration file
2022-04-03T16:53:47-0400 DEBUG cpus=1, memory=90M, passthru=0/20/3, console=no
2022-04-03T16:53:47-0400 INFO  Guest console is not configured to use
2022-04-03T16:53:47-0400 INFO  Passthru device is configured: 0/20/3
2022-04-03T16:53:47-0400 INFO  PPT driver is configured for pci0:20:3 device
2022-04-03T16:53:47-0400 INFO  tap interface is configured: tap0
2022-04-03T16:53:47-0400 INFO  Pulling WPA Supplicant control options from configuration file
2022-04-03T16:53:47-0400 DEBUG wpa_ctrl.enabled=yes
2022-04-03T16:53:47-0400 INFO  wpa_supplicant.conf will be mounted writable
2022-04-03T16:53:47-0400 INFO  Lauching guest wifibox with grub-bhyve
2022-04-03T16:53:47-0400 DEBUG Arguments:  -S -M 90M -r host  -m /usr/local/share/wifibox/device.map -d /usr/local/share/wifibox wifibox
2022-04-03T16:53:47-0400 INFO  Launching guest wifibox with bhyve
2022-04-03T16:53:47-0400 DEBUG Arguments:  -c 1 -m 90M -AHP -u -S  -s 0,hostbridge -s 31,lpc -s 4:0,virtio-blk,/usr/local/share/wifibox/disk.img -s 4:1,virtio-9p,config=/usr/local/etc/wifibox,ro -s 4:2,virtio-9p,wpa_config=/usr/local/etc/wifibox/wpa_supplicant -s 4:3,virtio-9p,var=/var/run/wifibox/appliance -s 5:0,e1000,tap0 -s 6:0,passthru,0/20/3 wifibox
2022-04-03T16:53:47-0400 INFO  Waiting for bhyve to start up
2022-04-03T16:53:48-0400 DEBUG [bhyve] rdmsr to register 0x140 on vcpu 0
2022-04-03T16:53:48-0400 DEBUG [bhyve] rdmsr to register 0x64e on vcpu 0
2022-04-03T16:53:48-0400 DEBUG [bhyve] rdmsr to register 0x34 on vcpu 0
2022-04-03T16:53:48-0400 DEBUG Guest is backed by PID 87176
2022-04-03T16:53:48-0400 INFO  Guest wifibox has started up
2022-04-03T16:53:48-0400 INFO  Bringing up WPA pass-through
2022-04-03T16:53:48-0400 INFO  Control interface: /var/run/wpa_supplicant
2022-04-03T16:53:48-0400 INFO  Found guest IP address: 10.0.0.1
2022-04-03T16:53:48-0400 INFO  Control interface group: 0
2022-04-03T16:53:48-0400 INFO  WLAN devices: [p2p_dev_wlan0
wlan0]
2022-04-03T16:53:48-0400 INFO  Hooking up 10.0.0.1:1201 as /var/run/wpa_supplicant/p2p-dev-wlan0
2022-04-03T16:53:48-0400 INFO  Hooking up 10.0.0.1:1200 as /var/run/wpa_supplicant/wlan0
2022-04-03T16:53:48-0400 INFO  End: wifibox start
2022-04-03T16:53:49-0400 DEBUG [socat] 2022/04/03 16:53:49 socat[86709] E connect(6, LEN=16 AF=2 10.0.0.1:1200, 16): Network is unreachable
2022-04-03T16:53:59-0400 DEBUG [socat] 2022/04/03 16:53:59 socat[89016] E connect(6, LEN=16 AF=2 10.0.0.1:1200, 16): Network is unreachable
pgj commented 2 years ago

Looks like socat could not start up for the first time. I do not know yet how this could be possible, but I will look into this, thanks for all the information!

It might be interesting to to see if the problem could be fixed by running the missed socat command when a blank socket is created. Please use this workaround next time, just to verify if it solves the problem:

/usr/local/bin/socat \
  UNIX-RECVFROM:/var/run/wpa_supplicant/wlan0,reuseaddr,fork,unlink-early,user=root,group=0,mode=770 \
  TCP4:10.0.0.1:1200
patovm04 commented 2 years ago

That did it! Running the above socat command fixes the problem and is way faster than my previous workaround! Thank you for all your help!! Hopefully you'll be able to find a proper fix. I'll be following this bug, so if you need me to test something, feel free to ask :)

pgj commented 2 years ago

Cool! By the way, what version of FreeBSD is this? Could you please post a freebsd-version -kru output? Also, can you see anything related to socat in the system logs, i.e. output of dmesg or in /var/log/messages? These might be able to show if socat crashed on startup.

patovm04 commented 2 years ago

At the moment I'm running FreeBSD 13.1-RC1, and using 'latest' pkg branch. freebsd-version -kru

13.1-RC1
13.1-RC1
13.1-RC1

Unfortunately, there's nothing about socat in either /var/run/dmesg.boot or /var/log/messages ...

pgj commented 2 years ago

No worries. I will try to reproduce the problem based on your feedback.

pgj commented 2 years ago

You said you are using the latest pkg branch, that is the version of socat you have is 1.7.4.3 ?

patovm04 commented 2 years ago

Yes, that's right. socat-1.7.4.3

pgj commented 2 years ago

I was able to extract more information from socat via its own debugging functionality. It seems that during boot, socat receives a SIGHUP signal which makes it exit, probably because it becomes detached from the terminal where wifibox was launched. Hence the problem can be reproduced later by sending a SIGHUP.

pgj commented 2 years ago

@patovm04 I created a version of the port that includes a version of Wifibox with a proposed fix, which can be found on this URL: https://github.com/pgj/freebsd-wifibox-port/tree/6dafc7355f9d66d0f64c08596fe863acfdad394b -- Please test it.

patovm04 commented 2 years ago

Nice! I just tried it and works like a charm :) Thanks for fixing this so quickly! I guess this bug can be closed now :)

pgj commented 2 years ago

Fixed in 15245e8eae1364d9f2ea41e23ef0b1f392dcd8cf .