From 0804766a40b96e569e492887a4461074e6f50639 Mon Sep 17 00:00:00 2001 From: Ali Mashtizadeh Date: Sun, 20 Aug 2023 19:08:26 -0400 Subject: [PATCH] Cleanup logging throughout kernel --- sys/dev/x86/ide.c | 26 +++++++++++++------------- sys/fs/o2fs/o2fs.c | 29 +++++++++++++++-------------- sys/include/kassert.h | 10 +++++----- sys/include/sysctl.h | 3 ++- 4 files changed, 35 insertions(+), 33 deletions(-) diff --git a/sys/dev/x86/ide.c b/sys/dev/x86/ide.c index 9614dfd..d098917 100644 --- a/sys/dev/x86/ide.c +++ b/sys/dev/x86/ide.c @@ -150,7 +150,7 @@ IDE_Reset(IDE *ide) status = IDEWaitForBusy(ide, true); if ((status & IDE_STATUS_RDY) != IDE_STATUS_RDY) { - kprintf("IDE: Controller not ready!\n"); + Log(ide, "Controller not ready!\n"); return; } } @@ -196,7 +196,7 @@ IDE_Identify(IDE *ide, int drive) status = IDEWaitForBusy(ide, true); if ((status & IDE_STATUS_ERR) != 0) { Spinlock_Unlock(&ide->lock); - kprintf("IDE: Error selecting drive %d\n", drive); + Log(ide, "Error selecting drive %d\n", drive); return; } ide->lastDriveCode = driveCode; @@ -209,7 +209,7 @@ IDE_Identify(IDE *ide, int drive) status = inb(ide->base + IDE_STATUS); if (status == 0) { - kprintf("IDE: Drive %d not present\n", drive); + Log(ide, "Drive %d not present\n", drive); return; } @@ -221,7 +221,7 @@ IDE_Identify(IDE *ide, int drive) } if ((status & IDE_STATUS_ERR) != 0) { - kprintf("IDE: Error trying to identify drive %d\n", drive); + Log(ide, "Error trying to identify drive %d\n", drive); return; } @@ -239,8 +239,8 @@ IDE_Identify(IDE *ide, int drive) serial[20] = '\0'; IDE_SwapAndTruncateString(&serial[0], 20); - kprintf("IDE: Drive %d Model: %s Serial: %s\n", drive, model, serial); - kprintf("IDE: Drive %d %llu Sectors (%llu MBs)\n", + Log(ide, "Drive %d Model: %s Serial: %s\n", drive, model, serial); + Log(ide, "Drive %d %llu Sectors (%llu MBs)\n", drive, ident.lbaSectors, ident.lbaSectors / 2048ULL); primaryDrives[drive].ide = &primary; @@ -328,7 +328,7 @@ IDE_ReadOne(IDEDrive *drive, void *buf, uint64_t off, uint64_t len) uint8_t status; IDE *ide = drive->ide; - kprintf("IDE: read %llx %llx\n", off, len); + DLOG(ide, "read %llx %llx\n", off, len); ASSERT(drive->drive == 0 || drive->drive == 1); @@ -347,7 +347,7 @@ IDE_ReadOne(IDEDrive *drive, void *buf, uint64_t off, uint64_t len) status = IDEWaitForBusy(ide, true); if ((status & IDE_STATUS_ERR) != 0) { Spinlock_Unlock(&ide->lock); - kprintf("IDE: Error selecting drive %d\n", drive->drive); + Log(ide, "Error selecting drive %d\n", drive->drive); return -1; } ide->lastDriveCode = driveCode; @@ -372,7 +372,7 @@ IDE_ReadOne(IDEDrive *drive, void *buf, uint64_t off, uint64_t len) status = IDEWaitForBusy(ide, false); if ((status & IDE_STATUS_ERR) != 0) { Spinlock_Unlock(&ide->lock); - kprintf("IDE: Error trying read from drive %d\n", drive->drive); + Log(ide, "Error trying read from drive %d\n", drive->drive); return -1; } @@ -385,7 +385,7 @@ IDE_ReadOne(IDEDrive *drive, void *buf, uint64_t off, uint64_t len) status = IDEWaitForBusy(ide, true); if ((status & IDE_STATUS_ERR) != 0) { Spinlock_Unlock(&ide->lock); - kprintf("IDE: Error reading from drive %d\n", drive->drive); + Log(ide, "Error reading from drive %d\n", drive->drive); return -1; } } @@ -402,7 +402,7 @@ IDE_WriteOne(IDEDrive *drive, void *buf, uint64_t off, uint64_t len) uint8_t status; IDE *ide = drive->ide; - kprintf("IDE: write %llx %llx\n", off, len); + Log(ide, "Write %llx %llx\n", off, len); ASSERT(drive->drive == 0 || drive->drive == 1); @@ -421,7 +421,7 @@ IDE_WriteOne(IDEDrive *drive, void *buf, uint64_t off, uint64_t len) status = IDEWaitForBusy(ide, true); if ((status & IDE_STATUS_ERR) != 0) { Spinlock_Unlock(&ide->lock); - kprintf("IDE: Error selecting drive %d\n", drive->drive); + Log(ide, "Error selecting drive %d\n", drive->drive); return -1; } ide->lastDriveCode = driveCode; @@ -445,7 +445,7 @@ IDE_WriteOne(IDEDrive *drive, void *buf, uint64_t off, uint64_t len) if ((status & IDE_STATUS_ERR) != 0) { Spinlock_Unlock(&ide->lock); - kprintf("IDE: Error trying write from drive %d\n", drive); + Log(ide, "Error trying write from drive %d\n", drive); return -1; } Spinlock_Unlock(&ide->lock); diff --git a/sys/fs/o2fs/o2fs.c b/sys/fs/o2fs/o2fs.c index 91987f1..d3074e7 100644 --- a/sys/fs/o2fs/o2fs.c +++ b/sys/fs/o2fs/o2fs.c @@ -53,26 +53,26 @@ O2FS_Mount(Disk *disk) status = BufCache_Read(disk, 0, &entry); if (status < 0) { - Alert(o2fs, "O2FS: Disk cache read failed\n"); + Alert(o2fs, "Disk cache read failed\n"); return NULL; } // Read superblock sb = entry->buffer; if (memcmp(sb->magic, SUPERBLOCK_MAGIC, 8) != 0) { - Alert(o2fs, "O2FS: Invalid file system\n"); + Alert(o2fs, "Invalid file system\n"); BufCache_Release(entry); return NULL; } if (sb->versionMajor != O2FS_VERSION_MAJOR || sb->versionMinor != O2FS_VERSION_MINOR) { - Alert(o2fs, "O2FS: Unsupported file system version\n"); + Alert(o2fs, "Unsupported file system version\n"); BufCache_Release(entry); return NULL; } - Log(o2fs, "O2FS: File system mounted\n"); - Log(o2fs, "O2FS: Root @ 0x%llx\n", sb->root.offset); + DLOG(o2fs, "File system mounted\n"); + DLOG(o2fs, "Root @ 0x%llx\n", sb->root.offset); fs->fsptr = entry; fs->fsval = sb->root.offset; @@ -86,7 +86,7 @@ O2FS_Mount(Disk *disk) status = O2FS_GetRoot(fs, &fs->root); if (status < 0) { - Alert(o2fs, "O2FS: Mount failed"); + Alert(o2fs, "Mount failed"); BufCache_Release(entry); return NULL; } @@ -111,19 +111,19 @@ O2FSLoadVNode(VFS *fs, ObjID *objid) status = BufCache_Read(fs->disk, objid->offset, &entry); if (status < 0) { - Alert(o2fs, "O2FS: disk read error\n"); + Alert(o2fs, "disk read error\n"); return NULL; } bn = entry->buffer; if (memcmp(&bn->magic, BNODE_MAGIC, 8) != 0) { - Alert(o2fs, "O2FS: bad BNode magic\n"); + Alert(o2fs, "bad BNode magic\n"); BufCache_Release(entry); return NULL; } if (bn->versionMajor != O2FS_VERSION_MAJOR || bn->versionMinor != O2FS_VERSION_MINOR) { - Alert(o2fs, "O2FS: unsupported BNode version\n"); + Alert(o2fs, "unsupported BNode version\n"); BufCache_Release(entry); return NULL; } @@ -176,19 +176,19 @@ O2FS_GetRoot(VFS *fs, VNode **dn) status = BufCache_Read(fs->disk, fs->fsval, &entry); if (status < 0) { - Alert(o2fs, "O2FS: disk read error\n"); + Alert(o2fs, "disk read error\n"); return status; } bn = entry->buffer; if (memcmp(&bn->magic, BNODE_MAGIC, 8) != 0) { - Alert(o2fs, "O2FS: bad BNode magic\n"); + Alert(o2fs, "bad BNode magic\n"); BufCache_Release(entry); return -1; } if (bn->versionMajor != O2FS_VERSION_MAJOR || bn->versionMinor != O2FS_VERSION_MINOR) { - Alert(o2fs, "O2FS: unsupported BNode version\n"); + Alert(o2fs, "unsupported BNode version\n"); BufCache_Release(entry); return -1; } @@ -224,7 +224,7 @@ O2FS_Lookup(VNode *dn, VNode **fn, const char *name) uint64_t blocks = (dirBN->size + sb->blockSize - 1) / sb->blockSize; uint64_t b; - VLOG(o2fs, "O2FS: LOOKUP %lld %d\n", dirBN->size, blocks); + DLOG(o2fs, "Lookup %lld %d\n", dirBN->size, blocks); for (b = 0; b < blocks; b++) { // Read block @@ -295,7 +295,7 @@ O2FS_Read(VNode *fn, void *buf, uint64_t off, uint64_t len) uint64_t blocks = (fileBN->size + sb->blockSize - 1) / sb->blockSize; uint64_t readBytes = 0; - VLOG(o2fs, "O2FS: READ %lld %d\n", fileBN->size, blocks); + DLOG(o2fs, "Read %lld %d\n", fileBN->size, blocks); if (off > fileBN->size) { return 0; @@ -321,6 +321,7 @@ O2FS_Read(VNode *fn, void *buf, uint64_t off, uint64_t len) if (status < 0) return status; + DLOG(o2fs, "READ %lx %lx %lld\n", buf, entry->buffer, bLen); memcpy(buf, entry->buffer + bOff, bLen); BufCache_Release(entry); diff --git a/sys/include/kassert.h b/sys/include/kassert.h index 9b67677..b34d9a2 100644 --- a/sys/include/kassert.h +++ b/sys/include/kassert.h @@ -25,20 +25,20 @@ void Debug_Assert(const char *fmt, ...); #define static_assert _Static_assert // Alert -#define Alert(_module, _format, ...) kprintf(_format, ##__VA_ARGS__) +#define Alert(_module, _format, ...) kprintf(#_module ": " _format, ##__VA_ARGS__) // Warning -#define Warning(_module, _format, ...) kprintf(_format, ##__VA_ARGS__) +#define Warning(_module, _format, ...) kprintf(#_module ": " _format, ##__VA_ARGS__) // Normal Logging -#define Log(_module, _format, ...) kprintf(_format, ##__VA_ARGS__) +#define Log(_module, _format, ...) kprintf(#_module ": " _format, ##__VA_ARGS__) // Debug Logging #define DLOG(_module, _format, ...) \ if (SYSCTL_GETINT(log_##_module) >= 5) { \ - kprintf(_format, ##__VA_ARGS__); \ + kprintf(#_module ": " _format, ##__VA_ARGS__); \ } // Verbose Logging #define VLOG(_module, _format, ...) \ if (SYSCTL_GETINT(log_##_module) >= 10) { \ - kprintf(_format, ##__VA_ARGS__); \ + kprintf(#_module ": " _format, ##__VA_ARGS__); \ } #endif /* __KASSERT_H__ */ diff --git a/sys/include/sysctl.h b/sys/include/sysctl.h index 2a8f1a8..ff350d0 100644 --- a/sys/include/sysctl.h +++ b/sys/include/sysctl.h @@ -26,7 +26,8 @@ SYSCTL_INT(time_tzadj, SYSCTL_FLAG_RW, "Time zone offset in seconds", 0) \ SYSCTL_INT(log_syscall, SYSCTL_FLAG_RW, "Syscall log level", 0) \ SYSCTL_INT(log_loader, SYSCTL_FLAG_RW, "Loader log level", 0) \ - SYSCTL_INT(log_o2fs, SYSCTL_FLAG_RW, "O2FS log level", 0) + SYSCTL_INT(log_o2fs, SYSCTL_FLAG_RW, "O2FS log level", 0) \ + SYSCTL_INT(log_ide, SYSCTL_FLAG_RW, "IDE log level", 0) #define SYSCTL_STR_MAXLENGTH 128