Sending Qt logs with tags to Sentry

Hi all.

I have been developing desktop applications using Qt for a long time and have already developed some approaches to working with logs. In this article, I would like to share these approaches with the community, they can be useful in different situations.

All actions were performed on a release build in Visual Studio 2022 on Windows and clang on macOS, but for the most part this is true for other compilers as well.

Source name in logs

We will not repeat the part about installing your own handler for writing to logs via qInstallMessageHandler and let's touch on more interesting things. So, first we need to get the file name with the source and the line number from which the log entry was made. We set up our own write handler and start writing to the log:

void MessageOutput(QtMsgType type, const QMessageLogContext& context, const QString& msg) {
  if (!context.file) {
    std::cout << "no file" << std::endl;
  }
}

int main(int, char*[]) {
  const QtMessageHandler prev_handler{qInstallMessageHandler(MessageOutput)};
  qInfo() << "example";
  qInstallMessageHandler(prev_handler);
}

link to example

in the release build we see in the output:

no file

It turns out that names are not transmitted in the release in Qt. In C++ there is a macro for the file name and string, we substitute it and check what will happen under Windows:

#define myInfo QMessageLogger(__FILE__, __LINE__, nullptr).info

void MessageOutput(QtMsgType type, const QMessageLogContext& context, const QString& msg) {
  if (!context.file) {
    std::cout << "no file" << std::endl;
  } else {
    std::cout << context.file << std::endl;
  }
}

int main(int argc, char* argv[]) {
  const QtMessageHandler prev_handler{qInstallMessageHandler(MessageOutput)};
  myInfo() << "example";
  qInstallMessageHandler(prev_handler);
}

link to example

and we get:

C:\soft\samples\logs\two.cc

The next step is to strip the file path during compilation so that only the file name is output:

template <typename T, size_t S>
inline constexpr size_t get_file_name_offset(const T (& str)[S], size_t i = S - 1) {
  return (str[i] == '/' || str[i] == '\\') ? i + 1 : (i > 0 ? get_file_name_offset(str, i - 1) : 0);
}

template <typename T>
inline constexpr size_t get_file_name_offset(T (& str)[1]) {
  (void)str;
  return 0;
}

namespace utility {
  template <typename T, T v>
  struct const_expr_value {
    static constexpr const T value = v;
  };
}

#define UTILITY_CONST_EXPR_VALUE(exp) ::utility::const_expr_value<decltype(exp), exp>::value

#define myInfo QMessageLogger(&__FILE__[UTILITY_CONST_EXPR_VALUE(get_file_name_offset(__FILE__))], __LINE__, nullptr).info

void MessageOutput(QtMsgType type, const QMessageLogContext& context, const QString& msg) {
  if (!context.file) {
    std::cout << "no file" << std::endl;
  } else {
    std::cout << context.file << std::endl;
  }
}

int main(int argc, char* argv[]) {
  const QtMessageHandler prev_handler{qInstallMessageHandler(MessageOutput)};
  myInfo() << "example";
  qInstallMessageHandler(prev_handler);
}

link to example

and we get:

three.cc

Transferring a unique label

Having the file name + line number in the logs is very convenient for finding the location of the error, but this information will not work for a unique label, since the line number changes as the source code of the application changes. We need a unique label so that we can aggregate logs by it and understand how many and what events occurred. Labels allow you to aggregate the same logs for different versions of applications.
To pass a label, we use a “category” in Qt terminology. There is a problem here: all “labels” must be unique. When building the application, we run scripts that check that all labels are unique, and if not, the build is suspended.

To pass a label through a category we use the following code:

#define myInfoC(err_fingerprint) QMessageLogger(&__FILE__[UTILITY_CONST_EXPR_VALUE(get_file_name_offset(__FILE__))], __LINE__, "", err_fingerprint).info()

void MessageOutput(QtMsgType type, const QMessageLogContext& context, const QString& msg) {
  const QString file{context.file ? u"%1:%2"_s.arg(context.file).arg(context.line) : u"no file"_s};
  std::cout << file.toStdString() << " (" << context.category << ")" << std::endl;
}

int main(int argc, char* argv[]) {
  const QtMessageHandler prev_handler{qInstallMessageHandler(MessageOutput)};
  myInfoC("category") << "example";
  qInstallMessageHandler(prev_handler);
}

link to example

and we see what we need:

four.cc:37 (category)

Info/Warning/Error

Another important parameter of the log output is its type. In our applications, we send only warnings and errors to the server. Information messages remain only in the log on the user's PC. It is better not to pass debugging suggestions to the release.

#define myInfoC(err_fingerprint) QMessageLogger(&__FILE__[UTILITY_CONST_EXPR_VALUE(get_file_name_offset(__FILE__))], __LINE__, "", err_fingerprint).info()
#define myWarningC(err_fingerprint) QMessageLogger(&__FILE__[UTILITY_CONST_EXPR_VALUE(get_file_name_offset(__FILE__))], __LINE__, "", err_fingerprint).warning()
#define myCriticalC(err_fingerprint) QMessageLogger(&__FILE__[UTILITY_CONST_EXPR_VALUE(get_file_name_offset(__FILE__))], __LINE__, "", err_fingerprint).critical()

link to example

and in the output we see:

Debug no file (default) Message
Info five.cc:56 (cat_info) Message
Warning five.cc:57 (cat_warning) Message
Critical five.cc:58 (cat_critical) Message

Sending to sentry

So, we have the following information when output to the log:

• message type,

• message text,

• label,

• file name,

• line number.

and we are ready to send all this information to sentry. I will not describe the sending of data directly here, since there is a lot of information on the network about implementing network interaction in Qt, so I will only describe the JSON being sent. We send much more information, but the examples are relevant to this article. I would like to note that we do not use the sentry SDK, but do all the sending through their API using QtNetwork.

API documentation for sentry can be found here

As an example, let's send three warning messages:

{
    "event_id": "00000000000000000000000000000001",
    "message": "example",
    "level": "warning",
    "transaction": "main.cc:10",
    "fingerprint": ["one"]
}

And three error messages:

{
    "event_id": "00000000000000000000000000000004",
    "message": "example",
    "level": "error",
    "transaction": "main.cc:10",
    "fingerprint": ["two"]
}

events in sentry are grouped by label:

If you go into the message details, you can see the transmitted data:

• 1 – text message

• 2 – message level (warning/error)

• 3 – file and line

• 4 – our mark

Link to the place where the message was sent

As additional information, we send a link to the place where the message was sent from. For this, all our releases have their own version, which is tagged in git. In sentry, this information is sent as additional information, and the JSON looks like this:

{
    "event_id": "00000000000000000000000000000007",
    "message": "example",
    "level": "warning",
    "transaction": "main.cc:10",
    "extra": {
        "source": "https://github.com/sploid/samples/blob/v0.1/README.md?plain=1#L5"
    },
    "fingerprint": ["three"]
}

in sentry we can quickly jump to the line from which the message was sent:

Don't flush logs unless absolutely necessary.

At some point in time, the application started to crash, and to be sure that we could see all the written logs, we inserted a flush call into the file after each log entry. After that, the application started to slow down terribly when writing to the log, so we came to the conclusion that it is not worth doing flush unless absolutely necessary, even if you really want to.

Converting time to string can significantly slow down your application.

In the application under development, we actively wrote logs, and when writing logs, the time of the event was displayed with an accuracy of up to a second. At some points in time, up to 100 events per second were written.
The event time was generated using approximately the following code:

std::string GetEventTime() {
  const std::time_t now{std::time(NULL)};
  const std::tm* const ptm{std::localtime(&now)};
  char buffer[32];
  std::strftime(buffer, 32, "%Y-%m-%d %H:%M:%S", ptm);
  return std::string{buffer};
}

After examining the application with a profiler, it turned out that converting time to text takes a long time and the code was changed to this:

time_t gPrevTime{};
std::string gPrevTimeStr;

const std::string& GetEventTime() {
  const std::time_t now{std::time(NULL)};
  if (now == gPrevTime) {
    return gPrevTimeStr;
  }
  const std::tm* const ptm{std::localtime(&now)};
  char buffer[32];
  std::strftime(buffer, 32, "%Y-%m-%d %H:%M:%S", ptm);
  gPrevTimeStr = std::string(buffer);
  gPrevTime = now;
  return gPrevTimeStr;
}

Of course, we must not forget about multithreading and we need to protect data, I deliberately neglected these aspects in this example in order to focus the readers' attention on the topic of the article.