ClassFinder.processClassLoadError Swallowing Exceptions

[astrelsky]

https://github.com/NationalSecurityAgency/ghidra/blob/25894ff9ae6b670811ce4e3ed1aea973069a5e21/Ghidra/Framework/Generic/src/main/java/ghidra/util/classfinder/ClassFinder.java#L114-L121

So I was implementing a Loader and spent several hours banging my head on my desk trying to figure out why my implementation wasn't being loaded yet was in the classpath. After finally tracing it to the catch block in the ClassFinder.loadExtensionPoint and executing t.printStackTrace() from my debugger did I figure out what my problem was.

Here is what my stackTrace was for the exception being swallowed.

java.lang.ExceptionInInitializerError
        at java.base/java.lang.Class.forName0(Native Method)
        at java.base/java.lang.Class.forName(Class.java:416)
        at ghidra.util.classfinder.ClassFinder.loadExtensionPoint(ClassFinder.java:100)
        at ghidra.util.classfinder.ClassPackage.scanClasses(ClassPackage.java:51)
        at ghidra.util.classfinder.ClassPackage.<init>(ClassPackage.java:42)
        at ghidra.util.classfinder.ClassPackage.scanSubPackages(ClassPackage.java:83)
        at ghidra.util.classfinder.ClassPackage.<init>(ClassPackage.java:43)
        at ghidra.util.classfinder.ClassPackage.scanSubPackages(ClassPackage.java:83)
        at ghidra.util.classfinder.ClassPackage.<init>(ClassPackage.java:43)
        at ghidra.util.classfinder.ClassDir.<init>(ClassDir.java:33)
        at ghidra.util.classfinder.ClassFinder.initialize(ClassFinder.java:70)
        at ghidra.util.classfinder.ClassFinder.<init>(ClassFinder.java:44)
        at ghidra.util.classfinder.ClassSearcher.search(ClassSearcher.java:233)
        at ghidra.framework.HeadlessGhidraApplicationConfiguration.performClassSearching(HeadlessGhidraApplicationConfiguration.java:91)
        at ghidra.framework.HeadlessGhidraApplicationConfiguration.initializeApplication(HeadlessGhidraApplicationConfiguration.java:41)
        at ghidra.framework.GhidraApplicationConfiguration.initializeApplication(GhidraApplicationConfiguration.java:57)  
        at ghidra.framework.Application.initializeApplication(Application.java:115)
        at ghidra.GhidraRun.lambda$launch$1(GhidraRun.java:78)
        at java.base/java.lang.Thread.run(Thread.java:830)
Caused by: java.lang.IllegalArgumentException: duplicate element: MIPS-R5900
        at java.base/java.util.ImmutableCollections$Set12.<init>(ImmutableCollections.java:574)
        at java.base/java.util.Set.of(Set.java:485)
        at ghidra.emotionengine.EmotionEngineLoader.<clinit>(EmotionEngineLoader.java:36)
        ... 19 more

While quite embarrassing here is what was causing the problem:

private static final Set<String> TARGET_PROCESSORS = Collections.unmodifiableSet(
        Set.of("MIPS-R5900", "MIPS-R5900")
    );

Attached is a fresh log with the bad implementation showing that the exception is indeed being swallowed.

application.log

[dragonmacher]

The exception is not exactly being 'squashed'. We are logging it at the trace level with the notion that developer could enable tracing while they are building extensions to Ghidra. If you believe the comment in the code that is logging the trace, then we potentially run into these exceptions when dealing with 3rd-party libraries that have naming patters similar to those that we use for discovery.

That being said, we could update the error handler to ignore 3rd-party jars only, allowing developer code to be logged.

[astrelsky]

The exception is not exactly being 'squashed'. We are logging it at the trace level with the notion that developer could enable tracing while they are building extensions to Ghidra. If you believe the comment in the code that is logging the trace, then we potentially run into these exceptions when dealing with 3rd-party libraries that have naming patters similar to those that we use for discovery.

That being said, we could update the error handler to ignore 3rd-party jars only, allowing developer code to be logged.

I'm fairly certain I have my debuggers console output to verbose but I'll double check in a bit. That being said no trace or anything was printed. It just ignored it.

[dragonmacher]

I can see the code path for this exception is outputting at the trace level. Assuming our logging implementation is not broken, then this would be a log configuration item.

To test this running from a build, you can:

1. Edit /support/debug.log4j.xml to have "console" set to "TRACE"
2. Edit that same file to have the "ghidra" entry set to "TRACE"
3. Launch ghidra from /ghidraDebug

If running from a repo clone using Eclipse, then you will either have to make similar edits to Generic/src/main/resources/generic.log4jdev.xml or override the log config file used inside of the Eclipse launcher.

[astrelsky]

I can see the code path for this exception is outputting at the trace level. Assuming our logging implementation is not broken, then this would be a log configuration item.

To test this running from a build, you can:

1. Edit /support/debug.log4j.xml to have "console" set to "TRACE"
2. Edit that same file to have the "ghidra" entry set to "TRACE"
3. Launch ghidra from /ghidraDebug

If running from a repo clone using Eclipse, then you will either have to make similar edits to Generic/src/main/resources/generic.log4jdev.xml or override the log config file used inside of the Eclipse launcher.

According to my output upon launch it is using the following: Using log config file: jar:file:/C:/Users/astre/Documents/ghidra_9.2_DEV/Ghidra/Framework/Generic/lib/Generic.jar!/generic.log4j.xml (LoggingInitialization) So I changed the one in the archive and lo and behold it was indeed logged. I'm not sure why it's using that one though.

EDIT: I forgot to set the DEBUG_LOG4J in my cmd arguments

[dragonmacher]

I'm not sure why it's using that one though.

In 'production mode' it will use generic.log4j.xml; in 'development mode' it will use the file I mentioned above. SystemUtilities determines which mode you are in by checking how it was loaded--loading from a jar file is 'production mode'; loading from a directory on the filesystem signals 'development mode'.

Regadless of the mode, you can specify your own log file from a system property in your launcher by using:

-Dlog4j.configuration=/path/to/log/file.xml