d1vanov / quentier

Cross-platform desktop Evernote client
GNU General Public License v3.0
134 stars 16 forks source link

[bug] First time start and not finishing evernote sync (3k notes) #391

Open Heart1010 opened 2 years ago

Heart1010 commented 2 years ago

Describe the problem I installed quentier (con. build from 9th may windows) and added my evernote login. Quentier started syncing and always got about 200-500 notes from my 3.2k notes I have on evernote (with more or less every note has a small jpg or pdf file attached). I checked the task manager on win10 and after that 200-500 notes I got with the sync the cpu usage of quentier stayed high at about 20-40% for another ~30 minutes and went down to zero then. At this point I can't do/click anything in quentier and I have to kill the task.

After a quentier restart and sync again I got the next 200-500 notes... I did that cycle again and again like described above.

Now after about one day I have all my evernote notes in quentier but a sync still not gets 'really finished' I think!? Why I think that? Because cpu usage is still high for that mentioned ~30 minutes and I also have mostly always thais on the bottom status line (always 74.13 - what does that mean!? 74.13%?)

image

So how I can help you more to find the reason for that 'not really 100% finishing evernote sync'?

Environment info OS - Win10 Con. build from 9th may (downloaded from GitHub releases)

d1vanov commented 2 years ago

Hi, thank you for the report.

If the sync is interrupted, the next sync attempt might have to download the same data from Evernote again, just to ensure that the data stored locally is relevant. It might explain that even though you see the downloaded content the sync still appears busy.

Current sync logic is admittedly not perfect. Right now I'm rewriting it from scratch, trying to make it more reliable but it would take months if not years before it would reach even the unstable version.

You can try to collect the debug level logs during sync, this article explains how to do it. Don't set trace log level, it would most likely overwhelm the log and slow things down way too much. Also probably there's no need to wait for 30+ minutes - when it gets to that 74.13 percent (yes, it's percentage), you can stop the sync, the log should capture enough info by that moment.

Heart1010 commented 2 years ago

zip file removed Please let me know when you downloaded it - I will remove the zip afterwards (or you can do it also after downloading, thanks)

d1vanov commented 2 years ago

Downloaded, thanks.

d1vanov commented 2 years ago

From a quick glance at the log I can say the following: unfortunately the log doesn't appear to contain the start of the sync. Probably it was due to log file rotation. But nevertheless it has captured the confirmation of my hypotheses:

MainWindow::onSyncChunksDownloadProgress: highest downloaded USN = 56206, highest server USN = 56206, last previous USN = 750

This line is the last progress update of downloading the sync chunks. USN stands for "update sequence number" - it is a number assigned by Evernote to every data item within your account - note, notebook, tag etc. It is an ever increasing number, the highest value belongs to the most recently created or modified data item within the account. "Last previous USN" stands for the USN that Quentier has saved during the previous sync as the one below which all data items are guaranteed to be downloaded. The numbers - 750 vs tens of thousands - indicate that Quentier actually managed to guarantee that quite a few data items were fully downloaded. Note that the guarantee vs what was actually downloaded might not be in agreement because the sync has to either complete or be stopped manually while the app is working to evaluate which data items it has managed to fully download this time. If you kill the app after it has downloaded something, it has no chance to do this evaluation so the next time the cycle would continue again.

I don't see any warnings or errors in the log so it doesn't seem like there's any problem with processing the data. If it was, the sync would stop itself and complain in the status bar that something goes wrong. But it doesn't.

As far as I can see for now, Quentier is trying to re-download the already downloaded notes and a lot of them. The status in the progress bar seems a little misleading as it doesn't reflect the actual stage of the sync - it's no longer processing sync chunks, it's downloading notes now. Probably the status bar is just not cleared after the sync chunks processing is finished while notes downloading hasn't started yet, I'll look into it in more detail later.

What I can recommend for now - try to repeat the sync but don't kill the app, instead try to press the sync button again to stop the sync - it should cause the re-evaluation of items up to which USN were guaranteedly downloaded this time. You can judge by this line in the log which I cited above - the last call of MainWindow::onSyncChunksDownloadProgress with highest downloaded USN equal to highest server USN indicates the finalization of sync chunks downloading while last previous USN means the progress done during previous sync. See whether the tactic of stopping the sync after you can't want to wait anymore gets this last number to increase in subsequent sync.

Alternatively you can check this number in the persistent data of the app - it should be in C:\Users\%USERNAME%\AppData\Roaming\Quentier\EvernoteAccounts\<your-account-dir>\settings\SynchronizationPersistence.ini, the field would be in [Synchronization] section called somewhat like <something>\last_sync_params\last_sync_update_count.

Heart1010 commented 2 years ago

See whether the tactic of stopping the sync after you can't want to wait anymore gets this last number to increase in subsequent sync.

This tactic doesn't increase the number... it always stays at 750

2022-05-12 12:11:02.483 quentier\bin\quentier\src\MainWindow.cpp:2308 [Info] [quentier:main_window]: MainWindow::onSyncChunksDownloadProgress: highest downloaded USN = 56208, highest server USN = 56208, last previous USN = 750

I pressed the sync icon again to stop syncing when I had that 'Processing data from sync chunks: 74.13' in the status line.

If I wait here a few minutes longer I can't click anything in the app anymore (that was the reason I've looked into the task manager - when I saw quentier has high cpu usage I let them work until this usage gets down to zero, after that I killed the app because as said I can't click anything anymore at this stage and opened it again and did sync again - with this technic I got all my notes into the app.)

d1vanov commented 2 years ago

Ok, then I need to understand why the GUI thread gets blocked in your case. My hypotheses is that it's busy processing the updates of notes which get downloaded and updated one by one in the background. Because there are so many notes, there are so many callbacks that GUI thread executes so it looks like it hangs.

The answers to this stackexchange question provide some ways to look into the backtraces of a running process on Windows. Can you please try to use either of them to get the backtraces from Quentier when it appears hanged? I'm interested primarily in GUI thread, I'm not sure what its name would be in the process explorer but probably somewhat like "Quentier.exe\<something>". It would be useful to post the pic with all the thread names as well, maybe some others would be interesting too.

A couple of other tricks you could try in theory:

  1. More or less safe one - let Quentier run sync overnight. There's still no guarantee it would be enough time for it to finish downloading and reconciling stuff but you might as well try it.
  2. More like a nuclear option - in that SynchronizationPersistence.ini file that I mentioned above you could change that number corresponding to the last update count to the highest from your account, i.e. 56208. But be aware that Quentier would then think it has downloaded all the stuff below that USN and won't try to do that again. It might seem to you that you have all notes from your account downloaded but a few might still be missing. If you go for that option, these notes won't be re-downloaded unless you modify them through some other Evernote client (it would give them higher USN) and then sync.
Heart1010 commented 2 years ago

1) Already did that.... but as mentioned after about ~30 mins the cpu usage from quentier goes down from ~30% to 0% and and I've let it running also with that 0% overnight, but nothing happens here (as the gui isn't also not responding anymore)

I went with 2) now and test further if a local change will be synced back to evernote cloud image

update: I ran one, two times now to the situation where I edited a note in quentier and when I want to sync (back to evernote) I had this in the status line image

d1vanov commented 2 years ago

Sorry I did not notice the comment's update a month ago. If it's still relevant, could you please collect and attach debug or trace logs while trying to sync modified notes with Evernote?

This status line means you tried to send some locally changed note to Evernote which Evernote has no knowledge of. It might be due to the fact that in Evernote you had deleted this note previously.

It might be the consequence of the nuclear option you used to overcome the problems with initial sync - although it seemed to you that all of the account's data has been synchronized, apparently some of the recent deletions might not have been synchronized so you ended up having phantom data items in Quentier's local storage which you can't sync back to Evernote. That's a hypothesis. I might be able to say more if you provide me with the logs.

Overall, although it saddens me to say this but the truth is, the current synchronization algorithm which Quentier uses is not really suitable for use with very large accounts. I know how to make it suitable and I'm already working on it but, as I said, it would take months if not years before I can deliver the solution.

charlescanato commented 1 year ago

Dmitry, I have less notes than @Heart1010 but still a good number. Not sure, but I guess that around 2000.

In my case, the download of all notes seemed to finish (still need to confirm it in a comparison), but I have the exact same error message when trying to sync up my local changes. I've already cleaned everything and started a new database two or three times, so this is surely reproducible.

Also I didn't do any of those options. Just using what's available in the UI.

Just wanted to say this in case you make any changes in any future time and might want a test.

I'll keep the database updated, just downloading updates I do in my notes (with NixNote2), since I can't upload changes through Quentier, for while.

d1vanov commented 1 year ago

Hmm. That's strange, I've never had such issue myself. Are you sure the initial sync runs to completion?

It would help if you could collect and share debug logs from initial sync until the moment the issue happens. This comment above has explanation how to do it.

charlescanato commented 1 year ago

Can't say I'm completely sure - but will test it from scratch.

One side effect I just noticed this weekend - one note I have changed had problems with syncing up as said above. Some duplicates even appeared in the process, and I always tried to delete them. Anyway, when using Evernote offical client on Android, I was able to open the note, edit it, but received a "Invalid URI" when closing the note (when EN tries to sync it). Strangely, I was able to open and update it in NixNote2 - seems the situation is fixed.

Well, anyway, I'll start from zero with debug logs. I'll probably have it by tomorrow morning.

P.S.: do we have any way of sending files (or pwpushes, or links, etc.) privately here? I know the traces have lots of personal data, don't know about the debug logs yet.

charlescanato commented 1 year ago

Well, as promised, I did it. Erased "Appdata\Local\quentier.org", started it, credentials and let it download.

It downloaded all notes, as in the previous tries.

Changed one note, tried to sync it. Worked. Another. Worked. This time I couldn't reproduce it. It's bad, but it's good. :-) I've saved the logs but I don't think they'd be helpful in this case - except if you do want them anyway.

Eventually, it gave me the same "failed to update" error when I was getting comfortable: I know my steps more or less, but then I'd say it's another bug title.