Enhance test Webhost logs and fix 503s (#1411)

YunchuWang · web-flow · commit c68159158e12 · 2024-01-31T16:14:32.000-05:00
* add sanity check for testwebhost and refactor webhost log after test * reduce ut pipeline passing log * format * format * update github action versions * codecov * fix ut ppl * fix deprecated output flag * Revert "fix deprecated output flag" This reverts commit af04661. * fix output 2 * Revert "fix output 2" This reverts commit 5b03b6f. * len check * enable host console log for ut pipeline * suppress passed ut log * reduce log * reduce log for e2e ppl * upload webhost log to artifact * fix * archive logs for e2e ppl * revert format * add lang version to log filename * fix * always publish archive * revert * upgrade eg ext version * revert gitignore * only publish log if failure * feedback * feedback * fix * fback * flake
diff --git a/.github/Scripts/e2e-tests.sh b/.github/Scripts/e2e-tests.sh
@@ -1,3 +1,3 @@
 #!/usr/bin/env bash
-python -m pytest -n auto --dist loadfile --reruns 4 -vv --instafail --cov=./azure_functions_worker --cov-report xml --cov-branch --cov-append tests/endtoend/test_worker_process_count_functions.py tests/endtoend/test_threadpool_thread_count_functions.py
-python -m pytest -n auto --dist loadfile --reruns 4 -vv --instafail --cov=./azure_functions_worker --cov-report xml --cov-branch --cov-append --ignore=tests/endtoend/test_worker_process_count_functions.py --ignore=tests/endtoend/test_threadpool_thread_count_functions.py tests/endtoend
+python -m pytest -q -n auto --dist loadfile --reruns 4 --instafail --cov=./azure_functions_worker --cov-report xml --cov-branch --cov-append tests/endtoend/test_worker_process_count_functions.py tests/endtoend/test_threadpool_thread_count_functions.py
+python -m pytest -q -n auto --dist loadfile --reruns 4 --instafail --cov=./azure_functions_worker --cov-report xml --cov-branch --cov-append --ignore=tests/endtoend/test_worker_process_count_functions.py --ignore=tests/endtoend/test_threadpool_thread_count_functions.py tests/endtoend
diff --git a/.github/workflows/ci_e2e_workflow.yml b/.github/workflows/ci_e2e_workflow.yml
@@ -5,10 +5,15 @@ name: CI E2E tests
 
 on:
   workflow_dispatch:
+    inputs:
+      archive_webhost_logging:
+        description: "For debugging purposes, archive test webhost logs"
+        required: false
+        default: "false"
   push:
-    branches: [ dev, master, main, release/* ]
+    branches: [dev, master, main, release/*]
   pull_request:
-    branches: [ dev, master, main, release/* ]
+    branches: [dev, master, main, release/*]
   schedule:
     # Monday to Thursday 1 AM PDT build
     # * is a special character in YAML so you have to quote this string
@@ -21,27 +26,23 @@ jobs:
     strategy:
       fail-fast: false
       matrix:
-        python-version: [ 3.7, 3.8, 3.9, "3.10", "3.11" ]
+        python-version: [3.7, 3.8, 3.9, "3.10", "3.11"]
     permissions: read-all
     steps:
       - name: Checkout code.
-        uses: actions/checkout@v2
+        uses: actions/checkout@v4
       - name: Set up Python ${{ matrix.python-version }}
-        uses: actions/setup-python@v2
+        uses: actions/setup-python@v5
         with:
           python-version: ${{ matrix.python-version }}
-      - name: Set up Dotnet 3.1.x
-        uses: actions/setup-dotnet@v1
-        with:
-          dotnet-version: '3.1.x'
       - name: Set up Dotnet 6.x
-        uses: actions/setup-dotnet@v1
+        uses: actions/setup-dotnet@v4
         with:
-          dotnet-version: '6.x'
+          dotnet-version: "6.x"
       - name: Set up Dotnet 8.0.x
-        uses: actions/setup-dotnet@v1
+        uses: actions/setup-dotnet@v4
         with:
-          dotnet-version: '8.0.x'
+          dotnet-version: "8.0.x"
       - name: Install dependencies and the worker
         run: |
           retry() {
@@ -64,11 +65,12 @@ jobs:
           python -m pip install --upgrade pip
           python -m pip install --index-url https://test.pypi.org/simple/ --extra-index-url https://pypi.org/simple -U azure-functions --pre
           python -m pip install -U -e .[dev]
-          
+
           # Retry a couple times to avoid certificate issue
           retry 5 python setup.py build
           retry 5 python setup.py webhost --branch-name=dev
           retry 5 python setup.py extension
+          mkdir logs
       - name: Grant execute permission
         run: chmod +x .github/Scripts/e2e-tests.sh
       - name: Running 3.7 Tests
@@ -81,6 +83,7 @@ jobs:
           AzureWebJobsSqlConnectionString: ${{ secrets.LinuxSqlConnectionString37 }}
           AzureWebJobsEventGridTopicUri: ${{ secrets.LinuxEventGridTopicUriString37 }}
           AzureWebJobsEventGridConnectionKey: ${{ secrets.LinuxEventGridConnectionKeyString37 }}
+          ARCHIVE_WEBHOST_LOGS: ${{ github.event.inputs.archive_webhost_logging }}
         run: .github/Scripts/e2e-tests.sh
       - name: Running 3.8 Tests
         if: matrix.python-version == 3.8
@@ -92,6 +95,7 @@ jobs:
           AzureWebJobsSqlConnectionString: ${{ secrets.LinuxSqlConnectionString38 }}
           AzureWebJobsEventGridTopicUri: ${{ secrets.LinuxEventGridTopicUriString38 }}
           AzureWebJobsEventGridConnectionKey: ${{ secrets.LinuxEventGridConnectionKeyString38 }}
+          ARCHIVE_WEBHOST_LOGS: ${{ github.event.inputs.archive_webhost_logging }}
         run: .github/Scripts/e2e-tests.sh
       - name: Running 3.9 Tests
         if: matrix.python-version == 3.9
@@ -103,6 +107,7 @@ jobs:
           AzureWebJobsSqlConnectionString: ${{ secrets.LinuxSqlConnectionString39 }}
           AzureWebJobsEventGridTopicUri: ${{ secrets.LinuxEventGridTopicUriString39 }}
           AzureWebJobsEventGridConnectionKey: ${{ secrets.LinuxEventGridConnectionKeyString39 }}
+          ARCHIVE_WEBHOST_LOGS: ${{ github.event.inputs.archive_webhost_logging }}
         run: .github/Scripts/e2e-tests.sh
       - name: Running 3.10 Tests
         if: matrix.python-version == 3.10
@@ -114,6 +119,7 @@ jobs:
           AzureWebJobsSqlConnectionString: ${{ secrets.LinuxSqlConnectionString310 }}
           AzureWebJobsEventGridTopicUri: ${{ secrets.LinuxEventGridTopicUriString310 }}
           AzureWebJobsEventGridConnectionKey: ${{ secrets.LinuxEventGridConnectionKeyString310 }}
+          ARCHIVE_WEBHOST_LOGS: ${{ github.event.inputs.archive_webhost_logging }}
         run: .github/Scripts/e2e-tests.sh
       - name: Running 3.11 Tests
         if: matrix.python-version == 3.11
@@ -125,11 +131,19 @@ jobs:
           AzureWebJobsSqlConnectionString: ${{ secrets.LinuxSqlConnectionString311 }}
           AzureWebJobsEventGridTopicUri: ${{ secrets.LinuxEventGridTopicUriString311 }}
           AzureWebJobsEventGridConnectionKey: ${{ secrets.LinuxEventGridConnectionKeyString311 }}
+          ARCHIVE_WEBHOST_LOGS: ${{ github.event.inputs.archive_webhost_logging }}
         run: .github/Scripts/e2e-tests.sh
       - name: Codecov
-        uses: codecov/codecov-action@v1.0.13
+        uses: codecov/codecov-action@v3
         with:
           file: ./coverage.xml # optional
           flags: unittests # optional
           name: codecov # optional
           fail_ci_if_error: false # optional (default = false)
+      - name: Publish Logs to Artifact
+        if: failure()
+        uses: actions/upload-artifact@v4
+        with:
+          name: Test WebHost Logs ${{ github.run_id }} ${{ matrix.python-version }}
+          path: logs/*.log
+          if-no-files-found: ignore
diff --git a/.github/workflows/ci_ut_workflow.yml b/.github/workflows/ci_ut_workflow.yml
@@ -5,6 +5,11 @@ name: CI Unit tests
 
 on:
   workflow_dispatch:
+    inputs:
+      archive_webhost_logging:
+        description: "For debugging purposes, archive test webhost logs"
+        required: false
+        default: "false"
   schedule:
     # Monday to Thursday 1 AM PDT build
     # * is a special character in YAML so you have to quote this string
@@ -23,21 +28,13 @@ jobs:
         python-version: [ 3.7, 3.8, 3.9, "3.10", "3.11" ]
     permissions: read-all
     steps:
-    - uses: actions/checkout@v2
+    - uses: actions/checkout@v4
     - name: Set up Python ${{ matrix.python-version }}
-      uses: actions/setup-python@v2
+      uses: actions/setup-python@v5
       with:
         python-version: ${{ matrix.python-version }}
-    - name: Set up Dotnet 3.1.x
-      uses: actions/setup-dotnet@v1
-      with:
-        dotnet-version: '3.1.x'
-    - name: Set up Dotnet 6.x
-      uses: actions/setup-dotnet@v1
-      with:
-        dotnet-version: '6.x'
     - name: Set up Dotnet 8.0.x
-      uses: actions/setup-dotnet@v1
+      uses: actions/setup-dotnet@v4
       with:
         dotnet-version: "8.0.x"
     - name: Install dependencies and the worker
@@ -67,15 +64,24 @@ jobs:
         retry 5 python setup.py build
         retry 5 python setup.py webhost --branch-name=dev
         retry 5 python setup.py extension
+        mkdir logs
     - name: Test with pytest
       env:
         AzureWebJobsStorage: ${{ secrets.LinuxStorageConnectionString310 }} # needed for installing azure-functions-durable while running setup.py
+        ARCHIVE_WEBHOST_LOGS: ${{ github.event.inputs.archive_webhost_logging }}
       run: |
-        python -m pytest -n auto --dist loadfile --reruns 4 -vv --instafail --cov=./azure_functions_worker --cov-report xml --cov-branch tests/unittests
+        python -m pytest -q -n auto --dist loadfile --reruns 4 --instafail --cov=./azure_functions_worker --cov-report xml --cov-branch tests/unittests
     - name: Codecov
       uses: codecov/codecov-action@v3
       with:
         file: ./coverage.xml # optional
         flags: unittests # optional
         name: codecov # optional
         fail_ci_if_error: false # optional (default = false)
+    - name: Publish Logs to Artifact
+      if: failure()
+      uses: actions/upload-artifact@v4
+      with:
+        name: Test WebHost Logs ${{ github.run_id }} ${{ matrix.python-version }}
+        path: logs/*.log
+        if-no-files-found: ignore
diff --git a/setup.py b/setup.py
@@ -45,7 +45,7 @@
       <PackageReference Include="Microsoft.Azure.WebJobs.Extensions.EventHubs"
         Version="5.0.0" />
       <PackageReference Include="Microsoft.Azure.WebJobs.Extensions.EventGrid"
-        Version="3.1.0" />
+        Version="3.3.1" />
       <PackageReference Include="Microsoft.Azure.WebJobs.Extensions.Storage"
         Version="4.0.5" />
       <PackageReference Include="Microsoft.Azure.WebJobs.Extensions.ServiceBus"
diff --git a/tests/utils/constants.py b/tests/utils/constants.py
@@ -14,6 +14,7 @@
 
 # Debug Flags
 PYAZURE_WEBHOST_DEBUG = "PYAZURE_WEBHOST_DEBUG"
+ARCHIVE_WEBHOST_LOGS = "ARCHIVE_WEBHOST_LOGS"
 
 # CI test constants
 CONSUMPTION_DOCKER_TEST = "CONSUMPTION_DOCKER_TEST"
diff --git a/tests/utils/testutils.py b/tests/utils/testutils.py
@@ -48,7 +48,8 @@
 from azure_functions_worker.utils.common import is_envvar_true, get_app_setting
 from tests.utils.constants import PYAZURE_WORKER_DIR, \
     PYAZURE_INTEGRATION_TEST, PROJECT_ROOT, WORKER_CONFIG, \
-    CONSUMPTION_DOCKER_TEST, DEDICATED_DOCKER_TEST, PYAZURE_WEBHOST_DEBUG
+    CONSUMPTION_DOCKER_TEST, DEDICATED_DOCKER_TEST, PYAZURE_WEBHOST_DEBUG, \
+    ARCHIVE_WEBHOST_LOGS
 from tests.utils.testutils_docker import WebHostConsumption, WebHostDedicated, \
     DockerConfigs
 
@@ -257,6 +258,14 @@ def setUpClass(cls):
                 _setup_func_app(TESTS_ROOT / script_dir)
                 cls.webhost = start_webhost(script_dir=script_dir,
                                             stdout=cls.host_stdout)
+            if not cls.webhost.is_healthy():
+                cls.host_out = cls.host_stdout.read()
+                if cls.host_out is not None and len(cls.host_out) > 0:
+                    error_message = 'WebHost is not started correctly. '
+                    f'{cls.host_stdout.name}: {cls.host_out}'
+                    cls.host_stdout_logger.error(error_message)
+                    raise RuntimeError(error_message)
+
         except Exception:
             _teardown_func_app(TESTS_ROOT / script_dir)
             raise
@@ -267,6 +276,21 @@ def tearDownClass(cls):
         cls.webhost = None
 
         if cls.host_stdout is not None:
+            if is_envvar_true(ARCHIVE_WEBHOST_LOGS):
+                cls.host_stdout.seek(0)
+                content = cls.host_stdout.read()
+                if content is not None and len(content) > 0:
+                    version_info = sys.version_info
+                    log_file = (
+                        "logs/"
+                        f"{cls.__module__}_{cls.__name__}"
+                        f"{version_info.minor}_webhost.log"
+                    )
+                    with open(log_file, 'w+') as file:
+                        file.write(content)
+                    cls.host_stdout_logger.info("WebHost log is archived to"
+                                                f"{log_file} in the artifact")
+
             cls.host_stdout.close()
             cls.host_stdout = None
 
@@ -287,16 +311,18 @@ def _run_test(self, test, *args, **kwargs):
                 test(self, *args, **kwargs)
             except Exception as e:
                 test_exception = e
-
-            try:
-                self.host_stdout.seek(last_pos)
-                self.host_out = self.host_stdout.read()
-                self.host_stdout_logger.error(
-                    'Captured WebHost stdout from %s :\n%s',
-                    self.host_stdout.name, self.host_out)
             finally:
-                if test_exception is not None:
-                    raise test_exception
+                try:
+                    self.host_stdout.seek(last_pos)
+                    self.host_out = self.host_stdout.read()
+                    if self.host_out is not None and len(self.host_out) > 0:
+                        self.host_stdout_logger.error(
+                            'Captured WebHost log generated during test '
+                            '%s from %s :\n%s', test.__name__,
+                            self.host_stdout.name, self.host_out)
+                finally:
+                    if test_exception is not None:
+                        raise test_exception
 
 
 class SharedMemoryTestCase(unittest.TestCase):
@@ -776,6 +802,10 @@ def __init__(self, proc, addr):
         self._proc = proc
         self._addr = addr
 
+    def is_healthy(self):
+        r = self.request('GET', '', no_prefix=True)
+        return 200 <= r.status_code < 300
+
     def request(self, meth, funcname, *args, **kwargs):
         request_method = getattr(requests, meth.lower())
         params = dict(kwargs.pop('params', {}))
