[generate dump] Move the Core/Log collection to the End of process Execution and removed default timeout (sonic-net#2209)

Recently an issue is seen during the test_max_limit[core] sonic-mgmt test (Test for auto-techsupport).

This was a diff taken from two techsupport process runs and in the first case the core file to save was too large (almost 1G) and thus took upto 10 sec and all the commands that followed which append to the tar file have shown increased execution time.
Finally, after 30 mins the execution timed out.

Besides, it's better to collect the logs in the end, since we could collect more info and also core files are mostly static and it shouldn't matter much even if we collect them late.

Thus moved the core/log collection to the end.

But there is a catch regarding the above change, For eg: system is in a unstable state and most of the individual commands start to timeout, the techsupport dump eventually times out at 30m (because of the global timeout), then the dump is pretty useless, since it might not have any useful information at all
Thus, i've removed the default global timeout, Clients can/should knowingly provide a value using -g option if the execution time has to be capped.

A global timeout of 60 mins is used for Global timeout for Auto-techsupport invocation.

Fix related to since argument was overwritten by the latest commit related to auto-techsupport on master and thus the reason for issues like this Auto-Techsupport collect logs beyond since value sonic-buildimage#11208, Made changes to fix the issue in here

Signed-off-by: Vivek Reddy Karri <[email protected]>

Author: vivekrnv

scripts/generate_dump

@@ -1287,11 +1287,6 @@ main() {
     end_t=$(date +%s%3N)
     echo "[ Capture Proc State ] : $(($end_t-$start_t)) msec" >> $TECHSUPPORT_TIME_INFO
 
-    # Save logs and cores early
-    save_log_files
-    save_crash_files
-    save_warmboot_files
-
     # Save all the processes within each docker
     save_cmd "show services" services.summary
 
@@ -1426,6 +1421,10 @@ main() {
     end_t=$(date +%s%3N)
     echo "[ TAR /etc Files ] : $(($end_t-$start_t)) msec" >> $TECHSUPPORT_TIME_INFO
 
+    save_log_files
+    save_crash_files
+    save_warmboot_files
+
     finalize
 }
 

show/main.py

@@ -1266,7 +1266,7 @@ def users(verbose):
 
 @cli.command()
 @click.option('--since', required=False, help="Collect logs and core files since given date")
-@click.option('-g', '--global-timeout', default=30, type=int, help="Global timeout in minutes. Default 30 mins")
+@click.option('-g', '--global-timeout', required=False, type=int, help="Global timeout in minutes. WARN: Dump might be incomplete if enforced")
 @click.option('-c', '--cmd-timeout', default=5, type=int, help="Individual command timeout in minutes. Default 5 mins")
 @click.option('--verbose', is_flag=True, help="Enable verbose output")
 @click.option('--allow-process-stop', is_flag=True, help="Dump additional data which may require system interruption")
@@ -1275,7 +1275,10 @@ def users(verbose):
 @click.option('--redirect-stderr', '-r', is_flag=True, help="Redirect an intermediate errors to STDERR")
 def techsupport(since, global_timeout, cmd_timeout, verbose, allow_process_stop, silent, debug_dump, redirect_stderr):
     """Gather information for troubleshooting"""
-    cmd = "sudo timeout --kill-after={}s -s SIGTERM --foreground {}m".format(COMMAND_TIMEOUT, global_timeout)
+    cmd = "sudo"
+
+    if global_timeout:
+        cmd += " timeout --kill-after={}s -s SIGTERM --foreground {}m".format(COMMAND_TIMEOUT, global_timeout)
 
     if allow_process_stop:
         cmd += " -a"

tests/coredump_gen_handler_test.py

@@ -21,6 +21,8 @@
 /tmp/saisdkdump
 """
 
+TS_DEFAULT_CMD = "show techsupport --silent --global-timeout 60 --since 2 days ago"
+
 def signal_handler(signum, frame):
     raise Exception("Timed out!")
 
@@ -270,7 +272,7 @@ def test_since_argument(self):
             def mock_cmd(cmd, env):
                 ts_dump = "/var/dump/sonic_dump_random3.tar.gz"
                 cmd_str = " ".join(cmd)
-                if "--since '4 days ago'" in cmd_str:
+                if "--since 4 days ago" in cmd_str:
                     patcher.fs.create_file(ts_dump)
                     return 0, AUTO_TS_STDOUT + ts_dump, ""
                 elif "date --date=4 days ago" in cmd_str:
@@ -336,7 +338,7 @@ def test_invalid_since_argument(self):
             def mock_cmd(cmd, env):
                 ts_dump = "/var/dump/sonic_dump_random3.tar.gz"
                 cmd_str = " ".join(cmd)
-                if "--since '2 days ago'" in cmd_str:
+                if "--since 2 days ago" in cmd_str:
                     patcher.fs.create_file(ts_dump)
                     print(AUTO_TS_STDOUT + ts_dump)
                     return 0, AUTO_TS_STDOUT + ts_dump, ""
@@ -429,3 +431,21 @@ def mock_cmd(cmd, env):
             finally:
                 signal.alarm(0)
 
+    def test_auto_ts_options(self):
+        """
+        Scenario: Check if the techsupport is called as expected
+        """
+        db_wrap = Db()
+        redis_mock = db_wrap.db
+        set_auto_ts_cfg(redis_mock, state="enabled", since_cfg="2 days ago")
+        set_feature_table_cfg(redis_mock, state="enabled")
+        with Patcher() as patcher:
+            def mock_cmd(cmd, env):
+                cmd_str = " ".join(cmd)
+                if "show techsupport" in cmd_str and cmd_str != TS_DEFAULT_CMD:
+                    assert False, "Expected TS_CMD: {}, Recieved: {}".format(TS_DEFAULT_CMD, cmd_str)
+                return 0, AUTO_TS_STDOUT, ""
+            ts_helper.subprocess_exec = mock_cmd
+            patcher.fs.create_file("/var/core/orchagent.12345.123.core.gz")
+            cls = cdump_mod.CriticalProcCoreDumpHandle("orchagent.12345.123.core.gz", "swss", redis_mock)
+            cls.handle_core_dump_creation_event()

tests/techsupport_test.py

@@ -3,18 +3,18 @@
 from unittest.mock import patch, Mock
 from click.testing import CliRunner
 
-EXPECTED_BASE_COMMAND = 'sudo timeout --kill-after=300s -s SIGTERM --foreground '
+EXPECTED_BASE_COMMAND = 'sudo '
 
 @patch("show.main.run_command")
 @pytest.mark.parametrize(
         "cli_arguments,expected",
         [
-            ([], '30m generate_dump -v -t 5'),
-            (['--since', '2 days ago'], "30m generate_dump -v -s '2 days ago' -t 5"),
-            (['-g', '50'], '50m generate_dump -v -t 5'),
-            (['--allow-process-stop'], '30m -a generate_dump -v -t 5'),
-            (['--silent'], '30m generate_dump -t 5'),
-            (['--debug-dump', '--redirect-stderr'], '30m generate_dump -v -d -t 5 -r'),
+            ([], 'generate_dump -v -t 5'),
+            (['--since', '2 days ago'], "generate_dump -v -s '2 days ago' -t 5"),
+            (['-g', '50'], 'timeout --kill-after=300s -s SIGTERM --foreground 50m generate_dump -v -t 5'),
+            (['--allow-process-stop'], '-a generate_dump -v -t 5'),
+            (['--silent'], 'generate_dump -t 5'),
+            (['--debug-dump', '--redirect-stderr'], 'generate_dump -v -d -t 5 -r'),
         ]
 )
 def test_techsupport(run_command, cli_arguments, expected):

utilities_common/auto_techsupport_helper.py

@@ -68,6 +68,7 @@
 
 TIME_BUF = 20
 SINCE_DEFAULT = "2 days ago"
+TS_GLOBAL_TIMEOUT = "60"
 
 # Explicity Pass this to the subprocess invoking techsupport
 ENV_VAR = os.environ
@@ -229,8 +230,7 @@ def parse_ts_dump_name(ts_stdout):
 def invoke_ts_cmd(db, num_retry=0):
     """Invoke techsupport generation command"""
     since_cfg = get_since_arg(db)
-    since_cfg = "'" + since_cfg + "'"
-    cmd_opts = ["show", "techsupport", "--silent", "--since", since_cfg]
+    cmd_opts = ["show", "techsupport", "--silent", "--global-timeout", TS_GLOBAL_TIMEOUT, "--since", since_cfg]
     cmd  = " ".join(cmd_opts)
     rc, stdout, stderr = subprocess_exec(cmd_opts, env=ENV_VAR)
     new_dump = ""