d1vanov / quentier

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

Initial sync seems to be stuck in the middle #183

Closed robert7 closed 6 years ago

robert7 commented 6 years ago

Initial sync seems to be stuck exactly at 50%. Status bar info isn't updating anymore. According to log the app is still doing something (could be all is OK), but the not updated status is confusing.

Also many notes display "Please select some existing note..." - maybe just the header is downloaded (?) - which is also confusing.

..I don't want to post log here as with TRACE level it is very huge and contains my notes; I can try to recreate later with some test data. quentier-initial-sync

robert7 commented 6 years ago

After app restart, the sync seems to continue, but the status info isn't updated, so I have no idea how far it is. quentier-initial-sync2

d1vanov commented 6 years ago

Which version are you using? Please always specify the used version and OS in bug reports. I would actually recommend using the development version since in it some sync errors were fixed along with the introduction of sync tests - d1vanov/libquentier#54 and d1vanov/libquentier#60.

d1vanov commented 6 years ago

My guess is that you've encountered the API rate limit breach. I have actually never managed to encounter it with my account and so haven't tested its handling. The actual sync algorithm within libquentier should be processing it correctly in the development build as it's been checked with automated tests. However, the handling of API rate limit breach in UI might not work properly.

d1vanov commented 6 years ago

If it was indeed the API rate limit breach, the log should contain SynchronizationManagerPrivate::onRateLimitExceeded string. And shortly after that another entry - MainWindow::onRateLimitExceeded: <number of seconds to wait>. If you find these entries, you can cut a portion of log around these lines with the contents of your notes removed from the log as it shouldn't be really important.

robert7 commented 6 years ago

I used "ppa:d1vanov/quentier-stable" on Ubuntu 16.04 with Qt 5.5.1 OK i'll switch to development PPA. Btw I can reproduce the "rate limit exceeded" with nixnote2 quite easily. Should be same for quentier; I can post more details later.

robert7 commented 6 years ago

:) OK the development version doesn't even start (from ppa:d1vanov/quentier-development)

$ quentier
quentier: symbol lookup error: quentier: undefined symbol: _ZN8quentier22SynchronizationManager8finishedENS_7AccountEbb

d1vanov commented 6 years ago

It seems you didn't reinstall libquentier from development PPA.

robert7 commented 6 years ago

yes. sorry. this was my fault. the app from "ppa:d1vanov/quentier-development" works now

robert7 commented 6 years ago

ok. it does start now, but crashes on sync attempt crashinfo.zip i think I need to compile myself :)

d1vanov commented 6 years ago

Oh. Crashes are really bad things... I'll take a look at it but I would only be able to do so tomorrow or even later. You can of course build Quentier yourself but it won't fix the crashes magically. It would enable you to look at the crash backtrace yourself and figure out where within the code something goes wrong. And maybe even try to fix it.

robert7 commented 6 years ago

You can of course build Quentier yourself but it won't fix the crashes magically. It would enable you to look at the crash backtrace yourself and figure out where within the code something goes wrong.

:D yes. I meant exactly that.

robert7 commented 6 years ago

....I think the compiler which would "magically" fix the bugs, wasn't invented yet... actually good for us, because else we would be out of jobs

d1vanov commented 6 years ago

Looked at the crash dump. The bad news is that the crash seems to happen well outside Quentier's own code:

Thread 17 (crashed)
 0  0x40
    rax = 0x00007ff3e0008b40   rdx = 0x00007ff3e0001c00
    rcx = 0x0000000000000000   rbx = 0x00007ff412d063e0
    rsi = 0x0000000000000000   rdi = 0x00007ff3e0001f60
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee418
     r8 = 0x0000558f42b52701    r9 = 0x0000000000000000
    r10 = 0x0000000000000000   r11 = 0x0000000000000206
    r12 = 0x0000558f428a1e10   r13 = 0x00007ff3e0001ce0
    r14 = 0x00007ff3e0001f60   r15 = 0x0000000000000000
    rip = 0x0000000000000040
    Found by: given as instruction pointer in context
 1  libQt5Core.so.5.5.1 + 0x2b8f49
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee420
    rip = 0x00007ff412c65f49
    Found by: stack scanning
 2  libQt5Core.so.5.5.1 + 0x3593e0
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee478
    rip = 0x00007ff412d063e0
    Found by: stack scanning
 3  libQt5Core.so.5.5.1 + 0x3593e0
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee498
    rip = 0x00007ff412d063e0
    Found by: stack scanning
 4  libqt5keychain.so.0.7.0 + 0x16cfc
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee4d0
    rip = 0x00007ff411462cfc
    Found by: stack scanning
 5  libQt5Core.so.5.5.1 + 0x2b4ada
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee510
    rip = 0x00007ff412c61ada
    Found by: stack scanning
 6  libc-2.23.so + 0x8453c
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee600
    rip = 0x00007ff411ba953c
    Found by: stack scanning
 7  libQt5Core.so.5.5.1 + 0x2bcb48
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee650
    rip = 0x00007ff412c69b48
    Found by: stack scanning
 8  libqt5keychain.so.0.7.0 + 0x6dd3
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee6c0
    rip = 0x00007ff411452dd3
    Found by: stack scanning
 9  libqt5keychain.so.0.7.0 + 0x16d0c
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee6d0
    rip = 0x00007ff411462d0c
    Found by: stack scanning
10  libQt5Core.so.5.5.1 + 0x2b5c01
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee710
    rip = 0x00007ff412c62c01
    Found by: stack scanning

So the bug causing this crash can be anywhere: it can still actually be caused by Quentier or libquentier or it can be inside libqt5keychain or it can be inside Qt. Probably the best thing you could try is to run quentier under gdb so that in case of a crash you can receive a more meaningful backtrace.

d1vanov commented 6 years ago

I wasn't able to reproduce the crash myself but I found some other problems with sync in development version, will try to fix them shortly. The PPA updates daily so you'd have to wait for some time to get the version with fixes. Meanwhile you can try to build Quentier yourself and to debug the crash you are getting.

d1vanov commented 6 years ago

Just in case, there's an article on building of Quentier's dependencies on various platforms.

robert7 commented 6 years ago

So I tried few times, I can get through the initial sync. It seems the sync restarts from beginning after each app restart. I got few time up to 40% or 60% but never up to finish. I will later try to compile myself.

d1vanov commented 6 years ago

Sorry that it doesn't work for you. That's what early adopters of alpha version usually get, unfortunately.

I suppose the sync halting is either due to improper handling of API rate limits exceeding or probably something is screwed up in the bookkeeping during sync so that it starts waiting for some event forever. The synchronization is in large part asynchronous so it maintains various lists of pending events and waits for certain events to finish before continuing. It can also be some uncaught exception in which case the word "exception" should be greppable from the log.

I actually have some thoughts how to make the sync process more troubleshooting friendly: since the sync is in large part asynchronous, it should be possible to communicate with the synchronization manager asking it to perform some self-diagnostic or to print the contents of pending events lists. It requires some development though.

d1vanov commented 6 years ago

Also, when you'll be building stuff to investigate deeper, please use development branch of everything - QEverCloud, libquentier and Quentier. At least the synchronization code is different enough in development than in master and there are 86 tests for synchronization logic in development branch so it at least should be much more robust than master version.

robert7 commented 6 years ago

OK. I'll have only little time now during week, but I will have some more at end of the week. So I will compile & run in debugger.

robert7 commented 6 years ago

I actually have some thoughts how to make the sync process more troubleshooting friendly ...

I think one thing which could help, would be to increase a bit the count of INFO messages. Maybe switch some strategically selected logs from DEBUG level to INFO.

Because currently there are almost none (at least for the initial sync). So currently there is option either almost no logging (with INFO) or really much logging (like tens on megabytes - DEBUG or TRACE). This could help at least for little advanced users.

d1vanov commented 6 years ago

It could be useful, indeed. However, one other thing which would be nice to have is some command line utility capable of grepping the already produced debug/trace log on per-log-entry basis. Then it would be possible to filter the collected debug/trace log to focus on relevant things and then, when some suspicious place is found, look at the original debug/trace log at a known place of it.

robert7 commented 6 years ago

However, one other thing which would be nice to have is some command line utility capable of grepping the already produced debug/trace log on per-log-entry basis.

But exactly this would you reach by putting those statements at INFO. Then you can use some logviewer (e.g. glogg) to filter by INFO or what ever you want and just by click see the whole context.

Is there some reason why you don't add ".gitignore" to all of your repositories? :) E.g. the "build" directory you suggest to use in INSTALL.md would be a candidate to add to .gitignore.

robert7 commented 6 years ago

I succeeded to compile the app with development branch(es). Your intro documents related to compiling are great! I could repeat the segmentation fault while running in debugger, but could not so far see anything useful out the stacktrace. I looks some unknown event was received and that crashed the event loop. q-segv-stacktrace

So I deleted ~/quentier and did a retry of first run with my development build. Everything was well, the intro note was displayed and the dialog with prompt to Evernote login. I could login. I did a login with a test account with 150 notes and the initial sync went without problems. In case I can repeat the event-loop problem later, I will investigate in more details.

update: :( it happens also with the test account. so I will need to find the cause else I can't sync anything

d1vanov commented 6 years ago

Haven't heard of glogg before, will need to take a look into it.

I was hoping someone would appreciate the effort I put into writing these docs :smiley: Glad you found them helpful.

Can't really comment anything about the crash, it looks like it would require a handful of effort to figure out its reason. So far I wasn't able to reproduce it myself.

You must have something special in your notes which breaks the logic of the sync algorithm. If you can share the trace log from your test account i.e. if it doesn't contain any sensitive private content, I could try to investigate the reason in parallel with you.

d1vanov commented 6 years ago

I totally forgot about one thing you can try and see whether it makes any difference for the sync: disable the downloading of ink note images and/or note thumbnails during the sync: "Service" -> "Preferences" -> "Synchronization" tab -> two checkboxes with relevant names. On the first sync these would be enabled by default, however, since you now have your custom built version, you can disable this in MainWindow::setSynchronizationOptions.

d1vanov commented 6 years ago

Also forgot to answer the question about .gitignore: I just don't consider it a good practice to put this file under git version control: different people might want to ignore different files within their repos and having the centralized list of such things only adds unnecessary complications to their workflow. Some repos do include .gitignore nevertheless and I have to edit .git/info/exclude file to make git not care about some files I wish it would ignore but don't want to do it via .gitignore since it's under version control and I have no idea what would the repo owner say if I open a PR containing a change to .gitignore - maybe he would freak out and say .gitignore is sacred and shouldn't be touched :smiley: I haven't seen such a thing here on GitHub but have once encountered a similar situation at work, it wasn't much pleasure.

robert7 commented 6 years ago

Still no idea about the seg. fault, but it doesn't happen, if the logging is set to TRACE. With TRACE the sync finishes, but doesn't upload the notes (I created 3 new test notes). I attach full log with TRACE level: Quentier-log.zip

To be honest, I never saw a repository used by a bigger team without .gitignore. Can't imagine how a repository could be used by 20 people and each new team member should set a list of ignored files by himself (sometimes we have like 50 lines). So I can workaround it here. But I really see no problem to have it checked in.

We also always check the IDE project files in (with few exceptions of the user settings which go to .gitignore). This way new team members using same IDE get some minor advantage and people using other IDE just don't care about project file for foreign IDE. I can also workaround it here, but I find it a bit unnecessary hurdle. I can put the IDE files on gitignore but then I can easily lose them when cleaning/switching branches which is again unnecessary.. :(

d1vanov commented 6 years ago

Thanks, will look into the log later.

I would still prefer to not have .gitignore checked in. I understand there are different workflows and in some having some files ignored by default might make sense. But I don't think Quentier is that kind of project actually - create a build folder, add it to .gitignore and you should be fine. I usually have two build folders in fact - one for Qt4 build and one for Qt5 one. I don't use any IDE myself (but QtCreator for .ui files) so I don't know where common IDEs put their stuff but putting it into the build folder should work well enough. Plus, I wouldn't like to distribute any IDE's project files along with Quentier sources because I have no intention to support them. CMakeLists.txt should be enough for everyone to generate project files for their IDEs.

d1vanov commented 6 years ago

Looked into the log, there are indeed some problems with sending new notes to Evernote:

Sending new note: Note: {
localUid: 7e62a017-4613-4024-848e-129a4a995332;                                                                         
guid is not set;                                                                                                        
updateSequenceNumber is not set;                                                                                        
title is not set;                                                                                                       
content: <en-note><div></div></en-note>;                                                                                
contentHash is not set;                                                                                                 
contentLength is not set;                                                                                               
creationTimestamp: 1531854631047, datetime: 1531854631047 (2018-07-17 21:10:31.047 CEST);                               
modificationTimestamp: 1531854631047, datetime: 1531854631047 (2018-07-17 21:10:31.047 CEST);                           
deletionTimestamp is not set;                                                                                           
active is not set;                                                                                                      
notebookGuid: d1e41f1f-8082-4555-9ad1-31b1c4aa8385;                                                                     
notebookLocalUid: d9993d09-5f46-4859-828b-c6d909db5365;                                                                 
tagGuids are not set;                                                                                                   
tagLocalUids are not set;                                                                                               
thumbnail is null;                                                                                                      
resources are not set;                                                                                                  
attributes: qevercloud::NoteAttributes: {                                                                               
  subjectDate = <empty>;                                                                                                
  latitude = <empty>;                                                                                                   
  longitude = <empty>;                                                                                                  
  altitude = <empty>;                                                                                                   
  author = <empty>;                                                                                                     
  source = <empty>;                                                                                                     
  sourceURL = <empty>;                                                                                                  
  sourceApplication = Quentier;                                                                                         
  shareDate = <empty>;                                                                                                  
  reminderOrder = <empty>;                                                                                              
  reminderDoneTime = <empty>;                                                                                           
  reminderTime = <empty>;                                                                                               
  placeName = <empty>;                                                                                                  
  contentClass = <empty>;                                                                                               
  lastEditedBy = <empty>;                                                                                               
  creatorId = <empty>;                                                                                                  
  lastEditorId = <empty>;                                                                                               
  sharedWithBusiness = <empty>;                                                                                         
  conflictSourceNoteGuid = <empty>;                                                                                     
  noteTitleQuality = <empty>;                                                                                           
};                                                                                                                      
;                                                                                                                       
shared notes are not set;
isDirty: true;                                                                                                          
isLocal: false;                                                                                                         
isFavorited = false;                                                                                                    
};                                                                                                                      

2018-07-17 21:55:59.018 CEST libquentier/src/synchronization/SynchronizationManager_p.cpp @ 709 [Debug]: SynchronizationManagerPrivate::onSendLocalChangesFailure: Failed to send new and/or mofidied notes to Evernote service, DATA_REQUIRED exception during the attempt to create a note
2018-07-17 21:55:59.018 CEST libquentier/src/synchronization/SynchronizationManager_p.cpp @ 213 [Debug]: SynchronizationManagerPrivate::stop

That is kinda strange because according to Evernote API docs the exception with this error code should occur if the new note contains a resource which lacks the data body. However, the note attempted to be sent contained no resources. I'm puzzled about what happens here, to be honest. Maybe we are facing this error due to some undocumented convention of Evernote to not accept empty notes (this one contains only an empty div), so perhaps it'd be worth trying to enter some "hello world" content into the note and try syncing again.

d1vanov commented 6 years ago

Also, about the mysterious crash: are building Quentier against system built-in Qt libs which are of 5.5 version? If yes, you can building against Qt 5.11.1 from this launchpad repo. If the crashes would disappear (although I think it is unlikely), we would know it has something to do with a particular Qt version.

d1vanov commented 6 years ago

And one more thing about the crash: I tried to investigate this crashdump in more details and I can see that the stack contains something for libqt5keychain.so.0.7.0:

Thread 17 (crashed)                                                                                                     
 0  0x40                                                                                                                
    rax = 0x00007ff3e0008b40   rdx = 0x00007ff3e0001c00                                                                 
    rcx = 0x0000000000000000   rbx = 0x00007ff412d063e0                                                                 
    rsi = 0x0000000000000000   rdi = 0x00007ff3e0001f60                                                                 
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee418                                                                 
     r8 = 0x0000558f42b52701    r9 = 0x0000000000000000                                                                 
    r10 = 0x0000000000000000   r11 = 0x0000000000000206                                                                 
    r12 = 0x0000558f428a1e10   r13 = 0x00007ff3e0001ce0                                                                 
    r14 = 0x00007ff3e0001f60   r15 = 0x0000000000000000                                                                 
    rip = 0x0000000000000040                                                                                            
    Found by: given as instruction pointer in context                                                                   
 1  libQt5Core.so.5.5.1 + 0x2b8f49                                                                                      
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee420                                                                 
    rip = 0x00007ff412c65f49                                                                                            
    Found by: stack scanning                                                                                            
 2  libQt5Core.so.5.5.1 + 0x3593e0                                                                                      
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee478                                                                 
    rip = 0x00007ff412d063e0                                                                                            
    Found by: stack scanning                                                                                            
 3  libQt5Core.so.5.5.1 + 0x3593e0                                                                                      
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee498                                                                 
    rip = 0x00007ff412d063e0                                                                                            
    Found by: stack scanning                                                                                            
 4  libqt5keychain.so.0.7.0!_fini + 0x640                                                                               
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee4d0                                                                 
    rip = 0x00007ff411462cfc                                                                                            
    Found by: stack scanning                                                                                            
 5  libQt5Core.so.5.5.1 + 0x2b4ada                                                                                      
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee510                                                                 
    rip = 0x00007ff412c61ada                                                                                            
    Found by: stack scanning                                                                                            
 6  libc-2.23.so + 0x8453c                                                                                              
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee600                                                                 
    rip = 0x00007ff411ba953c                                                                                            
    Found by: stack scanning
 7  libQt5Core.so.5.5.1 + 0x2bcb48                                                                                      
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee650                                                                 
    rip = 0x00007ff412c69b48                                                                                            
    Found by: stack scanning                                                                                            
 8  libqt5keychain.so.0.7.0!QKeychain::WritePasswordJob::WritePasswordJob(QString const&, QObject*) + 0x5e3             
    rbp = 0x00007ff3ea3ee780   rsp = 0x00007ff3ea3ee6c0                                                                 
    rip = 0x00007ff411452dd3                                                                                            
    Found by: stack scanning

while with AppImage I actually distribute qtkeychain library named differently: libqt5keychain.so.1. Don't you by any chance have some version of qtkeychain library installed e.g. within /usr/local/lib/x86_64-linux-gnu? I noticed before that AppImages seem to "prefer" libraries from /usr/local prefix rather than their own bundled versions for some reason.

d1vanov commented 6 years ago

I have a suspect that wrong versions of one or more libraries are being linked in: if wrong version of libqt5qevercloud is linked, it can explain the sync halting and not sending new notes; wrong version of libqt5keychain can probably be related to this mysterious crash. Did you reinstall libqt5qevercloud after switching to the development PPA? Can you post the output of ldd /usr/bin/quentier?

robert7 commented 6 years ago

I uninstalled the quentier from PPA - currently I only using the version I compiled myself. Today I'm busy, I will look at the issues later this week.

d1vanov commented 6 years ago

Ok, take your time 😃

robert7 commented 6 years ago

Maybe we are facing this error due to some undocumented convention of Evernote to not accept empty notes (this one contains only an empty div), so perhaps it'd be worth trying to enter some "hello world" content into the note and try syncing again.

there was 1 node (from 3 I created) without body. I written something in the body, but nothing changed. Sync "stopps", but notes are not uploaded.

d1vanov commented 6 years ago

Currently the sync is very coward and tries to stop on the first encounter of any kind of failure, so if the first note doesn't sync for whatever reason, the other two don't get a single chance to sync. Probably some kind of error tolerance could be introduced in future but right now it works like that.

Could you please attach another log of the attempt to sync the note after specifying the body? Just to double check whether the error code remains the same. If it indeed does, we need to make sure the compatible version of QEverCloud library is used when the app is running (it may be different version of QEverCloud than the one used during build), ldd should be able to tell that.

robert7 commented 6 years ago

as far as I can see, the log message seems to be the same

2018-07-18 15:51:45.980 CEST src/MainWindow.cpp @ 1793 [Debug]: MainWindow::onSynchronizationManagerFailure: Failed to send new and/or mofidied notes to Evernote service, DATA_REQUIRED exception during the attempt to create a note

I'm attaching ldd output and "ls -l /usr/local/bin" - I believe the correct libsa are used (the ones I compiled yesterday with development branches for libquentier & libevercloud)

logs.zip ls_usrlibx86_64-linux-gnu.log

d1vanov commented 6 years ago

Wow, now that's really puzzling. I would perhaps advice to add some logs to NoteStore::createNote and to NoteStore::processEdamUserExceptionForNote within libquentier to try and locate the problem further. Now I'm starting to think it might be a bug in QEverCloud library. Speaking of which, are you using gcc to build things? If yes, which version of it? 5.3, the default for Ubuntu 16.04? I'm asking because I have once had to workaround a compiler bug in QEverCloud. Maybe you could try to build QEverCloud without optimization irregardless of gcc version and see if it would change anything.

d1vanov commented 6 years ago

One other experiment might be building QEverCloud with clang - you'd need to install clang and then to pass -DCMAKE_C_COMPILER=$(which clang) -DCMAKE_CXX_COMPILER=$(which clang++) to cmake.

robert7 commented 6 years ago

Sorry, I'm not much familiar with cmake. How do I see which compiler was used?

I have gcc version 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.10) I suppose this was used to compile. How I can confirm?

update: I think /usr/bin/c++ was used, which is g++ "5.4.0"

d1vanov commented 6 years ago

How do I see which compiler was used?

In the build folder there should be a file called CMakeCache.txt. Inside this file search for lines starting with CMAKE_C_COMPILER and CMAKE_CXX_COMPILER, they contain paths to used compilers. In order to use another compiler, namely clang, you'd need to cleanup the build folder (or pick a new one) and then repeat the entire build process starting from cmake doing precisely the same as before only with two additional flags passed to cmake: -DCMAKE_C_COMPILER=$(which clang) -DCMAKE_CXX_COMPILER=$(which clang++)

d1vanov commented 6 years ago

I was able to reproduce this problem with new note not sending due to DATA_REQUIRED exception. Building QEverCloud with clang won't help since I reproduced this having QEverCloud library built with clang. This error looks quite strange and for now I can't figure out the cause but I will surely try my best to do so.

d1vanov commented 6 years ago

Furthermore, I was also able to reproduce the crash and I believe it is the same mysterious one that you encountered. It seems to be somehow related to the threading and QtKeychain:

QObject: Cannot create children for a parent that is in a different thread.                                             
(Parent is QKeychain::ReadPasswordJobPrivate(0x5bbd720), parent's thread is QThread(0x238a200), current thread is QThread(0x512a050)

Shortly after that the crash occurs. Looks like some kind of race in which some thread randomly corrupts memory thus sometimes causing the crash. Haven't understood the exact reason yet, will keep digging.

d1vanov commented 6 years ago

Ok, I think I understood what this threading problem was about: I meant to put the synchronization events processing into a separate thread but it looks like I miserably failed to actually do that: inside libquentier there's a public class called SynchronizationManager and its private counterpart - SynchronizationManagerPrivate. Inside quentier app I can only operate by the public class - for one thing, I move that public class to a separate thread. But the problem is: SynchronizationManagerPrivate class is not a child (in QObject parent-child relations terms) of SynchronizationManager so its thread was not changed along with its parent's one. So SynchronizationManagerPrivate continued to run in the GUI thread. Probably calling some method of SynchronizationManager inside a separate thread meant to be sync thread caused the synchronous call of some method of SynchronizationManagerPrivate which operated in GUI thread; that in turn caused some problems within QtKeychain library and sometimes things crashed due to these problems.

I have just pushed a fix for this crash problem to libquentier's development branch. Things don't seem to crash for me anymore, however, I can see another occurrence of QObject: Cannot create children for a parent that is in a different thread within the log which doesn't seem to be related to QtKeychain anymore but to something else. It is possible that thing, whatever it is, is causing the initial sync to halt at some point.

Furthermore, it seems that I understood the cause of that DATA_REQUIRED exception: QtKeychain failed to retrieve the authentication token which should be used to interact with Evernote - it was received during the initial sync from Evernote, then it should have been written to the system keychain but it seems that failed. Then, during the attempt to send new notes to Evernote, that auth token failed to be read from the system keychain but due to missing error checking somewhere the attempt to sync continued and lead to this reject from Evernote - because we tried to contact it with empty auth token. Need to find the place within the code where I screwed up the error checking.

And one more thing: once I realized the above described problem with the auth token, I decided to start a fresh sync with my test account because, well, there doesn't seem to be an easier way to "resurrect" the presence of the auth token in the system keychain. I did the initial sync with trace level logs enabled and I managed to get my sync to halt in the middle of the process. Attaching the logs here to ensure I won't lose them.

I hope that finding the root cause of sync halt and fixing it should put this issue to an end.

Bugs are surely no fun to encounter and most of the time they are not much pleasant to investigate but when you finally understand what the hell is going on, it feels oddly satisfying. I'm sorry you bumped into these issues but hopefully now it should be more or less clear how to fix them.

trace_level_log_on_sync_not_finishing.txt.tar.gz

robert7 commented 6 years ago

ok. good news. I'll look later in more detail!

pls add some logging with ERROR level for the case when token retrieval from keychain fails - so we will see this clearly next time it occurs somewhere

d1vanov commented 6 years ago

I decided to do a simple short term solution to this threading problem and run the most part of the sync logic in the GUI thread. The heaviest part of sync logic is downloading of full note contents including the resources (attachments) but that part is performed asynchronously i.e. it doesn't block whatever thread executes this logic. Given that due to my failure it worked like this before, it should be bearable for now at least. In future I might try to fix this threading problem properly but it would require some more dedicated effort.

I've also figured out I was wrong about that DATA_REQUIRED thing. Turns out it's not actually due to the auth token - after fixing that thing involving QtKeychain the auth token is saved and restored properly but the error still triggers. I figured out I didn't print the contents of a supplementary string to this error code. When I did print it, it said "Note.title". So Evernote doesn't seem to like that the new note has no title, that's it.

After digging a bit into their documentation I found out that there's a note attribute called noteTitleQuality and the doc says:

Clients MUST set this attribute to one of the following values when the corresponding note's title was not manually entered by the user: EDAM_NOTE_TITLE_QUALITY_UNTITLED, EDAM_NOTE_TITLE_QUALITY_LOW, EDAM_NOTE_TITLE_QUALITY_MEDIUM or EDAM_NOTE_TITLE_QUALITY_HIGH.

So I thought that for a title-less note I should set this attribute to EDAM_NOTE_TITLE_QUALITY_UNTITLED. I did but it didn't help a single bit, the same error - DATA_REQUIRED with explanation string of Note.title is returned in response. I'm kinda puzzled and can't figure out why on Earth do I get this. Perhaps I should try and ask Evernote folks why note title is a hard requirement now.

d1vanov commented 6 years ago

Since Quentier uses the unofficial implementation of Evernote API - QEverCloud, - I should perhaps try to reproduce this with some of their official SDKs, for example, with Python one. If I manage to get the same error, it would be legitimate to ask Evernote guys about this.

d1vanov commented 6 years ago

On the other hand I could probably simply try to generate some note title - for example, if note has some non-empty content, I could use its first phrase for a title. Otherwise I could name the note somewhat like "untitled note". And set the note title quality attribute appropriately.

Also need to find out if note title is mandatory only for new notes or also for updated ones.

robert7 commented 6 years ago

I think simply set default title (either to "Untitled note" or to first phrase) is easiest fix here. I always set note title manually myself. So I would not spend much time investigating why empty title is not accepted.

I was now able to do a full sync with a very small test account with like 5 notes and also few incremental sync (with ratio 3 incremental sync to 2 crashes :) ). So its quite progress :)

After some random edits it got stuck with another problem: "Error description = can't do the partial update of note's resources, found invalid resource linked with note, Resource's data body is not set, requestId = QUuid({e5d9302d-545d-4a08-bdb3-2b2cc856f8ce})" "2018-07-20 08:50:12.479 CEST "libquentier/src/synchronization/RemoteToLocalSynchronizationManager.cpp @ 1305 [Warn]: Failed to add the data item fetched from the remote database to the local storage, can't do the partial update of note's resources, found invalid resource linked with note, Resource's data body is not set".

Another thing I find a bit "sub optimal" is, that once I have one local offending note which is blocking sync for some reason - I can't get rid out of it. Even if I delete it, it seems to be involved in sync. I can't really delete it from "deleted notes". I fixed the issue by deleting ~/.quentier & doing a full sync - but this isn't option for real accounts with big amount of notes.

(I will play with it further and create separate issue, if I find some reproducible behavior.)

d1vanov commented 6 years ago

with ratio 3 incremental sync to 2 crashes

Under crashes you mean the actual crashes of Quentier process, not sync failures? If so, then it needs to be investigated and fixed. Crashes should not be acceptable.

Sync failures need to be investigated as well. The one you cited a log for seems to be something special, worthy of its own issue.

Yes, I agree, sync error reporting is almost missing now, it doesn't even show anything useful in the status bar although it was originally intended. At a minimal, there should be some message box widget which at the very least would show you the error details. About getting rid of particular notes blocking the sync - it should actually be possible to delete the notes not yet synchronized with Evernote (i.e. locally created & not yet synced) permanently. If it doesn't work, it's a bug.