ProjectResolverTest failing

reckart commented 1 month ago

When I try running ./gradlew :build on master on my machine, ProjectResolverTest fails:

> Task :biz.aQute.resolve:test

biz.aQute.resolve.ProjectResolverTest > testAugment() STANDARD_ERROR
    [HttpClient,https://raw.githubusercontent.com/osgi/osgi.enroute/v1.0.0/cnf/distro/index.xml] INFO aQute.bnd.build.LoggingProgressPlugin - Download https://raw.githubusercontent.com/osgi/osgi.enroute/v1.0.0/cnf/distro/index.xml
    -----------------
    Errors
    000: Resolution failed Unable to resolve <<INITIAL>>: missing requirement foo;filter:='(bar=1)'

biz.aQute.resolve.ProjectResolverTest > testAugment() STANDARD_OUT
    [enroute [.../git/bnd/biz.aQute.resolve/testdata/projectresolver/ws/cnf/cache/7.1.0/enroute r/w=false], bnd-cache [.../git/bnd/biz.aQute.resolve/testdata/projectresolver/ws/cnf/cache/7.1.0/bnd-cache r/w=false]]
    [enroute [.../git/bnd/biz.aQute.resolve/testdata/projectresolver/ws/cnf/cache/7.1.0/enroute r/w=false], [com.example.jerome.application version=1.0.0.201502190831, osgi.enroute.base.api version=1.5.0.201502191630, foo.bar version=0.0.0]]

ProjectResolverTest > testAugment() FAILED
    org.opentest4j.AssertionFailedError: expected: <true> but was: <false>
        at app//org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
        at app//org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
        at app//org.junit.jupiter.api.AssertTrue.failNotTrue(AssertTrue.java:63)
        at app//org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:36)
        at app//org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:31)
        at app//org.junit.jupiter.api.Assertions.assertTrue(Assertions.java:180)
        at app//biz.aQute.resolve.ProjectResolverTest.testAugment(ProjectResolverTest.java:116)

102 tests completed, 1 failed

> Task :biz.aQute.resolve:test FAILED

Any idea what might be going wrong here?

chrisrueger commented 1 month ago

@reckart hmm don't know. for me it passes (MacOS 14.4.1) I can only guess. Maybe have a look at the bnd caches and try clearing them. maybe something is messed up. Not sure if this only applies for the bnd CLI tool or in general where bnd is used:

cd ~/.bnd/
ls
rm -rf cachefolders

Update: Or maybe clear the cache folders mentioned in your output above:

[.../git/bnd/biz.aQute.resolve/testdata/projectresolver/ws/cnf/cache/7.1.0/enroute

reckart commented 1 month ago

I have tried deleting all contents of the .bnd folder and then rebuilt with ./gradlew clean build in the bnd repo - test still fails.

reckart commented 1 month ago

When I run biz.aQute.resolve.ProjectResolverTest#testAugment with a breakpoint in aQute.bnd.osgi.MessageReporter#putMessage, I get this warning logged to the message reporter (which seems to be swallowed by the text and never reaching the console):

The JAR is empty: The instructions for the JAR named foo.bar did not cause any content to be included, this is likely wrong

Do you also get that when you run the test in the debugger?

That is probably a normal message as the JAR to be tested is built... I can see the JAR is being created and it also seems to contain the proper augmentation entries.

reckart commented 1 month ago

Debugging the resolving step, I can see that the generated foo.bar.jar is available in one of the repositories accessible to the resolver, but there is only the bnd.augment;path='augments.bnd' capability, not the foo;bar=1 requested by the augment.bndrun file.

chrisrueger commented 1 month ago

I try to check in the afternoon

chrisrueger commented 1 month ago

@reckart I have now put my breakpoint in the same location and a bit further down in biz.aQute.resolve.ResolveProcess.resolveRequired(Processor, Project, Registry, Resolver, Collection<ResolutionCallback>, LogService) line 113

there I can see this:

The output on the console of biz.aQute.resolve.ProjectResolverTest#testAugment is:


[enroute [/Users/christoph/git/bnd_chrisrueger/biz.aQute.resolve/testdata/projectresolver/ws/cnf/cache/7.1.0/enroute r/w=false], bnd-cache [/Users/christoph/git/bnd_chrisrueger/biz.aQute.resolve/testdata/projectresolver/ws/cnf/cache/7.1.0/bnd-cache r/w=false]]
[[com.example.jerome.application version=1.0.0.201502190831, osgi.enroute.base.api version=1.5.0.201502191630, foo.bar version=0.0.0], enroute [/Users/christoph/git/bnd_chrisrueger/biz.aQute.resolve/testdata/projectresolver/ws/cnf/cache/7.1.0/enroute r/w=false]]

I also checked the temporary folder when the breakpoint was hit and examined the .jar file:

cd /Users/christoph/git/bnd_chrisrueger/biz.aQute.resolve/generated/tmp/test/biz.aQute.resolve.ProjectResolverTest/testAugment

The content of the two files is:

Ideas and questions coming to mind

Earlier you wrote that you found an error message starting with "The JAR is empty".

is foo.jar empty in your case? Maybe a write permission issue?
is some other process having locked that folder (gradle vs maven vs eclipse vs intellij) ?
anti virus scanner?

reckart commented 1 month ago

The JAR, Manifest and augments.bnd look good.

But I don't even get to the line you indicated in the debugger screenshot.

For me it fails a few lines upwards from your line in line 86:

wirings = resolver.resolve(rc);

reckart commented 1 month ago

I ensured that no virus scanner was interfering when I ran the test.

chrisrueger commented 1 month ago

For me it fails a few lines upwards from your line in line 86:

This works for me:

reckart commented 1 month ago

What do you get when you set a breakpoint in biz/aQute/resolve/AbstractResolveContext.java:237?

For me, that returns no capabilities.

That subsequently leads to an exception being thrown and the resource being removed from the list of candidates:

and then the whole resolve process fails and thus the test fails...

chrisrueger commented 1 month ago

This is my breakpoint at

biz/aQute/resolve/AbstractResolveContext.java:237

reckart commented 1 month ago

Ok, I think I don't understand what the test aims to do in the first place.

Originally, I thought that it was generating a JAR foo.bar.jar containing an augments.bnd that would somehow add an additional capability to foo.bar.jar.

I guess what it actually does is generating a JAR foo.bar.jar that contains an augments.bnd which instructs the resolver to believe that the bundle with the identity osgi.promise has an additional capability foo.bar=1 and this osgi.promise would come from https://raw.githubusercontent.com/osgi/osgi.enroute/v1.0.0/cnf/distro/index.xml.

Is me updated understanding correct or am I still getting something wrong?

When you run the test, is the osgi.promise artifact downloaded to your .../bnd/biz.aQute.resolve/testdata/projectresolver/ws/cnf/cache/7.1.0/enroute folder?

chrisrueger commented 1 month ago

Ok, I think I don't understand what the test aims to do in the first place.

Originally, I thought that it was generating a JAR foo.bar.jar containing an augments.bnd that would somehow add an additional capability to foo.bar.jar.

It sounds correct what you say, but I am honestly not familar with the feature. But to me it sounds like yes. Maybe @pkriens can explain better.

When you run the test, is the osgi.promise artifact downloaded to your .../bnd/biz.aQute.resolve/testdata/projectresolver/ws/cnf/cache/7.1.0/enroute folder?

I don't see anything downloaded but I think the osgi.promise .jar artifact (from https://raw.githubusercontent.com/osgi/osgi.enroute/v1.0.0/cnf/distro/osgi.promise/osgi.promise-6.0.0.jar)

contains a

Export-Package: org.osgi.util.promise;version="1.0"

and this export is also contained in the local jar in the source code.jar

/biz.aQute.resolve/testdata/projectresolver/jar/osgi.enroute.base.api.jar

So my interpretation is:

the package org.osgi.util.promise is satisfied by the local osgi.enroute.base.api.jar

I have no clue why it behaves differently on your machine. Btw: I am currently debugging in the branch of PR https://github.com/bndtools/bnd/pull/6117

reckart commented 1 month ago

I'm also on the PR for #6117

chrisrueger commented 1 month ago

Hmm I'm running out of ideas. Maybe could you try another clean checkout of the branch in a completely new folder... just as a last resort.

Here are some things from my environment:

cd git/bndrepo
./gradlew --version

------------------------------------------------------------
Gradle 8.1.1
------------------------------------------------------------

Build time:   2023-04-21 12:31:26 UTC
Revision:     1cf537a851c635c364a4214885f8b9798051175b

Kotlin:       1.8.10
Groovy:       3.0.15
Ant:          Apache Ant(TM) version 1.10.11 compiled on July 10 2021
JVM:          17.0.9 (Eclipse Adoptium 17.0.9+9)
OS:           Mac OS X 14.4.1 aarch64

java --version
openjdk 17.0.9 2023-10-17
OpenJDK Runtime Environment Temurin-17.0.9+9 (build 17.0.9+9)
OpenJDK 64-Bit Server VM Temurin-17.0.9+9 (build 17.0.9+9, mixed mode)

Eclipse from which I start debugger / testcase:

Eclipse IDE for Eclipse Committers (includes Incubating components)

Version: 2023-09 (4.29.0)
Build id: 20230907-1323

includes:   Bndtools    7.0.0.REL-202310060912-gb82dc86 bndtools.main.feature.feature.group Bndtools

Yes my Eclipse from which I start the debugging session is running on bndtools 7.0.0 and NOT the latest 7.1. snapshot Not sure this is relevant when you are running the testcases from a master-like / 7.1.snapshot like branch.

reckart commented 1 month ago

------------------------------------------------------------
Gradle 8.1.1
------------------------------------------------------------

Build time:   2023-04-21 12:31:26 UTC
Revision:     1cf537a851c635c364a4214885f8b9798051175b

Kotlin:       1.8.10
Groovy:       3.0.15
Ant:          Apache Ant(TM) version 1.10.11 compiled on July 10 2021
JVM:          17.0.3 (Azul Systems, Inc. 17.0.3+7-LTS)
OS:           Mac OS X 14.5 x86_64

I used IntelliJ to debug the test but it also fails simply by running the gradle build on the command line.

reckart commented 1 month ago

Ok, another question. What do you get when when you set a breakpoint in aQute/bnd/osgi/repository/AugmentRepository.java:99?

That location to me seems to be the place where the augmentation would be applied to the bundles in the repository. However, it seems like the list of bundles to be augmented for me ends up being empty, so it seems the augmentation is never applied. I would assume on your system, bundles is a list of 1 with the osgi.promise bundle being inside it?

chrisrueger commented 1 month ago

I would assume on your system, bundles is a list of 1 with the osgi.promise bundle being inside it?

Yes.

Question to you:

Could you set a breakpoint inaQute.bnd.repository.osgi.OSGiIndex.download(URI, boolean) and see if the file gets downloaded or comes from a cache?

This is what I get:

reckart commented 1 month ago

I get a null file. Looks like I have 404 stuck in a cache:

IMHO unit tests should not use a global cache (this one uses a cache from my home directory). If needed at all, caches should be local to a particular test and be cleaned properly...

Anyway, even if I clear that cache folder, it still fails.

It looks like the actual request to the GitHub URL https://raw.githubusercontent.com/osgi/osgi.enroute/v1.0.0/cnf/distro/index.xml returns a 404:

When I open the URL in my browser, it works though....

reckart commented 1 month ago

Manually constructing a URL and opening an URL connection to the GitHub URL and retrieving its contents works for me (added the respective code to the beginning of the testAugment() method, so it runs in the same environment).

chrisrueger commented 1 month ago

This is strange.

It looks like the actual request to the GitHub URL https://raw.githubusercontent.com/osgi/osgi.enroute/v1.0.0/cnf/distro/index.xml returns a 404:

I get a 304

chrisrueger commented 1 month ago

I came across this

https://www.debugpoint.com/failed-connect-raw-githubusercontent-com-port-443/ via https://github.com/componentjs/remotes.js/issues/19

reckart commented 1 month ago

With a breakpoint in /Library/Java/JavaVirtualMachines/zulu-17.jdk/Contents/Home/lib/src.zip!/java.base/sun/net/www/http/HttpClient.java:804, I see this response from GitHub:

HTTP/1.1 404 Not Found
Connection: keep-alive
Content-Length: 14
Content-Security-Policy: default-src 'none'; style-src 'unsafe-inline'; sandbox
Strict-Transport-Security: max-age=31536000
X-Content-Type-Options: nosniff
X-Frame-Options: deny
X-XSS-Protection: 1; mode=block
Content-Type: text/plain; charset=utf-8
X-GitHub-Request-Id: XXX
Accept-Ranges: bytes
Date: Thu, 23 May 2024 07:34:53 GMT
Via: 1.1 varnish
X-Served-By: cache-fra-eddf8230103-FRA
X-Cache: MISS
X-Cache-Hits: 0
X-Timer: S1716449693.044624,VS0,VE115
Vary: Authorization,Accept-Encoding,Origin
Access-Control-Allow-Origin: *
Cross-Origin-Resource-Policy: cross-origin
X-Fastly-Request-ID: XXX
Expires: Thu, 23 May 2024 07:39:53 GMT
Source-Age: 0

Ok... so digging deeper and looking the request headers, I can see that something has set a BASIC authentication header on the connection that that header could be using an outdated GitHub token.

The big question is: where the heck did bnd take that token from and why is it used in a test case?!

chrisrueger commented 1 month ago

The big question is: where the heck did bnd take that token from and why is it used in a test case?!

I do not have an answer, but I just found the class aQute.bnd.url.BndAuthentication

and maybe together with https://bnd.bndtools.org/instructions/connection-settings.html

reckart commented 1 month ago

@chrisrueger You struck gold. Moving my settings.xml out of the way fixes the issue :)

The question is: what are the lessons learned and is there something that should be done on the bnd side to facilitate finding such issues?

What comes to my mind:

Test cases should try not to use resources from outside the test cases scope, in particular not stuff from the user home (~/.bnd folder, ~/.m2/settings.xml etc.). If specific configuration files are required by the test, they should be provided by the test, otherwise it should be assumed such files do not exists.
I have seen an occasional debug log statement while going through the code, but I don't know how to configure the test to use them. In Maven projects in usually have a log4j2.xml or similar file in the src/test/resources folder. Where would I have found such a thing in the bnd build?
Should there be more logging / warn-level logging e.g. if URLs are accessed that do not work?

chrisrueger commented 1 month ago

Yeah :) Glad we found something. Good questions.

Should there be more logging / warn-level logging e.g. if URLs are accessed that do not work?

I would definitly say yes. Since you came across at various places during debugging maybe you are the best person right now to provide suggestions where to add logging.

Have you seen anything which prints out that a settings.xml is used? Maybe bnd HttpClient should print something in BOLD somewhere central. Maybe stuff like if options are taken from settings.xml like authentication or proxy settings. I think this could even be logged at INFO level.

Regarding the other points I cannot say much about the philosophy why things are as they are. Maybe @pkriens or @bjhargrave have some thoughts.

reckart commented 1 month ago

Have you seen anything which prints out that a settings.xml is used?

No. I looked at the page you pointed me to (https://bnd.bndtools.org/instructions/connection-settings.html) and came to the right conclusions - and then just tried moving the file out of the way to see if it helps.

I think the logging I found (e.g. related to the caching mechanism) would have helped a bit already - but I didn't know (research) how to turn it on. Eventually, I had to debug down almost to the wire level to see the request headers. I wouldn't expect logging at that level. But some logging that authentication data was being used would probably have been helpful.

chrisrueger commented 1 month ago

@reckart could you maybe create a PR and add some logging to aQute.bnd.connection.settings.ConnectionSettings.readSettings() it looks like this is the place where the settings.xml (e.g. aQute.bnd.connection.settings.ConnectionSettings.BND_CONNECTION_SETTINGS_XML) is read.

chrisrueger commented 1 month ago

@reckart I have added a suggestion for logging in PR https://github.com/bndtools/bnd/pull/6130 I am open to suggestion... you can also take over if you want.

@pkriens concerns?

chrisrueger commented 1 month ago

@reckart https://github.com/bndtools/bnd/pull/6130 has been merged which adds a little bit of additional logging e.g. if there is a settings.xml being used. Just for the record and other people finding this: there is a bnd com command which outputs even more debugging output about connection settings.

Can we close this issue here?

reckart commented 1 month ago

Feel free to merge. I'll try out the new debugging output eventually... sorry for the delay.

chrisrueger commented 1 month ago

Closed via https://github.com/bndtools/bnd/pull/6130

bndtools / bnd

ProjectResolverTest failing #6123

Ideas and questions coming to mind