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);
}