Error running fts processQueue on Ubuntu

Support
#1

Hi,

I’m having an issue in which I get these errors every 30 s if I enable the fts process queue task. This has worked but now shows this problem which I cannot get to solve.

This only happens in production, in my test environment (Windows) it seems to work fine.
I have removed all data in my database earlier on and also reduced the set of entities that is being searched but the error still pops up.
Any help appreciated.

The error:

web_1       | 18:30:58.876 WARN  c.h.fts.core.sys.LuceneIndexer - Unsupported file extension: png
web_1       | 18:30:58.877 WARN  c.h.fts.core.sys.LuceneIndexer - Unsupported file extension: png
web_1       | 18:30:58.878 WARN  c.h.fts.core.sys.LuceneIndexer - Unsupported file extension: png
web_1       | 18:30:58.879 WARN  c.h.fts.core.sys.LuceneIndexer - Unsupported file extension: jpg
web_1       | 18:30:58.880 WARN  c.h.fts.core.sys.LuceneIndexer - Unsupported file extension: png
web_1       | 18:30:58.880 WARN  c.h.fts.core.sys.LuceneIndexer - Unsupported file extension: png
web_1       | 18:31:01.202 ERROR com.haulmont.fts.core.jmx.FtsManager - Error
web_1       | javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.6.2.cuba12): org.eclipse.persistence.exceptions.DatabaseException
web_1       | Internal Exception: org.postgresql.util.PSQLException: Can't infer the SQL type to use for an instance of com.haulmont.cuba.core.sys.persistence.PostgresUUID. Use setObject() with an explicit Types value to specify the type to use.
web_1       | Error Code: 0
web_1       | Call: delete from SYS_FTS_QUEUE where ID in (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
web_1       |   bind => [2b89d324-1228-a691-ccd6-9b59f7b31fda, b15981e5-a02a-4188-4a43-091d805a5958, be438a9f-c13f-a646-7f04-a8958fdfe488, b9566fa7-90de-9ba2-0c64-2b4a659dd9f6, 4ec9bd28-248b-f7e6-65f9-c28fd6cd9aef, 704b2ef2-55c0-5b70-dd92-236ed234adc9, 72acf73f-fd38-d92f-ae69-4e64879c7d17, 88871378-789d-7abe-e3a6-1bea1e61d1f6, 588453ea-343e-b297-ffe9-c013e2519470, ac35cbb4-a02b-c7d7-9922-2c82d81524bf]
web_1       | Query: DataModifyQuery(sql="delete from SYS_FTS_QUEUE where ID in (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)")
web_1       |   at org.eclipse.persistence.internal.jpa.QueryImpl.executeUpdate(QueryImpl.java:308) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at com.haulmont.cuba.core.sys.QueryImpl.executeUpdate(QueryImpl.java:393) ~[cuba-core-6.4.4.jar:6.4.4]
web_1       |   at com.haulmont.fts.core.app.FtsManager.removeQueuedItems(FtsManager.java:272) ~[fts-core-6.4.4.jar:6.4.4]
web_1       |   at com.haulmont.fts.core.app.FtsManager.processQueue(FtsManager.java:227) ~[fts-core-6.4.4.jar:6.4.4]
web_1       |   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_111]
web_1       |   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_111]
web_1       |   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_111]
web_1       |   at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_111]
web_1       |   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at com.sun.proxy.$Proxy141.processQueue(Unknown Source) ~[na:na]
web_1       |   at com.haulmont.fts.core.jmx.FtsManager.processQueue(FtsManager.java:55) ~[fts-core-6.4.4.jar:6.4.4]
web_1       |   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_111]
web_1       |   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_111]
web_1       |   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_111]
web_1       |   at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_111]
web_1       |   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at com.haulmont.cuba.core.sys.MBeanInterceptor.aroundInvoke(MBeanInterceptor.java:40) [cuba-core-6.4.4.jar:6.4.4]
web_1       |   at sun.reflect.GeneratedMethodAccessor98.invoke(Unknown Source) ~[na:na]
web_1       |   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_111]
web_1       |   at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_111]
web_1       |   at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:618) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) [spring-aop-4.3.3.RELEASE.jar:4.3.3.RELEASE]
web_1       |   at com.sun.proxy.$Proxy142.processQueue(Unknown Source) [na:na]
web_1       |   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_111]
web_1       |   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_111]
web_1       |   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_111]
web_1       |   at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_111]
web_1       |   at com.haulmont.cuba.core.app.scheduling.RunnerBean.executeTask(RunnerBean.java:215) [cuba-core-6.4.4.jar:6.4.4]
web_1       |   at com.haulmont.cuba.core.app.scheduling.RunnerBean.lambda$runTask$0(RunnerBean.java:124) [cuba-core-6.4.4.jar:6.4.4]
web_1       |   at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_111]
web_1       |   at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_111]
web_1       |   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_111]
web_1       |   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_111]
web_1       |   at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_111]
web_1       | Caused by: org.eclipse.persistence.exceptions.DatabaseException:
web_1       | Internal Exception: org.postgresql.util.PSQLException: Can't infer the SQL type to use for an instance of com.haulmont.cuba.core.sys.persistence.PostgresUUID. Use setObject() with an explicit Types value to specify the type to use.
web_1       | Error Code: 0
web_1       | Call: delete from SYS_FTS_QUEUE where ID in (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
web_1       |   bind => [2b89d324-1228-a691-ccd6-9b59f7b31fda, b15981e5-a02a-4188-4a43-091d805a5958, be438a9f-c13f-a646-7f04-a8958fdfe488, b9566fa7-90de-9ba2-0c64-2b4a659dd9f6, 4ec9bd28-248b-f7e6-65f9-c28fd6cd9aef, 704b2ef2-55c0-5b70-dd92-236ed234adc9, 72acf73f-fd38-d92f-ae69-4e64879c7d17, 88871378-789d-7abe-e3a6-1bea1e61d1f6, 588453ea-343e-b297-ffe9-c013e2519470, ac35cbb4-a02b-c7d7-9922-2c82d81524bf]
web_1       | Query: DataModifyQuery(sql="delete from SYS_FTS_QUEUE where ID in (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)")
web_1       |   at org.eclipse.persistence.exceptions.DatabaseException.sqlException(DatabaseException.java:340) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:684) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:560) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:2052) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:306) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:242) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:228) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeNoSelectCall(DatasourceCallQueryMechanism.java:271) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeNoSelect(DatasourceCallQueryMechanism.java:251) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.queries.DataModifyQuery.executeDatabaseQuery(DataModifyQuery.java:85) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:904) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.queries.DatabaseQuery.executeInUnitOfWork(DatabaseQuery.java:803) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2944) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1854) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1836) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1801) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.jpa.QueryImpl.executeUpdate(QueryImpl.java:298) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   ... 46 common frames omitted
web_1       | Caused by: org.postgresql.util.PSQLException: Can't infer the SQL type to use for an instance of com.haulmont.cuba.core.sys.persistence.PostgresUUID. Use setObject() with an explicit Types value to specify the type to use.
web_1       |   at org.postgresql.jdbc.PgPreparedStatement.setObject(PgPreparedStatement.java:1051) ~[postgresql.jar:9.4.1212]
web_1       |   at org.apache.tomcat.dbcp.dbcp2.DelegatingPreparedStatement.setObject(DelegatingPreparedStatement.java:188) ~[tomcat-dbcp.jar:8.0.41]
web_1       |   at org.apache.tomcat.dbcp.dbcp2.DelegatingPreparedStatement.setObject(DelegatingPreparedStatement.java:188) ~[tomcat-dbcp.jar:8.0.41]
web_1       |   at org.eclipse.persistence.internal.databaseaccess.DatabasePlatform.setParameterValueInDatabaseCall(DatabasePlatform.java:2506) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.databaseaccess.DatabaseCall.prepareStatement(DatabaseCall.java:797) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:621) ~[eclipselink-2.6.2.cuba12.jar:2.6.2.cuba12]
web_1       |   ... 61 common frames omitted
#2

By the way: I’m running on Docker and using postgress but that may be clear from the logging as well.

#3

After some more research I found that ID aa944e48-8471-c76e-dc7e-e64ea362ab71 was a record in the sys_fts_queue table and in turn pointed to an entity of type sec$Role. I actually exclude this type from the fts so why is this in there? And is this causing the error?

#4

(the ID is different from the log I included but that’s because it’s from a new run after restart)

#5

Hi!
A several questions:

  1. What platform version do you use?
  2. What postgresql version do you use on you dev machine and in production?
  3. How do you deploy your app in production? What postgresql driver version is used there?
#6

Hi Max, thanks for your support.

Platform: Ubuntu 16.04.2 LTS

I’m using an Nginx proxy server (version 1.10.0) with docker containers running the configuration below:

  • Tomcat: 8.0.41
  • JRE: 1.8.0.111
  • Postgres: 9.6.1
  • Postgres driver: 9.4.1212

Docker version: 17.05.0

The application is built on CUBA platform version 6.4.5.

Hope this gives you sufficient information to find a cause for the issue.

Regards,
Berend

#7

How do you deploy to production: build war file, copy the whole tomcat directory or smth else? I’ve found the similar topic on forum: Weird FTS issue - CUBA.Platform and it seems that there was a problem with outdated jbdc driver there.

#8

Hi Max,

I build a war using gradle and then copy the war to the production server. I will see if a new(er) or other jdbc driver behaves differently.

And I saw that in my project the ‘includeJdbcDriver’ is set to true as well. That is a thing to look at as well.

i’ll keep you posted on any findings.

Regards,
Berend

#9

Hi Max,

It turns out that switching off the ‘includeJdbcDriver’ in the gradle configuration did the trick. Excellent - case solved.

Regards,
Berend