Update log timestamp in custom scripts align with supervisord (#2441)

Author: VietND96

Diff for: .circleci/config.yml

@@ -37,7 +37,7 @@ workflows:
           name: "K8s test - Autoscaling Deployments"
           platforms: linux/arm64
           machine-type: ubuntu2204arm64large
-          k8s-version: 'v1.28.14'
+          k8s-version: 'v1.28.15'
           test-strategy: deployment
           cluster: 'minikube'
           helm-version: 'v3.13.3'
@@ -47,7 +47,7 @@ workflows:
           name: "K8s test - Autoscaling Jobs - HTTPS"
           platforms: linux/arm64
           machine-type: ubuntu2204arm64large
-          k8s-version: 'v1.29.9'
+          k8s-version: 'v1.29.10'
           test-strategy: job_https
           cluster: 'minikube'
           helm-version: 'v3.14.3'
@@ -57,7 +57,7 @@ workflows:
           name: "K8s test - Autoscaling Jobs - Ingress hostname"
           platforms: linux/arm64
           machine-type: ubuntu2204arm64large
-          k8s-version: 'v1.30.5'
+          k8s-version: 'v1.30.6'
           test-strategy: job_hostname
           cluster: 'minikube'
           helm-version: 'v3.15.4'

Diff for: .github/workflows/helm-chart-test.yml

@@ -55,21 +55,21 @@ jobs:
             docker-version: '24.0.9'
             test-upgrade: true
             service-mesh: true
-          - k8s-version: 'v1.28.14'
+          - k8s-version: 'v1.28.15'
             test-strategy: deployment
             cluster: 'minikube'
             helm-version: 'v3.13.3'
             docker-version: '24.0.9'
             test-upgrade: true
             service-mesh: true
-          - k8s-version: 'v1.29.9'
+          - k8s-version: 'v1.29.10'
             test-strategy: job_https
             cluster: 'minikube'
             helm-version: 'v3.14.3'
             docker-version: '25.0.5'
             test-upgrade: true
             service-mesh: false
-          - k8s-version: 'v1.30.5'
+          - k8s-version: 'v1.30.6'
             test-strategy: job_hostname
             cluster: 'minikube'
             helm-version: 'v3.15.4'

Diff for: Base/Dockerfile

@@ -163,6 +163,7 @@ ENV SE_BIND_HOST=false \
     SE_SUPERVISORD_CHILD_LOG_DIR="/tmp" \
     SE_SUPERVISORD_LOG_FILE="/tmp/supervisord.log" \
     SE_SUPERVISORD_PID_FILE="/tmp/supervisord.pid" \
+    SE_LOG_TIMESTAMP_FORMAT="%Y-%m-%d %H:%M:%S,%3N" \
     SE_LOG_LEVEL="INFO" \
     SE_HTTP_LOGS=false \
     SE_STRUCTURED_LOGS=false \

Diff for: Video/upload.sh

@@ -9,6 +9,7 @@ UPLOAD_RETAIN_LOCAL_FILE=${SE_UPLOAD_RETAIN_LOCAL_FILE:-"false"}
 UPLOAD_PIPE_FILE_NAME=${SE_UPLOAD_PIPE_FILE_NAME:-"uploadpipe"}
 VIDEO_INTERNAL_UPLOAD=${VIDEO_INTERNAL_UPLOAD:-$SE_VIDEO_INTERNAL_UPLOAD}
 VIDEO_UPLOAD_BATCH_CHECK=${SE_VIDEO_UPLOAD_BATCH_CHECK:-"10"}
+ts_format=${SE_LOG_TIMESTAMP_FORMAT:-"%Y-%m-%d %H:%M:%S,%3N"}
 process_name="video.uploader"
 
 if [ "${VIDEO_INTERNAL_UPLOAD}" = "true" ]; then
@@ -22,7 +23,7 @@ else
 fi
 
 if [ "${UPLOAD_RETAIN_LOCAL_FILE}" = "false" ]; then
-  echo "$(date +%FT%T%Z) [${process_name}] - UPLOAD_RETAIN_LOCAL_FILE is set to false, force to use RCLONE command: move"
+  echo "$(date -u +"${ts_format}") [${process_name}] - UPLOAD_RETAIN_LOCAL_FILE is set to false, force to use RCLONE command: move"
   UPLOAD_COMMAND="move"
 fi
 
@@ -55,7 +56,7 @@ function check_and_clear_background() {
 function rclone_upload() {
   local source=$1
   local target=$2
-  echo "$(date +%FT%T%Z) [${process_name}] - Uploading ${source} to ${target}"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Uploading ${source} to ${target}"
   rclone --config ${UPLOAD_CONFIG_DIRECTORY}/${UPLOAD_CONFIG_FILE_NAME} ${UPLOAD_COMMAND} ${UPLOAD_OPTS} "${source}" "${target}" &
   list_rclone_pid+=($!)
   check_and_clear_background
@@ -70,46 +71,46 @@ function check_if_pid_alive() {
 }
 
 function consume_pipe_file_in_background() {
-  echo "$(date +%FT%T%Z) [${process_name}] - Start consuming pipe file to upload"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Start consuming pipe file to upload"
   while read FILE DESTINATION <${UPLOAD_PIPE_FILE}; do
     if [ "${FILE}" = "exit" ]; then
-      echo "$(date +%FT%T%Z) [${process_name}] - Received exit signal. Aborting upload process"
+      echo "$(date -u +"${ts_format}") [${process_name}] - Received exit signal. Aborting upload process"
       return 0
     elif [ "$FILE" != "" ] && [ "$DESTINATION" != "" ]; then
       rclone_upload "${FILE}" "${DESTINATION}"
     fi
   done
-  echo "$(date +%FT%T%Z) [${process_name}] - Stopped consuming pipe file. Upload process is done"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Stopped consuming pipe file. Upload process is done"
   return 0
 }
 
 # Function to check if the named pipe exists
 check_if_pipefile_exists() {
   if [ -p "${UPLOAD_PIPE_FILE}" ]; then
-    echo "$(date +%FT%T%Z) [${process_name}] - Named pipe ${UPLOAD_PIPE_FILE} exists"
+    echo "$(date -u +"${ts_format}") [${process_name}] - Named pipe ${UPLOAD_PIPE_FILE} exists"
     return 0
   fi
   return 1
 }
 
 function wait_until_pipefile_exists() {
-  echo "$(date +%FT%T%Z) [${process_name}] - Waiting for ${UPLOAD_PIPE_FILE} to be present"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Waiting for ${UPLOAD_PIPE_FILE} to be present"
   until check_if_pipefile_exists; do
     sleep 1
   done
 }
 
 function graceful_exit() {
-  echo "$(date +%FT%T%Z) [${process_name}] - Trapped SIGTERM/SIGINT/x so shutting down uploader"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Trapped SIGTERM/SIGINT/x so shutting down uploader"
   if ! check_if_pid_alive "${UPLOAD_PID}"; then
     consume_pipe_file_in_background &
     UPLOAD_PID=$!
   fi
   echo "exit" >>"${UPLOAD_PIPE_FILE}" &
   wait "${UPLOAD_PID}"
-  echo "$(date +%FT%T%Z) [${process_name}] - Uploader consumed all files in the pipe"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Uploader consumed all files in the pipe"
   rm -rf "${FORCE_EXIT_FILE}"
-  echo "$(date +%FT%T%Z) [${process_name}] - Uploader is ready to shutdown"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Uploader is ready to shutdown"
   exit 0
 }
 

Diff for: Video/validate_endpoint.sh

@@ -3,6 +3,7 @@
 endpoint=$1
 graphql_endpoint=${2:-false}
 max_time=1
+ts_format=${SE_LOG_TIMESTAMP_FORMAT:-"%Y-%m-%d %H:%M:%S,%3N"}
 process_name="endpoint.checks"
 
 BASIC_AUTH="$(echo -en "${SE_ROUTER_USERNAME}:${SE_ROUTER_PASSWORD}" | base64 -w0)"
@@ -18,9 +19,9 @@ else
 fi
 
 if [[ "$endpoint_checks" = "404" ]]; then
-  echo "$(date +%FT%T%Z) [${process_name}] - Endpoint ${endpoint} is not found - status code: ${endpoint_checks}"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Endpoint ${endpoint} is not found - status code: ${endpoint_checks}"
 elif [[ "$endpoint_checks" = "401" ]]; then
-  echo "$(date +%FT%T%Z) [${process_name}] - Endpoint ${endpoint} requires authentication - status code: ${endpoint_checks}. Please provide valid credentials via SE_ROUTER_USERNAME and SE_ROUTER_PASSWORD environment variables."
+  echo "$(date -u +"${ts_format}") [${process_name}] - Endpoint ${endpoint} requires authentication - status code: ${endpoint_checks}. Please provide valid credentials via SE_ROUTER_USERNAME and SE_ROUTER_PASSWORD environment variables."
 elif [[ "$endpoint_checks" != "200" ]]; then
-  echo "$(date +%FT%T%Z) [${process_name}] - Endpoint ${endpoint} is not available - status code: ${endpoint_checks}"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Endpoint ${endpoint} is not available - status code: ${endpoint_checks}"
 fi

Diff for: Video/video.sh

@@ -16,6 +16,7 @@ UPLOAD_PIPE_FILE_NAME=${SE_UPLOAD_PIPE_FILE_NAME:-"uploadpipe"}
 SE_SERVER_PROTOCOL=${SE_SERVER_PROTOCOL:-"http"}
 poll_interval=${SE_VIDEO_POLL_INTERVAL:-1}
 max_attempts=${SE_VIDEO_WAIT_ATTEMPTS:-50}
+ts_format=${SE_LOG_TIMESTAMP_FORMAT:-"%Y-%m-%d %H:%M:%S,%3N"}
 process_name="video.recorder"
 
 if [ "${SE_VIDEO_RECORD_STANDALONE}" = "true" ]; then
@@ -32,9 +33,9 @@ fi
 BASIC_AUTH="$(echo -en "${SE_ROUTER_USERNAME}:${SE_ROUTER_PASSWORD}" | base64 -w0)"
 
 if [ -d "${VIDEO_FOLDER}" ]; then
-  echo "$(date +%FT%T%Z) [${process_name}] - Video folder exists: ${VIDEO_FOLDER}"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Video folder exists: ${VIDEO_FOLDER}"
 else
-  echo "$(date +%FT%T%Z) [${process_name}] - Video folder does not exist: ${VIDEO_FOLDER}. Due to permission, folder name could not be changed via environment variable. Exiting..."
+  echo "$(date -u +"${ts_format}") [${process_name}] - Video folder does not exist: ${VIDEO_FOLDER}. Due to permission, folder name could not be changed via environment variable. Exiting..."
   exit 1
 fi
 
@@ -56,20 +57,20 @@ function create_named_pipe() {
         rm -f "${UPLOAD_PIPE_FILE}"
       fi
       mkfifo "${UPLOAD_PIPE_FILE}"
-      echo "$(date +%FT%T%Z) [${process_name}] - Created named pipe ${UPLOAD_PIPE_FILE}"
+      echo "$(date -u +"${ts_format}") [${process_name}] - Created named pipe ${UPLOAD_PIPE_FILE}"
     fi
   fi
 }
 
 function wait_for_display() {
   DISPLAY=${DISPLAY_CONTAINER_NAME}:${DISPLAY_NUM}.0
   export DISPLAY=${DISPLAY}
-  echo "$(date +%FT%T%Z) [${process_name}] - Waiting for the display ${DISPLAY} is open"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Waiting for the display ${DISPLAY} is open"
   until xset b off >/dev/null 2>&1; do
     sleep ${poll_interval}
   done
   VIDEO_SIZE=$(xdpyinfo | grep 'dimensions:' | awk '{print $2}')
-  echo "$(date +%FT%T%Z) [${process_name}] - Display ${DISPLAY} is open with dimensions ${VIDEO_SIZE}"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Display ${DISPLAY} is open with dimensions ${VIDEO_SIZE}"
 }
 
 function check_if_api_respond() {
@@ -81,7 +82,7 @@ function check_if_api_respond() {
 }
 
 function wait_for_api_respond() {
-  echo "$(date +%FT%T%Z) [${process_name}] - Waiting for Node endpoint responds"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Waiting for Node endpoint responds"
   until check_if_api_respond; do
     sleep ${poll_interval}
   done
@@ -94,31 +95,31 @@ function wait_util_uploader_shutdown() {
   if [[ "${VIDEO_UPLOAD_ENABLED}" = "true" ]] && [[ -n "${UPLOAD_DESTINATION_PREFIX}" ]] && [[ "${VIDEO_INTERNAL_UPLOAD}" != "true" ]]; then
     while [[ -f ${FORCE_EXIT_FILE} ]] && [[ ${wait} -lt ${max_wait} ]]; do
       echo "exit" >>${UPLOAD_PIPE_FILE} &
-      echo "$(date +%FT%T%Z) [${process_name}] - Waiting for force exit file to be consumed by external upload container"
+      echo "$(date -u +"${ts_format}") [${process_name}] - Waiting for force exit file to be consumed by external upload container"
       sleep 1
       wait=$((wait + 1))
     done
   fi
   if [[ "${VIDEO_UPLOAD_ENABLED}" = "true" ]] && [[ -n "${UPLOAD_DESTINATION_PREFIX}" ]] && [[ "${VIDEO_INTERNAL_UPLOAD}" = "true" ]]; then
     while [[ $(pgrep rclone | wc -l) -gt 0 ]]; do
       echo "exit" >>${UPLOAD_PIPE_FILE} &
-      echo "$(date +%FT%T%Z) [${process_name}] - Recorder is waiting for RCLONE to finish"
+      echo "$(date -u +"${ts_format}") [${process_name}] - Recorder is waiting for RCLONE to finish"
       sleep 1
     done
   fi
 }
 
 function send_exit_signal_to_uploader() {
   if [[ "${VIDEO_UPLOAD_ENABLED}" = "true" ]] && [[ -n "${UPLOAD_DESTINATION_PREFIX}" ]]; then
-    echo "$(date +%FT%T%Z) [${process_name}] - Sending a signal to force exit the uploader"
+    echo "$(date -u +"${ts_format}") [${process_name}] - Sending a signal to force exit the uploader"
     echo "exit" >>${UPLOAD_PIPE_FILE} &
     echo "exit" >${FORCE_EXIT_FILE}
   fi
 }
 
 function exit_on_max_session_reach() {
   if [[ $max_recorded_count -gt 0 ]] && [[ $recorded_count -ge $max_recorded_count ]]; then
-    echo "$(date +%FT%T%Z) [${process_name}] - Node will be drained since max sessions reached count number ($max_recorded_count)"
+    echo "$(date -u +"${ts_format}") [${process_name}] - Node will be drained since max sessions reached count number ($max_recorded_count)"
     exit
   fi
 }
@@ -139,14 +140,14 @@ function stop_ffmpeg() {
 
 function stop_recording() {
   stop_ffmpeg
-  echo "$(date +%FT%T%Z) [${process_name}] - Video recording stopped"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Video recording stopped"
   recorded_count=$((recorded_count + 1))
   if [[ "${VIDEO_UPLOAD_ENABLED}" = "true" ]] && [[ -n "${UPLOAD_DESTINATION_PREFIX}" ]]; then
     upload_destination=${UPLOAD_DESTINATION_PREFIX}/${video_file_name}
-    echo "$(date +%FT%T%Z) [${process_name}] - Add to pipe a signal Uploading video to $upload_destination"
+    echo "$(date -u +"${ts_format}") [${process_name}] - Add to pipe a signal Uploading video to $upload_destination"
     echo "$video_file ${UPLOAD_DESTINATION_PREFIX}" >>${UPLOAD_PIPE_FILE} &
   elif [[ "${VIDEO_UPLOAD_ENABLED}" = "true" ]] && [[ -z "${UPLOAD_DESTINATION_PREFIX}" ]]; then
-    echo "$(date +%FT%T%Z) [${process_name}] - Upload destination not known since UPLOAD_DESTINATION_PREFIX is not set. Continue without uploading."
+    echo "$(date -u +"${ts_format}") [${process_name}] - Upload destination not known since UPLOAD_DESTINATION_PREFIX is not set. Continue without uploading."
   fi
   recording_started="false"
 }
@@ -171,12 +172,12 @@ function log_node_response() {
 }
 
 function graceful_exit() {
-  echo "$(date +%FT%T%Z) [${process_name}] - Trapped SIGTERM/SIGINT/x so shutting down recorder"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Trapped SIGTERM/SIGINT/x so shutting down recorder"
   stop_if_recording_inprogress
   send_exit_signal_to_uploader
   wait_util_uploader_shutdown
   kill -SIGTERM "$(cat ${SE_SUPERVISORD_PID_FILE})" 2>/dev/null
-  echo "$(date +%FT%T%Z) [${process_name}] - Ready to shutdown the recorder"
+  echo "$(date -u +"${ts_format}") [${process_name}] - Ready to shutdown the recorder"
   exit 0
 }
 
@@ -204,36 +205,36 @@ else
   while curl --noproxy "*" -H "Authorization: Basic ${BASIC_AUTH}" -sk --request GET ${NODE_STATUS_ENDPOINT} >/tmp/status.json; do
     session_id=$(jq -r "${JQ_SESSION_ID_QUERY}" /tmp/status.json)
     if [[ "$session_id" != "null" && "$session_id" != "" && "$session_id" != "reserved" && "$recording_started" = "false" ]]; then
-      echo "$(date +%FT%T%Z) [${process_name}] - Session: $session_id is created"
+      echo "$(date -u +"${ts_format}") [${process_name}] - Session: $session_id is created"
       return_list=($(bash ${VIDEO_CONFIG_DIRECTORY}/video_graphQLQuery.sh "$session_id"))
       caps_se_video_record="${return_list[0]}"
       video_file_name="${return_list[1]}.mp4"
       endpoint_url="${return_list[2]}"
       /opt/bin/validate_endpoint.sh "${endpoint_url}" "true"
-      echo "$(date +%FT%T%Z) [${process_name}] - Start recording: $caps_se_video_record, video file name: $video_file_name"
+      echo "$(date -u +"${ts_format}") [${process_name}] - Start recording: $caps_se_video_record, video file name: $video_file_name"
       log_node_response
     fi
     if [[ "$session_id" != "null" && "$session_id" != "" && "$session_id" != "reserved" && "$recording_started" = "false" && "$caps_se_video_record" = "true" ]]; then
       video_file="${VIDEO_FOLDER}/$video_file_name"
-      echo "$(date +%FT%T%Z) [${process_name}] - Starting to record video"
+      echo "$(date -u +"${ts_format}") [${process_name}] - Starting to record video"
       ffmpeg -hide_banner -loglevel warning -flags low_delay -threads 2 -fflags nobuffer+genpts -strict experimental -y -f x11grab \
         -video_size ${VIDEO_SIZE} -r ${FRAME_RATE} -i ${DISPLAY} -codec:v ${CODEC} ${PRESET} -pix_fmt yuv420p "$video_file" &
       recording_started="true"
-      echo "$(date +%FT%T%Z) [${process_name}] - Video recording started"
+      echo "$(date -u +"${ts_format}") [${process_name}] - Video recording started"
       sleep ${poll_interval}
     elif [[ "$session_id" != "$prev_session_id" && "$recording_started" = "true" ]]; then
       stop_recording
       if [[ $max_recorded_count -gt 0 ]] && [[ $recorded_count -ge $max_recorded_count ]]; then
-        echo "$(date +%FT%T%Z) [${process_name}] - Node will be drained since max sessions reached count number ($max_recorded_count)"
+        echo "$(date -u +"${ts_format}") [${process_name}] - Node will be drained since max sessions reached count number ($max_recorded_count)"
         exit
       fi
     elif [[ $recording_started = "true" ]]; then
-      echo "$(date +%FT%T%Z) [${process_name}] - Video recording in progress"
+      echo "$(date -u +"${ts_format}") [${process_name}] - Video recording in progress"
       sleep ${poll_interval}
     else
       sleep ${poll_interval}
     fi
     prev_session_id=$session_id
   done
-  echo "$(date +%FT%T%Z) [${process_name}] - Node API is not responding now, exiting..."
+  echo "$(date -u +"${ts_format}") [${process_name}] - Node API is not responding now, exiting..."
 fi

Diff for: charts/selenium-grid/configs/distributor/distributorProbe.sh

@@ -3,21 +3,21 @@
 max_time=3
 retry_time=3
 probe_name="Probe.${1:-"Liveness"}"
-ts_format=${SE_LOG_TIMESTAMP_FORMAT:-"+%T.%3N"}
+ts_format=${SE_LOG_TIMESTAMP_FORMAT:-"%Y-%m-%d %H:%M:%S,%3N"}
 ROUTER_CONFIG_DIRECTORY=${ROUTER_CONFIG_DIRECTORY:-"/opt/bin"}
 
 GRID_GRAPHQL_URL=$(bash ${ROUTER_CONFIG_DIRECTORY}/routerGraphQLUrl.sh)
 BASIC_AUTH="$(echo -en "${SE_ROUTER_USERNAME}:${SE_ROUTER_PASSWORD}" | base64 -w0)"
 
 if [ -z "${GRID_GRAPHQL_URL}" ]; then
-  echo "$(date ${ts_format}) DEBUG [${probe_name}] - Could not construct GraphQL endpoint, please provide SE_HUB_HOST (or SE_ROUTER_HOST) and SE_HUB_PORT (or SE_ROUTER_PORT). Bypass the probe checks for now."
+  echo "$(date -u +"${ts_format}") DEBUG [${probe_name}] - Could not construct GraphQL endpoint, please provide SE_HUB_HOST (or SE_ROUTER_HOST) and SE_HUB_PORT (or SE_ROUTER_PORT). Bypass the probe checks for now."
   exit 0
 fi
 
 GRAPHQL_PRE_CHECK=$(curl --noproxy "*" -m ${max_time} -k -X POST -H "Authorization: Basic ${BASIC_AUTH}" -H "Content-Type: application/json" --data '{"query":"{ grid { sessionCount } }"}' -s -o /dev/null -w "%{http_code}" ${GRID_GRAPHQL_URL})
 
 if [ ${GRAPHQL_PRE_CHECK} -ne 200 ]; then
-  echo "$(date ${ts_format}) DEBUG [${probe_name}] - GraphQL endpoint ${GRID_GRAPHQL_URL} is not reachable. Status code: ${GRAPHQL_PRE_CHECK}."
+  echo "$(date -u +"${ts_format}") DEBUG [${probe_name}] - GraphQL endpoint ${GRID_GRAPHQL_URL} is not reachable. Status code: ${GRAPHQL_PRE_CHECK}."
   exit 1
 fi
 
@@ -32,10 +32,10 @@ if [ "${SE_LOG_LISTEN_GRAPHQL:-"false"}" = "true" ]; then
 fi
 
 if [ ${SESSION_QUEUE_SIZE} -gt 0 ] && [ ${SESSION_COUNT} -eq 0 ]; then
-  echo "$(date ${ts_format}) DEBUG [${probe_name}] - Session Queue Size: ${SESSION_QUEUE_SIZE}, Session Count: ${SESSION_COUNT}, Max Session: ${MAX_SESSION}"
-  echo "$(date ${ts_format}) DEBUG [${probe_name}] - It seems the Distributor is delayed in processing a new session in the queue. Probe checks failed."
+  echo "$(date -u +"${ts_format}") DEBUG [${probe_name}] - Session Queue Size: ${SESSION_QUEUE_SIZE}, Session Count: ${SESSION_COUNT}, Max Session: ${MAX_SESSION}"
+  echo "$(date -u +"${ts_format}") DEBUG [${probe_name}] - It seems the Distributor is delayed in processing a new session in the queue. Probe checks failed."
   exit 1
 else
-  echo "$(date ${ts_format}) DEBUG [${probe_name}] - Distributor is healthy."
+  echo "$(date -u +"${ts_format}") DEBUG [${probe_name}] - Distributor is healthy."
   exit 0
 fi