[fcrepo-user] Problem with DEBUG log level iin 3.5?

[Stephen Bayliss]

When starting Fedora with all logging set to DEBUG, I'm getting the
following exception (resource index is enabled). It's fine if I set it to
WARN. Tomcat and Fedora logs below.

I wonder if anyone replicate this?

Steve

Tomcat log:

**************************
** FEDORA STARTUP ERROR **
**************************

Fedora startup failed
org.fcrepo.server.errors.ModuleInitializationException: Error initializing
RI
at
org.fcrepo.server.resourceIndex.ResourceIndexModule.postInitModule(Re
sourceIndexModule.java:127)
at org.fcrepo.server.Server.<init>(Server.java:644)
at org.fcrepo.server.BasicServer.<init>(BasicServer.java:41)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
Method)

at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstruct
orAccessorImpl.java:39)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingC
onstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at org.fcrepo.server.Server.getInstance(Server.java:1239)
at
org.fcrepo.server.ServerController.init(ServerController.java:403)
at javax.servlet.GenericServlet.init(GenericServlet.java:212)
at
org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.
java:1173)
at
org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:99
3)
at
org.apache.catalina.core.StandardContext.loadOnStartup(StandardContex
t.java:4350)
at
org.apache.catalina.core.StandardContext.start(StandardContext.java:4
659)
at
org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase
.java:791)
at
org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:77
1)
at
org.apache.catalina.core.StandardHost.addChild(StandardHost.java:546)

at
org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.ja
va:637)
at
org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.j
ava:563)
at
org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:498
)
at
org.apache.catalina.startup.HostConfig.start(HostConfig.java:1277)
at
org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java
:321)
at
org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(Lifecycl
eSupport.java:119)
at
org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1053)

at
org.apache.catalina.core.StandardHost.start(StandardHost.java:785)
at
org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1045)

at
org.apache.catalina.core.StandardEngine.start(StandardEngine.java:445
)
at
org.apache.catalina.core.StandardService.start(StandardService.java:5
19)
at
org.apache.catalina.core.StandardServer.start(StandardServer.java:710
)
at org.apache.catalina.startup.Catalina.start(Catalina.java:581)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.
java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
sorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:289)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:414)
Caused by: java.lang.UnsupportedOperationException: This MulgaraConnector is
rea
d-only!
at
org.trippi.impl.mulgara.MulgaraConnector.getWriter(MulgaraConnector.j
ava:104)
at
org.fcrepo.server.resourceIndex.ResourceIndexImpl.<init>(ResourceInde
xImpl.java:74)
at
org.fcrepo.server.resourceIndex.ResourceIndexModule.postInitModule(Re
sourceIndexModule.java:120)
... 35 more




Fedora log:

DEBUG 2011-09-14 18:11:41.036 [main] (DefaultListableBeanFactory) Finished
creating instance of bean 'org.fcrepo.server.resourceIndex.TripleGenerator'
DEBUG 2011-09-14 18:11:41.067 [main] (SessionFactoryFinder) Attempting to
connect via RMI
DEBUG 2011-09-14 18:11:42.177 [main] (SessionFactoryFinder) Failed to
connect via RMI
javax.naming.ServiceUnavailableException: null
at
com.sun.jndi.rmi.registry.RegistryContext.lookup(RegistryContext.java:101)
[na:1.6.0_17]
at
com.sun.jndi.rmi.registry.RegistryContext.lookup(RegistryContext.java:107)
[na:1.6.0_17]
at javax.naming.InitialContext.lookup(InitialContext.java:392)
[na:1.6.0_17]
at
org.mulgara.server.driver.SessionFactoryFinder.newSessionFactory(SessionFact
oryFinder.java:147) [mulgara-core-2.1.4.jar:na]
at
org.trippi.impl.mulgara.MulgaraSessionFactory.<init>(MulgaraSessionFactory.j
ava:75) [trippi-mulgara-1.5.4.jar:na]
at org.trippi.impl.mulgara.MulgaraConnector.open(MulgaraConnector.java:242)
[trippi-mulgara-1.5.4.jar:na]
at
org.trippi.impl.mulgara.MulgaraConnector.getWriter(MulgaraConnector.java:97)
[trippi-mulgara-1.5.4.jar:na]
at
org.fcrepo.server.resourceIndex.ResourceIndexImpl.<init>(ResourceIndexImpl.j
ava:74) [fcrepo-server-3.5.jar:na]
at
org.fcrepo.server.resourceIndex.ResourceIndexModule.postInitModule(ResourceI
ndexModule.java:120) [fcrepo-server-3.5.jar:na]
at org.fcrepo.server.Server.<init>(Server.java:644)
[fcrepo-server-3.5.jar:na]
at org.fcrepo.server.BasicServer.<init>(BasicServer.java:41)
[fcrepo-server-3.5.jar:na]
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
[na:1.6.0_17]
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAcces
sorImpl.java:39) [na:1.6.0_17]
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstruc
torAccessorImpl.java:27) [na:1.6.0_17]
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
[na:1.6.0_17]
at org.fcrepo.server.Server.getInstance(Server.java:1239)
[fcrepo-server-3.5.jar:na]
at org.fcrepo.server.ServerController.init(ServerController.java:403)
[fcrepo-server-3.5.jar:na]
at javax.servlet.GenericServlet.init(GenericServlet.java:212)
[servlet-api.jar:2.5.MR2]
at
org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:11
73) [catalina.jar:6.0.29]
at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:993)
[catalina.jar:6.0.29]
at
org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:
4350) [catalina.jar:6.0.29]
at
org.apache.catalina.core.StandardContext.start(StandardContext.java:4659)
[catalina.jar:6.0.29]
at
org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:7
91) [catalina.jar:6.0.29]
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:771)
[catalina.jar:6.0.29]
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:546)
[catalina.jar:6.0.29]
at
org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:637)
[catalina.jar:6.0.29]
at
org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:563
) [catalina.jar:6.0.29]
at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:498)
[catalina.jar:6.0.29]
at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1277)
[catalina.jar:6.0.29]
at
org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:321)
[catalina.jar:6.0.29]
at
org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSuppor
t.java:119) [catalina.jar:6.0.29]
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1053)
[catalina.jar:6.0.29]
at org.apache.catalina.core.StandardHost.start(StandardHost.java:785)
[catalina.jar:6.0.29]
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1045)
[catalina.jar:6.0.29]
at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:445)
[catalina.jar:6.0.29]
at org.apache.catalina.core.StandardService.start(StandardService.java:519)
[catalina.jar:6.0.29]
at org.apache.catalina.core.StandardServer.start(StandardServer.java:710)
[catalina.jar:6.0.29]
at org.apache.catalina.startup.Catalina.start(Catalina.java:581)
[catalina.jar:6.0.29]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[na:1.6.0_17]
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39
) [na:1.6.0_17]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:25) [na:1.6.0_17]
at java.lang.reflect.Method.invoke(Method.java:597) [na:1.6.0_17]
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:289)
[bootstrap.jar:6.0.29]
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:414)
[bootstrap.jar:6.0.29]
Caused by: java.rmi.ConnectException: Connection refused to host: localhost;
nested exception is:
java.net.ConnectException: Connection refused: connect
at sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:601)
[na:1.6.0_17]
at sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:198)
[na:1.6.0_17]
at sun.rmi.transport.tcp.TCPChannel.newConnection(TCPChannel.java:184)
[na:1.6.0_17]
at sun.rmi.server.UnicastRef.newCall(UnicastRef.java:322) [na:1.6.0_17]
at sun.rmi.registry.RegistryImpl_Stub.lookup(Unknown Source) [na:1.6.0_17]
at
com.sun.jndi.rmi.registry.RegistryContext.lookup(RegistryContext.java:97)
[na:1.6.0_17]
... 43 common frames omitted
Caused by: java.net.ConnectException: Connection refused: connect
at java.net.PlainSocketImpl.socketConnect(Native Method) [na:1.6.0_17]
at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
[na:1.6.0_17]
at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
[na:1.6.0_17]
at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182) [na:1.6.0_17]
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366) [na:1.6.0_17]
at java.net.Socket.connect(Socket.java:525) [na:1.6.0_17]
at java.net.Socket.connect(Socket.java:475) [na:1.6.0_17]
at java.net.Socket.<init>(Socket.java:372) [na:1.6.0_17]
at java.net.Socket.<init>(Socket.java:186) [na:1.6.0_17]
at
sun.rmi.transport.proxy.RMIDirectSocketFactory.createSocket(RMIDirectSocketF
actory.java:22) [na:1.6.0_17]
at
sun.rmi.transport.proxy.RMIMasterSocketFactory.createSocket(RMIMasterSocketF
actory.java:128) [na:1.6.0_17]
at sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:595)
[na:1.6.0_17]
... 48 common frames omitted
DEBUG 2011-09-14 18:11:42.239 [main] (SessionFactoryFinder) Attempting to
fallback to local
javax.naming.ServiceUnavailableException: null
at
com.sun.jndi.rmi.registry.RegistryContext.lookup(RegistryContext.java:101)
[na:1.6.0_17]
at
com.sun.jndi.rmi.registry.RegistryContext.lookup(RegistryContext.java:107)
[na:1.6.0_17]
at javax.naming.InitialContext.lookup(InitialContext.java:392)
[na:1.6.0_17]
at
org.mulgara.server.driver.SessionFactoryFinder.newSessionFactory(SessionFact
oryFinder.java:147) [mulgara-core-2.1.4.jar:na]
at
org.trippi.impl.mulgara.MulgaraSessionFactory.<init>(MulgaraSessionFactory.j
ava:75) [trippi-mulgara-1.5.4.jar:na]
at org.trippi.impl.mulgara.MulgaraConnector.open(MulgaraConnector.java:242)
[trippi-mulgara-1.5.4.jar:na]
at
org.trippi.impl.mulgara.MulgaraConnector.getWriter(MulgaraConnector.java:97)
[trippi-mulgara-1.5.4.jar:na]
at
org.fcrepo.server.resourceIndex.ResourceIndexImpl.<init>(ResourceIndexImpl.j
ava:74) [fcrepo-server-3.5.jar:na]
at
org.fcrepo.server.resourceIndex.ResourceIndexModule.postInitModule(ResourceI
ndexModule.java:120) [fcrepo-server-3.5.jar:na]
at org.fcrepo.server.Server.<init>(Server.java:644)
[fcrepo-server-3.5.jar:na]
at org.fcrepo.server.BasicServer.<init>(BasicServer.java:41)
[fcrepo-server-3.5.jar:na]
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
[na:1.6.0_17]
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAcces
sorImpl.java:39) [na:1.6.0_17]
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstruc
torAccessorImpl.java:27) [na:1.6.0_17]
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
[na:1.6.0_17]
at org.fcrepo.server.Server.getInstance(Server.java:1239)
[fcrepo-server-3.5.jar:na]
at org.fcrepo.server.ServerController.init(ServerController.java:403)
[fcrepo-server-3.5.jar:na]
at javax.servlet.GenericServlet.init(GenericServlet.java:212)
[servlet-api.jar:2.5.MR2]
at
org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:11
73) [catalina.jar:6.0.29]
at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:993)
[catalina.jar:6.0.29]
at
org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:
4350) [catalina.jar:6.0.29]
at
org.apache.catalina.core.StandardContext.start(StandardContext.java:4659)
[catalina.jar:6.0.29]
at
org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:7
91) [catalina.jar:6.0.29]
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:771)
[catalina.jar:6.0.29]
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:546)
[catalina.jar:6.0.29]
at
org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:637)
[catalina.jar:6.0.29]
at
org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:563
) [catalina.jar:6.0.29]
at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:498)
[catalina.jar:6.0.29]
at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1277)
[catalina.jar:6.0.29]
at
org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:321)
[catalina.jar:6.0.29]
at
org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSuppor
t.java:119) [catalina.jar:6.0.29]
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1053)
[catalina.jar:6.0.29]
at org.apache.catalina.core.StandardHost.start(StandardHost.java:785)
[catalina.jar:6.0.29]
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1045)
[catalina.jar:6.0.29]
at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:445)
[catalina.jar:6.0.29]
at org.apache.catalina.core.StandardService.start(StandardService.java:519)
[catalina.jar:6.0.29]
at org.apache.catalina.core.StandardServer.start(StandardServer.java:710)
[catalina.jar:6.0.29]
at org.apache.catalina.startup.Catalina.start(Catalina.java:581)
[catalina.jar:6.0.29]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[na:1.6.0_17]
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39
) [na:1.6.0_17]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:25) [na:1.6.0_17]
at java.lang.reflect.Method.invoke(Method.java:597) [na:1.6.0_17]
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:289)
[bootstrap.jar:6.0.29]
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:414)
[bootstrap.jar:6.0.29]
Caused by: java.rmi.ConnectException: Connection refused to host: localhost;
nested exception is:
java.net.ConnectException: Connection refused: connect
at sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:601)
[na:1.6.0_17]
at sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:198)
[na:1.6.0_17]
at sun.rmi.transport.tcp.TCPChannel.newConnection(TCPChannel.java:184)
[na:1.6.0_17]
at sun.rmi.server.UnicastRef.newCall(UnicastRef.java:322) [na:1.6.0_17]
at sun.rmi.registry.RegistryImpl_Stub.lookup(Unknown Source) [na:1.6.0_17]
at
com.sun.jndi.rmi.registry.RegistryContext.lookup(RegistryContext.java:97)
[na:1.6.0_17]
... 43 common frames omitted
Caused by: java.net.ConnectException: Connection refused: connect
at java.net.PlainSocketImpl.socketConnect(Native Method) [na:1.6.0_17]
at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
[na:1.6.0_17]
at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
[na:1.6.0_17]
at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182) [na:1.6.0_17]
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366) [na:1.6.0_17]
at java.net.Socket.connect(Socket.java:525) [na:1.6.0_17]
at java.net.Socket.connect(Socket.java:475) [na:1.6.0_17]
at java.net.Socket.<init>(Socket.java:372) [na:1.6.0_17]
at java.net.Socket.<init>(Socket.java:186) [na:1.6.0_17]
at
sun.rmi.transport.proxy.RMIDirectSocketFactory.createSocket(RMIDirectSocketF
actory.java:22) [na:1.6.0_17]
at
sun.rmi.transport.proxy.RMIMasterSocketFactory.createSocket(RMIMasterSocketF
actory.java:128) [na:1.6.0_17]
at sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:595)
[na:1.6.0_17]
... 48 common frames omitted

[Janna Wemekamp]

Steve,

I have the same result with a just installed FC 3.5 with RI enabled;
neither FeSL nor XACML enabled. I rebuilt the RI index before changing
the logging level from the defaults.

Also, $CATALINA_HOME/bin/shutdown.sh doesn't succeed; I have to use kill
-15 to remove the process.


Janna Wemekamp

> ------------------------------------------------------------------------------
> BlackBerry&reg; DevCon Americas, Oct. 18-20, San Francisco, CA
> Learn about the latest advances in developing for the
> BlackBerry&reg; mobile platform with sessions, labs& more.
> See new tools and technologies. Register for BlackBerry&reg; DevCon today!
> http://p.sf.net/sfu/rim-devcon-copy1
> _______________________________________________
> Fedora-commons-users mailing list
> Fedora-com...@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/fedora-commons-users

[Steve Bayliss]

Thanks Janna!

I have reported this as https://jira.duraspace.org/browse/FCREPO-998

The first thing I tried when I saw this was to rebuild the RI (which
was successful) but it still failed to start afterwards.

I also got the shutdown problem - it wouldn't shutdown cleanly whilst
the RI module was failing to start.

Steve