Starting adding logging with spdlog.

[whit2333]

• Mixins defined in Logger.h
• spdlog should probably be pulled into the analyzer too.
• Mixin used in base classes (THcDC is currently a good example)
• Added logging to many classes.

[whit2333]

Not sure why the check fails the second time. It appears to compile just fine. The check needs to be re done from scratch probably.

[hansenjo]

It fails because you didn't update the main Makefile.

[brash99]

There are many that would disagree with you, Whit ... https://scons.org/refer.html

[whit2333]

It's strange because the compiler works fine (see the end of the output) and finds spdlog but scons does not.

Why is it building hcana before evio/analyzer?

If the scons experts could fix it, I would appreciate it.

[brash99]

I’ll have a look at it as soon as I can. Best, E.

…

-- Dr. Edward J. Brash Professor of Physics - Christopher Newport University Staff Scientist - Thomas Jefferson National Accelerator Facility Honorary Senior Research Fellow - University of Glasgow Office: 757-594-7451 Mobile: 757-753-2831 FAX: 757-594-7919

On Dec 14, 2018, 10:56 PM -0500, Whitney Armstrong ***@***.***>, wrote: It's strange because the compiler works fine (see the end of the output) and finds spdlog but scons does not. Why is it building hcana before evio/analyzer? If the scons experts could fix it, I would appreciate it. — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

[whit2333]

Thanks. BTW spdlog is header-only and I was installing it to include/hcana/spdlog. This was to hide it from other projects that might be using it too.

…

On December 14, 2018 9:59:55 PM CST, brash99 ***@***.***> wrote: I’ll have a look at it as soon as I can.> > Best,> E.> > --> Dr. Edward J. Brash> Professor of Physics - Christopher Newport University> Staff Scientist - Thomas Jefferson National Accelerator Facility> Honorary Senior Research Fellow - University of Glasgow> Office: 757-594-7451> Mobile: 757-753-2831> FAX: 757-594-7919> On Dec 14, 2018, 10:56 PM -0500, Whitney Armstrong ***@***.***>, wrote:> > It's strange because the compiler works fine (see the end of the output) and finds spdlog but scons does not.> > Why is it building hcana before evio/analyzer?> > If the scons experts could fix it, I would appreciate it.> > —> > You are receiving this because you commented.> > Reply to this email directly, view it on GitHub, or mute the thread.> > > -- > You are receiving this because you authored the thread.> Reply to this email directly or view it on GitHub:> #426 (comment)

-- Sent from my Android device with K-9 Mail. Please excuse my brevity.

[hansenjo]

Ed, no need to put time into it. The SCons build is fine. Just a little careful reading of the Travis config file and log will reveal that hcana is built twice, first with make, then with SCons. The make build fails, the SCons build succeeds. Travis notices that at least one of the script commands had a nonzero exit status and thus reports failure. All that needs to be done to fix it is to add one include path to the main Makefile, in the same manner as with the SConstruct file.

[hansenjo]

The idea of adding a message logger to hcana (and analyzer) is not bad IMHO. In the analyzer we've been using ROOT messaging (Error(), Warning() etc.), but I don't particularly like it, and people haven't been using it consistently. I'll play with the spdlog package a little to see how it works.

At first glance I notice that this particular logging facility inserts itself directly into the class inheritance hierarchy. I find that quite awkward. Also, actually logging messages seems to require an unusual syntax. I'm not sure how easy that'll play with users.

A bigger question: How complete is this pull request? Have all messages from all hcana classes been converted to this logger format? If so, hcana doesn't seem to have much to say ... If not, well ... this brings me to the sticking point. Who would be supporting this? I count about 1400 ROOT-style and cout/cerr messages in the analyzer. hcana's count is about 850. I don't think we have the resources to dedicate anyone to converting those to spdlog. Think a week of mind-numbing tedium. I could ask my high school intern to do it, but I'm pretty sure that person wouldn't ever want to come near a science lab again afterwards. And at first glance it doesn't look like it would be easy to automate, at least not within a much shorter time frame than brute-forcing it. If a conversion script was at hand, I bet this pull request would already include the results.

So yeah, in my opinion the benefit/cost ratio for this sort of thing seems pretty small. But I'm open to convincing arguments.

I do have a suggestion for a project with high payoff: add unit and integration tests to the analyzer and hcana. Steve already runs a high level integration test (a small test replay) as part of his private nightly builds, which is very valuable. But I am sure it only tests a fraction of the available functionality. And it isn't part of the Travis tests yet. Put differently, we're looking for a "make test" feature which, if successful, would give us a very high degree of confidence that the software is working as designed, and which is granular enough to allow quick pinpointing of newly-introduced bugs in a particular component. In the vein of the current popularity of header-only packages, let me suggest Catch2: https://github.com/catchorg/Catch2

[whit2333]

At first glance I notice that this particular logging facility inserts itself directly into the class inheritance hierarchy. I find that quite awkward.

This is called a "Mixin". It is way to add functionality to the underlying class without modifying it. Also, it a simple way of tweaking all the loggers or adding more loggers. I can explain this in detail if you would like.

Also, actually logging messages seems to require an unusual syntax. I'm not sure how easy that'll play with users.

This is the very popular and excellent libfmt syntax which emulates python's string format. Spdlog uses libfmt hence the syntax.

A bigger question: How complete is this pull request? Have all messages from all hcana classes been converted to this logger format?

It doesn't need to be "complete". The logging doesn't need to be universally used for it to work. In fact, it provides a great way to find code that is not yet using this logging facility and errors become visually easier to spot.

Having 100% usage isn't the goal of this PR. I would rather encourage a thoughtful planning of its usage in concurrence with the strategy outlined here
#417.

For example, one could have a logger for just the trigger related code and use a mixin that looks like something like this:

template <typename Base>
  class TrigLogging : public Base {
  protected:
    std::shared_ptr<spdlog::logger> _logger;
  public:
    template <class... Args>
    TrigLogging(Args&&... args) : Base(std::forward<Args>(args)...) {
      _logger = spdlog::get("trig");
      if(!_logger) {
        _logger = spdlog::stdout_color_mt("trig");
      }
    }
  };

Or perhaps, in some cases, logging to a file would better? Or possibly the both by having a _file_logger member. Mixins can be nested too:

class NewWhatever : public FileLogging<TrigLogging<THWhatever>> {
...
// cout logging:
_logger->info("blah");
...
// file logging:
_file_logger->info("blah into a file");
 
};

I do have a suggestion for a project with high payoff: add unit and integration tests to the analyzer and hcana. Steve already runs a high level integration test (a small test replay) as part of his private nightly builds, which is very valuable. But I am sure it only tests a fraction of the available functionality. And it isn't part of the Travis tests yet. Put differently, we're looking for a "make test" feature which, if successful, would give us a very high degree of confidence that the software is working as designed, and which is granular enough to allow quick pinpointing of newly-introduced bugs in a particular component. In the vein of the current popularity of header-only packages, let me suggest Catch2: https://github.com/catchorg/Catch2

I use catch2 on almost all my code bases and it is trivial to integrate with a cmake build (which, BTW is still slighly broken). Again, a testing framework is another strong argument for adopting something like this #417.

[hansenjo]

I finally had a chance to look at this PR a little more closely.

I guess there are two questions to consider: (1) which logging library to use and (2) how to best integrate it.

spdlog by itself looks fine. Perhaps a bit complex, but fine. The main thing that strikes me odd is its Python-like message formatting. Not that it's difficult to learn, but it's unexpected for people working with C/C++ code. Perhaps for that reason, most C++ logging libraries I've seen use the C++-style streaming operator syntax, something like

LOG_WARN << "Too many hits: " << nhits << ", limit is " << MAXHITS;

The streaming syntax would have the advantage that we could automate the conversion of all the code where we currently use cout and cerr. That would be about 2/3 of all messages. Then again, spdlog's printf-like style probably makes the conversion of the ROOT Warning, Error etc. messages easier. In part it's a matter of taste, but there are some objective advantages to the streaming syntax in our case, I think.

Another feature a logging library should offer is on-the-fly switching to different (or adding of additional) logging targets. We want to be able to say something like

hcana --log-output=run_1234.log 'replay.C(1234)'

and all messages will be sent to the given file.

Unfortunately, the PR falls short on this point. As it is, to switch to file output, it looks like we are supposed to modify the headers of all classes that do logging (i.e. nearly everything) and recompile the code. Seriously?

From browsing the documentation, spdlog does seem to offer the capability to change or configure multiple logging "sinks". That would probably do the job for us. Someone should write a small prototype to test it.

Now, about the second point, how to integrate the logger. As it turns out, spdlog does not require a mix-in pattern for its use as suggested in this PR. Far from it. And the suggested mix-in classes ... and here I am actually wondering whether Whit is pulling a prank on us. If we accepted this PR, things could be said about us that I would not want to be said. So—no.

As written, the so-called mix-ins with their cool-looking code-bloating variadic templating do exactly one useful thing: they each add (and initialize) a class member variable.

If you think about it, the _logger member variable could even be static, couldn't it? Does it even have to be a class member? Could it be a global, initialized in main or THaInterface or on first use via an access function, like so

logger()->print("Red alert in {}", GetName());

The main reason that comes to mind why a member variable might make sense is to treat the output of some specific class (or specific instance of a class) differently, for example log drift chamber messages with more verbosity. If a class doesn't want default logging behavior, it would instantiate a different logger object to its taste. That assumes that each logger object only supports a single configuration. Different logging libraries surely take different approaches for specifying log sources and their handling. rsyslogd, for instance, lets you set destinations and verbosity of each different source in a global configuration file. When comparing logging libraries, the configuration would be an item to pay attention to.

But—this topic is not high on my to-do list, so I won't spend time to research this in depth now.

Which brings me to one final point. I am puzzled by "pull requests" that are patently incomplete and essentially proof-of-concept alpha code "to be fleshed out" by someone sometime perhaps who knows. Why not make a feature request in the Issue tracker and, possibly, propose specifics, maybe a concept for the solution. Once agreement is reached that the request should proceed, and how to proceed (i.e. "let's use xyzlogger"), and how quickly to proceed, then people start on the implementation, perhaps on a branch, which, when finished, becomes a pull request.

[whit2333]

Did you even try it?

[whit2333]

[whit2333]

. And the suggested mix-in classes ... and here I am actually wondering whether Whit is pulling a prank on us. If we accepted this PR, things could be said about us that I would not want to be said. So—no.

Really!? I am done.