Commit 92aadc59 authored by Paal Kvamme's avatar Paal Kvamme
Browse files

Merge branch 'kvamme62/verbose-logging' into 'master'

Logging to file, etc.

See merge request !87
parents c582821c a141c4b0
Pipeline #55468 passed with stages
in 12 minutes and 50 seconds
......@@ -29,6 +29,9 @@
#include "impl/genlod.h"
#include "impl/compression.h"
#include "impl/guid.h"
#include "impl/logger.h"
#include <tuple>
#ifdef _MSC_VER
#pragma warning(push)
......@@ -68,6 +71,41 @@ namespace {
}
}
namespace {
/**
* Attach a logger. Used by the ZgyReader and ZgyWriter constructors.
*
* If the iocontext belongs to seismic store and if it has a logger
* set then use that logger also for the higher level ZgyInteralMeta
* and ZgyInternalBulk instances. And the other was around: If a
* logger is created here, and a seismic store iocontext exists
* without a logger, then use the iocontext to push the logger down
* to the low level code.
*
* TODO-Medium: Bad code smell. The iocontext is supposed to be
* populated by the application code only, and used by the file
* layer only.
*/
std::tuple<std::function<bool(int, const std::string&)>, std::shared_ptr<OpenZGY::IOContext>> setupLogging(const OpenZGY::IOContext *iocontext)
{
std::function<bool(int, const std::string&)> logger;
std::shared_ptr<OpenZGY::IOContext> ctxt = iocontext ? iocontext->clone() : nullptr;
auto iocontext_sd = dynamic_cast<OpenZGY::SeismicStoreIOContext*>(ctxt.get());
if (iocontext_sd && iocontext_sd->getLogger()) {
logger = iocontext_sd->getLogger();
}
else {
logger = InternalZGY::LoggerBase::standardCallback
(InternalZGY::LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"),
"openzgy-api: ", "");
// logger = std::ref(logger);
if (iocontext_sd)
iocontext_sd->logger(logger);
}
return std::make_tuple(logger, ctxt);
}
}
namespace OpenZGY {
class IOContext;
}
......@@ -537,24 +575,29 @@ public:
*/
ZgyReader(const std::string& filename, const IOContext* iocontext)
{
std::function<bool(int, const std::string&)> logger;
std::shared_ptr<IOContext> ctxt;
std::tie(logger, ctxt) = setupLogging(iocontext);
logger(1, "open for read: \"" + filename + "\"");
// Note: Currently the Python version of this constructor has an
// additional "update" parameter which, if set, causes the underlying
// file to be opened in read/write mode. This is a kludge to facilitate
// a stand alone lowres generator. Which was only ever used for testing.
_fd = InternalZGY::FileFactory::instance().create(
filename, InternalZGY::OpenMode::ReadOnly, iocontext);
filename, InternalZGY::OpenMode::ReadOnly, ctxt.get());
// Set the protected metadata information in the ZgyMeta base class.
// ZgyInternalMeta does not retain the file descriptor. The file is
// only used inside the constructor to populate the headers.
_meta.reset(new InternalZGY::ZgyInternalMeta(this->_fd));
_meta.reset(new InternalZGY::ZgyInternalMeta(this->_fd, logger));
// At the implementation level the bulk- and meta access are separate,
// and the bulk accessor needs some of the meta information to work.
// The accessor will have its own metadata pointer which it holds on to.
// It also holds on to the file descriptor. Unlike the metadata reader
// it is obviously not possible to read everything up front.
_accessor.reset(new InternalZGY::ZgyInternalBulk(_fd, _meta, nullptr, false));
_accessor.reset(new InternalZGY::ZgyInternalBulk(_fd, _meta, nullptr, false, logger));
}
~ZgyReader()
......@@ -788,6 +831,11 @@ public:
, _compressor(args._compressor)
, _lodcompressor(args._lodcompressor ? args._lodcompressor : args._compressor)
{
std::function<bool(int, const std::string&)> logger;
std::shared_ptr<IOContext> ctxt;
std::tie(logger, ctxt) = setupLogging(args._iocontext.get());
logger(1, "open for write: \"" + args._filename + "\"");
for (int ii=0; ii<3; ++ii) {
if (args._size[ii] < 1)
throw Errors::ZgyUserError("Survey size cannot be empty or negative.");
......@@ -805,16 +853,16 @@ public:
// we need to hold on to _fd ourselves and provide it when it is time
// to flush metadata to disk.
InternalZGY::ZgyInternalWriterArgs iargs = EnumMapper::mapWriterArgs(args);
_meta_rw.reset(new InternalZGY::ZgyInternalMeta(iargs, compress));
_meta_rw.reset(new InternalZGY::ZgyInternalMeta(iargs, compress, logger));
_meta = _meta_rw; // in base class
// The file creation was deferred until after the consistency checks.
_fd = InternalZGY::FileFactory::instance().create(
args._filename, InternalZGY::OpenMode::Truncate, args._iocontext.get());
args._filename, InternalZGY::OpenMode::Truncate, ctxt.get());
_meta_rw->flushMeta(_fd);
// Compress or not at this level only controls alignment etc.
// The actual compression functor is passed to each write.
_accessor_rw.reset(new InternalZGY::ZgyInternalBulk(_fd, _meta_rw, _meta_rw, compress));
_accessor_rw.reset(new InternalZGY::ZgyInternalBulk(_fd, _meta_rw, _meta_rw, compress, logger));
// A file that is recently created is dirty because even if nothing
// was written to it the low resolution bricks should be generated.
......@@ -841,17 +889,22 @@ public:
, _compressor(args._compressor)
, _lodcompressor(args._lodcompressor ? args._lodcompressor : args._compressor)
{
std::function<bool(int, const std::string&)> logger;
std::shared_ptr<IOContext> ctxt;
std::tie(logger, ctxt) = setupLogging(args._iocontext.get());
logger(1, "open for update: \"" + args._filename + "\"");
const bool compress = _compressor || _lodcompressor;
_fd = InternalZGY::FileFactory::instance().create(
args._filename, InternalZGY::OpenMode::ReadWrite, args._iocontext.get());
args._filename, InternalZGY::OpenMode::ReadWrite, ctxt.get());
// Set the protected metadata information in the ZgyMeta base class.
// The metadata ctor is very different on update. bulkdata is not.
// ZgyInternalMeta does not retain the file descriptor. The file is
// only used inside the constructor to populate the headers.
InternalZGY::ZgyInternalWriterArgs iargs = EnumMapper::mapWriterArgs(args);
_meta_rw.reset(new InternalZGY::ZgyInternalMeta(_fd, iargs, compress));
_meta_rw.reset(new InternalZGY::ZgyInternalMeta(_fd, iargs, compress, logger));
_meta = _meta_rw;
if (compress && _meta->ih().datatype() != InternalZGY::RawDataType::Float32)
......@@ -862,7 +915,7 @@ public:
// The accessor will have its own metadata pointer which it holds on to.
// It also holds on to the file descriptor. Unlike the metadata reader
// it is obviously not possible to read everything up front.
_accessor_rw.reset(new InternalZGY::ZgyInternalBulk(_fd, _meta_rw, _meta_rw, compress));
_accessor_rw.reset(new InternalZGY::ZgyInternalBulk(_fd, _meta_rw, _meta_rw, compress, logger));
// If low resolution data, statistics, or histogram are not
// available, mark as dirty because even if there has been no
......@@ -1660,8 +1713,13 @@ public:
*/
ZgyUtils(const std::string& prefix, const IOContext* iocontext)
{
std::function<bool(int, const std::string&)> logger;
std::shared_ptr<IOContext> ctxt;
std::tie(logger, ctxt) = setupLogging(iocontext);
logger(1, "open utility class");
_fd = InternalZGY::FileFactory::instance().create
(prefix, InternalZGY::OpenMode::Closed, iocontext);
(prefix, InternalZGY::OpenMode::Closed, ctxt.get());
// TODO-Low: Use some kind of factory here.
#ifdef HAVE_SD
_fd_sd = std::dynamic_pointer_cast<InternalZGY::FileUtilsSeismicStore>(_fd);
......
......@@ -492,7 +492,7 @@ ZgyInternalBulk::ZgyInternalBulk(
, _is_bad(false)
, _written_sample_min(std::numeric_limits<double>::infinity())
, _written_sample_max(-std::numeric_limits<double>::infinity())
, _loggerfn(logger ? logger : LoggerBase::standardCallback(LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"), "openzgy-bulk:", ""))
, _loggerfn(logger ? logger : LoggerBase::standardCallback(LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"), "openzgy-bulk: ", ""))
, _ptimer_st(new SummaryPrintingTimerEx("writeAligned[S]"))
, _ptimer_mt(new SummaryPrintingTimerEx("writeAligned[M]"))
, _ststimer(new SummaryPrintingTimerEx("scaleToStorage"))
......
This diff is collapsed.
......@@ -16,18 +16,74 @@
#include "environment.h"
#include <iostream>
#include <fstream>
#include <iomanip>
#include <mutex>
#include <atomic>
#include <memory>
#include <chrono>
namespace InternalZGY {
#if 0
}
#endif
/**
* Static class so it doesn't actually need to be attached as a pimpl.
* The methods and data is used by standardCallback().
*/
class LoggerBaseImpl
{
public:
static std::atomic<int> next_id_;
static std::mutex mutex_;
public:
static std::shared_ptr<std::ostream> getVerboseFileFromEnv(int id);
static int getVerboseDetailsFromEnv();
static double timestamp();
};
std::atomic<int> LoggerBaseImpl::next_id_{1};
std::mutex LoggerBaseImpl::mutex_{};
int
LoggerBase::getVerboseFromEnv(const char *envname)
{
return Environment::getNumericEnv(envname, 0);
}
std::shared_ptr<std::ostream>
LoggerBaseImpl::getVerboseFileFromEnv(int id)
{
std::string name = Environment::getStringEnv("OPENZGY_VERBOSE_LOGFILE");
if (!name.empty()) {
std::size_t pos = name.find("{}");
if (pos != std::string::npos)
name = name.substr(0, pos) + std::to_string(id) + name.substr(pos+2);
return std::make_shared<std::ofstream>(name, std::ofstream::app);
}
else {
return std::shared_ptr<std::ostream>(&std::cerr, [](std::ostream*){});
}
}
int
LoggerBaseImpl::getVerboseDetailsFromEnv()
{
return Environment::getNumericEnv("OPENZGY_VERBOSE_DETAILS", 0);
}
double
LoggerBaseImpl::timestamp()
{
// Remember the good old days with ::time(nullptr) ?
typedef std::chrono::high_resolution_clock clock;
static constexpr double factor =
static_cast<double>(clock::duration::period::num) /
static_cast<double>(clock::duration::period::den);
return clock::now().time_since_epoch().count() * factor;
}
/**
* Invoke the specified logger function with a string argument.
* This isn't much different from invoking the callback directly.
......@@ -77,18 +133,23 @@ LoggerBase::emptyCallback()
* Level < 0 will never show anything. Not even messages with pri < 0.
*
* Suggested use of priority levels:
* -1 => Serious errors, always show unless messages disbled completely.
* 0 => Shown during normal execution. Also in production mode.
* 1+ => For debugging and testing.
* - -1 => Serious errors, always show unless messages disbled completely.
* - 0 => Shown during normal execution. Also in production mode.
* - 1+ => For debugging and testing.
*
* By default the following environment variables are recognized:
* - OPENZGY_VERBOSE (choose how much is dumped)
* - OPENZGY_VERBOSE_LOGFILE (redirect output to a file)
* - OPENZGY_VERBOSE_DETAILS (bitmask to turn on optional features)
*
* It is the caller of standardCallback that looks up OPENZGY_VERBOSE
* and it can choose to use some other mechanism to enable or disable.
* The other two are currently local to this file and can only be set
* by these environment variables.
*
* Thread safety: May be used concurrently from different threads.
* The underlying std::cerr also allows this. There may be a visual
* issue with output from different logging statements being
* interleaved. The function tries to mitigate this by writing full
* lines at a time in the hope that only lines, not individual
* characters, might be interleaved. There is no guarantee that this
* will work. This is just a minor issue since log messages are for
* debugging only.
* Uses a global lock. The lock might be skipped is std::ios is thread
* safe, but that would technically trigger undefined behavior.
*/
LoggerBase::LoggerFn
LoggerBase::standardCallback(int currentlevel, const std::string& prefix_in, const std::string& suffix_in)
......@@ -102,15 +163,38 @@ LoggerBase::standardCallback(int currentlevel, const std::string& prefix_in, con
return test;
}
else {
std::string prefix(prefix_in); // Avoid capturing just a reference.
std::string prefix(prefix_in);
std::string suffix(suffix_in + "\n");
return [currentlevel, prefix, suffix](int pri, const std::string& msg) {
int id = LoggerBaseImpl::next_id_++;
int details = LoggerBaseImpl::getVerboseDetailsFromEnv();
std::shared_ptr<std::ostream> os =
LoggerBaseImpl::getVerboseFileFromEnv(id);
if (details & 2)
prefix = prefix + "<" + std::to_string(id) + "> ";
return [currentlevel, prefix, suffix, os, details](int pri, const std::string& msg) {
if (!msg.empty() && pri <= currentlevel) {
std::istringstream f(msg);
std::string s;
while (std::getline(f, s, '\n'))
if (!s.empty())
std::cerr << (prefix + s + suffix); // Only one <<; full lines out.
std::lock_guard<std::mutex> lk(LoggerBaseImpl::mutex_);
if (os->good()) {
while (std::getline(f, s, '\n')) {
if (!s.empty()) {
if (details & 1) {
std::stringstream ss;
ss << std::setprecision(3) << std::fixed
<< LoggerBaseImpl::timestamp() << ": ";
ss << prefix << s << suffix;
*os << ss.str();
}
else {
*os << (prefix + s + suffix);
}
}
}
// This will slow down logging to file but is safer if there
// is a crash or if logging is done from a static destructor.
*os << std::flush;
}
}
return pri <= currentlevel;
};
......
......@@ -1673,7 +1673,7 @@ public:
* Open for read
*/
ZgyInternalMeta::ZgyInternalMeta(const std::shared_ptr<FileADT>& file, const LoggerFn& logger)
: _loggerfn(logger ? logger : LoggerBase::standardCallback(LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"), "openzgy-meta:", ""))
: _loggerfn(logger ? logger : LoggerBase::standardCallback(LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"), "openzgy-meta: ", ""))
, _is_bad(false)
{
initFromOpenFile(file);
......@@ -1683,7 +1683,7 @@ ZgyInternalMeta::ZgyInternalMeta(const std::shared_ptr<FileADT>& file, const Log
* Open for write
*/
ZgyInternalMeta::ZgyInternalMeta(const ZgyInternalWriterArgs& args_in, bool compress, const LoggerFn& logger)
: _loggerfn(logger ? logger : LoggerBase::standardCallback(LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"), "openzgy-meta:", ""))
: _loggerfn(logger ? logger : LoggerBase::standardCallback(LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"), "openzgy-meta: ", ""))
, _is_bad(false)
{
initFromScratch(args_in, compress);
......@@ -1693,7 +1693,7 @@ ZgyInternalMeta::ZgyInternalMeta(const ZgyInternalWriterArgs& args_in, bool comp
* Open for update
*/
ZgyInternalMeta::ZgyInternalMeta(const std::shared_ptr<FileADT>& file, const ZgyInternalWriterArgs& args_in, bool compress, const LoggerFn& logger)
: _loggerfn(logger ? logger : LoggerBase::standardCallback(LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"), "openzgy-meta:", ""))
: _loggerfn(logger ? logger : LoggerBase::standardCallback(LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"), "openzgy-meta: ", ""))
, _is_bad(false)
{
ZgyInternalWriterArgs args = validateOpenForUpdate(args_in);
......
......@@ -93,6 +93,7 @@ class OPENZGY_API SeismicStoreIOContext : public IOContext
public:
typedef std::function<std::string()> tokencb_t;
typedef std::function<void(const std::string&, std::int64_t, std::int64_t, std::int64_t, const std::vector<std::int64_t>&)> debugtrace_t;
typedef std::function<bool(int, const std::string&)> logger_t;
virtual std::string toString() const override;
virtual std::shared_ptr<IOContext> clone() const override;
SeismicStoreIOContext();
......@@ -115,6 +116,7 @@ private:
std::string _sdtoken_cbtype;
tokencb_t _sdtokencb;
debugtrace_t _debug_trace;
logger_t _logger;
private: // really private. Keep off.
std::int64_t _real_segsize;
......@@ -451,6 +453,35 @@ public:
this->_debug_trace = value;
return *this;
}
/**
* For debugging. This callback will be invoked whenever
* something needs to be written to the console or to a file.
* See LoggerBase::standardCallback() for an example.
*
* The default is to use standardCallback() configured
* according to OPENZGY_VERBOSE, OPENZGY_VERBOSE_LOGFILE,
* and OPENZGY_VERBOSE_DETAILS.
*
* Note that it might be a good idea to use a std::ref here,
* that could avoid some surprises.
*/
SeismicStoreIOContext& logger(const logger_t& logger)
{
this->_logger = logger;
return *this;
}
/**
* Internal access to read out the current logger.
* The logger is applied to higher level parts
* of the system and needs this slight breakage
* of encapsulation.
*/
logger_t getLogger() const
{
return this->_logger;
}
};
/** \endcond */
......
......@@ -18,6 +18,7 @@
#include "test_utils.h"
#include "test_all.h"
#include "../impl/environment.h"
#include "../impl/logger.h"
#include <sstream>
#include <chrono>
......@@ -207,14 +208,21 @@ CloudFileAutoDelete::remove(const std::string& name, const OpenZGY::SeismicStore
if (ctx) {
// Using the low level delete functionality;
// I could also have used OpenZGY::IZgyUtils.
// The low level code needs a logger attached here,
// unless I am ok with the default.
OpenZGY::SeismicStoreIOContext localctx(*ctx);
localctx.logger
(InternalZGY::LoggerBase::standardCallback
(InternalZGY::LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"),
"openzgy-testutils: ", ""));
std::shared_ptr<InternalZGY::FileADT> fd = InternalZGY::FileFactory::instance().create
(name, InternalZGY::OpenMode::Closed, ctx);
(name, InternalZGY::OpenMode::Closed, &localctx);
auto fd_sd = dynamic_cast<InternalZGY::FileUtilsSeismicStore*>(fd.get());
if (fd_sd) {
fd_sd->deleteFile(name, /*missing_ok=*/true);
}
else {
throw OpenZGY::Errors::ZgyInternalError("CloudFileAutoDelete::remove founbd no FileUtils");
throw OpenZGY::Errors::ZgyInternalError("CloudFileAutoDelete::remove found no FileUtils");
}
}
else {
......@@ -281,6 +289,12 @@ default_sd_context()
using InternalZGY::Environment;
static OpenZGY::SeismicStoreIOContext instance =
OpenZGY::SeismicStoreIOContext()
// Enable to prove that logging is configurable, for seismic storeat least.
#if 0
.logger(InternalZGY::LoggerBase::standardCallback
(InternalZGY::LoggerBase::getVerboseFromEnv("OPENZGY_VERBOSE"),
"openzgy-unittest: ", ""))
#endif
.sdurl(Environment::getStringEnv("OPENZGY_SDURL"))
.sdapikey(Environment::getStringEnv("OPENZGY_SDAPIKEY"))
.sdtoken(Environment::getStringEnv("OPENZGY_TOKEN"), "");
......
......@@ -1846,7 +1846,7 @@ ZgyReader_setverbose(ZgyClass *self, PyObject *value, void *closure)
}
long newvalue = PyLong_AsLong(value);
self->pimpl_->logger_verbose_ = static_cast<int>(newvalue);
self->pimpl_->logger_ = LoggerBase::standardCallback(self->pimpl_->logger_verbose_, "openzgy: ", "");
self->pimpl_->logger_ = LoggerBase::standardCallback(self->pimpl_->logger_verbose_, "openzgy-python: ", "");
// Nitpick: not distinguishing between reader and writer in prefix,
// as happens when logger is set from environment variable.
// Because the same setter is used in both classes.
......
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