SoftwareAG Integration Server startup up hung for long time in wrapper logs

Firoz · January 5, 2021, 3:19pm

Hi Team,

Regarding Integration Server 10.3 startup getting delayed after git code merge.

I’m facing an issue without much info logged in wrapper logs. Whenever I do Integration server startup mainly after merging the code from one branch to other and then start the Integration server, then server takes almost 45 minutes to start.

The server.log doesn’t start untill 30 minutes and first 30 to 35 minutes the hung can be noticed in wrapper.log under IS_default/logs folder.

Please find below wrapper logs for your analysis, there are two places where the process is hung for 10 minutes each, not sure what it is happening here. I have increased the min/max to 512 and 4096 , but still same issue. There is no issues with JVM ping/timout as there is no such error.

Please check the below logs and see if you can help to find the root cause.

STATUS | wrapper  | 2021/01/05 14:33:30 | Base configuration file is C:\SoftwareAG\profiles\IS_default\configuration\wrapper.conf
STATUS | wrapper  | 2021/01/05 14:33:30 | Found #include file in C:\SoftwareAG\profiles\IS_default\configuration\wrapper.conf: %OSGI_INSTALL_AREA%/configuration/wrapper-license.conf
STATUS | wrapper  | 2021/01/05 14:33:30 |   After environment variable replacements: C:\SoftwareAG\profiles\IS_default/configuration/wrapper-license.conf
STATUS | wrapper  | 2021/01/05 14:33:30 |   Reading included configuration file, C:\SoftwareAG\profiles\IS_default\configuration\wrapper-license.conf
STATUS | wrapper  | 2021/01/05 14:33:30 | Found #include file in C:\SoftwareAG\profiles\IS_default\configuration\wrapper.conf: %OSGI_INSTALL_AREA%/configuration/custom_wrapper.conf
STATUS | wrapper  | 2021/01/05 14:33:30 |   After environment variable replacements: C:\SoftwareAG\profiles\IS_default/configuration/custom_wrapper.conf
STATUS | wrapper  | 2021/01/05 14:33:30 |   Reading included configuration file, C:\SoftwareAG\profiles\IS_default\configuration\custom_wrapper.conf
STATUS | wrapper  | 2021/01/05 14:33:30 | --> Wrapper Started as Service
STATUS | wrapper  | 2021/01/05 14:33:30 | Java Service Wrapper Standard Edition 64-bit 3.5.32
STATUS | wrapper  | 2021/01/05 14:33:30 |   Copyright (C) 1999-2017 Tanuki Software, Ltd. All Rights Reserved.
STATUS | wrapper  | 2021/01/05 14:33:30 |     http://wrapper.tanukisoftware.com
STATUS | wrapper  | 2021/01/05 14:33:30 |   Licensed to Software AG USA, Inc. for Software AG Integration Server
STATUS | wrapper  | 2021/01/05 14:33:30 | 
STATUS | wrapper  | 2021/01/05 14:33:32 | Launching a JVM...
ERROR  | wrapper  | 2021/01/05 14:34:03 | Startup failed: Timed out waiting for a signal from the JVM.
ERROR  | wrapper  | 2021/01/05 14:34:03 | JVM did not exit on request, termination requested.
STATUS | wrapper  | 2021/01/05 14:34:17 | JVM exited after being requested to terminate.
STATUS | wrapper  | 2021/01/05 14:34:22 | Reloading Wrapper configuration...
STATUS | wrapper  | 2021/01/05 14:34:22 | Base configuration file is C:\SoftwareAG\profiles\IS_default\configuration\wrapper.conf
STATUS | wrapper  | 2021/01/05 14:34:22 | Found #include file in C:\SoftwareAG\profiles\IS_default\configuration\wrapper.conf: %OSGI_INSTALL_AREA%/configuration/wrapper-license.conf
STATUS | wrapper  | 2021/01/05 14:34:22 |   After environment variable replacements: C:\SoftwareAG\profiles\IS_default/configuration/wrapper-license.conf
STATUS | wrapper  | 2021/01/05 14:34:22 |   Reading included configuration file, C:\SoftwareAG\profiles\IS_default\configuration\wrapper-license.conf
STATUS | wrapper  | 2021/01/05 14:34:22 | Found #include file in C:\SoftwareAG\profiles\IS_default\configuration\wrapper.conf: %OSGI_INSTALL_AREA%/configuration/custom_wrapper.conf
STATUS | wrapper  | 2021/01/05 14:34:22 |   After environment variable replacements: C:\SoftwareAG\profiles\IS_default/configuration/custom_wrapper.conf
STATUS | wrapper  | 2021/01/05 14:34:22 |   Reading included configuration file, C:\SoftwareAG\profiles\IS_default\configuration\custom_wrapper.conf
STATUS | wrapper  | 2021/01/05 14:34:22 | Launching a JVM...
INFO   | jvm 2    | 2021/01/05 14:34:23 | WrapperManager: Initializing...
INFO   | jvm 2    | 2021/01/05 14:34:33 | Debug options:
INFO   | jvm 2    | 2021/01/05 14:34:33 |     file:/C:/SoftwareAG/profiles/IS_default/bin/.options not found
INFO   | jvm 2    | 2021/01/05 14:34:34 | !SESSION 2021-01-05 14:34:26.130 -----------------------------------------------
INFO   | jvm 2    | 2021/01/05 14:34:34 | eclipse.buildId=unknown
INFO   | jvm 2    | 2021/01/05 14:34:34 | java.version=1.8.0_181
INFO   | jvm 2    | 2021/01/05 14:34:34 | java.vendor=Azul Systems, Inc.
INFO   | jvm 2    | 2021/01/05 14:34:34 | BootLoader constants: OS=win32, ARCH=x86_64, WS=win32, NL=en_GB
INFO   | jvm 2    | 2021/01/05 14:34:34 | 
INFO   | jvm 2    | 2021/01/05 14:34:34 | !ENTRY com.softwareag.platform.hook.locations 1 0 2021-01-05 14:34:33.958
INFO   | jvm 2    | 2021/01/05 14:34:34 | !MESSAGE Registering the location resolver hooks.
INFO   | jvm 2    | 2021/01/05 14:34:34 | 
INFO   | jvm 2    | 2021/01/05 14:34:34 | !ENTRY com.softwareag.platform.hook.mirrors 1 0 2021-01-05 14:34:33.958
INFO   | jvm 2    | 2021/01/05 14:34:34 | !MESSAGE Registering the mirror bundle management hooks.
INFO   | jvm 2    | 2021/01/05 14:34:34 | 
INFO   | jvm 2    | 2021/01/05 14:34:34 | !ENTRY com.softwareag.platform.hook.shutdown 1 0 2021-01-05 14:34:33.958
INFO   | jvm 2    | 2021/01/05 14:34:34 | !MESSAGE Registering the shutdown hook.
INFO   | jvm 2    | 2021/01/05 14:34:34 | 
INFO   | jvm 2    | 2021/01/05 14:34:34 | !ENTRY com.softwareag.platform.hook.locations 1 0 2021-01-05 14:34:34.349
INFO   | jvm 2    | 2021/01/05 14:34:34 | !MESSAGE Discovered location: osgi.user.area=file:/C:/Windows/System32/config/systemprofile/user/
INFO   | jvm 2    | 2021/01/05 14:34:34 | 
INFO   | jvm 2    | 2021/01/05 14:34:34 | !ENTRY com.softwareag.platform.hook.locations 1 0 2021-01-05 14:34:34.349
INFO   | jvm 2    | 2021/01/05 14:34:34 | !MESSAGE Discovered location: osgi.instance.area=file:/C:/SoftwareAG/profiles/IS_default/workspace/
INFO   | jvm 2    | 2021/01/05 14:34:34 | 
INFO   | jvm 2    | 2021/01/05 14:34:34 | !ENTRY com.softwareag.platform.hook.locations 1 0 2021-01-05 14:34:34.349
INFO   | jvm 2    | 2021/01/05 14:34:34 | !MESSAGE Discovered location: osgi.configuration.area=file:/C:/SoftwareAG/profiles/IS_default/configuration/
INFO   | jvm 2    | 2021/01/05 14:34:34 | 
INFO   | jvm 2    | 2021/01/05 14:34:34 | !ENTRY com.softwareag.platform.hook.locations 1 0 2021-01-05 14:34:34.349
INFO   | jvm 2    | 2021/01/05 14:34:34 | !MESSAGE Discovered location: osgi.install.area=file:/C:/SoftwareAG/profiles/IS_default/
INFO   | jvm 2    | 2021/01/05 14:34:34 | 
INFO   | jvm 2    | 2021/01/05 14:34:34 | !ENTRY com.softwareag.platform.hook.locations 1 0 2021-01-05 14:34:34.349
INFO   | jvm 2    | 2021/01/05 14:34:34 | !MESSAGE Discovered location: eclipse.home.location=file:/C:/SoftwareAG/profiles/IS_default/
INFO   | jvm 2    | 2021/01/05 14:34:34 | 
INFO   | jvm 2    | 2021/01/05 14:34:34 | !ENTRY com.softwareag.platform.hook.locations 1 0 2021-01-05 14:34:34.349
INFO   | jvm 2    | 2021/01/05 14:34:34 | !MESSAGE Replacing system property sag.install.area->@url:osgi.install.area/../.. with sag.install.area->file:/C:/SoftwareAG/
INFO   | jvm 2    | 2021/01/05 14:34:34 | 
INFO   | jvm 2    | 2021/01/05 14:34:34 | !ENTRY com.softwareag.platform.hook.locations 1 0 2021-01-05 14:34:34.364
INFO   | jvm 2    | 2021/01/05 14:34:34 | !MESSAGE Discovered location: sag.install.area=file:/C:/SoftwareAG/
INFO   | jvm 2    | 2021/01/05 14:34:34 | 
INFO   | jvm 2    | 2021/01/05 14:34:34 | !ENTRY com.softwareag.platform.hook.locations 1 0 2021-01-05 14:34:34.364
INFO   | jvm 2    | 2021/01/05 14:34:34 | !MESSAGE Registered location sag.install.area=file:/C:/SoftwareAG/
INFO   | jvm 2    | 2021/01/05 14:34:34 | [Tue Jan 05 14:34:34 GMT 2021] Bootstrap: Initialized shutdown handler to com.softwareag.platform.hook.shutdown.HookConfiguratorImpl$$Lambda$1/918889351@17f328a8
INFO   | jvm 2    | 2021/01/05 14:34:34 | 
INFO   | jvm 2    | 2021/01/05 14:34:34 | !ENTRY com.softwareag.platform.hook.shutdown 1 0 2021-01-05 14:34:34.411
INFO   | jvm 2    | 2021/01/05 14:34:34 | !MESSAGE Initialized graceful shutdown handler.
INFO   | jvm 2    | 2021/01/05 14:34:52 | Jan 05, 2021 2:34:36 PM com.softwareag.platform.console.internal.LocalConsoleManager open
INFO   | jvm 2    | 2021/01/05 14:34:52 | INFO: Local JLine console flag: com.softwareag.platform.console.local.enabled=auto
INFO   | jvm 2    | 2021/01/05 14:34:52 | Jan 05, 2021 2:34:52 PM com.softwareag.platform.console.internal.LocalConsoleManager open
INFO   | jvm 2    | 2021/01/05 14:34:52 | INFO: Local JLine console disabled: JVM not attached to a terminal.
INFO   | jvm 2    | 2021/01/05 14:35:17 | log4j:WARN No appenders could be found for logger (com.softwareag.security.config.filter.jaas.ldap.lm.internal.Activator).
INFO   | jvm 2    | 2021/01/05 14:35:17 | log4j:WARN Please initialize the log4j system properly.
INFO   | jvm 2    | 2021/01/05 14:35:17 | log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
INFO   | jvm 2    | 2021/01/05 14:35:20 | Jan 05, 2021 2:35:20 PM com.softwareag.platform.logging.init.internal.Activator start
INFO   | jvm 2    | 2021/01/05 14:35:20 | INFO: Setting configuration directory to C:\SoftwareAG\profiles\IS_default/configuration
INFO   | jvm 2    | 2021/01/05 14:35:20 | Jan 05, 2021 2:35:20 PM com.webmethods.sc.config.ConfigurationLogger log
INFO   | jvm 2    | 2021/01/05 14:35:20 | INFO: Out-of-band file changes will be monitored every '60000' milliseconds
INFO   | jvm 2    | 2021/01/05 14:35:20 | Jan 05, 2021 2:35:20 PM com.softwareag.platform.logging.init.internal.Activator start
**INFO   | jvm 2    | 2021/01/05 14:35:20 | INFO: Initializing Journal Logger with the greedy JUL bridge**
**INFO   | jvm 2    | 2021/01/05 14:46:35 |** 
INFO   | jvm 2    | 2021/01/05 14:46:35 | !ENTRY org.eclipse.equinox.ds 1 0 2021-01-05 14:46:35.407
INFO   | jvm 2    | 2021/01/05 14:46:35 | !MESSAGE Could not bind a reference of component evpServiceTypeConfigurationService. The reference is: Reference[name = JmxConnectorFactoryService, interface = com.softwareag.platform.management.core.jmx.JmxConnectorFactoryService, policy = dynamic, cardinality = 0..1, target = null, bind = setJMXConnectorService, unbind = unsetJMXConnectorService]
INFO   | jvm 2    | 2021/01/05 14:46:35 | 
INFO   | jvm 2    | 2021/01/05 14:46:35 | !ENTRY org.eclipse.equinox.ds 1 0 2021-01-05 14:46:35.407
INFO   | jvm 2    | 2021/01/05 14:46:35 | !MESSAGE Could not bind a reference of component evpServiceTypeConfigurationService. The reference is: Reference[name = InventoryExService, interface = com.softwareag.platform.management.inventory.spi.InventoryExService, policy = dynamic, cardinality = 0..1, target = null, bind = setInventoryService, unbind = unsetInventoryService]
INFO   | jvm 2    | 2021/01/05 14:46:35 | 
INFO   | jvm 2    | 2021/01/05 14:46:35 | !ENTRY org.eclipse.equinox.ds 1 0 2021-01-05 14:46:35.422
INFO   | jvm 2    | 2021/01/05 14:46:35 | !MESSAGE Could not bind a reference of component EvpServiceTypeDES. The reference is: Reference[name = JmxConnectorFactoryService, interface = com.softwareag.platform.management.core.jmx.JmxConnectorFactoryService, policy = dynamic, cardinality = 0..1, target = null, bind = setJMXConnectorService, unbind = unsetJMXConnectorService]
INFO   | jvm 2    | 2021/01/05 14:46:35 | 
INFO   | jvm 2    | 2021/01/05 14:46:35 | !ENTRY org.eclipse.equinox.ds 1 0 2021-01-05 14:46:35.422
INFO   | jvm 2    | 2021/01/05 14:46:35 | !MESSAGE Could not bind a reference of component EvpServiceTypeDES. The reference is: Reference[name = InventoryExService, interface = com.softwareag.platform.management.inventory.spi.InventoryExService, policy = dynamic, cardinality = 0..1, target = null, bind = setInventoryService, unbind = unsetInventoryService]
INFO   | jvm 2    | 2021/01/05 14:46:35 | 
INFO   | jvm 2    | 2021/01/05 14:46:35 | !ENTRY org.eclipse.equinox.ds 1 0 2021-01-05 14:46:35.438
**INFO   | jvm 2    | 2021/01/05 14:46:35 | !MESS**AGE Could not bind a reference of component com.softwareag.platform.proxy.PlatformProxySelector. The reference is: Reference[name = Proxy, interface = com.softwareag.platform.proxy.PlatformProxy, policy = dynamic, policy-option = reluctant, cardinality = 0..n, target = null, bind = addProxy, unbind = removeProxy, updated = null]
**INFO   | jvm 2    | 2021/01/05 14:51:34** | 
INFO   | jvm 2    | 2021/01/05 14:51:34 | !ENTRY com.softwareag.platform.hook.mirrors 1 0 2021-01-05 14:51:34.294
INFO   | jvm 2    | 2021/01/05 14:51:34 | !MESSAGE Overriding ClassLoader of com.softwareag.osgi.is.proxy_10.3.0.0012-0118 with tracker (service.pid=com.softwareag.osgi.is.classloader)
INFO   | jvm 2    | 2021/01/05 14:51:40 | SecurityConfiguration for ESAPI.Logger not found in ESAPI.properties. Using default: org.owasp.esapi.reference.JavaLogFactory
INFO   | jvm 2    | 2021/01/05 14:51:40 | SecurityConfiguration for ESAPI.Logger not found in ESAPI.properties. Using default: org.owasp.esapi.reference.JavaLogFactory
INFO   | jvm 2    | 2021/01/05 14:51:40 | SecurityConfiguration for ESAPI.Logger not found in ESAPI.properties. Using default: org.owasp.esapi.reference.JavaLogFactory
INFO   | jvm 2    | 2021/01/05 14:51:40 | SecurityConfiguration for ESAPI.Logger not found in ESAPI.properties. Using default: org.owasp.esapi.reference.JavaLogFactory
INFO   | jvm 2    | 2021/01/05 14:51:41 | INFO: Getting audit  config from it's default location.
INFO   | jvm 2    | 2021/01/05 14:51:41 | WARNING: Audit configuration neither exists, nor could be found on the classpath. Auditing will not work.
**INFO   | jvm 2    | 2021/01/05 14:51:41 | INFO: Using dummy audit implementation.**
**INFO   | jvm 2    | 2021/01/05 15:03:31 | SLF4J: Class path contains multiple SLF4J bindings.**
INFO   | jvm 2    | 2021/01/05 15:03:31 | SLF4J: Found binding in [jar:file:C:/SoftwareAG/common/lib/ext/slf4j-log4j.jar!/org/slf4j/impl/StaticLoggerBinder.class]
INFO   | jvm 2    | 2021/01/05 15:03:31 | SLF4J: Found binding in [jar:file:C:/SoftwareAG/common/lib/ext/slf4j-jdk14.jar!/org/slf4j/impl/StaticLoggerBinder.class]
INFO   | jvm 2    | 2021/01/05 15:03:31 | SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
INFO   | jvm 2    | 2021/01/05 15:03:31 | SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
INFO   | jvm 2    | 2021/01/05 15:03:34 | [Tue Jan 05 15:03:34.615 GMT 2021] Setting log level to ERROR
INFO   | jvm 2    | 2021/01/05 15:03:34 | --------- Log File Closed ---------
INFO   | jvm 2    | 2021/01/05 15:03:34 | 
INFO   | jvm 2    | 2021/01/05 15:03:34 | 
INFO   | jvm 2    | 2021/01/05 15:07:37 | Successfully loaded PSUtilities configuration file into memory

Once this restart is done, the later on restarts will be quick, untill we merge the code again.

I highlighted the hung or gap between timestamps in bold.

Regards,
Firoz Nalband.

Kalpesh_Shah1 · January 5, 2021, 3:34pm

Hi Firoz,

Can you please take few thread dumps during the startup when problem occurs?

Thanks,
-Kalpesh.

Firoz · January 8, 2021, 3:54pm

Hi Kalpesh,

I am running Integration server as a windows service and tried to use below commands, but not sure if this work like that. Please check and update

C:\SoftwareAG\jvm\jvm\bin>jstack -F 12876
Attaching to process ID 12876, please wait...
Error attaching to process: Doesn't appear to be a HotSpot VM (could not find symbol "gHotSpotVMTypes" in remote process)
sun.jvm.hotspot.debugger.DebuggerException: Doesn't appear to be a HotSpot VM (could not find symbol "gHotSpotVMTypes" in remote process)
        at sun.jvm.hotspot.HotSpotAgent.setupVM(HotSpotAgent.java:411)

C:\SoftwareAG\jvm\jvm\bin>jstack -l 12876
12876: jvm.dll not loaded by target process
The -F option can be used when the target process is not responding

PID is taken from Services under TaskManager

Can you check let me know exact step to run this on Windows.

Regards,
Firoz N

Kalpesh_Shah1 · January 8, 2021, 9:57pm

Hi Firoz,

Can you please try executing

service.bat -dump …\configuration\wrapper.conf

from profiles\IS_\bin directory and see if it generates thread dump in wrapper.log?

Regards,
-Kalpesh.

Firoz · January 12, 2021, 5:54pm

Hi Kalpesh,

I manage to run the thread dump using above command you shared. I will explicitly run it again while there is ongoing issue during server start. Now I ran the thread dump when the server came up without any delays.

Hope I can run this in this order

Stop the IS service from Services.msc
Start the IS service from Services.msc
When I monitor that service is starting still and wrapper log is hung then
Open Command prompt
CD to SAGHome\profiles\IS_default\bin
Run service.bat -dump …\configuration\wrapper.conf
Hope it logs the thread dump in middle of IS startup process.

Thanks for your help

Regards,
Firoz N

Kalpesh_Shah1 · January 12, 2021, 8:59pm

Hi Firoz,

Yes, that should work.

Regards,
-Kalpesh.

Firoz · January 14, 2021, 5:54pm

Hi Kalpesh,

Here you find attached wrapper log file when the issue occurred. Let me know if you are able to find the culprit here.

WrapperLog_JVMDump.txt (138.6 KB)

You might find two thread dumps back to back when the first hung occurred, I tried to run the command again to see if any difference.

After some time the process resumed by writing some 4 lines of logs and again it got hung, then this time as well I ran JVM thread dump to capture that as well. 3rd time it got hung, I ran that time as well. So 3 hungs and 3 JVM dumps, then finally server started.

Hope this should be good enough for you to analyze and identify the root cause.

Let me know your findings. Thanks.

Regards,
Firoz N

Firoz · January 19, 2021, 2:53pm

Hi Kalpesh,

Did you manage to find the issue here? Any Tanuki wrapper parameters I can add in custom_wrapper.conf let me know, I will try to do it and verify if that fixes this issue?

Thanks.

Regards,
Firoz N

Kalpesh_Shah1 · January 19, 2021, 3:23pm

Hi Firoz,

I don’t see anything wrong in the thread dumps that you have provided. Does this slowness only happen on one specific node? Looking @ the dumps, it appears that Classloader is trying open ZIP files for loading classes. Can you please ensure that there is nothing wrong with the disk? If needed, can you run applications to check disk? Please see if this helps, if not you may want to raise support ticket for further analysis.

Regards,
-Kalpesh.

Firoz · January 19, 2021, 4:07pm

Hi Kalpesh,

I appreciate you checking on the thread dumps provided and confirming everything alright with it.

I will try to analyze this at OS level and see if something is blocking this, as if I restart system then IS service gets started without any delay, whenever this issue occurs.

Also for every restart this issue doesn’t happen and only once after merging GIT changes probably from main branch to feature branch.

I will update you if I find anything which can resolve this, I kept re-installing IS as last option for now.

Regards
Firoz N

system · April 19, 2021, 4:08pm

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.