Improve the logging during image import (see #11020) #1251

bpindelski · 2013-06-05T14:38:30Z

This PR extends the contents of the import log file created during the upload/import phase. The file can be accessed after the import finishes in Insight (using the View button).

The logback.xml configuration modifications might slightly affect Blitz-0.log and friends (after local comparison, the contents of those log files should be roughly the same before this PR and after).

To test - upload images (different types) and view the import log file - contents should be quite verbose (messages of levels: DEBUG, INFO, WARN and ERROR - latter two not always present).

ximenesuk · 2013-06-06T08:12:12Z

I've checked this against gretzky and I am getting nicely full logs for a handful of image and SPW formats. The one thing I noticed is that the import log contains only DEBUG level messages. I don't know if this means the filter is too strict or if messages levels are being rewritten or if the logs genuinely do only have that data in them.

bpindelski · 2013-06-06T09:14:36Z

@ximenesuk Currently logback.xml is set up with the LevelFilter which does exact matching. I can change it to ThresholdFilter and ask it to catch everything in the import file log that falls into INFO and below. @joshmoore is it worth a test?

bpindelski · 2013-06-06T10:21:45Z

Changed the filter settings so that it catches both INFO and DEBUG.

joshmoore · 2013-06-06T11:57:37Z

Interesting. I would think we want DEBUG and higher always. I can't think of a case where we would want, say, INFO but not WARN. So across the board we should be using thresholding, I'd say, though in some cases not starting at DEBUG.

bpindelski · 2013-06-06T12:31:08Z

@joshmoore So we want DEBUG, INFO, WARN and ERROR in the import log file, yes? If so, then the ThresholdFilter should be able to do it when set to DEBUG.

joshmoore · 2013-06-07T16:05:05Z

Sounds like a plan.

joshmoore · 2013-06-11T21:46:54Z

Apologies, @bpindelski . I didn't get to this today. Re-adding for tomorrow.

joshmoore · 2013-06-12T07:38:45Z

This looks great. Tested via:

$ touch 1251.fake
$ bin/omero import 1251.fake
...
2013-06-12 08:31:05,780 2966       [l.Client-0] INFO   ormats.importer.cli.LoggingImportMonitor  - OBJECTS_RETURNED Step: 5 of 5  Logfile: 2348
2013-06-12 08:31:05,870 3056       [l.Client-1] INFO   ormats.importer.cli.LoggingImportMonitor  - IMPORT_DONE Imported file: /home/omero/slave/workspace/OMERO-merge-develop/src/dist/1251.fake
Imported pixels:
771
Other imported objects:
Fileset:5
Image:771
2013-06-12 08:31:05,871 3057       [l.Client-1] INFO      ome.formats.importer.cli.ErrorHandler  - Number of errors: 0
# Find log id in the output, e.g. 2348
$ bin/omero download 2348 1251.log

The following categories look to be a bit much at DEBUG and could be limited to INFO:

ome.annotations
ome.logic
ome.security
ome.tools

@melissalinkert, do you have any thoughts on what we want/need from ome.scifio.* and loci.*. Location is at DEBUG which might be too much. Are there any formats where DEBUG for those package hierarchies would be complete overkill?

joshmoore · 2013-06-12T07:40:03Z

components/blitz/src/omero/cmd/CallContext.java

@@ -52,10 +53,18 @@ public Object invoke(final MethodInvocation arg0) throws Throwable {
                    final Map<String, String> ctx = current.ctx;
                    if (ctx != null && ctx.size() > 0) {
                        cd.setContext(ctx);
+                        if (ctx.containsKey("omero.logfilename")) {
+                            MDC.put("fileset", ctx.get("omero.logfilename"));


We'll need some ideas on how to limit the scope of this, since at the moment anyone will be able to write to whatever log file they like just by passing a value.

joshmoore · 2013-06-12T07:41:37Z

Final question, perhaps for @ximenesuk & another PR: what if any of the lines are being duplicated to Blitz-0.log and what options do we have to limit that?

melissalinkert · 2013-06-12T16:52:43Z

Location at DEBUG in general is too much - for single files it might be fine, but for larger multi-file datasets it will make a bit of a mess.

Having loci.* (and specifically `loci.formats.tiff.*) atDEBUG`` is also likely to be overkill for pretty much anything TIFF-based, which is the majority of supported formats. Looking at the logs for any non-fake plate should give you an idea of what to expect.

joshmoore · 2013-06-13T20:15:04Z

@bpindelski : could you lower to INFO then and we'll gather several logs there?

bpindelski · 2013-06-14T08:20:41Z

@joshmoore Updated logback.xml. Tried importing bd-pathway and indeed lowering to INFO in some cases was necessary, as the log file grew in size.

joshmoore · 2013-06-17T09:22:18Z

Looking through the logs from today's auto-import:

omero@gretzky:/OMERO/ManagedRepository$ find . -name "*.log"
./user-4_5/2013-06/17/08-37-37.065.log
./user-4_5/2013-06/17/09-24-24.350.log
./user-4_5/2013-06/17/09-21-30.475.log
./user-4_5/2013-06/17/08-38-56.485.log
./user-4_5/2013-06/17/08-40-47.930.log
./user-4_5/2013-06/17/09-24-27.120.log
./user-4_5/2013-06/17/09-20-31.203.log
./user-4_5/2013-06/17/08-38-30.724.log
./user-4_5/2013-06/17/09-23-08.408.log
./user-4_5/2013-06/17/08-39-35.286.log
./user-4_5/2013-06/17/08-41-33.666.log
./user-4_5/2013-06/17/08-41-13.694.log
./user-4_5/2013-06/17/09-24-21.979.log
./user-4_5/2013-06/17/08-39-53.243.log
./user-4_5/2013-06/17/08-39-16.936.log
./user-4_5/2013-06/17/08-47-44.015.log
./user-4_5/2013-06/17/08-40-13.664.log
./user-10_13/2013-06/17/09-52-30.087.log
./user-9_2/2013-06/17/09-46-36.071.log
./user-2_10/2013-06/17/09-29-19.637.log
./user-2_10/2013-06/17/09-29-25.596.log
./user-2_10/2013-06/17/09-29-16.746.log
./user-2_10/2013-06/17/09-58-02.582.log
./user-2_10/2013-06/17/09-29-22.482.log
./user-2_10/2013-06/17/09-58-06.197.log

the files look not overly full with DEBUG but generally usable. There was at least one exception which it would be interesting to look into further (i.e. good data). It's nice that we now have the timestamps for all the actions, which we could optionally start parsing out at some point. 👍

joshmoore · 2013-06-17T11:24:40Z

etc/logback.xml

@@ -19,6 +19,12 @@
      <pattern>%date %-5level [%40.40logger{40}] \(%10.10thread\) %msg%n</pattern>
    </encoder>

+    <filter class="ch.qos.logback.classic.filter.LevelFilter">


@bpindelski: sorry, I missed this while focusing on the import logs. Was this supposed to be changed to a ThresholdFilter?

joshmoore · 2013-06-18T13:44:45Z

Tested on gretzky and locally. Both DEBUG and WARN messages are again appearing. This looks great, thanks @bpindelski.

Improve the logging during image import (see #11020)

ximenesuk · 2013-11-13T14:07:49Z

components/blitz/src/ome/formats/OMEROMetadataStoreClient.java

@@ -219,6 +219,7 @@
 import omero.util.TempFileManager;

 import org.apache.commons.io.FilenameUtils;
+import org.apache.log4j.MDC;


This should be:

import org.slf4j.MDC;

A bit late for this PR but I'll reference this minor change to an ongoing ticket so it can be included in a suitable PR.

Blazej Pindelski added 7 commits June 4, 2013 14:20

Make OMSC logback aware.

7c793d1

Update log file setting in OMSC.

743c2bc

Make consumers of OMSC call logfile setter.

41dad3c

Allow CallCtx to setup MDC.

38148bb

Increase import log file verbosity.

c5188be

Include a filter for the SIFT appender.

6a36f1b

Only allow INFO in FILE appender.

29aa272

Add INFO level msgs to import log file.

49440c4

Use threshold filter instead of exact filter.

6610d62

joshmoore reviewed Jun 12, 2013
View reviewed changes

Blazej Pindelski added 2 commits June 14, 2013 09:09

Lower set of loggers to INFO level.

ad694b2

Bring back ManagedImportRequestI in logback.xml.

e853f3e

joshmoore reviewed Jun 17, 2013
View reviewed changes

Remove LevelFilter from FILE appender.

653b9a1

joshmoore added a commit that referenced this pull request Jun 18, 2013

Merge pull request #1251 from bpindelski/11020-log-file

605db3f

Improve the logging during image import (see #11020)

joshmoore merged commit 605db3f into ome:develop Jun 18, 2013

ximenesuk reviewed Nov 13, 2013
View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve the logging during image import (see #11020) #1251

Improve the logging during image import (see #11020) #1251

bpindelski commented Jun 5, 2013

ximenesuk commented Jun 6, 2013

bpindelski commented Jun 6, 2013

bpindelski commented Jun 6, 2013

joshmoore commented Jun 6, 2013

bpindelski commented Jun 6, 2013

joshmoore commented Jun 7, 2013

joshmoore commented Jun 11, 2013

joshmoore commented Jun 12, 2013

joshmoore Jun 12, 2013

joshmoore commented Jun 12, 2013

melissalinkert commented Jun 12, 2013

joshmoore commented Jun 13, 2013

bpindelski commented Jun 14, 2013

joshmoore commented Jun 17, 2013

joshmoore Jun 17, 2013

joshmoore commented Jun 18, 2013

ximenesuk Nov 13, 2013

Improve the logging during image import (see #11020) #1251

Improve the logging during image import (see #11020) #1251

Conversation

bpindelski commented Jun 5, 2013

ximenesuk commented Jun 6, 2013

bpindelski commented Jun 6, 2013

bpindelski commented Jun 6, 2013

joshmoore commented Jun 6, 2013

bpindelski commented Jun 6, 2013

joshmoore commented Jun 7, 2013

joshmoore commented Jun 11, 2013

joshmoore commented Jun 12, 2013

joshmoore Jun 12, 2013

Choose a reason for hiding this comment

joshmoore commented Jun 12, 2013

melissalinkert commented Jun 12, 2013

joshmoore commented Jun 13, 2013

bpindelski commented Jun 14, 2013

joshmoore commented Jun 17, 2013

joshmoore Jun 17, 2013

Choose a reason for hiding this comment

joshmoore commented Jun 18, 2013

ximenesuk Nov 13, 2013

Choose a reason for hiding this comment