AmendHub

Download:

jcs

/

subtext

/

amendments

/

90

logger: Add central log window, sprinkle logging in some places


jcs made amendment 90 over 2 years ago
--- logger.c Thu Mar 31 15:04:33 2022 +++ logger.c Thu Mar 31 15:04:33 2022 @@ -0,0 +1,313 @@ +/* + * Copyright (c) 2021-2022 joshua stein <jcs@jcs.org> + * + * Permission to use, copy, modify, and distribute this software for any + * purpose with or without fee is hereby granted, provided that the above + * copyright notice and this permission notice appear in all copies. + * + * THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES + * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF + * MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR + * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES + * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN + * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF + * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. + */ + +#include <stdio.h> +#include <stdarg.h> +#include <string.h> +#include "logger.h" +#include "subtext.h" +#include "util.h" + +void logger_layout(struct logger *logger, bool init, Rect *init_bounds); +void logger_key_down(struct focusable *focusable, EventRecord *event); +void logger_mouse_down(struct focusable *focusable, EventRecord *event); +void logger_update(struct focusable *focusable, EventRecord *event); +void logger_resume(struct focusable *focusable, EventRecord *event); +void logger_close(struct focusable *focusable, EventRecord *event); +bool logger_quit(struct focusable *focusable); + +struct logger * +logger_init(void) +{ + struct focusable *focusable; + struct logger *logger; + char title[64]; + Rect bounds = { 0 }; + short padding = 10; + + logger = xmalloczero(sizeof(struct logger)); + + bounds.left = padding; + bounds.top = ((screenBits.bounds.bottom - + screenBits.bounds.top) / 3) * 2; + bounds.right = screenBits.bounds.right - padding - 1; + bounds.bottom = screenBits.bounds.bottom - padding - 1; + + snprintf(title, sizeof(title), "%s: %s", PROGRAM_NAME, db->config.name); + logger->win = NewWindow(0L, &bounds, CtoPstr(title), false, + documentProc, (WindowPtr)-1L, true, 0); + if (!logger->win) + panic("Can't create logger window"); + + SetPort(logger->win); + TextFont(LOGGER_FONT); + TextSize(LOGGER_FONT_SIZE); + + bounds.right -= bounds.left; + bounds.bottom -= bounds.top; + bounds.top = bounds.left = 0; + logger_layout(logger, true, &bounds); + + focusable = xmalloczero(sizeof(struct focusable)); + focusable->win = logger->win; + focusable->cookie = logger; + focusable->mouse_down = logger_mouse_down; + focusable->update = logger_update; + focusable->close = logger_close; + focusable->resume = logger_resume; + add_focusable(focusable); + logger->focusable = focusable; + + return logger; +} + +void +logger_layout(struct logger *logger, bool init, Rect *init_bounds) +{ + Rect bounds, inset_bounds, win_bounds; + Rect control_bounds = { 0 }; + Rect data_bounds = { 0, 0, 0, 1 }; /* tlbr */ + Point cell_size = { 0 }; + Cell cell = { 0, 0 }; + + if (init) + win_bounds = *init_bounds; + else + win_bounds = logger->win->portRect; + + /* messages scrollbar */ + bounds.top = -1; + bounds.right = win_bounds.right - win_bounds.left; + bounds.bottom = win_bounds.bottom - win_bounds.top; + bounds.left = bounds.right - SCROLLBAR_WIDTH; + if (init) + logger->messages_scroller = NewControl(logger->win, &bounds, + "\p", true, 1, 1, 1, scrollBarProc, 0L); + else + (*(logger->messages_scroller))->contrlRect = bounds; + + /* messages */ + bounds.right = (*(logger->messages_scroller))->contrlRect.left - + SCROLLBAR_WIDTH; + bounds.left = 0; + bounds.top = 0; + if (init) { + inset_bounds = bounds; + InsetRect(&inset_bounds, 4, 4); + logger->messages_te = TEStylNew(&inset_bounds, &bounds); + (*(logger->messages_te))->caretHook = NullCaretHook; + TEActivate(logger->messages_te); + } else { + (*(logger->messages_te))->viewRect = bounds; + InsetRect(&bounds, 4, 4); + (*(logger->messages_te))->destRect = bounds; + TECalText(logger->messages_te); + } + + InvalRect(logger->win->visRgn); +} + +void +logger_resume(struct focusable *focusable, EventRecord *event) +{ + struct logger *logger = (struct logger *)(focusable->cookie); + + show_focusable(focusable); + InvalRect(logger->win->visRgn); +} + +void +logger_close(struct focusable *focusable, EventRecord *event) +{ + close_focusable(focusable); +} + +void +logger_update(struct focusable *focusable, EventRecord *event) +{ + struct logger *logger = (struct logger *)(focusable->cookie); + GrafPtr old_port; + Rect r; + short what = -1; + + GetPort(&old_port); + + if (event != NULL) + what = event->what; + + switch (what) { + case -1: + case updateEvt: + TextFont(applFont); + TextSize(10); + + EraseRect(&logger->win->portRect); + + r = (*(logger->messages_te))->viewRect; + InsetRect(&r, -1, -1); + FrameRect(&r); + + TEUpdate(&(*(logger->messages_te))->viewRect, logger->messages_te); + DrawControls(logger->win); + break; + case activateEvt: + if (event->modifiers & activeFlag) { + TEActivate(logger->messages_te); + } else { + TEDeactivate(logger->messages_te); + } + break; + } +} + +void +logger_mouse_down(struct focusable *focusable, EventRecord *event) +{ + struct logger *logger = (struct logger *)(focusable->cookie); + Point p; + Cell selected = { 0 }, now = { 0 }, t = { 0 }; + ControlHandle control; + Rect r; + int val, adj, page, ret; + short part; + + p = event->where; + GlobalToLocal(&p); + + r = (*(logger->messages_te))->viewRect; + if (PtInRect(p, &r)) { + TEClick(p, ((event->modifiers & shiftKey) != 0), + logger->messages_te); + HLock(logger->messages_te); + if ((*(logger->messages_te))->selStart != + (*(logger->messages_te))->selEnd) + TESetSelect(0, 0, logger->messages_te); + HUnlock(logger->messages_te); + return; + } + + switch (part = FindControl(p, logger->win, &control)) { + case inUpButton: + case inDownButton: + case inPageUp: + case inPageDown: + if (control != logger->messages_scroller) + break; + SetTrackControlTE(logger->messages_te); + TrackControl(control, p, TrackMouseDownInControl); + break; + case inThumb: + val = GetCtlValue(control); + if (TrackControl(control, p, 0L) == 0) + break; + adj = val - GetCtlValue(control); + if (adj != 0) { + val -= adj; + if (control == logger->messages_scroller) + TEScroll(0, adj * TEGetHeight(0, 0, logger->messages_te), + logger->messages_te); + SetCtlValue(control, val); + } + break; + } +} + +size_t +logger_printf(struct logger *logger, const char *format, ...) +{ + static char buf[600]; + RgnHandle savergn; + Rect zerorect = { 0, 0, 0, 0 }; + va_list argptr; + size_t len, n; + time_t now = Time; + short line_height = 0; + bool stop_formatting = false; + + len = 0; + + if ((*(logger->messages_te))->teLength > 0) { + buf[0] = '\r'; + len++; + } + + len += strftime(buf + len, sizeof(buf) - len, "[%H:%M] ", + localtime(&now)); + + va_start(argptr, format); + len += vsnprintf(buf + len, sizeof(buf) - len, format, argptr); + va_end(argptr); + + if (buf[len - 1] == '\r') { + buf[len - 1] = '\0'; + len--; + } + + line_height = LOGGER_FONT_SIZE + 3; + + HLock(logger->messages_te); + + /* check for TE overflow */ + + /* too many lines */ + if ((*(logger->messages_te))->nLines >= + (nitems((*(logger->messages_te))->lineStarts) - 10)) + goto te_overflow; + + /* too many characters */ + if ((*(logger->messages_te))->teLength >= (SHRT_MAX - 500)) + goto te_overflow; + + /* rect of all lines is too tall */ + if ((*(logger->messages_te))->nLines * line_height >= (SHRT_MAX - 100)) + goto te_overflow; + + goto no_overflow; + +te_overflow: + savergn = NewRgn(); + GetClip(savergn); + /* create an empty clip region so all TE updates are hidden */ + ClipRect(&zerorect); + + /* select some lines at the start, delete them */ + TESetSelect(0, (*(logger->messages_te))->lineStarts[5], + logger->messages_te); + TEDelete(logger->messages_te); + + /* scroll up, causing a repaint */ + TEPinScroll(0, INT_MAX, logger->messages_te); + + /* then scroll back down to what it looked like before we did anything */ + TEPinScroll(0, -INT_MAX, logger->messages_te); + + /* resume normal drawing */ + SetClip(savergn); + DisposeRgn(savergn); + +no_overflow: + TESetSelect(SHRT_MAX, SHRT_MAX, logger->messages_te); + TEInsert(buf, len, logger->messages_te); + + TEPinScroll(0, -INT_MAX, logger->messages_te); + SetCtlValue(logger->messages_scroller, + GetCtlMax(logger->messages_scroller)); + UpdateScrollbarForTE(logger->messages_scroller, + logger->messages_te, false); + HUnlock(logger->messages_te); + + return len; +} --- logger.h Thu Mar 31 14:07:54 2022 +++ logger.h Thu Mar 31 14:07:54 2022 @@ -0,0 +1,37 @@ +/* + * Copyright (c) 2021-2022 joshua stein <jcs@jcs.org> + * + * Permission to use, copy, modify, and distribute this software for any + * purpose with or without fee is hereby granted, provided that the above + * copyright notice and this permission notice appear in all copies. + * + * THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES + * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF + * MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR + * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES + * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN + * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF + * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. + */ + +#ifndef __CHATTER_H__ +#define __CHATTER_H__ + +#include <stdio.h> + +#include "util.h" + +#define LOGGER_FONT geneva +#define LOGGER_FONT_SIZE 10 + +struct logger { + struct focusable *focusable; + WindowPtr win; + TEHandle messages_te; + ControlHandle messages_scroller; +}; + +struct logger * logger_init(void); +size_t logger_printf(struct logger *logger, const char *format, ...); + +#endif --- main.c Thu Mar 17 15:34:59 2022 +++ main.c Thu Mar 31 15:38:50 2022 @@ -20,6 +20,7 @@ #include "subtext.h" #include "console.h" #include "db.h" +#include "logger.h" #include "serial_local.h" #include "session.h" #include "settings.h" @@ -33,7 +34,7 @@ short quitting = 0; struct db *db = NULL; struct focusable **focusables = NULL; short nfocusables = 0; - +struct logger *logger; bool handle_menu(long menu_id); void handle_exit(void); @@ -73,7 +74,7 @@ main(void) panic("no file menu"); InsertMenu(GetMenu(VIEWS_SUBMENU_ID), -1); DrawMenuBar(); - + /* see if we were started by double-clicking a .bbs file */ CountAppFiles(&finder_action, &finder_count); if (finder_count) { @@ -89,6 +90,9 @@ main(void) if (!db) panic("Failed to open database"); + logger = logger_init(); + + logger_printf(logger, "[db] Updating user cache"); user_update_cache_map(); if (db->config.telnet_port) --- serial.c Tue Mar 29 16:32:16 2022 +++ serial.c Thu Mar 31 15:06:28 2022 @@ -82,7 +82,10 @@ serial_init(void) in_port[2] = 'B'; out_port[2] = 'B'; } - + + logger_printf(logger, "[modem] Initializing %s port", + (db->config.modem_port == 2 ? "printer" : "modem")); + if ((error = OpenDriver(out_port, &serial_out_refnum)) != 0) panic("OpenDriver(%s) failed: %d", PtoCstr(out_port), error); if ((error = OpenDriver(in_port, &serial_in_refnum)) != 0) @@ -118,6 +121,7 @@ serial_reset(void) long m; /* reset */ + logger_printf(logger, "[modem] Hanging up"); serial_hangup(); serial_printf("ATZ\r"); Delay(TICKS_PER_SEC * 2, &m); @@ -126,11 +130,11 @@ serial_reset(void) /* disable echo */ serial_printf("ATE0\r"); resp = serial_get_line(true); - if (resp[0] == 'A' && resp[1] == 'T' && resp[2] == 'E') + if (resp && resp[0] == 'A' && resp[1] == 'T' && resp[2] == 'E') /* eat echo */ resp = serial_get_line(true); - if (resp[0] != 'O' || resp[1] != 'K') - warn("bad response to ATE0: \"%s\"", resp); + if (!resp || (resp[0] != 'O' || resp[1] != 'K')) + warn("bad response to ATE0: \"%s\"", resp == NULL ? "" : resp); /* initialize */ serial_printf("%s\r", db->config.modem_init); @@ -188,6 +192,8 @@ serial_printf(const char *format, ...) format, ap); va_end(ap); + logger_printf(logger, "[modem] Sending: %s", serial_printf_tbuf); + pbr.ioParam.ioRefNum = serial_out_refnum; pbr.ioParam.ioBuffer = (Ptr)&serial_printf_tbuf; pbr.ioParam.ioReqCount = len; @@ -206,6 +212,7 @@ serial_get_line(bool wait) static char serial_cur_line[sizeof(serial_input_buf)]; size_t n; long len, rem; + unsigned long started = Time; maybe_read: /* append as much new data as we can fit */ @@ -217,7 +224,8 @@ maybe_read: FSRead(serial_in_refnum, &len, serial_input_buf + serial_input_buf_len); serial_input_buf[serial_input_buf_len + len] = '\0'; - progress("%s", serial_input_buf + serial_input_buf_len); + logger_printf(logger, "[modem] Read: %s", + serial_input_buf + serial_input_buf_len); serial_input_buf_len += len; } } @@ -255,6 +263,10 @@ find_line: if (wait) { if (serial_input_buf_len >= sizeof(serial_input_buf)) panic("serial_get_line with wait but input buffer full"); + if (Time - started > 5) { + warn("Timed out waiting for modem response"); + return NULL; + } goto maybe_read; } @@ -304,13 +316,12 @@ serial_idle(void) the_serial_node.session = session_create(tty, "modem", &serial_node_funcs); the_serial_node.session->cookie = (void *)&the_serial_node; + the_serial_node.session->vt100 = 1; /* TODO: pass caller id */ if (sscanf(line, "CONNECT %ld/%n", baud, &count) == 1 && - count > 0) { - console->session->vt100 = 1; - console->session->tspeed = baud; - } + count > 0) + the_serial_node.session->tspeed = baud; } } --- session.c Thu Mar 3 15:43:04 2022 +++ session.c Thu Mar 31 15:25:52 2022 @@ -62,6 +62,8 @@ session_create(char *node, char *via, struct node_func sessions = xreallocarray(sessions, nsessions, sizeof(struct session)); sessions[nsessions - 1] = session; + logger_printf(logger, "[%s] New session via %s", node, via); + return session; } @@ -209,6 +211,8 @@ session_close(struct session *session) /* finalize session log */ session->log.logged_off_at = Time; + logger_printf(logger, "[%s] Closing session", session->node); + if (bile_write(db->sessions_bile, SL_LOG_RTYPE, session->log.id, &session->log, sizeof(session->log)) != sizeof(session->log)) panic("bile_write of session log failed: %d", @@ -666,6 +670,8 @@ session_login(struct session *s) if (strcmp(username, GUEST_USERNAME) == 0) { free(username); + logger_printf(logger, "[%s] Successful login in as %s", + s->node, GUEST_USERNAME); return AUTH_USER_OK; } @@ -680,6 +686,8 @@ session_login(struct session *s) if (user) { free(username); s->user = user; + logger_printf(logger, "[%s] Automatically logged in as %s", + s->node, s->autologin_username); return AUTH_USER_OK; } @@ -699,10 +707,16 @@ session_login(struct session *s) if (user) { if (user_authenticate(user, password) == AUTH_USER_OK) s->user = user; - } else + else + logger_printf(logger, "[%s] Failed password login for %s", + s->node, user->username); + } else { /* kill some time */ SHA256Data((const u_int8_t *)password, strlen(password), junk); - + logger_printf(logger, "[%s] Failed password login for " + "invalid user %s", s->node, username); + } + len = strlen(username); memset(username, 0, len); free(username); @@ -713,8 +727,11 @@ session_login(struct session *s) free(password); password = NULL; - if (s->user) + if (s->user) { + logger_printf(logger, "[%s] Successful password login for " + "user %s", s->node, s->user->username); return AUTH_USER_OK; + } uthread_msleep(60); session_output_string(s, "Login incorrect\r\n"); --- subtext.h Sat Mar 5 21:26:32 2022 +++ subtext.h Thu Mar 31 14:33:37 2022 @@ -61,9 +61,11 @@ #define SETTINGS_EDIT_VIEW_DLOG_ID 131 #include "db.h" +#include "logger.h" extern struct db *db; extern MenuHandle file_menu; +extern struct logger *logger; struct focusable { WindowPtr win; --- telnet.c Fri Mar 4 14:52:25 2022 +++ telnet.c Thu Mar 31 15:38:37 2022 @@ -17,6 +17,7 @@ #include <stdio.h> #include <string.h> +#include "logger.h" #include "session.h" #include "subtext.h" #include "telnet.h" @@ -128,7 +129,9 @@ telnet_init(void) { if (!db->config.telnet_port) return; - + + logger_printf(logger, "[telnet] Initializing MacTCP"); + if (_TCPInit() != noErr) panic("Failed initializing MacTCP"); } @@ -161,9 +164,12 @@ telnet_atexit(void) void telnet_idle(void) { + char ip_s[20]; struct telnet_node *node; short n, error; + ip_addr ip; tcp_port port; + long mask; if (!db->config.telnet_port) return; @@ -183,9 +189,17 @@ telnet_idle(void) if (error) panic("TCPCreate[%d] failed: %d", node->id, error); + error = _TCPGetOurIP(&ip, &mask); + if (error) + panic("TCPGetOurIP failed: %d", error); + port = db->config.telnet_port; + long2ip(ip, ip_s); + logger_printf(logger, "[telnet] Listening on %s:%d", ip_s, + port); + error = _TCPPassiveOpen(&node->listen_pb, node->stream, nil, - nil, nil, &port, nil, nil, true); + nil, &ip, &port, nil, nil, true); if (error) panic("TCPPassiveOpen[%d] on port %d failed: %d", node->id, db->config.telnet_port, error); @@ -206,7 +220,14 @@ telnet_idle(void) if (telnet_status_pb.connectionState == ConnectionStateEstablished) { char tty[7]; + char ip_s[20]; + sprintf(tty, "ttyt%d", n); + + long2ip(telnet_status_pb.remoteHost, ip_s); + logger_printf(logger, "[%s] New telnet connection from %s", + tty, ip_s); + node->state = TELNET_PB_STATE_CONNECTED; node->session = session_create(tty, "telnet", &telnet_node_funcs); @@ -577,6 +598,9 @@ telnet_close(struct session *session) { struct telnet_node *node = (struct telnet_node *)session->cookie; short error; + + logger_printf(logger, "[%s] Closing telnet connection", + session->node); error = _TCPClose(&telnet_exit_pb, node->stream, nil, nil, false); /* TODO: allow some time to fully close? */ @@ -586,12 +610,12 @@ telnet_close(struct session *session) warn("error shutting down telnet session: %d", error); return; } - + session->cookie = NULL; telnet_nodes[node->id] = NULL; if (node == telnet_listener_node) telnet_listener_node = NULL; - + free(node); }