Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Libfreenect2 not working on Jetson TX1 #581

Closed
menlocaleb opened this issue Feb 19, 2016 · 54 comments
Closed

Libfreenect2 not working on Jetson TX1 #581

menlocaleb opened this issue Feb 19, 2016 · 54 comments
Labels

Comments

@menlocaleb
Copy link

I'm trying to run libfreenect2 on an Nvidia Jetson TX1 Developer Kit and can't seem to get it working. Here's the output I'm getting:

$ LIBUSB_DEBUG=3 ./bin/Protonect 
Version: 0.2.0
Environment variables: LOGFILE=<protonect.log>
Usage: ./bin/Protonect [gl | cl | cuda | cpu] [<device serial>]
        [-noviewer] [-norgb | -nodepth] [-help] [-version]
To pause and unpause: pkill -USR1 Protonect
[Info] [Freenect2Impl] enumerating devices...
[Info] [Freenect2Impl] 18 usb devices connected
[Info] [Freenect2Impl] found valid Kinect v2 @2:6 with serial 068176734547
[Info] [Freenect2Impl] found 1 devices
[Info] [Freenect2DeviceImpl] opening...
[Info] [Freenect2DeviceImpl] opened
[Info] [Freenect2DeviceImpl] starting...
[Debug] [Freenect2DeviceImpl] status 0x090000: 9855
[Debug] [Freenect2DeviceImpl] status 0x090000: 9855
[Info] [Freenect2DeviceImpl] submitting rgb transfers...
[Info] [Freenect2DeviceImpl] submitting depth transfers...
[Error] [RgbPacketStreamParser] packetsize or sequence doesn't match!
[Debug] [DepthPacketStreamParser] subpacket too large
[Debug] [DepthPacketStreamParser] subpacket too large
[Info] [Freenect2DeviceImpl] started
device serial: 068176734547
device firmware: 4.0.3911.0
[Debug] [DepthPacketStreamParser] image data too short!
[Debug] [DepthPacketStreamParser] subpacket too large
[Debug] [DepthPacketStreamParser] image data too short!
[Debug] [DepthPacketStreamParser] subpacket too large
[Debug] [DepthPacketStreamParser] image data too short!
[Debug] [DepthPacketStreamParser] subpacket too large
[Debug] [DepthPacketStreamParser] image data too short!
[Debug] [DepthPacketStreamParser] subpacket too large
[Debug] [DepthPacketStreamParser] subpacket too large
[Debug] [DepthPacketStreamParser] image data too short!
[Debug] [DepthPacketStreamParser] subpacket too large
[Debug] [DepthPacketStreamParser] image data too short!
[Debug] [DepthPacketStreamParser] not all subsequences received 0

I've ensured that USB 3 is enabled in /boot/extlinux/extlinux.conf and turned off usb autosuspend using for i in /sys/bus/usb/devices/*/power/autosuspend; do echo -1 >$i; done

I've checked dmesg for all of the issues mentioned in the Troubleshooting wiki and couldn't find anything.

$ lspci
00:01.0 PCI bridge: NVIDIA Corporation Device 0fae (rev a1)
01:00.0 PCI bridge: Pericom Semiconductor Device 2608
02:01.0 PCI bridge: Pericom Semiconductor Device 2608
02:02.0 PCI bridge: Pericom Semiconductor Device 2608
02:03.0 PCI bridge: Pericom Semiconductor Device 2608
02:04.0 PCI bridge: Pericom Semiconductor Device 2608
03:00.0 USB controller: Renesas Technology Corp. uPD720202 USB 3.0 Host Controller (rev 02)
04:00.0 USB controller: Renesas Technology Corp. uPD720202 USB 3.0 Host Controller (rev 02)
05:00.0 USB controller: Renesas Technology Corp. uPD720202 USB 3.0 Host Controller (rev 02)
06:00.0 USB controller: Renesas Technology Corp. uPD720202 USB 3.0 Host Controller (rev 02)
$ lsusb -t
/:  Bus 10.Port 1: Dev 1, Class=root_hub, Driver=tegra-xhci/4p, 5000M
    |__ Port 1: Dev 2, If 0, Class=Vendor Specific Class, Driver=r8152, 5000M
    |__ Port 2: Dev 3, If 0, Class=Hub, Driver=hub/4p, 5000M
/:  Bus 09.Port 1: Dev 1, Class=root_hub, Driver=tegra-xhci/5p, 480M
    |__ Port 3: Dev 3, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 1: Dev 4, If 0, Class=Human Interface Device, Driver=usbhid, 1.5M
        |__ Port 1: Dev 4, If 1, Class=Human Interface Device, Driver=usbhid, 1.5M
        |__ Port 2: Dev 6, If 0, Class=Human Interface Device, Driver=usbhid, 1.5M
/:  Bus 08.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 5000M
/:  Bus 07.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 480M
/:  Bus 06.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 5000M
/:  Bus 05.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 480M
/:  Bus 04.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 5000M
/:  Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 480M
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 5000M
    |__ Port 1: Dev 5, If 0, Class=Hub, Driver=hub/1p, 5000M
        |__ Port 1: Dev 6, If 0, Class=Vendor Specific Class, Driver=, 5000M
        |__ Port 1: Dev 6, If 1, Class=Vendor Specific Class, Driver=, 5000M
        |__ Port 1: Dev 6, If 2, Class=Audio, Driver=snd-usb-audio, 5000M
        |__ Port 1: Dev 6, If 3, Class=Audio, Driver=snd-usb-audio, 5000M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 480M
    |__ Port 1: Dev 4, If 0, Class=Hub, Driver=hub/1p, 480M

I did succeed in getting the jetsonhacks version of libfreenect2 to work after a few small tweaks so I know it's possible to run on the TX1, I just can't figure out how to get the main version of libfreenect2 to work. I need to do this because I want to use the iai_kinect2 code to integrate with ROS, and that code needs the main version of libfreenect2. Any help would be greatly appreciated!

@xlz
Copy link
Member

xlz commented Feb 19, 2016

I did succeed in getting the jetsonhacks version of libfreenect2 to work after a few small tweaks

How? Anything more specific? jetsonhacks was mostly using one of my branches which has been incorporated into the upstream libfreenect2 so there shouldn't be any functional difference. It's the a few small tweaks that made the difference.

Frankly, several people have come to ask about problems with TX1. As I don't have a TX1, some of the investigation can only be done on the user side. And they did not follow up so the problems are never solved.

@menlocaleb
Copy link
Author

I changed the wget line in jetsonhacks' install script to a new version of gstjpeg: http://developer.download.nvidia.com/embedded/L4T/r23_Release_v1.0/source/gstjpeg_src.tbz2

I also changed line 113 of CMakeLists.txt from "jpeg" to "nvjpeg" to fix a build error.

Those are the only changes I made. However, I also ran the jetsonhacks version without CUDA or the Tegra acceleration in order to try to get it to work with the iai_kinect2 code and it still worked (the altered iai_kinect2 code crashes though). So I think something other than the optimizations (CUDA and Tegra) that you added are making it work.

Are there any other commands I can run to help you help me debug? Or any issues you think it might be?

@xlz
Copy link
Member

xlz commented Feb 20, 2016

You may need to maximize CPU and GPU clock to maintain basic Kinect functionalities, see http://elinux.org/Jetson/Performance for instructions.

I suppose you have done this? Also checked other issues here https://github.com/OpenKinect/libfreenect2/wiki/Troubleshooting#jetson-tk1-issues ?

We definitely have one working version and one non-working version to compare with. Several things to look for

@menlocaleb
Copy link
Author

I maximized all CPU's and set the GPU clock speed to 10x what it was (76800 kHz -> 768000 kHz). This didn't fix anything.

I have the correct udev rules in place and I've enabled usb3 with usb_port_owner_info=2 and disabled autosuspend with usbcore.autosuspend=-1.

When I run the Kinect through a USB3 hub rather than a PCI Express USB 3.0 card I only get the following error: [Debug] [RgbPacketStreamParser] skipping rgb packet! I don't get any depth errors. However when I run the jetson version, the opposite is true: it works when run through the PCI board, but fails with the following error when run through the USB 3 hub: [DepthPacketStreamParser::handleNewData] subpacket incomplete (needed 298496 received 28160). It is worth noting that the jetson version when it works also outputs a number of [Debug] [RgbPacketStreamParser] skipping rgb packet! errors, but it still outputs at a decent framerate.

Using the libusb debs you linked to didn't fix anything either. However, I didn't have a depends/libusb* folder or file, I only have the install_libusb.sh script and the two deb files in the debs folder.

There weren't any libusb errors or messages when run with LIBUSB_DEBUG=3.

I get the following errors in dmesg:
usb 4-1.1: reset SuperSpeed USB device number 7 using xhci_hcd
usb 4-1.1: Parent hub missing LPM exit latency info. Power management will be impacted
xhci_hcd 0000:04:00.0: WARN Successful completion on short TX: needs XHCI_TRUST_TX_LENGTH quirk?

Does that tell you anything?

@xlz
Copy link
Member

xlz commented Feb 20, 2016

Everyone thinks [Debug] [RgbPacketStreamParser] skipping rgb packet! is an error. It's not, sigh. It means the JPEG decoder is too slow and some usb data is received and then discarded.

[Debug] [RgbPacketStreamParser] skipping rgb packet!
[DepthPacketStreamParser::handleNewData] subpacket incomplete (needed 298496 received 28160)

These are not errors. They just show inefficiency. They are irrelevant in determining if it works or not.

usb 4-1.1: reset SuperSpeed USB device number 7 using xhci_hcd
usb 4-1.1: Parent hub missing LPM exit latency info. Power management will be impacted

Not errors.

xhci_hcd 0000:04:00.0: WARN Successful completion on short TX: needs XHCI_TRUST_TX_LENGTH quirk?

Not an error, but could indicate something indirect about your USB controller.

It's not clear to me from your report which is working and which is not. Also, you really need to clarify your hardware configuration. Something unusual is going on with your lspci, four USB controllers really?

  • With the upstream libfreenect2 (Btw I can tell you are not using the latest version because added command line options is not in your Protonect output)
    • "When I run the Kinect through a USB3 hub",
      1. Is there framerate stats printed?
      2. Does the viewer show images?
    • "When I run the Kinect through a PCI Express USB 3.0 card",
      1. Is there framerate stats printed?
      2. Does the viewer show images?
    • When you connect the Kinect directly to the onboard USB 3 port, instead of a hub or an USB extension card?
      1. Is there framerate stats printed?
      2. Does the viewer show images?
  • With jetsonhacks version
    • "When I run the Kinect through a USB3 hub",
      1. Is there framerate stats printed?
      2. Does the viewer show images?
    • "When I run the Kinect through a PCI Express USB 3.0 card",
      1. Is there framerate stats printed?
      2. Does the viewer show images?
    • When you connect the Kinect directly to the onboard USB 3 port, instead of a hub or an USB extension card?
      1. Is there framerate stats printed?
      2. Does the viewer show images?

@menlocaleb
Copy link
Author

  • Upstream libfreenect2 (now up to date)
    • USB 3 Hub
      • TurboJpegRgbPacketProcesser ~23.78Hz and no depth frame rate
      • The viewer is just a black screen
    • PCI Express USB 3.0 Card
      • TurboJpegRgbPacketProcesser ~23.69Hz and no depth frame rate
      • The viewer is just a black screen
    • jestonhacks version
    • USB 3 Hub
      • no frame rate output
      • viewers don't work
    • PCI Express USB 3.0 Card
      • TurboJpeg ~22.81 Hz and OpenGL ~61.96 Hz
      • Viewers all work

I had trouble testing the onboard USB 3 port because I wasn't able to run the program over ssh because of a GLFW error. Could it be because of a version mismatch between glfw on my workstation vs the TX1?

I'm running the TX1 development board with a 4 port PCI Express USB 3.0 Card with 4 dedicated 5Gbps Channels as well as a USB 3.0 4 port hub plugged into the built-in TX1 usb port.

@xlz
Copy link
Member

xlz commented Feb 20, 2016

You can run it over ssh using DISPLAY=:0.0 ./bin/Protonect.

@xlz
Copy link
Member

xlz commented Feb 21, 2016

Previously there are several cases when people use external USB extension cards or USB hubs on Jetson and it didn't work. Once they use the built-in port it worked. So definitely check the built-in port.

This hints at mostly USB problems. Yes, the upstream libfreenect2 should work even with the USB extension card. I don't recall any dramatic changes to the USB transfer code in libfreenect2 since the jetsonhacks version.

Besides the test with the built-in port, can you do the test using the upstream version and the extension card port, and provide:

  • Log of LIBUSB_DEBUG=4 ./bin/Protonect (this will be lengthy)
  • Full dmesg

@menlocaleb
Copy link
Author

Running with built-in usb port (run over ssh -X with DISPLAY=:0.0)

  • upstream
    • Turbo jpeg ~24 Hz, not depth hz output
    • No viewer at all
  • jetsonhacks
    • No frame rate info or viewer at all

@xlz
Copy link
Member

xlz commented Feb 22, 2016

I really need log of LIBUSB_DEBUG=4 ./bin/Protonect and the full dmesg. If you can, run it with LIBUSB_DEBUG=4 ../bin/Protonect cuda.

Even with Jetson TK1, TegraJPEG and CUDA processors provide 85Hz and 94Hz.

Also, it seems your build didn't enable TegraJPEG support. A user #480 (comment) had the same issue but hasn't followed up. The problem is there should be gstjpeg_src/nv_headers extracted under build directory, but it didn't. Maybe you can find out why.

@menlocaleb
Copy link
Author

Running upstream libfreenect with PCI express card (not CUDA or Tegra accelerated):

$ LIBUSB_DEBUG=4 ./bin/Protonect 
Version: 0.2.0
Environment variables: LOGFILE=<protonect.log>
Usage: ./bin/Protonect [-gpu=<id>] [gl | cl | cuda | cpu] [<device serial>]
        [-noviewer] [-norgb | -nodepth] [-help] [-version]
To pause and unpause: pkill -USR1 Protonect
[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 0.000005] [00003191] libusb: debug [libusb_init] created default context
[ 0.000099] [00003191] libusb: debug [libusb_init] libusb v1.0.20.11004
[ 0.000187] [00003191] libusb: debug [find_usbfs_path] found usbfs at /dev/bus/usb
[ 0.000237] [00003191] libusb: debug [op_init] bulk continuation flag supported
[ 0.000267] [00003191] libusb: debug [op_init] zero length packet flag supported
[ 0.000317] [00003191] libusb: debug [op_init] sysfs can relate devices
[ 0.000343] [00003191] libusb: debug [op_init] sysfs has complete descriptors
[ 0.000653] [00003192] libusb: debug [linux_udev_event_thread_main] udev event thread entering.
[ 0.002135] [00003191] libusb: debug [linux_get_device_address] getting address for device: usb1 detached: 0
[ 0.002189] [00003191] libusb: debug [linux_get_device_address] scan usb1
[ 0.002377] [00003191] libusb: debug [linux_get_device_address] bus=1 dev=1
[ 0.002412] [00003191] libusb: debug [linux_enumerate_device] busnum 1 devaddr 1 session_id 257
[ 0.002438] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 1/1 (session 257)
[ 0.002825] [00003191] libusb: debug [linux_get_device_address] getting address for device: usb2 detached: 0
[ 0.002868] [00003191] libusb: debug [linux_get_device_address] scan usb2
[ 0.003079] [00003191] libusb: debug [linux_get_device_address] bus=2 dev=1
[ 0.003111] [00003191] libusb: debug [linux_enumerate_device] busnum 2 devaddr 1 session_id 513
[ 0.003137] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 2/1 (session 513)
[ 0.003424] [00003191] libusb: debug [linux_get_device_address] getting address for device: usb3 detached: 0
[ 0.003457] [00003191] libusb: debug [linux_get_device_address] scan usb3
[ 0.003587] [00003191] libusb: debug [linux_get_device_address] bus=3 dev=1
[ 0.003615] [00003191] libusb: debug [linux_enumerate_device] busnum 3 devaddr 1 session_id 769
[ 0.003641] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 3/1 (session 769)
[ 0.003928] [00003191] libusb: debug [linux_get_device_address] getting address for device: 3-1 detached: 0
[ 0.003961] [00003191] libusb: debug [linux_get_device_address] scan 3-1
[ 0.004092] [00003191] libusb: debug [linux_get_device_address] bus=3 dev=7
[ 0.004123] [00003191] libusb: debug [linux_enumerate_device] busnum 3 devaddr 7 session_id 775
[ 0.004150] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 3/7 (session 775)
[ 0.004283] [00003191] libusb: debug [linux_get_parent_info] Dev 0x1c6e8 (3-1) has parent 0x1c318 (usb3) port 1
[ 0.004492] [00003191] libusb: debug [linux_get_device_address] getting address for device: usb4 detached: 0
[ 0.004525] [00003191] libusb: debug [linux_get_device_address] scan usb4
[ 0.004654] [00003191] libusb: debug [linux_get_device_address] bus=4 dev=1
[ 0.004687] [00003191] libusb: debug [linux_enumerate_device] busnum 4 devaddr 1 session_id 1025
[ 0.004715] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 4/1 (session 1025)
[ 0.004995] [00003191] libusb: debug [linux_get_device_address] getting address for device: 4-1 detached: 0
[ 0.005028] [00003191] libusb: debug [linux_get_device_address] scan 4-1
[ 0.005160] [00003191] libusb: debug [linux_get_device_address] bus=4 dev=12
[ 0.005192] [00003191] libusb: debug [linux_enumerate_device] busnum 4 devaddr 12 session_id 1036
[ 0.005219] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 4/12 (session 1036)
[ 0.005338] [00003191] libusb: debug [linux_get_parent_info] Dev 0x1df08 (4-1) has parent 0x1c408 (usb4) port 1
[ 0.005466] [00003191] libusb: debug [linux_get_device_address] getting address for device: 4-1.1 detached: 0
[ 0.005498] [00003191] libusb: debug [linux_get_device_address] scan 4-1.1
[ 0.005630] [00003191] libusb: debug [linux_get_device_address] bus=4 dev=13
[ 0.005654] [00003191] libusb: debug [linux_enumerate_device] busnum 4 devaddr 13 session_id 1037
[ 0.005675] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 4/13 (session 1037)
[ 0.005789] [00003191] libusb: debug [linux_get_parent_info] Dev 0x1e388 (4-1.1) has parent 0x1df08 (4-1) port 1
[ 0.006335] [00003191] libusb: debug [linux_get_device_address] getting address for device: usb5 detached: 0
[ 0.006363] [00003191] libusb: debug [linux_get_device_address] scan usb5
[ 0.006488] [00003191] libusb: debug [linux_get_device_address] bus=5 dev=1
[ 0.006514] [00003191] libusb: debug [linux_enumerate_device] busnum 5 devaddr 1 session_id 1281
[ 0.006536] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 5/1 (session 1281)
[ 0.006985] [00003191] libusb: debug [linux_get_device_address] getting address for device: usb6 detached: 0
[ 0.007015] [00003191] libusb: debug [linux_get_device_address] scan usb6
[ 0.007142] [00003191] libusb: debug [linux_get_device_address] bus=6 dev=1
[ 0.007169] [00003191] libusb: debug [linux_enumerate_device] busnum 6 devaddr 1 session_id 1537
[ 0.007191] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 6/1 (session 1537)
[ 0.007469] [00003191] libusb: debug [linux_get_device_address] getting address for device: usb7 detached: 0
[ 0.007495] [00003191] libusb: debug [linux_get_device_address] scan usb7
[ 0.007618] [00003191] libusb: debug [linux_get_device_address] bus=7 dev=1
[ 0.007642] [00003191] libusb: debug [linux_enumerate_device] busnum 7 devaddr 1 session_id 1793
[ 0.007665] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 7/1 (session 1793)
[ 0.007941] [00003191] libusb: debug [linux_get_device_address] getting address for device: usb8 detached: 0
[ 0.007966] [00003191] libusb: debug [linux_get_device_address] scan usb8
[ 0.008091] [00003191] libusb: debug [linux_get_device_address] bus=8 dev=1
[ 0.008116] [00003191] libusb: debug [linux_enumerate_device] busnum 8 devaddr 1 session_id 2049
[ 0.008138] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 8/1 (session 2049)
[ 0.008404] [00003191] libusb: debug [linux_get_device_address] getting address for device: usb10 detached: 0
[ 0.008431] [00003191] libusb: debug [linux_get_device_address] scan usb10
[ 0.008545] [00003191] libusb: debug [linux_get_device_address] bus=10 dev=1
[ 0.008570] [00003191] libusb: debug [linux_enumerate_device] busnum 10 devaddr 1 session_id 2561
[ 0.008593] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 10/1 (session 2561)
[ 0.008845] [00003191] libusb: debug [linux_get_device_address] getting address for device: 10-1 detached: 0
[ 0.008871] [00003191] libusb: debug [linux_get_device_address] scan 10-1
[ 0.008987] [00003191] libusb: debug [linux_get_device_address] bus=10 dev=2
[ 0.009012] [00003191] libusb: debug [linux_enumerate_device] busnum 10 devaddr 2 session_id 2562
[ 0.009035] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 10/2 (session 2562)
[ 0.009137] [00003191] libusb: debug [linux_get_parent_info] Dev 0x1e468 (10-1) has parent 0x1c760 (usb10) port 1
[ 0.009316] [00003191] libusb: debug [linux_get_device_address] getting address for device: 10-2 detached: 0
[ 0.009341] [00003191] libusb: debug [linux_get_device_address] scan 10-2
[ 0.009461] [00003191] libusb: debug [linux_get_device_address] bus=10 dev=33
[ 0.009486] [00003191] libusb: debug [linux_enumerate_device] busnum 10 devaddr 33 session_id 2593
[ 0.009508] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 10/33 (session 2593)
[ 0.009609] [00003191] libusb: debug [linux_get_parent_info] Dev 0x20338 (10-2) has parent 0x1c760 (usb10) port 2
[ 0.009785] [00003191] libusb: debug [linux_get_device_address] getting address for device: usb9 detached: 0
[ 0.009810] [00003191] libusb: debug [linux_get_device_address] scan usb9
[ 0.009925] [00003191] libusb: debug [linux_get_device_address] bus=9 dev=1
[ 0.009949] [00003191] libusb: debug [linux_enumerate_device] busnum 9 devaddr 1 session_id 2305
[ 0.009971] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 9/1 (session 2305)
[ 0.010218] [00003191] libusb: debug [linux_get_device_address] getting address for device: 9-3 detached: 0
[ 0.010243] [00003191] libusb: debug [linux_get_device_address] scan 9-3
[ 0.010360] [00003191] libusb: debug [linux_get_device_address] bus=9 dev=28
[ 0.010384] [00003191] libusb: debug [linux_enumerate_device] busnum 9 devaddr 28 session_id 2332
[ 0.010410] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 9/28 (session 2332)
[ 0.010517] [00003191] libusb: debug [linux_get_parent_info] Dev 0x20c38 (9-3) has parent 0x207b8 (usb9) port 3
[ 0.010628] [00003191] libusb: debug [linux_get_device_address] getting address for device: 9-3.1 detached: 0
[ 0.010653] [00003191] libusb: debug [linux_get_device_address] scan 9-3.1
[ 0.010770] [00003191] libusb: debug [linux_get_device_address] bus=9 dev=29
[ 0.010795] [00003191] libusb: debug [linux_enumerate_device] busnum 9 devaddr 29 session_id 2333
[ 0.010816] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 9/29 (session 2333)
[ 0.010921] [00003191] libusb: debug [linux_get_parent_info] Dev 0x210a8 (9-3.1) has parent 0x20c38 (9-3) port 1
[ 0.011176] [00003191] libusb: debug [linux_get_device_address] getting address for device: 9-3.2 detached: 0
[ 0.011202] [00003191] libusb: debug [linux_get_device_address] scan 9-3.2
[ 0.011322] [00003191] libusb: debug [linux_get_device_address] bus=9 dev=30
[ 0.011347] [00003191] libusb: debug [linux_enumerate_device] busnum 9 devaddr 30 session_id 2334
[ 0.011369] [00003191] libusb: debug [linux_enumerate_device] allocating new device for 9/30 (session 2334)
[ 0.011477] [00003191] libusb: debug [linux_get_parent_info] Dev 0x1fe68 (9-3.2) has parent 0x20c38 (9-3) port 2
[ 0.011706] [00003191] libusb: debug [usbi_add_pollfd] add fd 7 events 1
[ 0.011753] [00003191] libusb: debug [usbi_io_init] using timerfd for timeouts
[ 0.011777] [00003191] libusb: debug [usbi_add_pollfd] add fd 9 events 1
[ 0.011931] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[Info] [Freenect2Impl] enumerating devices...
[ 0.011972] [00003193] libusb: debug [handle_events] poll fds modified, reallocating
[ 0.012128] [00003193] libusb: debug [handle_events] poll() 2 fds with timeout in 100ms
[ 0.012007] [00003191] libusb: debug [libusb_get_device_list] 
[ 0.012270] [00003191] libusb: debug [discovered_devs_append] need to increase capacity
[ 0.012295] [00003191] libusb: debug [discovered_devs_append] need to increase capacity
[Info] [Freenect2Impl] 18 usb devices connected
[ 0.012365] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.012390] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.012411] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.012431] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.012452] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.012472] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.012492] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.012512] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.012533] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.012552] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.012572] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.012593] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.012616] [00003191] libusb: debug [libusb_open] open 4.13
[ 0.012684] [00003191] libusb: debug [usbi_add_pollfd] add fd 10 events 4
[ 0.012717] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1c838
[ 0.012739] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1c838
[ 0.012765] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.012812] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.012766] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.012883] [00003193] libusb: debug [handle_events] caught a fish on the event pipe
[ 0.012905] [00003193] libusb: debug [handle_events] someone updated the poll fds
[ 0.012936] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.012962] [00003193] libusb: debug [handle_events] poll fds modified, reallocating
[ 0.012944] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.012989] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.013319] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.013359] [00003193] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.013381] [00003193] libusb: debug [handle_control_completion] handling completion status 0
[ 0.013402] [00003193] libusb: debug [disarm_timerfd] 
[ 0.013422] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1c838 has callback 0xf7141485
[ 0.013443] [00003193] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.013473] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.013497] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.013485] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1c838
[ 0.013549] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1c838
[ 0.013569] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1c838
[ 0.013589] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.013619] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.014062] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.014097] [00003193] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=26
[ 0.014118] [00003193] libusb: debug [handle_control_completion] handling completion status 0
[ 0.014138] [00003193] libusb: debug [disarm_timerfd] 
[ 0.014160] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1c838 has callback 0xf7141485
[ 0.014180] [00003193] libusb: debug [sync_transfer_cb] actual_length=26
[ 0.014206] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.014229] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.014213] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1c838
[ 0.014279] [00003191] libusb: debug [libusb_close] 
[ 0.014312] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.014344] [00003193] libusb: debug [handle_events] caught a fish on the event pipe
[ 0.014364] [00003193] libusb: debug [handle_events] someone is closing a device
[ 0.014387] [00003193] libusb: debug [libusb_try_lock_events] someone else is closing a device
[ 0.014410] [00003193] libusb: debug [libusb_event_handler_active] someone else is closing a device
[ 0.014432] [00003193] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.014392] [00003191] libusb: debug [usbi_remove_pollfd] remove fd 10
[ 0.014498] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[Info] [Freenect2Impl] found valid Kinect v2 @4:13 with serial 068176734547
[ 0.014523] [00003193] libusb: debug [handle_events] poll fds modified, reallocating
[ 0.014552] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.014599] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.014623] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.014646] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.014669] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.014693] [00003191] libusb: debug [libusb_get_device_descriptor] 
[ 0.014576] [00003193] libusb: debug [handle_events] poll() 2 fds with timeout in 100ms
[Info] [Freenect2Impl] found 1 devices
[ 0.114872] [00003193] libusb: debug [handle_events] poll() returned 0
[ 0.114906] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.114917] [00003193] libusb: debug [handle_events] poll() 2 fds with timeout in 100ms
[ 0.141244] [00003191] libusb: debug [libusb_open] open 4.13
[ 0.141342] [00003191] libusb: debug [usbi_add_pollfd] add fd 20 events 4
[ 0.141388] [00003191] libusb: debug [libusb_reset_device] 
[ 0.141451] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.141472] [00003193] libusb: debug [handle_events] caught a fish on the event pipe
[ 0.141482] [00003193] libusb: debug [handle_events] someone updated the poll fds
[ 0.141493] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.141501] [00003193] libusb: debug [handle_events] poll fds modified, reallocating
[ 0.141516] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.241928] [00003193] libusb: debug [handle_events] poll() returned 0
[ 0.241959] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.241968] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[Info] [Freenect2DeviceImpl] opening...
[ 0.248484] [00003191] libusb: debug [libusb_get_configuration] 
[ 0.248549] [00003191] libusb: debug [libusb_get_configuration] active config 1
[ 0.248564] [00003191] libusb: debug [libusb_claim_interface] interface 0
[ 0.248590] [00003191] libusb: debug [libusb_claim_interface] interface 1
[ 0.248621] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229370
[ 0.248633] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229370
[ 0.248643] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.248692] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.249065] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.249091] [00003193] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=0
[ 0.249102] [00003193] libusb: debug [handle_control_completion] handling completion status 0
[ 0.249112] [00003193] libusb: debug [disarm_timerfd] 
[ 0.249122] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x229370 has callback 0xf7141485
[ 0.249131] [00003193] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.249151] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.249161] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.249159] [00003191] libusb: debug [libusb_free_transfer] transfer 0x229370
[ 0.249200] [00003191] libusb: debug [libusb_set_interface_alt_setting] interface 1 altsetting 0
[ 0.249575] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229370
[ 0.249594] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229370
[ 0.249604] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.249627] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.249947] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.249968] [00003193] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=0
[ 0.249977] [00003193] libusb: debug [handle_control_completion] handling completion status 0
[ 0.249986] [00003193] libusb: debug [disarm_timerfd] 
[ 0.249997] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x229370 has callback 0xf7141485
[ 0.250006] [00003193] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.250024] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.250033] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.250033] [00003191] libusb: debug [libusb_free_transfer] transfer 0x229370
[ 0.250070] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229370
[ 0.250084] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229370
[ 0.250094] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.250117] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.250762] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.250789] [00003193] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=0
[ 0.250799] [00003193] libusb: debug [handle_control_completion] handling completion status 0
[ 0.250810] [00003193] libusb: debug [disarm_timerfd] 
[ 0.250821] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x229370 has callback 0xf7141485
[ 0.250830] [00003193] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.250847] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.250857] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.250858] [00003191] libusb: debug [libusb_free_transfer] transfer 0x229370
[ 0.250886] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229370
[ 0.250899] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229370
[ 0.250909] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.250935] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.251418] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.251442] [00003193] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=0
[ 0.251451] [00003193] libusb: debug [handle_control_completion] handling completion status 0
[ 0.251461] [00003193] libusb: debug [disarm_timerfd] 
[ 0.251472] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x229370 has callback 0xf7141485
[ 0.251481] [00003193] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.251496] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.251506] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.251760] [00003191] libusb: debug [libusb_free_transfer] transfer 0x229370
[ 0.251795] [00003191] libusb: debug [parse_configuration] skipping descriptor 0xb
[ 0.251807] [00003191] libusb: debug [parse_endpoint] skipping descriptor 30
[ 0.251816] [00003191] libusb: debug [parse_endpoint] skipping descriptor 30
[ 0.251824] [00003191] libusb: debug [parse_endpoint] skipping descriptor 30
[ 0.251832] [00003191] libusb: debug [parse_endpoint] skipping descriptor 30
[ 0.251841] [00003191] libusb: debug [parse_endpoint] skipping descriptor 30
[ 0.251849] [00003191] libusb: debug [parse_endpoint] skipping descriptor b
[ 0.251859] [00003191] libusb: debug [parse_endpoint] skipping descriptor 30
[ 0.251867] [00003191] libusb: debug [parse_endpoint] skipping descriptor 25
[ 0.251905] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229468
[ 0.251915] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229508
[ 0.251924] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x2295a8
[ 0.251933] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229648
[ 0.251941] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x2296e8
[ 0.251949] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229788
[ 0.251957] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229828
[ 0.251965] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x2298c8
[ 0.251973] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229968
[ 0.251982] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229a08
[ 0.251990] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229aa8
[ 0.251998] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229b48
[ 0.252006] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229be8
[ 0.252014] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229c88
[ 0.252022] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229d28
[ 0.252030] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229dc8
[ 0.252038] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229e68
[ 0.252045] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229f08
[ 0.252054] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x229fa8
[ 0.252062] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x22a048
[ 0.252081] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x22a3c0
[ 0.252091] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x22a4c0
[ 0.252100] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x22a5c0
[ 0.252109] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5038
[ 0.252118] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5138
[ 0.252126] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5238
[ 0.252134] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5338
[ 0.252142] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5438
[ 0.252150] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5538
[ 0.252158] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5638
[ 0.252167] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5738
[ 0.252175] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5838
[ 0.252182] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5938
[ 0.252191] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5a38
[ 0.252199] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5b38
[ 0.252207] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5c38
[ 0.252215] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5d38
[ 0.252223] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5e38
[ 0.252231] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e5f38
[ 0.252239] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6038
[ 0.252248] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6138
[ 0.252255] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6238
[ 0.252273] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6338
[ 0.252282] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6438
[ 0.252290] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6538
[ 0.252299] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6638
[ 0.252307] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6738
[ 0.252315] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6838
[ 0.252324] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6938
[ 0.252332] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6a38
[ 0.252341] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6b38
[ 0.252349] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6c38
[ 0.252357] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6d38
[ 0.252365] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6e38
[ 0.252373] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e6f38
[ 0.252382] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7038
[ 0.252390] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7138
[ 0.252398] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7238
[ 0.252406] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7338
[ 0.252414] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7438
[ 0.252422] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7538
[ 0.252430] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7638
[ 0.252438] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7738
[ 0.252448] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7838
[ 0.252456] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7938
[ 0.252464] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7a38
[ 0.252473] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7b38
[ 0.252481] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7c38
[ 0.252489] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7d38
[ 0.252498] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7e38
[ 0.252506] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e7f38
[ 0.252514] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8038
[ 0.252522] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8138
[ 0.252530] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8238
[ 0.252538] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8338
[ 0.252547] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8438
[ 0.252555] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8538
[ 0.252564] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8638
[ 0.252572] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8738
[ 0.252580] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8838
[Info] [Freenect2DeviceImpl] opened
[Info] [Freenect2DeviceImpl] starting...
[ 0.252790] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e89b0
[ 0.252802] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e89b0
[ 0.252811] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.252841] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.253194] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.253219] [00003193] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=0
[ 0.253228] [00003193] libusb: debug [handle_control_completion] handling completion status 0
[ 0.253238] [00003193] libusb: debug [disarm_timerfd] 
[ 0.253248] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e89b0 has callback 0xf7141485
[ 0.253258] [00003193] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.253275] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.253284] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.253311] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e89b0
[ 0.253335] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x22a6c0
[ 0.253344] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x22a6c0
[ 0.253354] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.253366] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 20
[ 0.253384] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.253410] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.253424] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=20
[ 0.253433] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.253443] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.253451] [00003193] libusb: debug [disarm_timerfd] 
[ 0.253461] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x22a6c0 has callback 0xf7141485
[ 0.253470] [00003193] libusb: debug [sync_transfer_cb] actual_length=20
[ 0.253483] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.253491] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.253515] [00003191] libusb: debug [libusb_free_transfer] transfer 0x22a6c0
[ 0.253528] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x22a6c0
[ 0.253536] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x22a6c0
[ 0.253545] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.253555] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 512
[ 0.253571] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.290320] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.290353] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=512
[ 0.290363] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.290372] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.290381] [00003193] libusb: debug [disarm_timerfd] 
[ 0.290392] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x22a6c0 has callback 0xf7141485
[ 0.290401] [00003193] libusb: debug [sync_transfer_cb] actual_length=512
[ 0.290420] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.290429] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.290476] [00003191] libusb: debug [libusb_free_transfer] transfer 0x22a6c0
[ 0.290500] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x22a6c0
[ 0.290508] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x22a6c0
[ 0.290518] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.290529] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.290551] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.290583] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.290598] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.290607] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.290614] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.290626] [00003193] libusb: debug [disarm_timerfd] 
[ 0.290634] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x22a6c0 has callback 0xf7141485
[ 0.290642] [00003193] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.290655] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.290664] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.290710] [00003191] libusb: debug [libusb_free_transfer] transfer 0x22a6c0
[ 0.290759] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8bb8
[ 0.290769] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8bb8
[ 0.290778] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.290789] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 20
[ 0.290805] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.290837] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.290853] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=20
[ 0.290862] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.290870] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.290878] [00003193] libusb: debug [disarm_timerfd] 
[ 0.290887] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e8bb8 has callback 0xf7141485
[ 0.290895] [00003193] libusb: debug [sync_transfer_cb] actual_length=20
[ 0.290908] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.290916] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.290962] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e8bb8
[ 0.290979] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8bb8
[ 0.290988] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8bb8
[ 0.290997] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.291007] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 92
[ 0.291023] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.303989] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.304022] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=92
[ 0.304032] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.304065] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.304075] [00003193] libusb: debug [disarm_timerfd] 
[ 0.304085] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e8bb8 has callback 0xf7141485
[ 0.304094] [00003193] libusb: debug [sync_transfer_cb] actual_length=92
[ 0.304113] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.304122] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.304123] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e8bb8
[ 0.304151] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8bb8
[ 0.304164] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8bb8
[ 0.304173] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.304185] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.304203] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.304233] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.304248] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.304256] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.304264] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.304272] [00003193] libusb: debug [disarm_timerfd] 
[ 0.304280] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e8bb8 has callback 0xf7141485
[ 0.304288] [00003193] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.304301] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.304308] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e8bb8
[ 0.304309] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.304327] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8c40
[ 0.304360] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8c40
[ 0.304368] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.304378] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 24
[ 0.304394] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.304425] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.304439] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=24
[ 0.304448] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.304456] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.304463] [00003193] libusb: debug [disarm_timerfd] 
[ 0.304472] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e8c40 has callback 0xf7141485
[ 0.304480] [00003193] libusb: debug [sync_transfer_cb] actual_length=24
[ 0.304493] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.304500] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e8c40
[ 0.304516] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8c40
[ 0.304529] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8c40
[ 0.304501] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.304541] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.304578] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 128
[ 0.304596] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.304627] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.304642] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=128
[ 0.304651] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.304659] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.304667] [00003193] libusb: debug [disarm_timerfd] 
[ 0.304675] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e8c40 has callback 0xf7141485
[ 0.304683] [00003193] libusb: debug [sync_transfer_cb] actual_length=128
[ 0.304697] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.304705] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.304704] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e8c40
[ 0.304729] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8c40
[ 0.304740] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8c40
[ 0.304749] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.304760] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.304776] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.304806] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.304820] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.304829] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.304837] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.304845] [00003193] libusb: debug [disarm_timerfd] 
[ 0.304854] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e8c40 has callback 0xf7141485
[ 0.304862] [00003193] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.304875] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.304882] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e8c40
[ 0.304883] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.306339] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x22a6c0
[ 0.306376] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x22a6c0
[ 0.306400] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.306426] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 24
[ 0.306460] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.306493] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.306509] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=24
[ 0.306518] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.306527] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.306536] [00003193] libusb: debug [disarm_timerfd] 
[ 0.306545] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x22a6c0 has callback 0xf7141485
[ 0.306553] [00003193] libusb: debug [sync_transfer_cb] actual_length=24
[ 0.306568] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.306576] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.306575] [00003191] libusb: debug [libusb_free_transfer] transfer 0x22a6c0
[ 0.306601] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x22a6c0
[ 0.306650] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x22a6c0
[ 0.306673] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.306698] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1835008
[ 0.306912] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.307070] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.307149] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=92
[ 0.307159] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.307168] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.307177] [00003193] libusb: debug [disarm_timerfd] 
[ 0.307187] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x22a6c0 has callback 0xf7141485
[ 0.307196] [00003193] libusb: debug [sync_transfer_cb] actual_length=92
[ 0.307212] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.307221] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.307220] [00003191] libusb: debug [libusb_free_transfer] transfer 0x22a6c0
[ 0.307246] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x22a6c0
[ 0.307269] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x22a6c0
[ 0.307290] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.307314] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.307343] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.307421] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.307440] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.307450] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.307458] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.307467] [00003193] libusb: debug [disarm_timerfd] 
[ 0.307477] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x22a6c0 has callback 0xf7141485
[ 0.307485] [00003193] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.307500] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.307508] [00003191] libusb: debug [libusb_free_transfer] transfer 0x22a6c0
[ 0.307508] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.389105] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8c40
[ 0.389158] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8c40
[ 0.389184] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.389218] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 24
[ 0.389259] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.389349] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.389372] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=24
[ 0.389381] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.389391] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.389400] [00003193] libusb: debug [disarm_timerfd] 
[ 0.389410] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e8c40 has callback 0xf7141485
[ 0.389419] [00003193] libusb: debug [sync_transfer_cb] actual_length=24
[ 0.389436] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.389445] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.389445] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e8c40
[ 0.389475] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8c40
[ 0.389498] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8c40
[ 0.389525] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.389559] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1835008
[ 0.389786] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.489588] [00003193] libusb: debug [handle_events] poll() returned 0
[ 0.489633] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.489644] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.489697] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.589780] [00003193] libusb: debug [handle_events] poll() returned 0
[ 0.589823] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.589833] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.589885] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.672537] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.672979] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=1302878
[ 0.672998] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.673008] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.673019] [00003193] libusb: debug [disarm_timerfd] 
[ 0.673032] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e8c40 has callback 0xf7141485
[ 0.673043] [00003193] libusb: debug [sync_transfer_cb] actual_length=1302878
[ 0.673103] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.673114] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.673169] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e8c40
[ 0.673199] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e8c40
[ 0.673208] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8c40
[ 0.673218] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.673231] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.673252] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.673288] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.673305] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.673314] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.673324] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.673335] [00003193] libusb: debug [disarm_timerfd] 
[ 0.673344] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e8c40 has callback 0xf7141485
[ 0.673353] [00003193] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.673367] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.673376] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.673377] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e8c40
[ 0.677878] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e9af8
[ 0.677935] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e9af8
[ 0.677961] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.677998] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 24
[ 0.678042] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.678091] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.678113] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=24
[ 0.678123] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.678133] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.678142] [00003193] libusb: debug [disarm_timerfd] 
[ 0.678152] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e9af8 has callback 0xf7141485
[ 0.678161] [00003193] libusb: debug [sync_transfer_cb] actual_length=24
[ 0.678178] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.678186] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e9af8
[ 0.678204] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e9af8
[ 0.678226] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e9af8
[ 0.678249] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.678285] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1835008
[ 0.678187] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.678519] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.678756] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.678839] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=12981
[ 0.678849] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.678858] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.678867] [00003193] libusb: debug [disarm_timerfd] 
[ 0.678877] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e9af8 has callback 0xf7141485
[ 0.678886] [00003193] libusb: debug [sync_transfer_cb] actual_length=12981
[ 0.678903] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.678913] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.678965] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e9af8
[ 0.679000] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e9af8
[ 0.679022] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e9af8
[ 0.679043] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.679067] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.679099] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.679133] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.679153] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.679162] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.679172] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.679181] [00003193] libusb: debug [disarm_timerfd] 
[ 0.679191] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e9af8 has callback 0xf7141485
[ 0.679200] [00003193] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.679214] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.679224] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.679273] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e9af8
[ 0.679304] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e9af8
[ 0.679326] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e9af8
[ 0.679347] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.679370] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 36
[ 0.679399] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.679434] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.679449] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=36
[ 0.679458] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.679467] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.679475] [00003193] libusb: debug [disarm_timerfd] 
[ 0.679484] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e9af8 has callback 0xf7141485
[ 0.679492] [00003193] libusb: debug [sync_transfer_cb] actual_length=36
[ 0.679506] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.679514] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.679565] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e9af8
[ 0.679595] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e9af8
[ 0.679617] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e9af8
[ 0.679638] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.679661] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.679690] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.679723] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.679739] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.679747] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.679756] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.679764] [00003193] libusb: debug [disarm_timerfd] 
[ 0.679773] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e9af8 has callback 0xf7141485
[ 0.679781] [00003193] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.679795] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.679803] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.679854] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e9af8
[ 0.679884] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e9af8
[ 0.679905] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e9af8
[ 0.679927] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.679950] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 36
[ 0.679978] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.680011] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.680026] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=36
[ 0.680035] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.680066] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.680075] [00003193] libusb: debug [disarm_timerfd] 
[ 0.680084] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e9af8 has callback 0xf7141485
[ 0.680093] [00003193] libusb: debug [sync_transfer_cb] actual_length=36
[ 0.680107] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.680115] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.680165] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e9af8
[ 0.680195] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e9af8
[ 0.680217] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e9af8
[ 0.680238] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.680262] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.680290] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.680322] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.680338] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.680346] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.680355] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.680363] [00003193] libusb: debug [disarm_timerfd] 
[ 0.680372] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e9af8 has callback 0xf7141485
[ 0.680381] [00003193] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.680394] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.680402] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e9af8
[ 0.680419] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e9af8
[ 0.680440] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e9af8
[ 0.680462] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.680492] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 24
[ 0.680521] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.680403] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.680587] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.680601] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=24
[ 0.680610] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.680618] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.680626] [00003193] libusb: debug [disarm_timerfd] 
[ 0.680636] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e9af8 has callback 0xf7141485
[ 0.680644] [00003193] libusb: debug [sync_transfer_cb] actual_length=24
[ 0.680659] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.680667] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.680717] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e9af8
[ 0.680747] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e9af8
[ 0.680769] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e9af8
[ 0.680790] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.680813] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4
[ 0.680843] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.680873] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.680889] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=4
[ 0.680898] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.680906] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.680915] [00003193] libusb: debug [disarm_timerfd] 
[ 0.680923] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e9af8 has callback 0xf7141485
[ 0.680932] [00003193] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.680945] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.680954] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.681004] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e9af8
[ 0.681034] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1e9af8
[ 0.681055] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e9af8
[ 0.681077] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.681100] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.681130] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.681160] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.681175] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.681183] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.681192] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.681200] [00003193] libusb: debug [disarm_timerfd] 
[ 0.681209] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e9af8 has callback 0xf7141485
[ 0.681217] [00003193] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.681230] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.681238] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1e9af8
[ 0.681239] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[Debug] [Freenect2DeviceImpl] status 0x090000: 9729
[ 0.681302] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1eb1f0
[ 0.681324] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1eb1f0
[ 0.681345] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.681368] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 20
[ 0.681396] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.681430] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.681445] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=20
[ 0.681454] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.681462] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.681470] [00003193] libusb: debug [disarm_timerfd] 
[ 0.681479] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1eb1f0 has callback 0xf7141485
[ 0.681487] [00003193] libusb: debug [sync_transfer_cb] actual_length=20
[ 0.681501] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.681509] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1eb1f0
[ 0.681524] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1eb1f0
[ 0.681549] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1eb1f0
[ 0.681574] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.681601] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.681509] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.681633] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.684998] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.685020] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.685029] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.685037] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.685069] [00003193] libusb: debug [disarm_timerfd] 
[ 0.685080] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1eb1f0 has callback 0xf7141485
[ 0.685089] [00003193] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.685104] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.685113] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.685113] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1eb1f0
[ 0.685136] [00003191] libusb: debug [libusb_set_interface_alt_setting] interface 1 altsetting 1
[ 0.686498] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1eb1f0
[ 0.686534] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1eb1f0
[ 0.686557] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.686583] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 24
[ 0.686648] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.686705] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.686725] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=24
[ 0.686735] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.686745] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.686754] [00003193] libusb: debug [disarm_timerfd] 
[ 0.686764] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1eb1f0 has callback 0xf7141485
[ 0.686773] [00003193] libusb: debug [sync_transfer_cb] actual_length=24
[ 0.686791] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.686801] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.686970] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1eb1f0
[ 0.687006] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1eb1f0
[ 0.687029] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1eb1f0
[ 0.687354] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.687385] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4
[ 0.687423] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.687463] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.687483] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=4
[ 0.687493] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.687502] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.687511] [00003193] libusb: debug [disarm_timerfd] 
[ 0.687521] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1eb1f0 has callback 0xf7141485
[ 0.687529] [00003193] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.687544] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.687553] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.687588] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1eb1f0
[ 0.687615] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1eb1f0
[ 0.687639] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1eb1f0
[ 0.687663] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.687689] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.687722] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.687754] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.687784] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.687794] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.687803] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.687812] [00003193] libusb: debug [disarm_timerfd] 
[ 0.687822] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1eb1f0 has callback 0xf7141485
[ 0.687831] [00003193] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.687965] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.687984] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.688057] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1eb1f0
[Debug] [Freenect2DeviceImpl] status 0x090000: 9731
[ 0.688143] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1eb1f0
[ 0.688167] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1eb1f0
[ 0.688190] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.688216] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 24
[ 0.688248] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.688289] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.688308] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=24
[ 0.688318] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.688327] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.688336] [00003193] libusb: debug [disarm_timerfd] 
[ 0.688345] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1eb1f0 has callback 0xf7141485
[ 0.688354] [00003193] libusb: debug [sync_transfer_cb] actual_length=24
[ 0.688407] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.688415] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1eb1f0
[ 0.688431] [00003191] libusb: debug [libusb_alloc_transfer] transfer 0x1eb1f0
[ 0.688454] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1eb1f0
[ 0.688478] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.688507] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.688540] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.688416] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.789003] [00003193] libusb: debug [handle_events] poll() returned 0
[ 0.789058] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.789069] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.789140] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.889343] [00003193] libusb: debug [handle_events] poll() returned 0
[ 0.889381] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.889390] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.889434] [00003191] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.930130] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.930162] [00003193] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.930171] [00003193] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.930181] [00003193] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.930191] [00003193] libusb: debug [disarm_timerfd] 
[ 0.930201] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1eb1f0 has callback 0xf7141485
[ 0.930210] [00003193] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.930230] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.930239] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.930279] [00003191] libusb: debug [libusb_free_transfer] transfer 0x1eb1f0
[Info] [Freenect2DeviceImpl] submitting rgb transfers...
[ 0.930422] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229468
[ 0.930438] [00003191] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.930453] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930478] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229508
[ 0.930488] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930504] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x2295a8
[ 0.930513] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930528] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229648
[ 0.930537] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930551] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x2296e8
[ 0.930560] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930573] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229788
[ 0.930583] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930596] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229828
[ 0.930606] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930620] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x2298c8
[ 0.930630] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930644] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229968
[ 0.930654] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930670] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229a08
[ 0.930679] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930695] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229aa8
[ 0.930704] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930719] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229b48
[ 0.930728] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930742] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229be8
[ 0.930751] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930766] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229c88
[ 0.930776] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930791] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229d28
[ 0.930800] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930814] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229dc8
[ 0.930824] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930839] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229e68
[ 0.930849] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930863] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229f08
[ 0.930873] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930890] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x229fa8
[ 0.930899] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[ 0.930915] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x22a048
[ 0.930925] [00003191] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[Info] [Freenect2DeviceImpl] submitting depth transfers...
[ 0.930956] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x22a3c0
[ 0.930967] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.931128] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x22a4c0
[ 0.931144] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.931219] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x22a5c0
[ 0.931229] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.931303] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5038
[ 0.931313] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.931385] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5138
[ 0.931395] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.931467] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5238
[ 0.931477] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.931552] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5338
[ 0.931562] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.931633] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5438
[ 0.931643] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.931714] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5538
[ 0.931724] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.931798] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5638
[ 0.931808] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.931880] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5738
[ 0.931891] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.931970] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5838
[ 0.931981] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.932055] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5938
[ 0.932066] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.932109] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.932138] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5a38
[ 0.932149] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.932430] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=135168
[ 0.932447] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 0.932456] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 0.932467] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x22a3c0 has callback 0xf73fb335
[ 0.932509] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5b38
[ 0.932521] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.932546] [00003193] libusb: debug [libusb_submit_transfer] transfer 0x22a3c0
[ 0.932557] [00003193] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.932593] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5c38
[ 0.932604] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.932724] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5d38
[ 0.932726] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.932760] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.932745] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.932892] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5e38
[ 0.932905] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.932977] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e5f38
[ 0.932988] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.933057] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6038
[ 0.933067] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.933145] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6138
[ 0.933155] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.933174] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.933227] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6238
[ 0.933237] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.933478] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=202752
[ 0.933491] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 0.933500] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 0.933509] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x22a4c0 has callback 0xf73fb335
[ 0.933563] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6338
[ 0.933575] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.933655] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6438
[ 0.933665] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.933710] [00003193] libusb: debug [libusb_submit_transfer] transfer 0x22a4c0
[ 0.933724] [00003193] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.933740] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6538
[ 0.933751] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.934005] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6638
[ 0.934029] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.934007] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.934092] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.934107] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.934107] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6738
[ 0.934213] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.934397] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=231064
[ 0.934417] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 0.934426] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 0.934436] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x22a5c0 has callback 0xf73fb335
[ 0.934478] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6838
[ 0.934490] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.934567] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6938
[ 0.934578] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[Debug] [DepthPacketStreamParser] subpacket too large
[ 0.934621] [00003193] libusb: debug [libusb_submit_transfer] transfer 0x22a5c0
[ 0.934634] [00003193] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.934651] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6a38
[ 0.934662] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.934778] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6b38
[ 0.934788] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.934858] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6c38
[ 0.934878] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.934861] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.934941] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.934969] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6d38
[ 0.934994] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.935081] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6e38
[ 0.935096] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.935108] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.935392] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=135168
[ 0.935407] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 0.935416] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 0.935425] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5038 has callback 0xf73fb335
[ 0.935477] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e6f38
[ 0.935499] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.935482] [00003193] libusb: debug [libusb_submit_transfer] transfer 0x1e5038
[ 0.935545] [00003193] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.935593] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7038
[ 0.935604] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.935724] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7138
[ 0.935739] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.935726] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.935795] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.935832] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7238
[ 0.935857] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.935954] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7338
[ 0.935978] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.936068] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7438
[ 0.936092] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.936101] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.936178] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7538
[ 0.936190] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.936447] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=135168
[ 0.936460] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 0.936469] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 0.936479] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5138 has callback 0xf73fb335
[ 0.936530] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7638
[ 0.936537] [00003193] libusb: debug [libusb_submit_transfer] transfer 0x1e5138
[ 0.936543] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.936573] [00003193] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.936674] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7738
[ 0.936705] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.936819] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7838
[ 0.936851] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.936821] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.936940] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.936943] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7938
[ 0.937057] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.937099] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.937149] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7a38
[ 0.937162] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.937420] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=135168
[ 0.937436] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 0.937445] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 0.937455] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5238 has callback 0xf73fb335
[ 0.937504] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7b38
[ 0.937512] [00003193] libusb: debug [libusb_submit_transfer] transfer 0x1e5238
[ 0.937518] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.937538] [00003193] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.937618] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7c38
[ 0.937659] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.937763] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7d38
[ 0.937791] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.937765] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.937843] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.937881] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7e38
[ 0.937906] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.937991] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e7f38
[ 0.938014] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.938102] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8038
[ 0.938127] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.938172] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.938212] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8138
[ 0.938224] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.938462] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=168960
[ 0.938476] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 0.938485] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 0.938495] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5338 has callback 0xf73fb335
[ 0.938547] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8238
[ 0.938559] [00003193] libusb: debug [libusb_submit_transfer] transfer 0x1e5338
[ 0.938579] [00003193] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.938560] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.938666] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.938706] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.938746] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8338
[ 0.938776] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.938862] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8438
[ 0.938886] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.938975] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8538
[ 0.939001] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.939088] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8638
[ 0.939112] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.939119] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.939204] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8738
[ 0.939216] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.939472] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=231064
[ 0.939488] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 0.939496] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 0.939506] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5438 has callback 0xf73fb335
[ 0.939554] [00003191] libusb: debug [libusb_submit_transfer] transfer 0x1e8838
[ 0.939566] [00003191] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[Debug] [DepthPacketStreamParser] not all subsequences received 0
[Info] [Freenect2DeviceImpl] started
device serial: 068176734547
device firmware: 4.0.3911.0
[ 0.940330] [00003193] libusb: debug [libusb_submit_transfer] transfer 0x1e5438
[ 0.940356] [00003193] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.940710] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=135168
[ 0.940728] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 0.940737] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 0.940747] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5538 has callback 0xf73fb335
[ 0.940795] [00003193] libusb: debug [libusb_submit_transfer] transfer 0x1e5538
[ 0.940827] [00003193] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.940917] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.940928] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.941100] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.941393] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=135168
[ 0.941407] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 0.941416] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 0.941426] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5638 has callback 0xf73fb335
[ 0.941471] [00003193] libusb: debug [libusb_submit_transfer] transfer 0x1e5638
[ 0.941485] [00003193] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 0.941588] [00003193] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.941600] [00003193] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.942096] [00003193] libusb: debug [handle_events] poll() returned 1
[ 0.942383] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=135168
[ 0.942396] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 0.942405] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 0.942415] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5738 has callback 0xf73fb335

I've attached my dmesg.
dmesg.txt

@xlz
Copy link
Member

xlz commented Feb 22, 2016

Does the output of LIBUSB_DEBUG=4 ./bin/Protonect stop after

[ 0.942415] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5738 has callback 0xf73fb335

?

@menlocaleb
Copy link
Author

No but I wasn't sure how much more to do, by that point it was seeming like it was repeating.

By the time I stopped it (after running for 5 - 10 seconds) this is what was approximately repeating:

[Debug] [DepthPacketStreamParser] subpacket too large
[ 5.068774] [00003193] libusb: debug [libusb_submit_transfer] transfer 0x1e5c38
[ 5.069475] [00003193] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 5.070595] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=264856
[ 5.070713] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 5.071177] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 5.071201] [00003193] libusb: debug [arm_timerfd_for_next_timeout] next timeout originally 1000ms
[ 5.071225] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5d38 has callback 0xf73fb335
[Debug] [DepthPacketStreamParser] subpacket too large
[ 5.071361] [00003193] libusb: debug [libusb_submit_transfer] transfer 0x1e5d38
[ 5.071392] [00003193] libusb: debug [submit_iso_transfer] need 1 6144k URBs for transfer
[ 5.071567] [00003193] libusb: debug [reap_for_handle] urb type=0 status=0 transferred=270336
[ 5.071596] [00003193] libusb: debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
[ 5.071617] [00003193] libusb: debug [handle_iso_completion] last URB in transfer --> complete!
[ 5.071637] [00003193] libusb: debug [arm_timerfd_for_next_timeout] next timeout originally 1000ms
[ 5.071660] [00003193] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5e38 has callback

@xlz
Copy link
Member

xlz commented Feb 22, 2016

So I suppose you are still getting a stream of

[Debug] [DepthPacketStreamParser] image data too short!
[Debug] [DepthPacketStreamParser] subpacket too large

? This points to data loss at kernel driver level (WARN Successful completion on short TX). It's probably some changes in libusb behaviors that expose bugs in the kernel driver for uPD720202.

This can be verified by printing packet lengths here

Actually here: https://github.com/OpenKinect/libfreenect2/blob/master/src/depth_packet_stream_parser.cpp#L72

https://github.com/jetsonhacks/libfreenect2/blob/jetsontk1/examples/protonect/src/depth_packet_stream_parser.cpp#L65

Add

LOG_DEBUG << "pkt len " << length;

And record it.

I still want to verify which libusb this test was run with. Can you provide the output of ldd ./bin/Protonect | grep libusb?

@xlz
Copy link
Member

xlz commented Feb 22, 2016

The output of ldd ./bin/Protonect | grep libusb for both the upstream version and jetsonhacks version.

I really think there is some difference in their libusb.

@menlocaleb
Copy link
Author

In regards to the tegra headers, in the jetsonhacks version I changed the following line of the build file from

 FIND_LIBRARY(TEGRA_JPEG_LIBRARY jpeg PATHS /usr/lib/arm-linux-gnueabihf/tegra NO_DEFAULT_PATH)

to

 FIND_LIBRARY(TEGRA_JPEG_LIBRARY nvjpeg PATHS /usr/lib/arm-linux-gnueabihf/tegra NO_DEFAULT_PATH)

(changed jpeg to nvjpeg).

For packet lengths in the jetsonhacks version (where all viewer windows work) there seem to be two variations:

pkt len 28312
pkt len 33792

Libusb versions:

  • Jetsonhacks (some of path altered to hide real directory names)
$ ldd ./bin/Protonect | grep libusb
    libusb-1.0.so.0 => /home/user_name/dir1/root_of_jetsonhacks_repo/examples/protonect/../../depends/libusb/lib/libusb-1.0.so.0 (0xf696f000)
  • upstream
ldd ./bin/Protonect | grep libusb
    libusb-1.0.so.0 => /lib/arm-linux-gnueabihf/libusb-1.0.so.0 (0xf71a8000)

You were right, there is a difference: the jetsonhacks version uses one from it's depends directory.

@xlz
Copy link
Member

xlz commented Feb 22, 2016

What happens if

LD_PRELOAD=jetsonhacks/libusb.so.0 upstream/ build/bin/Protonect

?

@xlz
Copy link
Member

xlz commented Feb 22, 2016

Also, what happens if jetsonhacks version uses the system libusb? (Remove the libusb in depends directory)

@menlocaleb
Copy link
Author

$ LD_PRELOAD=/home/user_name/dir1/jetsonhacks_root_dir/depends/libusb/lib/libusb-1.0.so.0 ./bin/Protonect 
Version: 0.2.0
Environment variables: LOGFILE=<protonect.log>
Usage: ./bin/Protonect [-gpu=<id>] [gl | cl | cuda | cpu] [<device serial>]
        [-noviewer] [-norgb | -nodepth] [-help] [-version]
To pause and unpause: pkill -USR1 Protonect
[Error] [Freenect2Impl] Your libusb does not support large iso buffer!
no device connected!
$ lsusb
Bus 009 Device 030: ID 046d:c077 Logitech, Inc. 
Bus 009 Device 029: ID 046d:c31c Logitech, Inc. Keyboard K120 for Business
Bus 009 Device 028: ID 2109:3431  
Bus 009 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 010 Device 033: ID 2109:0811  
Bus 010 Device 002: ID 0955:09ff NVidia Corp. 
Bus 010 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 008 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 007 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 006 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 015: ID 045e:02c4 Microsoft Corp. 
Bus 004 Device 014: ID 045e:02d9 Microsoft Corp. 
Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 008: ID 045e:02d9 Microsoft Corp. 
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

Am I doing something wrong? My Kinect is connected as my lsusb shows.

@menlocaleb
Copy link
Author

If I move the libusb directory out of the depends directory and try to build the jetsonhacks version I get a build error

$ make
[ 45%] Built target glfw
[ 47%] Built target generate_resources_tool
Scanning dependencies of target freenect2
[ 50%] Building CXX object CMakeFiles/freenect2.dir/src/transfer_pool.cpp.o
In file included from /home/user_name/dev/jetson_libfreenect2/examples/protonect/src/transfer_pool.cpp:27:0:
/home/user_name/dev/jetson_libfreenect2/examples/protonect/include/libfreenect2/usb/transfer_pool.h:31:20: fatal error: libusb.h: No such file or directory
 #include <libusb.h>
                    ^
compilation terminated.
make[2]: *** [CMakeFiles/freenect2.dir/src/transfer_pool.cpp.o] Error 1
make[1]: *** [CMakeFiles/freenect2.dir/all] Error 2
make: *** [all] Error 2

Here are the offending lines of the cmake I assume:

INCLUDE_DIRECTORIES("${MY_DIR}/../../depends/libusb/include/libusb-1.0/")
LINK_DIRECTORIES("${MY_DIR}/../../depends/libusb/lib/")

@xlz
Copy link
Member

xlz commented Feb 22, 2016

You didn't do anything wrong. Maybe it's the code structure which won't allow my proposed test.

I suspect the difference in libusb is this: jetsonhacks@e818be2

Can you git revert e818be215f8e863dc6b5c0bea424d85d626dc7ec in the jetsonhacks directory, rebuild, and see if it gets the same error as upstream libfreenect2?

@xlz
Copy link
Member

xlz commented Feb 23, 2016

If this commit indeed makes the difference, you can try to build libusb from source by patching it to change MAX_ISO_BUFFER_LENGTH from 49152 * 128 to 49152.

@menlocaleb
Copy link
Author

You're right! When I reverted that commit the jetsonhacks version also broke. So in the upstream version I ran install_libusb.sh in the depends directory, then edited MAX_ISO_BUFFER_LENGTH to be 49152. To get it to build I added the following lines to my CMakeLists.txt, but there might be a better way.

INCLUDE_DIRECTORIES("${MY_DIR}/depends/libusb/include/libusb-1.0/")
LINK_DIRECTORIES("${MY_DIR}/depends/libusb/lib/")

Now the upstream libfreenect2 works on the TX1!

However, now when I run the kinect2_bridge it outputs nanms/nanHz for the depth processing. This is better than before when it wasn't working at all, but I'd rather it worked all the way!

@xlz
Copy link
Member

xlz commented Feb 23, 2016

I don't think you are supposed to need INCLUDE_DIRECTORIES("${MY_DIR}/depends/libusb/include/libusb-1.0/")?

After you built libusb in depends directory, and rm -rf * under build directory, what does cmake .. output?

@xlz
Copy link
Member

xlz commented Feb 23, 2016

Now there are two remaining issues:

  • Does the upstream with the patched libusb work with the built-in USB port?
  • Are you able to enable the TegraJPEG decoder?

@menlocaleb
Copy link
Author

You're right, I didn't need those two CMake additions. With the original CMakeLists.txt file here is my output:

$ cmake ..
-- The C compiler identification is GNU 4.8.4
-- The CXX compiler identification is GNU 4.8.4
-- Check for working C compiler: /usr/bin/cc
-- Check for working C compiler: /usr/bin/cc -- works
-- Detecting C compiler ABI info
-- Detecting C compiler ABI info - done
-- Check for working CXX compiler: /usr/bin/c++
-- Check for working CXX compiler: /usr/bin/c++ -- works
-- Detecting CXX compiler ABI info
-- Detecting CXX compiler ABI info - done
-- using tinythread as threading library
-- Found PkgConfig: /usr/bin/pkg-config (found version "0.26") 
-- checking for module 'libusb-1.0>=1.0.20'
--   found libusb-1.0, version 1.0.20
-- checking for modules 'libva;libva-drm'
--   package 'libva' not found
--   package 'libva-drm' not found
-- Found JPEG: /usr/lib/arm-linux-gnueabihf/libjpeg.so  
-- Found Linux4Tegra 23.1.1
-- Could NOT find TegraJPEG (missing:  TegraJPEG_INCLUDE_DIRS TegraJPEG_WORKS) 
-- Performing Test TURBOJPEG_WORKS
-- Performing Test TURBOJPEG_WORKS - Success
-- Found TurboJPEG: /usr/lib/arm-linux-gnueabihf/libturbojpeg.so.0  
-- checking for module 'glfw3'
--   found glfw3, version 3.0.4
-- Looking for XOpenDisplay in /usr/lib/arm-linux-gnueabihf/libX11.so;/usr/lib/arm-linux-gnueabihf/libXext.so
-- Looking for XOpenDisplay in /usr/lib/arm-linux-gnueabihf/libX11.so;/usr/lib/arm-linux-gnueabihf/libXext.so - found
-- Looking for gethostbyname
-- Looking for gethostbyname - found
-- Looking for connect
-- Looking for connect - found
-- Looking for remove
-- Looking for remove - found
-- Looking for shmat
-- Looking for shmat - found
-- Looking for IceConnectionNumber in ICE
-- Looking for IceConnectionNumber in ICE - found
-- Found X11: /usr/lib/arm-linux-gnueabihf/libX11.so
-- Found OpenGL: /usr/lib/arm-linux-gnueabihf/libGL.so  
-- Looking for CL_VERSION_2_0
-- Looking for CL_VERSION_2_0 - not found
-- Looking for CL_VERSION_1_2
-- Looking for CL_VERSION_1_2 - not found
-- Looking for CL_VERSION_1_1
-- Looking for CL_VERSION_1_1 - not found
-- Looking for CL_VERSION_1_0
-- Looking for CL_VERSION_1_0 - not found
-- Could NOT find OpenCL (missing:  OpenCL_INCLUDE_DIR) 
CMake Warning (dev) in CMakeLists.txt:
  A logical block opening on the line

    /home/user_name/dev/libfreenect2/CMakeLists.txt:333 (IF)

  closes on the line

    /home/user_name/dev/libfreenect2/CMakeLists.txt:371 (ENDIF)

  with mis-matching arguments.
This warning is for project developers.  Use -Wno-dev to suppress it.

-- RPATH set to /home/user_name/dev/libfreenect2/depends/libusb/lib
-- Performing Test COMPILER_HAS_HIDDEN_VISIBILITY
-- Performing Test COMPILER_HAS_HIDDEN_VISIBILITY - Success
-- Performing Test COMPILER_HAS_HIDDEN_INLINE_VISIBILITY
-- Performing Test COMPILER_HAS_HIDDEN_INLINE_VISIBILITY - Success
-- Performing Test COMPILER_HAS_DEPRECATED_ATTR
-- Performing Test COMPILER_HAS_DEPRECATED_ATTR - Success
-- Linking with these libraries: 
 /home/user_name/dev/libfreenect2/depends/libusb/lib/libusb-1.0.so
 pthread
 /usr/lib/arm-linux-gnueabihf/libturbojpeg.so.0
 /usr/local/lib/libglfw.so
 /usr/lib/arm-linux-gnueabihf/libGL.so
-- Found Doxygen: /usr/bin/doxygen (found version "1.8.6") 
-- Configurating examples
-- Using in-tree freenect2 target
-- checking for module 'libopenni2'
--   package 'libopenni2' not found
-- Could NOT find OpenNI2 (missing:  OpenNI2_LIBRARY_DIR OpenNI2_INCLUDE_DIRS) 
-- Feature list:
--   CUDA    disablsed
--   CXX11    disabled
--   Examples    yes
--   OpenCL    no
--   OpenGL    yes
--   OpenNI2    no
--   TegraJPEG    no
--   Threading    tinythread
--   TurboJPEG    yes
--   VAAPI    no
--   VideoToolbox    no (Apple only)
-- Configuring done
-- Generating done
-- Build files have been written to: /home/user_name/dev/libfreenect2/build

When I run the upstream libfreenect2 with libusb patched I don't get any errors, but no windows show up on my machine. I'm running ssh -X then DISPLAY=:0.0 ./bin/Protonect

I'll have to look into Tegra more tomorrow, I haven't disabled it, but CMake can't find the right headers.

@xlz
Copy link
Member

xlz commented Feb 23, 2016

A few things that don't look right to me:

  • A logical block opening on the line... /home/user_name/dev/libfreenect2/CMakeLists.txt:333 (IF): what happened to ENABLE_CUDA?
  • Is there something that made you unable to enable CUDA?
  • /usr/local/lib/libglfw.so (you built libglfw3 and make install'd it)? The upstream libfreenect2 asks to use download_debs_trusty.sh to download glfw debs to install.

I don't know your setup. The viewer is supposed to show up on the monitor that is connected to the Jetson. If no monitor is connected to it, framerate information can also prove it works. I don't know if you still get nanHz or 0Hz, but cmake -DENABLE_CXX11=ON may solve it.

There are some new commits these two days, remember to update.

@menlocaleb
Copy link
Author

Sorry I misunderstood - the viewer does launch on the monitor connected to the TX1 when I run it over ssh -X with DISPLAY=:0.0 ./bin/Protonect. When the Kinect is using the PCI Express USB slot it works, but I get a lot of "skipping rgb packet!" and "[DepthPacketStreamParser] 3 packets were lost" or "skipping depth packet". I get frame rates for both color and depth though (18 and 60 Hz respectively).

When running the Kinect through the built-in USB port the viewer appears but is only a black screen. I get lots of "skipping rgb packet!" messages and a color frame rate, but nothing for depth. For both of these tests I built using cmake -DENABLE_CXX11=ON using the most up to date code from the repo.

I was able to get the TegraJPEG decoder to build, but I had to replace the the current section in CMakeLists.txt relating to TegraJPEG with (adapted from the jetsonhacks CMakeLists.txt):

SET(HAVE_TegraJPEG disabled)
IF(ENABLE_TEGRAJPEG AND EXISTS "/etc/nv_tegra_release")
  FIND_LIBRARY(TEGRA_JPEG_LIBRARY nvjpeg PATHS /usr/lib/arm-linux-gnueabihf/tegra NO_DEFAULT_PATH)
  IF(NOT TEGRA_JPEG_LIBRARY)
    SET(HAVE_TegraJPEG no)
    MESSAGE(FATAL_ERROR "Did not find Tegra JPEG library")
  ENDIF(NOT TEGRA_JPEG_LIBRARY)


  INCLUDE_DIRECTORIES("${MY_DIR}/depends")
  CHECK_SYMBOL_EXISTS(TEGRA_ACCELERATE "${MY_DIR}/depends/nv_headers/jconfig.h" TEGRA_JPEG_HEADERS)
  IF(NOT TEGRA_JPEG_HEADERS)
    MESSAGE(FATAL_ERROR "Did not find headers for Tegra JPEG library in ${MY_DIR}/depends/nv_headers")
  ENDIF(NOT TEGRA_JPEG_HEADERS)

  MESSAGE(STATUS "Found Tegra hardware accelerated JPEG support")
  SET(LIBFREENECT2_WITH_TEGRAJPEG_SUPPORT 1)
  SET(HAVE_TegraJPEG yes)

  LIST(APPEND SOURCES
    src/tegra_jpeg_rgb_packet_processor.cpp
  )
  LIST(APPEND LIBRARIES
    ${TEGRA_JPEG_LIBRARY}
  )
ENDIF()

I also had to download the tegra headers (adapted from jetsonhacks install script):

wget http://developer.download.nvidia.com/embedded/L4T/r23_Release_v1.0/source/gstjpeg_src.tbz2
tar -xvf gstjpeg_src.tbz2 gstjpeg_src/nv_headers
mv gstjpeg_src/nv_headers/ libfreenect2/depends/
# Cleanup the empty folder
rmdir gstjpeg_src/

I also disabled VA-API support to ensure the Tegra version would be run. However, after all this, when I run `./bin/Protonect' I get the following error:

[Error] [libjpeg_handle()] dlsym: ./bin/Protonect: undefined symbol: jpeg_std_error

This error happens in src/packet_pipeline.cpp when the tegra processor is tested. The tegra->good() check results in the else running, deleting the tegra processor and defaulting to the turbo processor.

RgbPacketProcessor *tegra = new TegraJpegRgbPacketProcessor();
if (tegra->good())
    return tegra;
else {
    delete tegra;
}
return new TurboJpegRgbPacketProcessor();

I'm going to continue to debug the Tegra and CUDA optimizations tomorrow. Do you notice anything wrong that you know how to fix?

@xlz
Copy link
Member

xlz commented Feb 25, 2016

I had to replace the the current section in CMakeLists.txt relating to TegraJPEG

This will not work. And I'm unable to support the old CMake code. You can't simply mix the old code with new code and expect it to work.

If you take a look, https://github.com/OpenKinect/libfreenect2/blob/master/cmake_modules/FindTegraJPEG.cmake#L38, CMake supposedly downloads the headers to depends/gstjpeg/gstjpeg_src.tbz2 and extracts this tarball into build/gstjpeg_src/nv_headers.

Now the problem is somehow it fails to extract the headers. Some very trivial error happens here. It just needs someone with TX1 to take a look.

@xlz
Copy link
Member

xlz commented Feb 25, 2016

OK, I know the problem now.

@xlz
Copy link
Member

xlz commented Feb 25, 2016

@marketto89
Copy link

@xlz, sorry for not replying to #480 I have been busy.

I just tried your tree tegra-url and I confirm that now cmake downloads and extract the tarball.

Here is the final output:

ubuntu@tegra-ubuntu:~/workspace/libfreenect2/build$ cmake .. -DCMAKE_INSTALL_PREFIX=$HOME/freenect2
-- The C compiler identification is GNU 4.8.4
-- The CXX compiler identification is GNU 4.8.4
-- Check for working C compiler: /usr/bin/cc
-- Check for working C compiler: /usr/bin/cc -- works
-- Detecting C compiler ABI info
-- Detecting C compiler ABI info - done
-- Check for working CXX compiler: /usr/bin/c++
-- Check for working CXX compiler: /usr/bin/c++ -- works
-- Detecting CXX compiler ABI info
-- Detecting CXX compiler ABI info - done
-- using tinythread as threading library
-- Found PkgConfig: /usr/bin/pkg-config (found version "0.26") 
-- checking for module 'libusb-1.0>=1.0.20'
--   found libusb-1.0, version 1.0.20
-- checking for modules 'libva;libva-drm'
--   package 'libva' not found
--   package 'libva-drm' not found
-- Found JPEG: /usr/lib/arm-linux-gnueabihf/libjpeg.so  
-- Found Linux4Tegra 23.1.1
-- Downloading gstjpeg_src.tbz2 to /home/ubuntu/workspace/libfreenect2/depends...
-- Performing Test TegraJPEG_WORKS
-- Performing Test TegraJPEG_WORKS - Success
-- Found TegraJPEG: /usr/lib/arm-linux-gnueabihf/tegra/libnvjpeg.so  
-- Performing Test TURBOJPEG_WORKS
-- Performing Test TURBOJPEG_WORKS - Success
-- Found TurboJPEG: /usr/lib/arm-linux-gnueabihf/libturbojpeg.so.0  
-- checking for module 'glfw3'
--   found glfw3, version 3.1.2
-- Looking for XOpenDisplay in /usr/lib/arm-linux-gnueabihf/libX11.so;/usr/lib/arm-linux-gnueabihf/libXext.so
-- Looking for XOpenDisplay in /usr/lib/arm-linux-gnueabihf/libX11.so;/usr/lib/arm-linux-gnueabihf/libXext.so - found
-- Looking for gethostbyname
-- Looking for gethostbyname - found
-- Looking for connect
-- Looking for connect - found
-- Looking for remove
-- Looking for remove - found
-- Looking for shmat
-- Looking for shmat - found
-- Looking for IceConnectionNumber in ICE
-- Looking for IceConnectionNumber in ICE - found
-- Found X11: /usr/lib/arm-linux-gnueabihf/libX11.so
-- Found OpenGL: /usr/lib/arm-linux-gnueabihf/libGL.so  
-- Looking for CL_VERSION_2_0
-- Looking for CL_VERSION_2_0 - not found
-- Looking for CL_VERSION_1_2
-- Looking for CL_VERSION_1_2 - found
-- Found OpenCL: /usr/lib/arm-linux-gnueabihf/libOpenCL.so (found version "1.2") 
-- Performing Test OpenCL_C_WORKS
-- Performing Test OpenCL_C_WORKS - Success
-- Performing Test OpenCL_CXX_WORKS
-- Performing Test OpenCL_CXX_WORKS - Success
-- Found CUDA: /usr/local/cuda (found version "6.5") 
-- Performing Test COMPILER_HAS_HIDDEN_VISIBILITY
-- Performing Test COMPILER_HAS_HIDDEN_VISIBILITY - Success
-- Performing Test COMPILER_HAS_HIDDEN_INLINE_VISIBILITY
-- Performing Test COMPILER_HAS_HIDDEN_INLINE_VISIBILITY - Success
-- Performing Test COMPILER_HAS_DEPRECATED_ATTR
-- Performing Test COMPILER_HAS_DEPRECATED_ATTR - Success
-- Linking with these libraries: 
 /usr/lib/arm-linux-gnueabihf/libusb-1.0.so
 pthread
 dl
 /usr/lib/arm-linux-gnueabihf/libturbojpeg.so.0
 /usr/lib/arm-linux-gnueabihf/libglfw.so
 /usr/lib/arm-linux-gnueabihf/libGL.so
 /usr/lib/arm-linux-gnueabihf/libOpenCL.so
 /usr/local/cuda/lib/libcudart.so
-- Found Doxygen: /usr/bin/doxygen (found version "1.8.6") 
-- Configurating examples
-- Using in-tree freenect2 target
-- checking for module 'libopenni2'
--   package 'libopenni2' not found
-- Could NOT find OpenNI2 (missing:  OpenNI2_LIBRARY_DIR OpenNI2_INCLUDE_DIRS) 
-- Feature list:
--   CUDA    yes
--   CXX11    disabled
--   Examples    yes
--   OpenCL    yes
--   OpenGL    yes
--   OpenNI2    no
--   TegraJPEG    yes
--   Threading    tinythread
--   TurboJPEG    yes
--   VAAPI    no
--   VideoToolbox    no (Apple only)
-- Configuring done
-- Generating done
-- Build files have been written to: /home/ubuntu/workspace/libfreenect2/build
ubuntu@tegra-ubuntu:~/workspace/libfreenect2/build$

Nevertheless, it seems that Protonect has still problems:

ubuntu@tegra-ubuntu:~/workspace/libfreenect2/build$ ./bin/Protonect cuda -noviewer
Version: 0.2.0
Environment variables: LOGFILE=<protonect.log>
Usage: ./bin/Protonect [-gpu=<id>] [gl | cl | cuda | cpu] [<device serial>]
        [-noviewer] [-norgb | -nodepth] [-help] [-version]
        [-frames <number of frames to process>]
To pause and unpause: pkill -USR1 Protonect
[Info] [CudaDepthPacketProcessorImpl] device 0: GM20B @ 72MHz Memory 3853MB
[Info] [CudaDepthPacketProcessorImpl] selected device 0
[Info] [Freenect2Impl] enumerating devices...
[Info] [Freenect2Impl] 6 usb devices connected
[Info] [Freenect2Impl] found valid Kinect v2 @2:4 with serial 010354144947
[Info] [Freenect2Impl] found 1 devices
[Info] [Freenect2DeviceImpl] opening...
[Info] [Freenect2DeviceImpl] opened
[Info] [Freenect2DeviceImpl] starting...
[Debug] [Freenect2DeviceImpl] status 0x090000: 9763
[Debug] [Freenect2DeviceImpl] status 0x090000: 9763
[Info] [Freenect2DeviceImpl] submitting rgb transfers...
[Info] [Freenect2DeviceImpl] submitting depth transfers...
[Info] [Freenect2DeviceImpl] started
device serial: 010354144947
device firmware: 2.3.3913.0
[Error] [RgbPacketStreamParser] packetsize or sequence doesn't match!
[Info] [TegraJpegRgbPacketProcessor] avg. time: 0ms -> ~infHz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 0ms -> ~infHz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 0ms -> ~infHz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 0ms -> ~infHz
Killed

@marketto89
Copy link

After some reboots it seems that TegraJpeg started to work, but I still can't see any depth information from the output.

ubuntu@tegra-ubuntu:~/workspace/libfreenect2_xlz/build$ ./bin/Protonect cuda -noviewer
Version: 0.2.0
Environment variables: LOGFILE=<protonect.log>
Usage: ./bin/Protonect [-gpu=<id>] [gl | cl | cuda | cpu] [<device serial>]
        [-noviewer] [-norgb | -nodepth] [-help] [-version]
        [-frames <number of frames to process>]
To pause and unpause: pkill -USR1 Protonect
[Info] [CudaDepthPacketProcessorImpl] device 0: GM20B @ 72MHz Memory 3853MB
[Info] [CudaDepthPacketProcessorImpl] selected device 0
[Info] [Freenect2Impl] enumerating devices...
[Info] [Freenect2Impl] 6 usb devices connected
[Info] [Freenect2Impl] found valid Kinect v2 @2:10 with serial 010354144947
[Info] [Freenect2Impl] found 1 devices
[Info] [Freenect2DeviceImpl] opening...
[Info] [Freenect2DeviceImpl] opened
[Info] [Freenect2DeviceImpl] starting...
[Debug] [Freenect2DeviceImpl] status 0x090000: 9855
[Debug] [Freenect2DeviceImpl] status 0x090000: 9855
[Info] [Freenect2DeviceImpl] submitting rgb transfers...
[Info] [Freenect2DeviceImpl] submitting depth transfers...
[Info] [Freenect2DeviceImpl] started
device serial: 010354144947
device firmware: 2.3.3913.0
[Info] [TegraJpegRgbPacketProcessor] avg. time: 5.3481ms -> ~186.982Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 5.29576ms -> ~188.83Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 5.19811ms -> ~192.378Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 5.21103ms -> ~191.9Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 4.97272ms -> ~201.097Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 4.98701ms -> ~200.521Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 4.91539ms -> ~203.443Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 4.93047ms -> ~202.82Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 4.93109ms -> ~202.795Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 5.03911ms -> ~198.448Hz
Killed

@menlocaleb, how did you set your TX1 for max performance? My CPU speed is 1.9 GHz, the GPU clock speed is 998.4 MHz and the GPU memory clock is 1.6 GHz. Do these numbers make sense to you?

@xlz
Copy link
Member

xlz commented Feb 25, 2016

@marketto89 Your setup is different from @menlocaleb

@menlocaleb has been using a uPD720202 extension card with patched libusb.

Right now both of you could not get libfreenect2 to work with the built-in USB 3 port.

Regarding the built-in USB 3 port, there are several things to verify:

(See the logs here #480 (comment))

@marketto89
Copy link

Does LIBUSB_DEBUG=4 ./bin/Protonect show [handle_iso_completion] low-level USB error -18?

Yes I see many of these errors!

What does dmesg show?

Here is the tail of my dmesg:

[17471.437320] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.471820] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.477565] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.501194] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.535944] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.539829] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.566815] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.569314] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.605003] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.605137] smmu_dump_pagetable(): fault_address=0x0000000080200000 pa=0x0000000000000000 bytes=1000 #pte=492 in L2
[17471.605178] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.605181] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.605422] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.605425] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.605665] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.605668] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.605881] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.605926] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.605929] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.617827] mc-err: [mcerr] (20) csw_xusb_hostw: EMEM decode error on PDE or PTE entry
[17471.627947] mc-err: [mcerr]   status = 0x6001004b; addr = 0x80200000
[17471.635432] mc-err: [mcerr]   secure: no, access-type: write, SMMU fault: nr-nw-s
[17471.636089] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.649069] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.700755] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.700894] smmu_dump_pagetable(): fault_address=0x0000000080280000 pa=0x0000000000000000 bytes=1000 #pte=412 in L2
[17471.700926] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.700929] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.701175] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.701178] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.701428] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.701431] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.701678] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.701681] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.701684] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.703533] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.703674] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.703678] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.703924] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.703927] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.704175] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.704179] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.704426] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.704429] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.704432] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.706209] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.710710] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.713596] mc-err: [mcerr] (20) csw_xusb_hostw: EMEM decode error on PDE or PTE entry
[17471.723732] mc-err: [mcerr]   status = 0x6001004b; addr = 0x80280000
[17471.731221] mc-err: [mcerr]   secure: no, access-type: write, SMMU fault: nr-nw-s
[17471.732863] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.737584] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.866825] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.871447] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.877564] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.905003] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.905145] smmu_dump_pagetable(): fault_address=0x0000000080180000 pa=0x0000000000000000 bytes=1000 #pte=413 in L2
[17471.905180] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.905184] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.905438] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.905441] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.905679] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.905683] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.905923] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.905926] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.905929] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.917837] mc-err: [mcerr] (20) csw_xusb_hostw: EMEM decode error on PDE or PTE entry
[17471.927969] mc-err: [mcerr]   status = 0x6001004b; addr = 0x80180000
[17471.935453] mc-err: [mcerr]   secure: no, access-type: write, SMMU fault: nr-nw-s
[17471.944067] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17471.949572] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.009198] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.042946] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.099447] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.102693] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.109445] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.110688] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.137628] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.137776] smmu_dump_pagetable(): fault_address=0x0000000080180000 pa=0x0000000000000000 bytes=1000 #pte=418 in L2
[17472.137804] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.137808] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.137812] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.138065] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.138191] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.138631] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.138635] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.150472] mc-err: [mcerr] (20) csw_xusb_hostw: EMEM decode error on PDE or PTE entry
[17472.160603] mc-err: [mcerr]   status = 0x6001004b; addr = 0x80180000
[17472.168070] mc-err: [mcerr]   secure: no, access-type: write, SMMU fault: nr-nw-s
[17472.173080] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.175080] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.216314] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.235941] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.241696] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.249576] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.269316] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.274932] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.302693] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.304943] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.308444] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.315569] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.333314] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.338694] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.340066] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.341438] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.367940] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.382943] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.401256] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.401391] smmu_dump_pagetable(): fault_address=0x0000000080180000 pa=0x0000000000000000 bytes=1000 #pte=418 in L2
[17472.401424] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.401428] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.401680] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.401683] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.401686] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.401809] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.401925] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.401928] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.402174] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.402177] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.403704] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.409332] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.414108] mc-err: [mcerr] (20) csw_xusb_hostw: EMEM decode error on PDE or PTE entry
[17472.424305] mc-err: [mcerr]   status = 0x6001004b; addr = 0x80180000
[17472.431803] mc-err: [mcerr]   secure: no, access-type: write, SMMU fault: nr-nw-s
[17472.434236] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.444499] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.444619] mc-err: Too many MC errors; throttling prints
[17472.444674] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.444678] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.444681] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.444911] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.444937] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.444940] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.445075] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.445178] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.445181] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.445425] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.445429] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.445432] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.507697] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.510438] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.541692] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.549570] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.575695] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.577063] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.600696] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.604940] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.616083] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.637565] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.642567] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.648837] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.666348] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.682804] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.699442] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.701193] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.706693] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.709182] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.733069] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.799948] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.844447] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.866068] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.867925] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17472.874211] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 8 with no TDs queued?
[17473.079991] tegra-xhci tegra-xhci: Signal while waiting for configure endpoint command
[17610.554117] usb 2-2.1: reset SuperSpeed USB device number 12 using tegra-xhci
[17610.582148] usb 2-2.1: Parent hub missing LPM exit latency info.  Power management will be impacted.
[17610.605448] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 2 with no TDs queued?
[17610.701931] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 2 with no TDs queued?
[17610.710400] tegra-xhci tegra-xhci: WARN Event TRB for slot 3 ep 2 with no TDs queued?

Does patching and building libusb 1.0.20 (instructions: #581 (comment)) from source make it work?

I will inform you if this fix works!

@marketto89
Copy link

Does patching and building libusb 1.0.20 (instructions: #581 (comment)) from source make it work?

I followed the instructions and verified that Protonect was linked to the patched libusb but it is still not working:

ubuntu@tegra-ubuntu:~/workspace/libfreenect2_xlz/build$ DISPLAY=:0.0 ./bin/Protonect cuda  
Version: 0.2.0
Environment variables: LOGFILE=<protonect.log>
Usage: ./bin/Protonect [-gpu=<id>] [gl | cl | cuda | cpu] [<device serial>]
        [-noviewer] [-norgb | -nodepth] [-help] [-version]
        [-frames <number of frames to process>]
To pause and unpause: pkill -USR1 Protonect
[Info] [CudaDepthPacketProcessorImpl] device 0: GM20B @ 72MHz Memory 3853MB
[Info] [CudaDepthPacketProcessorImpl] selected device 0
[Info] [Freenect2Impl] enumerating devices...
[Info] [Freenect2Impl] 6 usb devices connected
[Info] [Freenect2Impl] found valid Kinect v2 @2:4 with serial 010354144947
[Info] [Freenect2Impl] found 1 devices
[Info] [Freenect2DeviceImpl] opening...
[Info] [Freenect2DeviceImpl] opened
[Info] [Freenect2DeviceImpl] starting...
[Debug] [Freenect2DeviceImpl] status 0x090000: 9729
[Debug] [Freenect2DeviceImpl] status 0x090000: 9739
[Info] [Freenect2DeviceImpl] submitting rgb transfers...
[Info] [Freenect2DeviceImpl] submitting depth transfers...
[Info] [Freenect2DeviceImpl] started
device serial: 010354144947
device firmware: 2.3.3913.0
[Info] [TegraJpegRgbPacketProcessor] avg. time: 5.56633ms -> ~179.651Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 5.32445ms -> ~187.813Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 5.17759ms -> ~193.14Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 5.12778ms -> ~195.016Hz
[Info] [TegraJpegRgbPacketProcessor] avg. time: 5.15028ms -> ~194.164Hz
Killed

@xlz
Copy link
Member

xlz commented Feb 25, 2016

OK this confirms it's the same USB kernel driver issue as last time. There is no solution to that yet. I will try to contact Nvidia developers about this bug.

In the meantime, I think the best workaround is to acquire a uPD720202 extension card as menlocaleb did.

@xlz
Copy link
Member

xlz commented Feb 25, 2016

@marketto89
Copy link

Given the answers, is there anything we can do to test the built-in USB 3.0 port?

@xlz
Copy link
Member

xlz commented Mar 2, 2016

@marketto89 I think the easiest thing to do right now is get a uPD720202 extension card.

@xlz
Copy link
Member

xlz commented Mar 11, 2016

I have obtained a TX1 and I have reproduced all the errors you've had.

I'm working on it, but this one is really hard.

@menlocaleb
Copy link
Author

@xlz sorry for not responding on this thread recently. I was just looking into this problem again and went to try your new branch https://github.com/xlz/libfreenect2/tree/tegra-url but it looks like it's deleted. Was the problem just changing a url for the jpeg headers to be compatible with the X1?

Is there anything I should try to help, or should I wait for you to fix on your X1?

@xlz
Copy link
Member

xlz commented Mar 16, 2016

@menlocaleb I thought your had it working #581 (comment), what is the new problem?

tegra-url is merged into upstream so it's deleted.

I have put the recommendation of "uPD720202 extension card with libusb 49152" into docs. I can't fix this issue because it's a problem with Nvidia's tegra kernel driver.

@menlocaleb
Copy link
Author

Sorry for not being specific: I can run the upstream libfreenect, I was working on fixing the tegra acceleration, which it sounds like should work now that you've checked in the fix.

Last time I tried the iai_kinect2 code was crashing, but maybe after the tegra acceleration fix and rebuilding it will work. If it doesn't I'll let you know.

@xlz xlz added the arm label Mar 23, 2016
@RedAlice64
Copy link

@xlz @menlocaleb

Hi,
I am following the instructions and I am still getting streams of image data too short and subpacket too large.

Here's the message from
LIBUSB_DEBUG=4 ./bin/Protonect cuda

`Version: 0.2.0
Environment variables: LOGFILE=<protonect.log>
Usage: ./bin/Protonect [-gpu=] [gl | cl | cuda | cpu] []
[-noviewer] [-norgb | -nodepth] [-help] [-version]
[-frames ]
To pause and unpause: pkill -USR1 Protonect
[timestamp] [threadID] facility level [function call]

[ 0.000005] [00000cac] libusb: debug [libusb_init] created default context
[ 0.000056] [00000cac] libusb: debug [libusb_init] libusb v1.0.20.11004
[ 0.000121] [00000cac] libusb: debug [find_usbfs_path] found usbfs at /dev/bus/usb
[ 0.000151] [00000cac] libusb: debug [op_init] bulk continuation flag supported
[ 0.000166] [00000cac] libusb: debug [op_init] zero length packet flag supported
[ 0.000197] [00000cac] libusb: debug [op_init] sysfs can relate devices
[ 0.000210] [00000cac] libusb: debug [op_init] sysfs has complete descriptors
[ 0.000494] [00000cad] libusb: debug [linux_udev_event_thread_main] udev event thread entering.
[ 0.001665] [00000cac] libusb: debug [linux_get_device_address] getting address for device: usb1 detached: 0
[ 0.001695] [00000cac] libusb: debug [linux_get_device_address] scan usb1
[ 0.001836] [00000cac] libusb: debug [linux_get_device_address] bus=1 dev=1
[ 0.001852] [00000cac] libusb: debug [linux_enumerate_device] busnum 1 devaddr 1 session_id 257
[ 0.001865] [00000cac] libusb: debug [linux_enumerate_device] allocating new device for 1/1 (session 257)
[ 0.002191] [00000cac] libusb: debug [linux_get_device_address] getting address for device: 1-1 detached: 0
[ 0.002207] [00000cac] libusb: debug [linux_get_device_address] scan 1-1
[ 0.002331] [00000cac] libusb: debug [linux_get_device_address] bus=1 dev=2
[ 0.002345] [00000cac] libusb: debug [linux_enumerate_device] busnum 1 devaddr 2 session_id 258
[ 0.002357] [00000cac] libusb: debug [linux_enumerate_device] allocating new device for 1/2 (session 258)
[ 0.002475] [00000cac] libusb: debug [linux_get_parent_info] Dev 0x1c920 (1-1) has parent 0x1cbd8 (usb1) port 1
[ 0.002678] [00000cac] libusb: debug [linux_get_device_address] getting address for device: 1-2 detached: 0
[ 0.002693] [00000cac] libusb: debug [linux_get_device_address] scan 1-2
[ 0.002815] [00000cac] libusb: debug [linux_get_device_address] bus=1 dev=3
[ 0.002830] [00000cac] libusb: debug [linux_enumerate_device] busnum 1 devaddr 3 session_id 259
[ 0.002841] [00000cac] libusb: debug [linux_enumerate_device] allocating new device for 1/3 (session 259)
[ 0.002949] [00000cac] libusb: debug [linux_get_parent_info] Dev 0x1cc50 (1-2) has parent 0x1cbd8 (usb1) port 2
[ 0.003146] [00000cac] libusb: debug [linux_get_device_address] getting address for device: usb2 detached: 0
[ 0.003161] [00000cac] libusb: debug [linux_get_device_address] scan usb2
[ 0.003282] [00000cac] libusb: debug [linux_get_device_address] bus=2 dev=1
[ 0.003296] [00000cac] libusb: debug [linux_enumerate_device] busnum 2 devaddr 1 session_id 513
[ 0.003307] [00000cac] libusb: debug [linux_enumerate_device] allocating new device for 2/1 (session 513)
[ 0.003588] [00000cac] libusb: debug [linux_get_device_address] getting address for device: 2-1 detached: 0
[ 0.003603] [00000cac] libusb: debug [linux_get_device_address] scan 2-1
[ 0.003727] [00000cac] libusb: debug [linux_get_device_address] bus=2 dev=2
[ 0.003742] [00000cac] libusb: debug [linux_enumerate_device] busnum 2 devaddr 2 session_id 514
[ 0.003754] [00000cac] libusb: debug [linux_enumerate_device] allocating new device for 2/2 (session 514)
[ 0.003860] [00000cac] libusb: debug [linux_get_parent_info] Dev 0x1e110 (2-1) has parent 0x1c998 (usb2) port 1
[ 0.003971] [00000cac] libusb: debug [linux_get_device_address] getting address for device: 2-1.1 detached: 0
[ 0.003986] [00000cac] libusb: debug [linux_get_device_address] scan 2-1.1
[ 0.004110] [00000cac] libusb: debug [linux_get_device_address] bus=2 dev=3
[ 0.004125] [00000cac] libusb: debug [linux_enumerate_device] busnum 2 devaddr 3 session_id 515
[ 0.004136] [00000cac] libusb: debug [linux_enumerate_device] allocating new device for 2/3 (session 515)
[ 0.004266] [00000cac] libusb: debug [linux_get_parent_info] Dev 0x1ca10 (2-1.1) has parent 0x1e110 (2-1) port 1
[ 0.004831] [00000cac] libusb: debug [linux_get_device_address] getting address for device: usb4 detached: 0
[ 0.004847] [00000cac] libusb: debug [linux_get_device_address] scan usb4
[ 0.004964] [00000cac] libusb: debug [linux_get_device_address] bus=4 dev=1
[ 0.004978] [00000cac] libusb: debug [linux_enumerate_device] busnum 4 devaddr 1 session_id 1025
[ 0.004989] [00000cac] libusb: debug [linux_enumerate_device] allocating new device for 4/1 (session 1025)
[ 0.005248] [00000cac] libusb: debug [linux_get_device_address] getting address for device: usb5 detached: 0
[ 0.005262] [00000cac] libusb: debug [linux_get_device_address] scan usb5
[ 0.005377] [00000cac] libusb: debug [linux_get_device_address] bus=5 dev=1
[ 0.005392] [00000cac] libusb: debug [linux_enumerate_device] busnum 5 devaddr 1 session_id 1281
[ 0.005403] [00000cac] libusb: debug [linux_enumerate_device] allocating new device for 5/1 (session 1281)
[ 0.005676] [00000cac] libusb: debug [linux_get_device_address] getting address for device: 5-1 detached: 0
[ 0.005692] [00000cac] libusb: debug [linux_get_device_address] scan 5-1
[ 0.005812] [00000cac] libusb: debug [linux_get_device_address] bus=5 dev=2
[ 0.005827] [00000cac] libusb: debug [linux_enumerate_device] busnum 5 devaddr 2 session_id 1282
[ 0.005839] [00000cac] libusb: debug [linux_enumerate_device] allocating new device for 5/2 (session 1282)
[ 0.005940] [00000cac] libusb: debug [linux_get_parent_info] Dev 0x1f298 (5-1) has parent 0x1ee18 (usb5) port 1
[ 0.006121] [00000cac] libusb: debug [linux_get_device_address] getting address for device: usb3 detached: 0
[ 0.006135] [00000cac] libusb: debug [linux_get_device_address] scan usb3
[ 0.006250] [00000cac] libusb: debug [linux_get_device_address] bus=3 dev=1
[ 0.006263] [00000cac] libusb: debug [linux_enumerate_device] busnum 3 devaddr 1 session_id 769
[ 0.006275] [00000cac] libusb: debug [linux_enumerate_device] allocating new device for 3/1 (session 769)
[ 0.006531] [00000cac] libusb: debug [linux_get_device_address] getting address for device: 3-1 detached: 0
[ 0.006545] [00000cac] libusb: debug [linux_get_device_address] scan 3-1
[ 0.006665] [00000cac] libusb: debug [linux_get_device_address] bus=3 dev=2
[ 0.006680] [00000cac] libusb: debug [linux_enumerate_device] busnum 3 devaddr 2 session_id 770
[ 0.006692] [00000cac] libusb: debug [linux_enumerate_device] allocating new device for 3/2 (session 770)
[ 0.006789] [00000cac] libusb: debug [linux_get_parent_info] Dev 0x1fbf0 (3-1) has parent 0x1f780 (usb3) port 1
[ 0.007012] [00000cac] libusb: debug [usbi_add_pollfd] add fd 7 events 1
[ 0.007048] [00000cac] libusb: debug [usbi_io_init] using timerfd for timeouts
[ 0.007061] [00000cac] libusb: debug [usbi_add_pollfd] add fd 9 events 1
[ 0.007186] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.007208] [00000cae] libusb: debug [handle_events] poll fds modified, reallocating
[ 0.007343] [00000cae] libusb: debug [handle_events] poll() 2 fds with timeout in 100ms
[ 0.107518] [00000cae] libusb: debug [handle_events] poll() returned 0
[ 0.107577] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.107590] [00000cae] libusb: debug [handle_events] poll() 2 fds with timeout in 100ms
[ 0.207809] [00000cae] libusb: debug [handle_events] poll() returned 0
[ 0.207888] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.207908] [00000cae] libusb: debug [handle_events] poll() 2 fds with timeout in 100ms
[ 0.295006] [00000cac] libusb: debug [libusb_get_device_list]
[ 0.295079] [00000cac] libusb: debug [discovered_devs_append] need to increase capacity
[ 0.295146] [00000cac] libusb: debug [libusb_get_device_descriptor]
[ 0.295164] [00000cac] libusb: debug [libusb_get_device_descriptor]
[ 0.295176] [00000cac] libusb: debug [libusb_get_device_descriptor]
[ 0.295211] [00000cac] libusb: debug [libusb_get_device_descriptor]
[ 0.295223] [00000cac] libusb: debug [libusb_get_device_descriptor]
[ 0.295235] [00000cac] libusb: debug [libusb_get_device_descriptor]
[ 0.295248] [00000cac] libusb: debug [libusb_open] open 2.3
[ 0.308051] [00000cae] libusb: debug [handle_events] poll() returned 0
[ 0.308090] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.308104] [00000cae] libusb: debug [handle_events] poll() 2 fds with timeout in 100ms
[ 0.408790] [00000cae] libusb: debug [handle_events] poll() returned 0
[ 0.409249] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.409455] [00000cae] libusb: debug [handle_events] poll() 2 fds with timeout in 100ms
[ 0.444477] [00000cac] libusb: debug [usbi_add_pollfd] add fd 54 events 4
[ 0.445062] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6127b8
[ 0.445310] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x6127b8
[ 0.445340] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.445945] [00000cae] libusb: debug [handle_events] caught a fish on the event pipe
[ 0.446185] [00000cae] libusb: debug [handle_events] someone updated the poll fds
[ 0.445595] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.446445] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.447041] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.447399] [00000cae] libusb: debug [handle_events] poll fds modified, reallocating
[ 0.448416] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.448719] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.448988] [00000cae] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.449194] [00000cae] libusb: debug [handle_control_completion] handling completion status 0
[ 0.449386] [00000cae] libusb: debug [disarm_timerfd]
[ 0.449598] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x6127b8 has callback 0xf6ef521d
[ 0.449797] [00000cae] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.450143] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.450380] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.450511] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x6127b8
[ 0.450887] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6127b8
[ 0.451372] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x6127b8
[ 0.451588] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.451964] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.452658] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.452940] [00000cae] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=26
[ 0.453145] [00000cae] libusb: debug [handle_control_completion] handling completion status 0
[ 0.453340] [00000cae] libusb: debug [disarm_timerfd]
[ 0.453551] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x6127b8 has callback 0xf6ef521d
[ 0.453773] [00000cae] libusb: debug [sync_transfer_cb] actual_length=26
[ 0.454084] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.454322] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.454472] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x6127b8
[ 0.454877] [00000cac] libusb: debug [libusb_close]
[ 0.455508] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.455798] [00000cae] libusb: debug [handle_events] caught a fish on the event pipe
[ 0.455996] [00000cae] libusb: debug [handle_events] someone is closing a device
[ 0.456269] [00000cae] libusb: debug [libusb_try_lock_events] someone else is closing a device
[ 0.456503] [00000cae] libusb: debug [libusb_event_handler_active] someone else is closing a device
[ 0.456897] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.457569] [00000cac] libusb: debug [usbi_remove_pollfd] remove fd 54
[ 0.457875] [00000cae] libusb: debug [libusb_try_lock_events] someone else is closing a device
[ 0.458200] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] event handler was active but went away, retrying
[ 0.458403] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.458587] [00000cae] libusb: debug [handle_events] poll fds modified, reallocating
[ 0.458872] [00000cae] libusb: debug [handle_events] poll() 2 fds with timeout in 100ms
[ 0.459057] [00000cac] libusb: debug [libusb_get_device_descriptor]
[ 0.459335] [00000cac] libusb: debug [libusb_get_device_descriptor]
[ 0.459533] [00000cac] libusb: debug [libusb_get_device_descriptor]
[ 0.459718] [00000cac] libusb: debug [libusb_get_device_descriptor]
[ 0.459900] [00000cac] libusb: debug [libusb_get_device_descriptor]
[ 0.461298] [00000cac] libusb: debug [libusb_open] open 2.3
[ 0.462016] [00000cac] libusb: debug [usbi_add_pollfd] add fd 54 events 4
[ 0.462390] [00000cac] libusb: debug [libusb_reset_device]
[ 0.462716] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.463032] [00000cae] libusb: debug [handle_events] caught a fish on the event pipe
[ 0.463235] [00000cae] libusb: debug [handle_events] someone updated the poll fds
[ 0.463475] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.463666] [00000cae] libusb: debug [handle_events] poll fds modified, reallocating
[ 0.463962] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.564341] [00000cae] libusb: debug [handle_events] poll() returned 0
[ 0.564459] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.564516] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.587108] [00000cac] libusb: debug [libusb_get_configuration]
[ 0.587669] [00000cac] libusb: debug [libusb_get_configuration] active config 1
[ 0.587817] [00000cac] libusb: debug [libusb_claim_interface] interface 0
[ 0.588033] [00000cac] libusb: debug [libusb_claim_interface] interface 1
[ 0.588298] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6129d0
[ 0.588422] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x6129d0
[ 0.588525] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.588717] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.589249] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.589442] [00000cae] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=0
[ 0.589551] [00000cae] libusb: debug [handle_control_completion] handling completion status 0
[ 0.589650] [00000cae] libusb: debug [disarm_timerfd]
[ 0.589759] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x6129d0 has callback 0xf6ef521d
[ 0.589859] [00000cae] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.590020] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.590122] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.590310] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x6129d0
[ 0.590445] [00000cac] libusb: debug [libusb_set_interface_alt_setting] interface 1 altsetting 0
[ 0.591181] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6129d0
[ 0.591395] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x6129d0
[ 0.591509] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.591702] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.592111] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.592421] [00000cae] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=0
[ 0.592526] [00000cae] libusb: debug [handle_control_completion] handling completion status 0
[ 0.592625] [00000cae] libusb: debug [disarm_timerfd]
[ 0.592729] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x6129d0 has callback 0xf6ef521d
[ 0.592830] [00000cae] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.592988] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.593041] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x6129d0
[ 0.593147] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.593325] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6129d0
[ 0.593583] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x6129d0
[ 0.593694] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.593888] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.594367] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.594520] [00000cae] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=0
[ 0.594625] [00000cae] libusb: debug [handle_control_completion] handling completion status 0
[ 0.594726] [00000cae] libusb: debug [disarm_timerfd]
[ 0.594833] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x6129d0 has callback 0xf6ef521d
[ 0.594936] [00000cae] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.595097] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.595205] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.595388] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x6129d0
[ 0.595510] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6129d0
[ 0.595608] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x6129d0
[ 0.595708] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.595884] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.596369] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.596554] [00000cae] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=0
[ 0.596661] [00000cae] libusb: debug [handle_control_completion] handling completion status 0
[ 0.596762] [00000cae] libusb: debug [disarm_timerfd]
[ 0.596871] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x6129d0 has callback 0xf6ef521d
[ 0.596970] [00000cae] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.597125] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.597231] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.597428] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x6129d0
[ 0.597628] [00000cac] libusb: debug [parse_configuration] skipping descriptor 0xb
[ 0.597745] [00000cac] libusb: debug [parse_endpoint] skipping descriptor 30
[ 0.597845] [00000cac] libusb: debug [parse_endpoint] skipping descriptor 30
[ 0.597946] [00000cac] libusb: debug [parse_endpoint] skipping descriptor 30
[ 0.598046] [00000cac] libusb: debug [parse_endpoint] skipping descriptor 30
[ 0.598155] [00000cac] libusb: debug [parse_endpoint] skipping descriptor 30
[ 0.598250] [00000cac] libusb: debug [parse_endpoint] skipping descriptor b
[ 0.598369] [00000cac] libusb: debug [parse_endpoint] skipping descriptor 30
[ 0.598467] [00000cac] libusb: debug [parse_endpoint] skipping descriptor 25
[ 0.600811] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x612ac8
[ 0.600955] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x612b68
[ 0.601233] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x612c08
[ 0.601339] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x612ca8
[ 0.601459] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x612d48
[ 0.601595] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x612de8
[ 0.601614] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x612e88
[ 0.601632] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x612f28
[ 0.601649] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x612fc8
[ 0.601666] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613068
[ 0.601684] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613108
[ 0.601701] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6131a8
[ 0.601719] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613248
[ 0.601735] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6132e8
[ 0.601752] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613388
[ 0.601769] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613428
[ 0.601786] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6134c8
[ 0.601803] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613568
[ 0.601820] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613608
[ 0.601837] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6136a8
[ 0.601881] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613a20
[ 0.601903] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613b20
[ 0.601921] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613c20
[ 0.601938] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613d20
[ 0.601955] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613e20
[ 0.601972] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x613f20
[ 0.601991] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614020
[ 0.602008] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614120
[ 0.602025] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614220
[ 0.602041] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614320
[ 0.602058] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614420
[ 0.602074] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614520
[ 0.602091] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614620
[ 0.602108] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614720
[ 0.602124] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614820
[ 0.602140] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614920
[ 0.602157] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614a20
[ 0.602173] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614b20
[ 0.602191] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614c20
[ 0.602207] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614d20
[ 0.602224] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614e20
[ 0.602240] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x614f20
[ 0.602256] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615020
[ 0.602272] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615120
[ 0.602288] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615220
[ 0.602305] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615320
[ 0.602325] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615420
[ 0.602343] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615520
[ 0.602360] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615620
[ 0.602376] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615720
[ 0.602393] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615820
[ 0.602409] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615920
[ 0.602426] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615a20
[ 0.602442] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615b20
[ 0.602459] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615c20
[ 0.602476] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615d20
[ 0.602493] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615e20
[ 0.602537] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x615f20
[ 0.602556] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616020
[ 0.602572] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616120
[ 0.602588] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616220
[ 0.602605] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616320
[ 0.602621] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616420
[ 0.602637] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616520
[ 0.602653] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616620
[ 0.602669] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616720
[ 0.602685] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616820
[ 0.602702] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616920
[ 0.602718] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616a20
[ 0.602735] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616b20
[ 0.602751] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616c20
[ 0.602766] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616d20
[ 0.602783] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616e20
[ 0.602799] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x616f20
[ 0.602817] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617020
[ 0.602834] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617120
[ 0.602850] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617220
[ 0.602865] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617320
[ 0.602881] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617420
[ 0.602897] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617520
[ 0.603070] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617698
[ 0.603099] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617698
[ 0.603118] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.603166] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.603519] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.603574] [00000cae] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=0
[ 0.603595] [00000cae] libusb: debug [handle_control_completion] handling completion status 0
[ 0.603615] [00000cae] libusb: debug [disarm_timerfd]
[ 0.603635] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617698 has callback 0xf6ef521d
[ 0.603670] [00000cae] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.603705] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.603725] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.604516] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617698
[ 0.604573] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6178a0
[ 0.604593] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x6178a0
[ 0.604612] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.604637] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 20
[ 0.604677] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.604713] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.604747] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=20
[ 0.604766] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.604784] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.604802] [00000cae] libusb: debug [disarm_timerfd]
[ 0.604822] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x6178a0 has callback 0xf6ef521d
[ 0.604838] [00000cae] libusb: debug [sync_transfer_cb] actual_length=20
[ 0.604866] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.604917] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.604951] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x6178a0
[ 0.604984] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6178a0
[ 0.605001] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x6178a0
[ 0.605018] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.605040] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 512
[ 0.605072] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.641200] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.641251] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=512
[ 0.641265] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.641278] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.641291] [00000cae] libusb: debug [disarm_timerfd]
[ 0.641306] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x6178a0 has callback 0xf6ef521d
[ 0.641320] [00000cae] libusb: debug [sync_transfer_cb] actual_length=512
[ 0.641344] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.641358] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.641385] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x6178a0
[ 0.641409] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6178a0
[ 0.641422] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x6178a0
[ 0.641434] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.641450] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.641476] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.641528] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.641551] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.641563] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.641575] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.641587] [00000cae] libusb: debug [disarm_timerfd]
[ 0.641600] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x6178a0 has callback 0xf6ef521d
[ 0.641612] [00000cae] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.641631] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.641643] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.641669] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x6178a0
[ 0.641724] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6178a0
[ 0.641740] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x6178a0
[ 0.641753] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.641768] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 20
[ 0.641791] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.641846] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.641868] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=20
[ 0.641881] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.641893] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.641904] [00000cae] libusb: debug [disarm_timerfd]
[ 0.641917] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x6178a0 has callback 0xf6ef521d
[ 0.641929] [00000cae] libusb: debug [sync_transfer_cb] actual_length=20
[ 0.641949] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.641988] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.641988] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x6178a0
[ 0.642025] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6178a0
[ 0.642038] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x6178a0
[ 0.642050] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.642064] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 92
[ 0.642085] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.642138] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.642160] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=92
[ 0.642172] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.642184] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.642196] [00000cae] libusb: debug [disarm_timerfd]
[ 0.642208] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x6178a0 has callback 0xf6ef521d
[ 0.642220] [00000cae] libusb: debug [sync_transfer_cb] actual_length=92
[ 0.642238] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.642250] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.642277] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x6178a0
[ 0.642297] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x6178a0
[ 0.642309] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x6178a0
[ 0.642321] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.642335] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.642355] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.642406] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.642428] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.642441] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.642453] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.642464] [00000cae] libusb: debug [disarm_timerfd]
[ 0.642477] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x6178a0 has callback 0xf6ef521d
[ 0.642489] [00000cae] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.642506] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.642518] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.642544] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x6178a0
[ 0.642566] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617970
[ 0.642578] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617970
[ 0.642590] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.642605] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 24
[ 0.642625] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.642678] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.642699] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=24
[ 0.642712] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.642723] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.642735] [00000cae] libusb: debug [disarm_timerfd]
[ 0.642749] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617970 has callback 0xf6ef521d
[ 0.642760] [00000cae] libusb: debug [sync_transfer_cb] actual_length=24
[ 0.642778] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.642807] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.642817] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617970
[ 0.642838] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617970
[ 0.642850] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617970
[ 0.642861] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.642875] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 128
[ 0.642896] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.642948] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.642970] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=128
[ 0.642982] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.642994] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.643005] [00000cae] libusb: debug [disarm_timerfd]
[ 0.643018] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617970 has callback 0xf6ef521d
[ 0.643030] [00000cae] libusb: debug [sync_transfer_cb] actual_length=128
[ 0.643047] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.643059] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.643086] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617970
[ 0.643106] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617970
[ 0.643117] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617970
[ 0.643129] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.643143] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.643163] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.643184] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.643201] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.643213] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.643224] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.643235] [00000cae] libusb: debug [disarm_timerfd]
[ 0.643247] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617970 has callback 0xf6ef521d
[ 0.643259] [00000cae] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.643275] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.643281] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617970
[ 0.643291] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.644871] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617928
[ 0.644894] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617928
[ 0.644907] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.644924] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 24
[ 0.644950] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.644978] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.644997] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=24
[ 0.645009] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.645021] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.645032] [00000cae] libusb: debug [disarm_timerfd]
[ 0.645045] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617928 has callback 0xf6ef521d
[ 0.645056] [00000cae] libusb: debug [sync_transfer_cb] actual_length=24
[ 0.645096] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.645103] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617928
[ 0.645112] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.645131] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617928
[ 0.645163] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617928
[ 0.645176] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.645189] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1835008
[ 0.645408] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.645518] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.645598] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=92
[ 0.645612] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.645623] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.645634] [00000cae] libusb: debug [disarm_timerfd]
[ 0.645646] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617928 has callback 0xf6ef521d
[ 0.645658] [00000cae] libusb: debug [sync_transfer_cb] actual_length=92
[ 0.645674] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.645681] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617928
[ 0.645689] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.645707] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617928
[ 0.645738] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617928
[ 0.645751] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.645765] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 0.645784] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.645805] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.645822] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 0.645834] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.645845] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.645856] [00000cae] libusb: debug [disarm_timerfd]
[ 0.645868] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617928 has callback 0xf6ef521d
[ 0.645879] [00000cae] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.645896] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.645902] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617928
[ 0.645911] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.734221] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617928
[ 0.734269] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617928
[ 0.734285] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.734304] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 24
[ 0.734332] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.734367] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 0.734393] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=24
[ 0.734406] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.734419] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.734431] [00000cae] libusb: debug [disarm_timerfd]
[ 0.734444] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617928 has callback 0xf6ef521d
[ 0.734456] [00000cae] libusb: debug [sync_transfer_cb] actual_length=24
[ 0.734501] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.734508] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617928
[ 0.734518] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.734536] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617928
[ 0.734569] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617928
[ 0.734582] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.734596] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1835008
[ 0.734819] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.834982] [00000cae] libusb: debug [handle_events] poll() returned 0
[ 0.835636] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.835892] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 0.836033] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.936642] [00000cae] libusb: debug [handle_events] poll() returned 0
[ 0.937126] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.937513] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 0.937543] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 1.019112] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 1.025806] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=1302882
[ 1.026191] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 1.026576] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 1.026785] [00000cae] libusb: debug [disarm_timerfd]
[ 1.027013] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617928 has callback 0xf6ef521d
[ 1.027217] [00000cae] libusb: debug [sync_transfer_cb] actual_length=1302882
[ 1.027701] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.027949] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 1.028108] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617928
[ 1.028474] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617928
[ 1.028685] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617928
[ 1.028898] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 1.029140] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 1.029521] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 1.029923] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 1.030439] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 1.030673] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 1.030871] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 1.031240] [00000cae] libusb: debug [disarm_timerfd]
[ 1.031698] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617928 has callback 0xf6ef521d
[ 1.031901] [00000cae] libusb: debug [sync_transfer_cb] actual_length=16
[ 1.032206] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.032525] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617928
[ 1.032599] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 1.083468] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617928
[ 1.083632] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617928
[ 1.083870] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 1.083962] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 24
[ 1.084247] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 1.084386] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 1.084519] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=24
[ 1.084591] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 1.084658] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 1.084725] [00000cae] libusb: debug [disarm_timerfd]
[ 1.084798] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617928 has callback 0xf6ef521d
[ 1.084864] [00000cae] libusb: debug [sync_transfer_cb] actual_length=24
[ 1.084967] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.084995] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617928
[ 1.085054] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 1.085149] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617928
[ 1.085373] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617928
[ 1.085446] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 1.085524] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1835008
[ 1.086572] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 1.091634] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 1.092134] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=12981
[ 1.092215] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 1.092351] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 1.092426] [00000cae] libusb: debug [disarm_timerfd]
[ 1.092501] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617928 has callback 0xf6ef521d
[ 1.092567] [00000cae] libusb: debug [sync_transfer_cb] actual_length=12981
[ 1.092673] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.092752] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 1.092789] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617928
[ 1.092912] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617928
[ 1.092977] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617928
[ 1.093043] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 1.093121] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 1.093232] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 1.093367] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 1.093469] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 1.093536] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 1.093600] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 1.093662] [00000cae] libusb: debug [disarm_timerfd]
[ 1.093731] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617928 has callback 0xf6ef521d
[ 1.093794] [00000cae] libusb: debug [sync_transfer_cb] actual_length=16
[ 1.093892] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.093921] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617928
[ 1.093978] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 1.094083] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617928
[ 1.094260] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617928
[ 1.094328] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 1.094400] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 36
[ 1.094651] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 1.107578] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 1.107687] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=36
[ 1.107742] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 1.107798] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 1.107854] [00000cae] libusb: debug [disarm_timerfd]
[ 1.107920] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617928 has callback 0xf6ef521d
[ 1.107981] [00000cae] libusb: debug [sync_transfer_cb] actual_length=36
[ 1.108072] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.108146] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 1.108189] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617928
[ 1.108305] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617928
[ 1.108371] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617928
[ 1.108609] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 1.108689] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16
[ 1.108801] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 1.115939] [00000cae] libusb: debug [handle_events] poll() returned 1
[ 1.116059] [00000cae] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16
[ 1.116121] [00000cae] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 1.116179] [00000cae] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 1.116239] [00000cae] libusb: debug [disarm_timerfd]
[ 1.116363] [00000cae] libusb: debug [usbi_handle_transfer_completion] transfer 0x617928 has callback 0xf6ef521d
[ 1.116432] [00000cae] libusb: debug [sync_transfer_cb] actual_length=16
[ 1.116534] [00000cae] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.116610] [00000cae] libusb: debug [handle_events] poll() 3 fds with timeout in 100ms
[ 1.116652] [00000cac] libusb: debug [libusb_free_transfer] transfer 0x617928
[ 1.116767] [00000cac] libusb: debug [libusb_alloc_transfer] transfer 0x617928
[ 1.116833] [00000cac] libusb: debug [libusb_submit_transfer] transfer 0x617928
[ 1.116900] [00000cac] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 1.116976] [00000cac] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 36
[ 1.117088] [00000cac] libusb: debug [libusb_handle_events_timeout_completed] another thread is doing event handling
[ 1.124190] [00000cae] libusb: debug [handle_events] poll() returned 1`

@nznobody
Copy link

nznobody commented May 5, 2016

Hello, I have read through a majority of this and other treads related to the Tegra TX1 and the Kinect v2 on the native built in USB3.0 port. has there been any progress?

I have seen the progress at https://devtalk.nvidia.com/default/topic/919354/jetson-tx1/usb-3-transfer-failures/post/4836312/#4836312

I can reproduce all the known problems resulting in no viewer output. Attached are reproduced logs for consistencies sake.

other_logs.txt
Protonect_Log_DEBUG4.txt
dmesg.txt

Any progress apart from buying the suggested PCIe card?

@xlz
Copy link
Member

xlz commented May 5, 2016

Nvidia's kay was looking at the issue but there is no update. So, no progress.

@jetsonhacks
Copy link

jetsonhacks commented Jun 11, 2016

NVIDIA has posted a USB firmware patch that appears to resolve the issue:

https://devtalk.nvidia.com/default/topic/919354/jetson-tx1/usb-3-transfer-failures/post/4899105/#4899105

The data appears to be transferred correctly, though the RGB color stream appears to have tint issues, suggesting a possible color decoding problem.

@xlz
Copy link
Member

xlz commented Jun 11, 2016

Cool news.

@jetsonhacks how does the tint look? Can you post a screen shot?

@jetsonhacks
Copy link

I'm a monster, but one of a different color. The shirt is black as reference, painting is brown/gold/orange.

screenshot from 2016-06-11 13 59 11

It's been several months, but I seem to recall that the Jetson TK1 has the same issue with coloring.

@xlz
Copy link
Member

xlz commented Jun 12, 2016

Oh, this is because Jetson hardware JPEG decoder outputs image in RGBA format but the viewer is expecting BGRA. You can check this by checking frame->format.

@jetsonhacks
Copy link

Yes, converting to BGRA solves the issue. Thank you very much for your help.

@Shaluols
Copy link

@xlz @menlocaleb
Hi, I used the kinect2 with TX1 and I met the same issue mentioned above!
As:
[Debug] [RgbPacketStreamParser] skipping rgb packet!
[Debug] [DepthPacketStreamParser] skipping depth packet
[Info] [OpenGLDepthPacketProcessor] avg. time: 21.9789ms -> ~45.4983Hz
[Info] [TurboJpegRgbPacketProcessor] avg. time: 41.8277ms -> ~23.9076Hz
[Info] [DepthPacketStreamParser] 5 packets were lost
but i didn't find the solutions.
Have you solved it ? Can you tell me how?

@xlz
Copy link
Member

xlz commented Dec 5, 2016

I believe this has been resolved by newer TX1 firmware.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

7 participants