Skip to content

Latest commit

 

History

History
287 lines (219 loc) · 16.1 KB

diagnose-experience.md

File metadata and controls

287 lines (219 loc) · 16.1 KB
Raw

Improve ORAS diagnose experience

Note

The version of this specification is v1.3.0 Beta.1. It is subject to change until ORAS v1.3.0 is released.

ORAS v1.2.0 offers two global options, --verbose and --debug, which enable users to generate verbose output and logs respectively. These features facilitate both users and developers in inspecting ORAS's performance, interactions with external services and internal systems, and in diagnosing issues by providing a clear picture of the tool's operations.

Given the diverse roles and scenarios in which ORAS CLI is utilized, we have received feedback from users and developers to improve the diagnostic experience. Enhancing debug logs can significantly benefit ORAS users and developers by making diagnostics clearer and more unambiguous.

This proposal document aims to:

  1. Identify the issues associated with the current implementation of the --verbose and --debug options.
  2. Clarify the concepts of different types of output and logs for diagnostic purposes.
  3. List the guiding principles to write comprehensive, clear, and conducive debug output and debug logs for effective diagnosis.
  4. Propose solutions to improve the diagnostic experience for ORAS CLI users and developers.

Problem Statement

Specifically, there are existing GitHub issues raised in the ORAS community.

  • The user is confused about when to use --verbose and --debug. See the relevant issue #1382.
  • Poor readability of debug logs. No separator lines between request and response information. Users need to add separator lines manually for readability. See the relevant issue #1382.
  • Critical information is missing in debug logs. For example, the error code and metadata of the processed resource object (e.g. image manifest) are not displayed.
  • The detailed operation information is missing in verbose output. For example, how many and where are objects processed. Less or no verbose output of ORAS commands in some use cases.
  • The user environment information is not printed out. This causes a higher cost to reproduce the issues for ORAS developers locally.
  • Timestamp of each request and response is missing in debug logs, which is hard to trace historical operation and trace the sequence of events accurately.

Concepts

At first, the output of ORAS flag --verbose and --debug should be clarified before restructuring them.

Output

There are four types of output in ORAS CLI:

  • Status output: such as progress information, progress bar in pulling or pushing files.
  • Metadata output: showing what has been pulled (e.g. filename, digest, etc.) in specified format, such as JSON, text.
  • Content output: it is to output the raw data obtained from the remote registry server or file system, such as the pulled artifact content saved as a file.
  • Error output: error message are expected to be helpful to troubleshoot where the user has done something wrong and the program is guiding them in the right direction.

The target users of these types of output are general users.

Currently, the output of ORAS --verbose flag only exists in oras pull/push/attach/discover commands, which prints out detailed status output and metadata output. Since ORAS v1.2.0, progress bar is enabled in pull/push/attach by default, thus the ORAS output is already verbose on a terminal.

The original output of ORAS --verbose is intended for end-users who want to observe the detailed file operation when using ORAS. It gives users a comprehensive view of what the tool is doing at every step and how long does it take when push or pull a file.

Logs

Logs focus on providing technical details for in-depth diagnosing and troubleshooting issues. It is intended for developers or technical users who need to understand the inner workings of the tool. Debug logs are detailed and technical, often including HTTP request and response from interactions between client and server, as well as code-specific information. In general, there are different levels of logs. Logrus has been used by ORAS, which has seven logging levels: Trace, Debug, Info, Warning, Error, Fatal and Panic, but only DEBUG level log is used in ORAS, which is controlled by the flag --debug.

  • Purpose: Debug logs are specifically aimed to facilitate ORAS developers to diagnose ORAS tool itself. They contain detailed technical information that is useful for troubleshooting problems.
  • Target users: Primarily intended for developers or technical users who are trying to understand the inner workings of the code and identify the root cause of a possible issue with the tool itself.
  • Content: Debug logs focus on providing context needed to troubleshoot issues, like variable values, execution paths, error stack traces, and internal states of the application.
  • Level of Detail: Extremely detailed, providing insights into the application's internal workings and logic, often including low-level details that are essential for debugging.

Common Conventions

Here are the common conventions to print clear and analyzable debug logs.

Timestamp Each Log Entry

  • Precise Timing: Ensure each log entry has a precise timestamp to trace the sequence of events accurately. ORAS SHOULD use the Nanoseconds precision to print the timestamp in the first field of each line.
    • Example: [2024-08-02 23:56:02.6738192Z] Starting metadata retrieval for repository oras-demo

Avoid Logging Sensitive Information

  • Privacy and Security: Abstain from logging sensitive information such as passwords, personal data, or authentication tokens.
    • Example: [2024-08-02 23:56:02.7338192Z] Attempting to authenticate user [UserID: usr123] (exclude authentication token and password information).

Proposals for ORAS CLI

Based on the concepts and conventions above, here are the proposal for ORAS diagnose experience improvement:

  • Deprecate the --verbose flag and keep --debug flag to avoid ambiguity. It is reasonable to continue using --debug to enable the output of DEBUG level logs as it is in ORAS. Meanwhile, this change will make the diagnose experience much more straightforward and less breaking since only ORAS pull/push/attach/discover commands have verbose output.
  • Make the verbose output of commands pull, push, attach as the default (status) output. See examples at the bottom.
  • Make the verbose output of command discover as a formatted output, controlled by --format tree-full.
  • Add two empty lines as the separator between each request and response for readability.
  • Add timestamp of each request and response to the beginning of each request and response.
  • Print out the response body in the debug logs if the Content-Type of the HTTP response body is JSON or plain text format. ORAS SHOULD limit the size of a response body for preventing clients from overloading the registry server with massive payloads that could lead to performance issues.
  • Upon a response with failures, the error code should be included in the response body by default for diagnose purposes.
  • Considering ORAS is not a daemon service so parsing debug logs to a logging system is not a common scenario. The target users of the debug logs are normal users and ORAS developers. Thereby, the debug logs in TTY mode and non-TTY (--no-tty) should be consistent, except for the color. Specifically, debug logs SHOULD be colored-code in a TTY mode for better readability on terminal but keeping plain text in a non-TTY mode.
  • Summarize common conventions for writing clear and analyzable debug logs.
  • Show running environment details of ORAS such as OS/Arch in the output of oras version. It would be helpful to help the ORAS developers locate and reproduce the issue easier.

Investigation on other CLI tools

To make sure the ORAS diagnose functions are natural and easier to use, it worth knowing how diagnose functions work in other popular client tools.

Curl

Curl only has a --verbose option to output verbose logs. No --debug option.

Docker and Podman

Docker provides two options --debug and --log-level to control debug logs output within different log levels, such as INFO, DEBUG, WARN, etc. No --verbose option. Docker has its own daemon service running in local so its logs might be much more complex.

Helm

Helm CLI tool provides a global flag --debug to enable verbose output.

Examples in ORAS

This section lists the current behaviors of ORAS debug logs, proposes the suggested changes to ORAS CLI commands.

oras copy

Take the first two requests and responses from its debug logs as examples:

oras copy ghcr.io/oras-project/oras:v1.2.0 --to-oci-layout oras-dev:v1.2.0 --debug

Current debug log in TTY mode

DEBU[0000] Request #0
> Request URL: "https://ghcr.io/v2/oras-project/oras/manifests/v1.2.0"
> Request method: "GET"
> Request headers:
   "User-Agent": "oras/1.2.0+Homebrew"
   "Accept": "application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, application/vnd.oci.artifact.manifest.v1+json" 
DEBU[0001] Response #0
< Response Status: "401 Unauthorized"
< Response headers:
   "Content-Length": "73"
   "X-Github-Request-Id": "9FC6:30019C:17C06:1C462:66AD0463"
   "Content-Type": "application/json"
   "Www-Authenticate": "Bearer realm=\"https://ghcr.io/token\",service=\"ghcr.io\",scope=\"repository:oras-project/oras:pull\""
   "Date": "Fri, 02 Aug 2024 16:08:04 GMT" 
DEBU[0001] Request #1
> Request URL: "https://ghcr.io/token?scope=repository%3Aoras-project%2Foras%3Apull&service=ghcr.io"
> Request method: "GET"
> Request headers:
   "User-Agent": "oras/1.2.0+Homebrew" 
DEBU[0002] Response #1
< Response Status: "200 OK"
< Response headers:
   "Content-Type": "application/json"
   "Docker-Distribution-Api-Version": "registry/2.0"
   "Date": "Fri, 02 Aug 2024 16:08:05 GMT"
   "Content-Length": "69"
   "X-Github-Request-Id": "9FC6:30019C:17C0D:1C46C:66AD0464"

Current debug log in non-TTY mode

time=2024-11-13T00:08:03-08:00 level=debug msg=Request #0
> Request URL: "https://ghcr.io/v2/oras-project/oras/manifests/v1.2.0"
> Request method: "GET"
> Request headers:
   "Accept": "application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, application/vnd.oci.artifact.manifest.v1+json"
   "User-Agent": "oras/1.2.0+Homebrew"
time=2024-11-13T00:08:04-08:00 level=debug msg=Response #0
< Response Status: "401 Unauthorized"
< Response headers:
   "Content-Type": "application/json"
   "Www-Authenticate": "Bearer realm=\"https://ghcr.io/token\",service=\"ghcr.io\",scope=\"repository:oras-project/oras:pull\""
   "Date": "Wed, 13 Nov 2024 08:08:04 GMT"
   "Content-Length": "73"
   "X-Github-Request-Id": "A976:6E843:5D1712B:5F3E769:67345E64"
time=2024-11-13T00:08:04-08:00 level=debug msg=Request #1
> Request URL: "https://ghcr.io/token?scope=repository%3Aoras-project%2Foras%3Apull&service=ghcr.io"
> Request method: "GET"
> Request headers:
   "User-Agent": "oras/1.2.0+Homebrew"
time=2024-11-13T00:08:04-08:00 level=debug msg=Response #1
< Response Status: "200 OK"
< Response headers:
   "X-Github-Request-Id": "A976:6E843:5D171B4:5F3E7EE:67345E64"
   "Content-Type": "application/json"
   "Docker-Distribution-Api-Version": "registry/2.0"
   "Date": "Wed, 13 Nov 2024 08:08:04 GMT"
   "Content-Length": "69"

Suggested debug logs in TTY and Non-TTY mode:

The debug logs in TTY mode and non-TTY (--no-tty) should be consistent, except for the color.

[2024-08-02 23:56:02.6738192Z] --> Request #0
> Request URL: "https://ghcr.io/v2/oras-project/oras/manifests/v1.2.0"
> Request method: "GET"
> Request headers:
   "User-Agent": "oras/1.2.0+Homebrew"
   "Accept": "application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, application/vnd.oci.artifact.manifest.v1+json" 


[2024-08-02 23:56:03.6738192Z] <-- Response #0
< Response Status: "401 Unauthorized"
< Response headers:
   "Content-Length": "73"
   "X-Github-Request-Id": "9FC6:30019C:17C06:1C462:66AD0463"
   "Content-Type": "application/json"
   "Www-Authenticate": "Bearer realm=\"https://ghcr.io/token\",service=\"ghcr.io\",scope=\"repository:oras-project/oras:pull\""
   "Date": "Fri, 02 Aug 2024 23:56:03 GMT"
< Response body:
{
        "errors": [
            {
                "code": "<UNAUTHORIZED>",
                "message": "<message describing condition>",
                "detail": "<unstructured>"
            },
            ...
        ]
}


[2024-08-02 23:56:04.6738192Z] --> Request #1
> Request URL: "https://ghcr.io/token?scope=repository%3Aoras-project%2Foras%3Apull&service=ghcr.io"
> Request method: "GET"
> Request headers:
   "User-Agent": "oras/1.2.0+Homebrew" 


[2024-08-02 23:56:04.6738192Z] <-- Response #1
< Response Status: "200 OK"
< Response headers:
   "Content-Type": "application/json"
   "Docker-Distribution-Api-Version": "registry/2.0"
   "Date": "Fri, 02 Aug 2024 16:08:05 GMT"
   "Content-Length": "69"
   "X-Github-Request-Id": "9FC6:30019C:17C0D:1C46C:66AD0464" 
<  Response body:
{
  "schemaVersion": 2,
  "mediaType": "application/vnd.oci.image.index.v1+json",
  "manifests": [
    {
      "mediaType": "application/vnd.oci.image.manifest.v1+json",
      "digest": "sha256:42c524c48e0672568dbd2842d3a0cb34a415347145ee9fe1c8abaf65e7455b46",
      "size": 1239,
      "platform": {
        "architecture": "amd64",
        "os": "linux"
      }
    },
    ···
}

oras push/pull/attach

The verbose output of commands pull, push, attach is now printed out in the default (status) output, the --verbose is no longer needed. Considering the progress bar is shown on terminal by default, the verbose output should be available on non-terminal environment using --no-tty. See oras pull command as an example:

$ oras push --oci-layout layout-test:sample README.md --no-tty

Preparing README.md
Uploading 9500d720111f README.md
Uploading 44136fa355b3 application/vnd.oci.empty.v1+json
Uploaded  44136fa355b3 application/vnd.oci.empty.v1+json
Uploaded  9500d720111f README.md
Uploading 655f5cc5d5d2 application/vnd.oci.image.manifest.v1+json
Uploaded  655f5cc5d5d2 application/vnd.oci.image.manifest.v1+json
Pushed [oci-layout] layout-test:sample
ArtifactType: application/vnd.unknown.artifact.v1
Digest: sha256:655f5cc5d5d2e7ff2ab90378514103996523b065ce5ef43cd6e6a4de7d80a535

Show user's environment details

Output the user's running environment details of ORAS such as operating system and architecture information would be helpful to help the ORAS developers locate the issue and reproduce easier.

For example, the operating system and architecture are supposed to be outputted in oras version:

$ oras version

ORAS Version:    1.2.0+Homebrew
Go version:      go1.22.3
OS/Arch:         linux/amd64
Git commit:      xxxxxxxxxxxx
Git tree state:  clean

Q & A

Q1: Is it a common practice to use an environment variable like export ORAS_DEBUG=1 as a global switch for debug logs? What are the Pros and Cons of using this design?

A: Per our discussion in the ORAS community meeting, ORAS maintainers agreed to not introduce an additional environment variable as a global switch to enable debug logs since --debug is intuitive enough.

Q2: For the diagnose flag options, why deprecate --verbose and remain --debug as it is?

A: The major reason is that this change avoids overloading the flag --verbose and reduce ambiguity in ORAS diagnose experience. Moreover, the --debug is consistent with other popular container client tools, such as Helm and Docker. Deprecation of --verbose is less breaking than changing behaviors of --debug.