[CERTTF-458] feat: use agent config in reimplemented log truncation (#…

…458)

* feat: use agent config in reimplemented log truncation

Log files were truncated to their last 1MB of data. Now
the size of the output log can be specified through the
`output_bytes` agent configuration field.

* chore: increase default size for truncated log from 1 to 10MB
* chore: remove unused function
* docs: add paragraph in the tutorial section that discusses results

agent/testflinger_agent/job.py

@@ -12,7 +12,6 @@
 # You should have received a copy of the GNU General Public License
 # along with this program.  If not, see <http://www.gnu.org/licenses/>
 
-import fcntl
 import json
 import logging
 import os
@@ -151,18 +150,19 @@ def _update_phase_results(
         :param serial_log:
             Path to the serial log file
         """
+        # the default for `output_bytes` when it is not explicitly set
+        # in the agent config is specified in the config schema
+        max_log_size = self.client.config["output_bytes"]
         with open(results_file, "r+") as results:
             outcome_data = json.load(results)
             if os.path.exists(output_log):
-                with open(output_log, "r+", encoding="utf-8") as logfile:
-                    self._set_truncate(logfile)
-                    outcome_data[phase + "_output"] = logfile.read()
+                outcome_data[phase + "_output"] = read_truncated(
+                    output_log, size=max_log_size
+                )
             if os.path.exists(serial_log):
-                with open(
-                    serial_log, "r+", encoding="utf-8", errors="ignore"
-                ) as logfile:
-                    self._set_truncate(logfile)
-                    outcome_data[phase + "_serial"] = logfile.read()
+                outcome_data[phase + "_serial"] = read_truncated(
+                    serial_log, max_log_size
+                )
             outcome_data[phase + "_status"] = exitcode
             results.seek(0)
             json.dump(outcome_data, results)
@@ -215,23 +215,6 @@ def wait_for_completion(self):
                 logger.warning("Failed to get allocated job status, retrying")
             time.sleep(60)
 
-    def _set_truncate(self, f, size=1024 * 1024):
-        """Set up an open file so that we don't read more than a specified
-           size. We want to read from the end of the file rather than the
-           beginning. Write a warning at the end of the file if it was too big.
-
-        :param f:
-            The file object, which should be opened for read/write
-        :param size:
-            Maximum number of bytes we want to allow from reading the file
-        """
-        end = f.seek(0, 2)
-        if end > size:
-            f.write("\nWARNING: File has been truncated due to length!")
-            f.seek(end - size, 0)
-        else:
-            f.seek(0, 0)
-
     def get_global_timeout(self):
         """Get the global timeout for the test run in seconds"""
         # Default timeout is 4 hours
@@ -265,14 +248,24 @@ def banner(self, line):
         yield "*" * (len(line) + 4)
 
 
-def set_nonblock(fd):
-    """Set the specified fd to nonblocking output
+def read_truncated(filename: str, size: int) -> str:
+    """Return a string corresponding to the last bytes of a text file.
 
-    :param fd:
-        File descriptor that should be set to nonblocking mode
-    """
+    Include a warning message at the end of the returned value if the file
+    has been truncated.
 
-    # XXX: This is only used in one place right now, may want to consider
-    # moving it if it gets wider use in the future
-    fl = fcntl.fcntl(fd, fcntl.F_GETFL)
-    fcntl.fcntl(fd, fcntl.F_SETFL, fl | os.O_NONBLOCK)
+    :param filename:
+        The name of the text file
+    :param size:
+        Maximum number of bytes to be read from the end of the file
+        (overrides default `output_bytes` value in the agent config)
+    """
+    with open(filename, "r", encoding="utf-8", errors="ignore") as file:
+        end = file.seek(0, 2)
+        if end > size:
+            file.seek(end - size, 0)
+            return file.read() + (
+                f"\nWARNING: File truncated to its last {size} bytes!"
+            )
+        file.seek(0, 0)
+        return file.read()

agent/testflinger_agent/schema.py

@@ -45,6 +45,9 @@
     voluptuous.Optional("output_timeout"): int,
     voluptuous.Optional("advertised_queues"): dict,
     voluptuous.Optional("advertised_images"): dict,
+    # only the last `output_bytes` of the log will be included
+    # in the results submitted to the server (default: 10MB)
+    voluptuous.Optional("output_bytes", default=10 * 1024 * 1024): int,
 }
 
 

agent/testflinger_agent/tests/test_agent.py

@@ -16,26 +16,28 @@
 from testflinger_agent.errors import TFServerError
 from testflinger_agent.client import TestflingerClient as _TestflingerClient
 from testflinger_agent.agent import TestflingerAgent as _TestflingerAgent
+from testflinger_agent.schema import validate
 from testflinger_common.enums import TestPhase, TestEvent
 
 
 class TestClient:
     @pytest.fixture
     def agent(self, requests_mock):
         self.tmpdir = tempfile.mkdtemp()
-        self.config = {
-            "agent_id": "test01",
-            "identifier": "12345-123456",
-            "polling_interval": "2",
-            "server_address": "127.0.0.1:8000",
-            "job_queues": ["test"],
-            "location": "nowhere",
-            "provision_type": "noprovision",
-            "execution_basedir": self.tmpdir,
-            "logging_basedir": self.tmpdir,
-            "results_basedir": os.path.join(self.tmpdir, "results"),
-            "test_string": "ThisIsATest",
-        }
+        self.config = validate(
+            {
+                "agent_id": "test01",
+                "identifier": "12345-123456",
+                "polling_interval": 2,
+                "server_address": "127.0.0.1:8000",
+                "job_queues": ["test"],
+                "location": "nowhere",
+                "provision_type": "noprovision",
+                "execution_basedir": self.tmpdir,
+                "logging_basedir": self.tmpdir,
+                "results_basedir": os.path.join(self.tmpdir, "results"),
+            }
+        )
         testflinger_agent.configure_logging(self.config)
         client = _TestflingerClient(self.config)
         requests_mock.get(rmock.ANY)
@@ -268,9 +270,7 @@ def test_attachments_insecure_out_of_hierarchy(self, agent, tmp_path):
             assert not attachment.exists()
 
     def test_config_vars_in_env(self, agent, requests_mock):
-        self.config["test_command"] = (
-            "bash -c 'echo test_string is $test_string'"
-        )
+        self.config["test_command"] = "bash -c 'echo agent_id is $agent_id'"
         mock_job_data = {
             "job_id": str(uuid.uuid1()),
             "job_queue": "test",
@@ -285,7 +285,7 @@ def test_config_vars_in_env(self, agent, requests_mock):
         testlog = open(
             os.path.join(self.tmpdir, mock_job_data.get("job_id"), "test.log")
         ).read()
-        assert "ThisIsATest" in testlog
+        assert self.config["agent_id"] in testlog
 
     def test_phase_failed(self, agent, requests_mock):
         # Make sure we stop running after a failed phase

agent/testflinger_agent/tests/test_job.py

@@ -8,9 +8,13 @@
 
 import testflinger_agent
 from testflinger_agent.client import TestflingerClient as _TestflingerClient
-from testflinger_agent.job import TestflingerJob as _TestflingerJob
+from testflinger_agent.job import (
+    TestflingerJob as _TestflingerJob,
+    read_truncated,
+)
 from testflinger_agent.runner import CommandRunner
 from testflinger_agent.handlers import LogUpdateHandler
+from testflinger_agent.schema import validate
 from testflinger_agent.stop_condition_checkers import (
     GlobalTimeoutChecker,
     OutputTimeoutChecker,
@@ -22,15 +26,17 @@ class TestJob:
     @pytest.fixture
     def client(self):
         self.tmpdir = tempfile.mkdtemp()
-        self.config = {
-            "agent_id": "test01",
-            "polling_interval": "2",
-            "server_address": "127.0.0.1:8000",
-            "job_queues": ["test"],
-            "execution_basedir": self.tmpdir,
-            "logging_basedir": self.tmpdir,
-            "results_basedir": os.path.join(self.tmpdir, "results"),
-        }
+        self.config = validate(
+            {
+                "agent_id": "test01",
+                "polling_interval": 2,
+                "server_address": "127.0.0.1:8000",
+                "job_queues": ["test"],
+                "execution_basedir": self.tmpdir,
+                "logging_basedir": self.tmpdir,
+                "results_basedir": os.path.join(self.tmpdir, "results"),
+            }
+        )
         testflinger_agent.configure_logging(self.config)
         yield _TestflingerClient(self.config)
         shutil.rmtree(self.tmpdir)
@@ -173,24 +179,26 @@ def test_run_test_phase_with_run_exception(
         assert exit_event == "setup_fail"
         assert exit_reason == "failed"
 
-    def test_set_truncate(self, client):
-        """Test the _set_truncate method of TestflingerJob"""
-        job = _TestflingerJob({}, client)
-        with tempfile.TemporaryFile(mode="r+") as f:
-            # First check that a small file doesn't get truncated
-            f.write("x" * 100)
-            job._set_truncate(f, size=100)
-            contents = f.read()
-            assert len(contents) == 100
-            assert "WARNING" not in contents
-
-            # Now check that a larger file does get truncated
-            f.write("x" * 100)
-            job._set_truncate(f, size=100)
-            contents = f.read()
-            # It won't be exactly 100 bytes, because a warning is added
-            assert len(contents) < 150
-            assert "WARNING" in contents
+    def test_read_truncated(self, client, tmp_path):
+        """Test the read_truncated function"""
+
+        # First check that a small file doesn't get truncated
+        short_file = tmp_path / "short"
+        short_file.write_text("x" * 100)
+        contents = read_truncated(short_file, size=100)
+        assert len(contents) == 100
+        assert "WARNING" not in contents
+
+        # Now check that a larger file does get truncated
+        long_file = tmp_path / "long"
+        long_file.write_text("x" * 200)
+        contents = read_truncated(long_file, size=100)
+        # It won't be exactly 100 bytes, because a warning is added
+        assert len(contents) < 150
+        assert "WARNING" in contents
+
+        # Check that a default value exists for `output_bytes`
+        assert "output_bytes" in client.config
 
     @pytest.mark.timeout(1)
     def test_wait_for_completion(self, client):

docs/tutorial/index.rst

@@ -212,6 +212,11 @@ In some cases, you might want to check the device output to know how each job ph
 
 Besides the output from the provisioning and testing commands, the returned data also includes an exit code of each phase and output from the Testflinger agent. This information is very useful for troubleshooting testing issues.
 
+Note: Testflinger agents truncate the `*_output` fields when submitting job results to the server,
+keeping only the last section of the output log if it exceeds a certain threshold. This threshold
+can be set through the `output_bytes` field of the agent configuration file and its default value
+is 10 MB.
+
 ---------
 
 Congratulations! You've successfully set up the Testflinger CLI, created and submitted your first test job, and checked its status. You can now create more complex jobs and manage your test jobs efficiently using the command line tool. Happy testing!