Occasionally getting struct.error exception on fresh sync

[felciano]

Ran a full fresh sync overnight and ran into this failure:

2021-09-03 23:00:02,397 | [DEBUG] | 4520603136 | Adding/updating note 'Packing' [7ace7ad1-6997-4fe7-97fa-b450e3120add], notebook_id [88e9bfed-4d4e-497b-b5b3-e32b806b9d55]
2021-09-03 23:00:02,407 | [DEBUG] | 4520603136 | Added note [7ace7ad1-6997-4fe7-97fa-b450e3120add]
2021-09-03 23:00:02,407 | [CRITICAL] | 4520603136 | Exception caught while downloading note 'Packing list - short (2-4 work days) business trip overseas'!
2021-09-03 23:00:02,407 | [WARNING] | 4520603136 | Aborting, please wait...
2021-09-03 23:00:08,755 | [DEBUG] | 123145456091136 | Finished downloading note [a324de10-592f-46d4-b33e-25be5f989012]
2021-09-03 23:00:08,755 | [DEBUG] | 123145456091136 | Memory consumed: 0.0% [LIMIT 256 MB]
2021-09-03 23:00:09,205 | [DEBUG] | 123145405722624 | Finished downloading note [a3bedb49-07f9-4edf-a1fe-58f3f1297f4f]
2021-09-03 23:00:09,205 | [DEBUG] | 123145405722624 | Memory consumed: 0.001% [LIMIT 256 MB]
2021-09-03 23:00:09,226 | [DEBUG] | 123145439301632 | Finished downloading note [57be1baa-e716-4206-b8f7-ec5443e3f4d0]
2021-09-03 23:00:09,227 | [DEBUG] | 123145439301632 | Memory consumed: 0.002% [LIMIT 256 MB]
2021-09-03 23:00:17,490 | [DEBUG] | 123145422512128 | Finished downloading note [5ce693dd-bfab-4242-99f6-e30d8bab8286]
2021-09-03 23:00:17,490 | [DEBUG] | 123145422512128 | Memory consumed: 0.003% [LIMIT 256 MB]
2021-09-03 23:00:33,544 | [DEBUG] | 123145472880640 | Finished downloading note [65bdc413-5e45-4d5d-8e19-850e28a15edf]
2021-09-03 23:00:33,566 | [DEBUG] | 123145472880640 | Memory consumed: 0.052% [LIMIT 256 MB]
2021-09-03 23:00:33,566 | [CRITICAL] | 4520603136 | Traceback (most recent call last):
  File "evernote_backup/cli.py", line 272, in main
  File "click/core.py", line 1137, in __call__
  File "click/core.py", line 1062, in main
  File "click/core.py", line 1668, in invoke
  File "click/core.py", line 1404, in invoke
  File "click/core.py", line 763, in invoke
  File "evernote_backup/cli.py", line 199, in sync
  File "evernote_backup/cli_app.py", line 123, in sync
  File "evernote_backup/note_synchronizer.py", line 197, in sync
  File "evernote_backup/note_synchronizer.py", line 342, in _download_scheduled_notes
  File "evernote_backup/note_synchronizer.py", line 370, in _process_download_chunk
  File "concurrent/futures/thread.py", line 57, in run
  File "evernote_backup/note_synchronizer.py", line 134, in __call__
  File "evernote_backup/evernote_client_sync.py", line 39, in get_note
  File "evernote_backup/evernote_client.py", line 131, in wrapper
  File "evernote_backup/evernote_client_util.py", line 28, in wrapper
  File "evernote/edam/notestore/NoteStore.py", line 4142, in getNote
  File "evernote/edam/notestore/NoteStore.py", line 4158, in recv_getNote
  File "thrift/protocol/TBinaryProtocol.py", line 145, in readMessageBegin
  File "thrift/protocol/TBinaryProtocol.py", line 201, in readByte
struct.error: unpack requires a buffer of 1 bytes

This looks to be related to Evernote/evernote-sdk-python3#27. That issue is open, but in the discussion thread it looks like Evernote may have patched it earlier this year in a recent build of the Python3 SDK?

[felciano]

This might be the fix: Evernote/evernote-sdk-python3@9219222

[vzhd1701]

This fix is already applied to the SDK version that I use. It seems like a recurring problem on the side of the Evernote server. I think I can fix it by making the request retry a couple of times before failing.

Does it happen on random notes? Is the traceback the same every time?

[felciano]

Yes it seems to be inconsistent. If I try again in a few hours, sometimes it completes successfully.

I think retries would likely address the issue. However even with retries, I think the more important solution would be to catch the error and help the user understand what to do about it. In particular, whether the sync data (database) has been left in an inconsistent state and perhaps needs a full fresh sync, or whether simply restarting the sync process will pick up where it failed (including retrying the failed one) and continue syncing. Right now I'm assuming the db is an unknown state, so rebuilding from scratch each time.

[vzhd1701]

The problem is that server returns 4xx or 5xx error instead of expected binary data due to some overload issues.

Yes, I should make it more clear to the user when things go south and what to do about it.

As for consistency, the database stays safe in case of any remote server errors. You can just run the sync again and it will download all notes that it missed when an exception occurred. Network exceptions happen before anything is written to the database and every commit to the database is atomic, so nothing to worry about. You don't have to rebuild from scratch.

[vzhd1701]

Check out the new version. Now it will retry when the server sends bad data.

[felciano]

So far so good, although I'm not sure if I'd be able to tell whether this exception-retry mechanism kicked in during my tests. If this sporadic bad data situation occurs, will it still show up in the --verbose log, or will the retry mechanism just kick in behind the scenes without a log message?

[vzhd1701]

Yes, you will see "Remote server returned bad data while downloading note [xxx], retrying..." messages in the log.

[felciano]

Confirmed. I ran 6 full fresh syncs over the past 2 days and on two occasions it caught and recovered from the bad data exception. Well done!