CPU Depth Processor no longer works on Mac

[RyanGordon]

I built the 0.1-RC1 tag on my MacBook Air Mid 2013 10.11.1 and while both the OpenGL and OpenCL options work fantastically, the cpu option does not appear to work anymore (it used to work). The viewer window does not pop up either and I'm unable to use Ctrl-C to SIGINT out of the program, instead reverting to a SIGQUIT to stop it. I haven't delved into it yet, but I was just curious to see if anyone else could reproduce on their system first (Mac or not). Some basic logs below:

  bin git:(master) ./Protonect cpu
Environment variables: LOGFILE=<protonect.log>
Usage: ./Protonect [gl | cl | cpu] [<device serial>] [-noviewer]
[Info] [Freenect2Impl] enumerating devices...
[Info] [Freenect2Impl] 6 usb devices connected
[Info] [Freenect2Impl] found valid Kinect v2 @20:15 with serial 501870742542
[Info] [Freenect2Impl] found 1 devices
[Info] [Freenect2DeviceImpl] opening...
[Info] [Freenect2DeviceImpl] opened
[Info] [Freenect2DeviceImpl] starting...
[Debug] [Freenect2DeviceImpl] ReadData0x14 response
[Debug] [Freenect2DeviceImpl] 92 bytes of raw data
0x0000:  00 00 12 00 00 00 00 00 01 00 00 00 43 c1 1f 41    2e2e2e2e2e2e2e2e2e2e2e2e432e2e41
0x0010:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00    2e2e2e2e2e2e2e2e2e2e2e2e2e2e2e2e
0x0020:  0a 21 33 55 c2 00 17 20 00 08 00 00 10 00 00 00    2e2133552e2e2e202e2e2e2e2e2e2e2e
0x0030:  00 01 00 00 00 10 00 00 00 00 80 00 01 00 00 00    2e2e2e2e2e2e2e2e2e2e802e2e2e2e2e
0x0040:  31 33 00 00 00 00 0e 10 47 4d 46 31 33 33 2e 31    31332e2e2e2e2e2e474d463133332e31
0x0050:  58 00 00 00 00 00 00 00 00 00 00 00                582e2e2e2e2e2e2e2e2e2e2e

[Debug] [Freenect2DeviceImpl] ReadStatus0x090000 response
[Debug] [Freenect2DeviceImpl] 4 bytes of raw data
0x0000:  00 04 00 00                                        2e2e2e2e

[Debug] [Freenect2DeviceImpl] ReadStatus0x090000 response
[Debug] [Freenect2DeviceImpl] 4 bytes of raw data
0x0000:  02 04 00 00                                        2e2e2e2e

[Info] [Freenect2DeviceImpl] enabling usb transfer submission...
[Info] [Freenect2DeviceImpl] submitting usb transfers...
[Info] [Freenect2DeviceImpl] started
device serial: 501870742542
device firmware: 2.3.3912.0.7
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
...
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Info] [DepthPacketStreamParser] 37 packets were lost
...
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
...
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Info] [DepthPacketStreamParser] 30 packets were lost
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
^\[1]    63745 quit       ./Protonect cpu

[xlz]

Has it processed a single depth or rgb frame? The window pops up only when both a depth and a rgb frame are processed. I don't see messages about rgb here. "skipping depth packet" just means depth processing is too slow. Wait longer and there should be "avg. time:" messages.

[RyanGordon]

So eventually I see this:
[Info] [CpuDepthPacketProcessor] avg. time: 283.721ms -> ~3.52459Hz

But there's never a message about RgbPacketStreamParser or an avg for it or anything like that

[RyanGordon]

Alright odd, it does work sometimes:

[Info] [TurboJpegRgbPacketProcessor] avg. time: 42.4022ms -> ~23.5837Hz
[Info] [CpuDepthPacketProcessor] avg. time: 319.991ms -> ~3.12509Hz

When the problem does happen, it seems to happen with the following sequence of events:

1. ./bin/Protonect cpu
   run for a while w/o issue
   Ctrl-C
2. Right after the program gracefully exits, start it again:

./bin/Protonect cpu
Environment variables: LOGFILE=<protonect.log>
Usage: ./bin/Protonect [gl | cl | cpu] [<device serial>] [-noviewer]
[Info] [Freenect2Impl] enumerating devices...
[Info] [Freenect2Impl] 5 usb devices connected
[Info] [Freenect2Impl] found 0 devices
no device connected!

1. Run it again without delay. This time the Kinect connects but viewer won't show and there is no indication of a RGB frame being processed/transmitted by the Kinect:

./bin/Protonect cpu
Environment variables: LOGFILE=<protonect.log>
Usage: ./bin/Protonect [gl | cl | cpu] [<device serial>] [-noviewer]
[Info] [Freenect2Impl] enumerating devices...
[Info] [Freenect2Impl] 6 usb devices connected
[Info] [Freenect2Impl] found valid Kinect v2 @20:3 with serial 501870742542
[Info] [Freenect2Impl] found 1 devices
[Info] [Freenect2DeviceImpl] opening...
[Info] [Freenect2DeviceImpl] opened
[Info] [Freenect2DeviceImpl] starting...
[Debug] [Freenect2DeviceImpl] ReadData0x14 response
[Debug] [Freenect2DeviceImpl] 92 bytes of raw data
0x0000:  00 00 12 00 00 00 00 00 01 00 00 00 43 c1 1f 41    2e2e2e2e2e2e2e2e2e2e2e2e432e2e41
0x0010:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00    2e2e2e2e2e2e2e2e2e2e2e2e2e2e2e2e
0x0020:  0a 21 33 55 c2 00 17 20 00 08 00 00 10 00 00 00    2e2133552e2e2e202e2e2e2e2e2e2e2e
0x0030:  00 01 00 00 00 10 00 00 00 00 80 00 01 00 00 00    2e2e2e2e2e2e2e2e2e2e802e2e2e2e2e
0x0040:  31 33 00 00 00 00 0e 10 47 4d 46 31 33 33 2e 31    31332e2e2e2e2e2e474d463133332e31
0x0050:  58 00 00 00 00 00 00 00 00 00 00 00                582e2e2e2e2e2e2e2e2e2e2e

[Debug] [Freenect2DeviceImpl] ReadStatus0x090000 response
[Debug] [Freenect2DeviceImpl] 4 bytes of raw data
0x0000:  00 04 00 00                                        2e2e2e2e

[Debug] [Freenect2DeviceImpl] ReadStatus0x090000 response
[Debug] [Freenect2DeviceImpl] 4 bytes of raw data
0x0000:  1e 04 00 00                                        2e2e2e2e

[Info] [Freenect2DeviceImpl] enabling usb transfer submission...
[Info] [Freenect2DeviceImpl] submitting usb transfers...
[Info] [Freenect2DeviceImpl] started
device serial: 501870742542
device firmware: 2.3.3912.0.7
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
[Debug] [DepthPacketStreamParser] skipping depth packet
....

If I wait long enough between 2 & 3 or 1 & 2, the issue doesn't happen. So this is probably some timeout condition of sorts with the Kinect itself or the USB stack.

[xlz]

@RyanGordon I think what you are demonstrating is the lack of proper startup. There is some kind of warmup sequence that Kinect SDK communicates with the Kinect. Right now libfreenect2 does not wait for the warmup.

[RyanGordon]

Ahh, very interesting, is that data somewhere in the USB dump that was done quite some time ago?

[xlz]

Yes it's in here https://gist.github.com/xlz/1d737766bb5a97f77475#file-kinect3-txt. At least one thing is to keep sending readstatus0x0900 until the first byte returned has 0x01.

[xlz]

I added code for the warmup sequence here https://github.com/xlz/libfreenect2/commits/usb-fixes

See if this behaves well.

Also, I added a potentially thread unsafe pausing test. You can use pkill -USR1 Protonect to see if pausing works correctly.

[RyanGordon]

Just tested that out, including the pausing test and it works great! I haven't been able to reproduce my original issue at all 👍

I would agree that it is probably thread unsafe but I haven't seen it cause any issues in my limited tests (several iterations)

[floe]

Seems to count as an internal bugfix, so something we should consider for 0.1-final?

[xlz]

Right, I'll create a PR later. There are a few USB things here I need to check. Also, I need to think through the thread safety issue here.