Reference Application UI Tests Failures!

@raff if am to help or any one else, can you give us some pointers? Like where the server logs are, or anything else you think would be useful.

@dkayiwa, perfect. As I wrote in my previous post Tomcat logs should be appended in build logs on Travis, however our tests get stuck and produce too much output, which exceed build log limit of 4 MBs on Travis.

Therefore, we first need to fix things so that tests fail fast when server is not properly initialized. I attempted to do it at https://github.com/openmrs/openmrs-contrib-uitestframework/commit/ff4db0069ac4b4fbfec7868433e9d144a442675f but for some reason you can still see in logs that they are being rerun too many times…

Once you fix tests to fail fast in a scenario when server is not properly up, then you will see Tomcat logs being appended by Travis at the end of build log and hopefully see why modules don’t start.

@domenico may be able to help with the issue as well.

Ok guys I can help you, but give me some time since I have hard work to do during this week.

For now, i have enabled the bamboo plan to run these tests, but disabled the provider test which fails as per the details at https://issues.openmrs.org/browse/RA-1200

I have a guess about why the tests do not fail fast. Is it possible to visualize the page with the text “If you are seeing this page, it means that the OpenMRS Platform is running” somewhere on the integration server? Basically I’d like to reproduce Rafal conditions. Thank you.

I guess your best bet is to run the server with platform 2.0.1 locally without any modules… The easiest way is to setup a platform with SDK… see https://wiki.openmrs.org/display/docs/OpenMRS+SDK#OpenMRSSDK-Settingupservers

Rafal,

I’m trying to install OpenMRS, but I got a problem. Regarding your issue, what I guess it does not work properly is the following method which returns false even if it should return true.

public boolean containsTextWithoutWait(String text) {
return driver.getPageSource().contains(text);
}

Some users report of a problem with getPageSource. Maybe here we have the same issue, unfortunately I can’t verify my hypothesis. I hope to make OpenMRS work asap and provides your with a solution.

@domenico, I replied to the problem you reported. We need to change the condition to use something different than getPageSource() then…

Yes, but I have to verify if my guess is correct.

@raff as we figure out how to append tomcat logs to the build logs on travis, how can i get access to the source tomcat logs? That will help me figure out why the current tests fail. In other words, can i access the tomcat logs as i used to, when the tests were running on our bamboo server?

@dkayiwa, I’ve committed https://github.com/openmrs/openmrs-contrib-uitestframework/commit/7ade6b9910c482647749231309867c4c5d511258 so that when we have a server failure, no other tests will run. You can see that Tomcat logs are now appended at the end of the travis log file at https://travis-ci.org/openmrs/openmrs-distro-referenceapplication/builds/194852568 (expand travis_after_script.sh)

Currently, the build is passing. We’ll need to wait for a server failure to see if my fix works and then we can look at Tomcat logs.

Thanks @raff :smile:

Daniel, do you know if we removed any apps from RA? See https://travis-ci.org/openmrs/openmrs-distro-referenceapplication/builds/195220208

@raff i do not remember very well. But we can just change to test to reflect those we currently have.

@raff, I saw your fix. It seems that the method waitForPage() threw the exceptions but it wasn’t blocking (You now catch it and exit from the execution). Therefore the following method works, as consequence I made an erroneous guess.

public boolean containsTextWithoutWait(String text) {
return driver.getPageSource().contains(text);
}

Please, can you confirm so I will not investigate on it? Thank you in advance.

I think your guess was right… I needed to apply this fix https://github.com/openmrs/openmrs-contrib-uitestframework/commit/e1eb9a379bec7f3ddb9e2aaa8dc4a28de013b7ca to make it work… Thanks for the pointer!

@dkayiwa, okay, changed the expected number of apps in https://github.com/openmrs/openmrs-distro-referenceapplication/commit/6966b0fa23dd7501fd97ae655311704e12e465e4

Also FYI, I fixed the setup to be more what it used to be i.e. tests are still run by Travis, but https://ci.openmrs.org/browse/REFAPP-OMODDISTRO-INTTESTS-5645 waits until they complete and reports the result. There’s no dedicated Travis plan anymore.

Okay, we finally got the failing build with Tomcat logs, please see https://api.travis-ci.org/jobs/196952629/log.txt?deansi=true

We have 2 errors as far as I can see… one may be causing another. First one:

ERROR - SqlExceptionHelper.logExceptions(146) |2017-01-31 14:06:03,552| Duplicate entry 'search.indexVersion' for key 'PRIMARY'
ERROR - BatchingBatch.performExecution(141) |2017-01-31 14:06:03,565| HHH000315: Exception executing batch [could not execute batch]
INFO - LoggingAdvice.invoke(155) |2017-01-31 14:06:03,574| Exiting method saveGlobalProperty
ERROR - Context.checkCoreDataset(1082) |2017-01-31 14:06:03,576| Error while setting core global properties
org.springframework.dao.DataIntegrityViolationException: could not execute batch; SQL [insert into global_property (property_value, description, datatype, datatype_config, preferred_handler, handler_config, uuid, property) values (?, ?, ?, ?, ?, ?, ?, ?)]; constraint [null]; nested exception is org.hibernate.exception.ConstraintViolationException: could not execute batch
	at org.springframework.orm.hibernate4.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:163)
	at org.springframework.orm.hibernate4.HibernateTransactionManager.convertHibernateAccessException(HibernateTransactionManager.java:730)
	at org.springframework.orm.hibernate4.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:592)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:757)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:726)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:515)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:291)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
	at com.sun.proxy.$Proxy57.saveGlobalProperty(Unknown Source)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
	at org.openmrs.aop.LoggingAdvice.invoke(LoggingAdvice.java:121)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:52)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:52)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
	at com.sun.proxy.$Proxy79.saveGlobalProperty(Unknown Source)
	at org.openmrs.api.context.Context.checkCoreDataset(Context.java:1059)
	at org.openmrs.api.context.Context.startup(Context.java:836)
	at org.openmrs.web.Listener.startOpenmrs(Listener.java:246)
	at org.openmrs.web.WebDaemon$1.run(WebDaemon.java:42)
Caused by: org.hibernate.exception.ConstraintViolationException: could not execute batch
	at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:129)
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49)
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126)
	at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:136)
	at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.doExecuteBatch(BatchingBatch.java:114)
	at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.execute(AbstractBatchImpl.java:163)
	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.executeBatch(JdbcCoordinatorImpl.java:226)
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:484)
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:351)
	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350)
	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56)
	at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1258)
	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:425)
	at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.beforeTransactionCommit(JdbcTransaction.java:101)
	at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:177)
	at org.springframework.orm.hibernate4.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:584)
	... 27 more
Caused by: java.sql.BatchUpdateException: Duplicate entry 'search.indexVersion' for key 'PRIMARY'
	at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2055)
	at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1467)
	at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:1135)
	at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:127)
	... 39 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry 'search.indexVersion' for key 'PRIMARY'
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
	at com.mysql.jdbc.Util.getInstance(Util.java:386)
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1041)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4237)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4169)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2617)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2778)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2825)
	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2156)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2441)
	at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2007)
	... 42 more

Second one, which effectively prevents modules from starting up:

INFO 1/31/17 2:06 PM:liquibase: Successfully released change log lock
Exception in thread "Thread-7" java.lang.IllegalStateException: Cannot initialize context because there is already a root application context present - check whether you have multiple ContextLoader* definitions in your web.xml!
	at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:277)
	at org.openmrs.web.filter.initialization.InitializationFilter$InitializationCompletion$1.run(InitializationFilter.java:1662)
	at java.lang.Thread.run(Thread.java:745)

I haven’t looked yet into why we get them, but just wanted to share it in case someone seen them before.

I’m pretty sure we have a bug in OpenMRS startup methods…

We execute 5 tests parallel, so after we start up a fresh instance of a server those 5 tests hit the server at the same time and trigger context startup… Apparently, when it happens fast enough, the startup method may be executed twice or more thus we see in logs:

INFO 1/31/17 2:05 PM:liquibase: Reading from `liquibasechangelog`
INFO 1/31/17 2:05 PM:liquibase: Reading from `liquibasechangelog`
INFO 1/31/17 2:05 PM:liquibase: Reading from `liquibasechangelog`

It’s an evidence of triggering the startup procedure 3 times (starting from updating database). It will then end in obscure failures like DataIntegrityViolationException quoted in my previous post.

1 Like

Created https://issues.openmrs.org/browse/TRUNK-5029

I worked around the issue with UI tests by using the latest version of SDK, which creates a docker image that sends a single request to initiate a server before executing any UI tests.