Mismatch client-server protocol prefix

Hello!

We migrated one of our legacy webservices to Spring Boot/Spring MVC.
Now i have a strange problem. At first the app runs perfectly for a couple of hours.
After that it stops working and I get the following exception:

2015-06-17 01:16:28.450 ERROR 25197 --- [ajp-nio-8053-exec-4] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.orm.jpa.JpaSystemException: com.objectdb.o.UserException: Mismatch client-server protocol prefix; nested exception is javax.persistence.PersistenceException: com.objectdb.o.UserException: Mismatch client-server protocol prefix] with root cause

com.objectdb.o.UserException: Mismatch client-server protocol prefix
        at com.objectdb.o.MSG.d(MSG.java:62)
        at com.objectdb.o.SCO.b(SCO.java:210)
        at com.objectdb.o.NTS.z(NTS.java:287)
        at com.objectdb.o.CLS.S(CLS.java:349)
        at com.objectdb.o.CLS.Q(CLS.java:282)
        at com.objectdb.o.CST.UD(CST.java:416)
        at com.objectdb.o.GEN.x(GEN.java:256)
        at com.objectdb.o.ENH.f(ENH.java:328)
        at com.objectdb.o.STM.E(STM.java:421)
        at com.objectdb.o.OBM.bP(OBM.java:919)
        at com.objectdb.jdo.PMImpl.bP(PMImpl.java:2267)
        at com.objectdb.o.OBM.bO(OBM.java:833)
        at com.objectdb.o.OBM.bM(OBM.java:742)
        at com.objectdb.jpa.EMImpl.commit(EMImpl.java:299)
        at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:517)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:757)

I checked multiple times if the versions match. They do. DB server version 2.6.2. Client version 2.6.2. Also there's only one objectdb jar on the classpath.

It's also not a network problem. It also happens on the node which also runs the DB server. -> Connection on localhost

We also have a Spring Boot/Vaadin Webapp which works without any problems.

What's going on here?

Regards

Ralph

This exception indicates a client-server communication error. Every client request starts with a prefix that is checked by the server before handling the request. That check could fail if different ObjectDB versions are in use on the client and on the server, but such exceptions have also been reported due to other issues. Since the same connection and sockets are used for more than one request, failure to read a full request by the server can cause next requests to fail with this exception.

Please check the log files for other exceptions, possibly before this exception is thrown. Try also to consider any change in the migration of code that could cause it. More information about this exception may help.

You're right. There is an exception right before it. Exactly at this point the application refuses to work and throws the mismatch exception while processing a request.

com.objectdb.o.InternalException: null
        at com.objectdb.o.BYR.o(BYR.java:113)
        at com.objectdb.o.BYR.w(BYR.java:206)
        at com.objectdb.o.BYR.J(BYR.java:428)
        at com.objectdb.o.RRB.n(RRB.java:220)
        at com.objectdb.o.QRS.u(QRS.java:356)
        at com.objectdb.o.CST.Vb(CST.java:610)
        at com.objectdb.o.QRR.g(QRR.java:247)
        at com.objectdb.o.QRR.f(QRR.java:153)
        at com.objectdb.jpa.JpaQuery.getResultList(JpaQuery.java:716)

This exception indicates an unexpected query execution error.

Could you please check the specific query that caused the exception (assuming the stack trace starts at your code), and provide more information? Is it different from what was used before migration?

No wed didn't change anything in our DAOs.

This is the code which raises the Exception:

@Transactional
    @Override
    public TrackerUser findByName(String username) {
        Query q = em.createQuery("SELECT t FROM TrackerUser t WHERE t.username = :uname");
        q.setParameter("uname", username);
        TrackerUser result = null;
        result = (TrackerUser) q.getSingleResult();
        em.detach(result);
        return result;
    }

This code worked for a couple of years now and is used in multiple projects.

Looks like very ordinary code.

Could you check the database with the ObjectDB Doctor?

I found some other nice exceptions:

@Transactional
    @Override
    public Unit findByName(String unitName) throws at.co.pjm.tracker.data.exceptions.NoResultException {
        Query q = em.createQuery("SELECT t FROM Unit t WHERE LOWER(t.unitID) = LOWER(:uname)");
        q.setParameter("uname", unitName);
        Object result = null;
        try {
            result = q.getSingleResult();
        } catch (Throwable ex) {
            throw new at.co.pjm.tracker.data.exceptions.NoResultException("No unit found!", ex);
        }
        return (Unit) result;
    }

This exception gets thrown at the getSingleResult line:

java.lang.ClassCastException: at.co.pjm.tracker.persistence.TrackerUser cannot be cast to at.co.pjm.tracker.persistence.Unit
        at at.co.pjm.tracker.data.impl.UnitDAO.findByName_aroundBody2(UnitDAO.java:89)
        at at.co.pjm.tracker.data.impl.UnitDAO$AjcClosure3.run(UnitDAO.java:1)
        at org.springframework.transaction.aspectj.AbstractTransactionAspect.ajc$around$org_springframework_transaction_aspectj_AbstractTransactionAspect$1$2a73e96cproceed(AbstractTransactionAspect.aj:66)
        at org.springframework.transaction.aspectj.AbstractTransactionAspect$AbstractTransactionAspect$1.proceedWithInvocation(AbstractTransactionAspect.aj:72)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
        at org.springframework.transaction.aspectj.AbstractTransactionAspect.ajc$around$org_springframework_transaction_aspectj_AbstractTransactionAspect$1$2a73e96c(AbstractTransactionAspect.aj:70)
        at at.co.pjm.tracker.data.impl.UnitDAO.findByName(UnitDAO.java:80)
        at at.co.pjm.tracker.data.impl.UnitDAO$$FastClassBySpringCGLIB$$9166d7ec.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:717)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
        at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:653)
        at at.co.pjm.tracker.data.impl.UnitDAO$$EnhancerBySpringCGLIB$$f5218d0.findByName(<generated>)
        at at.co.pjm.tracker.webservice.controller.PositionController.getPositions(PositionController.java:55)

Another one in the same method:

java.lang.ClassCastException: java.util.ArrayList cannot be cast to at.co.pjm.tracker.persistence.Unit
        at at.co.pjm.tracker.data.impl.UnitDAO.findByName_aroundBody2(UnitDAO.java:89)
        at at.co.pjm.tracker.data.impl.UnitDAO$AjcClosure3.run(UnitDAO.java:1)
        at org.springframework.transaction.aspectj.AbstractTransactionAspect.ajc$around$org_springframework_transaction_aspectj_AbstractTransactionAspect$1$2a73e96cproceed(AbstractTransactionAspect.aj:66)
        at org.springframework.transaction.aspectj.AbstractTransactionAspect$AbstractTransactionAspect$1.proceedWithInvocation(AbstractTransactionAspect.aj:72)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
        at org.springframework.transaction.aspectj.AbstractTransactionAspect.ajc$around$org_springframework_transaction_aspectj_AbstractTransactionAspect$1$2a73e96c(AbstractTransactionAspect.aj:70)
        at at.co.pjm.tracker.data.impl.UnitDAO.findByName(UnitDAO.java:80)
        at at.co.pjm.tracker.data.impl.UnitDAO$$FastClassBySpringCGLIB$$9166d7ec.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:717)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
        at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)

I also found some exceptions clearly related to Issue 256. They should go away after upgrading to the newest underscore release I suppose.

I also checked the logs of our other apps which use the same DAO artifact and there are no errors in them.

The last two stack traces do not mention ObjectDB.

In addition to checking the database file with ObjectDB Doctor, could you please check these queries outside of your application (e.g. in the Explorer)? Maybe you can find a pattern.

These traces indeed don't mention ObjectDB but look at the code. There should be no possibility to get something else back than an Unit object.
I checked the DB two times and installed the copy generated by the Doctor. It found no errors.
We use this method for over 3 years now. It's from the early days of our software when we used MySQL. This method is called thousands of times a day by different daemons and webapps. It only fails in our webservice after the NPE occours. 

Something fails with client-server communication.

It could be because of concurrent use of the same connection and sockets (i.e. same EntityManager) by two concurrent threads. ObjectDB synchronizes use of EntityManager by different threads, but maybe there is an uncovered situation that affects only in rare cases and shows up now in the new implementation. Maybe a socket from a closed EntityManager is still used after the EntityManager is closed after its resources are allocated and used by a new EntityManager.

You may try the following configuration and see if it makes a difference (for diagnosis):

<database>
  ...
  <processing cache="64mb" max-threads="1" synchronized="true" />
  ..
</database>

Check also the possibility of operations on an EntityManager by one thread when it is closed by another one.

If this doesn't help, maybe you can isolate the problem by returning some of the services to the old implementation, until you can identify the specific part of the application that is relevant to the failure.

Do I have to make this change on the server? How does this affect performance?
The implementation hasn't changed at all. We only converted our WAR to a standalone runnable WAR with embedded Tomcat. In addition we converted our Spring configuration from xml to configuration classes. That's all. Basically this also updated all the Spring libraries to a newer version and maybe the tomcat configuration changed. The strange thing is that we use this setup for all of our daemons and webapps but the problem only occurs with this one.

The entity manager get's injected into every DAO by Spring at creation. It's a thread safe transactional proxy according to the documentation. So I have not much control what happens to the entity manager. From what I see from the logs Spring reuses them and creates new ones if there are more needed. Basically I have to use it this way to make @Transactional annotations work.
The weird thing is that this works perfectly in any other app we have with the same libs and setup.

Yes, this is a server configuration. It may decrease performance a bit or may not, but if it eliminates the issue it will help for diagnosis. It is definitely weird. Maybe it is a conflict between embedded Tomcat / new Spring and ObjectDB.

Yesterday I upgraded to Version 2.6.2_06. 
In addition I compared the spring configuration of this project with other projects. I think I found the solution. Now the error isn't happening anymore.

I don't understand it fully.

This are the annotations of the config class:

@SpringBootApplication
@EnableSpringConfigured
@EnableJpaRepositories("at.co.pjm.tracker.data")
@EnableTransactionManagement(mode = AdviceMode.ASPECTJ)
@Import(RepositoryHazelcastConfig.class)

What I added is the @EnableSpringConfigured annotation. It just doesn't makes sense. In this project we aren't using AspectJ enhanced @Configurable classes. Yeah but now the error went away. I think it's a bug in Spring. @EnableTransactionManagement(mode = AdviceMode.ASPECTJ) should be enough to to tell Spring that the DAOs are enhanced by AspectJ. I really have no idea why this lead to a such a weird behavior. In fact the transaction manager which is also responsible for assigning exactly one entity manager to every transaction stops to work correctly. I also found multiple examples on the Internet where they don't have to use this workaround.

I also had a look on an older revision with XML configuration. We haven't had the XML counterpart of @EnableSpringConfigured there.

One thing is still happening.

public void login(TrackerUser loggedInUser, AccessType accessType, String note) {
        LoginEvent event = new LoginEvent();
        event.setAccessType(AccessType.REST);
        event.setNote(note);
        event.setTimestamp(new Date());
        if(accessType != null) {
            event.setAccessType(accessType);
        }
        event.setTrackerUser(loggedInUser);
        loggedInUser.setLastLogin(event.getTimestamp());
        trackerUserDAO.persistUser(loggedInUser);
        loginDAO.save(event);
    }

This is the only method in which we persist an LoginEvent. Again it's only happening in this project. Our frontend webapp also calls this on every login. The exception is rather unusual because it doesn't say where in the code it's happening.

com.objectdb.o.UserException: Attempt to reuse an existing primary key value (at.co.pjm.tracker.persistence.LoginEvent:0)
        at com.objectdb.o.MSG.d(MSG.java:62)
        at com.objectdb.o.PPW.ao(PPW.java:207)
        at com.objectdb.o.PGW.aj(PGW.java:211)
        at com.objectdb.o.UPT.C(UPT.java:134)
        at com.objectdb.o.UPT.l(UPT.java:110)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.UPT.s(UPT.java:157)
        at com.objectdb.o.PGT.q(PGT.java:109)
        at com.objectdb.o.UPT.C(UPT.java:121)
        at com.objectdb.o.UPT.l(UPT.java:110)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.UPT.s(UPT.java:157)
        at com.objectdb.o.PGT.q(PGT.java:109)
        at com.objectdb.o.UPT.C(UPT.java:121)
        at com.objectdb.o.URT.l(URT.java:171)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.TSM.e(TSM.java:86)
        at com.objectdb.o.UTT.A(UTT.java:370)
        at com.objectdb.o.UTT.l(UTT.java:208)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.TSM.e(TSM.java:86)
        at com.objectdb.o.MST.Vh(MST.java:1393)
        at com.objectdb.o.WRA.Vh(WRA.java:396)
        at com.objectdb.o.WSM.Vh(WSM.java:184)
        at com.objectdb.o.WRA.Vh(WRA.java:396)
        at com.objectdb.o.WSN.Vh(WSN.java:661)
        at com.objectdb.o.STC.v(STC.java:514)
        at com.objectdb.o.SHN.an(SHN.java:562)
        at com.objectdb.o.SHN.K(SHN.java:169)
        at com.objectdb.o.HND.run(HND.java:133)
        at java.lang.Thread.run(Thread.java:745)

It only happens from time to time. Not at every login. Before upgrading to _06 i thought it might be bug 256 but its obviously not.

Additionally this exception got raised multiple times during the day:

com.objectdb.o.InternalException: Error reading UTF string
        at com.objectdb.o.BYR.N(BYR.java:1216)
        at com.objectdb.o.BYR.N(BYR.java:522)
        at com.objectdb.o.BYR.M(BYR.java:503)
        at com.objectdb.o.BYR.T(BYR.java:630)
        at com.objectdb.o.TRS.k(TRS.java:273)
        at com.objectdb.o.QRS.u(QRS.java:350)
        at com.objectdb.o.CST.Vb(CST.java:610)
        at com.objectdb.o.QRR.g(QRR.java:247)
        at com.objectdb.o.QRR.f(QRR.java:153)
        at com.objectdb.jpa.JpaQuery.getSingleResult(JpaQuery.java:747)

1. Regarding the Spring configuration - it is weird, thanks for updating.
2. The "Attempt to reuse an existing primary key value" exception is thrown during commit or flush and should indicate an attempt to persist a new entity object with a primary key that is already in use by an existing entity object of that type. Currently there are no known issues about getting this exception in other cases.
3. The "Error reading UTF string" exception is very general internal exception. In this context it happens during reading query response on the client side, and again it may indicate unsynchronized client-server communication maybe due to unexpected concurrent use of the same EntityManager in different threads.

How can #2 happen? We are persisting a new instance of LoginEvent. The Id field is not explicitly set and the field is annotated with:

@Id
@GeneratedValue
public Long getId() {
  return Id;
}

Regarding #2 and #3 - are these new issues, started after switching to new Spring / Tomcat?

Yes.

The UTF-8 error happened the last time 4 days ago but the primary key exception raises every few calls of our logging method.

The cause is unclear. Are you using exactly the same ObjectDB version?

Something that may be worth checking is switching to another value generation method, to see if it makes any difference.