{"id":155,"date":"2025-09-27T13:38:00","date_gmt":"2025-09-27T11:38:00","guid":{"rendered":"https:\/\/microsproject.dev\/?p=155"},"modified":"2025-09-25T14:07:55","modified_gmt":"2025-09-25T12:07:55","slug":"building-a-lightweight-logging-framework-for-micros-part-3-compile-time-and-per-module-filtering","status":"publish","type":"post","link":"https:\/\/microsproject.dev\/index.php\/2025\/09\/27\/building-a-lightweight-logging-framework-for-micros-part-3-compile-time-and-per-module-filtering\/","title":{"rendered":"Building a Lightweight Logging Framework for MicrOS \u2013 Part 3: Compile-Time and Per-Module Filtering"},"content":{"rendered":"\n

In Part 2<\/a>, we added colors, severity tags, and file\/line information to MicrOS logs. Now we\u2019re going to take it further: instead of just printing everything, we\u2019ll give developers fine-grained control<\/strong> over what gets logged.<\/p>\n\n\n\n

This is crucial in embedded systems, where every byte of flash and every CPU cycle counts. We want debug detail when we need it<\/strong>, but zero overhead when we don\u2019t<\/strong>.<\/p>\n\n\n\n

\n\n\n\n

The Two Layers of Filtering<\/h2>\n\n\n\n

MicrOS logging supports two filters<\/strong>:<\/p>\n\n\n\n

    \n
  1. Global filter<\/strong>\n
      \n
    • Controlled by CONFIG_MICROS_LOG_LEVEL<\/code>.<\/li>\n\n\n\n
    • Defines the absolute maximum<\/em> verbosity compiled into the system.<\/li>\n\n\n\n
    • Example: if you set it to INFO<\/code>, then all D()<\/code> logs vanish at compile time.<\/li>\n<\/ul>\n<\/li>\n\n\n\n
    • Per-module filter<\/strong>\n
        \n
      • Defined by MICROS_LOG_REGISTER(module, level)<\/code>.<\/li>\n\n\n\n
      • Lets each source file decide how chatty it should be.<\/li>\n\n\n\n
      • Example: boot<\/code> might default to INFO<\/code>, while scheduler<\/code> runs at DEBUG<\/code>.<\/li>\n<\/ul>\n<\/li>\n<\/ol>\n\n\n\n

        The effective log level is the intersection of both.<\/p>\n\n\n\n

        \n\n\n\n

        The Global Ceiling<\/h2>\n\n\n\n

        At build time, you choose the global level:<\/p>\n\n\n\n

        #define CONFIG_MICROS_LOG_LEVEL MICROS_LOG_LEVEL_DEBUG\n<\/code><\/pre>\n\n\n\n
        This controls which macros are compiled in. For example, if the global level is INFO<\/code>, then the D()<\/code> macro literally expands to nothing:<\/p>\n\n\n\n
        #if CONFIG_MICROS_LOG_LEVEL >= MICROS_LOG_LEVEL_DEBUG\n#define D(...) _log(MICROS_LOG_LEVEL_DEBUG, _micros_log_module_name, __FILE__, __LINE__, __VA_ARGS__)\n#else\n#define D(...) do {} while (0)\n#endif\n<\/code><\/pre>\n\n\n\n
        So debug logs don\u2019t even exist in the binary.<\/p>\n\n\n\n
        \n\n\n\n
        Registering a Module<\/h2>\n\n\n\n
        Each source file declares itself like this:<\/p>\n\n\n\n
        MICROS_LOG_REGISTER(main, MICROS_LOG_LEVEL_INFO);\n<\/code><\/pre>\n\n\n\n
        This expands to:<\/p>\n\n\n\n
        static const char* _micros_log_module_name = \"main\";\nstatic const micros_log_level_t _micros_log_level = MICROS_LOG_LEVEL_INFO;\n<\/code><\/pre>\n\n\n\n
        So now the macros know both which module is speaking<\/strong> and how chatty it\u2019s allowed to be<\/strong>.<\/p>\n\n\n\n
        \n\n\n\n
        The Logging Macros<\/h2>\n\n\n\n
        Here\u2019s how an info log works:<\/p>\n\n\n\n
        #if CONFIG_MICROS_LOG_LEVEL >= MICROS_LOG_LEVEL_INFO\n#define I(...) \\\n    do { \\\n        if (_micros_log_level >= MICROS_LOG_LEVEL_INFO) { \\\n            _log(MICROS_LOG_LEVEL_INFO, _micros_log_module_name, __FILE__, __LINE__, __VA_ARGS__); \\\n        } \\\n    } while (0)\n#else\n#define I(...) do {} while (0)\n#endif\n<\/code><\/pre>\n\n\n\n
          \n
        • First, we check the global level<\/strong> (CONFIG_MICROS_LOG_LEVEL<\/code>).<\/li>\n\n\n\n
        • Then, at runtime, we check the module\u2019s level<\/strong> (_micros_log_level<\/code>).<\/li>\n<\/ul>\n\n\n\n
          This way, you can build with DEBUG<\/code> globally but keep certain modules quieter by registering them with INFO<\/code> or WARN<\/code>.<\/p>\n\n\n\n
          \n\n\n\n
          Real Output: init_functions<\/code> in QEMU<\/h2>\n\n\n\n
          Here\u2019s what it looks like when running the init_functions<\/code> sample:<\/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
          Notice:<\/p>\n\n\n\n
            \n
          • main<\/code> is set to DEBUG<\/code>, so we see detailed traces with file\/line.<\/li>\n\n\n\n
          • boot<\/code> is set to INFO<\/code>, so only info-level logs are printed \u2014 no debug noise.<\/li>\n<\/ul>\n\n\n\n
            This is the power of per-module filtering: you see the details where you need them, but keep the rest of the system quiet.<\/p>\n\n\n\n
            \n\n\n\n
            Efficiency Matters<\/h2>\n\n\n\n
            Why not just check levels at runtime? Because:<\/p>\n\n\n\n
              \n
            • Logs above the global level are compiled out completely \u2192 zero code size<\/strong>.<\/li>\n\n\n\n
            • The runtime check only applies inside enabled macros \u2192 minimal cost<\/strong>.<\/li>\n\n\n\n
            • Disabled logs don\u2019t even reach _log()<\/code> \u2192 no wasted formatting<\/strong>.<\/li>\n<\/ul>\n\n\n\n
              This makes the system suitable even for tiny Cortex-M0 devices with <32 KB of flash.<\/p>\n\n\n\n
              \n\n\n\n
              Where We Stand<\/h2>\n\n\n\n
              At this point, MicrOS logging provides:<\/p>\n\n\n\n
                \n
              • Severity levels with colors<\/strong> (from Part 2).<\/li>\n\n\n\n
              • Global filtering<\/strong> to keep the binary lean.<\/li>\n\n\n\n
              • Per-module filtering<\/strong> for fine-grained verbosity.<\/li>\n\n\n\n
              • Minimal runtime overhead<\/strong> when logs are disabled.<\/li>\n<\/ul>\n\n\n\n
                This is already a professional-grade logging system for an embedded OS.<\/p>\n\n\n\n
                \n\n\n\n
                Coming Up Next<\/h2>\n\n\n\n
                In Part 4<\/strong>, we\u2019ll look at how to extend the framework:<\/p>\n\n\n\n
                  \n
                • Changing log levels at runtime<\/strong> (via UART shell or debug CLI).<\/li>\n\n\n\n
                • Routing logs to different backends<\/strong> (UART, RTT, memory buffer, network).<\/li>\n\n\n\n
                • Adding timestamps<\/strong> for precise sequencing.<\/li>\n\n\n\n
                • Even exploring structured logs<\/strong> for automated testing.<\/li>\n<\/ul>\n\n\n\n
                  That\u2019s where logging goes from debugging tool<\/em> to system-level instrumentation<\/em>.<\/p>\n\n\n\n
                  \n\n\n\n
                  \ud83d\udc49 Stay tuned for Part 4: Extending the Framework<\/strong> \u2014 where we make MicrOS logs dynamic, flexible, and even more powerful.<\/p>\n","protected":false},"excerpt":{"rendered":"
                  In Part 2, we added colors, severity tags, and file\/line information to MicrOS logs. Now we\u2019re going to take it further: instead of just printing everything, we\u2019ll give developers fine-grained control over what gets logged. This is crucial in embedded systems, where every byte of flash and every CPU cycle counts. We want debug detail […]<\/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-155","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\/155","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=155"}],"version-history":[{"count":1,"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/posts\/155\/revisions"}],"predecessor-version":[{"id":156,"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/posts\/155\/revisions\/156"}],"wp:attachment":[{"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/media?parent=155"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/categories?post=155"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/microsproject.dev\/index.php\/wp-json\/wp\/v2\/tags?post=155"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}