Adding a timestamp to debug messages #61

SejalBehere · 2023-06-15T14:37:54Z

Changes were made to Debug.c to include a timestamp (Format - Day Y:M:D H:M:S.ms) in front of the debug messages being printed. Change was made to MotoROS_PlatformLib.h to add the function localtime_r. These changes were "Fixes #38" to resolve the issue "Add timestamp to debug udp broadcasts" .

gavanderhoorn

Thanks for the PR 👍

I've left a couple in-line comments.

Besides those: IIUC, this returns time in 'local time'. Many controllers will not be configured with the correct timezone (if that is even possible), and will likely not have NTP setup.

This means stamps prefixed to debug output would not necessarily show the correct time, when compared to the time of the receiving systems.

In a previous version I believe you used the time from the host, synced using the micro-ROS Agent. That would seem to avoid the timezone issue.

Did that not work correctly?

gavanderhoorn · 2023-06-15T17:04:23Z

src/Debug.c

@@ -36,6 +36,7 @@ void Ros_Debug_Init()
 void Ros_Debug_BroadcastMsg(char* fmt, ...)
 {
    char str[MAX_DEBUG_MESSAGE_SIZE];
+    char Formatted_Time[300];


Please use a named constant (ie: #define) for the buffer size instead of a magic nr.

I will make that change

It doesn't appear that Formatted_Time is used in the code below. Looks like a leftover artifact from debugging. I recommend removing this unused variable.
(If you do want to use it for something, be sure to replace the 300 with FORMATTED_TIME_SIZE.)

src/Debug.c

ted-miller · 2023-06-15T17:45:26Z

In a previous version I believe you used the time from the host, synced using the micro-ROS Agent. That would seem to avoid the timezone issue.

gavanderhoorn is right, we have used another time function that is synchronized with the PC running the microROS Agent.

motoros2/src/PositionMonitor.c

Lines 404 to 406 in 9f1c599

    
           INT64 theTime = rmw_uros_epoch_nanos(); 
        
           Ros_Nanos_To_Time_Msg(theTime, &g_messages_PositionMonitor.jointStateAllGroups->header.stamp);

rmw_uros_epoch_nanos gets nanoseconds. Then Ros_Nanos_To_Time_Msg will break that into seconds and remaining nanoseconds.

gavanderhoorn · 2023-06-15T17:50:58Z

I was looking at Yaskawa-Global:9f1c599...SejalBehere:7f163ac.

That seems to do what you also suggest @ted-miller, but there must be a reason this didn't make it into this PR. Hence my question.

SejalBehere · 2023-06-15T18:03:27Z

In a previous version I did use time from the host, synced using the micro-ROS Agent. I was able to get the timestamp in the format of H:M:S.ms but was not able to add the day to it without adding the whole of what I have used now as well.

I will make some more changes to the previous version and get the current timestamp format using the host time.

…for debug messages

ted-miller · 2023-06-19T21:03:30Z

src/Debug.c

+    builtin_interfaces__msg__Time debug_msg_timestamp;
+
+    Ros_Nanos_To_Time_Msg(nanosecs, &debug_msg_timestamp);
+    time(&debug_msg_timestamp);


IIUC, the time function will put the current time into debug_msg_timestamp. But, this is not needed because the current timestamp was already obtained above with rmw_uros_epoch_nanos. I think that this line can be deleted.

I did try by removing that line but what is happening is that for the fist few messages, before the message "Attempting to connect to the micro-ROS agent", the timestamp being showed is the epoch time (THU 1970-01-01 00:00:00.000) and it is only after this message that it shows the current timestamp.

I see. Then I would suggest making the time source conditional on whether the agent is connected.

if (g_Ros_Communication_AgentIsConnected) { //get synchronized time from the agent int64_t nanosecs = rmw_uros_epoch_nanos(); Ros_Nanos_To_Time_Msg(nanosecs, &debug_msg_timestamp); } else { //rmw_uros_epoch_nanos cannot sync with agent because it's not connected time(&debug_msg_timestamp); }

Okay, I will replace the time function with the conditional

I'm not sure you can pass an instance of builtin_interfaces__msg__Time to time(..).

gavanderhoorn · 2023-06-27T13:39:52Z

@SejalBehere: if this is ready for another review please either request one or comment.

SejalBehere · 2023-06-27T14:25:30Z

@gavanderhoorn This is ready for another review.

src/Debug.c

SejalBehere · 2023-06-28T15:53:12Z

I have made the changes to address the points raised in the above review. Also, I have removed the +1 as like @ted-miller said str buffer is getting zeroed at the top and hence there's no need for considering the null terminator.

ted-miller

The only other question I have is to confirm whether you have a tested this on a live controller. If so, please post an example copy/paste of the output so we can see the final product.
Thanks!

ted-miller · 2023-06-28T19:52:38Z

src/Debug.c

@@ -36,6 +36,7 @@ void Ros_Debug_Init()
 void Ros_Debug_BroadcastMsg(char* fmt, ...)
 {
    char str[MAX_DEBUG_MESSAGE_SIZE];
+    char Formatted_Time[300];


It doesn't appear that Formatted_Time is used in the code below. Looks like a leftover artifact from debugging. I recommend removing this unused variable.
(If you do want to use it for something, be sure to replace the 300 with FORMATTED_TIME_SIZE.)

ted-miller · 2023-06-28T20:23:48Z

Also, I owe you an updated version of MotoROS_PlatformLib.h

SejalBehere · 2023-06-28T20:36:48Z

I have made the changes to the branch. I did test this on a live controller and the output was obtained in the following format:

[1687983037.99751401] [192.168.1.31:58649]: WED 2023-06-28 16:10:25.768 Using ROS domain ID: 0
[1687983037.99761701] [192.168.1.31:58649]: WED 2023-06-28 16:10:25.768 Using client key: 0x73B9D4ED
[1687983037.99765611] [192.168.1.31:58649]: WED 2023-06-28 16:10:25.768 Attempting to connect to Micro-ROS PC Agent (at udp://192.168.1.50:8888)
[1687983039.01968718] [192.168.1.31:58649]: THU 1970-01-01 00:00:00.000 Found Micro-ROS PC Agent
[1687983039.02444792] [192.168.1.31:58649]: WED 2023-06-28 16:10:26.795 rclc_support_init_with_options = 0
[1687983039.02451229] [192.168.1.31:58649]: WED 2023-06-28 16:10:26.795 remap_rules str: ''
[1687983039.02464890] [192.168.1.31:58649]: WED 2023-06-28 16:10:26.795 len(remap_rules str): 0
[1687983039.02472425] [192.168.1.31:58649]: WED 2023-06-28 16:10:26.795 num parsed remap rules: 0

ted-miller · 2023-06-30T15:51:07Z

Looks good to me. Thanks for the contribution!

I'll work on resolving the conflicts this afternoon and get this merged.

src/MotoROS_PlatformLib.h

gavanderhoorn

See my comment.

Header updated with just the changes to localtime_r

gavanderhoorn · 2023-07-10T18:41:33Z

Building this for DX200 I get several warnings, with one sticking out:

src/Debug.c:63: warning: passing argument 1 of 'localtime_r' from incompatible pointer type

that would be this line.

@SejalBehere: could you confirm the YRC build doesn't warn on this?

ted-miller · 2023-07-10T19:14:11Z

I can confirm that YRC does raise a warning. It's wanting a time_t instead of int32_t. I guess a simple explicit cast should resolve it.

ted-miller · 2023-07-10T19:22:17Z

@gavanderhoorn, I'm also getting a warning for gettimeofday. Is that not defined somewhere? (It seems to work/run...)

gavanderhoorn · 2023-07-10T19:23:32Z

Not on DX200.

See #18 (comment).

PR Yaskawa-Global#61 added a timestamp to the log message sent out by MotoROS2. Use that timestamp instead of calculating a new one upon reception. The format of the timestamp prefixed by MotoROS2 is exactly the same as what `debug_listener.py` used to prefix. But due to limitations on the VxWorks side, will likely not take time-zones into account.

SejalBehere added 3 commits June 13, 2023 14:42

Update Debug.c to show Y-m-D, H:M:S.msec Timestamp for Debug Messages

11f27db

Update Debug.c to add comments

f6c1e1c

Update MotoROS_PlatformLib.h to add localtime_r

e203af9

gavanderhoorn requested changes Jun 15, 2023

View reviewed changes

gavanderhoorn added this to the 0.1.1 milestone Jun 16, 2023

ted-miller mentioned this pull request Jun 16, 2023

Possible failure of rmw_uros_sync_session #68

Open

Update Debug.c to obtain micro-ROS agent synced host-time timestamps …

449fe4d

…for debug messages

ted-miller reviewed Jun 19, 2023

View reviewed changes

SejalBehere added 4 commits June 20, 2023 14:34

Update Debug.c Removal of time function

07e7789

Update Debug.c comments added

0c40e96

Update Debug.c to remove a blank line

4c5db61

Update Debug.c Removal of blank lines

1175e30

ted-miller requested changes Jun 27, 2023

View reviewed changes

src/Debug.c Outdated Show resolved Hide resolved

src/Debug.c Show resolved Hide resolved

src/Debug.c Outdated Show resolved Hide resolved

Update Debug.c Changes made to reflect the points raised in review

100c430

ted-miller requested changes Jun 28, 2023

View reviewed changes

SejalBehere added 2 commits June 28, 2023 16:08

Update Debug.c Removal of Formatted_Time

3869a7d

Update Debug.c To add space after the timestamp

80d0850

ted-miller previously approved these changes Jun 30, 2023

View reviewed changes

gavanderhoorn reviewed Jun 30, 2023

View reviewed changes

src/MotoROS_PlatformLib.h Outdated Show resolved Hide resolved

gavanderhoorn previously requested changes Jun 30, 2023

View reviewed changes

SejalBehere dismissed ted-miller’s stale review via 914a805 June 30, 2023 18:43

SejalBehere and others added 2 commits July 5, 2023 11:01

Update Debug.c Declaration of timestamp

1be2893

Update declaration of localtime_r for different controller models

ad5a349

ted-miller force-pushed the Final_Timestamp_Debug_Msg branch from 914a805 to ad5a349 Compare July 5, 2023 15:06

Merge branch 'main' into Final_Timestamp_Debug_Msg

38c6a91

ted-miller approved these changes Jul 5, 2023

View reviewed changes

ted-miller merged commit 9f68b48 into Yaskawa-Global:main Jul 5, 2023

gavanderhoorn mentioned this pull request Jun 29, 2023

Add support for DX200 #18

Closed

9 tasks

gavanderhoorn mentioned this pull request Jul 10, 2023

debug: use Ros wrapper of strnlen(..) instead #82

Merged

ted-miller mentioned this pull request Jul 10, 2023

Explicit casting to resolve warning #83

Merged

This was referenced Jul 13, 2023

Implicit declaration of gettimeofday(..) #91

Closed

Double timestamps on debug log lines #96

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adding a timestamp to debug messages #61

Adding a timestamp to debug messages #61

SejalBehere commented Jun 15, 2023

gavanderhoorn left a comment

gavanderhoorn Jun 15, 2023

SejalBehere Jun 15, 2023

ted-miller Jun 28, 2023

ted-miller commented Jun 15, 2023

gavanderhoorn commented Jun 15, 2023 •

edited

Loading

SejalBehere commented Jun 15, 2023 •

edited by gavanderhoorn

Loading

ted-miller Jun 19, 2023

SejalBehere Jun 19, 2023

ted-miller Jun 20, 2023

SejalBehere Jun 20, 2023

gavanderhoorn Jun 20, 2023

gavanderhoorn commented Jun 27, 2023

SejalBehere commented Jun 27, 2023

SejalBehere commented Jun 28, 2023

ted-miller left a comment

ted-miller Jun 28, 2023

ted-miller commented Jun 28, 2023

SejalBehere commented Jun 28, 2023

ted-miller commented Jun 30, 2023

gavanderhoorn left a comment

gavanderhoorn commented Jul 10, 2023

ted-miller commented Jul 10, 2023

ted-miller commented Jul 10, 2023

gavanderhoorn commented Jul 10, 2023 •

edited

Loading

Adding a timestamp to debug messages #61

Adding a timestamp to debug messages #61

Conversation

SejalBehere commented Jun 15, 2023

gavanderhoorn left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ted-miller commented Jun 15, 2023

gavanderhoorn commented Jun 15, 2023 • edited Loading

SejalBehere commented Jun 15, 2023 • edited by gavanderhoorn Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gavanderhoorn commented Jun 27, 2023

SejalBehere commented Jun 27, 2023

SejalBehere commented Jun 28, 2023

ted-miller left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ted-miller commented Jun 28, 2023

SejalBehere commented Jun 28, 2023

ted-miller commented Jun 30, 2023

gavanderhoorn left a comment

Choose a reason for hiding this comment

gavanderhoorn commented Jul 10, 2023

ted-miller commented Jul 10, 2023

ted-miller commented Jul 10, 2023

gavanderhoorn commented Jul 10, 2023 • edited Loading

gavanderhoorn commented Jun 15, 2023 •

edited

Loading

SejalBehere commented Jun 15, 2023 •

edited by gavanderhoorn

Loading

gavanderhoorn commented Jul 10, 2023 •

edited

Loading