From 74c77412bf960cd5bc5eb2fe95434ec80f5a0e78 Mon Sep 17 00:00:00 2001 From: 4lDO2 <4lDO2@protonmail.com> Date: Sun, 5 Apr 2020 00:17:55 +0200 Subject: [PATCH] Replace all calls to [e]println with log macros. --- xhcid/src/xhci/context.rs | 3 +- xhcid/src/xhci/irq_reactor.rs | 33 +++++----- xhcid/src/xhci/mod.rs | 111 ++++++++++++++-------------------- xhcid/src/xhci/scheme.rs | 23 ++----- 4 files changed, 72 insertions(+), 98 deletions(-) diff --git a/xhcid/src/xhci/context.rs b/xhcid/src/xhci/context.rs index 45023397cc..e971ad28a7 100644 --- a/xhcid/src/xhci/context.rs +++ b/xhcid/src/xhci/context.rs @@ -1,5 +1,6 @@ use std::collections::BTreeMap; +use log::debug; use syscall::error::Result; use syscall::io::{Dma, Io, Mmio}; @@ -59,7 +60,7 @@ pub struct InputContext { } impl InputContext { pub fn dump_control(&self) { - println!( + debug!( "INPUT CONTEXT: {} {} [{} {} {} {} {}] {}", self.drop_context.read(), self.add_context.read(), diff --git a/xhcid/src/xhci/irq_reactor.rs b/xhcid/src/xhci/irq_reactor.rs index 0abc6a2a9b..581e2214d2 100644 --- a/xhcid/src/xhci/irq_reactor.rs +++ b/xhcid/src/xhci/irq_reactor.rs @@ -10,6 +10,7 @@ use std::{io, mem, task, thread}; use std::os::unix::io::AsRawFd; use crossbeam_channel::{Sender, Receiver}; +use log::{debug, error, info, warn, trace}; use futures::Stream; use syscall::Io; @@ -106,7 +107,7 @@ impl IrqReactor { std::thread::yield_now(); } fn run_polling(mut self) { - println!("Running IRQ reactor in polling mode."); + debug!("Running IRQ reactor in polling mode."); let hci_clone = Arc::clone(&self.hci); 'event_loop: loop { @@ -133,7 +134,7 @@ impl IrqReactor { } } fn run_with_irq_file(mut self) { - println!("Running IRQ reactor with IRQ file and event queue"); + debug!("Running IRQ reactor with IRQ file and event queue"); let hci_clone = Arc::clone(&self.hci); let mut event_queue = EventQueue::<()>::new().expect("xhcid irq_reactor: failed to create IRQ event queue"); @@ -142,18 +143,18 @@ impl IrqReactor { let mut event_trb_index = { hci_clone.primary_event_ring.lock().unwrap().ring.next_index() }; event_queue.add(irq_fd, move |_| -> io::Result> { - println!("IRQ event queue notified"); + trace!("IRQ event queue notified"); let mut buffer = [0u8; 8]; let _ = self.irq_file.as_mut().unwrap().read(&mut buffer).expect("Failed to read from irq scheme"); if !self.hci.received_irq() { // continue only when an IRQ to this device was received - println!("no interrupt pending"); + trace!("no interrupt pending"); return Ok(None); } - println!("IRQ reactor received an IRQ"); + trace!("IRQ reactor received an IRQ"); let _ = self.irq_file.as_mut().unwrap().write(&buffer); @@ -167,15 +168,15 @@ impl IrqReactor { let event_trb = &mut event_ring.ring.trbs[event_trb_index]; if event_trb.completion_code() == TrbCompletionCode::Invalid as u8 { - if count == 0 { println!("xhci: Received interrupt, but no event was found in the event ring. Ignoring interrupt.") } + if count == 0 { warn!("xhci: Received interrupt, but no event was found in the event ring. Ignoring interrupt.") } // no more events were found, continue the loop return Ok(None); } else { count += 1 } - println!("Found event TRB: {:?}", event_trb); + trace!("Found event TRB: {:?}", event_trb); if self.check_event_ring_full(event_trb.clone()) { - println!("Had to resize event TRB, retrying..."); + info!("Had to resize event TRB, retrying..."); hci_clone.event_handler_finished(); return Ok(None); } @@ -197,12 +198,12 @@ impl IrqReactor { let dequeue_pointer = dequeue_pointer_and_dcs & 0xFFFF_FFFF_FFFF_FFFE; assert_eq!(dequeue_pointer & 0xFFFF_FFFF_FFFF_FFF0, dequeue_pointer, "unaligned ERDP received from primary event ring"); - println!("Updated ERDP to {:#0x}", dequeue_pointer); + debug!("Updated ERDP to {:#0x}", dequeue_pointer); self.hci.run.lock().unwrap().ints[0].erdp.write(dequeue_pointer); } fn handle_requests(&mut self) { - self.states.extend(self.receiver.try_iter().inspect(|req| println!("Received request: {:?}", req))); + self.states.extend(self.receiver.try_iter().inspect(|req| trace!("Received request: {:?}", req))); } fn acknowledge(&mut self, trb: Trb) { let mut index = 0; @@ -212,7 +213,7 @@ impl IrqReactor { match self.states[index].kind { StateKind::CommandCompletion { phys_ptr } if dbg!(trb.trb_type()) == TrbType::CommandCompletion as u8 => if dbg!(trb.completion_trb_pointer()) == Some(phys_ptr) { - println!("Found matching command completion future"); + trace!("Found matching command completion future"); let state = self.states.remove(index); // Before waking, it's crucial that the command TRB that generated this event @@ -224,7 +225,7 @@ impl IrqReactor { t }, None => { - println!("The xHC supplied a pointer to a command TRB that was outside the known command ring bounds. Ignoring event TRB {:?}.", trb); + warn!("The xHC supplied a pointer to a command TRB that was outside the known command ring bounds. Ignoring event TRB {:?}.", trb); continue; } }; @@ -235,12 +236,12 @@ impl IrqReactor { event_trb: trb.clone(), }); - println!("Waking up future with waker: {:?}", state.waker); + trace!("Waking up future with waker: {:?}", state.waker); state.waker.wake(); return; } else if trb.completion_trb_pointer().is_none() { - println!("Command TRB somehow resulted in an error that only can be caused by transfer TRBs. Ignoring event TRB: {:?}.", trb); + warn!("Command TRB somehow resulted in an error that only can be caused by transfer TRBs. Ignoring event TRB: {:?}.", trb); continue; } else { // The event TRB simply didn't match the current future @@ -290,7 +291,7 @@ impl IrqReactor { } } } - println!("Lost event TRB: {:?}", trb); + warn!("Lost event TRB: {:?}", trb); } fn acknowledge_failed_transfer_trbs(&mut self, trb: Trb) { let mut index = 0; @@ -325,7 +326,7 @@ impl IrqReactor { /// Grows the event ring fn grow_event_ring(&mut self) { // TODO - println!("TODO: grow event ring"); + error!("TODO: grow event ring"); } pub fn run(mut self) { diff --git a/xhcid/src/xhci/mod.rs b/xhcid/src/xhci/mod.rs index 8e11e56781..6656b78fe9 100644 --- a/xhcid/src/xhci/mod.rs +++ b/xhcid/src/xhci/mod.rs @@ -11,6 +11,7 @@ use std::{mem, process, slice, sync::atomic, task, thread}; use chashmap::CHashMap; use crossbeam_channel::{Receiver, Sender}; +use log::{debug, error, info, trace, warn}; use serde::Deserialize; use syscall::error::{Error, Result, EBADF, EBADMSG, ENOENT, EIO}; use syscall::flag::O_RDONLY; @@ -94,14 +95,11 @@ impl MsixInfo { impl Xhci { /// Gets descriptors, before the port state is initiated. async fn get_desc_raw(&self, port: usize, slot: u8, kind: usb::DescriptorKind, index: u8, desc: &mut Dma) -> Result<()> { - println!("A"); let len = mem::size_of::(); let future = { - println!("B"); let mut port_state = self.port_states.get_mut(&port).ok_or(Error::new(ENOENT))?; let ring = port_state.endpoint_states.get_mut(&0).ok_or(Error::new(EIO))?.ring().expect("no ring for the default control pipe"); - println!("C"); let (cmd, cycle) = ring.next(); cmd.setup( @@ -117,24 +115,18 @@ impl Xhci { let (cmd, cycle) = (&mut ring.trbs[last_index], ring.cycle); cmd.status(0, true, true, false, false, cycle); - println!("D"); self.next_transfer_event_trb(RingId::default_control_pipe(port as u8), &ring, &ring.trbs[last_index]) }; - println!("E"); self.dbs.lock().unwrap()[usize::from(slot)].write(Self::def_control_endp_doorbell()); - println!("F"); let trbs = future.await; let event_trb = trbs.event_trb; let status_trb = trbs.src_trb.unwrap(); - println!("G"); self::scheme::handle_transfer_event_trb("GET_DESC", &event_trb, &status_trb)?; - println!("H"); self.event_handler_finished(); - println!("I"); Ok(()) } @@ -242,7 +234,7 @@ impl EndpointState { impl Xhci { pub fn new(scheme_name: String, address: usize, interrupt_method: InterruptMethod, pcid_handle: PcidServerHandle) -> Result { let cap = unsafe { &mut *(address as *mut CapabilityRegs) }; - println!(" - CAP {:X}", address); + debug!("CAP REGS BASE {:X}", address); let page_size = { let memory_fd = syscall::open("memory:", O_RDONLY)?; @@ -253,52 +245,52 @@ impl Xhci { let op_base = address + cap.len.read() as usize; let op = unsafe { &mut *(op_base as *mut OperationalRegs) }; - println!(" - OP {:X}", op_base); + debug!("OP REGS BASE {:X}", op_base); let (max_slots, max_ports) = { - println!(" - Wait for ready"); + debug!("Waiting for xHC becoming ready."); // Wait until controller is ready while op.usb_sts.readf(1 << 11) { - println!(" - Waiting for XHCI ready"); + trace!("Waiting for the xHC to be ready."); } - println!(" - Stop"); + debug!("Stopping the xHC"); // Set run/stop to 0 op.usb_cmd.writef(1, false); - println!(" - Wait for not running"); + debug!("Waiting for the xHC to stop."); // Wait until controller not running while !op.usb_sts.readf(1) { - println!(" - Waiting for XHCI stopped"); + trace!("Waiting for the xHC to stop."); } - println!(" - Reset"); + debug!("Resetting the xHC."); op.usb_cmd.writef(1 << 1, true); while op.usb_sts.readf(1 << 1) { - println!(" - Waiting for XHCI reset"); + trace!("Waiting for the xHC to reset."); } - println!(" - Read max slots"); + debug!("Reading max slots."); let max_slots = cap.max_slots(); let max_ports = cap.max_ports(); - println!(" - Max Slots: {}, Max Ports {}", max_slots, max_ports); + info!("xHC max slots: {}, max ports: {}", max_slots, max_ports); (max_slots, max_ports) }; let port_base = op_base + 0x400; let ports = unsafe { slice::from_raw_parts_mut(port_base as *mut Port, max_ports as usize) }; - println!(" - PORT {:X}", port_base); + debug!("PORT BASE {:X}", port_base); let db_base = address + cap.db_offset.read() as usize; let dbs = unsafe { slice::from_raw_parts_mut(db_base as *mut Doorbell, 256) }; - println!(" - DOORBELL {:X}", db_base); + debug!("DOORBELL REGS BASE {:X}", db_base); let run_base = address + cap.rts_offset.read() as usize; let run = unsafe { &mut *(run_base as *mut RuntimeRegs) }; - println!(" - RUNTIME {:X}", run_base); + debug!("RUNTIME REGS BASE {:X}", run_base); // Create the command ring with 4096 / 16 (TRB size) entries, so that it uses all of the // DMA allocation (which is at least a 4k page). @@ -345,42 +337,42 @@ impl Xhci { pub fn init(&mut self, max_slots: u8) -> Result<()> { // Set enabled slots - println!(" - Set enabled slots to {}", max_slots); + debug!("Setting enabled slots to {}.", max_slots); self.op.get_mut().unwrap().config.write(max_slots as u32); - println!(" - Enabled Slots: {}", self.op.get_mut().unwrap().config.read() & 0xFF); + debug!("Enabled Slots: {}", self.op.get_mut().unwrap().config.read() & 0xFF); // Set device context address array pointer let dcbaap = self.dev_ctx.dcbaap(); - println!(" - Write DCBAAP: {:X}", dcbaap); + debug!("Writing DCBAAP: {:X}", dcbaap); self.op.get_mut().unwrap().dcbaap.write(dcbaap as u64); // Set command ring control register let crcr = self.cmd.get_mut().unwrap().register(); assert_eq!(crcr & 0xFFFF_FFFF_FFFF_FFC1, crcr, "unaligned CRCR"); - println!(" - Write CRCR: {:X}", crcr); + debug!("Writing CRCR: {:X}", crcr); self.op.get_mut().unwrap().crcr.write(crcr as u64); // Set event ring segment table registers - println!(" - Interrupter 0: {:X}", self.run.get_mut().unwrap().ints.as_ptr() as usize); + debug!("Interrupter 0: {:p}", self.run.get_mut().unwrap().ints.as_ptr()); { let int = &mut self.run.get_mut().unwrap().ints[0]; let erstz = 1; - println!(" - Write ERSTZ: {}", erstz); + debug!("Writing ERSTZ: {}", erstz); int.erstsz.write(erstz); let erdp = self.primary_event_ring.get_mut().unwrap().erdp(); - println!(" - Write ERDP: {:X}", erdp); + debug!("Writing ERDP: {:X}", erdp); int.erdp.write(erdp as u64 | (1 << 3)); let erstba = self.primary_event_ring.get_mut().unwrap().erstba(); - println!(" - Write ERSTBA: {:X}", erstba); + debug!("Writing ERSTBA: {:X}", erstba); int.erstba.write(erstba as u64); - println!(" - Write IMODC and IMODI: {} and {}", 0, 0); + debug!("Writing IMODC and IMODI: {} and {}", 0, 0); int.imod.write(0); - println!(" - Enable interrupts"); + debug!("Enabling Primary Interrupter."); int.iman.writef(1 << 1 | 1, true); } @@ -390,22 +382,20 @@ impl Xhci { self.setup_scratchpads()?; // Set run/stop to 1 - println!(" - Start"); + info!("Starting xHC."); self.op.get_mut().unwrap().usb_cmd.writef(1, true); // Wait until controller is running - println!(" - Wait for running"); + debug!("Waiting for start request to complete."); while self.op.get_mut().unwrap().usb_sts.readf(1) { - println!(" - Waiting for XHCI running"); + trace!("Waiting for XHCI to report running status."); } - println!("IP={}", self.run.get_mut().unwrap().ints[0].iman.readf(1)); - // Ring command doorbell - println!(" - Ring doorbell"); + debug!("Ringing command doorbell."); self.dbs.get_mut().unwrap()[0].write(0); - println!(" - XHCI initialized"); + info!("XHCI initialized."); if self.cap.cic() { self.op.get_mut().unwrap().set_cie(true); @@ -422,6 +412,7 @@ impl Xhci { } let scratchpad_buf_arr = ScratchpadBufferArray::new(self.page_size,buf_count)?; self.dev_ctx.dcbaa[0] = scratchpad_buf_arr.register() as u64; + debug!("Setting up {} scratchpads, at {:#0x}", buf_count, scratchpad_buf_arr.register()); self.scratchpad_buf_arr = Some(scratchpad_buf_arr); Ok(()) @@ -452,7 +443,7 @@ impl Xhci { } pub async fn probe(&self) -> Result<()> { - println!("XHCI capabilities: {:?}", self.capabilities_iter().collect::>()); + info!("XHCI capabilities: {:?}", self.capabilities_iter().collect::>()); let port_count = { self.ports.lock().unwrap().len() }; @@ -461,29 +452,26 @@ impl Xhci { let port = &self.ports.lock().unwrap()[i]; (port.read(), port.state(), port.speed(), port.flags()) }; - println!( - " + XHCI Port {}: {:X}, State {}, Speed {}, Flags {:?}", + info!( + "XHCI Port {}: {:X}, State {}, Speed {}, Flags {:?}", i, data, state, speed, flags ); if flags.contains(port::PortFlags::PORT_CCS) { - //TODO: Link TRB when running to the end of the ring buffer - - println!(" - Enable slot"); - let slot_ty = self .supported_protocol(i as u8) .expect("Failed to find supported protocol information for port") .proto_slot_ty(); - println!("Got slot type: {}", slot_ty); + debug!("Slot type: {}", slot_ty); + debug!("Enabling slot."); let slot = self.enable_port_slot(slot_ty).await?; - println!(" - Slot {}", slot); + info!("Enabled port {}, which the xHC mapped to {}", i, slot); let mut input = Dma::::zeroed()?; let mut ring = self.address_device(&mut input, i, slot_ty, slot, speed).await?; - println!("Addressed device"); + info!("Addressed device"); // TODO: Should the descriptors be cached in PortState, or refetched? @@ -504,9 +492,7 @@ impl Xhci { }; self.port_states.insert(i, port_state); - println!("pre get desc"); let dev_desc = self.get_desc(i, slot).await?; - println!("post get desc"); self.port_states.get_mut(&i).unwrap().dev_desc = Some(dev_desc); { @@ -520,7 +506,7 @@ impl Xhci { /*match self.spawn_drivers(i, &mut port_state) { Ok(()) => (), - Err(err) => println!("Failed to spawn driver for port {}: `{}`", i, err), + Err(err) => error!("Failed to spawn driver for port {}: `{}`", i, err), }*/ } @@ -648,14 +634,14 @@ impl Xhci { let input_context_physical = input_context.physical(); - println!("pre_address_device"); let (event_trb, _) = self.execute_command(|trb, cycle| { trb.address_device(slot, input_context_physical, false, cycle) }).await; - println!("post_address_device"); if event_trb.completion_code() != TrbCompletionCode::Success as u8 { - println!("Failed to address device at slot {} (port {})", slot, i); + error!("Failed to address device at slot {} (port {})", slot, i); + self.event_handler_finished(); + return Err(Error::new(EIO)); } self.event_handler_finished(); @@ -690,13 +676,10 @@ impl Xhci { if self.uses_msi() || self.uses_msix() { // Since using MSI and MSI-X implies having no IRQ sharing whatsoever, the IP bit // doesn't have to be touched. - println!("Successfully received MSI/MSI-X interrupt, IP={}, EHB={}", runtime_regs.ints[0].iman.readf(1), runtime_regs.ints[0].erdp.readf(3)); - println!("MSI-X PB={}", self.msix_info_mut().unwrap().pba(0)); - let mut msix = self.msix_info_mut().unwrap(); - let entry = msix.table_entry_pointer(0); - println!("MSI-X entry (addr_lo, addr_hi, msg_data, vec_ctl: {:#0x} {:#0x} {:#0x} {:#0x}", entry.addr_lo.read(), entry.addr_hi.read(), entry.msg_data.read(), entry.vec_ctl.read()); + trace!("Successfully received MSI/MSI-X interrupt, IP={}, EHB={}", runtime_regs.ints[0].iman.readf(1), runtime_regs.ints[0].erdp.readf(3)); true } else if runtime_regs.ints[0].iman.readf(1) { + trace!("Successfully received INTx# interrupt, IP={}, EHB={}", runtime_regs.ints[0].iman.readf(1), runtime_regs.ints[0].erdp.readf(3)); // If MSI and/or MSI-X are not used, the interrupt might have to be shared, and thus there is // a special register to specify whether the IRQ actually came from the xHC. runtime_regs.ints[0].iman.writef(1, true); @@ -734,7 +717,7 @@ impl Xhci { .map(|subclass| subclass == ifdesc.sub_class) .unwrap_or(true) }) { - println!("Loading driver \"{}\"", driver.name); + info!("Loading subdriver\"{}\"", driver.name); let (command, args) = driver.command.split_first().ok_or(Error::new(EBADMSG))?; let if_proto = ifdesc.protocol; @@ -865,10 +848,10 @@ pub fn start_irq_reactor(hci: &Arc, irq_file: Option) { let receiver = hci.irq_reactor_receiver.clone(); let hci_clone = Arc::clone(&hci); - println!("About to start IRQ reactor"); + debug!("About to start IRQ reactor"); *hci.irq_reactor.lock().unwrap() = Some(thread::spawn(move || { - println!("Started IRQ reactor thread"); + info!("Started IRQ reactor thread"); IrqReactor::new(hci_clone, receiver, irq_file).run() })); } diff --git a/xhcid/src/xhci/scheme.rs b/xhcid/src/xhci/scheme.rs index 3709b18845..c39cf56163 100644 --- a/xhcid/src/xhci/scheme.rs +++ b/xhcid/src/xhci/scheme.rs @@ -4,6 +4,7 @@ use std::sync::atomic; use std::{cmp, io, mem, path, str}; use futures::executor::block_on; +use log::{debug, error, info, warn, trace}; use serde::{Deserialize, Serialize}; use smallvec::{smallvec, SmallVec}; @@ -235,9 +236,7 @@ impl Xhci { self.next_command_completion_event_trb(&*command_ring, command_trb) }; - println!("Ringing doorbell"); self.dbs.lock().unwrap()[0].write(0); - println!("Doorbell rung"); let trbs = next_event.await; let event_trb = trbs.event_trb; @@ -381,14 +380,14 @@ impl Xhci { if event_trb.completion_code() != TrbCompletionCode::ShortPacket as u8 && event_trb.transfer_length() != 0 { - println!( + error!( "Event trb didn't yield a short packet, but some bytes were not transferred" ); return Err(Error::new(EIO)); } // TODO: Handle event data - println!("EVENT DATA: {:?}", event_trb.event_data()); + debug!("EVENT DATA: {:?}", event_trb.event_data()); Ok(event_trb) } @@ -925,41 +924,33 @@ impl Xhci { port_id: usize, slot: u8, ) -> Result { - println!("Checkpoint 1"); let ports = self.ports.lock().unwrap(); let port = ports.get(port_id).ok_or(Error::new(ENOENT))?; if !port.flags().contains(port::PortFlags::PORT_CCS) { return Err(Error::new(ENOENT)); } - println!("Checkpoint 2"); let raw_dd = self.fetch_dev_desc(port_id, slot).await?; - println!("Checkpoint 3"); let (manufacturer_str, product_str, serial_str) = ( if raw_dd.manufacturer_str > 0 { - println!("Checkpoint 4a"); Some(self.fetch_string_desc(port_id, slot, raw_dd.manufacturer_str).await?) } else { None }, if raw_dd.product_str > 0 { - println!("Checkpoint 4b"); Some(self.fetch_string_desc(port_id, slot, raw_dd.product_str).await?) } else { None }, if raw_dd.serial_str > 0 { - println!("Checkpoint 4c"); Some(self.fetch_string_desc(port_id, slot, raw_dd.serial_str).await?) } else { None }, ); - println!("Checkpoint 5"); let (bos_desc, bos_data) = self.fetch_bos_desc(port_id, slot).await?; - println!("Checkpoint 6"); let supports_superspeed = usb::bos_capability_descs(bos_desc, &bos_data).any(|desc| desc.is_superspeed()); @@ -969,9 +960,7 @@ impl Xhci { let mut config_descs = SmallVec::new(); for index in 0..raw_dd.configurations { - println!("Checkpoint 7: {}", index); let (desc, data) = self.fetch_config_desc(port_id, slot, index).await?; - println!("Checkpoint 8: {}", index); let extra_length = desc.total_length as usize - mem::size_of_val(&desc); let data = &data[..extra_length]; @@ -2001,7 +1990,7 @@ impl Xhci { /// # Locking /// This function locks `Xhci::run`. pub fn event_handler_finished(&self) { - println!("Event handler finished"); + trace!("Event handler finished"); // write 1 to EHB to clear it self.run.lock().unwrap().ints[0].erdp.writef(1 << 3, true); } @@ -2010,7 +1999,7 @@ pub fn handle_event_trb(name: &str, event_trb: &Trb, command_trb: &Trb) -> Resul if event_trb.completion_code() == TrbCompletionCode::Success as u8 { Ok(()) } else { - println!("{} command (TRB {:?}) failed with event trb {:?}", name, command_trb, event_trb); + error!("{} command (TRB {:?}) failed with event trb {:?}", name, command_trb, event_trb); Err(Error::new(EIO)) } } @@ -2018,7 +2007,7 @@ pub fn handle_transfer_event_trb(name: &str, event_trb: &Trb, transfer_trb: &Trb if event_trb.completion_code() == TrbCompletionCode::Success as u8 || event_trb.completion_code() == TrbCompletionCode::ShortPacket as u8 { Ok(()) } else { - println!("{} transfer (TRB {:?}) failed with event trb {:?}", name, transfer_trb, event_trb); + error!("{} transfer (TRB {:?}) failed with event trb {:?}", name, transfer_trb, event_trb); Err(Error::new(EIO)) } }