pr1040の調子が悪い

症状

kinectの出力がないのにrestartがかからない
rosservice call /check_openni_node/restart で強制的にrestartをかけるとブツブツに切れがかった音声でrestartしたことをspeakし始めるもののkinectは出力されてこない
/imu_node, /robot_pose_ekfから以下のようなエラーが出ている
robot stopしてrobot start しなおしても症状が変わらない
pr2-shutdownしてrebootすると治る

データの取得などが遅れていてこれが原因のような気がするが、負荷は高くない
c1 htop
c2 htop

このようなエラーはなったことないですね。

一般的なエラー診断として

c1とc2の時間は合っているかな？
pr2-shutdown→後ろの電源スイッチOFF→ON→robot startしてもだめかな？

kinectの出力がないのにrestartがかからない

これはもう少し状況を調べることができるのでは? check_openni_node はちゃんとkinectの出力を見ているか、出力がないことを判別しているか、restartをかけているか、の各段階を追って下さい．

◉ Kei Okada

2016-11-13 22:14 GMT+09:00 Furushchev notifications@github.com:

このようなエラーはなったことないですね。

一般的なエラー診断として

c1とc2の時間は合っているかな？

pr2-shutdown→後ろの電源スイッチOFF→ON→robot startしてもだめかな？

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/jsk-ros-pkg/jsk_robot/issues/724#issuecomment-260185521, or mute the thread https://github.com/notifications/unsubscribe-auth/AAeG3OYtPaNR7bta53Y6ZQCMxbRnI8xpks5q9w0-gaJpZM4KwrCH .

以前と状況が同じかは分かりませんが、再びkinectのrestart がかからなくなりました。 ros_console.py -n /check_openni_node として出力をlogしてみましたが、最後の出力は

[INFO] [1479271850.06] [/check_openni_node] [CheckOpenNINode] sum of pixels is 31832581 at 1479271849^[[0m
[INFO] [1479271910.17] [/check_openni_node] [CheckOpenNINode] sum of pixels is 31776627 at 1479271910^[[0m
[INFO] [1479271970.24] [/check_openni_node]  [CheckOpenNINode] sum of pixels is 0 at 1479271970^[[0m
[ERROR] [1479271970.24] [/check_openni_node] ^[[31mRestart openni_node1^[[0m
[ERROR] [1479271970.24] [/check_openni_node] ^[[31m[CheckOpenNINode] resetting u s b^[[0m
[ERROR] [1479271982.41] [/check_openni_node] ^[[31m[CheckOpenNINode] something wrong with kinect, I'll restart it, killing nodelet manager^[[0m
[ERROR] [1479271993.02] [/check_openni_node] ^[[31m[CheckOpenNINode] killing child processes^[[0m
[ERROR] [1479272003.06] [/check_openni_node] ^[[31m[CheckOpenNINode] restarting processes^[[0m

となっていました。これを見る限りでは、restartまではかかっているものの、restartが実際には出来ていない、という状況に見えます。

リスタートのコマンドを手動で売って、実際にリスタートがかかるか確認するのと、 2．リスタートかけてもリスタートしていないのであれば、なぜその状況が検出されていないかチェックする．

◉ Kei Okada

2016-11-16 14:12 GMT+09:00 h-kamada notifications@github.com:

以前と状況が同じかは分かりませんが、再びkinectのrestart がかからなくなりました。 ros_console.py -n /check_openni_node として出力をlogしてみましたが、最後の出力は

[INFO] [1479271850.06] [/check_openni_node] [CheckOpenNINode] sum of pixels is 31832581 at 1479271849^[[0m [INFO] [1479271910.17] [/check_openni_node] [CheckOpenNINode] sum of pixels is 31776627 at 1479271910^[[0m [INFO] [1479271970.24] [/check_openni_node] [CheckOpenNINode] sum of pixels is 0 at 1479271970^[[0m [ERROR] [1479271970.24] [/check_openni_node] ^[[31mRestart openni_node1^[[0m [ERROR] [1479271970.24] [/check_openni_node] ^[[31m[CheckOpenNINode] resetting u s b^[[0m [ERROR] [1479271982.41] [/check_openni_node] ^[[31m[CheckOpenNINode] something wrong with kinect, I'll restart it, killing nodelet manager^[[0m [ERROR] [1479271993.02] [/check_openni_node] ^[[31m[CheckOpenNINode] killing child processes^[[0m [ERROR] [1479272003.06] [/check_openni_node] ^[[31m[CheckOpenNINode] restarting processes^[[0m

となっていました。これを見る限りでは、restartまではかかっているものの、restartが実際には出来ていない、という状況に見えます。

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/jsk-ros-pkg/jsk_robot/issues/724#issuecomment-260855958, or mute the thread https://github.com/notifications/unsubscribe-auth/AAeG3Jt3bBQcHFH5o5PUBOEvYrHbFrz4ks5q-pC5gaJpZM4KwrCH .

この行を実行すると https://github.com/jsk-ros-pkg/jsk_robot/blob/master/jsk_pr2_robot/jsk_pr2_startup/jsk_pr2_sensors/check_openni_node.py#L79

SUMMARY
========

PARAMETERS
 * /kinect_head/driver/depth_camera_info_url
 * /kinect_head/driver/depth_frame_id
 * /kinect_head/driver/depth_registration
 * /kinect_head/driver/device_id
 * /kinect_head/driver/rgb_camera_info_url
 * /kinect_head/driver/rgb_frame_id
 * /kinect_head/kinect_head_nodelet_manager/num_worker_threads
 * /rosdistro
 * /rosversion

NODES
  /kinect_head/
    driver (nodelet/nodelet)
    kinect_head_nodelet_manager (nodelet/nodelet)

ROS_MASTER_URI=http://c1:11311
^[]2;/opt/ros/hydro/share/openni_launch/launch/openni.launch http://c1:11311^G
core service [/rosout] found
process[kinect_head/kinect_head_nodelet_manager-1]: started with pid [2660]
process[kinect_head/driver-2]: started with pid [2661]
[ INFO] [1479370075.982477954]: Initializing nodelet with 4 worker threads.
terminate called after throwing an instance of 'openni_wrapper::OpenNIException'
  what():  unsigned int openni_wrapper::OpenNIDriver::updateDeviceList() @ /tmp/buildd/ros-hydro-openni-camera-1.9.2-0precise-20150515-0510/src/openni_driver.cpp @ 125 : enumerating image nodes failed. Re\
ason: One or more of the following nodes could not be enumerated:

Image: PrimeSense/SensorV2/5.1.0.41: Failed to set USB interface!

[kinect_head/kinect_head_nodelet_manager-1] process has died [pid 2660, exit code -6, cmd /opt/ros/hydro/lib/nodelet/nodelet manager __name:=kinect_head_nodelet_manager __log:=/home/applications/.ros/log/\
a68c8ad6-ac8b-11e6-8a75-001517ebc305/kinect_head-kinect_head_nodelet_manager-1.log].                                                                                                                         
log file: /home/applications/.ros/log/a68c8ad6-ac8b-11e6-8a75-001517ebc305/kinect_head-kinect_head_nodelet_manager-1*.log
[FATAL] [1479370086.319115635]: Service call failed!
[kinect_head/driver-2] process has died [pid 2661, exit code 255, cmd /opt/ros/hydro/lib/nodelet/nodelet load openni_camera/driver kinect_head_nodelet_manager --no-bond ir:=ir rgb:=rgb depth:=depth depth_\
registered:=depth_registered projector:=projector __name:=driver __log:=/home/applications/.ros/log/a68c8ad6-ac8b-11e6-8a75-001517ebc305/kinect_head-driver-2.log].                                          
log file: /home/applications/.ros/log/a68c8ad6-ac8b-11e6-8a75-001517ebc305/kinect_head-driver-2*.log
all processes on machine have died, roslaunch will exit
shutting down processing monitor...
... shutting down processing monitor complete
done

とエラーが出ます。 USBを読み込めていないために生じているエラーでしょうか？？ pr1040ではunable to read ~~というエラーが出ています。

pr1040 (dmesg |tail -n 20)

[ 7056.071595] retire_capture_urb: 9208 callbacks suppressed
[ 7061.064318] retire_capture_urb: 9204 callbacks suppressed
[ 7062.496462] usb 2-5.3: reset high-speed USB device number 16 using ehci_hcd
[ 7062.583498] usb 2-5.3: usbfs: process 3407 (XnSensorServer) did not claim interface 0 before use
[ 7063.074478] usb 2-5.1: reset high-speed USB device number 15 using ehci_hcd
[ 7063.686515] usb 2-5.2: reset full-speed USB device number 8 using ehci_hcd
[ 7063.698189] usb 2-5.1: USB disconnect, device number 15
[ 7063.802516] usb 2-5.3: USB disconnect, device number 16
[ 7065.153086] usb 2-5.1: new high-speed USB device number 17 using ehci_hcd
[ 7065.311145] usb 2-5.1: string descriptor 0 read error: -71
[ 7065.364285] usb 2-5.1: New USB device found, idVendor=045e, idProduct=02ad
[ 7065.364289] usb 2-5.1: New USB device strings: Mfr=1, Product=2, SerialNumber=4
[ 7066.686487] usb 2-5.3: new high-speed USB device number 18 using ehci_hcd
[ 7066.868178] usb 2-5.3: unable to read config index 0 descriptor/start: -71
[ 7066.923148] usb 2-5.3: chopping to 0 config(s)
[ 7067.005451] usb 2-5.3: string descriptor 0 read error: -71
[ 7067.060723] usb 2-5.3: New USB device found, idVendor=045e, idProduct=02ae
[ 7067.060727] usb 2-5.3: New USB device strings: Mfr=2, Product=1, SerialNumber=3
[ 7067.060855] usb 2-5.3: no configuration chosen from 0 choices
[ 7203.311174] retire_capture_urb: 2523 callbacks suppressed

pr1012(dmesg |tail -n 55)

[ 9312.110557] NOHZ: local_softirq_pending 08
[101412.689799] usb 2-4.3: reset high-speed USB device number 9 using ehci_hcd
[101412.776851] usb 2-4.3: usbfs: process 29843 (XnSensorServer) did not claim interface 0 before use
[101413.273964] usb 2-4.1: reset high-speed USB device number 8 using ehci_hcd
[101413.870975] usb 2-4.2: reset full-speed USB device number 7 using ehci_hcd
[101413.976035] usb 2-4.1: USB disconnect, device number 8
[101414.079866] usb 2-4.3: USB disconnect, device number 9
[101415.430895] usb 2-4.1: new high-speed USB device number 10 using ehci_hcd
[101415.519352] usb 2-4.1: New USB device found, idVendor=045e, idProduct=02ad
[101415.519357] usb 2-4.1: New USB device strings: Mfr=1, Product=2, SerialNumber=4
[101415.519360] usb 2-4.1: Product: Xbox NUI Audio
[101415.519362] usb 2-4.1: Manufacturer: Microsoft
[101415.519364] usb 2-4.1: SerialNumber: B44882509779048B
[101416.964202] usb 2-4.3: new high-speed USB device number 11 using ehci_hcd
[101417.052433] usb 2-4.3: New USB device found, idVendor=045e, idProduct=02ae
[101417.052439] usb 2-4.3: New USB device strings: Mfr=2, Product=1, SerialNumber=3
[101417.052447] usb 2-4.3: Product: Xbox NUI Camera
[101417.052452] usb 2-4.3: Manufacturer: Microsoft
[101417.052454] usb 2-4.3: SerialNumber: B00364625506048B
[108668.109246] usb 2-4.3: reset high-speed USB device number 11 using ehci_hcd
[108668.196039] usb 2-4.3: usbfs: process 16953 (XnSensorServer) did not claim interface 0 before use
[108668.698264] usb 2-4.1: reset high-speed USB device number 10 using ehci_hcd
[108669.260263] usb 2-4.1: USB disconnect, device number 10
[108669.303264] usb 2-4.2: reset full-speed USB device number 7 using ehci_hcd
[108669.364405] usb 2-4.3: USB disconnect, device number 11
[108670.970121] usb 2-4.1: new high-speed USB device number 12 using ehci_hcd
[108671.058594] usb 2-4.1: New USB device found, idVendor=045e, idProduct=02ad
[108671.058598] usb 2-4.1: New USB device strings: Mfr=1, Product=2, SerialNumber=4
[108671.058606] usb 2-4.1: Product: Xbox NUI Audio
[108671.058608] usb 2-4.1: Manufacturer: Microsoft
[108671.058610] usb 2-4.1: SerialNumber: B44882509779048B
[108672.503576] usb 2-4.3: new high-speed USB device number 13 using ehci_hcd
[108672.591806] usb 2-4.3: New USB device found, idVendor=045e, idProduct=02ae
[108672.591825] usb 2-4.3: New USB device strings: Mfr=2, Product=1, SerialNumber=3
[108672.591828] usb 2-4.3: Product: Xbox NUI Camera
[108672.591830] usb 2-4.3: Manufacturer: Microsoft
[108672.591832] usb 2-4.3: SerialNumber: B00364625506048B
[110720.057368] usb 2-4.3: reset high-speed USB device number 13 using ehci_hcd
[110720.144249] usb 2-4.3: usbfs: process 32293 (XnSensorServer) did not claim interface 0 before use
[110720.665370] usb 2-4.1: reset high-speed USB device number 12 using ehci_hcd
[110721.250393] usb 2-4.2: reset full-speed USB device number 7 using ehci_hcd
[110721.277837] usb 2-4.1: USB disconnect, device number 12
[110721.382542] usb 2-4.3: USB disconnect, device number 13
[110722.731980] usb 2-4.1: new high-speed USB device number 14 using ehci_hcd
[110722.821658] usb 2-4.1: New USB device found, idVendor=045e, idProduct=02ad
[110722.821667] usb 2-4.1: New USB device strings: Mfr=1, Product=2, SerialNumber=4
[110722.821670] usb 2-4.1: Product: Xbox NUI Audio
[110722.821672] usb 2-4.1: Manufacturer: Microsoft
[110722.821674] usb 2-4.1: SerialNumber: B44882509779048B
[110724.265784] usb 2-4.3: new high-speed USB device number 15 using ehci_hcd
[110724.353997] usb 2-4.3: New USB device found, idVendor=045e, idProduct=02ae
[110724.354002] usb 2-4.3: New USB device strings: Mfr=2, Product=1, SerialNumber=3
[110724.354004] usb 2-4.3: Product: Xbox NUI Camera
[110724.354006] usb 2-4.3: Manufacturer: Microsoft
[110724.354008] usb 2-4.3: SerialNumber: B00364625506048B

check_openni_node.pyでは Bus 002 Device 023: ID 045e:02ad Microsoft Corp. Xbox NUI Audio のみprocessをkillしてから立ち上げ直しているが、 lsusb

Bus 002 Device 023: ID 045e:02ad Microsoft Corp. Xbox NUI Audio
Bus 002 Device 008: ID 045e:02b0 Microsoft Corp. Xbox NUI Motor
Bus 002 Device 024: ID 045e:02ae Microsoft Corp. Xbox NUI Camera

3つ全てに対して rosrun openni2_camera usb_reset /dev/bus/usb/002/023 etc を行いrestart するとnodeが立ち上がった。

TODO

次に同じ事態が起きた時には、usb_resetの順番が関係しているかどうかを試してみる

jsk-ros-pkg / jsk_robot

pr1040の調子が悪い #724

症状

TODO