Comment 11 for bug 551095

Revision history for this message
Natalia Bidart (nataliabidart) wrote :

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
2010-03-31 19:02:31,555 - ubuntuone.SyncDaemon.ActionQueue - DEBUG - ListDir share:'cfd7e79f-a376-4
719-8cc2-be3810ad48dd' node:'99169447-aace-4494-8f58-bf839dff53a3' ListDir(fileobj_factory='<function <lambda> at 0x
4200140>', share_id="'cfd7e79f-a376-4719-8cc2-be3810ad48dd'", node_id="'99169447-aace-4494-8f58-bf839dff53a3'", server_h
ash="'sha1:b291018d3c21ee41493d21c0d7f7dbb82c2e374e'") starting

(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
2010-04-05 14:10:20,529 - ubuntuone.SyncDaemon.fsm - INFO - initialized: idx_path: 34081, idx_node_id: 34080, shares: 8

 * Local rescan: 6 minutes 36 seconds

2010-04-05 14:10:21,605 - ubuntuone.SyncDaemon.Main - NOTE - Local rescan starting...
...
2010-04-05 14:16:57,765 - ubuntuone.SyncDaemon.Main - NOTE - Local rescan finished!

 * 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

 * 13615 LR_SCAN_ERRORs:

nessita@dali:~/Documents/canonical/logs/rmcbride/06042010_1$ grep "push_event: LR_SCAN_ERROR, args:('4352976b-7042-4ad4-8568-2d737ca60131'" 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)
...
2010-04-06 05:48:01,717 - ubuntuone.SyncDaemon.StateManager - DEBUG - Transition SERVER_RESCAN --[SYS_CONNECTION_LOST]--> WAITING (queues: WORKING_ON_BOTH; connection: With User With Network)

 * 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) ----