Bug: DropBox imports some files twice

[cblackburn]

Copying a DV file and its log file into a DropBox directory causes two independent imports. Initially I thought this might be related to #5970 but in the case of DropBox the result is that the image is imported twice:

2011-06-23 11:11:07,914 INFO  [         fsclient.fsDropBoxMonitorClient] (MainThread) EVENT_RECORD::Cookie::1308823867.91::Directory::/OMERO/DropBox
2011-06-23 11:11:08,430 INFO  [                        fsclient.DropBox] (MainThread) Created monitor with id = 1cb631b3-9d81-11e0-b014-001b6392eb8c
2011-06-23 11:11:08,434 INFO  [                        fsclient.DropBox] (MainThread) Started OMERO.fs DropBox client
2011-06-23 11:38:04,465 INFO  [                            omero.remote] (Dummy-4   )  Meth: MonitorClientI.fsEventHappened
2011-06-23 11:38:04,483 INFO  [         fsclient.fsDropBoxMonitorClient] (Dummy-4   ) EVENT_RECORD::Cookie::1308825484.48::Batch::1
2011-06-23 11:38:04,484 INFO  [         fsclient.fsDropBoxMonitorClient] (Dummy-4   ) EVENT_RECORD::Cookie::1308825484.48::Create::/OMERO/DropBox/root/dv4/mt1_R3D_D3D_log.txt
2011-06-23 11:38:04,635 INFO  [                            omero.remote] (Dummy-4   )  Rslt: None
2011-06-23 11:38:07,842 INFO  [                            omero.remote] (Dummy-5   )  Meth: MonitorClientI.fsEventHappened
2011-06-23 11:38:07,843 INFO  [         fsclient.fsDropBoxMonitorClient] (Dummy-5   ) EVENT_RECORD::Cookie::1308825487.84::Batch::1
2011-06-23 11:38:07,843 INFO  [         fsclient.fsDropBoxMonitorClient] (Dummy-5   ) EVENT_RECORD::Cookie::1308825487.84::Create::/OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv
2011-06-23 11:38:07,858 INFO  [                            omero.remote] (Dummy-5   )  Rslt: None
2011-06-23 11:38:08,189 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-3  ) Processing 1 events (1 ids). 1 remaining
2011-06-23 11:38:08,189 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-3  ) Getting filesets on : set(['/OMERO/DropBox/root/dv4/mt1_R3D_D3D_log.txt'])
2011-06-23 11:38:16,864 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-3  ) EVENT_RECORD::Cookie::1308825496.86::Filesets::{'/OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv': ['/OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv', '/OMERO/DropBox/root/dv4/mt1_R3D_D3D_log.txt']}
2011-06-23 11:38:16,943 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-3  ) New entry /OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv contains 2 file(s). Files=2 Timers=1
2011-06-23 11:39:16,944 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-6  ) Removed key /OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv
2011-06-23 11:39:16,966 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-3  ) Processing 1 events (1 ids). 0 remaining
2011-06-23 11:39:16,967 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-3  ) Getting filesets on : set(['/OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv'])
2011-06-23 11:39:17,698 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-6  ) Importing /OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv (session=46b7ed6e-6934-4b77-b0ae-2d2ece11c60d)
2011-06-23 11:39:19,771 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-3  ) EVENT_RECORD::Cookie::1308825559.77::Filesets::{'/OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv': ['/OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv', '/OMERO/DropBox/root/dv4/mt1_R3D_D3D_log.txt']}
2011-06-23 11:39:19,869 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-3  ) New entry /OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv contains 2 file(s). Files=2 Timers=1
2011-06-23 11:39:20,614 INFO  [                    omero.util.Resources] (Thread-8  ) Starting
2011-06-23 11:39:20,798 WARNI [                                  stderr] (Thread-6  ) Joined session 46b7ed6e-6934-4b77-b0ae-2d2ece11c60d (root@localhost:4064). Idle timeout: 10.0 min. Current group: system
2011-06-23 11:39:48,470 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-6  ) Import of /OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv completed (session=46b7ed6e-6934-4b77-b0ae-2d2ece11c60d)
2011-06-23 11:39:48,493 INFO  [                    omero.util.Resources] (Thread-8  ) Halted
2011-06-23 11:40:19,870 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-7  ) Removed key /OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv
2011-06-23 11:40:20,243 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-7  ) Importing /OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv (session=cb2b1ce9-2d35-44b0-856f-275c3292d7c2)
2011-06-23 11:40:20,664 INFO  [                    omero.util.Resources] (Thread-9  ) Starting
2011-06-23 11:40:20,678 WARNI [                                  stderr] (Thread-7  ) Joined session cb2b1ce9-2d35-44b0-856f-275c3292d7c2 (root@localhost:4064). Idle timeout: 10.0 min. Current group: system
2011-06-23 11:40:29,962 INFO  [                    omero.util.Resources] (Thread-9  ) Halted
2011-06-23 11:40:29,966 INFO  [         fsclient.fsDropBoxMonitorClient] (Thread-7  ) Import of /OMERO/DropBox/root/dv4/mt1_R3D_D3D.dv completed (session=cb2b1ce9-2d35-44b0-856f-275c3292d7c2)

[cblackburn]

Results from running an automatic script a few times which copies a dv and then x seconds later its log file, x in (0,3,...60) are shown below. These are all non-overlapping imports to make the logs easier to follow but also to keep what's happening as simple as possible. Other than longer gaps seem to more consistently lead to double imports there doesn't seem to be a strong pattern for shorter gaps. One log file is attached.

CFPNEAT01_R3D: Duplicate imports on: 15, 21, 30, 33, 36, 39, 42, 48, 51, 54, 57, 60 (12/21)
CFPNEAT01_R3D: Duplicate imports on: 12, 27, 30, 33, 36, 39, 42, 45, 51, 54, 57, 60 (12/21)
mt1_R3D_D3D:   Duplicate imports on: 3, 21, 39, 42, 45, 48, 51, 54, 57, 60          (10/21)

[cblackburn]

The main cause of this bug is that a file notification can be received near the end of the execute() loop and then a companion file notification might be received on a new invocation of execute. This causes two separate imports. The fix in ​https://github.com/ximenesuk/openmicroscopy/tree/bug/5972 stops this but there are still other edge effects such as the file and its companion falling in two separate batches or the batch size not being large enough for a multi-file format. To some extent configuration can reduce this effect but it will always remain an edge case with the current strategy. We should document the config changes necessary to reduce the likelihood of a double import but may need to reconsider how DropBox works as part of a wider story.

[cblackburn]

Re-opening. In looking at the documentation I realised the problem may be more subtle. It is possibly due to race condition between the wait in the execute loop and the wait of import events. If this is the case a better fix can be implemented.

[cblackburn]

Fix tested locally, will push to branch after discussion.

[jburel]

Moved from sprint 2012-01-03 (5)

[cblackburn]

Closing this leaving the fraction that is used to calculate worker_wait from dirImportWait hard-coded at 25%. Leaving fileBatch as config.