diff --git a/devices/common/scsi/mesh.cpp b/devices/common/scsi/mesh.cpp index 9d97a03e75..e2771d9b3d 100644 --- a/devices/common/scsi/mesh.cpp +++ b/devices/common/scsi/mesh.cpp @@ -35,6 +35,8 @@ along with this program. If not, see . using namespace MeshScsi; int MeshController::device_postinit() { + LOG_F(9, "MESH: device_postinit chip_id=0x%X", this->chip_id); + this->bus_obj = dynamic_cast(gMachineObj->get_comp_by_name("ScsiMesh")); if (bus_obj) { bus_obj->register_device(7, static_cast(this)); @@ -45,10 +47,13 @@ int MeshController::device_postinit() { gMachineObj->get_comp_by_type(HWCompType::INT_CTRL)); this->irq_id = this->int_ctrl->register_dev_int(IntSrc::SCSI_MESH); + LOG_F(9, "MESH: device_postinit done, irq_id=%d", this->irq_id); return 0; } void MeshController::reset(bool is_hard_reset) { + LOG_F(9, "MESH: %s reset", is_hard_reset ? "hard" : "soft"); + this->cur_cmd = SeqCmd::NoOperation; this->fifo_pos = 0; this->int_mask = 0; @@ -149,24 +154,31 @@ void MeshController::write(uint8_t reg_offset, uint8_t value) { void MeshController::perform_command(const uint8_t cmd) { this->cur_cmd = cmd; + LOG_F(9, "MESH: perform_command 0x%02X (seq=%d, dma=%d)", + cmd, cmd & 0xF, !!(cmd & 0x80)); + this->int_stat &= ~INT_CMD_DONE; this->is_dma_cmd = !!(this->cur_cmd & 0x80); switch (this->cur_cmd & 0xF) { case SeqCmd::Arbitrate: + LOG_F(9, "MESH: SeqCmd::Arbitrate"); this->exception &= EXC_ARB_LOST; this->bus_obj->release_ctrl_lines(this->src_id); this->cur_state = Scsi_Bus_Controller::SeqState::BUS_FREE; this->sequencer(); break; case SeqCmd::Select: + LOG_F(9, "MESH: SeqCmd::Select dst_id=%d, atn=%d", + this->dst_id, !!(this->cur_cmd & 0x20)); this->assert_atn = !!(this->cur_cmd & 0x20); this->exception &= EXC_SEL_TIMEOUT; this->cur_state = Scsi_Bus_Controller::SeqState::SEL_BEGIN; this->sequencer(); break; case SeqCmd::Command: + LOG_F(9, "MESH: SeqCmd::Command fifo_pos=%d", this->fifo_pos); if (this->bus_obj->current_phase() != ScsiPhase::COMMAND) LOG_F(WARNING, "%s: not in COMMAND phase", this->name.c_str()); this->cur_state = Scsi_Bus_Controller::SeqState::SEND_CMD; @@ -174,6 +186,7 @@ void MeshController::perform_command(const uint8_t cmd) { this->sequencer(); break; case SeqCmd::Status: + LOG_F(9, "MESH: SeqCmd::Status xfer_count=%d", this->xfer_count); if (this->bus_obj->current_phase() != ScsiPhase::STATUS) LOG_F(WARNING, "%s: not in STATUS phase", this->name.c_str()); this->to_xfer = this->xfer_count; @@ -181,6 +194,7 @@ void MeshController::perform_command(const uint8_t cmd) { this->sequencer(); break; case SeqCmd::DataOut: + LOG_F(9, "MESH: SeqCmd::DataOut xfer_count=%d", this->xfer_count); if (this->bus_obj->current_phase() != ScsiPhase::DATA_OUT) LOG_F(WARNING, "%s: not in DATA OUT phase", this->name.c_str()); this->to_xfer = this->xfer_count ? this->xfer_count : 65536; @@ -188,6 +202,7 @@ void MeshController::perform_command(const uint8_t cmd) { this->sequencer(); break; case SeqCmd::DataIn: + LOG_F(9, "MESH: SeqCmd::DataIn xfer_count=%d", this->xfer_count); if (this->bus_obj->current_phase() != ScsiPhase::DATA_IN) LOG_F(WARNING, "%s: not in DATA IN phase", this->name.c_str()); this->to_xfer = this->xfer_count ? this->xfer_count : 65536; @@ -195,6 +210,7 @@ void MeshController::perform_command(const uint8_t cmd) { this->sequencer(); break; case SeqCmd::MessageOut: + LOG_F(9, "MESH: SeqCmd::MessageOut xfer_count=%d", this->xfer_count); if (this->bus_obj->current_phase() != ScsiPhase::MESSAGE_OUT) LOG_F(WARNING, "%s: not in MESSAGE OUT phase", this->name.c_str()); this->to_xfer = this->xfer_count; @@ -202,6 +218,7 @@ void MeshController::perform_command(const uint8_t cmd) { this->sequencer(); break; case SeqCmd::MessageIn: + LOG_F(9, "MESH: SeqCmd::MessageIn xfer_count=%d", this->xfer_count); if (this->bus_obj->current_phase() != ScsiPhase::MESSAGE_IN) LOG_F(WARNING, "%s: not in MESSAGE IN phase", this->name.c_str()); this->to_xfer = this->xfer_count; @@ -209,6 +226,7 @@ void MeshController::perform_command(const uint8_t cmd) { this->sequencer(); break; case SeqCmd::BusFree: + LOG_F(9, "MESH: SeqCmd::BusFree"); // Don't release ACK if ATN is asserted. This condition indicates // that the initiator wants to reject last message. if (!this->bus_obj->test_ctrl_lines(SCSI_CTRL_ATN)) @@ -229,9 +247,11 @@ void MeshController::perform_command(const uint8_t cmd) { this->update_irq(); break; case SeqCmd::EnaParityCheck: + LOG_F(9, "MESH: SeqCmd::EnaParityCheck"); this->check_parity = true; break; case SeqCmd::DisParityCheck: + LOG_F(9, "MESH: SeqCmd::DisParityCheck"); this->check_parity = false; break; case SeqCmd::EnaReselect: @@ -243,11 +263,13 @@ void MeshController::perform_command(const uint8_t cmd) { this->int_stat |= INT_CMD_DONE; break; case SeqCmd::ResetMesh: + LOG_F(9, "MESH: SeqCmd::ResetMesh"); this->reset(false); this->int_stat |= INT_CMD_DONE; update_irq(); break; case SeqCmd::FlushFIFO: + LOG_F(9, "MESH: SeqCmd::FlushFIFO (was %d bytes)", this->fifo_pos); this->fifo_pos = 0; break; default: @@ -258,6 +280,9 @@ void MeshController::perform_command(const uint8_t cmd) { void MeshController::update_bus_status(const uint16_t new_stat) { uint16_t mask; + LOG_F(9, "MESH: update_bus_status 0x%04X -> 0x%04X", + this->bus_stat, new_stat); + // update the lower part (BusStatus0) if ((new_stat ^ this->bus_stat) & 0xFF) { for (mask = SCSI_CTRL_REQ; mask >= SCSI_CTRL_IO; mask >>= 1) { @@ -291,6 +316,10 @@ void MeshController::step_completed() { } void MeshController::report_error(const int error) { + LOG_F(9, "MESH: report_error %d (%s)", error, + error == ARB_LOST ? "ARB_LOST" : + error == SEL_TIMEOUT ? "SEL_TIMEOUT" : "UNKNOWN"); + switch (error) { case ARB_LOST: this->exception |= EXC_ARB_LOST; diff --git a/devices/common/scsi/sc53c94.cpp b/devices/common/scsi/sc53c94.cpp index 310128db50..c909094608 100644 --- a/devices/common/scsi/sc53c94.cpp +++ b/devices/common/scsi/sc53c94.cpp @@ -35,6 +35,7 @@ along with this program. If not, see . Sc53C94::Sc53C94(uint8_t chip_id, uint8_t my_id) : ScsiPhysDevice("SC53C94", my_id), DmaDevice() { + LOG_F(9, "SC53C94: ctor chip_id=0x%X, my_bus_id=%d", chip_id, my_id); this->chip_id = chip_id; this->my_bus_id = my_id; supports_types(HWCompType::SCSI_HOST | HWCompType::SCSI_DEV); @@ -43,6 +44,8 @@ Sc53C94::Sc53C94(uint8_t chip_id, uint8_t my_id) : ScsiPhysDevice("SC53C94", my_ int Sc53C94::device_postinit() { + LOG_F(9, "%s: device_postinit", this->name.c_str()); + ScsiBus* bus = dynamic_cast(gMachineObj->get_comp_by_name("ScsiCurio")); if (bus) { bus->register_device(7, static_cast(this)); @@ -53,11 +56,14 @@ int Sc53C94::device_postinit() gMachineObj->get_comp_by_type(HWCompType::INT_CTRL)); this->irq_id = this->int_ctrl->register_dev_int(IntSrc::SCSI_CURIO); + LOG_F(9, "%s: device_postinit done, irq_id=%d", this->name.c_str(), this->irq_id); return 0; } void Sc53C94::reset_device() { + LOG_F(9, "%s: reset_device", this->name.c_str()); + // part-unique ID to be read using a magic sequence this->xfer_count = this->chip_id << 16; @@ -236,6 +242,9 @@ uint16_t Sc53C94::pseudo_dma_read() } void Sc53C94::pseudo_dma_write(uint16_t data) { + LOG_F(9, "%s: pseudo_dma_write 0x%04X, fifo_pos=%d, xfer_count=%u", + this->name.c_str(), data, this->data_fifo_pos, + (unsigned)this->xfer_count); this->fifo_push((data >> 8) & 0xFFU); this->fifo_push(data & 0xFFU); @@ -284,6 +293,10 @@ void Sc53C94::exec_command() this->is_dma_cmd = !!(this->cmd_fifo[0] & CMD_ISDMA); + LOG_F(9, "%s: exec_command opcode=0x%02X, dma=%d, set_xfer_count=%u", + this->name.c_str(), cmd, this->is_dma_cmd, + (unsigned)this->set_xfer_count); + if (this->is_dma_cmd) { if (this->config2 & CFG2_ENF) { // extended mode: 24-bit this->xfer_count = this->set_xfer_count & 0xFFFFFFUL; @@ -302,15 +315,18 @@ void Sc53C94::exec_command() // and handled by the sequencer switch (cmd) { case CMD_NOP: + LOG_F(9, "%s: CMD_NOP", this->name.c_str()); this->on_reset = false; // unblock the command register exec_next_command(); break; case CMD_CLEAR_FIFO: + LOG_F(9, "%s: CMD_CLEAR_FIFO", this->name.c_str()); this->data_fifo_pos = 0; // set the bottom of the data FIFO to zero this->data_fifo[0] = 0; exec_next_command(); break; case CMD_RESET_DEVICE: + LOG_F(9, "%s: CMD_RESET_DEVICE", this->name.c_str()); reset_device(); this->on_reset = true; // block the command register return; @@ -337,6 +353,8 @@ void Sc53C94::exec_command() exec_next_command(); break; case CMD_XFER: + LOG_F(9, "%s: CMD_XFER is_initiator=%d", this->name.c_str(), + this->is_initiator); if (!this->is_initiator) { // clear command FIFO this->cmd_fifo_pos = 0; @@ -348,6 +366,7 @@ void Sc53C94::exec_command() } break; case CMD_COMPLETE_STEPS: + LOG_F(9, "%s: CMD_COMPLETE_STEPS", this->name.c_str()); if (this->bus_obj->current_phase() != ScsiPhase::STATUS) { ABORT_F("%s: complete steps only works in the STATUS phase", this->name.c_str()); } @@ -355,6 +374,7 @@ void Sc53C94::exec_command() this->sequencer(); break; case CMD_MSG_ACCEPTED: + LOG_F(9, "%s: CMD_MSG_ACCEPTED", this->name.c_str()); // Don't release ACK if ATN is asserted. // Executing this command with ATN true means that // the initiator wants to reject the current message. @@ -371,6 +391,8 @@ void Sc53C94::exec_command() exec_next_command(); break; case CMD_XFER_PAD_BYTES: + LOG_F(9, "%s: CMD_XFER_PAD_BYTES set_xfer_count=%u", + this->name.c_str(), (unsigned)this->set_xfer_count); if (this->bus_obj->current_phase() != ScsiPhase::COMMAND) ABORT_F("%s: unsupported phase %d in CMD_XFER_PAD_BYTES", this->name.c_str(), this->bus_obj->current_phase()); @@ -386,6 +408,7 @@ void Sc53C94::exec_command() } break; case CMD_RESET_ATN: + LOG_F(9, "%s: CMD_RESET_ATN", this->name.c_str()); this->bus_obj->release_ctrl_line(this->my_bus_id, SCSI_CTRL_ATN); exec_next_command(); break; @@ -426,6 +449,7 @@ void Sc53C94::exec_command() LOG_F(9, "%s: SELECT WITH ATN AND STOP command started", this->name.c_str()); break; case CMD_ENA_SEL_RESEL: + LOG_F(9, "%s: CMD_ENA_SEL_RESEL", this->name.c_str()); exec_next_command(); break; default: @@ -438,6 +462,8 @@ void Sc53C94::exec_command() void Sc53C94::exec_next_command() { + LOG_F(9, "%s: exec_next_command, cmd_fifo_pos=%d", + this->name.c_str(), this->cmd_fifo_pos); if (this->cmd_fifo_pos) { // skip empty command FIFO this->cmd_fifo_pos--; // remove completed command if (this->cmd_fifo_pos) { // is there another command in the FIFO? @@ -475,6 +501,9 @@ uint8_t Sc53C94::fifo_pop() void Sc53C94::seq_defer_state(uint64_t delay_ns) { + LOG_F(9, "%s: seq_defer_state next_state=%d, delay=%llu ns", + this->name.c_str(), this->next_state, (unsigned long long)delay_ns); + if (this->seq_timer_id) { TimerManager::get_instance()->cancel_timer(this->seq_timer_id); this->seq_timer_id = 0; @@ -502,6 +531,8 @@ void Sc53C94::seq_defer_state(uint64_t delay_ns) void Sc53C94::sequencer() { + LOG_F(9, "%s: sequencer entry, cur_state=%d, bus_phase=%d", + this->name.c_str(), this->cur_state, this->cur_bus_phase); switch (this->cur_state) { case SeqState::IDLE: break; @@ -755,6 +786,10 @@ int Sc53C94::send_data(uint8_t* dst_ptr, int count) int actual_count = std::min(this->data_fifo_pos, count); + LOG_F(9, "%s: send_data count=%d (requested %d), fifo_pos=%d, phase=%d", + this->name.c_str(), actual_count, count, this->data_fifo_pos, + this->cur_bus_phase); + // move data out of the data FIFO std::memcpy(dst_ptr, this->data_fifo, actual_count); @@ -785,6 +820,10 @@ bool Sc53C94::rcv_data() req_count = 1; } + LOG_F(9, "%s: rcv_data req_count=%d, phase=%d, dma=%d, fifo_pos=%d, xfer_count=%u", + this->name.c_str(), req_count, this->cur_bus_phase, this->is_dma_cmd, + this->data_fifo_pos, (unsigned)this->xfer_count); + this->bus_obj->pull_data(this->target_id, &this->data_fifo[this->data_fifo_pos], req_count); this->data_fifo_pos += req_count; return true; @@ -794,6 +833,9 @@ void Sc53C94::real_dma_xfer_out() { // transfer data from host's memory to target + LOG_F(9, "%s: real_dma_xfer_out xfer_count=%u, fifo_pos=%d", + this->name.c_str(), (unsigned)this->xfer_count, this->data_fifo_pos); + if (this->xfer_count) { uint32_t got_bytes; uint8_t* src_ptr; @@ -829,6 +871,9 @@ void Sc53C94::real_dma_xfer_in() // transfer data from target to host's memory + LOG_F(9, "%s: real_dma_xfer_in xfer_count=%u, fifo_pos=%d", + this->name.c_str(), (unsigned)this->xfer_count, this->data_fifo_pos); + if (this->xfer_count && this->data_fifo_pos) { this->dma_ch->push_data((char*)this->data_fifo, this->data_fifo_pos); @@ -856,6 +901,8 @@ void Sc53C94::real_dma_xfer_in() } void Sc53C94::dma_wait() { + LOG_F(9, "%s: dma_wait phase=%d, state=%d", + this->name.c_str(), this->cur_bus_phase, this->cur_state); if (this->cur_bus_phase == ScsiPhase::DATA_IN && this->cur_state == SeqState::RCV_DATA) { real_dma_xfer_in(); } @@ -874,11 +921,14 @@ void Sc53C94::dma_wait() { void Sc53C94::dma_start() { + LOG_F(9, "%s: dma_start xfer_count=%u", + this->name.c_str(), (unsigned)this->xfer_count); dma_wait(); } void Sc53C94::dma_stop() { + LOG_F(9, "%s: dma_stop", this->name.c_str()); if (this->dma_timer_id) { TimerManager::get_instance()->cancel_timer(this->dma_timer_id); this->dma_timer_id = 0; diff --git a/devices/common/scsi/scsiblockcmds.cpp b/devices/common/scsi/scsiblockcmds.cpp index 25192286e9..448c077f06 100644 --- a/devices/common/scsi/scsiblockcmds.cpp +++ b/devices/common/scsi/scsiblockcmds.cpp @@ -24,6 +24,7 @@ along with this program. If not, see . #include ScsiBlockCmds::ScsiBlockCmds() { + LOG_F(9, "ScsiBlockCmds: enabling block-command set"); this->enable_cmd(ScsiCommand::READ_6); this->enable_cmd(ScsiCommand::READ_10); this->enable_cmd(ScsiCommand::READ_12); @@ -41,6 +42,10 @@ ScsiBlockCmds::ScsiBlockCmds() { void ScsiBlockCmds::init_block_device(uint8_t medium_type, uint8_t dev_flags, uint8_t density_code, bool is_apple_compliant) { + LOG_F(9, "ScsiBlockCmds: init_block_device medium_type=0x%02X, flags=0x%02X, " + "density=0x%02X, apple_compliant=%d", + medium_type, dev_flags, density_code, is_apple_compliant); + this->medium_type = medium_type; this->device_flags = dev_flags; @@ -81,6 +86,8 @@ void ScsiBlockCmds::init_block_device(uint8_t medium_type, uint8_t dev_flags, void ScsiBlockCmds::process_command() { int next_phase; + LOG_F(9, "ScsiBlockCmds: process_command opcode=0x%02X", this->cdb_ptr[0]); + // use non-disk buffer by default phy_impl->set_buffer(this->buf_ptr); @@ -88,21 +95,31 @@ void ScsiBlockCmds::process_command() { case ScsiCommand::READ_6: case ScsiCommand::READ_10: case ScsiCommand::READ_12: + LOG_F(9, "ScsiBlockCmds: dispatch READ_%d", + this->cdb_ptr[0] == ScsiCommand::READ_6 ? 6 : + this->cdb_ptr[0] == ScsiCommand::READ_10 ? 10 : 12); next_phase = this->read_new(); break; case ScsiCommand::WRITE_6: case ScsiCommand::WRITE_10: case ScsiCommand::WRITE_12: + LOG_F(9, "ScsiBlockCmds: dispatch WRITE_%d", + this->cdb_ptr[0] == ScsiCommand::WRITE_6 ? 6 : + this->cdb_ptr[0] == ScsiCommand::WRITE_10 ? 10 : 12); next_phase = this->write_new(); break; case ScsiCommand::START_STOP_UNIT: + LOG_F(9, "ScsiBlockCmds: dispatch START_STOP_UNIT"); next_phase = this->start_stop_unit(); break; case ScsiCommand::PREVENT_ALLOW_MEDIUM_REMOVAL: + LOG_F(9, "ScsiBlockCmds: dispatch PREVENT_ALLOW_MEDIUM_REMOVAL, eject=%d", + (this->cdb_ptr[4] & 1) == 0); phy_impl->set_eject_state((this->cdb_ptr[4] & 1) == 0); next_phase = ScsiPhase::STATUS; break; case ScsiCommand::READ_CAPACITY: + LOG_F(9, "ScsiBlockCmds: dispatch READ_CAPACITY"); next_phase = this->read_capacity(); break; default: @@ -224,6 +241,9 @@ int ScsiBlockCmds::format_block_descriptors(uint8_t* out_ptr) { uint32_t nblocks = (uint32_t)std::min( this->blk_dev->get_size_in_blocks(), (uint64_t)0xFFFFFFFFU); + LOG_F(9, "ScsiBlockCmds: format_block_descriptors nblocks=%u, density=0x%02X, blk_size=%u", + nblocks, this->density_code, this->blk_dev->get_block_size()); + WRITE_DWORD_BE_A(&out_ptr[0], nblocks); WRITE_DWORD_BE_A(&out_ptr[4], (this->density_code << 24) | (this->blk_dev->get_block_size() & 0xFFFFFF)); @@ -234,6 +254,9 @@ int ScsiBlockCmds::format_block_descriptors(uint8_t* out_ptr) { int ScsiBlockCmds::get_error_recovery_page(uint8_t ctrl, uint8_t subpage, uint8_t *out_ptr, int avail_len) { + LOG_F(9, "ScsiBlockCmds: get_error_recovery_page ctrl=%d, subpage=0x%02X, avail=%d", + ctrl, subpage, avail_len); + if (subpage && subpage != 0xFFU) return FORMAT_ERR_BAD_SUBPAGE; @@ -252,16 +275,23 @@ int ScsiBlockCmds::get_error_recovery_page(uint8_t ctrl, uint8_t subpage, uint32_t ScsiBlockCmds::get_lba() { int cmd_len = this->get_cdb_length(this->cdb_ptr[0]); + uint32_t lba; switch(cmd_len) { case 6: - return ((this->cdb_ptr[1] & 0x1F) << 16) | READ_WORD_BE_A(&this->cdb_ptr[2]); + lba = ((this->cdb_ptr[1] & 0x1F) << 16) | READ_WORD_BE_A(&this->cdb_ptr[2]); + break; case 10: case 12: - return READ_DWORD_BE_U(&this->cdb_ptr[2]); + lba = READ_DWORD_BE_U(&this->cdb_ptr[2]); + break; default: ABORT_F("unsupported command length %d in get_lba", cmd_len); } + + LOG_F(9, "ScsiBlockCmds: get_lba opcode=0x%02X, cdb_len=%d, lba=%u", + this->cdb_ptr[0], cmd_len, lba); + return lba; } static char Apple_Copyright_Page_Data[] = "APPLE COMPUTER, INC "; @@ -269,6 +299,9 @@ static char Apple_Copyright_Page_Data[] = "APPLE COMPUTER, INC "; int ScsiBlockCmds::get_apple_copyright_page(uint8_t ctrl, uint8_t subpage, uint8_t *out_ptr, int avail_len) { + LOG_F(9, "ScsiBlockCmds: get_apple_copyright_page ctrl=%d, subpage=0x%02X, avail=%d", + ctrl, subpage, avail_len); + if (subpage && subpage != 0xFFU) return FORMAT_ERR_BAD_SUBPAGE; diff --git a/devices/common/scsi/scsibus.cpp b/devices/common/scsi/scsibus.cpp index 432ddef29b..9819c501eb 100644 --- a/devices/common/scsi/scsibus.cpp +++ b/devices/common/scsi/scsibus.cpp @@ -47,10 +47,15 @@ ScsiBus::ScsiBus(const std::string name) this->arb_winner_id = -1; this->initiator_id = -1; this->target_id = -1; + + LOG_F(9, "%s: bus created, max devices=%d", this->get_name().c_str(), SCSI_MAX_DEVS); } void ScsiBus::register_device(int id, ScsiPhysDevice* dev_obj) { + LOG_F(9, "%s: register device id=%d (%s)", this->get_name().c_str(), id, + dev_obj ? dev_obj->get_name().c_str() : ""); + if (this->devices[id] != nullptr) { ABORT_F("%s: device with ID %d already registered", this->get_name().c_str(), id); } @@ -62,6 +67,9 @@ void ScsiBus::register_device(int id, ScsiPhysDevice* dev_obj) void ScsiBus::change_bus_phase(int initiator_id) { + LOG_F(9, "%s: change_bus_phase initiator=%d, new_phase=%d", + this->get_name().c_str(), initiator_id, this->cur_phase); + for (int i = 0; i < SCSI_MAX_DEVS; i++) { if (i == initiator_id) continue; // don't notify the initiator @@ -121,6 +129,7 @@ void ScsiBus::release_ctrl_line(int id, uint16_t mask) void ScsiBus::release_ctrl_lines(int id) { + LOG_F(9, "%s: release all ctrl lines for id=%d", this->get_name().c_str(), id); this->release_ctrl_line(id, 0xFFFFUL); } @@ -140,6 +149,9 @@ int ScsiBus::switch_phase(int id, int new_phase) { int old_phase = this->cur_phase; + LOG_F(9, "%s: switch_phase id=%d, %d -> %d", + this->get_name().c_str(), id, old_phase, new_phase); + // leave the current phase (low-level) switch (old_phase) { case ScsiPhase::COMMAND: @@ -187,12 +199,17 @@ int ScsiBus::switch_phase(int id, int new_phase) bool ScsiBus::begin_arbitration(int initiator_id) { + LOG_F(9, "%s: begin_arbitration initiator=%d, cur_phase=%d", + this->get_name().c_str(), initiator_id, this->cur_phase); + if (this->cur_phase == ScsiPhase::BUS_FREE) { this->data_lines |= 1 << initiator_id; this->cur_phase = ScsiPhase::ARBITRATION; change_bus_phase(initiator_id); return true; } else { + LOG_F(9, "%s: begin_arbitration denied, bus not free (phase=%d)", + this->get_name().c_str(), this->cur_phase); return false; } } @@ -213,14 +230,23 @@ bool ScsiBus::end_arbitration(int initiator_id) this->arb_winner_id = highest_id; } + LOG_F(9, "%s: end_arbitration initiator=%d, winner=%d, data_lines=0x%02x", + this->get_name().c_str(), initiator_id, highest_id, this->data_lines); + return highest_id == initiator_id; } bool ScsiBus::begin_selection(int initiator_id, int target_id, bool atn) { + LOG_F(9, "%s: begin_selection initiator=%d, target=%d, atn=%d", + this->get_name().c_str(), initiator_id, target_id, atn); + // perform bus integrity checks - if (this->cur_phase != ScsiPhase::ARBITRATION || this->arb_winner_id != initiator_id) + if (this->cur_phase != ScsiPhase::ARBITRATION || this->arb_winner_id != initiator_id) { + LOG_F(9, "%s: begin_selection denied, phase=%d, arb_winner=%d", + this->get_name().c_str(), this->cur_phase, this->arb_winner_id); return false; + } this->assert_ctrl_line(initiator_id, SCSI_CTRL_SEL); @@ -238,6 +264,9 @@ bool ScsiBus::begin_selection(int initiator_id, int target_id, bool atn) void ScsiBus::confirm_selection(int target_id) { + LOG_F(9, "%s: confirm_selection target=%d, initiator=%d", + this->get_name().c_str(), target_id, this->initiator_id); + this->target_id = target_id; // notify initiator about selection confirmation from target @@ -248,8 +277,12 @@ void ScsiBus::confirm_selection(int target_id) bool ScsiBus::end_selection(int initiator_id, int target_id) { + bool confirmed = (this->target_id == target_id); + LOG_F(9, "%s: end_selection initiator=%d, target=%d, confirmed=%d", + this->get_name().c_str(), initiator_id, target_id, confirmed); + // check for selection confirmation from target - return this->target_id == target_id; + return confirmed; } bool ScsiBus::pull_data(const int id, uint8_t* dst_ptr, const int size) @@ -285,6 +318,8 @@ bool ScsiBus::push_data(const int id, const uint8_t* src_ptr, const int size) } int ScsiBus::target_xfer_data() { + LOG_F(9, "%s: target_xfer_data target_id=%d", + this->get_name().c_str(), this->target_id); return this->devices[this->target_id]->xfer_data(); } diff --git a/devices/common/scsi/scsibusctrl.cpp b/devices/common/scsi/scsibusctrl.cpp index fd694606d0..c549525bac 100644 --- a/devices/common/scsi/scsibusctrl.cpp +++ b/devices/common/scsi/scsibusctrl.cpp @@ -31,6 +31,8 @@ along with this program. If not, see . using namespace Scsi_Bus_Controller; void ScsiBusController::seq_defer_state(uint64_t delay_ns) { + LOG_F(9, "%s: seq_defer_state next_state=%d, delay=%llu ns", + this->name.c_str(), this->next_state, (unsigned long long)delay_ns); seq_timer_id = TimerManager::get_instance()->add_oneshot_timer( delay_ns, [this]() { @@ -41,6 +43,8 @@ void ScsiBusController::seq_defer_state(uint64_t delay_ns) { } void ScsiBusController::sequencer() { + LOG_F(9, "%s: sequencer entry, cur_state=%d, bus_phase=%d", + this->name.c_str(), this->cur_state, this->bus_obj->current_phase()); switch (this->cur_state) { case SeqState::IDLE: break; @@ -92,6 +96,8 @@ void ScsiBusController::sequencer() { } break; case SeqState::SEND_MSG: + LOG_F(9, "%s: seq SEND_MSG, fifo_pos=%d, to_xfer=%d", + this->name.c_str(), this->fifo_pos, this->to_xfer); if (this->fifo_pos) { this->bus_obj->target_xfer_data(); this->bus_obj->release_ctrl_line(this->src_id, SCSI_CTRL_ATN); @@ -102,12 +108,16 @@ void ScsiBusController::sequencer() { } break; case SeqState::SEND_CMD: + LOG_F(9, "%s: seq SEND_CMD, fifo_pos=%d", + this->name.c_str(), this->fifo_pos); this->bus_obj->target_xfer_data(); if (!this->fifo_pos) this->step_completed(); break; case SeqState::XFER_BEGIN: this->cur_bus_phase = this->bus_obj->current_phase(); + LOG_F(9, "%s: seq XFER_BEGIN, bus_phase=%d", + this->name.c_str(), this->cur_bus_phase); switch (this->cur_bus_phase) { case ScsiPhase::DATA_OUT: this->cur_state = SeqState::SEND_DATA; @@ -118,11 +128,15 @@ void ScsiBusController::sequencer() { } break; case SeqState::XFER_END: + LOG_F(9, "%s: seq XFER_END, is_initiator=%d", + this->name.c_str(), this->is_initiator); if (this->is_initiator) this->bus_obj->target_next_step(); this->step_completed(); break; case SeqState::SEND_DATA: + LOG_F(9, "%s: seq SEND_DATA, fifo_pos=%d, to_xfer=%d", + this->name.c_str(), this->fifo_pos, this->to_xfer); if (this->bus_obj->push_data(this->dst_id, this->data_fifo, this->fifo_pos)) { this->to_xfer -= this->fifo_pos; this->fifo_pos = 0; @@ -137,6 +151,8 @@ void ScsiBusController::sequencer() { if (this->bus_obj->current_phase() != this->cur_bus_phase) { LOG_F(WARNING, "%s: phase mismatch!", this->name.c_str()); } else { + LOG_F(9, "%s: seq RCV_DATA, to_xfer=%d", + this->name.c_str(), this->to_xfer); if (!this->rcv_data()) { this->cur_state = SeqState::XFER_END; this->sequencer(); @@ -145,6 +161,9 @@ void ScsiBusController::sequencer() { break; case SeqState::RCV_STATUS: case SeqState::RCV_MESSAGE: + LOG_F(9, "%s: seq %s, bus_phase=%d", this->name.c_str(), + this->cur_state == SeqState::RCV_STATUS ? "RCV_STATUS" : "RCV_MESSAGE", + this->cur_bus_phase); if (this->cur_bus_phase == ScsiPhase::MESSAGE_IN) this->bus_obj->assert_ctrl_line(this->src_id, SCSI_CTRL_REQ); this->rcv_data(); @@ -208,6 +227,10 @@ bool ScsiBusController::rcv_data() { req_count = std::min(this->to_xfer, DATA_FIFO_DEPTH - this->fifo_pos); + LOG_F(9, "%s: rcv_data %d bytes, phase=%d, fifo_pos=%d, to_xfer=%d", + this->name.c_str(), req_count, this->cur_bus_phase, + this->fifo_pos, this->to_xfer); + this->bus_obj->pull_data(this->dst_id, &this->data_fifo[this->fifo_pos], req_count); this->fifo_pos += req_count; this->to_xfer -= req_count; @@ -220,6 +243,9 @@ int ScsiBusController::send_data(uint8_t* dst_ptr, int count) { int actual_count = std::min(this->fifo_pos, count); + LOG_F(9, "%s: send_data %d bytes (requested %d), fifo_pos=%d, to_xfer=%d", + this->name.c_str(), actual_count, count, this->fifo_pos, this->to_xfer); + // move data out of the data FIFO std::memcpy(dst_ptr, this->data_fifo, actual_count); @@ -233,6 +259,9 @@ int ScsiBusController::send_data(uint8_t* dst_ptr, int count) { } int ScsiBusController::xfer_from(DmaChannel *ch_obj, uint8_t *buf, int len) { + LOG_F(9, "%s: xfer_from len=%d, to_xfer=%d, fifo_pos=%d", + this->name.c_str(), len, this->to_xfer, this->fifo_pos); + if (len > this->to_xfer + this->fifo_pos) LOG_F(WARNING, "%s: DMA xfer len > command xfer len", this->name.c_str()); diff --git a/devices/common/scsi/scsicdrom.cpp b/devices/common/scsi/scsicdrom.cpp index 1c4aace4b7..bc293049e0 100644 --- a/devices/common/scsi/scsicdrom.cpp +++ b/devices/common/scsi/scsicdrom.cpp @@ -32,6 +32,9 @@ static char my_revision_id[] = "1.9a"; ScsiCdrom::ScsiCdrom(std::string name, int my_id) : ScsiPhysDevice(name, my_id) { + LOG_F(9, "%s: ScsiCdrom ctor, scsi_id=%d, vendor=%s, product=%s, rev=%s", + name.c_str(), my_id, my_vendor_id, my_product_id, my_revision_id); + this->set_phys_dev(this); this->set_cdb_ptr(this->cmd_buf); this->set_buf_ptr(this->data_buf); @@ -54,6 +57,9 @@ ScsiCdrom::ScsiCdrom(std::string name, int my_id) : ScsiPhysDevice(name, my_id) void ScsiCdrom::process_command() { uint32_t lba; + LOG_F(9, "%s: process_command opcode=0x%02X, lun=%d", + this->name.c_str(), this->cmd_buf[0], (this->cmd_buf[1] >> 5) & 7); + if (this->verify_cdb() < 0) { this->switch_phase(ScsiPhase::STATUS); return; @@ -70,6 +76,8 @@ void ScsiCdrom::process_command() { switch (cmd[0]) { case ScsiCommand::MODE_SELECT_6: + LOG_F(9, "%s: dispatch MODE_SELECT_6, param_len=%d", + this->name.c_str(), cmd[4]); this->mode_select_6(cmd[4]); break; default: diff --git a/devices/common/scsi/scsicdromcmds.cpp b/devices/common/scsi/scsicdromcmds.cpp index 01c1645577..fa4d1d026c 100644 --- a/devices/common/scsi/scsicdromcmds.cpp +++ b/devices/common/scsi/scsicdromcmds.cpp @@ -26,6 +26,7 @@ along with this program. If not, see . #include ScsiCdromCmds::ScsiCdromCmds() { + LOG_F(9, "ScsiCdromCmds: enabling CD-ROM command set"); this->set_phys_block_dev(this); this->enable_cmd(ScsiCommand::READ_TOC); @@ -34,11 +35,14 @@ ScsiCdromCmds::ScsiCdromCmds() { void ScsiCdromCmds::process_command() { int next_phase; + LOG_F(9, "ScsiCdromCmds: process_command opcode=0x%02X", this->cdb_ptr[0]); + // use non-disk buffer by default phy_impl->set_buffer(this->buf_ptr); switch(this->cdb_ptr[0]) { case ScsiCommand::READ_TOC: + LOG_F(9, "ScsiCdromCmds: dispatch READ_TOC"); next_phase = this->read_toc_new(); break; default: diff --git a/devices/common/scsi/scsicommoncmds.cpp b/devices/common/scsi/scsicommoncmds.cpp index ce11ed4894..cb87fc4fda 100644 --- a/devices/common/scsi/scsicommoncmds.cpp +++ b/devices/common/scsi/scsicommoncmds.cpp @@ -24,6 +24,7 @@ along with this program. If not, see . #include ScsiCommonCmds::ScsiCommonCmds() { + LOG_F(9, "ScsiCommonCmds: enabling common SCSI commands"); this->enable_cmd(ScsiCommand::TEST_UNIT_READY); this->enable_cmd(ScsiCommand::REQ_SENSE); this->enable_cmd(ScsiCommand::INQUIRY); @@ -34,18 +35,25 @@ ScsiCommonCmds::ScsiCommonCmds() { void ScsiCommonCmds::process_command() { int next_phase; + LOG_F(9, "ScsiCommonCmds: process_command opcode=0x%02X", this->cdb_ptr[0]); + switch(this->cdb_ptr[0]) { case ScsiCommand::TEST_UNIT_READY: + LOG_F(9, "ScsiCommonCmds: dispatch TEST_UNIT_READY"); next_phase = this->test_unit_ready(); break; case ScsiCommand::REQ_SENSE: + LOG_F(9, "ScsiCommonCmds: dispatch REQ_SENSE"); next_phase = this->request_sense_new(); break; case ScsiCommand::INQUIRY: + LOG_F(9, "ScsiCommonCmds: dispatch INQUIRY"); next_phase = this->inquiry_new(); break; case ScsiCommand::MODE_SENSE_6: case ScsiCommand::MODE_SENSE_10: + LOG_F(9, "ScsiCommonCmds: dispatch %s", + this->cdb_ptr[0] == ScsiCommand::MODE_SENSE_6 ? "MODE_SENSE_6" : "MODE_SENSE_10"); next_phase = this->mode_sense(); break; default: @@ -70,6 +78,9 @@ int ScsiCommonCmds::verify_cdb() { int cdb_len = this->get_cdb_length(this->cdb_ptr[0]); + LOG_F(9, "ScsiCommonCmds: verify_cdb opcode=0x%02X, cdb_len=%d", + this->cdb_ptr[0], cdb_len); + if (cdb_len < 0) return 0; // don't know how to verify non-standard CDBs @@ -111,7 +122,10 @@ int ScsiCommonCmds::verify_cdb() { int ScsiCommonCmds::test_unit_ready() { // Assume that LUN is okay and the status has been set to GOOD - if (!phy_impl->is_device_ready()) { + bool ready = phy_impl->is_device_ready(); + LOG_F(9, "ScsiCommonCmds: test_unit_ready, ready=%d", ready); + + if (!ready) { this->sense_key = ScsiSense::NOT_READY; this->asc = phy_impl->not_ready_reason(); this->ascq = 0; @@ -339,6 +353,9 @@ int ScsiCommonCmds::get_one_page(uint8_t ctrl, uint8_t page, uint8_t subpage, { int len, err; + LOG_F(9, "ScsiCommonCmds: get_one_page page=0x%02X, subpage=0x%02X, ctrl=%d, avail=%d", + page, subpage, ctrl, avail_len); + try_again: len = this->getters[page](ctrl, subpage, &out_ptr[2], avail_len - 2); if (len < 0) { diff --git a/devices/common/scsi/scsihd.cpp b/devices/common/scsi/scsihd.cpp index 0af5428c26..f762b99c0d 100644 --- a/devices/common/scsi/scsihd.cpp +++ b/devices/common/scsi/scsihd.cpp @@ -35,6 +35,9 @@ static char my_revision_id[] = "di01"; ScsiHardDisk::ScsiHardDisk(std::string name, int my_id) : ScsiPhysDevice(name, my_id), BlockStorageDevice(256) { + LOG_F(9, "%s: ScsiHardDisk ctor, scsi_id=%d, vendor=%s, product=%s, rev=%s", + name.c_str(), my_id, my_vendor_id, my_product_id, my_revision_id); + this->set_phys_dev(this); this->set_phys_block_dev(this); this->set_cdb_ptr(this->cmd_buf); @@ -56,6 +59,8 @@ ScsiHardDisk::ScsiHardDisk(std::string name, int my_id) : ScsiPhysDevice(name, m } void ScsiHardDisk::insert_image(std::string filename) { + LOG_F(9, "%s: insert_image %s", this->name.c_str(), filename.c_str()); + if (this->set_host_file(filename) < 0) ABORT_F("%s: could not open image file %s", this->name.c_str(), filename.c_str()); @@ -67,6 +72,9 @@ void ScsiHardDisk::insert_image(std::string filename) { void ScsiHardDisk::process_command() { uint32_t lba; + LOG_F(9, "%s: process_command opcode=0x%02X, lun=%d", + this->name.c_str(), this->cmd_buf[0], (this->cmd_buf[1] >> 5) & 7); + if (this->verify_cdb() < 0) { this->switch_phase(ScsiPhase::STATUS); return; @@ -83,12 +91,16 @@ void ScsiHardDisk::process_command() { switch (cmd[0]) { case ScsiCommand::FORMAT_UNIT: + LOG_F(9, "%s: dispatch FORMAT_UNIT", this->name.c_str()); this->format(); break; case ScsiCommand::MODE_SELECT_6: + LOG_F(9, "%s: dispatch MODE_SELECT_6, param_len=%d", + this->name.c_str(), cmd[4]); mode_select_6(cmd[4]); break; case ScsiCommand::READ_BUFFER: + LOG_F(9, "%s: dispatch READ_BUFFER", this->name.c_str()); read_buffer(); break; default: @@ -97,6 +109,8 @@ void ScsiHardDisk::process_command() { } void ScsiHardDisk::mode_select_6(uint8_t param_len) { + LOG_F(9, "%s: mode_select_6 param_len=%d", this->name.c_str(), param_len); + if (!param_len) { this->switch_phase(ScsiPhase::STATUS); return; @@ -107,6 +121,8 @@ void ScsiHardDisk::mode_select_6(uint8_t param_len) { std::memset(&this->data_buf[0], 0xDD, this->block_size); this->post_xfer_action = [this]() { + LOG_F(9, "%s: mode_select_6 post_xfer_action invoked", + this->name.c_str()); // TODO: parse the received mode parameter list here }; @@ -116,6 +132,9 @@ void ScsiHardDisk::mode_select_6(uint8_t param_len) { int ScsiHardDisk::get_dev_format_page(uint8_t ctrl, uint8_t subpage, uint8_t *out_ptr, int avail_len) { + LOG_F(9, "%s: get_dev_format_page ctrl=%d, subpage=0x%02X, avail_len=%d", + this->name.c_str(), ctrl, subpage, avail_len); + if (subpage && subpage != 0xFFU) return FORMAT_ERR_BAD_SUBPAGE; @@ -146,6 +165,9 @@ int ScsiHardDisk::get_dev_format_page(uint8_t ctrl, uint8_t subpage, uint8_t *ou int ScsiHardDisk::get_rigid_geometry_page(uint8_t ctrl, uint8_t subpage, uint8_t *out_ptr, int avail_len) { + LOG_F(9, "%s: get_rigid_geometry_page ctrl=%d, subpage=0x%02X, avail_len=%d", + this->name.c_str(), ctrl, subpage, avail_len); + if (subpage && subpage != 0xFFU) return FORMAT_ERR_BAD_SUBPAGE; @@ -187,6 +209,9 @@ void ScsiHardDisk::read_buffer() { uint32_t alloc_len = (this->cmd_buf[6] << 24) | (this->cmd_buf[7] << 16) | this->cmd_buf[8]; + LOG_F(9, "%s: read_buffer mode=%d, alloc_len=%u", + this->name.c_str(), mode, alloc_len); + switch(mode) { case 0: // Combined header and data mode WRITE_DWORD_BE_A(&this->data_buf[0], 0x10000); // report buffer size of 64K diff --git a/devices/common/scsi/scsiphysdevice.cpp b/devices/common/scsi/scsiphysdevice.cpp index 18ae17fea6..a2b532ac84 100644 --- a/devices/common/scsi/scsiphysdevice.cpp +++ b/devices/common/scsi/scsiphysdevice.cpp @@ -63,6 +63,8 @@ void ScsiPhysDevice::notify(ScsiNotification notif_type, int param) void ScsiPhysDevice::switch_phase(const int new_phase) { + LOG_F(9, "%s: switch_phase %d -> %d", this->name.c_str(), + this->cur_phase, new_phase); this->cur_phase = new_phase; this->bus_obj->switch_phase(this->scsi_id, this->cur_phase); this->prepare_xfer(); @@ -73,14 +75,17 @@ bool ScsiPhysDevice::allow_phase_change() { (SCSI_CTRL_ATN | SCSI_CTRL_ACK)) ABORT_F("%s: reject message requested", this->name.c_str()); - if (this->data_size || this->bus_obj->test_ctrl_lines(SCSI_CTRL_ACK)) - return false; - else - return true; + bool allow = !(this->data_size || this->bus_obj->test_ctrl_lines(SCSI_CTRL_ACK)); + LOG_F(9, "%s: allow_phase_change=%d (data_size=%d, ack=%d)", + this->name.c_str(), allow, this->data_size, + !!this->bus_obj->test_ctrl_lines(SCSI_CTRL_ACK)); + return allow; } void ScsiPhysDevice::next_step() { + LOG_F(9, "%s: next_step, cur_phase=%d", this->name.c_str(), this->cur_phase); + // special case: data transfers during MESSAGE_IN phase // require handshaking. Rejecting needs to be detected too. if (bus_obj->current_phase() == ScsiPhase::MESSAGE_IN && @@ -140,6 +145,9 @@ void ScsiPhysDevice::next_step() void ScsiPhysDevice::prepare_xfer() { this->cur_phase = this->bus_obj->current_phase(); + LOG_F(9, "%s: prepare_xfer for phase=%d, xfer_len=%d", + this->name.c_str(), this->cur_phase, this->xfer_len); + switch (this->cur_phase) { case ScsiPhase::COMMAND: // handled in xfer_data() this->data_ptr = this->cmd_buf; @@ -211,6 +219,9 @@ int ScsiPhysDevice::send_data(uint8_t* dst_ptr, const int count) if (dst_ptr == nullptr || !count) return 0; + LOG_F(9, "%s: send_data count=%d, data_size=%d", + this->name.c_str(), count, this->data_size); + int remainder = count; while (remainder) { @@ -227,6 +238,8 @@ int ScsiPhysDevice::send_data(uint8_t* dst_ptr, const int count) if (!this->data_size) { if (!this->read_more_data(&this->data_size, &this->data_ptr)) break; + LOG_F(9, "%s: send_data read_more refilled data_size=%d", + this->name.c_str(), this->data_size); } } @@ -238,6 +251,9 @@ int ScsiPhysDevice::rcv_data(const uint8_t* src_ptr, const int count) if (src_ptr == nullptr || !count) return 0; + LOG_F(9, "%s: rcv_data count=%d, phase=%d", + this->name.c_str(), count, this->cur_phase); + // DATA_OUT can transfer big data in several chunks while crossing buffer boundaries if (this->cur_phase == ScsiPhase::DATA_OUT) { int remainder = count; @@ -256,6 +272,8 @@ int ScsiPhysDevice::rcv_data(const uint8_t* src_ptr, const int count) if (this->data_size >= this->incoming_size) { if (!this->write_more_data(&this->incoming_size, &this->data_ptr)) break; + LOG_F(9, "%s: rcv_data write_more incoming_size=%d", + this->name.c_str(), this->incoming_size); this->data_size = 0; } } diff --git a/main.cpp b/main.cpp index 8288630aa5..cbc4f894a8 100644 --- a/main.cpp +++ b/main.cpp @@ -138,7 +138,7 @@ int main(int argc, char** argv) { bool log_no_uptime = false; app.add_flag("--log-to-stderr", log_to_stderr, "Send internal logging to stderr (instead of dingusppc.log)"); - app.add_flag("--log-verbosity", log_verbosity, + app.add_option("--log-verbosity", log_verbosity, "Adjust logging verbosity (default is 0 a.k.a. INFO)") ->check(CLI::Number); app.add_flag("--log-no-uptime", log_no_uptime,