| 1 | /* @title: Logging */ |
| 2 | #pragma once |
| 3 | #include <bootstage.h> |
| 4 | #include <colors.h> |
| 5 | #include <linker/symbols.h> |
| 6 | #include <sch/irql.h> |
| 7 | #include <stdbool.h> |
| 8 | #include <stddef.h> |
| 9 | #include <stdint.h> |
| 10 | #include <structures/list.h> |
| 11 | #include <types/refcount.h> |
| 12 | #include <types/types.h> |
| 13 | |
| 14 | struct log_site; |
| 15 | struct log_record; |
| 16 | |
| 17 | enum log_handle_flags : uint32_t { |
| 18 | LOG_HANDLE_PRINT = 1 << 0, /* emit to console immediately */ |
| 19 | LOG_HANDLE_IMPORTANT = 1 << 1, /* never drop / elevated visibility */ |
| 20 | LOG_HANDLE_RATELIMIT = 1 << 2, /* suppress floods */ |
| 21 | LOG_HANDLE_ONCE = 1 << 3, /* print only first occurrence */ |
| 22 | LOG_HANDLE_PANIC = 1 << 4, /* fatal if level >= ERROR */ |
| 23 | LOG_HANDLE_NO_NEWLINE = 1 << 5, |
| 24 | LOG_HANDLE_FLAGS_DEFAULT = 0, |
| 25 | }; |
| 26 | |
| 27 | enum log_level : uint8_t { |
| 28 | LOG_TRACE, |
| 29 | LOG_DEBUG, |
| 30 | LOG_INFO, |
| 31 | LOG_WARN, |
| 32 | LOG_ERROR, |
| 33 | }; |
| 34 | |
| 35 | enum log_site_flags : uint32_t { |
| 36 | LOG_SITE_PRINT = 1 << 0, /* print all logs in site */ |
| 37 | LOG_SITE_DROP_OLD = 1 << 1, /* overwrite oldest on overflow */ |
| 38 | LOG_SITE_NO_IRQ = 1 << 2, /* suppress in IRQ context */ |
| 39 | LOG_SITE_PANIC_VISIBLE = 1 << 3, |
| 40 | |
| 41 | /* All messages are internally copied, so the passed in pointer |
| 42 | * is not what ends up getting used, this is for pointer reuse/freeing |
| 43 | * after the pointer is passed into log() */ |
| 44 | LOG_SITE_DUP_MESSAGES = 1 << 4, /* If this is set, we also expect the |
| 45 | * msg_max_len of log_site_options |
| 46 | * to be set, else panic */ |
| 47 | LOG_SITE_NDJSON = 1 << 5, /* emit records directly to NDJSON wire */ |
| 48 | LOG_SITE_NONE = 0, |
| 49 | LOG_SITE_DEFAULT = LOG_SITE_DROP_OLD, |
| 50 | }; |
| 51 | |
| 52 | enum log_record_flags : uint16_t { |
| 53 | LOG_REC_FROM_IRQ = 1 << 0, |
| 54 | LOG_REC_TRUNCATED = 1 << 1, |
| 55 | }; |
| 56 | |
| 57 | /* Governs what to print */ |
| 58 | struct log_dump_options { |
| 59 | uint8_t min_level; |
| 60 | bool show_cpu : 1; |
| 61 | bool show_tid : 1; |
| 62 | bool show_irql : 1; |
| 63 | bool show_caller : 1; |
| 64 | bool resolve_symbols : 1; |
| 65 | bool clear_after_dump : 1; |
| 66 | }; |
| 67 | |
| 68 | struct log_handle { |
| 69 | void (*print)(const struct log_site *site, const struct log_record *rec, |
| 70 | void (*print)(const char *fmt, ...)); |
| 71 | enum log_handle_flags flags; |
| 72 | _Atomic uint32_t seen_internal; |
| 73 | _Atomic uint64_t last_ts_internal; |
| 74 | }; |
| 75 | |
| 76 | struct log_record { |
| 77 | time_ms_t timestamp; |
| 78 | cpu_id_t cpu; |
| 79 | uint32_t tid; |
| 80 | |
| 81 | const struct log_handle *handle; |
| 82 | enum log_level level; |
| 83 | enum bootstage boostage; |
| 84 | |
| 85 | uint16_t msg_len; |
| 86 | |
| 87 | const char *fmt; /* Becomes a pointer to the shadow_buf in cases where |
| 88 | * LOG_SITE_DUP_MESSAGES is set */ |
| 89 | uint8_t nargs; |
| 90 | uint64_t args[8]; |
| 91 | |
| 92 | char *caller_fn; |
| 93 | char *caller_file; |
| 94 | int32_t caller_line; |
| 95 | uintptr_t caller_pc; |
| 96 | enum log_record_flags flags; |
| 97 | enum irql logged_at_irql; |
| 98 | }; |
| 99 | |
| 100 | struct log_ring_slot { |
| 101 | _Atomic uint64_t seq; |
| 102 | struct log_record rec; |
| 103 | char *shadow_buf; /* With a len of msg_max_len */ |
| 104 | }; |
| 105 | |
| 106 | struct log_ringbuf { |
| 107 | struct log_ring_slot *slots; |
| 108 | |
| 109 | _Atomic uint64_t head; |
| 110 | _Atomic uint64_t tail; |
| 111 | }; |
| 112 | |
| 113 | /* Ephemeral argument passed in creation */ |
| 114 | struct log_site_options { |
| 115 | char *name; |
| 116 | enum log_site_flags flags; |
| 117 | size_t capacity; |
| 118 | size_t msg_max_len; /* only if LOG_SITE_DUP_MESSAGES on, |
| 119 | * will truncate trailing characters if strlen |
| 120 | * of the input fmt str is too long */ |
| 121 | |
| 122 | uint32_t enabled_mask; |
| 123 | struct log_dump_options dump_opts; |
| 124 | }; |
| 125 | |
| 126 | struct log_site { |
| 127 | struct list_head list; |
| 128 | char *name; |
| 129 | struct log_ringbuf rb; |
| 130 | uint32_t enabled_mask; /* Governs what actually goes in the site */ |
| 131 | size_t capacity; |
| 132 | |
| 133 | /* Only relevant for dynamic log sites */ |
| 134 | refcount_t refcount; |
| 135 | |
| 136 | size_t msg_max_len; |
| 137 | uint32_t dropped; /* Accumulation of all missed logs */ |
| 138 | enum log_site_flags flags; |
| 139 | struct log_dump_options dump_opts; /* If LOG_SITE_PRINT, use this */ |
| 140 | }; |
| 141 | |
| 142 | static inline const char *log_level_color(enum log_level l) { |
| 143 | switch (l) { |
| 144 | case LOG_INFO: return ANSI_GREEN; |
| 145 | case LOG_WARN: return ANSI_YELLOW; |
| 146 | case LOG_ERROR: return ANSI_RED; |
| 147 | case LOG_TRACE: return ANSI_BLUE; |
| 148 | case LOG_DEBUG: return ANSI_MAGENTA; |
| 149 | default: return ANSI_RESET; |
| 150 | } |
| 151 | } |
| 152 | |
| 153 | static inline bool log_handle_should_print(const struct log_handle *h, |
| 154 | const struct log_site *s, |
| 155 | uint8_t level) { |
| 156 | if (h->flags & LOG_HANDLE_PRINT) |
| 157 | return true; |
| 158 | |
| 159 | if (s && (s->flags & LOG_SITE_PRINT)) |
| 160 | return true; |
| 161 | |
| 162 | if ((h->flags & LOG_HANDLE_PANIC) && level >= LOG_ERROR) |
| 163 | return true; |
| 164 | |
| 165 | return false; |
| 166 | } |
| 167 | |
| 168 | static inline bool log_site_enabled(const struct log_site *ss, uint8_t level) { |
| 169 | if (!ss) |
| 170 | return true; |
| 171 | |
| 172 | return ss->enabled_mask & (1u << level); |
| 173 | } |
| 174 | |
| 175 | void log_emit_internal(struct log_site *, struct log_handle *, enum log_level, |
| 176 | const char *func, const char *fname, int32_t line, |
| 177 | uintptr_t ip, uint8_t nargs, char *fmt, ...); |
| 178 | void log_dump_site_with_opts(struct log_site *, struct log_dump_options opts); |
| 179 | void log_dump_site(struct log_site *site); |
| 180 | void log_dump_site_default(struct log_site *); |
| 181 | void log_dump_all(void); |
| 182 | void log_dump_panic(void); |
| 183 | void log_sites_init(void); |
| 184 | void log_site_free(struct log_site *site); |
| 185 | struct log_site *log_site_create(struct log_site_options opts); |
| 186 | void log_handle_init(struct log_handle *h, enum log_handle_flags f); |
| 187 | |
| 188 | static inline bool log_site_get(struct log_site *site) { |
| 189 | return refcount_inc_not_zero(rc: &site->refcount); |
| 190 | } |
| 191 | |
| 192 | static inline void log_site_put(struct log_site *site) { |
| 193 | if (refcount_dec_and_test(rc: &site->refcount)) |
| 194 | log_site_free(site); |
| 195 | } |
| 196 | |
| 197 | /* NOTE: RACY, only usable as a heuristic */ |
| 198 | static inline size_t log_site_message_count(struct log_site *site) { |
| 199 | uint64_t head = atomic_load_explicit(&site->rb.head, memory_order_acquire); |
| 200 | uint64_t tail = atomic_load_explicit(&site->rb.tail, memory_order_acquire); |
| 201 | |
| 202 | return head - tail; |
| 203 | } |
| 204 | |
| 205 | #define LOG_HANDLE_DEFAULT \ |
| 206 | (struct log_handle){.flags = LOG_HANDLE_FLAGS_DEFAULT, \ |
| 207 | .seen_internal = 0, \ |
| 208 | .last_ts_internal = 0} |
| 209 | |
| 210 | #define LOG_DUMP_DEFAULT \ |
| 211 | (struct log_dump_options) { \ |
| 212 | .min_level = LOG_TRACE, .show_cpu = true, .show_tid = true, \ |
| 213 | .show_irql = true, .show_caller = true, .resolve_symbols = true, \ |
| 214 | .clear_after_dump = false, \ |
| 215 | } |
| 216 | |
| 217 | #define LOG_DUMP_CONSOLE \ |
| 218 | (struct log_dump_options) { \ |
| 219 | .min_level = LOG_TRACE, .show_cpu = false, .show_tid = false, \ |
| 220 | .show_irql = false, .show_caller = false, .resolve_symbols = false, \ |
| 221 | .clear_after_dump = false, \ |
| 222 | } |
| 223 | |
| 224 | #define log_msg(lvl, fmt, ...) \ |
| 225 | log_emit_internal(LOG_SITE(global), LOG_HANDLE(global), lvl, __func__, \ |
| 226 | __FILE__, __LINE__, \ |
| 227 | (uintptr_t) __builtin_return_address(0), \ |
| 228 | PP_NARG(__VA_ARGS__), fmt, ##__VA_ARGS__) |
| 229 | |
| 230 | #define log_warn_once(fmt, ...) \ |
| 231 | do { \ |
| 232 | static bool done_internal_log = false; \ |
| 233 | if (!done_internal_log) { \ |
| 234 | log_msg(LOG_WARN, fmt, ##__VA_ARGS__); \ |
| 235 | done_internal_log = true; \ |
| 236 | } \ |
| 237 | } while (0) |
| 238 | |
| 239 | #define log_global(handle, lvl, fmt, ...) \ |
| 240 | log_emit_internal(LOG_SITE(global), handle, lvl, __func__, __FILE__, \ |
| 241 | __LINE__, (uintptr_t) __builtin_return_address(0), \ |
| 242 | PP_NARG(__VA_ARGS__), fmt, ##__VA_ARGS__) |
| 243 | |
| 244 | #define log(site, handle, lvl, fmt, ...) \ |
| 245 | log_emit_internal(site, handle, lvl, __func__, __FILE__, __LINE__, \ |
| 246 | (uintptr_t) __builtin_return_address(0), \ |
| 247 | PP_NARG(__VA_ARGS__), fmt, ##__VA_ARGS__) |
| 248 | |
| 249 | #define log_err(site, handle, fmt, ...) \ |
| 250 | log(site, handle, LOG_ERROR, fmt, ##__VA_ARGS__) |
| 251 | #define log_warn(site, handle, fmt, ...) \ |
| 252 | log(site, handle, LOG_WARN, fmt, ##__VA_ARGS__) |
| 253 | #define log_info(site, handle, fmt, ...) \ |
| 254 | log(site, handle, LOG_INFO, fmt, ##__VA_ARGS__) |
| 255 | #define log_debug(site, handle, fmt, ...) \ |
| 256 | log(site, handle, LOG_DEBUG, fmt, ##__VA_ARGS__) |
| 257 | #define log_trace(site, handle, fmt, ...) \ |
| 258 | log(site, handle, LOG_TRACE, fmt, ##__VA_ARGS__) |
| 259 | |
| 260 | #define log_err_global(handle, fmt, ...) \ |
| 261 | log_global(handle, LOG_ERROR, fmt, ##__VA_ARGS__) |
| 262 | #define log_warn_global(handle, fmt, ...) \ |
| 263 | log_global(handle, LOG_WARN, fmt, ##__VA_ARGS__) |
| 264 | #define log_info_global(handle, fmt, ...) \ |
| 265 | log_global(handle, LOG_INFO, fmt, ##__VA_ARGS__) |
| 266 | #define log_debug_global(handle, fmt, ...) \ |
| 267 | log_global(handle, LOG_DEBUG, fmt, ##__VA_ARGS__) |
| 268 | #define log_trace_global(handle, fmt, ...) \ |
| 269 | log_global(handle, LOG_TRACE, fmt, ##__VA_ARGS__) |
| 270 | |
| 271 | #define LOG_SITE_CAPACITY_DEFAULT 128 /* good enough for most purposes */ |
| 272 | #define LOG_SITE_EXTERN(name) extern struct log_site __log_site_##name |
| 273 | |
| 274 | /* For static ones */ |
| 275 | #define LOG_SITE_LEVEL(l) (1u << l) |
| 276 | #define LOG_SITE_ALL UINT32_MAX |
| 277 | |
| 278 | #define LOG_SITE_DECLARE(_name, ...) \ |
| 279 | LINKER_SECTION_ATTRIBUTE(log_sites) \ |
| 280 | struct log_site __log_site_##_name = {.capacity = \ |
| 281 | LOG_SITE_CAPACITY_DEFAULT, \ |
| 282 | .enabled_mask = LOG_SITE_ALL, \ |
| 283 | .dump_opts = LOG_DUMP_CONSOLE, \ |
| 284 | .name = #_name, \ |
| 285 | __VA_ARGS__} |
| 286 | |
| 287 | #define LOG_SITE_DECLARE_PRINT(_name, ...) \ |
| 288 | LINKER_SECTION_ATTRIBUTE(log_sites) \ |
| 289 | struct log_site __log_site_##_name = { \ |
| 290 | .name = #_name, \ |
| 291 | .flags = LOG_SITE_DEFAULT, \ |
| 292 | .capacity = LOG_SITE_CAPACITY_DEFAULT, \ |
| 293 | .enabled_mask = LOG_SITE_ALL, \ |
| 294 | .dump_opts = LOG_DUMP_CONSOLE, \ |
| 295 | __VA_ARGS__} /* Rest will get initialized at boot */ |
| 296 | |
| 297 | #define LOG_SITE(name) (&(__log_site_##name)) |
| 298 | |
| 299 | #define LOG_HANDLE_SUBSYSTEM_NONE NULL |
| 300 | #define LOG_HANDLE_EXTERN(name) extern struct log_handle __log_handle_##name |
| 301 | |
| 302 | #define LOG_HANDLE_DECLARE(_name, ...) \ |
| 303 | struct log_handle __log_handle_##_name = { \ |
| 304 | .seen_internal = 0, .last_ts_internal = 0, __VA_ARGS__} |
| 305 | |
| 306 | #define LOG_HANDLE_DECLARE_PRINT(n, ...) \ |
| 307 | struct log_handle __log_handle_##n = {.flags = LOG_HANDLE_PRINT, \ |
| 308 | .seen_internal = 0, \ |
| 309 | .last_ts_internal = 0, \ |
| 310 | __VA_ARGS__} |
| 311 | |
| 312 | #define LOG_HANDLE(name) &(__log_handle_##name) |
| 313 | |
| 314 | LINKER_SECTION_DEFINE(struct log_site, log_sites); |
| 315 | |
| 316 | LOG_HANDLE_EXTERN(global); |
| 317 | LOG_SITE_EXTERN(global); |
| 318 | |