Page 1 of 1

Recursive Permission Changes results in Error communicating with server

PostPosted:Mon Feb 13, 2017 12:16 pm
by cgeek
Hi,

I've got OpenKM 6.3.0 installed on an AWS Instance running on Ubuntu 14.04.5 LTS. There is approximately 200GB of data stored in the system. I've tested and confirmed the issue in Chrome (Mac OS Sierra) and Firefox (Windows 10 64 bit).

When I attempt to do a recursive permission change on a folder with a large number of files and subdirectories inside it, the web interface seems to time out while the process on the server continues to run to completion and successfully changes the permissions. I've tested it a number of times and at approximately the five minute mark I get a pop up with one of the messages below (the first if adding permissions and the second if removing them).
Code: Select all
Error communicating with server (AddUser)
Code: Select all
Error communicating with server (RevokeUser)
I've monitored the logs and system resource usage while the process is running and found no related errors. The process seems to complete successfully (see below).
Code: Select all
2017-02-13 21:44:50,329 [ajp-bio-127.0.0.1-8009-exec-2293] INFO  com.openkm.dao.NodeBaseDAO- grantUserPermissions.Time: 00:10:59.851
I've already changed the system.execution.timeout property to 20 (well beyond the time used by the task at hand) with no effect.

The only errors in the log seem to be related to OCR or text extraction (see below) so I'm fairly sure those aren't related.
Code: Select all
2017-02-13 21:40:00,096 [Thread-10188] INFO  com.openkm.extractor.TextExtractorWorker- processSerial.Working on {docUuid=REDACTED, docPath=/okm:root/REDACTED.pdf, docVerUuid=REDACTED, date=Thu Jul 03 05:23:29 EST 2014}
2017-02-13 21:40:01,510 [Thread-10188] WARN  org.hibernate.util.JDBCExceptionReporter- SQL Error: 1366, SQLState: HY000
2017-02-13 21:40:01,510 [Thread-10188] ERROR org.hibernate.util.JDBCExceptionReporter- Incorrect string value: '\xEF\x81\xA00.5...' for column 'NDC_TEXT' at row 1
2017-02-13 21:40:01,512 [Thread-10188] WARN  com.openkm.extractor.TextExtractorWorker- could not update: [com.openkm.dao.bean.NodeDocument#001a0047-f0d7-45a4-a23d-ac3d2b180e30]
com.openkm.core.DatabaseException: could not update: [com.openkm.dao.bean.NodeDocument#REDACTED]
	at com.openkm.dao.NodeDocumentDAO.textExtractorHelper(NodeDocumentDAO.java:1384)
	at com.openkm.extractor.TextExtractorWorker.processSerial(TextExtractorWorker.java:164)
	at com.openkm.extractor.TextExtractorWorker.processQueue(TextExtractorWorker.java:149)
	at com.openkm.extractor.TextExtractorWorker.run(TextExtractorWorker.java:100)
	at sun.reflect.GeneratedMethodAccessor197.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at bsh.Reflect.invokeMethod(Reflect.java:134)
	at bsh.Reflect.invokeObjectMethod(Reflect.java:80)
	at bsh.BSHPrimarySuffix.doName(BSHPrimarySuffix.java:176)
	at bsh.BSHPrimarySuffix.doSuffix(BSHPrimarySuffix.java:120)
	at bsh.BSHPrimaryExpression.eval(BSHPrimaryExpression.java:80)
	at bsh.BSHPrimaryExpression.eval(BSHPrimaryExpression.java:47)
	at bsh.Interpreter.eval(Interpreter.java:645)
	at bsh.Interpreter.eval(Interpreter.java:739)
	at bsh.Interpreter.eval(Interpreter.java:728)
	at com.openkm.util.ExecutionUtils.runScript(ExecutionUtils.java:112)
	at com.openkm.core.Cron$RunnerBsh.run(Cron.java:103)
	at java.lang.Thread.run(Thread.java:662)
Caused by: org.hibernate.exception.GenericJDBCException: could not update: [com.openkm.dao.bean.NodeDocument#REDACTED]
	at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140)
	at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128)
	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2613)
	at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2495)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2822)
	at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:113)
	at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:273)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:265)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:185)
	at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
	at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:51)
	at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1216)
	at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:383)
	at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:133)
	at com.openkm.dao.HibernateUtil.commit(HibernateUtil.java:299)
	at com.openkm.dao.NodeDocumentDAO.textExtractorHelper(NodeDocumentDAO.java:1379)
	... 18 more
Caused by: java.sql.SQLException: Incorrect string value: '\xEF\x81\xA00.5...' for column 'NDC_TEXT' at row 1
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1075)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3562)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3494)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1960)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2114)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2696)
	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2105)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2398)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2316)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2301)
	at org.apache.tomcat.dbcp.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
	at org.apache.tomcat.dbcp.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2595)
	... 31 more
Does anyone have any insight into this issue? I've found numerous accounts of similar error messages but for different methods and with different symptoms so they're not much help.

Any assistance you can offer would be much appreciated.

Cheers,
Jack

Re: Recursive Permission Changes results in Error communicating with server

PostPosted:Tue Feb 14, 2017 3:04 pm
by jllort
How many nodes are you changing, more or less ? The problem in community version is that the change in all the cases it does into a single database commit, when you have a lot of nodes affected is a problem. Probably the error you getting from the UI has not direct relation with this issue. You are applying the change from root node ? give us some idea about what are you doing.

Re: Recursive Permission Changes results in Error communicating with server

PostPosted:Thu Feb 16, 2017 12:56 am
by cgeek
jllort wrote:How many nodes are you changing, more or less ? The problem in community version is that the change in all the cases it does into a single database commit, when you have a lot of nodes affected is a problem. Probably the error you getting from the UI has not direct relation with this issue. You are applying the change from root node ? give us some idea about what are you doing.
Hi jllort,

Thanks for your help.

There are many thousands of folders and many thousands more files in this OpenKM installation. I'm not trying to do a recursive permissions change at the root, but rather on subfolder. I estimate this subfolder has 1-2 thousand folders with at least double the number of files. I haven't found a way to count down through subfolders though so it is only an estimate.

My investigation indicates that the permissions change does finish successfully it's just the that the web interface times out at about five minutes, is that correct?

Cheers,
Jack

Re: Recursive Permission Changes results in Error communicating with server

PostPosted:Fri Feb 17, 2017 11:27 am
by jllort
Is correct, because the UI has called and RPC ( remote process call ) to a servlet what started making changes, and you are getting a timeout of this RPC call what is still binding looking for the servlet finishes. That's why in professional version we introduced the background process while changing more than 100 nodes, to prevent this kind of issue. In future we will propagate this change to community version.