Commit e8b4ec34 authored by Victor Kotlyar's avatar Victor Kotlyar
Browse files

Ported commits from castor/master for general,drive,volume SCSI statistics:

fa889fed2541e22179b5e035d863f87e7be18fb9
  CASTOR-5322 RFE: Enhance tapeserverd logs with SCSI tape drive
    statistics

b13f495e4ee229b2469f9470a2ffa6b4003a29ec
  Fix for mhtvl scsi log sense exceptions

ad71058fbcb6de85e0440797d7ffa5358e26bf89
  CASTOR-5329 Enhance tape statistics

806e48f4285122d8ab9f118364a15e740518028f
  CASTOR-5332 RFE: Reduce log level to INFO with MHVTL - SCSI Statistics
    could not be acquired from drive

79c5a4c2c36b7acc5b10505ca1694fd521fc6832
c7f6d4d7aaa564b37c2b36c3110dfe2fc96ec970
  Move volume SCSI statistics inside the dtor of TapeCleaningMove volume
    SCSI statistics inside the dtor of TapeCleaning

  ## Description

  When first introduced volume SCSI Statistics (at the moment
  IBM-specific), we explicitly put the function after the unmount of the
  tape was done due to an invalid file descriptor error occurring during
  the SCSI query.

  This bug no longer occurs for IBM drives.
  This may be attributed to the update of firmware of the IBM drives

  Apart from the change of the position of the changes, there is no
  alteration in terms of the metrics reported from the drive to the logs.

  ## Testing

  The tests the new code has been through are:
    * Write/Read file on IBM lib0 drive *(older one)*
    * Write/Read file on IBM lib4 drive *(newer one)*
    * Write/Read file on Oracle T10k drive
parent aee926be
......@@ -238,9 +238,18 @@ namespace SCSI {
class logSensePages {
public:
enum {
writeErrors = 0x02,
readErrors = 0x03,
nonMediumErrors = 0x06,
sequentialAccessDevicePage = 0x0C,
volumeStatistics = 0x17, // IBM specific page
tapeAlert = 0x2e,
dataCompression32h = 0x32, // for LTO, SDLT. We have Data Compression 1Bh for LTO5,6 and DataComppression 0Fh in SSC-3
driveWriteErrors = 0x32, // IBM specific page
driveReadForwardErrors = 0x34, // IBM specific page
driveReadBackwardErrors = 0x36, // IBM specific page
performanceCharacteristics = 0x37, // IBM specific page
vendorUniqueDriveStatistics= 0x3d, // Oracle T1000D/E specific page
blockBytesTransferred = 0x38 // parameters in this page are reset when a cartridge is loaded
};
};
......@@ -272,7 +281,109 @@ namespace SCSI {
unitSerialNumber = 0x80
};
};
class writeErrorsDevicePage {
public:
enum {
totalCorrectedErrors = 0x0003,
totalProcessed = 0x0005,
totalUncorrectedErrors = 0x0006
};
};
class readErrorsDevicePage {
public:
enum {
totalCorrectedErrors = 0x0003,
totalProcessed = 0x0005,
totalUncorrectedErrors = 0x0006
};
};
class nonMediumErrorsDevicePage {
public:
enum {
totalCount = 0x0000
};
};
class volumeStatisticsPage { // IBM 3592 specific
public:
enum {
validityFlag = 0x0000,
volumeMounts = 0x0001,
volumeRecoveredWriteDataErrors = 0x0003,
volumeUnrecoveredWriteDataErrors = 0x0004,
volumeRecoveredReadErrors = 0x0008,
volumeUnrecoveredReadErrors = 0x0009,
volumeManufacturingDate = 0x0046,
BOTPasses = 0x0101,
MOTPasses = 0x0102
};
};
class performanceCharacteristicsQualitySummaryPage { // IBM 3592 specific
public:
enum {
driveEfficiency = 0x0000,
mediaEfficiency = 0x0001,
primaryInterfaceEfficiency0 = 0x0011,
primaryInterfaceEfficiency1 = 0x0012,
libraryInterfaceEfficiency = 0x001a
};
};
class performanceCharacteristicsHostCommandsPage { // IBM 3592 specific
public:
enum {
readPerformanceEfficiency = 0x03d0,
writePerformanceEfficiency = 0x04d0
};
};
class driveWriteErrorsPage { // IBM 3592 specific
public:
enum {
servoTransients = 0x0001,
dataTransients = 0x0002,
servoTemps = 0x0006,
dataTemps = 0x0007,
totalRetries = 0x0008
};
};
class driveReadErrorsPage { // IBM 3592 specific (both FW and BW)
public:
enum {
servoTransients = 0x0001,
dataTransients = 0x0002,
servoTemps = 0x0006,
dataTemps = 0x0007,
totalRetries = 0x0015
};
};
class vendorUniqueDriveStatistics { // Oracle T10K specific
public:
enum {
// Drive stats
readRecoveryRetries = 0x0104,
readTransientConditions = 0x0105,
writeTransientConditions = 0x0106,
servoTepomporaries = 0x0107,
servoTransientConditions = 0x0108,
writeRecoveryRetries = 0x0112,
temporaryDriveErrors = 0x0203,
permanentDriveErrors = 0x0204,
// Quality stats
tapeEfficiency = 0x0400,
readQualityIndex = 0x0401,
readBackCheckQualityIndex = 0x0402,
writeEfficiency = 0x0407
};
};
/**
* Sun StorageTekTM T10000 Tape Drive Fibre Channel Interface Reference Manual
*/
......
......@@ -51,57 +51,97 @@ TEST(castor_tape_SCSI_DeviceList, ScansCorrectly) {
sysWrapper.delegateToFake();
/* Populate the test harness */
sysWrapper.fake.setupSLC5();
// TODO: Test against SLC6 setup
/* We expect the following calls: */
EXPECT_CALL(sysWrapper, opendir(_)).Times(AtLeast(3));
EXPECT_CALL(sysWrapper, readdir(_)).Times(AtLeast(30));
EXPECT_CALL(sysWrapper, closedir(_)).Times(AtLeast(3));
EXPECT_CALL(sysWrapper, realpath(_, _)).Times(3);
EXPECT_CALL(sysWrapper, open(_, _)).Times(19);
EXPECT_CALL(sysWrapper, read(_, _, _)).Times(38);
EXPECT_CALL(sysWrapper, realpath(_, _)).Times(6);
EXPECT_CALL(sysWrapper, open(_, _)).Times(38);
EXPECT_CALL(sysWrapper, read(_, _, _)).Times(76);
EXPECT_CALL(sysWrapper, write(_, _, _)).Times(0);
EXPECT_CALL(sysWrapper, close(_)).Times(19);
EXPECT_CALL(sysWrapper, readlink(_, _, _)).Times(3);
EXPECT_CALL(sysWrapper, stat(_,_)).Times(7);
EXPECT_CALL(sysWrapper, close(_)).Times(38);
EXPECT_CALL(sysWrapper, readlink(_, _, _)).Times(6);
EXPECT_CALL(sysWrapper, stat(_,_)).Times(14);
/* Everything should have been found correctly */
castor::tape::SCSI::DeviceVector dl(sysWrapper);
ASSERT_EQ(3U, dl.size());
ASSERT_EQ(6U, dl.size());
ASSERT_EQ(castor::tape::SCSI::Types::mediumChanger, dl[0].type);
ASSERT_EQ(castor::tape::SCSI::Types::tape, dl[1].type);
ASSERT_EQ(castor::tape::SCSI::Types::tape, dl[2].type);
ASSERT_EQ(castor::tape::SCSI::Types::mediumChanger, dl[3].type);
ASSERT_EQ(castor::tape::SCSI::Types::tape, dl[4].type);
ASSERT_EQ(castor::tape::SCSI::Types::tape, dl[5].type);
ASSERT_EQ( "/dev/sg2", dl[0].sg_dev);
ASSERT_EQ( "/dev/sg0", dl[1].sg_dev);
ASSERT_EQ( "/dev/sg1", dl[2].sg_dev);
ASSERT_EQ( "/dev/sg5", dl[3].sg_dev);
ASSERT_EQ( "/dev/sg3", dl[4].sg_dev);
ASSERT_EQ( "/dev/sg4", dl[5].sg_dev);
ASSERT_EQ( "", dl[0].st_dev);
ASSERT_EQ( "/dev/st0", dl[1].st_dev);
ASSERT_EQ( "/dev/st1", dl[2].st_dev);
ASSERT_EQ( "", dl[3].st_dev);
ASSERT_EQ( "/dev/st2", dl[4].st_dev);
ASSERT_EQ( "/dev/st3", dl[5].st_dev);
ASSERT_EQ( "", dl[0].nst_dev);
ASSERT_EQ("/dev/nst0", dl[1].nst_dev);
ASSERT_EQ("/dev/nst1", dl[2].nst_dev);
ASSERT_EQ( "", dl[3].nst_dev);
ASSERT_EQ("/dev/nst2", dl[4].nst_dev);
ASSERT_EQ("/dev/nst3", dl[5].nst_dev);
ASSERT_EQ("/sys/devices/pseudo_0/adapter0/host3/target3:0:0/3:0:0:0", dl[0].sysfs_entry);
ASSERT_EQ("/sys/devices/pseudo_0/adapter0/host3/target3:0:1/3:0:1:0", dl[1].sysfs_entry);
ASSERT_EQ("/sys/devices/pseudo_0/adapter0/host3/target3:0:2/3:0:2:0", dl[2].sysfs_entry);
ASSERT_EQ("/sys/devices/pseudo_0/adapter0/host2/target2:0:0/2:0:0:0", dl[3].sysfs_entry);
ASSERT_EQ("/sys/devices/pseudo_0/adapter0/host2/target2:0:1/2:0:1:0", dl[4].sysfs_entry);
ASSERT_EQ("/sys/devices/pseudo_0/adapter0/host2/target2:0:2/2:0:2:0", dl[5].sysfs_entry);
ASSERT_EQ( 21U, dl[0].sg.major);
ASSERT_EQ( 2U, dl[0].sg.minor);
ASSERT_EQ( 21U, dl[1].sg.major);
ASSERT_EQ( 0U, dl[1].sg.minor);
ASSERT_EQ( 21U, dl[2].sg.major);
ASSERT_EQ( 1U, dl[2].sg.minor);
ASSERT_EQ( 21U, dl[3].sg.major);
ASSERT_EQ( 5U, dl[3].sg.minor);
ASSERT_EQ( 21U, dl[4].sg.major);
ASSERT_EQ( 3U, dl[4].sg.minor);
ASSERT_EQ( 21U, dl[5].sg.major);
ASSERT_EQ( 4U, dl[5].sg.minor);
ASSERT_EQ( 0U, dl[0].st.major);
ASSERT_EQ( 0U, dl[0].st.minor);
ASSERT_EQ( 9U, dl[1].st.major);
ASSERT_EQ( 0U, dl[1].st.minor);
ASSERT_EQ( 9U, dl[2].st.major);
ASSERT_EQ( 1U, dl[2].st.minor);
ASSERT_EQ( 0U, dl[3].st.major);
ASSERT_EQ( 0U, dl[3].st.minor);
ASSERT_EQ( 9U, dl[4].st.major);
ASSERT_EQ( 2U, dl[4].st.minor);
ASSERT_EQ( 9U, dl[5].st.major);
ASSERT_EQ( 3U, dl[5].st.minor);
ASSERT_EQ( 0U, dl[0].nst.major);
ASSERT_EQ( 0U, dl[0].nst.minor);
ASSERT_EQ( 9U, dl[1].nst.major);
ASSERT_EQ(128U, dl[1].nst.minor);
ASSERT_EQ( 9U, dl[2].nst.major);
ASSERT_EQ(129U, dl[2].nst.minor);
ASSERT_EQ( 0U, dl[3].nst.major);
ASSERT_EQ( 0U, dl[3].nst.minor);
ASSERT_EQ( 9U, dl[4].nst.major);
ASSERT_EQ(130U, dl[4].nst.minor);
ASSERT_EQ( 9U, dl[5].nst.major);
ASSERT_EQ(131U, dl[5].nst.minor);
ASSERT_EQ("STK", dl[0].vendor);
ASSERT_EQ("STK", dl[1].vendor);
ASSERT_EQ("STK", dl[2].vendor);
......@@ -111,6 +151,15 @@ TEST(castor_tape_SCSI_DeviceList, ScansCorrectly) {
ASSERT_EQ("0104", dl[0].productRevisionLevel);
ASSERT_EQ("0104", dl[1].productRevisionLevel);
ASSERT_EQ("0104", dl[2].productRevisionLevel);
ASSERT_EQ("IBM", dl[3].vendor);
ASSERT_EQ("IBM", dl[4].vendor);
ASSERT_EQ("IBM", dl[5].vendor);
ASSERT_EQ("03584L22", dl[3].product);
ASSERT_EQ("03592E08", dl[4].product);
ASSERT_EQ("03592E08", dl[5].product);
ASSERT_EQ("F030", dl[3].productRevisionLevel);
ASSERT_EQ("460E", dl[4].productRevisionLevel);
ASSERT_EQ("460E", dl[5].productRevisionLevel);
}
TEST(castor_tape_SCSI_DeviceList, FindBySymlink) {
......
......@@ -453,6 +453,18 @@ TEST_P(DataTransferSessionTest, DataTransferSessionGooddayRecall) {
ASSERT_EQ(0, statRc);
ASSERT_EQ(1000, statBuf.st_size); //same size of data
}
// 10) Check logs
std::string logToCheck = logger.getLog();
logToCheck += "";
ASSERT_NE(std::string::npos, logToCheck.find("firmwareVersion=\"123A\" "
"mountTotalCorrectedReadErrors=\"5\" mountTotalReadBytesProcessed=\"4096\" "
"mountTotalUncorrectedReadErrors=\"1\" mountTotalNonMediumErrorCounts=\"2\""));
ASSERT_NE(std::string::npos, logToCheck.find("firmwareVersion=\"123A\" lifetimeMediumEfficiencyPrct=\"100\" "
"mountReadEfficiencyPrct=\"100\" mountWriteEfficiencyPrct=\"100\" "
"mountReadTransients=\"10\" "
"mountServoTemps=\"10\" mountServoTransients=\"5\" mountTemps=\"100\" "
"mountTotalReadRetries=\"25\" mountTotalWriteRetries=\"25\" mountWriteTransients=\"10\""));
}
TEST_P(DataTransferSessionTest, DataTransferSessionWrongRecall) {
......@@ -621,6 +633,18 @@ TEST_P(DataTransferSessionTest, DataTransferSessionWrongRecall) {
// 10) Check the remote files exist and have the correct size
std::string temp = logger.getLog();
ASSERT_NE(std::string::npos, logger.getLog().find("trying to position beyond the end of data"));
// 11) Check logs for drive statistics
std::string logToCheck = logger.getLog();
logToCheck += "";
ASSERT_NE(std::string::npos, logToCheck.find("firmwareVersion=\"123A\" "
"mountTotalCorrectedReadErrors=\"5\" mountTotalReadBytesProcessed=\"4096\" "
"mountTotalUncorrectedReadErrors=\"1\" mountTotalNonMediumErrorCounts=\"2\""));
ASSERT_NE(std::string::npos, logToCheck.find("firmwareVersion=\"123A\" lifetimeMediumEfficiencyPrct=\"100\" "
"mountReadEfficiencyPrct=\"100\" mountWriteEfficiencyPrct=\"100\" "
"mountReadTransients=\"10\" "
"mountServoTemps=\"10\" mountServoTransients=\"5\" mountTemps=\"100\" "
"mountTotalReadRetries=\"25\" mountTotalWriteRetries=\"25\" mountWriteTransients=\"10\""));
}
TEST_P(DataTransferSessionTest, DataTransferSessionNoSuchDrive) {
......@@ -894,6 +918,18 @@ TEST_P(DataTransferSessionTest, DataTransferSessionFailtoMount) {
ASSERT_NO_THROW(sess.execute());
std::string temp = logger.getLog();
ASSERT_NE(std::string::npos, logger.getLog().find("Failed to mount the tape"));
// 10) Check logs for drive statistics
std::string logToCheck = logger.getLog();
logToCheck += "";
ASSERT_NE(std::string::npos, logToCheck.find("firmwareVersion=\"123A\" "
"mountTotalCorrectedReadErrors=\"5\" mountTotalReadBytesProcessed=\"4096\" "
"mountTotalUncorrectedReadErrors=\"1\" mountTotalNonMediumErrorCounts=\"2\""));
ASSERT_NE(std::string::npos, logToCheck.find("firmwareVersion=\"123A\" lifetimeMediumEfficiencyPrct=\"100\" "
"mountReadEfficiencyPrct=\"100\" mountWriteEfficiencyPrct=\"100\" "
"mountReadTransients=\"10\" "
"mountServoTemps=\"10\" mountServoTransients=\"5\" mountTemps=\"100\" "
"mountTotalReadRetries=\"25\" mountTotalWriteRetries=\"25\" mountWriteTransients=\"10\""));
}
TEST_P(DataTransferSessionTest, DataTransferSessionEmptyOnVolReq) {
......@@ -1058,6 +1094,17 @@ TEST_P(DataTransferSessionTest, DataTransferSessionGooddayMigration) {
ASSERT_EQ(sf->adler32(), afs.checksumValue);
ASSERT_EQ(1000, afs.fileSize);
}
// Check logs for drive statistics
ASSERT_NE(std::string::npos, temp.find("firmwareVersion=\"123A\" "
"mountTotalCorrectedWriteErrors=\"5\" mountTotalUncorrectedWriteErrors=\"1\" "
"mountTotalWriteBytesProcessed=\"4096\" mountTotalNonMediumErrorCounts=\"2\""));
ASSERT_NE(std::string::npos, temp.find("firmwareVersion=\"123A\" lifetimeMediumEfficiencyPrct=\"100\" "
"mountReadEfficiencyPrct=\"100\" mountWriteEfficiencyPrct=\"100\" "
"mountReadTransients=\"10\" "
"mountServoTemps=\"10\" mountServoTransients=\"5\" mountTemps=\"100\" "
"mountTotalReadRetries=\"25\" mountTotalWriteRetries=\"25\" mountWriteTransients=\"10\""));
}
//
......@@ -1172,6 +1219,18 @@ TEST_P(DataTransferSessionTest, DataTransferSessionMissingFilesMigration) {
ASSERT_EQ(s_vid, sess.getVid());
// We should no have logged a single successful file read.
ASSERT_EQ(std::string::npos, logger.getLog().find("MSG=\"File successfully read from disk\""));
// Check logs for drive statistics
std::string logToCheck = logger.getLog();
logToCheck += "";
ASSERT_NE(std::string::npos, logToCheck.find("firmwareVersion=\"123A\" "
"mountTotalCorrectedWriteErrors=\"5\" mountTotalUncorrectedWriteErrors=\"1\" "
"mountTotalWriteBytesProcessed=\"4096\" mountTotalNonMediumErrorCounts=\"2\""));
ASSERT_NE(std::string::npos, logToCheck.find("firmwareVersion=\"123A\" lifetimeMediumEfficiencyPrct=\"100\" "
"mountReadEfficiencyPrct=\"100\" mountWriteEfficiencyPrct=\"100\" "
"mountReadTransients=\"10\" "
"mountServoTemps=\"10\" mountServoTransients=\"5\" mountTemps=\"100\" "
"mountTotalReadRetries=\"25\" mountTotalWriteRetries=\"25\" mountWriteTransients=\"10\""));
}
//
......@@ -1303,6 +1362,18 @@ TEST_P(DataTransferSessionTest, DataTransferSessionTapeFullMigration) {
ASSERT_EQ(s_vid, tapes.front().vid);
ASSERT_EQ(true, tapes.front().full);
}
// Check logs for drive statistics
std::string logToCheck = logger.getLog();
logToCheck += "";
ASSERT_NE(std::string::npos, logToCheck.find("firmwareVersion=\"123A\" "
"mountTotalCorrectedWriteErrors=\"5\" mountTotalUncorrectedWriteErrors=\"1\" "
"mountTotalWriteBytesProcessed=\"4096\" mountTotalNonMediumErrorCounts=\"2\""));
ASSERT_NE(std::string::npos, logToCheck.find("firmwareVersion=\"123A\" lifetimeMediumEfficiencyPrct=\"100\" "
"mountReadEfficiencyPrct=\"100\" mountWriteEfficiencyPrct=\"100\" "
"mountReadTransients=\"10\" "
"mountServoTemps=\"10\" mountServoTransients=\"5\" mountTemps=\"100\" "
"mountTotalReadRetries=\"25\" mountTotalWriteRetries=\"25\" mountWriteTransients=\"10\""));
}
TEST_P(DataTransferSessionTest, DataTransferSessionTapeFullOnFlushMigration) {
......@@ -1430,6 +1501,17 @@ TEST_P(DataTransferSessionTest, DataTransferSessionTapeFullOnFlushMigration) {
ASSERT_EQ(s_vid, tapes.front().vid);
ASSERT_EQ(true, tapes.front().full);
}
// Check logs for drive statistics
std::string logToCheck = logger.getLog();
logToCheck += "";
ASSERT_NE(std::string::npos, logToCheck.find("firmwareVersion=\"123A\" "
"mountTotalCorrectedWriteErrors=\"5\" mountTotalUncorrectedWriteErrors=\"1\" "
"mountTotalWriteBytesProcessed=\"4096\" mountTotalNonMediumErrorCounts=\"2\""));
ASSERT_NE(std::string::npos, logToCheck.find("firmwareVersion=\"123A\" lifetimeMediumEfficiencyPrct=\"100\" "
"mountReadEfficiencyPrct=\"100\" mountWriteEfficiencyPrct=\"100\" "
"mountReadTransients=\"10\" "
"mountServoTemps=\"10\" mountServoTransients=\"5\" mountTemps=\"100\" "
"mountTotalReadRetries=\"25\" mountTotalWriteRetries=\"25\" mountWriteTransients=\"10\""));
}
#undef TEST_MOCK_DB
......
......@@ -128,6 +128,8 @@ namespace unitTests
}
virtual void countTapeLogError(const std::string & error) {};
protected:
virtual void logSCSIMetrics() {};
};
class TestingDatabaseRetrieveMount: public cta::SchedulerDatabase::RetrieveMount {
......
......@@ -57,6 +57,10 @@ castor::tape::tapeserver::daemon::TapeReadSingleThread::TapeCleaning::~TapeClean
m_this.m_stats.waitReportingTime += m_timer.secs(cta::utils::Timer::resetCounter);
// Log (safely, exception-wise) the tape alerts (if any) at the end of the session
try { m_this.logTapeAlerts(); } catch (...) {}
// Log safely SCSI Metrits
try { m_this.logSCSIMetrics(); } catch (...) {}
// Log safely errors at the end of the session
// This out-of-try-catch variables allows us to record the stage of the
// process we're in, and to count the error if it occurs.
// We will not record errors for an empty string. This will allow us to
......@@ -279,6 +283,7 @@ void castor::tape::tapeserver::daemon::TapeReadSingleThread::run() {
}
}
}
// The session completed successfully, and the cleaner (unmount) executed
// at the end of the previous block. Log the results.
cta::log::ScopedParamContainer params(m_logContext);
......@@ -345,3 +350,59 @@ void castor::tape::tapeserver::daemon::TapeReadSingleThread::logWithStat(
/1000/1000/m_stats.totalTime:0.0);
m_logContext.log(level,msg);
}
//------------------------------------------------------------------------------
//logSCSIMetrics
//------------------------------------------------------------------------------
void castor::tape::tapeserver::daemon::TapeReadSingleThread::logSCSIMetrics() {
try {
// mount general statistics
cta::log::ScopedParamContainer scopedContainer(m_logContext);
appendDriveAndTapeInfoToScopedParams(scopedContainer);
// get mount general stats
std::map<std::string, uint32_t> scsi_read_metrics_hash = m_drive.getTapeReadErrors();
appendMetricsToScopedParams(scopedContainer, scsi_read_metrics_hash);
std::map<std::string, uint32_t> scsi_nonmedium_metrics_hash = m_drive.getTapeNonMediumErrors();
appendMetricsToScopedParams(scopedContainer, scsi_nonmedium_metrics_hash);
logSCSIStats("Logging mount general statistics",
scsi_read_metrics_hash.size() + scsi_nonmedium_metrics_hash.size());
}
catch (const cta::exception::Exception &ex) {
cta::log::ScopedParamContainer scoped(m_logContext);
scoped.add("exception_message", ex.getMessageValue());
m_logContext.log(cta::log::ERR, "Exception in logging mount general statistics");
}
// drive statistic
try {
cta::log::ScopedParamContainer scopedContainer(m_logContext);
appendDriveAndTapeInfoToScopedParams(scopedContainer);
// get drive stats
std::map<std::string,float> scsi_quality_metrics_hash = m_drive.getQualityStats();
appendMetricsToScopedParams(scopedContainer, scsi_quality_metrics_hash);
std::map<std::string,uint32_t> scsi_drive_metrics_hash = m_drive.getDriveStats();
appendMetricsToScopedParams(scopedContainer, scsi_drive_metrics_hash);
logSCSIStats("Logging drive statistics",
scsi_quality_metrics_hash.size()+scsi_drive_metrics_hash.size());
}
catch (const cta::exception::Exception &ex) {
cta::log::ScopedParamContainer scoped(m_logContext);
scoped.add("exception_message", ex.getMessageValue());
m_logContext.log(cta::log::ERR, "Exception in logging drive statistics");
}
// volume statistics
try {
cta::log::ScopedParamContainer scopedContainer(m_logContext);
appendDriveAndTapeInfoToScopedParams(scopedContainer);
std::map<std::string,uint32_t> scsi_metrics_hash = m_drive.getVolumeStats();
appendMetricsToScopedParams(scopedContainer, scsi_metrics_hash);
logSCSIStats("Logging volume statistics", scsi_metrics_hash.size());
}
catch (const cta::exception::Exception &ex) {
cta::log::ScopedParamContainer scoped(m_logContext);
scoped.add("exception_message", ex.getMessageValue());
m_logContext.log(cta::log::ERR, "Exception in logging volume statistics");
}
}
......@@ -150,6 +150,11 @@ private:
m_watchdog.addToErrorCount(error);
}
protected:
/**
* Logs SCSI metrics for read session.
*/
virtual void logSCSIMetrics();
}; // class TapeReadSingleThread
} // namespace daemon
......
......@@ -203,7 +203,43 @@ protected:
}
return true;
}
/**
* Log SCSI metrics for session.
*/
virtual void logSCSIMetrics() = 0;
/**
* Function iterating through the map of available SCSI metrics and logging them.
*/
void logSCSIStats(const std::string & logTitle, size_t metricsHashLength) {
if(metricsHashLength == 0) { // skip logging entirely if hash is empty.
m_logContext.log(cta::log::INFO, "SCSI Statistics could not be acquired from drive");
return;
}
m_logContext.log(cta::log::INFO, logTitle);
}
/**
* Function appending Tape VID, drive manufacturer and model and firmware version to the Scoped Container passed.
*/
void appendDriveAndTapeInfoToScopedParams(cta::log::ScopedParamContainer &scopedContainer) {
drive::deviceInfo di = m_drive.getDeviceInfo();
scopedContainer.add("driveManufacturer", di.vendor);
scopedContainer.add("driveType", di.product);
scopedContainer.add("firmwareVersion", m_drive.getDriveFirmwareVersion());
}
/**
* Function appending SCSI Metrics to the Scoped Container passed.
*/
template<class N>
static void appendMetricsToScopedParams( cta::log::ScopedParamContainer &scopedContainer, const std::map<std::string,N> & metricsHash) {
for(auto it = metricsHash.cbegin(); it != metricsHash.end(); it++) {
scopedContainer.add(it->first, it->second);
}
}
/**
* Helper virtual function allowing the access to the m_watchdog member
* in the inherited classes (TapeReadSingleThread and TapeWriteSingleThread)
......
......@@ -266,6 +266,7 @@ void castor::tape::tapeserver::daemon::TapeWriteSingleThread::run() {
}
} //end of while(1))
}
// The session completed successfully, and the cleaner (unmount) executed
// at the end of the previous block. Log the results.
cta::log::ScopedParamContainer params(m_logContext);
......@@ -372,3 +373,59 @@ int level,const std::string& msg, cta::log::ScopedParamContainer& params){
/1000/1000/m_stats.totalTime:0.0);
m_logContext.log(level, msg);
}
//------------------------------------------------------------------------------
//logSCSIMetrics
//------------------------------------------------------------------------------
void castor::tape::tapeserver::daemon::TapeWriteSingleThread::logSCSIMetrics() {
try {
// mount general statistics
cta::log::ScopedParamContainer scopedContainer(m_logContext);
appendDriveAndTapeInfoToScopedParams(scopedContainer);
// get mount general stats
std::map<std::string, uint32_t> scsi_write_metrics_hash = m_drive.getTapeWriteErrors();
appendMetricsToScopedParams(scopedContainer, scsi_write_metrics_hash);
std::map<std::string, uint32_t> scsi_nonmedium_metrics_hash = m_drive.getTapeNonMediumErrors();
appendMetricsToScopedParams(scopedContainer, scsi_nonmedium_metrics_hash);
logSCSIStats("Logging mount general statistics",
scsi_write_metrics_hash.size() + scsi_nonmedium_metrics_hash.size());
}
catch (const cta::exception::Exception &ex) {
cta::log::ScopedParamContainer scoped(m_logContext);
scoped.add("exception_message", ex.getMessageValue());
m_logContext.log(cta::log::ERR, "Exception in logging mount general statistics");
}
// drive statistics
try {
cta::log::ScopedParamContainer scopedContainer(m_logContext);