Commit 620a1952 authored by Paal Kvamme's avatar Paal Kvamme
Browse files

Rename some logging functions that got confusing after recent changes - step 1.

parent e358019c
......@@ -187,11 +187,8 @@ public:
// The raw SDGenericDataset is needed by SeismicStoreFileDelayedWrite
// when opening a file for update.
std::shared_ptr<SDGenericDatasetWrapper> datasetwrapper() const {return _dataset;}
// TODO-Low per-instance logging. This is tedious to implement
// because many of the helper classes will need to hold a logger
// instance as well, or need the logger passed in each call.
bool _logger(int priority, const std::string& message = std::string()) const;
bool _logger(int priority, const std::ios& ss) const;
bool _mylogger(int priority, const std::string& message) const;
bool _sslogger(int priority, const std::ios& ss) const;
private:
/**
* This class is used by _split_by_segment to describe a request as seen by
......@@ -229,7 +226,7 @@ private:
// The downside is that it gets more tedious to maintain.
std::shared_ptr<OpenZGY::SeismicStoreIOContext> _config;
std::shared_ptr<SDGenericDatasetWrapper> _dataset;
LoggerFn _loggerfn;
LoggerFn _logger;
// As long as we don't inherit FileCommon we need our own timers.
std::shared_ptr<SummaryPrintingTimerEx> _rtimer; // Access is thread safe
std::shared_ptr<SummaryPrintingTimerEx> _wtimer; // Access is thread safe
......@@ -359,7 +356,7 @@ private:
std::int64_t last_block_size_;
// For debugging
SeismicStoreFile::LoggerFn loggerfn_;
SeismicStoreFile::LoggerFn logger_;
public:
explicit DatasetInformation(const SeismicStoreFile::LoggerFn& logger);
......@@ -385,7 +382,7 @@ DatasetInformation::DatasetInformation(const SeismicStoreFile::LoggerFn& logger)
, block0_size_(0)
, block1_size_(0)
, last_block_size_(0)
, loggerfn_(logger ? logger : LoggerBase::emptyCallback())
, logger_(logger ? logger : LoggerBase::emptyCallback())
{
}
......@@ -398,7 +395,7 @@ DatasetInformation::DatasetInformation(seismicdrive::SDGenericDataset* sdgd, con
, block0_size_(0)
, block1_size_(0)
, last_block_size_(0)
, loggerfn_(logger ? logger : LoggerBase::emptyCallback())
, logger_(logger ? logger : LoggerBase::emptyCallback())
{
// Note that sdapi is a bit confusing with respect to signed/unsigned.
// getBlockNum() returns an unsigned (uint64_t).
......@@ -449,10 +446,10 @@ DatasetInformation::DatasetInformation(seismicdrive::SDGenericDataset* sdgd, con
// But the problem *could* be that the block sizes of all the middle blocks
// is not the same. Which would be a real problem.
if (nbytes >= 0 && nbytes != (long long)totalSize())
this->loggerfn_(0, "Dataset has inconsistent size");
this->logger_(0, "Dataset has inconsistent size");
if (this->loggerfn_(1, ""))
this->loggerfn_(1, toString());
if (this->logger_(1, ""))
this->logger_(1, toString());
}
std::string
......@@ -623,7 +620,7 @@ DatasetInformation::getLocalOffset(std::int64_t offset, std::int64_t size, std::
else if (size > std::numeric_limits<std::int64_t>::max() - offset)
throw OpenZGY::Errors::ZgyInternalError("Overflow in offset + size.");
else if (offset + size > totalSize()) {
if (this->loggerfn_(1, "")) {
if (this->logger_(1, "")) {
std::stringstream ss;
ss << "Reading past EOF: read("
<< "off=" << offset
......@@ -631,7 +628,7 @@ DatasetInformation::getLocalOffset(std::int64_t offset, std::int64_t size, std::
<< ", end=" << offset+size
<< ") dataset: " << toString()
<< std::endl;
this->loggerfn_(1, ss.str());
this->logger_(1, ss.str());
}
throw OpenZGY::Errors::ZgyInternalError("Reading past EOF");
}
......@@ -720,7 +717,7 @@ class SDGenericDatasetWrapper
std::shared_ptr<const DatasetInformation> info_;
OpenMode disposition_;
bool virgin_; // If true, the cached CTag should be ok.
SeismicStoreFile::LoggerFn loggerfn_;
SeismicStoreFile::LoggerFn logger_;
mutable std::mutex mutex_; // Protect all members.
std::string saved_token_; // To avoid setting it again.
std::string saved_tokentype_;
......@@ -735,7 +732,7 @@ public:
OpenMode disp,
const SeismicStoreFile::LoggerFn& logger)
: manager_(manager), dataset_(dataset), disposition_(disp), virgin_(true)
, loggerfn_(logger ? logger : LoggerBase::emptyCallback())
, logger_(logger ? logger : LoggerBase::emptyCallback())
, mutex_()
, saved_token_(), saved_tokentype_()
, tokenrefresh_(), tokenrefreshtype_()
......@@ -762,11 +759,11 @@ public:
try {
switch (disposition_) {
case OpenMode::Truncate:
info_.reset(new DatasetInformation(loggerfn_));
info_.reset(new DatasetInformation(logger_));
break;
case OpenMode::ReadOnly:
case OpenMode::ReadWrite:
info_.reset(new DatasetInformation(dataset_.get(), loggerfn_));
info_.reset(new DatasetInformation(dataset_.get(), logger_));
break;
case OpenMode::Closed:
default:
......@@ -856,11 +853,11 @@ public:
* it will be re-thrown without modification.
*/
void throwCloudException(const std::exception& ex, const char *message) {
if (this->loggerfn_(1, "")) {
if (this->logger_(1, "")) {
std::stringstream ss;
ss << "Oops (" << message << ")" << " ("
<< tokenmessage_ << "): " << ex.what();
this->loggerfn_(1, ss.str());
this->logger_(1, ss.str());
}
if (dynamic_cast<const OpenZGY::Errors::ZgyError*>(&ex))
throw;
......@@ -998,9 +995,9 @@ public:
saved_token_ = newtoken;
saved_tokentype_ = newtokentype;
if (newtoken.empty())
this->loggerfn_(1, "The token was cleared");
this->logger_(1, "The token was cleared");
else
this->loggerfn_(1, "A new token was provided");
this->logger_(1, "A new token was provided");
}
}
}
......@@ -1028,13 +1025,13 @@ public:
policy.maxWaitingTimeMicroSec = 32 * 1000 * 1000;
}
dataset_->setExponentialRetryBackoffPolicy(&policy);
if (this->loggerfn_(2, "")) {
if (this->logger_(2, "")) {
std::stringstream ss;
ss << "Backoff " << (policy.enabled ? "enabled" : "disabled")
<< " retries " << policy.maxRetry
<< " start " << (float)policy.initialWaitingTimeMicroSec*1.0e-6
<< " max " << (float)policy.maxWaitingTimeMicroSec*1.0e-6;
this->loggerfn_(2, ss.str());
this->logger_(2, ss.str());
}
}
}
......@@ -1052,14 +1049,14 @@ SDGenericDatasetWrapper::~SDGenericDatasetWrapper()
}
catch (const std::exception& ex) {
if (std::string(ex.what()).find("dataset is not open") == std::string::npos)
this->loggerfn_(0, "SDGenericDataset::close(): " + std::string(ex.what()));
this->logger_(0, "SDGenericDataset::close(): " + std::string(ex.what()));
}
try {
// Catch exceptions raised inside a destructor might not work. But I tried.
dataset_.reset();
}
catch (const std::exception& ex) {
this->loggerfn_(0, "SDGenericDataset::dtor(): " + std::string(ex.what()));
this->logger_(0, "SDGenericDataset::dtor(): " + std::string(ex.what()));
}
manager_.reset();
}
......@@ -1082,18 +1079,19 @@ SeismicStoreFile::SeismicStoreFile(const std::string& filename, OpenMode mode, c
, _config()
{
auto context = dynamic_cast<const OpenZGY::SeismicStoreIOContext*>(iocontext);
_loggerfn = ((context && context->_logger) ? context->_logger :
LoggerBase::standardCallback
(LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"),
"openzgy-cloud: ", ""));
_logger = ((context && context->_logger) ? context->_logger :
LoggerBase::standardCallback
(LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"),
"openzgy-cloud: ", ""));
if (!context)
throw OpenZGY::Errors::ZgyUserError("Opening a file from seismic store requires a SeismicStoreIOContext");
this->_config.reset(new OpenZGY::SeismicStoreIOContext(*context));
_rtimer.reset(new SummaryPrintingTimerEx(mode == OpenMode::ReadWrite || mode == OpenMode::Truncate ? "Cloud.reread" : "Cloud.read"));
_wtimer.reset(new SummaryPrintingTimerEx("Cloud.write"));
_logger(3, std::stringstream() << "SeismicStoreFile("
<< "\"" << filename << "\", " << int(mode) << ", *)\n");
if (_logger(3, ""))
_sslogger(3, std::stringstream() << "SeismicStoreFile("
<< "\"" << filename << "\", " << int(mode) << ", *)\n");
std::unordered_map<std::string, std::string> extra;
using seismicdrive::api::json::Constants;
......@@ -1113,9 +1111,10 @@ SeismicStoreFile::SeismicStoreFile(const std::string& filename, OpenMode mode, c
manager->setLogStatus(sd_mgr_log);
std::shared_ptr<seismicdrive::SDGenericDataset> dataset;
if (mode != OpenMode::Closed) {
_logger(5, std::stringstream()
<< "make dataset using manager "
<< std::hex << (std::uint64_t)manager.get());
if (_logger(5, ""))
_sslogger(5, std::stringstream()
<< "make dataset using manager "
<< std::hex << (std::uint64_t)manager.get());
dataset = std::make_shared<seismicdrive::SDGenericDataset>
(manager.get(), filename, sd_ds_log);
_logger(5, "dataset ok");
......@@ -1124,7 +1123,7 @@ SeismicStoreFile::SeismicStoreFile(const std::string& filename, OpenMode mode, c
// TODO-Low: Cache the manager and possibly the SDUtils instance.
auto datasetwrapper = std::make_shared<SDGenericDatasetWrapper>
(manager, dataset, mode, _loggerfn);
(manager, dataset, mode, _logger);
datasetwrapper->authorizeManager
(context->_sdtoken, context->_sdtokentype,
......@@ -1182,36 +1181,30 @@ SeismicStoreFile::~SeismicStoreFile()
}
/**
* Convenience for invoking _loggerfn with a simple message.
* This isn't much different from invoking the callback directly.
* But it makes debugging slightly simpler to have an easy place
* to set a breakpoint. It also adds more symmetry with respect
* to the stringstream version, which does add value.
*
* Thread safety: Yes, because the global _loggerfn can only be set
* while the very first instance is being constructed.
* Convenience for invoking _logger with a simple message. Useful for
* logging from outside this class, e.g. in the delayed-write class.
*/
bool
SeismicStoreFile::_logger(int priority, const std::string& message) const
SeismicStoreFile::_mylogger(int priority, const std::string& message) const
{
return _loggerfn(priority, message);
return _logger(priority, message);
}
/**
* Convenience for invoking _loggerfn with a stringstream.
* Convenience for invoking _logger with a stringstream.
* Due to a somewhat naughty cast, the function can be caller as:
*
* if(_logger(pr1))
* _logger(pri, std::stringstream() << some << data << here);
* _sslogger(pri, std::stringstream() << some << data << here);
*
* The first line is optional. It just prevents the expression in
* the second line from being evaluatet if debugging is disabled.
*
* Thread safety: Yes, because the global _loggerfn can only be set
* Thread safety: Yes, because the global _logger can only be set
* while the very first instance is being constructed.
*/
bool
SeismicStoreFile::_logger(int priority, const std::ios& ss) const
SeismicStoreFile::_sslogger(int priority, const std::ios& ss) const
{
auto sstream = dynamic_cast<const std::stringstream*>(&ss);
return _logger(priority, sstream ? sstream->str() : std::string());
......@@ -1430,12 +1423,12 @@ SeismicStoreFile::xx_write(const void* data, std::int64_t offset, std::int64_t s
this->_dataset->reAuthorizeManager();
std::int64_t current_eof = SeismicStoreFile::xx_eof(); // MUST be nonvirtual
if (_logger(5, ""))
_logger(5, std::stringstream()
<< "SeismicStoreFile.xx_write("
<< "offset=" << offset
<< ", size=" << size
<< ", current EOF is " << current_eof
<< ")\n");
_sslogger(5, std::stringstream()
<< "SeismicStoreFile.xx_write("
<< "offset=" << offset
<< ", size=" << size
<< ", current EOF is " << current_eof
<< ")\n");
std::int64_t blocknum{0}, local_offset{0}, local_size{0};
bool overwrite{false};
if (offset == current_eof) {
......@@ -1513,9 +1506,9 @@ SeismicStoreFile::do_write_one(
const bool overwrite)
{
if (_logger(1, "")) {
_logger(1, std::stringstream()
<< "do_write_one(*, " << blocknum << ", " << size << ", "
<< std::boolalpha << overwrite << ")");
_sslogger(1, std::stringstream()
<< "do_write_one(*, " << blocknum << ", " << size << ", "
<< std::boolalpha << overwrite << ")");
}
this->_dataset->info()->checkOnWrite(blocknum, size);
this->_dataset->dataset()->writeBlock
......@@ -1587,13 +1580,13 @@ SeismicStoreFile::do_write_many(
#pragma omp parallel for num_threads(blobcount)
for (int ii = 0; ii < blobcount; ++ii) {
if (/*blocknum == 1 &&*/ ii == 0 && _logger(1, "")) {
_logger(1, std::stringstream()
<< "do_write_many(*, "
<< blocknum << ".." << (blocknum + blobcount - 1) << ", "
<< size << ", "
<< blobsize << ", "
<< std::boolalpha << overwrite << ")"
<< " using " << omp_get_num_threads() << " threads");
_sslogger(1, std::stringstream()
<< "do_write_many(*, "
<< blocknum << ".." << (blocknum + blobcount - 1) << ", "
<< size << ", "
<< blobsize << ", "
<< std::boolalpha << overwrite << ")"
<< " using " << omp_get_num_threads() << " threads");
}
guard.run([&](){
const int iter_blocknum = ii + static_cast<int>(blocknum);
......@@ -1659,9 +1652,9 @@ SeismicStoreFile::xx_close()
// Maybe we didn't need credentials just to close.
// So just log and swallow this one.
if (_logger(0, ""))
_logger(0, std::stringstream()
<< "Ignoring exception during close: "
<< ex.what());
_sslogger(0, std::stringstream()
<< "Ignoring exception during close: "
<< ex.what());
}
victim->close();
}
......@@ -1728,11 +1721,12 @@ SeismicStoreFile::xx_iscloud() const
void
SeismicStoreFile::deleteFile(const std::string& filename, bool missing_ok) const
{
_logger(2, std::stringstream()
<< "SeismicStoreFile::deleteFile("
<< "\"" << filename << "\", "
<< "missing_ok=" << std::boolalpha << missing_ok
<< ")\n");
if (_logger(2, ""))
_sslogger(2, std::stringstream()
<< "SeismicStoreFile::deleteFile("
<< "\"" << filename << "\", "
<< "missing_ok=" << std::boolalpha << missing_ok
<< ")\n");
// Make sure the returned smart pointer doesn't go out of scope.
std::shared_ptr<seismicdrive::SDManager> smart_manager = _dataset->manager();
seismicdrive::SDUtils utils(smart_manager.get());
......@@ -1740,10 +1734,11 @@ SeismicStoreFile::deleteFile(const std::string& filename, bool missing_ok) const
utils.deleteDataset(filename);
}
catch (const std::exception& ex) {
if (std::string(ex.what()).find("does not exist") != std::string::npos) {
this->_logger(1, std::stringstream()
<< "Deleting already deleted"
<< " \"" << filename << "\"\n");
if (std::string(ex.what()).find("does not exist") != std::string::npos) {
if (_logger(1, ""))
_sslogger(1, std::stringstream()
<< "Deleting already deleted"
<< " \"" << filename << "\"\n");
if (!missing_ok)
_dataset->throwCloudException(ex, "Delete");
}
......@@ -1780,12 +1775,13 @@ SeismicStoreFile::altUrl(const std::string& filename) const
throw;
_logger(0, "getSerializedContext() caused bogus exception for wid "+ wid + ": " + std::string(ex.what()));
}
_logger(2, std::stringstream()
<< "SeismicStoreFile::altUrl(\""
<< (filename.size() < 76 ? filename : filename.substr(0, 72) + "...")
<< "\")"
<< " = \"" << "REDACTED"/*url*/ << "\"" // Don't log secrets!
<< "\n");
if (_logger(2, ""))
_sslogger(2, std::stringstream()
<< "SeismicStoreFile::altUrl(\""
<< (filename.size() < 76 ? filename : filename.substr(0, 72) + "...")
<< "\")"
<< " = \"" << "REDACTED"/*url*/ << "\"" // Don't log secrets!
<< "\n");
return url;
}
catch (const std::exception& ex) {
......@@ -1889,7 +1885,7 @@ SeismicStoreFileDelayedWrite::~SeismicStoreFileDelayedWrite()
// The calling layer is supposed to do an explicit xx_close()
// so it can catch and handle exceptions. This blind catch is
// just a desperate attempt to avoid an application crash.
_relay->_logger(0, "EXCEPTION flushing file: " + std::string(ex.what()));
_relay->_mylogger(0, "EXCEPTION flushing file: " + std::string(ex.what()));
}
// Note: The dataset itself will be closed in _relay's destructor.
// That should happen very shortly.
......@@ -2021,8 +2017,8 @@ SeismicStoreFileDelayedWrite::xx_write(const void* data, std::int64_t offset, st
const std::int64_t written = this->xx_eof();
const std::int64_t committed = this->_relay->xx_eof();
if (_relay->_logger(5, ""))
_relay->_logger(5, std::stringstream()
if (_relay->_mylogger(5, ""))
_relay->_sslogger(5, std::stringstream()
<< "SeismicStoreFileDelayedWrite.xx_write("
<< "offset=" << offset
<< ", size=" << size
......@@ -2043,11 +2039,11 @@ SeismicStoreFileDelayedWrite::xx_write(const void* data, std::int64_t offset, st
// TODO-Low: If caller doesn't catch ZgySegmentIsClosed then the memory
// buffer should also be off limits to avoid heissenbugs. But as of today
// the exception is always caught and handled so this might be academic.
if (_relay->_logger(1, ""))
_relay->_logger(1, std::stringstream() << std::hex
<< "Cannot write at 0x" << offset
<< " because data up to 0x" << committed
<< " has already been flushed to the cloud\n");
if (_relay->_mylogger(1, ""))
_relay->_sslogger(1, std::stringstream() << std::hex
<< "Cannot write at 0x" << offset
<< " because data up to 0x" << committed
<< " has already been flushed to the cloud\n");
throw OpenZGY::Errors::ZgySegmentIsClosed("Block has already been flushed.");
}
......@@ -2069,8 +2065,8 @@ SeismicStoreFileDelayedWrite::xx_write(const void* data, std::int64_t offset, st
// ZGY is our only client and does in fact catch that exception then
// this is low priority to change.
if (offset != written) {
if (_relay->_logger(1, ""))
_relay->_logger(1, std::stringstream()
if (_relay->_mylogger(1, ""))
_relay->_sslogger(1, std::stringstream()
<< "Write at " << offset << " which is neither 0 nor EOF"
<< " when EOF is " << this->xx_eof()
<< ". Also, size is " << size
......@@ -2289,11 +2285,11 @@ SeismicStoreFileDelayedWrite::_flush(bool final_call)
{
if (this->_config->_segsize > 0)
while (this->_open_segment.size() >= static_cast<std::uint64_t>(this->_config->_segsize)) {
_relay->_logger(2, "_flush " + std::to_string(this->_config->_segsize) + " bytes\n");
_relay->_mylogger(2, "_flush " + std::to_string(this->_config->_segsize) + " bytes\n");
this->_flush_part(this->_config->_segsize);
}
if (final_call && this->_open_segment.size() > 0) {
_relay->_logger(2, "_final " + std::to_string(this->_open_segment.size()) + " bytes\n");
_relay->_mylogger(2, "_final " + std::to_string(this->_open_segment.size()) + " bytes\n");
this->_flush_part(this->_open_segment.size());
}
if (this->_open_segment.size() == 0)
......
Markdown is supported
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