AppSync: Filesystem mapping fails with "HeapDumpOnOutOfMemoryError"
Summary: AppSync: The user is unable to successfully map filesystems in AppSync 2.2.3
Symptoms
AppSync jobs are hanging and subsequent jobs are unable to run.
In the AppSync Server log (C:\EMC\AppSync\jboss\logs\server.log on the AppSync server), we see the AppSync Server service restarting here....
07-30-2016 01:10:13.494 INFO [MSC service thread 1-1] [org.jboss.as.naming] [] [] JBAS011802: Starting Naming Service
07-30-2016 01:10:14.823 INFO [MSC service thread 1-7] [org.jboss.ws.common.management.AbstractServerConfig] [] [] JBoss Web Services - Stack CXF Server 4.0.2.GA
In the AppSync Executive log (C:\EMC\AppSync\jboss\logs\executive.log on the AppSync server) we see the following out of memory error:
4098664.623: [Full GC
[PSYoungGen: 384064K->384062K(404032K)] [ParOldGen: 1398143K->1398143K(1398144K)] 1782207K->1782205K(1802176K) [PSPermGen: 157954K->157954K(158272K)], 1.4650114 secs] [Times: user=5.06 sys=0.00, real=1.47 secs]
Shutdown failed: Timed out waiting for signal from JVM.
Enqueue Event 'jvm_kill'
4098666.090: [Full GC
JVM did not exit on request, terminated
Enqueue Event 'jvm_killed'
Enqueue Event 'jvm_stopped'
socket read failed. (An existing connection was forcibly closed by the remote host. (0x2746))
Closing backend socket.
Preparing to restart with mode 4.
JVM was only running for -547624 seconds leading to a failed restart count of 1.
Enqueue Event 'jvm_failed_invocation'
Waiting 5 seconds before launching another JVM.
server listening on port 32000.
Ping settings: wrapper.ping.interval=5, wrapper.ping.interval.logged=1, wrapper.ping.timeout=300
Enqueue Event 'jvm_restart'
Enqueue Event 'jvm_prelaunch'
Launching a JVM...
Command: "_jre\bin\java" -server -Xms1024m -Xmx2048m -XX:MaxPermSize=512m -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintCommandLineFlags -XX:+UseCompressedOops -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -Djava.net.preferIPv4Stack=false -Dorg.jboss.resolver.warning=true -Dorg.tanukisoftware.wrapper.WrapperManager.mbean=false -Djboss.modules.system.pkgs=org.jboss.byteman -Djboss.server.default.config=standalone.xml -Djava.util.logging.manager=org.jboss.logmanager.LogManager -Dorg.jboss.boot.log.file=logs/boot.log -Dlogging.configuration=file:standalone/configuration/logging.properties -Djboss.server.log.dir=logs -Dappsync.server=SVRAPPSYNC.PHYSIOCORP.COM -Dfile.encoding=UTF8 -Duser.language=en -Djava.library.path="executive;../CST/builds/win_vc100_x64_r/bin" -classpath "executive/wrapper.jar;./jboss-modules.jar" -Dwrapper.key="g6PkoEa65igOyT26W3eDRDQ6_Kektd7Q" -Dwrapper.port=32000 -Dwrapper.jvm.port.min=31000 -Dwrapper.jvm.port.max=31999 -Dwrapper.debug="TRUE" -Dwrapper.pid=3408 -Dwrapper.version="3.5.14-pro" -Dwrapper.native_library="wrapper" -Dwrapper.service="TRUE" -Dwrapper.cpu.timeout="10" -Dwrapper.jvmid=2 -Dwrapper.lang.domain=wrapper -Dwrapper.lang.folder=../lang org.tanukisoftware.wrapper.WrapperJarApp jboss-modules.jar -mp modules -jaxpmodule javax.xml.jaxp-provider org.jboss.as.standalone -Djboss.home.dir=.
JVM started (PID=7788)
Enqueue Event 'jvm_start'
-XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=1073741824 -XX:MaxHeapSize=2147483648 -XX:MaxPermSize=536870912 -XX:+PrintCommandLineFlags -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
WrapperManager Debug: WrapperManager class initialized by thread: main Using classloader: sun.misc.Launcher$AppClassLoader@78d5c653
WrapperManager: Initializing...
WrapperManager Debug: JVM #2
WrapperManager Debug: Running a 64-bit JVM.
WrapperManager Debug: org.tanukisoftware.wrapper.WrapperManager package information:
WrapperManager Debug: Implementation Title: org.tanukisoftware.wrapper
WrapperManager Debug: Implementation Vendor: Tanuki Software, Ltd.
WrapperManager Debug: Implementation Version: 3.5.14
WrapperManager Debug: Is Sealed?: False
WrapperManager Debug: org.tanukisoftware.wrapper.WrapperManager protection domain:
WrapperManager Debug: Location: file:/C:/EMC/AppSync/jboss/executive/wrapper.jar
WrapperManager Debug: Size: 117,262
WrapperManager Debug: MD5: 3a16b23744071559f42f26c48b36e756
WrapperManager Debug: Registering shutdown hook
WrapperManager Debug: Using wrapper
WrapperManager Debug: Load native library. There are multiple possible file names and the first to be found will be used. Errors loading non-existing files is normal and is only a problem if they all fail.
WrapperManager Debug: Attempt to load native library with name: wrapper-windows-x86-64.dll Result: no wrapper-windows-x86-64 in java.library.path
WrapperManager Debug: Attempt to load native library with name: wrapper.dll Result: Success!
WrapperManager Debug: Successfully loaded native library.
WrapperManager Debug: Loaded localized resources.
WrapperManager Debug: Calling native initialization method.
WrapperJNI Debug: Initializing WrapperManager native library.
WrapperJNI Debug: Java Executable: C:\EMC\AppSync\jboss\_jre\bin\java.exe
WrapperJNI Debug: Native Library: C:\EMC\AppSync\jboss\executive\wrapper.dll
WrapperJNI Debug: Windows version: 6.2.9200
WrapperManager Debug: Java Version : 1.7.0_17-b02 Java HotSpot(TM) 64-Bit Server VM
WrapperManager Debug: Java VM Vendor : Oracle Corporation
WrapperManager Debug: OS Name : Windows Server 2012
WrapperManager Debug: OS Arch : amd64
WrapperManager Debug:
WrapperManager Debug: Control event monitor thread started.
WrapperManager Debug: Startup runner thread started.
WrapperJarApp Debug: Jar Main-Class: org.jboss.modules.Main
WrapperJarApp Debug: Jar Classpath: Not specified.
WrapperJarApp Debug: Classpath[0]=file:C:/EMC/AppSync/jboss/jboss-modules.jar
WrapperManager Debug: WrapperManager.start(org.tanukisoftware.wrapper.WrapperJarApp@5bfa19ca, args["-mp", "modules", "-jaxpmodule", "javax.xml.jaxp-provider", "org.jboss.as.standalone", "-Djboss.home.dir=."]) called by thread: main
WrapperManager Debug: Communications runner thread started.
WrapperManager Debug: Open socket to wrapper...Wrapper-Connection
WrapperManager Debug: Opened Socket from 31,000 to 32,000
WrapperManager Debug: Send a packet KEY : g6PkoEa65igOyT26W3eDRDQ6_Kektd7Q
WrapperManager Debug: handleBackend()
accepted a socket from 127.0.0.1 on port 31000
closing backend server.
read a packet KEY : g6PkoEa65igOyT26W3eDRDQ6_Kektd7Q
Got key from JVM: g6PkoEa65igOyT26W3eDRDQ6_Kektd7Q
send a packet LOW_LOG_LEVEL : 1
send a packet LOGFILE : logs\executive.log
send a packet PROPERTIES : (Property Values)
Start Application.
send a packet START : start
WrapperManager Debug: Received a packet LOW_LOG_LEVEL : 1
WrapperManager Debug: LowLogLevel from Wrapper is 1
WrapperManager Debug: Received a packet LOGFILE : logs\executive.log
WrapperManager Debug: Received a packet PROPERTIES : (Property Values)
WrapperManager Debug: Received a packet START : start
WrapperManager Debug: Java temporary directory: C:\Windows\TEMP
WrapperManager Debug: calling WrapperListener.start()
WrapperManager Debug: WrapperListener.start runner thread started.
WrapperJarApp Debug: start(args) Will wait up to 2 seconds for the main method to complete.
WrapperJarApp Debug: invoking main method
WrapperManager Debug: Send a packet START_PENDING : 5000
read a packet START_PENDING : 5000
JVM signaled a start pending with waitHint of 5000 millis.
WrapperManager Debug: Send a packet START_PENDING : 5000
WrapperJarApp Debug: start(args) end. Main Completed=false, exitCode=null
WrapperManager Debug: returned from WrapperListener.start()
WrapperManager Debug: Send a packet STARTED :
WrapperManager Debug: WrapperListener.start runner thread stopped.
WrapperManager Debug: Startup runner thread stopped.
read a packet START_PENDING : 5000
JVM signaled a start pending with waitHint of 5000 millis.
read a packet STARTED :
JVM signaled that it was started.
Enqueue Event 'jvm_started'
send a packet PING : ping
WrapperManager Debug: Received a packet PING : ping
WrapperManager Debug: Send a packet PING : ping
read a packet PING : ping
INFO (WrapperJarAppMain) 2016-07-30 01:10:02,400 [org.jboss.modules] Module JBoss Modules version 1.1.1.GA
send a packet PING : ping
WrapperManager Debug: Received a packet PING : ping
WrapperManager Debug: Send a packet PING : ping
read a packet PING : ping
INFO (WrapperJarAppMain) 2016-07-30 01:10:05,072 [org.jboss.msc] ServiceLogger_$logger JBoss MSC version 1.0.2.GA
INFO (MSC service thread 1-4) 2016-07-30 01:10:05,151 [org.jboss.as] ApplicationServerService JBAS015899: JBoss AS 7.1.1.Final "Brontes" starting
WrapperJarApp Debug: main method completed
send a packet PING : ping
WrapperManager Debug: Received a packet PING : ping
WrapperManager Debug: Send a packet PING : ping
read a packet PING : ping
INFO (MSC service thread 1-3) 2016-07-30 01:10:11,057 [org.xnio] Xnio XNIO Version 3.0.3.GA
INFO (Controller Boot Thread) 2016-07-30 01:10:11,057 [org.jboss.as.server] HttpManagementAddHandler JBAS015888: Creating http management service using socket-binding (management-http)
INFO (MSC service thread 1-3) 2016-07-30 01:10:11,213 [org.xnio.nio] NioXnio XNIO NIO Implementation Version 3.0.3.GA
INFO (ServerService Thread Pool -- 25) 2016-07-30 01:10:11,651 [org.jboss.as.configadmin] ConfigAdminAdd JBAS016200: Activating ConfigAdmin Subsystem
21.020: [GC [PSYoungGen: 262208K->21745K(305856K)] 262263K->21808K(1004928K), 0.0279106 secs] [Times: user=0.05 sys=0.03, real=0.03 secs]
21.051: [GC [PSYoungGen: 82212K->21713K(305856K)] 82275K->21848K(1004928K), 0.0207127 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
INFO (ServerService Thread Pool -- 30) 2016-07-30 01:10:11,713 [org.jboss.as.clustering.infinispan] InfinispanSubsystemAdd JBAS010280: Activating Infinispan subsystem.
INFO (ServerService Thread Pool -- 46) 2016-07-30 01:10:
Cause
An AppSync Server service restart occurred while the mapping operation was in progress due to the out of memory issue. This resulted in a stale mapping entry in the AppSync internal database.
Resolution
Resolution:
The fix will prevent the stale entry from being encountered, thus preventing the hang and allow subsequent jobs to run.
This issue is resolved in AppSync 2.2.3.1.