vhclient sporadic segfault

Submitted by apchandr on #1

Hello,

I recently updated VirtualHere client to version 4.8.8 from version 4.2.6 and i see the sporadic segfault in Linux and I am able to reproduce this issue using the script below. The same issue occurs in VirtualHere client version 4.9.1 also. Any help will be greatly appreciated.

Segfault:
$ tail /var/log/syslog
...
Nov 1 14:52:53 Host1 VirtualHere Client: Connection 158 remotely disconnected gracefully (rx)
Nov 1 14:52:53 Host1 VirtualHere Client: Connection 159 remotely disconnected gracefully (rx)
Nov 1 14:52:53 Host1 kernel: [1464574.769249] vhclientx86_64[77049]: segfault at 61 ip 0000000000688c32 sp 00007ffc04b71e40 error 4
...

$ /usr/sbin/vhclientx86_64 -t "LIST"
No response from IPC server

Debian Kernel version: Debian 4.9.110-3+deb9u6

################

#!/bin/bash

# tail the response in another window like tail -f /tmp/vhclient_response
set -o noclobber
set -o notify

communicate () {
echo "$1 at `date`"

# sleep 1
sudo service vhclient status | grep "active (exited)"
if [ $? -eq 0 ]
then
echo "Ok, found an error"
exit 1
fi

echo "$1" > /tmp/vhclient
}

echo "LOOP BEGIN"
sudo service vhclient status
COUNT=0

while [ $COUNT -lt 100 ]; do

echo
echo "Session test $COUNT begin at `date`"

communicate "HELP"

communicate "MANUAL HUB ADD,SERVER1"

sleep 1

communicate "MANUAL HUB ADD,SERVER2"

sleep 1

communicate "LIST"

sleep 4

communicate "USE,DEVICE1.ADDRESS"

sleep 4

communicate "LIST"

communicate "STOP USING,DEVICE1.ADDRESS"

sleep 1

communicate "LIST"

sleep 4

communicate "MANUAL HUB REMOVE ALL"

sleep 1

communicate "LIST"

echo "Session test $COUNT end at `date`"

let COUNT=COUNT+1
done

################

Thanks,
Arun

Submitted by Michael on Tue, 2019/11/05 - 11:10

#2

Seems ok for me, im using Linux debian9test 4.9.0-11-amd64 #1 SMP Debian 4.9.189-3+deb9u1 (2019-09-20) x86_64 GNU/Linux just downloaded from debian

I let it run up to loop 32 (connecting to iLok device on a virtualhere server) , perhaps you might need to update the debian kernel there could be a bug somewhere there. What sort of usb device are you using?

Submitted by apchandr on Wed, 2019/11/06 - 01:15

#3

Hi Michael,
I am using boards like Arduino Uno, Arduino Mega, etc.,. I see this issue usually occur after "MANUAL HUB REMOVE ALL". Can you please run up to loop 80 - 90 when testing the device.

###############################

Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: assert:../include/wx/vector.h,480,at,idx < m_size,
Nov 5 09:46:42 Host1 VirtualHere Client: Connection 34 remotely disconnected gracefully (rx)
Nov 5 09:46:42 Host1 VirtualHere Client: Connection 33 remotely disconnected gracefully (rx)
Nov 5 09:46:49 Host1 kernel: [ 663.472999] vhci_hcd vhci_hcd: pdev(0) rhport(0) sockfd(10)
Nov 5 09:46:49 Host1 kernel: [ 663.473003] vhci_hcd vhci_hcd: devid(4) speed(2) speed_str(full-speed)
Nov 5 09:46:49 Host1 kernel: [ 663.700699] usb 2-1: new full-speed USB device number 19 using vhci_hcd
Nov 5 09:46:49 Host1 kernel: [ 663.820732] usb 2-1: SetAddress Request (19) to port 0
Nov 5 09:46:49 Host1 kernel: [ 663.853687] usb 2-1: New USB device found, idVendor=2341, idProduct=0043
Nov 5 09:46:49 Host1 kernel: [ 663.853691] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=220
Nov 5 09:46:49 Host1 kernel: [ 663.853693] usb 2-1: Manufacturer: Arduino (www.arduino.cc)
Nov 5 09:46:49 Host1 kernel: [ 663.853694] usb 2-1: SerialNumber:
Nov 5 09:46:49 Host1 kernel: [ 663.854932] cdc_acm 2-1:1.0: ttyACM0: USB ACM device
Nov 5 09:46:49 Host1 mtp-probe: checking bus 2, device 19: "/sys/devices/platform/vhci_hcd/usb2/2-1"
Nov 5 09:46:49 Host1 mtp-probe: bus: 2, device: 19 was not an MTP device
Nov 5 09:46:50 Host1 dbus[842]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service'
Nov 5 09:46:50 Host1 dbus[842]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service not found.
Nov 5 09:46:51 Host1 dbus[842]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service'
Nov 5 09:46:51 Host1 dbus[842]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service not found.
Nov 5 09:46:53 Host1 kernel: [ 667.350619] vhci_hcd: connection closed
Nov 5 09:46:53 Host1 kernel: [ 667.350662] vhci_hcd: stop threads
Nov 5 09:46:53 Host1 kernel: [ 667.350665] vhci_hcd: release socket
Nov 5 09:46:53 Host1 kernel: [ 667.350669] vhci_hcd: disconnect device
Nov 5 09:46:53 Host1 kernel: [ 667.350698] usb 2-1: USB disconnect, device number 19
Nov 5 09:46:54 Host1 dbus[842]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service'
Nov 5 09:46:54 Host1 dbus[842]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service not found.
Nov 5 09:46:55 Host1 dbus[842]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service'
Nov 5 09:46:55 Host1 dbus[842]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service not found.
Nov 5 09:46:58 Host1 VirtualHere Client: Connection 35 remotely disconnected gracefully (rx)
Nov 5 09:46:58 Host1 VirtualHere Client: Connection 36 remotely disconnected gracefully (rx)
Nov 5 09:46:59 Host1 kernel: [ 673.129374] vhclientx86_64[1001]: segfault at 61 ip 00000000006897e8 sp 00007ffcf98bead0 error 4

Submitted by Michael on Wed, 2019/11/06 - 20:50

#4

Could you

1. Update to 4.9.3

2. Tell me if auto-find is ON. You can do ./vhclientx86_64 -t "LIST" and at the bottom of the output it will say if auto-find is on. Could you turn that off if it is on by doing ./vhclient86_64 -t "AUTOFIND" and see if that resolves the issue

Submitted by apchandr on Thu, 2019/11/07 - 08:12

#5

HI Michael,

Thank you for looking at this issue. I updated to 4.9.3 and turned off "AUTOFIND" as you mentioned. I am still seeing the segfault. Also I tried using other devices like USB flash drive and seeing the same result. Any help will be greatly appreciated.

...
Nov 6 15:44:17 HOST1 kernel: [16820.198775] vhci_hcd: connection closed
Nov 6 15:44:17 HOST1 kernel: [16820.198801] vhci_hcd: stop threads
Nov 6 15:44:17 HOST1 kernel: [16820.198803] vhci_hcd: release socket
Nov 6 15:44:17 HOST1 kernel: [16820.198807] vhci_hcd: disconnect device
Nov 6 15:44:17 HOST1 kernel: [16820.198833] usb 3-1: USB disconnect, device number 79
Nov 6 15:44:22 HOST1 VirtualHere Client: Connection 42 remotely disconnected gracefully (rx)
Nov 6 15:44:23 HOST1 kernel: [16826.000881] vhclientx86_64[163190]: segfault at 61 ip 0000000000672e2f sp 00007ffda01774b0 error 4
...

###########################
% /usr/sbin/vhclientx86_64 -t "LIST"
VirtualHere Client IPC, below are the available devices:
(Value in brackets = address, * = Auto-Use)

Auto-Find currently on
Auto-Use All currently off
Reverse Lookup currently off
Reverse SSL Lookup currently off
VirtualHere Client is running as a service

% /usr/sbin/vhclientx86_64 -t "AUTOFIND"
OK

% /usr/sbin/vhclientx86_64 -t "LIST"
VirtualHere Client IPC, below are the available devices:
(Value in brackets = address, * = Auto-Use)

Auto-Find currently off
Auto-Use All currently off
Reverse Lookup currently off
Reverse SSL Lookup currently off
VirtualHere Client is running as a service

###############################

Submitted by apchandr on Fri, 2019/11/08 - 03:00

#7

Please find the output of syslog below,

Nov 7 10:03:52 HOST1 VirtualHere Client: Connection 83 remotely disconnected gracefully (rx)
Nov 7 10:04:00 HOST1 kernel: [ 1712.292481] vhci_hcd vhci_hcd: pdev(0) rhport(0) sockfd(9)
Nov 7 10:04:00 HOST1 kernel: [ 1712.292485] vhci_hcd vhci_hcd: devid(4) speed(2) speed_str(full-speed)
Nov 7 10:04:00 HOST1 kernel: [ 1712.522894] usb 3-1: new full-speed USB device number 84 using vhci_hcd
Nov 7 10:04:00 HOST1 kernel: [ 1712.642793] usb 3-1: SetAddress Request (84) to port 0
Nov 7 10:04:00 HOST1 kernel: [ 1712.672308] usb 3-1: New USB device found, idVendor=2341, idProduct=0043
Nov 7 10:04:00 HOST1 kernel: [ 1712.672312] usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=220
Nov 7 10:04:00 HOST1 kernel: [ 1712.672314] usb 3-1: Manufacturer: Arduino (www.arduino.cc)
Nov 7 10:04:00 HOST1 kernel: [ 1712.672316] usb 3-1: SerialNumber:
Nov 7 10:04:00 HOST1 kernel: [ 1712.674039] cdc_acm 3-1:1.0: ttyACM0: USB ACM device
Nov 7 10:04:00 HOST1 mtp-probe: checking bus 3, device 84: "/sys/devices/platform/vhci_hcd/usb3/3-1"
Nov 7 10:04:00 HOST1 mtp-probe: bus: 3, device: 84 was not an MTP device
Nov 7 10:04:01 HOST1 dbus[644]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service'
Nov 7 10:04:01 HOST1 dbus[644]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service not found.
Nov 7 10:04:01 HOST1 CRON[37538]: (root) CMD ( /usr/local/lib/g1004279usagereporting/logger.sh)
Nov 7 10:04:01 HOST1 CRON[37541]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Nov 7 10:04:02 HOST1 dbus[644]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service'
Nov 7 10:04:02 HOST1 dbus[644]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service not found.
Nov 7 10:04:03 HOST1 kernel: [ 1716.200984] vhci_hcd: connection closed
Nov 7 10:04:03 HOST1 kernel: [ 1716.201017] vhci_hcd: stop threads
Nov 7 10:04:03 HOST1 kernel: [ 1716.201020] vhci_hcd: release socket
Nov 7 10:04:03 HOST1 kernel: [ 1716.201025] vhci_hcd: disconnect device
Nov 7 10:04:03 HOST1 kernel: [ 1716.201065] usb 3-1: USB disconnect, device number 84
Nov 7 10:04:04 HOST1 dbus[644]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service'
Nov 7 10:04:04 HOST1 dbus[644]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service not found.
Nov 7 10:04:05 HOST1 dbus[644]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service'
Nov 7 10:04:05 HOST1 dbus[644]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service not found.
Nov 7 10:04:09 HOST1 VirtualHere Client: Connection 84 remotely disconnected gracefully (rx)
Nov 7 10:04:09 HOST1 kernel: [ 1722.010187] vhclientx86_64[1233]: segfault at 1a1 ip 000000000067c87f sp 00007ffdaadf4500 error 4 in vhclientx86_64[400000+847000]

Submitted by Michael on Mon, 2019/11/11 - 20:14

#8

Im away for a week on a business trip but will try to get you a fix this week..

Submitted by Michael on Fri, 2019/11/15 - 02:34

#9

I was wondering if i could login e.g via teamviewer to your machine while you are there, and run the client under gdb as im having trouble seeing the issue at my office. If so email me at mail [at] virtualhere.com (mail[at]virtualhere[dot]com)