Commit bb2436c1 authored by Eric Cano's avatar Eric Cano
Browse files

Fixed end of session being reported too early in ArchiveSessions.

This led to VID being marked as available during unmount, and another drive could try an mount the same tape.
Added various logs.

The following sequence was observed in tests (with a sleep(3) at the end of MigrationReportPacker::ReportDriveStatus::execute() ):
 [eric@localhost ~]$ date; kubectl -n cta exec ctacli -- cta dr ls VDSTK11
Thu Jun 22 11:19:10 CEST 2017
    drive   host  library  mountType    status  desiredUp  forceDown     vid
  VDSTK11  tpsrv  VLSTK10    Archive  Mounting         UP             V01001
[eric@localhost ~]$ date; kubectl -n cta exec ctacli -- cta dr ls VDSTK11
Thu Jun 22 11:19:12 CEST 2017
    drive   host  library  mountType       status  desiredUp  forceDown     vid
  VDSTK11  tpsrv  VLSTK10    Archive  Transfering         UP             V01001
[eric@localhost ~]$ date; kubectl -n cta exec ctacli -- cta dr ls VDSTK11
Thu Jun 22 11:19:16 CEST 2017
    drive   host  library  mountType      status  desiredUp  forceDown     vid
  VDSTK11  tpsrv  VLSTK10    Archive  CleaningUp         UP             V01001
[eric@localhost ~]$ date; kubectl -n cta exec ctacli -- cta dr ls VDSTK11
Thu Jun 22 11:19:18 CEST 2017
    drive   host  library  mountType     status  desiredUp  forceDown     vid
  VDSTK11  tpsrv  VLSTK10    Archive  Unloading         UP             V01001
[eric@localhost ~]$ date; kubectl -n cta exec ctacli -- cta dr ls VDSTK11
Thu Jun 22 11:19:22 CEST 2017
    drive   host  library  mountType      status  desiredUp  forceDown     vid
  VDSTK11  tpsrv  VLSTK10    Archive  Unmounting         UP             V01001
[eric@localhost ~]$ date; kubectl -n cta exec ctacli -- cta dr ls VDSTK11
Thu Jun 22 11:19:25 CEST 2017
    drive   host  library  mountType  status  desiredUp  forceDown  vid
  VDSTK11  tpsrv  VLSTK10    NoMount      Up         UP               -
parent 617acd73
......@@ -137,7 +137,7 @@ void MigrationReportPacker::reportTestGoingToEnd(cta::log::LogContext & lc){
void MigrationReportPacker::synchronousReportEndWithErrors(const std::string msg, int errorCode, cta::log::LogContext & lc){
cta::log::ScopedParamContainer params(lc);
params.add("type", "ReportEndofSessionWithErrors");
lc.log(cta::log::DEBUG, "In MigrationReportPacker::synchronousReportEndWithErrors(), reporting asynchronously.");
lc.log(cta::log::DEBUG, "In MigrationReportPacker::synchronousReportEndWithErrors(), reporting asynchronously session complete.");
m_continue=false;
m_archiveMount->complete();
if(m_errorHappened) {
......@@ -176,7 +176,8 @@ void MigrationReportPacker::ReportSuccessful::execute(MigrationReportPacker& rep
//------------------------------------------------------------------------------
void MigrationReportPacker::reportDriveStatus(cta::common::dataStructures::DriveStatus status, cta::log::LogContext & lc) {
cta::log::ScopedParamContainer params(lc);
params.add("type", "ReportDriveStatus");
params.add("type", "ReportDriveStatus")
.add("Status", cta::common::dataStructures::toString(status));
lc.log(cta::log::DEBUG, "In MigrationReportPacker::reportDriveStatus(), pushing a report.");
cta::threading::MutexLocker ml(m_producterProtection);
m_fifo.push(new ReportDriveStatus(status));
......@@ -186,6 +187,9 @@ void MigrationReportPacker::reportDriveStatus(cta::common::dataStructures::Drive
//ReportDriveStatus::execute
//------------------------------------------------------------------------------
void MigrationReportPacker::ReportDriveStatus::execute(MigrationReportPacker& parent){
cta::log::ScopedParamContainer params(parent.m_lc);
params.add("status", cta::common::dataStructures::toString(m_status));
parent.m_lc.log(cta::log::DEBUG, "In MigrationReportPacker::ReportDriveStatus::execute(): reporting drive status.");
parent.m_archiveMount->setDriveStatus(m_status);
}
......@@ -266,6 +270,7 @@ void MigrationReportPacker::ReportTapeFull::execute(MigrationReportPacker& repor
//------------------------------------------------------------------------------
void MigrationReportPacker::ReportEndofSession::execute(MigrationReportPacker& reportPacker){
reportPacker.m_continue=false;
reportPacker.m_lc.log(cta::log::DEBUG, "In MigrationReportPacker::ReportEndofSession::execute(): reporting session complete.");
reportPacker.m_archiveMount->complete();
if(!reportPacker.m_errorHappened){
cta::log::ScopedParamContainer sp(reportPacker.m_lc);
......@@ -298,6 +303,7 @@ void MigrationReportPacker::ReportEndofSession::execute(MigrationReportPacker& r
//------------------------------------------------------------------------------
void MigrationReportPacker::ReportEndofSessionWithErrors::execute(MigrationReportPacker& reportPacker){
reportPacker.m_continue=false;
reportPacker.m_lc.log(cta::log::DEBUG, "In MigrationReportPacker::ReportEndofSessionWithErrors::execute(): reporting session complete.");
reportPacker.m_archiveMount->complete();
if(reportPacker.m_errorHappened) {
cta::log::ScopedParamContainer sp(reportPacker.m_lc);
......
......@@ -140,7 +140,9 @@ private:
public:
ReportTestGoingToEnd() {}
virtual void execute(MigrationReportPacker& reportPacker) override {
reportPacker.m_continue=false;reportPacker.m_archiveMount->complete();
reportPacker.m_continue=false;
reportPacker.m_lc.log(cta::log::DEBUG, "In MigrationReportPacker::ReportTestGoingToEnd::execute(): Reporting session complete.");
reportPacker.m_archiveMount->complete();
}
};
......
......@@ -27,6 +27,7 @@
#include <signal.h>
#include <iostream>
#include <cxxabi.h>
namespace{
struct failedReportRecallResult : public cta::exception::Exception{
......@@ -221,7 +222,14 @@ void RecallReportPacker::WorkerThread::run(){
std::unique_ptr<Report> rep(m_parent.m_fifo.pop());
{
cta::log::ScopedParamContainer spc(m_parent.m_lc);
spc.add("ReportType", debugType=typeid(*rep).name());
int demangleStatus;
char * demangledReportType = abi::__cxa_demangle(typeid(*rep.get()).name(), nullptr, nullptr, &demangleStatus);
if (!demangleStatus) {
spc.add("typeId", demangledReportType);
} else {
spc.add("typeId", typeid(*rep.get()).name());
}
free(demangledReportType);
if (rep->goingToEnd())
spc.add("goingToEnd", "true");
m_parent.m_lc.log(cta::log::DEBUG, "Popping report");
......
......@@ -397,8 +397,6 @@ void castor::tape::tapeserver::daemon::TapeWriteSingleThread::run() {
//we flush without asking
tapeFlush("No more data to write on tape, unconditional flushing to the client",bytes,files,timer);
m_stats.flushTime += timer.secs(cta::utils::Timer::resetCounter);
//end of session + log
m_reportPacker.reportEndOfSession(m_logContext);
cta::log::LogContext::ScopedParam sp0(m_logContext, cta::log::Param("tapeThreadDuration", totalTimer.secs()));
m_logContext.log(cta::log::DEBUG, "writing data to tape has finished");
break;
......@@ -432,6 +430,8 @@ void castor::tape::tapeserver::daemon::TapeWriteSingleThread::run() {
logWithStats(cta::log::INFO, "Tape thread complete",params);
// Report one last time the stats, after unloading/unmounting.
m_watchdog.updateStats(m_stats);
//end of session + log
m_reportPacker.reportEndOfSession(m_logContext);
} //end of try
catch(const cta::exception::Exception& e){
//we end there because write session could not be opened
......
Supports Markdown
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment