YARPRobotLoggerDevice: excessively long time horizon for signals logged with YARP_CLOCK

[rob-mau]

I would like to report a peculiar behavior of the YARPRobotLoggerDevice. If I run it with YARP_CLOCK:

YARP_CLOCK=/clock YARP_ROBOT_NAME=ergoCubGazeboV1_1 yarprobotinterface --config launch-yarp-robot-logger.xml

and then I launch the robot-log-visualizer, the signal plot displays an excessively long time horizon (on the order of 1e9 seconds!).

Conversely, when I launch the logger without YARP_CLOCK, the amplitude of the time window is consistent with the logger's execution time.

[S-Dafarra]

Can you add the mat file here?

cc @GiulioRomualdi

[GiulioRomualdi]

was able to replicate the issue in my setup. I noticed that once the logger is closed, the last timestamp appears to be a high number.

This is the first timestamp

>> robot_logger_device.FTs.r_foot_front_ft.timestamps(1)

ans =

   10.5960

This is the second-to-last timestamp:

>> robot_logger_device.FTs.r_foot_front_ft.timestamps(end-1)

ans =

  122.3720

However, the last one is

>> robot_logger_device.FTs.r_foot_front_ft.timestamps(end)

ans =

   1.7086e+09

The device utilizes the YarpClock to obtain the time

[GiulioRomualdi]

I'm afraid it is something related to the clock when we destroy the device @traversaro

[S-Dafarra]

When pressing CTRL+C, the close method should be called (see here, then here and finally here). I noticed that in the close method we do not stop the acquisition thread. We probably should add a this->askToStop(); at the beginning of the close method

[rob-mau]

Can you add the mat file here?

robot_logger_device_2024_02_16_09_31_31.zip

[GiulioRomualdi]

When pressing CTRL+C, the close method should be called (see here, then here and finally here). I noticed that in the close method we do not stop the acquisition thread. We probably should add a this->askToStop(); at the beginning of the close method

Nice catch! @rob-mau could you try to implement what @S-Dafarra suggests and open a PR for that :) ?

[DanielePucci]

CC @nicktrem

[S-Dafarra]

When pressing CTRL+C, the close method should be called (see here, then here and finally here). I noticed that in the close method we do not stop the acquisition thread. We probably should add a this->askToStop(); at the beginning of the close method

Probably we should also substitute the default destructor adding a this->stop() to make sure that the thread is stopped before starting to destroy stuff.

[rob-mau]

rob-mau could you try to implement what S-Dafarra suggests and open a PR for that :) ?

I have implemented the suggested changes and opened a PR. The problem still persists.

[GiulioRomualdi]

We may double-check the attachments levels as explained in robotology/robots-configuration#377

[GiulioRomualdi]

We may double-check the attachments levels as explained in robotology/robots-configuration#377

I checked them, I fixed one of the detach level still the problem is there.

I noticed that when I press ctrl-c we got

^C[WARNING] |yarp.os.NetworkClock| Destroying network clock
[ERROR] [2024-04-15 11:45:01.780] [thread: 65590] [blf] [YarpSensorBridge::Impl::readAllJointSensors] Unable to read from IEncodersTimed interface, use previous measurement.
[ERROR] [2024-04-15 11:45:01.780] [thread: 65590] [blf] [YarpSensorBridge::Impl::readAllJointSensors] Unable to read from ITorqueControl interface, use previous measurement.
[ERROR] |yarp.device.multipleanalogsensorsclient| No data received in the last 1713170648.783669 seconds, timeout enabled.
[ERROR] |yarp.device.multipleanalogsensorsclient| Sensor of type ThreeAxisLinearAccelerometers with index 1 has non-MAS_OK status.
[ERROR] [2024-04-15 11:45:01.780] [thread: 65590] [blf] [YarpSensorBridge::Impl::readMASSensor] Unable to read from r_foot_rear_ft_imu, use previous measurement.

So the clock is destroyed while the thread is still running. As you can notice

[WARNING] |yarp.os.NetworkClock| Destroying network clock

is before

[ERROR] [2024-04-15 11:45:01.780] [thread: 65590] [blf] [YarpSensorBridge::Impl::readAllJointSensors] Unable to read from IEncodersTimed interface, use previous measurement.

[GiulioRomualdi]

I added a print at the beginning of the close and detachAll methods.

This is the trace. The clock is destroyed before the detachAll is called. That could be the reason why @rob-mau didn't solve the problem #812 (comment)

[WARNING] |yarp.os.NetworkClock| Destroying network clock
[INFO] |yarp.os.Network| Success: port-to-port persistent connection added.
[INFO] |yarp.os.impl.PortCoreInputUnit|/iiticublap261/yarprobotinterface/69520/clock:i| Removing input from /clock to /iiticublap261/yarprobotinterface/69520/clock:i
[INFO] |yarp.os.RFModule| [try 1 of 3] Trying to shut down.
[WARNING] Interrupt # 1 # received.
[INFO] Interrupt received. Stopping all running threads.
[INFO] All actions for action level 15 of startup phase started. Waiting for unfinished actions.
[INFO] All actions for action level 15 of startup phase finished.
[INFO] startup phase finished.
[INFO] run phase starting...
[INFO] |yarp.os.RFModule| RFModule closing.
[INFO] interrupt1 phase starting...
[INFO] interrupt1 phase finished.
[INFO] shutdown phase starting...
[INFO] Entering action level 2 of phase shutdown
[INFO] Executing detach action, level 2 on device yarp-robot-logger with parameters []
-----> detachAll
[INFO] All actions for action level 2 of shutdown phase started. Waiting for unfinished actions.
[INFO] All actions for action level 2 of shutdown phase finished.
[INFO] Entering action level 20 of phase shutdown
[INFO] Executing detach action, level 20 on device mas-remapper with parameters []
[INFO] All actions for action level 20 of shutdown phase started. Waiting for unfinished actions.
[INFO] All actions for action level 20 of shutdown phase finished.
[INFO] Closing device yarp-robot-logger
-----> close

[GiulioRomualdi]

Perhaps @traversaro and/or @randaz81 have some hints

[S-Dafarra]

I have noticed that the clock gets destroyed when calling removeClock, which is done in NetworkBase::finiMinimum

[GiulioRomualdi]

I have noticed that the clock gets destroyed when calling removeClock, which is done in NetworkBase::finiMinimum

That is called by the destructor of the RFModule

[S-Dafarra]

I think I might have an idea. yarprobotinterface is itself a RFModule. When pressing CTRL-C, it sets the use of SystemClock that in turns delete the Network clock

[S-Dafarra]

I guess that the problem is not the switch to the SystemClock per-se. I guess that the big number arises because the network clock and the System clock might use a different epoch.

[GiulioRomualdi]

I guess that the problem is not the switch to the SystemClock per-se. I guess that the big number arises because the network clock and the System clock might use a different epoch.

From a theoretical perspective, I don't see anything preventing the two clocks from starting at different epochs 🤔

In our case, the network clock is generated by https://github.com/robotology/gazebo-yarp-plugins/tree/master/plugins/clock.

The content of the /clock port is as follows:

0 1000000
0 2000000
0 3000000
0 4000000
0 5000000
...

when I start Gazebo.

As explained here, the first value represents seconds and the second represents nanoseconds. It starts from 0.0000000 s. However, starting the network clock from the system clock might not be the correct solution, as the network clock, i.e., the Gazebo simulation, could quickly diverge from the system clock (realtime factor different from 1)

[GiulioRomualdi]

Talking with @S-Dafarra we thought that we could avoid saving the data if the difference between the current time instant and the previous one is greater than the threshold

[GiulioRomualdi]

Fixed by #839

[GiulioRomualdi]

cc @FabioBergonti