Reduce excessive info logging #5780

thrimbor · 2023-06-07T14:11:34Z

This cuts back logging from the worst offenders of #5302 - there might be more that appear when the client runs for a longer time, I mainly checked the ones that appeared after a few minutes of running the client.
#5752 might be a better solution, but I decided to submit a quick fix because I was frustrated that this critical issue (it causes significant SSD wear and potentially causes data loss by filling up the volume) didn't get enough attention in months.
Even after #5769 the client is unusable for me without these changes.

I think it's possible that this masks a deeper issue, a lot of the log messages referred to files that Nextcloud shouldn't even care about (i.e. files that are stored outside of any synced folders).

mgallien

thanks for the contribution
please see my comments
unfortunately it would be very hard to analyze synchronization issues without the "Processing" log lines
I think the other one are good candidate to move to debug level

mgallien · 2023-06-08T06:58:37Z

src/libsync/discovery.cpp

+    qCDebug(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;


I rely heavily on this one to analyze any sync issue. So I would object the move from info level to debug level.

I agree debugging often requires as many information as you can get..

but this must not pollute log files during normal operation

even in debugging case "useless" logging should be avoided
(if there is nothing to change maximum 1 log line telling "nothing to do on the file" is expected")

further improvement: ideally the "noting to do" log line exists not for each file but only once for each directory

@isdnfan ideally I would like to be able to log those "Processing" log lines only when there is going to be a sync action by the client
currently we are not yet there

mgallien · 2023-06-08T06:58:45Z

src/libsync/discovery.cpp

@@ -1537,7 +1537,7 @@ void ProcessDirectoryJob::processFileFinalize(
        item->_direction = _dirItem->_direction;
    }

-    qCInfo(lcDisco) << "Discovered" << item->_file << item->_instruction << item->_direction << item->_type;
+    qCDebug(lcDisco) << "Discovered" << item->_file << item->_instruction << item->_direction << item->_type;


same comment

thrimbor · 2023-06-08T12:32:08Z

@mgallien I don't doubt they're useful, but they're the issue. Having those log increases the log size by 3400% when running the client for five minutes. And that is without any file changes happening. It's too much for me to be able to use the client.

/edit:
I'd like to note that excessive logging didn't use to be an issue until sometime late last year iirc. I don't know what has changed or when exactly, and I haven't looked into the client logs before, but I've used the client for years and never had problems before.

mgallien · 2023-06-13T12:39:42Z

@mgallien I don't doubt they're useful, but they're the issue. Having those log increases the log size by 3400% when running the client for five minutes. And that is without any file changes happening. It's too much for me to be able to use the client.

/edit: I'd like to note that excessive logging didn't use to be an issue until sometime late last year iirc. I don't know what has changed or when exactly, and I haven't looked into the client logs before, but I've used the client for years and never had problems before.

there was a couple of change that made the situation worse.
Sorry to have mostly duplicated your work by merging changes the last days but there was some kind of urgency to improve the situation
as I said earlier, the ideal situation would be to get the "Processing" log lines only when a sync action is going to be done by the client
we are not yet there

mgallien · 2023-06-13T12:40:26Z

@thrimbor again, I am sorry to create extra work for you but could you rebase your work on the changes that were merged and see if you can resolve the conflicts ?

Signed-off-by: Stefan Schmidt <[email protected]>

thrimbor · 2023-06-22T23:39:53Z

Sorry for the delay, it's rebased now.

nextcloud-desktop-bot · 2023-06-22T23:52:23Z

AppImage file: nextcloud-PR-5780-58cb5bcd27bb836aeeebd6bcfa076bebbb2f9c2a-x86_64.AppImage

To test this change/fix you can simply download above AppImage file and test it.

Please make sure to quit your existing Nextcloud app and backup your data.

isdnfan · 2023-06-25T09:22:39Z

I tested the appimage above and confirm there is no more "processing" log entries. log archives are split into very small chunks (after a start on a small file set it created 4 .gz archives with 18.9kB total size).

regarding the logging it looks promising. I see logs for changed files but no logs related to unchanged files.

mgallien

see my comment

mgallien · 2023-06-28T09:24:10Z

src/libsync/discovery.cpp

-                              << " | e2ee: " << dbEntry.isE2eEncrypted() << "/" << serverEntry.isE2eEncrypted()
-                              << " | e2eeMangledName: " << dbEntry.e2eMangledName() << "/" << serverEntry.e2eMangledName
-                              << " | file lock: " << localFileIsLocked << "//" << serverFileIsLocked;
+    qCDebug(lcDisco).nospace() << "Processing " << path._original


that change cannot get merged as it would basically make it impossible to analyze any sync issue without having affected users change their default log level and reproduce the issue
as far as I know, the main performance issue with logs is already solved and I am unconvinced we need this change

I disagree with you statement this PR makes sync troubleshooting impossible. the logs still contains file changes - which is exactly what I want to see during normal operations.

I'm system engineer with 20+ years of experience with different applications. reading logs is my daily job - I know what I want to find there. My view might be different then yours but in my opinion regular logs files should contain information related to application health and changes performed (high level). Adjusting log level is definitely an accepted approach in case of troubleshooting. The logs should rather remain small so one could keep them for long time.

In my eyes there are two major issues

the size of the logs

Writing multiple GBs of logs every 1-2 hours brakes SSDs which are limited in "data written" amount - look at the calculation in [Bug]: Nextcloud client generates >100 GB worth of log files every day (800MB per sync run). #5302. e.g. very common Samsung EVO860 has 150 TBW for 250 GB model. current desktop client kills such SSD in 3 years already!

inefficient operations

"touching" every file on the system on every sync cycle, even this only happens virtually costs CPU and burns energy. I don't really get why this is necessary.. Even you need this for some reason in my eyes there is no reason to logs this actions until you change something. In my scenario with 100k files there are ~300MB logs with 3.9.0 every single sync even with no changes.

in general the approach to always "touch" every file is bad in term of resources. On my client with modern i7 CPU and SSD the regular 2h sync cycle (without changes) takes 1-2 minutes already (according to the logs) eating significant CPU and disk. Today when everybody is looking to save energy this is not a good habit.

I suggest

short term this PR should be merged as soon as possible.

long term more resource efficient sync algorithm should be implemented (e.g. only check all files on client start and rely on OS events for file changes)

@mgallien
@isdnfan
well that's 1 year 4 months now.
can we move forward on this smh?

eibex · 2023-10-25T11:21:59Z

Would it be feasible to make it an option (eg radio button near the logs section) that users can turn on or off if you need to analyse sync issues?

mgallien requested changes Jun 8, 2023

View reviewed changes

Reduce excessive logging

58cb5bc

Signed-off-by: Stefan Schmidt <[email protected]>

thrimbor force-pushed the reduce_excessive_logging branch from dea06db to 58cb5bc Compare June 22, 2023 23:39

mgallien requested changes Jun 28, 2023

View reviewed changes

isdnfan mentioned this pull request Aug 19, 2024

[Bug]: Nextcloud client generates >100 GB worth of log files every day (800MB per sync run). #5302

Open

8 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Reduce excessive info logging #5780

Reduce excessive info logging #5780

thrimbor commented Jun 7, 2023

mgallien left a comment

mgallien Jun 8, 2023

isdnfan Jun 8, 2023 •

edited

Loading

mgallien Jun 13, 2023

mgallien Jun 8, 2023

thrimbor commented Jun 8, 2023 •

edited

Loading

mgallien commented Jun 13, 2023

mgallien commented Jun 13, 2023

thrimbor commented Jun 22, 2023

nextcloud-desktop-bot commented Jun 22, 2023

isdnfan commented Jun 25, 2023

mgallien left a comment

mgallien Jun 28, 2023

isdnfan Jun 28, 2023

ne0YT Oct 31, 2024

eibex commented Oct 25, 2023

Reduce excessive info logging #5780

Are you sure you want to change the base?

Reduce excessive info logging #5780

Conversation

thrimbor commented Jun 7, 2023

mgallien left a comment

Choose a reason for hiding this comment

mgallien Jun 8, 2023

Choose a reason for hiding this comment

isdnfan Jun 8, 2023 • edited Loading

Choose a reason for hiding this comment

mgallien Jun 13, 2023

Choose a reason for hiding this comment

mgallien Jun 8, 2023

Choose a reason for hiding this comment

thrimbor commented Jun 8, 2023 • edited Loading

mgallien commented Jun 13, 2023

mgallien commented Jun 13, 2023

thrimbor commented Jun 22, 2023

nextcloud-desktop-bot commented Jun 22, 2023

isdnfan commented Jun 25, 2023

mgallien left a comment

Choose a reason for hiding this comment

mgallien Jun 28, 2023

Choose a reason for hiding this comment

isdnfan Jun 28, 2023

Choose a reason for hiding this comment

ne0YT Oct 31, 2024

Choose a reason for hiding this comment

eibex commented Oct 25, 2023

isdnfan Jun 8, 2023 •

edited

Loading

thrimbor commented Jun 8, 2023 •

edited

Loading