Bug 1198335

Summary: no response from server machine after attaching busid
Product: [Fedora] Fedora Reporter: Tomas Lestach <tlestach>
Component: usbipAssignee: Jonathan Dieter <jonathan>
Status: CLOSED WORKSFORME QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 21CC: jonathan, tkasparek
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-08-18 14:25:11 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
captured output form the serial console none

Description Tomas Lestach 2015-03-03 20:12:08 UTC
Description of problem:
RaspberryPi2 should host binded USB port, x86_64 machine should attach and use it. Attach runs fine. After accessing the USB from the client, RPi2 stops responding completely.

Version-Release number of selected component (if applicable):
server:
usbip-3.18-1.fc21.armv7hl
# usbipd -v
usbipd (usbip-utils 2.0)
# uname -a
Linux fidora-minimal-remix 3.18.8-501.20150228git246530f.sc20.armv7hl.bcm2709 #1 SMP PREEMPT Sat Feb 28 09:58:44 GMT 2015 armv7l armv7l armv7l GNU/Linux
# cat /etc/redhat-release 
Fedora release 21 (Twenty One)
using OS image from: http://www.digitaldreamtime.co.uk/images/Fidora/21/20150301/Pi2B-Fedora-Minimal-armhfp-21-5-20150301-1-sda.raw.xz

client:
# rpm -q usbip
usbip-3.18-1.fc21.x86_64
# usbip version
usbip (usbip-utils 2.0)
How reproducible:
always

Steps to Reproduce:
1. server: modprobe usbip-core; modprobe usbip-host; usbipd -d; usbip list -l; usbip bind -b 1-1.5
2. client: modprobe usbip-core; modprobe vhci-hcd; usbip list -r <ip>; usbip attach -r <ip> -b 1-1.5; usbip port

Actual results:
server:
# lsusb
Bus 001 Device 004: ID 04f9:0331 Brother Industries, Ltd 
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp. SMSC9512/9514 Fast Ethernet Adapter
Bus 001 Device 002: ID 0424:9514 Standard Microsystems Corp. SMC9514 Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
# usbip list -l
 - busid 1-1.1 (0424:ec00)
   Standard Microsystems Corp. : SMSC9512/9514 Fast Ethernet Adapter (0424:ec00)

 - busid 1-1.5 (04f9:0331)
   Brother Industries, Ltd : unknown product (04f9:0331)
# usbip bind -b 1-1.5
usbip: info: bind device on busid 1-1.5: complete
#
# usbipd -d
usbipd: info: starting usbipd (usbip-utils 2.0)
usbipd: debug: usbipd.c:377:[listen_all_addrinfo] opening 0.0.0.0:3240
usbip: debug: usbip_network.c:253:[usbip_net_set_v6only] setsockopt: IPV6_V6ONLY
usbipd: info: listening on 0.0.0.0:3240
usbipd: debug: usbipd.c:377:[listen_all_addrinfo] opening :::3240
usbipd: info: listening on :::3240
usbipd: debug: usbipd.c:542:[do_standalone_mode] listening on 2 addresses
usbipd: debug: usbipd.c:573:[do_standalone_mode] heartbeat timeout on ppoll()
usbipd: debug: usbipd.c:573:[do_standalone_mode] heartbeat timeout on ppoll()
usbipd: debug: usbipd.c:573:[do_standalone_mode] heartbeat timeout on ppoll()
usbipd: debug: usbipd.c:573:[do_standalone_mode] heartbeat timeout on ppoll()
usbipd: debug: usbipd.c:573:[do_standalone_mode] heartbeat timeout on ppoll()
usbipd: debug: usbipd.c:568:[do_standalone_mode] read event on fd[0]=3
usbipd: info: connection from 192.168.88.242:45509
usbipd: info: received request: 0x8003(5)
usbipd: info: found requested device: 1-1.5
libusbip: info: connect: 1-1.5
usbipd: debug: usbipd.c:155:[recv_request_import] import request busid 1-1.5: complete
usbipd: info: request 0x8003(5): complete
usbipd: debug: usbipd.c:573:[do_standalone_mode] heartbeat timeout on ppoll()
usbipd: debug: usbipd.c:573:[do_standalone_mode] heartbeat timeout on ppoll()


client:
# modprobe usbip-core
# modprobe vhci-hcd
# usbip list -r 192.168.88.239
Exportable USB devices
======================
 - 192.168.88.239
      1-1.5: Brother Industries, Ltd : unknown product (04f9:0331)
           : /sys/devices/platform/bcm2708_usb/usb1/1-1/1-1.5
           : (Defined at Interface level) (00/00/00)
# usbip list attach -r 192.168.88.239
Exportable USB devices
======================
 - 192.168.88.239
      1-1.5: Brother Industries, Ltd : unknown product (04f9:0331)
           : /sys/devices/platform/bcm2708_usb/usb1/1-1/1-1.5
           : (Defined at Interface level) (00/00/00)
# usbip --debug  attach -r 192.168.88.239 -b 1-1.5
usbip: debug: usbip.c:141:[run_command] running command: `attach'
libusbip: debug: vhci_driver.c:242:[usbip_vhci_driver_open] available ports: 7
libusbip: debug: vhci_driver.c:71:[parse_status] port 0 status 4 speed 0 devid 0
libusbip: debug: vhci_driver.c:72:[parse_status] socket 0 lbusid 0000000000000000
libusbip: debug: vhci_driver.c:71:[parse_status] port 1 status 4 speed 0 devid 0
libusbip: debug: vhci_driver.c:72:[parse_status] socket 0 lbusid 0000000000000000
libusbip: debug: vhci_driver.c:71:[parse_status] port 2 status 4 speed 0 devid 0
libusbip: debug: vhci_driver.c:72:[parse_status] socket 0 lbusid 0000000000000000
libusbip: debug: vhci_driver.c:71:[parse_status] port 3 status 4 speed 0 devid 0
libusbip: debug: vhci_driver.c:72:[parse_status] socket 0 lbusid 0000000000000000
libusbip: debug: vhci_driver.c:71:[parse_status] port 4 status 4 speed 0 devid 0
libusbip: debug: vhci_driver.c:72:[parse_status] socket 0 lbusid 0000000000000000
libusbip: debug: vhci_driver.c:71:[parse_status] port 5 status 4 speed 0 devid 0
libusbip: debug: vhci_driver.c:72:[parse_status] socket 0 lbusid 0000000000000000
libusbip: debug: vhci_driver.c:71:[parse_status] port 6 status 4 speed 0 devid 0
libusbip: debug: vhci_driver.c:72:[parse_status] socket 0 lbusid 0000000000000000
libusbip: debug: vhci_driver.c:71:[parse_status] port 7 status 4 speed 0 devid 0
libusbip: debug: vhci_driver.c:72:[parse_status] socket 0 lbusid 0000000000000000
libusbip: debug: vhci_driver.c:105:[parse_status] exit
libusbip: debug: vhci_driver.c:311:[usbip_vhci_attach_device2] writing: 0 3 65540 3
libusbip: debug: vhci_driver.c:316:[usbip_vhci_attach_device2] attach attribute path: /sys/devices/platform/vhci_hcd/attach
libusbip: debug: vhci_driver.c:324:[usbip_vhci_attach_device2] attached port: 0
# usbip port
Imported USB devices
====================
Port 00: <Port in Use> at High Speed(480Mbps)
       unknown vendor : unknown product (04f9:0331)
       9-1 -> usbip://192.168.88.239:3240/1-1.5
           -> remote bus/dev 001/004

[After this command, RPi2 server stops responding completely, no response in ssh terminal or to ping, usbipd hearthbeat stops even if ethernet LED still blinks, reboot needed]

Expected results:
Successfully start using the USB over IP.

Additional info:
I didn't find any useful logs, journalctl does not report anything usbip related. When needed, let me know, where to look for more information.

Comment 1 Jonathan Dieter 2015-03-04 10:35:55 UTC
I suspect this is a kernel panic, because the system completely stops responding.  Is there any way you can set up a serial console so we can get the kernel's error messages?  I don't have a Pi 2, so I don't really have a way of testing this myself.

Comment 2 Jonathan Dieter 2015-03-04 10:40:48 UTC
If there's no way to do a serial connection, perhaps look into netconsole.  I'm seeing conflicting information as to whether it's useful for kernel panics after the system has booted (it's definitely useless when trying to trace early kernel panics).

Comment 3 Tomas Lestach 2015-03-04 12:56:24 UTC
I'll try to get a cable for the serial console.

Comment 4 Tomas Lestach 2015-03-05 20:07:52 UTC
Created attachment 998537 [details]
captured output form the serial console

Here we go. I got the serial console and I'm attaching the captured output. Is that, what you need?

Comment 5 Jonathan Dieter 2015-03-06 08:16:24 UTC
Yes, at least in that it shows that we're hitting a kernel bug rather than a userspace problem.

It looks like the problem is when the USB/IP driver unlinks the usb device on the host so it can make it available, but to debug this further will require building a debug kernel for the RPi2.

The real issue is that I'm most definitely not a kernel developer and we're rapidly reaching the point where I'm out of my depth.

So we can go one of two ways.  Either I can post this bug to linux-usb.org, or you can.

If I do it, I'll be adding another layer between the bug reporter and the potential bug fixer, so I'd prefer to let you go there directly.  On the other hand, if you'd rather I try to deal with it, I'm happy to do so.

Either way, the first step is to build a debug kernel.

Comment 6 Tomas Lestach 2015-03-06 09:03:35 UTC
I'd appreciate, if you could post it as I'm afraid I couldn't answer any of the possible kernel or usbip questions. But feel free to put me into CC, so I can get any additional information, when needed.

Comment 7 Jonathan Dieter 2015-03-06 10:04:48 UTC
Ok, that's fine.  Can you please build a debug kernel, preferably with something like https://repos.fedorapeople.org/repos/thl/kernel-vanilla-mainline/fedora-21/SRPMS/kernel-4.0.0-0.rc2.git0.1.vanilla.mainline.knurd.1.fc21.src.rpm as its base, and upload the serial console output from that.

Comment 8 Tomas Lestach 2015-03-10 23:19:43 UTC
Hello Jonathan,
even if I've built the debug kernel (the build process took almost 8 hours), I wasn't able to boot it, yet.

However I updated the kernel to raspberrypi-kernel-3.18.9-501.20150308git780e681.sc20.armv7hl and was able to attach and use the USB port over IP!
It works like expected, the issue must have been fixed in the mentioned kernel!

client:
# usbip port
Imported USB devices
====================
Port 01: <Port in Use> at High Speed(480Mbps)
       unknown vendor : unknown product (04f9:0331)
       9-2 -> usbip://192.168.88.239:3240/1-1.5
           -> remote bus/dev 001/004
# lsusb
Bus 009 Device 028: ID 04f9:0331 Brother Industries, Ltd 
...
# scanimage -L
device `brother4:bus1;dev1' is a Brother MFC-L2700DW USB scanner
...

Let me use and watch it for couple of days to make sure, it's stable.

Comment 9 Jonathan Dieter 2015-03-11 07:16:42 UTC
I'm sorry you weren't able to run the debug kernel, but I'm glad the latest kernel seems to fix the problem.  Let me know if you run into any more problems.

Comment 10 Jonathan Dieter 2015-08-18 14:25:11 UTC
Seeing as there don't seem to have been any problems in the last few months, I'm closing this.  Please reopen if the problem has persisted.