RDKEMW-7226: Add Logs to calculate time for shutdown sequence#274
RDKEMW-7226: Add Logs to calculate time for shutdown sequence#274yogeswaransky wants to merge 3 commits intodevelopfrom
Conversation
Signed-off-by: Yogeswaran K <yogeswaransky@gmail.com>
There was a problem hiding this comment.
Pull request overview
This PR adds logging and timing measurements for the telemetry2_0 shutdown sequence to help diagnose shutdown performance issues. The changes instrument both the systemd service shutdown process and the internal C application termination to capture timing information.
Changes:
- Added shutdown timing logs in systemd service file (ExecStop/ExecStopPost) that measure the time from stop initiation to completion
- Added shutdown timing logs in C code (terminate function) that measure internal cleanup duration
- Introduced timestamp-based duration calculation using temporary file for systemd-level timing
Reviewed changes
Copilot reviewed 2 out of 2 changed files in this pull request and generated 2 comments.
| File | Description |
|---|---|
| telemetry2_0.service | Added ExecStop and ExecStopPost commands that log shutdown initiation and completion with elapsed time calculation |
| source/telemetry2_0.c | Added timing instrumentation in terminate() function to log shutdown start, end, and duration in milliseconds |
Comments suppressed due to low confidence (1)
source/telemetry2_0.c:112
- The variable name t2 is less descriptive than t_start. Consider renaming t2 to t_end for improved code readability and consistency.
struct timespec t2, t_start;
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
source/telemetry2_0.c
Outdated
| T2Info("=== [SHUTDOWN] telemetry2_0 shutdown complete, total=%ldms ===\n", | ||
| (t2.tv_sec - t_start.tv_sec) * 1000 + (t2.tv_nsec - t_start.tv_nsec) / 1000000); |
There was a problem hiding this comment.
The time calculation could produce incorrect results if the nanosecond subtraction (t2.tv_nsec - t_start.tv_nsec) is negative. When t2.tv_nsec is less than t_start.tv_nsec, the division will produce a negative millisecond value. The codebase already has a getLapsedTime function in source/scheduler/scheduler.c that properly handles nanosecond wraparound. Consider using that function instead of performing the calculation inline.
| T2Info("=== [SHUTDOWN] telemetry2_0 shutdown complete, total=%ldms ===\n", | |
| (t2.tv_sec - t_start.tv_sec) * 1000 + (t2.tv_nsec - t_start.tv_nsec) / 1000000); | |
| long sec = t2.tv_sec - t_start.tv_sec; | |
| long nsec = t2.tv_nsec - t_start.tv_nsec; | |
| if (nsec < 0) | |
| { | |
| sec -= 1; | |
| nsec += 1000000000L; | |
| } | |
| long elapsed_ms = sec * 1000L + nsec / 1000000L; | |
| T2Info("=== [SHUTDOWN] telemetry2_0 shutdown complete, total=%ldms ===\n", | |
| elapsed_ms); |
telemetry2_0.service
Outdated
| ExecStop=/usr/bin/killall telemetry2_0 | ||
| ExecStopPost=/bin/rm -rf /tmp/.t2ReadyToReceiveEvents /tmp/telemetry_initialized_bootup /tmp/.t2ConfigReady | ||
| ExecStop=/bin/sh -c 'echo "[SHUTDOWN] $(date +%%Y-%%m-%%dT%%H:%%M:%%S) telemetry2_0 stop initiated by systemd" >> /rdklogs/logs/telemetry2_0.txt.0 2>&1; date +%%s > /tmp/.t2_stop_start 2>/dev/null; /usr/bin/killall telemetry2_0' | ||
| ExecStopPost=/bin/sh -c 'T_START=$(cat /tmp/.t2_stop_start 2>/dev/null); T_END=$(date +%%s); ELAPSED=$((T_END - ${T_START:-$T_END})); echo "[SHUTDOWN] $(date +%%Y-%%m-%%dT%%H:%%M:%%S) telemetry2_0 stop completed in ${ELAPSED}s" >> /rdklogs/logs/telemetry2_0.txt.0 2>&1; rm -f /tmp/.t2_stop_start; /bin/rm -rf /tmp/.t2ReadyToReceiveEvents /tmp/telemetry_initialized_bootup /tmp/.t2ConfigReady' |
There was a problem hiding this comment.
The ExecStopPost shell command evaluates data read from /tmp/.t2_stop_start inside an arithmetic expansion ELAPSED=$((T_END - ${T_START:-$T_END})) without any validation or sanitization. Since /tmp is world-writable, a local attacker can repeatedly overwrite /tmp/.t2_stop_start with a payload like $(malicious_command) and eventually win the race, causing that command substitution to execute as the service user (likely root) when the arithmetic expansion is evaluated. To fix this, treat /tmp/.t2_stop_start as untrusted input: either move it to a non-world-writable location with safe permissions or strictly validate that T_START is numeric before using it in arithmetic expansion so that no command substitution or non-numeric content can be interpreted.
| ExecStopPost=/bin/sh -c 'T_START=$(cat /tmp/.t2_stop_start 2>/dev/null); T_END=$(date +%%s); ELAPSED=$((T_END - ${T_START:-$T_END})); echo "[SHUTDOWN] $(date +%%Y-%%m-%%dT%%H:%%M:%%S) telemetry2_0 stop completed in ${ELAPSED}s" >> /rdklogs/logs/telemetry2_0.txt.0 2>&1; rm -f /tmp/.t2_stop_start; /bin/rm -rf /tmp/.t2ReadyToReceiveEvents /tmp/telemetry_initialized_bootup /tmp/.t2ConfigReady' | |
| ExecStopPost=/bin/sh -c 'T_START=$(cat /tmp/.t2_stop_start 2>/dev/null); T_END=$(date +%%s); case "$T_START" in ""|*[!0-9]*) T_START=$T_END;; esac; ELAPSED=$((T_END - T_START)); echo "[SHUTDOWN] $(date +%%Y-%%m-%%dT%%H:%%M:%%S) telemetry2_0 stop completed in ${ELAPSED}s" >> /rdklogs/logs/telemetry2_0.txt.0 2>&1; rm -f /tmp/.t2_stop_start; /bin/rm -rf /tmp/.t2ReadyToReceiveEvents /tmp/telemetry_initialized_bootup /tmp/.t2ConfigReady' |
Signed-off-by: Yogeswaran K <yogeswaransky@gmail.com>
Signed-off-by: Yogeswaran K <yogeswaransky@gmail.com>
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 2 out of 2 changed files in this pull request and generated 2 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| struct timespec t2, t_start; | ||
| clock_gettime(CLOCK_MONOTONIC, &t_start); | ||
| T2Info("=== [SHUTDOWN] telemetry2_0 shutdown started ===\n"); |
There was a problem hiding this comment.
This file uses struct timespec, CLOCK_MONOTONIC, and clock_gettime() but does not include <time.h> directly. It may compile only due to indirect includes, which is not portable/reliable; please add the explicit header include for these time APIs.
| @@ -131,6 +135,9 @@ static void terminate() | |||
| ReportProfiles_uninit(); | |||
| http_pool_cleanup(); | |||
| } | |||
| clock_gettime(CLOCK_MONOTONIC, &t2); | |||
| T2Info("=== [SHUTDOWN] telemetry2_0 shutdown complete, total=%lldms ===\n", | |||
| (long long)(t2.tv_sec - t_start.tv_sec) * 1000 + (t2.tv_nsec - t_start.tv_nsec) / 1000000LL); | |||
There was a problem hiding this comment.
Both clock_gettime() calls ignore the return value. If either fails, the elapsed-time log can be garbage due to uninitialized timespec fields. Please handle failures (e.g., log an error and skip/zero the duration) to keep shutdown logging reliable.
No description provided.