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

* 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 af046611f1. * fix output 2 * Revert "fix output 2" This reverts commit 5b03b6f142. * 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
2024-01-31 16:14:32 -05:00 · 2024-01-31 16:14:32 -05:00 · c68159158e
--- 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
--- 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
--- 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,11 +64,13 @@ 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:
@ -79,3 +78,10 @@ jobs:
        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
--- a/setup.py
+++ b/setup.py
@ -45,7 +45,7 @@ AZURE_EXTENSIONS = """\
      <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"
--- a/tests/utils/constants.py
+++ b/tests/utils/constants.py
@ -14,6 +14,7 @@ PYAZURE_WORKER_DIR = "PYAZURE_WORKER_DIR"

 # Debug Flags
 PYAZURE_WEBHOST_DEBUG = "PYAZURE_WEBHOST_DEBUG"
+ARCHIVE_WEBHOST_LOGS = "ARCHIVE_WEBHOST_LOGS"

 # CI test constants
 CONSUMPTION_DOCKER_TEST = "CONSUMPTION_DOCKER_TEST"
--- a/tests/utils/testutils.py
+++ b/tests/utils/testutils.py
@ -48,7 +48,8 @@ from azure_functions_worker.constants import (
 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 @@ class WebHostTestCase(unittest.TestCase, metaclass=WebHostTestCaseMeta):
                _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 @@ class WebHostTestCase(unittest.TestCase, metaclass=WebHostTestCaseMeta):
        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 @@ class WebHostTestCase(unittest.TestCase, metaclass=WebHostTestCaseMeta):
                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 @@ class _WebHostProxy:
        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', {}))