search

oss-review-toolkit / ort

A suite of tools to automate software compliance checks.
https://oss-review-toolkit.org
Apache License 2.0
1.57k stars 308 forks source link

Stuck at JNI boundary? #5782

Closed ghost closed 1 year ago

ghost commented 2 years ago

Background

A Java application has ties to a C/C++ program via the JNI.

Problem

ORT did not complete processing the build.gradle file, yet gave no indication as to an error.

  ~/dev/ort/bin/ort --info analyze -f JSON -i . -o ./ort/analyzer
  12:34:06.484 [DefaultDispatcher-worker-1] INFO  org.ossreviewtoolkit.analyzer.PackageManager - Resolving Gradle dependencies for path 'conformance/build.gradle'...

Expected

ORT shows an error to indicate that it encountered an issue resolving licensing information or the hanging loop prints a progress report to the user to indicate what's happening.

Actual

ORT hangs. After 30 minutes, no progress made, I stopped ORT.

Work around

  1. Comment out the references to JNI projects in conformance/build.gradle.
  2. Re-run ORT.

This allowed ORT to proceed without hanging. (At least until the troublesome JNI project was referenced from another project, which resulted in another hang, but it appears to be the same issue.)

sschuberth commented 2 years ago
  1. Comment out the references to JNI projects in conformance/build.gradle.

Are you able to share the source code to the project?

Also, do you get more details when running with --debug?

ghost commented 2 years ago

Are you able to share the source code to the project?

Proprietary, sorry. I'll see about running with --debug (aside, it'd be nice to add that option to the README.md file in the debugging section).

ghost commented 2 years ago

Ran using:

~/dev/ort/bin/ort --debug --info analyze -f JSON -i . -o ./ort/analyzer

No additional processing information was written to the console.

Perhaps the first task in tracking this down would be to add more logging into the system around the resolver/analyzer?

13:13:20.211 [DefaultDispatcher-worker-1] INFO  org.ossreviewtoolkit.analyzer.PackageManager - Resolving Gradle dependencies for path 'project.name'...

As a work around you could put the analyzer thread on a timeout and if it blocks for more than 5 minutes (configurable, of course), throw an exception and move on.

sschuberth commented 2 years ago

No additional processing information was written to the console.

That's probably because you use both --debug and --info, and the latter overrides the former. Please use --debug instead of --info (or put --debug last).

ghost commented 2 years ago

Hangs here:

14:32:37.186 [DefaultDispatcher-worker-1] DEBUG org.gradle.tooling.GradleConnector - Connecting from tooling API consumer version 7.5.1
mpbecker commented 1 year ago

We are having the same issue, but without any JNI dependency whatsoever. Unfortunately the --debug flag is not offering more information than the one already mentioned in this issue. So how to proceed?

sschuberth commented 1 year ago

So how to proceed?

Are you maybe in a position to debug this yourself? Eventually, adding more logger.debug statements to init.gradle could also give a clue where it's hanging.

mpbecker commented 1 year ago

If you could give me some more instructions about where to put additional log statements, I could do that. I tried adding a log in the buildAll method of the init.kt but it does not appear even for a gradle file that got analyzed successful. My assumption right now is that it hangs somewhere after https://github.com/oss-review-toolkit/ort/blob/d4651191ee06a30134b228c314544434674e72e0/analyzer/src/main/kotlin/managers/Gradle.kt#L191 but I don't have the time right now to dig deeper into the structure of ORT to know what is connected how. So I would appreciate if your could give me some more n00b hints on this additional logging :-) Thanks!

sschuberth commented 1 year ago

Do you see the "Gradle may use a maximum of XXXX MiB of memory" message somewhere in the log output?

Alternatively, can you share the project you're analyzing?

mpbecker commented 1 year ago

Unfortunately I cannot share. But I can provide the relevant logs (even though I have to cut any company information, replaced with XXX):

17:35:13.899 [main] INFO org.ossreviewtoolkit.utils.ort.OrtAuthenticator - Authenticator was successfully installed. 17:35:13.913 [main] INFO org.ossreviewtoolkit.utils.ort.OrtProxySelector - Proxy selector was successfully installed. Found 3 Gradle definition file(s) at: build.gradle app/build.gradle demo/build.gradle Found 3 definition file(s) from 1 package manager(s) in total. 17:35:13.974 [main] INFO org.ossreviewtoolkit.analyzer.Analyzer - Starting Gradle analysis. 17:35:13.985 [DefaultDispatcher-worker-1] INFO org.ossreviewtoolkit.analyzer.PackageManager - Resolving Gradle dependencies for path 'build.gradle'... 17:35:14.017 [DefaultDispatcher-worker-1] DEBUG org.gradle.tooling.GradleConnector - Connecting from tooling API consumer version 7.5.1 17:35:14.087 [Connection worker] DEBUG org.gradle.tooling.internal.consumer.loader.DefaultToolingImplementationLoader - Using tooling provider from Gradle distribution 'XXX/gradle-7.5.1-all.zip' 17:35:14.087 [Connection worker] DEBUG org.gradle.tooling.internal.consumer.loader.DefaultToolingImplementationLoader - Using tooling provider classpath: [XXX] 17:35:27.356 [DefaultDispatcher-worker-1] DEBUG org.ossreviewtoolkit.analyzer.managers.Gradle - Analyzing the project in 'XXX-app' produced the following standard output: Gradle may use a maximum of 8192 MiB of memory.

Configure project : XXX

Configure project :app XXX

Configure project :demo XXX

CONFIGURE SUCCESSFUL in 13s

17:35:27.361 [DefaultDispatcher-worker-1] DEBUG org.ossreviewtoolkit.analyzer.managers.Gradle - The Gradle project 'XXX-app' uses the following Maven repositories: [XXX] 17:35:27.538 [DefaultDispatcher-worker-1] DEBUG org.eclipse.jgit.util.FS - readpipe [/usr/bin/git, --version],/usr/bin 17:35:27.540 [DefaultDispatcher-worker-1] DEBUG org.eclipse.jgit.util.FS - readpipe may return 'git version 2.34.1' 17:35:27.540 [DefaultDispatcher-worker-1] DEBUG org.eclipse.jgit.util.FS - remaining output:

17:35:27.541 [DefaultDispatcher-worker-1] DEBUG org.eclipse.jgit.util.FS - readpipe [/usr/bin/git, config, --system, --show-origin, --list, -z],/usr/bin 17:35:27.544 [DefaultDispatcher-worker-1] DEBUG org.eclipse.jgit.util.FS - readpipe may return 'file:/etc/gitconfigfilter.lfs.clean' 17:35:27.544 [DefaultDispatcher-worker-1] DEBUG org.eclipse.jgit.util.FS - remaining output:

17:35:27.544 [DefaultDispatcher-worker-1] DEBUG org.eclipse.jgit.util.FS - git-lfs clean -- %ffile:/etc/gitconfigfilter.lfs.smudge 17:35:27.544 [DefaultDispatcher-worker-1] DEBUG org.eclipse.jgit.util.FS - git-lfs smudge -- %ffile:/etc/gitconfigfilter.lfs.process 17:35:27.544 [DefaultDispatcher-worker-1] DEBUG org.eclipse.jgit.util.FS - git-lfs filter-processfile:/etc/gitconfigfilter.lfs.required 17:35:27.544 [DefaultDispatcher-worker-1] DEBUG org.eclipse.jgit.util.FS - true 17:35:27.545 [DefaultDispatcher-worker-1] DEBUG org.eclipse.jgit.util.SystemReader - loading config FileBasedConfig[/etc/gitconfig] 17:35:27.546 [DefaultDispatcher-worker-1] DEBUG org.eclipse.jgit.util.SystemReader - loading config FileBasedConfig[XXX/.gitconfig] 17:35:27.595 [DefaultDispatcher-worker-1] WARN org.ossreviewtoolkit.analyzer.managers.Gradle - Project uses an Ivy repository which is not supported by the analyzer. Dependencies from this repository will be ignored: XXX 17:35:27.601 [DefaultDispatcher-worker-1] INFO org.ossreviewtoolkit.analyzer.PackageManager - Resolving Gradle dependencies for path 'build.gradle' took 13.607519556s. 17:35:27.601 [DefaultDispatcher-worker-1] INFO org.ossreviewtoolkit.analyzer.PackageManager - Resolving Gradle dependencies for path 'app/build.gradle'... 17:35:27.601 [DefaultDispatcher-worker-1] DEBUG org.gradle.tooling.GradleConnector - Connecting from tooling API consumer version 7.5.1

It is an Android project. As you can see we have three build.gradle files in it. The root file contains variables containing the version numbers we are adding as implementation dependencies to the app and demo module, e.g. implementation "org.jetbrains.kotlinx:kotlinx-coroutines-android:$kotlinx_coroutines_version" Could this lead to a problem? Other teams in our project do it the same way and aren't experiencing the current issue, so I guess it should work.

Thanks for taking a look and helping!

sschuberth commented 1 year ago

Could this lead to a problem?

I don't think so.

Could you maybe try to minimize your project to that it still reproduces the issue, but does not contain any private information, and then share it? Or alternatively, try to modify our existing Android test project so that it reproduces the issue?

mpbecker commented 1 year ago

Unfortunately I cannot strip down the project to publish it (too much effort), so I took your example and adapted it step by step. I found three dependencies responsible for ORT hanging at the Connecting from tooling... message in combination with a setting in our gradle.properties file. Project is uploaded here: https://github.com/mpbecker/OSS_debug Further information how to reproduce are found here: https://github.com/mpbecker/OSS_debug/blob/c00626e9b178acfcdfb8f7adb03707bfda431c21/app/build.gradle#L63 All tested with the latest Android Studio version on a Ubuntu machine. Please let me know if you can reproduce, so maybe we can do some further investigations. Thanks!

mpbecker commented 1 year ago

I just tried an older version for Hilt: going back from 2.44 to 2.43.2 seems to solve the issue. No clue what they changed there, but maybe that could give a hint what could cause the problem.

sschuberth commented 1 year ago

I just tried an older version for Hilt: going back from 2.44 to 2.43.2 seems to solve the issue.

I can reproduce the issue, that's great, thanks for that! However, I also see it hanging with Hilt 2.43.2.

sschuberth commented 1 year ago

Changing the lines

https://github.com/oss-review-toolkit/ort/blob/63b2b2d3e29b822ff75af42772682f35bf5e3a31/analyzer/src/main/kotlin/managers/Gradle.kt#L204-L205

to read

.setStandardOutput(System.out)
.setStandardError(System.err)

yields on-the-fly output that shows that analysis is actually not hanging, but extremely slow, and this message shows up for every Gradle configuration:

Configuration 'amazonDemoDebugAndroidTestAnnotationProcessorClasspath' was resolved during configuration time.
This is a build performance and scalability issue.
See https://github.com/gradle/gradle/issues/2298
mpbecker commented 1 year ago

Oh wow, thanks for revealing what's going on here! Well that's somehow annoying since I left ORT running for our Project for about 7 hours hanging at this message and then finally canceled the task :D And the machine was quite powerful. So it seems we are stuck here or have to live with the fact that it could take hours to run ORT or do you have any idea how to tackle this? I must admit, I am not that familiar with Gradle config, etc.

sschuberth commented 1 year ago

Here's a stacktrace:

at com.android.build.gradle.internal.DependencyResolutionChecks$registerDependencyCheck$4$1.execute(DependencyResolutionChecks.kt:84)
at com.android.build.gradle.internal.DependencyResolutionChecks$registerDependencyCheck$4$1.execute(DependencyResolutionChecks.kt:62)
at org.gradle.configuration.internal.DefaultUserCodeApplicationContext$CurrentApplication$1.execute(DefaultUserCodeApplicationContext.java:123)
at org.gradle.internal.event.BroadcastDispatch$ActionInvocationHandler.dispatch(BroadcastDispatch.java:95)
at org.gradle.internal.event.BroadcastDispatch$ActionInvocationHandler.dispatch(BroadcastDispatch.java:83)
at org.gradle.internal.event.AbstractBroadcastDispatch.dispatch(AbstractBroadcastDispatch.java:43)
at org.gradle.internal.event.BroadcastDispatch$SingletonDispatch.dispatch(BroadcastDispatch.java:245)
at org.gradle.internal.event.BroadcastDispatch$SingletonDispatch.dispatch(BroadcastDispatch.java:157)
at org.gradle.internal.event.AbstractBroadcastDispatch.dispatch(AbstractBroadcastDispatch.java:61)
at org.gradle.internal.event.BroadcastDispatch$CompositeDispatch.dispatch(BroadcastDispatch.java:346)
at org.gradle.internal.event.BroadcastDispatch$CompositeDispatch.dispatch(BroadcastDispatch.java:249)
at org.gradle.internal.event.ListenerBroadcast.dispatch(ListenerBroadcast.java:141)
at org.gradle.internal.event.ListenerBroadcast.dispatch(ListenerBroadcast.java:37)
at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
at com.sun.proxy.$Proxy48.beforeResolve(Unknown Source)
at org.gradle.api.internal.artifacts.configurations.DefaultConfiguration.performPreResolveActions(DefaultConfiguration.java:811)
at org.gradle.api.internal.artifacts.configurations.DefaultConfiguration.access$400(DefaultConfiguration.java:159)
at org.gradle.api.internal.artifacts.configurations.DefaultConfiguration$1.call(DefaultConfiguration.java:654)
at org.gradle.api.internal.artifacts.configurations.DefaultConfiguration$1.call(DefaultConfiguration.java:647)
at org.gradle.internal.operations.DefaultBuildOperationRunner$CallableBuildOperationWorker.execute(DefaultBuildOperationRunner.java:204)
at org.gradle.internal.operations.DefaultBuildOperationRunner$CallableBuildOperationWorker.execute(DefaultBuildOperationRunner.java:199)
at org.gradle.internal.operations.DefaultBuildOperationRunner$2.execute(DefaultBuildOperationRunner.java:66)
at org.gradle.internal.operations.DefaultBuildOperationRunner$2.execute(DefaultBuildOperationRunner.java:59)
at org.gradle.internal.operations.DefaultBuildOperationRunner.execute(DefaultBuildOperationRunner.java:157)
at org.gradle.internal.operations.DefaultBuildOperationRunner.execute(DefaultBuildOperationRunner.java:59)
at org.gradle.internal.operations.DefaultBuildOperationRunner.call(DefaultBuildOperationRunner.java:53)
at org.gradle.internal.operations.DefaultBuildOperationExecutor.call(DefaultBuildOperationExecutor.java:73)
at org.gradle.api.internal.artifacts.configurations.DefaultConfiguration.resolveGraphIfRequired(DefaultConfiguration.java:647)
at org.gradle.api.internal.artifacts.configurations.DefaultConfiguration.lambda$resolveExclusively$4(DefaultConfiguration.java:627)
at org.gradle.api.internal.project.DefaultProjectStateRegistry$CalculatedModelValueImpl.update(DefaultProjectStateRegistry.java:444)
at org.gradle.api.internal.artifacts.configurations.DefaultConfiguration.resolveExclusively(DefaultConfiguration.java:624)
at org.gradle.api.internal.artifacts.configurations.DefaultConfiguration.resolveToStateOrLater(DefaultConfiguration.java:611)
at org.gradle.api.internal.artifacts.configurations.DefaultConfiguration.getResolvedConfiguration(DefaultConfiguration.java:586)
at org.gradle.api.internal.artifacts.configurations.DefaultConfiguration_Decorated.getResolvedConfiguration(Unknown Source)
at jdk.internal.reflect.GeneratedMethodAccessor65.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:107)
at groovy.lang.MetaBeanProperty.getProperty(MetaBeanProperty.java:59)
at org.gradle.internal.metaobject.BeanDynamicObject$MetaClassAdapter.getProperty(BeanDynamicObject.java:233)
at org.gradle.internal.metaobject.BeanDynamicObject.tryGetProperty(BeanDynamicObject.java:176)
at org.gradle.internal.metaobject.CompositeDynamicObject.tryGetProperty(CompositeDynamicObject.java:55)
at org.gradle.internal.metaobject.AbstractDynamicObject.getProperty(AbstractDynamicObject.java:60)
at org.gradle.api.internal.artifacts.configurations.DefaultConfiguration_Decorated.getProperty(Unknown Source)
at org.codehaus.groovy.runtime.callsite.PogoGetPropertySite.getProperty(PogoGetPropertySite.java:49)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callGetProperty(AbstractCallSite.java:329)
at AbstractDependencyTreePlugin$DependencyTreeModelBuilder$_buildAll_closure1.doCall(/tmp/ort-Gradle16581747034260241197/init4185485621798155021.gradle:176)
at jdk.internal.reflect.GeneratedMethodAccessor31.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:107)
at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:323)
at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:274)
at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1035)
at groovy.lang.Closure.call(Closure.java:412)
at groovy.lang.Closure.call(Closure.java:428)
at org.codehaus.groovy.runtime.DefaultGroovyMethods.findResults(DefaultGroovyMethods.java:4761)
at org.codehaus.groovy.runtime.DefaultGroovyMethods.findResults(DefaultGroovyMethods.java:4745)
at org.codehaus.groovy.runtime.dgm$285.invoke(Unknown Source)
at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoMetaMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:226)
at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.call(PogoMetaMethodSite.java:73)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:47)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:125)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:139)
at AbstractDependencyTreePlugin$DependencyTreeModelBuilder.buildAll(/tmp/ort-Gradle16581747034260241197/init4185485621798155021.gradle:170)

So it seems ORT's way of resolving dependencies at Gradle configuration time is inherently incompatible with the Android plugin's check not to do that.

We have several ideas how to change the Gradle analysis in the context of another issue, but until then I don't have an idea for a work-around right now.

All in all, your issue @mpbecker more looks like #5622 than this issue, as @DaveJarvis does not seem to be using an Android project.

mpbecker commented 1 year ago

Alright! Big shout outs for helping on such short notice. Really appreciate it, thanks!

ghost commented 1 year ago

Correct, we're not using Android. And it could be that ORT isn't hanging but merely taking a long time to run.

In either case, having tonnes of information about what's going on would be quite helpful. Information such as:

We're running ORT through a rather picky firewall, so it could be getting stuck on downloads.

sschuberth commented 1 year ago

FYI, @DaveJarvis, some more progress info has just been added with https://github.com/oss-review-toolkit/ort/pull/5964.

sschuberth commented 1 year ago

@DaveJarvis, do you happen to know whether there's a BOM artifact in your dependency tree? If so, #5964 might fix your issue, too.

ghost commented 1 year ago

Thanks for the update. I don't know whether there was a BOM artifact.

sschuberth commented 1 year ago

@DaveJarvis could you give the new GradleInspector a try?

ghost commented 1 year ago

new GradleInspector a try?

Sorry, I won't be back this way. We now hand-maintain our XML files that contain the licensing information. ORT was instrumental in getting us 80% of the way there.

sschuberth commented 1 year ago

Thanks for reporting back anyway @DaveJarvis, and good to hear that ORT was at least of some help to you!

sschuberth commented 1 year ago

I found three dependencies responsible for ORT hanging at the Connecting from tooling... message in combination with a setting in our gradle.properties file. Project is uploaded here: https://github.com/mpbecker/OSS_debug

I just verified that the current version of ORT's Gradle analyzer also does not hang anymore for @mpbecker's case, see the analyzer-result.

So I'm closing this as the issue is not reproducible anymore.