Confluence dies while trying to start after upgrade from 4.3.7 to 5.10.9

[Bryan Stephenson]

I read all the release and upgrade notes. The installation script worked fine. The java process went away several times while starting after the upgrade. I kept starting Confluence again and it made more progress on the upgrade tasks each time. Eventually got a log message:

2018-06-16 12:28:35,785 INFO [localhost-startStop-1] [confluence.upgrade.upgradetask.RenameEhcachePropertiesUpgradeTask] doUpgrade Upgrade task complete.

But the java process still goes away a few minutes after starting (about 5-7 minutes). I get 5 warnings like this in catalina.out:

16-Jun-2018 12:13:36.757 WARNING [main] org.apache.tomcat.util.digester.SetProperti
esRule.begin [SetPropertiesRule]{Server} Setting property 'debug' to '0' did not fi
nd a matching property.

In atlassian-confluence.log I see:

2018-06-16 13:23:18,277 WARN [localhost-startStop-1] [org.springframework.beans.GenericTypeAwarePrope
rtyDescriptor] getWriteMethodForActualAccess Invalid JavaBean property 'cacheFactory' being accessed!
Ambiguous write methods found next to actually used [public void com.atlassian.confluence.spaces.per
sistence.dao.hibernate.HibernateSpaceDao.setCacheFactory(com.atlassian.vcache.VCacheFactory)]: [publi
c void com.atlassian.confluence.core.persistence.hibernate.VersionedHibernateObjectDao.setCacheFactor
y(com.atlassian.cache.CacheFactory)]

and seven of these:

2018-06-16 13:24:14,166 WARN [ThreadPoolAsyncTaskExecutor::Thread 22] [spring.scanner.util.ProductFilterUtil] detectProduct Couldn't detect product, will use ProductFilter.ALL

then this and nothing more:

2018-06-16 13:24:52,068 INFO [localhost-startStop-1] [confluence.upgrade.recovery.ConfluenceProgressMonitor] begin TABLE_DATA: [BANDANA]
2018-06-16 13:24:53,054 INFO [localhost-startStop-1] [confluence.upgrade.recovery.ConfluenceProgressMonitor] end TABLE_DATA: [BANDANA]
2018-06-16 13:24:53,055 INFO [localhost-startStop-1] [confluence.upgrade.recovery.ConfluenceProgressMonitor] begin TABLE_DATA: [BODYCONTENT]

shortly after that the java process is no longer running.

How can I find out why the java process stopped?

How can I get this installation working again?

[Bryan Stephenson · Accepted solution]

So the problem turned out to be the JVM was requesting more memory than was available and getting killed by the OOM killer several times while doing the first start after the upgrade. One can tell this is happening by looking in /var/log/messages for messages like this:

2018-06-16T17:55:10.609012-07:00 susewiki kernel: [ 351.886599] Out of memory: Kill process 3087 (java) score 705 or sacrifice child
2018-06-16T17:55:10.609023-07:00 susewiki kernel: [ 351.886684] Killed process

The solution was to modify this line in setenv.sh to ensure the JVM does not grow too large for the server and get killed by the kernel

CATALINA_OPTS="-Xms1024m -Xmx2048m -XX:+UseG1GC ${CATALINA_OPTS}"

[Igor M.]

Sorry, did not see this reply, glad you got it fixed.

[Bryan Stephenson]

So now I am getting a new error. Should I be running start-confluence.sh as root? 

16-Jun-2018 16:53:14.152 SEVERE [main] org.apache.coyote.AbstractProtocol.init Failed
to initialize end point associated with ProtocolHandler ["http-nio-80"]
java.net.SocketException: Permission denied
at sun.nio.ch.Net.bind0(Native Method)
at sun.nio.ch.Net.bind(Net.java:433)
at sun.nio.ch.Net.bind(Net.java:425)
at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223)
at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74)
at org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:350)
at org.apache.tomcat.util.net.AbstractEndpoint.init(AbstractEndpoint.java:823
)
at org.apache.coyote.AbstractProtocol.init(AbstractProtocol.java:476)
at org.apache.coyote.http11.AbstractHttp11JsseProtocol.init(AbstractHttp11Jss
eProtocol.java:120)
at org.apache.catalina.connector.Connector.initInternal(Connector.java:960)
at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
at org.apache.catalina.core.StandardService.initInternal(StandardService.java
:568)
at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
at org.apache.catalina.core.StandardServer.initInternal(StandardServer.java:8
71)
at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:102)
at org.apache.catalina.startup.Catalina.load(Catalina.java:581)
at org.apache.catalina.startup.Catalina.load(Catalina.java:604)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:
62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorIm
pl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:310)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:484)

[Igor M.]

It depends on how your confluence process is configured to run.

If you have confluence installed as service then you should run 

sudo /etc/init.d/confluence start

or

service confluence start

 You should not use a script to start service. 

Also if confluence is configured to run with a dedicated account, then the service should be started with that account, not with root. 

Finally, have you checked if there is enough free memory on the system for service to startup? You can also try lowering resources a little bit, like cut -xms and -xmx by half.

It could also be that upgrade did not complete successfully and your system files are broken, hence why service can't properly start. You can test it by stopping all services and installing a blank new standalone 5.9.10 version of confluence on the same service but with the different install and home path with new blank DB. See if that starts successfully with the same memory allocation and if it does, compare installation files between new and upgraded version to make sure all is in order.

[Igor M.]

Hello,

We would need a complete atlassian-confluence.log log, but from the very last messages, I suspect your DB upgrade did not complete properly. I recommend rollback upgrade (Restore DB and Data from backup) and then proceed with the following:

• Check if your DB version is compatible with your target Confluence version. You can check what 5.10 supports in Supported Platforms page. If not compatible, you should update DB version. If there is no supported DB supported by both 4.3 and 5.10, then upgrading to 5.1 first might be a good step.
• Database character encoding must be set to UTF+8 (or AL32UTF8 for Oracle databases).
• Newer versions of Confluence require more resources, make sure you allocate enough memory to Java for your target version.
• Confluence comes with bundled JRE, however, if you have configured to use your own JDK instead of bundled, make sure it's the right version as 5.10 only supports 1.8

After all above is done, try upgrading to 5.1 at first, and if goes smoothly, higher up.

Regards,

Igor

[Igor M.]

P.S. Also try to clear plugins cache before starting the process, there are a few errors related to plug-in startup.

[Bryan Stephenson]

We are using the same DB version, mysql 5.6.40, which is supported by both 4.3.7 and 5.10.9 so that should be fine.

I did set the character encoding to UTF+8 a few days ago and restarted and everything was fine with that. Confluence was running normally with that addition.

I modifed in setenv.sh this line:
CATALINA_OPTS="-Xms4096m -Xmx8192m -XX:+UseG1GC ${CATALINA_OPTS}"

so that we would have enough resources. Would you recommend more? Shouldn't I get a clear error message if we run out of some required resource?

I am using the bundled JRE so that should be fine also.

I am planning on waiting to see what Atlassian support says on Monday before rolling everything back. The upgrade from 4.3.7 to 5..9.10 is supposed to work so I think (hope) I am close and can salvage this upgrade rather than start over.

Thank you for the help!

[Igor M.]

Thank you for the confirmation. That memory setting should be sufficient for 5.10, I wonder why JRE crashed with out of memory error

2018-06-16 12:24:14,327 INFO [localhost-startStop-1] [com.atlassian.confluence.lifecycle] contextInitialized Starting Confluence 5.10.9 [build 6441 based on commit hash f56d01dc1388edb9fbfe5d6fe43d946a6108a463]

Java HotSpot(TM) 64-Bit Server VM warning: INFO: os::commit_memory(0x00000005c0000000, 4294967296, 0) failed; error='Cannot allocate memory' (errno=12)

#

# There is insufficient memory for the Java Runtime Environment to continue.

# Native memory allocation (mmap) failed to map 4294967296 bytes for committing reserved memory.

# An error report file with more information is saved as:

# /opt/confluence/bin/hs_err_pid5377.log

Java HotSpot(TM) 64-Bit Server VM warning: INFO: os::commit_memory(0x00000005c0000000, 4294967296, 0) failed; error='Cannot allocate memory' (errno=12)

#

# There is insufficient memory for the Java Runtime Environment to continue.

# Native memory allocation (mmap) failed to map 4294967296 bytes for committing reserved memory.

# An error report file with more information is saved as:

# /opt/confluence/bin/hs_err_pid5427.log

.

Could you make sure all old processes are completely killed and start confluence using startup script?

[Igor M.]

Hey,

I would be more inclined to try and lower both values by half. It seems like JRE is struggling to allocate 4gb

What was your allocation prior to the upgrade?

[Igor M.]

Check if your server has enough free memory with top and free -m, you might be running out of memory on the server. This way lowering Confluence allocation might help.

[Bryan Stephenson]

Yes, it is the JVM not being able to allocate enough memory. I am using the same values as before the upgrade. After the java process mysteriously disappears a few times I get this when trying to start confluence. I just reboot to clear the memory issue and try again, and I can do a few tries at starting confluence before getting the memory error.

[Steven Behnke]

Can you upload the entire log to pastebin and link it here?

[Bryan Stephenson]

Here are the log files:

atlassian-confluence.log (the last parts, not all would fit):
https://pastebin.com/nCt1Aqvt

catalina.out:
https://pastebin.com/KV5KVkLK

gc-2018-06-16_13-22-55.log.0.current:
https://pastebin.com/U60zrpK8

 Let me know if you want other log files.

[Igor M.]

Hello,

I can see this error:

There is insufficient memory for the Java Runtime Environment to continue.

Can you please increase allocated memory as per these instructions.

I would suggest giving 5.10 at least 1 GB of -xms and -xmx  for a start

[Bryan Stephenson]

I have 4 GB and 8 GB. That error happened twice when trying to restart after the upgrade. I rebooted the machine and it has not happened since with many tries to start confluence. Should I increase beyond 4 GB and 8 GB?

CATALINA_OPTS="-Xms4096m -Xmx8192m -XX:+UseG1GC ${CATALINA_OPTS}"