End of change request not received

[aaronmelzak]

I was downloading files fine via fuse last night until this morning I get this message when trying to sync.

[WARNING] [acdcli.api.metadata] - End of change request not reached.

I thought maybe my database was corrupted, so I unmounted, cleared the node.db, and then tried to do a fresh sync. Same message. I switched to a different machine where it has worked before, cleared everything and started fresh. I can get the oauth token but when it goes to sync, I get same error.

I was able to sync and re-sync another account I have without issue. I am running the latest acdcli:

acd_cli 0.3.2, api 0.9.0

16-09-05 12:52:29.074 [INFO] [acd_cli] - Plugin leaf classes: TestPlugin
16-09-05 12:52:29.074 [INFO] [acd_cli] - TestPlugin attached.
16-09-05 12:52:29.074 [INFO] [acd_cli] - Settings path is "/Users/amelzak/Library/Application Support/acd_cli".
16-09-05 12:52:29.075 [INFO] [acdcli.api.client] - Initializing ACD with path "/Users/amelzak/Library/Caches/acd_cli".
16-09-05 12:52:29.076 [INFO] [acdcli.api.oauth] - AppspotOAuthHandler initialized
16-09-05 12:52:29.084 [INFO] [acdcli.cache.schema] - DB schema version is 2.
Getting changes16-09-05 12:52:29.085 [INFO] [acdcli.api.metadata] - Getting changes with checkpoint "None".
16-09-05 12:52:29.085 [INFO] [acdcli.api.backoff_req] - POST "https://cdws.us-east-1.amazonaws.com/drive/v1/changes"
16-09-05 12:52:29.095 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (1): cdws.us-east-1.amazonaws.com
.
16-09-05 12:52:34.195 [INFO] [acdcli.api.metadata] - Found "reset" tag in changes.
16-09-05 12:52:34.201 [INFO] [acdcli.cache.schema] - Dropped all tables.
16-09-05 12:52:34.206 [INFO] [acdcli.cache.schema] - DB schema version is 2.
Inserting nodes16-09-05 12:52:34.221 [INFO] [acdcli.cache.sync] - Inserted/updated 39 folder(s).
16-09-05 12:52:34.770 [INFO] [acdcli.cache.sync] - Inserted/updated 1949 file(s).
16-09-05 12:52:34.781 [INFO] [acdcli.cache.sync] - Parented 1988 node(s).
.16-09-05 12:52:34.782 [INFO] [acdcli.api.metadata] - 0 page(s) in changes.
16-09-05 12:52:34.782 [WARNING] [acdcli.api.metadata] - End of change request not reached.

[aaronmelzak]

Issue no longer reproducible.

[aaronmelzak]

Nevermind. It synced for a little bit then spit out the same error. :(

[cfoucher]

I'm receiving the same error. "old-sync" appears to work as a temporary solution. But using it to update the fuse mounts is causing a bunch of other issues.

[aaronmelzak]

old-sync appears to work for me but the node.db file never gets any bigger than 14kb even though it is writing a lot of data to the log file.

[aaronmelzak]

Now it's working. I've fully synced through the standard sync. Maybe it was an Amazon issue.

[cfoucher]

I'm still receiving that issue.

#acd_cli -vv sync -f
16-09-06 15:40:29.236 [INFO] [acd_cli] - Plugin leaf classes: TestPlugin
16-09-06 15:40:29.236 [INFO] [acd_cli] - TestPlugin attached.
16-09-06 15:40:29.237 [INFO] [acd_cli] - Settings path is "/root/.config/acd_cli".
16-09-06 15:40:29.241 [INFO] [acdcli.api.client] - Initializing ACD with path "/root/.cache/acd_cli".
16-09-06 15:40:29.242 [INFO] [acdcli.api.oauth] - AppspotOAuthHandler initialized
16-09-06 15:40:29.956 [INFO] [acdcli.cache.schema] - DB schema version is 2.
Getting changes16-09-06 15:40:29.959 [INFO] [acdcli.api.metadata] - Getting changes with checkpoint "None".
16-09-06 15:40:29.960 [INFO] [acdcli.api.backoff_req] - POST "https://cdws.us-east-1.amazonaws.com/drive/v1/changes"
16-09-06 15:40:29.965 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (1): cdws.us-east-1.amazonaws.com
16-09-06 15:41:34.027 [INFO] [acdcli.api.metadata] - ('Connection broken: IncompleteRead(0 bytes read)', IncompleteRead(0 bytes read))
16-09-06 15:41:34.029 [INFO] [acdcli.api.metadata] - -1 page(s) in changes.
16-09-06 15:41:34.030 [WARNING] [acdcli.api.metadata] - End of change request not reached.

[yadayada]

If for whatever reason not all changesets can be downloaded, you should run (the incremental) sync again until it does not throw a warning. Using -f will decrease the chances of a sync succeeding, I suppose.

[cfoucher]

Sorry that was a bad example. I only ran the full sync that once for the example. I have been running the incremental sync command and am still receiving the same issue. It doesn't appear to matter how many times I run the command as well.

conrad@ubuntu:~$ acd_cli -dd sync
16-09-07 19:31:04.149 [INFO] [acd_cli] - Plugin leaf classes: TestPlugin
16-09-07 19:31:04.149 [INFO] [acd_cli] - TestPlugin attached.
16-09-07 19:31:04.150 [INFO] [acd_cli] - Settings path is "/home/conrad/.config/acd_cli".
16-09-07 19:31:04.151 [DEBUG] [acdcli.utils.conf] - configuration resulting from merging default and acd_cli.ini: {'DEFAULT': {}, 'download': {'keep_corrupt': 'False', 'keep_incomplete': 'True'}}
16-09-07 19:31:04.152 [DEBUG] [acdcli.utils.conf] - configuration resulting from merging default and acd_client.ini: {'transfer': {'idle_timeout': '60', 'dl_chunk_size': '524288000', 'fs_chunk_size': '131072', 'chunk_retries': '1', 'connection_timeout': '30'}, 'DEFAULT': {}, 'endpoints': {'validity_duration': '259200', 'filename': 'endpoint_data'}, 'proxies': {}}
16-09-07 19:31:04.152 [INFO] [acdcli.api.client] - Initializing ACD with path "/home/conrad/.cache/acd_cli".
16-09-07 19:31:04.153 [INFO] [acdcli.api.oauth] - AppspotOAuthHandler initialized
16-09-07 19:31:04.155 [DEBUG] [acdcli.utils.conf] - configuration resulting from merging default and cache.ini: {'sqlite': {'filename': 'nodes.db', 'journal_mode': 'wal', 'busy_timeout': '30000'}, 'blacklist': {'folders': '[]'}, 'DEFAULT': {}}
16-09-07 19:31:04.764 [INFO] [acdcli.cache.schema] - DB schema version is 2.
16-09-07 19:31:04.765 [DEBUG] [acdcli.cache.db] - Set busy_timeout to 30000. Result: 30000.
16-09-07 19:31:04.766 [DEBUG] [acdcli.cache.db] - Set journal_mode to wal. Result: wal.
16-09-07 19:31:04.766 [DEBUG] [acd_cli] - Namespace(acd_client=<acdcli.api.client.ACDClient object at 0x7f0218d68320>, action='sync', cache=<acdcli.cache.db.NodeCache object at 0x7f0218d7e320>, check=0, color=2, debug=2, from_file=None, full=False, func=<function sync_action at 0x7f0218fbd0d0>, log=True, no_wait=False, to_file=None, utf=False, verbose=None)
Getting changes16-09-07 19:31:04.767 [INFO] [acdcli.api.metadata] - Getting changes with checkpoint "None".
16-09-07 19:31:04.767 [DEBUG] [acdcli.api.backoff_req] - Retry 0, waiting -0.613469s
16-09-07 19:31:04.768 [INFO] [acdcli.api.backoff_req] - POST "https://cdws.us-east-1.amazonaws.com/drive/v1/changes"
16-09-07 19:31:04.768 [DEBUG] [acdcli.api.backoff_req] - {}
16-09-07 19:31:04.771 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (1): cdws.us-east-1.amazonaws.com
send: b'POST /drive/v1/changes HTTP/1.1\r\nHost: cdws.us-east-1.amazonaws.com\r\nAccept-Encoding: gzip, deflate\r\nUser-Agent: acdcli.api/0.9.0 python-requests/2.11.1\r\nAccept: */*\r\nConnection: keep-alive\r\nContent-Length: 2\r\nAuthorization: Bearer Atza|IwEBIG3UdvX7Lbt2V7kDN_0lZgJ9xhPeX_tsg1l6SRLwAh2oniBSJ4RC-mQMbRSelnogOag6TaabGew8u8XJXZShkTaSwW1gQOH47XMhi98o1WtHsPhhShtHq6IgVoBfi5hlU9ufF2HPkQtLS-MT4Xns52ZhSlzGpJ28uDTq65ZA80OQ1bEw9OIOu0819lD_V94-VT09LKq98VVgMxBeBigRfRB0q_EEPN0lvDv7zjagRa_LoFlQsMAs_eNuWTBS9LqisHFAQBKP0ZoRFLUYP1jRvywcs2F19z3WswYn871m7XH0VxKvs5XnCRYI4IijRT9SpcZ9nRBsx42BpdtwMJD87q7JjFO_ahB4UXSROOMbqEEO3MroGY_OQ2HE1XCs9P6VeE0k7mOdVvnxEfRVz6mW0iq4fO0xWPfdVQlyDElwx4qsSphLxjJWl9d2VqNhusS_Tt-EVUIx3zAJbMwLrTUy35R3J9aZ1UrDfIcdPVji15ckV_YpbpqztV4RmvbyNzptwg6ohW70tOQFA0LaAfNUzPSMg0iK_de9ZFWJHDf4ayyloBBmLjsrI6epXwurAv_kbuushW33iZx29IrhxVqnYX8PS-tR\r\n\r\n{}'
reply: 'HTTP/1.1 200 OK\r\n'
header: Server header: Date header: Content-Type header: Transfer-Encoding header: Connection header: x-amzn-RequestId header: Content-Encoding header: Cache-Control header: Pragma header: Vary 16-09-07 19:31:07.105 [DEBUG] [requests.packages.urllib3.connectionpool] - "POST /drive/v1/changes HTTP/1.1" 200 None
16-09-07 19:31:07.107 [DEBUG] [acdcli.api.backoff_req] - x-amzn-RequestId: 2927959f-7553-11e6-b7b8-e75ba0e21c1a
16-09-07 19:32:07.180 [INFO] [acdcli.api.metadata] - ('Connection broken: IncompleteRead(0 bytes read)', IncompleteRead(0 bytes read))
16-09-07 19:32:07.182 [INFO] [acdcli.api.metadata] - -1 page(s) in changes.
16-09-07 19:32:07.182 [WARNING] [acdcli.api.metadata] - End of change request not reached.

[cfoucher]

Took a few days but perseverance paid off. The default sync appears to be working again!