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

NamingManager fails to find java.naming.factory.initial during reindex #2211

Closed
vladak opened this issue Jul 10, 2018 · 8 comments
Closed

NamingManager fails to find java.naming.factory.initial during reindex #2211

vladak opened this issue Jul 10, 2018 · 8 comments

Comments

@vladak
Copy link
Member

vladak commented Jul 10, 2018

Since upgrading to 1.1-rc31 the following (seemingly innocuous) exception is thrown during indexing:

2018-07-10 14:30:45.587+0200 INFO t1 Configuration.read: Reading configuration from /tmp/opengrok-conf.tyYwBc
2018-07-10 14:30:46.219+0200 INFO t1 Configuration.read: Reading configuration from /opengrok/etc/configuration.xml
2018-07-10 14:30:46.711+0200 INFO t1 Statistics.report: done invalidating repositories (took 53 ms)
2018-07-10 14:30:46.720+0200 INFO t1 Indexer.main: Indexer version 1.1-rc31 (4661bfa7181765acb5ff8a6c34c7ac9d707682f0)
2018-07-10 14:30:46.746+0200 INFO t1 Indexer.prepareIndexer: Generating history cache for repositories: prm4.0
2018-07-10 14:30:46.750+0200 INFO t1 HistoryGuru.createCacheReal: Creating historycache for 1 repositories
2018-07-10 14:30:46.757+0200 INFO t28 HistoryGuru.createCache: Creating historycache for /ws-local/prm4.0 (SCCSRepository)
2018-07-10 14:30:46.758+0200 INFO t28 Repository.createCache: Skipping creation of history cache for /ws-local/prm4.0, since retrieval of history for d
irectories is not implemented for this repository type.
2018-07-10 14:30:46.760+0200 INFO t28 Statistics.report: Done historycache for /ws-local/prm4.0 (took 3 ms)
2018-07-10 14:30:46.762+0200 INFO t1 Statistics.report: Done historycache for all repositories (took 12 ms)
2018-07-10 14:30:46.763+0200 INFO t1 Indexer.prepareIndexer: Done...
2018-07-10 14:30:46.765+0200 INFO t1 Indexer.doIndexerExecution: Starting indexing
2018-07-10 14:30:48.042+0200 CONFIG t29 ServiceFinder.<clinit>: Running in a non-OSGi environment
2018-07-10 14:30:48.380+0200 FINE t29 AbstractHk2InjectionManager.<init>: Clearing Jersey HK2 caches. Service cache size: 3, reflection cache size: 20.
2018-07-10 14:30:48.467+0200 FINE t29 DataStructures.<clinit>: USING LTQ class:class java.util.concurrent.LinkedTransferQueue
2018-07-10 14:30:48.755+0200 FINE t29 ClientExecutorProvidersConfigurator.lookupManagedExecutorService: null
java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.glassfish.jersey.client.ClientExecutorProvidersConfigurator.lookupManagedExecutorService(ClientExecutorProvidersConfigurator.java:176)
        at org.glassfish.jersey.client.ClientExecutorProvidersConfigurator.<clinit>(ClientExecutorProvidersConfigurator.java:73)
        at org.glassfish.jersey.client.ClientConfig$State.initRuntime(ClientConfig.java:461)
        at org.glassfish.jersey.internal.util.collection.Values$LazyValueImpl.get(Values.java:341)
        at org.glassfish.jersey.client.ClientConfig.getRuntime(ClientConfig.java:826)
        at org.glassfish.jersey.client.ClientRequest.getConfiguration(ClientRequest.java:285)
        at org.glassfish.jersey.client.JerseyInvocation.validateHttpMethodAndEntity(JerseyInvocation.java:143)
        at org.glassfish.jersey.client.JerseyInvocation.<init>(JerseyInvocation.java:112)
        at org.glassfish.jersey.client.JerseyInvocation.<init>(JerseyInvocation.java:108)
        at org.glassfish.jersey.client.JerseyInvocation.<init>(JerseyInvocation.java:99)
        at org.glassfish.jersey.client.JerseyInvocation$Builder.method(JerseyInvocation.java:445)
        at org.glassfish.jersey.client.JerseyInvocation$Builder.put(JerseyInvocation.java:334)
        at org.opensolaris.opengrok.index.IndexDatabase.markProjectIndexed(IndexDatabase.java:381)
        at org.opensolaris.opengrok.index.IndexDatabase.update(IndexDatabase.java:515)
        at org.opensolaris.opengrok.index.Indexer$1.run(Indexer.java:1074)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: javax.naming.NoInitialContextException: Need to specify class name in environment or system property, or as an applet parameter, or in an ap
plication resource file:  java.naming.factory.initial
        at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:662)
        at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:313)
        at javax.naming.InitialContext.getURLOrDefaultInitCtx(InitialContext.java:350)
        at javax.naming.InitialContext.lookup(InitialContext.java:417)
        ... 24 more
@ahornace
Copy link
Contributor

I think this does not break the Jersey client functionality.

It is logged from here:

    private static ExecutorService lookupManagedExecutorService() {
        // Get the default ManagedExecutorService, if available
        try {
            // Android and some other environments don't have InitialContext class available.
            final Class<?> aClass =
                    AccessController.doPrivileged(ReflectionHelper.classForNamePA("javax.naming.InitialContext"));

            final Object initialContext = aClass.newInstance();

            final Method lookupMethod = aClass.getMethod("lookup", String.class);
            return (ExecutorService) lookupMethod.invoke(initialContext, "java:comp/DefaultManagedExecutorService");
        } catch (Exception e) {
            // ignore
            if (LOGGER.isLoggable(Level.FINE)) {
                LOGGER.log(Level.FINE, e.getMessage(), e);
            }
        } catch (LinkageError error) {
            // ignore - JDK8 compact2 profile - http://openjdk.java.net/jeps/161
        }

        return null;
    }

which is called from here

private static final ExecutorService MANAGED_EXECUTOR_SERVICE = lookupManagedExecutorService();

However, there is a null check and other default behaviour so it does not seem it is a big deal:

if (MANAGED_EXECUTOR_SERVICE != null) {
    defaultAsyncExecutorProvider = new ClientExecutorServiceProvider(MANAGED_EXECUTOR_SERVICE);
} else {
    defaultAsyncExecutorProvider = new DefaultClientAsyncExecutorProvider(0);
}

Whole class: https://github.com/jersey/jersey/blob/12e5d8bdf22bcd2676a1032ed69473cf2bbc48c7/core-client/src/main/java/org/glassfish/jersey/client/ClientExecutorProvidersConfigurator.java

I cannot reproduce on my setup. Maybe Solaris specific?

Either way, this code should log an exception instead of printing to stderr:

    Response r = ClientBuilder.newClient()
                        .target(env.getConfigHost())
                        .path("api")
                        .path("v1")
                        .path("projects")
                        .path(Util.URIEncode(project.getName()))
                        .path("indexed")
                        .request()
                        .put(Entity.text(""));

                if (r.getStatusInfo().getFamily() != Response.Status.Family.SUCCESSFUL) {
                    System.err.println("Couldn't notify the webapp: " + r.toString());
                }

@vladak
Copy link
Member Author

vladak commented Jul 30, 2018

I see that the logging of the Response problem was fixed in cset 4550891.

@vladak
Copy link
Member Author

vladak commented Jul 30, 2018

So, Jersey needs an implementation of ManagedExecutorService. https://docs.oracle.com/javaee/7/api/javax/enterprise/concurrent/ManagedExecutorService.html says:

A ManagedExecutorService extends the Java™ SE ExecutorService to provide methods for submitting tasks for execution in a Java™ EE environment. Implementations of the ManagedExecutorService are provided by a Java™ EE Product Provider. Application Component Providers use the Java Naming and Directory Interface™ (JNDI) to look-up instances of one or more ManagedExecutorService objects using resource environment references. ManagedExecutorService instances can also be injected into application components through the use of the Resource annotation.

So, JNDI needs to be setup in order to perform the lookup. It needs the InitialContext for the setup.

According to https://docs.oracle.com/javase/tutorial/jndi/ops/faq.html#1 (and https://stackoverflow.com/questions/1525385/noinitialcontextexception-error) the NoInitialContextException gets thrown if there is no implementation for the naming interface:

Cause: You did not specify which implementation to use for the initial context. Specifically, the Context.INITIAL_CONTEXT_FACTORY environment property was not set to the class name of the factory that will create the initial context. Or, you did not make available to the program the classes of the service provider named by Context.INITIAL_CONTEXT_FACTORY.
Solution: Set the Context.INITIAL_CONTEXT_FACTORY environment property to the class name of the initial context implementation that you are using.

Now, Tomcat does actually perform some voodoo to inject the initialContext factory. According to https://tomcat.apache.org/tomcat-8.0-doc/jndi-resources-howto.html

Tomcat provides a JNDI InitialContext implementation instance for each web application running under it, in a manner that is compatible with those provided by a Java Enterprise Edition application server.

https://stackoverflow.com/questions/17573219/how-does-tomcat-inject-the-jndi-component-local-context explains how this works:

First of all early in the startup process Tomcat calls:
System.setProperty(javax.naming.Context.INITIAL_CONTEXT_FACTORY,
"org.apache.naming.java.javaURLContextFactory");
This tells the JVM to use Tomcat's own factory for creating instances of InitialContext.
The second part is based around the fact that each web application has its own class loader and that all user code executes with that class loader set as the thread context class loader. Therefore, when a new InitialContext is created, Tomcat can look at the thread context class loader to determine which web application is making the request.
From there it is a simple process to hook up the new InitialContext object wth the right set of JNDI resources for the current application.

So evidently this mechanism got broken somehow. I wonder if the trick still works with the above code using reflection.

@tulinkry
Copy link
Contributor

tulinkry commented Oct 2, 2018

I know it's not that important, but can we mute it?

@cross
Copy link
Contributor

cross commented May 31, 2019

I am seeing a similar exception thrown indexing one of my projects with 1.2.8. It seems to be lookupM anagedScheduledExecutorService, instead of lookupManagedExecutorService, but I presume it may be another case as this issue describes.

I see multiple (at least 2) occurrences of this within the same projects indexing:

2019-05-31 08:52:07.742-0400 FINE t1 ClientExecutorProvidersConfigurator.lookupManagedScheduledExecutorService: null
java.lang.reflect.InvocationTargetException
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.glassfish.jersey.client.ClientExecutorProvidersConfigurator.lookupManagedScheduledExecutorService(ClientExecutorProvidersConfigurator.java:198)
        at org.glassfish.jersey.client.ClientExecutorProvidersConfigurator.init(ClientExecutorProvidersConfigurator.java:148)
        at org.glassfish.jersey.client.ClientConfig$State.initRuntime(ClientConfig.java:466)
        at org.glassfish.jersey.internal.util.collection.Values$LazyValueImpl.get(Values.java:341)
        at org.glassfish.jersey.client.ClientConfig.getRuntime(ClientConfig.java:826)   
        at org.glassfish.jersey.client.ClientRequest.getConfiguration(ClientRequest.java:285)
        at org.glassfish.jersey.client.JerseyInvocation.validateHttpMethodAndEntity(JerseyInvocation.java:143)
        at org.glassfish.jersey.client.JerseyInvocation.<init>(JerseyInvocation.java:112)
        at org.glassfish.jersey.client.JerseyInvocation.<init>(JerseyInvocation.java:108)
        at org.glassfish.jersey.client.JerseyInvocation.<init>(JerseyInvocation.java:99)
        at org.glassfish.jersey.client.JerseyInvocation$Builder.method(JerseyInvocation.java:445)
        at org.glassfish.jersey.client.JerseyInvocation$Builder.put(JerseyInvocation.java:334)
        at org.opengrok.indexer.configuration.RuntimeEnvironment.lambda$signalTorefreshSearcherManagers$3(RuntimeEnvironment.java:1429)
        at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
        at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
        at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1654)
        at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
        at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
        at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
        at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
        at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
        at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
        at org.opengrok.indexer.configuration.RuntimeEnvironment.signalTorefreshSearcherManagers(RuntimeEnvironment.java:1421)
        at org.opengrok.indexer.index.Indexer.refreshSearcherManagers(Indexer.java:1107)
[...]
Caused by: javax.naming.NoInitialContextException: Need to specify class name in environment or system property, or in an application resource file: java.naming.factory.initial
        at java.naming/javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:685)
        at java.naming/javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:305)
[...]

@vladak
Copy link
Member Author

vladak commented Jan 22, 2024

I know it's not that important, but can we mute it?

Definitely can be muted. The exception is thrown from Jersey code at the FINE level. This happens when the indexer runs with -Djava.util.logging.config.file=logging.properties where the contents of the file look like this:

handlers= java.util.logging.FileHandler

.level = FINEST

java.util.logging.FileHandler.pattern = /opengrok/log/%PROJ%/opengrok%g.%u.log
java.util.logging.FileHandler.append = false
java.util.logging.FileHandler.limit = 0
java.util.logging.FileHandler.count = 120
java.util.logging.FileHandler.formatter = org.opengrok.indexer.logger.formatter.SimpleFileLogFormatter

java.util.logging.ConsoleHandler.level = WARNING
java.util.logging.ConsoleHandler.formatter = org.opengrok.indexer.logger.formatter.SimpleFileLogFormatter

Setting the log level to FINEST (or FINE for this case) globally is probably a stretch. Using something like org.opengrok.level = FINEST is good enough.

I constructed a test case using HostUtil#isWebAppReachable() (from IDEA) and stepped in the debugger to org.glassfish.jersey.client.ClientExecutorProvidersConfigurator#lookupManagedExecutorService() to discover the exception is thrown in that case well, however it is not reported because the log level was at the default value.

I corrected this in the https://github.com/oracle/opengrok/wiki/Debugging#indexer

As quoted on #2211 (comment), the lookup is meant for Java EE environment, which the indexer is not, hence closing.

@vladak vladak closed this as completed Jan 22, 2024
@vladak
Copy link
Member Author

vladak commented Jan 22, 2024

For the record, here is the log snippet of the recent indexer run with the global log level set to FINEST:

2024-01-19 18:50:59.770+0100 CONFIG t1 ServiceFinder.<clinit>: Running in a non-OSGi environment
2024-01-19 18:50:59.795+0100 FINE t1 HostUtil.isWebAppReachable: checking reachability of http://localhost:8080/source with connect/read timeout of 10 seconds
2024-01-19 18:50:59.817+0100 FINER t1 SystemPropertiesConfigurationModel.getProperties: System properties configuration provider not allowed
2024-01-19 18:50:59.898+0100 FINEST t1 ServiceFinder$LazyObjectIterator.next: Loading next object: org.glassfish.jersey.inject.hk2.Hk2InjectionManagerFactory
2024-01-19 18:50:59.949+0100 FINER t1 Logger.debug: Created ServiceLocator ServiceLocatorImpl(__HK2_Generated_0,0,473524237)
2024-01-19 18:51:00.041+0100 FINE t1 AbstractHk2InjectionManager.<init>: Clearing Jersey HK2 caches. Service cache size: 3, reflection cache size: 20.
2024-01-19 18:51:00.096+0100 FINEST t1 ServiceFinder$LazyClassIterator.next: Loading next class: org.glassfish.jersey.logging.LoggingFeatureAutoDiscoverable
2024-01-19 18:51:00.100+0100 FINEST t1 ServiceFinder$LazyClassIterator.next: Loading next class: org.glassfish.jersey.server.filter.internal.ServerFiltersAutoDiscoverable
2024-01-19 18:51:00.101+0100 FINEST t1 ServiceFinder$LazyClassIterator.next: Loading next class: org.glassfish.jersey.jackson.internal.JacksonAutoDiscoverable
2024-01-19 18:51:00.112+0100 FINEST t1 ServiceFinder$LazyClassIterator.next: Loading next class: org.glassfish.jersey.server.validation.internal.ValidationAutoDiscoverable
2024-01-19 18:51:00.114+0100 FINEST t1 ServiceFinder$LazyClassIterator.next: Loading next class: org.glassfish.jersey.server.wadl.internal.WadlAutoDiscoverable
2024-01-19 18:51:00.115+0100 FINEST t1 ServiceFinder$LazyClassIterator.next: Loading next class: org.glassfish.jersey.server.internal.monitoring.MonitoringAutodiscoverable
2024-01-19 18:51:00.181+0100 FINE t1 ClientExecutorProvidersConfigurator.lookupManagedExecutorService: null
java.lang.reflect.InvocationTargetException
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.glassfish.jersey.client.ClientExecutorProvidersConfigurator.lookupManagedExecutorService(ClientExecutorProvidersConfigurator.java:150)
        at org.glassfish.jersey.client.ClientExecutorProvidersConfigurator.<clinit>(ClientExecutorProvidersConfigurator.java:49)
        at org.glassfish.jersey.client.ClientConfig$State.initRuntime(ClientConfig.java:459)
        at org.glassfish.jersey.internal.util.collection.Values$LazyValueImpl.get(Values.java:317)
        at org.glassfish.jersey.client.ClientConfig.getRuntime(ClientConfig.java:834)
        at org.glassfish.jersey.client.ClientRequest.getClientRuntime(ClientRequest.java:181)
        at org.glassfish.jersey.client.JerseyWebTarget.onBuilder(JerseyWebTarget.java:371)
        at org.glassfish.jersey.client.JerseyWebTarget.request(JerseyWebTarget.java:199)
        at org.glassfish.jersey.client.JerseyWebTarget.request(JerseyWebTarget.java:38)
        at org.opengrok.indexer.util.HostUtil.isWebAppReachable(HostUtil.java:83)
        at org.opengrok.indexer.util.HostUtil.isReachable(HostUtil.java:117)
        at org.opengrok.indexer.index.Indexer.main(Indexer.java:177)
Caused by: javax.naming.NoInitialContextException: Need to specify class name in environment or system property, or in an application resource file: java.naming.factory.initial
        at java.naming/javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:691)
        at java.naming/javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:305)
        at java.naming/javax.naming.InitialContext.getURLOrDefaultInitCtx(InitialContext.java:342)
        at java.naming/javax.naming.InitialContext.lookup(InitialContext.java:409)
        ... 16 more

@vladak
Copy link
Member Author

vladak commented Jan 22, 2024

Actually, I found some sample logging.properties files in the code base that specify the global log level. These should be fixed.

@vladak vladak reopened this Jan 22, 2024
vladak added a commit to vladak/OpenGrok that referenced this issue Jan 22, 2024
@vladak vladak closed this as completed in e11eb6e Jan 22, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants