Volumio Debian Buster Beta - Raspi images debugging

@Damur I don’t see anything strange in your logs w.t.r the WiFi.
Can you confirm if this is with a pi0W or just pi0?

I also added a new image that should fix all the hotspot issues. It will still how ever need you to connect via SSH to get the right nodejs version for armv6 as before (but please change NODE_VERSION=12 to NODE_VERSION=14 when you run it).

Do let me know, I will try in the meantime to get a pi0 to test my self…

I have both a RPi0 and a RPi0W, but the test I’m performing right now are done with RPi0 (no wifi and bt).

I’ll try the new image and let you know

I’ve flashed latest image 3.007 and did some further test on RPi0, same setup.

I’ve enabled SSH and run the script for nodejs fix, selecting v14 as recommended.

After reboot UI was up and running. I connected WiFi to my home network, after reboot I had same issue I had before, WiFi does not connect automatically.

I hooked up the RPi0 to the serial terminal to have a look to debug messages during bootup, this one hit my attention:

[  OK  ] Started RPC bind portmap service.
[  OK  ] Started Save/Restore Sound Card State.
[b][FAILED] Failed to start Wireless Services.
See 'systemctl status wireless.service' for details.[/b]
[  OK  ] Started Volumio Backend Module.
[  OK  ] Reached target Sound Card.
[  OK  ] Reached target Remote File Systems (Pre).

This is the outcome of “systemctl status wireless.service”:

● wireless.service - Wireless Services
   Loaded: loaded (/lib/systemd/system/wireless.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Mon 2020-05-18 18:48:08 UTC; 1h 10min ago
  Process: 274 ExecStartPre=/sbin/iw dev wlan0 set power_save off (code=exited, status=161)

May 18 18:48:07 volumio-rpi0 systemd[1]: Starting Wireless Services...
May 18 18:48:08 volumio-rpi0 iw[274]: command failed: Operation not supported (-95)
May 18 18:48:08 volumio-rpi0 systemd[1]: wireless.service: Control process exited, code=exited, status=161/n/a
May 18 18:48:08 volumio-rpi0 systemd[1]: wireless.service: Failed with result 'exit-code'.
May 18 18:48:08 volumio-rpi0 systemd[1]: Failed to start Wireless Services.

I think this is the root cause of WiFi not connecting. If I restart the service the connection becomes active.

● wireless.service - Wireless Services
   Loaded: loaded (/lib/systemd/system/wireless.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2020-05-18 19:59:56 UTC; 8min ago
  Process: 1367 ExecStartPre=/sbin/iw dev wlan0 set power_save off (code=exited, status=0/SUCCESS)
  Process: 1368 ExecStart=/volumio/app/plugins/system_controller/network/wireless.js start (code=exited, status=0/SUCCESS)
 Main PID: 1426 (wpa_supplicant)
   Memory: 2.8M
   CGroup: /system.slice/wireless.service
           └─1426 wpa_supplicant -s -B -Dnl80211,wext -c/etc/wpa_supplicant/wpa_supplicant.conf -iwlan0

May 18 19:59:56 volumio-rpi0 wireless.js[1368]: Connected to: ----Boris
May 18 19:59:56 volumio-rpi0 wireless.js[1368]: ----
May 18 19:59:56 volumio-rpi0 wireless.js[1368]: ... joined AP, wlan0 IPv4 is 192.168.1.42, ipV6 is undefined
May 18 19:59:56 volumio-rpi0 wireless.js[1368]: It's done! AP
May 18 19:59:56 volumio-rpi0 sudo[1591]:     root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
May 18 19:59:56 volumio-rpi0 sudo[1591]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 18 19:59:56 volumio-rpi0 sudo[1591]: pam_unix(sudo:session): session closed for user root
May 18 19:59:56 volumio-rpi0 wireless.js[1368]: ... joined AP, wlan0 IPv4 is 192.168.1.42, ipV6 is undefined
May 18 19:59:56 volumio-rpi0 wireless.js[1368]: It's done! AP
May 18 19:59:56 volumio-rpi0 systemd[1]: Started Wireless Services.

As a workaround I’ve added “sudo systemctl status wireless.service” at the enf of /etc/rc.local and I can use RPi0 with laters Volumio 3.007 without serial or ethernet. Please let me know if you need further testing.

Hmm, I am not completely sure what is going on here with the mt7601u dongle.

If it was only this, I would reckon that the power_save feature in the kernel driver for mt7601u might not be enabled or have some issues…

  Process: 274 ExecStartPre=/sbin/iw dev wlan0 set power_save off (code=exited, status=161)
command failed: Operation not supported (-95)

But, it seems starting the service is later successful when you run it manually/later via rc.local?
So I am guessing some driver initialisation is not complete when wireless.service is first run. Not sure though?

May 17 15:04:03 volumio-rpi0 systemd[1]: Starting Disk Manager...
May 17 15:04:03 volumio-rpi0 systemd[1]: Starting Bluetooth service...
May 17 15:04:03 volumio-rpi0 systemd[1]: wireless.service: Control process exited, code=exited, status=161/n/a
May 17 15:04:03 volumio-rpi0 systemd[1]: wireless.service: Failed with result 'exit-code'.
May 17 15:04:03 volumio-rpi0 systemd[1]: Failed to start Wireless Services.
May 17 15:04:03 volumio-rpi0 systemd[1]: Started Save/Restore Sound Card State.
May 17 15:04:03 volumio-rpi0 systemd[1]: Reached target Sound Card.
May 17 15:04:04 volumio-rpi0 systemd[1]: Started Volumio Backend Module.
May 17 15:04:05 volumio-rpi0 avahi-daemon[279]: Found user 'avahi' (UID 111) and group 'avahi' (GID 113).
May 17 15:04:05 volumio-rpi0 avahi-daemon[279]: Successfully dropped root privileges.
May 17 15:04:05 volumio-rpi0 avahi-daemon[279]: avahi-daemon 0.7 starting up.
May 17 15:04:06 volumio-rpi0 systemd-logind[281]: New seat seat0.
May 17 15:04:06 volumio-rpi0 sudo[258]:  volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start ssh
May 17 15:04:06 volumio-rpi0 sudo[274]:     root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cset -y 1 0x6c 0x00 0x2000 w
May 17 15:04:06 volumio-rpi0 dhcpcd[272]: no interfaces have a carrier
May 17 15:04:06 volumio-rpi0 dhcpcd[272]: no interfaces have a carrier
May 17 15:04:06 volumio-rpi0 dhcpcd[320]: eth0: waiting for carrier
May 17 15:04:06 volumio-rpi0 dhcpcd[272]: forked to background, child pid 320
May 17 15:04:06 volumio-rpi0 dhcpcd[272]: forked to background, child pid 320
May 17 15:04:06 volumio-rpi0 dhcpcd[320]: wlan0: waiting for carrier
May 17 15:04:06 volumio-rpi0 dhcpcd[320]: wlan0: carrier acquired
May 17 15:04:06 volumio-rpi0 kernel: asix 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC1E1

Probably have to look into the WantedBy and ensure that sys-subsystem-net-devices-wlan0.device is up before we call the powersave. This doesn’t seem to manifest in the onboard wifi, as it’s probably initiated earlier, than the usb based WiFi.

But these are just guesse in the dark here, so lets confirm that it’s power_save is working fine first:

sudo iw dev wlan0 get power_save
sudo iw --debug dev wlan0 set power_save on
sudo iw --debug dev wlan0 set power_save off

Either way, I think moving this power save command from ExecStartPre to ExecStartPost would be smart first step.
Could you confirm if that works for you already on a reboot? (after removing the systemctl start wireless in rc.local)

sudo sed -i s/ExecStartPre/ExecStartPost/ /lib/systemd/system/wireless.service

Thanks for all the testing! :slight_smile:

Here the required test:

volumio@volumio-rpi0:~$ sudo iw dev wlan0 get power_save
Power save: off
volumio@volumio-rpi0:~$ sudo iw --debug dev wlan0 set power_save on
-- Debug: Sent Message:
--------------------------   BEGIN NETLINK MESSAGE ---------------------------
  [NETLINK HEADER] 16 octets
    .nlmsg_len = 36
    .type = 23 <0x17>
    .flags = 5 <REQUEST,ACK>
    .seq = 1589903690
    .port = 364905748
  [GENERIC NETLINK HEADER] 4 octets
    .cmd = 61
    .version = 0
    .unused = 0
  [PAYLOAD] 16 octets
    08 00 03 00 02 00 00 00 08 00 5d 00 01 00 00 00 ..........].....
---------------------------  END NETLINK MESSAGE   ---------------------------
-- Debug: Received Message:
--------------------------   BEGIN NETLINK MESSAGE ---------------------------
  [NETLINK HEADER] 16 octets
    .nlmsg_len = 56
    .type = 2 <ERROR>
    .flags = 0 <>
    .seq = 1589903690
    .port = 364905748
  [ERRORMSG] 20 octets
    .error = -95 "Operation not supported"
  [ORIGINAL MESSAGE] 16 octets
    .nlmsg_len = 16
    .type = 23 <0x17>
    .flags = 5 <REQUEST,ACK>
    .seq = 1589903690
    .port = 364905748
---------------------------  END NETLINK MESSAGE   ---------------------------
command failed: Operation not supported (-95)
volumio@volumio-rpi0:~$ sudo iw --debug dev wlan0 set power_save off
-- Debug: Sent Message:
--------------------------   BEGIN NETLINK MESSAGE ---------------------------
  [NETLINK HEADER] 16 octets
    .nlmsg_len = 36
    .type = 23 <0x17>
    .flags = 5 <REQUEST,ACK>
    .seq = 1589903751
    .port = -595589853
  [GENERIC NETLINK HEADER] 4 octets
    .cmd = 61
    .version = 0
    .unused = 0
  [PAYLOAD] 16 octets
    08 00 03 00 02 00 00 00 08 00 5d 00 00 00 00 00 ..........].....
---------------------------  END NETLINK MESSAGE   ---------------------------
-- Debug: Received Message:
--------------------------   BEGIN NETLINK MESSAGE ---------------------------
  [NETLINK HEADER] 16 octets
    .nlmsg_len = 36
    .type = 2 <ERROR>
    .flags = 256 <ROOT>
    .seq = 1589903751
    .port = -595589853
  [ERRORMSG] 20 octets
    .error = 0 "Success"
  [ORIGINAL MESSAGE] 16 octets
    .nlmsg_len = 16
    .type = 23 <0x17>
    .flags = 5 <REQUEST,ACK>
    .seq = 1589903751
    .port = -595589853
---------------------------  END NETLINK MESSAGE   ---------------------------

It looks like enabling power_safe is not supported, the command for disabling power_safe does not give any error.

I also tried the last part, to execute the call for disabling power_safe at the end

volumio@volumio-rpi0:~$ cat /lib/systemd/system/wireless.service
[Unit]
Description=Wireless Services
Before=volumio.service

[Service]
Type=forking
ExecStartPost=/sbin/iw dev wlan0 set power_save off
ExecStart=/volumio/app/plugins/system_controller/network/wireless.js start
KillMode=mixed

The trick works, the error is gone and WiFi connects automatically after reboot. Your assumption was correct, nice that you found the root-cause because this dongle is a very popular one.

Something else to report: I noticed some weird behavior with volume control (sw mixer).
Setting of a predefined value on boot does not work (I always have 51%), if I start or stop the playback the value goes back to 51%.

Nice, glad it works! Will add it into the next build. :slight_smile:

That doesn’t seem right, can you capture logs journalctl -f when you try and change volume?

I’m performing some more testing to understand where the issue is.

Right after reboot, volume shown in the GUI is 30, latest value I did set before reboot.

I start the playback of one webradio, then I change volume to 38.

May 20 16:35:18 volumio-rpi0 volumio[996]: info: STATE SERVICE {"status":"play","position":0,"seek":1183,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Subsonica - Colpo di pistola","artist":"Radio Libera Tutti","album":null,"uri":"http://185.242.180.227:8000/mp3","trackType":""}
May 20 16:35:18 volumio-rpi0 volumio[996]: info: CURRENT POSITION 0
May 20 16:35:18 volumio-rpi0 volumio[996]: info: CoreStateMachine::syncState   stateService play
May 20 16:35:18 volumio-rpi0 volumio[996]: info: CoreStateMachine::syncState   currentStatus play
May 20 16:35:18 volumio-rpi0 volumio[996]: info: Received an update from plugin. extracting info from payload
May 20 16:35:18 volumio-rpi0 volumio[996]: info: CoreStateMachine::pushState
May 20 16:35:18 volumio-rpi0 volumio[996]: info: CoreStateMachine::getState
May 20 16:35:18 volumio-rpi0 volumio[996]: info: CoreCommandRouter::volumioPushState
May 20 16:35:18 volumio-rpi0 volumio[996]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 20 16:35:18 volumio-rpi0 volumio[996]: info: CoreStateMachine::pushState
May 20 16:35:18 volumio-rpi0 volumio[996]: info: CoreStateMachine::getState
May 20 16:35:18 volumio-rpi0 volumio[996]: info: CoreCommandRouter::volumioPushState
May 20 16:35:18 volumio-rpi0 volumio[996]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 20 16:35:18 volumio-rpi0 volumio[996]: info: ------------------------------ 613ms
May 20 16:35:19 volumio-rpi0 volumio[996]: info: ------------------------------ 613ms
May 20 16:35:19 volumio-rpi0 volumio[996]: info: VolumeController::SetAlsaVolume37

Latest message shows volume changed, but to a different value. After a short moment the value shown in the UI goes back to 30, but no further messages in journalctl.

After that, I changed the volume to 20, this time the selected value is maintained in the UI

After that, I stop the playback of the webradio. Volume on UI goes back to 30

After another reboot, volume shown in the UI is 20. This makes me think of a visual issue on the UI, because what I see in the log looks correct and the selected value is saved before reboot.

It is a visual issue, the volume is changing as you click or move the bar but for some reason the UI is always falling back to the initial value.

Yes, it this a known issue?

Is this what your describing?
github.com/volumio/Volumio2/issues/1972

Yes that’s it

I also have this issue, but I have problems with other volume controls too

@ashthespy: Awesome, I justed tested your version 0.008 successfully on a Pi3.
However, for a more clear structured configuration I would like to move the hotspot specific dnsmasq config lines into a separated file. Intead of adding those lines onto the /etc/dnsmasq.conf file put it into /etc/dnsmasq.d/hotspot.conf

# Only listen on wifi interface
interface=wlan0
# Always return 192.168.211.1 for any query not answered from /etc/hosts or DHCP and not sent to an upstream nameserver
address=/#/192.168.211.1
# DHCP server not active on wired lan interface
no-dhcp-interface=eth0
# IPv4 address range, netmask and lease time
dhcp-range=192.168.211.100,192.168.211.200,255.255.255.0,24h
# DNS server
dhcp-option=option:dns-server,192.168.211.1
expand-hosts
domain=local
# Facility to which dnsmasq will send syslog entries
log-facility=local7

Futher, I noticed there are some upgrades for packages like dhcpcd5, dnsmasq, openssl etc. available in the official raspbian repos. Do you integrate these into a new version or what is your policy to handle that? By doing it manually I also noticed that package upgrades like libavcodec58 require the raspberrypi-bootloader package which is kept back by apt preferences in /etc/apt/preferences.d/raspberrypi-kernel.

Thanks for all your effort. :slight_smile:

FWIW, for everybody who is going to use Kodi Leia on the Volumio Buster image instead of the integrated Kodi Kryton plugin which is still linked by default, these lines might be helpful to install the Kodi Leia plugin manually.

volumio@volumio:~$ mkdir -p /data/plugins/miscellanea/kodi
volumio@volumio:~$ git clone -b Buster https://github.com/Saiyato/volumio-kodi-plugin /data/plugins/miscellanea/kodi/
chmod 755 /data/plugins/miscellanea/kodi/*.sh
sudo /data/plugins/miscellanea/kodi/install.sh

Hm, I thought I was already doing that, the commit must have slipped through during the build. Will check, thanks!

Right now, as everything is picked up from buster repos, you should be able to safely just un-pin the kernel and upgrade… It gets tricky only when we use the custom volumio build mpd and friends. I will look into why the latest packages weren’t picked up automatically, it could be that my image was using an old multistrap rootfs…

Again, thanks for testing - please do report if you face some funny issues - the new version uses armv6l based unofficial nodejs binaries, to preserve compatibility with older pis.
It would be prudent to make some images with armv7 binaries to do some real world A/B checks for performance. If someone is interested in testing, let me know, will make the images/scripts…

I’m testing the latest image on the old setup (RPi0 + WiFi dongle)

I can see the dongle is recognized properly and hotspot is created, but I can’t find the network, it does not appear searching with PC, smartphone and tablet.

I’ll try to use a different WiFi dongle and test again

volumio@volumio:~$ ifconfig
lo: flags=73<UP,LOOPBACK,RUNNING>  mtu 65536
        inet 127.0.0.1  netmask 255.0.0.0
        loop  txqueuelen 1000  (Local Loopback)
        RX packets 520  bytes 44646 (43.5 KiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 520  bytes 44646 (43.5 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

wlan0: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        inet 192.168.211.1  netmask 255.255.255.0  broadcast 192.168.211.255
        ether cc:79:cf:5b:e4:e3  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 1  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

volumio@volumio:~$

I did some more testing, I moved the SD-card from RPi0 with WiFi dongle to RPi0W and Hotspot was accessible. After connecting to my WiFi network, I put back the SD-card on RPi0 with WiFi dongle and it’s working fine.

It looks like the WiFi dongle has some problems in creating a hotspot, unfortunately the other dongle I have is not supported out-of-the-box by kernel 4.19

  • glitch on changing volume is still there.
  • Spotify, web radio and playback from NAS are OK.
  • GPIO plugins still not working

Is there something more I should test?

I can confirm mt7601u driver included in the kernel does not support AP mode, some modified drivers are available but nothing official for supporting that feature.

We pick up the firmware for this dongle from thefirmware-ralink package. If it’s not fixed/supported in the buster repo, not much we can do, sorry!

You reported more than just the the visual volume glitch correct? Does your mixer work directly with alsamixer? Cause then it’s a Volumio (backend/frontend) issue, and I will take a look there. I am assuming that the volume control works fine with a regular volumio build?

As for the GPIO plugins, the authors need to rebuild node modules, or you’ll can build the node modules for it yourself… You will need to install build-essential, and then head to the plugin’s dir (/data/plugins/... and run npm install

No problem, the goal was to verify if the issue was related to the build or to my crappy dongle.

I described the test I did in the post from Wed May 20 2020 17:47.
Volume control with speaker icons has problems with latest Volumio 2.773 too, but using the circle control works fine with that version.

I’ll try that