Error when download/cat files using mavftp: IOError [Errno 110] Connection timed out

[fionachui]

This is only bug and feature tracker, please use it
to report bugs or request features.

---

Issue details

When trying to download a .px4log through mavftp, I get the following error:

ubuntu@ubuntu:~$ rosrun mavros mavftp download /fs/microsd/log/2016-11-01/21_43_29.px4log
Prigressbar disabled. install python-progressbar
Traceback (most recent call last):
  File "/opt/ros/indigo/lib/mavros/mavftp", line 296, in <module>
    main()
  File "/opt/ros/indigo/lib/mavros/mavftp", line 292, in main
    args.func(args)
  File "/opt/ros/indigo/lib/mavros/mavftp", line 152, in do_download
    buf = from_fd.read(FTP_PAGE_SIZE)
  File "/opt/ros/indigo/lib/python2.7/dist-packages/mavros/ftp.py", line 107, in read
    _check_raise_errno(ret)
  File "/opt/ros/indigo/lib/python2.7/dist-packages/mavros/ftp.py", line 39, in _check_raise_errno
    raise IOError(ret.r_errno, os.strerror(ret.r_errno))
IOError: [Errno 110] Connection timed out

So I'm able to open the file, as the main roslaunch mavros window displays:

[ INFO] [1491328759.740312395]: FTP:Open /fs/microsd/log/2016-11-01/21_43_29.px4log: success, session 0, size 263247

But I get the [Errno 110] Connection timed out error on reading the file.

MAVROS version and platform

Mavros: 0.17.4
ROS: Indigo
Ubuntu: 14.04

Autopilot type and version

[ ] ArduPilot
[X] PX4

Version: 1.1

Node logs

ubuntu@ubuntu:~$ roslaunch mavros px4.launch fcu_url:="/dev/ttyUSB0:921600"
... logging to /home/ubuntu/.ros/log/4bfe2358-1960-11e7-a396-54ee75c35d17/roslaunch-ubuntu-10479.log
Checking log directory for disk usage. This may take awhile.
Press Ctrl-C to interrupt
Done checking log file disk usage. Usage is <1GB.

started roslaunch server http://ubuntu:40096/

SUMMARY
========

CLEAR PARAMETERS
 * /mavros/

PARAMETERS
 * /mavros/cmd/use_comp_id_system_control: False
 * /mavros/conn/heartbeat_rate: 1.0
 * /mavros/conn/system_time_rate: 1.0
 * /mavros/conn/timeout: 10.0
 * /mavros/conn/timesync_rate: 10.0
 * /mavros/distance_sensor/hrlv_ez4_pub/field_of_view: 0.0
 * /mavros/distance_sensor/hrlv_ez4_pub/frame_id: hrlv_ez4_sonar
 * /mavros/distance_sensor/hrlv_ez4_pub/id: 0
 * /mavros/distance_sensor/hrlv_ez4_pub/orientation: ROLL_180
 * /mavros/distance_sensor/hrlv_ez4_pub/send_tf: True
 * /mavros/distance_sensor/hrlv_ez4_pub/sensor_position/x: 0.0
 * /mavros/distance_sensor/hrlv_ez4_pub/sensor_position/y: 0.0
 * /mavros/distance_sensor/hrlv_ez4_pub/sensor_position/z: -0.1
 * /mavros/distance_sensor/laser_1_sub/id: 3
 * /mavros/distance_sensor/laser_1_sub/orientation: ROLL_180
 * /mavros/distance_sensor/laser_1_sub/subscriber: True
 * /mavros/distance_sensor/lidarlite_pub/field_of_view: 0.0
 * /mavros/distance_sensor/lidarlite_pub/frame_id: lidarlite_laser
 * /mavros/distance_sensor/lidarlite_pub/id: 1
 * /mavros/distance_sensor/lidarlite_pub/orientation: ROLL_180
 * /mavros/distance_sensor/lidarlite_pub/send_tf: True
 * /mavros/distance_sensor/lidarlite_pub/sensor_position/x: 0.0
 * /mavros/distance_sensor/lidarlite_pub/sensor_position/y: 0.0
 * /mavros/distance_sensor/lidarlite_pub/sensor_position/z: -0.1
 * /mavros/distance_sensor/sonar_1_sub/id: 2
 * /mavros/distance_sensor/sonar_1_sub/orientation: ROLL_180
 * /mavros/distance_sensor/sonar_1_sub/subscriber: True
 * /mavros/fcu_url: /dev/ttyUSB0:921600
 * /mavros/gcs_url: 
 * /mavros/global_position/frame_id: fcu
 * /mavros/global_position/rot_covariance: 99999.0
 * /mavros/global_position/tf/child_frame_id: fcu_utm
 * /mavros/global_position/tf/frame_id: local_origin
 * /mavros/global_position/tf/send: False
 * /mavros/image/frame_id: px4flow
 * /mavros/imu/angular_velocity_stdev: 0.000349065850399
 * /mavros/imu/frame_id: fcu
 * /mavros/imu/linear_acceleration_stdev: 0.0003
 * /mavros/imu/magnetic_stdev: 0.0
 * /mavros/imu/orientation_stdev: 1.0
 * /mavros/local_position/frame_id: fcu
 * /mavros/local_position/tf/child_frame_id: fcu
 * /mavros/local_position/tf/frame_id: local_origin
 * /mavros/local_position/tf/send: False
 * /mavros/local_position/tf/send_fcu: False
 * /mavros/mission/pull_after_gcs: True
 * /mavros/mocap/use_pose: True
 * /mavros/mocap/use_tf: False
 * /mavros/plugin_blacklist: ['safety_area', '...
 * /mavros/plugin_whitelist: []
 * /mavros/px4flow/frame_id: px4flow
 * /mavros/px4flow/ranger_fov: 0.0
 * /mavros/px4flow/ranger_max_range: 5.0
 * /mavros/px4flow/ranger_min_range: 0.3
 * /mavros/safety_area/p1/x: 1.0
 * /mavros/safety_area/p1/y: 1.0
 * /mavros/safety_area/p1/z: 1.0
 * /mavros/safety_area/p2/x: -1.0
 * /mavros/safety_area/p2/y: -1.0
 * /mavros/safety_area/p2/z: -1.0
 * /mavros/setpoint_accel/send_force: False
 * /mavros/setpoint_attitude/reverse_throttle: False
 * /mavros/setpoint_attitude/tf/child_frame_id: attitude
 * /mavros/setpoint_attitude/tf/frame_id: local_origin
 * /mavros/setpoint_attitude/tf/listen: False
 * /mavros/setpoint_attitude/tf/rate_limit: 10.0
 * /mavros/setpoint_position/tf/child_frame_id: setpoint
 * /mavros/setpoint_position/tf/frame_id: local_origin
 * /mavros/setpoint_position/tf/listen: False
 * /mavros/setpoint_position/tf/rate_limit: 50.0
 * /mavros/startup_px4_usb_quirk: True
 * /mavros/sys/disable_diag: False
 * /mavros/sys/min_voltage: 10.0
 * /mavros/target_component_id: 1
 * /mavros/target_system_id: 1
 * /mavros/tdr_radio/low_rssi: 40
 * /mavros/time/time_ref_source: fcu
 * /mavros/time/timesync_avg_alpha: 0.6
 * /mavros/vibration/frame_id: vibration
 * /mavros/vision_pose/tf/child_frame_id: vision
 * /mavros/vision_pose/tf/frame_id: local_origin
 * /mavros/vision_pose/tf/listen: False
 * /mavros/vision_pose/tf/rate_limit: 10.0
 * /mavros/vision_speed/listen_twist: False
 * /rosdistro: indigo
 * /rosversion: 1.11.20

NODES
  /
    mavros (mavros/mavros_node)

auto-starting new master
process[master]: started with pid [10491]
ROS_MASTER_URI=http://localhost:11311/

setting /run_id to 4bfe2358-1960-11e7-a396-54ee75c35d17
process[rosout-1]: started with pid [10504]
started core service [/rosout]
process[mavros-2]: started with pid [10522]
[ INFO] [1491328704.639977423]: FCU URL: /dev/ttyUSB0:921600
[ INFO] [1491328704.640148669]: serial0: device: /dev/ttyUSB0 @ 921600 bps
[ INFO] [1491328704.640857865]: GCS bridge disabled
[ INFO] [1491328704.678791638]: Plugin 3dr_radio loaded and initialized
[ INFO] [1491328704.681584591]: Plugin actuator_control loaded and initialized
[ INFO] [1491328704.682806790]: Plugin altitude loaded and initialized
[ INFO] [1491328704.734773858]: Plugin cam_imu_sync loaded and initialized
[ INFO] [1491328704.741470118]: Plugin command loaded and initialized
[ INFO] [1491328704.741573052]: Plugin distance_sensor blacklisted
[ INFO] [1491328704.755546619]: Plugin ftp loaded and initialized
[ INFO] [1491328704.766173170]: Plugin global_position loaded and initialized
[ INFO] [1491328704.767192333]: Plugin hil_controls loaded and initialized
[ INFO] [1491328704.767303516]: Plugin image_pub blacklisted
[ INFO] [1491328704.778053521]: Plugin imu_pub loaded and initialized
[ INFO] [1491328704.784409686]: Plugin local_position loaded and initialized
[ INFO] [1491328704.785040013]: Plugin manual_control loaded and initialized
[ INFO] [1491328704.789160066]: IMU: High resolution IMU detected!
[ INFO] [1491328704.793286286]: Plugin mocap_pose_estimate loaded and initialized
[ INFO] [1491328704.795783133]: Plugin param loaded and initialized
[ INFO] [1491328704.803470692]: Plugin px4flow loaded and initialized
[ INFO] [1491328704.810457093]: Plugin rc_io loaded and initialized
[ INFO] [1491328704.810504287]: Plugin safety_area blacklisted
[ INFO] [1491328704.814195357]: Plugin setpoint_accel loaded and initialized
[ INFO] [1491328704.833646784]: Plugin setpoint_attitude loaded and initialized
[ INFO] [1491328704.843787243]: Plugin setpoint_position loaded and initialized
[ INFO] [1491328704.854228533]: Plugin setpoint_raw loaded and initialized
[ INFO] [1491328704.857035208]: Plugin setpoint_velocity loaded and initialized
[ INFO] [1491328704.868906236]: Plugin sys_status loaded and initialized
[ INFO] [1491328704.872289296]: Plugin sys_time loaded and initialized
[ INFO] [1491328704.873499821]: Plugin vfr_hud loaded and initialized
[ INFO] [1491328704.873528131]: Plugin vibration blacklisted
[ INFO] [1491328704.886149274]: Plugin vision_pose_estimate loaded and initialized
[ INFO] [1491328704.892185325]: Plugin vision_speed_estimate loaded and initialized
[ INFO] [1491328704.898632965]: Plugin waypoint loaded and initialized
[ INFO] [1491328704.899156813]: Autostarting mavlink via USB on PX4
[ INFO] [1491328704.899568244]: Built-in SIMD instructions: SSE, SSE2
[ INFO] [1491328704.899737606]: Built-in MAVLink package version: 2016.5.20
[ INFO] [1491328704.899814667]: Built-in MAVLink dialect: ardupilotmega
[ INFO] [1491328704.899913235]: MAVROS started. MY ID 1.240, TARGET ID 1.1
[ WARN] [1491328704.977042906]: TM: Clock skew detected (-1491328273.724662542 s). Hard syncing clocks.
[ INFO] [1491328705.728264902]: CON: Got HEARTBEAT, connected. FCU: PX4
[ INFO] [1491328705.730098822]: IMU: High resolution IMU detected!
[ INFO] [1491328706.741017002]: VER: 1.1: Capabilities 0x00000000000004eb
[ INFO] [1491328706.741277778]: VER: 1.1: Flight software:     00000000 (328018937301dc7e)
[ INFO] [1491328706.741430544]: VER: 1.1: Middleware software: 00000000 (328018937301dc7e)
[ INFO] [1491328706.741573285]: VER: 1.1: OS software:         00000000 (0000000000000000)
[ INFO] [1491328706.741672549]: VER: 1.1: Board hardware:      00000000
[ INFO] [1491328706.741741415]: VER: 1.1: VID/PID: 26ac:0011
[ INFO] [1491328706.741793858]: VER: 1.1: UID: 3135511735333436
[ WARN] [1491328716.730309039]: PR: request list timeout, retries left 2
[ WARN] [1491328717.730709455]: PR: request list timeout, retries left 1
[ WARN] [1491328718.731847404]: PR: request list timeout, retries left 0
[ INFO] [1491328720.737982744]: WP: mission received
[ WARN] [1491328740.830436979]: TM: Clock skew detected (0.024262897 s). Hard syncing clocks.
[ INFO] [1491328759.740312395]: FTP:Open /fs/microsd/log/2016-11-01/21_43_29.px4log: success, session 0, size 263247

Diagnostics

header: 
  seq: 27
  stamp: 
    secs: 1491329484
    nsecs: 383406366
  frame_id: ''
status: 
  - 
    level: 0
    name: mavros: FCU connection
    message: connected
    hardware_id: /dev/ttyUSB0:921600
    values: 
      - 
        key: Received packets:
        value: 8489
      - 
        key: Dropped packets:
        value: 0
      - 
        key: Buffer overruns:
        value: 0
      - 
        key: Parse errors:
        value: 0
      - 
        key: Rx sequence number:
        value: 177
      - 
        key: Tx sequence number:
        value: 138
      - 
        key: Rx total bytes:
        value: 346726
      - 
        key: Tx total bytes:
        value: 22004
      - 
        key: Rx speed:
        value: 17138.000000
      - 
        key: Tx speed:
        value: 709.000000
  - 
    level: 2
    name: mavros: GPS
    message: No satellites
    hardware_id: /dev/ttyUSB0:921600
    values: 
      - 
        key: Satellites visible
        value: 0
      - 
        key: Fix type
        value: 0
      - 
        key: EPH (m)
        value: Unknown
      - 
        key: EPV (m)
        value: Unknown
  - 
    level: 0
    name: mavros: Heartbeat
    message: Normal
    hardware_id: /dev/ttyUSB0:921600
    values: 
      - 
        key: Heartbeats since startup
        value: 29
      - 
        key: Frequency (Hz)
        value: 0.962921
      - 
        key: Vehicle type
        value: VTOL-Quadrotor
      - 
        key: Autopilot type
        value: PX4
      - 
        key: Mode
        value: MANUAL
      - 
        key: System status
        value: Uninit
  - 
    level: 0
    name: mavros: System
    message: Normal
    hardware_id: /dev/ttyUSB0:921600
    values: 
      - 
        key: Sensor present
        value: 0x00000000
      - 
        key: Sensor enabled
        value: 0x00000000
      - 
        key: Sensor helth
        value: 0x00000000
      - 
        key: CPU Load (%)
        value: 74.6
      - 
        key: Drop rate (%)
        value: 0.0
      - 
        key: Errors comm
        value: 0
      - 
        key: Errors count #1
        value: 0
      - 
        key: Errors count #2
        value: 0
      - 
        key: Errors count #3
        value: 0
      - 
        key: Errors count #4
        value: 0
  - 
    level: 1
    name: mavros: Battery
    message: Low voltage
    hardware_id: /dev/ttyUSB0:921600
    values: 
      - 
        key: Voltage
        value: 0.00
      - 
        key: Current
        value: 0.0
      - 
        key: Remaining
        value: -1.0
  - 
    level: 0
    name: mavros: Time Sync
    message: Normal
    hardware_id: /dev/ttyUSB0:921600
    values: 
      - 
        key: Timesyncs since startup
        value: 155
      - 
        key: Frequency (Hz)
        value: 9.999546
      - 
        key: Last dt (ms)
        value: -1.344876
      - 
        key: Mean dt (ms)
        value: 0.008980
      - 
        key: Last system time (s)
        value: 1210.658179000
      - 
        key: Time offset (s)
        value: 1491328273.698000193
---

Check ID

OK. I got messages from 1:1.

---
Received 4327 messages, from 1 addresses
sys:comp   list of messages
  1:1     32, 1, 2, 36, 147, 105, 74, 140, 141, 111, 76, 241, 83, 245, 251, 44, 30, 0

[vooon]

Flight logs often too big for FTP, also for some reason it is stable only with USB connection (usb on pihxawk - ttyACM%d).
On UART it only suitable when you need to modify extras rc or mixer file.
Also after file download script tell FCU to calculate CRC32 of entire file and here also may be timeout.

Note: FTP is slow, but QGC download implementation twice faster than mavros.

[TSC21]

Note: FTP is slow, but QGC download implementation twice faster than mavros.

Where may be the difference @vooon?

[vooon]

QGC support streaming download, it require only one request message to transfer whole file.
While mine uses older request buffer, so to transfer file i should request bunch of 239-byte responses.

I'm not going to implement that mode, just use QGC.

[TSC21]

I'm not going to implement that mode, just use QGC.

I think this is a need, given that we offer the FTP possibility on MAVROS. I will look into it and get back with news (and a PR).

[vooon]

@TSC21 because FTP stable only via USB, and main usage of mavros via TELEMx there no reason to implement that mode, and it is not compatible with current fuse-like interface.

So:

1. No strong reason for implementation
2. Logging may be done via mavlink and intel's router

[TSC21]

@vooon as you wish. I think one of the main usages of MAVROS to some people is also use it as a replacement of QGC. Still, we are lacking support for ULog streaming.

[mhkabir]

It's a usability thing. File transfer is ridiculously slow over telemetry, and pulling a log of any decent size (10-15 MB) will take too long even with an optimised implementation.

Regarding ULog streaming - Yes, it's a nice-to-have, but you can just use mavlink-router. (https://github.com/01org/mavlink-router).

[TSC21]

Regarding ULog streaming - Yes, it's a nice-to-have, but you can just use mavlink-router. (https://github.com/01org/mavlink-router).

True. Still, I think it's our wish as MAVROS developers and maintainers to have it full-featured.

[vooon]

Actually for newer drone i will setup router between tty and mavros.
Because TELEM1 will be occupied by RFD and TELEM2. So i need router inside FCU too.

And i don't thinking that mavros is replacement for any GCS, it is set of API to write your autonomous control software.
Anyway you need GCS to tune firmware.