Improvements to the logging API

[Lucas-C]

During PRs #25 & #27,
several future improvements to the logging API were mentioned.

This issue keeps track of them,
so that we can discuss those features,
in order to further extend & improve MOTIS logging.

• make the logging compatible with the OpenTelemetry (OTEL) standard
• document how to set s_verbosity
• support an extra warn log level?
• support more datatypes by making it a std::pair<std::string_view, std::variant</* ... all supported value types */>> (cf. Improved logging API #27 (comment))
• (performances) avoid a double call to fmt::format() & fmt::print(), and only make a single call to fmt::print() (cf. Initiating some documentation using Doxygen & Sphinx #25 (comment))

Also, we could start adopting utl logging functions in other MOTIS modules.

[felixguendling]

Also, we could start adopting utl logging functions in other MOTIS modules.

This should be done for all calls of fmt::print, fmt::println, std::cout, std::cerr, std::clog, printf, fprintf, etc. in all repositories involved in MOTIS.

[Lucas-C]

PR for using utl::log in nigiri module: motis-project/nigiri#165

[felixguendling]

The new API doesn't work. fmt::streamed takes a reference to an r-value which works if printed immediately while parameters are kept alive. But like I tried to do it in the destructor it won't work. I guess we'll have to "record" the message using fmt::format in the constructor and do the actual log in the destructor. I guess we can live with this extra allocation for now.

[Lucas-C]

The new API doesn't work. fmt::streamed takes a reference to an r-value which works if printed immediately while parameters are kept alive. But like I tried to do it in the destructor it won't work. I guess we'll have to "record" the message using fmt::format in the constructor and do the actual log in the destructor. I guess we can live with this extra allocation for now.

Alright.

I'm a bit surprised that it doesn't work, whereas the unit tests added seem to show that it works fine.

Would you have a minimal test code revealing that it doesn't work?

[felixguendling]

I couldn't.

I had issues with this:

        utl::log_info(
            "motis.compute_footpaths",
            "missing footpath: {} [{}]  {} -> {}: {} updated to {}min",
            tt.locations_.names_[miss.target()].view(),
            tags.id(tt, miss.target()),
            fmt::streamed(get_loc(tt, w, pl, matches, l_idx)),
            fmt::streamed(get_loc(tt, w, pl, matches, miss.target())),
            miss.duration(), new_duration);

and changing it back to fmt::println fixed it. So I thought it has to do with fmt::streamed.

I tried to produce a problem with this code:

struct dtor {
  friend std::ostream& operator<<(std::ostream& out, dtor const& x) {
    return out << x.x_;
  }
  ~dtor() { std::clog << "DESTROY\n";}
  int x_;
};
TEST(log, temporary_streamed) {
  testing::internal::CaptureStderr();
  auto const tmp = []() {
    return dtor{.x_ = 9999};
  };
  utl::log_info("MyCtx", "{} {}", fmt::streamed(tmp()), fmt::streamed(tmp()));
  EXPECT_THAT(
      testing::internal::GetCapturedStderr(),
      MatchesRegex(
          ".+T.+Z \\[info\\] \\[logging.+:.+\\] \\[MyCtx\\] 9999 9999\nDESTROY\nDESTROY\n"));
}

My idea is that fmt::streamed takes a reference. If this reference points to a temporary, it might crash. But in this example it doesn't because the destructor is called after the printing.

Maybe stay alert if you experience strange behavior around printing lines with fmt::streamed.

If I encounter something again I'll try to make a minimal reproducible example.