movidius_ncs_stream nodelet can be run only once

[paLeziart]

Greetings,

I am facing an issue working with the ncs detection nodes, basically it works only once. I cannot launch the network again if I stop the node. Rebooting my hardware allows me to launch the node again but it is not very convenient.

When I run roslaunch movidius_ncs_launch ncs_camera.launch cnn_type:=mobilenetssd camera:=realsense for the first time I get:

process[camera/realsense2_camera_manager-1]: started with pid [2226]
process[camera/realsense2_camera-2]: started with pid [2227]
process[movidius_ncs_nodelet/movidius_manager-3]: started with pid [2228]
process[movidius_ncs_nodelet/movidius_ncs_stream-4]: started with pid [2229]
[ INFO] [1554457489.210911859]: Loading nodelet /movidius_ncs_nodelet/movidius_ncs_stream of type movidius_ncs_stream/NCSNodelet to manager movidius_manager with the following remappings:
[ INFO] [1554457489.211065780]: /camera/rgb/image_raw -> /camera/color/image_raw
[ INFO] [1554457489.211114048]: /movidius_ncs_nodelet/detected_objects -> /movidius_ncs_nodelet/detected_objects
[ INFO] [1554457489.221994285]: waitForService: Service [/movidius_ncs_nodelet/movidius_manager/load_nodelet] has not been advertised, waiting...
[ INFO] [1554457489.261505979]: Initializing nodelet with 4 worker threads.
[ INFO] [1554457489.262707015]: Initializing nodelet with 4 worker threads.
[ INFO] [1554457489.275586087]: waitForService: Service [/movidius_ncs_nodelet/movidius_manager/load_nodelet] is now available.
[ INFO] [1554457489.378324329]: use max_device_number = 255
[ INFO] [1554457489.380450115]: use start_device_index = 0
[ INFO] [1554457489.382499916]: use log_level = 1
[ INFO] [1554457489.384359431]: use graph_file_path = /opt/movidius/ncappzoo/caffe/SSD_MobileNet/graph
[ INFO] [1554457489.387608964]: use category_file_path = /opt/movidius/ncappzoo/data/ilsvrc12/voc21.txt
[ INFO] [1554457489.389817783]: use cnn_type_ = mobilenetssd
[ INFO] [1554457489.392377066]: use network_dimension = 300
[ INFO] [1554457489.394444863]: use channel1_mean = 127.5
[ INFO] [1554457489.396635105]: use channel2_mean = 127.5
[ INFO] [1554457489.398820141]: use channel3_mean = 127.5
[ INFO] [1554457489.400888289]: use top_n = 3
[ INFO] [1554457489.402968658]: use scale = 0.007843
[ INFO] [1554457489.405262297]: opening device #0 name=6
[ INFO] [1554457489.418905933]: RealSense ROS v2.2.3
[ INFO] [1554457489.419005667]: Running with LibRealSense v2.20.0
11:44:49.571 [2321] [E] TrackingManager: Error while loading image - libusb_claim_interface failed (0xFFFFFFFA)
11:44:49.581 [2321] [E] TrackingManager: Error while loading image - libusb_claim_interface failed (0xFFFFFFFA)
11:44:49.592 [2321] [E] TrackingManager: Error while loading image - libusb_claim_interface failed (0xFFFFFFFA)
Booted 6 -> VSC
[ INFO] [1554457490.549816805]: graph is loaded
[ INFO] [1554457490.713956402]: getParameters...
[ INFO] [1554457490.962501356]: setupDevice...
[ INFO] [1554457490.962585599]: JSON file is not provided

And if I then run in another terminal roslaunch movidius_ncs_launch ncs_stream_detection_example.launch camera_topic:="/camera/color/image_raw" a window opens with the video stream and the bounding boxes of detected objects. So everything works and I am happy.

If I shut down both terminal with CTRL+C then run again roslaunch movidius_ncs_launch ncs_camera.launch cnn_type:=mobilenetssd camera:=realsense I get:

process[camera/realsense2_camera_manager-1]: started with pid [3278]
process[camera/realsense2_camera-2]: started with pid [3279]
process[movidius_ncs_nodelet/movidius_manager-3]: started with pid [3280]
process[movidius_ncs_nodelet/movidius_ncs_stream-4]: started with pid [3288]
[ INFO] [1554457579.835109997]: Loading nodelet /movidius_ncs_nodelet/movidius_ncs_stream of type movidius_ncs_stream/NCSNodelet to manager movidius_manager with the following remappings:
[ INFO] [1554457579.835240482]: /camera/rgb/image_raw -> /camera/color/image_raw
[ INFO] [1554457579.835284639]: /movidius_ncs_nodelet/detected_objects -> /movidius_ncs_nodelet/detected_objects
[ INFO] [1554457579.837925864]: Initializing nodelet with 4 worker threads.
[ INFO] [1554457579.859020090]: waitForService: Service [/movidius_ncs_nodelet/movidius_manager/load_nodelet] has not been advertised, waiting...
[ INFO] [1554457579.873417542]: Initializing nodelet with 4 worker threads.
[ INFO] [1554457579.883868514]: waitForService: Service [/movidius_ncs_nodelet/movidius_manager/load_nodelet] is now available.
[ INFO] [1554457579.928377601]: use max_device_number = 255
[ INFO] [1554457579.930317976]: RealSense ROS v2.2.3
[ INFO] [1554457579.930413976]: Running with LibRealSense v2.20.0
[ INFO] [1554457579.930458016]: use start_device_index = 0
[ INFO] [1554457579.932477104]: use log_level = 1
[ INFO] [1554457579.939527660]: use graph_file_path = /opt/movidius/ncappzoo/caffe/SSD_MobileNet/graph
[ INFO] [1554457579.942985119]: use category_file_path = /opt/movidius/ncappzoo/data/ilsvrc12/voc21.txt
[ INFO] [1554457579.944957047]: use cnn_type_ = mobilenetssd
[ INFO] [1554457579.947107781]: use network_dimension = 300
[ INFO] [1554457579.949556228]: use channel1_mean = 127.5
[ INFO] [1554457579.951735875]: use channel2_mean = 127.5
[ INFO] [1554457579.953838835]: use channel3_mean = 127.5
[ INFO] [1554457579.955837218]: use top_n = 3
[ INFO] [1554457579.958236128]: use scale = 0.007843
[ INFO] [1554457580.460648445]: opening device #0 name=6
[ERROR] [1554457581.352538426]: Error: an unexpected error was encontered during the function call
[FATAL] [1554457581.528124734]: Failed to load nodelet '/movidius_ncs_nodelet/movidius_ncs_streamof typemovidius_ncs_stream/NCSNodeletto managermovidius_manager'
[movidius_ncs_nodelet/movidius_ncs_stream-4] process has died [pid 3288, exit code 255, cmd /opt/ros/kinetic/lib/nodelet/nodelet load movidius_ncs_stream/NCSNodelet movidius_manager /camera/rgb/image_raw:=/camera/color/image_raw detected_objects:=detected_objects __name:=movidius_ncs_stream __log:=/home/upsquared/.ros/log/6cd556de-5787-11e9-9025-00073258cd8f/movidius_ncs_nodelet-movidius_ncs_stream-4.log].
log file: /home/upsquared/.ros/log/6cd556de-5787-11e9-9025-00073258cd8f/movidius_ncs_nodelet-movidius_ncs_stream-4*.log
[ INFO] [1554457582.177802434]: getParameters...
[movidius_ncs_nodelet/movidius_manager-3] process has died [pid 3280, exit code -11, cmd /opt/ros/kinetic/lib/nodelet/nodelet manager __name:=movidius_manager __log:=/home/upsquared/.ros/log/6cd556de-5787-11e9-9025-00073258cd8f/movidius_ncs_nodelet-movidius_manager-3.log].
log file: /home/upsquared/.ros/log/6cd556de-5787-11e9-9025-00073258cd8f/movidius_ncs_nodelet-movidius_manager-3*.log
[ INFO] [1554457582.470173684]: setupDevice...
[ INFO] [1554457582.470261508]: JSON file is not provided

I tried to avoid this error with: roslaunch realsense2_camera rs_camera.launch then roslaunch movidius_ncs_launch ncs_camera.launch cnn_type:=mobilenetssd camera:=others input_topic:=/camera/color/image_raw . There is no red error message but it still does not work.

process[movidius_ncs_nodelet/movidius_manager-1]: started with pid [6201]
process[movidius_ncs_nodelet/movidius_ncs_stream-2]: started with pid [6202]
[ INFO] [1554459676.315438413]: Loading nodelet /movidius_ncs_nodelet/movidius_ncs_stream of type movidius_ncs_stream/NCSNodelet to manager movidius_manager with the following remappings:
[ INFO] [1554459676.315579517]: /camera/rgb/image_raw -> /camera/color/image_raw
[ INFO] [1554459676.315626690]: /movidius_ncs_nodelet/detected_objects -> /movidius_ncs_nodelet/detected_objects
[ INFO] [1554459676.322538316]: waitForService: Service [/movidius_ncs_nodelet/movidius_manager/load_nodelet] has not been advertised, waiting...
[ INFO] [1554459676.376258119]: Initializing nodelet with 4 worker threads.
[ INFO] [1554459676.391216214]: waitForService: Service [/movidius_ncs_nodelet/movidius_manager/load_nodelet] is now available.
[ INFO] [1554459676.435680415]: use max_device_number = 255
[ INFO] [1554459676.438282196]: use start_device_index = 0
[ INFO] [1554459676.440665404]: use log_level = 1
[ INFO] [1554459676.443117431]: use graph_file_path = /opt/movidius/ncappzoo/caffe/SSD_MobileNet/graph
[ INFO] [1554459676.445097948]: use category_file_path = /opt/movidius/ncappzoo/data/ilsvrc12/voc21.txt
[ INFO] [1554459676.447782560]: use cnn_type_ = mobilenetssd
[ INFO] [1554459676.450301135]: use network_dimension = 300
[ INFO] [1554459676.452566311]: use channel1_mean = 127.5
[ INFO] [1554459676.454628908]: use channel2_mean = 127.5
[ INFO] [1554459676.457104045]: use channel3_mean = 127.5
[ INFO] [1554459676.459800443]: use top_n = 3
[ INFO] [1554459676.462506786]: use scale = 0.007843
[ INFO] [1554459676.489097130]: started 0 threads

Finally, I quickly looked into the ncs_nodelet.cpp in /movidius_ncs_stream/src. I just tried to change the subscribed topic "/camera/rgb/image_raw" into "/camera/color/image_raw". After running catkin_make to take into account that change, running roslaunch movidius_ncs_launch ncs_camera.launch cnn_type:=mobilenetssd camera:=realsense outputs [ INFO] [1554458577.420255220]: started 0 threads instead of the group of error messages.

For the hardware, I am using an upboard squared with a movidius myriad X and a Realsense D435 camera. OS is Ubuntu 16.04 with Ubuntu kernel 4.15.0 for UP (UP is for upboard).

Can provide more information if you need it, the error logs for instance.

Thank you for your help.

Best,

[chaoli2]

@paLeziart
It seems that this issue is caused by the failure of program termination. Will you please check if the nodes are actually cleared after the CTRL+C with rosnode list? Besides that, re-plug in the NCS stick sometimes helps to reset hardware resource. I suggest you also have a try.

[paLeziart]

@chaoli2
Thank you for your answer.
The first time I launch the nodes (when it works) they are not actually cleared after the CTRL+C. Even after using rosnode kill --all.

upsquared@upsquared-UP-APL01:~$ rosnode kill --all
killing:
/camera/color_rectify_color
/camera/realsense2_camera
/camera/realsense2_camera_manager
/movidius_ncs_nodelet/movidius_manager
/movidius_ncs_nodelet/movidius_ncs_stream
/rosout
killed
upsquared@upsquared-UP-APL01:~$ rosnode list
/camera/color_rectify_color
/camera/realsense2_camera
/camera/realsense2_camera_manager
/movidius_ncs_nodelet/movidius_manager
/movidius_ncs_nodelet/movidius_ncs_stream
/rosout

However the next times, when I relaunch the nodes and it doesn't work (output started 0 threads), using CTRL+C clears the node properly.

upsquared@upsquared-UP-APL01:~$ rosnode list
/rosout

I will try to unplug the stick (mine is this one https://up-shop.org/1071-large_default/up-ai-core-x.jpg), boot once, shutdown then re-plug the stick to see if it changes something.

Best,

[paLeziart]

@chaoli2

Hello, I have some news.

After some tests, it looks like the problem is not entirely linked to the movidius node.
For instance:

• run movidius for the first time -> it works
• run movidius a second time -> doesn't work
  But:
• run realsense-viewer for the first time -> you can see the video stream in realsense
• run movidius for the first time after realsense-viewer -> it does not work

So I was wondering if it was not some kind of communication issue with the realsense cameram especially since I did not have the "realsense" string that I was supposed to have by typing modinfo uvcvideo | grep "version:"

So I just tried to install everything again from scratch with the "classic" ubuntu kernel just in case it was the special ubuntu kernel for upboard which was messing up some packages.

With the classic Ubuntu 16.04 kernel I have this "realsense" string after the modinfo uvcvideo | grep "version:" but there is still an issue with the movidius node:

13/05 15:23:20,200 WARNING [140355284772736] (types.cpp:59) hwmon command 0x4f failed. Error type: No data to return (-21).

is displayed in the middle of the [INFO] outputs when I run the node and

13/05 15:39:22,389 ERROR [140355284772736] (types.h:243) Failed to enable_sensor /sys/devices/pci0000:00/0000:00:15.0/usb2/2-4/2-4.3/2-4.3:1.5/0003:8086:0B3A.0004/HID-SENSOR-2000e1.4.auto/enable_sensor Last Error: Permission denied
terminate called after throwing an instance of 'rs2::backend_error'
  what():  Failed to enable_sensor /sys/devices/pci0000:00/0000:00:15.0/usb2/2-4/2-4.3/2-4.3:1.5/0003:8086:0B3A.0004/HID-SENSOR-2000e1.4.auto/enable_sensor Last Error: Permission denied

when I Ctrl+C the node, thing that I did not have before. There are still crashes with the movidius nodes not properly being killed.

I tried to find a solution by searching a bit everywhere online and I finally found a workaround:

# Launch ROS
roscore

# Launch the realsense camera, the output topic is /camera/color/image_raw
roslaunch realsense2_camera rs_camera.launch

# Launch the movidius node for a specific input topic (/camera/color/image_raw)
roslaunch movidius_ncs_launch ncs_camera.launch cnn_type:=mobilenetssd camera:=others input_topic:=/camera/color/image_raw

# Display the bounding boxes with the video stream
roslaunch movidius_ncs_launch ncs_stream_detection_example.launch camera_topic:="/camera/color/image_raw"

So basically I am decoupling the movidius node from the realsense camera nodes and there is no issue, I can run everything as many time as I want.

In conclusion, I think there is something wrong going on with the communication between the movidius node which is in charge of calling the realsense camera nodes with the standard command roslaunch movidius_ncs_launch ncs_camera.launch cnn_type:=mobilenetssd camera:=realsense. I don't know if the problem is on your side or not.

I don't know if I can close the issue, as you want.

Best,

[chaoli2]

@paLeziart
Your analysis is great. I think the root cause is just as you post. In order to resolve this issue, we'd like to evaluate your information and fix it when available. Thanks very much for this update.

For this issue, we have no concern to close it. Thanks.