Commit 6dba38c5 authored by Eric Cano's avatar Eric Cano
Browse files

CASTOR-4823: tapeserverd's main process should log statistics and status of...

CASTOR-4823: tapeserverd's main process should log statistics and status of the closing session in all cases

Added new messages between the session process and the main process: addition and removal of log parameters.
Added storage of the log parameters in the catalogueTransferSession.
Added logging of the tape session at the end in the initial process, allowing statistics gathering even in
case of crash. This standard log message is intended to be used as an input for the tape log system.
Changed the default off the formatting of doubles in the log so that we don't end up with hard to parse
scientific notation in the logs.
parent adfea7ba
......@@ -24,7 +24,6 @@
#pragma once
#include <ostream>
#include <cstdio>
#include "castor/log/Logger.hpp"
namespace castor {
......@@ -162,9 +161,7 @@ class ScopedParamContainer{
}
ScopedParamContainer& addSnprintfDouble(const std::string& s,double t){
char buf[100];
std::snprintf(buf, sizeof(buf), "%f", t);
m_context.pushOrReplace(Param(s,buf));
m_context.pushOrReplace(ParamDoubleSnprintf(s,t));
m_names.push_back(s);
return *this;
}
......
......@@ -22,6 +22,7 @@
*****************************************************************************/
#include "castor/log/Param.hpp"
#include <cstdio>
//------------------------------------------------------------------------------
// getName
......@@ -36,3 +37,16 @@ const std::string &castor::log::Param::getName() const throw() {
const std::string &castor::log::Param::getValue() const throw() {
return m_value;
}
//------------------------------------------------------------------------------
// ParamDoubleSnprintf constructor
//------------------------------------------------------------------------------
castor::log::ParamDoubleSnprintf::ParamDoubleSnprintf
(const std::string& name, const double value):
castor::log::Param(name, "") {
char buf[100];
std::snprintf(buf, sizeof(buf), "%f", value);
// Just in case we overflow
buf[sizeof(buf)-1]='\0';
m_value = buf;
}
......@@ -26,6 +26,7 @@
#include <sstream>
#include <string.h>
#include <cstdio>
namespace castor {
namespace log {
......@@ -46,10 +47,26 @@ public:
*/
template <typename T> Param(const std::string &name, const T &value) throw():
m_name(name) {
std::stringstream oss;
std::ostringstream oss;
oss << value;
m_value = oss.str();
}
/**
* Constructor.
*
* @param name The name of the parameter.
* @param value The value of the parameter that will be converted to a string
* using snprintf for doubles
*/
Param (const std::string &name, const double value) throw():
m_name(name) {
char buf[100];
std::snprintf(buf, sizeof(buf), "%f", value);
// Just in case we overflow
buf[sizeof(buf)-1]='\0';
m_value = buf;
}
/**
* Value changer. Useful for log contexts.
......@@ -72,7 +89,7 @@ public:
*/
const std::string &getValue() const throw();
private:
protected:
/**
* Name of the parameter
......@@ -86,6 +103,15 @@ private:
}; // class Param
/**
* An helper class allowing the construction of a Param class with sprintf
* formatting for a double.
*/
class ParamDoubleSnprintf: public Param {
public:
ParamDoubleSnprintf(const std::string &name, const double value);
}; // class ParamDoubleSnprintf
} // namespace log
} // namespace castor
// This file is part of the Castor project.
// See http://castor.web.cern.ch/castor
//
// Copyright (C) 2003 CERN
// This program is free software; you can redistribute it and/or
// modify it under the terms of the GNU General Public License
// as published by the Free Software Foundation; either version 2
// of the License, or (at your option) any later version.
// This program is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU General Public License for more details.
// You should have received a copy of the GNU General Public License
// along with this program; if not, write to the Free Software
// Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA.
//
// @author Castor Dev team, castor-dev@cern.ch
package castor.messages;
message LogParam {
required string name = 1;
required string value = 2;
}
message AddLogParams {
required string unitname = 1;
repeated LogParam params = 2;
}
......@@ -76,6 +76,10 @@ const char *castor::messages::msgTypeToString(const MsgType msgType) throw() {
return "AcsMountTapeReadWrite";
case MSG_TYPE_ACSDISMOUNTTAPE:
return "AcsDismountTape";
case MSG_TYPE_ADDLOGPARAMS:
return "AddLogParams";
case MSG_TYPE_DELETELOGPARAMS:
return "DeleteLogParams";
default:
return "Unknown";
}
......
......@@ -55,7 +55,9 @@ enum MsgType {
MSG_TYPE_LABELERROR,
MSG_TYPE_ACSMOUNTTAPEREADONLY,
MSG_TYPE_ACSMOUNTTAPEREADWRITE,
MSG_TYPE_ACSDISMOUNTTAPE
MSG_TYPE_ACSDISMOUNTTAPE,
MSG_TYPE_ADDLOGPARAMS,
MSG_TYPE_DELETELOGPARAMS
};
enum ProtocolVersion {
......
// This file is part of the Castor project.
// See http://castor.web.cern.ch/castor
//
// Copyright (C) 2003 CERN
// This program is free software; you can redistribute it and/or
// modify it under the terms of the GNU General Public License
// as published by the Free Software Foundation; either version 2
// of the License, or (at your option) any later version.
// This program is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU General Public License for more details.
// You should have received a copy of the GNU General Public License
// along with this program; if not, write to the Free Software
// Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA.
//
// @author Castor Dev team, castor-dev@cern.ch
package castor.messages;
message DeleteLogParams {
required string unitname = 1;
repeated string param_names = 2;
}
......@@ -22,9 +22,11 @@
#pragma once
#include "castor/exception/Exception.hpp"
#include "castor/log/Param.hpp"
#include <stdint.h>
#include <string>
#include <list>
namespace castor {
namespace messages {
......@@ -131,6 +133,20 @@ public:
*/
virtual void notifyHeartbeat(const std::string &unitName,
const uint64_t nbBytesMoved) = 0;
/**
* Sends a new set of parameters, to be logged by the mother process when the
* transfer session is over.
* @param params: a vector of log parameters
*/
virtual void addLogParams(const std::string &unitName,
const std::list<castor::log::Param> & params) = 0;
/**
* Sends a list of parameters to remove from the end of session logging.
*/
virtual void deleteLogParams(const std::string &unitName,
const std::list<std::string> & paramNames) = 0;
/**
* Notifies the tapeserverd daemon that a label session has encountered the
......
......@@ -80,12 +80,28 @@ void castor::messages::TapeserverProxyDummy::tapeUnmounted(
}
//------------------------------------------------------------------------------
// tapeUnmounted
// notifyHeartbeat
//------------------------------------------------------------------------------
void castor::messages::TapeserverProxyDummy::
notifyHeartbeat(const std::string &unitName, const uint64_t nbBlocksMoved) {
}
//------------------------------------------------------------------------------
// addLogParams
//------------------------------------------------------------------------------
void castor::messages::TapeserverProxyDummy::
addLogParams(const std::string &unitName,
const std::list<castor::log::Param> & params) {
}
//------------------------------------------------------------------------------
// deleteLogParans
//------------------------------------------------------------------------------
void castor::messages::TapeserverProxyDummy::
deleteLogParams(const std::string &unitName,
const std::list<std::string> & paramNames) {
}
//------------------------------------------------------------------------------
// labelError
//------------------------------------------------------------------------------
......
......@@ -123,7 +123,21 @@ public:
*/
void notifyHeartbeat(const std::string &unitName,
const uint64_t nbBlocksMoved);
/**
* Sends a new set of parameters, to be logged by the mother process when the
* transfer session is over.
* @param params: a vector of log parameters
*/
virtual void addLogParams(const std::string &unitName,
const std::list<castor::log::Param> & params);
/**
* Sends a list of parameters to remove from the end of session logging.
*/
virtual void deleteLogParams(const std::string &unitName,
const std::list<std::string> & paramNames);
/**
* Notifies the tapeserverd daemon that a label session has encountered the
* specified error.
......
......@@ -35,6 +35,8 @@
#include "castor/messages/TapeserverProxyZmq.hpp"
#include "castor/messages/TapeUnmounted.pb.h"
#include "castor/messages/TapeUnmountStarted.pb.h"
#include "castor/messages/AddLogParams.pb.h"
#include "castor/messages/DeleteLogParams.pb.h"
#include "castor/server/MutexLocker.hpp"
//------------------------------------------------------------------------------
......@@ -550,6 +552,130 @@ castor::messages::Frame castor::messages::TapeserverProxyZmq::
}
}
//-----------------------------------------------------------------------------
// addLogParams
//-----------------------------------------------------------------------------
void castor::messages::TapeserverProxyZmq::addLogParams(
const std::string &unitName,
const std::list<castor::log::Param> & params) {
server::MutexLocker lock(&m_mutex);
try {
const Frame rqst = createAddLogParamsFrame(unitName, params);
sendFrame(m_serverSocket, rqst);
ReturnValue reply;
recvTapeReplyOrEx(m_serverSocket, reply);
if(0 != reply.value()) {
// Should never get here
castor::exception::Exception ex;
ex.getMessage() << "Received an unexpected return value"
": expected=0 actual=" << reply.value();
throw ex;
}
} catch(castor::exception::Exception &ne) {
castor::exception::Exception ex;
ex.getMessage() <<
"Failed to send tapeserver addLogParams: " <<
"unitName=" << unitName << ": " <<
ne.getMessage().str();
throw ex;
}
}
//------------------------------------------------------------------------------
// createAddLogParamsFrame
//------------------------------------------------------------------------------
castor::messages::Frame castor::messages::TapeserverProxyZmq::
createAddLogParamsFrame(const std::string &unitName,
const std::list<castor::log::Param> & params) {
try {
Frame frame;
frame.header = messages::protoTapePreFillHeader();
frame.header.set_msgtype(messages::MSG_TYPE_ADDLOGPARAMS);
frame.header.set_bodysignature("PIPO");
AddLogParams body;
body.set_unitname(unitName);
for(std::list<castor::log::Param>::const_iterator i=params.begin();
i!=params.end(); i++) {
LogParam * lp = body.add_params();
lp->set_name(i->getName());
lp->set_value(i->getValue());
}
frame.serializeProtocolBufferIntoBody(body);
return frame;
} catch(castor::exception::Exception &ne) {
castor::exception::Exception ex;
ex.getMessage() << "Failed to create AddLogParams frame: " <<
ne.getMessage().str();
throw ex;
}
}
//-----------------------------------------------------------------------------
// deleteLogParams
//-----------------------------------------------------------------------------
void castor::messages::TapeserverProxyZmq::deleteLogParams(
const std::string &unitName,
const std::list<std::string> & paramNames) {
server::MutexLocker lock(&m_mutex);
try {
const Frame rqst = createDeleteLogParamsFrame(unitName, paramNames);
sendFrame(m_serverSocket, rqst);
ReturnValue reply;
recvTapeReplyOrEx(m_serverSocket, reply);
if(0 != reply.value()) {
// Should never get here
castor::exception::Exception ex;
ex.getMessage() << "Received an unexpected return value"
": expected=0 actual=" << reply.value();
throw ex;
}
} catch(castor::exception::Exception &ne) {
castor::exception::Exception ex;
ex.getMessage() <<
"Failed to send tapeserver deleteLogParams: " <<
"unitName=" << unitName << ": " <<
ne.getMessage().str();
throw ex;
}
}
//------------------------------------------------------------------------------
// createAddLogParamsFrame
//------------------------------------------------------------------------------
castor::messages::Frame castor::messages::TapeserverProxyZmq::
createDeleteLogParamsFrame(const std::string &unitName,
const std::list<std::string> & paramNames) {
try {
Frame frame;
frame.header = messages::protoTapePreFillHeader();
frame.header.set_msgtype(messages::MSG_TYPE_DELETELOGPARAMS);
frame.header.set_bodysignature("PIPO");
DeleteLogParams body;
body.set_unitname(unitName);
for(std::list<std::string>::const_iterator i=paramNames.begin();
i!=paramNames.end(); i++) {
body.add_param_names(*i);
}
frame.serializeProtocolBufferIntoBody(body);
return frame;
} catch(castor::exception::Exception &ne) {
castor::exception::Exception ex;
ex.getMessage() << "Failed to create DeleteLogParams frame: " <<
ne.getMessage().str();
throw ex;
}
}
//------------------------------------------------------------------------------
// labelError
//------------------------------------------------------------------------------
......
......@@ -128,7 +128,6 @@ public:
void tapeUnmounted(const std::string &vid,
const std::string &unitName);
void notifyHeartbeat(const uint64_t nbOfMemblocksMoved);
/**
* Notifies the tapeserverd daemon that the data-transfer session is still
* alive and gives an indication of how much data has been moved.
......@@ -139,7 +138,21 @@ public:
*/
void notifyHeartbeat(const std::string &unitName,
const uint64_t nbBlocksMoved);
/**
* Sends a new set of parameters, to be logged by the mother process when the
* transfer session is over.
* @param params: a vector of log parameters
*/
virtual void addLogParams(const std::string &unitName,
const std::list<castor::log::Param> & params);
/**
* Sends a list of parameters to remove from the end of session logging.
*/
virtual void deleteLogParams(const std::string &unitName,
const std::list<std::string> & paramNames);
/**
* Notifies the tapeserverd daemon that a label session has encountered the
* specified error.
......@@ -268,7 +281,28 @@ private:
*/
Frame createHeartbeatFrame(const std::string &unitName,
const uint64_t nbBlocksMoved);
/**
* Creates a frame containing an add log params.
*
* @param unitName The unit name of the tape drive.
* @param params Values of the log parameters to be added or overwritten
* in the status that the session will have in the main process's logs.
* @return The frame.
*/
Frame createAddLogParamsFrame(const std::string &unitName,
const std::list<castor::log::Param> & params);
/**
* Creates a frame containing a delete log params.
*
* @param unitName The unit name of the tape drive.
* @param paramNames names of the log parameters to remove
* @return The frame.
*/
Frame createDeleteLogParamsFrame(const std::string &unitName,
const std::list<std::string> & paramNames);
/**
* Creates a frame containing a LabelError message.
*
......
......@@ -95,7 +95,19 @@ castor::tape::tapeserver::daemon::CatalogueTransferSession::
m_hostName(hostName),
m_waitJobTimeoutInSecs(waitJobTimeoutInSecs),
m_mountTimeoutInSecs(mountTimeoutInSecs),
m_blockMoveTimeoutInSecs(blockMoveTimeoutInSecs) {
m_blockMoveTimeoutInSecs(blockMoveTimeoutInSecs),
m_sessionLogContext(log)
{
// Record immediately the parameters from the vdqm request for the end of
// session logs.
typedef castor::log::Param Param;
m_sessionLogContext.pushOrReplace(Param("volReqId", m_vdqmJob.volReqId));
m_sessionLogContext.pushOrReplace(Param("dgn", m_vdqmJob.dgn));
m_sessionLogContext.pushOrReplace(Param("driveUnit", m_vdqmJob.driveUnit));
m_sessionLogContext.pushOrReplace(Param("clientHost", m_vdqmJob.clientHost));
m_sessionLogContext.pushOrReplace(Param("clientPort", m_vdqmJob.clientPort));
m_sessionLogContext.pushOrReplace(Param("clientEuid", m_vdqmJob.clientEuid));
m_sessionLogContext.pushOrReplace(Param("clientEgid", m_vdqmJob.clientEgid));
}
//------------------------------------------------------------------------------
......@@ -217,6 +229,8 @@ bool castor::tape::tapeserver::daemon::CatalogueTransferSession::
//------------------------------------------------------------------------------
void castor::tape::tapeserver::daemon::CatalogueTransferSession::
sessionSucceeded() {
m_sessionLogContext.pushOrReplace(log::Param("status","success"));
m_sessionLogContext.log(LOG_INFO, "Tape session finished");
}
//------------------------------------------------------------------------------
......@@ -224,6 +238,8 @@ void castor::tape::tapeserver::daemon::CatalogueTransferSession::
//------------------------------------------------------------------------------
void castor::tape::tapeserver::daemon::CatalogueTransferSession::
sessionFailed() {
m_sessionLogContext.pushOrReplace(log::Param("status","failed"));
m_sessionLogContext.log(LOG_INFO, "Tape session finished");
}
//------------------------------------------------------------------------------
......@@ -562,3 +578,19 @@ void castor::tape::tapeserver::daemon::CatalogueTransferSession::
m_lastTimeSomeBlocksWereMoved = time(0);
}
}
//-----------------------------------------------------------------------------
// addLogParam
//-----------------------------------------------------------------------------
void castor::tape::tapeserver::daemon::CatalogueTransferSession::
addLogParam(const log::Param & param) {
m_sessionLogContext.pushOrReplace(param);
}
//-----------------------------------------------------------------------------
// deleteLogParam
//-----------------------------------------------------------------------------
void castor::tape::tapeserver::daemon::CatalogueTransferSession::
deleteLogParam(const std::string & paramName) {
m_sessionLogContext.erase(paramName);
}
......@@ -215,6 +215,22 @@ public:
* since the last heartbeat message.
*/
void receivedHeartbeat(const uint64_t nbBlocksMoved);
/**
* Adds or updates in the catalogue entry log parameters relevant to the session.
*
* @param param Log parameter to add to the log context used at the end of the
* session.
*/
void addLogParam(const log::Param & param);
/**
* deletes from the catalogue entry log parameters relevant to the session.
*
* @param param Log parameter to delete from the log context used at the end
* of the session.
*/
void deleteLogParam(const std::string & paramName);
protected:
......@@ -345,6 +361,13 @@ private:
* move data blocks.
*/
const time_t m_blockMoveTimeoutInSecs;
/**
* The context that will be used to log the end of session. Parameters will
* be updated regularly by the session process, so we get a good picture
* of the session's state even after a crash.
*/
log::LogContext m_sessionLogContext;
/**
* Handles a tick in time whilst in the TRANSFERSTATE_WAIT_JOB state. Time
......
......@@ -197,7 +197,7 @@ castor::tape::tapeserver::daemon::Session::EndOfSessionAction
if (tapegateway::READ_TP == m_volInfo.clientType) {
rrp.disableBulk();
}
RecallWatchDog rwd(2,60*10,m_intialProcess,m_driveConfig.unitName,lc);
RecallWatchDog rwd(15,60*10,m_intialProcess,m_driveConfig.unitName,lc);
RecallMemoryManager mm(m_castorConf.nbBufs, m_castorConf.bufsz,lc);
TapeServerReporter tsr(m_intialProcess, m_driveConfig,
......@@ -289,7 +289,7 @@ castor::tape::tapeserver::daemon::Session::EndOfSessionAction
m_castorConf.bufsz,lc);
MigrationReportPacker mrp(m_clientProxy,
lc);
MigrationWatchDog mwd(2,60*10,m_intialProcess,m_driveConfig.unitName,lc);
MigrationWatchDog mwd(15,60*10,m_intialProcess,m_driveConfig.unitName,lc);
TapeWriteSingleThread twst(*drive.get(),
m_mc,
tsr,
......
......@@ -55,7 +55,8 @@ bool DiskWriteTask::execute(RecallReportPacker& reporter,log::LogContext& lc,
// after getting a first correct memory block.
std::auto_ptr<tape::diskFile::WriteFile> writeFile;
log::ScopedParamContainer URLcontext(lc);
URLcontext.add("path", m_recallingFile->path());
URLcontext.add("",m_recallingFile->fileid())
.add("path", m_recallingFile->path());
int blockId = 0;
unsigned long checksum = Payload::zeroAdler32();
......
......@@ -35,6 +35,8 @@
#include "castor/messages/TapeMountedForRecall.pb.h"
#include "castor/messages/TapeUnmounted.pb.h"
#include "castor/messages/TapeUnmountStarted.pb.h"
#include "castor/messages/AddLogParams.pb.h"
#include "castor/messages/DeleteLogParams.pb.h"
#include "castor/tape/tapeserver/daemon/Constants.hpp"
#include "castor/tape/tapeserver/daemon/TapeMessageHandler.hpp"
#include "castor/tape/utils/utils.hpp"
......@@ -217,6 +219,12 @@ castor::messages::Frame castor::tape::tapeserver::daemon::TapeMessageHandler::
case messages::MSG_TYPE_TAPEUNMOUNTED: