From 92846d216a4def803aa72a2f3db6f72f784f8d96 Mon Sep 17 00:00:00 2001
From: Hannah von Reth <hannah.vonreth@owncloud.com>
Date: Tue, 27 Sep 2022 13:47:40 +0200
Subject: [PATCH] Log http request duration

---
 changelog/unreleased/10142 |  5 +++++
 src/common/utility.cpp     | 30 +++++++++++++++---------------
 src/common/utility.h       |  4 ++--
 src/libsync/httplogger.cpp | 22 ++++++++++++++++------
 4 files changed, 38 insertions(+), 23 deletions(-)
 create mode 100644 changelog/unreleased/10142

diff --git a/changelog/unreleased/10142 b/changelog/unreleased/10142
new file mode 100644
index 00000000000..dbc8b9d49e3
--- /dev/null
+++ b/changelog/unreleased/10142
@@ -0,0 +1,5 @@
+Enhancement: Estimate duration of network requests in httplogger
+
+We now include an estimated duration in the httploger.
+
+https://github.com/owncloud/client/pull/10142
diff --git a/src/common/utility.cpp b/src/common/utility.cpp
index dafd1882a37..7f9d486b66b 100644
--- a/src/common/utility.cpp
+++ b/src/common/utility.cpp
@@ -592,21 +592,6 @@ QString Utility::sanitizeForFileName(const QString &name)
     return result;
 }
 
-QDebug &operator<<(QDebug &debug, nanoseconds in)
-{
-    QDebugStateSaver save(debug);
-    debug.nospace();
-    const auto h = duration_cast<hours>(in);
-    const auto min = duration_cast<minutes>(in -= h);
-    const auto s = duration_cast<seconds>(in -= min);
-    const auto ms = duration_cast<milliseconds>(in -= s);
-    return debug << "std::chrono::duration("
-                 << h.count() << "h, "
-                 << min.count() << "min, "
-                 << s.count() << "s, "
-                 << ms.count() << "ms)";
-}
-
 QString Utility::renderTemplate(QString templ, const QMap<QString, QString> &values)
 {
     static const QRegularExpression pattern(QStringLiteral("@{([^{}]+)}"));
@@ -636,3 +621,18 @@ QString Utility::renderTemplate(QString templ, const QMap<QString, QString> &val
 }
 
 } // namespace OCC
+
+QDebug &operator<<(QDebug &debug, nanoseconds in)
+{
+    QDebugStateSaver save(debug);
+    debug.nospace();
+    const auto h = duration_cast<hours>(in);
+    const auto min = duration_cast<minutes>(in -= h);
+    const auto s = duration_cast<seconds>(in -= min);
+    const auto ms = duration_cast<milliseconds>(in -= s);
+    return debug << "std::chrono::duration("
+                 << h.count() << "h, "
+                 << min.count() << "min, "
+                 << s.count() << "s, "
+                 << ms.count() << "ms)";
+}
\ No newline at end of file
diff --git a/src/common/utility.h b/src/common/utility.h
index 0dd67b8aabc..869fc3adcfc 100644
--- a/src/common/utility.h
+++ b/src/common/utility.h
@@ -428,7 +428,7 @@ inline bool Utility::isBSD()
     return false;
 #endif
 }
-
-OCSYNC_EXPORT QDebug &operator<<(QDebug &debug, std::chrono::nanoseconds in);
 }
 #endif // UTILITY_H
+
+OCSYNC_EXPORT QDebug &operator<<(QDebug &debug, std::chrono::nanoseconds in);
\ No newline at end of file
diff --git a/src/libsync/httplogger.cpp b/src/libsync/httplogger.cpp
index 4a3b621eb98..645e122a880 100644
--- a/src/libsync/httplogger.cpp
+++ b/src/libsync/httplogger.cpp
@@ -14,10 +14,16 @@
 
 #include "httplogger.h"
 
+#include "common/utility.h"
+
 #include <QRegularExpression>
 #include <QLoggingCategory>
 #include <QBuffer>
 
+#include <chrono>
+
+using namespace std::chrono;
+
 namespace {
 Q_LOGGING_CATEGORY(lcNetworkHttp, "sync.httplogger", QtWarningMsg)
 
@@ -33,12 +39,13 @@ bool isTextBody(const QString &s)
     return regexp.match(s).hasMatch();
 }
 
-void logHttp(const QByteArray &verb, const QString &url, const QByteArray &id, const QString &contentType, const QList<QNetworkReply::RawHeaderPair> &header, QIODevice *device)
+void logHttp(const QByteArray &verb, const QString &url, const QByteArray &id, const QString &contentType, const QList<QNetworkReply::RawHeaderPair> &header, QIODevice *device, const nanoseconds &duration = {})
 {
     const auto reply = qobject_cast<QNetworkReply *>(device);
     const auto contentLength = device ? device->size() : 0;
     QString msg;
-    QTextStream stream(&msg);
+    QDebug stream(&msg);
+    stream.nospace().noquote();
     stream << id << ": ";
     if (!reply) {
         stream << "Request: ";
@@ -54,7 +61,7 @@ void logHttp(const QByteArray &verb, const QString &url, const QByteArray &id, c
         if (reply->attribute(QNetworkRequest::HttpPipeliningWasUsedAttribute).toBool()) {
             stream << "Piplined,";
         }
-        stream << ")";
+        stream << duration << ")";
     }
     stream << " " << url << " Header: { ";
     for (const auto &it : header) {
@@ -95,10 +102,12 @@ namespace OCC {
 
 void HttpLogger::logRequest(QNetworkReply *reply, QNetworkAccessManager::Operation operation, QIODevice *device)
 {
-    const auto request = reply->request();
     if (!lcNetworkHttp().isInfoEnabled()) {
         return;
     }
+    const auto start = steady_clock::now();
+    const auto request = reply->request();
+
     const auto keys = request.rawHeaderList();
     QList<QNetworkReply::RawHeaderPair> header;
     header.reserve(keys.size());
@@ -112,13 +121,14 @@ void HttpLogger::logRequest(QNetworkReply *reply, QNetworkAccessManager::Operati
         header,
         device);
 
-    QObject::connect(reply, &QNetworkReply::finished, reply, [reply] {
+    QObject::connect(reply, &QNetworkReply::finished, reply, [reply, start] {
         logHttp(requestVerb(*reply),
             reply->url().toString(),
             reply->request().rawHeader(XRequestId()),
             reply->header(QNetworkRequest::ContentTypeHeader).toString(),
             reply->rawHeaderPairs(),
-            reply);
+            reply,
+            steady_clock::now() - start);
     });
 }