Bug: Drop-box duplicate import

[wmoore]

Following the drop-box test #6053.

Dropping a log file in to DropBox?/somename/ at about 1 minute 5 seconds after the DV file: The DV file got the file attached (and metadata from the file) and was imported twice.

Tried to repeat this in /someothername/ with another DV. Waited 1 min 30 secs after DV file (not much activity in Blitz.log) then dropped the log file - DV got imported twice.

In this example, DV was dropped at 10:31:42 and log at 10:32:57

2011-07-04 10:31:42,459 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Meth:	interface ome.api.IAdmin.lookupExperimenter
2011-07-04 10:31:42,459 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Args:	[root]
2011-07-04 10:31:42,460 INFO  [         ome.security.basic.EventHandler] (l.Server-8)  Auth:	user=0,group=4,event=null(User),sess=17934f3d-a8b6-4bc1-9fbd-9209df84b617
2011-07-04 10:31:42,466 INFO  [                 org.perf4j.TimingLogger] (l.Server-8) start[1309771902459] time[7] tag[omero.call.success.ome.logic.AdminImpl.lookupExperimenter]
2011-07-04 10:31:42,466 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Rslt:	ome.model.meta.Experimenter:Id_0
2011-07-04 10:31:57,533 INFO  [        ome.services.util.ServiceHandler] (.Server-10)  Meth:	interface ome.api.ISession.getSession
2011-07-04 10:31:57,534 INFO  [        ome.services.util.ServiceHandler] (.Server-10)  Args:	[f2b08fa0-dc8f-455b-9681-0576eed3bd65]
2011-07-04 10:31:57,534 INFO  [                 org.perf4j.TimingLogger] (.Server-10) start[1309771917534] time[0] tag[omero.call.success.ome.services.sessions.SessionBean.getSession]
2011-07-04 10:31:57,534 INFO  [        ome.services.util.ServiceHandler] (.Server-10)  Rslt:	ome.model.meta.Session:Id_5342
2011-07-04 10:32:50,114 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Meth:	interface ome.api.IAdmin.lookupExperimenter
2011-07-04 10:32:50,114 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Args:	[root]
2011-07-04 10:32:50,115 INFO  [         ome.security.basic.EventHandler] (l.Server-8)  Auth:	user=0,group=4,event=null(User),sess=17934f3d-a8b6-4bc1-9fbd-9209df84b617
2011-07-04 10:32:50,120 INFO  [                 org.perf4j.TimingLogger] (l.Server-8) start[1309771970114] time[6] tag[omero.call.success.ome.logic.AdminImpl.lookupExperimenter]
2011-07-04 10:32:50,120 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Rslt:	ome.model.meta.Experimenter:Id_0
2011-07-04 10:32:57,545 INFO  [        ome.services.util.ServiceHandler] (.Server-10)  Meth:	interface ome.api.ISession.getSession
2011-07-04 10:32:57,545 INFO  [        ome.services.util.ServiceHandler] (.Server-10)  Args:	[f2b08fa0-dc8f-455b-9681-0576eed3bd65]
2011-07-04 10:32:57,545 INFO  [                 org.perf4j.TimingLogger] (.Server-10) start[1309771977545] time[0] tag[omero.call.success.ome.services.sessions.SessionBean.getSession]
2011-07-04 10:32:57,545 INFO  [        ome.services.util.ServiceHandler] (.Server-10)  Rslt:	ome.model.meta.Session:Id_5342
2011-07-04 10:32:59,832 INFO  [        ome.services.util.ServiceHandler] (l.Server-3)  Meth:	interface ome.api.IAdmin.lookupExperimenter

Also noticed that Blitz.log seems to print same line (x not changing) during plane import....

2011-07-04 10:25:30,642 INFO  [                ome.io.nio.PixelsService] (l.Server-6) Pixel buffer file exists returning read-only ROMIO pixel buffer.
2011-07-04 10:25:30,643 INFO  [             ome.io.nio.RomioPixelBuffer] (l.Server-6) Retrieving plane: 24x0x0
2011-07-04 10:25:30,689 INFO  [             ome.io.nio.RomioPixelBuffer] (l.Server-6) Retrieving plane: 24x0x0
2011-07-04 10:25:30,734 INFO  [             ome.io.nio.RomioPixelBuffer] (l.Server-6) Retrieving plane: 24x0x0
2011-07-04 10:25:30,783 INFO  [             ome.io.nio.RomioPixelBuffer] (l.Server-6) Retrieving plane: 24x0x0
2011-07-04 10:25:30,831 INFO  [             ome.io.nio.RomioPixelBuffer] (l.Server-6) Retrieving plane: 24x0x0
2011-07-04 10:25:30,876 INFO  [             ome.io.nio.RomioPixelBuffer] (l.Server-6) Retrieving plane: 24x0x0
2011-07-04 10:25:30,926 INFO  [             ome.io.nio.RomioPixelBuffer] (l.Server-6) Retrieving plane: 24x0x0
....

[cblackburn]

Currently, double imports are expected behaviour is there is more than a 60 second period between the image file and the companion file. The 60 seconds is user configurable and documented. If the companion file hasn't turned up before 60 seconds after the image then the image file is imported. If the companion file is then copied it will trigger the image file to be imported for a second time with its companion file.

I'm cc'ing to Chris for comments on the romio pixel buffer log, that might need to be put under a different ticket if necessary.

[wmoore]

Hmmm - What confused me here was that the first import "knew" about the existence of the log file. The first import has not started by the time the log file arrived, and the first import includes the log file. Therefore, I wouldn't expect the log file to be considered a second import.

If the first import HAD already started by the time the log file arrived (had stopped waiting for the log file) then I could understand that the log file arrival could be seen as a new import.

[cblackburn]

There may be an issue here as the delay is not that much greater than 60 seconds. There are other wait periods in there and file copies are not instantaneous. So it is possible that this was a duplicate import was an edge case in the known issue #5972 I'll investigate duplicate imports more fully under that ticket.