search

meganz / MEGAsync

Easy automated syncing between your computers and your MEGA Cloud Drive
Other
1.59k stars 277 forks source link

MEGAsync is performing full scan at every startup ('Scanning' takes more than 10 minutes) #734

Open Eldaw opened 1 year ago

Eldaw commented 1 year ago

Every time I start MEGAsync, it deletes everything in my local database and then forces a full scan, which takes more than 10 minutes. In other words, every single time MEGAsync starts, the system tray icon has the message 'Scanning' for more than 10 minutes. I'm currently using v4.7.0 on Windows 10, but the problem existed also with v4.6.8.

Another user logged a similar issue in #722 where I took part in the discussion. Eventually that user found that they could solve their problem by changing their MEGA password via the web. That hasn't worked for me. Please refer to that issue to see more of my comments regarding this problem.

I've also tried completely uninstalling and reinstalling the MEGAsync client, but that made no difference either. As soon as I add in any synced folders, startup of MEGAsync takes ages, because it's forcing itself to do a full scan every single time.

I've looked in the log file called MEGAsync.log and to me it appears that what is happening is that the MEGAsync client considers itself to be in a "crashed" state, and it is then deleting everything in the local database, and then doing a full scan on my synced folders. Basically doing everything from scratch at every startup, and that's presumably why I have to wait for 10+ minutes of 'Scanning' at every startup.

How can I resolve this, and how can I get MEGAsync into a normal state, where it doesn't do a full scan and rebuild of its database from scratch at every startup?

Some entries from MEGAsync.log that get logged at every startup:

09/22-13:17:03.391735 22504 WARN Force reloading (isCrashed true)

09/22-13:17:03.409532 22504 INFO Checking pending crash repors

09/22-13:18:08.206781 22504 DBG  Setting isCrashed true: !root || !inbox || !rubbish (account details callback)

Thousands of these: 09/22-13:04:39.662129 22072 DTL Megaclient exec is pending resolutions. scpaused=0 stopsc=0 mBlocked=0 jsonsc.pos= syncsup=1 statecurrent=0 syncadding=0 syncactivity=0 syncdownrequired=0 syncdownretry=0 [megaclient.cpp:2327]

Thousands of these: 09/22-13:04:42.122546 22072 DTL Removing node from database: aQxihR5T [megaclient.cpp:5233]

Eldaw commented 1 year ago

It's disappointing that the developers at MEGA are so inactive here in the issues list on GitHub. Users trying to proactively help report issues and even trying to provide troubleshooting information from the logs, etc. to try to resolve issues and there's little to no engagement from the MEGA staff. MEGA are getting free QA and Testing, from the public, and they can't be bothered to respond, which is a bit ungrateful and disrespectful really. I've been talking about this particular problem for a month (since starting to talk about it in the other issue referenced above) and there's been no progress whatsoever. And before that, I'd tried contacting Support, which didn't lead anywhere either. I really hoped and expected that it would be possible to get more engagement from the dev team here on GitHub and be able to work through to a resolution. Unfortunately, I was expecting too much.

angelds-mega commented 1 year ago

Hello. Sorry to read this.

We have checked and one of our support team have replied to your email. Please kindly check.

Eldaw commented 1 year ago

@angelds-mega I'm not sure if you're serious. First, I'm expecting engagement here in the GitHub issue, not from your support team. I already mentioned here, as well as in the other GitHub issue referenced above, that the template reply I received from support was not useful and that's why I've tried to pursue the issue here. Second, I've provided different and detailed information here, including information from the logs, and including analysis I've done, which I'm expecting someone to at least pretend to care about and respond to. Third, how do you even know what email response I got from your support team -- my credentials (including username and email address) for my MEGA account bear no relation to my username and other details here on GitHub. So your response is utter nonsense I'm afraid. Did you really think that after all my posts in this GitHub issue and the other GitHub issue, that all I was looking for was for you to check (dishonestly as it turns out) whether I'd received a response from your support team by email. What a joke.

MEGA Team, there is a bug in your software. I'm trying to work with you to get it fixed. Is there nobody from MEGA that can provide a useful response?

Eldaw commented 1 year ago

@mattw-mega Are you or any of the MEGA developers able and/or willing to look into this issue?

mattw-mega commented 1 year ago

Hi Eldaw, as I said before, scanning is normal on MEGAsync start. How else will it know if something changed on disk when it wasn't running? And there's no fast or slow scan - there's just scan. You may perceive it going faster or slower depending on whether your PC has cached some of the relevant portion of the filesystem. The comment about rebuilding the database is a bit concerning, what evidence do you have for that, please? thanks

Eldaw commented 1 year ago

Hi @mattw-mega thank you for responding - I appreciate it. I'm afraid we may be speaking past each other. I realise you are likely very busy, but have you had a look at the example log file entries I gave in my first post within this issue? I've actually got several computers running MEGAsync, and they're each syncing folders with MEGA. I've spent quite some time analysing the logs from all of them, and the log from the problematic PC looks a lot different to all of the other PCs which have no problems. It is only on the 1 PC where I see that the log has the entries about '(isCrashed true)' which you can see in my post above. After lines such as the ones below from today's log, there are thousands of entries showing everything being removed from the local database, the sync folders being fully scanned, and everything being added again. None of the working PCs (which also have lots of syncs) do this.

09/28-18:38:56.925215 37524 WARN Force reloading (isCrashed true)
09/28-18:38:56.941192 37524 WARN Deleting local cache: C:/Users/username/AppData/Local/Mega Limited/MEGAsync/megaclient_statecache12_b0VYZmZlMDlnMUkskFTxmfC6UncEBKdfALGa.db
09/28-18:38:56.942695 37524 WARN Deleting local cache: C:/Users/username/AppData/Local/Mega Limited/MEGAsync/megaclient_statecache12_rCsAAAAAAQDIzFdMHBsAAKBF333tPYNS.db
09/28-18:38:56.943721 37524 WARN Deleting local cache: C:/Users/username/AppData/Local/Mega Limited/MEGAsync/megaclient_statecache12_status_b0VYZmZlMDlnMUkskFTxmfC6UncEBKdfALGa.db

I really think that is the clue to what's going on here. Why on just 1 computer am I getting this issue where it says 'Force reloading (isCrashed true)', followed by thousands of events, when none of my other computers do that?

EDIT - To provide some more information: Regarding my comments about fast or slow scanning: when MEGAsync already has the hash/checksum for a local file in its local cache, it doesn't try to recalculate the hash on subsequent startup scans. But when no hashes are in the local cache, then the scan has to calculate the checksums for everything. That is what is happening from scratch each time for me on just the 1 PC, because every subsequent start of MEGAsync is deleting everything from the local cache (as per the thousands of entries in the log), and then adding everything again from scratch (and therefore having to recalculate the hashes of everything). That is why it's taking ages to start on just that PC. On all the other PCs, the local cache is being used, which is why MEGAsync starts quite quickly on all of those computers.

mattw-mega commented 1 year ago

Ah, I see, yes the Force reloading (isCrashed true) indicates that MEGAsync started up and detected that it crashed last time it ran. Looks like it deletes most databases in that case, node and sync databases included. Tracing the code back, it was introduced in 2014, my guess would be that some database corruption was seen after crashes in some cases. That could still be the case sometimes if we were to remove that functionality. So, you're right that it will be starting from scratch (the sync configs are not deleted), and will need to recalculate the fingerprints(hashes) of all the files on disk. So your best bet would be to figure out what's causing those crashes (possibly some local image file that the freeimage library can't handle?) and avoid the crash, hence avoiding having those databases wiped on start.

Eldaw commented 1 year ago

Thanks for the reply @mattw-mega I'm encouraged that there's potentially light at the end of the tunnel for this issue. The thing is, I don't see any indication that the client is crashing. I even went as far as completely uninstalling (including deleting all leftover registry entries and all leftover files in all locations in any way related to MEGAsync). I really was confident that there was no trace of MEGAsync left anywhere on the computer. I then rebooted and reinstalled MEGAsync, as if it was on a fresh new PC, and the same behavior has continued. I really don't get why the client thinks it has crashed. How can I figure out why it believes it has? Is there anything specific I can look for in the log, or something I can do in a configuration file to indicate to it that it hasn't crashed? I'm really keen to get this solved on this PC.

mattw-mega commented 1 year ago

You can check your logs for any mention of isCrashed. All the places that flag is set, are logged, eg. 

                MegaApi::log(MegaApi::LOG_LEVEL_DEBUG, "Setting isCrashed true: !mRootNode (fetch node callback)");
                preferences->setCrashed(true);
Eldaw commented 1 year ago

Thanks, from my MEGAsync.log which contains all events from a single startup until everything was happy, until it was then gracefully exited, here is every occurence of isCrashed:

09/28-18:38:56.925215 37524 WARN Force reloading (isCrashed true)
09/28-18:38:57.658077 37524 DBG  Setting isCrashed true: !root || !inbox || !rubbish (account details callback)

And then if I start MEGAsync again, here are the next lines that get added in MEGAsync.log, from the time it starts right up to the time where it decides that it crashed last time:

----------------------------- program start -----------------------------
09/28-22:23:56.318051 33628 DBG  Windows 10 (10.0)
09/28-22:23:56.318179 33628 DBG  Screen detected: \\.\DISPLAY1, 1920, 1170, 96.000000, 1.000000
09/28-22:23:56.318180 33628 DBG  Screen detected: \\.\DISPLAY2, 1920, 1200, 96.000000, 1.000000
09/28-22:23:56.318180 33628 DBG  Scaling not needed.
09/28-22:23:56.388629 33628 WARN Qt Warning: QCoreApplication::postEvent: Unexpected null receiver
09/28-22:23:56.388638 33628 WARN Qt Context: default    2
09/28-22:23:56.388802 33628 WARN Qt Warning: QCoreApplication::postEvent: Unexpected null receiver
09/28-22:23:56.388807 33628 WARN Qt Context: default    2
09/28-22:23:56.630604 33628 DBG  libuv version: 1.39.0 [megaapi_impl.cpp:5359]
09/28-22:23:56.630650 33628 DBG  cURL version: 7.79.1-DEV [net.cpp:207]
09/28-22:23:56.630655 33628 DBG  SSL version: Schannel [net.cpp:212]
09/28-22:23:56.630663 33628 DBG  libz version: 1.2.11 [net.cpp:236]
09/28-22:23:56.630673 33628 DBG  IPv6 enabled: 1 [net.cpp:255]
09/28-22:23:56.630677 33628 DBG  Initializing OpenSSL locking callbacks [net.cpp:279]
09/28-22:23:56.631687 33628 DBG  c-ares version: 1.17.0 [net.cpp:302]
09/28-22:23:56.638662 33628 DBG  DNS servers: 1.1.1.1,1.0.0.1 [net.cpp:479]
09/28-22:23:56.639475 33628 DBG  MegaClient Worker threads running: 1 [utils.cpp:2724]
09/28-22:23:56.640686 33628 DBG  MediaInfo version: 1909 [mediafileattribute.cpp:72]
09/28-22:23:56.640844 33628 DBG  User-Agent: MEGAsync/4.7.0.0 (Windows 10.0.19044) MegaClient/4.0.4/64 [megaclient.cpp:1343]
09/28-22:23:56.640849 33628 DBG  Cryptopp version: 820 [megaclient.cpp:1344]
09/28-22:23:56.640915 33628 DBG  libuv version: 1.39.0 [megaapi_impl.cpp:5359]
09/28-22:23:56.640925 33628 DBG  cURL version: 7.79.1-DEV [net.cpp:207]
09/28-22:23:56.640926 33628 DBG  SSL version: Schannel [net.cpp:212]
09/28-22:23:56.640928 33628 DBG  libz version: 1.2.11 [net.cpp:236]
09/28-22:23:56.640930 33628 DBG  IPv6 enabled: 1 [net.cpp:255]
09/28-22:23:56.640931 33628 DBG  Initializing OpenSSL locking callbacks [net.cpp:279]
09/28-22:23:56.645960 33628 DBG  DNS servers: 1.1.1.1,1.0.0.1 [net.cpp:479]
09/28-22:23:56.646344 33628 DBG  MegaClient Worker threads running: 1 [utils.cpp:2724]
09/28-22:23:56.646354 33628 DBG  MediaInfo version: 1909 [mediafileattribute.cpp:72]
09/28-22:23:56.646475 33628 DBG  User-Agent: MEGAsync/4.7.0.0 (Windows 10.0.19044) MegaClient/4.0.4/64 [megaclient.cpp:1343]
09/28-22:23:56.646477 33628 DBG  Cryptopp version: 820 [megaclient.cpp:1344]
09/28-22:23:56.646545 33628 INFO Establishing max payload log size: 10240
09/28-22:23:56.673560 33628 INFO MEGAsync is starting. Version string: 4.7.0   Version code: 4700.4   User-Agent: MEGAsync/4.7.0.0 (Windows 10.0.19044) MegaClient/4.0.4/64
09/28-22:23:56.673578 33628 DBG  Unknown language code: en_gb [megaapi_impl.cpp:11775]
09/28-22:23:56.673583 33628 DBG  Unknown language code: en_g [megaapi_impl.cpp:11775]
09/28-22:23:56.673584 33628 DBG  Unknown language code: en_ [megaapi_impl.cpp:11775]
09/28-22:23:56.673591 33628 DBG  Unknown language code: en_gb [megaapi_impl.cpp:11775]
09/28-22:23:56.673592 33628 DBG  Unknown language code: en_g [megaapi_impl.cpp:11775]
09/28-22:23:56.673593 33628 DBG  Unknown language code: en_ [megaapi_impl.cpp:11775]
09/28-22:23:56.674606 31536 INFO Request (SET_MAX_CONNECTIONS) starting [megaapi_impl.cpp:16147]
09/28-22:23:56.674640 31536 INFO Request (SET_MAX_CONNECTIONS) finished [megaapi_impl.cpp:16179]
09/28-22:23:56.674679 31536 DTL   Megaclient exec is pending resolutions. scpaused=0 stopsc=0 mBlocked=0 jsonsc.pos= syncsup=1 statecurrent=0 syncadding=0 syncactivity=0 syncdownrequired=0 syncdownretry=0 [megaclient.cpp:2327]
09/28-22:23:56.675042 31536 INFO Request (SET_MAX_CONNECTIONS) starting [megaapi_impl.cpp:16147]
09/28-22:23:56.675044 31536 INFO Request (SET_MAX_CONNECTIONS) finished [megaapi_impl.cpp:16179]
09/28-22:23:56.675048 31536 DTL   Megaclient exec is pending resolutions. scpaused=0 stopsc=0 mBlocked=0 jsonsc.pos= syncsup=1 statecurrent=0 syncadding=0 syncactivity=0 syncdownrequired=0 syncdownretry=0 [megaclient.cpp:2327]
09/28-22:23:56.675562 31536 INFO Request (USE_HTTPS_ONLY) starting [megaapi_impl.cpp:16147]
09/28-22:23:56.675569 31536 INFO Request (USE_HTTPS_ONLY) finished [megaapi_impl.cpp:16179]
09/28-22:23:56.675573 31536 DTL   Megaclient exec is pending resolutions. scpaused=0 stopsc=0 mBlocked=0 jsonsc.pos= syncsup=1 statecurrent=0 syncadding=0 syncactivity=0 syncdownrequired=0 syncdownretry=0 [megaclient.cpp:2327]
09/28-22:23:56.679073 33628 WARN Force reloading (isCrashed true)
mattw-mega commented 1 year ago

Hi Eldaw, thanks very much for that info, that identifies the problem. The isCrashed flag is getting set erroneously, that line is in the processing of an account details response. Probably, that request was sent before the FETCHNODES request completed. You could confirm that in your first log, searching on that you'll see the request starting and completing. That line has been present for years, but perhaps something changed with when those requests are sent. I suspect you have a larger account than most, so the fetchnodes step probably takes longer than usual, with more chance for that to occur. Anyway, I will follow up and get that fixed. In the meantime you may be able to get around it with the following procedure:

thanks

Eldaw commented 1 year ago

@mattw-mega Thanks very much, that is great news! I can confirm that by following your steps and logging in again, the client now starts up very quickly. I can also see in the log that it is happily using the cached state of every file. I've also confirmed that exiting MEGAsync and restarting it again, it still starts up quickly. So the problem does indeed appear to be resolved. Thank you!

By the way, this particular MEGA account is actually not big at all. It contains about 36000 files, totalling about 42GB in size. If it makes any difference, it's an account started right at the very launch of MEGA in January 2013.

Thanks again for your help. Hopefully the fix you'll be making should ensure that the issue doesn't come back again.

Eldaw commented 1 year ago

@mattw-mega I've discovered exactly what action causes the problem to come back. I went into Settings, Folders, and then removed one of the entries from the section 'Excluded file and folder names'. That then causes a message to be shown underneath, prompting me to restart MEGAsync. When I click on the 'Restart' button, MEGAsync does the really slow startup where it re-hashes everything from scratch. But even when it finishes, if I then restart, I'm back in the "Crash" cycle again. So it seems that after applying your workaround, for the time being I must avoid making any changes to the exclusions list.

mattw-mega commented 1 year ago

hi @Eldaw , thanks for reporting that additional case. Someone who it taking care of this will be in touch. cheers

rl-mega commented 1 year ago

Hi @eldaw! First of all, thank you for your report and your patience. The very-soon-to-be-released v4.7.1 includes a fix for the unexpected request callback which is leading to the isCrashed loop (the logs you saw documenting the cache deletes and the setting of isCrashed were intended to diagnose this particular issue). As @mattw-mega mentioned, the logic of the isCrashed mechanism is pretty ancient, and this bug brought our attention to it. As a matter of fact, the name itself of the parameter is misleading: as you noticed, it is used in case of crash, but also for unexpected situations like processing a request callback before having fetched the nodes, or when we need to do a full scan: "Force a full scan" button and changing exclusions. Furthermore, while you expect the full scan to actually do a full re-scan and thus take time, MEGAsync does not make it clear that it will happen when changing the exclusions, which adds to the confusion. We are now working to re-evaluate all this logic to provide a better user experience, and you can expect improvements pretty soon.

Eldaw commented 1 year ago

Hi @rl-mega that's good news. Thanks for the followup and detailed explanation, it is much appreciated. I'm glad I could bring attention to this issue, and it's good to hear that it will all soon be fixed.

rl-mega commented 1 year ago

Hi @Eldaw, v4.7.1 has now been published here: https://mega.nz/desktop (it is not available yet with auto-update). If you still have problems, we need to investigate more and I'll give you instructions to contact support and we'll follow-up from there.

Notes:

Thanks for your patience.

Eldaw commented 1 year ago

Hi @rl-mega, thanks for the follow-up. I'll be able to test v4.7.1 within a few days when I'm back home. I'll let you know if there are any further problems. I appreciate the quick turnaround after the right people got involved (after getting past the gauntlet of 1st line support).

rl-mega commented 1 year ago

Thank you @Eldaw. @gittyperson reported that his problem is solved, and it should work for you too. Nevertheless, if you still encounter problems, please let us know!