Repository: Azure/WALinuxAgent
Pull request #2148 (2021-01-25 21:54:19)

Command execution log fix
<!-- DO NOT DELETE THIS TEMPLATE -->

## Description

Added some custom log management to the `CommandExecution.log` file after the `logrotate` config was removed in a prior PR.

Also, has a small fix for a unit test that sometimes failed on python2 envs.

<!--
Please add an informative description that covers that changes made by the pull request. 
This checklist is used to make sure that common issues in a pull request are addressed.
This will expedite the process of getting your pull request merged and avoid extra work on your part to fix issues discovered during the review process.
-->

---

### PR information
- [ ] The title of the PR is clear and informative.
- [ ] There are a small number of commits, each of which has an informative message. This means that previously merged commits do not appear in the history of the PR. For information on cleaning up the commits in your pull request, [see this page](https://github.com/Azure/azure-powershell/blob/master/documentation/development-docs/cleaning-up-commits.md).
- [ ] Except for special cases involving multiple contributors, the PR is started from a fork of the main repository, not a branch.
- [ ] If applicable, the PR references the bug/issue that it fixes in the description.
- [ ] New Unit tests were added for the changes made and Travis.CI is passing.

### Quality of Code and Contribution Guidelines
- [ ] I have read the [contribution guidelines](https://github.com/Azure/WALinuxAgent/blob/master/.github/CONTRIBUTING.md).

codecov[bot]: # [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/2148?src=pr&el=h1) Report
> Merging [#2148](https://codecov.io/gh/Azure/WALinuxAgent/pull/2148?src=pr&el=desc) (81f1a72) into [develop](https://codecov.io/gh/Azure/WALinuxAgent/commit/f0f326ba9748039418694da3f1274fe3b34f9fb4?el=desc) (f0f326b) will **increase** coverage by `0.02%`.
> The diff coverage is `100.00%`.

[![Impacted file tree graph](https://codecov.io/gh/Azure/WALinuxAgent/pull/2148/graphs/tree.svg?width=650&height=150&src=pr&token=ae90E2KYCw)](https://codecov.io/gh/Azure/WALinuxAgent/pull/2148?src=pr&el=tree)

```diff
@@             Coverage Diff             @@
##           develop    #2148      +/-   ##
===========================================
+ Coverage    70.64%   70.66%   +0.02%     
===========================================
  Files           95       95              
  Lines        12939    12948       +9     
  Branches      1842     1843       +1     
===========================================
+ Hits          9141     9150       +9     
  Misses        3390     3390              
  Partials       408      408              
```


| [Impacted Files](https://codecov.io/gh/Azure/WALinuxAgent/pull/2148?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [azurelinuxagent/common/version.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2148/diff?src=pr&el=tree#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi92ZXJzaW9uLnB5) | `72.28% <100.00%> (ø)` | |
| [azurelinuxagent/ga/exthandlers.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2148/diff?src=pr&el=tree#diff-YXp1cmVsaW51eGFnZW50L2dhL2V4dGhhbmRsZXJzLnB5) | `87.50% <100.00%> (+0.10%)` | :arrow_up: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/2148?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/2148?src=pr&el=footer). Last update [f0f326b...81f1a72](https://codecov.io/gh/Azure/WALinuxAgent/pull/2148?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).


Patch:
diff --git a/azurelinuxagent/common/future.py b/azurelinuxagent/common/future.py
index a7e7a6c0..73d19f27 100644
--- a/azurelinuxagent/common/future.py
+++ b/azurelinuxagent/common/future.py
@@ -128,6 +128,20 @@ def get_openwrt_platform():
                     result[0] = "openwrt"
     return result
 
+def is_file_not_found_error(exception):
+    
+    # pylint for python2 complains, but FileNotFoundError is
+    # defined for python3.
+    
+    # pylint: disable=undefined-variable
+
+    if sys.version_info[0] == 2:
+        # Python 2 uses IOError(errno=2)
+        return isinstance(exception, IOError) and exception.errno == 2
+    elif sys.version_info[0] == 3:
+        return isinstance(exception, FileNotFoundError)
+    
+    return isinstance(exception, FileNotFoundError)
 
 def array_to_bytes(buff):
     # Python 3.9 removed the tostring() method on arrays, the new alias is tobytes()
diff --git a/azurelinuxagent/common/version.py b/azurelinuxagent/common/version.py
index b350985e..fc71a89d 100644
--- a/azurelinuxagent/common/version.py
+++ b/azurelinuxagent/common/version.py
@@ -148,8 +148,8 @@ def get_distro():
     osinfo[0] = osinfo[0].strip('"').strip(' ').lower()
     return osinfo
 
-COMMAND_ABSENT = "Absent"
-COMMAND_FAILED = "Failed"
+COMMAND_ABSENT = ustr("Absent")
+COMMAND_FAILED = ustr("Failed")
 
 
 def get_lis_version():
diff --git a/azurelinuxagent/ga/exthandlers.py b/azurelinuxagent/ga/exthandlers.py
index ce76adcf..0d23d8ea 100644
--- a/azurelinuxagent/ga/exthandlers.py
+++ b/azurelinuxagent/ga/exthandlers.py
@@ -43,7 +43,7 @@ from azurelinuxagent.common.event import add_event, elapsed_milliseconds, report
     add_periodic, EVENTS_DIRECTORY
 from azurelinuxagent.common.exception import ExtensionDownloadError, ExtensionError, ExtensionErrorCodes, \
     ExtensionOperationError, ExtensionUpdateError, ProtocolError, ProtocolNotFoundError, ExtensionConfigError
-from azurelinuxagent.common.future import ustr
+from azurelinuxagent.common.future import ustr, is_file_not_found_error
 from azurelinuxagent.common.protocol.restapi import ExtensionStatus, ExtensionSubStatus, ExtHandler, ExtHandlerStatus, \
     VMStatus
 from azurelinuxagent.common.utils.flexible_version import FlexibleVersion
@@ -768,7 +768,43 @@ class ExtHandlersHandler(object):
 
 
 class ExtHandlerInstance(object):
-    def __init__(self, ext_handler, protocol):
+
+    def __truncate_file_head(self, filename, max_size):
+        try:
+            if os.stat(filename).st_size <= max_size:
+                return
+            
+            with open(filename, "rb") as existing_file:
+                existing_file.seek(-1 * max_size, 2)
+                _ = existing_file.readline()
+
+                with open(filename + ".tmp", "wb") as tmp_file:
+                    shutil.copyfileobj(existing_file, tmp_file)
+
+            os.rename(filename + ".tmp", filename)
+
+        except (IOError, OSError) as e:
+            if is_file_not_found_error(e):
+                # If CommandExecution.log does not exist, it's not noteworthy;
+                # this just means that no extension with self.ext_handler.name is
+                # installed.
+                return
+            
+            logger.error("Exception occurred while attempting to truncate CommandExecution.log "
+                "for extension {0}. Exception is: {1}", self.ext_handler.name, e)
+
+            for f in (filename, filename + ".tmp"):
+                try:
+                    os.remove(f)
+                except (IOError, OSError) as cleanup_exception:
+                    if is_file_not_found_error(cleanup_exception):
+                        logger.info("File '{0}' does not exist.", f)
+                    else:
+                        logger.warn("Exception occurred while attempting "
+                            "to remove file '{0}': {1}", f, cleanup_exception)
+
+
+    def __init__(self, ext_handler, protocol, execution_log_max_size=(10 * 1024 * 1024)):
         self.ext_handler = ext_handler
         self.protocol = protocol
         self.operation = None
@@ -781,10 +817,12 @@ class ExtHandlerInstance(object):
             fileutil.mkdir(self.get_log_dir(), mode=0o755)
         except IOError as e:
             self.logger.error(u"Failed to create extension log dir: {0}", e)
+        else:
+            log_file = os.path.join(self.get_log_dir(), "CommandExecution.log")
+
+            self.__truncate_file_head(log_file, execution_log_max_size)
 
-        log_file = os.path.join(self.get_log_dir(), "CommandExecution.log")
-        self.logger.add_appender(logger.AppenderType.FILE,
-                                 logger.LogLevel.INFO, log_file)
+            self.logger.add_appender(logger.AppenderType.FILE, logger.LogLevel.INFO, log_file)
 
     def decide_version(self, target_state=None):
         self.logger.verbose("Decide which version to use")


Test patch:
diff --git a/tests/common/test_version.py b/tests/common/test_version.py
index 78237019..ba1fb767 100644
--- a/tests/common/test_version.py
+++ b/tests/common/test_version.py
@@ -23,6 +23,7 @@ import textwrap
 import mock
 
 import azurelinuxagent.common.conf as conf
+from azurelinuxagent.common.future import ustr
 from azurelinuxagent.common.event import EVENTS_DIRECTORY
 from azurelinuxagent.common.version import set_current_agent, \
     AGENT_LONG_VERSION, AGENT_VERSION, AGENT_NAME, AGENT_NAME_PATTERN, \
@@ -122,7 +123,7 @@ class TestAgentVersion(AgentTestCase):
         it returns a string'.
         """
         lis_version = get_lis_version()
-        self.assertIsInstance(lis_version, str)
+        self.assertIsInstance(lis_version, ustr)
 
     def test_get_daemon_version_should_return_the_version_that_was_previously_set(self):
         set_daemon_version("1.2.3.4")
diff --git a/tests/ga/test_exthandlers.py b/tests/ga/test_exthandlers.py
index 123f3c52..343a4d0d 100644
--- a/tests/ga/test_exthandlers.py
+++ b/tests/ga/test_exthandlers.py
@@ -27,6 +27,7 @@ from azurelinuxagent.common.exception import ExtensionError, ExtensionErrorCodes
 from azurelinuxagent.common.protocol.restapi import ExtensionStatus, Extension, ExtHandler, ExtHandlerProperties
 from azurelinuxagent.common.protocol.util import ProtocolUtil
 from azurelinuxagent.common.protocol.wire import WireProtocol
+from azurelinuxagent.common.utils import fileutil
 from azurelinuxagent.common.utils.extensionprocessutil import TELEMETRY_MESSAGE_MAX_LEN, format_stdout_stderr, \
     read_output
 from azurelinuxagent.ga.exthandlers import parse_ext_status, ExtHandlerInstance, ExtCommandEnvVariable, \
@@ -285,6 +286,32 @@ class TestExtHandlers(AgentTestCase):
                               "Error message should contain the incorrect versions")
                 self.assertFalse(plugin_setting_mismatch_calls[0]['is_success'], "The event should be false")
 
+    @patch("azurelinuxagent.common.conf.get_ext_log_dir")
+    def test_command_extension_log_truncates_correctly(self, mock_log_dir):
+        log_dir_path = os.path.join(self.tmp_dir, "log_directory")
+        mock_log_dir.return_value = log_dir_path
+
+        ext_handler_props = ExtHandlerProperties()
+        ext_handler_props.version = "1.2.3"
+        ext_handler = ExtHandler(name='foo')
+        ext_handler.properties = ext_handler_props
+
+        first_line = "This is the first line!"
+        second_line = "This is the second line."
+        old_logfile_contents = "{first_line}\n{second_line}\n".format(first_line=first_line, second_line=second_line)
+
+        log_file_path = os.path.join(log_dir_path, "foo", "CommandExecution.log")
+
+        fileutil.mkdir(os.path.join(log_dir_path, "foo"), mode=0o755)
+        with open(log_file_path, "a") as log_file:
+            log_file.write(old_logfile_contents)
+
+        _ = ExtHandlerInstance(ext_handler=ext_handler, protocol=None,
+            execution_log_max_size=(len(first_line)+len(second_line)//2))
+
+        with open(log_file_path) as truncated_log_file:
+            self.assertEqual(truncated_log_file.read(), "{second_line}\n".format(second_line=second_line))
+
 class LaunchCommandTestCase(AgentTestCase):
     """
     Test cases for launch_command