From 98bed83aaeea45f429612e353d65f8e0209b5389 Mon Sep 17 00:00:00 2001 From: Matthieu Gallien Date: Mon, 26 Aug 2024 15:04:05 +0200 Subject: [PATCH 1/2] create a permanent log of delete actions will log all deletions with the result of the discovery by the sync enginre should enable analyze even long time after such a delete occured Signed-off-by: Matthieu Gallien --- src/csync/csync.h | 16 +++-- src/gui/application.cpp | 3 +- src/gui/logbrowser.cpp | 2 +- src/gui/owncloudgui.cpp | 2 +- src/libsync/discovery.cpp | 37 ++++++----- src/libsync/logger.cpp | 92 ++++++++++++++++++++++----- src/libsync/logger.h | 19 ++++-- src/libsync/propagateremotedelete.cpp | 1 + src/libsync/propagatorjobs.cpp | 1 + src/libsync/syncfileitem.h | 2 + src/libsync/syncfilestatustracker.cpp | 3 + 11 files changed, 132 insertions(+), 46 deletions(-) diff --git a/src/csync/csync.h b/src/csync/csync.h index ee5cee0502413..5c8fbc0978b6b 100644 --- a/src/csync/csync.h +++ b/src/csync/csync.h @@ -32,22 +32,24 @@ #ifndef _CSYNC_H #define _CSYNC_H -#include "std/c_private.h" -#include "ocsynclib.h" - -#include +#include +#include +#include #include +#include #include -#include #include #include -#include -#include +#include "ocsynclib.h" +#include "config_csync.h" +#include "std/c_private.h" #include "common/remotepermissions.h" namespace OCC { +Q_DECLARE_LOGGING_CATEGORY(lcPermanentLog) + class SyncJournalFileRecord; namespace EncryptionStatusEnums { diff --git a/src/gui/application.cpp b/src/gui/application.cpp index 6363045a2bf20..171acc75cfa8a 100644 --- a/src/gui/application.cpp +++ b/src/gui/application.cpp @@ -716,7 +716,8 @@ void Application::setupLogging() logger->setLogDebug(true); #endif - logger->enterNextLogFile(); + logger->enterNextLogFile(QStringLiteral("nextcloud.log"), OCC::Logger::LogType::Log); + logger->enterNextLogFile(QStringLiteral("permanent_delete.log"), OCC::Logger::LogType::DeleteLog); qCInfo(lcApplication) << "##################" << _theme->appName() << "locale:" << QLocale::system().name() diff --git a/src/gui/logbrowser.cpp b/src/gui/logbrowser.cpp index 38f59930a9506..46357edc50a5d 100644 --- a/src/gui/logbrowser.cpp +++ b/src/gui/logbrowser.cpp @@ -118,7 +118,7 @@ void LogBrowser::togglePermanentLogging(bool enabled) if (enabled) { if (!logger->isLoggingToFile()) { logger->setupTemporaryFolderLogDir(); - logger->enterNextLogFile(); + logger->enterNextLogFile(QStringLiteral("nextcloud.log"), OCC::Logger::LogType::Log); } } else { logger->disableTemporaryFolderLogDir(); diff --git a/src/gui/owncloudgui.cpp b/src/gui/owncloudgui.cpp index f9e6ea117672f..60138a494943b 100644 --- a/src/gui/owncloudgui.cpp +++ b/src/gui/owncloudgui.cpp @@ -254,7 +254,7 @@ void ownCloudGui::slotSyncStateChange(Folder *folder) || result.status() == SyncResult::Problem || result.status() == SyncResult::SyncAbortRequested || result.status() == SyncResult::Error) { - Logger::instance()->enterNextLogFile(); + Logger::instance()->enterNextLogFile(QStringLiteral("nextcloud.log"), OCC::Logger::LogType::Log); } } diff --git a/src/libsync/discovery.cpp b/src/libsync/discovery.cpp index e505c258766d7..505c0e8123f84 100644 --- a/src/libsync/discovery.cpp +++ b/src/libsync/discovery.cpp @@ -528,22 +528,26 @@ void ProcessDirectoryJob::processFile(PathTuple path, const auto localFileIsLocked = dbEntry._lockstate._locked ? "locked" : "not locked"; const auto serverFileLockType = serverEntry.isValid() ? QString::number(static_cast(serverEntry.lockOwnerType)) : QStringLiteral(""); const auto localFileLockType = dbEntry._lockstate._locked ? QString::number(static_cast(dbEntry._lockstate._lockOwnerType)) : QStringLiteral(""); - qCInfo(lcDisco).nospace() << "Processing " << path._original - << " | (db/local/remote)" - << " | valid: " << dbEntry.isValid() << "/" << hasLocal << "/" << hasServer - << " | mtime: " << dbEntry._modtime << "/" << localEntry.modtime << "/" << serverEntry.modtime - << " | size: " << dbEntry._fileSize << "/" << localEntry.size << "/" << serverEntry.size - << " | etag: " << dbEntry._etag << "//" << serverEntry.etag - << " | checksum: " << dbEntry._checksumHeader << "//" << serverEntry.checksumHeader - << " | perm: " << dbEntry._remotePerm << "//" << serverEntry.remotePerm - << " | fileid: " << dbEntry._fileId << "//" << serverEntry.fileId - << " | inode: " << dbEntry._inode << "/" << localEntry.inode << "/" - << " | type: " << dbEntry._type << "/" << localEntry.type << "/" << (serverEntry.isDirectory ? ItemTypeDirectory : ItemTypeFile) - << " | e2ee: " << dbEntry.isE2eEncrypted() << "/" << serverEntry.isE2eEncrypted() - << " | e2eeMangledName: " << dbEntry.e2eMangledName() << "/" << serverEntry.e2eMangledName - << " | file lock: " << localFileIsLocked << "//" << serverFileIsLocked - << " | file lock type: " << localFileLockType << "//" << serverFileLockType - << " | metadata missing: /" << localEntry.isMetadataMissing << '/'; + + QString processingLog; + QDebug deleteLogger{&processingLog}; + deleteLogger.nospace() << "Processing " << path._original + << " | (db/local/remote)" + << " | valid: " << dbEntry.isValid() << "/" << hasLocal << "/" << hasServer + << " | mtime: " << dbEntry._modtime << "/" << localEntry.modtime << "/" << serverEntry.modtime + << " | size: " << dbEntry._fileSize << "/" << localEntry.size << "/" << serverEntry.size + << " | etag: " << dbEntry._etag << "//" << serverEntry.etag + << " | checksum: " << dbEntry._checksumHeader << "//" << serverEntry.checksumHeader + << " | perm: " << dbEntry._remotePerm << "//" << serverEntry.remotePerm + << " | fileid: " << dbEntry._fileId << "//" << serverEntry.fileId + << " | type: " << dbEntry._type << "/" << localEntry.type << "/" << (serverEntry.isDirectory ? ItemTypeDirectory : ItemTypeFile) + << " | e2ee: " << dbEntry.isE2eEncrypted() << "/" << serverEntry.isE2eEncrypted() + << " | e2eeMangledName: " << dbEntry.e2eMangledName() << "/" << serverEntry.e2eMangledName + << " | file lock: " << localFileIsLocked << "//" << serverFileIsLocked + << " | file lock type: " << localFileLockType << "//" << serverFileLockType + << " | metadata missing: /" << localEntry.isMetadataMissing << '/'; + + qCInfo(lcDisco).nospace() << processingLog; if (localEntry.isValid() && !serverEntry.isValid() @@ -562,6 +566,7 @@ void ProcessDirectoryJob::processFile(PathTuple path, item->_originalFile = path._original; item->_previousSize = dbEntry._fileSize; item->_previousModtime = dbEntry._modtime; + item->_discoveryResult = std::move(processingLog); if (dbEntry._modtime == localEntry.modtime && dbEntry._type == ItemTypeVirtualFile && localEntry.type == ItemTypeFile) { item->_type = ItemTypeFile; diff --git a/src/libsync/logger.cpp b/src/libsync/logger.cpp index 65aeb61041a0f..5e84be48ac0d7 100644 --- a/src/libsync/logger.cpp +++ b/src/libsync/logger.cpp @@ -68,6 +68,8 @@ static bool compressLog(const QString &originalName, const QString &targetName) namespace OCC { +Q_LOGGING_CATEGORY(lcPermanentLog, "nextcloud.log.permanent") + Logger *Logger::instance() { static Logger log; @@ -134,7 +136,7 @@ void Logger::doLog(QtMsgType type, const QMessageLogContext &ctx, const QString _logstream->flush(); } closeNoLock(); - enterNextLogFileNoLock(); + enterNextLogFileNoLock(QStringLiteral("nextcloud.log"), LogType::Log); } ++linesCounter; @@ -146,6 +148,13 @@ void Logger::doLog(QtMsgType type, const QMessageLogContext &ctx, const QString if (_doFileFlush) _logstream->flush(); } + if (_permanentDeleteLogStream && strcmp(ctx.category, lcPermanentLog().categoryName()) == 0) { + (*_permanentDeleteLogStream) << msg << "\n"; + _permanentDeleteLogStream->flush(); + if (_permanentDeleteLogFile.size() > 10LL * 1024LL) { + enterNextLogFileNoLock(QStringLiteral("permanent_delete.log"), LogType::DeleteLog); + } + } if (type == QtFatalMsg) { closeNoLock(); #if defined(Q_OS_WIN) @@ -180,6 +189,12 @@ void Logger::setLogFile(const QString &name) setLogFileNoLock(name); } +void Logger::setPermanentDeleteLogFile(const QString &name) +{ + QMutexLocker locker(&_mutex); + setPermanentDeleteLogFileNoLock(name); +} + void Logger::setLogExpire(int expire) { _logExpire = expire; @@ -232,7 +247,7 @@ void Logger::disableTemporaryFolderLogDir() if (!_temporaryFolderLogDir) return; - enterNextLogFile(); + enterNextLogFile("nextcloud.log", LogType::Log); setLogDir(QString()); setLogDebug(false); setLogFile(QString()); @@ -262,7 +277,7 @@ void Logger::dumpCrashLog() } } -void Logger::enterNextLogFileNoLock() +void Logger::enterNextLogFileNoLock(const QString &baseFileName, LogType type) { if (!_logDirectory.isEmpty()) { @@ -274,29 +289,44 @@ void Logger::enterNextLogFileNoLock() // Tentative new log name, will be adjusted if one like this already exists const auto now = QDateTime::currentDateTime(); const auto cLocale = QLocale::c(); // Some system locales generate strings that are incompatible with filesystem - QString newLogName = cLocale.toString(now, QStringLiteral("yyyyMMdd_HHmm")) + QStringLiteral("_nextcloud.log"); + QString newLogName = cLocale.toString(now, QStringLiteral("yyyyMMdd_HHmm")) + QStringLiteral("_%1").arg(baseFileName); // Expire old log files and deal with conflicts - QStringList files = dir.entryList(QStringList("*owncloud.log.*"), QDir::Files, QDir::Name) + - dir.entryList(QStringList("*nextcloud.log.*"), QDir::Files, QDir::Name); - static const QRegularExpression rx(QRegularExpression::anchoredPattern(R"(.*(next|own)cloud\.log\.(\d+).*)")); - int maxNumber = -1; - foreach (const QString &s, files) { + const auto files = dir.entryList({QStringLiteral("*owncloud.log.*"), QStringLiteral("*%1.*").arg(baseFileName)}, QDir::Files, QDir::Name); + for (const auto &s : files) { if (_logExpire > 0) { QFileInfo fileInfo(dir.absoluteFilePath(s)); if (fileInfo.lastModified().addSecs(60 * 60 * _logExpire) < now) { dir.remove(s); } } - const auto rxMatch = rx.match(s); - if (s.startsWith(newLogName) && rxMatch.hasMatch()) { - maxNumber = qMax(maxNumber, rxMatch.captured(2).toInt()); + } + + const auto regexpText = QString{"%1\\.(\\d+).*"}.arg(QRegularExpression::escape(newLogName)); + const auto anchoredPatternRegexpText = QRegularExpression::anchoredPattern(regexpText); + const QRegularExpression rx(regexpText); + int maxNumber = -1; + const auto collidingFileNames = dir.entryList({QStringLiteral("%1.*").arg(newLogName)}, QDir::Files, QDir::Name); + for(const auto &fileName : collidingFileNames) { + const auto rxMatch = rx.match(fileName); + if (rxMatch.hasMatch()) { + maxNumber = qMax(maxNumber, rxMatch.captured(1).toInt()); } } newLogName.append("." + QString::number(maxNumber + 1)); - auto previousLog = _logFile.fileName(); - setLogFileNoLock(dir.filePath(newLogName)); + auto previousLog = QString{}; + switch (type) + { + case OCC::Logger::LogType::Log: + previousLog = _logFile.fileName(); + setLogFileNoLock(dir.filePath(newLogName)); + break; + case OCC::Logger::LogType::DeleteLog: + previousLog = _permanentDeleteLogFile.fileName(); + setPermanentDeleteLogFileNoLock(dir.filePath(newLogName)); + break; + } // Compress the previous log file. On a restart this can be the most recent // log file. @@ -344,10 +374,40 @@ void Logger::setLogFileNoLock(const QString &name) _logstream.reset(new QTextStream(&_logFile)); } -void Logger::enterNextLogFile() +void Logger::setPermanentDeleteLogFileNoLock(const QString &name) +{ + if (_permanentDeleteLogStream) { + _permanentDeleteLogStream.reset(nullptr); + _permanentDeleteLogFile.close(); + } + + if (name.isEmpty()) { + return; + } + + bool openSucceeded = false; + if (name == QLatin1String("-")) { + openSucceeded = _permanentDeleteLogFile.open(stdout, QIODevice::WriteOnly); + } else { + _permanentDeleteLogFile.setFileName(name); + openSucceeded = _permanentDeleteLogFile.open(QIODevice::WriteOnly); + } + + if (!openSucceeded) { + postGuiMessage(tr("Error"), + QString(tr("File \"%1\"
cannot be opened for writing.

" + "The log output cannot be saved!")) + .arg(name)); + return; + } + + _permanentDeleteLogStream.reset(new QTextStream(&_permanentDeleteLogFile)); +} + +void Logger::enterNextLogFile(const QString &baseFileName, LogType type) { QMutexLocker locker(&_mutex); - enterNextLogFileNoLock(); + enterNextLogFileNoLock(baseFileName, type); } } // namespace OCC diff --git a/src/libsync/logger.h b/src/libsync/logger.h index bfcb2989d5db0..2d9dce3193edd 100644 --- a/src/libsync/logger.h +++ b/src/libsync/logger.h @@ -20,7 +20,7 @@ #include #include #include -#include +#include #include "common/utility.h" #include "owncloudlib.h" @@ -35,6 +35,12 @@ class OWNCLOUDSYNC_EXPORT Logger : public QObject { Q_OBJECT public: + enum class LogType { + Log, + DeleteLog, + }; + Q_ENUM(LogType) + bool isLoggingToFile() const; void doLog(QtMsgType type, const QMessageLogContext &ctx, const QString &message); @@ -47,6 +53,8 @@ class OWNCLOUDSYNC_EXPORT Logger : public QObject QString logFile() const; void setLogFile(const QString &name); + void setPermanentDeleteLogFile(const QString &name); + void setLogExpire(int expire); QString logDir() const; @@ -88,7 +96,7 @@ class OWNCLOUDSYNC_EXPORT Logger : public QObject void guiMessage(const QString &, const QString &); public slots: - void enterNextLogFile(); + void enterNextLogFile(const QString &baseFileName, OCC::Logger::LogType type); private: Logger(QObject *parent = nullptr); @@ -96,20 +104,23 @@ public slots: void closeNoLock(); void dumpCrashLog(); - void enterNextLogFileNoLock(); + void enterNextLogFileNoLock(const QString &baseFileName, LogType type); void setLogFileNoLock(const QString &name); + void setPermanentDeleteLogFileNoLock(const QString &name); QFile _logFile; bool _doFileFlush = false; int _logExpire = 0; bool _logDebug = false; QScopedPointer _logstream; - mutable QMutex _mutex; + mutable QRecursiveMutex _mutex; QString _logDirectory; bool _temporaryFolderLogDir = false; QSet _logRules; QVector _crashLog; int _crashLogIndex = 0; + QFile _permanentDeleteLogFile; + QScopedPointer _permanentDeleteLogStream; }; } // namespace OCC diff --git a/src/libsync/propagateremotedelete.cpp b/src/libsync/propagateremotedelete.cpp index 7bc5be9528889..708b0f2ed2a0a 100644 --- a/src/libsync/propagateremotedelete.cpp +++ b/src/libsync/propagateremotedelete.cpp @@ -29,6 +29,7 @@ Q_LOGGING_CATEGORY(lcPropagateRemoteDelete, "nextcloud.sync.propagator.remotedel void PropagateRemoteDelete::start() { qCInfo(lcPropagateRemoteDelete) << "Start propagate remote delete job for" << _item->_file; + qCInfo(lcPermanentLog) << "delete" << _item->_file << _item->_discoveryResult; if (propagator()->_abortRequested) return; diff --git a/src/libsync/propagatorjobs.cpp b/src/libsync/propagatorjobs.cpp index 0a0a84e0d4934..bcdf5a4697e69 100644 --- a/src/libsync/propagatorjobs.cpp +++ b/src/libsync/propagatorjobs.cpp @@ -101,6 +101,7 @@ bool PropagateLocalRemove::removeRecursively(const QString &path) void PropagateLocalRemove::start() { qCInfo(lcPropagateLocalRemove) << "Start propagate local remove job"; + qCInfo(lcPermanentLog) << "delete" << _item->_file << _item->_discoveryResult; _moveToTrash = propagator()->syncOptions()._moveFilesToTrash; diff --git a/src/libsync/syncfileitem.h b/src/libsync/syncfileitem.h index 4bf481a138c86..a4619535561b1 100644 --- a/src/libsync/syncfileitem.h +++ b/src/libsync/syncfileitem.h @@ -339,6 +339,8 @@ class OWNCLOUDSYNC_EXPORT SyncFileItem bool _isAnyInvalidCharChild = false; bool _isAnyCaseClashChild = false; + + QString _discoveryResult; }; inline bool operator<(const SyncFileItemPtr &item1, const SyncFileItemPtr &item2) diff --git a/src/libsync/syncfilestatustracker.cpp b/src/libsync/syncfilestatustracker.cpp index 67ad27ad0e59e..2b934806fa08c 100644 --- a/src/libsync/syncfilestatustracker.cpp +++ b/src/libsync/syncfilestatustracker.cpp @@ -249,6 +249,9 @@ void SyncFileStatusTracker::slotAboutToPropagate(SyncFileItemVector &items) } SharedFlag sharedFlag = item->_remotePerm.hasPermission(RemotePermissions::IsShared) ? Shared : NotShared; + if (item->_instruction != CSyncEnums::CSYNC_INSTRUCTION_REMOVE) { + item->_discoveryResult.clear(); + } if (item->_instruction != CSYNC_INSTRUCTION_NONE && item->_instruction != CSYNC_INSTRUCTION_UPDATE_METADATA && item->_instruction != CSYNC_INSTRUCTION_IGNORE From 5882404099c6b40ec0b164aad78c249c77f978a6 Mon Sep 17 00:00:00 2001 From: Matthieu Gallien Date: Mon, 30 Sep 2024 17:11:33 +0200 Subject: [PATCH 2/2] remove not so usefull log line for new files Signed-off-by: Matthieu Gallien --- src/libsync/discovery.cpp | 7 ------- 1 file changed, 7 deletions(-) diff --git a/src/libsync/discovery.cpp b/src/libsync/discovery.cpp index 505c0e8123f84..690a668da433a 100644 --- a/src/libsync/discovery.cpp +++ b/src/libsync/discovery.cpp @@ -549,13 +549,6 @@ void ProcessDirectoryJob::processFile(PathTuple path, qCInfo(lcDisco).nospace() << processingLog; - if (localEntry.isValid() - && !serverEntry.isValid() - && !dbEntry.isValid() - && localEntry.modtime < _lastSyncTimestamp) { - qCWarning(lcDisco) << "File" << path._original << "was modified before the last sync run and is not in the sync journal and server"; - } - if (_discoveryData->isRenamed(path._original)) { qCDebug(lcDisco) << "Ignoring renamed"; return; // Ignore this.