Skip to content

Latest commit

 

History

History
507 lines (387 loc) · 17 KB

logging.md

File metadata and controls

507 lines (387 loc) · 17 KB
Raw

OpenIM Logging and Error Handling Documentation

Script Logging Documentation Link

If you wish to view the script's logging documentation, you can click on this link: Logging Documentation.

Below is the documentation for logging and error handling in the OpenIM Go project.

To create a standard set of documentation that is quick to read and easy to understand, we will highlight key information about the Logger interface and the CodeError interface. This includes the purpose of each interface, key methods, and their use cases. This will help developers quickly grasp how to effectively use logging and error handling within the project.

Logging (Logger Interface)

Purpose

The Logger interface aims to provide the OpenIM project with a unified and flexible logging mechanism, supporting structured logging formats for efficient log management and analysis.

Key Methods

  • Debug, Info, Warn, Error
    Log messages of different levels to suit various logging needs and scenarios. These methods accept a context (context.Context), a message (string), and key-value pairs (...interface{}), allowing the log to carry rich context information.

  • WithValues
    Append key-value pair information to log messages, returning a new Logger instance. This helps in adding consistent context information.

  • WithName
    Set the name of the logger, which helps in identifying the source of the logs.

  • WithCallDepth
    Adjust the call stack depth to accurately identify the source of the log message.

Use Cases

  • Developers should choose the appropriate logging level (such as Debug, Info, Warn, Error) based on the importance of the information when logging.
  • Use WithValues and WithName to add richer context information to logs, facilitating subsequent tracking and analysis.

Error Handling (CodeError Interface)

Purpose

The CodeError interface is designed to provide a unified mechanism for error handling and wrapping, making error information more detailed and manageable.

Key Methods

  • Code
    Return the error code to distinguish between different types of errors.

  • Msg
    Return the error message description to display to the user.

  • Detail
    Return detailed information about the error for further debugging by developers.

  • WithDetail
    Add detailed information to the error, returning a new CodeError instance.

  • Is
    Determine whether the current error matches a specified error, supporting a flexible error comparison mechanism.

  • Wrap
    Wrap another error with additional message description, facilitating the tracing of the error's cause.

Use Cases

  • When defining errors with specific codes and messages, use error types that implement the CodeError interface.
  • Use WithDetail to add additional context information to errors for more accurate problem localization.
  • Use the Is method to judge the type of error for conditional branching.
  • Use the Wrap method to wrap underlying errors while adding more contextual descriptions.

Logging Standards and Code Examples

In the OpenIM project, we use the unified logging package github.com/openimsdk/tools/log for logging to achieve efficient log management and analysis. This logging package supports structured logging formats, making it easier for developers to handle log information.

Logger Interface and Implementation

The logger interface is defined as follows:

type Logger interface {
    Debug(ctx context.Context, msg string, keysAndValues ...interface{})
    Info(ctx context.Context, msg string, keysAndValues ...interface{})
    Warn(ctx context.Context, msg string, err error, keysAndValues ...interface{})
    Error(ctx context.Context, msg string, err error, keysAndValues ...interface{})
    WithValues(keysAndValues ...interface{}) Logger
    WithName(name string) Logger
    WithCallDepth(depth int) Logger
}

Example code: Using the Logger interface to log at the info level.

func main() {
	logger := log.NewLogger().WithName("MyService")
	ctx := context.Background()
	logger.Info(ctx, "Service started", "port", "8080")
}

Error Handling and Code Examples

We use the github.com/openimsdk/tools/errs package for unified error handling and wrapping.

CodeError Interface and Implementation

The error interface is defined as follows:

type CodeError interface {
    Code() int
    Msg() string
    Detail() string
    WithDetail(detail string) CodeError
    Is(err error, loose ...bool) bool
    Wrap(msg ...string) error
    error
}

Example code: Creating and using the CodeError interface to handle errors.

package main

import (
	"fmt"
	"github.com/openimsdk/tools/errs"
)

func main() {
	err := errs.New(404, "Resource not found")
	err = err.WithDetail("

More details")
	if e, ok := err.(errs.CodeError); ok {
		fmt.Println(e.Code(), e.Msg(), e.Detail())
	}
}

Detailed Logging Standards and Code Examples

  1. Print key information at startup
    It is crucial to print entry parameters and key process information at program startup. This helps understand the startup state and configuration of the program.

    Code Example:

    package main

import (
    "fmt"
    "os"
)

func main() {
    fmt.Println("Program startup, version: 1.0.0")
    fmt.Printf("Connecting to database: %s\n", os.Getenv("DATABASE_URL"))
}

  2. Use tools/log and fmt for logging
    Logging should be done using a specialized logging library for unified management and formatted log output.

    Code Example: Logging an info level message with tools/log.

    package main

import (
    "context"
    "github.com/openimsdk/tools/log"
)

func main() {
    ctx := context.Background()
    log.Info(ctx, "Application started successfully")
}

  3. Use standard error output for startup failures or critical information
    Critical error messages or program startup failures should be indicated to the user through standard error output.

    Code Example:

    package main

import (
    "fmt"
    "os"
)

func checkEnvironment() bool {
    return os.Getenv("REQUIRED_ENV") != ""
}

func main() {
    if !checkEnvironment() {
        fmt.Fprintln(os.Stderr, "Missing required environment variable")
        os.Exit(1)
    }
}

    We encapsulate it into separate tools, which can output error information through the tools/log package.

     package main

 import (
     util "github.com/openimsdk/open-im-server/v3/pkg/util/genutil"
 )

 func main() {
     if err := apiCmd.Execute(); err != nil {
         util.ExitWithError(err)
     }
 }

  4. Use tools/log package for runtime logging
    This ensures consistency and control over logging.

    Code Example: Same as the above example using tools/log. When tools/log is not initialized, consider using fmt for standard output.

  5. Error logs should be printed by the top-level caller
    This is to avoid duplicate logging of errors, typically errors are caught and logged at the application's outermost level.

    Code Example:

    package main

import (
    "github.com/openimsdk/tools/log"
    "context"
)

func doSomething() error {
    // An error occurs here
    return errs.Wrap(errors.New("An error occurred"))
}

func controller() error {
    err := doSomething()
    if err != nil {
        return err
    }
    return nil
}

func main() {
    err := controller()
    if err != nil {
        log.Error(context.Background(), "Operation failed", err)
    }
}

  6. Handling logs for API RPC calls and non-RPC applications

    For API RPC calls using gRPC, logs at the information level are printed by middleware on the gRPC server side, reducing the need to manually log in each RPC method. For non-RPC applications, it's recommended to manually log key execution paths to track the application's execution flow.

    gRPC Server-Side Logging Middleware:

    In gRPC, UnaryInterceptor and StreamInterceptor can intercept Unary and Stream type RPC calls, respectively. Here's an example of how to implement a simple Unary RPC logging middleware:

    package main

import (
    "context"
    "google.golang.org/grpc"
    "google.golang.org/grpc/codes"
    "google.golang.org/grpc/status"
    "log"
    "time"
)

// unaryServerInterceptor returns a new unary server interceptor that logs each request.
func unaryServerInterceptor() grpc.UnaryServerInterceptor {
    return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
        // Record the start time of the request
        start := time.Now()
        // Call the actual RPC method
        resp, err = handler(ctx, req)
        // After the request ends, log the duration and other information
        log.Printf("Request method: %s, duration: %s, error status: %v", info.FullMethod, time.Since(start), status.Code(err))
        return resp, err
    }
}

func main() {
    // Create a gRPC server and add the middleware
    s := grpc.NewServer

(grpc.UnaryInterceptor(unaryServerInterceptor())) // Register your service

    // Start the gRPC server
    log.Println("Starting gRPC server...")
    // ...
}
```

**Logging for Non-RPC Applications:**

For non-RPC applications, the key is to log at appropriate places in the code to maintain an execution trace. Here's a simple example showing how to log when handling a task:

```go
package main

import (
    "log"
)

func processTask(taskID string) {
    // Log the start of task processing
    log.Printf("Starting task processing: %s", taskID)
    // Suppose this is where the task is processed

    // Log after the task is completed
    log.Printf("Task processing completed: %s", taskID)
}

func main() {
    // Example task ID
    taskID := "task123"
    processTask(taskID)
}
```

In both scenarios, appropriate logging can help developers and operators monitor the health of the system, trace the source of issues, and quickly locate and resolve problems. For gRPC logging, using middleware can effectively centralize log management and control. For non-RPC applications, ensuring logs are placed at critical execution points can help understand the program's operational flow and state changes.

When to Wrap Errors?

  1. Wrap errors generated within the function
    When an error occurs within a function, use errs.Wrap to add context information to the original error.

    Code Example:

    func doSomething() error {
    // Suppose an error occurs here
    err, _ := someFunc()
    if err != nil {
      return errs.WrapMsg(err, "doSomething failed")
    }
}

    It just works if the package is wrong:

       func doSomething() error {
    // Suppose an error occurs here
    err, _ := someFunc()
    if err != nil {
      return errs.Wrap(err)
    }
}

  2. Wrap errors from system calls or other packages
    When calling external libraries or system functions that return errors, also add context information to wrap the error.

    Code Example:

    func readConfig(file string) error {
    _, err := os.ReadFile(file)
    if err != nil {
        return errs.Wrap(err, "Failed to read config file")
    }
    return nil
}

  3. No need to re-wrap errors for internal module calls

    If an error has been appropriately wrapped with sufficient context information in an internal module call, there's no need to wrap it again.

    Code Example:

    func doSomething() error {
    err := doAnotherThing()
    if err != nil {
        return err
    }
    return nil
}

  4. Ensure comprehensive wrapping of errors with detailed messages When wrapping errors, ensure to provide ample context information to make the error more understandable and easier to debug.

    Code Example:

    func connectDatabase() error {
    err := db.Connect(config.DatabaseURL)
    if err != nil {
        return errs.Wrap(err, fmt.Sprintf("Failed to connect to database, URL: %s", config.DatabaseURL))
    }
    return nil
}

About WrapMsg Use

// 	"github.com/openimsdk/tools/errs"
func WrapMsg(err error, msg string, kv ...any) error {
	if len(kv) == 0 {
		if len(msg) == 0 {
			return errors.WithStack(err)
		} else {
			return errors.WithMessage(err, msg)
		}
	}
	var buf bytes.Buffer
	if len(msg) > 0 {
		buf.WriteString(msg)
		buf.WriteString(" ")
	}
	for i := 0; i < len(kv); i += 2 {
		if i > 0 {
			buf.WriteString(", ")
		}
		buf.WriteString(toString(kv[i]))
		buf.WriteString("=")
		buf.WriteString(toString(kv[i+1]))
	}
	return errors.WithMessage(err, buf.String())
}

  1. Function Signature:

    • err error: The original error object.
    • msg string: The message text to append to the error.
    • kv ...any: A variable number of parameters used to pass key-value pairs. any was introduced in Go 1.18 and is equivalent to interface{}, meaning any type.

  2. Logic:

    • If there are no key-value pairs (kv is empty):
      • If msg is also empty, use errors.WithStack(err) to return the original error with the call stack appended.
      • If msg is not empty, use errors.WithMessage(err, msg) to append the message text to the original error.
    • If there are key-value pairs, the function constructs a string containing the message text and all key-value pairs. The key-value pairs are added in the format "key=value", separated by commas. If a message text is provided, it is added first, followed by a space.

  3. Key-Value Pair Formatting:

    • A loop iterates over all the key-value pairs, processing one pair at a time.
    • The toString function (although not provided in the code, we can assume it converts any type to a string) is used to convert both keys and values to strings, and they are added to a bytes.Buffer in the format "key=value".

  4. Result:

    • Use errors.WithMessage(err, buf.String()) to append the constructed message text to the original error, and return this new error object.

Next, let's demonstrate several ways to use the WrapMsg function:

Example 1: No Additional Information

// "github.com/openimsdk/tools/errs"
err := errors.New("original error")
wrappedErr := errs.WrapMsg(err, "")
// wrappedErr will contain the original error and its call stack

Example 2: Message Text Only

// "github.com/openimsdk/tools/errs"
err := errors.New("original error")
wrappedErr := errs.WrapMsg(err, "additional error information")
// wrappedErr will contain the original error, call stack, and "additional error information"

Example 3: Message Text and Key-Value Pairs

// "github.com/openimsdk/tools/errs"
err := errors.New("original error")
wrappedErr := errs.WrapMsg(err, "problem occurred", "code", 404, "url", "webhook://example.com")
// wrappedErr will contain the original error, call stack, and "problem occurred code=404, url=http://example.com"

Example 4: Key-Value Pairs Only

// "github.com/openimsdk/tools/errs"
err := errors.New("original error")
wrappedErr := errs.WrapMsg(err, "", "user", "john_doe", "action", "login")
// wrappedErr will contain the original error, call stack, and "user=john_doe, action=login"

[!TIP] WThese examples demonstrate how the errs.WrapMsg function can flexibly handle error messages and context data, helping developers to more effectively track and debug their programs.

Example 5: Dynamic Key-Value Pairs from Context

Suppose we have some runtime context variables, such as a user ID and the type of operation being performed, and we want to include these variables in the error message. This can help with later debugging and identifying the specific environment of the issue.

// Define some context variables
userID := "user123"
operation := "update profile"
errorCode := 500
requestURL := "webhook://example.com/updateProfile"

// Create a new error
err := errors.New("original error")

// Wrap the error, including dynamic key-value pairs from the context
wrappedErr := errs.WrapMsg(err, "operation failed", "user", userID, "action", operation, "code", errorCode, "url", requestURL)
// wrappedErr will contain the original error, call stack, and "operation failed user=user123, action=update profile, code=500, url=http://example.com/updateProfile"

[!TIP]In this example, the WrapMsg function accepts not just a static error message and additional information, but also dynamic key-value pairs generated from the code's execution context, such as the user ID, operation type, error code, and the URL of the request. Including this contextual information in the error message makes it easier for developers to understand and resolve the issue.