Looks like this is a bug that was introduced in v22.1.0. If you check connection on a private URL and your auth isn't correct it will timeout the entire server. I've verified it works in v21.4.0, v21.3.0, and v21.1.0.
I've bug reported this as I'm guessing the main server thread is doing the check instead of a child thread. Hence the timeout taking the entire server down. On Wednesday, June 29, 2022 at 1:32:41 PM UTC-6 [email protected] wrote: > Howdy all, > > Sorry got pulled off onto another project and just got back to this. > > I did diff the log files from a clean launch of GoCD vs a crashing one. > The only difference was the JVM saying it was restarting. > I tried setting the wrapper.ping.interval and timeout.action and let it > run over night. It never completed. > > I doubt the NAS resources are the issues as it's still got 4GB of free > memory and the CPU is only at 6-10% usage. > > I ultimately just deleted the container and recreated it with the previous > container's volumes and it launched cleanly. Once it came up I could see > the error that Github no longer supports username and passwords to private > repos. Somehow the previous container got in a weird state from this error > and just had to be rebuilt, which isn't great to be honest. Don't like the > idea of an external material being able to take down all my pipelines. > > Anyway, thanks for the help. Guess next time I know to just rebuild the > server container as it can get in a weird state. > > On Thursday, June 16, 2022 at 10:41:55 PM UTC-6 Chad Wilson wrote: > >> The LDAP plugin is bundled and it is just trying to initialise/load the >> plugin. The error can be ignored - as it says in the subsequent log line >> "Not all plugins are required to implement the request above. This error >> may be safe to ignore.". >> >> Unfortunately I'm not sure what to do about your problem - there's still >> not much information there to go on that I can see. :-( It looks like the >> JVM has been stopped which is weird ("JVM process was stopped") or perhaps >> is running extremely slowly/hung for some reason. There aren't any logs >> that indicate it's trying to interact with your material at the time the >> JVM seems to get stuck. I can't really understand why it would be different >> between a private/public repo, unless there is something else you are >> changing in between attempts. >> >> My only thoughts are >> >> - What does the CPU usage look like of the process/container up to >> when it crashes? >> - On the assumption that the wrapper is prematurely killing the JVM, >> you could try and increase wrapper.ping.interval >> <https://wrapper.tanukisoftware.com/doc/english/prop-ping-interval.html> >> in the wrapper-config/wrapper-properties.conf to see if it eventually >> recovers if given longer. Alternatively change >> wrapper.ping.timeout.action >> >> <https://wrapper.tanukisoftware.com/doc/english/prop-ping-timeout.html#action> >> >> to "DUMP" or "NONE" rather than the default of RESTART to disable it. >> Difficult to interpret the output of DUMP, but might give some clues. >> - Perhaps you can compare the server logs in the "good" and >> "crashing" case and see what you are missing in the crashing case to >> determine where it has got up to. >> - I'm not sure on your Synology NAS spec, but generally I'd have >> thought this might be too constrained an environment to run a GoCD server >> except with quite a bit of tweaking. Not sure though, never tried it. Can >> you replicate the problem when running via Docker on a regular >> machine/laptop? If not, it may be that Synology DSM is doing something to >> protect itself from a container that is using too many resources. >> >> -Chad >> >> On Fri, Jun 17, 2022 at 12:35 AM Lawrence Spear <[email protected]> >> wrote: >> >>> Hi Chad, >>> >>> Thanks for the reply. Totally forgot about wrapper.log. This is my first >>> time to setup GoCD in a few years and it's a little different now and using >>> docker I sort of glossed over the actual running of wrapper since docker >>> "magically" did it for me. >>> >>> As for what I mean by crashing, when going to the GoCD site it gives you >>> the GoCD server is starting please wait message after a while it will >>> complete and a few moments after that it will go back to starting please >>> wait. Looking in the wrapper.log it looks like the JVM is being killed and >>> restarted after a timeout. Oddly the only errors are around the LDAP >>> plugin, which is really strange since I don't use that. Only the file >>> password plugin. When I have the repo set to public and I start the server >>> I still get the ldap errors, but GoCD starts fine, so I'd assume the LDAP >>> error can be ignored. >>> >>> As for external config settings I'm just setting the port and volumes >>> (/home/go and /godata). I'd copy/paste the command line here, but I use >>> Synology NAS's docker GUI to launch this container, since I'm lazy and also >>> still a docker newbie. >>> >>> Here's the config.xml: >>> >>> <?xml version="1.0" encoding="utf-8"?> >>> <cruise xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; >>> xsi:noNamespaceSchemaLocation="cruise-config.xsd" schemaVersion="139"> >>> <server agentAutoRegisterKey=" redacted " webhookSecret=" redacted " >>> serverId=" redacted " tokenGenerationKey=" redacted "> >>> <security> >>> <authConfigs> >>> <authConfig id="users" >>> pluginId="cd.go.authentication.passwordfile"> >>> <property> >>> <key>PasswordFilePath</key> >>> <value>/home/go/users</value> >>> </property> >>> </authConfig> >>> </authConfigs> >>> </security> >>> <backup emailOnSuccess="true" emailOnFailure="true" /> >>> <artifacts> >>> <artifactsDir>artifacts</artifactsDir> >>> </artifacts> >>> </server> >>> <pipelines group="defaultGroup"> >>> <pipeline name="Test"> >>> <materials> >>> <git url="https://github.com/mtmg-li/Pipeline-Test.git"; >>> branch="main" username="redacted" encryptedPassword="AES: redacted" /> >>> </materials> >>> <stage name="Test"> >>> <jobs> >>> <job name="Test"> >>> <tasks> >>> <exec command="ls" /> >>> </tasks> >>> </job> >>> </jobs> >>> </stage> >>> </pipeline> >>> </pipelines> >>> </cruise> >>> >>> The config is really as simple as it gets, since I'd just started >>> configuring the server. >>> >>> Here's what's in the other logs: >>> >>> go-server-perf.log - empty >>> plugin-cd.go.authentication.ldap.log: >>> 2022-06-16 15:06:29,024 INFO [Thread-78] LdapPlugin:72 - Loading plugin >>> null version 2.2.0-144 >>> 2022-06-16 15:06:29,103 ERROR [Thread-78] LdapPlugin:127 - Error while >>> executing request go.plugin-settings.get-configuration >>> com.thoughtworks.go.plugin.api.exceptions.UnhandledRequestTypeException: >>> This is an invalid request type :go.plugin-settings.get-configuration >>> at >>> cd.go.plugin.base.dispatcher.RequestDispatcher.dispatch(RequestDispatcher.java:45) >>> at cd.go.authentication.ldap.LdapPlugin.handle(LdapPlugin.java:68) >>> at >>> com.thoughtworks.go.plugin.infra.DefaultPluginManager.lambda$submitTo$0(DefaultPluginManager.java:134) >>> at >>> com.thoughtworks.go.plugin.infra.FelixGoPluginOSGiFramework.executeActionOnTheService(FelixGoPluginOSGiFramework.java:208) >>> at >>> com.thoughtworks.go.plugin.infra.FelixGoPluginOSGiFramework.doOn(FelixGoPluginOSGiFramework.java:164) >>> at >>> com.thoughtworks.go.plugin.infra.DefaultPluginManager.submitTo(DefaultPluginManager.java:131) >>> at >>> com.thoughtworks.go.plugin.access.PluginRequestHelper.submitRequest(PluginRequestHelper.java:49) >>> at >>> com.thoughtworks.go.plugin.access.common.AbstractExtension.getPluginSettingsConfiguration(AbstractExtension.java:56) >>> at >>> com.thoughtworks.go.plugin.access.common.settings.PluginSettingsMetadataLoader.lambda$findSettingsAndViewOfAllExtensionsIn$2(PluginSettingsMetadataLoader.java:84) >>> at java.base/java.util.stream.ReferencePipeline$3$1.accept(Unknown >>> Source) >>> at java.base/java.util.stream.ReferencePipeline$2$1.accept(Unknown >>> Source) >>> at >>> java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(Unknown >>> Source) >>> at java.base/java.util.stream.AbstractPipeline.copyInto(Unknown >>> Source) >>> at >>> java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source) >>> at >>> java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(Unknown >>> Source) >>> at java.base/java.util.stream.AbstractPipeline.evaluate(Unknown >>> Source) >>> at java.base/java.util.stream.ReferencePipeline.collect(Unknown >>> Source) >>> at >>> com.thoughtworks.go.plugin.access.common.settings.PluginSettingsMetadataLoader.findSettingsAndViewOfAllExtensionsIn(PluginSettingsMetadataLoader.java:89) >>> at >>> com.thoughtworks.go.plugin.access.common.settings.PluginSettingsMetadataLoader.fetchPluginSettingsMetaData(PluginSettingsMetadataLoader.java:59) >>> at >>> com.thoughtworks.go.plugin.access.common.settings.PluginSettingsMetadataLoader.pluginLoaded(PluginSettingsMetadataLoader.java:49) >>> at >>> com.thoughtworks.go.plugin.infra.PluginLoader.lambda$doPostBundleInstallActivities$0(PluginLoader.java:113) >>> at >>> org.apache.commons.collections4.IteratorUtils.forEach(IteratorUtils.java:1224) >>> at >>> org.apache.commons.collections4.IterableUtils.forEach(IterableUtils.java:585) >>> at >>> com.thoughtworks.go.plugin.infra.PluginLoader.lambda$doPostBundleInstallActivities$1(PluginLoader.java:113) >>> at >>> org.apache.commons.collections4.IteratorUtils.forEach(IteratorUtils.java:1224) >>> at >>> org.apache.commons.collections4.IterableUtils.forEach(IterableUtils.java:585) >>> at >>> com.thoughtworks.go.plugin.infra.PluginLoader.doPostBundleInstallActivities(PluginLoader.java:112) >>> at >>> com.thoughtworks.go.plugin.infra.PluginLoader.loadPlugin(PluginLoader.java:70) >>> at >>> com.thoughtworks.go.plugin.infra.listeners.DefaultPluginJarChangeListener.refreshBundle(DefaultPluginJarChangeListener.java:180) >>> at >>> com.thoughtworks.go.plugin.infra.listeners.DefaultPluginJarChangeListener.addPlugin(DefaultPluginJarChangeListener.java:123) >>> at >>> com.thoughtworks.go.plugin.infra.listeners.DefaultPluginJarChangeListener.pluginJarAdded(DefaultPluginJarChangeListener.java:72) >>> at >>> com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread$DoOnAllListeners.lambda$pluginJarAdded$0(DefaultPluginJarLocationMonitor.java:237) >>> at >>> com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread$DoOnAllListeners.doOnAllPluginJarChangeListener(DefaultPluginJarLocationMonitor.java:258) >>> at >>> com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread$DoOnAllListeners.pluginJarAdded(DefaultPluginJarLocationMonitor.java:237) >>> at >>> com.thoughtworks.go.plugin.infra.monitor.PluginChangeNotifier.lambda$notify$0(PluginChangeNotifier.java:33) >>> at java.base/java.lang.Iterable.forEach(Unknown Source) >>> at >>> com.thoughtworks.go.plugin.infra.monitor.PluginChangeNotifier.notify(PluginChangeNotifier.java:30) >>> at >>> com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread.loadAndNotifyPluginsFrom(DefaultPluginJarLocationMonitor.java:204) >>> at >>> com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread.oneShot(DefaultPluginJarLocationMonitor.java:191) >>> at >>> com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread.run(DefaultPluginJarLocationMonitor.java:177) >>> >>> plugin-cd.go.authentication.passwordfile.log: >>> 2022-06-16 15:06:30,609 INFO [Thread-78] PasswordFilePlugin:72 - >>> Loading plugin null version 2.1.0-123 >>> 2022-06-16 15:06:30,629 WARN [Thread-78] PasswordFilePlugin:97 - >>> Request go.plugin-settings.get-configuration is not supported by plugin. >>> >>> web-requests.log - empty >>> >>> wrapper.log: >>> >>> WARN | wrapper | 2022/06/16 15:06:09 | The >>> "wrapper.java.additional.100" property was redefined on line #41 of >>> configuration file: /go-server/wrapper-config/wrapper-properties.conf >>> WARN | wrapper | 2022/06/16 15:06:09 | Old Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | New Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | The >>> "wrapper.java.additional.100" property was redefined on line #42 of >>> configuration file: /go-server/wrapper-config/wrapper-properties.conf >>> WARN | wrapper | 2022/06/16 15:06:09 | Old Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | New Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | The >>> "wrapper.java.additional.100" property was redefined on line #43 of >>> configuration file: /go-server/wrapper-config/wrapper-properties.conf >>> WARN | wrapper | 2022/06/16 15:06:09 | Old Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | New Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | The >>> "wrapper.java.additional.100" property was redefined on line #44 of >>> configuration file: /go-server/wrapper-config/wrapper-properties.conf >>> WARN | wrapper | 2022/06/16 15:06:09 | Old Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | New Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | The >>> "wrapper.java.additional.100" property was redefined on line #45 of >>> configuration file: /go-server/wrapper-config/wrapper-properties.conf >>> WARN | wrapper | 2022/06/16 15:06:09 | Old Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | New Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | The >>> "wrapper.java.additional.100" property was redefined on line #46 of >>> configuration file: /go-server/wrapper-config/wrapper-properties.conf >>> WARN | wrapper | 2022/06/16 15:06:09 | Old Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | New Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | The >>> "wrapper.java.additional.100" property was redefined on line #47 of >>> configuration file: /go-server/wrapper-config/wrapper-properties.conf >>> WARN | wrapper | 2022/06/16 15:06:09 | Old Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> WARN | wrapper | 2022/06/16 15:06:09 | New Value >>> wrapper.java.additional.100=-Dgo.console.stdout=true >>> STATUS | wrapper | 2022/06/16 15:06:09 | --> Wrapper Started as Console >>> STATUS | wrapper | 2022/06/16 15:06:09 | Java Service Wrapper Standard >>> Edition 64-bit 3.5.49 >>> STATUS | wrapper | 2022/06/16 15:06:09 | Copyright (C) 1999-2022 >>> Tanuki Software, Ltd. All Rights Reserved. >>> STATUS | wrapper | 2022/06/16 15:06:09 | >>> http://wrapper.tanukisoftware.com >>> STATUS | wrapper | 2022/06/16 15:06:09 | Licensed to ThoughtWorks for >>> GoCD Server >>> STATUS | wrapper | 2022/06/16 15:06:09 | >>> STATUS | wrapper | 2022/06/16 15:06:09 | Launching a JVM... >>> INFO | jvm 1 | 2022/06/16 15:06:10 | WrapperManager: Initializing... >>> INFO | jvm 1 | 2022/06/16 15:06:10 | [Thu Jun 16 15:06:10 GMT 2022] >>> Starting process: >>> INFO | jvm 1 | 2022/06/16 15:06:10 | [Thu Jun 16 15:06:10 GMT 2022] >>> Working directory : /go-working-dir >>> INFO | jvm 1 | 2022/06/16 15:06:10 | [Thu Jun 16 15:06:10 GMT 2022] >>> Application arguments: [] >>> INFO | jvm 1 | 2022/06/16 15:06:10 | [Thu Jun 16 15:06:10 GMT 2022] >>> GoCD Version: 22.1.0-13913 >>> INFO | jvm 1 | 2022/06/16 15:06:10 | [Thu Jun 16 15:06:10 GMT 2022] >>> Java Version: 17.0.2 >>> INFO | jvm 1 | 2022/06/16 15:06:10 | [Thu Jun 16 15:06:10 GMT 2022] >>> Operating System: Linux(4.4.180+) >>> INFO | jvm 1 | 2022/06/16 15:06:11 | Could not find file >>> `config/logback.xml'. Attempting to load from classpath. >>> INFO | jvm 1 | 2022/06/16 15:06:11 | Using classpath resource >>> `jar:onejar:lib/server-launcher-22.1.0-13913-main.jar!/config/logback.xml'. >>> INFO | jvm 1 | 2022/06/16 15:06:13 | 2022-06-16 15:06:13,280 INFO >>> [WrapperJarAppMain] Jetty9Server:199 - Configuring Jetty using >>> /go-working-dir/config/jetty.xml >>> INFO | jvm 1 | 2022/06/16 15:06:13 | 2022-06-16 15:06:13,350 WARN >>> [WrapperJarAppMain] Server:357 - ErrorPageMapper not supported for Server >>> level Error Handling >>> INFO | jvm 1 | 2022/06/16 15:06:13 | 2022-06-16 15:06:13,446 WARN >>> [WrapperJarAppMain] AbstractHandler:96 - No Server set for >>> ResourceHandler@e06552b{STOPPED} >>> INFO | jvm 1 | 2022/06/16 15:06:18 | 2022-06-16 15:06:18,900 WARN >>> [WrapperJarAppMain] ConnectionManager:117 - The file config/db.properties >>> specified by `go.db.config` does not exist. >>> INFO | jvm 1 | 2022/06/16 15:06:19 | 2022-06-16 15:06:19,373 INFO >>> [WrapperJarAppMain] DatabaseMigrator:40 - Upgrading database, this might >>> take a while depending on the size of the database. >>> INFO | jvm 1 | 2022/06/16 15:06:19 | >>> ************************************************************************ >>> INFO | jvm 1 | 2022/06/16 15:06:19 | 2022-06-16 15:06:19,374 INFO >>> [WrapperJarAppMain] DatabaseMigrator:49 - >>> ************************************************************************ >>> INFO | jvm 1 | 2022/06/16 15:06:19 | WARNING: Shutting down your >>> server at this point will lead to a database corruption. Please wait until >>> the database upgrade completes. >>> INFO | jvm 1 | 2022/06/16 15:06:19 | 2022-06-16 15:06:19,374 INFO >>> [WrapperJarAppMain] DatabaseMigrator:49 - WARNING: Shutting down your >>> server at this point will lead to a database corruption. Please wait until >>> the database upgrade completes. >>> INFO | jvm 1 | 2022/06/16 15:06:19 | >>> ************************************************************************ >>> INFO | jvm 1 | 2022/06/16 15:06:19 | 2022-06-16 15:06:19,374 INFO >>> [WrapperJarAppMain] DatabaseMigrator:49 - >>> ************************************************************************ >>> INFO | jvm 1 | 2022/06/16 15:06:19 | Jun 16, 2022 3:06:19 PM >>> liquibase.database >>> INFO | jvm 1 | 2022/06/16 15:06:19 | INFO: Set default schema name >>> to PUBLIC >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:19 PM >>> liquibase.lockservice >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Successfully acquired >>> change log lock >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.servicelocator >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Cannot load service: >>> liquibase.parser.ChangeLogParser: >>> liquibase.parser.core.json.JsonChangeLogParser Unable to get public no-arg >>> constructor >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.servicelocator >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Cannot load service: >>> liquibase.parser.ChangeLogParser: >>> liquibase.parser.core.yaml.YamlChangeLogParser Unable to get public no-arg >>> constructor >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/tfs-impl-14.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/go-plugin-activator.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/websocket-server-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-plus-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-deploy-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-webapp-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-servlet-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-security-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-server-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/websocket-servlet-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/javax.servlet-api-4.0.1.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/bcpkix-jdk15on-1.70.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/bcutil-jdk15on-1.70.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/bcprov-jdk15on-1.70.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/commons-io-2.6.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/commons-lang3-3.12.0.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/joda-time-2.10.14.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/log4j-over-slf4j-1.7.36.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jcl-over-slf4j-1.7.36.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jul-to-slf4j-1.7.36.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/logback-classic-1.2.11.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/slf4j-api-1.7.36.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-jmx-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-servlets-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/websocket-client-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-client-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-http-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/websocket-common-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-io-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-jndi-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-xml-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-util-ajax-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-util-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/logback-core-1.2.11.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/jetty-continuation-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/websocket-api-9.4.45.v20220203.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.resource >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Configured classpath >>> location onejar:lib/server-launcher-22.1.0-13913-main.jar does not exist >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.changelog >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Reading resource: >>> db-migration-scripts/migrations/2006.xml >>> INFO | jvm 1 | 2022/06/16 15:06:20 | Jun 16, 2022 3:06:20 PM >>> liquibase.changelog >>> INFO | jvm 1 | 2022/06/16 15:06:20 | INFO: Reading from >>> PUBLIC.DATABASECHANGELOG >>> INFO | jvm 1 | 2022/06/16 15:06:21 | Jun 16, 2022 3:06:21 PM >>> liquibase.servicelocator >>> INFO | jvm 1 | 2022/06/16 15:06:21 | INFO: Cannot load service: >>> liquibase.hub.HubService: Provider liquibase.hub.core.StandardHubService >>> could not be instantiated >>> INFO | jvm 1 | 2022/06/16 15:06:21 | Jun 16, 2022 3:06:21 PM >>> liquibase.lockservice >>> INFO | jvm 1 | 2022/06/16 15:06:21 | INFO: Successfully released >>> change log lock >>> INFO | jvm 1 | 2022/06/16 15:06:21 | INFO: Database upgrade >>> completed successfully. >>> INFO | jvm 1 | 2022/06/16 15:06:21 | 2022-06-16 15:06:21,144 INFO >>> [WrapperJarAppMain] DatabaseMigrator:57 - Database upgrade completed >>> successfully. >>> INFO | jvm 1 | 2022/06/16 15:06:21 | 2022-06-16 15:06:21,145 INFO >>> [WrapperJarAppMain] DataMigrationRunner:34 - Running data migrations... >>> INFO | jvm 1 | 2022/06/16 15:06:21 | 2022-06-16 15:06:21,189 INFO >>> [WrapperJarAppMain] DataMigrationRunner:49 - Data migration took 4 ms >>> INFO | jvm 1 | 2022/06/16 15:06:21 | 2022-06-16 15:06:21,193 INFO >>> [WrapperJarAppMain] DataMigrationRunner:49 - Data migration took 0 ms >>> INFO | jvm 1 | 2022/06/16 15:06:21 | 2022-06-16 15:06:21,193 INFO >>> [WrapperJarAppMain] DataMigrationRunner:39 - Data migrations completed. >>> INFO | jvm 1 | 2022/06/16 15:06:22 | 2022-06-16 15:06:22,035 WARN >>> [WrapperJarAppMain] ConfigurationFactory:136 - No configuration found. >>> Configuring ehcache from ehcache-failsafe.xml found in the classpath: >>> jar:file:/go-working-dir/work/jetty-0_0_0_0-8153-cruise_war-_go-any-/webapp/WEB-INF/lib/ehcache-2.10.9.2.jar!/ehcache-failsafe.xml >>> INFO | jvm 1 | 2022/06/16 15:06:22 | 2022-06-16 15:06:22,109 WARN >>> [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration >>> [com.thoughtworks.go.domain.AccessToken]; using defaults. >>> INFO | jvm 1 | 2022/06/16 15:06:22 | 2022-06-16 15:06:22,147 WARN >>> [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration >>> [com.thoughtworks.go.domain.NotificationFilter]; using defaults. >>> INFO | jvm 1 | 2022/06/16 15:06:22 | 2022-06-16 15:06:22,294 WARN >>> [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration >>> [com.thoughtworks.go.domain.User]; using defaults. >>> INFO | jvm 1 | 2022/06/16 15:06:22 | 2022-06-16 15:06:22,322 WARN >>> [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration >>> [com.thoughtworks.go.domain.Plugin]; using defaults. >>> INFO | jvm 1 | 2022/06/16 15:06:22 | 2022-06-16 15:06:22,335 WARN >>> [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration >>> [com.thoughtworks.go.domain.EnvironmentVariable]; using defaults. >>> INFO | jvm 1 | 2022/06/16 15:06:22 | 2022-06-16 15:06:22,381 WARN >>> [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration >>> [com.thoughtworks.go.domain.User.notificationFilters]; using defaults. >>> INFO | jvm 1 | 2022/06/16 15:06:22 | 2022-06-16 15:06:22,455 WARN >>> [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration >>> [org.hibernate.cache.UpdateTimestampsCache]; using defaults. >>> INFO | jvm 1 | 2022/06/16 15:06:22 | 2022-06-16 15:06:22,463 WARN >>> [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration >>> [org.hibernate.cache.StandardQueryCache]; using defaults. >>> INFO | jvm 1 | 2022/06/16 15:06:24 | 2022-06-16 15:06:24,311 WARN >>> [WrapperJarAppMain] BrokerService:2209 - Memory Usage for the Broker >>> (1024mb) is more than the maximum available for the JVM: 989 mb - resetting >>> to 70% of maximum available: 692 >>> INFO | jvm 1 | 2022/06/16 15:06:24 | 2022-06-16 15:06:24,636 INFO >>> [WrapperJarAppMain] ConnectionManager:98 - Done loading query extensions, >>> found com.thoughtworks.go.server.database.h2.H2QueryExtensions@3cf96df >>> INFO | jvm 1 | 2022/06/16 15:06:28 | 2022-06-16 15:06:28,602 INFO >>> [WrapperJarAppMain] GoConfigMigration:93 - Upgrading config file from >>> version 139 to version 139 >>> INFO | jvm 1 | 2022/06/16 15:06:28 | 2022-06-16 15:06:28,636 INFO >>> [WrapperJarAppMain] GoConfigMigration:101 - Finished upgrading config file >>> INFO | jvm 1 | 2022/06/16 15:06:28 | 2022-06-16 15:06:28,637 INFO >>> [WrapperJarAppMain] GoConfigMigrator:106 - [Config Save] Starting Config >>> Save post upgrade using FullConfigSaveNormalFlow >>> INFO | jvm 1 | 2022/06/16 15:06:28 | 2022-06-16 15:06:28,790 INFO >>> [Thread-78] DefaultPluginJarChangeListener:67 - Plugin load starting: >>> /go-working-dir/plugins/bundled/gocd-ldap-authentication-plugin.jar >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,023 INFO >>> [WrapperJarAppMain] CachedGoConfig:223 - About to notify config listeners >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,024 INFO >>> [Thread-78] p.c.g.a.l.c.g.a.l.LdapPlugin:72 >>> [plugin-cd.go.authentication.ldap] - Loading plugin null version 2.2.0-144 >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,094 INFO >>> [WrapperJarAppMain] CachedGoConfig:231 - Finished notifying all listeners >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,103 ERROR >>> [Thread-78] p.c.g.a.l.c.g.a.l.LdapPlugin:127 >>> [plugin-cd.go.authentication.ldap] - Error while executing request >>> go.plugin-settings.get-configuration >>> INFO | jvm 1 | 2022/06/16 15:06:29 | >>> com.thoughtworks.go.plugin.api.exceptions.UnhandledRequestTypeException: >>> This is an invalid request type :go.plugin-settings.get-configuration >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> cd.go.plugin.base.dispatcher.RequestDispatcher.dispatch(RequestDispatcher.java:45) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> cd.go.authentication.ldap.LdapPlugin.handle(LdapPlugin.java:68) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.DefaultPluginManager.lambda$submitTo$0(DefaultPluginManager.java:134) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.FelixGoPluginOSGiFramework.executeActionOnTheService(FelixGoPluginOSGiFramework.java:208) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.FelixGoPluginOSGiFramework.doOn(FelixGoPluginOSGiFramework.java:164) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.DefaultPluginManager.submitTo(DefaultPluginManager.java:131) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.access.PluginRequestHelper.submitRequest(PluginRequestHelper.java:49) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.access.common.AbstractExtension.getPluginSettingsConfiguration(AbstractExtension.java:56) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.access.common.settings.PluginSettingsMetadataLoader.lambda$findSettingsAndViewOfAllExtensionsIn$2(PluginSettingsMetadataLoader.java:84) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> java.base/java.util.stream.ReferencePipeline$3$1.accept(Unknown Source) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> java.base/java.util.stream.ReferencePipeline$2$1.accept(Unknown Source) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(Unknown >>> Source) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> java.base/java.util.stream.AbstractPipeline.copyInto(Unknown Source) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(Unknown >>> Source) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> java.base/java.util.stream.AbstractPipeline.evaluate(Unknown Source) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> java.base/java.util.stream.ReferencePipeline.collect(Unknown Source) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.access.common.settings.PluginSettingsMetadataLoader.findSettingsAndViewOfAllExtensionsIn(PluginSettingsMetadataLoader.java:89) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.access.common.settings.PluginSettingsMetadataLoader.fetchPluginSettingsMetaData(PluginSettingsMetadataLoader.java:59) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.access.common.settings.PluginSettingsMetadataLoader.pluginLoaded(PluginSettingsMetadataLoader.java:49) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.PluginLoader.lambda$doPostBundleInstallActivities$0(PluginLoader.java:113) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> org.apache.commons.collections4.IteratorUtils.forEach(IteratorUtils.java:1224) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> org.apache.commons.collections4.IterableUtils.forEach(IterableUtils.java:585) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.PluginLoader.lambda$doPostBundleInstallActivities$1(PluginLoader.java:113) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> org.apache.commons.collections4.IteratorUtils.forEach(IteratorUtils.java:1224) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> org.apache.commons.collections4.IterableUtils.forEach(IterableUtils.java:585) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.PluginLoader.doPostBundleInstallActivities(PluginLoader.java:112) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.PluginLoader.loadPlugin(PluginLoader.java:70) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.listeners.DefaultPluginJarChangeListener.refreshBundle(DefaultPluginJarChangeListener.java:180) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.listeners.DefaultPluginJarChangeListener.addPlugin(DefaultPluginJarChangeListener.java:123) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.listeners.DefaultPluginJarChangeListener.pluginJarAdded(DefaultPluginJarChangeListener.java:72) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread$DoOnAllListeners.lambda$pluginJarAdded$0(DefaultPluginJarLocationMonitor.java:237) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread$DoOnAllListeners.doOnAllPluginJarChangeListener(DefaultPluginJarLocationMonitor.java:258) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread$DoOnAllListeners.pluginJarAdded(DefaultPluginJarLocationMonitor.java:237) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.monitor.PluginChangeNotifier.lambda$notify$0(PluginChangeNotifier.java:33) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> java.base/java.lang.Iterable.forEach(Unknown Source) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.monitor.PluginChangeNotifier.notify(PluginChangeNotifier.java:30) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread.loadAndNotifyPluginsFrom(DefaultPluginJarLocationMonitor.java:204) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread.oneShot(DefaultPluginJarLocationMonitor.java:191) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | at >>> com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread.run(DefaultPluginJarLocationMonitor.java:177) >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,106 WARN >>> [Thread-78] PluginSettingsMetadataLoader:63 - Failed to fetch plugin >>> settings metadata for plugin cd.go.authentication.ldap. Maybe the plugin >>> does not implement plugin settings and view? >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,106 WARN >>> [Thread-78] PluginSettingsMetadataLoader:64 - Plugin: >>> cd.go.authentication.ldap - Metadata load info: >>> [{extension='authorization', configuration='null', view='null', error='The >>> plugin sent a response that could not be understood by Go. Plugin returned >>> with code '500' and the following response: 'This is an invalid request >>> type :go.plugin-settings.get-configuration''}] >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,107 WARN >>> [Thread-78] PluginSettingsMetadataLoader:65 - Not all plugins are required >>> to implement the request above. This error may be safe to ignore. >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,108 INFO >>> [Thread-78] DefaultPluginJarChangeListener:74 - Plugin load finished: >>> /go-working-dir/plugins/bundled/gocd-ldap-authentication-plugin.jar >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,148 INFO >>> [Thread-78] DefaultPluginJarChangeListener:67 - Plugin load starting: >>> /go-working-dir/plugins/bundled/gocd-file-based-secrets-plugin.jar >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,207 ERROR >>> [Thread-78] DefaultPluginManager:136 - This is an invalid request type >>> :go.plugin-settings.get-configuration >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,207 WARN >>> [Thread-78] PluginSettingsMetadataLoader:63 - Failed to fetch plugin >>> settings metadata for plugin cd.go.secrets.file-based-plugin. Maybe the >>> plugin does not implement plugin settings and view? >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,207 WARN >>> [Thread-78] PluginSettingsMetadataLoader:64 - Plugin: >>> cd.go.secrets.file-based-plugin - Metadata load info: >>> [{extension='secrets', configuration='null', view='null', >>> error='com.thoughtworks.go.plugin.api.exceptions.UnhandledRequestTypeException: >>> >>> This is an invalid request type :go.plugin-settings.get-configuration'}] >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,207 WARN >>> [Thread-78] PluginSettingsMetadataLoader:65 - Not all plugins are required >>> to implement the request above. This error may be safe to ignore. >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,226 INFO >>> [WrapperJarAppMain] BuildAssignmentService:251 - [Configuration Changed] >>> Removing jobs for pipelines that no longer exist in configuration. >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,252 INFO >>> [WrapperJarAppMain] >>> InvalidateAuthenticationOnSecurityConfigChangeFilter:78 - [Configuration >>> Changed] Security Configuration is changed. Updating the last changed time. >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,263 INFO >>> [Thread-78] DefaultPluginJarChangeListener:74 - Plugin load finished: >>> /go-working-dir/plugins/bundled/gocd-file-based-secrets-plugin.jar >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,268 INFO >>> [WrapperJarAppMain] PipelineRepository:78 - Start updating pipeline >>> timeline >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,274 INFO >>> [Thread-78] DefaultPluginJarChangeListener:67 - Plugin load starting: >>> /go-working-dir/plugins/bundled/gocd-yum-repository-poller-plugin.jar >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,294 INFO >>> [WrapperJarAppMain] PipelineRepository:84 - Pipeline timeline updated >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,295 INFO >>> [WrapperJarAppMain] PipelineSqlMapDao:135 - Loading active pipelines into >>> memory. >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,295 INFO >>> [WrapperJarAppMain] PipelineSqlMapDao:402 - Retriving Active Pipelines >>> from Database... >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,311 INFO >>> [Thread-81] PipelineSqlMapDao:443 - Loading pipeline history to >>> cache...Started >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,311 INFO >>> [Thread-80] PipelineSqlMapDao:434 - Loading Active Pipelines to >>> cache...Started >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,311 INFO >>> [WrapperJarAppMain] MaterialRepository:238 - Loading PMRs,Remaining 1 >>> Pipelines (Total: 1)... >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,313 INFO >>> [Thread-81] PipelineSqlMapDao:447 - Loading pipeline history to >>> cache...Done >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,314 INFO >>> [Thread-80] PipelineSqlMapDao:437 - Loading Active Pipelines to >>> cache...Done >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,342 INFO >>> [WrapperJarAppMain] MaterialRepository:313 - Loading modifications, >>> Remaining 1 PMRs(Total: 1)... >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,352 INFO >>> [WrapperJarAppMain] PipelineSqlMapDao:137 - Done loading active pipelines >>> into memory. >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,391 INFO >>> [WrapperJarAppMain] ConsoleActivityMonitor:78 - Found '0' building jobs. >>> Added them with '2022-06-16T15:06:29.353Z' as the last heard time >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,399 INFO >>> [WrapperJarAppMain] ConsoleActivityMonitor:79 - Found '0' scheduled jobs. >>> Added them with '2022-06-16T15:06:29.353Z' as the last heard time >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,406 INFO >>> [WrapperJarAppMain] RailsAssetsService:68 - Found rails assets manifest >>> file named .sprockets-manifest-b1796fd25cb1e0bd6dac0c9cba00d851.json >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,418 INFO >>> [WrapperJarAppMain] RailsAssetsService:72 - Successfully read rails assets >>> manifest file located at >>> /go-working-dir/work/jetty-0_0_0_0-8153-cruise_war-_go-any-/webapp/WEB-INF/rails/public/assets/.sprockets-manifest-b1796fd25cb1e0bd6dac0c9cba00d851.json >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,455 WARN >>> [Thread-78] PluginSettingsMetadataLoader:63 - Failed to fetch plugin >>> settings metadata for plugin yum. Maybe the plugin does not implement >>> plugin settings and view? >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,455 WARN >>> [Thread-78] PluginSettingsMetadataLoader:64 - Plugin: yum - Metadata load >>> info: [{extension='package-repository', configuration='null', view='null', >>> error='The plugin sent a response that could not be understood by Go. >>> Plugin returned with code '400' and the following response: 'Invalid >>> request name go.plugin-settings.get-configuration''}] >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,455 WARN >>> [Thread-78] PluginSettingsMetadataLoader:65 - Not all plugins are required >>> to implement the request above. This error may be safe to ignore. >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,498 ERROR >>> [Thread-78] PluginInfoBuilder:54 - Failed to fetch Plugin Settings metadata >>> for plugin yum. Maybe the plugin does not implement plugin settings and >>> view? >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,503 INFO >>> [Thread-78] DefaultPluginJarChangeListener:74 - Plugin load finished: >>> /go-working-dir/plugins/bundled/gocd-yum-repository-poller-plugin.jar >>> INFO | jvm 1 | 2022/06/16 15:06:29 | 2022-06-16 15:06:29,586 INFO >>> [Thread-78] DefaultPluginJarChangeListener:67 - Plugin load starting: >>> /go-working-dir/plugins/bundled/gocd-json-config-plugin.jar >>> INFO | jvm 1 | 2022/06/16 15:06:29 | jruby: warning: unknown >>> property jruby.rack.request.size.threshold.bytes >>> INFO | jvm 1 | 2022/06/16 15:06:30 | 2022-06-16 15:06:30,502 INFO >>> [Thread-78] ConfigRepositoryInitializer:108 - [Config Repository >>> Initializer] Start initializing the config repositories for plugin >>> 'json.config.plugin' >>> INFO | jvm 1 | 2022/06/16 15:06:30 | 2022-06-16 15:06:30,503 INFO >>> [Thread-78] ConfigRepositoryInitializer:112 - [Config Repository >>> Initializer] Done initializing the config repositories for plugin >>> 'json.config.plugin' >>> INFO | jvm 1 | 2022/06/16 15:06:30 | 2022-06-16 15:06:30,520 INFO >>> [Thread-78] DefaultPluginJarChangeListener:74 - Plugin load finished: >>> /go-working-dir/plugins/bundled/gocd-json-config-plugin.jar >>> INFO | jvm 1 | 2022/06/16 15:06:30 | 2022-06-16 15:06:30,537 INFO >>> [Thread-78] DefaultPluginJarChangeListener:67 - Plugin load starting: >>> /go-working-dir/plugins/bundled/gocd-filebased-authentication-plugin.jar >>> INFO | jvm 1 | 2022/06/16 15:06:30 | 2022-06-16 15:06:30,609 INFO >>> [Thread-78] p.c.g.a.p.c.g.a.p.PasswordFilePlugin:72 >>> [plugin-cd.go.authentication.passwordfile] - Loading plugin null version >>> 2.1.0-123 >>> INFO | jvm 1 | 2022/06/16 15:06:30 | 2022-06-16 15:06:30,629 WARN >>> [Thread-78] p.c.g.a.p.c.g.a.p.PasswordFilePlugin:97 >>> [plugin-cd.go.authentication.passwordfile] - Request >>> go.plugin-settings.get-configuration is not supported by plugin. >>> INFO | jvm 1 | 2022/06/16 15:06:30 | 2022-06-16 15:06:30,630 WARN >>> [Thread-78] PluginSettingsMetadataLoader:63 - Failed to fetch plugin >>> settings metadata for plugin cd.go.authentication.passwordfile. Maybe the >>> plugin does not implement plugin settings and view? >>> INFO | jvm 1 | 2022/06/16 15:06:30 | 2022-06-16 15:06:30,630 WARN >>> [Thread-78] PluginSettingsMetadataLoader:64 - Plugin: >>> cd.go.authentication.passwordfile - Metadata load info: >>> [{extension='authorization', configuration='null', view='null', error='The >>> plugin sent a response that could not be understood by Go. Plugin returned >>> with code '500' and the following response: 'Request >>> go.plugin-settings.get-configuration is not supported by plugin.''}] >>> INFO | jvm 1 | 2022/06/16 15:06:30 | 2022-06-16 15:06:30,630 WARN >>> [Thread-78] PluginSettingsMetadataLoader:65 - Not all plugins are required >>> to implement the request above. This error may be safe to ignore. >>> INFO | jvm 1 | 2022/06/16 15:06:30 | 2022-06-16 15:06:30,631 INFO >>> [Thread-78] DefaultPluginJarChangeListener:74 - Plugin load finished: >>> /go-working-dir/plugins/bundled/gocd-filebased-authentication-plugin.jar >>> INFO | jvm 1 | 2022/06/16 15:06:30 | 2022-06-16 15:06:30,678 INFO >>> [Thread-78] DefaultPluginJarChangeListener:67 - Plugin load starting: >>> /go-working-dir/plugins/bundled/gocd-yaml-config-plugin.jar >>> INFO | jvm 1 | 2022/06/16 15:06:31 | 2022-06-16 15:06:31,446 INFO >>> [Thread-78] ConfigRepositoryInitializer:108 - [Config Repository >>> Initializer] Start initializing the config repositories for plugin >>> 'yaml.config.plugin' >>> INFO | jvm 1 | 2022/06/16 15:06:31 | 2022-06-16 15:06:31,446 INFO >>> [Thread-78] ConfigRepositoryInitializer:112 - [Config Repository >>> Initializer] Done initializing the config repositories for plugin >>> 'yaml.config.plugin' >>> INFO | jvm 1 | 2022/06/16 15:06:31 | 2022-06-16 15:06:31,459 INFO >>> [Thread-78] DefaultPluginJarChangeListener:74 - Plugin load finished: >>> /go-working-dir/plugins/bundled/gocd-yaml-config-plugin.jar >>> INFO | jvm 1 | 2022/06/16 15:06:31 | 2022-06-16T15:06:31.583Z >>> [WrapperJarAppMain] WARN FilenoUtil : Native subprocess control requires >>> open access to the JDK IO subsystem >>> INFO | jvm 1 | 2022/06/16 15:06:31 | Pass '--add-opens java.base/ >>> sun.nio.ch=ALL-UNNAMED --add-opens java.base/java.io=ALL-UNNAMED' to >>> enable. >>> INFO | jvm 1 | 2022/06/16 15:06:33 | >>> uri:classloader:/jruby/rack/response.rb:294: warning: constant ::Fixnum is >>> deprecated >>> INFO | jvm 1 | 2022/06/16 15:06:33 | >>> uri:classloader:/jruby/rack/core_ext.rb:26: warning: constant :: >>> NativeException is deprecated >>> INFO | jvm 1 | 2022/06/16 15:06:42 | >>> /go-working-dir/work/jetty-0_0_0_0-8153-cruise_war-_go-any-/webapp/WEB-INF/rails/gems/jruby/2.6.0/gems/js-routes-1.4.14/lib/js_routes.rb:22: >>> >>> warning: Dir.exists? is a deprecated name, use Dir.exist? instead >>> INFO | jvm 1 | 2022/06/16 15:06:42 | >>> uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/socket.rb:4: warning: >>> already initialized constant Socket::Constants::AF_INET6 >>> INFO | jvm 1 | 2022/06/16 15:06:42 | >>> uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/socket.rb:4: warning: >>> already initialized constant Socket::Constants::IPPROTO_ICMPV6 >>> INFO | jvm 1 | 2022/06/16 15:06:42 | >>> uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/socket.rb:4: warning: >>> already initialized constant Socket::Constants::IPPROTO_IPV6 >>> INFO | jvm 1 | 2022/06/16 15:06:42 | >>> uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/socket.rb:4: warning: >>> already initialized constant Socket::Constants::PF_INET6 >>> INFO | jvm 1 | 2022/06/16 15:06:42 | >>> uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/socket.rb:4: warning: >>> already initialized constant Socket::Constants::SOL_IPV6 >>> INFO | jvm 1 | 2022/06/16 15:06:44 | 2022-06-16 15:06:44,022 WARN >>> [WrapperJarAppMain] DeprecationWarning:43 - Using @Deprecated Class >>> com.thoughtworks.go.server.web.DefaultHeadersFilter >>> INFO | jvm 1 | 2022/06/16 15:06:50 | 2022-06-16 15:06:50,714 INFO >>> [ThreadPoolTaskScheduler-3] GoFileConfigDataSource:263 - Config file >>> changed at 1655391989003 >>> INFO | jvm 1 | 2022/06/16 15:06:50 | 2022-06-16 15:06:50,715 INFO >>> [ThreadPoolTaskScheduler-3] GoFileConfigDataSource:264 - Reloading config >>> file: config/cruise-config.xml >>> INFO | jvm 1 | 2022/06/16 15:06:50 | 2022-06-16 15:06:50,770 INFO >>> [ThreadPoolTaskScheduler-3] CachedGoConfig:223 - About to notify config >>> listeners >>> INFO | jvm 1 | 2022/06/16 15:06:50 | 2022-06-16 15:06:50,774 INFO >>> [ThreadPoolTaskScheduler-3] BuildAssignmentService:251 - [Configuration >>> Changed] Removing jobs for pipelines that no longer exist in configuration. >>> INFO | jvm 1 | 2022/06/16 15:06:50 | 2022-06-16 15:06:50,775 INFO >>> [ThreadPoolTaskScheduler-3] CachedGoConfig:231 - Finished notifying all >>> listeners >>> WARN | wrapper | 2022/06/16 15:06:56 | JVM process was stopped. It >>> will be killed if the ping timeout expires. >>> STATUS | wrapper | 2022/06/16 15:07:29 | JVM appears hung: Timed out >>> waiting for signal from JVM. Restarting JVM. >>> STATUS | wrapper | 2022/06/16 15:07:29 | JVM received a signal SIGKILL >>> (9). >>> STATUS | wrapper | 2022/06/16 15:07:29 | JVM process is gone. >>> STATUS | wrapper | 2022/06/16 15:07:29 | JVM exited after being >>> requested to terminate. >>> STATUS | wrapper | 2022/06/16 15:07:34 | JVM process is gone. >>> >>> >>> On Thursday, June 16, 2022 at 4:57:57 AM UTC-6 Chad Wilson wrote: >>> >>>> Hi Lawrence >>>> >>>> That sounds odd - but there isn't really enough information below to >>>> tell anything. Those errors aren't of concern, or related. >>>> >>>> >>>> - Can you check what is contained within other log files in your >>>> log dir (/go-working-dir/logs by default) and >>>> /go-working-dir/wrapper.log? >>>> - Can you describe what you mean by "crashing"? Does the container >>>> die or get killed or just the Java process inside the container gets >>>> automatically restarted? >>>> - Can you include the rest of the logs (redacted if necessary) >>>> immediately before it "crashes"? >>>> - What external config settings are you starting the server or >>>> container with? >>>> >>>> -Chad >>>> >>>> >>>> On Thu, Jun 16, 2022 at 4:57 AM Lawrence Spear < >>>> [email protected]> wrote: >>>> >>>>> I seem to be unable to get GoCD to use a private repo on Github >>>>> without it completely crashing the server and putting it into a >>>>> continuous >>>>> restart/crash loop. >>>>> >>>>> I've set up a simple example GoCD docker instance using >>>>> gocd/gocd-server:v22.1.0 and gocd/gocd-agent-docker-dind:v22.1.0 with >>>>> only >>>>> 1 pipeline with a material that points a github repo that only contains a >>>>> ReadMe.md and execute the ls command. >>>>> >>>>> if the repo is public everything is fine. Even with or without >>>>> username/password included. >>>>> >>>>> if the repo is switched to private GoCD server will crash and get >>>>> stuck in a restart/crash loop till I switch the repo back to public. >>>>> >>>>> One bad material shouldn't be able to crash GoCD Server like this. I'd >>>>> guess I've got the correct username/password since it works fine when >>>>> public. The log file only contains two errors: >>>>> >>>>> 2022-06-15 20:50:08,040 ERROR [Thread-78] DefaultPluginManager:136 - >>>>> This is an invalid request type :go.plugin-settings.get-configuration >>>>> 2022-06-15 20:50:08,320 ERROR [Thread-78] PluginInfoBuilder:54 - >>>>> Failed to fetch Plugin Settings metadata for plugin yum. Maybe the plugin >>>>> does not implement plugin settings and view? >>>>> >>>>> The only errors in the log file for the agent seems to get be not >>>>> being able to find the server, so I'm guessing the agent isn't even being >>>>> assigned the job before the crash. >>>>> >>>>> Any ideas what is causing 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 [email protected]. >>>>> To view this discussion on the web visit >>>>> https://groups.google.com/d/msgid/go-cd/e78e96db-8b1d-48aa-a617-66f8fff422cfn%40googlegroups.com >>>>> >>>>> <https://groups.google.com/d/msgid/go-cd/e78e96db-8b1d-48aa-a617-66f8fff422cfn%40googlegroups.com?utm_medium=email&utm_source=footer> >>>>> . >>>>> >>>> -- >>> 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 [email protected]. >>> >> To view this discussion on the web visit >>> https://groups.google.com/d/msgid/go-cd/23fcb498-0645-4516-bdb1-b20be557acc6n%40googlegroups.com >>> >>> <https://groups.google.com/d/msgid/go-cd/23fcb498-0645-4516-bdb1-b20be557acc6n%40googlegroups.com?utm_medium=email&utm_source=footer> >>> . >>> >> -- 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 [email protected]. To view this discussion on the web visit https://groups.google.com/d/msgid/go-cd/e973b68f-3ee8-405c-b806-e5ad43c53cc0n%40googlegroups.com.
