diff --git a/.github/workflows/main.yml b/.github/workflows/main.yml index a1c265f3fb..8144f8b267 100644 --- a/.github/workflows/main.yml +++ b/.github/workflows/main.yml @@ -177,3 +177,33 @@ jobs: name: yellow-ai-vs-ai-proto-logs path: | /tmp/tbots/yellow/proto_* + + common-commands: + strategy: + # TODO: set fail-fast to true in production. + fail-fast: false + matrix: + commands: + - ../scripts/safe_run.sh bazel run --run_under="xvfb-run" //software/thunderscope:thunderscope_main -- --run_blue --run_diagnostics --interface lo --keyboard_estop --ci_mode + - ../scripts/safe_run.sh bazel run --run_under="xvfb-run" //software/ai/hl/stp/tactic/goalie:goalie_tactic_test -- --enable_thunderscope + - ../scripts/safe_run.sh bazel run --run_under="xvfb-run" //software/thunderscope:thunderscope_main -- --enable_autoref --ci_mode && ../scripts/safe_run.sh bazel run --run_under="xvfb-run" //software/thunderscope:thunderscope_main -- blue_log="$(find /tmp/tbots/blue -maxdepth 1 -type d -name 'proto_*' -printf '/tmp/tbots/blue/%f\n' 2>/dev/null | head -n1)" + + name: Sanity Check on Common Commands + runs-on: ubuntu-20.04 + steps: + - uses: actions/checkout@v4 + + - name: Environment Setup + run: | + "${GITHUB_WORKSPACE}"/environment_setup/setup_software.sh + + - name: Build Thunderscope + run: | + cd src + bazel build //software/thunderscope:thunderscope_main + + - name: Check Common Commands + run: | + cd src + ${{ matrix.commands }} + diff --git a/scripts/ci_runner.py b/scripts/ci_runner.py new file mode 100755 index 0000000000..0ca69aab08 --- /dev/null +++ b/scripts/ci_runner.py @@ -0,0 +1,104 @@ +#!/opt/tbotspython/bin/python3 + +""" +ci_runner.py runs a given command for a fix amount of time and +return 0 if there is no Python runtime exception found in the output +otherwise return 1 + +Because bazel outputs in both stderr and stdout regardless the content, +(https://github.com/bazelbuild/bazel/issues/10496) +only checking stderr is insufficient. Therefore, we are doing a pattern +matching in both stderr and stdout, which tells us if there is any runtime exception. +""" + +from typing import List +import subprocess +import sys +import time +import select + +# Default timeout is 120 seconds +TIME_LIMIT_S = 30 +# Key pattern of python exception +PYTHON_ERROR_PATTERN="Traceback (most recent call last):" +# Delimiter which splits the target command output and this program logs +SECTION_DELIM = "=" * 50 + + +def print_command(command: List[str]) -> None: + """ + Format and print commands + + :param command: command to be printed in a list of string + """ + print(" ".join(command)) + +def read_available_output(proc: subprocess.Popen) -> str: + """ + Safely read available output from process without blocking + + :param proc: Running process + :return: string output of stdout + """ + output = "" + if proc.stdout: + rlist, _, _ = select.select([proc.stdout], [], [], 0) + if rlist: + output = proc.stdout.readline() + return output + +def test_command(command: List[str]) -> int: + """ + Run a given command and return status code + + :param command: command to run and test + :return: 0 if the given command was run successfully and did not + throw any error in the given time limit. + 1 if the give command failed to run or threw errors to console. + """ + start_time = time.time() + + # Run the command as a subprocess + proc = subprocess.Popen(command, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True, bufsize=1) + + # Keep polling and checking ONLY if + # - did not reach time limit yet AND + # - the process is still running + while time.time() - start_time <= TIME_LIMIT_S and proc.poll() is None: + stdout_data = read_available_output(proc) + if PYTHON_ERROR_PATTERN in stdout_data: + print(SECTION_DELIM) + print("Oops! Error found while running the following command :(") + print_command(command) + + proc.kill() + return 1 + if stdout_data: + print(stdout_data, end="") + + # If the process is still running, send SIGKILL signal + if proc.poll() is None: + # TODO: remove the following print statement + print("killing the proc") + proc.kill() + + remaining_output = proc.communicate()[0] + print(remaining_output) + print(SECTION_DELIM) + + print("Nice! Test passed! :)") + return 0 + + +if __name__ == "__main__": + if len(sys.argv) < 2: + print("Usage: command_runner.py [args...]", file=sys.stderr) + sys.exit(1) + + command = sys.argv[1:] + print(f"Testing the following command:") + print_command(command) + + print(SECTION_DELIM) + sys.exit(test_command(sys.argv[1:])) + diff --git a/scripts/safe_run.sh b/scripts/safe_run.sh new file mode 100755 index 0000000000..3be54c7521 --- /dev/null +++ b/scripts/safe_run.sh @@ -0,0 +1,52 @@ +#!/bin/bash + +# Timeout in seconds +# When the time is up and no error was shown, this test will pass +TIME_LIMIT=120 # 2 minutes + +# Match Python traceback +ERROR_PATTERN="Traceback (most recent call last):" + +# Temporary log file +LOG_FILE=$(mktemp) + +# Run the command and record the log +"$@" &> "$LOG_FILE" & +CMD_PID=$! + +echo "Process Running in Wrapper with Timeout $TIME_LIMIT ..." + +# Time the process +SECONDS=0 +while kill -0 $CMD_PID 2>/dev/null; do + # Check if time is up + if [ $SECONDS -ge $TIME_LIMIT ]; then + echo "Time limit reached, stopping process: $CMD_PID" + kill -SIGINT $CMD_PID + wait $CMD_PID + exit 0 # Upon time out and no error, returns 0 status code + fi + + # Check if the log contains Traceback + if grep -q "$ERROR_PATTERN" "$LOG_FILE"; then + echo "[Error detected] Potential error found in command output!" + kill -SIGINT $CMD_PID + wait $CMD_PID + exit 1 + fi + + sleep 1 # Run this loop once per second +done + +cat $LOG_FILE +# Get the exit code of the process +wait $CMD_PID +EXIT_CODE=$? + +# Clean up log file +rm -f "$LOG_FILE" + +# Exit with the command status code +exit $EXIT_CODE + + diff --git a/src/software/logger/proto_logger.cpp b/src/software/logger/proto_logger.cpp index 2362267139..58affd4444 100644 --- a/src/software/logger/proto_logger.cpp +++ b/src/software/logger/proto_logger.cpp @@ -37,6 +37,22 @@ ProtoLogger::ProtoLogger(const std::string& log_path, log_thread_ = std::thread(&ProtoLogger::logProtobufs, this); } +ProtoLogger::ProtoLogger(const std::string& log_path, + std::function time_provider, + const bool friendly_colour_yellow, + const std::string& log_name) + : log_path_(log_path), + time_provider_(time_provider), + friendly_colour_yellow_(friendly_colour_yellow), + stop_logging_(false), + buffer_(PROTOBUF_BUFFER_SIZE, true) +{ + start_time_ = time_provider_(); + log_folder_ = log_path_ + "/" + log_name + "/"; + std::experimental::filesystem::create_directories(log_folder_); + log_thread_ = std::thread(&ProtoLogger::logProtobufs, this); +} + ProtoLogger::~ProtoLogger() { flushAndStopLogging(); diff --git a/src/software/logger/proto_logger.h b/src/software/logger/proto_logger.h index ad920463ba..6404e6cb9a 100644 --- a/src/software/logger/proto_logger.h +++ b/src/software/logger/proto_logger.h @@ -54,6 +54,18 @@ class ProtoLogger std::function time_provider, bool friendly_colour_yellow); + /** + * Constructor + * @param log_path The path to the directory where the logs will be saved + * @param time_provider A function that returns the current time in seconds + * @param friendly_colour_yellow Whether the friendly team is yellow or not + * @param log_name The name of the log directory + */ + explicit ProtoLogger(const std::string& log_path, + std::function time_provider, + const bool friendly_colour_yellow, + const std::string& log_name); + ProtoLogger() = delete; /** diff --git a/src/software/thunderscope/binary_context_managers/full_system.py b/src/software/thunderscope/binary_context_managers/full_system.py index fcdd8d806f..0727d7f609 100644 --- a/src/software/thunderscope/binary_context_managers/full_system.py +++ b/src/software/thunderscope/binary_context_managers/full_system.py @@ -24,6 +24,7 @@ def __init__( should_restart_on_crash: bool = True, run_sudo: bool = False, running_in_realtime: bool = True, + log_name: str = None, ) -> None: """Run FullSystem @@ -33,6 +34,7 @@ def __init__( :param should_restart_on_crash: whether or not to restart the program after it has been crashed :param run_sudo: true if we should run full system under sudo :param running_in_realtime: True if we are running fullsystem in realtime, else False + :param log_name: Name of the proto log folder """ self.full_system_runtime_dir = full_system_runtime_dir self.debug_full_system = debug_full_system @@ -41,6 +43,7 @@ def __init__( self.should_restart_on_crash = should_restart_on_crash self.should_run_under_sudo = run_sudo self.running_in_realtime = running_in_realtime + self.log_name = log_name self.thread = threading.Thread(target=self.__restart__, daemon=True) @@ -60,10 +63,11 @@ def __enter__(self) -> FullSystem: except: pass - self.full_system = "software/unix_full_system --runtime_dir={} {} {}".format( + self.full_system = "software/unix_full_system --runtime_dir={} {} {} {}".format( self.full_system_runtime_dir, "--friendly_colour_yellow" if self.friendly_colour_yellow else "", "--ci" if not self.running_in_realtime else "", + f"--log_name={self.log_name}" if self.log_name else "", ) if self.should_run_under_sudo: diff --git a/src/software/thunderscope/thunderscope_main.py b/src/software/thunderscope/thunderscope_main.py index 951780cbb7..adb99a1cac 100644 --- a/src/software/thunderscope/thunderscope_main.py +++ b/src/software/thunderscope/thunderscope_main.py @@ -75,6 +75,14 @@ default="/tmp/tbots/yellow", ) + # Proto log folder name + parser.add_argument( + "--log_name", + type=str, + help="proto log folder name to save to", + default=None, + ) + # Debugging parser.add_argument( "--debug_blue_full_system", @@ -374,6 +382,7 @@ friendly_colour_yellow=friendly_colour_yellow, should_restart_on_crash=True, run_sudo=args.sudo, + log_name=args.log_name ) as full_system: full_system.setup_proto_unix_io(current_proto_unix_io) @@ -447,6 +456,7 @@ def __ticker(tick_rate_ms: int) -> None: should_restart_on_crash=False, run_sudo=args.sudo, running_in_realtime=(not args.ci_mode), + log_name=args.log_name, ) as blue_fs, FullSystem( full_system_runtime_dir=args.yellow_full_system_runtime_dir, debug_full_system=args.debug_yellow_full_system, @@ -454,6 +464,7 @@ def __ticker(tick_rate_ms: int) -> None: should_restart_on_crash=False, run_sudo=args.sudo, running_in_realtime=(not args.ci_mode), + log_name=args.log_name, ) as yellow_fs, Gamecontroller( suppress_logs=(not args.verbose) ) as gamecontroller, ( diff --git a/src/software/unix_full_system_main.cpp b/src/software/unix_full_system_main.cpp index 6c59bde203..20cf48ed30 100644 --- a/src/software/unix_full_system_main.cpp +++ b/src/software/unix_full_system_main.cpp @@ -52,6 +52,7 @@ int main(int argc, char** argv) { bool help = false; std::string runtime_dir = "/tmp/tbots"; + std::string log_name = std::string(); bool friendly_colour_yellow = false; bool ci = false; }; @@ -64,6 +65,9 @@ int main(int argc, char** argv) desc.add_options()("runtime_dir", boost::program_options::value(&args.runtime_dir), "The directory to output logs and setup unix sockets."); + desc.add_options()("log_name", + boost::program_options::value(&args.log_name), + "The directory name to contain proto logs."); desc.add_options()("friendly_colour_yellow", boost::program_options::bool_switch(&args.friendly_colour_yellow), "If false, friendly colour is blue"); @@ -107,8 +111,18 @@ int main(int argc, char** argv) // timestamp once the backend is set up time_provider = []() { return 0; }; } - proto_logger = std::make_shared(args.runtime_dir, time_provider, + + if (args.log_name.empty()) + { + proto_logger = std::make_shared(args.runtime_dir, time_provider, args.friendly_colour_yellow); + } + else + { + proto_logger = std::make_shared(args.runtime_dir, time_provider, + args.friendly_colour_yellow, args.log_name); + } + LoggerSingleton::initializeLogger(args.runtime_dir, proto_logger); TbotsProto::ThunderbotsConfig tbots_proto;