JackRabbit seemingly jacked up is actually something much simpler!

[Anthony Shortland]

Lest you someday fall into this trap yourself, read on; or, maybe you've found this by searching the group!

Even though I was running as ctier:

[anthony@centos54 ~]$ ps -fu ctier
UID        PID  PPID  C STIME TTY          TIME CMD
ctier     4760     1 18 16:51 ?        00:00:36 /usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/bin/java -XX:MaxPermSize=256m -Xmx1024m -Xms256m -Djobcenter.conf

... and the file permissions were all cool I found that JackRabbit had got itself into a completely unusable state! (I'm running 3.4.9 on 64-bit CentOS 5.4 and OpenJDK 1.6).

Switching Workbench to DEBUG logging:

[anthony@centos54 classes]$ pwd
/opt/ctier/pkgs/jetty-6.1.14/webapps/itnav/WEB-INF/classes
[anthony@centos54 classes]$ diff log4j.properties log4j.properties.orig 
5,6c5
< #log4j.rootCategory=WARN, stdout, R
< log4j.rootCategory=DEBUG, stdout, R
---
> log4j.rootCategory=WARN, stdout, R

I saw the following as I tried to login to Workbench:

DEBUG : btpool0-5 << enterCS: Thread R/W: 1/0 :: Model R/W: 1/0 (thread: btpool0-5)
DEBUG : template query string set to:
SELECT ?revUri, ?versHistUri, ?revAuthor, ?revComment, ?revDate, ?headRevUri, ?revType, ?revTag, ?revSerial
WHERE
( <http://www.opendepo.org/ct/Development/Objects#obj_1d>, <http://www.opendepo.org/DepOnt/System#version-history>, ?versHistUri ),
( ?versHistUri, <http://www.opendepo.org/DepOnt/System#revision>, ?revUri ),
( ?versHistUri, <http://www.opendepo.org/DepOnt/System#head-revision>, ?headRevUri ),
( ?revUri, <http://www.opendepo.org/DepOnt/System#revision-author>, ?revAuthor ),
( ?revUri, <http://www.opendepo.org/DepOnt/System#revision-comment>, ?revComment ),
( ?revUri, <http://www.opendepo.org/DepOnt/System#revision-date>, ?revDate ),
( ?revUri, <http://www.opendepo.org/DepOnt/System#revision-type>, ?revType ),
( ?revUri, <http://www.opendepo.org/DepOnt/System#revision-serial>, ?revSerial )
USING
d FOR <http://www.opendepo.org/DepOnt/System#>, 
rdf FOR <http://www.w3.org/1999/02/22-rdf-syntax-ns#>, 
rdfs FOR <http://www.w3.org/2000/01/rdf-schema#>, 
a FOR <http://protege.stanford.edu/system#>
DEBUG : Query parse time: 3
DEBUG : Query parse and build time: 1
DEBUG : btpool0-5 >> leaveCS: Thread R/W: 1/0 :: Model R/W: 1/0 (thread: btpool0-5)
DEBUG : btpool0-5 << leaveCS: Thread R/W: 0/0 :: Model R/W: 0/0 (thread: btpool0-5)
DEBUG : SetCtx: XFORM to null
DEBUG : context now: {Context: [Project: Development], [Type: rpm], [Object: name=sampleWwwRpm-1.0-1.noarch.rpm, maprefUri=http://www.opendepo.org/ct/Development/Objects#obj_1d] }
DEBUG : BeanUtils.copyProperties(com.networkgps.itnav.report.ProjectSummaryList@77cb95b3, {multipartRequestHandler=null, includeTypes=true, collectionId=null, subject=null, servletWrapper=org.apache.struts.action.ActionServletWrapper@56d15836, restageAllSubmodules=false, includeViewTemplates=true, includeAllModuleJars=false, includeTemplates=true, uploadFile=null, author=nobody, resourceId=null, organization=null, keywordName=null, description=null, name=null, depot=null, sessionLocale=null, mapCollectionUri=null, dispatch=null, createDate=null, viewCollectionUri=null, reqId=null, keywordValue=null, commanderParFile=null, dispatchForward=null, contents=null, importName=null, localeDisplay=English (United States), includeTransforms=true, class=class com.networkgps.itnav.projects.struts.ProjectForm, includeViews=true, project=null, importOption=new, archiveId=null, archiveComment=null, copyContent=exact, context={Context: [Project: Development], [Type: rpm], [Object: name=sampleWwwRpm-1.0-1.noarch.rpm, maprefUri=http://www.opendepo.org/ct/Development/Objects#obj_1d] }, entityClass=null, mutable=true, docCollectionUri=null, includeObjects=true, remoteAddr=10.0.1.2})
DEBUG : build time: 0ms
DEBUG : Checking index at path: /opt/ctier/jackrabbit/repository/workbench/Development/reports
2009-11-08 16:53:14.221:/itnav:WARN:  action: *** ACTION EXCEPTION: 
java.io.IOException: Permission denied
        at java.io.UnixFileSystem.createFileExclusively(Native Method)
        at java.io.File.createNewFile(File.java:900)
        at org.apache.lucene.store.FSDirectory$1.obtain(FSDirectory.java:307)
        at org.apache.lucene.store.Lock.obtain(Lock.java:53)
        at org.apache.lucene.store.Lock$With.run(Lock.java:108)
        at org.apache.lucene.index.IndexReader.open(IndexReader.java:111)
        at org.apache.lucene.index.IndexReader.open(IndexReader.java:95)
        at org.apache.lucene.search.IndexSearcher.<init>(IndexSearcher.java:38)
        at org.opendepo.services.correlation.IndexService.list(IndexService.java:169)
        at com.networkgps.itnav.report.ProjectSummaryList.go(ProjectSummaryList.java:65)
        at com.networkgps.itnav.context.ContextProcessBeanBase.execute(ContextProcessBeanBase.java:101)
        at org.apache.commons.scaffold.util.ProcessBeanBase.execute(Unknown Source)
        at org.apache.struts.scaffold.ProcessAction.executeLogic(Unknown Source)
        at com.networkgps.itnav.context.BaseContextProcessAction.executeLogic(BaseContextProcessAction.java:283)
        at org.apache.struts.scaffold.BaseHelperAction.executeLogic(Unknown Source)
        at org.apache.struts.scaffold.BaseAction.execute(Unknown Source)
        at com.networkgps.itnav.context.BaseContextProcessAction.execute(BaseContextProcessAction.java:229)
        at com.networkgps.itnav.context.BaseContextProcessAction.execute(BaseContextProcessAction.java:267)
        at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:484)
        at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:274)
        at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482)
        at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:507)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:363)
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
        at org.mortbay.jetty.Server.handle(Server.java:324)
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
        at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)
        at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
        at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:451)
java.io.IOException: Permission denied
        at java.io.UnixFileSystem.createFileExclusively(Native Method)
        at java.io.File.createNewFile(File.java:900)
        at org.apache.lucene.store.FSDirectory$1.obtain(FSDirectory.java:307)
        at org.apache.lucene.store.Lock.obtain(Lock.java:53)
        at org.apache.lucene.store.Lock$With.run(Lock.java:108)
        at org.apache.lucene.index.IndexReader.open(IndexReader.java:111)
        at org.apache.lucene.index.IndexReader.open(IndexReader.java:95)
        at org.apache.lucene.search.IndexSearcher.<init>(IndexSearcher.java:38)
        at org.opendepo.services.correlation.IndexService.list(IndexService.java:169)
        at com.networkgps.itnav.report.ProjectSummaryList.go(ProjectSummaryList.java:65)
        at com.networkgps.itnav.context.ContextProcessBeanBase.execute(ContextProcessBeanBase.java:101)
        at org.apache.commons.scaffold.util.ProcessBeanBase.execute(Unknown Source)
        at org.apache.struts.scaffold.ProcessAction.executeLogic(Unknown Source)
        at com.networkgps.itnav.context.BaseContextProcessAction.executeLogic(BaseContextProcessAction.java:283)
        at org.apache.struts.scaffold.BaseHelperAction.executeLogic(Unknown Source)
        at org.apache.struts.scaffold.BaseAction.execute(Unknown Source)
        at com.networkgps.itnav.context.BaseContextProcessAction.execute(BaseContextProcessAction.java:229)
        at com.networkgps.itnav.context.BaseContextProcessAction.execute(BaseContextProcessAction.java:267)
        at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:484)
        at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:274)
        at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482)
        at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:507)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:363)
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
        at org.mortbay.jetty.Server.handle(Server.java:324)
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
        at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)
        at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
        at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:451)
DEBUG : passthru or valid: returned forward: ForwardConfig[name=failure,path=/pages/exception/View.jsp,redirect=false,contextRelative=false], checking cookie. isErrors? true, time: 95ms
DEBUG : processForwardConfig(ForwardConfig[name=failure,path=/pages/exception/View.jsp,redirect=false,contextRelative=false])
DEBUG : insert page='/pages/tiles/layouts/FormBase.jsp'.
DEBUG : insert page='/pages/tiles/common/header.jsp'.
DEBUG : keyString css.taglist returned null value
DEBUG : insert page='/pages/tiles/common/logonWidget.jsp'.
INFO  : Initializing, config='org.apache.struts.taglib.logic.LocalStrings', returnNull=true
DEBUG : insert page='/mbuildernull'.
DEBUG : insert page='null'.
DEBUG : insert page='/pages/tiles/common/titleBar.jsp'.
DEBUG : insert page='/pages/tiles/exception/View.jsp'.
INFO  : Initializing, config='org.apache.struts.taglib.html.LocalStrings', returnNull=true
DEBUG : getMessage(en_US,errors.header)
DEBUG : getMessage(en_US,errors.footer)
DEBUG : getMessage(en_US,errors.prefix)
DEBUG : getMessage(en_US,errors.suffix)
DEBUG : getMessage(en_US,errors.header)
DEBUG : getMessage(en_US,error.general)
DEBUG : getMessage(en_US,error.detail)
DEBUG : getMessage(en_US,errors.footer)
DEBUG : insert page='/pages/tiles/footer.jsp'.
DEBUG : Get module name for path /module/go.do
DEBUG : Module name found: default
DEBUG : Processing a 'GET' for path '/module/go'
DEBUG :  Looking for Action instance for class org.apache.struts.actions.SwitchAction
INFO  : Initializing, config='org.apache.struts.actions.LocalStrings', returnNull=true
DEBUG : processForwardConfig(ForwardConfig[name=null,path=/assets/images/icon-small-user-admin.png,redirect=false,contextRelative=false])

Checking the file system I saw:

[anthony@centos54 classes]$ ls -la  /opt/ctier/jackrabbit/repository/workbench/Development/reports
total 76
drwxrwxr-x 2 ctier ctier  4096 Nov  7 21:36 .
drwxrwxr-x 3 ctier ctier  4096 Nov  5 17:10 ..
-rw-rw-r-- 1 ctier ctier 31033 Nov  7 17:06 _5k.cfs
-rw-rw-r-- 1 ctier ctier  1109 Nov  7 21:36 _5o.cfs
-rw-rw-r-- 1 ctier ctier     4 Nov  7 21:36 deletable
-rw-rw-r-- 1 ctier ctier    36 Nov  7 21:36 segments

Wasn't sure what I was looking at, but seemed reasonable enough.

To demonstrate how fundamental this was: just attempting to access the JackRabbit repository from my web browser (http://centos54:8080/jackrabbit/repository/workbench) I got:

HTTP ERROR: 500

Permission denied
RequestURI=/jackrabbit/repository/workbench

Caused by:

java.io.IOException: Permission denied
at java.io.UnixFileSystem.createFileExclusively(Native Method)
at java.io.File.checkAndCreate(File.java:1716)
at java.io.File.createTempFile(File.java:1804)
at java.io.File.createTempFile(File.java:1840)
at org.apache.jackrabbit.server.io.ExportContextImpl.
(ExportContextImpl.java:66)
at org.apache.jackrabbit.webdav.simple.DavResourceImpl.getExportContext(DavResourceImpl.java:991)
at org.apache.jackrabbit.webdav.simple.DavResourceImpl.spool(DavResourceImpl.java:331)
at org.apache.jackrabbit.webdav.server.AbstractWebdavServlet.spoolResource(AbstractWebdavServlet.java:422)
at org.apache.jackrabbit.webdav.server.AbstractWebdavServlet.doGet(AbstractWebdavServlet.java:388)
at org.apache.jackrabbit.webdav.server.AbstractWebdavServlet.execute(AbstractWebdavServlet.java:229)
at org.apache.jackrabbit.webdav.server.AbstractWebdavServlet.service(AbstractWebdavServlet.java:196)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:363)
at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
at org.mortbay.jetty.Server.handle(Server.java:324)
at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864)
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207)
at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)
at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)

at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:451)

08.11.2009 17:00:15 *INFO * AbstractConfig: Configuration of BootstrapConfig (AbstractConfig.java, line 101)
08.11.2009 17:00:15 *INFO * AbstractConfig: ---------------------------------------------- (AbstractConfig.java, line 102)
08.11.2009 17:00:15 *INFO * AbstractConfig:   valid: true (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   rmiConfig: org.apache.jackrabbit.j2ee.RMIConfig@2369bc4 (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   repositoryConfig: /opt/ctier/pkgs/jetty-6.1.14/webapps/jackrabbit/WEB-INF/repository.xml (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   class: class org.apache.jackrabbit.j2ee.BootstrapConfig (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   repositoryHome: /opt/ctier/jackrabbit/webdav (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   repositoryName: jackrabbit.repository (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   jndiConfig: org.apache.jackrabbit.j2ee.JNDIConfig@4f2c61fe (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig: ---------------------------------------------- (AbstractConfig.java, line 108)
08.11.2009 17:00:15 *INFO * AbstractConfig: Configuration of JNDIConfig (AbstractConfig.java, line 101)
08.11.2009 17:00:15 *INFO * AbstractConfig: ---------------------------------------------- (AbstractConfig.java, line 102)
08.11.2009 17:00:15 *INFO * AbstractConfig:   valid: true (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   jndiName: jackrabbit.repository (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   jndiEnabled: true (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   class: class org.apache.jackrabbit.j2ee.JNDIConfig (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   jndiEnv: {java.naming.provider.url=http://www.apache.org/jackrabbit, java.naming.factory.initial=org.apache.jackrabbit.core.jndi.provider.DummyInitialContextFactory} (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig: ---------------------------------------------- (AbstractConfig.java, line 108)
08.11.2009 17:00:15 *INFO * AbstractConfig: Configuration of RMIConfig (AbstractConfig.java, line 101)
08.11.2009 17:00:15 *INFO * AbstractConfig: ---------------------------------------------- (AbstractConfig.java, line 102)
08.11.2009 17:00:15 *INFO * AbstractConfig:   valid: true (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   rmiName: jackrabbit.repository (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   class: class org.apache.jackrabbit.j2ee.RMIConfig (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   rmiUri: //localhost:1099/jackrabbit.repository (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   rmiPort: 1099 (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   rmiEnabled: true (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig:   rmiHost: localhost (AbstractConfig.java, line 106)
08.11.2009 17:00:15 *INFO * AbstractConfig: ---------------------------------------------- (AbstractConfig.java, line 108)
08.11.2009 17:00:15 *INFO * RepositoryAccessServlet: Acquired repository via JNDI. (RepositoryAccessServlet.java, line 207)
08.11.2009 17:00:16 *INFO * SimpleSecurityManager: init: using Repository LoginModule configuration for Jackrabbit (SimpleSecurityManager.java, line 116)
08.11.2009 17:00:16 *INFO * RepositoryImpl: SecurityManager = class org.apache.jackrabbit.core.security.simple.SimpleSecurityManager (RepositoryImpl.java, line 435)
2009-11-08 17:00:17.280::WARN:  /jackrabbit/repository/workbench/: java.io.IOException: Permission denied

Making this look like some weird JackRabbit problem!

Reviewing the Jetty log as a whole I found the following as a the first error message in the file:

[0] spring.GrailsWebApplicationContext Bean factory for application context [org.codehaus.groovy.grails.commons.spring.GrailsWebApplicationContext@5b2bc407]: or
g.springframework.beans.factory.support.DefaultListableBeanFactory@2f995c9a
[2509] store.DiskStore org.hibernate.cache.UpdateTimestampsCacheCache: Could not create disk store. Initial cause was /tmp/org.hibernate.cache.UpdateTimestampsC
ache.data (Permission denied)
java.io.FileNotFoundException: /tmp/org.hibernate.cache.UpdateTimestampsCache.data (Permission denied)
        at java.io.RandomAccessFile.open(Native Method)
        at java.io.RandomAccessFile.<init>(RandomAccessFile.java:233)
        at net.sf.ehcache.store.DiskStore.initialiseFiles(DiskStore.java:208)
        at net.sf.ehcache.store.DiskStore.<init>(DiskStore.java:153)
        at net.sf.ehcache.Cache.createDiskStore(Cache.java:526)

Checking /tmp I found:

[root@centos54 ~]# ls -ld /tmp
drwxrwsr-x 8 root root 20480 Nov  8 17:29 /tmp

Grrr ... collateral damage! Some RPM testing I'd been doing had simply screwed up the permissions on /tmp!

Fixed the permissions as follows:

[root@centos54 ~]# chmod 777 /tmp
[root@centos54 ~]# chmod +t /tmp
[root@centos54 ~]# ls -ld /tmp
drwxrwxrwt 8 root root 20480 Nov  8 17:32 /tmp

Restarted ctier:

[root@centos54 ~]# service ctier restart
Stopping Jetty: OK
Starting Jetty: STARTED Jetty Sun Nov  8 17:35:11 PST 2009
2009-11-08 17:35:12.564::INFO:  Logging to STDERR via org.mortbay.log.StdErrLog
2009-11-08 17:35:12.946::INFO:  Redirecting stderr/stdout to /opt/ctier/pkgs/jetty-6.1.14/logs/2009_11_09.stderrout.log

All fixed: Yay! (Sometimes those Java stack traces are too arcane to be of any use at all ... especially without context).

Anthony.

On Nov 8, 2009, at 11:44 AM, Alex Honor wrote:

And the process is running as ctier too?

On Nov 8, 2009, at 11:40 AM, Anthony Shortland wrote:

Clean as a whistle (ctier rwx/rw) across the whole hierarchy ... can you narrow the stack trace to an area of the code? Is it Workbench accessing the WebDAV? 

On Nov 8, 2009, at 7:43 AM, Alex Honor wrote:

Check the perms under CTIER_ROOT/jackrabbit

On Nov 8, 2009, at 2:43 AM, Anthony Shortland wrote:

... reports:

Error

<icon-warn.png> Sorry, but the action could not be performed.

ERROR: java.io.IOException: Permission denied DETAILS: Permission denied

... and I get this from in the Jetty log: 

java.io.IOException: Permission denied
        at java.io.UnixFileSystem.createFileExclusively(Native Method)
        at java.io.File.createNewFile(File.java:900)
        at org.apache.lucene.store.FSDirectory$1.obtain(FSDirectory.java:307)
        at org.apache.lucene.store.Lock.obtain(Lock.java:53)
        at org.apache.lucene.store.Lock$With.run(Lock.java:108)
        at org.apache.lucene.index.IndexReader.open(IndexReader.java:111)
        at org.apache.lucene.index.IndexReader.open(IndexReader.java:95)
        at org.apache.lucene.search.IndexSearcher.<init>(IndexSearcher.java:38)
        at org.opendepo.services.correlation.IndexService.list(IndexService.java:169)
        at com.networkgps.itnav.report.ProjectSummaryList.go(ProjectSummaryList.java:65)
        at com.networkgps.itnav.context.ContextProcessBeanBase.execute(ContextProcessBeanBase.java:101)
        at org.apache.commons.scaffold.util.ProcessBeanBase.execute(Unknown Source)
        at org.apache.struts.scaffold.ProcessAction.executeLogic(Unknown Source)
        at com.networkgps.itnav.context.BaseContextProcessAction.executeLogic(BaseContextProcessAction.java:283)
        at org.apache.struts.scaffold.BaseHelperAction.executeLogic(Unknown Source)
        at org.apache.struts.scaffold.BaseAction.execute(Unknown Source)
        at com.networkgps.itnav.context.BaseContextProcessAction.execute(BaseContextProcessAction.java:229)
        at com.networkgps.itnav.context.BaseContextProcessAction.execute(BaseContextProcessAction.java:267)
        at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:484)
        at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:274)
        at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482)
        at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:507)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:363)
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
        at org.mortbay.jetty.Server.handle(Server.java:324)
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
        at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)
        at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
        at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:451)

No indication of the specific details of the permissions problem. Restarting the server doesn't help.

Here's another example:

ERROR : Colony request: exception caught during execute: Failed storing object: Error generating Nodes properties: java.io.IOException: Permission denied
org.apache.commons.scaffold.lang.ResourceException: Failed storing object: Error generating Nodes properties: java.io.IOException: Permission denied
        at com.networkgps.itnav.instances.ColonyStore.go(ColonyStore.java:153)
        at com.networkgps.itnav.context.ContextProcessBeanBase.execute(ContextProcessBeanBase.java:101)
        at com.networkgps.itnav.process.ForkedProcessBeanBase.execute(ForkedProcessBeanBase.java:126)
        at org.apache.commons.scaffold.util.ProcessBeanBase.execute(Unknown Source)
        at org.apache.struts.scaffold.ProcessAction.executeLogic(Unknown Source)
        at com.networkgps.itnav.context.BaseContextProcessAction.executeLogic(BaseContextProcessAction.java:283)
        at org.apache.struts.scaffold.BaseHelperAction.executeLogic(Unknown Source)
        at org.apache.struts.scaffold.BaseAction.execute(Unknown Source)
        at com.networkgps.itnav.context.BaseContextProcessAction.execute(BaseContextProcessAction.java:229)
        at com.networkgps.itnav.context.BaseContextProcessAction.execute(BaseContextProcessAction.java:267)
        at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:484)
        at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:274)
        at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482)
        at org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:525)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:363)
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
        at org.mortbay.jetty.Server.handle(Server.java:324)
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
        at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:879)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:741)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:213)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)
        at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
        at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:451)

Not even rebooting the VM cleans up the problem!

Anthony.

[Alex-SF]

Nice work! Is While the permissions of /tmp were borked, maybe this is
another example of why it might be a good to manage the TMP
configuration of Jetty and place it under CTIER_ROOT.

> (ContextHandler.java:766)
>         at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:
> 417)
>         at org.mortbay.jetty.handler.ContextHandlerCollection.handle
> (ContextHandlerCollection.java:230)
>         at org.mortbay.jetty.handler.HandlerCollection.handle
> (HandlerCollection.java:114)
>         at org.mortbay.jetty.handler.HandlerWrapper.handle
> (HandlerWrapper.java:152)
>         at org.mortbay.jetty.Server.handle(Server.java:324)
>         at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:
> 534)
>         at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete
> (HttpConnection.java:864)
>         at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533)
>         at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207)
>         at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)
>         at org.mortbay.io.nio.SelectChannelEndPoint.run
> (SelectChannelEndPoint.java:409)
>         at org.mortbay.thread.BoundedThreadPool$PoolThread.run

> >>>> (BaseContextProcessAction.java:283)
> >>>>         at  
> >>>> org.apache.struts.scaffold.BaseHelperAction.executeLogic(Unknown  
> >>>> Source)
> >>>>         at org.apache.struts.scaffold.BaseAction.execute(Unknown  
> >>>> Source)
> >>>>         at  
> >>>> com.networkgps.itnav.context.BaseContextProcessAction.execute
> >>>> (BaseContextProcessAction.java:229)
> >>>>         at  
> >>>> com.networkgps.itnav.context.BaseContextProcessAction.execute
> >>>> (BaseContextProcessAction.java:267)
> >>>>         at  
> >>>> org.apache.struts.action.RequestProcessor.processActionPerform
> >>>> (RequestProcessor.java:484)
> >>>>         at org.apache.struts.action.RequestProcessor.process
> >>>> (RequestProcessor.java:274)
> >>>>         at org.apache.struts.action.ActionServlet.process
> >>>> (ActionServlet.java:1482)

> >>>>         at org.apache.struts.action.ActionServlet.doPost
> >>>> (ActionServlet.java:525)
> >>>>         at javax.servlet.http.HttpServlet.service
> >>>> (HttpServlet.java:727)
> >>>>         at javax.servlet.http.HttpServlet.service
> >>>> (HttpServlet.java:820)
> >>>>         at org.mortbay.jetty.servlet.ServletHolder.handle
> >>>> (ServletHolder.java:502)
> >>>>         at org.mortbay.jetty.servlet.ServletHandler.handle
> >>>> (ServletHandler.java:363)
> >>>>         at org.mortbay.jetty.security.SecurityHandler.handle
> >>>> (SecurityHandler.java:216)
> >>>>         at org.mortbay.jetty.servlet.SessionHandler.handle
> >>>> (SessionHandler.java:181)
> >>>>         at org.mortbay.jetty.handler.ContextHandler.handle
> >>>> (ContextHandler.java:766)
> >>>>         at org.mortbay.jetty.webapp.WebAppContext.handle
> >>>> (WebAppContext.java:417)
> >>>>         at  
> >>>> org.mortbay.jetty.handler.ContextHandlerCollection.handle
> >>>> (ContextHandlerCollection.java:230)
> >>>>         at org.mortbay.jetty.handler.HandlerCollection.handle
> >>>> (HandlerCollection.java:114)
> >>>>         at org.mortbay.jetty.handler.HandlerWrapper.handle

> >>>> (HandlerWrapper.java:152)
> >>>>         at org.mortbay.jetty.Server.handle(Server.java:324)
> >>>>         at org.mortbay.jetty.HttpConnection.handleRequest
> >>>> (HttpConnection.java:534)

> >>>>         at org.mortbay.jetty.HttpConnection$RequestHandler.content

[Anthony Shortland]

I was thinking exactly the same thing. That and that we should always
be careful to log context wherever possible through custom error
handlers in our code.

>> at org.apache.lucene.index.IndexReader.open
>> (IndexReader.java:
>> 111)
>> at org.apache.lucene.index.IndexReader.open
>> (IndexReader.java:
>> 95)
>> at org.apache.lucene.search.IndexSearcher.<init>
>> (IndexSearcher.java:38)
>> at org.opendepo.services.correlation.IndexService.list
>> (IndexService.java:169)
>> at com.networkgps.itnav.report.ProjectSummaryList.go
>> (ProjectSummaryList.java:65)
>> at
>> com.networkgps.itnav.context.ContextProcessBeanBase.execute
>> (ContextProcessBeanBase.java:101)

>> at org.apache.lucene.index.IndexReader.open
>> (IndexReader.java:
>> 111)
>> at org.apache.lucene.index.IndexReader.open
>> (IndexReader.java:
>> 95)
>> at org.apache.lucene.search.IndexSearcher.<init>
>> (IndexSearcher.java:38)
>> at org.opendepo.services.correlation.IndexService.list
>> (IndexService.java:169)
>> at com.networkgps.itnav.report.ProjectSummaryList.go
>> (ProjectSummaryList.java:65)
>> at
>> com.networkgps.itnav.context.ContextProcessBeanBase.execute
>> (ContextProcessBeanBase.java:101)

>> (HttpConnection.java:864)
>> at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:
>> 533)

>> at org.mortbay.jetty.HttpParser.parseAvailable
>> (HttpParser.java:207)
>> at org.mortbay.jetty.HttpConnection.handle
>> (HttpConnection.java:403)
>> at org.mortbay.io.nio.SelectChannelEndPoint.run
>> (SelectChannelEndPoint.java:409)
>> at org.mortbay.thread.BoundedThreadPool$PoolThread.run
>> (BoundedThreadPool.java:451)
>>