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 53a0eae 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 1db5a87
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?