{"id":153,"date":"2025-09-26T13:36:00","date_gmt":"2025-09-26T11:36:00","guid":{"rendered":"https:\/\/microsproject.dev\/?p=153"},"modified":"2025-09-25T14:07:55","modified_gmt":"2025-09-25T12:07:55","slug":"building-a-lightweight-logging-framework-for-micros-part-2-coloring-and-structuring-logs","status":"publish","type":"post","link":"https:\/\/microsproject.dev\/index.php\/2025\/09\/26\/building-a-lightweight-logging-framework-for-micros-part-2-coloring-and-structuring-logs\/","title":{"rendered":"Building a Lightweight Logging Framework for MicrOS \u2013 Part 2: Coloring and Structuring Logs"},"content":{"rendered":"\n

In Part 1<\/a> of this series, I explained why logging matters for MicrOS and how we started with a simple design: log levels, a global ceiling, and per-module registration. That gave us the skeleton of a logging system \u2014 but the output was still plain and hard to scan.<\/p>\n\n\n\n

In this part, we\u2019ll bring logs to life by adding VT100 colors, severity tags, and structured formatting<\/strong>. This way, you can spot errors immediately, follow debug traces line by line, and keep your terminal readable even when dozens of modules are talking at once.<\/p>\n\n\n\n

\n\n\n\n

Adding Color with VT100 Escape Codes<\/h2>\n\n\n\n

Most serial terminals and QEMU consoles understand VT100 escape codes<\/strong>. These are simple strings that tell the terminal to switch text color. For example:<\/p>\n\n\n\n

    \n
  • \\033[31m<\/code> \u2192 red<\/li>\n\n\n\n
  • \\033[32m<\/code> \u2192 green<\/li>\n\n\n\n
  • \\033[33m<\/code> \u2192 yellow<\/li>\n\n\n\n
  • \\033[34m<\/code> \u2192 blue<\/li>\n\n\n\n
  • \\033[0m<\/code> \u2192 reset<\/li>\n<\/ul>\n\n\n\n

    We map each severity level to a color:<\/p>\n\n\n\n

    #define MICROS_LOG_ESCAPE_CODE_COLOR_RED    \"\\033[31m\"\n#define MICROS_LOG_ESCAPE_CODE_COLOR_GREEN  \"\\033[32m\"\n#define MICROS_LOG_ESCAPE_CODE_COLOR_YELLOW \"\\033[33m\"\n#define MICROS_LOG_ESCAPE_CODE_COLOR_BLUE   \"\\033[34m\"\n#define MICROS_LOG_ESCAPE_CODE_COLOR_RESET  \"\\033[0m\"\n<\/code><\/pre>\n\n\n\n
    Errors stand out in red, warnings in yellow, informational logs in green, and debug traces in blue.<\/p>\n\n\n\n
    \n\n\n\n
    Formatting Messages<\/h2>\n\n\n\n
    The _log<\/code> function now does three things:<\/p>\n\n\n\n
      \n
    1. Selects the color<\/strong> and severity tag<\/strong> (E<\/code>, W<\/code>, I<\/code>, D<\/code>).<\/li>\n\n\n\n
    2. Prints either a compact message<\/strong> (for info\/warn\/error) or a detailed trace<\/strong> (for debug).<\/li>\n\n\n\n
    3. Resets the color so the terminal stays clean.<\/li>\n<\/ol>\n\n\n\n
      Here\u2019s the core logic:<\/p>\n\n\n\n
      switch (level) {\n    case MICROS_LOG_LEVEL_ERROR:\n        color_escape_str = MICROS_LOG_ESCAPE_CODE_COLOR_RED;\n        level_str = \"E\";\n        break;\n    case MICROS_LOG_LEVEL_WARN:\n        color_escape_str = MICROS_LOG_ESCAPE_CODE_COLOR_YELLOW;\n        level_str = \"W\";\n        break;\n    case MICROS_LOG_LEVEL_INFO:\n        color_escape_str = MICROS_LOG_ESCAPE_CODE_COLOR_GREEN;\n        level_str = \"I\";\n        break;\n    case MICROS_LOG_LEVEL_DEBUG:\n        color_escape_str = MICROS_LOG_ESCAPE_CODE_COLOR_BLUE;\n        level_str = \"D\";\n        break;\n}\n<\/code><\/pre>\n\n\n\n
      For debug logs<\/strong>, we include file and line:<\/p>\n\n\n\n
      fprintf(output, \"[%s] [%s] --%s:%d-- \",\n        level_str, module_name, file, line);\n<\/code><\/pre>\n\n\n\n
      For everything else:<\/p>\n\n\n\n
      fprintf(output, \"[%s] [%s] \", level_str, module_name);\n<\/code><\/pre>\n\n\n\n
      Finally, we call vfprintf()<\/code> with the user\u2019s message and reset the color:<\/p>\n\n\n\n
      vfprintf(output, fmt, args);\nfprintf(output, MICROS_LOG_ESCAPE_CODE_COLOR_RESET \"\\n\");\n<\/code><\/pre>\n\n\n\n
      \n\n\n\n
      Real Logs in Action<\/h2>\n\n\n\n
      Here\u2019s what it looks like when running the init_functions<\/code><\/strong> sample in QEMU:<\/p>\n\n\n\n
      [D] [main] --\/home\/grzegorz\/projects\/micros\/samples\/init_functions\/main.c:22-- System clock initialized - simulated\n[D] [main] --\/home\/grzegorz\/projects\/micros\/samples\/init_functions\/main.c:26-- UART initialized - simulated\n[D] [main] --\/home\/grzegorz\/projects\/micros\/samples\/init_functions\/main.c:31-- System initialized successfully - simulated\n[D] [main] --\/home\/grzegorz\/projects\/micros\/samples\/init_functions\/main.c:35-- Very early init function in section .init_array.50 - simulated\n[I] [main] MicrOS Initialization Framework Example\n[I] [main] System is up and running!\n[I] [main] Main function is exiting now.\n[I] [boot] Main function returned with code 0\n[D] [main] --\/home\/grzegorz\/projects\/micros\/samples\/init_functions\/main.c:39-- Very late fini function in section .fini_array - simulated\n[I] [boot] System halted after main return\n<\/code><\/pre>\n\n\n\n
      In a terminal, those lines appear:<\/p>\n\n\n\n
        \n
      • Blue<\/strong> for debug [D]<\/code> (with file and line).<\/li>\n\n\n\n
      • Green<\/strong> for info [I]<\/code>.<\/li>\n\n\n\n
      • Yellow<\/strong> for warnings [W]<\/code>.<\/li>\n\n\n\n
      • Red<\/strong> for errors [E]<\/code>.<\/li>\n<\/ul>\n\n\n\n
        This makes it instantly obvious what\u2019s routine, what\u2019s important, and what\u2019s catastrophic.<\/p>\n\n\n\n
        \n\n\n\n
        Why File and Line for Debug?<\/h2>\n\n\n\n
        You\u2019ll notice that only debug logs show the full --file:line--<\/code> prefix. That\u2019s intentional:<\/p>\n\n\n\n
          \n
        • Debugging sessions<\/strong> often require pinpoint accuracy \u2014 \u201cwhich path hit this code?\u201d<\/li>\n\n\n\n
        • Normal operation<\/strong> should remain readable and concise.<\/li>\n<\/ul>\n\n\n\n
          This balance keeps everyday logs short, while still letting you crank up detail when hunting a bug.<\/p>\n\n\n\n
          \n\n\n\n
          Where We Stand<\/h2>\n\n\n\n
          At this point, our logging system has:<\/p>\n\n\n\n
            \n
          • Severity levels (E<\/code>, W<\/code>, I<\/code>, D<\/code>).<\/li>\n\n\n\n
          • VT100 colors for instant readability.<\/li>\n\n\n\n
          • File\/line context for debug logs.<\/li>\n\n\n\n
          • Clean reset after each line.<\/li>\n<\/ul>\n\n\n\n
            Already, this makes MicrOS much easier to work with than raw printf<\/code>. But we\u2019re not done yet.<\/p>\n\n\n\n
            \n\n\n\n
            Coming Up Next<\/h2>\n\n\n\n
            In Part 3<\/strong>, we\u2019ll add compile-time and per-module filtering<\/strong>:<\/p>\n\n\n\n
              \n
            • A global ceiling (CONFIG_MICROS_LOG_LEVEL<\/code>).<\/li>\n\n\n\n
            • MICROS_LOG_REGISTER(module, level)<\/code> for per-module defaults.<\/li>\n\n\n\n
            • Macros like D()<\/code>, I()<\/code>, W()<\/code>, and E()<\/code> that automatically check both.<\/li>\n<\/ul>\n\n\n\n
              That\u2019s where logging really starts to feel powerful: each part of the OS can speak at its own volume, and you can globally tune the noise.<\/p>\n\n\n\n
              \n\n\n\n
              \ud83d\udc49 Stay tuned for Part 3: Compile-Time and Per-Module Filtering<\/strong> \u2014 where we turn the logging API into something you can really depend on in production.<\/p>\n","protected":false},"excerpt":{"rendered":"
              In Part 1 of this series, I explained why logging matters for MicrOS and how we started with a simple design: log levels, a global ceiling, and per-module registration. That gave us the skeleton of a logging system \u2014 but the output was still plain and hard to scan. In this part, we\u2019ll bring logs […]<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[6,7],"tags":[],"class_list":["post-153","post","type-post","status-publish","format-standard","hentry","category-development","category-logging"],"blocksy_meta":[],"_links":{"self":[{"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/posts\/153","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/comments?post=153"}],"version-history":[{"count":1,"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/posts\/153\/revisions"}],"predecessor-version":[{"id":154,"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/posts\/153\/revisions\/154"}],"wp:attachment":[{"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/media?parent=153"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/categories?post=153"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/tags?post=153"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}