Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Stuck at JNI boundary? #5782

Closed
ghost opened this issue Sep 12, 2022 · 26 comments
Closed

Stuck at JNI boundary? #5782

ghost opened this issue Sep 12, 2022 · 26 comments
Labels
analyzer About the analyzer tool bug Issues that are considered to be bugs help wanted An issue where third-party help is wanted on

Comments

@ghost
Copy link

ghost commented Sep 12, 2022

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 sschuberth added bug Issues that are considered to be bugs analyzer About the analyzer tool labels Sep 12, 2022
@sschuberth
Copy link
Member

  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
Copy link
Author

ghost commented Sep 12, 2022

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
Copy link
Author

ghost commented Sep 12, 2022

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
Copy link
Member

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
Copy link
Author

ghost commented Sep 12, 2022

Hangs here:

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

@oss-review-toolkit oss-review-toolkit deleted a comment Sep 13, 2022
@oss-review-toolkit oss-review-toolkit deleted a comment Sep 13, 2022
@mpbecker
Copy link

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
Copy link
Member

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.

@sschuberth sschuberth added the help wanted An issue where third-party help is wanted on label Oct 17, 2022
@mpbecker
Copy link

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

val gradleConnection = gradleConnector.forProjectDirectory(projectDir).connect()
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
Copy link
Member

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
Copy link

mpbecker commented Oct 17, 2022

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
Copy link
Member

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
Copy link

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
Copy link

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
Copy link
Member

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
Copy link
Member

Changing the lines

.setStandardOutput(stdout)
.setStandardError(stderr)

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
Copy link

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
Copy link
Member

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
Copy link

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

@ghost
Copy link
Author

ghost commented Oct 18, 2022

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:

  • What project is being analyzed?
  • What files are being downloaded (e.g., URLs)?
  • What actions are being taken (uncompressing jar file, scanning for pom.xml files, searching for authors, etc.)?
  • What commands are being run?
  • What exceptions are encountered?
  • What information for the project was gleaned (project name, version, authors, license)?
  • Was the license information indeterminate?

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

@sschuberth
Copy link
Member

FYI, @DaveJarvis, some more progress info has just been added with #5964.

@sschuberth
Copy link
Member

@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
Copy link
Author

ghost commented Nov 18, 2022

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

@sschuberth
Copy link
Member

@DaveJarvis could you give the new GradleInspector a try?

@ghost
Copy link
Author

ghost commented Apr 27, 2023

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
Copy link
Member

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

@sschuberth
Copy link
Member

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
analyzer About the analyzer tool bug Issues that are considered to be bugs help wanted An issue where third-party help is wanted on
Projects
None yet
Development

No branches or pull requests

2 participants