Wrong order of logs within `QTextEdit` in qt5

[WorstCodeWay]

Hi, I meet a problem when I logging to qt widget QTextEdit with different color. Sequence of logs are wrong.

Here my logs within QTextEdit

[I][7738][2023/06/06 07:55:14:907][device] Parse information.
[E][7731][2023/06/06 07:55:14:908] [device] Add pack wrong!
[E][7731][2023/06/06 07:55:14:909] [device] error!
[I][7738][2023/06/06 07:55:14:906][device] Receive from tcp server.

But within logged file ( same within std::out):

[I][7738][2023/06/06 07:55:14:906][device] Receive from tcp server.
[I][7738][2023/06/06 07:55:14:907][device] Parse information.
[E][7731][2023/06/06 07:55:14:908] [device] Add pack wrong!
[E][7731][2023/06/06 07:55:14:909] [device] error!

We can learn from logs( by timestamp) that the order of logs within QTextEditor is wrong.

Here is my implement of qt_sink:

template <typename Mutex>
  class QtSink: public spdlog::sinks::qt_sink<Mutex>
  {
  public:
    QtSink(QTextEdit *object = nullptr, const std::string &meta_method = ""):
      spdlog::sinks::qt_sink<Mutex>(object, meta_method),
      _editor(object)
    {}

    ~QtSink() = default;
  protected:
    void sink_it_(const spdlog::details::log_msg &msg) override {
      if(!_editor) return;

      spdlog::level::level_enum level = msg.level;
      switch(level)
      {
        case spdlog::level::trace:
          _editor->setTextColor(Qt::darkGray);
          break;
        case spdlog::level::debug:
          _editor->setTextColor(Qt::lightGray);
          break;
        case spdlog::level::info:
          _editor->setTextColor(Qt::green);
          break;
        case spdlog::level::warn:
          _editor->setTextColor(Qt::yellow);
          break;
        case spdlog::level::err:
          _editor->setTextColor(Qt::red);
          break;
        case spdlog::level::critical:
          _editor->setTextColor(Qt::darkRed);
          break;
        default:
          break;
      }
      spdlog::sinks::qt_sink<Mutex>::sink_it_(msg);
    }
  private:
    QTextEdit * _editor;
  };
  using QtSinkMt = QtSink<std::mutex>;
  typedef std::shared_ptr<QtSinkMt> QtSinkMtPtr;

And here I instant that sink:

  _qtSink = std::make_shared<QtSinkMt>(view,"append");
  _qtSink->set_pattern(pattern.c_str());
  _qtSink->set_level(spdlog::level::debug);
  _sysLogger->sinks().push_back(_qtSink);
  _sysLogger->info("Log Viewer Init Done!");

So, what wrong with that codes.

[tt4g]

Since qt_sink passes log messages to QObject*, it is assumed that spdlog does not guarantee the log order.

qt_sink calls QMetaObject::invokeMethod(), which seems to forward method calls to the main thread when called in a thread. I would not be surprised if this specification causes the order of the logs to be rearranged.

https://github.com/gabime/spdlog/blob/31cf79a70dfa61a4b2b7509eecca6a3b269bfc4a/include/spdlog/sinks/qt_sinks.h#L45-L46

See: multithreading - QMetaObject::invokeMethod is not called in the correct thread - Stack Overflow

[WorstCodeWay]

Since qt_sink passes log messages to QObject*, it is assumed that spdlog does not guarantee the log order.

qt_sink calls QMetaObject::invokeMethod(), which seems to forward method calls to the main thread when called in a thread. I would not be surprised if this specification causes the order of the logs to be rearranged.

https://github.com/gabime/spdlog/blob/31cf79a70dfa61a4b2b7509eecca6a3b269bfc4a/include/spdlog/sinks/qt_sinks.h#L45-L46

See: multithreading - QMetaObject::invokeMethod is not called in the correct thread - Stack Overflow

Thanks @tt4g . Yes, you are right. But how can I get ordered log based on current conditions(QTextEdit and spdlog)? Any ideas?

Or, is it a good idea to rewrite sink_it_ by call append from QTextEdit directly? Not from QMetaObject::invokeMethod()

[tt4g]

Or, is it a good idea to rewrite sink_it_ by call append from QTextEdit directly? Not from QMetaObject::invokeMethod()

As pointed out by many sites when checked by search engines, the QWdiget subclass crashes when controlled directly by anything other than the main thread. If you want to control a QWidget from another thread, use connect or QMetaObject::invokeMethod(), or use QEvent (https://stackoverflow.com/questions/9777911/how-do-i-create-a-window-in-different-qt-threads).

In any case, after calling QMetaObject::invokeMethod(), there is nothing spdlog can do to guarantee the order of the logs, since it follows the Qt specification.

[WorstCodeWay]

I realized that, however, it's frustrating. Thank you, @tt4g

Oh, another problem is my Info color is wrong due to wrong order of logs( I think ). Last line of log below should be of color green, but is red, just as [E](Error) log be. I think it's related to wrong order problem. How to fix wrong color?

[I][7738][2023/06/06 07:55:14:907][device] Parse information.
[E][7731][2023/06/06 07:55:14:908] [device] Add pack wrong!
[E][7731][2023/06/06 07:55:14:909] [device] error!
[I][7738][2023/06/06 07:55:14:906][device] Receive from tcp server.

What can I do to fixed it.

[tt4g]

This is because _editor->setTextColor(Qt::red); is called from a non-main thread. There is no guarantee that it will work correctly. And spdlog::sinks::qt_sink<Mutex>::sink_it_(msg); writes the log message after moving to the main thread, so between changing the color and writing the log message, _editor->setTextColor( Qt::red); may have been called again.

[WorstCodeWay]

This is because _editor->setTextColor(Qt::red); is called from a non-main thread. There is no guarantee that it will work correctly. And spdlog::sinks::qt_sink<Mutex>::sink_it_(msg); writes the log message after moving to the main thread, so between changing the color and writing the log message, _editor->setTextColor( Qt::red); may have been called again.

Yes, I make my effort to fix it, however it seems not easily. I noticed from other thread that there is a qt_colored_mt type or something like, from link github.com/gabime/spdlog#log-to-qt-with-nice-colors. However I cannot redirect to that specific link with that log-to-qt-with-nice-colors topic. Is it removed?

[tt4g]

I don't remember seeing such a topic in README.md.

[WorstCodeWay]

I don't remember seeing such a topic in README.md.

removed from this commit

https://github.com/gabime/spdlog/commit/4f4da7f114ef4b643afdba711aa5331e082bec91

[tt4g]

This change comes from #2752. The comment has been changed because spdlog is not responsible for Qt lifetime management.

[WorstCodeWay]

This change comes from #2752. The comment has been changed because spdlog is not responsible for Qt lifetime management.

Thank you @tt4g . Seems no solution...

Can I leave this open, in case of some one other has solutions to this problem?

[tt4g]

I'm sure there are people who know a lot about Qt on the Qt forum and StackOverflow, so it's better to ask there.

[gabime]

Re-added qt_color_sink after fixing threading issues.