Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Adding a timestamp to debug messages #61

Merged
merged 14 commits into from
Jul 5, 2023
Merged
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
46 changes: 19 additions & 27 deletions src/Debug.c
Original file line number Diff line number Diff line change
Expand Up @@ -47,37 +47,29 @@ void Ros_Debug_BroadcastMsg(char* fmt, ...)

if (ros_DebugSocket == -1)
Ros_Debug_Init();

// Timestamp

gavanderhoorn marked this conversation as resolved.
Show resolved Hide resolved
time_t DEBUG_MSG_TIMESTAMP;
struct tm ts;
struct timeval tv;


time(&DEBUG_MSG_TIMESTAMP);

localtime_r(&DEBUG_MSG_TIMESTAMP, &ts);

strftime(Formatted_Time, sizeof(Formatted_Time), "%a %Y-%m-%d %H:%M:%S", &ts);

gettimeofday(&tv, NULL);
long msec = tv.tv_usec / 1000;

snprintf(Formatted_Time, sizeof(Formatted_Time), "%s.%03ld", Formatted_Time, msec);

size_t Timestamp_Length = strlen(Formatted_Time);
size_t Debug_Message_Length = strlen(str);

// Pre-pending the timestamp to the debug message

if (Timestamp_Length + Debug_Message_Length + 1 < MAX_DEBUG_MESSAGE_SIZE)
// Timestamp
struct tm synced_time;
int64_t nanosecs = rmw_uros_epoch_nanos();
ted-miller marked this conversation as resolved.
Show resolved Hide resolved
builtin_interfaces__msg__Time debug_msg_timestamp;

Ros_Nanos_To_Time_Msg(nanosecs, &debug_msg_timestamp);
time(&debug_msg_timestamp);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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);
}

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay, I will replace the time function with the conditional

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

strftime(timestamp, FORMATTED_TIME_SIZE, "%a %Y-%m-%d %H:%M:%S", localtime_r(&debug_msg_timestamp.sec, &synced_time));
snprintf(timestamp + strlen(timestamp), FORMATTED_TIME_SIZE - strlen(timestamp), ".%03d", (int)debug_msg_timestamp.nanosec / 1000000);

// Pre - pending the timestamp to the debug message
size_t timestamp_length = strnlen(timestamp, FORMATTED_TIME_SIZE);
size_t debug_message_length = strnlen(str, MAX_DEBUG_MESSAGE_SIZE);
if (timestamp_length + debug_message_length + 1 < MAX_DEBUG_MESSAGE_SIZE)
{
memmove(str + Timestamp_Length, str, Debug_Message_Length + 1); // Move existing contents of str buffer to the end by Timestamp_Length to make space for the timestamp and avoiding overwriting the debug message during the move
memcpy(str, Formatted_Time, Timestamp_Length); // Copy the timestamp stored in Formatted_Timestamp buffer to the beginning of str buffer
// Move existing contents of str buffer to the end by Timestamp_Length to make space
//for the timestamp and avoiding overwriting the debug message during the move
memmove(str + timestamp_length, str, debug_message_length + 1);
ted-miller marked this conversation as resolved.
Show resolved Hide resolved
// Copy the timestamp stored in Formatted_time buffer to the beginning of str buffer
memcpy(str, timestamp, timestamp_length);
}
gavanderhoorn marked this conversation as resolved.
Show resolved Hide resolved


mpSendTo(ros_DebugSocket, str, strlen(str), 0, (struct sockaddr*) &ros_debug_destAddr1, sizeof(struct sockaddr_in));

if (g_nodeConfigSettings.log_to_stdout)
Expand Down