From f8d67b02aa241c0021ac88079e4a83b20cc4b45d Mon Sep 17 00:00:00 2001 From: Priya Chintalapati Date: Mon, 15 Jun 2026 01:00:53 +0530 Subject: [PATCH 1/3] Stream kudu logs during deployment --- .../appservice/_build_log_formatter.py | 309 +++++++++++++++++ .../cli/command_modules/appservice/_params.py | 6 + .../cli/command_modules/appservice/custom.py | 319 +++++++++++++++++- 3 files changed, 617 insertions(+), 17 deletions(-) create mode 100644 src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py diff --git a/src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py b/src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py new file mode 100644 index 00000000000..147e329f97d --- /dev/null +++ b/src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py @@ -0,0 +1,309 @@ +# -------------------------------------------------------------------------------------------- +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. See License.txt in the project root for license information. +# -------------------------------------------------------------------------------------------- + +""" +Build log formatter for `az webapp deploy` / `az functionapp deploy`. + +Provides intelligent log filtering that shows a clean summary by default, +with full verbosity available via --build-logs full. + +Log levels: + - PHASE: Major deployment phases (always shown) + - INFO: Important milestones (shown in summary + full) + - DETAIL: Individual package lines, SDK metadata (shown only in full) + - WARNING: Deprecation notices, pip warnings (aggregated in summary, shown in full) +""" + +import re + + +# Log verbosity levels +BUILD_LOGS_FULL = "full" +BUILD_LOGS_SUMMARY = "summary" +BUILD_LOGS_NONE = "none" + +# --- Patterns for classification --- + +# Oryx internal metadata lines (hidden in summary mode) +_ORYX_METADATA_PATTERNS = [ + re.compile(r'^\s*(Operation performed by Microsoft Oryx)'), + re.compile(r'^\s*(You can report issues at)'), + re.compile(r'^\s*(Oryx Version:)'), + re.compile(r'^\s*(Build Operation ID:)'), + re.compile(r'^\s*(Repository Commit\s*:)'), + re.compile(r'^\s*(OS Type\s*:)'), + re.compile(r'^\s*(Image Type\s*:)'), + re.compile(r'^\s*(Primary SDK Storage URL:)'), + re.compile(r'^\s*(Backup SDK Storage URL:)'), + re.compile(r'^\s*(ACR SDK Registry URL:)'), + re.compile(r'^\s*(SDK provider status:)'), + re.compile(r'^\s*(External ACR SDK provider)'), + re.compile(r'^\s*(External SDK provider)'), + re.compile(r'^\s*(Direct ACR SDK provider)'), + re.compile(r'^\s*(Blob SDK provider)'), + re.compile(r'^\s*(External ACR provider resolved)'), + re.compile(r'^\s*(Version resolved using)'), + re.compile(r'^\s*(Requesting SDK from ACR)'), + re.compile(r'^\s*(Successfully pulled SDK from ACR)'), + re.compile(r'^\s*(SDK for .* fetched via)'), + re.compile(r'^\s*(Requesting metadata for platform)'), + re.compile(r'^\s*(Not a vso image)'), + re.compile(r'^\s*(Creating directory for command manifest)'), + re.compile(r'^\s*(Removing existing manifest file)'), + re.compile(r'^\s*(Creating a manifest file)'), + re.compile(r'^\s*(Manifest file created)'), + re.compile(r'^\s*(Copying \.ostype)'), + re.compile(r'^\s*(Node Build Command Manifest)'), + # .NET first-run banner (noisy, not useful for deployment) + re.compile(r'^\s*(Welcome to \.NET)'), + re.compile(r'^\s*-{5,}$'), # separator lines like "---------------------" + re.compile(r'^\s*(SDK Version:)'), + re.compile(r'^\s*(Telemetry)$'), + re.compile(r'^\s*(The \.NET tools collect usage data)'), + re.compile(r'^\s*(Read more about \.NET CLI Tools telemetry)'), + re.compile(r'^\s*(Installed an ASP\.NET Core HTTPS)'), + re.compile(r'^\s*(To trust the certificate)'), + re.compile(r'^\s*(Learn about HTTPS)'), + re.compile(r'^\s*(Write your first app)'), + re.compile(r'^\s*(Find out what.s new)'), + re.compile(r'^\s*(Explore documentation)'), + re.compile(r'^\s*(Report issues and find source)'), + re.compile(r'^\s*(Use .dotnet --help.)'), + re.compile(r'^\s*={5,}$'), # separator lines like "===================" + # Kudu internal deployment metadata + re.compile(r'^\s*(PreDeployment:)'), + re.compile(r'^\s*(Repository path is)'), + re.compile(r'^\s*(Using standard output preparation)'), + re.compile(r'^\s*(Total time for destination directory preparation)'), + # Kudu build summary noise (0 errors/warnings not useful on success) + re.compile(r'^\s*(Found \d+ issue)'), + re.compile(r'^\s*(Build Summary)'), + re.compile(r'^\s*(Errors \(\d+\))'), + re.compile(r'^\s*(Warnings \(\d+\))'), + re.compile(r'^\s*(Parsing the build logs)'), + re.compile(r'^\s*(Preparing deployment for commit id)'), + # Kudu post-build noise + re.compile(r'^\s*(Updating submodules)'), + re.compile(r'^\s*(Triggering container recycle)'), + re.compile(r'^\s*(Generating summary of Oryx build)'), +] + +# Package download/cache lines (suppressed, counted instead) +_PACKAGE_LINE_PATTERNS = [ + re.compile(r'^\s*\[[\d:+]+\]\s*(Collecting|Using cached|Downloading|Using)'), + re.compile(r'^\s*\[[\d:+]+\]\s*(Successfully installed)'), + re.compile(r'^\s*(npm warn|npm notice)'), + re.compile(r'^\s*added \d+ packages'), + re.compile(r'^\s*-\s+(Locking|Installing|Downloading)\s+\S+'), # composer package ops + re.compile(r'^\s*\d+/\d+\s*\[[\s=>-]*\]\s*\d+%'), # composer progress bars (X/Y format) + re.compile(r'^\s*\d+\s*\[[->=<>\s]*\]'), # composer progress bars (single number format) + re.compile(r'^\s*Loading composer repositories'), + re.compile(r'^\s*(Updating dependencies|Lock file operations:)'), + re.compile(r'^\s*(Installing dependencies from lock file)'), + re.compile(r'^\s*(Writing lock file)'), + re.compile(r'^\s*Package operations:'), + re.compile(r'^\s*Generating autoload files'), + re.compile(r'^\s*\d+ package suggestions were added'), + re.compile(r'^\s*\d+ package you are using is looking for funding'), + re.compile(r'^\s*Use the `composer'), +] + +# Patterns for counting packages +_PIP_COLLECTING = re.compile(r'^\s*\[[\d:+]+\]\s*Collecting\s+(\S+)') +_PIP_CACHED = re.compile(r'^\s*\[[\d:+]+\]\s*Using cached\s+\S+') +_PIP_INSTALLING = re.compile(r'^\s*\[[\d:+]+\]\s*Installing collected packages:') +_PIP_INSTALLED = re.compile(r'^\s*\[[\d:+]+\]\s*Successfully installed\s+(.*)') +_NPM_ADDED = re.compile(r'^\s*added (\d+) packages') + +# Warning patterns (aggregated in summary mode) +_WARNING_PATTERNS = [ + re.compile(r'^\s*npm warn deprecated\s+(.+)'), + re.compile(r'^\s*npm warn\s+(.+)'), + re.compile(r'^\s*\[notice\]\s+(.+)'), + re.compile(r'^\s*\[[\d:+]+\]\s*WARNING:\s+(.+)'), + re.compile(r'^\s*DEPRECATION:\s+(.+)'), + re.compile(r'^\s*Deprecation Notice:\s+(.+)'), + re.compile(r'^\s*Deprecated:\s+(.+)'), +] + +# Important milestone lines (always shown in summary) +_MILESTONE_PATTERNS = [ + re.compile(r'^\s*(Detected following platforms:)'), + re.compile(r'^\s*(python|nodejs|dotnet|java|php|ruby):\s*[\d.]+', re.IGNORECASE), + re.compile(r'^\s*(Detected the following frameworks:)'), + re.compile(r'^\s*(Running pip install)'), + re.compile(r"^\s*(Running 'npm install')"), + re.compile(r"^\s*(Running 'yarn install')"), + re.compile(r'^\s*(pip install done in)'), + re.compile(r'^\s*(Running build script)'), + re.compile(r'^\s*(Build script snippets done in)'), + re.compile(r'^\s*(Preparing output)'), + re.compile(r'^\s*(Compressing content)'), + re.compile(r'^\s*(Using \w+ for compression)'), + re.compile(r'^\s*(Compression with .* done in)'), + re.compile(r'^\s*(Copying files to destination)'), + re.compile(r'^\s*(Copying to destination directory done in)'), + re.compile(r'^\s*(Total execution done in)'), + re.compile(r'^\s*(Platform installation done in)'), + re.compile(r'^\s*(Installing platform)'), + re.compile(r'^\s*(Downloading and extracting)'), + re.compile(r'^\s*(Successfully extracted)'), + re.compile(r'^\s*(Using Node version:)'), + re.compile(r'^\s*(Using Npm version:)'), + re.compile(r'^\s*v\d+\.\d+\.\d+$'), # version number lines like v24.15.0 + re.compile(r'^\s*\d+\.\d+\.\d+$'), # version number lines like 11.12.1 + re.compile(r'^\s*(Python Version:)'), + re.compile(r'^\s*(Python Virtual Environment:)'), + re.compile(r'^\s*(Creating virtual environment)'), + re.compile(r'^\s*(Activating virtual environment)'), + re.compile(r'^\s*(Source directory)'), + re.compile(r'^\s*(Destination directory)'), + re.compile(r'^\s*(Running oryx build)'), + re.compile(r'^\s*(Command:)'), + re.compile(r'^\s*(Running post deployment command)'), + re.compile(r'^\s*(Deployment successful)'), + # PHP/Composer milestones + re.compile(r"^\s*(Running 'composer install)"), + re.compile(r'^\s*(PHP executable:)'), + re.compile(r'^\s*(Composer archive:)'), + # .NET milestones + re.compile(r'^\s*(Using \.NET Core SDK Version:)'), + re.compile(r'^\s*(Publishing to directory)'), + re.compile(r'^\s*(Restored .+\.csproj)'), + re.compile(r'^\s*\S+\s*->\s*/home/site/wwwroot'), # dotnet publish output +] + + +class BuildLogFormatter: + """Formats and filters build log output for CLI display.""" + + def __init__(self, verbosity=BUILD_LOGS_SUMMARY): + self.verbosity = verbosity + self._package_count = 0 + self._packages_collecting = False + self._packages_installing = False + self._warning_count = 0 + self._suppressed_lines = [] # stored for auto-expand on failure + + def format_log_line(self, line): + """Process a single log line and return formatted output or None to suppress. + + Returns: + str or None: The formatted line to display, or None if suppressed. + """ + if self.verbosity == BUILD_LOGS_FULL: + return line + if self.verbosity == BUILD_LOGS_NONE: + self._suppressed_lines.append(line) + return None + + # Summary mode: intelligent filtering + stripped = line.strip() + if not stripped: + return None + + # Check if it's a warning line - aggregate it + if stripped.startswith('npm warn'): + self._warning_count += 1 + self._suppressed_lines.append(line) + return None + + for pattern in _WARNING_PATTERNS: + if pattern.match(stripped): + self._warning_count += 1 + self._suppressed_lines.append(line) + return None + + # Check if it's a package download/install line - count it + if _PIP_COLLECTING.match(stripped): + self._package_count += 1 + if not self._packages_collecting: + self._packages_collecting = True + self._suppressed_lines.append(line) + return None + self._suppressed_lines.append(line) + return None + + if _PIP_CACHED.match(stripped): + self._suppressed_lines.append(line) + return None + + if _PIP_INSTALLING.match(stripped): + self._packages_installing = True + self._suppressed_lines.append(line) + return None + + # "Successfully installed ..." - emit summary instead + pip_installed_match = _PIP_INSTALLED.match(stripped) + if pip_installed_match: + pkg_list = pip_installed_match.group(1) + count = len(pkg_list.split()) + self._suppressed_lines.append(line) + result = self._emit_package_summary(count) + self._packages_collecting = False + self._packages_installing = False + self._package_count = 0 + return result + + # npm "added N packages" + npm_match = _NPM_ADDED.match(stripped) + if npm_match: + count = int(npm_match.group(1)) + self._suppressed_lines.append(line) + return f" Installed {count} packages\n" + + # Check for Oryx metadata lines - suppress + for pattern in _ORYX_METADATA_PATTERNS: + if pattern.match(stripped): + self._suppressed_lines.append(line) + return None + + # Check for other package-level detail lines + for pattern in _PACKAGE_LINE_PATTERNS: + if pattern.match(stripped): + self._suppressed_lines.append(line) + return None + + # Check if it's a milestone line - always show + for pattern in _MILESTONE_PATTERNS: + if pattern.match(stripped): + return line + + # Default: show lines that aren't matched by any suppression pattern + return line + + def _emit_package_summary(self, installed_count): + """Generate summary line for package installation.""" + count = installed_count if installed_count > 0 else self._package_count + return f" Installed {count} packages successfully\n" + + def get_warning_summary(self): + """Get aggregated warning summary. Call at end of build phase.""" + if self._warning_count > 0: + return (f" [!] {self._warning_count} warning(s) " + f"(use --build-logs full to view)\n") + return None + + +def format_final_url(url): + """Format the final app URL to stand out in terminal output.""" + separator = "-" * 50 + return ( + f"\n{separator}\n" + f" Deployment complete!\n" + f" App URL: {url}\n" + f"{separator}\n" + ) + + +def format_build_failure_with_logs(error_text, suppressed_logs): + """On build failure, auto-expand suppressed logs for debugging.""" + output = [] + output.append("\n-- Build Failed -- Showing full build logs for debugging --\n\n") + for log_line in suppressed_logs: + output.append(log_line if log_line.endswith('\n') else log_line + '\n') + output.append("\n-- End of build logs --\n\n") + output.append(error_text) + return "".join(output) diff --git a/src/azure-cli/azure/cli/command_modules/appservice/_params.py b/src/azure-cli/azure/cli/command_modules/appservice/_params.py index 7958d119c36..1101eefaa8d 100644 --- a/src/azure-cli/azure/cli/command_modules/appservice/_params.py +++ b/src/azure-cli/azure/cli/command_modules/appservice/_params.py @@ -1100,6 +1100,12 @@ def load_arguments(self, _): c.argument('enriched_errors', options_list=['--enriched-errors'], help='If true, deployment failures will show context-enriched diagnostics with error codes, suggested fixes, and Copilot prompts.', arg_type=get_three_state_flag()) + c.argument('build_logs', options_list=['--build-logs'], + help='Controls verbosity of build log output during deployment. ' + '"summary" (default): shows phases, milestones, and aggregated warnings. ' + '"full": shows all raw build logs. ' + '"none": suppresses build logs entirely (auto-expands on failure).', + choices=['full', 'summary', 'none'], default='summary') with self.argument_context('functionapp deploy') as c: c.argument('name', options_list=['--name', '-n'], help='Name of the function app to deploy to.') diff --git a/src/azure-cli/azure/cli/command_modules/appservice/custom.py b/src/azure-cli/azure/cli/command_modules/appservice/custom.py index 31d333d7d28..528ee4fe4de 100644 --- a/src/azure-cli/azure/cli/command_modules/appservice/custom.py +++ b/src/azure-cli/azure/cli/command_modules/appservice/custom.py @@ -1,4 +1,4 @@ -# -------------------------------------------------------------------------------------------- +# -------------------------------------------------------------------------------------------- # Copyright (c) Microsoft Corporation. All rights reserved. # Licensed under the MIT License. See License.txt in the project root for license information. # -------------------------------------------------------------------------------------------- @@ -9877,11 +9877,12 @@ def _get_latest_deployment_id(cmd, rg_name, name, deployment_status_url, slot, d def _check_runtimestatus_with_deploymentstatusapi(cmd, resource_group_name, name, slot, deployment_status_url, is_async, timeout, - deploy_params=None): + deploy_params=None, + build_logs='summary'): response_body = None - logger.warning('Polling the status of %s deployment. Start Time: %s UTC', - "async" if is_async else "sync", - datetime.datetime.now(datetime.timezone.utc)) + timestamp = _utc_timestamp() + deployment_type = "async" if is_async else "sync" + logger.warning("%s Polling the status of %s deployment...", timestamp, deployment_type) # verify if the app is a linux web app if deploy_params is not None: # Reuse the Site fetched (or cached) during the publish leg. Saves @@ -9912,7 +9913,7 @@ def _check_runtimestatus_with_deploymentstatusapi(cmd, resource_group_name, name name, slot, deployment_id) response_body = _poll_deployment_runtime_status(cmd, resource_group_name, name, slot, deploymentstatisapi_url, deployment_id, timeout, - deploy_params=deploy_params) + deploy_params=deploy_params, build_logs=build_logs) # incase we are unable to fetch response from deploymentstatus API # fallback to polling kudu for deployment status if response_body is None: @@ -9923,19 +9924,197 @@ def _check_runtimestatus_with_deploymentstatusapi(cmd, resource_group_name, name return response_body +def _utc_timestamp(): + """Return current UTC time as HH:MM:SS string.""" + return datetime.datetime.now(datetime.timezone.utc).strftime('%H:%M:%S') + + +def _parse_log_time(log_time_str): + """Parse log_time from Kudu API (ISO 8601) into HH:MM:SS string in UTC. + + Returns UTC-formatted timestamp, or None if parsing fails. + """ + if not log_time_str: + return None + try: + # Kudu returns ISO 8601 with nanosecond precision: "2026-06-14T08:10:17.4127389Z" + # Python's fromisoformat() only supports up to 6 fractional digits (microseconds) + without_z = log_time_str.rstrip('Z') + if '.' in without_z: + date_part, fractional_seconds = without_z.rsplit('.', 1) + fractional_seconds = fractional_seconds[:6] # truncate to microseconds + without_z = f"{date_part}.{fractional_seconds}" + utc_datetime = datetime.datetime.fromisoformat(without_z).replace( + tzinfo=datetime.timezone.utc) + return utc_datetime.strftime('%H:%M:%S') + except (ValueError, AttributeError): + return None + + +def _fetch_kudu_log_entries(cmd, resource_group_name, webapp_name, slot, deployment_id): + """Fetch raw log entries from Kudu deployment log API. + + Returns a list of (message, log_time, detail_entries) tuples, or None if fetching fails. + Each detail_entries is a list of (message, log_time) tuples from the details_url. + """ + import requests + from azure.cli.core.util import should_disable_connection_verify + + try: + headers = get_scm_site_headers(cmd.cli_ctx, webapp_name, resource_group_name, slot) + scm_url = _get_scm_url(cmd, resource_group_name, webapp_name, slot) + log_url = scm_url + f'/api/deployments/{deployment_id}/log' + + response = requests.get(log_url, headers=headers, + verify=not should_disable_connection_verify(), + timeout=15) + + if response.status_code != 200: + return None + + log_entries = response.json() + if not isinstance(log_entries, list): + return None + + results = [] + for entry in log_entries: + message = (entry.get('message') or '').rstrip() + log_time = entry.get('log_time') + entry_id = entry.get('id') or log_time or message + details_url = entry.get('details_url') + + detail_items = [] + if details_url: + try: + detail_response = requests.get(details_url, headers=headers, + verify=not should_disable_connection_verify(), + timeout=10) + if detail_response.status_code == 200: + detail_entries = detail_response.json() + if isinstance(detail_entries, list): + for detail in detail_entries: + detail_msg = (detail.get('message') or '').rstrip() + detail_time = detail.get('log_time') + detail_id = detail.get('id') + if detail_msg: + detail_items.append((detail_msg, detail_time, detail_id)) + except Exception: # pylint: disable=broad-except + pass + + results.append((message, log_time, entry_id, detail_items)) + + return results if results else None + + except Exception: # pylint: disable=broad-except + return None + + +def _display_build_logs(cmd, resource_group_name, webapp_name, slot, deployment_id, + log_formatter=None, seen_log_ids=None): + """Fetch and display build logs from Kudu. + + Handles all log display scenarios: + - Real-time streaming during BuildInProgress (called every 5s) + - Retrospective display after fast/sync builds complete + - Deduplication via seen_log_ids across multiple calls + + Passes through the formatter so summary/full/none modes are respected. + """ + if seen_log_ids is None: + seen_log_ids = set() + + entries = _fetch_kudu_log_entries(cmd, resource_group_name, webapp_name, slot, deployment_id) + if not entries: + return + + for message, log_time, entry_key, detail_items in entries: + if entry_key and entry_key in seen_log_ids: + pass # Still check details for new sub-entries + elif message: + seen_log_ids.add(entry_key) + ts = _parse_log_time(log_time) + _emit_build_log_line(message, log_formatter, timestamp=ts, indent=False) + + for detail_msg, detail_time, detail_id in detail_items: + detail_key = 'detail:' + str(detail_time or detail_id or detail_msg) + if detail_key in seen_log_ids: + continue + seen_log_ids.add(detail_key) + _emit_build_log_line(detail_msg, log_formatter, timestamp=None, indent=True) + + +def _fetch_full_build_logs(cmd, resource_group_name, webapp_name, slot, deployment_id): + """Fetch all build logs as flat formatted lines (used on failure auto-expand). + + Returns a list of formatted log lines, or None if fetching fails. + """ + entries = _fetch_kudu_log_entries(cmd, resource_group_name, webapp_name, slot, deployment_id) + if not entries: + return None + + lines = [] + for message, log_time, _entry_id, detail_items in entries: + if message: + ts = _parse_log_time(log_time) + prefix = f"{ts} " if ts else " " + lines.append(f"{prefix}{message}\n") + + for detail_msg, _detail_time, _detail_id in detail_items: + lines.append(f" {detail_msg}\n") + + return lines if lines else None + + +def _emit_build_log_line(message, log_formatter, timestamp=None, indent=False): + """Emit a single build log line through the formatter. + + If formatter is None or verbosity is 'full', prints directly. + Otherwise, the formatter decides whether to show, suppress, or aggregate. + + The formatter classifies based on the raw message text (without timestamp prefix) + to ensure patterns match regardless of how the line is formatted for display. + """ + if indent or not timestamp: + display_line = f" {message}\n" + else: + display_line = f"{timestamp} {message}\n" + + if log_formatter is None: + logger.warning("%s", display_line.rstrip('\n')) + return + + # Pass message with indent prefix for classification (patterns expect leading whitespace) + classify_line = f" {message}\n" + formatted = log_formatter.format_log_line(classify_line) + if formatted is not None: + # Show the display_line (with timestamp) not the classify_line + logger.warning("%s", display_line.rstrip('\n')) + + # pylint: disable=too-many-branches def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, deploymentstatusapi_url, - deployment_id, timeout=None, deploy_params=None): + deployment_id, timeout=None, deploy_params=None, build_logs='summary'): + from azure.cli.command_modules.appservice._build_log_formatter import ( + BuildLogFormatter, format_build_failure_with_logs, BUILD_LOGS_SUMMARY + ) + max_time_sec = int(timeout) if timeout else 1000 start_time = time.time() time_elapsed = 0 deployment_status = None response_body = None + seen_log_ids = set() + last_log_poll_time = 0 + previous_status_text = None + build_phase_start = None + + # Initialize the log formatter based on verbosity + log_formatter = BuildLogFormatter(verbosity=build_logs or BUILD_LOGS_SUMMARY) + while time_elapsed < max_time_sec: try: response_body = send_raw_request(cmd.cli_ctx, "GET", deploymentstatusapi_url).json() except Exception as ex: # pylint: disable=broad-except - # we might get a 404 if a new deployment has started and this deployment_id is no longer latest logger.warning("Deployment status endpoint %s returned error: %s.", deploymentstatusapi_url, ex) break deployment_properties = response_body.get('properties') @@ -9943,7 +10122,46 @@ def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, time_elapsed = int(time.time() - start_time) status = RUNTIME_STATUS_TEXT_MAP.get(deployment_status) status = deployment_status if status is None else status - logger.warning("Status: %s Time: %s(s)", status, time_elapsed) + + # Print phase transitions with timing + if status != previous_status_text: + timestamp = _utc_timestamp() + + # Track build phase duration + if deployment_status == "BuildInProgress": + build_phase_start = time.time() + logger.warning("%s --- Build Phase ---------------------------------", timestamp) + elif deployment_status == "BuildSuccessful": + # Always fetch and display build logs on completion. + # For async (fast builds), real-time streaming may have missed most logs. + # For sync, build happened during POST so no logs were streamed at all. + # Pass seen_log_ids to avoid duplicating lines already shown in real-time. + if build_phase_start is None: + logger.warning("%s --- Build Phase ---------------------------------", timestamp) + _display_build_logs(cmd, resource_group_name, webapp_name, + slot, deployment_id, log_formatter, seen_log_ids) + warning_summary = log_formatter.get_warning_summary() + if warning_summary: + logger.warning("%s", warning_summary.rstrip('\n')) + if build_phase_start is not None: + elapsed = int(time.time() - build_phase_start) + logger.warning("%s --- Build Complete (%ds) -----------------------", timestamp, elapsed) + else: + logger.warning("%s --- Build Complete --------------------------------", timestamp) + elif deployment_status == "RuntimeStarting": + logger.warning("%s --- Site Startup --------------------------------", timestamp) + elif deployment_status == "RuntimeSuccessful": + logger.warning("%s [OK] Site started successfully", timestamp) + else: + logger.warning("%s %s", timestamp, status) + previous_status_text = status + + # Stream Kudu logs during build (every 5 seconds) + if deployment_status == "BuildInProgress" and time_elapsed - last_log_poll_time >= 5: + _display_build_logs(cmd, resource_group_name, webapp_name, slot, + deployment_id, log_formatter, seen_log_ids) + last_log_poll_time = time_elapsed + if deployment_status == "RuntimeStarting": logger.info("InprogressInstances: %s, SuccessfulInstances: %s", deployment_properties.get('numberOfInstancesInProgress'), @@ -10004,6 +10222,14 @@ def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, deployment_logs = scm_url + f"/api/deployments/{deployment_id}/log" else: deployment_logs = deployment_logs[0] + + # Auto-expand: fetch full build logs from Kudu and display them + full_build_logs = _fetch_full_build_logs(cmd, resource_group_name, webapp_name, + slot, deployment_id) + if full_build_logs: + full_error = format_build_failure_with_logs(error_text, full_build_logs) + raise CLIError(full_error) + error_text += "Please check the build logs for more info: {}\n".format(deployment_logs) raise CLIError(error_text) time.sleep(15) @@ -11074,7 +11300,8 @@ def perform_onedeploy_webapp(cmd, slot=None, track_status=True, enable_kudu_warmup=True, - enriched_errors=False): + enriched_errors=False, + build_logs='summary'): params = OneDeployParams() params.cmd = cmd @@ -11093,6 +11320,7 @@ def perform_onedeploy_webapp(cmd, params.track_status = track_status params.enable_kudu_warmup = enable_kudu_warmup params.enriched_errors = enriched_errors + params.build_logs = build_logs # When a slot is targeted, fetch the slot's Site (not production) so the # cached model matches what every downstream consumer expects — slots have @@ -11136,6 +11364,7 @@ def __init__(self): self.is_linux_webapp = None self.is_functionapp = None self.enriched_errors = False + self.build_logs = 'summary' # Per-invocation caches. Populated during a single deploy and # cleared in _perform_onedeploy_internal's `finally` block. These MUST # NOT be logged, serialized, or accessed outside the current call @@ -11491,7 +11720,8 @@ def _warmup_kudu_and_get_cookie_internal(params): response = send_raw_request(params.cmd.cli_ctx, "GET", kudu_warmup_url) if response.status_code in (200, 201, 202): - logger.warning("Warmed up Kudu instance successfully.") + timestamp = _utc_timestamp() + logger.warning("%s Warmed up Kudu instance successfully.", timestamp) return cookies time_out = 300 except Exception as ex: # pylint: disable=broad-except @@ -11502,6 +11732,49 @@ def _warmup_kudu_and_get_cookie_internal(params): return None +def _display_build_logs_on_sync_failure(params, scm_url): + """For sync deployment failures, fetch build logs and return formatted error text. + + This handles the case where the Kudu POST returns an error (e.g., 400) after the build + completed on the server. Without this, the customer only sees 'Status Code: 400' with no + build output. + + Returns a formatted error string with logs included, or None if logs can't be fetched. + """ + import requests + from azure.cli.core.util import should_disable_connection_verify + from azure.cli.command_modules.appservice._build_log_formatter import format_build_failure_with_logs + + try: + headers = get_scm_site_headers(params.cmd.cli_ctx, params.webapp_name, + params.resource_group_name, params.slot) + + # Get the latest deployment ID + latest_url = scm_url + "/api/deployments/latest" + resp = requests.get(latest_url, headers=headers, + verify=not should_disable_connection_verify(), timeout=15) + if resp.status_code != 200: + return None + + deployment_info = resp.json() + deployment_id = deployment_info.get('id') + if not deployment_id: + return None + + # Fetch build logs + full_logs = _fetch_full_build_logs(params.cmd, params.resource_group_name, + params.webapp_name, params.slot, deployment_id) + if not full_logs: + return None + + # Format in the same style as async BuildFailed + error_text = "Deployment failed because the build process failed\n" + return format_build_failure_with_logs(error_text, full_logs) + + except Exception: # pylint: disable=broad-except + return None + + def _make_onedeploy_request(params): import requests from azure.cli.core.util import should_disable_connection_verify @@ -11522,7 +11795,8 @@ def _make_onedeploy_request(params): # if linux webapp and not function app, then warmup kudu and use warmed up kudu for deployment if params.is_linux_webapp and not params.is_functionapp and params.enable_kudu_warmup: try: - logger.warning("Warming up Kudu before deployment.") + timestamp = _utc_timestamp() + logger.warning("%s Warming up Kudu before deployment.", timestamp) cookies = _warmup_kudu_and_get_cookie_internal(params) if cookies is None: logger.info("Failed to fetch affinity cookie for Kudu. " @@ -11544,7 +11818,8 @@ def _make_onedeploy_request(params): else: if params.is_linux_webapp and not params.is_functionapp and params.enable_kudu_warmup: try: - logger.warning("Warming up Kudu before deployment.") + timestamp = _utc_timestamp() + logger.warning("%s Warming up Kudu before deployment.", timestamp) cookies = _warmup_kudu_and_get_cookie_internal(params) if cookies is None: logger.info("Failed to fetch affinity cookie for Kudu. " @@ -11573,7 +11848,8 @@ def _make_onedeploy_request(params): deployment_status_url, params.is_async_deployment, params.timeout, - deploy_params=params) + deploy_params=params, + build_logs=params.build_logs) else: response_body = _check_zip_deployment_status( params.cmd, params.resource_group_name, @@ -11587,8 +11863,10 @@ def _make_onedeploy_request(params): if state: logger.warning("Deployment status is: \"%s\"", state) response_body = response.json().get("properties", {}) - logger.warning("Deployment has completed successfully") - logger.warning("You can visit your app at: %s", _get_visit_url(params)) + + from azure.cli.command_modules.appservice._build_log_formatter import format_final_url + app_url = _get_url(params.cmd, params.resource_group_name, params.webapp_name, params.slot) + logger.warning("%s", format_final_url(app_url).rstrip('\n')) return response_body # API not available yet! @@ -11614,6 +11892,12 @@ def _make_onedeploy_request(params): if response.status_code: scm_url = _get_or_fetch_scm_url(params) latest_deploymentinfo_url = scm_url + "/api/deployments/latest" + + # For sync deployment failures, fetch and display build logs in the error message + build_failure_text = _display_build_logs_on_sync_failure(params, scm_url) + if build_failure_text: + raise CLIError(build_failure_text) + if _should_enrich_errors and response.status_code >= 400: logger.error("Deployment failed. Visit %s to get more information about your deployment.", latest_deploymentinfo_url) @@ -11647,7 +11931,8 @@ def _perform_onedeploy_internal(params): _should_enrich_errors = params.enriched_errors and params.is_linux_webapp and not params.is_functionapp # Now make the OneDeploy API call - logger.warning("Initiating deployment") + timestamp = _utc_timestamp() + logger.warning("%s Initiating deployment", timestamp) try: try: response = _make_onedeploy_request(params) From ab1325f3f360aeaf27970b7d9055e759d30e8882 Mon Sep 17 00:00:00 2001 From: Priya Chintalapati Date: Fri, 26 Jun 2026 07:52:14 +0530 Subject: [PATCH 2/3] Stream build logs during deployment --- .../appservice/_build_log_formatter.py | 316 ++++++++-------- .../cli/command_modules/appservice/custom.py | 262 +++++++++---- .../tests/latest/test_build_log_formatter.py | 358 ++++++++++++++++++ 3 files changed, 705 insertions(+), 231 deletions(-) create mode 100644 src/azure-cli/azure/cli/command_modules/appservice/tests/latest/test_build_log_formatter.py diff --git a/src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py b/src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py index 147e329f97d..a78102c1484 100644 --- a/src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py +++ b/src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py @@ -6,17 +6,23 @@ """ Build log formatter for `az webapp deploy` / `az functionapp deploy`. -Provides intelligent log filtering that shows a clean summary by default, -with full verbosity available via --build-logs full. - -Log levels: - - PHASE: Major deployment phases (always shown) - - INFO: Important milestones (shown in summary + full) - - DETAIL: Individual package lines, SDK metadata (shown only in full) - - WARNING: Deprecation notices, pip warnings (aggregated in summary, shown in full) +Renders a clean, curated view of the Oryx build by default: deterministic milestones, +aggregated package counts and a warning tally are kept permanently on screen, while +ordinary build chatter is shown on a single self-overwriting status line (the current +line is replaced in place by the next -- like a progress line). Full verbatim output is +available via --build-logs full; --build-logs none hides build logs entirely. + +Classification (summary mode): + - PERSISTENT: stack/version detection, phase milestones, "Installed N packages" + - TRANSIENT: package downloads, oryx/SDK metadata, warnings, other chatter + (shown on the self-overwriting status line; warnings are also counted) + - OMITTED: blank lines """ import re +import shutil +import sys +import time # Log verbosity levels @@ -25,90 +31,12 @@ BUILD_LOGS_NONE = "none" # --- Patterns for classification --- - -# Oryx internal metadata lines (hidden in summary mode) -_ORYX_METADATA_PATTERNS = [ - re.compile(r'^\s*(Operation performed by Microsoft Oryx)'), - re.compile(r'^\s*(You can report issues at)'), - re.compile(r'^\s*(Oryx Version:)'), - re.compile(r'^\s*(Build Operation ID:)'), - re.compile(r'^\s*(Repository Commit\s*:)'), - re.compile(r'^\s*(OS Type\s*:)'), - re.compile(r'^\s*(Image Type\s*:)'), - re.compile(r'^\s*(Primary SDK Storage URL:)'), - re.compile(r'^\s*(Backup SDK Storage URL:)'), - re.compile(r'^\s*(ACR SDK Registry URL:)'), - re.compile(r'^\s*(SDK provider status:)'), - re.compile(r'^\s*(External ACR SDK provider)'), - re.compile(r'^\s*(External SDK provider)'), - re.compile(r'^\s*(Direct ACR SDK provider)'), - re.compile(r'^\s*(Blob SDK provider)'), - re.compile(r'^\s*(External ACR provider resolved)'), - re.compile(r'^\s*(Version resolved using)'), - re.compile(r'^\s*(Requesting SDK from ACR)'), - re.compile(r'^\s*(Successfully pulled SDK from ACR)'), - re.compile(r'^\s*(SDK for .* fetched via)'), - re.compile(r'^\s*(Requesting metadata for platform)'), - re.compile(r'^\s*(Not a vso image)'), - re.compile(r'^\s*(Creating directory for command manifest)'), - re.compile(r'^\s*(Removing existing manifest file)'), - re.compile(r'^\s*(Creating a manifest file)'), - re.compile(r'^\s*(Manifest file created)'), - re.compile(r'^\s*(Copying \.ostype)'), - re.compile(r'^\s*(Node Build Command Manifest)'), - # .NET first-run banner (noisy, not useful for deployment) - re.compile(r'^\s*(Welcome to \.NET)'), - re.compile(r'^\s*-{5,}$'), # separator lines like "---------------------" - re.compile(r'^\s*(SDK Version:)'), - re.compile(r'^\s*(Telemetry)$'), - re.compile(r'^\s*(The \.NET tools collect usage data)'), - re.compile(r'^\s*(Read more about \.NET CLI Tools telemetry)'), - re.compile(r'^\s*(Installed an ASP\.NET Core HTTPS)'), - re.compile(r'^\s*(To trust the certificate)'), - re.compile(r'^\s*(Learn about HTTPS)'), - re.compile(r'^\s*(Write your first app)'), - re.compile(r'^\s*(Find out what.s new)'), - re.compile(r'^\s*(Explore documentation)'), - re.compile(r'^\s*(Report issues and find source)'), - re.compile(r'^\s*(Use .dotnet --help.)'), - re.compile(r'^\s*={5,}$'), # separator lines like "===================" - # Kudu internal deployment metadata - re.compile(r'^\s*(PreDeployment:)'), - re.compile(r'^\s*(Repository path is)'), - re.compile(r'^\s*(Using standard output preparation)'), - re.compile(r'^\s*(Total time for destination directory preparation)'), - # Kudu build summary noise (0 errors/warnings not useful on success) - re.compile(r'^\s*(Found \d+ issue)'), - re.compile(r'^\s*(Build Summary)'), - re.compile(r'^\s*(Errors \(\d+\))'), - re.compile(r'^\s*(Warnings \(\d+\))'), - re.compile(r'^\s*(Parsing the build logs)'), - re.compile(r'^\s*(Preparing deployment for commit id)'), - # Kudu post-build noise - re.compile(r'^\s*(Updating submodules)'), - re.compile(r'^\s*(Triggering container recycle)'), - re.compile(r'^\s*(Generating summary of Oryx build)'), -] - -# Package download/cache lines (suppressed, counted instead) -_PACKAGE_LINE_PATTERNS = [ - re.compile(r'^\s*\[[\d:+]+\]\s*(Collecting|Using cached|Downloading|Using)'), - re.compile(r'^\s*\[[\d:+]+\]\s*(Successfully installed)'), - re.compile(r'^\s*(npm warn|npm notice)'), - re.compile(r'^\s*added \d+ packages'), - re.compile(r'^\s*-\s+(Locking|Installing|Downloading)\s+\S+'), # composer package ops - re.compile(r'^\s*\d+/\d+\s*\[[\s=>-]*\]\s*\d+%'), # composer progress bars (X/Y format) - re.compile(r'^\s*\d+\s*\[[->=<>\s]*\]'), # composer progress bars (single number format) - re.compile(r'^\s*Loading composer repositories'), - re.compile(r'^\s*(Updating dependencies|Lock file operations:)'), - re.compile(r'^\s*(Installing dependencies from lock file)'), - re.compile(r'^\s*(Writing lock file)'), - re.compile(r'^\s*Package operations:'), - re.compile(r'^\s*Generating autoload files'), - re.compile(r'^\s*\d+ package suggestions were added'), - re.compile(r'^\s*\d+ package you are using is looking for funding'), - re.compile(r'^\s*Use the `composer'), -] +# +# Design: we intentionally do NOT keep a denylist of "noise" lines. A line is shown +# *permanently* only if it matches a deterministic milestone (or is an aggregated +# package summary); every other non-blank line is treated as transient chatter shown on +# the self-overwriting status line (still fully available via --build-logs full). This +# avoids the brittle per-stack denylists that previously needed constant maintenance. # Patterns for counting packages _PIP_COLLECTING = re.compile(r'^\s*\[[\d:+]+\]\s*Collecting\s+(\S+)') @@ -182,97 +110,65 @@ class BuildLogFormatter: def __init__(self, verbosity=BUILD_LOGS_SUMMARY): self.verbosity = verbosity self._package_count = 0 - self._packages_collecting = False - self._packages_installing = False self._warning_count = 0 - self._suppressed_lines = [] # stored for auto-expand on failure - def format_log_line(self, line): - """Process a single log line and return formatted output or None to suppress. + def format_log_line(self, line): # pylint: disable=too-many-return-statements + """Classify a single log line for display. Returns: - str or None: The formatted line to display, or None if suppressed. + (text, is_persistent): ``text`` is the string to display; ``is_persistent`` + True means keep it permanently on screen (milestones, aggregated + summaries), False means it is transient build chatter shown on the + self-overwriting status line. + None: omit the line entirely (blank lines, or --build-logs none). """ if self.verbosity == BUILD_LOGS_FULL: - return line + return (line, True) if self.verbosity == BUILD_LOGS_NONE: - self._suppressed_lines.append(line) return None - # Summary mode: intelligent filtering + # Summary mode: milestones/aggregates are persistent; everything else (warnings, + # package chatter, oryx metadata, unknown lines) is transient. Blank lines drop. stripped = line.strip() if not stripped: return None - # Check if it's a warning line - aggregate it - if stripped.startswith('npm warn'): - self._warning_count += 1 - self._suppressed_lines.append(line) - return None - + # Warnings (incl. "npm warn ...") are counted, then shown transiently. for pattern in _WARNING_PATTERNS: if pattern.match(stripped): self._warning_count += 1 - self._suppressed_lines.append(line) - return None + return (line, False) - # Check if it's a package download/install line - count it + # pip "Collecting ": count for the install summary, then scroll transiently. if _PIP_COLLECTING.match(stripped): self._package_count += 1 - if not self._packages_collecting: - self._packages_collecting = True - self._suppressed_lines.append(line) - return None - self._suppressed_lines.append(line) - return None - - if _PIP_CACHED.match(stripped): - self._suppressed_lines.append(line) - return None + return (line, False) - if _PIP_INSTALLING.match(stripped): - self._packages_installing = True - self._suppressed_lines.append(line) - return None + if _PIP_CACHED.match(stripped) or _PIP_INSTALLING.match(stripped): + return (line, False) - # "Successfully installed ..." - emit summary instead + # "Successfully installed ..." -> aggregated persistent milestone. pip_installed_match = _PIP_INSTALLED.match(stripped) if pip_installed_match: pkg_list = pip_installed_match.group(1) count = len(pkg_list.split()) - self._suppressed_lines.append(line) result = self._emit_package_summary(count) - self._packages_collecting = False - self._packages_installing = False self._package_count = 0 - return result + return (result, True) - # npm "added N packages" + # npm "added N packages" -> aggregated persistent milestone. npm_match = _NPM_ADDED.match(stripped) if npm_match: count = int(npm_match.group(1)) - self._suppressed_lines.append(line) - return f" Installed {count} packages\n" - - # Check for Oryx metadata lines - suppress - for pattern in _ORYX_METADATA_PATTERNS: - if pattern.match(stripped): - self._suppressed_lines.append(line) - return None + return (f" Installed {count} packages\n", True) - # Check for other package-level detail lines - for pattern in _PACKAGE_LINE_PATTERNS: - if pattern.match(stripped): - self._suppressed_lines.append(line) - return None - - # Check if it's a milestone line - always show + # Deterministic milestones -> persistent. for pattern in _MILESTONE_PATTERNS: if pattern.match(stripped): - return line + return (line, True) - # Default: show lines that aren't matched by any suppression pattern - return line + # Everything else is build chatter -> transient rolling window. + return (line, False) def _emit_package_summary(self, installed_count): """Generate summary line for package installation.""" @@ -282,11 +178,125 @@ def _emit_package_summary(self, installed_count): def get_warning_summary(self): """Get aggregated warning summary. Call at end of build phase.""" if self._warning_count > 0: - return (f" [!] {self._warning_count} warning(s) " - f"(use --build-logs full to view)\n") + return f" [!] {self._warning_count} warning(s)\n" return None +class BuildLogRenderer: + """Render build logs as persistent milestones plus one self-overwriting status line. + + Milestones and phase headers are printed permanently (each on its own line). Ordinary + build chatter is shown on a single transient line that overwrites itself in place as new + chatter arrives -- like a progress/status line. Only a carriage return + clear-to-end-of- + line are used (no vertical cursor movement), so the display cannot desync even for very + long or very rapid output; each transient line is also truncated to the terminal width so + it never wraps. + + On a non-TTY -- or when interactive rendering is disabled (``--build-logs full``) -- there + is no overwriting: persistent and transient lines are all printed plainly so nothing is + lost. All output goes to a single stream (stdout by default); callers must route every + build-phase line through this renderer so no other writer corrupts the status line. + """ + + _DIM = "\x1b[90m" + _RESET = "\x1b[0m" + _CLEAR_LINE = "\r\x1b[2K" + _TRANSIENT_INDENT = " " # align the moving line under detail milestones + _PACE_SECONDS = 0.1 # small per-line delay so a batched reveal "streams" in (TTY only) + + def __init__(self, stream=None, interactive=None): + if interactive is None: + probe = stream if stream is not None else sys.stdout + try: + interactive = bool(probe.isatty()) + except Exception: # pylint: disable=broad-except + interactive = False + self._interactive = interactive + # On legacy Windows consoles colorama makes the ANSI escapes work; only needed + # when we own the real stdout (tests pass a StringIO and don't need it). + if self._interactive and stream is None: + try: + import colorama + if hasattr(colorama, 'just_fix_windows_console'): + colorama.just_fix_windows_console() + else: + colorama.init() + except Exception: # pylint: disable=broad-except + pass + self._stream = stream if stream is not None else sys.stdout + # True while a transient status line is on screen without a trailing newline. + self._active = False + + def _width(self): + try: + return shutil.get_terminal_size((100, 24)).columns + except Exception: # pylint: disable=broad-except + return 100 + + def _truncate(self, text): + # Collapse to a single physical row and clip to the terminal width so the status + # line never wraps (wrapping would leave stranded rows the clear cannot reach). + text = text.replace('\r', ' ').replace('\n', ' ').rstrip() + width = max(self._width() - 1, 20) + if len(text) > width: + text = text[:width - 1] + '\u2026' + return text + + def _clear_active(self): + if self._active: + self._stream.write(self._CLEAR_LINE) + self._active = False + + def emit_persistent(self, text): + """Print a line that stays on screen permanently (clears any active status line).""" + text = text.rstrip('\n') + self._clear_active() + self._stream.write(text + '\n') + self._stream.flush() + + def emit_transient(self, text): + """Show a chatter line on the single self-overwriting status line.""" + if not self._interactive: + line = text.rstrip('\n') + if line.strip(): + self._stream.write(line + '\n') + self._stream.flush() + return + line = self._truncate(self._TRANSIENT_INDENT + text) + if not line.strip(): + return + self._stream.write(self._CLEAR_LINE + self._DIM + line + self._RESET) + self._stream.flush() + self._active = True + + def finalize(self): + """Erase the active status line, leaving only the persistent lines.""" + self._clear_active() + self._stream.flush() + + def pace(self): + """Briefly pause between batched lines so a poll's worth of output streams in + one-by-one instead of appearing all at once. No-op unless interactive (so + --build-logs full, CI and piped output stay instant).""" + if self._interactive and self._PACE_SECONDS: + time.sleep(self._PACE_SECONDS) + + +def format_phase_header(label, width=50): + """Render a phase header with the label centered in a band of dashes. + + e.g. format_phase_header("Build Phase") -> + "------------------- Build Phase -------------------" + """ + label = " {} ".format(label.strip()) + if len(label) >= width: + return label.strip() + dashes = width - len(label) + left = dashes // 2 + right = dashes - left + return ("-" * left) + label + ("-" * right) + + def format_final_url(url): """Format the final app URL to stand out in terminal output.""" separator = "-" * 50 @@ -298,11 +308,11 @@ def format_final_url(url): ) -def format_build_failure_with_logs(error_text, suppressed_logs): - """On build failure, auto-expand suppressed logs for debugging.""" +def format_build_failure_with_logs(error_text, log_lines): + """On build failure, dump the full build logs for debugging, followed by the error.""" output = [] output.append("\n-- Build Failed -- Showing full build logs for debugging --\n\n") - for log_line in suppressed_logs: + for log_line in log_lines: output.append(log_line if log_line.endswith('\n') else log_line + '\n') output.append("\n-- End of build logs --\n\n") output.append(error_text) diff --git a/src/azure-cli/azure/cli/command_modules/appservice/custom.py b/src/azure-cli/azure/cli/command_modules/appservice/custom.py index 528ee4fe4de..a7b47a0cb07 100644 --- a/src/azure-cli/azure/cli/command_modules/appservice/custom.py +++ b/src/azure-cli/azure/cli/command_modules/appservice/custom.py @@ -9951,11 +9951,48 @@ def _parse_log_time(log_time_str): return None -def _fetch_kudu_log_entries(cmd, resource_group_name, webapp_name, slot, deployment_id): +def _fetch_log_detail_items(details_url, headers): + """Fetch and parse a deployment-log entry's details_url. + + Returns a list of (detail_msg, detail_time, detail_id) tuples, or an empty list on any + failure (network error, non-200, or unexpected payload shape). + """ + import requests + from azure.cli.core.util import should_disable_connection_verify + + detail_items = [] + try: + detail_response = requests.get(details_url, headers=headers, + verify=not should_disable_connection_verify(), + timeout=10) + if detail_response.status_code != 200: + return detail_items + detail_entries = detail_response.json() + if not isinstance(detail_entries, list): + return detail_items + for detail in detail_entries: + detail_msg = (detail.get('message') or '').rstrip() + if detail_msg: + detail_items.append((detail_msg, detail.get('log_time'), detail.get('id'))) + except Exception: # pylint: disable=broad-except + pass + return detail_items + + +def _fetch_kudu_log_entries(cmd, resource_group_name, webapp_name, slot, deployment_id, + details_complete_ids=None): """Fetch raw log entries from Kudu deployment log API. - Returns a list of (message, log_time, detail_entries) tuples, or None if fetching fails. - Each detail_entries is a list of (message, log_time) tuples from the details_url. + Returns a list of (message, log_time, entry_id, detail_items) tuples (empty if fetching + fails). Each detail_items is a list of (detail_msg, detail_time, detail_id) tuples fetched + from the entry's details_url. + + details_complete_ids (optional set): used to avoid the N+1 network pattern when this is + called repeatedly while streaming. Every parent entry except the last one has final details, + so once an entry is no longer the tail it is recorded here and its details_url is not + re-fetched on subsequent polls. The last (in-progress) entry's details keep growing, so it is + always re-fetched. Skipped entries return an empty detail_items list. Pass None (the default, + used by the failure-path full-log fetch) to always fetch every entry's details. """ import requests from azure.cli.core.util import should_disable_connection_verify @@ -9970,47 +10007,49 @@ def _fetch_kudu_log_entries(cmd, resource_group_name, webapp_name, slot, deploym timeout=15) if response.status_code != 200: - return None + return [] log_entries = response.json() if not isinstance(log_entries, list): - return None + return [] results = [] - for entry in log_entries: + total = len(log_entries) + for idx, entry in enumerate(log_entries): message = (entry.get('message') or '').rstrip() log_time = entry.get('log_time') entry_id = entry.get('id') or log_time or message details_url = entry.get('details_url') + is_last_entry = idx == total - 1 + + # Skip re-fetching details for entries whose details are already final. + # The last (in-progress) entry's details keep growing, so always re-fetch it. + skip_details = ( + details_complete_ids is not None and + not is_last_entry and + entry_id in details_complete_ids + ) detail_items = [] - if details_url: - try: - detail_response = requests.get(details_url, headers=headers, - verify=not should_disable_connection_verify(), - timeout=10) - if detail_response.status_code == 200: - detail_entries = detail_response.json() - if isinstance(detail_entries, list): - for detail in detail_entries: - detail_msg = (detail.get('message') or '').rstrip() - detail_time = detail.get('log_time') - detail_id = detail.get('id') - if detail_msg: - detail_items.append((detail_msg, detail_time, detail_id)) - except Exception: # pylint: disable=broad-except - pass + if details_url and not skip_details: + detail_items = _fetch_log_detail_items(details_url, headers) results.append((message, log_time, entry_id, detail_items)) - return results if results else None + # Once an entry is no longer the tail, its details are final; record it so future + # polls skip the redundant details_url fetch. + if details_complete_ids is not None and not is_last_entry and entry_id: + details_complete_ids.add(entry_id) + + return results except Exception: # pylint: disable=broad-except - return None + return [] def _display_build_logs(cmd, resource_group_name, webapp_name, slot, deployment_id, - log_formatter=None, seen_log_ids=None): + log_formatter=None, seen_log_ids=None, details_complete_ids=None, + renderer=None): """Fetch and display build logs from Kudu. Handles all log display scenarios: @@ -10018,29 +10057,53 @@ def _display_build_logs(cmd, resource_group_name, webapp_name, slot, deployment_ - Retrospective display after fast/sync builds complete - Deduplication via seen_log_ids across multiple calls - Passes through the formatter so summary/full/none modes are respected. + seen_log_ids dedupes already-displayed lines; details_complete_ids avoids re-fetching the + details_url of entries whose details are already final (see _fetch_kudu_log_entries). Both + persist across calls for the lifetime of a single deployment poll loop. + + Lines are routed through the formatter (summary/full/none modes) and the renderer + (persistent milestones vs the self-overwriting status line). """ if seen_log_ids is None: seen_log_ids = set() + if renderer is None: + from azure.cli.command_modules.appservice._build_log_formatter import BuildLogRenderer + renderer = BuildLogRenderer(interactive=False) - entries = _fetch_kudu_log_entries(cmd, resource_group_name, webapp_name, slot, deployment_id) + entries = _fetch_kudu_log_entries(cmd, resource_group_name, webapp_name, slot, deployment_id, + details_complete_ids=details_complete_ids) if not entries: return + # Reveal a batched poll one line at a time (renderer.pace() no-ops unless interactive). + # Persistent milestones are always paced (they are few and worth the reveal); high-volume + # transient chatter is capped so a large catch-up burst can't stall output for long, and + # can't exhaust the budget before the milestones that follow it. + paced_chatter = 0 + pace_limit = 40 + + def _pace(kind): + nonlocal paced_chatter + if kind == 'persistent': + renderer.pace() + elif kind == 'transient' and paced_chatter < pace_limit: + renderer.pace() + paced_chatter += 1 + for message, log_time, entry_key, detail_items in entries: if entry_key and entry_key in seen_log_ids: pass # Still check details for new sub-entries elif message: seen_log_ids.add(entry_key) ts = _parse_log_time(log_time) - _emit_build_log_line(message, log_formatter, timestamp=ts, indent=False) + _pace(_emit_build_log_line(message, log_formatter, renderer, timestamp=ts, indent=False)) for detail_msg, detail_time, detail_id in detail_items: detail_key = 'detail:' + str(detail_time or detail_id or detail_msg) if detail_key in seen_log_ids: continue seen_log_ids.add(detail_key) - _emit_build_log_line(detail_msg, log_formatter, timestamp=None, indent=True) + _pace(_emit_build_log_line(detail_msg, log_formatter, renderer, timestamp=None, indent=True)) def _fetch_full_build_logs(cmd, resource_group_name, webapp_name, slot, deployment_id): @@ -10065,37 +10128,75 @@ def _fetch_full_build_logs(cmd, resource_group_name, webapp_name, slot, deployme return lines if lines else None -def _emit_build_log_line(message, log_formatter, timestamp=None, indent=False): - """Emit a single build log line through the formatter. +def _emit_build_log_line(message, log_formatter, renderer, timestamp=None, indent=False): + """Classify a raw build log line and route it to the renderer. - If formatter is None or verbosity is 'full', prints directly. - Otherwise, the formatter decides whether to show, suppress, or aggregate. + Milestones / aggregated summaries are emitted as persistent lines (kept on screen); + all other build chatter is shown on the self-overwriting status line. When log_formatter + is None the line is shown verbatim as persistent output. - The formatter classifies based on the raw message text (without timestamp prefix) - to ensure patterns match regardless of how the line is formatted for display. - """ - if indent or not timestamp: - display_line = f" {message}\n" - else: - display_line = f"{timestamp} {message}\n" + Persistent lines use a consistent two-level hierarchy: + - top-level entries: "HH:MM:SS message" + - detail items: " message" (12-space indent) + - aggregated summaries already carry their own indentation. + Returns the kind of line emitted so callers can pace output: ``'persistent'`` for a + milestone/summary line, ``'transient'`` for build chatter on the status line, or None + if the line was omitted (blank line or --build-logs none). + """ if log_formatter is None: - logger.warning("%s", display_line.rstrip('\n')) - return + if indent or not timestamp: + renderer.emit_persistent(f" {message}") + else: + renderer.emit_persistent(f"{timestamp} {message}") + return 'persistent' # Pass message with indent prefix for classification (patterns expect leading whitespace) - classify_line = f" {message}\n" - formatted = log_formatter.format_log_line(classify_line) - if formatted is not None: - # Show the display_line (with timestamp) not the classify_line - logger.warning("%s", display_line.rstrip('\n')) + classified = log_formatter.format_log_line(f" {message}\n") + if classified is None: + return None + text, is_persistent = classified + rendered = text.rstrip('\n') + + if not is_persistent: + # Transient build chatter shown on the self-overwriting status line (raw message; + # the renderer truncates it to the terminal width). + renderer.emit_transient(message) + return 'transient' + + # Persistent: milestone or aggregated summary. + if rendered.strip() != message.strip(): + # Formatter transformed the line (e.g. aggregated "Installed N packages"); + # the returned text already carries its own indentation. + renderer.emit_persistent(rendered) + elif indent or not timestamp: + renderer.emit_persistent(f" {message}") + else: + renderer.emit_persistent(f"{timestamp} {message}") + return 'persistent' # pylint: disable=too-many-branches +def _format_deployment_status_error(deployment_properties): + """Extract a human-readable error line from a deployment-status payload's 'errors'. + + Returns "Error: \n" when a message is present, else "Extended ErrorCode: + \n", or "" when there are no errors. Shared by the RuntimeFailed/BuildFailed paths. + """ + errors = deployment_properties.get('errors') + if not errors: + return "" + error_message = errors[0].get('message') + if error_message is not None: + return "Error: {}\n".format(error_message) + return "Extended ErrorCode: {}\n".format(errors[0].get('extendedCode')) + + def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, deploymentstatusapi_url, deployment_id, timeout=None, deploy_params=None, build_logs='summary'): from azure.cli.command_modules.appservice._build_log_formatter import ( - BuildLogFormatter, format_build_failure_with_logs, BUILD_LOGS_SUMMARY + BuildLogFormatter, BuildLogRenderer, format_build_failure_with_logs, + format_phase_header, BUILD_LOGS_SUMMARY ) max_time_sec = int(timeout) if timeout else 1000 @@ -10104,12 +10205,19 @@ def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, deployment_status = None response_body = None seen_log_ids = set() + details_complete_ids = set() last_log_poll_time = 0 previous_status_text = None build_phase_start = None - # Initialize the log formatter based on verbosity - log_formatter = BuildLogFormatter(verbosity=build_logs or BUILD_LOGS_SUMMARY) + # Initialize the log formatter and renderer based on verbosity. The renderer keeps + # milestones/phase headers permanent and shows build chatter on a single self- + # overwriting status line on a TTY. For --build-logs full there is no overwriting + # (every line is printed verbatim); none hides build logs entirely. + verbosity = build_logs or BUILD_LOGS_SUMMARY + log_formatter = BuildLogFormatter(verbosity=verbosity) + # full -> plain line-by-line (no overwrite); otherwise auto-detect TTY (interactive=None). + renderer = BuildLogRenderer(interactive=False if verbosity == "full" else None) while time_elapsed < max_time_sec: try: @@ -10130,36 +10238,41 @@ def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, # Track build phase duration if deployment_status == "BuildInProgress": build_phase_start = time.time() - logger.warning("%s --- Build Phase ---------------------------------", timestamp) + renderer.emit_persistent(f"{timestamp} {format_phase_header('Build Phase')}") elif deployment_status == "BuildSuccessful": # Always fetch and display build logs on completion. # For async (fast builds), real-time streaming may have missed most logs. # For sync, build happened during POST so no logs were streamed at all. # Pass seen_log_ids to avoid duplicating lines already shown in real-time. if build_phase_start is None: - logger.warning("%s --- Build Phase ---------------------------------", timestamp) + renderer.emit_persistent(f"{timestamp} {format_phase_header('Build Phase')}") _display_build_logs(cmd, resource_group_name, webapp_name, - slot, deployment_id, log_formatter, seen_log_ids) + slot, deployment_id, log_formatter, seen_log_ids, + details_complete_ids, renderer) + # Build done: erase the transient chatter window before the summary. + renderer.finalize() warning_summary = log_formatter.get_warning_summary() if warning_summary: - logger.warning("%s", warning_summary.rstrip('\n')) + renderer.emit_persistent(warning_summary.rstrip('\n')) if build_phase_start is not None: elapsed = int(time.time() - build_phase_start) - logger.warning("%s --- Build Complete (%ds) -----------------------", timestamp, elapsed) + renderer.emit_persistent( + f"{timestamp} {format_phase_header(f'Build Complete ({elapsed}s)')}") else: - logger.warning("%s --- Build Complete --------------------------------", timestamp) + renderer.emit_persistent(f"{timestamp} {format_phase_header('Build Complete')}") elif deployment_status == "RuntimeStarting": - logger.warning("%s --- Site Startup --------------------------------", timestamp) + renderer.emit_persistent(f"{timestamp} {format_phase_header('Site Startup')}") elif deployment_status == "RuntimeSuccessful": - logger.warning("%s [OK] Site started successfully", timestamp) + renderer.emit_persistent(f"{timestamp} [OK] Site started successfully") else: - logger.warning("%s %s", timestamp, status) + renderer.emit_persistent(f"{timestamp} {status}") previous_status_text = status - # Stream Kudu logs during build (every 5 seconds) + # Stream Kudu logs during build (polled ~every 5s while the build is in progress) if deployment_status == "BuildInProgress" and time_elapsed - last_log_poll_time >= 5: _display_build_logs(cmd, resource_group_name, webapp_name, slot, - deployment_id, log_formatter, seen_log_ids) + deployment_id, log_formatter, seen_log_ids, + details_complete_ids, renderer) last_log_poll_time = time_elapsed if deployment_status == "RuntimeStarting": @@ -10169,6 +10282,7 @@ def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, if deployment_status == "RuntimeSuccessful": break if deployment_status == "RuntimeFailed": + renderer.finalize() error_text = "" total_num_instances = int(deployment_properties.get('numberOfInstancesInProgress')) + \ int(deployment_properties.get('numberOfInstancesSuccessful')) + \ @@ -10185,14 +10299,7 @@ def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, deployment_properties.get('numberOfInstancesInProgress'), deployment_properties.get('numberOfInstancesSuccessful'), deployment_properties.get('numberOfInstancesFailed')) - errors = deployment_properties.get('errors') - if errors is not None and len(errors) > 0: - error_extended_code = errors[0]['extendedCode'] - error_message = errors[0]['message'] - if error_message is not None: - error_text += "Error: {}\n".format(error_message) - else: - error_text += "Extended ErrorCode: {}\n".format(error_extended_code) + error_text += _format_deployment_status_error(deployment_properties) failure_logs = deployment_properties.get('failedInstancesLogs') if failure_logs is not None and len(failure_logs) > 0: failure_logs = failure_logs[0] @@ -10207,15 +10314,9 @@ def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, break raise CLIError(error_text) if deployment_status == "BuildFailed": + renderer.finalize() error_text = "Deployment failed because the build process failed\n" - errors = deployment_properties.get('errors') - if errors is not None and len(errors) > 0: - error_extended_code = errors[0]['extendedCode'] - error_message = errors[0]['message'] - if error_message is not None: - error_text += "Error: {}\n".format(error_message) - else: - error_text += "Extended ErrorCode: {}\n".format(error_extended_code) + error_text += _format_deployment_status_error(deployment_properties) deployment_logs = deployment_properties.get('failedInstancesLogs') if deployment_logs is None or len(deployment_logs) == 0: scm_url = _get_scm_url(cmd, resource_group_name, webapp_name, slot) @@ -10232,9 +10333,13 @@ def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, error_text += "Please check the build logs for more info: {}\n".format(deployment_logs) raise CLIError(error_text) - time.sleep(15) + # Poll more frequently while the build is streaming logs so output stays near real-time; + # fall back to a slower cadence for the longer runtime-startup phase. + poll_interval = 5 if deployment_status == "BuildInProgress" else 15 + time.sleep(poll_interval) if time_elapsed >= max_time_sec and deployment_status != "RuntimeSuccessful": + renderer.finalize() # Derive SCM URL from cache when available (avoids yet another GET /sites # in an error path that the customer never expected to hit). if deploy_params is not None: @@ -10265,6 +10370,7 @@ def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, error_text += ("\nTIP: Run '{}' " "to view container startup logs.").format(tip_cmd) raise CLIError(error_text) + renderer.finalize() return response_body diff --git a/src/azure-cli/azure/cli/command_modules/appservice/tests/latest/test_build_log_formatter.py b/src/azure-cli/azure/cli/command_modules/appservice/tests/latest/test_build_log_formatter.py new file mode 100644 index 00000000000..c7a5913c8ae --- /dev/null +++ b/src/azure-cli/azure/cli/command_modules/appservice/tests/latest/test_build_log_formatter.py @@ -0,0 +1,358 @@ +# -------------------------------------------------------------------------------------------- +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. See License.txt in the project root for license information. +# -------------------------------------------------------------------------------------------- + +""" +Unit tests for the build log streaming feature: + - _build_log_formatter.py (BuildLogFormatter verbosity/filtering, helpers) + - custom._fetch_kudu_log_entries streaming details-dedup carve-out +""" + +import io +import unittest +from unittest.mock import MagicMock, patch + +from azure.cli.command_modules.appservice._build_log_formatter import ( + BuildLogFormatter, + BuildLogRenderer, + BUILD_LOGS_FULL, + BUILD_LOGS_SUMMARY, + BUILD_LOGS_NONE, + format_final_url, + format_build_failure_with_logs, +) + + +def _text(result): + """Return the rendered text from a (text, persistent) classification.""" + return None if result is None else result[0] + + +def _is_persistent(result): + return result is not None and result[1] is True + + +def _is_transient(result): + return result is not None and result[1] is False + + +class TestBuildLogFormatterFullMode(unittest.TestCase): + def test_full_mode_passes_everything_through(self): + fmt = BuildLogFormatter(verbosity=BUILD_LOGS_FULL) + for line in [ + "Oryx Version: 0.2\n", + "npm warn deprecated something@1.0.0\n", + " Collecting flask\n", + "random build line\n", + "\n", + ]: + result = fmt.format_log_line(line) + self.assertEqual(_text(result), line) + self.assertTrue(_is_persistent(result), msg="full mode should be persistent") + + def test_full_mode_does_not_aggregate_warnings(self): + fmt = BuildLogFormatter(verbosity=BUILD_LOGS_FULL) + fmt.format_log_line("npm warn deprecated foo\n") + # Warnings are passed through, not counted, so there is no summary. + self.assertIsNone(fmt.get_warning_summary()) + + +class TestBuildLogFormatterNoneMode(unittest.TestCase): + def test_none_mode_suppresses_everything(self): + fmt = BuildLogFormatter(verbosity=BUILD_LOGS_NONE) + for line in ["anything\n", "Running pip install\n", "error: boom\n"]: + self.assertIsNone(fmt.format_log_line(line)) + + +class TestBuildLogFormatterSummaryMode(unittest.TestCase): + def setUp(self): + self.fmt = BuildLogFormatter(verbosity=BUILD_LOGS_SUMMARY) + + def test_blank_lines_suppressed(self): + self.assertIsNone(self.fmt.format_log_line(" \n")) + + def test_oryx_metadata_is_transient_not_persistent(self): + # No denylist: oryx/SDK chatter is transient (rolling window), not persistent. + for line in [ + "Oryx Version: 0.2.20\n", + "Build Operation ID: abc123\n", + "Operation performed by Microsoft Oryx\n", + "-----------------------------\n", + ]: + result = self.fmt.format_log_line(line) + self.assertTrue(_is_transient(result), + msg="expected transient for: {}".format(line)) + + def test_milestones_are_persistent(self): + for line in [ + "Running pip install\n", + "Detected following platforms:\n", + "Deployment successful\n", + ]: + result = self.fmt.format_log_line(line) + self.assertEqual(_text(result), line) + self.assertTrue(_is_persistent(result), msg="expected persistent for: {}".format(line)) + + def test_unknown_lines_are_transient(self): + line = "ModuleNotFoundError: No module named 'foo'\n" + result = self.fmt.format_log_line(line) + self.assertTrue(_is_transient(result)) + + def test_npm_warnings_counted_and_transient(self): + r1 = self.fmt.format_log_line("npm warn deprecated a@1\n") + r2 = self.fmt.format_log_line("npm warn deprecated b@2\n") + self.assertTrue(_is_transient(r1)) + self.assertTrue(_is_transient(r2)) + summary = self.fmt.get_warning_summary() + self.assertIsNotNone(summary) + self.assertIn("2 warning(s)", summary) + + def test_pip_notice_counted_and_transient(self): + result = self.fmt.format_log_line("[notice] A new release of pip\n") + self.assertTrue(_is_transient(result)) + self.assertIn("1 warning(s)", self.fmt.get_warning_summary()) + + def test_no_warning_summary_when_no_warnings(self): + self.fmt.format_log_line("Running pip install\n") + self.assertIsNone(self.fmt.get_warning_summary()) + + def test_pip_collecting_lines_are_transient(self): + self.assertTrue(_is_transient(self.fmt.format_log_line("[12:00:00+00:00] Collecting flask\n"))) + self.assertTrue(_is_transient(self.fmt.format_log_line("[12:00:01+00:00] Using cached flask.whl\n"))) + + def test_pip_successfully_installed_emits_aggregated_persistent_summary(self): + # Collecting lines are transient/counted, then the final line is aggregated persistent. + self.fmt.format_log_line("[12:00:00+00:00] Collecting flask\n") + self.fmt.format_log_line("[12:00:01+00:00] Collecting jinja2\n") + result = self.fmt.format_log_line( + "[12:00:05+00:00] Successfully installed flask-3.0 jinja2-3.1 click-8.1\n") + self.assertTrue(_is_persistent(result)) + self.assertIn("Installed 3 packages", _text(result)) + # The raw "Successfully installed ..." text must not be the returned value. + self.assertNotIn("Successfully installed flask-3.0", _text(result)) + + def test_npm_added_packages_aggregated_persistent(self): + result = self.fmt.format_log_line("added 145 packages in 12s\n") + self.assertTrue(_is_persistent(result)) + self.assertIn("Installed 145 packages", _text(result)) + + +class TestBuildLogRenderer(unittest.TestCase): + """The single self-overwriting status-line renderer.""" + + def _renderer(self): + buf = io.StringIO() + return buf, BuildLogRenderer(stream=buf, interactive=True) + + def test_non_interactive_writes_plain_lines(self): + buf = io.StringIO() + r = BuildLogRenderer(stream=buf, interactive=False) + r.emit_persistent("milestone") + r.emit_transient("chatter") + out = buf.getvalue() + self.assertIn("milestone\n", out) + # With no overwriting, transient lines are written plainly too (honest fallback). + self.assertIn("chatter\n", out) + + def test_transient_overwrites_in_place(self): + buf, r = self._renderer() + r.emit_transient("first") + r.emit_transient("second") + out = buf.getvalue() + # Both writes use carriage-return + clear-line and stay on one row (no '\n'). + self.assertIn("\r\x1b[2K", out) + self.assertIn("first", out) + self.assertIn("second", out) + self.assertNotIn("\n", out) + self.assertTrue(r._active) + + def test_persistent_clears_active_transient(self): + buf, r = self._renderer() + r.emit_transient("noise") + r.emit_persistent("MILESTONE") + out = buf.getvalue() + # The active status line is cleared, then the milestone is printed on its own row. + self.assertIn("MILESTONE\n", out) + self.assertFalse(r._active) + + def test_finalize_clears_active_line(self): + buf, r = self._renderer() + r.emit_transient("a") + self.assertTrue(r._active) + r.finalize() + self.assertFalse(r._active) + # A clear-line sequence is emitted so the transient text is wiped. + self.assertIn("\r\x1b[2K", buf.getvalue()) + + def test_empty_transient_ignored(self): + buf, r = self._renderer() + r.emit_transient(" ") + self.assertFalse(r._active) + + def test_long_transient_line_truncated_to_single_row(self): + # A line far longer than the terminal width must be clipped to a single physical + # row so it never wraps (a wrapped line cannot be fully cleared in place). + buf, r = self._renderer() + r.emit_transient("x" * 5000) + out = buf.getvalue() + self.assertNotIn("x" * 5000, out) # clipped well below the raw length + self.assertIn("\u2026", out) # ellipsis marker present + self.assertNotIn("\n", out) # stays on one row + + def test_non_tty_stream_auto_disables_interactive(self): + # A StringIO is not a TTY, so auto-detection must disable interactive rendering. + r = BuildLogRenderer(stream=io.StringIO()) + self.assertFalse(r._interactive) + + def test_pace_is_noop_when_not_interactive(self): + r = BuildLogRenderer(stream=io.StringIO(), interactive=False) + with patch("azure.cli.command_modules.appservice._build_log_formatter.time.sleep") as slept: + r.pace() + slept.assert_not_called() + + def test_pace_sleeps_when_interactive(self): + r = BuildLogRenderer(stream=io.StringIO(), interactive=True) + with patch("azure.cli.command_modules.appservice._build_log_formatter.time.sleep") as slept: + r.pace() + slept.assert_called_once() + + +class TestBuildLogFormatterHelpers(unittest.TestCase): + def test_format_final_url_contains_url(self): + out = format_final_url("https://myapp.azurewebsites.net") + self.assertIn("https://myapp.azurewebsites.net", out) + self.assertIn("Deployment complete!", out) + + def test_format_build_failure_with_logs_includes_logs_and_error(self): + out = format_build_failure_with_logs( + "Deployment failed because the build process failed\n", + ["line one\n", "line two"]) # second line intentionally lacks newline + self.assertIn("Build Failed", out) + self.assertIn("line one", out) + self.assertIn("line two", out) + self.assertIn("Deployment failed because the build process failed", out) + + def test_format_build_failure_with_empty_logs(self): + out = format_build_failure_with_logs("err\n", []) + self.assertIn("err", out) + + +class TestFetchKuduLogEntriesDedup(unittest.TestCase): + """Validate the streaming details-dedup carve-out in _fetch_kudu_log_entries. + + Completed (non-tail) entries must have their details fetched exactly once; the in-progress + tail entry must be re-fetched every poll; and no detail lines may be lost. + """ + + def _run_poll_sequence(self): + from azure.cli.command_modules.appservice import custom as m + + # Simulated server state across three polls. The deployment-log list grows, and the + # tail entry's details accumulate new lines each poll. + polls = [ + {"list": [{"id": "A", "log_time": "t0", "message": "A", "details_url": "d/A"}], + "details": {"d/A": [{"id": "a1", "log_time": "t0", "message": "a1"}]}}, + {"list": [{"id": "A", "log_time": "t0", "message": "A", "details_url": "d/A"}, + {"id": "B", "log_time": "t1", "message": "B", "details_url": "d/B"}], + "details": {"d/A": [{"id": "a1", "log_time": "t0", "message": "a1"}, + {"id": "a2", "log_time": "t0", "message": "a2"}], + "d/B": [{"id": "b1", "log_time": "t1", "message": "b1"}]}}, + {"list": [{"id": "A", "log_time": "t0", "message": "A", "details_url": "d/A"}, + {"id": "B", "log_time": "t1", "message": "B", "details_url": "d/B"}, + {"id": "C", "log_time": "t2", "message": "C", "details_url": "d/C"}], + "details": {"d/A": [{"id": "a1", "log_time": "t0", "message": "a1"}, + {"id": "a2", "log_time": "t0", "message": "a2"}], + "d/B": [{"id": "b1", "log_time": "t1", "message": "b1"}, + {"id": "b2", "log_time": "t1", "message": "b2"}], + "d/C": [{"id": "c1", "log_time": "t2", "message": "c1"}]}}, + ] + state = {"poll": 0} + detail_calls = [] + + class FakeResp: + def __init__(self, data): + self._d = data + self.status_code = 200 + + def json(self): + return self._d + + def fake_get(url, **kwargs): + cur = polls[state["poll"]] + if url.endswith("/log"): + return FakeResp(cur["list"]) + detail_calls.append((state["poll"], url)) + return FakeResp(cur["details"][url]) + + seen_details = [] + details_complete_ids = set() + with patch("requests.get", side_effect=fake_get), \ + patch.object(m, "get_scm_site_headers", return_value={}), \ + patch.object(m, "_get_scm_url", return_value="https://scm"), \ + patch.object(m, "should_disable_connection_verify", return_value=True, create=True): + for p in range(3): + state["poll"] = p + entries = m._fetch_kudu_log_entries( + MagicMock(), "rg", "app", None, "depid", + details_complete_ids=details_complete_ids) + for _msg, _lt, _eid, ditems in entries: + for dmsg, _dt, did in ditems: + seen_details.append(did) + return detail_calls, seen_details + + def test_completed_entries_fetched_once_tail_always(self): + detail_calls, _ = self._run_poll_sequence() + # A is the tail at poll 0 (fetched), becomes final at poll 1 (fetched once more), then + # must be skipped at poll 2. + self.assertEqual(detail_calls.count((0, "d/A")), 1) + self.assertEqual(detail_calls.count((1, "d/A")), 1) + self.assertEqual(detail_calls.count((2, "d/A")), 0) + # B becomes final at poll 2. + self.assertEqual(detail_calls.count((1, "d/B")), 1) + self.assertEqual(detail_calls.count((2, "d/B")), 1) + # C is the tail at poll 2. + self.assertEqual(detail_calls.count((2, "d/C")), 1) + + def test_no_detail_lines_lost(self): + _, seen_details = self._run_poll_sequence() + for did in ("a1", "a2", "b1", "b2", "c1"): + self.assertIn(did, seen_details) + + def test_default_fetches_all_details_every_call(self): + # Without details_complete_ids (failure-path full fetch), every entry is fetched. + from azure.cli.command_modules.appservice import custom as m + + entries_list = [{"id": "A", "log_time": "t0", "message": "A", "details_url": "d/A"}, + {"id": "B", "log_time": "t1", "message": "B", "details_url": "d/B"}] + details = {"d/A": [{"id": "a1", "log_time": "t0", "message": "a1"}], + "d/B": [{"id": "b1", "log_time": "t1", "message": "b1"}]} + detail_calls = [] + + class FakeResp: + def __init__(self, data): + self._d = data + self.status_code = 200 + + def json(self): + return self._d + + def fake_get(url, **kwargs): + if url.endswith("/log"): + return FakeResp(entries_list) + detail_calls.append(url) + return FakeResp(details[url]) + + with patch("requests.get", side_effect=fake_get), \ + patch.object(m, "get_scm_site_headers", return_value={}), \ + patch.object(m, "_get_scm_url", return_value="https://scm"), \ + patch.object(m, "should_disable_connection_verify", return_value=True, create=True): + for _ in range(2): + m._fetch_kudu_log_entries(MagicMock(), "rg", "app", None, "depid") + # Both polls fetch both entries' details (no dedup when set not provided). + self.assertEqual(detail_calls.count("d/A"), 2) + self.assertEqual(detail_calls.count("d/B"), 2) + + +if __name__ == "__main__": + unittest.main() From d01c6515c9af0ba3f848f3886a42e1a8606c95b0 Mon Sep 17 00:00:00 2001 From: Priya Chintalapati Date: Fri, 26 Jun 2026 19:54:52 +0530 Subject: [PATCH 3/3] Print build logs for only async deployments --- .../appservice/_build_log_formatter.py | 53 ++----- .../cli/command_modules/appservice/custom.py | 131 +++--------------- 2 files changed, 32 insertions(+), 152 deletions(-) diff --git a/src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py b/src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py index a78102c1484..e4d60fd48e8 100644 --- a/src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py +++ b/src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py @@ -6,17 +6,9 @@ """ Build log formatter for `az webapp deploy` / `az functionapp deploy`. -Renders a clean, curated view of the Oryx build by default: deterministic milestones, -aggregated package counts and a warning tally are kept permanently on screen, while -ordinary build chatter is shown on a single self-overwriting status line (the current -line is replaced in place by the next -- like a progress line). Full verbatim output is -available via --build-logs full; --build-logs none hides build logs entirely. - -Classification (summary mode): - - PERSISTENT: stack/version detection, phase milestones, "Installed N packages" - - TRANSIENT: package downloads, oryx/SDK metadata, warnings, other chatter - (shown on the self-overwriting status line; warnings are also counted) - - OMITTED: blank lines +Renders a curated view of the Oryx build by default: milestones, aggregated package counts and +a warning tally stay on screen, while ordinary chatter is shown on a single self-overwriting +status line. --build-logs full shows verbatim output; --build-logs none hides build logs. """ import re @@ -30,13 +22,8 @@ BUILD_LOGS_SUMMARY = "summary" BUILD_LOGS_NONE = "none" -# --- Patterns for classification --- -# -# Design: we intentionally do NOT keep a denylist of "noise" lines. A line is shown -# *permanently* only if it matches a deterministic milestone (or is an aggregated -# package summary); every other non-blank line is treated as transient chatter shown on -# the self-overwriting status line (still fully available via --build-logs full). This -# avoids the brittle per-stack denylists that previously needed constant maintenance. +# Design: no denylist of "noise". A line is kept permanently only if it matches a milestone +# (or is an aggregated summary); every other non-blank line is transient chatter. # Patterns for counting packages _PIP_COLLECTING = re.compile(r'^\s*\[[\d:+]+\]\s*Collecting\s+(\S+)') @@ -113,14 +100,10 @@ def __init__(self, verbosity=BUILD_LOGS_SUMMARY): self._warning_count = 0 def format_log_line(self, line): # pylint: disable=too-many-return-statements - """Classify a single log line for display. - - Returns: - (text, is_persistent): ``text`` is the string to display; ``is_persistent`` - True means keep it permanently on screen (milestones, aggregated - summaries), False means it is transient build chatter shown on the - self-overwriting status line. - None: omit the line entirely (blank lines, or --build-logs none). + """Classify a log line: returns (text, is_persistent), or None to omit. + + is_persistent True keeps it on screen (milestones/summaries); False shows it on the + transient status line. None omits blank lines or --build-logs none. """ if self.verbosity == BUILD_LOGS_FULL: return (line, True) @@ -185,17 +168,9 @@ def get_warning_summary(self): class BuildLogRenderer: """Render build logs as persistent milestones plus one self-overwriting status line. - Milestones and phase headers are printed permanently (each on its own line). Ordinary - build chatter is shown on a single transient line that overwrites itself in place as new - chatter arrives -- like a progress/status line. Only a carriage return + clear-to-end-of- - line are used (no vertical cursor movement), so the display cannot desync even for very - long or very rapid output; each transient line is also truncated to the terminal width so - it never wraps. - - On a non-TTY -- or when interactive rendering is disabled (``--build-logs full``) -- there - is no overwriting: persistent and transient lines are all printed plainly so nothing is - lost. All output goes to a single stream (stdout by default); callers must route every - build-phase line through this renderer so no other writer corrupts the status line. + Chatter overwrites itself in place via carriage-return + clear-to-EOL (no vertical cursor + moves), truncated to terminal width so it never wraps. On a non-TTY or --build-logs full, + lines are printed plainly with no overwriting. All output goes through one stream. """ _DIM = "\x1b[90m" @@ -275,9 +250,7 @@ def finalize(self): self._stream.flush() def pace(self): - """Briefly pause between batched lines so a poll's worth of output streams in - one-by-one instead of appearing all at once. No-op unless interactive (so - --build-logs full, CI and piped output stay instant).""" + """Briefly pause between batched lines so a poll streams in one-by-one. No-op unless interactive.""" if self._interactive and self._PACE_SECONDS: time.sleep(self._PACE_SECONDS) diff --git a/src/azure-cli/azure/cli/command_modules/appservice/custom.py b/src/azure-cli/azure/cli/command_modules/appservice/custom.py index a7b47a0cb07..cab03a8b878 100644 --- a/src/azure-cli/azure/cli/command_modules/appservice/custom.py +++ b/src/azure-cli/azure/cli/command_modules/appservice/custom.py @@ -9952,11 +9952,7 @@ def _parse_log_time(log_time_str): def _fetch_log_detail_items(details_url, headers): - """Fetch and parse a deployment-log entry's details_url. - - Returns a list of (detail_msg, detail_time, detail_id) tuples, or an empty list on any - failure (network error, non-200, or unexpected payload shape). - """ + """Fetch a log entry's details_url as (detail_msg, detail_time, detail_id) tuples; [] on failure.""" import requests from azure.cli.core.util import should_disable_connection_verify @@ -9981,18 +9977,10 @@ def _fetch_log_detail_items(details_url, headers): def _fetch_kudu_log_entries(cmd, resource_group_name, webapp_name, slot, deployment_id, details_complete_ids=None): - """Fetch raw log entries from Kudu deployment log API. - - Returns a list of (message, log_time, entry_id, detail_items) tuples (empty if fetching - fails). Each detail_items is a list of (detail_msg, detail_time, detail_id) tuples fetched - from the entry's details_url. - - details_complete_ids (optional set): used to avoid the N+1 network pattern when this is - called repeatedly while streaming. Every parent entry except the last one has final details, - so once an entry is no longer the tail it is recorded here and its details_url is not - re-fetched on subsequent polls. The last (in-progress) entry's details keep growing, so it is - always re-fetched. Skipped entries return an empty detail_items list. Pass None (the default, - used by the failure-path full-log fetch) to always fetch every entry's details. + """Fetch Kudu deployment log entries as (message, log_time, entry_id, detail_items) tuples. + + details_complete_ids (optional set) avoids the N+1 fetch while streaming: non-tail entries + have final details and are skipped on later polls. Pass None to fetch every entry's details. """ import requests from azure.cli.core.util import should_disable_connection_verify @@ -10022,8 +10010,7 @@ def _fetch_kudu_log_entries(cmd, resource_group_name, webapp_name, slot, deploym details_url = entry.get('details_url') is_last_entry = idx == total - 1 - # Skip re-fetching details for entries whose details are already final. - # The last (in-progress) entry's details keep growing, so always re-fetch it. + # Skip details already finalized; the in-progress tail entry is always re-fetched. skip_details = ( details_complete_ids is not None and not is_last_entry and @@ -10036,8 +10023,7 @@ def _fetch_kudu_log_entries(cmd, resource_group_name, webapp_name, slot, deploym results.append((message, log_time, entry_id, detail_items)) - # Once an entry is no longer the tail, its details are final; record it so future - # polls skip the redundant details_url fetch. + # Non-tail entries are final; record so later polls skip their details_url fetch. if details_complete_ids is not None and not is_last_entry and entry_id: details_complete_ids.add(entry_id) @@ -10050,19 +10036,10 @@ def _fetch_kudu_log_entries(cmd, resource_group_name, webapp_name, slot, deploym def _display_build_logs(cmd, resource_group_name, webapp_name, slot, deployment_id, log_formatter=None, seen_log_ids=None, details_complete_ids=None, renderer=None): - """Fetch and display build logs from Kudu. - - Handles all log display scenarios: - - Real-time streaming during BuildInProgress (called every 5s) - - Retrospective display after fast/sync builds complete - - Deduplication via seen_log_ids across multiple calls + """Fetch and display Kudu build logs, deduping across calls. - seen_log_ids dedupes already-displayed lines; details_complete_ids avoids re-fetching the - details_url of entries whose details are already final (see _fetch_kudu_log_entries). Both - persist across calls for the lifetime of a single deployment poll loop. - - Lines are routed through the formatter (summary/full/none modes) and the renderer - (persistent milestones vs the self-overwriting status line). + seen_log_ids skips already-shown lines; details_complete_ids skips finalized details_urls. + Lines route through the formatter (summary/full/none) and renderer (milestones vs status line). """ if seen_log_ids is None: seen_log_ids = set() @@ -10075,10 +10052,8 @@ def _display_build_logs(cmd, resource_group_name, webapp_name, slot, deployment_ if not entries: return - # Reveal a batched poll one line at a time (renderer.pace() no-ops unless interactive). - # Persistent milestones are always paced (they are few and worth the reveal); high-volume - # transient chatter is capped so a large catch-up burst can't stall output for long, and - # can't exhaust the budget before the milestones that follow it. + # Reveal a batched poll one line at a time: always pace milestones, cap transient chatter so + # a large catch-up burst can't stall output (pace() no-ops unless interactive). paced_chatter = 0 pace_limit = 40 @@ -10129,20 +10104,10 @@ def _fetch_full_build_logs(cmd, resource_group_name, webapp_name, slot, deployme def _emit_build_log_line(message, log_formatter, renderer, timestamp=None, indent=False): - """Classify a raw build log line and route it to the renderer. - - Milestones / aggregated summaries are emitted as persistent lines (kept on screen); - all other build chatter is shown on the self-overwriting status line. When log_formatter - is None the line is shown verbatim as persistent output. - - Persistent lines use a consistent two-level hierarchy: - - top-level entries: "HH:MM:SS message" - - detail items: " message" (12-space indent) - - aggregated summaries already carry their own indentation. + """Classify a build log line and route it to the renderer. - Returns the kind of line emitted so callers can pace output: ``'persistent'`` for a - milestone/summary line, ``'transient'`` for build chatter on the status line, or None - if the line was omitted (blank line or --build-logs none). + Milestones/summaries are persistent (kept on screen); other chatter goes to the + self-overwriting status line. Returns 'persistent', 'transient', or None (omitted). """ if log_formatter is None: if indent or not timestamp: @@ -10178,11 +10143,7 @@ def _emit_build_log_line(message, log_formatter, renderer, timestamp=None, inden # pylint: disable=too-many-branches def _format_deployment_status_error(deployment_properties): - """Extract a human-readable error line from a deployment-status payload's 'errors'. - - Returns "Error: \n" when a message is present, else "Extended ErrorCode: - \n", or "" when there are no errors. Shared by the RuntimeFailed/BuildFailed paths. - """ + """Extract an error line from a deployment-status payload's 'errors' ("" when none).""" errors = deployment_properties.get('errors') if not errors: return "" @@ -10210,13 +10171,9 @@ def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, previous_status_text = None build_phase_start = None - # Initialize the log formatter and renderer based on verbosity. The renderer keeps - # milestones/phase headers permanent and shows build chatter on a single self- - # overwriting status line on a TTY. For --build-logs full there is no overwriting - # (every line is printed verbatim); none hides build logs entirely. + # full -> verbatim lines; summary -> milestones + self-overwriting status line; none -> hidden. verbosity = build_logs or BUILD_LOGS_SUMMARY log_formatter = BuildLogFormatter(verbosity=verbosity) - # full -> plain line-by-line (no overwrite); otherwise auto-detect TTY (interactive=None). renderer = BuildLogRenderer(interactive=False if verbosity == "full" else None) while time_elapsed < max_time_sec: @@ -10240,10 +10197,8 @@ def _poll_deployment_runtime_status(cmd, resource_group_name, webapp_name, slot, build_phase_start = time.time() renderer.emit_persistent(f"{timestamp} {format_phase_header('Build Phase')}") elif deployment_status == "BuildSuccessful": - # Always fetch and display build logs on completion. - # For async (fast builds), real-time streaming may have missed most logs. - # For sync, build happened during POST so no logs were streamed at all. - # Pass seen_log_ids to avoid duplicating lines already shown in real-time. + # Fetch the full set on completion; fast builds may finish between polls + # so real-time streaming can miss lines. seen_log_ids prevents duplicates. if build_phase_start is None: renderer.emit_persistent(f"{timestamp} {format_phase_header('Build Phase')}") _display_build_logs(cmd, resource_group_name, webapp_name, @@ -11838,49 +11793,6 @@ def _warmup_kudu_and_get_cookie_internal(params): return None -def _display_build_logs_on_sync_failure(params, scm_url): - """For sync deployment failures, fetch build logs and return formatted error text. - - This handles the case where the Kudu POST returns an error (e.g., 400) after the build - completed on the server. Without this, the customer only sees 'Status Code: 400' with no - build output. - - Returns a formatted error string with logs included, or None if logs can't be fetched. - """ - import requests - from azure.cli.core.util import should_disable_connection_verify - from azure.cli.command_modules.appservice._build_log_formatter import format_build_failure_with_logs - - try: - headers = get_scm_site_headers(params.cmd.cli_ctx, params.webapp_name, - params.resource_group_name, params.slot) - - # Get the latest deployment ID - latest_url = scm_url + "/api/deployments/latest" - resp = requests.get(latest_url, headers=headers, - verify=not should_disable_connection_verify(), timeout=15) - if resp.status_code != 200: - return None - - deployment_info = resp.json() - deployment_id = deployment_info.get('id') - if not deployment_id: - return None - - # Fetch build logs - full_logs = _fetch_full_build_logs(params.cmd, params.resource_group_name, - params.webapp_name, params.slot, deployment_id) - if not full_logs: - return None - - # Format in the same style as async BuildFailed - error_text = "Deployment failed because the build process failed\n" - return format_build_failure_with_logs(error_text, full_logs) - - except Exception: # pylint: disable=broad-except - return None - - def _make_onedeploy_request(params): import requests from azure.cli.core.util import should_disable_connection_verify @@ -11999,11 +11911,6 @@ def _make_onedeploy_request(params): scm_url = _get_or_fetch_scm_url(params) latest_deploymentinfo_url = scm_url + "/api/deployments/latest" - # For sync deployment failures, fetch and display build logs in the error message - build_failure_text = _display_build_logs_on_sync_failure(params, scm_url) - if build_failure_text: - raise CLIError(build_failure_text) - if _should_enrich_errors and response.status_code >= 400: logger.error("Deployment failed. Visit %s to get more information about your deployment.", latest_deploymentinfo_url)