Added rascsi filter to limit logging to a particular device (#978)

* Support for ID and LUN parameter for the -L option in rascsi

* Added DeviceLogger class

* Removed dupiicate code

* Fixed SonarQube issues

* Added unit tests, improved code sharing

* Fixed regression (#979)
This commit is contained in:
Uwe Seimet 2022-11-11 21:08:48 +01:00 committed by GitHub
parent 4fa513090a
commit 454c61ac0d
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
47 changed files with 673 additions and 409 deletions

View File

@ -7,7 +7,6 @@
//
//---------------------------------------------------------------------------
#include "shared/log.h"
#include "shared/rascsi_exceptions.h"
#include "devices/primary_device.h"
#include "abstract_controller.h"
@ -104,7 +103,6 @@ void AbstractController::ProcessPhase()
break;
default:
LOGERROR("Cannot process phase %s", BUS::GetPhaseStrRaw(GetPhase()))
throw scsi_exception(sense_key::ABORTED_COMMAND);
break;
}
@ -136,7 +134,7 @@ bool AbstractController::HasDeviceForLun(int lun) const
int AbstractController::ExtractInitiatorId(int id_data) const
{
int initiator_id = -1;
int initiator_id = UNKNOWN_INITIATOR_ID;
if (int tmp = id_data - (1 << target_id); tmp) {
initiator_id = 0;

View File

@ -28,6 +28,8 @@ class AbstractController : public PhaseHandler, public enable_shared_from_this<A
{
public:
static inline const int UNKNOWN_INITIATOR_ID = -1;
enum class rascsi_shutdown_mode {
NONE,
STOP_RASCSI,

View File

@ -5,14 +5,14 @@
//
// Copyright (C) 2001-2006 (ytanaka@ipc-tokai.or.jp)
// Copyright (C) 2014-2020 GIMONS
// Copyright (C) akuker
// Copyright (C) akuker
// Copyright (C) 2022 Uwe Seimet
//
// Licensed under the BSD 3-Clause License.
// See LICENSE file in the project root folder.
//
//---------------------------------------------------------------------------
#include "shared/log.h"
#include "shared/rascsi_exceptions.h"
#include "hal/gpiobus.h"
#include "hal/systimer.h"
@ -31,6 +31,8 @@ using namespace scsi_defs;
ScsiController::ScsiController(shared_ptr<ControllerManager> controller_manager, int target_id)
: AbstractController(controller_manager, target_id, LUN_MAX)
{
logger.SetIdAndLun(target_id, -1);
// The initial buffer size will default to either the default buffer size OR
// the size of an Ethernet message, whichever is larger.
AllocateBuffer(std::max(DEFAULT_BUFFER_SIZE, ETH_FRAME_LEN + 16 + ETH_FCS_LEN));
@ -55,7 +57,7 @@ BUS::phase_t ScsiController::Process(int id)
GetBus().Acquire();
if (GetBus().GetRST()) {
LOGWARN("RESET signal received!")
logger.Warn("RESET signal received!");
Reset();
@ -64,13 +66,6 @@ BUS::phase_t ScsiController::Process(int id)
return GetPhase();
}
if (id != UNKNOWN_INITIATOR_ID) {
LOGTRACE("%s Initiator ID is %d", __PRETTY_FUNCTION__, id)
}
else {
LOGTRACE("%s Initiator ID is unknown", __PRETTY_FUNCTION__)
}
initiator_id = id;
try {
@ -78,7 +73,7 @@ BUS::phase_t ScsiController::Process(int id)
}
catch(const scsi_exception&) {
// Any exception should have been handled during the phase processing
LOGERROR("%s Unhandled SCSI error, resetting controller and bus and entering bus free phase", __PRETTY_FUNCTION__)
logger.Error("Unhandled SCSI error, resetting controller and bus and entering bus free phase");
Reset();
GetBus().Reset();
@ -92,7 +87,7 @@ BUS::phase_t ScsiController::Process(int id)
void ScsiController::BusFree()
{
if (!IsBusFree()) {
LOGTRACE("%s Bus free phase", __PRETTY_FUNCTION__)
logger.Trace("Bus free phase");
SetPhase(BUS::phase_t::busfree);
@ -124,21 +119,21 @@ void ScsiController::BusFree()
// This code has to be executed in the bus free phase and thus has to be located in the controller.
switch(shutdown_mode) {
case rascsi_shutdown_mode::STOP_RASCSI:
LOGINFO("RaSCSI shutdown requested")
logger.Info("RaSCSI shutdown requested");
exit(EXIT_SUCCESS);
break;
case rascsi_shutdown_mode::STOP_PI:
LOGINFO("Raspberry Pi shutdown requested")
logger.Info("Raspberry Pi shutdown requested");
if (system("init 0") == -1) {
LOGERROR("Raspberry Pi shutdown failed: %s", strerror(errno))
logger.Error("Raspberry Pi shutdown failed: " + string(strerror(errno)));
}
break;
case rascsi_shutdown_mode::RESTART_PI:
LOGINFO("Raspberry Pi restart requested")
logger.Info("Raspberry Pi restart requested");
if (system("init 6") == -1) {
LOGERROR("Raspberry Pi restart failed: %s", strerror(errno))
logger.Error("Raspberry Pi restart failed: " + string(strerror(errno)));
}
break;
@ -168,7 +163,7 @@ void ScsiController::Selection()
return;
}
LOGTRACE("%s Selection Phase Target ID=%d", __PRETTY_FUNCTION__, GetTargetId())
logger.Trace("Selection phase");
SetPhase(BUS::phase_t::selection);
@ -191,7 +186,7 @@ void ScsiController::Selection()
void ScsiController::Command()
{
if (!IsCommand()) {
LOGTRACE("%s Command Phase", __PRETTY_FUNCTION__)
logger.Trace("Command phase");
SetPhase(BUS::phase_t::command);
@ -201,7 +196,9 @@ void ScsiController::Command()
const int actual_count = GetBus().CommandHandShake(GetBuffer());
if (actual_count == 0) {
LOGTRACE("ID %d LUN %d received unknown command: $%02X", GetTargetId(), GetEffectiveLun(), GetBuffer()[0])
stringstream s;
s << "Received unknown command: $" << setfill('0') << setw(2) << hex << GetBuffer()[0];
logger.Trace(s.str());
Error(sense_key::ILLEGAL_REQUEST, asc::INVALID_COMMAND_OPERATION_CODE);
return;
@ -211,21 +208,19 @@ void ScsiController::Command()
// If not able to receive all, move to the status phase
if (actual_count != command_byte_count) {
LOGERROR("Command byte count mismatch for command $%02X: expected %d bytes, received %d byte(s)",
GetBuffer()[0], command_byte_count, actual_count)
stringstream s;
s << "Command byte count mismatch for command $" << setfill('0') << setw(2) << hex << GetBuffer()[0];
logger.Error(s.str() + ": expected " + to_string(command_byte_count) + " bytes, received"
+ to_string(actual_count) + " byte(s)");
Error(sense_key::ABORTED_COMMAND);
return;
}
AllocateCmd(command_byte_count);
// Command data transfer
stringstream s;
AllocateCmd(command_byte_count);
for (int i = 0; i < command_byte_count; i++) {
GetCmd()[i] = GetBuffer()[i];
s << setfill('0') << setw(2) << hex << GetCmd(i);
}
LOGTRACE("%s CDB=$%s",__PRETTY_FUNCTION__, s.str().c_str())
SetLength(0);
@ -235,7 +230,13 @@ void ScsiController::Command()
void ScsiController::Execute()
{
LOGDEBUG("++++ CMD ++++ Executing command $%02X", static_cast<int>(GetOpcode()))
stringstream s;
s << "Controller is executing " << command_mapping.find(GetOpcode())->second.second << ", CDB $"
<< setfill('0') << hex;
for (int i = 0; i < BUS::GetCommandByteCount(static_cast<uint8_t>(GetOpcode())); i++) {
s << setw(2) << GetCmd(i);
}
logger.Debug(s.str());
// Initialization for data transfer
ResetOffset();
@ -250,7 +251,7 @@ void ScsiController::Execute()
int lun = GetEffectiveLun();
if (!HasDeviceForLun(lun)) {
if (GetOpcode() != scsi_command::eCmdInquiry && GetOpcode() != scsi_command::eCmdRequestSense) {
LOGTRACE("Invalid LUN %d for device ID %d", lun, GetTargetId())
logger.Trace("Invalid LUN " + to_string(lun));
Error(sense_key::ILLEGAL_REQUEST, asc::INVALID_LUN);
@ -264,7 +265,7 @@ void ScsiController::Execute()
// SCSI-2 4.4.3 Incorrect logical unit handling
if (GetOpcode() == scsi_command::eCmdInquiry && !HasDeviceForLun(lun)) {
LOGTRACE("Reporting LUN %d for device ID %d as not supported", GetEffectiveLun(), GetTargetId())
logger.Trace("Reporting LUN" + to_string(GetEffectiveLun()) + " as not supported");
GetBuffer().data()[0] = 0x7f;
@ -295,13 +296,16 @@ void ScsiController::Status()
{
if (!IsStatus()) {
// Minimum execution time
// TODO Why is a delay needed? Is this covered by the SCSI specification?
if (execstart > 0) {
Sleep();
} else {
SysTimer::SleepUsec(5);
}
LOGTRACE("%s Status Phase, status is $%02X",__PRETTY_FUNCTION__, static_cast<int>(GetStatus()))
stringstream s;
s << "Status Phase, status is $" << setfill('0') << setw(2) << hex << static_cast<int>(GetStatus());
logger.Trace(s.str());
SetPhase(BUS::phase_t::status);
@ -325,7 +329,7 @@ void ScsiController::Status()
void ScsiController::MsgIn()
{
if (!IsMsgIn()) {
LOGTRACE("%s Message In phase", __PRETTY_FUNCTION__)
logger.Trace("Message In phase");
SetPhase(BUS::phase_t::msgin);
@ -342,10 +346,8 @@ void ScsiController::MsgIn()
void ScsiController::MsgOut()
{
LOGTRACE("%s ID %d",__PRETTY_FUNCTION__, GetTargetId())
if (!IsMsgOut()) {
LOGTRACE("Message Out Phase")
logger.Trace("Message Out phase");
// process the IDENTIFY message
if (IsSelection()) {
@ -385,7 +387,7 @@ void ScsiController::DataIn()
return;
}
LOGTRACE("%s Going into Data-in Phase", __PRETTY_FUNCTION__)
logger.Trace("Entering Data In phase");
SetPhase(BUS::phase_t::datain);
@ -415,7 +417,7 @@ void ScsiController::DataOut()
return;
}
LOGTRACE("%s Data out phase", __PRETTY_FUNCTION__)
logger.Trace("Data Out phase");
SetPhase(BUS::phase_t::dataout);
@ -453,7 +455,7 @@ void ScsiController::Error(sense_key sense_key, asc asc, status status)
int lun = GetEffectiveLun();
if (!HasDeviceForLun(lun) || asc == asc::INVALID_LUN) {
if (!HasDeviceForLun(0)) {
LOGERROR("No LUN 0 for device %d", GetTargetId())
logger.Error("No LUN 0");
SetStatus(status);
SetMessage(0x00);
@ -467,7 +469,10 @@ void ScsiController::Error(sense_key sense_key, asc asc, status status)
}
if (sense_key != sense_key::NO_SENSE || asc != asc::NO_ADDITIONAL_SENSE_INFORMATION) {
LOGDEBUG("Error status: Sense Key $%02X, ASC $%02X", static_cast<int>(sense_key), static_cast<int>(asc))
stringstream s;
s << setfill('0') << setw(2) << hex << "Error status: Sense Key $" << static_cast<int>(sense_key)
<< ", ASC $" << static_cast<int>(asc);
logger.Debug(s.str());
// Set Sense Key and ASC for a subsequent REQUEST SENSE
GetDeviceForLun(lun)->SetStatusCode((static_cast<int>(sense_key) << 16) | (static_cast<int>(asc) << 8));
@ -476,7 +481,7 @@ void ScsiController::Error(sense_key sense_key, asc asc, status status)
SetStatus(status);
SetMessage(0x00);
LOGTRACE("%s Error (to status phase)", __PRETTY_FUNCTION__)
logger.Trace("Error (to status phase)");
Status();
}
@ -487,8 +492,7 @@ void ScsiController::Send()
assert(GetBus().GetIO());
if (HasValidLength()) {
LOGTRACE("%s%s", __PRETTY_FUNCTION__, (" Sending handhake with offset " + to_string(GetOffset()) + ", length "
+ to_string(GetLength())).c_str())
logger.Trace("Sending data, offset: " + to_string(GetOffset()) + ", length: " + to_string(GetLength()));
// The delay should be taken from the respective LUN, but as there are no Daynaport drivers for
// LUNs other than 0 this work-around works.
@ -505,7 +509,6 @@ void ScsiController::Send()
return;
}
// Block subtraction, result initialization
DecrementBlocks();
bool result = true;
@ -513,7 +516,7 @@ void ScsiController::Send()
if (IsDataIn() && GetBlocks() != 0) {
// set next buffer (set offset, length)
result = XferIn(GetBuffer());
LOGTRACE("%s%s", __PRETTY_FUNCTION__, (" Processing after data collection. Blocks: " + to_string(GetBlocks())).c_str())
logger.Trace("Processing after data collection. Blocks: " + to_string(GetBlocks()));
}
// If result FALSE, move to status phase
@ -524,14 +527,14 @@ void ScsiController::Send()
// Continue sending if block !=0
if (GetBlocks() != 0){
LOGTRACE("%s%s", __PRETTY_FUNCTION__, (" Continuing to send. Blocks: " + to_string(GetBlocks())).c_str())
logger.Trace("Continuing to send. Blocks: " + to_string(GetBlocks()));
assert(HasValidLength());
assert(GetOffset() == 0);
return;
}
// Move to next phase
LOGTRACE("%s Move to next phase: %s", __PRETTY_FUNCTION__, BUS::GetPhaseStrRaw(GetPhase()))
logger.Trace("Moving to next phase: " + string(BUS::GetPhaseStrRaw(GetPhase())));
switch (GetPhase()) {
// Message in phase
case BUS::phase_t::msgin:
@ -571,40 +574,36 @@ void ScsiController::Send()
void ScsiController::Receive()
{
assert(!GetBus().GetREQ());
assert(!GetBus().GetIO());
if (HasValidLength()) {
logger.Trace("Receiving data, transfer length: " + to_string(GetLength()) + " byte(s)");
// If not able to receive all, move to status phase
if (uint32_t len = GetBus().ReceiveHandShake(GetBuffer().data() + GetOffset(), GetLength()); len != GetLength()) {
logger.Error("Not able to receive " + to_string(GetLength()) + " byte(s) of data, only received "
+ to_string(len));
Error(sense_key::ABORTED_COMMAND);
return;
}
}
if (IsByteTransfer()) {
ReceiveBytes();
return;
}
LOGTRACE("%s",__PRETTY_FUNCTION__)
// REQ is low
assert(!GetBus().GetREQ());
assert(!GetBus().GetIO());
// Length != 0 if received
if (HasValidLength()) {
LOGTRACE("%s Length is %d byte(s)", __PRETTY_FUNCTION__, GetLength())
// If not able to receive all, move to status phase
if (int len = GetBus().ReceiveHandShake(GetBuffer().data() + GetOffset(), GetLength());
len != static_cast<int>(GetLength())) {
LOGERROR("%s Not able to receive %d byte(s) of data, only received %d",__PRETTY_FUNCTION__, GetLength(), len)
Error(sense_key::ABORTED_COMMAND);
return;
}
UpdateOffsetAndLength();
return;
}
// Block subtraction, result initialization
DecrementBlocks();
bool result = true;
// Processing after receiving data (by phase)
LOGTRACE("%s Phase: %s",__PRETTY_FUNCTION__, BUS::GetPhaseStrRaw(GetPhase()))
logger.Trace("Phase: " + string(BUS::GetPhaseStrRaw(GetPhase())));
switch (GetPhase()) {
case BUS::phase_t::dataout:
if (GetBlocks() == 0) {
@ -684,32 +683,16 @@ bool ScsiController::XferMsg(int msg)
void ScsiController::ReceiveBytes()
{
assert(!GetBus().GetREQ());
assert(!GetBus().GetIO());
if (HasValidLength()) {
LOGTRACE("%s Length is %d bytes", __PRETTY_FUNCTION__, GetLength())
// If not able to receive all, move to status phase
if (uint32_t len = GetBus().ReceiveHandShake(GetBuffer().data() + GetOffset(), GetLength()); len != GetLength()) {
LOGERROR("%s Not able to receive %d byte(s) of data, only received %d",
__PRETTY_FUNCTION__, GetLength(), len)
Error(sense_key::ABORTED_COMMAND);
return;
}
SetBytesToTransfer(GetLength());
UpdateOffsetAndLength();
return;
}
// Result initialization
bool result = true;
// Processing after receiving data (by phase)
LOGTRACE("%s Phase: %s",__PRETTY_FUNCTION__, BUS::GetPhaseStrRaw(GetPhase()))
logger.Trace("Phase: " + string(BUS::GetPhaseStrRaw(GetPhase())));
switch (GetPhase()) {
case BUS::phase_t::dataout:
result = XferOut(false);
@ -804,7 +787,10 @@ void ScsiController::DataOutNonBlockOriented()
break;
default:
LOGWARN("Unexpected Data Out phase for command $%02X", static_cast<int>(GetOpcode()))
stringstream s;
s << "Unexpected Data Out phase for command $" << setfill('0') << setw(2) << hex
<< static_cast<int>(GetOpcode());
logger.Warn(s.str());
break;
}
}
@ -819,7 +805,9 @@ bool ScsiController::XferIn(vector<uint8_t>& buf)
{
assert(IsDataIn());
LOGTRACE("%s command=%02X", __PRETTY_FUNCTION__, static_cast<int>(GetOpcode()))
stringstream s;
s << "Command: $" << setfill('0') << setw(2) << hex << static_cast<int>(GetOpcode());
logger.Trace(s.str());
int lun = GetEffectiveLun();
if (!HasDeviceForLun(lun)) {
@ -930,11 +918,14 @@ bool ScsiController::XferOutBlockOriented(bool cont)
}
case scsi_command::eCmdSetMcastAddr:
LOGTRACE("%s Done with DaynaPort Set Multicast Address", __PRETTY_FUNCTION__)
logger.Trace("Done with DaynaPort Set Multicast Address");
break;
default:
LOGWARN("Received an unexpected command ($%02X) in %s", static_cast<int>(GetOpcode()), __PRETTY_FUNCTION__)
stringstream s;
s << "Received an unexpected command ($" << setfill('0') << setw(2) << hex
<< static_cast<int>(GetOpcode()) << ")";
logger.Warn(s.str());
break;
}
@ -946,12 +937,12 @@ void ScsiController::ProcessCommand()
uint32_t len = GPIOBUS::GetCommandByteCount(GetBuffer()[0]);
stringstream s;
s << setfill('0') << setw(2) << hex;
s << "CDB=$" << setfill('0') << setw(2) << hex;
for (uint32_t i = 0; i < len; i++) {
GetCmd()[i] = GetBuffer()[i];
s << GetCmd(i);
}
LOGTRACE("%s CDB=$%s",__PRETTY_FUNCTION__, s.str().c_str())
logger.Trace(s.str());
Execute();
}
@ -963,13 +954,13 @@ void ScsiController::ParseMessage()
const uint8_t message_type = scsi.msb[i];
if (message_type == 0x06) {
LOGTRACE("Received ABORT message")
logger.Trace("Received ABORT message");
BusFree();
return;
}
if (message_type == 0x0C) {
LOGTRACE("Received BUS DEVICE RESET message")
logger.Trace("Received BUS DEVICE RESET message");
scsi.syncoffset = 0;
if (auto device = GetDeviceForLun(identified_lun); device != nullptr) {
device->DiscardReservation();
@ -980,11 +971,11 @@ void ScsiController::ParseMessage()
if (message_type >= 0x80) {
identified_lun = static_cast<int>(message_type) & 0x1F;
LOGTRACE("Received IDENTIFY message for LUN %d", identified_lun)
logger.Trace("Received IDENTIFY message for LUN " + to_string(identified_lun));
}
if (message_type == 0x01) {
LOGTRACE("Received EXTENDED MESSAGE")
logger.Trace("Received EXTENDED MESSAGE");
// Check only when synchronous transfer is possible
if (!scsi.syncenable || scsi.msb[i + 2] != 0x01) {

View File

@ -16,6 +16,7 @@
#include "shared/scsi.h"
#include "controller_manager.h"
#include "devices/device_logger.h"
#include "abstract_controller.h"
#include <array>
@ -34,8 +35,6 @@ class ScsiController : public AbstractController
// REQ/ACK offset(limited to 16)
static const uint8_t MAX_SYNC_OFFSET = 16;
static const int UNKNOWN_INITIATOR_ID = -1;
const int DEFAULT_BUFFER_SIZE = 0x1000;
using scsi_t = struct _scsi_t {
@ -88,6 +87,8 @@ public:
private:
DeviceLogger logger;
// Execution start time
uint32_t execstart = 0;

View File

@ -7,7 +7,6 @@
//
//---------------------------------------------------------------------------
#include "shared/log.h"
#include "shared/rascsi_version.h"
#include "device.h"
#include <cassert>

View File

@ -9,6 +9,7 @@
#pragma once
#include "shared/log.h"
#include "generated/rascsi_interface.pb.h"
#include <unordered_map>
#include <string>
@ -72,6 +73,8 @@ class Device //NOSONAR The number of fields and methods is justified, the comple
protected:
Device(PbDeviceType, int);
void SetReady(bool b) { ready = b; }
bool IsReset() const { return reset; }
void SetReset(bool b) { reset = b; }
@ -89,8 +92,6 @@ protected:
string GetParam(const string&) const;
void SetParams(const unordered_map<string, string>&);
Device(PbDeviceType, int);
public:
virtual ~Device() = default;

View File

@ -0,0 +1,75 @@
//---------------------------------------------------------------------------
//
// SCSI Target Emulator RaSCSI Reloaded
// for Raspberry Pi
//
// Copyright (C) 2022 Uwe Seimet
//
//---------------------------------------------------------------------------
#include "shared/log.h"
#include "device_logger.h"
using namespace std;
void DeviceLogger::Trace(const string& message) const
{
if (const string m = GetLogMessage(message); !m.empty()) {
LOGTRACE("%s", m.c_str())
}
}
void DeviceLogger::Debug(const string& message) const
{
if (const string m = GetLogMessage(message); !m.empty()) {
LOGDEBUG("%s", m.c_str())
}
}
void DeviceLogger::Info(const string& message) const
{
if (const string m = GetLogMessage(message); !m.empty()) {
LOGINFO("%s", m.c_str())
}
}
void DeviceLogger::Warn(const string& message) const
{
if (const string m = GetLogMessage(message); !m.empty()) {
LOGWARN("%s", m.c_str())
}
}
void DeviceLogger::Error(const string& message) const
{
if (const string m = GetLogMessage(message); !m.empty()) {
LOGERROR("%s", m.c_str())
}
}
string DeviceLogger::GetLogMessage(const string& message) const
{
if (log_device_id == -1 || (log_device_id == id && (log_device_lun == -1 || log_device_lun == lun)))
{
if (lun == -1) {
return "(ID " + to_string(id) + ") - " + message;
}
else {
return "(ID:LUN " + to_string(id) + ":" + to_string(lun) + ") - " + message;
}
}
return "";
}
void DeviceLogger::SetIdAndLun(int i, int l)
{
id = i;
lun = l;
}
void DeviceLogger::SetLogIdAndLun(int i, int l)
{
log_device_id = i;
log_device_lun = l;
}

View File

@ -0,0 +1,44 @@
//---------------------------------------------------------------------------
//
// SCSI Target Emulator RaSCSI Reloaded
// for Raspberry Pi
//
// Copyright (C) 2022 Uwe Seimet
//
//---------------------------------------------------------------------------
#pragma once
#include <string>
using namespace std;
class DeviceLogger
{
public:
DeviceLogger() = default;
~DeviceLogger() = default;
void Trace(const string&) const;
void Debug(const string&) const;
void Info(const string&) const;
void Warn(const string&) const;
void Error(const string&) const;
string GetLogMessage(const string&) const;
void SetIdAndLun(int, int);
static void SetLogIdAndLun(int, int);
private:
int id = -1;
int lun = -1;
// TODO Try to only have one shared instance, so that these fields do not have to be static
static inline int log_device_id = -1;
static inline int log_device_lun = -1;
};

View File

@ -14,10 +14,11 @@
//
//---------------------------------------------------------------------------
#include "shared/log.h"
#include "shared/rascsi_exceptions.h"
#include "scsi_command_util.h"
#include "disk.h"
#include <sstream>
#include <iomanip>
using namespace scsi_defs;
using namespace scsi_command_util;
@ -116,7 +117,7 @@ void Disk::Read(access_mode mode)
GetController()->SetBlocks(blocks);
GetController()->SetLength(Read(GetController()->GetCmd(), GetController()->GetBuffer(), start));
LOGTRACE("%s ctrl.length is %d", __PRETTY_FUNCTION__, GetController()->GetLength())
GetLogger().Trace("Length is " + to_string(GetController()->GetLength()));
// Set next block
GetController()->SetNext(start + 1);
@ -203,10 +204,10 @@ void Disk::StartStopUnit()
const bool load = GetController()->GetCmd(4) & 0x02;
if (load) {
LOGTRACE(start ? "Loading medium" : "Ejecting medium")
GetLogger().Trace(start ? "Loading medium" : "Ejecting medium");
}
else {
LOGTRACE(start ? "Starting unit" : "Stopping unit")
GetLogger().Trace(start ? "Starting unit" : "Stopping unit");
SetStopped(!start);
}
@ -238,7 +239,7 @@ void Disk::PreventAllowMediumRemoval()
const bool lock = GetController()->GetCmd(4) & 0x01;
LOGTRACE(lock ? "Locking medium" : "Unlocking medium")
GetLogger().Trace(lock ? "Locking medium" : "Unlocking medium");
SetLocked(lock);
@ -618,8 +619,8 @@ void Disk::ValidateBlockAddress(access_mode mode) const
const uint64_t block = mode == RW16 ? GetInt64(GetController()->GetCmd(), 2) : GetInt32(GetController()->GetCmd(), 2);
if (block > GetBlockCount()) {
LOGTRACE("%s", ("Capacity of " + to_string(GetBlockCount()) + " block(s) exceeded: Trying to access block "
+ to_string(block)).c_str())
GetLogger().Trace("Capacity of " + to_string(GetBlockCount()) + " block(s) exceeded: Trying to access block "
+ to_string(block));
throw scsi_exception(sense_key::ILLEGAL_REQUEST, asc::LBA_OUT_OF_RANGE);
}
}
@ -651,13 +652,14 @@ tuple<bool, uint64_t, uint32_t> Disk::CheckAndGetStartAndCount(access_mode mode)
}
}
LOGTRACE("%s READ/WRITE/VERIFY/SEEK command record=$%08X blocks=%d", __PRETTY_FUNCTION__,
static_cast<uint32_t>(start), count)
stringstream s;
s << "READ/WRITE/VERIFY/SEEK, start block: $" << setfill('0') << setw(8) << hex << start;
GetLogger().Trace(s.str() + ", blocks: " + to_string(count));
// Check capacity
if (uint64_t capacity = GetBlockCount(); !capacity || start > capacity || start + count > capacity) {
LOGTRACE("%s", ("Capacity of " + to_string(capacity) + " block(s) exceeded: Trying to access block "
+ to_string(start) + ", block count " + to_string(count)).c_str())
GetLogger().Trace("Capacity of " + to_string(capacity) + " block(s) exceeded: Trying to access block "
+ to_string(start) + ", block count " + to_string(count));
throw scsi_exception(sense_key::ILLEGAL_REQUEST, asc::LBA_OUT_OF_RANGE);
}

View File

@ -75,7 +75,7 @@ bool DiskTrack::Load(const string& path)
if (dt.buffer == nullptr) {
if (posix_memalign((void **)&dt.buffer, 512, ((length + 511) / 512) * 512)) {
LOGWARN("%s posix_memalign failed", __PRETTY_FUNCTION__)
LOGWARN("posix_memalign failed")
}
dt.length = length;
}
@ -88,7 +88,7 @@ bool DiskTrack::Load(const string& path)
if (dt.length != static_cast<uint32_t>(length)) {
free(dt.buffer);
if (posix_memalign((void **)&dt.buffer, 512, ((length + 511) / 512) * 512)) {
LOGWARN("%s posix_memalign failed", __PRETTY_FUNCTION__)
LOGWARN("posix_memalign failed")
}
dt.length = length;
}
@ -219,8 +219,6 @@ bool DiskTrack::ReadSector(vector<uint8_t>& buf, int sec) const
{
assert(sec >= 0 && sec < 0x100);
LOGTRACE("%s reading sector: %d", __PRETTY_FUNCTION__,sec)
// Error if not initialized
if (!dt.init) {
return false;

View File

@ -9,11 +9,12 @@
//
//---------------------------------------------------------------------------
#include "shared/log.h"
#include "shared/rascsi_exceptions.h"
#include "scsi_command_util.h"
#include "mode_page_device.h"
#include <cstddef>
#include <sstream>
#include <iomanip>
using namespace std;
using namespace scsi_defs;
@ -43,14 +44,17 @@ int ModePageDevice::AddModePages(const vector<int>& cdb, vector<uint8_t>& buf, i
// Get page code (0x3f means all pages)
const int page = cdb[2] & 0x3f;
LOGTRACE("%s Requesting mode page $%02X", __PRETTY_FUNCTION__, page)
stringstream s;
s << "Requesting mode page $" << setfill('0') << setw(2) << hex << page;
GetLogger().Trace(s.str());
// Mode page data mapped to the respective page numbers, C++ maps are ordered by key
map<int, vector<byte>> pages;
SetUpModePages(pages, page, changeable);
if (pages.empty()) {
LOGTRACE("%s Unsupported mode page $%02X", __PRETTY_FUNCTION__, page)
s << "Unsupported mode page $" << page;
GetLogger().Trace(s.str());
throw scsi_exception(sense_key::ILLEGAL_REQUEST, asc::INVALID_FIELD_IN_CDB);
}

View File

@ -7,10 +7,11 @@
//
//---------------------------------------------------------------------------
#include "shared/log.h"
#include "shared/rascsi_exceptions.h"
#include "scsi_command_util.h"
#include "primary_device.h"
#include <sstream>
#include <iomanip>
using namespace std;
using namespace scsi_defs;
@ -41,13 +42,17 @@ void PrimaryDevice::AddCommand(scsi_command opcode, const operation& execute)
void PrimaryDevice::Dispatch(scsi_command cmd)
{
stringstream s;
s << "$" << setfill('0') << setw(2) << hex << static_cast<int>(cmd);
if (const auto& it = commands.find(cmd); it != commands.end()) {
LOGDEBUG("Executing %s ($%02X)", command_mapping.find(cmd)->second.second, static_cast<int>(cmd))
GetLogger().Debug("Device is executing " + string(command_mapping.find(cmd)->second.second) +
" (" + s.str() + ")");
it->second();
}
else {
LOGTRACE("ID %d LUN %d received unsupported command: $%02X", GetId(), GetLun(), static_cast<int>(cmd))
GetLogger().Trace("Received unsupported command: " + s.str());
throw scsi_exception(sense_key::ILLEGAL_REQUEST, asc::INVALID_COMMAND_OPERATION_CODE);
}
@ -63,7 +68,7 @@ void PrimaryDevice::Reset()
int PrimaryDevice::GetId() const
{
if (GetController() == nullptr) {
LOGERROR("Device is missing its controller")
GetLogger().Error("Device is missing its controller");
}
return GetController() != nullptr ? GetController()->GetTargetId() : -1;
@ -72,6 +77,8 @@ int PrimaryDevice::GetId() const
void PrimaryDevice::SetController(shared_ptr<AbstractController> c)
{
controller = c;
logger.SetIdAndLun(c != nullptr ? c->GetTargetId() : -1, GetLun());
}
void PrimaryDevice::TestUnitReady()
@ -97,7 +104,7 @@ void PrimaryDevice::Inquiry()
// Report if the device does not support the requested LUN
if (int lun = GetController()->GetEffectiveLun(); !GetController()->HasDeviceForLun(lun)) {
LOGTRACE("Reporting LUN %d for device ID %d as not supported", lun, GetId())
GetLogger().Trace("LUN is not available");
// Signal that the requested LUN does not exist
GetController()->GetBuffer().data()[0] = 0x7f;
@ -183,25 +190,24 @@ void PrimaryDevice::CheckReady()
// Not ready if reset
if (IsReset()) {
SetReset(false);
LOGTRACE("%s Device in reset", __PRETTY_FUNCTION__)
GetLogger().Trace("Device in reset");
throw scsi_exception(sense_key::UNIT_ATTENTION, asc::POWER_ON_OR_RESET);
}
// Not ready if it needs attention
if (IsAttn()) {
SetAttn(false);
LOGTRACE("%s Device in needs attention", __PRETTY_FUNCTION__)
GetLogger().Trace("Device in needs attention");
throw scsi_exception(sense_key::UNIT_ATTENTION, asc::NOT_READY_TO_READY_CHANGE);
}
// Return status if not ready
if (!IsReady()) {
LOGTRACE("%s Device not ready", __PRETTY_FUNCTION__)
GetLogger().Trace("Device not ready");
throw scsi_exception(sense_key::NOT_READY, asc::MEDIUM_NOT_PRESENT);
}
// Initialization with no error
LOGTRACE("%s Device is ready", __PRETTY_FUNCTION__)
GetLogger().Trace("Device is ready");
}
vector<uint8_t> PrimaryDevice::HandleInquiry(device_type type, scsi_level level, bool is_removable) const
@ -246,15 +252,19 @@ vector<byte> PrimaryDevice::HandleRequestSense() const
buf[12] = (byte)(GetStatusCode() >> 8);
buf[13] = (byte)GetStatusCode();
LOGTRACE("%s Status $%02X, Sense Key $%02X, ASC $%02X",__PRETTY_FUNCTION__, static_cast<int>(GetController()->GetStatus()),
static_cast<int>(buf[2]), static_cast<int>(buf[12]))
stringstream s;
s << setfill('0') << setw(2) << hex
<< "Status $" << static_cast<int>(GetController()->GetStatus())
<< ", Sense Key $" << static_cast<int>(buf[2])
<< ", ASC $" << static_cast<int>(buf[12]);
GetLogger().Trace(s.str());
return buf;
}
bool PrimaryDevice::WriteByteSequence(vector<uint8_t>&, uint32_t)
{
LOGERROR("%s Writing bytes is not supported by this device", __PRETTY_FUNCTION__)
GetLogger().Error("Writing bytes is not supported by this device");
return false;
}
@ -264,10 +274,10 @@ void PrimaryDevice::ReserveUnit()
reserving_initiator = GetController()->GetInitiatorId();
if (reserving_initiator != -1) {
LOGTRACE("Reserved device ID %d, LUN %d for initiator ID %d", GetId(), GetLun(), reserving_initiator)
GetLogger().Trace("Reserved device for initiator ID " + to_string(reserving_initiator));
}
else {
LOGTRACE("Reserved device ID %d, LUN %d for unknown initiator", GetId(), GetLun())
GetLogger().Trace("Reserved device for unknown initiator");
}
EnterStatusPhase();
@ -276,10 +286,10 @@ void PrimaryDevice::ReserveUnit()
void PrimaryDevice::ReleaseUnit()
{
if (reserving_initiator != -1) {
LOGTRACE("Released device ID %d, LUN %d reserved by initiator ID %d", GetId(), GetLun(), reserving_initiator)
GetLogger().Trace("Released device reserved by initiator ID " + to_string(reserving_initiator));
}
else {
LOGTRACE("Released device ID %d, LUN %d reserved by unknown initiator", GetId(), GetLun())
GetLogger().Trace("Released device reserved by unknown initiator");
}
DiscardReservation();
@ -303,10 +313,10 @@ bool PrimaryDevice::CheckReservation(int initiator_id, scsi_command cmd, bool pr
}
if (initiator_id != -1) {
LOGTRACE("Initiator ID %d tries to access reserved device ID %d, LUN %d", initiator_id, GetId(), GetLun())
GetLogger().Trace("Initiator ID " + to_string(initiator_id) + " tries to access reserved device");
}
else {
LOGTRACE("Unknown initiator tries to access reserved device ID %d, LUN %d", GetId(), GetLun())
GetLogger().Trace("Unknown initiator tries to access reserved device");
}
return false;

View File

@ -15,6 +15,7 @@
#include "interfaces/scsi_primary_commands.h"
#include "controllers/abstract_controller.h"
#include "device.h"
#include "device_logger.h"
#include <string>
#include <unordered_map>
#include <functional>
@ -56,6 +57,8 @@ protected:
void AddCommand(scsi_command, const operation&);
const DeviceLogger& GetLogger() const { return logger; }
vector<uint8_t> HandleInquiry(scsi_defs::device_type, scsi_level, bool) const;
virtual vector<uint8_t> InquiryInternal() const = 0;
void CheckReady();
@ -83,6 +86,8 @@ private:
vector<byte> HandleRequestSense() const;
DeviceLogger logger;
weak_ptr<AbstractController> controller;
unordered_map<scsi_command, operation> commands;

View File

@ -7,14 +7,18 @@
//
//---------------------------------------------------------------------------
#include "shared/log.h"
#include "shared/rascsi_exceptions.h"
#include "device_logger.h"
#include "scsi_command_util.h"
#include <cstring>
#include <cassert>
#include <sstream>
#include <iomanip>
using namespace scsi_defs;
void scsi_command_util::ModeSelect(scsi_command cmd, const vector<int>& cdb, const vector<uint8_t>& buf, int length,
int sector_size)
void scsi_command_util::ModeSelect(const DeviceLogger& logger, scsi_command cmd, const vector<int>& cdb,
const vector<uint8_t>& buf, int length, int sector_size)
{
assert(cmd == scsi_command::eCmdModeSelect6 || cmd == scsi_command::eCmdModeSelect10);
assert(length >= 0);
@ -52,14 +56,16 @@ void scsi_command_util::ModeSelect(scsi_command cmd, const vector<int>& cdb, con
if (GetInt16(buf, offset + 12) != sector_size) {
// With rascsi it is not possible to permanently (by formatting) change the sector size,
// because the size is an externally configurable setting only
LOGWARN("In order to change the sector size use the -b option when launching rascsi")
logger.Warn("In order to change the sector size use the -b option when launching rascsi");
throw scsi_exception(sense_key::ILLEGAL_REQUEST, asc::INVALID_FIELD_IN_PARAMETER_LIST);
}
has_valid_page_code = true;
}
else {
LOGWARN("Unknown MODE SELECT page code: $%02X", page)
stringstream s;
s << "Unknown MODE SELECT page code: $" << setfill('0') << setw(2) << hex << page;
logger.Warn(s.str());
}
// Advance to the next page

View File

@ -17,9 +17,11 @@
using namespace std;
class DeviceLogger;
namespace scsi_command_util
{
void ModeSelect(scsi_defs::scsi_command, const vector<int>&, const vector<uint8_t>&, int, int);
void ModeSelect(const DeviceLogger&, scsi_defs::scsi_command, const vector<int>&, const vector<uint8_t>&, int, int);
void EnrichFormatPage(map<int, vector<byte>>&, bool, int);
void AddAppleVendorModePage(map<int, vector<byte>>&, bool);

View File

@ -24,14 +24,20 @@
// Note: This requires a DaynaPort SCSI Link driver.
//---------------------------------------------------------------------------
#include "shared/log.h"
#include "shared/rascsi_exceptions.h"
#include "scsi_command_util.h"
#include "scsi_daynaport.h"
#include <sstream>
#include <iomanip>
using namespace scsi_defs;
using namespace scsi_command_util;
SCSIDaynaPort::SCSIDaynaPort(int lun) : PrimaryDevice(SCDP, lun)
{
SupportsParams(true);
}
bool SCSIDaynaPort::Init(const unordered_map<string, string>& params)
{
PrimaryDevice::Init(params);
@ -48,18 +54,16 @@ bool SCSIDaynaPort::Init(const unordered_map<string, string>& params)
// In the MacOS driver, it looks like the driver is doing two "READ" system calls.
SetSendDelay(DAYNAPORT_READ_HEADER_SZ);
SupportsParams(true);
m_bTapEnable = m_tap.Init(GetParams());
if(!m_bTapEnable){
LOGERROR("Unable to open the TAP interface")
GetLogger().Error("Unable to open the TAP interface");
// Not terminating on regular Linux PCs is helpful for testing
#if !defined(__x86_64__) && !defined(__X86__)
return false;
#endif
} else {
LOGDEBUG("Tap interface created")
GetLogger().Trace("Tap interface created");
}
Reset();
@ -118,7 +122,8 @@ int SCSIDaynaPort::Read(const vector<int>& cdb, vector<uint8_t>& buf, uint64_t)
const auto response = (scsi_resp_read_t*)buf.data();
const int requested_length = cdb[4];
LOGTRACE("%s Read maximum length %d, (%04X)", __PRETTY_FUNCTION__, requested_length, requested_length)
GetLogger().Trace("Read maximum length: " + to_string(requested_length));
// At startup the host may send a READ(6) command with a sector count of 1 to read the root sector.
// We should respond by going into the status mode with a code of 0x02.
@ -141,13 +146,13 @@ int SCSIDaynaPort::Read(const vector<int>& cdb, vector<uint8_t>& buf, uint64_t)
// If we didn't receive anything, return size of 0
if (rx_packet_size <= 0) {
LOGTRACE("%s No packet received", __PRETTY_FUNCTION__)
GetLogger().Trace("No packet received");
response->length = 0;
response->flags = read_data_flags_t::e_no_more_data;
return DAYNAPORT_READ_HEADER_SZ;
}
LOGTRACE("%s Packet Sz %d (%08X) read: %d", __PRETTY_FUNCTION__, (unsigned int) rx_packet_size, (unsigned int) rx_packet_size, read_count)
GetLogger().Trace("Packet Size " + to_string(rx_packet_size) + ", read count: " + to_string(read_count));
// This is a very basic filter to prevent unnecessary packets from
// being sent to the SCSI initiator.
@ -177,14 +182,12 @@ int SCSIDaynaPort::Read(const vector<int>& cdb, vector<uint8_t>& buf, uint64_t)
// configuration from SCSI command 0x0D
if (!send_message_to_host) {
LOGDEBUG("%s Received a packet that's not for me: %02X %02X %02X %02X %02X %02X", \
__PRETTY_FUNCTION__,
static_cast<int>(response->data[0]),
static_cast<int>(response->data[1]),
static_cast<int>(response->data[2]),
static_cast<int>(response->data[3]),
static_cast<int>(response->data[4]),
static_cast<int>(response->data[5]))
stringstream s;
s << "Received a packet that's not for me:" << setfill('0') << setw(2) << hex;
for (int i = 0 ; i < 6; i++) {
s << " $" << static_cast<int>(response->data[i]);
}
GetLogger().Debug(s.str());
// If there are pending packets to be processed, we'll tell the host that the read
// length was 0.
@ -253,16 +256,18 @@ bool SCSIDaynaPort::WriteBytes(const vector<int>& cdb, vector<uint8_t>& buf, uin
if (data_format == 0x00) {
m_tap.Send(buf.data(), data_length);
LOGTRACE("%s Transmitted %u bytes (00 format)", __PRETTY_FUNCTION__, data_length)
GetLogger().Trace("Transmitted " + to_string(data_length) + " byte(s) (00 format)");
}
else if (data_format == 0x80) {
// The data length is specified in the first 2 bytes of the payload
data_length = buf[1] + ((static_cast<int>(buf[0]) & 0xff) << 8);
m_tap.Send(&(buf.data()[4]), data_length);
LOGTRACE(