docs: Improve ORAS diagnose experience #1483

FeynmanZhou · 2024-08-19T05:08:57Z

What this PR does / why we need it:

This proposal document aims to:

Identify the issues associated with the current implementation of the --verbose and --debug options.
Clarify the concepts of verbose output and debug logs.
List the guiding principles to write comprehensive, clear, and conducive verbose output and debug logs for effective diagnosis.
Propose solutions to improve the diagnostic experience for ORAS CLI users and developers.
Add examples for proposed changes (more examples will be appended).

Which issue(s) this PR fixes (optional, in fixes #<issue number>(, fixes #<issue_number>, ...) format, will close the issue(s) when PR gets merged):
Fixes #1091

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

codecov · 2024-08-19T05:11:05Z

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 86.05%. Comparing base (60b1369) to head (12bfc72).
Report is 18 commits behind head on main.

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #1483      +/-   ##
==========================================
+ Coverage   85.54%   86.05%   +0.51%     
==========================================
  Files         113      118       +5     
  Lines        3936     4224     +288     
==========================================
+ Hits         3367     3635     +268     
- Misses        342      352      +10     
- Partials      227      237      +10

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

toddysm

IMHO, if a user decides to get verbose output, he or she will be prepared to receive a lot of information in the output (including very technical information - for example, curl gives details about the encryption algorithm). I am still not convinced that we need to complicate the interface to suppress some of the output.

docs/proposals/diagnose-experience.md

Wwwsylvia · 2024-08-21T11:08:18Z

docs/proposals/diagnose-experience.md

+> 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" 
+


Do we want to insert separators like -----?

Would recommend looking at other tools. There are so many nicer options -

I propose to add an empty line as separator between each request and response for readability since this is a very common design. Do you have better ideas on improving the debug logs' readability?

Maybe an empty line between incoming and outgoing message

docs/proposals/diagnose-experience.md

TerryHowe · 2024-08-21T14:55:22Z

docs/proposals/diagnose-experience.md

+  - Example: `DEBUG: [2023-10-01T12:00:00Z] Starting metadata retrieval for repository oras-demo`
+
+### 2. **Capture API-Specific Details**
+- **API Requests:** Log detailed information about API requests made to the registry server, including the HTTP method, endpoint, headers, and body (excluding sensitive information).


IMO, we should not exclude sensitive information for debug output for two reasons:

it is nearly impossible to redact all sensitive information

it may actually be useful to see the sensitive information in the logs

As some kind of compromise maybe attempt no redaction at the highest level of debug if we were to have levels. Ansible used this policy and I think it was very useful.

Will it be insecure and non-compliant to log sensitive information in ORAS debug logs?

docs/proposals/diagnose-experience.md

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

docs/proposals/diagnose-experience.md

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

docs/proposals/diagnose-experience.md

shizhMSFT · 2024-09-14T07:19:43Z

docs/proposals/diagnose-experience.md

+- 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](https://github.com/oras-project/oras/issues/1382).
+- Critical information is missing in debug logs. For example, the [error code](https://github.com/opencontainers/distribution-spec/blob/main/spec.md#error-codes) 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.
+- 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.


It depends on the OS and environment.

You may observe the differences by running the following commands:

oras manifest fetch -d --descriptor ghcr.io/oras-project/oras:v1.2.0 oras manifest fetch -d --descriptor ghcr.io/oras-project/oras:v1.2.0 2>&1 | cat

oras manifest fetch -d --descriptor ghcr.io/oras-project/oras:v1.2.0

gives

DEBU[0000] Request #0

while

oras manifest fetch -d --descriptor ghcr.io/oras-project/oras:v1.2.0 2>&1 | cat

reports

time=2024-09-14T15:17:52+08:00 level=debug msg=Request #0

Based on this example, it looks like timestamp is not visible to users in debug logs by default. Users have to output the timestamp information with an additional command cat.

How about making timestamp information to each request and response by default?

It depends on logrus. @Wwwsylvia Could you provide options in logrus?

Just tested a bit. We can enable TextFormatter.FullTimestamp to achieve the goal:

logger.SetFormatter(&logrus.TextFormatter{ DisableQuote: true, + FullTimestamp: true, })

As a result, logs in TTY will show as:

DEBU[2024-09-23T18:56:49+08:00] Request #0

And logs in non-TTY will show as:

time=2024-09-23T18:59:56+08:00 level=debug msg=Request #0

Thus, it is technically feasible to make full timestamp information to each request and response by default.

docs/proposals/diagnose-experience.md

shizhMSFT · 2024-09-14T07:46:59Z

docs/proposals/diagnose-experience.md

+- **State Logs:** Log important state information, function names, important variable state, file name and line number before and after key operations or decisions.
+  - Example: `DEBUG: Current retry attempt: 1, Max retries: 3`


This does not apply to implementation inside oras-go. In other words, no details in oras.Copy() will be output. The reason is simple that logging is tightly coupled with the specific logging implementation while oras-go should be generic.

Other than logurs, there are other logging implementations like log, log/slog, zap, apex/log, etc. Unfortunately, they don't share the same interface.

Note that all logs will be hooks in real implementations.

docs/proposals/diagnose-experience.md

shizhMSFT · 2024-09-14T07:56:05Z

docs/proposals/diagnose-experience.md

+  - Example: `DEBUG: Current registry URL: https://myregistry.io, Timeout setting:
+
+### 6. **Avoid Logging Sensitive Information**
+- **Privacy:** Abstain from logging sensitive information such as passwords, personal data, or security tokens.


Define "sensitive information".

docs/proposals/diagnose-experience.md

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

docs/proposals/diagnose-experience.md

Wwwsylvia · 2024-09-18T09:09:58Z

docs/proposals/diagnose-experience.md

@@ -52,7 +52,7 @@ Logs focus on providing technical details for in-depth diagnosing and troublesho
 ## Proposals for ORAS CLI

 - Deprecate the global flag `--verbose` and only remain `--debug` to avoid ambiguity. Based on the concept above, it is reasonable to continue using `--debug` to enable the output of `DEBUG` level logs in ORAS 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.
- The existing output of `--verbose` in several ORAS commands `pull/push/attach/discover` can still be reserved. Introducing an additional flag to these commands.
+- Introduce a new flag `--detail` to replace the existing global flag `--verbose` of commands like `pull`, `push`, `attach`, and `discover` for detailed output.


Just to discuss, how about --long?

I don't think --detail is a good option, since it will cause similar confusion as --verbose. Questions like is it about detailed logs or about detailed other outputs?

One option is output the --verbose content by default, then we do not need any flags for verbose output that are not logs. This also solves the problem that some commands have --verbose flags, some don't.

Will --debug be a global flag, or just available for some commands?

Instead of --detail, I think we can have --quiet for pull, push, and attach.

discover is different since the --verbose takes effect on the metadata output instead of the status output. In that case, we can just remove --verbose and introduce new values for --format such as --format tree-full. It is also a good time to revisit the outputs of oras discover.

Agree with @shizhMSFT . Current verbose output in pull, push, attach is progress information but in discover it is metadata output. They are different cases.

yizha1 · 2024-09-19T10:11:06Z

docs/proposals/diagnose-experience.md

+
+### Output
+
+There are three types of output in ORAS CLI:


I think log is also one type of output. An "output” of a command refers to the information that is displayed or returned after the command is executed, it can be logs, formatted data, error messages.

Logs are logs, and logs may not be displayed or returned. They may be collected in systemd, or sent to fluentd.

yizha1 · 2024-09-19T11:06:01Z

docs/proposals/diagnose-experience.md

+> 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" 
+


Maybe an empty line between incoming and outgoing message

yizha1 · 2024-09-19T11:25:03Z

docs/proposals/diagnose-experience.md

@@ -52,7 +52,7 @@ Logs focus on providing technical details for in-depth diagnosing and troublesho
 ## Proposals for ORAS CLI

 - Deprecate the global flag `--verbose` and only remain `--debug` to avoid ambiguity. Based on the concept above, it is reasonable to continue using `--debug` to enable the output of `DEBUG` level logs in ORAS 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.
- The existing output of `--verbose` in several ORAS commands `pull/push/attach/discover` can still be reserved. Introducing an additional flag to these commands.
+- Introduce a new flag `--detail` to replace the existing global flag `--verbose` of commands like `pull`, `push`, `attach`, and `discover` for detailed output.


I don't think --detail is a good option, since it will cause similar confusion as --verbose. Questions like is it about detailed logs or about detailed other outputs?

One option is output the --verbose content by default, then we do not need any flags for verbose output that are not logs. This also solves the problem that some commands have --verbose flags, some don't.

yizha1 · 2024-09-19T11:27:18Z

docs/proposals/diagnose-experience.md

+
+### Guiding Principles
+
+Here are the guiding principles to write debug logs.


I would suggest we can just select a popular logging library or tool and follow the formats that are defined by the library or tool, because I don't think it is worth spending time to develop/customize our own logging formats, unless it is easy to customize using the library or tool.

I agree. Currently, we use logrus, which is used by docker daemon / CLI. There are also other log implementations like zap, apex, slog, etc.

docs/proposals/diagnose-experience.md

yizha1 · 2024-09-19T11:30:41Z

docs/proposals/diagnose-experience.md

@@ -52,7 +52,7 @@ Logs focus on providing technical details for in-depth diagnosing and troublesho
 ## Proposals for ORAS CLI

 - Deprecate the global flag `--verbose` and only remain `--debug` to avoid ambiguity. Based on the concept above, it is reasonable to continue using `--debug` to enable the output of `DEBUG` level logs in ORAS 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.
- The existing output of `--verbose` in several ORAS commands `pull/push/attach/discover` can still be reserved. Introducing an additional flag to these commands.
+- Introduce a new flag `--detail` to replace the existing global flag `--verbose` of commands like `pull`, `push`, `attach`, and `discover` for detailed output.


Will --debug be a global flag, or just available for some commands?

docs/proposals/diagnose-experience.md

shizhMSFT · 2024-09-20T16:14:40Z

docs/proposals/diagnose-experience.md

+
+### Output
+
+There are three types of output in ORAS CLI:


Logs are logs, and logs may not be displayed or returned. They may be collected in systemd, or sent to fluentd.

shizhMSFT · 2024-09-20T16:18:13Z

docs/proposals/diagnose-experience.md

+
+### 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 log including `DEBUG`, `INFO`, `WARNING`, `ERROR`, but only `DEBUG` level log is used in ORAS, which is controlled by the flag `--debug`. 


Some log implementation has the TRACE level, and the FATAL level.

I changed the description as follows:

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.

shizhMSFT · 2024-09-20T16:37:41Z

docs/proposals/diagnose-experience.md

+- Introduce a new flag `--detail` to replace the existing global flag `--verbose` of commands like `pull`, `push`, `attach`, and `discover` for detailed output.
+- Add separator lines between each request and response for readability.
+- Add timestamp of each request and response to the beginning of each request and response.
+- Add the response body including [error code](https://github.com/opencontainers/distribution-spec/blob/main/spec.md#error-codes) and the metadata of processed OCI object (e.g. image manifest) to the debug logs


What does it mean? Is it applicable to OCI image layout?

shizhMSFT · 2024-09-20T16:38:13Z

docs/proposals/diagnose-experience.md

+- Add separator lines between each request and response for readability.
+- Add timestamp of each request and response to the beginning of each request and response.
+- Add the response body including [error code](https://github.com/opencontainers/distribution-spec/blob/main/spec.md#error-codes) and the metadata of processed OCI object (e.g. image manifest) to the debug logs
+- Define guiding principles and conventions for writing clear and conductive debug logs


What's the purpose / motivation of this?

shizhMSFT · 2024-09-20T16:39:59Z

docs/proposals/diagnose-experience.md

+
+### Guiding Principles
+
+Here are the guiding principles to write debug logs.


I agree. Currently, we use logrus, which is used by docker daemon / CLI. There are also other log implementations like zap, apex, slog, etc.

shizhMSFT · 2024-09-20T16:45:23Z

docs/proposals/diagnose-experience.md

+- **Catch and Log Exceptions:** Always catch exceptions and log them with relevant context and stack traces.
+  - Example: `ERROR: Exception occurred in fetchManifest: Network timeout while accessing /v2/oras-demo/manifests/latest`
+
+- **Error Codes:** Include specific error codes to facilitate quick identification and resolution.
+  - Example: `ERROR: [ErrorCode: 504] Network timeout while accessing /v2/oras-demo/manifests/latest`


Currently, oras only use debug logs.

shizhMSFT · 2024-09-20T16:46:35Z

docs/proposals/diagnose-experience.md

+ORAS Version:    1.2.0+Homebrew
+Go version:      go1.22.3
+OS/Arch:         linux/amd64


Missing git information

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

add spec: Improve ORAS diagnose experience

ba3dfc2

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

FeynmanZhou requested review from sajayantony, shizhMSFT, SteveLasker, qweeah and TerryHowe as code owners August 19, 2024 05:08

FeynmanZhou added 2 commits August 19, 2024 16:25

refine spec

55e1d7f

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

refine spec

30e3e28

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

toddysm reviewed Aug 21, 2024

View reviewed changes

Wwwsylvia reviewed Aug 21, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Show resolved Hide resolved

docs/proposals/diagnose-experience.md Show resolved Hide resolved

Wwwsylvia reviewed Aug 21, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Outdated Show resolved Hide resolved

Wwwsylvia reviewed Aug 21, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Show resolved Hide resolved

TerryHowe reviewed Aug 21, 2024

View reviewed changes

TerryHowe mentioned this pull request Aug 22, 2024

Add verbose http logging to blob fetch #911

Open

1 task

sajayantony reviewed Aug 22, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Outdated Show resolved Hide resolved

sajayantony reviewed Aug 22, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Outdated Show resolved Hide resolved

sajayantony reviewed Aug 22, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Show resolved Hide resolved

yizha1 reviewed Aug 27, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Outdated Show resolved Hide resolved

shizhMSFT reviewed Aug 28, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Outdated Show resolved Hide resolved

docs/proposals/diagnose-experience.md Outdated Show resolved Hide resolved

shizhMSFT reviewed Aug 28, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Show resolved Hide resolved

Wwwsylvia reviewed Sep 3, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Outdated Show resolved Hide resolved

FeynmanZhou added 2 commits September 4, 2024 06:55

update spec: Improve ORAS diagnose experience

7b823a5

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

update spec: Improve ORAS diagnose experience

f71aef8

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

sajayantony reviewed Sep 4, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Outdated Show resolved Hide resolved

FeynmanZhou added 4 commits September 5, 2024 18:40

update spec based on comments

65cc161

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

update spec per comments

b6193f8

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

resolve comments and refactor the spec content

d30b974

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

resolve comments

b1d7207

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

FeynmanZhou requested review from TerryHowe, toddysm, sajayantony, Wwwsylvia, shizhMSFT and yizha1 September 13, 2024 17:27

shizhMSFT reviewed Sep 14, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Show resolved Hide resolved

docs/proposals/diagnose-experience.md Outdated Show resolved Hide resolved

docs/proposals/diagnose-experience.md Outdated Show resolved Hide resolved

Wwwsylvia reviewed Sep 14, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Outdated Show resolved Hide resolved

Wwwsylvia reviewed Sep 14, 2024

View reviewed changes

docs/proposals/diagnose-experience.md Outdated Show resolved Hide resolved

FeynmanZhou added 2 commits September 17, 2024 00:30

resolve new comments

734dbbd

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

resolve new comments

4783369

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

Wwwsylvia reviewed Sep 18, 2024

View reviewed changes

FeynmanZhou mentioned this pull request Sep 19, 2024

Enrich discover --verbose command tree output with additional data (Layers, data from Descriptor) #1501

Draft

4 tasks

yizha1 reviewed Sep 19, 2024

View reviewed changes

shizhMSFT requested changes Sep 20, 2024

View reviewed changes

resolve recent comments

12bfc72

Signed-off-by: Feynman Zhou <feynmanzhou@microsoft.com>

		- State Logs: Log important state information, function names, important variable state, file name and line number before and after key operations or decisions.
		- Example: `DEBUG: Current retry attempt: 1, Max retries: 3`


		### Guiding Principles

		Here are the guiding principles to write debug logs.


		### 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 log including `DEBUG`, `INFO`, `WARNING`, `ERROR`, but only `DEBUG` level log is used in ORAS, which is controlled by the flag `--debug`.

docs: Improve ORAS diagnose experience #1483

Are you sure you want to change the base?

docs: Improve ORAS diagnose experience #1483

Conversation

FeynmanZhou commented Aug 19, 2024 • edited Loading

codecov bot commented Aug 19, 2024 • edited Loading

Codecov Report

toddysm left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

FeynmanZhou Sep 13, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Wwwsylvia Sep 23, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Wwwsylvia Sep 18, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

FeynmanZhou commented Aug 19, 2024 •

edited

Loading

codecov bot commented Aug 19, 2024 •

edited

Loading

FeynmanZhou Sep 13, 2024 •

edited

Loading

Wwwsylvia Sep 23, 2024 •

edited

Loading

Wwwsylvia Sep 18, 2024 •

edited

Loading