From c7506496dad6778ad0e98b5ae7666c6baab220a3 Mon Sep 17 00:00:00 2001 From: Kovid Goyal Date: Sun, 4 Mar 2018 11:55:47 +0530 Subject: [PATCH] Unify error logging between python and C --- kitty/child-monitor.c | 18 ++++++++-------- kitty/data-types.c | 2 ++ kitty/data-types.h | 3 ++- kitty/fonts.c | 4 ++-- kitty/gl.h | 2 +- kitty/glfw.c | 16 +++++++------- kitty/graphics.c | 2 +- kitty/logging.c | 50 +++++++++++++++++++++++++++++++++++++++++++ kitty/parser.c | 2 +- kitty/screen.c | 4 ++-- kitty/shaders.c | 4 ++-- kitty/utils.py | 7 +++--- 12 files changed, 83 insertions(+), 31 deletions(-) create mode 100644 kitty/logging.c diff --git a/kitty/child-monitor.c b/kitty/child-monitor.c index 43fa11dde..2d8652a5c 100644 --- a/kitty/child-monitor.c +++ b/kitty/child-monitor.c @@ -251,7 +251,7 @@ schedule_write_to_child(unsigned long id, const char *data, size_t sz) { size_t space_left = screen->write_buf_sz - screen->write_buf_used; if (space_left < sz) { if (screen->write_buf_used + sz > 100 * 1024 * 1024) { - fprintf(stderr, "Too much data being sent to child with id: %lu, ignoring it\n", id); + log_error("Too much data being sent to child with id: %lu, ignoring it", id); screen_mutex(unlock, write); break; } @@ -411,7 +411,7 @@ pty_resize(int fd, struct winsize *dim) { if (ioctl(fd, TIOCSWINSZ, dim) == -1) { if (errno == EINTR) continue; if (errno != EBADF && errno != ENOTTY) { - fprintf(stderr, "Failed to resize tty associated with fd: %d with error: %s", fd, strerror(errno)); + log_error("Failed to resize tty associated with fd: %d with error: %s", fd, strerror(errno)); return false; } } @@ -439,7 +439,7 @@ resize_pty(ChildMonitor *self, PyObject *args) { if (fd == -1) FIND(add_queue, add_queue_count); if (fd != -1) { if (!pty_resize(fd, &dim)) PyErr_SetFromErrno(PyExc_OSError); - } else fprintf(stderr, "Failed to send resize signal to child with id: %lu (children count: %u) (add queue: %zu)\n", window_id, self->count, add_queue_count); + } else log_error("Failed to send resize signal to child with id: %lu (children count: %u) (add queue: %zu)", window_id, self->count, add_queue_count); children_mutex(unlock); if (PyErr_Occurred()) return NULL; Py_RETURN_NONE; @@ -689,7 +689,7 @@ thread_write(void *x) { set_thread_name("KittyWriteStdin"); FILE *f = fdopen(data->fd, "w"); if (fwrite(data->buf, 1, data->sz, f) != data->sz) { - fprintf(stderr, "Failed to write all data\n"); + log_error("Failed to write all data"); } fclose(f); free_twd(data); @@ -948,7 +948,7 @@ io_loop(void *data) { children_mutex(lock); children[i].needs_removal = true; children_mutex(unlock); - fprintf(stderr, "The child %lu had its fd unexpectedly closed\n", children[i].id); + log_error("The child %lu had its fd unexpectedly closed", children[i].id); } } #ifdef DEBUG_POLL_EVENTS @@ -1029,7 +1029,7 @@ read_from_peer(ChildMonitor *self, int s) { bool read_finished = false; for (size_t i = 0; i < talk_data.num_reads; i++) { PeerReadData *rd = talk_data.reads + i; -#define failed(msg) { read_finished = true; fprintf(stderr, "%s\n", msg); rd->finished = true; rd->close_socket = true; break; } +#define failed(msg) { read_finished = true; log_error("%s", msg); rd->finished = true; rd->close_socket = true; break; } if (rd->fd == s) { if (rd->used >= rd->capacity) { if (rd->capacity >= 1024 * 1024) failed("Ignoring too large message from peer"); @@ -1064,7 +1064,7 @@ write_to_peer(int fd) { bool write_finished = false; for (size_t i = 0; i < talk_data.num_writes; i++) { PeerWriteData *wd = talk_data.writes + i; -#define failed(msg) { write_finished = true; fprintf(stderr, "%s\n", msg); wd->finished = true; break; } +#define failed(msg) { write_finished = true; log_error("%s", msg); wd->finished = true; break; } if (wd->fd == fd) { ssize_t n = send(fd, wd->data + wd->pos, wd->sz - wd->pos, MSG_NOSIGNAL); if (n == 0) { failed("send() to peer failed to send any data"); } @@ -1154,7 +1154,7 @@ move_queued_writes() { talk_data.writes[talk_data.num_writes++] = *src; talk_data.num_talk_fds++; } else { - fprintf(stderr, "Cannot send response to peer, too many peers\n"); + log_error("Cannot send response to peer, too many peers"); free(src->data); nuke_socket(src->fd); } *src = empty_pwd; @@ -1215,7 +1215,7 @@ add_peer_writer(int fd, const char* msg, size_t msg_sz) { talk_data.queued_writes[talk_data.num_queued_writes++].fd = fd; ok = true; } - } else fprintf(stderr, "Cannot send response to peer, too many peers\n"); + } else log_error("Cannot send response to peer, too many peers"); peer_mutex(unlock); return ok; } diff --git a/kitty/data-types.c b/kitty/data-types.c index 37a16cac2..bb3f2dbe2 100644 --- a/kitty/data-types.c +++ b/kitty/data-types.c @@ -174,6 +174,7 @@ extern bool init_graphics(PyObject *module); extern bool init_shaders(PyObject *module); extern bool init_mouse(PyObject *module); extern bool init_kittens(PyObject *module); +extern bool init_logging(PyObject *module); #ifdef __APPLE__ extern int init_CoreText(PyObject *); extern bool init_cocoa(PyObject *module); @@ -193,6 +194,7 @@ PyInit_fast_data_types(void) { #endif if (m != NULL) { + if (!init_logging(m)) return NULL; if (!init_LineBuf(m)) return NULL; if (!init_HistoryBuf(m)) return NULL; if (!init_Line(m)) return NULL; diff --git a/kitty/data-types.h b/kitty/data-types.h index 78e22784f..52df8d4e1 100644 --- a/kitty/data-types.h +++ b/kitty/data-types.h @@ -26,7 +26,8 @@ #define xstr(s) str(s) #define str(s) #s #define arraysz(x) (sizeof(x)/sizeof(x[0])) -#define fatal(...) { fprintf(stderr, __VA_ARGS__); fprintf(stderr, "\n"); exit(EXIT_FAILURE); } +void log_error(const char *fmt, ...); +#define fatal(...) { log_error(__VA_ARGS__); exit(EXIT_FAILURE); } typedef unsigned long long id_type; typedef uint32_t char_type; diff --git a/kitty/fonts.c b/kitty/fonts.c index fbb13293c..235b925c2 100644 --- a/kitty/fonts.c +++ b/kitty/fonts.c @@ -362,7 +362,7 @@ output_cell_fallback_data(Cell *cell, bool bold, bool italic, bool emoji_present static inline ssize_t load_fallback_font(Cell *cell, bool bold, bool italic, bool emoji_presentation) { - if (fonts.fallback_fonts_count > 100) { fprintf(stderr, "Too many fallback fonts\n"); return MISSING_FONT; } + if (fonts.fallback_fonts_count > 100) { log_error("Too many fallback fonts"); return MISSING_FONT; } ssize_t f; if (bold) f = fonts.italic_font_idx > 0 ? fonts.bi_font_idx : fonts.bold_font_idx; @@ -765,7 +765,7 @@ shape_run(Cell *first_cell, index_type num_cells, Font *font) { if (num_cells_consumed) { if (num_cells_consumed > MAX_GLYPHS_IN_GROUP) { // Nasty, a single glyph used more than MAX_GLYPHS_IN_GROUP cells, we cannot render this case correctly - fprintf(stderr, "The glyph: %u needs more than %u cells, cannot render it\n", glyph_id, MAX_GLYPHS_IN_GROUP); + log_error("The glyph: %u needs more than %u cells, cannot render it", glyph_id, MAX_GLYPHS_IN_GROUP); current_group->num_glyphs--; while (num_cells_consumed) { G(group_idx)++; current_group = G(groups) + G(group_idx); diff --git a/kitty/gl.h b/kitty/gl.h index 780070fec..4d7330cf8 100644 --- a/kitty/gl.h +++ b/kitty/gl.h @@ -117,7 +117,7 @@ compile_shader(GLenum shader_type, const char *source) { if (ret != GL_TRUE) { GLsizei len; glGetShaderInfoLog(shader_id, sizeof(glbuf), &len, glbuf); - fprintf(stderr, "Failed to compile GLSL shader!\n%s", glbuf); + log_error("Failed to compile GLSL shader!\n%s", glbuf); glDeleteShader(shader_id); PyErr_SetString(PyExc_ValueError, "Failed to compile shader"); return 0; diff --git a/kitty/glfw.c b/kitty/glfw.c index 78a9fe232..5f8fd36d6 100644 --- a/kitty/glfw.c +++ b/kitty/glfw.c @@ -82,7 +82,7 @@ framebuffer_size_callback(GLFWwindow *w, int width, int height) { OSWindow *window = global_state.callback_os_window; window->has_pending_resizes = true; global_state.has_pending_resizes = true; window->last_resize_event_at = monotonic(); - } else fprintf(stderr, "Ignoring resize request for tiny size: %dx%d\n", width, height); + } else log_error("Ignoring resize request for tiny size: %dx%d", width, height); global_state.callback_os_window = NULL; } @@ -340,7 +340,7 @@ create_os_window(PyObject UNUSED *self, PyObject *args) { glfwWindowHint(GLFW_TRANSPARENT_FRAMEBUFFER, want_semi_transparent); GLFWwindow *glfw_window = glfwCreateWindow(width, height, title, NULL, global_state.num_os_windows ? global_state.os_windows[0].handle : NULL); if (glfw_window == NULL) { - fprintf(stderr, "Failed to create a window at size: %dx%d, using a standard size instead.\n", width, height); + log_error("Failed to create a window at size: %dx%d, using a standard size instead.", width, height); glfw_window = glfwCreateWindow(640, 400, title, NULL, global_state.num_os_windows ? global_state.os_windows[0].handle : NULL); } if (glfw_window == NULL) { PyErr_SetString(PyExc_ValueError, "Failed to create GLFWwindow"); return NULL; } @@ -382,7 +382,7 @@ create_os_window(PyObject UNUSED *self, PyObject *args) { #ifdef __APPLE__ if (OPT(macos_hide_titlebar)) { if (glfwGetCocoaWindow) { if (!cocoa_make_window_resizable(glfwGetCocoaWindow(glfw_window))) { PyErr_Print(); } } - else fprintf(stderr, "Failed to load glfwGetCocoaWindow\n"); + else log_error("Failed to load glfwGetCocoaWindow"); } cocoa_set_titlebar_color(glfwGetCocoaWindow(glfw_window)); #endif @@ -394,7 +394,7 @@ create_os_window(PyObject UNUSED *self, PyObject *args) { if (want_semi_transparent && !w->is_semi_transparent) { static bool warned = false; if (!warned) { - fprintf(stderr, "Failed to enable transparency. This happens when your desktop environment does not support compositing.\n"); + log_error("Failed to enable transparency. This happens when your desktop environment does not support compositing."); warned = true; } } @@ -459,7 +459,7 @@ destroy_os_window(OSWindow *w) { // Global functions {{{ static void error_callback(int error, const char* description) { - fprintf(stderr, "[glfw error %d]: %s\n", error, description); + log_error("[glfw error %d]: %s", error, description); } @@ -679,7 +679,7 @@ static PyObject* x11_display(PyObject UNUSED *self) { if (glfwGetX11Display) { return PyLong_FromVoidPtr(glfwGetX11Display()); - } else fprintf(stderr, "Failed to load glfwGetX11Display\n"); + } else log_error("Failed to load glfwGetX11Display"); Py_RETURN_NONE; } @@ -701,7 +701,7 @@ static PyObject* get_primary_selection(PyObject UNUSED *self) { if (glfwGetX11SelectionString) { return Py_BuildValue("y", glfwGetX11SelectionString()); - } else fprintf(stderr, "Failed to load glfwGetX11SelectionString\n"); + } else log_error("Failed to load glfwGetX11SelectionString"); Py_RETURN_NONE; } @@ -710,7 +710,7 @@ set_primary_selection(PyObject UNUSED *self, PyObject *args) { char *text; if (!PyArg_ParseTuple(args, "s", &text)) return NULL; if (glfwSetX11SelectionString) glfwSetX11SelectionString(text); - else fprintf(stderr, "Failed to load glfwSetX11SelectionString\n"); + else log_error("Failed to load glfwSetX11SelectionString"); Py_RETURN_NONE; } diff --git a/kitty/graphics.c b/kitty/graphics.c index 4ff7f3d21..2581fe995 100644 --- a/kitty/graphics.c +++ b/kitty/graphics.c @@ -21,7 +21,7 @@ PyTypeObject GraphicsManager_Type; #define STORAGE_LIMIT (320 * (1024 * 1024)) -#define REPORT_ERROR(...) { fprintf(stderr, __VA_ARGS__); fprintf(stderr, "\n"); } +#define REPORT_ERROR(...) { log_error(__VA_ARGS__); } static bool send_to_gpu = true; diff --git a/kitty/logging.c b/kitty/logging.c new file mode 100644 index 000000000..b6ed01003 --- /dev/null +++ b/kitty/logging.c @@ -0,0 +1,50 @@ +/* + * logging.c + * Copyright (C) 2018 Kovid Goyal + * + * Distributed under terms of the GPL3 license. + */ + +#include "data-types.h" +#include +#include +#include + + +void +log_error(const char *fmt, ...) { + va_list ar; + struct timeval tv; + gettimeofday(&tv, NULL); + struct tm *tmp = localtime(&tv.tv_sec); + if (tmp) { + char tbuf[256], buf[256]; + if (strftime(buf, sizeof(buf), "%j %H:%M:%S.%%06u", tmp) != 0) { + snprintf(tbuf, sizeof(tbuf), buf, tv.tv_usec); + fprintf(stderr, "[%s] ", tbuf); + } + } + va_start(ar, fmt); + vfprintf(stderr, fmt, ar); + va_end(ar); + fprintf(stderr, "\n"); +} + +static PyObject* +log_error_string(PyObject *self UNUSED, PyObject *args) { + const char *msg; + if (!PyArg_ParseTuple(args, "s", &msg)) return NULL; + log_error("%s", msg); + Py_RETURN_NONE; +} + +static PyMethodDef module_methods[] = { + METHODB(log_error_string, METH_VARARGS), + {NULL, NULL, 0, NULL} /* Sentinel */ +}; + +bool +init_logging(PyObject *module) { + if (PyModule_AddFunctions(module, module_methods) != 0) return false; + return true; +} diff --git a/kitty/parser.c b/kitty/parser.c index 7f9859070..43df4bf30 100644 --- a/kitty/parser.c +++ b/kitty/parser.c @@ -123,7 +123,7 @@ _report_params(PyObject *dump_callback, const char *name, unsigned int *params, #define DUMP_UNUSED UNUSED -#define REPORT_ERROR(...) fprintf(stderr, "%s ", ERROR_PREFIX); fprintf(stderr, __VA_ARGS__); fprintf(stderr, "\n"); +#define REPORT_ERROR(...) log_error(ERROR_PREFIX " " __VA_ARGS__); #define REPORT_COMMAND(...) #define REPORT_VA_COMMAND(...) diff --git a/kitty/screen.c b/kitty/screen.c index 9a4a10cf5..1498faba7 100644 --- a/kitty/screen.c +++ b/kitty/screen.c @@ -561,7 +561,7 @@ set_mode_from_const(Screen *self, unsigned int mode, bool val) { default: private = mode >= 1 << 5; if (private) mode >>= 5; - fprintf(stderr, "%s %s %u %s\n", ERROR_PREFIX, "Unsupported screen mode: ", mode, private ? "(private)" : ""); + log_error("%s %s %u %s", ERROR_PREFIX, "Unsupported screen mode: ", mode, private ? "(private)" : ""); } #undef SIMPLE_MODE #undef MOUSE_MODE @@ -648,7 +648,7 @@ screen_clear_tab_stop(Screen *self, unsigned int how) { for (unsigned int i = 0; i < self->columns; i++) self->tabstops[i] = false; break; default: - fprintf(stderr, "%s %s %u\n", ERROR_PREFIX, "Unsupported clear tab stop mode: ", how); + log_error("%s %s %u", ERROR_PREFIX, "Unsupported clear tab stop mode: ", how); break; } } diff --git a/kitty/shaders.c b/kitty/shaders.c index 8881af7d6..80a19d73f 100644 --- a/kitty/shaders.c +++ b/kitty/shaders.c @@ -30,7 +30,7 @@ copy_image_sub_data(GLuint src_texture_id, GLuint dest_texture_id, unsigned int // ARB_copy_image not available, do a slow roundtrip copy if (!copy_image_warned) { copy_image_warned = true; - fprintf(stderr, "WARNING: Your system's OpenGL implementation does not have glCopyImageSubData, falling back to a slower implementation.\n"); + log_error("WARNING: Your system's OpenGL implementation does not have glCopyImageSubData, falling back to a slower implementation"); } size_t sz = width * height * num_levels; pixel *src = malloc(sz * sizeof(pixel)); @@ -573,7 +573,7 @@ compile_program(PyObject UNUSED *self, PyObject *args) { if (ret != GL_TRUE) { GLsizei len; glGetProgramInfoLog(programs[which].id, sizeof(glbuf), &len, glbuf); - fprintf(stderr, "Failed to compile GLSL shader!\n%s", glbuf); + log_error("Failed to compile GLSL shader!\n%s", glbuf); PyErr_SetString(PyExc_ValueError, "Failed to compile shader"); goto end; } diff --git a/kitty/utils.py b/kitty/utils.py index 84eab2f9e..9317e13df 100644 --- a/kitty/utils.py +++ b/kitty/utils.py @@ -3,7 +3,6 @@ # License: GPL v3 Copyright: 2016, Kovid Goyal import atexit -import datetime import errno import fcntl import math @@ -20,7 +19,8 @@ from time import monotonic from .constants import appname, is_macos, is_wayland from .fast_data_types import ( - GLSL_VERSION, redirect_std_streams, x11_display, x11_window_id + GLSL_VERSION, log_error_string, redirect_std_streams, x11_display, + x11_window_id ) from .rgb import Color, to_color @@ -43,8 +43,7 @@ def safe_print(*a, **k): def log_error(*a, **k): try: msg = k.get('sep', ' ').join(map(str, a)) + k.get('end', '\n') - msg = datetime.datetime.now().strftime('[%j %H:%M:%S.%f] ') + msg - sys.stderr.write(msg) + log_error_string(msg.replace('\0', '')) except Exception: pass