Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

runOnAllAgents="true" added to jobs at GoCD startup #11868

Closed
MPV opened this issue Aug 15, 2023 · 15 comments · Fixed by #11874
Closed

runOnAllAgents="true" added to jobs at GoCD startup #11868

MPV opened this issue Aug 15, 2023 · 15 comments · Fixed by #11874

Comments

@MPV
Copy link

MPV commented Aug 15, 2023

Issue Type
  • Bug Report
Summary

GoCD surprisingly adds runOnAllAgents="true" to jobs.

Environment

👋 Let me know if you need this and I can share this individually, as it might contain sensitive information.

Basic environment details
  • Go Version: 23.1.0 (16080-54a6971915ff8d402c9fea8cd2ceeb6e31c8cdc8)
  • JAVA Version: 17.0.6
  • OS: Linux 5.10.176+
Additional Environment Details
Steps to Reproduce
  1. Restarting GoCD
Expected Results
  1. GoCD config behaving like before.
Actual Results
  1. GoCD surprisingly adds runOnAllAgents="true" to jobs.
Possible Fix

🤷

Log snippets
Code snippets/Screenshots

Here is an example of a commit GoCD makes:

commit a29ab7eddd8a8d864f33a656f96ad1291abe53b7
Author: Upgrade <go-cd-dev@googlegroups.com>
Date:   Fri Aug 11 05:11:37 2023 +0000

    user:Upgrade|timestamp:1691730697644|schema_version:139|go_edition:OpenSource|go_version:23.1.0 (16080-54a6971915ff8d402c9fea8cd2ceeb6e31c8cdc8)|md5:536dedf85183254cabe2192eb1f7c5e2

diff --git a/cruise-config.xml b/cruise-config.xml
index 5234ae934..65a8023b5 100644
--- a/cruise-config.xml
+++ b/cruise-config.xml
@@ -34838,7 +34838,7 @@ fi</arg>
               <artifact type="test" src="some-tests/target/logs/docker" dest="logs" />
             </artifacts>
           </job>
-          <job name="some-tests">
+          <job name="some-tests" runOnAllAgents="true">
             <tasks>
               <fetchartifact artifactOrigin="gocd" srcfile="tag" stage="build" job="defaultJob" />
               <exec command="/bin/bash">
Any other info
@chadlwilson
Copy link
Member

Can you describe the pattern a bit more clearly here? I feel there is a lot of missing context.

Was this on server upgrade? A normal restart? For a single job as a once off? For many different pipelines? Every time you restart? Multiple times? What commonality is there between the type of jobs this is happening to if more than one? Have you seen this historically (if you're down in the history already and don't normally use this runOnAllAgents setting, perhaps a git log -S "runOnAllAgents" -p pickaxe or similar would be useful to dig into.

Possibly a dumb question, but are you confident that no-one manually changed the master cruise-config.xml on disk manually (outside of GoCD's knowledge) before triggering a restart (in which case GoCD could perhaps be flushing to the config repo a change made externally)?

Without any way of narrowing it down, patterns or method/theory for reproducing what you are seeing, there's unlikely much can be done here.

@k-c-p
Copy link

k-c-p commented Aug 16, 2023

I had this happen twice two me. On update from 23.1 -> 23.2 and from 23.2 -> 23.3. We have about 100 pipes and it only happend on one in each update round.

23.1 -> 23.2 excerpt from go-server.log

2023-07-24 15:21:22,991 INFO  [Thread-79] GoFileConfigDataSource:265 - Reloading config file: /etc/go/cruise-config.xml
2023-07-24 15:21:24,077 WARN  [WrapperJarAppMain] GoConfigMigrator:98 - Error upgrading config file, trying to upgrade using the versioned config file.
2023-07-24 15:21:24,098 INFO  [WrapperJarAppMain] GoConfigMigration:81 - Config file is backed up, location: /etc/go/cruise-config.xml.invalid.2023-07-24-15-21-24
2023-07-24 15:21:24,199 WARN  [WrapperJarAppMain] GoConfigMigrator:137 - Go encountered an invalid configuration file while starting up. The invalid configuration file has been renamed to ‘/etc/go/cruise-config.xml.invalid.2023-07-24-15-21-24’ and a new configuration file has been automatically created using the last good configuration. Cause: 'Could not set value [false] on Field [runOnAllAgents] of type [boolean] '
2023-07-24 15:21:24,260 INFO  [WrapperJarAppMain] GoConfigMigration:95 - Upgrading config file from version 139 to version 139
2023-07-24 15:21:24,484 INFO  [WrapperJarAppMain] GoConfigMigration:103 - Finished upgrading config file

Upgrader commit in config git added this

commit 83675591ebc7bc94c5125137b23d57b3e4de6fa2
Author: Upgrade <go-cd-dev@googlegroups.com>
Date:   Mon Jul 24 15:28:40 2023 +0200

    user:Upgrade|timestamp:1690205320175|schema_version:139|go_edition:OpenSource|go_version:23.2.0 (16938-e2b2936f3b573008381a3702139ebcb4383dc0b1)|md5:b83d96dadc2b43172e054c08f0907b6b

commit e8f904dad5179ab6d75306d082070f32e7ecca0b
Author: Filesystem <go-cd-dev@googlegroups.com>
Date:   Mon Jul 24 15:21:28 2023 +0200
$ git diff e8f904dad5179ab6d75306d082070f32e7ecca0b 83675591ebc7bc94c5125137b23d57b3e4de6fa2
diff --git a/cruise-config.xml b/cruise-config.xml
index 2417e5f99..d6820ad6f 100644
--- a/cruise-config.xml
+++ b/cruise-config.xml
@@ -21523,7 +21523,7 @@
       </stage>
       <stage name="QA">
         <jobs>
-          <job name="install">
+          <job name="install" runOnAllAgents="true">
             <tasks>
               <exec command="connect">
                 <arg>-k</arg>

23.2 -> 23.3

commit 77e4b92c28a5af72296ae45215de5b10aae0c5c4
Author: Upgrade <go-cd-dev@googlegroups.com>
Date:   Mon Jul 31 15:49:58 2023 +0200

    user:Upgrade|timestamp:1690811398223|schema_version:139|go_edition:OpenSource|go_version:23.3.0 (16991-f38981e8aa684d63ac96f517996cd888eff37640)|md5:b806bbcb01cd7c4a0a27593186b7aee6

commit c79bd365e1005a272d3438a77f612499ec07addf
Author: knorr <go-cd-dev@googlegroups.com>
Date:   Mon Jul 31 15:17:01 2023 +0200

    user:knorr|timestamp:1690809421493|schema_version:139|go_edition:OpenSource|go_version:23.2.0 (16938-e2b2936f3b573008381a3702139ebcb4383dc0b1)|md5:fce4b3b70675411baa925458de22ee41

This time it did a bit more. Apart from adding "runOnAllAgents=true" on one pipe it touch some more (mostly bool values)

$ git diff c79bd365e1005a272d3438a77f612499ec07addf 77e4b92c28a5af72296ae45215de5b10aae0c5c4
diff --git a/cruise-config.xml b/cruise-config.xml
index 407c71269..8d718b315 100644
--- a/cruise-config.xml
+++ b/cruise-config.xml
@@ -11760,7 +11760,7 @@
     <pipeline name="order_sys" lockBehavior="unlockWhenFinished">
       <timer>08 47 03 ? * WED *</timer>
       <materials>
-        <git url="REDACTED" shallowClone="true" dest="ansible" autoUpdate="false" materialName="system" />
+        <git url="REDACTED" dest="ansible" autoUpdate="false" materialName="system" />
       </materials>
       <stage name="qa">
         <approval type="manual" />
@@ -30902,7 +30902,7 @@
       </stage>
       <stage name="dev" cleanWorkingDir="true">
         <environmentvariables>
-          <variable name="ANSIBLE_VAULT_PASS" secure="true">
+          <variable name="ANSIBLE_VAULT_PASS">
             <encryptedValue>REDACTED</encryptedValue>
           </variable>
         </environmentvariables>
@@ -37924,7 +37924,7 @@
               <resource>ansible</resource>
             </resources>
           </job>
-          <job name="ccdevfe">
+          <job name="ccdevfe" runOnAllAgents="true">
             <tasks>
               <exec command="connect">
                 <arg>-g</arg>
@@ -42998,7 +42998,7 @@
     <pipeline name="qa15_start" labeltemplate="${ansible[:7]}" lockBehavior="unlockWhenFinished">
       <trackingtool link="REDACTED" regex="(\w+-\d+)" />
       <environmentvariables>
-        <variable name="VAULT_PW" secure="true">
+        <variable name="VAULT_PW">
           <encryptedValue>REDACTED</encryptedValue>
         </variable>
         <variable name="ANSIBLE_FORCE_COLOR">
@@ -46759,7 +46759,7 @@
         </variable>
       </environmentvariables>
       <materials>
-        <git url="gitea@REDACTED" branch="REDACTED" autoUpdate="false" username="" />
+        <git url="gitea@REDACTED" branch="REDACTED" autoUpdate="false" />
       </materials>
       <stage name="DEV">
         <jobs>

This time to go-server.log yielded some more information

2023-07-31 15:49:53,362 INFO  [Thread-79] GoFileConfigDataSource:264 - Config file changed at 2023-07-31T13:17:01.486Z
2023-07-31 15:49:53,363 INFO  [Thread-79] GoFileConfigDataSource:265 - Reloading config file: /etc/go/cruise-config.xml
2023-07-31 15:49:55,360 WARN  [Thread-79] CachedGoConfig:101 - Error loading cruise-config.xml from disk, keeping previous one
java.lang.RuntimeException: Could not set value [false] on Field [autoUpdate] of type [boolean] 
        at com.thoughtworks.go.util.ExceptionUtils.bomb(ExceptionUtils.java:38)
        at com.thoughtworks.go.config.parser.GoConfigFieldLoader.setValue(GoConfigFieldLoader.java:120)
 ...
Caused by: org.springframework.beans.TypeMismatchException: Failed to convert value of type 'java.lang.String' to required type 'boolean'; nested exception is java.lang.IllegalArgumentException: Cannot convert value of type 'java.lang.String' to required type 'boolean': PropertyEditor [org.springframework.beans.propertyeditors.CustomBooleanEditor] returned inappropriate value of type 'null'
        at org.springframework.beans.TypeConverterSupport.doConvert(TypeConverterSupport.java:77)
        at org.springframework.beans.TypeConverterSupport.convertIfNecessary(TypeConverterSupport.java:40)
        at com.thoughtworks.go.config.parser.GoConfigFieldLoader.setValue(GoConfigFieldLoader.java:112)
        ... 44 common frames omitted
Caused by: java.lang.IllegalArgumentException: Cannot convert value of type 'java.lang.String' to required type 'boolean': PropertyEditor [org.springframework.beans.propertyeditors.CustomBooleanEditor] returned inappropriate value of type 'null'
        at org.springframework.beans.TypeConverterDelegate.convertIfNecessary(TypeConverterDelegate.java:303)
        at org.springframework.beans.TypeConverterDelegate.convertIfNecessary(TypeConverterDelegate.java:109)
        at org.springframework.beans.TypeConverterSupport.doConvert(TypeConverterSupport.java:64)
        ... 46 common frames omitted

@MPV
Copy link
Author

MPV commented Aug 16, 2023

Can you describe the pattern a bit more clearly here? I feel there is a lot of missing context.

Was this on server upgrade? A normal restart? For a single job as a once off? For many different pipelines? Every time you restart? Multiple times? What commonality is there between the type of jobs this is happening to if more than one? Have you seen this historically (if you're down in the history already and don't normally use this runOnAllAgents setting, perhaps a git log -S "runOnAllAgents" -p pickaxe or similar would be useful to dig into.

Good questions! I was on holiday last week, let me ask the colleagues who were here during the restart, and we'll get back to you with more context.

Possibly a dumb question, but are you confident that no-one manually changed the master cruise-config.xml on disk manually (outside of GoCD's knowledge) before triggering a restart (in which case GoCD could perhaps be flushing to the config repo a change made externally)?

We've seen this multiple times over the last few months, looking back at the logs, here's another example of (what we believe is) GoCD doing this (note the timestamps, being within seconds of each other):

commit eca98b446e4322b8eba1ab19ba2c9378803bc572
Author: anonymous <go-cd-dev@googlegroups.com>
Date:   Sat Jul 22 14:07:10 2023 +0000

    user:anonymous|timestamp:1690034830125|schema_version:139|go_edition:OpenSource|go_version:23.1.0 (16080-54a6971915ff8d
402c9fea8cd2ceeb6e31c8cdc8)|md5:c3ca08a3776e3ccd6969b7e2417d7de3

diff --git a/cruise-config.xml b/cruise-config.xml
index 97b3f0694..c43f4def2 100644
--- a/cruise-config.xml
+++ b/cruise-config.xml
@@ -12102,7 +12102,7 @@ fi</arg>
               <artifact type="test" src="po-feature-tests/target/logs/docker" dest="logs" />
             </artifacts>
           </job>
-          <job name="compliance-feature-tests">
+          <job name="compliance-feature-tests" runOnAllAgents="true">
             <tasks>
               <fetchartifact artifactOrigin="gocd" srcfile="tag" stage="build" job="defaultJob" />
               <exec command="/bin/bash">

commit 6256feea1bcf9bcb5b48ce087a560450e60238f1
Author: Upgrade <go-cd-dev@googlegroups.com>
Date:   Sat Jul 22 14:07:05 2023 +0000

    user:Upgrade|timestamp:1690034824889|schema_version:139|go_edition:OpenSource|go_version:23.1.0 (16080-54a6971915ff8d402c9fea8cd2ceeb6e31c8cdc8)|md5:95adbb5a400a6292b8fd216333a07e53

diff --git a/cruise-config.xml b/cruise-config.xml
index c43f4def2..97b3f0694 100644
--- a/cruise-config.xml
+++ b/cruise-config.xml
@@ -12102,7 +12102,7 @@ fi</arg>
               <artifact type="test" src="po-feature-tests/target/logs/docker" dest="logs" />
             </artifacts>
           </job>
-          <job name="compliance-feature-tests" runOnAllAgents="true">
+          <job name="compliance-feature-tests">
             <tasks>
               <fetchartifact artifactOrigin="gocd" srcfile="tag" stage="build" job="defaultJob" />
               <exec command="/bin/bash">

commit 3d333bea4e45908713a238508128d70d42d2d4dc
Author: Filesystem <go-cd-dev@googlegroups.com>
Date:   Sat Jul 22 14:07:04 2023 +0000

    user:Filesystem|timestamp:1690034824645|schema_version:139|go_edition:OpenSource|go_version:23.1.0 (16080-54a6971915ff8d402c9fea8cd2ceeb6e31c8cdc8)|md5:c3ca08a3776e3ccd6969b7e2417d7de3

diff --git a/cruise-config.xml b/cruise-config.xml
index 97b3f0694..c43f4def2 100644
--- a/cruise-config.xml
+++ b/cruise-config.xml
@@ -12102,7 +12102,7 @@ fi</arg>
               <artifact type="test" src="po-feature-tests/target/logs/docker" dest="logs" />
             </artifacts>
           </job>
-          <job name="compliance-feature-tests">
+          <job name="compliance-feature-tests" runOnAllAgents="true">
             <tasks>
               <fetchartifact artifactOrigin="gocd" srcfile="tag" stage="build" job="defaultJob" />
               <exec command="/bin/bash">

As we are running our GoCD server in Kubernetes, it's possible that it may restart at "unplanned times", but maybe there's even more patterns to be found (like @k-c-p so nicely described above).

@chadlwilson
Copy link
Member

Thanks @k-c-p s log sharing is helpful.

I don't think anything has changed anywhere in the config loading area that would make it any more likely than it ever was for something like this to happen (at least over the past couple of years I have been helping maintain GoCD) which is why I am interested in folks who might have a longer config history. Honestly the whole config area is terrifying to me, and I avoid touching it 😇

I am aware of at least one other bug that seems somewhat similar to this (on restart certain encrypted values get persisted unclencrypted).

Clearly the Error loading cruise-config.xml from disk and either how it got into this state, or why it thinks it is invalid is the problem.

@MPV
Copy link
Author

MPV commented Aug 16, 2023

Searched logs for Error loading cruise-config.xml from disk, seeing matching occurrences:

INFO 2023-08-11T13:38:15.232918529Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 13:38:15,166 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T07:40:09.058405728Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 07:40:08,977 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T07:38:18.383278612Z [resource.labels.containerName: gocd-server] jvm 2 | 2023-08-11 07:38:18,298 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T07:12:18.910484097Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 07:12:18,827 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T06:56:35.405358631Z [resource.labels.containerName: gocd-server] jvm 2 | 2023-08-11 06:56:35,308 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T06:47:41.828978281Z [resource.labels.containerName: gocd-server] jvm 2 | 2023-08-11 06:47:41,739 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T06:21:46.527107271Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 06:21:46,430 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T06:19:51.595806260Z [resource.labels.containerName: gocd-server] jvm 2 | 2023-08-11 06:19:51,510 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T06:05:43.869867036Z [resource.labels.containerName: gocd-server] jvm 2 | 2023-08-11 06:05:43,777 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T05:51:04.610774125Z [resource.labels.containerName: gocd-server] jvm 2 | 2023-08-11 05:51:04,511 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T05:39:01.113739212Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:39:01,016 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T05:36:54.588637522Z [resource.labels.containerName: gocd-server] jvm 2 | 2023-08-11 05:36:54,490 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T05:24:59.118663807Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:24:59,020 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T05:11:34.708967869Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:11:34,704 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one

Here's one of them, with following log lines:

INFO 2023-08-11T05:11:38.118643857Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:11:38,027 INFO [WrapperJarAppMain] CachedGoConfig:223 - About to notify config listeners
INFO 2023-08-11T05:11:34.713735107Z [resource.labels.containerName: gocd-server] jvm 1 | ... 47 common frames omitted
INFO 2023-08-11T05:11:34.713727367Z [resource.labels.containerName: gocd-server] jvm 1 | at org.springframework.beans.TypeConverterSupport.doConvert(TypeConverterSupport.java:64)
INFO 2023-08-11T05:11:34.713709791Z [resource.labels.containerName: gocd-server] jvm 1 | at org.springframework.beans.TypeConverterDelegate.convertIfNecessary(TypeConverterDelegate.java:109)
INFO 2023-08-11T05:11:34.713696108Z [resource.labels.containerName: gocd-server] jvm 1 | at org.springframework.beans.TypeConverterDelegate.convertIfNecessary(TypeConverterDelegate.java:303)
INFO 2023-08-11T05:11:34.713654959Z [resource.labels.containerName: gocd-server] jvm 1 | Caused by: java.lang.IllegalArgumentException: Cannot convert value of type 'java.lang.String' to required type 'boolean': PropertyEditor [org.springframework.beans.propertyeditors.CustomBooleanEditor] returned inappropriate value of type 'null'
INFO 2023-08-11T05:11:34.712461337Z [resource.labels.containerName: gocd-server] jvm 1 | ... 45 common frames omitted
INFO 2023-08-11T05:11:34.712433039Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigFieldLoader.setValue(GoConfigFieldLoader.java:112)
INFO 2023-08-11T05:11:34.712400963Z [resource.labels.containerName: gocd-server] jvm 1 | at org.springframework.beans.TypeConverterSupport.convertIfNecessary(TypeConverterSupport.java:40)
INFO 2023-08-11T05:11:34.712391473Z [resource.labels.containerName: gocd-server] jvm 1 | at org.springframework.beans.TypeConverterSupport.doConvert(TypeConverterSupport.java:77)
INFO 2023-08-11T05:11:34.712297990Z [resource.labels.containerName: gocd-server] jvm 1 | Caused by: org.springframework.beans.TypeMismatchException: Failed to convert value of type 'java.lang.String' to required type 'boolean'; nested exception is java.lang.IllegalArgumentException: Cannot convert value of type 'java.lang.String' to required type 'boolean': PropertyEditor [org.springframework.beans.propertyeditors.CustomBooleanEditor] returned inappropriate value of type 'null'
INFO 2023-08-11T05:11:34.712232699Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread.run(DefaultPluginJarLocationMonitor.java:177)
INFO 2023-08-11T05:11:34.712189966Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread.oneShot(DefaultPluginJarLocationMonitor.java:191)
INFO 2023-08-11T05:11:34.712102359Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread.loadAndNotifyPluginsFrom(DefaultPluginJarLocationMonitor.java:204)
INFO 2023-08-11T05:11:34.712057639Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.monitor.PluginChangeNotifier.notify(PluginChangeNotifier.java:30)
INFO 2023-08-11T05:11:34.712015944Z [resource.labels.containerName: gocd-server] jvm 1 | at java.base/java.lang.Iterable.forEach(Unknown Source)
INFO 2023-08-11T05:11:34.711983695Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.monitor.PluginChangeNotifier.lambda$notify$0(PluginChangeNotifier.java:33)
INFO 2023-08-11T05:11:34.711901621Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread$DoOnAllListeners.pluginJarAdded(DefaultPluginJarLocationMonitor.java:237)
INFO 2023-08-11T05:11:34.711859834Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread$DoOnAllListeners.doOnAllPluginJarChangeListener(DefaultPluginJarLocationMonitor.java:258)
INFO 2023-08-11T05:11:34.711822596Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread$DoOnAllListeners.lambda$pluginJarAdded$0(DefaultPluginJarLocationMonitor.java:237)
INFO 2023-08-11T05:11:34.711760113Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.listeners.DefaultPluginJarChangeListener.pluginJarAdded(DefaultPluginJarChangeListener.java:72)
INFO 2023-08-11T05:11:34.711733288Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.listeners.DefaultPluginJarChangeListener.addPlugin(DefaultPluginJarChangeListener.java:123)
INFO 2023-08-11T05:11:34.711721373Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.listeners.DefaultPluginJarChangeListener.refreshBundle(DefaultPluginJarChangeListener.java:180)
INFO 2023-08-11T05:11:34.711712372Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.PluginLoader.loadPlugin(PluginLoader.java:70)
INFO 2023-08-11T05:11:34.711702796Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.PluginLoader.doPostBundleInstallActivities(PluginLoader.java:112)
INFO 2023-08-11T05:11:34.711686192Z [resource.labels.containerName: gocd-server] jvm 1 | at org.apache.commons.collections4.IterableUtils.forEach(IterableUtils.java:585)
INFO 2023-08-11T05:11:34.711677941Z [resource.labels.containerName: gocd-server] jvm 1 | at org.apache.commons.collections4.IteratorUtils.forEach(IteratorUtils.java:1224)
INFO 2023-08-11T05:11:34.711668365Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.PluginLoader.lambda$doPostBundleInstallActivities$1(PluginLoader.java:112)
INFO 2023-08-11T05:11:34.711654921Z [resource.labels.containerName: gocd-server] jvm 1 | at org.apache.commons.collections4.IterableUtils.forEach(IterableUtils.java:585)
INFO 2023-08-11T05:11:34.711612560Z [resource.labels.containerName: gocd-server] jvm 1 | at org.apache.commons.collections4.IteratorUtils.forEach(IteratorUtils.java:1224)
INFO 2023-08-11T05:11:34.710410103Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.plugin.infra.PluginLoader.lambda$doPostBundleInstallActivities$0(PluginLoader.java:112)
INFO 2023-08-11T05:11:34.710371299Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.server.service.ConfigRepositoryInitializer.pluginLoaded(ConfigRepositoryInitializer.java:90)
INFO 2023-08-11T05:11:34.710339570Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.server.service.ConfigRepositoryInitializer.initializeConfigRepositories(ConfigRepositoryInitializer.java:109)
INFO 2023-08-11T05:11:34.710291683Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.server.service.ConfigRepoService.getConfigRepos(ConfigRepoService.java:92)
INFO 2023-08-11T05:11:34.710283300Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.server.service.GoConfigService.getConfigForEditing(GoConfigService.java:226)
INFO 2023-08-11T05:11:34.710241387Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.GoConfigDao.loadForEditing(GoConfigDao.java:72)
INFO 2023-08-11T05:11:34.710185524Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.CachedGoConfig.loadForEditing(CachedGoConfig.java:116)
INFO 2023-08-11T05:11:34.710043320Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.CachedGoConfig.loadConfigIfNull(CachedGoConfig.java:138)
INFO 2023-08-11T05:11:34.709968632Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.CachedGoConfig.forceReload(CachedGoConfig.java:98)
INFO 2023-08-11T05:11:34.709947584Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.GoFileConfigDataSource.load(GoFileConfigDataSource.java:267)
INFO 2023-08-11T05:11:34.709919219Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.GoFileConfigDataSource.forceLoad(GoFileConfigDataSource.java:420)
INFO 2023-08-11T05:11:34.709784207Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.MagicalGoConfigXmlLoader.deserializeConfig(MagicalGoConfigXmlLoader.java:112)
INFO 2023-08-11T05:11:34.709664108Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigClassLoader.parse(GoConfigClassLoader.java:77)
INFO 2023-08-11T05:11:34.709647343Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigFieldLoader.parse(GoConfigFieldLoader.java:72)
INFO 2023-08-11T05:11:34.709551990Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigSubtagLoader.parse(GoConfigSubtagLoader.java:78)
INFO 2023-08-11T05:11:34.709537860Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigClassLoader.parse(GoConfigClassLoader.java:81)
INFO 2023-08-11T05:11:34.709470187Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigClassLoader.parseCollection(GoConfigClassLoader.java:116)
INFO 2023-08-11T05:11:34.709461690Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigClassLoader.parse(GoConfigClassLoader.java:81)
INFO 2023-08-11T05:11:34.709395888Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigClassLoader.parseCollection(GoConfigClassLoader.java:116)
INFO 2023-08-11T05:11:34.709388753Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigClassLoader.parse(GoConfigClassLoader.java:77)
INFO 2023-08-11T05:11:34.709379059Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigFieldLoader.parse(GoConfigFieldLoader.java:72)
INFO 2023-08-11T05:11:34.709304380Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigSubtagLoader.parse(GoConfigSubtagLoader.java:78)
INFO 2023-08-11T05:11:34.709297598Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigClassLoader.parse(GoConfigClassLoader.java:81)
INFO 2023-08-11T05:11:34.709290420Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigClassLoader.parseCollection(GoConfigClassLoader.java:116)
INFO 2023-08-11T05:11:34.709271641Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigClassLoader.parse(GoConfigClassLoader.java:77)
INFO 2023-08-11T05:11:34.709063394Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigFieldLoader.parse(GoConfigFieldLoader.java:77)
INFO 2023-08-11T05:11:34.709048060Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.config.parser.GoConfigFieldLoader.setValue(GoConfigFieldLoader.java:120)
INFO 2023-08-11T05:11:34.709041659Z [resource.labels.containerName: gocd-server] jvm 1 | at com.thoughtworks.go.util.ExceptionUtils.bomb(ExceptionUtils.java:38)
INFO 2023-08-11T05:11:34.709032348Z [resource.labels.containerName: gocd-server] jvm 1 | java.lang.RuntimeException: Could not set value [false] on Field [runOnAllAgents] of type [boolean]
INFO 2023-08-11T05:11:34.708967869Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:11:34,704 WARN [Thread-79] CachedGoConfig:103 - Error loading cruise-config.xml from disk, keeping previous one
INFO 2023-08-11T05:11:33.406115678Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:11:33,314 INFO [Thread-79] GoFileConfigDataSource:264 - Reloading config file: config/cruise-config.xml

@MPV
Copy link
Author

MPV commented Aug 16, 2023

Adding further logs before this (for context):

INFO 2023-08-11T05:11:33.406115678Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:11:33,314 INFO [Thread-79] GoFileConfigDataSource:264 - Reloading config file: config/cruise-config.xml
INFO 2023-08-11T05:11:33.406037531Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:11:33,314 INFO [Thread-79] GoFileConfigDataSource:263 - Config file changed at 1691730613876
INFO 2023-08-11T05:11:33.305755077Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:11:33,238 INFO [Thread-79] ConfigRepositoryInitializer:108 - [Config Repository Initializer] Start initializing the config repositories for plugin 'json.config.plugin'
INFO 2023-08-11T05:11:32.905271533Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:11:32,823 INFO [WrapperJarAppMain] GoConfigMigrator:106 - [Config Save] Starting Config Save post upgrade using FullConfigSaveNormalFlow
INFO 2023-08-11T05:11:32.905186519Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:11:32,822 INFO [WrapperJarAppMain] GoConfigMigration:103 - Finished upgrading config file
INFO 2023-08-11T05:11:32.203446348Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:11:32,119 INFO [Thread-79] DefaultPluginJarChangeListener:67 - Plugin load starting: /go-working-dir/plugins/bundled/gocd-json-config-plugin.jar
INFO 2023-08-11T05:11:32.202762018Z [resource.labels.containerName: gocd-server] jvm 1 | 2023-08-11 05:11:32,105 INFO [Thread-79] DefaultPluginJarChangeListener:74 - Plugin load finished: /go-working-dir/plugins/bundled/gocd-file-based-secrets-plugin.jar

@chadlwilson
Copy link
Member

The change being

  • made by Filesystem
  • and then reverted by Upgrade

... is weird, but might point at a possible circumstance of the problem. What is perhaps happening is some strange race condition between the normal config validation at startup (user:Upgrade), and the config being triggered to reload when it thinks cruise-config.xml has been modified externally (user:Filesystem). I've no idea how user:anonymous gets there though.

Overall, we'd have to correlated with what the logs say at that time to understand more - it's not particularly useful to just see the config history on its own.

The strangest thing here to me is how runOnAllAgents gets set to true. There must be some meta-deserialization reflection code that defaults bool to true somewhere in event of failure since inside the schema, and the domain objects the default value for runOnAllAgents is always false from what I can see.

@chadlwilson
Copy link
Member

chadlwilson commented Aug 16, 2023

@MPV In your case, how far back history would you have for your config repository? Years? Back through which GoCD version?

If you do have such a longer history, and can see a clear place this runOnAllAgents flip-flopping (in particular) might have started, that might help.

My current working, but largely unvalidated theory here is that there is some sort of thread safety problem with the ancient type converter logic here that is leading to this bizarre behaviour (it is starting with a false string from XML, trying to convert it with a Spring CustomBooleanEditor (seems correct), but that editor suggests the value as a Boolean should be null (!!?) which makes no sense logically or from the code.

Cannot convert value of type 'java.lang.String' to required type 'boolean': PropertyEditor [org.springframework.beans.propertyeditors.CustomBooleanEditor] returned inappropriate value of type 'null'`
...
Could not set value [false] on Field [runOnAllAgents] of type [boolean]

If that's the case, it's been that way for a very long time, and there's no obvious explanation of why it would have gotten any "worse" except perhaps with some other reason for increased chance of a race condition over time. But worth exploring.

@chadlwilson chadlwilson self-assigned this Aug 16, 2023
@MPV
Copy link
Author

MPV commented Aug 16, 2023

@MPV In your case, how far back history would you have for your config repository? Years? Back through which GoCD version?

If you do have such a longer history, and can see a clear place this runOnAllAgents flip-flopping (in particular) might have started, that might help.

I saw occurrences of changes to this value in our GoCD git history from back in 2015, though I'm not at my computer at the moment so I can't verify if it was flapping as early as that or just manual changes back then. If I remember correctly it was more recently (the past year) I saw it occurring. And mostly a single random pipeline/stage/job affected, not all of them (we have many hundreds).

We do run our GoCD in Kubernetes (since quite a few years back) so there's mounted ConfigMaps, paths and remote disks for persistence, but I guess that's common.

More context; we have some hundred pipelines defined manually, then a few hundred pipelines defined as code/yaml. We also maintain less than fifty pipeline templates as code, which we keep upserting into GoCD (using the json api) whenever developers (or us in the platform team) make changes to it. The latter gives occasional quite hefty diffs in the config repo (as in one templates being rearranged after/before another), but nothing which I assume would cause this (apart from making my troubleshooting/git history digging a bit messier).

@MPV
Copy link
Author

MPV commented Aug 17, 2023

And here are some logs from the issue back in July 22nd that I showed git commits from back in #11868 (comment)

jvm 2 | 2023-07-22 14:07:13,507 INFO [Thread-79] GoConfigDao:111 - Config update request com.thoughtworks.go.config.update.PartialConfigUpdateCommand@7930074d by anonymous is being processed
jvm 2 | 2023-07-22 14:07:13,507 INFO [Thread-79] GoConfigDao:108 - Config update request by anonymous is in queue - com.thoughtworks.go.config.update.PartialConfigUpdateCommand@7930074d
jvm 2 | 2023-07-22 14:07:13,483 INFO [Thread-79] GoConfigDao:126 - Config update request by anonymous is completed
jvm 2 | 2023-07-22 14:07:13,483 INFO [Thread-79] CachedGoConfig:231 - Finished notifying all listeners
jvm 2 | 2023-07-22 14:07:13,478 INFO [Thread-79] BuildAssignmentService:251 - [Configuration Changed] Removing jobs for pipelines that no longer exist in configuration.
jvm 2 | 2023-07-22 14:07:13,474 INFO [Thread-79] CachedGoConfig:223 - About to notify config listeners
jvm 2 | 2023-07-22 14:07:13,376 INFO [Thread-79] GoFileConfigDataSource:587 - [Configuration Changed] Saving updated configuration.
jvm 2 | 2023-07-22 14:07:11,940 INFO [Thread-79] MagicalGoConfigXmlWriter:85 - [Serializing Config] Generating config partial.
jvm 2 | 2023-07-22 14:07:10,457 INFO [Thread-79] GoConfigDao:111 - Config update request com.thoughtworks.go.config.update.PartialConfigUpdateCommand@1f5f8fd2 by anonymous is being processed
jvm 2 | 2023-07-22 14:07:10,456 INFO [Thread-79] GoConfigDao:108 - Config update request by anonymous is in queue - com.thoughtworks.go.config.update.PartialConfigUpdateCommand@1f5f8fd2
jvm 2 | 2023-07-22 14:07:10,435 INFO [Thread-79] GoConfigDao:126 - Config update request by anonymous is completed
jvm 2 | 2023-07-22 14:07:10,435 INFO [Thread-79] CachedGoConfig:231 - Finished notifying all listeners
jvm 2 | 2023-07-22 14:07:10,429 INFO [Thread-79] BuildAssignmentService:251 - [Configuration Changed] Removing jobs for pipelines that no longer exist in configuration.
jvm 2 | 2023-07-22 14:07:10,422 INFO [Thread-79] CachedGoConfig:223 - About to notify config listeners
jvm 2 | 2023-07-22 14:07:10,284 INFO [Thread-79] GoFileConfigDataSource:587 - [Configuration Changed] Saving updated configuration.
jvm 2 | 2023-07-22 14:07:08,111 INFO [Thread-79] MagicalGoConfigXmlWriter:85 - [Serializing Config] Generating config partial.
jvm 2 | 2023-07-22 14:07:06,440 INFO [Thread-79] GoConfigDao:111 - Config update request com.thoughtworks.go.config.update.PartialConfigUpdateCommand@5fa3073f by anonymous is being processed
jvm 2 | 2023-07-22 14:07:06,439 INFO [Thread-79] GoConfigDao:108 - Config update request by anonymous is in queue - com.thoughtworks.go.config.update.PartialConfigUpdateCommand@5fa3073f
jvm 2 | 2023-07-22 14:07:06,243 INFO [Thread-79] ConfigRepositoryInitializer:108 - [Config Repository Initializer] Start initializing the config repositories for plugin 'yaml.config.plugin'
jvm 2 | 2023-07-22 14:07:05,594 INFO [WrapperJarAppMain] PipelineRepository:78 - Start updating pipeline timeline
jvm 2 | 2023-07-22 14:07:05,575 INFO [WrapperJarAppMain] InvalidateAuthenticationOnSecurityConfigChangeFilter:78 - [Configuration Changed] Security Configuration is changed. Updating the last changed time.
jvm 2 | 2023-07-22 14:07:05,537 INFO [WrapperJarAppMain] BuildAssignmentService:251 - [Configuration Changed] Removing jobs for pipelines that no longer exist in configuration.
jvm 2 | 2023-07-22 14:07:05,369 INFO [Thread-79] DefaultPluginJarChangeListener:67 - Plugin load starting: /go-working-dir/plugins/bundled/gocd-yaml-config-plugin.jar
jvm 2 | 2023-07-22 14:07:05,357 INFO [Thread-79] DefaultPluginJarChangeListener:74 - Plugin load finished: /go-working-dir/plugins/bundled/gocd-filebased-authentication-plugin.jar
jvm 2 | 2023-07-22 14:07:05,356 WARN [Thread-79] PluginSettingsMetadataLoader:65 - Not all plugins are required to implement the request above. This error may be safe to ignore.
jvm 2 | 2023-07-22 14:07:05,356 WARN [Thread-79] 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.''}]
jvm 2 | 2023-07-22 14:07:05,356 WARN [Thread-79] PluginSettingsMetadataLoader:63 - Failed to fetch plugin settings metadata for plugin cd.go.authentication.passwordfile. Maybe the plugin does not implement plugin settings and view?
jvm 2 | 2023-07-22 14:07:05,355 WARN [Thread-79] 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.
jvm 2 | 2023-07-22 14:07:05,314 INFO [Thread-79] p.c.g.a.p.c.g.a.p.PasswordFilePlugin:72 [plugin-cd.go.authentication.passwordfile] - Loading plugin null version 2.1.2-180
jvm 2 | 2023-07-22 14:07:05,185 INFO [Thread-79] DefaultPluginJarChangeListener:67 - Plugin load starting: /go-working-dir/plugins/bundled/gocd-filebased-authentication-plugin.jar
jvm 2 | 2023-07-22 14:07:05,174 INFO [Thread-79] DefaultPluginJarChangeListener:74 - Plugin load finished: /go-working-dir/plugins/bundled/gocd-json-config-plugin.jar
jvm 2 | 2023-07-22 14:07:05,142 INFO [Thread-79] ConfigRepositoryInitializer:112 - [Config Repository Initializer] Done initializing the config repositories for plugin 'json.config.plugin'
jvm 2 | 2023-07-22 14:07:05,140 INFO [Thread-79] CachedGoConfig:231 - Finished notifying all listeners
jvm 2 | 2023-07-22 14:07:05,140 INFO [Thread-79] CachedGoConfig:223 - About to notify config listeners
jvm 2 | 2023-07-22 14:07:05,139 INFO [WrapperJarAppMain] CachedGoConfig:231 - Finished notifying all listeners
jvm 2 | 2023-07-22 14:07:05,068 INFO [WrapperJarAppMain] CachedGoConfig:223 - About to notify config listeners
jvm 2 | 2023-07-22 14:07:01,117 INFO [WrapperJarAppMain] GoConfigMigrator:106 - [Config Save] Starting Config Save post upgrade using FullConfigSaveNormalFlow
jvm 2 | 2023-07-22 14:07:01,117 INFO [WrapperJarAppMain] GoConfigMigration:103 - Finished upgrading config file
jvm 2 | 2023-07-22 14:07:00,757 INFO [WrapperJarAppMain] GoConfigMigration:95 - Upgrading config file from version 139 to version 139
jvm 2 | 2023-07-22 14:07:00,619 WARN [WrapperJarAppMain] GoConfigMigrator:137 - Go encountered an invalid configuration file while starting up. The invalid configuration file has been renamed to ‘/go-working-dir/config/cruise-config.xml.invalid.2023-07-22-14-07-00’ and a new configuration file has been automatically created using the last good configuration. Cause: 'Could not set value [true] on Field [allowOnlyOnSuccess] of type [boolean] '
jvm 2 | 2023-07-22 14:07:00,454 INFO [WrapperJarAppMain] GoConfigMigration:81 - Config file is backed up, location: /go-working-dir/config/cruise-config.xml.invalid.2023-07-22-14-07-00
jvm 2 | 2023-07-22 14:07:00,423 WARN [WrapperJarAppMain] GoConfigMigrator:98 - Error upgrading config file, trying to upgrade using the versioned config file.
jvm 2 | 2023-07-22 14:06:59,432 INFO [Thread-79] GoFileConfigDataSource:264 - Reloading config file: config/cruise-config.xml
jvm 2 | 2023-07-22 14:06:59,432 INFO [Thread-79] GoFileConfigDataSource:263 - Config file changed at 1690034564936
jvm 2 | 2023-07-22 14:06:59,391 INFO [Thread-79] ConfigRepositoryInitializer:108 - [Config Repository Initializer] Start initializing the config repositories for plugin 'json.config.plugin'
jvm 2 | 2023-07-22 14:06:58,645 INFO [WrapperJarAppMain] GoConfigMigrator:106 - [Config Save] Starting Config Save post upgrade using FullConfigSaveNormalFlow
jvm 2 | 2023-07-22 14:06:58,644 INFO [WrapperJarAppMain] GoConfigMigration:103 - Finished upgrading config file
jvm 2 | 2023-07-22 14:06:58,364 INFO [Thread-79] DefaultPluginJarChangeListener:67 - Plugin load starting: /go-working-dir/plugins/bundled/gocd-json-config-plugin.jar
jvm 2 | 2023-07-22 14:06:58,349 INFO [Thread-79] DefaultPluginJarChangeListener:74 - Plugin load finished: /go-working-dir/plugins/bundled/gocd-file-based-secrets-plugin.jar
jvm 2 | 2023-07-22 14:06:58,271 WARN [Thread-79] PluginSettingsMetadataLoader:65 - Not all plugins are required to implement the request above. This error may be safe to ignore.
jvm 2 | 2023-07-22 14:06:58,271 WARN [Thread-79] 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'}]
jvm 2 | 2023-07-22 14:06:58,271 WARN [Thread-79] 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?
jvm 2 | 2023-07-22 14:06:58,270 ERROR [Thread-79] DefaultPluginManager:136 - This is an invalid request type :go.plugin-settings.get-configuration
jvm 2 | 2023-07-22 14:06:58,111 INFO [Thread-79] DefaultPluginJarChangeListener:67 - Plugin load starting: /go-working-dir/plugins/bundled/gocd-file-based-secrets-plugin.jar
jvm 2 | 2023-07-22 14:06:58,098 INFO [Thread-79] DefaultPluginJarChangeListener:74 - Plugin load finished: /go-working-dir/plugins/bundled/gocd-ldap-authentication-plugin.jar
jvm 2 | 2023-07-22 14:06:58,096 WARN [Thread-79] PluginSettingsMetadataLoader:65 - Not all plugins are required to implement the request above. This error may be safe to ignore.
jvm 2 | 2023-07-22 14:06:58,096 WARN [Thread-79] 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''}]
jvm 2 | 2023-07-22 14:06:58,096 WARN [Thread-79] PluginSettingsMetadataLoader:63 - Failed to fetch plugin settings metadata for plugin cd.go.authentication.ldap. Maybe the plugin does not implement plugin settings and view?
jvm 2 | at com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread.run(DefaultPluginJarLocationMonitor.java:177)
jvm 2 | at com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread.oneShot(DefaultPluginJarLocationMonitor.java:191)
jvm 2 | at com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread.loadAndNotifyPluginsFrom(DefaultPluginJarLocationMonitor.java:204)
jvm 2 | at com.thoughtworks.go.plugin.infra.monitor.PluginChangeNotifier.notify(PluginChangeNotifier.java:30)
jvm 2 | at java.base/java.lang.Iterable.forEach(Unknown Source)
jvm 2 | at com.thoughtworks.go.plugin.infra.monitor.PluginChangeNotifier.lambda$notify$0(PluginChangeNotifier.java:33)
jvm 2 | at com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread$DoOnAllListeners.pluginJarAdded(DefaultPluginJarLocationMonitor.java:237)
jvm 2 | at com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread$DoOnAllListeners.doOnAllPluginJarChangeListener(DefaultPluginJarLocationMonitor.java:258)
jvm 2 | at com.thoughtworks.go.plugin.infra.monitor.DefaultPluginJarLocationMonitor$PluginLocationMonitorThread$DoOnAllListeners.lambda$pluginJarAdded$0(DefaultPluginJarLocationMonitor.java:237)
jvm 2 | at com.thoughtworks.go.plugin.infra.listeners.DefaultPluginJarChangeListener.pluginJarAdded(DefaultPluginJarChangeListener.java:72)
jvm 2 | at com.thoughtworks.go.plugin.infra.listeners.DefaultPluginJarChangeListener.addPlugin(DefaultPluginJarChangeListener.java:123)
jvm 2 | at com.thoughtworks.go.plugin.infra.listeners.DefaultPluginJarChangeListener.refreshBundle(DefaultPluginJarChangeListener.java:180)
jvm 2 | at com.thoughtworks.go.plugin.infra.PluginLoader.loadPlugin(PluginLoader.java:70)
jvm 2 | at com.thoughtworks.go.plugin.infra.PluginLoader.doPostBundleInstallActivities(PluginLoader.java:112)
jvm 2 | at org.apache.commons.collections4.IterableUtils.forEach(IterableUtils.java:585)
jvm 2 | at org.apache.commons.collections4.IteratorUtils.forEach(IteratorUtils.java:1224)
jvm 2 | at com.thoughtworks.go.plugin.infra.PluginLoader.lambda$doPostBundleInstallActivities$1(PluginLoader.java:112)
jvm 2 | at org.apache.commons.collections4.IterableUtils.forEach(IterableUtils.java:585)
jvm 2 | at org.apache.commons.collections4.IteratorUtils.forEach(IteratorUtils.java:1224)
jvm 2 | at com.thoughtworks.go.plugin.infra.PluginLoader.lambda$doPostBundleInstallActivities$0(PluginLoader.java:112)
jvm 2 | at com.thoughtworks.go.plugin.access.common.settings.PluginSettingsMetadataLoader.pluginLoaded(PluginSettingsMetadataLoader.java:49)
jvm 2 | at com.thoughtworks.go.plugin.access.common.settings.PluginSettingsMetadataLoader.fetchPluginSettingsMetaData(PluginSettingsMetadataLoader.java:59)
jvm 2 | at com.thoughtworks.go.plugin.access.common.settings.PluginSettingsMetadataLoader.findSettingsAndViewOfAllExtensionsIn(PluginSettingsMetadataLoader.java:89)
jvm 2 | at java.base/java.util.stream.ReferencePipeline.collect(Unknown Source)
jvm 2 | at java.base/java.util.stream.AbstractPipeline.evaluate(Unknown Source)
jvm 2 | at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(Unknown Source)
jvm 2 | at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source)
jvm 2 | at java.base/java.util.stream.AbstractPipeline.copyInto(Unknown Source)
jvm 2 | at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(Unknown Source)
jvm 2 | at java.base/java.util.stream.ReferencePipeline$2$1.accept(Unknown Source)
jvm 2 | at java.base/java.util.stream.ReferencePipeline$3$1.accept(Unknown Source)
jvm 2 | at com.thoughtworks.go.plugin.access.common.settings.PluginSettingsMetadataLoader.lambda$findSettingsAndViewOfAllExtensionsIn$2(PluginSettingsMetadataLoader.java:84)
jvm 2 | at com.thoughtworks.go.plugin.access.common.AbstractExtension.getPluginSettingsConfiguration(AbstractExtension.java:56)
jvm 2 | at com.thoughtworks.go.plugin.access.PluginRequestHelper.submitRequest(PluginRequestHelper.java:49)
jvm 2 | at com.thoughtworks.go.plugin.infra.DefaultPluginManager.submitTo(DefaultPluginManager.java:131)
jvm 2 | at com.thoughtworks.go.plugin.infra.FelixGoPluginOSGiFramework.doOn(FelixGoPluginOSGiFramework.java:164)
jvm 2 | at com.thoughtworks.go.plugin.infra.FelixGoPluginOSGiFramework.executeActionOnTheService(FelixGoPluginOSGiFramework.java:205)
jvm 2 | at com.thoughtworks.go.plugin.infra.DefaultPluginManager.lambda$submitTo$0(DefaultPluginManager.java:134)
jvm 2 | at cd.go.authentication.ldap.LdapPlugin.handle(LdapPlugin.java:68)
jvm 2 | at cd.go.plugin.base.dispatcher.RequestDispatcher.dispatch(RequestDispatcher.java:45)
jvm 2 | com.thoughtworks.go.plugin.api.exceptions.UnhandledRequestTypeException: This is an invalid request type :go.plugin-settings.get-configuration
jvm 2 | 2023-07-22 14:06:58,094 ERROR [Thread-79] 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
jvm 2 | 2023-07-22 14:06:58,004 INFO [Thread-79] p.c.g.a.l.c.g.a.l.LdapPlugin:72 [plugin-cd.go.authentication.ldap] - Loading plugin null version 2.2.1-211
jvm 2 | 2023-07-22 14:06:57,960 INFO [WrapperJarAppMain] GoConfigMigration:95 - Upgrading config file from version 139 to version 139
jvm 2 | 2023-07-22 14:06:57,624 INFO [Thread-79] DefaultPluginJarChangeListener:67 - Plugin load starting: /go-working-dir/plugins/bundled/gocd-ldap-authentication-plugin.jar
jvm 2 | 2023-07-22 14:06:54,434 INFO [WrapperJarAppMain] ConnectionManager:98 - Done loading query extensions, found com.thoughtworks.go.server.database.pg.PostgresqlQueryExtensions@31c97c76
jvm 2 | 2023-07-22 14:06:52,640 WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [org.hibernate.cache.StandardQueryCache]; using defaults.
jvm 2 | 2023-07-22 14:06:52,634 WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [org.hibernate.cache.UpdateTimestampsCache]; using defaults.
jvm 2 | 2023-07-22 14:06:52,579 WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [com.thoughtworks.go.domain.User.notificationFilters]; using defaults.
jvm 2 | 2023-07-22 14:06:52,541 WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [com.thoughtworks.go.domain.EnvironmentVariable]; using defaults.
jvm 2 | 2023-07-22 14:06:52,526 WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [com.thoughtworks.go.domain.Plugin]; using defaults.
jvm 2 | 2023-07-22 14:06:52,501 WARN [WrapperJarAppMain] EhCacheProvider:93 - Could not find configuration [com.thoughtworks.go.domain.User]; using defaults.

@MPV
Copy link
Author

MPV commented Aug 17, 2023

For the issue seen at 2023-07-22 14:06 I just raised this bug (which caused GoCD's JVM to restart):

@chadlwilson
Copy link
Member

chadlwilson commented Aug 18, 2023

Hey folks, ive closed the issue now on the basis that I can reliably replicate the specific bug that leads to the error deserializing the runOnAllAgents value and confirmed that it is a threading issue, which I've fixed.

What I haven't tried to do, or fully replicated, is how the value ends up as 'true' and then alternates back, nor specifically which threads are trying to do conconcurrent deserialisation at startup and whether that is expected - but I can see how it is conceptually possible (this is just a limitation of my own knowledge of the project).

The other attributes flipping in inexplicable ways are likely to be related, but booleans will cause more obvious issues since they are non-nullable primitives. Since this threading issue is essentially to do with the java memory model across threads, some really unpredictable situations could arise. It may just be that further CPU and JVM optimisations over time have made this more likely to happen - as it's code largely untouched for 8-9 years. I suspect the bigger the config (with lots of non config repo pipelines) the likelier the problem is to manifest.

You probably don't need to keep digging or analysing on this specific one, but will leave that to you to decide.

I'll re-open if I discover more but the real test will probably be in the real world with 23.4.0 I suspect.

@MPV
Copy link
Author

MPV commented Aug 18, 2023

@chadlwilson Thanks for all your help in troubleshooting and eventually (hopefully) fixing this. 🙏💐🎁

@chadlwilson
Copy link
Member

Hi folks. Sorry for the delay, but wanted to add that this change is now out in GoCD 23.4.0. Fingers crossed that we've nailed this one! https://www.gocd.org/download/

@k-c-p
Copy link

k-c-p commented Nov 3, 2023

I have just upated by GoCD instance from 23.3 to 23.4. Looks good: No "runOnAllAgents" setting appeared out of thin air :-)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants