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..e4d60fd48e8 --- /dev/null +++ b/src/azure-cli/azure/cli/command_modules/appservice/_build_log_formatter.py @@ -0,0 +1,292 @@ +# -------------------------------------------------------------------------------------------- +# 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`. + +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 +import shutil +import sys +import time + + +# Log verbosity levels +BUILD_LOGS_FULL = "full" +BUILD_LOGS_SUMMARY = "summary" +BUILD_LOGS_NONE = "none" + +# 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+)') +_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._warning_count = 0 + + def format_log_line(self, line): # pylint: disable=too-many-return-statements + """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) + if self.verbosity == BUILD_LOGS_NONE: + return None + + # 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 + + # Warnings (incl. "npm warn ...") are counted, then shown transiently. + for pattern in _WARNING_PATTERNS: + if pattern.match(stripped): + self._warning_count += 1 + return (line, False) + + # pip "Collecting ": count for the install summary, then scroll transiently. + if _PIP_COLLECTING.match(stripped): + self._package_count += 1 + return (line, False) + + if _PIP_CACHED.match(stripped) or _PIP_INSTALLING.match(stripped): + return (line, False) + + # "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()) + result = self._emit_package_summary(count) + self._package_count = 0 + return (result, True) + + # npm "added N packages" -> aggregated persistent milestone. + npm_match = _NPM_ADDED.match(stripped) + if npm_match: + count = int(npm_match.group(1)) + return (f" Installed {count} packages\n", True) + + # Deterministic milestones -> persistent. + for pattern in _MILESTONE_PATTERNS: + if pattern.match(stripped): + return (line, True) + + # Everything else is build chatter -> transient rolling window. + return (line, False) + + 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)\n" + return None + + +class BuildLogRenderer: + """Render build logs as persistent milestones plus one self-overwriting 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" + _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 streams in one-by-one. No-op unless interactive.""" + 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 + 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, 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 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) + 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..cab03a8b878 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,262 @@ 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_log_detail_items(details_url, headers): + """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 + + 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 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 + + 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 [] + + log_entries = response.json() + if not isinstance(log_entries, list): + return [] + + results = [] + 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 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 + entry_id in details_complete_ids + ) + + detail_items = [] + 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)) + + # 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) + + return results + + except Exception: # pylint: disable=broad-except + return [] + + +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 Kudu build logs, deduping across calls. + + 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() + 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, + details_complete_ids=details_complete_ids) + if not entries: + return + + # 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 + + 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) + _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) + _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): + """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, renderer, timestamp=None, indent=False): + """Classify a build log line and route it to the renderer. + + 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: + 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) + 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 an error line from a deployment-status payload's 'errors' ("" when none).""" + 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): + deployment_id, timeout=None, deploy_params=None, build_logs='summary'): + from azure.cli.command_modules.appservice._build_log_formatter import ( + BuildLogFormatter, BuildLogRenderer, format_build_failure_with_logs, + format_phase_header, 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() + details_complete_ids = set() + last_log_poll_time = 0 + previous_status_text = None + build_phase_start = None + + # full -> verbatim lines; summary -> milestones + self-overwriting status line; none -> hidden. + verbosity = build_logs or BUILD_LOGS_SUMMARY + log_formatter = BuildLogFormatter(verbosity=verbosity) + renderer = BuildLogRenderer(interactive=False if verbosity == "full" else None) + 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 +10187,49 @@ 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() + renderer.emit_persistent(f"{timestamp} {format_phase_header('Build Phase')}") + elif deployment_status == "BuildSuccessful": + # 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, + 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: + renderer.emit_persistent(warning_summary.rstrip('\n')) + if build_phase_start is not None: + elapsed = int(time.time() - build_phase_start) + renderer.emit_persistent( + f"{timestamp} {format_phase_header(f'Build Complete ({elapsed}s)')}") + else: + renderer.emit_persistent(f"{timestamp} {format_phase_header('Build Complete')}") + elif deployment_status == "RuntimeStarting": + renderer.emit_persistent(f"{timestamp} {format_phase_header('Site Startup')}") + elif deployment_status == "RuntimeSuccessful": + renderer.emit_persistent(f"{timestamp} [OK] Site started successfully") + else: + renderer.emit_persistent(f"{timestamp} {status}") + previous_status_text = status + + # 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, + details_complete_ids, renderer) + last_log_poll_time = time_elapsed + if deployment_status == "RuntimeStarting": logger.info("InprogressInstances: %s, SuccessfulInstances: %s", deployment_properties.get('numberOfInstancesInProgress'), @@ -9951,6 +10237,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')) + \ @@ -9967,14 +10254,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] @@ -9989,26 +10269,32 @@ 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) 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) + # 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: @@ -10039,6 +10325,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 @@ -11074,7 +11361,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 +11381,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 +11425,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 +11781,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 @@ -11522,7 +11813,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 +11836,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 +11866,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 +11881,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 +11910,7 @@ 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" + 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 +11944,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) 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()