jcs
/subtext
/amendments
/90
logger: Add central log window, sprinkle logging in some places
jcs made amendment 90 over 3 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);
 }