Better logging while also using GstCheck

Application Development
1

I have been using GstCheck to configure unit tests for an application and its various elements and I’ve reached a situation where being able to run the test with a more verbose log level would be helpful. It would also be fantastic if when running these tests via meson test that only test failures would actually be printed to the output log file, to keep it smaller.

My first inclination was to define an alternate GST_CHECK_MAIN macro to configure the ring buffer logger ahead of the gst_check_init() call and then only get those logs if the return from gst_check_run_suite() was non-zero:

#define GST_CHECK_MAIN(name)                                      \
  int main (int argc, char **argv)                                \
  {                                                               \
    Suite *s;                                                     \
    gint result = 0;                                              \
                                                                  \
    gst_debug_remove_log_function (gst_debug_log_default);        \
    gst_debug_add_ring_buffer_logger (16384, 20);                 \
    gst_check_init (&argc, &argv);                                \
                                                                  \
    s = name ## _suite ();                                        \
    result = gst_check_run_suite (s, # name, __FILE__);           \
    if (result) {                                                 \
      gchar **messages = gst_debug_ring_buffer_logger_get_logs ();\
      gchar *message = NULL;                                      \
                                                                  \
      while ((message = *messages++)) {                           \
        g_printerr ("%s", message);                               \
        g_clear_pointer (&message, g_free);                       \
      }                                                           \
    }                                                             \
    return result;                                                \
  }

However, this has two shortcomings. First, it’s printing the logs for all tests in every case in the entire suite if a single test fails (vs. only printing the logs from the failed case). Second, it only captures messages up until gst_check_init() redirects everything to private functions via g_log_set_handler(...) calls for various logging domains including ones from an internal array (log_domains).

This is an older test suite that predates some of my more recent things using Google Test, where I can make logging configuration changes like this prior to gst_init() and it all works as expected.

I’m currently using 1.22.6 and have not found an example gstcheck -based unit test that also configures something similar to the above with respect to logging, nor have I found any good results searching the internet, so I’m not confident in what questions I should even be asking at this point since these stdout/stderr default logging outputs are the root cause of making the test application run with entirely different results just by configuring the log level with GST_DEBUG.

  1. Is staying with GstCheck gaining providing a necessary benefit in terms of test stability, fidelity, etc. – something specific to gstreamer – over an alternative like Google Test (configuring logging, then calling gst_init() and gst_deinit() myself)?
  2. If GstCheck is providing some necessary benefit, has anyone found a way to tune the logging options to use the ring buffer, or some other performant solution, where the log level does not break tests?

Thank you all in advance for your suggestions.

2

For debugging, I’d suggest using the same logging system as GStreamer uses, you can add a category for the filtering.

Though for the second part, that would imply a lot of work if we don’t want to completely kill the performance (run each singular test case it’s its own process).

3

Thanks for the suggestion, however I am trying to use GStreamer’s logger but with a ring buffer option rather than writing to stdout/stderr for each GST_? () logging macro call. The tests have their own category because of GstCheck’s configuration, and by using the ring buffer the performance of the test itself is no longer impacted by the log level (so far as I can tell). The problem is that when the logs dump on a failed test, it only has messages up until GstCheck initializes. If I re-arrange the calls to setup the ring buffer after calling gst_check_init(), the test suite locks in a way that trying to identify the hang in gdb (running in WSL2) is a bit of a no-go; I cannot pause/break anywhere once it enters the run suite. I’m stumped on how to use the ring buffer with GstCheck and what I am trying to weigh is if those in the community think it’s worth fighting with GstCheck to get this working or dump it in favor of some other test apparatus like GoogleTest (where if I make no calls to the GstCheck library, I can get performant logging and unit testing working together…but it’s going to be a lot of work porting all of my tests over). If there’s some inherent “good” to GstCheck, I’ll keep at trying to get this to work.

I think we’re having different experiences with the performance of the logger. In my case, once I turn the log level up to something useful, even for only my own narrow category, the stdout/stderr logger that is configured as part of GstCheck has such low performance it causes timing issues in my tests (for example, measuring that part of the application replies in a specific amount of time will fail as the logger slowly writes each line out). We had the same problem with our application at deployment until changing how logs are captured/relayed to our logging service.

4

In GStreamer we introduced GstHarness which is combined with a fake clock so that we have reliable tests that don’t depend on timing. All tests that still depends on timing ends up flaky one way or another, and they don’t work under valgrind.

That asside, we ruin all tests in a pipe in upstream CI, and performance is still relatively good, even with some logging enabled. How much logging do you want to enable? Because at a certain level, even with the ring Buffett things will get slow. With all traces enabled, GStreamer can produce gigabytes of traces.

5

I was trying to run INFO on gstreamer itself and DEBUG on things in my own categories. We don’t have many messages defined per object or gstelement, but in aggregate, it seems to be enough to cause some very quirky behavior, like tests becoming unstable if we try to run a test multiple times via meson (i.e., meson launches the test application multiple times, up to the number of CPUs unless one specifies otherwise). If we let it run as many test instances as processors, we start seeing race conditions that don’t make sense at the log level we can successfully use – turning up the log level to capture why the Nth test instance failed results in more test failures elsewhere despite having locks about our data, etc.

I have been able to use GstHarness for some of our elements in the past, but I ran into issues pretty early on with this application and gave up trying to make use of it (I don’t recall the specifics, it was 2 years ago; what I do recall was the “cranks” API being difficult to predict just how many times one has to crank to get a buffer through a longer pipeline or if I would ever see a buffer out the other end).