VirtualHere client dies with `Too many writes to wake-up pipe?`

Submitted by grank on #1

I'm running Ubuntu 18.04.1 in a Hyper-V vm, on which I've installed Hass.io, and I'm using VirtualHere so that this guest vm can use the zigbee+z-wave USB stick that is plugged into its Windows 10 host machine. (This seems like a fairly common use case for usbip packages like VirtualHere.) This is a new setup for me, I'm only a few days in. It works for a while, but at some point when I'm not using it or looking at it, it stops responding and won't recover until I restart the VM. Sometimes it's like eight hours of uptime before it dies, sometimes it's only like half an hour, but I always see a reason:timeout in the VirtualHere USB Server event log on the host. Here's an example:


2019-12-16 12:34:24 PM - 192.168.0.138 connected as connection 11
2019-12-16 12:34:25 PM - Device 8 [10c4:8a2a] BOUND to connection 11
     
2019-12-16 1:31:46 PM - Device 8 [10c4:8a2a] UNBOUND from connection 11
2019-12-16 1:31:46 PM - Connection 11 successfully removed (reason:timeout)

I was able to correlate this example with /var/log/syslog on the client VM (timestamps here are in UTC instead of my GMT-7, sorry):

Dec 16 19:34:23 hossubuntu systemd[1]: Starting LSB: Start VirtualHere USB Sharing on startup...
Dec 16 19:34:23 hossubuntu systemd[1]: Started LSB: Start VirtualHere USB Sharing on startup.
Dec 16 19:34:23 hossubuntu VirtualHere Client: VirtualHere Client 4.9.5 starting (Compiled: Dec 3 2019 11:13:49)
Dec 16 19:34:23 hossubuntu VirtualHere Client: Client OS is Linux 4.15.0-72-generic x86_64
Dec 16 19:34:23 hossubuntu VirtualHere Client: Using config at /root/.vhui
Dec 16 19:34:24 hossubuntu VirtualHere Client: IPC available at /tmp/vhclient
Dec 16 19:34:24 hossubuntu VirtualHere Client: VirtualHere Client is running as a service
Dec 16 19:34:24 hossubuntu VirtualHere Client: Auto-find using Bonjour - on
Dec 16 19:34:24 hossubuntu VirtualHere Client: Auto-find using Bonjour SSL - on
     
[nothing relevant happens for a while. Actually no syslog entries at all for 14 minutes, before this:]
     
Dec 16 20:31:25 hossubuntu VirtualHere Client: assert:../src/unix/wakeuppipe.cpp,102,OnReadWaiting,size == 1,Too many writes to wake-up pipe?
Dec 16 20:31:25 hossubuntu VirtualHere message repeated 686 times: [ Client: assert:../src/unix/wakeuppipe.cpp,102,OnReadWaiting,size == 1,Too many writes to wake-up pipe?]

When the client is in this state, I can't even call the help command at the prompt:

$ vhclientx86_64 -t "HELP"
IPC client timeout waiting for server...

At this point, if I just restart the vhui service, it looks like it's reconnected and working, both from -t "LIST" and in the event log on the server...
but not only will Home Assistant not recover automatically, but it won't recover even if I restart it, because the interfaces are no longer on ttyUSB0 and ttyUSB1, but now on ttyUSB1 and ttyUSB2 instead:

Dec 17 18:36:22 hossubuntu systemd[1]: Stopping LSB: Start VirtualHere USB Sharing on startup...
Dec 17 18:36:26 hossubuntu kernel: [82928.239154] vhci_hcd: connection closed
Dec 17 18:36:26 hossubuntu kernel: [82928.239185] vhci_hcd: stop threads
Dec 17 18:36:26 hossubuntu kernel: [82928.239187] vhci_hcd: release socket
Dec 17 18:36:26 hossubuntu kernel: [82928.239190] vhci_hcd: disconnect device
Dec 17 18:36:26 hossubuntu kernel: [82928.239236] usb 1-1: USB disconnect, device number 2
Dec 17 18:36:26 hossubuntu kernel: [82928.239290] cp210x ttyUSB0: failed set request 0x7 status: -19
Dec 17 18:36:26 hossubuntu kernel: [82928.239924] cp210x ttyUSB0: failed set request 0x12 status: -19
Dec 17 18:36:26 hossubuntu kernel: [82928.244016] cp210x ttyUSB0: failed set request 0x0 status: -19
Dec 17 18:36:26 hossubuntu kernel: [82928.244612] cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
Dec 17 18:36:26 hossubuntu kernel: [82928.244706] cp210x 1-1:1.0: device disconnected
Dec 17 18:36:26 hossubuntu kernel: [82928.244762] cp210x ttyUSB1: failed set request 0x7 status: -19
Dec 17 18:36:26 hossubuntu kernel: [82928.245314] cp210x ttyUSB1: failed set request 0x12 status: -19
Dec 17 18:36:26 hossubuntu kernel: [82928.245871] cp210x ttyUSB1: failed set request 0x0 status: -19
Dec 17 18:36:26 hossubuntu kernel: [82928.248062] cp210x ttyUSB1: cp210x converter now disconnected from ttyUSB1
Dec 17 18:36:26 hossubuntu kernel: [82928.248112] cp210x 1-1:1.1: device disconnected
Dec 17 18:36:26 hossubuntu systemd[1]: Stopped LSB: Start VirtualHere USB Sharing on startup.
Dec 17 18:36:26 hossubuntu systemd[1]: Starting LSB: Start VirtualHere USB Sharing on startup...
Dec 17 18:36:27 hossubuntu systemd[1]: Started LSB: Start VirtualHere USB Sharing on startup.
Dec 17 18:36:27 hossubuntu VirtualHere Client: VirtualHere Client 4.9.5 starting (Compiled: Dec 3 2019 11:13:49)
Dec 17 18:36:27 hossubuntu VirtualHere Client: Client OS is Linux 4.15.0-72-generic x86_64
Dec 17 18:36:27 hossubuntu VirtualHere Client: Using config at /root/.vhui
Dec 17 18:36:27 hossubuntu VirtualHere Client: IPC available at /tmp/vhclient
Dec 17 18:36:27 hossubuntu VirtualHere Client: VirtualHere Client is running as a service
Dec 17 18:36:27 hossubuntu VirtualHere Client: Auto-find using Bonjour - on
Dec 17 18:36:27 hossubuntu VirtualHere Client: Auto-find using Bonjour SSL - on
Dec 17 18:36:29 hossubuntu kernel: [82930.623689] vhci_hcd vhci_hcd.0: pdev(0) rhport(0) sockfd(4)
Dec 17 18:36:29 hossubuntu kernel: [82930.623692] vhci_hcd vhci_hcd.0: devid(4) speed(2) speed_str(full-speed)
Dec 17 18:36:29 hossubuntu kernel: [82930.804020] vhci_hcd: vhci_device speed not set
Dec 17 18:36:29 hossubuntu kernel: [82930.864020] usb 1-1: new full-speed USB device number 3 using vhci_hcd
Dec 17 18:36:29 hossubuntu kernel: [82930.932021] vhci_hcd: vhci_device speed not set
Dec 17 18:36:29 hossubuntu kernel: [82930.992027] usb 1-1: SetAddress Request (3) to port 0
Dec 17 18:36:29 hossubuntu kernel: [82931.100070] usb 1-1: New USB device found, idVendor=10c4, idProduct=8a2a
Dec 17 18:36:29 hossubuntu kernel: [82931.100073] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=5
Dec 17 18:36:29 hossubuntu kernel: [82931.100074] usb 1-1: Product: HubZ Smart Home Controller
Dec 17 18:36:29 hossubuntu kernel: [82931.100075] usb 1-1: Manufacturer: Silicon Labs
Dec 17 18:36:29 hossubuntu kernel: [82931.100076] usb 1-1: SerialNumber: 51300E3E
Dec 17 18:36:29 hossubuntu kernel: [82931.106121] cp210x 1-1:1.0: cp210x converter detected
Dec 17 18:36:29 hossubuntu kernel: [82931.111988] usb 1-1: cp210x converter now attached to ttyUSB1
Dec 17 18:36:29 hossubuntu kernel: [82931.113206] cp210x 1-1:1.1: cp210x converter detected
Dec 17 18:36:29 hossubuntu kernel: [82931.119179] usb 1-1: cp210x converter now attached to ttyUSB2

So in order to get it up and running again have to restart the VM entirely.

Anyway, yeah. I don't know why it eventually goes Too many writes to wake-up pipe? and dies, is the main point.
I've ensured that USB selected suspend is turned off in the host power options, just in case... Not sure what else to do.
(I found this thread, but it doesn't contain a solution, it just suggests that v4.2.6 of the client would have solved it... I'm using v4.9.5.)

Any suggestions?

Submitted by grank on Wed, 2019/12/18 - 07:03

#2

Update:
So that I don't lose control of my lights while this is unresolved, for now I'm working around it by automatically rebooting the VM whenever that "Too many writes to wake-up pipe" message appears in the syslog.
(I'm not sure yet if this will be a viable workaround or not, as I just finished setting it up and I had to restart the server service on the host because it was happening immediately on reboot, but we'll see.)
 
The files I added to accomplish this on Ubuntu are below, in case anyone needs them, as it took me a while to figure it out.

/etc/rsyslog.d/rebootifwakeuppipe.conf:

module(load="omprog") # allows log messages to be fed to a script
 
*.* action(type="omprog" binary="/etc/rebootifwakeuppipe.sh" template="RSYSLOG_TraditionalFileFormat")

 
 
/etc/rebootifwakeuppipe.sh:

#!/bin/bash
while read LINE; do
  if [[ $LINE == *"Too many writes to wake-up pipe"* ]]; then
    logger -s "VirtualHere may have crashed; attempting to restart this machine..."
    sudo shutdown -r now
  fi
done

 
 
/etc/sudoers.d/shutdown:

## allows the syslog user to restart the system without needing a sudo password
syslog ALL=NOPASSWD: /sbin/shutdown, /sbin/reboot

Submitted by Michael on Thu, 2019/12/19 - 09:02

#3

I havent heard of this one for a few years, as it was resolved back then. I'll attempt to investigate this early in the new year...

Submitted by grank on Fri, 2019/12/20 - 02:32

#4

Thanks, I appreciate it. The auto-reset strategy above seems to be keeping it stable enough in the meantime (the only annoying thing about it is when I'm working on something in node-RED and then it restarts and I lose my changes, heh)

Submitted by caseyboardman on Sat, 2020/02/08 - 05:51

#5

Bump - any updates on this? We've seen it too every so often, still trying to isolate cause. Also using 4.9.5.

Interestingly, when we get to this state, running `service vhclient status` still looks like the service is active and running OK, even though it isn't.

If I find something I'll post back; let me know if there's anything in particular to look for?

Submitted by Michael on Mon, 2020/02/10 - 17:49

#6

Im investigating this - this week, so hopefully i find something...

Submitted by caseyboardman on Tue, 2020/02/11 - 04:21

#7

<p>I caught it again.
</p>
<p>Timeline highlights<br />
• 05:10:56 - brand new host<br />
• 06:04:03.527 - MANUAL HUB REMOVE ALL -> OK<br />
• 08:55:25.558 - HELP -> Timed out, null results
</p>
<p>1. service vhclient status<br />
● vhclient.service - LSB: Start VirtualHere USB Sharing on startup<br />
Loaded: loaded (/etc/init.d/vhclient; generated; vendor preset: enabled)<br />
Active: active (running) since Mon 2020-02-10 05:12:04 EST; 5h 52min ago<br />
Docs: man:systemd-sysv-generator(8)<br />
Process: 921 ExecStart=/etc/init.d/vhclient start (code=exited, status=0/SUCCESS)<br />
Tasks: 7 (limit: 4915)<br />
Memory: 14.5M<br />
CPU: 10.945s<br />
CGroup: /system.slice/vhclient.service<br />
└─1092 /usr/sbin/vhclientx86_64 -n
</p>
<p>2. /usr/sbin/vhclientx86_64 -t "HELP"<br />
IPC client timeout waiting for server...
</p>
<p>3. echo $?<br />
2
</p>
<p>4. uname --all<br />
Linux myhostname 4.9.0-4-amd64 #1 SMP Debian 4.9.65-3tmwu1 (2018-07-12) x86_64 GNU/Linux
</p>
<p>Highlights from the syslog<br />
1. Feb 10 06:04:03 myhostname kernel: [ 3154.149133] vhci_hcd: disconnect device<br />
* last time we see vhci_hcd<br />
* last time we see kernel<br />
2. Feb 10 06:04:03 myhostname VirtualHere Client: Connection 24 remotely disconnected gracefully (rx)<br />
3. Feb 10 08:33:23 myhostname VirtualHere Client: assert:../src/unix/wakeuppipe.cpp,102,OnReadWaiting,size == 1,Too many writes to wake-up pipe?
</p>
<p>I'll email full syslog, maybe it will offer some clues.
</p>

Submitted by Michael on Tue, 2020/02/11 - 07:52

#8

Thanks Casey, what makes this more complicated than usual is that the bug seems to be in a library i use rather than in my code so i need to figure out what that part of the library is doing to debug it

Submitted by Michael on Fri, 2020/02/14 - 23:15

#9

This should now be resolved in 4.9.8 of the client

Submitted by apchandr on Wed, 2020/04/29 - 01:47

#10

In follow-up to issue reported by Casey. We are seeing "Too many writes to wake-up pipe" message in syslog even after upgrading VirtualHere client to version 4.9.8. Can you please help us to resolve this issue?

Submitted by Michael on Mon, 2020/05/04 - 20:05

#11

Can you update to 5.0.2 and also make sure you are updating the daemon binary file. /usr/sbin/vhclientx86_64