Revert "Interrupt altool's CFNetworking retry loop (#394)"

This reverts commit 3069359.

CHANGELOG.md

@@ -1,9 +1,3 @@
-Version 0.50.4
--------------
-
-**Bugfixes**
-- Fix `app-store-connect publish` action getting stuck while binary is being uploaded using `altool`. [PR #394](https://github.com/codemagic-ci-cd/cli-tools/pull/394)
-
 Version 0.50.3
 -------------
 

pyproject.toml

@@ -1,6 +1,6 @@
 [tool.poetry]
 name = "codemagic-cli-tools"
-version = "0.50.4"
+version = "0.50.3"
 description = "CLI tools used in Codemagic builds"
 readme = "README.md"
 authors = [

src/codemagic/__version__.py

@@ -1,5 +1,5 @@
 __title__ = "codemagic-cli-tools"
 __description__ = "CLI tools used in Codemagic builds"
-__version__ = "0.50.4.dev"
+__version__ = "0.50.3.dev"
 __url__ = "https://github.com/codemagic-ci-cd/cli-tools"
 __licence__ = "GNU General Public License v3.0"

src/codemagic/cli/__init__.py

@@ -11,6 +11,5 @@
 from .cli_app import CliAppException
 from .cli_app import common_arguments
 from .cli_process import CliProcess
-from .cli_process import CliProcessHealthCheckError
 from .cli_types import CommandArg
 from .colors import Colors

src/codemagic/cli/cli_app.py

@@ -392,7 +392,7 @@ def _register_cli_action(
         ArgumentParserBuilder(cls, main_or_group_action, deprecated_action_parsers, for_deprecated_alias=True).build()
         CliHelpFormatter.suppress_deprecated_action(main_or_group_action.deprecation_info.alias)
 
-    def obfuscate_command(
+    def _obfuscate_command(
         self,
         command_args: Sequence[CommandArg],
         obfuscate_patterns: Optional[Iterable[ObfuscationPattern]] = None,
@@ -443,7 +443,7 @@ def execute(
 
         return CliProcess(
             command_args,
-            self.obfuscate_command(command_args, obfuscate_patterns),
+            self._obfuscate_command(command_args, obfuscate_patterns),
             dry=self.dry_run,
             print_streams=print_streams,
         ).execute(**execute_kwargs)

src/codemagic/cli/cli_process.py

@@ -7,7 +7,6 @@
 import sys
 import time
 from typing import IO
-from typing import Callable
 from typing import Dict
 from typing import Optional
 from typing import Sequence
@@ -20,19 +19,13 @@
 from .cli_types import ObfuscatedCommand
 
 
-class CliProcessHealthCheckError(Exception):
-    pass
-
-
 class CliProcess:
     def __init__(
         self,
         command_args: Sequence[CommandArg],
         safe_form: Optional[ObfuscatedCommand] = None,
         print_streams: bool = True,
         dry: bool = False,
-        process_health_check: Optional[Callable[[CliProcess], bool]] = None,
-        process_health_check_interval: float = 10,
     ):
         self.logger = log.get_logger(self.__class__)
         self.duration: float = 0
@@ -49,9 +42,6 @@ def __init__(
         self._stderr = ""
         self._stdout_stream: Optional[CliProcessStream] = None
         self._stderr_stream: Optional[CliProcessStream] = None
-        self._process_health_check = process_health_check
-        self._process_health_check_interval = process_health_check_interval
-        self._process_health_check_at: Optional[float] = None
 
     @property
     def stdout(self) -> str:
@@ -86,18 +76,6 @@ def _handle_streams(self, buffer_size: Optional[int] = None):
         if self._stderr_stream:
             self._stderr += self._stderr_stream.process_buffer(buffer_size, self._print_streams)
 
-    def _check_process_health(self):
-        if not self._process_health_check:
-            return
-
-        now = time.time()
-        if self._process_health_check_at and now - self._process_health_check_at < self._process_health_check_interval:
-            return
-
-        self._process_health_check_at = now
-        if not self._process_health_check(self):
-            raise CliProcessHealthCheckError("Process health check failed")
-
     def _configure_process_streams(self):
         if self._process.stdout:
             self._stdout_stream = CliProcessStream.create(self._process.stdout, sys.stdout, blocking=False)
@@ -124,7 +102,6 @@ def execute(
                 self._configure_process_streams()
                 while self._process.poll() is None:
                     self._handle_streams(self._buffer_size)
-                    self._check_process_health()
                     time.sleep(poll_interval)
                 self._handle_streams()
         finally:

src/codemagic/models/altool/altool.py

@@ -7,7 +7,6 @@
 import subprocess
 import time
 from contextlib import contextmanager
-from datetime import datetime
 from functools import lru_cache
 from typing import TYPE_CHECKING
 from typing import AnyStr
@@ -17,12 +16,9 @@
 from typing import Sequence
 from typing import Tuple
 from typing import Union
-from typing import cast
 
 import psutil
 
-from codemagic.cli import CliProcess
-from codemagic.cli import CliProcessHealthCheckError
 from codemagic.cli import environment
 from codemagic.mixins import RunningCliAppMixin
 from codemagic.mixins import StringConverterMixin
@@ -47,10 +43,6 @@ def __init__(self, error_message: str, process_output: str):
         self.process_output = process_output
 
 
-class CFNetworkingRetryError(AltoolCommandError):
-    pass
-
-
 class Altool(RunningCliAppMixin, StringConverterMixin):
     def __init__(
         self,
@@ -203,7 +195,7 @@ def _run_retrying_command(
                 return self._run_command(command, f'Failed to {action_name} archive at "{artifact_path}"', cli_app)
             except AltoolCommandError as error:
                 has_retries = retries > 0
-                should_retry = self._should_retry_command(error)
+                should_retry = self._should_retry_command(error.process_output)
                 if has_retries and should_retry:
                     if attempt == 1:
                         print_fn(f"Failed to {action_name} archive, but this might be a temporary issue, retrying...")
@@ -242,28 +234,21 @@ def _run_command(
         cli_app: Optional[CliApp],
     ) -> Optional[AltoolResult]:
         obfuscate_patterns = [self._password] if self._password else []
-        process = None
         try:
             if cli_app:
-                logs_inspector = CFNetworkErrorLogsInspector("altool", datetime.now())
-                process = CliProcess(
+                process = cli_app.execute(
                     command,
-                    cli_app.obfuscate_command(command, obfuscate_patterns),
-                    print_streams=cli_app.verbose,
-                    # Less than 100 should be fine. Retry attempts get to thousands within minutes
-                    process_health_check=lambda _: logs_inspector.get_estimated_errors_count() < 100,
-                    process_health_check_interval=10,
+                    obfuscate_patterns,
+                    show_output=False,
+                    stderr=subprocess.STDOUT,
                 )
-                process.execute(stderr=subprocess.STDOUT)
                 stdout = process.stdout
                 process.raise_for_returncode()
             else:
-                stdout = subprocess.check_output(command, stderr=subprocess.STDOUT).decode()
-        except CliProcessHealthCheckError as hce:
-            raise CFNetworkingRetryError(
-                f"{error_message}: Connection to Apple's cloud storage failed",
-                process.stdout if process else "",
-            ) from hce
+                stdout = subprocess.check_output(
+                    command,
+                    stderr=subprocess.STDOUT,
+                ).decode()
         except subprocess.CalledProcessError as cpe:
             result = self._get_action_result(cpe.stdout)
             if result and result.product_errors:
@@ -301,16 +286,12 @@ def _hide_environment_variable_values(cls, altool_output: Optional[AnyStr]) -> s
         return output
 
     @classmethod
-    def _should_retry_command(cls, error: Union[AltoolCommandError, CFNetworkingRetryError]):
-        if isinstance(error, CFNetworkingRetryError):
-            return True
-
+    def _should_retry_command(cls, process_output: str):
         patterns = (
             re.compile("Unable to authenticate.*-19209"),
             re.compile("server returned an invalid response.*try your request again"),
             re.compile("The request timed out."),
         )
-        process_output = cast(AltoolCommandError, error).process_output
         return any(pattern.search(process_output) for pattern in patterns)
 
     @classmethod
@@ -336,58 +317,3 @@ def _log_process_output(cls, output: Optional[AnyStr], cli_app: Optional[CliApp]
             cli_app.echo(prettified_result)
         else:
             print(prettified_result)
-
-
-class CFNetworkErrorLogsInspector:
-    ERROR_PATTERN = re.compile(r"^Task <[\w-]+>\.<(\d+)> finished with error")
-
-    def __init__(self, process: str, start: datetime):
-        self.logger = log.get_file_logger(self.__class__)
-        predicate = " and ".join(
-            [
-                'subsystem=="com.apple.CFNetwork"',
-                f'process=="{process}"',
-                'eventMessage contains "finished with error"',
-                'eventMessage contains "Error Domain=NSURLErrorDomain"',
-                'eventMessage contains "Code=-1003"',
-            ],
-        )
-        self.logs_command = (
-            "log",
-            "show",
-            "--no-backtrace",
-            "--no-debug",
-            "--no-info",
-            "--no-pager",
-            *("--start", start.strftime("%Y-%m-%d %H:%M:%S")),
-            *("--predicate", predicate),
-            *("--style", "ndjson"),
-        )
-
-    def iter_log_entries(self):
-        start = time.time()
-        try:
-            cp = subprocess.run(
-                self.logs_command,
-                capture_output=True,
-                check=True,
-                timeout=10,
-            )
-        except (subprocess.CalledProcessError, subprocess.TimeoutExpired):
-            self.logger.exception("Checking CFNetwork error logs failed")
-            return
-        finally:
-            self.logger.debug(f"Completed CFNetwork error logs check in {time.time() - start:.2f}s")
-
-        for line in cp.stdout.splitlines():
-            try:
-                log_entry = json.loads(line)
-                if log_entry.get("eventMessage") is not None:
-                    yield log_entry
-            except ValueError:
-                pass
-
-    def get_estimated_errors_count(self) -> int:
-        count = sum(1 for log_entry in self.iter_log_entries() if self.ERROR_PATTERN.match(log_entry["eventMessage"]))
-        self.logger.debug(f"Found {count} log that hint indefinite CFNetwork retry loop")
-        return count

tests/models/altool/test_altool_retrying.py

@@ -1,38 +1,25 @@
 import json
 import pathlib
+from types import SimpleNamespace
 from unittest import mock
 
 import pytest
 from codemagic.models import Altool
 from codemagic.models.altool import AltoolResult
 from codemagic.models.altool.altool import AltoolCommandError
-from codemagic.models.altool.altool import CFNetworkErrorLogsInspector
 from codemagic.models.altool.altool import PlatformType
 
 
 @pytest.fixture
-def mock_echo():
-    return mock.MagicMock()
-
-
-@pytest.fixture
-def mock_cli_app(mock_echo):
-    return mock.MagicMock(
-        echo=mock_echo,
-        verbose=False,
-        obfuscate_command=lambda cmd, _: cmd,
-    )
-
-
-@pytest.fixture
-def mock_altool(mock_cli_app):
+def mock_altool():
     Altool._ensure_altool = mock.Mock(return_value=True)
     altool = Altool(
         username="user@example.com",
         password="xxxx-yyyy-zzzz-wwww",
     )
+    mock_echo = mock.MagicMock()
     altool._kill_xcode_processes_for_retrying = mock.Mock()
-    altool.get_current_cli_app = lambda: mock_cli_app
+    altool.get_current_cli_app = lambda: SimpleNamespace(echo=mock_echo)
     return altool
 
 
@@ -158,29 +145,3 @@ def test_retrying_command_immediate_success(mock_altool, mock_success_stdout, mo
     with mock.patch.object(mock_altool, "_run_command", side_effect=[mock_success_result]):
         result = mock_altool.upload_app(pathlib.Path("app.ipa"), retries=100, retry_wait_seconds=0)
     assert result is mock_success_result
-
-
-@mock.patch("codemagic.cli.cli_process.subprocess.Popen")
-@mock.patch.object(CFNetworkErrorLogsInspector, "iter_log_entries")
-@mock.patch.object(PlatformType, "from_path", lambda _artifact_path: PlatformType.IOS)
-def test_cf_networking_error_retrying(mock_iter_log_entries, mock_popen, mock_altool, mock_echo):
-    mock_popen.return_value = mock.MagicMock(
-        poll=mock.MagicMock(return_value=None),
-        stdout=mock.MagicMock(read=mock.MagicMock(return_value=b"")),
-    )
-    event_message = "Task <0E1A3630>.<123> finished with error [-1003] Error Domain=NSURLErrorDomain Code=-1003 "
-    mock_iter_log_entries.return_value = [{"eventMessage": event_message} for _ in range(101)]
-
-    with pytest.raises(IOError) as exc_info:
-        mock_altool.upload_app(
-            pathlib.Path("app.ipa"),
-            retries=2,
-        )
-
-    assert str(exc_info.value) == 'Failed to upload archive at "app.ipa": Connection to Apple\'s cloud storage failed'
-    mock_echo.assert_has_calls(
-        [
-            mock.call("Failed to upload archive, but this might be a temporary issue, retrying..."),
-            mock.call("Attempt #2 to upload failed."),
-        ],
-    )