Runresolution should consider loglevel set via -resolvedebug

[chrisrueger]

Based on https://bnd.discourse.group/t/memory-usage-explosion-with-bnd-resolver-plugin/307/6 by @reckart

It seems the -resolvedebug instruction is not considered in a few places where it would make sense. This PR tries to improve this.

In this PR

1. Now resolution (more specifically the underlying ResolverLogger) should respect the loglevel set via -resolvedebug
2. the Resolution Failure Panel now also shows a part of this log at the end with a pointer to the larger logfile on disk, like this:

Update: Note that 53a0eae75ad764c1dce9e8385f74ba4b5d5047da now InternalResolverLogger.logUsesConstraintViolation() actually logs something. If I interpret it correctly that is exactly the logging output Richard wants to have and mentions in the forum post

Uses constraint violation. Unable to resolve resource plugin-a [plugin-a version=1.0.0-SNAPSHOT] because it is exposed to package 'some.package' from resources plugin-b [plugin-b version=2.3.1] and plugin-c [plugin-c version=1.4.2] via two dependency chains.

Chain 1:
  plugin-a [plugin-a version=1.0.0-SNAPSHOT]
    import: (&(osgi.wiring.package=some.package)(version>=1.0.0)(!(version>=2.0.0)))
     |
    export: osgi.wiring.package: some.package
  plugin-b [plugin-b version=2.3.1]

Chain 2:
  plugin-a [plugin-a version=1.0.0-SNAPSHOT]
    import: (&(osgi.wiring.package=some.other.package)(version>=1.0.0)(!(version>=2.0.0)))
     |
    export: osgi.wiring.package: some.other.package; uses:=some.package
    export: osgi.wiring.package=some.package
  plugin-c [plugin-c version=1.4.2]

Unfortunately I could not verify the output yet as I haven't found a testcase which triggers logUsesConstraintViolation(). Pointers are welcome.

@reckart could you try it out if this would have helped in your case? @pkriens do you see any concerns?

[chrisrueger]

Added a testcase which triggers a Uses Constrain violation and makes sure it gets logged when -resolvedebug:1 is set.

Uses constraint violation. Unable to resolve resource BundleB [BundleB version=1.0.0.SNAPSHOT] because it is exposed to package 'com.example.util.internal' from resources BundleA [BundleA version=1.0.0.SNAPSHOT] and BundleA2 [BundleA2 version=1.0.0.SNAPSHOT] via two dependency chains.

Chain 1:
  BundleB [BundleB version=1.0.0.SNAPSHOT]
    import: (&(osgi.wiring.package=com.example.util.internal)(version>=1.0.0)(version<=1.0.0))
     |
    export: osgi.wiring.package: com.example.util.internal
  BundleA [BundleA version=1.0.0.SNAPSHOT]

Chain 2:
  BundleB [BundleB version=1.0.0.SNAPSHOT]
    import: (&(osgi.wiring.package=com.example.util)(version>=1.0.0)(version<=1.0.0))
     |
    export: osgi.wiring.package=com.example.util; uses:=com.example.util.internal
  BundleA2 [BundleA2 version=1.0.0.SNAPSHOT]
    import: (&(osgi.wiring.package=com.example.util.internal)(version>=1.1.0)(!(version>=2.0.0)))
     |
    export: osgi.wiring.package: com.example.util.internal
  BundleA2 [BundleA2 version=1.0.0.SNAPSHOT]

This is comming from the debug logfile which is now mentioned via absolute path in the ResolutionFailurePanel in bndtools UI:

It is still required to open the log yourself in the command line, but at least it is there now e.g.:

One (maybe) open problem with the logfile:

I added a change which sets logger.setKeepLogFileTillExit(true) so that the tmp logfile is kept until JVM exit and not removed immediately after resolving. At least in the UI this should help that the logfile can be examined while the resolver error panel is visible.

But how does that behave with e.g. maven plugin triggering resolve? I guess since maven spans the JVM it might be finishing and removing the tmp logfile still too early before you had a chance to look at it.

[reckart]

But how does that behave with e.g. maven plugin triggering resolve? I guess since maven spans the JVM it might be finishing and removing the tmp logfile still too early before you had a chance to look at it.

For Maven, log output should IMHO either go into a debug-level logger (which can be made visible using the -X parameter) or be written to a log file in the target folder.

[chrisrueger]

For Maven, log output should IMHO either go into a debug-level logger (which can be made visible using the -X parameter) or be written to a log file in the target folder.

@pkriens any thoughts on that? To me it sounds like the caller (maven plugin which calls bnd resolve) should be able to control this somehow. Don't think that is the case right now. But I'm not familiar with the maven plugin

[pkriens]

I think it makes sense to make a Maven Logger that is given to the resolver and uses the Maven logging system. You might even use standard SLF4J logging on debug level. I assume maven will capture this.

[chrisrueger]

I think it makes sense to make a Maven Logger that is given to the resolver and uses the Maven logging system. You might even use standard SLF4J logging on debug level. I assume maven will capture this.

Just confirming: Is the whole Maven story starting here?

https://github.com/bndtools/bnd/blob/master/maven-plugins/bnd-resolver-maven-plugin/src/main/java/aQute/bnd/maven/resolver/plugin/ResolverMojo.java#L150

and here?

https://github.com/bndtools/bnd/blob/master/biz.aQute.bnd.maven/src/aQute/bnd/maven/lib/resolve/BndrunContainer.java#L169

I will dig deeper later, but just need some pointers where to hook in. Because I think at the moment there are not enough hooks to hook in from outside.

Regarding

SLF4J logging on debug level.

This sounds tempting. Which Logger would I need to log to? Just something like this?

private static final Logger                                     logger  = LoggerFactory
        .getLogger(ResolverLogger.class);

and then logger.debug(....)

And then Maven magically can capture this with this -x option? Sorry unexperienced Maven guy here. Richard @reckart : how would you make use of this?

[reckart]

The Maven AbstractMojo has a method getLog() which I typically use. But I believe @pkriens is probably right in presuming that Maven uses SLF4J under the hood these days and can also pick up anything logged through any SLF4J logger. So it is probably not necessary to use the getLog() method and sufficient to log through any SLF4J logger obtained through the LoggerFactory. In order to run Maven in debug log mode, I would run e.g. mvn -X clean install on my project.

[chrisrueger]

Ok will try and push something later.

[chrisrueger]

@reckart I added slf4j debug logging in 1db5a87ffec648548ea7e483c23151e52f299fa5 I used only logger.debug() ... not sure this is what you intended, but as I understood the mvn -X flag, it means "debug".

@pkriens I think the MavenLogger is a good idea but I think it requires deeper changes, so that a logger can be passed. I think the slf4j approach would be a more lightweight way to find out if we / @reckart is satisfied with the logging output (if it is helpful).

Once we know that we could think about refactoring. But at the moment I think also the maven bnd plugin needs to be adjusted since it currently only calles into biz.aQute.resolve.Bndrun.resolve(boolean, boolean) , but we need to pass the logger there. Maybe that part could be taken over by somebody more familiar with the maven stuff :)

At least we now have a unit test which triggers a Uses constraint violation which was swallowed before.

[pkriens]

men, you're amazing ...

It all looks good to me, I am ok to merge

[reckart]

@pkriens give me until EOB, I'll try if I can have a look at the debug output.

[reckart]

@pkriens I am sorry, I didn't manage to test this yesterday as I repeatedly ran into failing tests during the build...

[chrisrueger]

@pkriens I am sorry, I didn't manage to test this yesterday as I repeatedly ran into failing tests during the build...

@reckart Not sure if it helps (at least for testing), but you might try downloading the latest built artifact from github while you have trouble with the local build. e.g. https://github.com/bndtools/bnd/actions/runs/9069124930/artifacts/1498607455

You find this e.g. in the section "Upload dist/bundles" of https://github.com/bndtools/bnd/actions/runs/9069124930/job/24917977286?pr=6117

[reckart]

@chrisrueger thanks for the pointer. I can look at it again mid next week.

Wrt. the failing builds - I have a feeling that it might be related to concurrency. After the "Address in use" issues in several tests, I am not running into locking problems. Does grade build/test bnd using multiple parallel threads?

[reckart]

Btw. the artifacts are also listed here: https://github.com/bndtools/bnd/actions/runs/9069124930?pr=6117

[chrisrueger]

Wrt. the failing builds - I have a feeling that it might be related to concurrency. After the "Address in use" issues in several tests, I am not running into locking problems. Does grade build/test bnd using multiple parallel threads?

Maybe @pkriens knows more?

[pkriens]

@reckart who are things moving on?

[chrisrueger]

@chrisrueger thanks for the pointer. I can look at it again mid next week.

Wrt. the failing builds - I have a feeling that it might be related to concurrency. After the "Address in use" issues in several tests, I am not running into locking problems. Does grade build/test bnd using multiple parallel threads?

Hi @reckart, I think this PR is ready to being merged. The only reason we wait is your statement about failing builds. Since the builds were successful here in github, I guess it could be something on your environment? Maybe related to similiar issues you had here?

[reckart]

I thought we had already resolved that this was also caused by the bad GitHub credentials - but I may misremember. I'll double-check tomorrow and let you know.

[reckart]

Tried to build the PR without a settings.xml (so no invalid GitHub token in the build), but I hit https://github.com/bndtools/bnd/issues/6122

[reckart]

I switched to the master branch and built - that worked.

I switched back to this PR again, and then I got

ActivatorTest > testerUnresolvedFalse_withUnresolvedBundle_doesntFail() FAILED
    java.lang.NullPointerException: Cannot invoke "aQute.tester.test.utils.TestRunData.getNameMap()" because "result" is null
        at aQute.tester.test.ActivatorTest.testerUnresolvedFalse_withUnresolvedBundle_doesntFail(ActivatorTest.java:123)

🤷

[reckart]

Ok, and once more rebuilt the PR, this time successfully (using ./gradlew clean build like in the previous attempts as well - so no change).

Looks like the repo has various flaky tests.... - at least when I build in my system.

[reckart]

I'd say the PR should be good to merge. I don't think the build issues I'm having have to do anything with the PR in particular.

[chrisrueger]

Looks like the repo has various flaky tests

Yes i noticed that too sometimes.

i am fine with merging. @pkriens ok?