boot: driver chatter goes to the log; the console clears its margins

ACPI, DMI, SMP, xHCI, USB, I2C, NVMe, r8169 and ramdisk progress lines are
kinfo now: in dmesg and on a verbose boot, off the screen of a working
machine. Failures stay cprintf.

vt_repaint also paints the strip right of the last column and below the
last row, which kept the bottom of the X desktop after Ctrl+Alt+F-key.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01S1giNvrHTrPMPw7V6x1kQ4

kernel/acpi/aml.c

@@ -272,7 +272,7 @@ prt_lookup(uacpi_pci_routing_table *t, int slot, int pin, int *mode)
     if (f.gsi <= 0) {
       uacpi_object_name nm = uacpi_namespace_node_name(e->source);
       char name[5] = { nm.text[0], nm.text[1], nm.text[2], nm.text[3], 0 };
-      cprintf("acpi: link %s for slot %d is disabled\n", name, slot);
+      kinfo("acpi: link %s for slot %d is disabled\n", name, slot);
       return -1;
     }
     *mode = f.mode;

kernel/acpi/host.c

@@ -121,7 +121,7 @@ uacpi_kernel_log(uacpi_log_level level, const uacpi_char *msg)
   switch (level) {
   case UACPI_LOG_ERROR:
   case UACPI_LOG_WARN:
-    cprintf("acpi: %s", msg);
+    kinfo("acpi: %s", msg);
     break;
   case UACPI_LOG_INFO:
     kinfo("acpi: %s", msg);

kernel/acpi/i2c_hid.c

@@ -421,7 +421,7 @@ controller(const char *path, uint32 speed)
   if(dw_init(c, node, speed) < 0)
     return 0;
   nctl++;
-  cprintf("i2c: %s at 0x%p, %s mode, FIFOs %d/%d\n", path, c->phys,
+  kinfo("i2c: %s at 0x%p, %s mode, FIFOs %d/%d\n", path, c->phys,
           c->fast ? "fast" : "standard", c->txdepth, c->rxdepth);
   return c;
 }
@@ -541,12 +541,12 @@ probe(void *user, uacpi_namespace_node *node, uacpi_u32 depth)
 
   STEP("i2c-hid: %s: reading its resources\n", d->name);
   if(resources(node, &f) < 0 || !f.i2c){
-    cprintf("i2c-hid: %s has no I2C connection\n", d->name);
+    kinfo("i2c-hid: %s has no I2C connection\n", d->name);
     return UACPI_ITERATION_DECISION_CONTINUE;
   }
   STEP("i2c-hid: %s: _DSM\n", d->name);
   if(hid_desc_register(node, &descreg) < 0){
-    cprintf("i2c-hid: %s: _DSM gave no descriptor register\n", d->name);
+    kinfo("i2c-hid: %s: _DSM gave no descriptor register\n", d->name);
     return UACPI_ITERATION_DECISION_CONTINUE;
   }
   STEP("i2c-hid: %s: controller %s, address 0x%x\n", d->name, f.bus, f.addr);
@@ -601,10 +601,10 @@ probe(void *user, uacpi_namespace_node *node, uacpi_u32 depth)
   d->hid = hid_attach(rdesc, rlen, what);
   kfree((char *)rdesc);
   if(d->hid == 0){
-    cprintf("i2c-hid: %s is neither a keyboard nor a pointer\n", d->name);
+    kinfo("i2c-hid: %s is neither a keyboard nor a pointer\n", d->name);
     return UACPI_ITERATION_DECISION_CONTINUE;
   }
-  cprintf("i2c-hid: %s: %x:%x at 0x%x, %s\n", d->name,
+  kinfo("i2c-hid: %s: %x:%x at 0x%x, %s\n", d->name,
           desc[20] | desc[21] << 8, desc[22] | desc[23] << 8, d->addr,
           d->pin ? "interrupt pin watched" : "polled");
   ndev++;

kernel/arch/x86_64/mp.c

@@ -111,7 +111,7 @@ mpinit(void)
   struct mpioapic *ioapic;
 
   if((conf = mpconfig(&mp)) == 0) {
-    cprintf("No other CPUs found.\n");
+    kinfo("No other CPUs found.\n");
     return;
   }
   lapic = (uint*)P2V(conf->lapicaddr_p);
@@ -157,7 +157,7 @@ mpinit(void)
   // See docs/architecture/boot.md -- this is half of the SMP bug, and the
   // reason the other half (AP startup triple-faulting) cannot be reproduced
   // under QEMU until the MADT is parsed.
-  cprintf("Seems we are SMP, ncpu = %d\n",ncpu);
+  kinfo("Seems we are SMP, ncpu = %d\n",ncpu);
   if(mp->imcrp){
     // Bochs doesn't support IMCR, so this doesn't run on Bochs.
     // But it would on real hardware.

kernel/dev/dmi.c

@@ -273,7 +273,7 @@ dmi_init(void)
 
   find();
   if (tab == 0) {
-    cprintf("DMI: not present or invalid.\n");
+    kinfo("DMI: not present or invalid.\n");
     return;
   }
   if (dmi_field(DMI_SYS_VENDOR, v, sizeof v) < 0)       v[0] = 0;
@@ -281,5 +281,5 @@ dmi_init(void)
   if (dmi_field(DMI_BOARD_NAME, b, sizeof b) < 0)       b[0] = 0;
   if (dmi_field(DMI_BIOS_VERSION, bv, sizeof bv) < 0)   bv[0] = 0;
   if (dmi_field(DMI_BIOS_DATE, bd, sizeof bd) < 0)      bd[0] = 0;
-  cprintf("DMI: %s %s/%s, BIOS %s %s\n", v, p, b, bv, bd);
+  kinfo("DMI: %s %s/%s, BIOS %s %s\n", v, p, b, bv, bd);
 }

kernel/dev/ramdisk.c

@@ -110,7 +110,7 @@ ramdiskinit(void)
     rd_scff = h;
     rd_blocks = (uint)(h->image_bytes / BSIZE);
     rd_first = 0;
-    cprintf("ramdisk: SCFF, %u MB in %u MB, %u chunks of %u KB\n",
+    kinfo("ramdisk: SCFF, %u MB in %u MB, %u chunks of %u KB\n",
             (uint)(h->image_bytes >> 20), (uint)(rd_size >> 20),
             h->nchunks, h->chunk_bytes >> 10);
   }
@@ -124,7 +124,7 @@ ramdiskinit(void)
     panic("ramdiskinit: embedded image smaller than a superblock");
 
   if(!rd_scff)
-    cprintf("ramdisk: %u blocks (%u KB) at %p\n",
+    kinfo("ramdisk: %u blocks (%u KB) at %p\n",
             rd_blocks, (uint)(rd_size / 1024), rd_base);
 #else
   rd_base   = 0;
@@ -155,7 +155,7 @@ ramdisk_blocks(void)
     if (extra > room)
       extra = room;
     rd_total = rd_blocks + extra;
-    cprintf("ramdisk: %u MB image, %u MB of memory to grow into\n",
+    kinfo("ramdisk: %u MB image, %u MB of memory to grow into\n",
             (uint)(rd_size >> 20), (uint)(extra * BSIZE >> 20));
   }
   release(&rd_lock);

kernel/dev/vt.c

@@ -240,6 +240,21 @@ vt_repaint(struct vt *v)
 {
   if (!is_active(v))
     return;
+
+  // The margins first: the screen is rarely a whole number of cells, and the
+  // strip right of the last column and below the last row belongs to nobody.
+  // Coming back from X, that strip still held the bottom of the desktop.
+  int cw, ch;
+  gfx_cell_size(&cw, &ch);
+  if (cw > 0 && ch > 0) {
+    int w = (int)gfx_width(), h = (int)gfx_height();
+    uint32 bg = vt_rgb(v->bg);
+    if (w > v->cols * cw)
+      gfx_fill_rect(v->cols * cw, 0, w - v->cols * cw, h, bg);
+    if (h > v->rows * ch)
+      gfx_fill_rect(0, v->rows * ch, w, h - v->rows * ch, bg);
+  }
+
   for (int r = 0; r < v->rows; r++)
     for (int c = 0; c < v->cols; c++) {
       struct vtcell *k = cell_at(v, c, r);

kernel/drivers/bus/xhci/xhci.c

@@ -1062,7 +1062,7 @@ attach_device(struct xhci *x, const struct usb_dev *proto, int parent,
   // cprintf does not pad: "%04x" prints like "%x". It used to be worse -- an
   // unknown directive consumed no argument and every one after it landed in
   // the wrong place, which is what once turned this line into rubbish.
-  cprintf("usb: port %d%s slot %d %x:%x %s, %s speed, %d configuration%s\n",
+  kinfo("usb: port %d%s slot %d %x:%x %s, %s speed, %d configuration%s\n",
           proto->port, proto->route ? " (via hub)" : "", slot,
           desc->idVendor, desc->idProduct,
           class_name(desc->bDeviceClass), speed_name(speed),
@@ -1192,7 +1192,7 @@ xhci_detach(struct usb_dev *hub, int hub_port)
   for(i = 1; i <= MAX_SLOTS; i++)
     if(x->slot[i].used && x->slot[i].parent == hub->slot &&
        x->slot[i].pport == hub_port){
-      cprintf("usb: slot %d unplugged from hub slot %d port %d\n",
+      kinfo("usb: slot %d unplugged from hub slot %d port %d\n",
               i, hub->slot, hub_port);
       free_slot(x, i);
     }
@@ -1492,7 +1492,7 @@ bios_handoff(struct xhci *x)
         for(i = 0; i < 1000 && (rd32(x->cap, off) & LEGSUP_BIOS_OWNED); i++)
           microdelay(1000);
         if(rd32(x->cap, off) & LEGSUP_BIOS_OWNED){
-          cprintf("xhci: firmware would not hand over; taking it anyway\n");
+          kinfo("xhci: firmware would not hand over; taking it anyway\n");
           wr32(x->cap, off,
                (rd32(x->cap, off) & ~LEGSUP_BIOS_OWNED) | LEGSUP_OS_OWNED);
         } else
@@ -1583,7 +1583,7 @@ xhci_probe(struct pci_dev *d)
   // dword and take the top half.
   {
     uint32 v = rd32(x->cap, 0) >> 16;
-    cprintf("xhci: version %d.%d%d, %d ports, %d slots, %d-byte contexts\n",
+    kinfo("xhci: version %d.%d%d, %d ports, %d slots, %d-byte contexts\n",
             (v >> 8) & 0xFF, (v >> 4) & 0xF, v & 0xF,
             x->maxports, x->maxslots, x->ctxsize);
   }
@@ -1670,7 +1670,7 @@ xhci_probe(struct pci_dev *d)
   }
 
   if(x->ndevices == 0)
-    cprintf("xhci: no devices attached\n");
+    kinfo("xhci: no devices attached\n");
 
 
   // Now, and only now, turn interrupts on. The order is: claim the line
@@ -1689,7 +1689,7 @@ xhci_probe(struct pci_dev *d)
   // can sleep rather than spin -- but only if something will wake it. With
   // no interrupt at all, transfers go on spinning as they did during probe.
   if(pci_irq_attach(d, xhci_irq, x, "xhci", PCI_IRQF_MSIX) < 0){
-    cprintf("xhci: no interrupt; transfers will be polled\n");
+    kinfo("xhci: no interrupt; transfers will be polled\n");
   } else {
     x->can_sleep = 1;
     x->running = 1;
@@ -1754,13 +1754,13 @@ scan_ports(struct xhci *x)
     if(!(sc & PORT_CCS)){
       x->port_failed[port] = 0;
       if(slot){
-        cprintf("usb: port %d: unplugged\n", port);
+        kinfo("usb: port %d: unplugged\n", port);
         free_slot(x, slot);
       }
       continue;
     }
     if(slot && (chg & PORT_CSC)){
-      cprintf("usb: port %d: replugged\n", port);
+      kinfo("usb: port %d: replugged\n", port);
       free_slot(x, slot);
       slot = 0;
     }
@@ -1772,7 +1772,7 @@ scan_ports(struct xhci *x)
     sleep_ticks(100 / MSEC_PER_TICK);
     if(!(rd32(x->op, XHCI_PORTSC(port)) & PORT_CCS))
       continue;
-    cprintf("usb: port %d: plugged in\n", port);
+    kinfo("usb: port %d: plugged in\n", port);
     if(enumerate_port(x, port) < 0)
       x->port_failed[port] = 1;
   }

kernel/drivers/gpu/vga/vga_fb.c

@@ -187,7 +187,7 @@ vga_disp_acquire(struct device *d, uint32 *stride_out)
     return 0;
   }
   memset(back, 0, back_bytes);
-  cprintf("display: %d KB back buffer, double buffered\n",
+  kinfo("display: %d KB back buffer, double buffered\n",
           (int)(back_bytes / 1024));
   return back;
 }

kernel/drivers/gpu/vga/vga_pci.c

@@ -79,7 +79,7 @@ vga_pci_probe(struct pci_dev *d)
     // displayed, which is the thing vga.c is writing into. The BAR is the
     // card's whole aperture and the mode may sit at an offset within it. Say
     // so rather than silently preferring one.
-    cprintf("vga: framebuffer disagreement -- VBE says %x, BAR says %x\n",
+    kinfo("vga: framebuffer disagreement -- VBE says %x, BAR says %x\n",
             (uint32)vbe, (uint32)bar->base);
   }
 

kernel/drivers/net/r8169/r8169.c

@@ -471,7 +471,7 @@ r8169_probe(struct pci_dev *d)
   // MSI first: every 8111 has it, and on the boards these are soldered to it
   // is the only interrupt that is sure to arrive. See pci_irq_attach().
   if (pci_irq_attach(d, r8169_intr, r, "r8169", 0) < 0)
-    cprintf("r8169: no usable interrupt line; the link will be polled\n");
+    kinfo("r8169: no usable interrupt line; the link will be polled\n");
 
   r->ready = 1;
 
@@ -487,7 +487,7 @@ r8169_probe(struct pci_dev *d)
     uint32 xid = (rd32(r, R_TCR) >> 20) & 0xFCF;
     int    bmsr = mii_read(r, 1);
 
-    cprintf("r8169: xid %x, %x:%x:%x:%x:%x:%x, irq %d (%s), %s (bmsr %x)\n",
+    kinfo("r8169: xid %x, %x:%x:%x:%x:%x:%x, irq %d (%s), %s (bmsr %x)\n",
             xid,
             r->mac[0], r->mac[1], r->mac[2], r->mac[3], r->mac[4], r->mac[5],
             d->irq_line, pci_irq_kind(d),

kernel/drivers/storage/nvme/nvme.c

@@ -330,13 +330,13 @@ add_namespace(struct nvme *c, uint32 nsid)
   uint32 lbaf = *(uint32 *)(id + 128 + 4 * (id[26] & 0xF));
   uint32 lbads = (lbaf >> 16) & 0xFF;
   if (lbads < 9 || lbads > 12) {
-    cprintf("nvme%d: namespace %d has %d-byte sectors; not used\n",
+    kinfo("nvme%d: namespace %d has %d-byte sectors; not used\n",
             c->index, nsid, 1 << lbads);
     return;
   }
   if (lbaf & 0xFFFF) {
     // Metadata interleaved with the data would land in our bounce buffer.
-    cprintf("nvme%d: namespace %d carries metadata; not used\n",
+    kinfo("nvme%d: namespace %d carries metadata; not used\n",
             c->index, nsid);
     return;
   }
@@ -357,7 +357,7 @@ add_namespace(struct nvme *c, uint32 nsid)
   *p++ = '0' + nsid % 10;
   *p = 0;
 
-  cprintf("nvme: %s: %d MB, %d-byte sectors\n", ns->name,
+  kinfo("nvme: %s: %d MB, %d-byte sectors\n", ns->name,
           (int)((nsze << lbads) >> 20), ns->secsize);
   blkdev_register(ns->name, &nvme_ops, ns, ns->nsectors, ns->secsize);
 }

kernel/drivers/usb/core/usb.c

@@ -341,7 +341,7 @@ usb_attach(struct usb_dev *dev)
       break;
     }
 
-    cprintf("usb:   interface %d: class %d.%d protocol %d, %d endpoint%s%s%s%s\n",
+    kinfo("usb:   interface %d: class %d.%d protocol %d, %d endpoint%s%s%s%s\n",
             d->iface.bInterfaceNumber,
             d->iface.bInterfaceClass, d->iface.bInterfaceSubClass,
             d->iface.bInterfaceProtocol, d->iface.bNumEndpoints,
@@ -353,7 +353,7 @@ usb_attach(struct usb_dev *dev)
     usb_bind_all(d);
 
     if(d->driver == 0){
-      cprintf("usb:   no driver for this interface\n");
+      kinfo("usb:   no driver for this interface\n");
       if(n > 0)
         d->in_use = 0;            // nothing will ever use it; give it back
     }

kernel/drivers/usb/hid/usb_hid.c

@@ -732,7 +732,7 @@ hid_attach(const uchar *desc, int n, const char *what)
   h->proto = !h->x.ok ? USB_HID_PROTO_KEYBOARD :
              h->x.rel ? USB_HID_PROTO_MOUSE : USB_HID_PROTO_TABLET;
   h->in_use = 1;
-  cprintf("%s: %s%s\n", what,
+  kinfo("%s: %s%s\n", what,
           h->proto == USB_HID_PROTO_KEYBOARD ? "keyboard" :
           h->proto == USB_HID_PROTO_MOUSE ? "pointer" : "absolute pointer",
           h->rkbd && h->x.ok ? " and keyboard" : "");
@@ -853,7 +853,7 @@ hid_probe(struct usb_dev *dev)
   } else {
     // A consumer-control interface (volume keys), a game pad, a UPS: HID,
     // and not something this driver has a use for.
-    cprintf("usb-hid: interface %d is neither a keyboard nor a pointer\n",
+    kinfo("usb-hid: interface %d is neither a keyboard nor a pointer\n",
             dev->iface.bInterfaceNumber);
     return -1;
   }
@@ -878,7 +878,7 @@ hid_probe(struct usb_dev *dev)
     return -1;
   }
 
-  cprintf("usb-hid: %s%s on slot %d, endpoint 0x%x every %d ms\n",
+  kinfo("usb-hid: %s%s on slot %d, endpoint 0x%x every %d ms\n",
           h->proto == USB_HID_PROTO_KEYBOARD ? "keyboard" :
           h->proto == USB_HID_PROTO_MOUSE ? "mouse" : "absolute pointer",
           h->proto == USB_HID_PROTO_KEYBOARD ?
@@ -906,7 +906,7 @@ hid_disconnect(struct usb_dev *dev)
     krep.c = 0;
     release(&kqlock);
   }
-  cprintf("usb-hid: %s on slot %d unplugged\n",
+  kinfo("usb-hid: %s on slot %d unplugged\n",
           h->proto == USB_HID_PROTO_KEYBOARD ? "keyboard" : "pointer",
           dev->slot);
   h->in_use = 0;

kernel/drivers/usb/hub/usb_hub.c

@@ -194,7 +194,7 @@ hub_probe(struct usb_dev *dev)
   }
   mtt = (hd->wHubCharacteristics & HUB_CHAR_TT_MASK) != 0;
 
-  cprintf("usb-hub: %d ports on slot %d\n", nports, dev->slot);
+  kinfo("usb-hub: %d ports on slot %d\n", nports, dev->slot);
 
   // Tell the controller *before* powering anything on. Addressing a device
   // behind a slot the controller does not know is a hub fails, and it fails
@@ -291,7 +291,7 @@ usb_hub_poll(void)
       h->dev->ops->detach(h->dev, port);
       if(st & PORTSTAT_CONNECTION){
         microdelay(100000);             // debounce, as on a root port
-        cprintf("usb-hub: slot %d port %d: plugged in\n", h->dev->slot, port);
+        kinfo("usb-hub: slot %d port %d: plugged in\n", h->dev->slot, port);
         hub_port(h->dev, port, h->scratch);
       }
       // The hub may have been unplugged by what was just done; stop if so.

kernel/drivers/usb/storage/usb_storage.c

@@ -349,12 +349,12 @@ usb_storage_dump(void)
     return;
   }
 
-  cprintf("usb-storage: %d sectors of %d bytes\n", u->nsectors,
+  kinfo("usb-storage: %d sectors of %d bytes\n", u->nsectors,
           u->sector_size);
 
   b = bread(USBDISK_DEV, 1);
   sb = (struct superblock*)b->data;
-  cprintf("usb-storage: block 1 magic %x size %d nblocks %d ninodes %d\n",
+  kinfo("usb-storage: block 1 magic %x size %d nblocks %d ninodes %d\n",
           sb->magic, sb->size, sb->nblocks, sb->ninodes);
   brelse(b);
 }
@@ -480,7 +480,7 @@ storage_probe(struct usb_dev *dev)
   }
 
   u->present = 1;
-  cprintf("usb-storage: %s: %s %s, %d sectors (%d MB)\n", u->name,
+  kinfo("usb-storage: %s: %s %s, %d sectors (%d MB)\n", u->name,
           vendor, product, u->nsectors,
           (int)((uint64)u->nsectors * SECTOR_SIZE / (1024 * 1024)));
   u->blkdev = blkdev_register(u->name, &ums_blk_ops, u, u->nsectors,
@@ -517,7 +517,7 @@ storage_disconnect(struct usb_dev *dev)
   u->gone = 1;
   releasesleep(&u->lock);
 
-  cprintf("usb-storage: %s unplugged\n", u->name);
+  kinfo("usb-storage: %s unplugged\n", u->name);
   if(u->blkdev >= 0)
     blkdev_unregister(u->blkdev);
   // USBDISK_DEV may have been this stick; nothing it cached is true now.