Skip to content

08_system_wide_logging.md

Jump to bottom
Lavnish edited this page Mar 31, 2026 · 1 revision

Chapter 8: System-wide Logging

Welcome back, cdfs-ton adventurer! In our previous chapter, Persisted Metadata (FSImage & Edit Log), we learned how the Metadata Server reliably saves its "brain" to disk so that no precious file information is lost. That's great for data durability!

But what about when things are happening right now? What if your client tries to upload a file and fails? What if a Storage Node goes offline, and the Metadata Server notices? How do you, as an operator or developer, know what's going on inside the cdfs-ton system at any given moment?

Imagine you have a complex machine with many moving parts. If something jams or breaks, you wouldn't just want to know it's broken; you'd want a detailed record of what happened, when, and where in the machine it happened. This "record" is exactly what System-wide Logging provides for cdfs-ton.

The Problem: "What's Happening in the System?!"

cdfs-ton is a distributed system, meaning its different parts (client, Metadata Server, Storage Nodes) often run on different computers. Without a way for them to report their activities, it's like trying to manage a team where no one ever speaks up about what they're doing, or if they've encountered a problem.

If a file upload fails, was it because:

  • The client couldn't connect to the Metadata Server?
  • The Metadata Server was busy?
  • A Storage Node ran out of disk space?
  • Data got corrupted during transfer?

Without clues, figuring this out would be like looking for a needle in a haystack!

The Solution: A Centralized System Journal!

System-wide Logging is cdfs-ton's answer to this problem. It's a centralized way for every part of cdfs-ton to record important events, operational details, warnings, and errors. Think of it as a journal or a flight recorder for the entire system.

Every time something notable happens, cdfs-ton writes an entry to this journal. This helps developers and administrators:

  • Understand behavior: See the sequence of operations.
  • Diagnose problems: Pinpoint the exact moment and cause of an issue.
  • Monitor health: Keep an eye on the system's overall performance and status.

Key Concepts of Logging

A good log entry isn't just a random message. It contains specific, helpful information:

  1. Timestamp:
    • What it is: The exact date and time the event occurred.
    • Why it's important: Critical for understanding the order of events and correlating issues across different parts of the distributed system. "This happened at 10:30:05 AM."
  2. Log Level:
    • What it is: A category indicating the severity or importance of the message.
    • Why it's important: Allows you to quickly filter and focus on the most critical messages.
  3. Component Name:
    • What it is: Which part of cdfs-ton generated this message (e.g., "Client," "MD" for Metadata Server, "SN" for Storage Node).
    • Why it's important: Helps identify where in the system an event originated.

Understanding Log Levels

cdfs-ton uses three main log levels:

Log Level Description When to Use It Example Message
INFO Routine operations, successful actions, general status updates. When something normal and expected happens. "Client uploaded file successfully." "SN received heartbeat."
WARN Something unexpected but not critical enough to stop operations. When a potential problem occurs that might need attention. "Node appears dead, starting re-replication." "Disk space getting low."
ERROR A severe problem that prevents an operation from completing. When something goes wrong that indicates a failure or serious issue. "Failed to connect to Metadata Server." "Checksum mismatch, chunk corrupted."

How to Use Logging in cdfs-ton

As a developer, you don't need to manually create timestamps or format log messages. cdfs-ton provides simple helper functions (actually, they are "macros" for convenience) that you can use.

These macros are defined in common/log.h and make logging very similar to using printf!

  • LOG_INFO(component, format_string, ...)
  • LOG_WARN(component, format_string, ...)
  • LOG_ERR(component, format_string, ...)

Let's see some examples from different parts of cdfs-ton:

Example: Client Application (Chapter 1: Client Application Interface)

When your cdfs_client successfully uploads a file, it should log an informational message:

// File: client/dfs_client.c (simplified cdfs_put)
int32_t cdfs_put(const uint8_t *local_path, const uint8_t *cdfs_path) {
    // ... (complex logic for chunking, sending, registering) ...

    if (status == 0) {
        // Log success!
        LOG_INFO("Client", "Successfully put '%s' -> '%s'\n", (char *)local_path, (char *)cdfs_path);
    } else {
        // Log failure as an error
        LOG_ERR("Client", "Failed to put file '%s'. Status: %d\n", (char *)local_path, status);
    }
    return status;
}

Example: Metadata Server (Chapter 5: Fault Tolerance & Replication Monitoring)

If the Metadata Server detects a Storage Node is no longer responding, it logs a warning:

// File: metadata_server/metadata_server.c (simplified replication_monitor)
void* replication_monitor(void *arg) {
    // ...
    if (!active_nodes[i].dead && (now - active_nodes[i].last_seen) > 15) {
        // Node appears dead! Log a warning.
        LOG_WARN("MD", "Node %s:%d appears dead!\n", active_nodes[i].ip, active_nodes[i].port);
        active_nodes[i].dead = 1; // Mark as dead
        // ... (logic to re-replicate chunks) ...
    }
    // ...
    return NULL;
}

Example: Storage Node (Chapter 3: Chunk Storage & Management)

If a Storage Node receives a chunk of data, but its checksum doesn't match the expected value (meaning the data got corrupted during transfer), it logs an error:

// File: storage_node/storage.c (simplified store_chunk_stream)
int32_t store_chunk_stream(int32_t chunk_id, int32_t sockfd, size_t size, uint32_t expected_checksum) {
    // ... (code to receive data and calculate checksum) ...

    if (calc_chk != expected_checksum) {
        // Checksum mismatch means data is bad, log an error.
        LOG_ERR("SN", "Checksum mismatch for chunk %d! Deleting corrupted file.\n", chunk_id);
        remove(path); // Delete the bad file
        return -1;
    }
    // ... (save checksum and return success) ...
    return 0;
}

Example Output

When you run cdfs-ton components, you'll see a stream of log messages on your terminal, like this:

[2023-10-27T10:30:05] [INFO ] [Client] Successfully put 'my_photo.jpg' -> '/photos/my_photo.jpg'
[2023-10-27T10:30:10] [INFO ] [SN] Received heartbeat from Metadata Server.
[2023-10-27T10:30:11] [INFO ] [MD] Registering file '/photos/my_photo.jpg' with 3 chunks.
[2023-10-27T10:30:25] [WARN ] [MD] Node 192.168.1.5:9000 appears dead!
[2023-10-27T10:30:30] [ERROR] [SN] Checksum mismatch for chunk 123! Deleting corrupted file.
[2023-10-27T10:30:35] [INFO ] [MD] Started re-replication for chunk 123.

This combined output from all components gives you a clear timeline of events, helping you trace exactly what happened when.

Under the Hood: How Logging Works

Now, let's peek behind the curtain to see how cdfs-ton generates these useful log messages. The core logic is handled by a single function, cdfs_log_msg, found in common/log.c.

The cdfs_log_msg Function: The Log Printer

When you use LOG_INFO, LOG_WARN, or LOG_ERR, they actually call this cdfs_log_msg function. This function then does all the heavy lifting of formatting and printing the message.

Here's a simplified sequence of what happens when you call a log macro:

sequenceDiagram
    participant C as CDFS Component
    participant M as "LOG_INFO / WARN / ERR"
    participant L as "cdfs_log_msg()"
    participant Sys as System Functions
    participant Out as Console Output

    C->>M: 1. Call LOG_INFO("MD", "File added: %s\n", filename)
    Note over M: Macro expands to cdfs_log_msg(LOG_LEVEL_INFO, "MD", "File added: %s\n", filename)
    M->>L: 2. Call cdfs_log_msg with arguments
    L->>Sys: 3. Get current time (time(), localtime(), strftime())
    Sys-->>L: 4. Return formatted timestamp string
    L->>L: 5. Convert log level (e.g., LOG_LEVEL_INFO -> "INFO ")
    L->>L: 6. Prepare full message parts
    L->>Sys: 7. Print to console (fprintf() for prefix, vfprintf() for message)
    Sys-->>Out: 8. "[Timestamp] [INFO ] [MD] File added: my_file.txt"
Loading

Diving into the Code (common/log.h and common/log.c)

Let's examine the actual code that implements this.

1. common/log.h: Defining Log Levels and Macros

This header file is where the log levels are defined and where the convenient logging macros (LOG_INFO, etc.) are created.

// File: common/log.h
#ifndef LOG_H
#define LOG_H

#include <stdio.h>    // For printf-like functions
#include <stdint.h>   // For uint8_t (used for string types)

// Define our log levels
typedef enum {
    LOG_LEVEL_INFO,
    LOG_LEVEL_WARN,
    LOG_LEVEL_ERR
} log_level_t;

// The main logging function declaration
void cdfs_log_msg(log_level_t level, const uint8_t *component, const char *fmt, ...);

// Convenience macros to easily log messages
#define LOG_INFO(comp, ...)  cdfs_log_msg(LOG_LEVEL_INFO, (const uint8_t *)(comp), __VA_ARGS__)
#define LOG_WARN(comp, ...)  cdfs_log_msg(LOG_LEVEL_WARN, (const uint8_t *)(comp), __VA_ARGS__)
#define LOG_ERR(comp, ...)   cdfs_log_msg(LOG_LEVEL_ERR,  (const uint8_t *)(comp), __VA_ARGS__)

#endif
  • log_level_t enum: This simply assigns names (LOG_LEVEL_INFO, LOG_LEVEL_WARN, LOG_LEVEL_ERR) to underlying integer values (0, 1, 2). This makes the code much more readable.
  • cdfs_log_msg(...) declaration: This tells the compiler that a function named cdfs_log_msg exists, and it takes a log_level_t, a component string, a format string, and then any number of additional arguments (the ... part, just like printf).
  • Macros (#define LOG_INFO(...)): These are like shortcuts. When you write LOG_INFO("MD", "Hello %s\n", name), the preprocessor replaces it with cdfs_log_msg(LOG_LEVEL_INFO, (const uint8_t *)"MD", "Hello %s\n", name).
    • __VA_ARGS__ is a special C feature that means "take all the remaining arguments passed to the macro and put them here." This is what allows LOG_INFO to work exactly like printf when it comes to extra variables.

2. common/log.c: Implementing the Log Printer

This file contains the actual cdfs_log_msg function that does all the work.

// File: common/log.c
#include "log.h"     // Our log definitions
#include <stdarg.h>  // For va_list, va_start, va_end, vfprintf (variable arguments)
#include <time.h>    // For time functions (timestamps)
#include <string.h>  // For strftime (string formatting)

void cdfs_log_msg(log_level_t level, const uint8_t *component, const char *fmt, ...) {
    time_t rawtime;        // Holds the raw time value
    struct tm *timeinfo;   // Holds structured time (year, month, day, etc.)
    uint8_t time_str[32];  // Buffer to store the formatted timestamp string

    // 1. Get and format the current timestamp
    time(&rawtime);                    // Get current time as a raw number
    timeinfo = localtime(&rawtime);    // Convert to a local time structure
    strftime((char *)time_str, sizeof(time_str), "%Y-%m-%dT%H:%M:%S", timeinfo); // Format into "YYYY-MM-DDTHH:MM:SS"

    // 2. Determine the log level string (e.g., "INFO ", "WARN ", "ERROR")
    const uint8_t *lvl_str;
    switch (level) {
        case LOG_LEVEL_INFO: lvl_str = (const uint8_t *)"INFO "; break;
        case LOG_LEVEL_WARN: lvl_str = (const uint8_t *)"WARN "; break;
        case LOG_LEVEL_ERR:  lvl_str = (const uint8_t *)"ERROR"; break;
        default:             lvl_str = (const uint8_t *)"DEBUG"; break; // Fallback for undefined levels
    }

    // 3. Print the timestamp, log level, and component name
    fprintf(stdout, "[%s] [%s] [%s] ", (char *)time_str, (char *)lvl_str, (char *)component);

    // 4. Print the actual message using variable arguments
    va_list args;      // Declare a variable argument list
    va_start(args, fmt); // Initialize 'args' to point to the arguments after 'fmt'
    vfprintf(stdout, fmt, args); // Print the message using the format string and variable arguments
    va_end(args);      // Clean up the variable argument list
    
    // Note: The 'fmt' string passed to LOG_ macros should generally end with '\n'
    // for standard line breaks in the console output.
}
  • Timestamping: The time(), localtime(), and strftime() functions are standard C library calls used to get the current time and format it into a readable string (e.g., [2023-10-27T10:30:05]).
  • Log Level String: A switch statement checks the level argument (which came from the LOG_INFO macro) and assigns the appropriate text string ("INFO ", "WARN ", "ERROR") to lvl_str.
  • fprintf(stdout, ...): This first fprintf prints the initial part of the log message: the timestamp, the level string, and the component name (e.g., [2023-10-27T10:30:05] [INFO ] [Client] ). stdout means it prints directly to your terminal screen.
  • Variable Arguments (va_list, va_start, vfprintf, va_end): This is a powerful feature of C that allows cdfs_log_msg to accept any number of arguments, just like printf.
    • va_list args; declares a variable that will hold information about the extra arguments.
    • va_start(args, fmt); tells the system where the variable arguments begin (right after the fmt parameter).
    • vfprintf(stdout, fmt, args); is like fprintf, but instead of taking individual arguments, it takes the va_list structure. This is what actually prints your custom message with all its variables (e.g., "Successfully put '%s' -> '%s'\n", along with local_path and cdfs_path).
    • va_end(args); cleans up the variable argument list.

By combining these steps, cdfs_log_msg ensures that every message is consistently formatted with all the necessary details, making your cdfs-ton system much easier to understand and manage.

Conclusion

System-wide Logging is an indispensable feature for any robust distributed system like cdfs-ton. It provides a clear, timestamped, and categorized journal of all system activities, enabling developers and administrators to quickly diagnose problems, monitor performance, and understand the flow of operations across all components. With simple macros like LOG_INFO, LOG_WARN, and LOG_ERR, you can easily add crucial insights into your cdfs-ton system's behavior. This ability to "look inside" the system is vital for maintaining a healthy and reliable distributed file system.

Clone this wiki locally