Skip to content

More logging #181

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
claunia wants to merge 2 commits into from
Closed

More logging #181

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
0901014
Add loggers to all SCSI subsystem
claunia Jun 1, 2026
38bdfe6
main.cpp: change log verbosity flag from add_flag to add_option for b…
claunia Jun 1, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
29 changes: 29 additions & 0 deletions devices/common/scsi/mesh.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,8 @@ along with this program. If not, see <https://www.gnu.org/licenses/>.
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<ScsiBus*>(gMachineObj->get_comp_by_name("ScsiMesh"));
if (bus_obj) {
bus_obj->register_device(7, static_cast<ScsiPhysDevice*>(this));
Expand All @@ -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;
Expand Down Expand Up @@ -149,66 +154,79 @@ 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;
if (this->fifo_pos)
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;
this->cur_state = Scsi_Bus_Controller::SeqState::RCV_STATUS;
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;
this->cur_state = Scsi_Bus_Controller::SeqState::XFER_BEGIN;
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;
this->cur_state = Scsi_Bus_Controller::SeqState::XFER_BEGIN;
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;
this->cur_state = Scsi_Bus_Controller::SeqState::SEND_MSG;
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;
this->cur_state = Scsi_Bus_Controller::SeqState::RCV_MESSAGE;
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))
Expand All @@ -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:
Expand All @@ -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:
Expand All @@ -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) {
Expand Down Expand Up @@ -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;
Expand Down
50 changes: 50 additions & 0 deletions devices/common/scsi/sc53c94.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,7 @@ along with this program. If not, see <https://www.gnu.org/licenses/>.

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);
Expand All @@ -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<ScsiBus*>(gMachineObj->get_comp_by_name("ScsiCurio"));
if (bus) {
bus->register_device(7, static_cast<ScsiPhysDevice*>(this));
Expand All @@ -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;

Expand Down Expand Up @@ -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);

Expand Down Expand Up @@ -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;
Expand All @@ -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;
Expand All @@ -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;
Expand All @@ -348,13 +366,15 @@ 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());
}
this->cur_state = SeqState::RCV_STATUS;
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.
Expand All @@ -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());
Expand All @@ -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;
Expand Down Expand Up @@ -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:
Expand All @@ -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?
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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);

Expand Down Expand Up @@ -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;
Expand All @@ -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;
Expand Down Expand Up @@ -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);

Expand Down Expand Up @@ -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();
}
Expand All @@ -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;
Expand Down
Loading
Loading