kernel: Initial pass at new debug printf interface

apps/splash-log.c

@@ -59,6 +59,11 @@ static void write_char(int x, int y, int val, uint32_t color) {
 
 static unsigned int line_offset = 0;
 static void fb_update_message(char * c, int line) {
+	FILE * console = fopen("/dev/console","a");
+	fprintf(console, "\r%s\033[K%s", c, line == 0 ? "\n" : "");
+	fflush(console);
+	fclose(console);
+	#if 0
 	int x = 20;
 	int y = 20 + line_offset * char_height;
 	if (line == 0) {
@@ -73,15 +78,18 @@ static void fb_update_message(char * c, int line) {
 		write_char(x, y, ' ', FG_COLOR);
 		x += char_width;
 	}
+	#endif
 }
 
 static void fb_clear_screen(void) {
+	#if 0
 	line_offset = 0;
 	for (int y = 0; y < height; ++y) {
 		for (int x = 0; x < width; ++x) {
 			set_point(x,y,BG_COLOR);
 		}
 	}
+	#endif
 }
 
 static void placech(unsigned char c, int x, int y, int attr) {
@@ -203,7 +211,7 @@ int main(int argc, char * argv[]) {
 				memcpy(tmp, p->data, p->size);
 				tmp[p->size] = '\0';
 				update_message(tmp, 0);
-				update_message("", 1);
+				//update_message("", 1);
 				free(tmp);
 			}
 		}

base/usr/include/kernel/printf.h

@@ -9,3 +9,6 @@ extern size_t (*printf_output)(size_t, uint8_t *);
 __attribute__((format(__printf__,3,4)))
 extern int snprintf(char * str, size_t size, const char * format, ...);
 extern size_t xvasprintf(int (*callback)(void *, char), void * userData, const char * fmt, va_list args);
+
+__attribute__((format(__printf__,1,2)))
+extern int dprintf(const char *fmt, ...);

kernel/arch/x86_64/cmos.c

@@ -15,6 +15,11 @@
 #include <kernel/arch/x86_64/irq.h>
 #include <sys/time.h>
 
+uint64_t arch_boot_time = 0;
+uint64_t tsc_basis_time = 0;
+
+unsigned long tsc_mhz = 3500; /* XXX */
+
 #define from_bcd(val)  ((val / 16) * 10 + (val & 0xf))
 #define CMOS_ADDRESS   0x70
 #define CMOS_DATA      0x71
@@ -126,9 +131,6 @@ uint32_t read_cmos(void) {
 	return time;
 }
 
-static uint64_t boot_time = 0;
-unsigned long tsc_mhz = 3500; /* XXX */
-
 static inline uint64_t read_tsc(void) {
 	uint32_t lo, hi;
 	asm volatile ( "rdtsc" : "=a"(lo), "=d"(hi) );
@@ -144,7 +146,8 @@ size_t arch_cpu_mhz(void) {
 }
 
 void arch_clock_initialize(void) {
-	boot_time = read_cmos();
+	dprintf("Calibrating system timestamp counter.\n");
+	arch_boot_time = read_cmos();
 	uintptr_t end_lo, end_hi;
 	uint32_t start_lo, start_hi;
 	asm volatile (
@@ -200,11 +203,15 @@ void arch_clock_initialize(void) {
 	uintptr_t start = ((uintptr_t)(start_hi & 0xFFFFffff) << 32) | (start_lo & 0xFFFFffff);
 	tsc_mhz = (end - start) / 10000;
 	if (tsc_mhz == 0) tsc_mhz = 2000; /* uh oh */
+	tsc_basis_time = start / tsc_mhz;
+
+	dprintf("TSC timed at %lu MHz. Use tsc_mhz= to override if this is very wrong.\n", tsc_mhz);
+	dprintf("Boot time is %lus. Initial TSC timestamp was %luus.\n", arch_boot_time, tsc_basis_time);
 }
 
 #define SUBSECONDS_PER_SECOND 1000000
 static void update_ticks(uint64_t ticks, uint64_t *timer_ticks, uint64_t *timer_subticks) {
-	*timer_subticks = ticks;
+	*timer_subticks = ticks - tsc_basis_time;
 	*timer_ticks = *timer_subticks / SUBSECONDS_PER_SECOND;
 	*timer_subticks = *timer_subticks % SUBSECONDS_PER_SECOND;
 }
@@ -213,7 +220,7 @@ int gettimeofday(struct timeval * t, void *z) {
 	uint64_t tsc = read_tsc();
 	uint64_t timer_ticks, timer_subticks;
 	update_ticks(tsc / tsc_mhz, &timer_ticks, &timer_subticks);
-	t->tv_sec = boot_time + timer_ticks;
+	t->tv_sec = arch_boot_time + timer_ticks;
 	t->tv_usec = timer_subticks;
 	return 0;
 }
@@ -226,6 +233,12 @@ uint64_t now(void) {
 
 
 void relative_time(unsigned long seconds, unsigned long subseconds, unsigned long * out_seconds, unsigned long * out_subseconds) {
+	if (!arch_boot_time) {
+		*out_seconds = 0;
+		*out_subseconds = 0;
+		return;
+	}
+
 	uint64_t tsc = read_tsc();
 	uint64_t timer_ticks, timer_subticks;
 	update_ticks(tsc / tsc_mhz, &timer_ticks, &timer_subticks);

kernel/arch/x86_64/idt.c

@@ -114,7 +114,7 @@ void idt_ap_install(void) {
 static spin_lock_t dump_lock = {0};
 static void dump_regs(struct regs * r) {
 	spin_lock(dump_lock);
-	printf(
+	dprintf(
 		"Registers at interrupt:\n"
 		"  $rip=0x%016lx\n"
 		"  $rsi=0x%016lx,$rdi=0x%016lx,$rbp=0x%016lx,$rsp=0x%016lx\n"
@@ -218,29 +218,29 @@ static void safe_dump_traceback(struct regs * r) {
 	int max_depth = 20;
 
 	while (bp && ip && depth < max_depth) {
-		printf(" 0x%016zx ", ip);
+		dprintf(" 0x%016zx ", ip);
 		if (ip >= 0xffffffff80000000UL) {
 			char * name = NULL;
 			struct LoadedModule * mod = find_module(ip, &name);
 			if (mod) {
-				printf(" in module '%s', base address %#zx (offset %#zx)\n",
+				dprintf("\a in module '%s', base address %#zx (offset %#zx)\n",
 					name, mod->baseAddress, r->rip - mod->baseAddress);
 			} else {
-				printf(" (unknown)\n");
+				dprintf("\a (unknown)\n");
 			}
 		} else if (ip >= (uintptr_t)&end && ip <= 0x800000000000) {
-			printf(" in userspace\n");
+			dprintf("\a in userspace\n");
 		} else if (ip <= (uintptr_t)&end) {
 			/* Find symbol match */
 			char * name;
 			uintptr_t addr = matching_symbol(ip, &name);
 			if (!addr) {
-				printf(" (no match)\n");
+				dprintf("\a (no match)\n");
 			} else {
-				printf(" %s+0x%zx\n", name, ip-addr);
+				dprintf("\a %s+0x%zx\n", name, ip-addr);
 			}
 		} else {
-			printf(" (unknown)\n");
+			dprintf("\a (unknown)\n");
 		}
 		if (!validate_pointer(bp, sizeof(uintptr_t) * 2)) {
 			break;
@@ -266,6 +266,19 @@ static void map_more_stack(uintptr_t fromAddr) {
 	spin_unlock(proc->image.lock);
 }
 
+extern void arch_fatal_prepare(void);
+static void panic(const char * desc, struct regs * r, uintptr_t faulting_address) {
+	arch_fatal_prepare();
+	dprintf("\033[31mPanic!\033[0m %s pid=%d (%s) at %#zx\n", desc,
+		this_core->current_process ? (int)this_core->current_process->id : 0,
+		this_core->current_process ? this_core->current_process->name : "kernel",
+		faulting_address
+	);
+	dump_regs(r);
+	safe_dump_traceback(r);
+	arch_fatal();
+}
+
 struct regs * isr_handler(struct regs * r) {
 	this_core->interrupt_registers = r;
 
@@ -278,14 +291,7 @@ struct regs * isr_handler(struct regs * r) {
 			uintptr_t faulting_address;
 			asm volatile("mov %%cr2, %0" : "=r"(faulting_address));
 			if (!this_core->current_process || r->cs == 0x08) {
-				printf("Page fault in kernel ");
+				panic("Page fault in kernel", r, faulting_address);
-				if (this_core->current_process) {
-					printf("pid=%d (%s) ", (int)this_core->current_process->id, this_core->current_process->name);
-				}
-				printf("at %#zx\n", faulting_address);
-				safe_dump_traceback(r);
-				dump_regs(r);
-				arch_fatal();
 			}
 			if (faulting_address == 0xFFFFB00F) {
 				/* Thread exit */
@@ -305,13 +311,13 @@ struct regs * isr_handler(struct regs * r) {
 		}
 		case 13: /* GPF */ {
 			if (!this_core->current_process || r->cs == 0x08) {
-				arch_fatal();
+				panic("GPF in kernel", r, 0);
 			}
 			send_signal(this_core->current_process->id, SIGSEGV, 1);
 			break;
 		}
 		case 8: /* Double fault */ {
-			arch_fatal();
+			panic("Double fault", r, 0);
 			break;
 		}
 		case 127: /* syscall */ {
@@ -338,10 +344,8 @@ struct regs * isr_handler(struct regs * r) {
 		default: {
 			if (r->int_no < 32) {
 				if (!this_core->current_process || r->cs == 0x08) {
-					arch_fatal();
+					panic("Unexpected interrupt", r, r->int_no);
 				}
-				printf("int_no %ld in process %d\n",
-					r->int_no, this_core->current_process->id);
 				send_signal(this_core->current_process->id, SIGILL, 1);
 			} else {
 				for (size_t i = 0; i < IRQ_CHAIN_DEPTH; i++) {

kernel/arch/x86_64/main.c

@@ -22,6 +22,7 @@
 #include <kernel/args.h>
 #include <kernel/ksym.h>
 #include <kernel/misc.h>
+#include <kernel/version.h>
 
 #include <kernel/arch/x86_64/ports.h>
 #include <kernel/arch/x86_64/cmos.h>
@@ -32,6 +33,7 @@
 extern void arch_clock_initialize(void);
 
 extern char end[];
+extern unsigned long tsc_mhz;
 
 extern void gdt_install(void);
 extern void idt_install(void);
@@ -46,8 +48,11 @@ extern void pci_remap(void);
 
 struct multiboot * mboot_struct = NULL;
 
+static int _serial_debug = 1;
 #define EARLY_LOG_DEVICE 0x3F8
 static size_t _early_log_write(size_t size, uint8_t * buffer) {
+	if (!_serial_debug) return size;
+
 	for (unsigned int i = 0; i < size; ++i) {
 		outportb(EARLY_LOG_DEVICE, buffer[i]);
 	}
@@ -178,21 +183,25 @@ void mount_multiboot_ramdisks(struct multiboot * mboot) {
 		uint8_t * data = mmu_map_from_physical(mods[i].mod_start);
 		if (data[0] == 0x1F && data[1] == 0x8B) {
 			/* Yes - decompress it first */
+			dprintf("Decompressing initial ramdisk...\n");
 			uint32_t decompressedSize = *(uint32_t*)mmu_map_from_physical(mods[i].mod_end - sizeof(uint32_t));
 			size_t pageCount = (((size_t)decompressedSize + 0xFFF) & ~(0xFFF)) >> 12;
 			uintptr_t physicalAddress = mmu_allocate_n_frames(pageCount) << 12;
 			if (physicalAddress == (uintptr_t)-1) {
-				printf("gzip: failed to allocate pages for decompressed payload, skipping\n");
+				dprintf("gzip: failed to allocate pages for decompressed payload, skipping\n");
 				continue;
 			}
 			gzip_inputPtr = (void*)data;
 			gzip_outputPtr = mmu_map_from_physical(physicalAddress);
 			/* Do the deed */
 			if (gzip_decompress()) {
-				printf("gzip: failed to decompress payload, skipping\n");
+				dprintf("gzip: failed to decompress payload, skipping\n");
 				continue;
 			}
 			ramdisk_mount(physicalAddress, decompressedSize);
+			dprintf("Decompressed %u kB to %u kB, freeing compressed image.\n",
+				(mods[i].mod_end - mods[i].mod_start) / 1024,
+				(decompressedSize) / 1024);
 			/* Free the pages from the original mod */
 			for (size_t j = mods[i].mod_start; j < mods[i].mod_end; j += 0x1000) {
 				mmu_frame_clear(j);
@@ -241,6 +250,15 @@ int kmain(struct multiboot * mboot, uint32_t mboot_mag, void* esp) {
 	 * as soon as we can call printf(), which is as soon as we get to long mode. */
 	early_log_initialize();
 
+	dprintf("%s %d.%d.%d-%s \"%s\" %s\n",
+		__kernel_name,
+		__kernel_version_major,
+		__kernel_version_minor,
+		__kernel_version_lower,
+		__kernel_version_suffix,
+		__kernel_version_codename,
+		__kernel_arch);
+
 	/* Initialize GS base */
 	arch_set_core_base((uintptr_t)&processor_local_data[0]);
 
@@ -269,10 +287,13 @@ int kmain(struct multiboot * mboot, uint32_t mboot_mag, void* esp) {
 
 	/* Should we override the TSC timing? */
 	if (args_present("tsc_mhz")) {
-		extern unsigned long tsc_mhz;
 		tsc_mhz = atoi(args_value("tsc_mhz"));
 	}
 
+	if (!args_present("debug")) {
+		_serial_debug = 0;
+	}
+
 	/* Scheduler is running and we have parsed the kcmdline, initialize video. */
 	framebuffer_initialize();
 	fbterm_initialize();

kernel/arch/x86_64/smp.c

@@ -321,6 +321,8 @@ _toomany:
 		/* Wait for AP to signal it is ready before starting next AP */
 		do { asm volatile ("pause" : : : "memory"); } while (!_ap_startup_flag);
 	}
+
+	dprintf("SMP enabled with %d cores\n", cores);
 }
 
 void arch_wakeup_others(void) {

kernel/generic.c

@@ -27,6 +27,7 @@ extern void random_initialize(void);
 extern int system(const char * path, int argc, const char ** argv, const char ** envin);
 extern void snd_install(void);
 extern void net_install(void);
+extern void console_initialize(void);
 
 void generic_startup(void) {
 	args_parse(arch_get_cmdline());
@@ -36,6 +37,7 @@ void generic_startup(void) {
 	tarfs_register_init();
 	tmpfs_register_init();
 	map_vfs_directory("/dev");
+	console_initialize();
 	packetfs_initialize();
 	zero_initialize();
 	procfs_initialize();
@@ -65,6 +67,8 @@ int generic_main(void) {
 		boot_app = args_value("init");
 	}
 
+	dprintf("Running %s as init process.\n", boot_app);
+
 	const char * argv[] = {
 		boot_app,
 		boot_arg,

kernel/misc/fbterm.c

@@ -11,10 +11,6 @@
 #include <kernel/string.h>
 #include <kernel/args.h>
 
-/* Exported cell sizing */
-size_t fbterm_width = 0;
-size_t fbterm_height = 0;
-
 /* Whether to scroll or wrap when cursor reaches the bottom. */
 static int fbterm_scroll = 0;
 
@@ -40,7 +36,7 @@ static uint32_t bg_color = BG_COLOR;
 
 extern uint32_t lfb_resolution_s;
 
-static void set_point(int x, int y, uint32_t value) {
+static inline void set_point(int x, int y, uint32_t value) {
 	((uint32_t*)lfb_vid_memory)[y * (lfb_resolution_s/4) + x] = value;
 }
 
@@ -60,6 +56,14 @@ static void write_char(int x, int y, int val, uint32_t color) {
 	}
 }
 
+static void fbterm_init_framebuffer(void) {
+	for (size_t y = 0; y < lfb_resolution_y; ++y) {
+		for (size_t x = 0; x < lfb_resolution_x; ++x) {
+			set_point(x,y,BG_COLOR);
+		}
+	}
+}
+
 /* We push text in one pixel, which unfortunately means we have slightly less room,
  * but it also means the text doesn't run right into the left and right edges which
  * just looks kinda bad. */
@@ -95,6 +99,8 @@ static char term_buf[1024] = {0};
 static int term_buf_c = 0;
 
 static void invert_at(int x, int y) {
+	/* Disable cursor for now, as it reads from video memory which is generally slow. */
+#if 0
 	for (uint8_t i = 0; i < char_height; ++i) {
 		for (uint8_t j = 0; j < char_width; ++j) {
 			uint32_t current = ((uint32_t*)lfb_vid_memory)[(y+i) * lfb_resolution_x + (x+j)];
@@ -105,6 +111,7 @@ static void invert_at(int x, int y) {
 			((uint32_t*)lfb_vid_memory)[(y+i) * lfb_resolution_x + (x+j)] = current;
 		}
 	}
+#endif
 }
 
 static void process_char(char ch) {
@@ -240,6 +247,27 @@ size_t fbterm_write(size_t size, uint8_t *buffer) {
 	return size;
 }
 
+static void draw_square(int x, int y) {
+	for (size_t _y = 0; _y < 7; ++_y) {
+		for (size_t _x = 0; _x < 7; ++_x) {
+			set_point(1 + x * 8 + _x, 1 + y * 8 + _y,
+				0xFF00B2FF - (y * 8 + _y) * 0x200);
+		}
+	}
+}
+
+static void fbterm_draw_logo(void) {
+	uint64_t logo_squares = 0x981818181818FFFFUL;
+	for (size_t y = 0; y < 8; ++y) {
+		for (size_t x = 0; x < 8; ++x) {
+			if (logo_squares & (1 << x)) {
+				draw_square(x,y);
+			}
+		}
+		logo_squares >>= 8;
+	}
+}
+
 void fbterm_initialize(void) {
 	if (!lfb_resolution_x) return;
 
@@ -247,8 +275,12 @@ void fbterm_initialize(void) {
 		fbterm_scroll = 1;
 	}
 
-	fbterm_width = (lfb_resolution_x - LEFT_PAD) / char_width;
+	fbterm_init_framebuffer();
-	fbterm_height = (lfb_resolution_y) / char_height;
+	fbterm_draw_logo();
+	y = 66;
+
 	previous_writer = printf_output;
 	printf_output = fbterm_write;
+
+	dprintf("fbterm: Generic framebuffer text output enabled.\n");
 }

kernel/vfs/console.c

@@ -0,0 +1,124 @@
+/**
+ * @file  kernel/vfs/console.c
+ * @brief Device file interface to the kernel console.
+ *
+ * @copyright
+ * This file is part of ToaruOS and is released under the terms
+ * of the NCSA / University of Illinois License - see LICENSE.md
+ * Copyright (C) 2021 K. Lange
+ */
+#include <stdarg.h>
+#include <errno.h>
+#include <kernel/process.h>
+#include <kernel/vfs.h>
+#include <kernel/string.h>
+#include <kernel/printf.h>
+#include <kernel/time.h>
+
+static fs_node_t * console_dev = NULL;
+
+/** Things we use to determine if the clock is ready. */
+extern uint64_t arch_boot_time;
+
+/** Things we use for framebuffer output. */
+extern uint16_t lfb_resolution_x;
+extern size_t (*printf_output)(size_t, uint8_t *);
+extern size_t fbterm_write(size_t, uint8_t *);
+
+static uint8_t tmp_buffer[4096] __attribute__((aligned(4096)));
+static uint8_t * buffer_start = tmp_buffer;
+
+static ssize_t write_console(size_t size, uint8_t *buffer) {
+	if (lfb_resolution_x) return fbterm_write(size,buffer);
+
+	if (buffer_start + size >= tmp_buffer + sizeof(tmp_buffer)) {
+		return 0; /* uh oh */
+	}
+
+	memcpy(buffer_start, buffer, size);
+	buffer_start += size;
+
+	return size;
+}
+
+struct dprintf_data {
+	int prev_was_lf;
+	int left_width;
+};
+
+static int cb_printf(void * user, char c) {
+	struct dprintf_data * data = user;
+	if (data->prev_was_lf) {
+		for (int i = 0; i < data->left_width; ++i) write_console(1, (uint8_t*)" ");
+		data->prev_was_lf = 0;
+	}
+	if (c == '\n') data->prev_was_lf = 1;
+	write_console(1, (uint8_t*)&c);
+	return 0;
+}
+
+int dprintf(const char * fmt, ...) {
+	va_list args;
+	va_start(args, fmt);
+
+	/* Is a viable output ready? */
+	if (lfb_resolution_x && buffer_start != tmp_buffer) {
+		fbterm_write(buffer_start - tmp_buffer, tmp_buffer);
+		buffer_start = tmp_buffer;
+	}
+
+	/* Is this a FATAL message? */
+
+	/* If it's ready now but wasn't ready previously, are there
+	 * things in the queue to dump? */
+
+	/* Is this a fresh message for this core that we need to assign a timestamp to? */
+
+
+	struct dprintf_data _data = {0,0};
+
+	if (*fmt == '\a') {
+		fmt++;
+	} else {
+		char timestamp[32];
+		unsigned long timer_ticks, timer_subticks;
+		relative_time(0,0,&timer_ticks,&timer_subticks);
+		size_t ts_len = snprintf(timestamp, 31, "[%5lu.%06lu] ", timer_ticks, timer_subticks);
+		_data.left_width = ts_len;
+		write_console(ts_len, (uint8_t*)timestamp);
+	}
+
+	int out = xvasprintf(cb_printf, &_data, fmt, args);
+	va_end(args);
+	return out;
+}
+
+static ssize_t write_fs_console(fs_node_t * node, off_t offset, size_t size, uint8_t * buffer) {
+	if (size > 0x1000) return -EINVAL;
+	size_t size_in = size;
+	if (size && *buffer == '\r') {
+		write_console(1,(uint8_t*)"\r");
+		buffer++;
+		size--;
+	}
+	if (size) dprintf("%*s", (unsigned int)size, buffer);
+	return size_in;
+}
+
+static fs_node_t * console_device_create(void) {
+	fs_node_t * fnode = malloc(sizeof(fs_node_t));
+	memset(fnode, 0x00, sizeof(fs_node_t));
+	fnode->inode = 0;
+	strcpy(fnode->name, "console");
+	fnode->uid = 0;
+	fnode->gid = 0;
+	fnode->mask = 0660;
+	fnode->flags   = FS_CHARDEVICE;
+	fnode->write   = write_fs_console;
+	return fnode;
+}
+
+void console_initialize(void) {
+	console_dev = console_device_create();
+	vfs_mount("/dev/console", console_dev);
+}