Go Server failed and cannot start anymore

[Jessie Wei]

Hi all, 

Our go Server (Version 14.4.0) suddenly stopped and cannot started up any more this morning.

The go server service can be started. But just do not function.

This is part of the log from go-server file when the go server restarts:

2015-06-16 15:59:37,610  WARN [WrapperJarAppMain] ConfigurationFactory:134 - No configuration found. Configuring ehcache from ehcache-failsafe.xml  found in the classpath: jar:file:/C:/Program%20Files%20(x86)/Go%20Server/work/Jetty_0_0_0_0_8153_cruise.war__go__.mt8b37/webapp/WEB-INF/lib/ehcache-core-2.0.0.jar!/ehcache-failsafe.xml

2015-06-16 15:59:37,645  WARN [WrapperJarAppMain] CacheManager:566 - Creating a new instance of CacheManager using the diskStorePath "C:\Users\Administrator\AppData\Local\Temp\" which is already used by an existing CacheManager.

The source of the configuration was net.sf.ehcache.config.generator.ConfigurationSource$DefaultConfigurationSource@73b2eaec.

The diskStore path for this CacheManager will be set to C:\Users\Administrator\AppData\Local\Temp\\ehcache_auto_created_1434434377645.

To avoid this warning consider using the CacheManager factory methods to create a singleton CacheManager or specifying a separate ehcache configuration (ehcache.xml) for each CacheManager instance.

2015-06-16 15:59:37,775  WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [com.thoughtworks.go.domain.NotificationFilter]; using defaults.

2015-06-16 15:59:37,789  WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [com.thoughtworks.go.domain.User]; using defaults.

2015-06-16 15:59:37,792  WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [com.thoughtworks.go.config.EnvironmentVariableConfig]; using defaults.

2015-06-16 15:59:37,811  WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [com.thoughtworks.go.domain.User.notificationFilters]; using defaults.

2015-06-16 15:59:37,872  WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [org.hibernate.cache.UpdateTimestampsCache]; using defaults.

2015-06-16 15:59:37,875  WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [org.hibernate.cache.StandardQueryCache]; using defaults.

We have upgraded the Go Server from version 14.4.0 to 15.1.0. But the issue still exists.

Any one knows what may cause this issue?

Best regards,

[Aravind SV]

All of those are warnings. Do you have more logs shown below this?

--
You received this message because you are subscribed to the Google Groups "go-cd" group.
To unsubscribe from this group and stop receiving emails from it, send an email to go-cd+un...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Jessie Wei]

Hi Aravind,

this is the whole log after a Go Server Service restart:

2015-06-16 22:40:00,447  INFO [WrapperJarAppMain] GoJetty6SslSocketConnector:61 - Using SSL socket selector SslSelectChannelConnector (NIO) with maxIdleTime=30000

2015-06-16 22:40:00,692  INFO [WrapperJarAppMain] Jetty6Server:126 - Configuring Jetty using C:\Program Files (x86)\Go Server\config\jetty6.xml

2015-06-16 22:40:00,714  INFO [WrapperJarAppMain] GoServer:101 - Including addons: 

2015-06-16 22:40:09,249  INFO [WrapperJarAppMain] H2Database:128 - [db] Using connection configuration jdbc:h2:db\h2db/cruise;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=FALSE;MVCC=FALSE;CACHE_SIZE=131072;TRACE_LEVEL_FILE=1;TRACE_MAX_FILE_SIZE=16;DATABASE_EVENT_LISTENER='com.thoughtworks.go.server.util.H2EventListener' [User: sa]

2015-06-16 22:40:09,250  INFO [WrapperJarAppMain] H2Database:118 - Creating data source with url=jdbc:h2:db\h2db/cruise;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=FALSE;MVCC=FALSE;CACHE_SIZE=131072;TRACE_LEVEL_FILE=1;TRACE_MAX_FILE_SIZE=16;DATABASE_EVENT_LISTENER='com.thoughtworks.go.server.util.H2EventListener'

2015-06-16 22:40:09,254  INFO [WrapperJarAppMain] DbDeployMigration:48 - Upgrading database at org.apache.commons.dbcp.BasicDataSource@4f4ef0ab. This might take a while depending on the size of the database.

2015-06-16 22:40:09,319  INFO [WrapperJarAppMain] H2EventListener:30 - Initializing database: jdbc:h2:db\h2db/cruise

2015-06-16 22:40:11,589  INFO [WrapperJarAppMain] H2EventListener:82 - Creating index SYS:SYS_ID 0%

2015-06-16 22:40:11,590  INFO [WrapperJarAppMain] H2EventListener:82 - Creating index SYS:SYS_ID 0%

2015-06-16 22:40:11,712  INFO [WrapperJarAppMain] H2EventListener:34 - Database is opened

2015-06-16 22:40:11,717  INFO [WrapperJarAppMain] H2EventListener:30 - Initializing database: jdbc:h2:db\h2db/cruise

2015-06-16 22:40:11,745  INFO [WrapperJarAppMain] H2EventListener:30 - Initializing database: jdbc:h2:db\h2db/cruise

2015-06-16 22:40:11,749  INFO [WrapperJarAppMain] DbDeployMigration:63 - Database upgraded

2015-06-16 22:40:11,751  INFO [WrapperJarAppMain] H2EventListener:77 - Closing database

2015-06-16 22:40:12,122  INFO [WrapperJarAppMain] H2Database:128 - [db] Using connection configuration jdbc:h2:db\h2db/cruise;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=FALSE;MVCC=TRUE;CACHE_SIZE=131072;TRACE_LEVEL_FILE=1;TRACE_MAX_FILE_SIZE=16;DATABASE_EVENT_LISTENER='com.thoughtworks.go.server.util.H2EventListener' [User: sa]

2015-06-16 22:40:12,122  INFO [WrapperJarAppMain] H2Database:118 - Creating data source with url=jdbc:h2:db\h2db/cruise;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=FALSE;MVCC=TRUE;CACHE_SIZE=131072;TRACE_LEVEL_FILE=1;TRACE_MAX_FILE_SIZE=16;DATABASE_EVENT_LISTENER='com.thoughtworks.go.server.util.H2EventListener'

2015-06-16 22:40:12,922  INFO [WrapperJarAppMain] H2EventListener:30 - Initializing database: jdbc:h2:db\h2db/cruise

2015-06-16 22:40:12,992  INFO [WrapperJarAppMain] H2EventListener:82 - Creating index SYS:SYS_ID 0%

2015-06-16 22:40:12,993  INFO [WrapperJarAppMain] H2EventListener:82 - Creating index SYS:SYS_ID 0%

2015-06-16 22:40:13,036  INFO [WrapperJarAppMain] H2EventListener:34 - Database is opened

2015-06-16 22:40:13,048  INFO [WrapperJarAppMain] H2EventListener:30 - Initializing database: jdbc:h2:db\h2db/cruise

2015-06-16 22:40:13,126  WARN [WrapperJarAppMain] ConfigurationFactory:134 - No configuration found. Configuring ehcache from ehcache-failsafe.xml  found in the classpath: jar:file:/C:/Program%20Files%20(x86)/Go%20Server/work/Jetty_0_0_0_0_8153_cruise.war__go__.mt8b37/webapp/WEB-INF/lib/ehcache-core-2.0.0.jar!/ehcache-failsafe.xml

2015-06-16 22:40:13,160  WARN [WrapperJarAppMain] CacheManager:566 - Creating a new instance of CacheManager using the diskStorePath "C:\Users\Administrator\AppData\Local\Temp\" which is already used by an existing CacheManager.

The source of the configuration was net.sf.ehcache.config.generator.ConfigurationSource$DefaultConfigurationSource@a344072.

The diskStore path for this CacheManager will be set to C:\Users\Administrator\AppData\Local\Temp\\ehcache_auto_created_1434458413160.

To avoid this warning consider using the CacheManager factory methods to create a singleton CacheManager or specifying a separate ehcache configuration (ehcache.xml) for each CacheManager instance.

2015-06-16 22:40:13,324  WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [com.thoughtworks.go.domain.NotificationFilter]; using defaults.

2015-06-16 22:40:13,339  WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [com.thoughtworks.go.domain.User]; using defaults.

2015-06-16 22:40:13,343  WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [com.thoughtworks.go.config.EnvironmentVariableConfig]; using defaults.

2015-06-16 22:40:13,364  WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [com.thoughtworks.go.domain.User.notificationFilters]; using defaults.

2015-06-16 22:40:13,442  WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [org.hibernate.cache.UpdateTimestampsCache]; using defaults.

2015-06-16 22:40:13,450  WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [org.hibernate.cache.StandardQueryCache]; using defaults.

2015-06-16 22:40:13,962  INFO [WrapperJarAppMain] ServerVersion:69 - [Startup] Go Version: 15.1.0(1863-42e58c22aefd03)

2015-06-16 22:40:13,975  INFO [WrapperJarAppMain] ServerVersion:70 - [Startup] PID: 4264

2015-06-16 22:40:13,976  INFO [WrapperJarAppMain] ServerVersion:71 - [Startup] JVM properties: {java.vendor=Oracle Corporation, sun.java.launcher=SUN_STANDARD, app.server=com.thoughtworks.go.server.Jetty6Server, sun.management.compiler=HotSpot 64-Bit Tiered Compilers, os.name=Windows Server 2008 R2, sun.boot.class.path=C:\Program Files\Java\jre7\lib\resources.jar;C:\Program Files\Java\jre7\lib\rt.jar;C:\Program Files\Java\jre7\lib\sunrsasign.jar;C:\Program Files\Java\jre7\lib\jsse.jar;C:\Program Files\Java\jre7\lib\jce.jar;C:\Program Files\Java\jre7\lib\charsets.jar;C:\Program Files\Java\jre7\classes, sun.desktop=windows, java.vm.specification.vendor=Oracle Corporation, java.runtime.version=1.7.0-b147, wrapper.native_library=wrapper, jetty.xml.file.name=jetty6.xml, wrapper.key=EqOG47BFJxxujFQYeKJ3SfWcJ197-zCT, user.name=SYSTEM, wrapper.jvm.port.min=31000, user.language=en, sun.boot.library.path=C:\Program Files\Java\jre7\bin, java.version=1.7.0, user.timezone=Australia/Brisbane, org.eclipse.jetty.server.Request.maxFormContentSize=30000000, jetty.base=C:\Program Files (x86)\Go Server, sun.arch.data.model=64, java.endorsed.dirs=C:\Program Files\Java\jre7\lib\endorsed, sun.cpu.isalist=amd64, sun.jnu.encoding=Cp1252, file.encoding.pkg=sun.io, file.separator=\, java.specification.name=Java Platform API Specification, java.class.version=51.0, user.country=US, java.home=C:\Program Files\Java\jre7, java.vm.info=mixed mode, wrapper.version=3.3.5-st, os.version=6.1, no_gc_logging=, jruby.rack.request.size.threshold.bytes=30000000, path.separator=;, java.vm.version=21.0-b17, wrapper.pid=3668, wrapper.jvm.port.max=31999, user.variant=, java.protocol.handler.pkgs=com.simontuffs, cruise.server.ssl.port=8154, java.awt.printerjob=sun.awt.windows.WPrinterJob, sun.io.unicode.encoding=UnicodeLittle, awt.toolkit=sun.awt.windows.WToolkit, user.script=, user.home=C:\Users\Administrator, cruise.config.dir=C:\Program Files (x86)\Go Server\config, java.specification.vendor=Oracle Corporation, java.library.path=lib, java.vendor.url=http://java.oracle.com/, cruise.server.port=8153, net.sf.ehcache.skipUpdateCheck=true, java.vm.vendor=Oracle Corporation, wrapper.jvmid=1, java.runtime.name=Java(TM) SE Runtime Environment, sun.java.command=org.tanukisoftware.wrapper.WrapperJarApp go.jar, java.class.path=lib/wrapper.jar;go.jar, java.vm.specification.name=Java Virtual Machine Specification, java.vm.specification.version=1.7, sun.cpu.endian=little, sun.os.patch.level=, wrapper.cpu.timeout=10, java.io.tmpdir=C:\Users\Administrator\AppData\Local\Temp\, java.vendor.url.bug=http://bugreport.sun.com/bugreport/, no_debugging=, os.arch=amd64, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.ext.dirs=C:\Program Files\Java\jre7\lib\ext;C:\Windows\Sun\Java\lib\ext, user.dir=C:\Program Files (x86)\Go Server, cruise.config.file=C:\Program Files (x86)\Go Server\config\cruise-config.xml, line.separator=

, java.vm.name=Java HotSpot(TM) 64-Bit Server VM, org.mortbay.jetty.Request.maxFormContentSize=30000000, file.encoding=Cp1252, java.specification.version=1.7, wrapper.service=TRUE, rails.use.compressed.js=true, wrapper.port=32001, jetty.home=C:\Program Files (x86)\Go Server, JAVA_SYS_MON_TEMP_DIR=C:\Program Files (x86)\Go Server\tmp}

2015-06-16 22:40:13,978  INFO [WrapperJarAppMain] ServerVersion:72 - [Startup] Environment Variables: {USERPROFILE=C:\Users\Administrator, GO_SERVER_JAVA_HOME=C:\Program Files\Java\jre7, JAVA_HOME=C:\Program Files\Java\jre7, VS110COMNTOOLS=C:\Program Files (x86)\Microsoft Visual Studio 11.0\Common7\Tools\, SERVER_MAX_MEM=6144m, SystemDrive=C:, GO_SERVER=localhost, Path=C:\ProgramData\Oracle\Java\javapath;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\Microsoft SQL Server\100\Tools\Binn\;C:\Program Files\Microsoft SQL Server\100\Tools\Binn\;C:\Program Files\Microsoft SQL Server\100\DTS\Binn\;C:\Windows\idmu\common;C:\Program Files\Java\jre8\bin;D:\GoUtilities\zip;C:\Program Files\IIS\Microsoft Web Deploy V3;C:\Windows\Microsoft.NET\Framework64\v4.0.30319;C:\Program Files (x86)\Microsoft ASP.NET\ASP.NET Web Pages\v1.0\;C:\Program Files (x86)\Windows Kits\8.0\Windows Performance Toolkit\;C:\Program Files\Microsoft SQL Server\110\Tools\Binn\;C:\Program Files (x86)\Microsoft Visual Studio 11.0\Common7\IDE;D:\GoUtilities\Ruby200-x64\bin;C:\Program Files\GacUtil;C:\Program Files\7-Zip;C:\Program Files\Microsoft\Web Platform Installer\;C:\Program Files (x86)\Git\cmd;d:\deployment;C:\Program Files\Microsoft Network Monitor 3\, CRUISE_SERVER_DIR=C:\Program Files (x86)\Go Server, PROCESSOR_REVISION=0f01, WRAPPER_BITS=32, USERDOMAIN=SAUDEV04, ALLUSERSPROFILE=C:\ProgramData, WRAPPER_HOST_NAME=saudev04, WRAPPER_WORKING_DIR=C:\Program Files (x86)\Go Server, GO_AGENT_DIR=D:\GoAgent, TMP=C:\Users\Administrator\AppData\Local\Temp, LOGONSERVER=\\SAUDEV04, CommonProgramFiles=C:\Program Files\Common Files, VS100COMNTOOLS=C:\Program Files (x86)\Microsoft Visual Studio 10.0\Common7\Tools\, PROCESSOR_LEVEL=6, LOCALAPPDATA=C:\Users\Administrator\AppData\Local, COMPUTERNAME=SAUDEV04, GC_LOG=-Dno_gc_logging, SystemRoot=C:\Windows, USERNAME=SYSTEM, GO_AGENT_JAVA_HOME=D:\GoAgent\jre, APPDATA=C:\Users\Administrator\AppData\Roaming, ProgramData=C:\ProgramData, WRAPPER_FILE_SEPARATOR=\, PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC, WRAPPER_OS=windows, ProgramFiles(x86)=C:\Program Files (x86), WRAPPER_BIN_DIR=C:\Program Files (x86)\Go Server, TEMP=C:\Users\Administrator\AppData\Local\Temp, ProgramFiles=C:\Program Files, HOMEDRIVE=C:, =C:=C:\Program Files (x86)\Go Server, ProgramW6432=C:\Program Files, PROCESSOR_IDENTIFIER=Intel64 Family 6 Model 15 Stepping 1, GenuineIntel, SERVER_MEM=512m, JVM_DEBUG=-Dno_debugging, JVM_DEBUG_PORT=5005, GC_LOG_LOCATION="C:\Program Files (x86)\Go Server\go-server-gc.log", PROCESSOR_ARCHITECTURE=AMD64, FP_NO_HOST_CHECK=NO, OS=Windows_NT, WRAPPER_ARCH=x86, HOMEPATH=\Users\Administrator, CommonProgramW6432=C:\Program Files\Common Files, windir=C:\Windows, NUMBER_OF_PROCESSORS=4, PSModulePath=C:\Windows\system32\WindowsPowerShell\v1.0\Modules\;C:\Program Files (x86)\AWS Tools\PowerShell\, PUBLIC=C:\Users\Public, CommonProgramFiles(x86)=C:\Program Files (x86)\Common Files, ComSpec=C:\Windows\system32\cmd.exe, WRAPPER_PATH_SEPARATOR=;, EnableNuGetPackageRestore=true}

2015-06-16 22:40:17,854  INFO [WrapperJarAppMain] GoConfigMigration:198 - Config file is backed up, location: C:\Program Files (x86)\Go Server\config\cruise-config.xml.2015-06-16-22-40-17

2015-06-16 22:40:17,854  INFO [WrapperJarAppMain] GoConfigMigration:212 - Upgrading config file from version 74 to version 75

The Go Server is running on Windows. And the java.exe process still occupy more than 24% CPU 1 hour after restart. But the 8153 still not accessible. And the log never update since the first beginning. 

Thank you.

[Aravind SV]

Can you tell me what's going on now? I guess something happened to have caused this. Did anything change? I find it strange that it suddenly doesn't start, for no reason. Can you run jstack on that process, as the user that the Go Server runs as, and send the output? Might help to see what it is (was) doing, using 24% CPU.

[Jessie Wei]

Hi Avarind,

The java.exe process still hangs for more than 6 hours. When I run the jstack. I just got the error:

Attaching to core -F from executable 1000, please wait...

Error attaching to core file: Windbg Error: OpenDumpFile failed!

And I tried to only include 1 pipeline group. The server can be started. And looks like everything works fine on that pipeline group.

But I changed cruise-config file back to the original one and restarts. The go server hangs.

One possible cause for the issue maybe the server was restarted a couple of minutes after the Go server was restarted. 

Best regards,

[Jessie Wei]

Hi Avarind, 

Just a bit update on the issue. 

We have a huge number of pipelines on the Go Server. 

I started from including no pipeline group cruise config file, and then including back 1 pipeline group, and then including back a couple of more pipeline groups, the new cruise config can be reloaded successfully until I included a batch of pipeline group. As can be seen from the Go server log,  the thread cachedGoConfigRefreshExecutorThread hangs again:

2015-06-17 11:54:53,883  INFO [cachedGoConfigRefreshExecutorThread] GoConfigDataSource:125 - Config file changed at 1434506076223

2015-06-17 11:54:53,884  INFO [cachedGoConfigRefreshExecutorThread] GoConfigDataSource:126 - Reloading config file: C:\Program Files (x86)\Go Server\config\cruise-config.xml  

It never returns the 

CachedGoConfig:112 - Finished notifying all listeners

log message.

I think it may be issues for this batch of pipeline groups. The java.exe CPU increases again.

I think these pipeline groups cause issues.

Best regards,

[Aravind SV]

On Tue, Jun 16, 2015 at 11:49 PM, Jessie Wei <jessi...@gmail.com> wrote:

We have a huge number of pipelines on the Go Server. 

How many? I've seen it handle at least a 1000 pipelines on the default database, given that there is enough RAM. I wonder if it is stuck in garbage collection. You can try increasing the memory given to the Go process, if possible.

I started from including no pipeline group cruise config file, and then including back 1 pipeline group, and then including back a couple of more pipeline groups, the new cruise config can be reloaded successfully until I included a batch of pipeline group. As can be seen from the Go server log,  the thread cachedGoConfigRefreshExecutorThread hangs again:

2015-06-17 11:54:53,883  INFO [cachedGoConfigRefreshExecutorThread] GoConfigDataSource:125 - Config file changed at 1434506076223

2015-06-17 11:54:53,884  INFO [cachedGoConfigRefreshExecutorThread] GoConfigDataSource:126 - Reloading config file: C:\Program Files (x86)\Go Server\config\cruise-config.xml  

It never returns the 

CachedGoConfig:112 - Finished notifying all listeners

log message.

It would really help if you figured out how to get the stack trace, when it is stuck there. Without that data, it's all just guesses. Maybe this will help get jstack working.

[Jessie Wei]

Hi Aravind, 

Sorry for late reply. I have found out why the Go Server hanged. We are using ruby rake to maintain the update of the cruise configuration file from source control.    

We have a task configuration as below: 

 <tasks>

    <exec command="7z a -t7z test.7z go* tools\*.dll " />

 </tasks>

As you can see there is a empty space at the end of the command text. When the Go server service restarts, the Go server will hang forever with CPU more than 25%. 

If we remove the empty space from the config, the server can be started successfully:

 <tasks>

    <exec command="7z a -t7z test.7z go* tools\*.dll" />

 </tasks>

Even if I updated the configuration via Config XML in the Go Console by adding the extra space at the end of the command text, the web page will hangs as well after I clicked the Save button.   

I used a online Regular Expression Validator (http://www.regexplanet.com/advanced/java/index.html) to check whether the text is conformed to the regular expression used in the command text field. Even the validator is having error: The second test is without space at the end while the third test is having space at the end. 

I believe it is the combination of backslash and space making the parsing hangs forever. 

Best regards,