You are viewing a plain text version of this content. The canonical link for it is here.

Posted to dev@sling.apache.org by Ian Boston <ie...@tfd.co.uk> on 2016/07/26 14:58:49 UTC

Reducing Surefire Logging output.

Hi,
I am trying to reduce the volume of logging output that a Sling build
produces so that we can build pull requests using Travis. Travis kills the
build when it produces > 4MB of log file, which is about 32K lines of log
files. 99% of those lines serve no real purpose other than to bloat the
output.

[1] is an example travis run, started using a maven wrapper to allow maven
3.3.9 to be used. (you may not be able to load it, as it's so huge)

 ./mvnw -q
 -Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
-Dorg.apache.sling.commons.log.level=warn" clean install
-DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests

The -q puts the maven logger in ERROR level.
The -Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
-Dorg.apache.sling.commons.log.level=warn" causes forked surefire processes
which log with SLF4J to log at WARN level.

This all works, except many of the tests in Sling still log at INFO level,
presumably because it doesn't take any notice of the surefire settings.

Does anyone know how to prevent Felix when running Sling tests  from
logging 1000s of REGISTERED, UNREGISTERED messages ?

eg

Running org.apache.sling.commons.classloader.it.DynamicClassLoaderIT

[main] INFO org.ops4j.pax.exam.spi.DefaultExamSystem - Pax Exam System
(Version: 4.9.1) created.

[main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner - creating PaxExam
runner for class
org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
[main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner - running test class
org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
[main] INFO org.ops4j.exec.DefaultJavaRunner - DefaultJavaRunner completed
successfully

[org.ops4j.pax.swissbox.extender.BundleWatcher] : Creating bundle watcher
with scanner [org.ops4j.pax.swissbox.extender.BundleManifestScanner@35c29153]...[org.ops4j.pax.swissbox.extender.BundleWatcher]
: Scanning bundle
[org.apache.felix.framework][org.ops4j.pax.swissbox.extender.BundleWatcher]
: Scanning bundle
[org.ops4j.pax.exam][org.ops4j.pax.swissbox.extender.BundleWatcher] :
Scanning bundle
[org.ops4j.pax.exam.inject][org.ops4j.pax.swissbox.extender.BundleWatcher]
: Scanning bundle
[org.ops4j.pax.exam.extender.service][org.ops4j.pax.swissbox.extender.BundleWatcher]
: Scanning bundle [osgi.cmpn]

org.ops4j.pax.logging.pax-logging-api[org.ops4j.pax.logging.internal.Activator]
: Enabling SLF4J API support.
If I can't find some way of reducing the output I will have to resort to
grep on the output of mvn.

Best Regards
Ian


1 https://travis-ci.org/apache/sling/jobs/147487804

Re: Reducing Surefire Logging output.

Posted by Ian Boston <ie...@tfd.co.uk>.

On 27 July 2016 at 10:03, Robert Munteanu <ro...@apache.org> wrote:

> On Wed, 2016-07-27 at 09:58 +0100, Ian Boston wrote:
> > Hi,
> > Yes, this is the command when I got those numbers
> >
> > mvn -q
> > -Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > -Dorg.apache.sling.commons.log.level=WARN" clean install
> > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1
> > |  egrep -v
> > "^\W*at|DEBUG|WARN|INFO|REGISTER|\*ERROR\*|^ERROR|org\.ops4j\.pax\.|^
> > \W*-
> > > ^org\.apache\.|^registerMimeType"
> >
> > However, I have had to disable tests and filter more ...
> >
> > mvn -Dmaven.test.skip=true clean install | tee >(tail -500 1>&2) |
> > grep
> > "Building Apache"
> >
> > becasue, the tests are too unreliable and give false negatives well
> > over
> > 50% of the time and even the testless build produces so much output
> > that
> > Travis will kill. Maven isnt very good at producing minimal output -q
> > results in no outputput for > 10 mins so Travis kills the job
> > believing its
> > dead. The above shows 1 line per pom and the last 500 lines on
> > stderr. I
> > have to propagate the pipe error with a set -o pipefail to get the
> > maven
> > fail out to travis.
> >
> > Our travis builds run in Docker so start in < 10s after a pull
> > request is
> > updated with a commit. Pitty they done complete in < 1min.
>
> Is it possible to trigger a job on a module only? I guess that would
> cover a large majority of the cases.
>


While all the modules are in 1 repo there is no way of knowing what a
commit will impact as it will impact everything downstream.
Also, Travis doesn't provide any such mechanism.
I guess it could be scripted (ie find the changes, regex for the paths,
build only those modules), but that would not take account of downstream
impact.

Travis now succeeds so I will gather some stats and share them on a JIRA.
Best Regards
Ian



>
> Robert
>
> >
> > Best Regards
> >
> > Ian
> >
> > On 27 July 2016 at 09:32, Robert Munteanu <ro...@apache.org> wrote:
> >
> > > On Tue, 2016-07-26 at 16:48 +0100, Ian Boston wrote:
> > > > Hi,
> > > >
> > > > On 26 July 2016 at 16:27, Robert Munteanu <ro...@apache.org>
> > > > wrote:
> > > >
> > > > > On Tue, 2016-07-26 at 16:24 +0100, Ian Boston wrote:
> > > > > > Hi,
> > > > > > On the command line that doesnt appear to do anything.
> > > > > >
> > > > > > cd bundles/commons/classloader
> > > > > > mvn -q
> > > > > > -Dmaven.surefire.debug="-
> > > > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > > > -Dorg.apache.sling.commons.log.level=WARN
> > > > > > -Dorg.ops4j.pax.logging.DefaultServiceLog.level=ERROR" clean
> > > > > > install
> > > > >
> > > > > No, it probably needs to be set in the Java code, as the pax-
> > > > > exam
> > > > > container is usually forked.
> > > > >
> > > > > Perhaps we can add a utility method which forwards a well-known
> > > > > system
> > > > > property to pax-exam in the new pax-exam support bundle.
> > > > >
> > > >
> > > >
> > > > I think it's probably not worth changing the code or adding
> > > > complexity. I
> > > > am able to eliminate most of the noise and get Travis to build
> > > > with
> > > > the
> > > > following.
> > > >
> > > > mvn -q
> > > > -Dmaven.surefire.debug="-
> > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > -Dorg.apache.sling.commons.log.level=WARN" clean install
> > > > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1
> > > > >  egrep -v
> > > > "^\W*at|DEBUG|WARN|INFO|REGISTER|\*ERROR\*|^ERROR|org\.ops4j\.pax
> > > > \.|^
> > > > \W*-
> > > > > ^org\.apache\.|^registerMimeType"
> > > >
> > > >
> > > > It might make it hard for someone to see the root cause in
> > > > travis,
> > > > but it
> > > > should indicate approximately where the problem is.
> > > >
> > > > Builds on pull requests are taking 21 minutes on Travis to do a
> > > > matrix of
> > > > JDK8,7 and OpenJDK7, which isn't ideal, but better than Jenkins
> > > > which
> > > > takes
> > > > 1h40m to complete JDK8.
> > >
> > > Is Travis running the exact same buid as Jenkins? 5 times faster is
> > > a
> > > very good result.
> > >
> > > Robert
> > >
> > > >
> > > > Obviously Travis only works on GitHub repos.
> > > >
> > > > Best Regards
> > > >
> > > > Ian
> > > >
> > > >
> > > >
> > > >
> > > > >
> > > > > Robert
> > > > >
> > > > > >
> > > > > > ...
> > > > > >
> > > > > >
> > > > > > [main] INFO org.ops4j.exec.DefaultJavaRunner - Platform has
> > > > > > been
> > > > > > shutdown.
> > > > > > [main] INFO org.ops4j.pax.exam.spi.reactors.ReactorManager -
> > > > > > suite
> > > > > > finished
> > > > > >
> > > > > > Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time
> > > > > > elapsed:
> > > > > > 6.947
> > > > > > sec -
> > > > > > in
> > > > > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > > > >
> > > > > > even with
> > > > > >
> > > > > > ./mvnw -q
> > > > > > -Dmaven.surefire.debug="-
> > > > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > > > -Dorg.apache.sling.commons.log.level=WARN" clean install
> > > > > > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests
> > > > > > 2>&1
> > > > > > >  grep -v
> > > > > > DEBUG | grep -v INFO | grep -v REGISTER
> > > > > >
> > > > > >
> > > > > > I still get > 30K lines of logs, but the build is getting
> > > > > > further
> > > > > > through. I
> > > > > > may have to get a lot more aggressive at filtering out the
> > > > > > junk.
> > > > > >
> > > > > >
> > > > > > Thanks for the pointer.
> > > > > >
> > > > > > Best Regards
> > > > > >
> > > > > > Ian
> > > > > >
> > > > > >
> > > > > >
> > > > > > On 26 July 2016 at 16:08, Robert Munteanu <rombert@apache.org
> > > > > > >
> > > > > > wrote:
> > > > > >
> > > > > > > Hi Ian,
> > > > > > >
> > > > > > > On Tue, 2016-07-26 at 15:58 +0100, Ian Boston wrote:
> > > > > > > > Hi,
> > > > > > > > I am trying to reduce the volume of logging output that a
> > > > > > > > Sling
> > > > > > > > build
> > > > > > > > produces so that we can build pull requests using Travis.
> > > > > > > > Travis
> > > > > > > > kills the
> > > > > > > > build when it produces > 4MB of log file, which is about
> > > > > > > > 32K
> > > > > > > > lines of
> > > > > > > > log
> > > > > > > > files. 99% of those lines serve no real purpose other
> > > > > > > > than to
> > > > > > > > bloat
> > > > > > > > the
> > > > > > > > output.
> > > > > > > >
> > > > > > > > [1] is an example travis run, started using a maven
> > > > > > > > wrapper
> > > > > > > > to
> > > > > > > > allow
> > > > > > > > maven
> > > > > > > > 3.3.9 to be used. (you may not be able to load it, as
> > > > > > > > it's so
> > > > > > > > huge)
> > > > > > > >
> > > > > > > >  ./mvnw -q
> > > > > > > >  -Dmaven.surefire.debug="-
> > > > > > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > > > > > -Dorg.apache.sling.commons.log.level=warn" clean install
> > > > > > > > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests
> > > > > > > >
> > > > > > > > The -q puts the maven logger in ERROR level.
> > > > > > > > The -Dmaven.surefire.debug="-
> > > > > > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > > > > > -Dorg.apache.sling.commons.log.level=warn" causes forked
> > > > > > > > surefire
> > > > > > > > processes
> > > > > > > > which log with SLF4J to log at WARN level.
> > > > > > > >
> > > > > > > > This all works, except many of the tests in Sling still
> > > > > > > > log
> > > > > > > > at
> > > > > > > > INFO
> > > > > > > > level,
> > > > > > > > presumably because it doesn't take any notice of the
> > > > > > > > surefire
> > > > > > > > settings.
> > > > > > > >
> > > > > > > > Does anyone know how to prevent Felix when running Sling
> > > > > > > > tests  from
> > > > > > > > logging 1000s of REGISTERED, UNREGISTERED messages ?
> > > > > > >
> > > > > > > There might be multiple issues here, but for the pax-exam
> > > > > > > tests, at
> > > > > > > least when using the provided logging wrapper you would
> > > > > > > need to
> > > > > > > configure the tests with
> > > > > > >
> > > > > > >
> > > > > > > CoreOptions.systemProperty("org.ops4j.pax.logging.DefaultSe
> > > > > > > rvic
> > > > > > > eLog
> > > > > > > .l
> > > > > > > evel").val‌ue("WARN")
> > > > > > >
> > > > > > > Robert
> > > > > > >
> > > > > > > >
> > > > > > > > eg
> > > > > > > >
> > > > > > > > Running
> > > > > > > > org.apache.sling.commons.classloader.it.DynamicClassLoade
> > > > > > > > rIT
> > > > > > > >
> > > > > > > > [main] INFO org.ops4j.pax.exam.spi.DefaultExamSystem -
> > > > > > > > Pax
> > > > > > > > Exam
> > > > > > > > System
> > > > > > > > (Version: 4.9.1) created.
> > > > > > > >
> > > > > > > > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner -
> > > > > > > > creating
> > > > > > > > PaxExam
> > > > > > > > runner for class
> > > > > > > > org.apache.sling.commons.classloader.it.DynamicClassLoade
> > > > > > > > rIT
> > > > > > > > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner -
> > > > > > > > running
> > > > > > > > test
> > > > > > > > class
> > > > > > > > org.apache.sling.commons.classloader.it.DynamicClassLoade
> > > > > > > > rIT
> > > > > > > > [main] INFO org.ops4j.exec.DefaultJavaRunner -
> > > > > > > > DefaultJavaRunner
> > > > > > > > completed
> > > > > > > > successfully
> > > > > > > >
> > > > > > > > [org.ops4j.pax.swissbox.extender.BundleWatcher] :
> > > > > > > > Creating
> > > > > > > > bundle
> > > > > > > > watcher
> > > > > > > > with scanner
> > > > > > > > [org.ops4j.pax.swissbox.extender.BundleManifestScann
> > > > > > > > er@3
> > > > > > > > 5c29153]...[org.ops4j.pax.swissbox.extender.BundleWatcher
> > > > > > > > ]
> > > > > > > > : Scanning bundle
> > > > > > > > [org.apache.felix.framework][org.ops4j.pax.swissbox.exten
> > > > > > > > der.
> > > > > > > > Bund
> > > > > > > > leWa
> > > > > > > > tcher]
> > > > > > > > : Scanning bundle
> > > > > > > > [org.ops4j.pax.exam][org.ops4j.pax.swissbox.extender.Bund
> > > > > > > > leWa
> > > > > > > > tche
> > > > > > > > r] :
> > > > > > > > Scanning bundle
> > > > > > > > [org.ops4j.pax.exam.inject][org.ops4j.pax.swissbox.extend
> > > > > > > > er.B
> > > > > > > > undl
> > > > > > > > eWat
> > > > > > > > cher]
> > > > > > > > : Scanning bundle
> > > > > > > > [org.ops4j.pax.exam.extender.service][org.ops4j.pax.swiss
> > > > > > > > box.
> > > > > > > > exte
> > > > > > > > nder
> > > > > > > > .BundleWatcher]
> > > > > > > > : Scanning bundle [osgi.cmpn]
> > > > > > > >
> > > > > > > > org.ops4j.pax.logging.pax-logging-
> > > > > > > > api[org.ops4j.pax.logging.internal.Activator]
> > > > > > > > : Enabling SLF4J API support.
> > > > > > > > If I can't find some way of reducing the output I will
> > > > > > > > have
> > > > > > > > to
> > > > > > > > resort
> > > > > > > > to
> > > > > > > > grep on the output of mvn.
> > > > > > > >
> > > > > > > > Best Regards
> > > > > > > > Ian
> > > > > > > >
> > > > > > > >
> > > > > > > > 1 https://travis-ci.org/apache/sling/jobs/147487804
> > > > > > >
> > > > > > >
> > > > >
> > > > >
> > >
> > >
>
>

Re: Reducing Surefire Logging output.

Posted by Robert Munteanu <ro...@apache.org>.

On Wed, 2016-07-27 at 09:58 +0100, Ian Boston wrote:
> Hi,
> Yes, this is the command when I got those numbers
> 
> mvn -q
> -Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> -Dorg.apache.sling.commons.log.level=WARN" clean install
> -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1
> |��egrep -v
> "^\W*at|DEBUG|WARN|INFO|REGISTER|\*ERROR\*|^ERROR|org\.ops4j\.pax\.|^
> \W*-
> > ^org\.apache\.|^registerMimeType"
> 
> However, I have had to disable tests and filter more ...
> 
> mvn -Dmaven.test.skip=true clean install | tee >(tail -500 1>&2) |
> grep
> "Building Apache"
> 
> becasue, the tests are too unreliable and give false negatives well
> over
> 50% of the time and even the testless build produces so much output
> that
> Travis will kill. Maven isnt very good at producing minimal output -q
> results in no outputput for > 10 mins so Travis kills the job
> believing its
> dead. The above shows 1 line per pom and the last 500 lines on
> stderr. I
> have to propagate the pipe error with a set -o pipefail to get the
> maven
> fail out to travis.
> 
> Our travis builds run in Docker so start in < 10s after a pull
> request is
> updated with a commit. Pitty they done complete in < 1min.

Is it possible to trigger a job on a module only? I guess that would
cover a large majority of the cases.

Robert

> 
> Best Regards
> 
> Ian
> 
> On 27 July 2016 at 09:32, Robert Munteanu <ro...@apache.org> wrote:
> 
> > On Tue, 2016-07-26 at 16:48 +0100, Ian Boston wrote:
> > > Hi,
> > > 
> > > On 26 July 2016 at 16:27, Robert Munteanu <ro...@apache.org>
> > > wrote:
> > > 
> > > > On Tue, 2016-07-26 at 16:24 +0100, Ian Boston wrote:
> > > > > Hi,
> > > > > On the command line that doesnt appear to do anything.
> > > > > 
> > > > > cd bundles/commons/classloader
> > > > > mvn -q
> > > > > -Dmaven.surefire.debug="-
> > > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > > -Dorg.apache.sling.commons.log.level=WARN
> > > > > -Dorg.ops4j.pax.logging.DefaultServiceLog.level=ERROR" clean
> > > > > install
> > > > 
> > > > No, it probably needs to be set in the Java code, as the pax-
> > > > exam
> > > > container is usually forked.
> > > > 
> > > > Perhaps we can add a utility method which forwards a well-known
> > > > system
> > > > property to pax-exam in the new pax-exam support bundle.
> > > > 
> > > 
> > > 
> > > I think it's probably not worth changing the code or adding
> > > complexity. I
> > > am able to eliminate most of the noise and get Travis to build
> > > with
> > > the
> > > following.
> > > 
> > > mvn -q
> > > -Dmaven.surefire.debug="-
> > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > -Dorg.apache.sling.commons.log.level=WARN" clean install
> > > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1
> > > > �egrep -v
> > > "^\W*at|DEBUG|WARN|INFO|REGISTER|\*ERROR\*|^ERROR|org\.ops4j\.pax
> > > \.|^
> > > \W*-
> > > > ^org\.apache\.|^registerMimeType"
> > > 
> > > 
> > > It might make it hard for someone to see the root cause in
> > > travis,
> > > but it
> > > should indicate approximately where the problem is.
> > > 
> > > Builds on pull requests are taking 21 minutes on Travis to do a
> > > matrix of
> > > JDK8,7 and OpenJDK7, which isn't ideal, but better than Jenkins
> > > which
> > > takes
> > > 1h40m to complete JDK8.
> > 
> > Is Travis running the exact same buid as Jenkins? 5 times faster is
> > a
> > very good result.
> > 
> > Robert
> > 
> > > 
> > > Obviously Travis only works on GitHub repos.
> > > 
> > > Best Regards
> > > 
> > > Ian
> > > 
> > > 
> > > 
> > > 
> > > > 
> > > > Robert
> > > > 
> > > > > 
> > > > > ...
> > > > > 
> > > > > 
> > > > > [main] INFO org.ops4j.exec.DefaultJavaRunner - Platform has
> > > > > been
> > > > > shutdown.
> > > > > [main] INFO org.ops4j.pax.exam.spi.reactors.ReactorManager -
> > > > > suite
> > > > > finished
> > > > > 
> > > > > Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time
> > > > > elapsed:
> > > > > 6.947
> > > > > sec -
> > > > > in
> > > > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > > > 
> > > > > even with
> > > > > 
> > > > > ./mvnw -q
> > > > > -Dmaven.surefire.debug="-
> > > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > > -Dorg.apache.sling.commons.log.level=WARN" clean install
> > > > > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests
> > > > > 2>&1
> > > > > > �grep -v
> > > > > DEBUG | grep -v INFO | grep -v REGISTER
> > > > > 
> > > > > 
> > > > > I still get > 30K lines of logs, but the build is getting
> > > > > further
> > > > > through. I
> > > > > may have to get a lot more aggressive at filtering out the
> > > > > junk.
> > > > > 
> > > > > 
> > > > > Thanks for the pointer.
> > > > > 
> > > > > Best Regards
> > > > > 
> > > > > Ian
> > > > > 
> > > > > 
> > > > > 
> > > > > On 26 July 2016 at 16:08, Robert Munteanu <rombert@apache.org
> > > > > >
> > > > > wrote:
> > > > > 
> > > > > > Hi Ian,
> > > > > > 
> > > > > > On Tue, 2016-07-26 at 15:58 +0100, Ian Boston wrote:
> > > > > > > Hi,
> > > > > > > I am trying to reduce the volume of logging output that a
> > > > > > > Sling
> > > > > > > build
> > > > > > > produces so that we can build pull requests using Travis.
> > > > > > > Travis
> > > > > > > kills the
> > > > > > > build when it produces > 4MB of log file, which is about
> > > > > > > 32K
> > > > > > > lines of
> > > > > > > log
> > > > > > > files. 99% of those lines serve no real purpose other
> > > > > > > than to
> > > > > > > bloat
> > > > > > > the
> > > > > > > output.
> > > > > > > 
> > > > > > > [1] is an example travis run, started using a maven
> > > > > > > wrapper
> > > > > > > to
> > > > > > > allow
> > > > > > > maven
> > > > > > > 3.3.9 to be used. (you may not be able to load it, as
> > > > > > > it's so
> > > > > > > huge)
> > > > > > > 
> > > > > > > �./mvnw -q
> > > > > > > �-Dmaven.surefire.debug="-
> > > > > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > > > > -Dorg.apache.sling.commons.log.level=warn" clean install
> > > > > > > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests
> > > > > > > 
> > > > > > > The -q puts the maven logger in ERROR level.
> > > > > > > The -Dmaven.surefire.debug="-
> > > > > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > > > > -Dorg.apache.sling.commons.log.level=warn" causes forked
> > > > > > > surefire
> > > > > > > processes
> > > > > > > which log with SLF4J to log at WARN level.
> > > > > > > 
> > > > > > > This all works, except many of the tests in Sling still
> > > > > > > log
> > > > > > > at
> > > > > > > INFO
> > > > > > > level,
> > > > > > > presumably because it doesn't take any notice of the
> > > > > > > surefire
> > > > > > > settings.
> > > > > > > 
> > > > > > > Does anyone know how to prevent Felix when running Sling
> > > > > > > tests��from
> > > > > > > logging 1000s of REGISTERED, UNREGISTERED messages ?
> > > > > > 
> > > > > > There might be multiple issues here, but for the pax-exam
> > > > > > tests, at
> > > > > > least when using the provided logging wrapper you would
> > > > > > need to
> > > > > > configure the tests with
> > > > > > 
> > > > > > 
> > > > > > CoreOptions.systemProperty("org.ops4j.pax.logging.DefaultSe
> > > > > > rvic
> > > > > > eLog
> > > > > > .l
> > > > > > evel").val\u200cue("WARN")
> > > > > > 
> > > > > > Robert
> > > > > > 
> > > > > > > 
> > > > > > > eg
> > > > > > > 
> > > > > > > Running
> > > > > > > org.apache.sling.commons.classloader.it.DynamicClassLoade
> > > > > > > rIT
> > > > > > > 
> > > > > > > [main] INFO org.ops4j.pax.exam.spi.DefaultExamSystem -
> > > > > > > Pax
> > > > > > > Exam
> > > > > > > System
> > > > > > > (Version: 4.9.1) created.
> > > > > > > 
> > > > > > > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner -
> > > > > > > creating
> > > > > > > PaxExam
> > > > > > > runner for class
> > > > > > > org.apache.sling.commons.classloader.it.DynamicClassLoade
> > > > > > > rIT
> > > > > > > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner -
> > > > > > > running
> > > > > > > test
> > > > > > > class
> > > > > > > org.apache.sling.commons.classloader.it.DynamicClassLoade
> > > > > > > rIT
> > > > > > > [main] INFO org.ops4j.exec.DefaultJavaRunner -
> > > > > > > DefaultJavaRunner
> > > > > > > completed
> > > > > > > successfully
> > > > > > > 
> > > > > > > [org.ops4j.pax.swissbox.extender.BundleWatcher] :
> > > > > > > Creating
> > > > > > > bundle
> > > > > > > watcher
> > > > > > > with scanner
> > > > > > > [org.ops4j.pax.swissbox.extender.BundleManifestScann
> > > > > > > er@3
> > > > > > > 5c29153]...[org.ops4j.pax.swissbox.extender.BundleWatcher
> > > > > > > ]
> > > > > > > : Scanning bundle
> > > > > > > [org.apache.felix.framework][org.ops4j.pax.swissbox.exten
> > > > > > > der.
> > > > > > > Bund
> > > > > > > leWa
> > > > > > > tcher]
> > > > > > > : Scanning bundle
> > > > > > > [org.ops4j.pax.exam][org.ops4j.pax.swissbox.extender.Bund
> > > > > > > leWa
> > > > > > > tche
> > > > > > > r] :
> > > > > > > Scanning bundle
> > > > > > > [org.ops4j.pax.exam.inject][org.ops4j.pax.swissbox.extend
> > > > > > > er.B
> > > > > > > undl
> > > > > > > eWat
> > > > > > > cher]
> > > > > > > : Scanning bundle
> > > > > > > [org.ops4j.pax.exam.extender.service][org.ops4j.pax.swiss
> > > > > > > box.
> > > > > > > exte
> > > > > > > nder
> > > > > > > .BundleWatcher]
> > > > > > > : Scanning bundle [osgi.cmpn]
> > > > > > > 
> > > > > > > org.ops4j.pax.logging.pax-logging-
> > > > > > > api[org.ops4j.pax.logging.internal.Activator]
> > > > > > > : Enabling SLF4J API support.
> > > > > > > If I can't find some way of reducing the output I will
> > > > > > > have
> > > > > > > to
> > > > > > > resort
> > > > > > > to
> > > > > > > grep on the output of mvn.
> > > > > > > 
> > > > > > > Best Regards
> > > > > > > Ian
> > > > > > > 
> > > > > > > 
> > > > > > > 1 https://travis-ci.org/apache/sling/jobs/147487804
> > > > > > 
> > > > > > 
> > > > 
> > > > 
> > 
> >

Re: Reducing Surefire Logging output.

Posted by Ian Boston <ie...@tfd.co.uk>.

Hi,
Yes, this is the command when I got those numbers

mvn -q
-Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
-Dorg.apache.sling.commons.log.level=WARN" clean install
-DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1 |  egrep -v
"^\W*at|DEBUG|WARN|INFO|REGISTER|\*ERROR\*|^ERROR|org\.ops4j\.pax\.|^\W*-
|^org\.apache\.|^registerMimeType"

However, I have had to disable tests and filter more ...

mvn -Dmaven.test.skip=true clean install | tee >(tail -500 1>&2) | grep
"Building Apache"

becasue, the tests are too unreliable and give false negatives well over
50% of the time and even the testless build produces so much output that
Travis will kill. Maven isnt very good at producing minimal output -q
results in no outputput for > 10 mins so Travis kills the job believing its
dead. The above shows 1 line per pom and the last 500 lines on stderr. I
have to propagate the pipe error with a set -o pipefail to get the maven
fail out to travis.

Our travis builds run in Docker so start in < 10s after a pull request is
updated with a commit. Pitty they done complete in < 1min.

Best Regards

Ian

On 27 July 2016 at 09:32, Robert Munteanu <ro...@apache.org> wrote:

> On Tue, 2016-07-26 at 16:48 +0100, Ian Boston wrote:
> > Hi,
> >
> > On 26 July 2016 at 16:27, Robert Munteanu <ro...@apache.org> wrote:
> >
> > > On Tue, 2016-07-26 at 16:24 +0100, Ian Boston wrote:
> > > > Hi,
> > > > On the command line that doesnt appear to do anything.
> > > >
> > > > cd bundles/commons/classloader
> > > > mvn -q
> > > > -Dmaven.surefire.debug="-
> > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > -Dorg.apache.sling.commons.log.level=WARN
> > > > -Dorg.ops4j.pax.logging.DefaultServiceLog.level=ERROR" clean
> > > > install
> > >
> > > No, it probably needs to be set in the Java code, as the pax-exam
> > > container is usually forked.
> > >
> > > Perhaps we can add a utility method which forwards a well-known
> > > system
> > > property to pax-exam in the new pax-exam support bundle.
> > >
> >
> >
> > I think it's probably not worth changing the code or adding
> > complexity. I
> > am able to eliminate most of the noise and get Travis to build with
> > the
> > following.
> >
> > mvn -q
> > -Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > -Dorg.apache.sling.commons.log.level=WARN" clean install
> > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1
> > |  egrep -v
> > "^\W*at|DEBUG|WARN|INFO|REGISTER|\*ERROR\*|^ERROR|org\.ops4j\.pax\.|^
> > \W*-
> > > ^org\.apache\.|^registerMimeType"
> >
> >
> > It might make it hard for someone to see the root cause in travis,
> > but it
> > should indicate approximately where the problem is.
> >
> > Builds on pull requests are taking 21 minutes on Travis to do a
> > matrix of
> > JDK8,7 and OpenJDK7, which isn't ideal, but better than Jenkins which
> > takes
> > 1h40m to complete JDK8.
>
> Is Travis running the exact same buid as Jenkins? 5 times faster is a
> very good result.
>
> Robert
>
> >
> > Obviously Travis only works on GitHub repos.
> >
> > Best Regards
> >
> > Ian
> >
> >
> >
> >
> > >
> > > Robert
> > >
> > > >
> > > > ...
> > > >
> > > >
> > > > [main] INFO org.ops4j.exec.DefaultJavaRunner - Platform has been
> > > > shutdown.
> > > > [main] INFO org.ops4j.pax.exam.spi.reactors.ReactorManager -
> > > > suite
> > > > finished
> > > >
> > > > Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed:
> > > > 6.947
> > > > sec -
> > > > in org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > >
> > > > even with
> > > >
> > > > ./mvnw -q
> > > > -Dmaven.surefire.debug="-
> > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > -Dorg.apache.sling.commons.log.level=WARN" clean install
> > > > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1
> > > > >  grep -v
> > > > DEBUG | grep -v INFO | grep -v REGISTER
> > > >
> > > >
> > > > I still get > 30K lines of logs, but the build is getting further
> > > > through. I
> > > > may have to get a lot more aggressive at filtering out the junk.
> > > >
> > > >
> > > > Thanks for the pointer.
> > > >
> > > > Best Regards
> > > >
> > > > Ian
> > > >
> > > >
> > > >
> > > > On 26 July 2016 at 16:08, Robert Munteanu <ro...@apache.org>
> > > > wrote:
> > > >
> > > > > Hi Ian,
> > > > >
> > > > > On Tue, 2016-07-26 at 15:58 +0100, Ian Boston wrote:
> > > > > > Hi,
> > > > > > I am trying to reduce the volume of logging output that a
> > > > > > Sling
> > > > > > build
> > > > > > produces so that we can build pull requests using Travis.
> > > > > > Travis
> > > > > > kills the
> > > > > > build when it produces > 4MB of log file, which is about 32K
> > > > > > lines of
> > > > > > log
> > > > > > files. 99% of those lines serve no real purpose other than to
> > > > > > bloat
> > > > > > the
> > > > > > output.
> > > > > >
> > > > > > [1] is an example travis run, started using a maven wrapper
> > > > > > to
> > > > > > allow
> > > > > > maven
> > > > > > 3.3.9 to be used. (you may not be able to load it, as it's so
> > > > > > huge)
> > > > > >
> > > > > >  ./mvnw -q
> > > > > >  -Dmaven.surefire.debug="-
> > > > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > > > -Dorg.apache.sling.commons.log.level=warn" clean install
> > > > > > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests
> > > > > >
> > > > > > The -q puts the maven logger in ERROR level.
> > > > > > The -Dmaven.surefire.debug="-
> > > > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > > > -Dorg.apache.sling.commons.log.level=warn" causes forked
> > > > > > surefire
> > > > > > processes
> > > > > > which log with SLF4J to log at WARN level.
> > > > > >
> > > > > > This all works, except many of the tests in Sling still log
> > > > > > at
> > > > > > INFO
> > > > > > level,
> > > > > > presumably because it doesn't take any notice of the surefire
> > > > > > settings.
> > > > > >
> > > > > > Does anyone know how to prevent Felix when running Sling
> > > > > > tests  from
> > > > > > logging 1000s of REGISTERED, UNREGISTERED messages ?
> > > > >
> > > > > There might be multiple issues here, but for the pax-exam
> > > > > tests, at
> > > > > least when using the provided logging wrapper you would need to
> > > > > configure the tests with
> > > > >
> > > > >
> > > > > CoreOptions.systemProperty("org.ops4j.pax.logging.DefaultServic
> > > > > eLog
> > > > > .l
> > > > > evel").val‌ue("WARN")
> > > > >
> > > > > Robert
> > > > >
> > > > > >
> > > > > > eg
> > > > > >
> > > > > > Running
> > > > > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > > > >
> > > > > > [main] INFO org.ops4j.pax.exam.spi.DefaultExamSystem - Pax
> > > > > > Exam
> > > > > > System
> > > > > > (Version: 4.9.1) created.
> > > > > >
> > > > > > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner -
> > > > > > creating
> > > > > > PaxExam
> > > > > > runner for class
> > > > > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > > > > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner -
> > > > > > running
> > > > > > test
> > > > > > class
> > > > > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > > > > [main] INFO org.ops4j.exec.DefaultJavaRunner -
> > > > > > DefaultJavaRunner
> > > > > > completed
> > > > > > successfully
> > > > > >
> > > > > > [org.ops4j.pax.swissbox.extender.BundleWatcher] : Creating
> > > > > > bundle
> > > > > > watcher
> > > > > > with scanner
> > > > > > [org.ops4j.pax.swissbox.extender.BundleManifestScann
> > > > > > er@3
> > > > > > 5c29153]...[org.ops4j.pax.swissbox.extender.BundleWatcher]
> > > > > > : Scanning bundle
> > > > > > [org.apache.felix.framework][org.ops4j.pax.swissbox.extender.
> > > > > > Bund
> > > > > > leWa
> > > > > > tcher]
> > > > > > : Scanning bundle
> > > > > > [org.ops4j.pax.exam][org.ops4j.pax.swissbox.extender.BundleWa
> > > > > > tche
> > > > > > r] :
> > > > > > Scanning bundle
> > > > > > [org.ops4j.pax.exam.inject][org.ops4j.pax.swissbox.extender.B
> > > > > > undl
> > > > > > eWat
> > > > > > cher]
> > > > > > : Scanning bundle
> > > > > > [org.ops4j.pax.exam.extender.service][org.ops4j.pax.swissbox.
> > > > > > exte
> > > > > > nder
> > > > > > .BundleWatcher]
> > > > > > : Scanning bundle [osgi.cmpn]
> > > > > >
> > > > > > org.ops4j.pax.logging.pax-logging-
> > > > > > api[org.ops4j.pax.logging.internal.Activator]
> > > > > > : Enabling SLF4J API support.
> > > > > > If I can't find some way of reducing the output I will have
> > > > > > to
> > > > > > resort
> > > > > > to
> > > > > > grep on the output of mvn.
> > > > > >
> > > > > > Best Regards
> > > > > > Ian
> > > > > >
> > > > > >
> > > > > > 1 https://travis-ci.org/apache/sling/jobs/147487804
> > > > >
> > > > >
> > >
> > >
>
>

Re: Reducing Surefire Logging output.

Posted by Robert Munteanu <ro...@apache.org>.

On Tue, 2016-07-26 at 16:48 +0100, Ian Boston wrote:
> Hi,
> 
> On 26 July 2016 at 16:27, Robert Munteanu <ro...@apache.org> wrote:
> 
> > On Tue, 2016-07-26 at 16:24 +0100, Ian Boston wrote:
> > > Hi,
> > > On the command line that doesnt appear to do anything.
> > > 
> > > cd bundles/commons/classloader
> > > mvn -q
> > > -Dmaven.surefire.debug="-
> > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > -Dorg.apache.sling.commons.log.level=WARN
> > > -Dorg.ops4j.pax.logging.DefaultServiceLog.level=ERROR" clean
> > > install
> > 
> > No, it probably needs to be set in the Java code, as the pax-exam
> > container is usually forked.
> > 
> > Perhaps we can add a utility method which forwards a well-known
> > system
> > property to pax-exam in the new pax-exam support bundle.
> > 
> 
> 
> I think it's probably not worth changing the code or adding
> complexity. I
> am able to eliminate most of the noise and get Travis to build with
> the
> following.
> 
> mvn -q
> -Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> -Dorg.apache.sling.commons.log.level=WARN" clean install
> -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1
> |��egrep -v
> "^\W*at|DEBUG|WARN|INFO|REGISTER|\*ERROR\*|^ERROR|org\.ops4j\.pax\.|^
> \W*-
> > ^org\.apache\.|^registerMimeType"
> 
> 
> It might make it hard for someone to see the root cause in travis,
> but it
> should indicate approximately where the problem is.
> 
> Builds on pull requests are taking 21 minutes on Travis to do a
> matrix of
> JDK8,7 and OpenJDK7, which isn't ideal, but better than Jenkins which
> takes
> 1h40m to complete JDK8.

Is Travis running the exact same buid as Jenkins? 5 times faster is a
very good result.

Robert

> 
> Obviously Travis only works on GitHub repos.
> 
> Best Regards
> 
> Ian
> 
> 
> 
> 
> > 
> > Robert
> > 
> > > 
> > > ...
> > > 
> > > 
> > > [main] INFO org.ops4j.exec.DefaultJavaRunner - Platform has been
> > > shutdown.
> > > [main] INFO org.ops4j.pax.exam.spi.reactors.ReactorManager -
> > > suite
> > > finished
> > > 
> > > Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed:
> > > 6.947
> > > sec -
> > > in org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > 
> > > even with
> > > 
> > > ./mvnw -q
> > > -Dmaven.surefire.debug="-
> > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > -Dorg.apache.sling.commons.log.level=WARN" clean install
> > > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1
> > > > �grep -v
> > > DEBUG | grep -v INFO | grep -v REGISTER
> > > 
> > > 
> > > I still get > 30K lines of logs, but the build is getting further
> > > through. I
> > > may have to get a lot more aggressive at filtering out the junk.
> > > 
> > > 
> > > Thanks for the pointer.
> > > 
> > > Best Regards
> > > 
> > > Ian
> > > 
> > > 
> > > 
> > > On 26 July 2016 at 16:08, Robert Munteanu <ro...@apache.org>
> > > wrote:
> > > 
> > > > Hi Ian,
> > > > 
> > > > On Tue, 2016-07-26 at 15:58 +0100, Ian Boston wrote:
> > > > > Hi,
> > > > > I am trying to reduce the volume of logging output that a
> > > > > Sling
> > > > > build
> > > > > produces so that we can build pull requests using Travis.
> > > > > Travis
> > > > > kills the
> > > > > build when it produces > 4MB of log file, which is about 32K
> > > > > lines of
> > > > > log
> > > > > files. 99% of those lines serve no real purpose other than to
> > > > > bloat
> > > > > the
> > > > > output.
> > > > > 
> > > > > [1] is an example travis run, started using a maven wrapper
> > > > > to
> > > > > allow
> > > > > maven
> > > > > 3.3.9 to be used. (you may not be able to load it, as it's so
> > > > > huge)
> > > > > 
> > > > > �./mvnw -q
> > > > > �-Dmaven.surefire.debug="-
> > > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > > -Dorg.apache.sling.commons.log.level=warn" clean install
> > > > > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests
> > > > > 
> > > > > The -q puts the maven logger in ERROR level.
> > > > > The -Dmaven.surefire.debug="-
> > > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > > -Dorg.apache.sling.commons.log.level=warn" causes forked
> > > > > surefire
> > > > > processes
> > > > > which log with SLF4J to log at WARN level.
> > > > > 
> > > > > This all works, except many of the tests in Sling still log
> > > > > at
> > > > > INFO
> > > > > level,
> > > > > presumably because it doesn't take any notice of the surefire
> > > > > settings.
> > > > > 
> > > > > Does anyone know how to prevent Felix when running Sling
> > > > > tests��from
> > > > > logging 1000s of REGISTERED, UNREGISTERED messages ?
> > > > 
> > > > There might be multiple issues here, but for the pax-exam
> > > > tests, at
> > > > least when using the provided logging wrapper you would need to
> > > > configure the tests with
> > > > 
> > > > 
> > > > CoreOptions.systemProperty("org.ops4j.pax.logging.DefaultServic
> > > > eLog
> > > > .l
> > > > evel").val\u200cue("WARN")
> > > > 
> > > > Robert
> > > > 
> > > > > 
> > > > > eg
> > > > > 
> > > > > Running
> > > > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > > > 
> > > > > [main] INFO org.ops4j.pax.exam.spi.DefaultExamSystem - Pax
> > > > > Exam
> > > > > System
> > > > > (Version: 4.9.1) created.
> > > > > 
> > > > > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner -
> > > > > creating
> > > > > PaxExam
> > > > > runner for class
> > > > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > > > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner -
> > > > > running
> > > > > test
> > > > > class
> > > > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > > > [main] INFO org.ops4j.exec.DefaultJavaRunner -
> > > > > DefaultJavaRunner
> > > > > completed
> > > > > successfully
> > > > > 
> > > > > [org.ops4j.pax.swissbox.extender.BundleWatcher] : Creating
> > > > > bundle
> > > > > watcher
> > > > > with scanner
> > > > > [org.ops4j.pax.swissbox.extender.BundleManifestScann
> > > > > er@3
> > > > > 5c29153]...[org.ops4j.pax.swissbox.extender.BundleWatcher]
> > > > > : Scanning bundle
> > > > > [org.apache.felix.framework][org.ops4j.pax.swissbox.extender.
> > > > > Bund
> > > > > leWa
> > > > > tcher]
> > > > > : Scanning bundle
> > > > > [org.ops4j.pax.exam][org.ops4j.pax.swissbox.extender.BundleWa
> > > > > tche
> > > > > r] :
> > > > > Scanning bundle
> > > > > [org.ops4j.pax.exam.inject][org.ops4j.pax.swissbox.extender.B
> > > > > undl
> > > > > eWat
> > > > > cher]
> > > > > : Scanning bundle
> > > > > [org.ops4j.pax.exam.extender.service][org.ops4j.pax.swissbox.
> > > > > exte
> > > > > nder
> > > > > .BundleWatcher]
> > > > > : Scanning bundle [osgi.cmpn]
> > > > > 
> > > > > org.ops4j.pax.logging.pax-logging-
> > > > > api[org.ops4j.pax.logging.internal.Activator]
> > > > > : Enabling SLF4J API support.
> > > > > If I can't find some way of reducing the output I will have
> > > > > to
> > > > > resort
> > > > > to
> > > > > grep on the output of mvn.
> > > > > 
> > > > > Best Regards
> > > > > Ian
> > > > > 
> > > > > 
> > > > > 1 https://travis-ci.org/apache/sling/jobs/147487804
> > > > 
> > > > 
> > 
> >

Re: Reducing Surefire Logging output.

Posted by Ian Boston <ie...@tfd.co.uk>.

Hi,

On 26 July 2016 at 16:27, Robert Munteanu <ro...@apache.org> wrote:

> On Tue, 2016-07-26 at 16:24 +0100, Ian Boston wrote:
> > Hi,
> > On the command line that doesnt appear to do anything.
> >
> > cd bundles/commons/classloader
> > mvn -q
> > -Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > -Dorg.apache.sling.commons.log.level=WARN
> > -Dorg.ops4j.pax.logging.DefaultServiceLog.level=ERROR" clean install
>
> No, it probably needs to be set in the Java code, as the pax-exam
> container is usually forked.
>
> Perhaps we can add a utility method which forwards a well-known system
> property to pax-exam in the new pax-exam support bundle.
>


I think it's probably not worth changing the code or adding complexity. I
am able to eliminate most of the noise and get Travis to build with the
following.

mvn -q
-Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
-Dorg.apache.sling.commons.log.level=WARN" clean install
-DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1 |  egrep -v
"^\W*at|DEBUG|WARN|INFO|REGISTER|\*ERROR\*|^ERROR|org\.ops4j\.pax\.|^\W*-
|^org\.apache\.|^registerMimeType"


It might make it hard for someone to see the root cause in travis, but it
should indicate approximately where the problem is.

Builds on pull requests are taking 21 minutes on Travis to do a matrix of
JDK8,7 and OpenJDK7, which isn't ideal, but better than Jenkins which takes
1h40m to complete JDK8.

Obviously Travis only works on GitHub repos.

Best Regards

Ian




>
> Robert
>
> >
> > ...
> >
> >
> > [main] INFO org.ops4j.exec.DefaultJavaRunner - Platform has been
> > shutdown.
> > [main] INFO org.ops4j.pax.exam.spi.reactors.ReactorManager - suite
> > finished
> >
> > Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 6.947
> > sec -
> > in org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> >
> > even with
> >
> > ./mvnw -q
> > -Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > -Dorg.apache.sling.commons.log.level=WARN" clean install
> > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1
> > |  grep -v
> > DEBUG | grep -v INFO | grep -v REGISTER
> >
> >
> > I still get > 30K lines of logs, but the build is getting further
> > through. I
> > may have to get a lot more aggressive at filtering out the junk.
> >
> >
> > Thanks for the pointer.
> >
> > Best Regards
> >
> > Ian
> >
> >
> >
> > On 26 July 2016 at 16:08, Robert Munteanu <ro...@apache.org> wrote:
> >
> > > Hi Ian,
> > >
> > > On Tue, 2016-07-26 at 15:58 +0100, Ian Boston wrote:
> > > > Hi,
> > > > I am trying to reduce the volume of logging output that a Sling
> > > > build
> > > > produces so that we can build pull requests using Travis. Travis
> > > > kills the
> > > > build when it produces > 4MB of log file, which is about 32K
> > > > lines of
> > > > log
> > > > files. 99% of those lines serve no real purpose other than to
> > > > bloat
> > > > the
> > > > output.
> > > >
> > > > [1] is an example travis run, started using a maven wrapper to
> > > > allow
> > > > maven
> > > > 3.3.9 to be used. (you may not be able to load it, as it's so
> > > > huge)
> > > >
> > > >  ./mvnw -q
> > > >  -Dmaven.surefire.debug="-
> > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > -Dorg.apache.sling.commons.log.level=warn" clean install
> > > > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests
> > > >
> > > > The -q puts the maven logger in ERROR level.
> > > > The -Dmaven.surefire.debug="-
> > > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > > -Dorg.apache.sling.commons.log.level=warn" causes forked surefire
> > > > processes
> > > > which log with SLF4J to log at WARN level.
> > > >
> > > > This all works, except many of the tests in Sling still log at
> > > > INFO
> > > > level,
> > > > presumably because it doesn't take any notice of the surefire
> > > > settings.
> > > >
> > > > Does anyone know how to prevent Felix when running Sling
> > > > tests  from
> > > > logging 1000s of REGISTERED, UNREGISTERED messages ?
> > >
> > > There might be multiple issues here, but for the pax-exam tests, at
> > > least when using the provided logging wrapper you would need to
> > > configure the tests with
> > >
> > >
> > > CoreOptions.systemProperty("org.ops4j.pax.logging.DefaultServiceLog
> > > .l
> > > evel").val‌ue("WARN")
> > >
> > > Robert
> > >
> > > >
> > > > eg
> > > >
> > > > Running
> > > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > >
> > > > [main] INFO org.ops4j.pax.exam.spi.DefaultExamSystem - Pax Exam
> > > > System
> > > > (Version: 4.9.1) created.
> > > >
> > > > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner - creating
> > > > PaxExam
> > > > runner for class
> > > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner - running
> > > > test
> > > > class
> > > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > > [main] INFO org.ops4j.exec.DefaultJavaRunner - DefaultJavaRunner
> > > > completed
> > > > successfully
> > > >
> > > > [org.ops4j.pax.swissbox.extender.BundleWatcher] : Creating bundle
> > > > watcher
> > > > with scanner [org.ops4j.pax.swissbox.extender.BundleManifestScann
> > > > er@3
> > > > 5c29153]...[org.ops4j.pax.swissbox.extender.BundleWatcher]
> > > > : Scanning bundle
> > > > [org.apache.felix.framework][org.ops4j.pax.swissbox.extender.Bund
> > > > leWa
> > > > tcher]
> > > > : Scanning bundle
> > > > [org.ops4j.pax.exam][org.ops4j.pax.swissbox.extender.BundleWatche
> > > > r] :
> > > > Scanning bundle
> > > > [org.ops4j.pax.exam.inject][org.ops4j.pax.swissbox.extender.Bundl
> > > > eWat
> > > > cher]
> > > > : Scanning bundle
> > > > [org.ops4j.pax.exam.extender.service][org.ops4j.pax.swissbox.exte
> > > > nder
> > > > .BundleWatcher]
> > > > : Scanning bundle [osgi.cmpn]
> > > >
> > > > org.ops4j.pax.logging.pax-logging-
> > > > api[org.ops4j.pax.logging.internal.Activator]
> > > > : Enabling SLF4J API support.
> > > > If I can't find some way of reducing the output I will have to
> > > > resort
> > > > to
> > > > grep on the output of mvn.
> > > >
> > > > Best Regards
> > > > Ian
> > > >
> > > >
> > > > 1 https://travis-ci.org/apache/sling/jobs/147487804
> > >
> > >
>
>

Re: Reducing Surefire Logging output.

Posted by Robert Munteanu <ro...@apache.org>.

On Tue, 2016-07-26 at 16:24 +0100, Ian Boston wrote:
> Hi,
> On the command line that doesnt appear to do anything.
> 
> cd bundles/commons/classloader
> mvn -q
> -Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> -Dorg.apache.sling.commons.log.level=WARN
> -Dorg.ops4j.pax.logging.DefaultServiceLog.level=ERROR" clean install

No, it probably needs to be set in the Java code, as the pax-exam
container is usually forked.

Perhaps we can add a utility method which forwards a well-known system
property to pax-exam in the new pax-exam support bundle.

Robert

> 
> ...
> 
> 
> [main] INFO org.ops4j.exec.DefaultJavaRunner - Platform has been
> shutdown.
> [main] INFO org.ops4j.pax.exam.spi.reactors.ReactorManager - suite
> finished
> 
> Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 6.947
> sec -
> in org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> 
> even with
> 
> ./mvnw -q
> -Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> -Dorg.apache.sling.commons.log.level=WARN" clean install
> -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1
> |��grep -v
> DEBUG | grep -v INFO | grep -v REGISTER
> 
> 
> I still get > 30K lines of logs, but the build is getting further
> through. I
> may have to get a lot more aggressive at filtering out the junk.
> 
> 
> Thanks for the pointer.
> 
> Best Regards
> 
> Ian
> 
> 
> 
> On 26 July 2016 at 16:08, Robert Munteanu <ro...@apache.org> wrote:
> 
> > Hi Ian,
> > 
> > On Tue, 2016-07-26 at 15:58 +0100, Ian Boston wrote:
> > > Hi,
> > > I am trying to reduce the volume of logging output that a Sling
> > > build
> > > produces so that we can build pull requests using Travis. Travis
> > > kills the
> > > build when it produces > 4MB of log file, which is about 32K
> > > lines of
> > > log
> > > files. 99% of those lines serve no real purpose other than to
> > > bloat
> > > the
> > > output.
> > > 
> > > [1] is an example travis run, started using a maven wrapper to
> > > allow
> > > maven
> > > 3.3.9 to be used. (you may not be able to load it, as it's so
> > > huge)
> > > 
> > > �./mvnw -q
> > > �-Dmaven.surefire.debug="-
> > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > -Dorg.apache.sling.commons.log.level=warn" clean install
> > > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests
> > > 
> > > The -q puts the maven logger in ERROR level.
> > > The -Dmaven.surefire.debug="-
> > > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > > -Dorg.apache.sling.commons.log.level=warn" causes forked surefire
> > > processes
> > > which log with SLF4J to log at WARN level.
> > > 
> > > This all works, except many of the tests in Sling still log at
> > > INFO
> > > level,
> > > presumably because it doesn't take any notice of the surefire
> > > settings.
> > > 
> > > Does anyone know how to prevent Felix when running Sling
> > > tests��from
> > > logging 1000s of REGISTERED, UNREGISTERED messages ?
> > 
> > There might be multiple issues here, but for the pax-exam tests, at
> > least when using the provided logging wrapper you would need to
> > configure the tests with
> > 
> > �
> > CoreOptions.systemProperty("org.ops4j.pax.logging.DefaultServiceLog
> > .l
> > evel").val\u200cue("WARN")
> > 
> > Robert
> > 
> > > 
> > > eg
> > > 
> > > Running
> > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > 
> > > [main] INFO org.ops4j.pax.exam.spi.DefaultExamSystem - Pax Exam
> > > System
> > > (Version: 4.9.1) created.
> > > 
> > > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner - creating
> > > PaxExam
> > > runner for class
> > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner - running
> > > test
> > > class
> > > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > > [main] INFO org.ops4j.exec.DefaultJavaRunner - DefaultJavaRunner
> > > completed
> > > successfully
> > > 
> > > [org.ops4j.pax.swissbox.extender.BundleWatcher] : Creating bundle
> > > watcher
> > > with scanner [org.ops4j.pax.swissbox.extender.BundleManifestScann
> > > er@3
> > > 5c29153]...[org.ops4j.pax.swissbox.extender.BundleWatcher]
> > > : Scanning bundle
> > > [org.apache.felix.framework][org.ops4j.pax.swissbox.extender.Bund
> > > leWa
> > > tcher]
> > > : Scanning bundle
> > > [org.ops4j.pax.exam][org.ops4j.pax.swissbox.extender.BundleWatche
> > > r] :
> > > Scanning bundle
> > > [org.ops4j.pax.exam.inject][org.ops4j.pax.swissbox.extender.Bundl
> > > eWat
> > > cher]
> > > : Scanning bundle
> > > [org.ops4j.pax.exam.extender.service][org.ops4j.pax.swissbox.exte
> > > nder
> > > .BundleWatcher]
> > > : Scanning bundle [osgi.cmpn]
> > > 
> > > org.ops4j.pax.logging.pax-logging-
> > > api[org.ops4j.pax.logging.internal.Activator]
> > > : Enabling SLF4J API support.
> > > If I can't find some way of reducing the output I will have to
> > > resort
> > > to
> > > grep on the output of mvn.
> > > 
> > > Best Regards
> > > Ian
> > > 
> > > 
> > > 1 https://travis-ci.org/apache/sling/jobs/147487804
> > 
> >

Re: Reducing Surefire Logging output.

Posted by Ian Boston <ie...@tfd.co.uk>.

Hi,
On the command line that doesnt appear to do anything.

cd bundles/commons/classloader
mvn -q
-Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
-Dorg.apache.sling.commons.log.level=WARN
-Dorg.ops4j.pax.logging.DefaultServiceLog.level=ERROR" clean install

...


[main] INFO org.ops4j.exec.DefaultJavaRunner - Platform has been shutdown.
[main] INFO org.ops4j.pax.exam.spi.reactors.ReactorManager - suite finished

Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 6.947 sec -
in org.apache.sling.commons.classloader.it.DynamicClassLoaderIT

even with

./mvnw -q
-Dmaven.surefire.debug="-Dorg.slf4j.simpleLogger.defaultLogLevel=warn
-Dorg.apache.sling.commons.log.level=WARN" clean install
-DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests 2>&1 |  grep -v
DEBUG | grep -v INFO | grep -v REGISTER


I still get > 30K lines of logs, but the build is getting further through. I
may have to get a lot more aggressive at filtering out the junk.


Thanks for the pointer.

Best Regards

Ian



On 26 July 2016 at 16:08, Robert Munteanu <ro...@apache.org> wrote:

> Hi Ian,
>
> On Tue, 2016-07-26 at 15:58 +0100, Ian Boston wrote:
> > Hi,
> > I am trying to reduce the volume of logging output that a Sling build
> > produces so that we can build pull requests using Travis. Travis
> > kills the
> > build when it produces > 4MB of log file, which is about 32K lines of
> > log
> > files. 99% of those lines serve no real purpose other than to bloat
> > the
> > output.
> >
> > [1] is an example travis run, started using a maven wrapper to allow
> > maven
> > 3.3.9 to be used. (you may not be able to load it, as it's so huge)
> >
> >  ./mvnw -q
> >  -Dmaven.surefire.debug="-
> > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > -Dorg.apache.sling.commons.log.level=warn" clean install
> > -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests
> >
> > The -q puts the maven logger in ERROR level.
> > The -Dmaven.surefire.debug="-
> > Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> > -Dorg.apache.sling.commons.log.level=warn" causes forked surefire
> > processes
> > which log with SLF4J to log at WARN level.
> >
> > This all works, except many of the tests in Sling still log at INFO
> > level,
> > presumably because it doesn't take any notice of the surefire
> > settings.
> >
> > Does anyone know how to prevent Felix when running Sling tests  from
> > logging 1000s of REGISTERED, UNREGISTERED messages ?
>
> There might be multiple issues here, but for the pax-exam tests, at
> least when using the provided logging wrapper you would need to
> configure the tests with
>
>   CoreOptions.systemProperty("org.ops4j.pax.logging.DefaultServiceLog.l
> evel").val‌ue("WARN")
>
> Robert
>
> >
> > eg
> >
> > Running org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> >
> > [main] INFO org.ops4j.pax.exam.spi.DefaultExamSystem - Pax Exam
> > System
> > (Version: 4.9.1) created.
> >
> > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner - creating
> > PaxExam
> > runner for class
> > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner - running test
> > class
> > org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> > [main] INFO org.ops4j.exec.DefaultJavaRunner - DefaultJavaRunner
> > completed
> > successfully
> >
> > [org.ops4j.pax.swissbox.extender.BundleWatcher] : Creating bundle
> > watcher
> > with scanner [org.ops4j.pax.swissbox.extender.BundleManifestScanner@3
> > 5c29153]...[org.ops4j.pax.swissbox.extender.BundleWatcher]
> > : Scanning bundle
> > [org.apache.felix.framework][org.ops4j.pax.swissbox.extender.BundleWa
> > tcher]
> > : Scanning bundle
> > [org.ops4j.pax.exam][org.ops4j.pax.swissbox.extender.BundleWatcher] :
> > Scanning bundle
> > [org.ops4j.pax.exam.inject][org.ops4j.pax.swissbox.extender.BundleWat
> > cher]
> > : Scanning bundle
> > [org.ops4j.pax.exam.extender.service][org.ops4j.pax.swissbox.extender
> > .BundleWatcher]
> > : Scanning bundle [osgi.cmpn]
> >
> > org.ops4j.pax.logging.pax-logging-
> > api[org.ops4j.pax.logging.internal.Activator]
> > : Enabling SLF4J API support.
> > If I can't find some way of reducing the output I will have to resort
> > to
> > grep on the output of mvn.
> >
> > Best Regards
> > Ian
> >
> >
> > 1 https://travis-ci.org/apache/sling/jobs/147487804
>
>

Re: Reducing Surefire Logging output.

Posted by Robert Munteanu <ro...@apache.org>.

Hi Ian,

On Tue, 2016-07-26 at 15:58 +0100, Ian Boston wrote:
> Hi,
> I am trying to reduce the volume of logging output that a Sling build
> produces so that we can build pull requests using Travis. Travis
> kills the
> build when it produces > 4MB of log file, which is about 32K lines of
> log
> files. 99% of those lines serve no real purpose other than to bloat
> the
> output.
> 
> [1] is an example travis run, started using a maven wrapper to allow
> maven
> 3.3.9 to be used. (you may not be able to load it, as it's so huge)
> 
> �./mvnw -q
> �-Dmaven.surefire.debug="-
> Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> -Dorg.apache.sling.commons.log.level=warn" clean install
> -DHttpTestBase.readyTimeoutSeconds=300 -PintegrationTests
> 
> The -q puts the maven logger in ERROR level.
> The -Dmaven.surefire.debug="-
> Dorg.slf4j.simpleLogger.defaultLogLevel=warn
> -Dorg.apache.sling.commons.log.level=warn" causes forked surefire
> processes
> which log with SLF4J to log at WARN level.
> 
> This all works, except many of the tests in Sling still log at INFO
> level,
> presumably because it doesn't take any notice of the surefire
> settings.
> 
> Does anyone know how to prevent Felix when running Sling tests��from
> logging 1000s of REGISTERED, UNREGISTERED messages ?

There might be multiple issues here, but for the pax-exam tests, at
least when using the provided logging wrapper you would need to
configure the tests with

��CoreOptions.systemProperty("org.ops4j.pax.logging.DefaultServiceLog.l
evel").val\u200cue("WARN")

Robert

> 
> eg
> 
> Running org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> 
> [main] INFO org.ops4j.pax.exam.spi.DefaultExamSystem - Pax Exam
> System
> (Version: 4.9.1) created.
> 
> [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner - creating
> PaxExam
> runner for class
> org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> [main] INFO org.ops4j.pax.exam.junit.impl.ProbeRunner - running test
> class
> org.apache.sling.commons.classloader.it.DynamicClassLoaderIT
> [main] INFO org.ops4j.exec.DefaultJavaRunner - DefaultJavaRunner
> completed
> successfully
> 
> [org.ops4j.pax.swissbox.extender.BundleWatcher] : Creating bundle
> watcher
> with scanner [org.ops4j.pax.swissbox.extender.BundleManifestScanner@3
> 5c29153]...[org.ops4j.pax.swissbox.extender.BundleWatcher]
> : Scanning bundle
> [org.apache.felix.framework][org.ops4j.pax.swissbox.extender.BundleWa
> tcher]
> : Scanning bundle
> [org.ops4j.pax.exam][org.ops4j.pax.swissbox.extender.BundleWatcher] :
> Scanning bundle
> [org.ops4j.pax.exam.inject][org.ops4j.pax.swissbox.extender.BundleWat
> cher]
> : Scanning bundle
> [org.ops4j.pax.exam.extender.service][org.ops4j.pax.swissbox.extender
> .BundleWatcher]
> : Scanning bundle [osgi.cmpn]
> 
> org.ops4j.pax.logging.pax-logging-
> api[org.ops4j.pax.logging.internal.Activator]
> : Enabling SLF4J API support.
> If I can't find some way of reducing the output I will have to resort
> to
> grep on the output of mvn.
> 
> Best Regards
> Ian
> 
> 
> 1 https://travis-ci.org/apache/sling/jobs/147487804