* While local rescan was working, Rick removed the 'Shared with me' folder, as per:
2010-04-05 14:10:39,121 - ubuntuone.SyncDaemon.local_rescan - INFO - comp yield: directory '/home/rmcbride/Ubuntu One/Shared With Me' is gone!
* Since removing this directory is not supported (see Bug #556783 for details), the client entered on a loop of LR_SCAN_ERROR, as per:
2010-04-05 14:10:21,882 - ubuntuone.SyncDaemon.local_rescan - DEBUG - Disk error while scanning path '/home/rmcbride/.local/share/ubuntuone/shares/Ubuntu One from System User', reason: [Errno 2] No such file or directory: '/home/rmcbride/.local/share/ubuntuone/shares/Ubuntu One from System User'
2010-04-05 14:10:39,162 - ubuntuone.SyncDaemon.EQ - DEBUG - push_event: LR_SCAN_ERROR, args:('4352976b-7042-4ad4-8568-2d737ca60131', False), kw:{}
2010-04-05 14:10:39,163 - ubuntuone.SyncDaemon.sync - DEBUG - T:SERVER:T 4352976b-7042-4ad4-8568-2d737ca60131 ['b2d8565f-e6e6-4025-878a-137bef9f6764'::'298c27ab-6d9e-4ac1-89c4-6fdd31f2d261'] ''/home/rmcbride/.local/share/ubuntuone/shares/Ubuntu One from System User'' | EVENT: LR_SCAN_ERROR:{} with ARGS:(False,)
2010-04-05 14:10:39,163 - ubuntuone.SyncDaemon.sync - DEBUG - T:SERVER:T 4352976b-7042-4ad4-8568-2d737ca60131 ['b2d8565f-e6e6-4025-878a-137bef9f6764'::'298c27ab-6d9e-4ac1-89c4-6fdd31f2d261'] ''/home/rmcbride/.local/share/ubuntuone/shares/Ubuntu One from System User'' | Calling rescan_dir
2010-04-05 14:10:39,164 - ubuntuone.SyncDaemon.local_rescan - INFO - scan dir: '/home/rmcbride/.local/share/ubuntuone/shares/Ubuntu One from System User' mdid: 4352976b-7042-4ad4-8568-2d737ca60131
2010-04-05 14:10:39,166 - ubuntuone.SyncDaemon.local_rescan - DEBUG - The received path is not in disk: path '/home/rmcbride/.local/share/ubuntuone/shares/Ubuntu One from System User' mdid 4352976b-7042-4ad4-8568-2d737ca60131
After analizing a lot of log files from the client and from the server, I've arrived to the following conclusions:
* Until April, 5th the client was waiting for a ListDir that never finished, and we couldn't find any signs of it in the server logs:
2010-03-31 19:02:31,554 - ubuntuone. SyncDaemon. QueueManager - DEBUG - In WORKING_ON_BOTH: running META_QUEUE SyncDaemon. ActionQueue - DEBUG - ListDir share:' cfd7e79f- a376-4 be3810ad48dd' node:'99169447- aace-4494- 8f58-bf839dff53 a3' ListDir( fileobj_ factory= '<function <lambda> at 0x "'cfd7e79f- a376-4719- 8cc2-be3810ad48 dd'", node_id= "'99169447- aace-4494- 8f58-bf839dff53 a3'", server_h b291018d3c21ee4 1493d21c0d7f7db b82c2e374e' ") starting
2010-03-31 19:02:31,555 - ubuntuone.
719-8cc2-
4200140>', share_id=
ash="'sha1:
(this behavior should be revised and it's filled under Bug #556507)
* After that, Rick restarted the client and the following happened. Metadata load: 6 minutes 25 seconds:
2010-04-05 14:03:55,840 - ubuntuone. SyncDaemon. fsm - INFO - loading updated metadata SyncDaemon. fsm - INFO - initialized: idx_path: 34081, idx_node_id: 34080, shares: 8
2010-04-05 14:10:20,529 - ubuntuone.
* Local rescan: 6 minutes 36 seconds
2010-04-05 14:10:21,605 - ubuntuone. SyncDaemon. Main - NOTE - Local rescan starting... SyncDaemon. Main - NOTE - Local rescan finished!
...
2010-04-05 14:16:57,765 - ubuntuone.
* While local rescan was working, Rick removed the 'Shared with me' folder, as per:
2010-04-05 14:10:39,121 - ubuntuone. SyncDaemon. local_rescan - INFO - comp yield: directory '/home/ rmcbride/ Ubuntu One/Shared With Me' is gone!
* Since removing this directory is not supported (see Bug #556783 for details), the client entered on a loop of LR_SCAN_ERROR, as per:
2010-04-05 14:10:21,882 - ubuntuone. SyncDaemon. local_rescan - DEBUG - Disk error while scanning path '/home/ rmcbride/ .local/ share/ubuntuone /shares/ Ubuntu One from System User', reason: [Errno 2] No such file or directory: '/home/ rmcbride/ .local/ share/ubuntuone /shares/ Ubuntu One from System User'
2010-04-05 14:10:39,162 - ubuntuone. SyncDaemon. EQ - DEBUG - push_event: LR_SCAN_ERROR, args:(' 4352976b- 7042-4ad4- 8568-2d737ca601 31', False), kw:{} SyncDaemon. sync - DEBUG - T:SERVER:T 4352976b- 7042-4ad4- 8568-2d737ca601 31 ['b2d8565f- e6e6-4025- 878a-137bef9f67 64'::'298c27ab- 6d9e-4ac1- 89c4-6fdd31f2d2 61'] ''/home/ rmcbride/ .local/ share/ubuntuone /shares/ Ubuntu One from System User'' | EVENT: LR_SCAN_ERROR:{} with ARGS:(False,) SyncDaemon. sync - DEBUG - T:SERVER:T 4352976b- 7042-4ad4- 8568-2d737ca601 31 ['b2d8565f- e6e6-4025- 878a-137bef9f67 64'::'298c27ab- 6d9e-4ac1- 89c4-6fdd31f2d2 61'] ''/home/ rmcbride/ .local/ share/ubuntuone /shares/ Ubuntu One from System User'' | Calling rescan_dir SyncDaemon. local_rescan - INFO - scan dir: '/home/ rmcbride/ .local/ share/ubuntuone /shares/ Ubuntu One from System User' mdid: 4352976b- 7042-4ad4- 8568-2d737ca601 31 SyncDaemon. local_rescan - DEBUG - The received path is not in disk: path '/home/ rmcbride/ .local/ share/ubuntuone /shares/ Ubuntu One from System User' mdid 4352976b- 7042-4ad4- 8568-2d737ca601 31
2010-04-05 14:10:39,163 - ubuntuone.
2010-04-05 14:10:39,163 - ubuntuone.
2010-04-05 14:10:39,164 - ubuntuone.
2010-04-05 14:10:39,166 - ubuntuone.
* 13615 LR_SCAN_ERRORs:
nessita@ dali:~/ Documents/ canonical/ logs/rmcbride/ 06042010_ 1$ grep "push_event: LR_SCAN_ERROR, args:(' 4352976b- 7042-4ad4- 8568-2d737ca601 31'" all.log | wc -l
13615
* Finally, the client transitioned to the online state QUEUE_MANAGER:
2010-04-05 14:38:24,117 - ubuntuone. SyncDaemon. StateManager - DEBUG - Transition SERVER_RESCAN --[SYS_ SERVER_ RESCAN_ DONE]-- > QUEUE_MANAGER (queues: WORKING_ON_BOTH; connection: With User With Network)
* But then, a lot of disconnections started happening (the server disconnected the client):
2010-04-05 20:16:19,754 - ubuntuone. SyncDaemon. StateManager - DEBUG - Transition QUEUE_MANAGER --[SYS_ CONNECTION_ LOST]-- > WAITING (queues: WORKING_ON_BOTH; connection: With User With Network) SyncDaemon. StateManager - DEBUG - Transition SERVER_RESCAN --[SYS_ CONNECTION_ LOST]-- > WAITING (queues: WORKING_ON_BOTH; connection: With User With Network)
...
2010-04-06 05:48:01,717 - ubuntuone.
* 59 disconnections in 9:30 hours:
nessita@ dali:~/ Documents/ canonical/ logs/rmcbride/ 06042010_ 1$ grep "Transition .* --\[SYS_ CONNECTION_ LOST\]" all.log | wc -l
59
* And the log ends up with the client still doing server rescan, because the server is sloooooooow:
2010-04-06 08:36:21,603 - ubuntuone. SyncDaemon. Main - NOTE - ---- MARK (state: <State: 'SERVER_RESCAN' (queues WORKING_ON_BOTH connection 'With User With Network')>; queues: metadata: 40711; content: 1894; hash: 0, fsm-cache: hit=2132072 miss=2932951) ----