Bug: log output in db script file

[mtbcarroll]

With bin/omero db script from dev_4_4 I managed to create the attached remarkable script -- see the last page or so. ​https://github.com/openmicroscopy/openmicroscopy/pull/1843/ was merged in at the time.

[mtbcarroll]

omero db script output

[jamoore]

Moving to 4.4.10 for review. Mark: could you try to reproduce either with origin/dev_4_4 or the snoopy builds? Does this happen after a clean build? Only when changing from origin/develop?

[wmoore]

I saw this problem after a non-clean build of dev_4_4 (coming from develop - see below) but was fixed by a clean build.

$ git fetch snoopy
$ git checkout dev_4_4-latest
$ git reset --hard snoopy/merge/dev_4_4/latest 
$ git submodule foreach hub remote update snoopycrimecop
$ git submodule update
$ ./build.py
$ omero config set omero.web.application_server development
$ omero config set omero.web.debug True
$ omero web start
$ dropdb omero
$ rm -rf /OMERO/*
$ createdb -O omero omero
$ omero db script
$ psql -h localhost -U omero omero < OMERO4.4__0.sql 

[mtbcarroll]

To reproduce it looks like I need to move from a develop merge build back to some dev_4_4. For instance,

git checkout scc/merge/develop/latest
git submodule update
./build.py
git checkout remotes/origin/dev_4_4
git submodule update
./build.py
omero db script

[jamoore]

What are the contents of lib/server and lib/client?

[mtbcarroll]

all the files after the reproduction steps

[mtbcarroll]

mtbc@ls28101:~/src/openmicroscopy$ ls dist/lib/{server,client}/
dist/lib/client/:
ai_path.jar                   JWlz.jar
asm-attrs.jar                 kryo.jar
asm.jar                       loci-common.jar
assumeng.jar                  log4j.jar
axis.jar                      lwf-stubs.jar
backport-util-concurrent.jar  mdbtools-java.jar
bio-formats.jar               metakit.jar
blitz.jar                     model-psql.jar
bufr.jar                      nanoxml.jar
cglib-nodep.jar               native-lib-loader.jar
common.jar                    netcdf.jar
commons-codec.jar             ols-client.jar
commons-collections.jar       ome-io.jar
commons-digester.jar          ome-java.jar
commons-discovery.jar         omero_client.jar
commons-httpclient.jar        omero-clients-util.jar
commons-io.jar                OmeroImporter.jar
commons-lang.jar              ome-xml.jar
commons-logging.jar           org.springframework.asm.jar
commons-validator.jar         org.springframework.beans.jar
dsl.jar                       org.springframework.context.jar
ehcache-core.jar              org.springframework.core.jar
ehcache.jar                   org.springframework.expression.jar
gicentreUtils.jar             org.springframework.jdbc.jar
gluegen-rt.jar                org.springframework.orm.jar
grib.jar                      org.springframework.transaction.jar
gtkjfilechooser.jar           perf4j.jar
guava-jdk5.jar                physics.jar
hibernate.jar                 platform.jar
hibernate-jpa-2.0-api.jar     poi.jar
ice.jar                       poi-loci.jar
ij.jar                        processing-controlP5.jar
ini4j.jar                     processing-core.jar
insight.jar                   romio.jar
jai_imageio.jar               saaj.jar
java-getopt.jar               scifio.jar
java-image-scaling.jar        serializer.jar
jaxrpc.jar                    slf4j-api.jar
jcommon.jar                   slf4j-log4j12.jar
jfreechart.jar                specification.jar
JHotDraw.jar                  swingx.jar
jna.jar                       TableLayout.jar
joda-time.jar                 turbojpeg.jar
jogl.jar                      wsdl4j.jar
jul-to-slf4j.jar              xalan.jar

dist/lib/server/:
activation.jar                        log4j.jar
antlr.jar                             logback-classic.jar
asm-attrs.jar                         logback-core.jar
asm.jar                               lucene-core.jar
assumeng.jar                          lucene-highlighter.jar
backport-util-concurrent.jar          lucene-misc.jar
batik-all.jar                         lucene-spellchecker.jar
bio-formats.jar                       lwf-stubs.jar
blitz.jar                             mail.jar
btm.jar                               mdbtools-java.jar
bufr.jar                              metakit.jar
cglib-nodep.jar                       model-psql.jar
common.jar                            native-lib-loader.jar
commons-beanutils.jar                 netcdf.jar
commons-codec.jar                     ome-io.jar
commons-collections.jar               ome-java.jar
commons-httpclient.jar                omero-shares.jar
commons-io.jar                        ome-xml.jar
commons-lang.jar                      org.springframework.aop.jar
commons-logging.jar                   org.springframework.asm.jar
commons-pool.jar                      org.springframework.beans.jar
com.springsource.org.aopalliance.jar  org.springframework.context.jar
dom4j.jar                             org.springframework.context.support.jar
dsl.jar                               org.springframework.core.jar
ehcache-core.jar                      org.springframework.expression.jar
ehcache.jar                           org.springframework.jdbc.jar
FontBox.jar                           org.springframework.orm.jar
geronimo-spec-jta.jar                 org.springframework.transaction.jar
grib.jar                              PDFBox.jar
guava-jdk5.jar                        perf4j.jar
hibernate.jar                         poi-loci.jar
hibernate-jpa-2.0-api.jar             postgresql.jar
hibernate-search.jar                  quartz.jar
hibernate-validator.jar               rendering.jar
ice-db.jar                            romio.jar
ice-freeze.jar                        scifio.jar
ice.jar                               serializer.jar
ini4j.jar                             server.jar
jai_imageio.jar                       services.jar
jamon.jar                             slf4j-api.jar
janino.jar                            slf4j-log4j12.jar
java-getopt.jar                       specification.jar
java-image-scaling.jar                spring-ldap.jar
javassist.jar                         spring-security-config.jar
jcl-over-slf4j.jar                    spring-security-core.jar
joda-time.jar                         spring-security-ldap.jar
jsr107cache.jar                       turbojpeg.jar
jts.jar                               xalan.jar
jul-to-slf4j.jar                      xercesImpl.jar
JWlz.jar                              xml-apis-ext.jar
kryo.jar                              xml-apis.jar
loci-common.jar
mtbc@ls28101:~/src/openmicroscopy$ 

[jamoore]

The lib/server directory contains both logback and log4j, i.e. libraries are not being deleted between the two builds. Other than detecting the branch switch and performing a clean, we could at most try to force the output of the call to java ome.*PasswordUtil to be a single line.

[jamoore]

Note: output as seen by Will:

insert into password values (0,'12:14:28,688 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
12:14:28,688 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
12:14:28,688 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/Users/will/Desktop/OMERO/dist/lib/server/server.jar!/logback.xml]
12:14:28,689 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs multiple times on the classpath.
12:14:28,689 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [jar:file:/Users/will/Desktop/OMERO/dist/lib/server/romio.jar!/logback.xml]
12:14:28,689 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [jar:file:/Users/will/Desktop/OMERO/dist/lib/server/dsl.jar!/logback.xml]
12:14:28,689 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [jar:file:/Users/will/Desktop/OMERO/dist/lib/server/rendering.jar!/logback.xml]
12:14:28,689 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [jar:file:/Users/will/Desktop/OMERO/dist/lib/server/server.jar!/logback.xml]
12:14:28,689 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [jar:file:/Users/will/Desktop/OMERO/dist/lib/server/common.jar!/logback.xml]
12:14:28,689 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [jar:file:/Users/will/Desktop/OMERO/dist/lib/server/model-psql.jar!/logback.xml]
12:14:28,703 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@4f8235ed - URL [jar:file:/Users/will/Desktop/OMERO/dist/lib/server/server.jar!/logback.xml] is not of type file
12:14:28,807 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
12:14:28,812 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
12:14:28,818 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [stderr]
12:14:28,851 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
12:14:28,887 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [velocity] to ERROR
12:14:28,887 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org] to INFO
12:14:28,887 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [ome.adapters] to ERROR
12:14:28,887 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [ome] to INFO
12:14:28,887 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [ome.formats] to INFO
12:14:28,887 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [loci] to ERROR
12:14:28,887 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [ome.system] to WARN
12:14:28,888 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [ome.services.db.SelfCorrectingDataSource] to ERROR
12:14:28,888 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN
12:14:28,888 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [stderr] to Logger[ROOT]
12:14:28,888 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
12:14:28,889 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@6da28362 - Registering current configuration as safe fallback point

LSjpGNDDKH/7iZyIwB8OTA==');

[mtbcarroll]

It is fine with me if we have to make sure that the docs warn people to do a clean in between branch changes. I think that our CI infrastructure probably starts out with pretty clean build directories each time so that is probably safe from awkward leftovers.

It is a pity that this particular problem manifests in such a confusing way, but I don't have immediate ideas for easily improving that.

There is a more general issue here: the results of testing a branch may not be valid if the presence of some JAR from a build at some other branch / time affects the behavior. Perhaps we need to more eagerly tell people that, while a clean may not be needed in the middle of an iterative development cycle, it is probably generally a good idea to do one before final checks on work and in PR review.

[jamoore]

Since there's no intent of opening a PR for 4.4.10, I'm moving this to 5.0.0. Other than documenting (or auto-detecting) the issue, there's probably not much we can do without moving to a more maven-like dependency directory where everything is referenced explicitly by version number.

[jamoore]

Taking my name off this. It may be that we can't do anything for 5.0.0. If someone wants to try, please feel free.

[jamoore]

Pushing. May even need to go to 5.1.0 for a complete jar reworking.

[mtbcarroll]

Okay with me to push again once we have a 5.0.2 milestone.

[mtbcarroll]

Because this seemed worst for when moving between 4.4.x and 5.x I'm happy for this ticket to be pushed out beyond 5.0 given how inactive 4.4.x now is and all what else needs to be done.

[jamoore]

I'm tempted to close since A) I don't forsee it happening again and B) I don't see what we can do about it.

[mtbcarroll]

Fine with me, there are certainly higher priorities!