Make the debug logging functions consistent

They now all output the same format of:
[time since program start] msg

glfw/cocoa_window.m

@@ -36,7 +36,7 @@
 #include <float.h>
 #include <string.h>
 
-#define debug(...) if (_glfw.hints.init.debugRendering) fprintf(stderr, __VA_ARGS__);
+#define debug debug_rendering
 
 static const char*
 polymorphic_string_as_utf8(id string) {

glfw/ibus_glfw.c

@@ -46,8 +46,7 @@
 #include "internal.h"
 #include "ibus_glfw.h"
 
-#undef debug
-#define debug(...) if (_glfw.hints.init.debugKeyboard) printf(__VA_ARGS__);
+#define debug debug_input
 static const char IBUS_SERVICE[]         = "org.freedesktop.IBus";
 static const char IBUS_PATH[]            = "/org/freedesktop/IBus";
 static const char IBUS_INTERFACE[]       = "org.freedesktop.IBus";

glfw/internal.h

@@ -883,3 +883,5 @@ char* _glfw_strdup(const char* source);
 
 void _glfw_free_clipboard_data(_GLFWClipboardData *cd);
 
+#define debug_rendering(...) if (_glfw.hints.init.debugRendering) { timed_debug_print(__VA_ARGS__); }
+#define debug_input(...) if (_glfw.hints.init.debugKeyboard) { timed_debug_print(__VA_ARGS__); }

glfw/wl_client_side_decorations.c

@@ -14,6 +14,7 @@
 #include <stdlib.h>
 
 #define decs window->wl.decorations
+#define debug debug_rendering
 
 #define ARGB(a, r, g, b) (((a) << 24) | ((r) << 16) | ((g) << 8) | (b))
 #define A(x) (((x) >> 24) & 0xff)

glfw/wl_init.c

@@ -56,6 +56,7 @@
 #include <linux/input.h>
 #endif
 
+#define debug debug_rendering
 
 static int min(int n1, int n2)
 {

glfw/wl_platform.h

@@ -413,7 +413,6 @@ int _glfwWaylandIntegerWindowScale(_GLFWwindow*);
 void animateCursorImage(id_type timer_id, void *data);
 struct wl_cursor* _glfwLoadCursor(GLFWCursorShape, struct wl_cursor_theme*);
 void destroy_data_offer(_GLFWWaylandDataOffer*);
-#define debug(...) if (_glfw.hints.init.debugRendering) { fprintf(stderr, "[%.3f] ", monotonic_t_to_s_double(monotonic())); fprintf(stderr, __VA_ARGS__); }
 
 typedef struct wayland_cursor_shape {
     int which; const char *name;

glfw/wl_text_input.c

@@ -10,8 +10,7 @@
 #include "wayland-text-input-unstable-v3-client-protocol.h"
 #include <stdlib.h>
 #include <string.h>
-#undef debug
-#define debug(...) if (_glfw.hints.init.debugKeyboard) printf(__VA_ARGS__);
+#define debug debug_input
 
 static struct zwp_text_input_v3*                  text_input;
 static struct zwp_text_input_manager_v3*          text_input_manager;

glfw/wl_window.c

@@ -41,6 +41,7 @@
 #include <fcntl.h>
 #include <sys/mman.h>
 
+#define debug debug_rendering
 
 static GLFWLayerShellConfig layer_shell_config_for_next_window = {0};
 
@@ -636,7 +637,7 @@ xdgToplevelHandleConfigure(void* data,
 
     wl_array_for_each(state, states) {
         switch (*state) {
-#define C(x) case XDG_##x: new_states |= x; if (_glfw.hints.init.debugRendering) fprintf(stderr, "%s ", #x); break
+#define C(x) case XDG_##x: new_states |= x; debug("%s ", #x); break
             C(TOPLEVEL_STATE_RESIZING);
             C(TOPLEVEL_STATE_MAXIMIZED);
             C(TOPLEVEL_STATE_FULLSCREEN);
@@ -651,7 +652,7 @@ xdgToplevelHandleConfigure(void* data,
 #undef C
         }
     }
-    if (_glfw.hints.init.debugRendering) fprintf(stderr, "\n");
+    debug("\n");
     if (new_states & TOPLEVEL_STATE_RESIZING) {
         if (width) window->wl.user_requested_content_size.width = width;
         if (height) window->wl.user_requested_content_size.height = height;

glfw/xkb_glfw.c

@@ -33,8 +33,7 @@
 #include <X11/XKBlib.h>
 #endif
 
-#undef debug
-#define debug(...) if (_glfw.hints.init.debugKeyboard) fprintf(stderr, __VA_ARGS__);
+#define debug debug_input
 
 #ifdef XKB_HAS_NO_UTF32
 #include "xkb-compat-shim.h"
@@ -940,7 +939,7 @@ glfw_xkb_handle_key_event(_GLFWwindow *window, _GLFWXKBData *xkb, xkb_keycode_t
         glfw_ev.alternate_key = glfw_key_for_sym(alternate_xkb_sym);
         if (glfw_ev.alternate_key) debug(" alternate_key: %d (%s)", glfw_ev.alternate_key, _glfwGetKeyName(glfw_ev.alternate_key))
     }
-    debug("%s", "\n");
+    debug("\n");
 
     // NOTE: On linux, the reported native key identifier is the XKB keysym value.
     // Do not confuse `native_key` with `xkb_keycode` (the native keycode reported for the

kitty/boss.py

@@ -150,6 +150,7 @@
     sanitize_url_for_dispay_to_user,
     single_instance,
     startup_notification_handler,
+    timed_debug_print,
     which,
 )
 from .window import CommandOutput, CwdRequest, Window
@@ -1518,7 +1519,7 @@ def report_match(f: Callable[..., Any]) -> None:
             if self.args.debug_keyboard:
                 prefix = '\n' if dispatch_type == 'KeyPress' else ''
                 end = ', ' if dispatch_type == 'KeyPress' else '\n'
-                print(f'{prefix}\x1b[35m{dispatch_type}\x1b[m matched action:', func_name(f), end=end, flush=True)
+                timed_debug_print(f'{prefix}\x1b[35m{dispatch_type}\x1b[m matched action:', func_name(f), end=end)
 
         if key_action is not None:
             f = getattr(self, key_action.func, None)

kitty/child-monitor.c

@@ -27,7 +27,7 @@ extern PyTypeObject Screen_Type;
 #endif
 
 #ifdef DEBUG_EVENT_LOOP
-#define EVDBG(...) log_event(__VA_ARGS__)
+#define EVDBG(...) timed_debug_print(__VA_ARGS__)
 #else
 #define EVDBG(...)
 #endif

kitty/core_text.m

@@ -21,7 +21,7 @@
 #import <Foundation/NSString.h>
 #import <Foundation/NSDictionary.h>
 
-#define debug(...) if (global_state.debug_font_fallback) { fprintf(stderr, __VA_ARGS__); fflush(stderr); }
+#define debug debug_fonts
 
 typedef struct {
     PyObject_HEAD

kitty/data-types.c

@@ -416,6 +416,17 @@ py_monotonic(PyObject *self UNUSED, PyObject *args UNUSED) {
     return PyFloat_FromDouble(monotonic_t_to_s_double(monotonic()));
 }
 
+static PyObject*
+py_timed_debug_print(PyObject *self UNUSED, PyObject *args) {
+    const char *payload; Py_ssize_t sz;
+    if (!PyArg_ParseTuple(args, "s#", &payload, &sz)) return NULL;
+    const char *fmt = "%.*s";
+    if (sz && payload[sz-1] == '\n') { fmt = "%.*s\n"; sz--; }
+    timed_debug_print(fmt, sz, payload);
+    Py_RETURN_NONE;
+}
+
+
 static PyMethodDef module_methods[] = {
     METHODB(replace_c0_codes_except_nl_space_tab, METH_O),
     {"wcwidth", (PyCFunction)wcwidth_wrap, METH_O, ""},
@@ -439,6 +450,7 @@ static PyMethodDef module_methods[] = {
     {"wrapped_kitten_names", (PyCFunction)wrapped_kittens, METH_NOARGS, ""},
     {"terminfo_data", (PyCFunction)py_terminfo_data, METH_NOARGS, ""},
     {"monotonic", (PyCFunction)py_monotonic, METH_NOARGS, ""},
+    {"timed_debug_print", (PyCFunction)py_timed_debug_print, METH_VARARGS, ""},
     {"find_in_memoryview", (PyCFunction)find_in_memoryview, METH_VARARGS, ""},
 #ifdef __APPLE__
     METHODB(user_cache_dir, METH_NOARGS),

kitty/data-types.h

@@ -426,7 +426,6 @@ void play_canberra_sound(const char *which_sound, const char *event_id, bool is_
 SPRITE_MAP_HANDLE alloc_sprite_map(unsigned int, unsigned int);
 SPRITE_MAP_HANDLE free_sprite_map(SPRITE_MAP_HANDLE);
 const char* get_hyperlink_for_id(const HYPERLINK_POOL_HANDLE, hyperlink_id_type id, bool only_url);
-void log_event(const char *format, ...) __attribute__((format(printf, 1, 2)));
 
 #define memset_array(array, val, count) if ((count) > 0) { \
     (array)[0] = (val); \

kitty/fast_data_types.pyi

@@ -1578,3 +1578,4 @@ def replace_c0_codes_except_nl_space_tab(text: Union[bytes, memoryview, bytearra
 def terminfo_data() -> bytes:...
 def wayland_compositor_data() -> Tuple[int, Optional[str]]:...
 def monotonic() -> float: ...
+def timed_debug_print(x: str) -> None: ...

kitty/fonts.c

@@ -15,7 +15,7 @@
 #define MISSING_GLYPH (NUM_UNDERLINE_STYLES + 2)
 #define MAX_NUM_EXTRA_GLYPHS_PUA 4u
 
-#define debug(...) if (global_state.debug_font_fallback) { fprintf(stderr, __VA_ARGS__); fflush(stderr); }
+#define debug debug_fonts
 
 static PyObject *python_send_to_gpu_impl = NULL;
 #define current_send_sprite_to_gpu(...) (python_send_to_gpu_impl ? python_send_to_gpu(__VA_ARGS__) : send_sprite_to_gpu(__VA_ARGS__))
@@ -455,16 +455,16 @@ has_cell_text(PyObject *face, CPUCell *cell) {
 
 static void
 output_cell_fallback_data(CPUCell *cell, bool bold, bool italic, bool emoji_presentation, PyObject *face) {
-    printf("U+%x ", cell->ch);
+    debug("U+%x ", cell->ch);
     for (unsigned i = 0; i < arraysz(cell->cc_idx) && cell->cc_idx[i]; i++) {
-        printf("U+%x ", codepoint_for_mark(cell->cc_idx[i]));
+        debug("U+%x ", codepoint_for_mark(cell->cc_idx[i]));
     }
-    if (bold) printf("bold ");
-    if (italic) printf("italic ");
-    if (emoji_presentation) printf("emoji_presentation ");
-    if (PyLong_Check(face)) printf("using previous fallback font at index: ");
-    PyObject_Print(face, stdout, 0);
-    printf("\n");
+    if (bold) debug("bold ");
+    if (italic) debug("italic ");
+    if (emoji_presentation) debug("emoji_presentation ");
+    if (PyLong_Check(face)) debug("using previous fallback font at index: ");
+    PyObject_Print(face, stderr, 0);
+    debug("\n");
 }
 
 PyObject*

kitty/glfw.c

@@ -31,7 +31,7 @@ extern void cocoa_update_menu_bar_title(PyObject*);
 extern size_t cocoa_get_workspace_ids(void *w, size_t *workspace_ids, size_t array_sz);
 extern monotonic_t cocoa_cursor_blink_interval(void);
 
-#define debug(...) if (global_state.debug_rendering) { fprintf(stderr, "[%.3f] ", monotonic_t_to_s_double(monotonic())); fprintf(stderr, __VA_ARGS__); }
+#define debug debug_rendering
 
 typedef struct mouse_cursor {
     GLFWcursor *glfw;
@@ -168,22 +168,6 @@ update_os_window_viewport(OSWindow *window, bool notify_boss) {
     }
 }
 
-void
-log_event(const char *format, ...) {
-    if (format)
-    {
-        va_list vl;
-
-        fprintf(stderr, "[%.3f] ", monotonic_t_to_s_double(monotonic()));
-        va_start(vl, format);
-        vfprintf(stderr, format, vl);
-        va_end(vl);
-        fprintf(stderr, "\n");
-    }
-
-}
-
-
 // callbacks {{{
 
 void
@@ -512,9 +496,7 @@ static id_type focus_counter = 0;
 static void
 window_focus_callback(GLFWwindow *w, int focused) {
     if (!set_callback_window(w)) return;
-    if (OPT(debug_keyboard)) {
-        fprintf(stderr, "\x1b[35mon_focus_change\x1b[m: window id: 0x%llu focused: %d\n", global_state.callback_os_window->id, focused);
-    }
+    debug_input("\x1b[35mon_focus_change\x1b[m: window id: 0x%llu focused: %d\n", global_state.callback_os_window->id, focused);
     // There exist some numbnut Wayland compositors, like kwin, that send mouse
     // press events before focus gained events. So only clear the active drag
     // window if it is not the focused window. See https://github.com/kovidgoyal/kitty/issues/6095

kitty/keys.h

@@ -13,7 +13,7 @@
 
 #define KEY_BUFFER_SIZE 128
 #define SEND_TEXT_TO_CHILD INT_MIN
-#define debug(...) if (OPT(debug_keyboard)) { fprintf(stderr, __VA_ARGS__); fflush(stderr); }
+#define debug debug_input
 
 int
 encode_glfw_key_event(const GLFWkeyevent *e, const bool cursor_key_mode, const unsigned flags, char *output);

kitty/monotonic.h

@@ -67,8 +67,14 @@ init_monotonic(void) {
     monotonic_start_time = monotonic_();
 }
 
+extern int timed_debug_print(const char *fmt, ...) __attribute__((format(printf, 1, 2)));
+
 #ifdef MONOTONIC_IMPLEMENTATION
 #include <time.h>
+#include <stdarg.h>
+#include <stdio.h>
+#include <string.h>
+
 monotonic_t monotonic_start_time = 0;
 
 static inline monotonic_t
@@ -88,4 +94,17 @@ monotonic_(void) {
 #endif
     return calc_nano_time(ts);
 }
+
+int
+timed_debug_print(const char *fmt, ...) {
+    int result;
+    static int starting_print = 1;
+    if (starting_print) fprintf(stderr, "[%.3f] ", monotonic_t_to_s_double(monotonic()));
+    va_list args;
+    va_start(args, fmt);
+    result = vfprintf(stderr, fmt, args);
+    va_end(args);
+    starting_print = fmt && strchr(fmt, '\n') != NULL;
+    return result;
+}
 #endif

kitty/mouse.c

@@ -18,7 +18,7 @@ extern PyTypeObject Screen_Type;
 
 static MouseShape mouse_cursor_shape = TEXT_POINTER;
 typedef enum MouseActions { PRESS, RELEASE, DRAG, MOVE } MouseAction;
-#define debug(...) if (OPT(debug_keyboard)) printf(__VA_ARGS__);
+#define debug debug_input
 
 // Encoding of mouse events {{{
 #define SHIFT_INDICATOR  (1 << 2)

kitty/screen.c

@@ -1168,9 +1168,7 @@ screen_current_key_encoding_flags(Screen *self) {
 void
 screen_report_key_encoding_flags(Screen *self) {
     char buf[16] = {0};
-    if (OPT(debug_keyboard)) {
-        debug("\x1b[35mReporting key encoding flags: %u\x1b[39m\n", screen_current_key_encoding_flags(self));
-    }
+    debug_input("\x1b[35mReporting key encoding flags: %u\x1b[39m\n", screen_current_key_encoding_flags(self));
     snprintf(buf, sizeof(buf), "?%uu", screen_current_key_encoding_flags(self));
     write_escape_code_to_child(self, ESC_CSI, buf);
 }
@@ -1186,9 +1184,7 @@ screen_set_key_encoding_flags(Screen *self, uint32_t val, uint32_t how) {
     else if (how == 2) self->key_encoding_flags[idx] |= q;
     else if (how == 3) self->key_encoding_flags[idx] &= ~q;
     self->key_encoding_flags[idx] |= 0x80;
-    if (OPT(debug_keyboard)) {
-        debug("\x1b[35mSet key encoding flags to: %u\x1b[39m\n", screen_current_key_encoding_flags(self));
-    }
+    debug_input("\x1b[35mSet key encoding flags to: %u\x1b[39m\n", screen_current_key_encoding_flags(self));
 }
 
 void
@@ -1202,9 +1198,7 @@ screen_push_key_encoding_flags(Screen *self, uint32_t val) {
     if (current_idx == sz - 1) memmove(self->key_encoding_flags, self->key_encoding_flags + 1, (sz - 1) * sizeof(self->main_key_encoding_flags[0]));
     else self->key_encoding_flags[current_idx++] |= 0x80;
     self->key_encoding_flags[current_idx] = 0x80 | q;
-    if (OPT(debug_keyboard)) {
-        debug("\x1b[35mPushed key encoding flags to: %u\x1b[39m\n", screen_current_key_encoding_flags(self));
-    }
+    debug_input("\x1b[35mPushed key encoding flags to: %u\x1b[39m\n", screen_current_key_encoding_flags(self));
 }
 
 void
@@ -1212,9 +1206,7 @@ screen_pop_key_encoding_flags(Screen *self, uint32_t num) {
     for (unsigned i = arraysz(self->main_key_encoding_flags); num && i-- > 0; ) {
         if (self->key_encoding_flags[i] & 0x80) { num--; self->key_encoding_flags[i] = 0; }
     }
-    if (OPT(debug_keyboard)) {
-        debug("\x1b[35mPopped key encoding flags to: %u\x1b[39m\n", screen_current_key_encoding_flags(self));
-    }
+    debug_input("\x1b[35mPopped key encoding flags to: %u\x1b[39m\n", screen_current_key_encoding_flags(self));
 }
 
 // }}}

kitty/state.h

@@ -11,6 +11,9 @@
 #include "window_logo.h"
 
 #define OPT(name) global_state.opts.name
+#define debug_rendering(...) if (global_state.debug_rendering) { timed_debug_print(__VA_ARGS__); }
+#define debug_input(...) if (OPT(debug_keyboard)) { timed_debug_print(__VA_ARGS__); }
+#define debug_fonts(...) if (global_state.debug_font_fallback) { timed_debug_print(__VA_ARGS__); }
 
 typedef enum { LEFT_EDGE, TOP_EDGE, RIGHT_EDGE, BOTTOM_EDGE } Edge;
 typedef enum { REPEAT_MIRROR, REPEAT_CLAMP, REPEAT_DEFAULT } RepeatStrategy;

kitty/utils.py

@@ -43,6 +43,7 @@
     ssh_control_master_template,
 )
 from .fast_data_types import WINDOW_FULLSCREEN, WINDOW_MAXIMIZED, WINDOW_MINIMIZED, WINDOW_NORMAL, Color, Shlex, get_options, monotonic, open_tty
+from .fast_data_types import timed_debug_print as _timed_debug_print
 from .rgb import to_color
 from .types import run_once
 from .typing import AddressFamily, PopenType, Socket, StartupCtx
@@ -1236,3 +1237,7 @@ def shlex_split_with_positions(text: str) -> Iterator[Tuple[int, str]]:
     s = Shlex(text)
     while (q := s.next_word())[0] > -1:
         yield q
+
+
+def timed_debug_print(*a: Any, sep: str = ' ', end: str = '\n') -> None:
+    _timed_debug_print(sep.join(map(str, a)) + end)