Did not find 'configrepo' plugin with id 'yaml.config.plugin'

[greuelpirat]

Issue Type

Bug

Summary

Over night Go Server lost all pipelines. Showing error Did not find 'configrepo' plugin with id 'yaml.config.plugin'. Looks like plugin is missing. After restart of go service everything was fine again.

Environment

Basic environment details

• Go Version: 20.1.0 (11114-f2c1771e333ea92dae82cd78d2efa1310c1086f0).
• JAVA Version: 13.0.1
• OS: Windows Server 2019 10.0

Steps to Reproduce

Not known

Log snippets

2020-02-18 22:21:14,972 INFO  [ThreadPoolTaskScheduler-5] GoFileConfigDataSource:137 - Config file changed at 1582060816566
2020-02-18 22:21:14,972 INFO  [ThreadPoolTaskScheduler-5] GoFileConfigDataSource:138 - Reloading config file: config\cruise-config.xml
2020-02-18 22:21:15,134 INFO  [ThreadPoolTaskScheduler-5] CachedGoConfig:222 - About to notify config listeners
2020-02-18 22:21:15,146 INFO  [ThreadPoolTaskScheduler-5] BuildAssignmentService:238 - [Configuration Changed] Removing jobs for pipelines that no longer exist in configuration.
2020-02-18 22:21:15,148 INFO  [ThreadPoolTaskScheduler-5] CachedGoConfig:230 - Finished notifying all listeners
2020-02-18 22:21:20,054 INFO  [ThreadPoolTaskScheduler-6] H2EventListener:31 - Initializing database: jdbc:h2:G:\Server\db\h2db/cruise
2020-02-18 22:21:22,979 ERROR [127@MessageListener for ConfigMaterialUpdateListener] GoRepoConfigDataSource:171 - Failed to parse configuration material ****
com.thoughtworks.go.config.exceptions.RecordNotFoundException: Did not find 'configrepo' plugin with id 'yaml.config.plugin'. Looks like plugin is missing
	at com.thoughtworks.go.plugin.access.PluginRequestHelper.submitRequest(PluginRequestHelper.java:41)
	at com.thoughtworks.go.plugin.access.configrepo.ConfigRepoExtension.parseDirectory(ConfigRepoExtension.java:132)
	at com.thoughtworks.go.config.ConfigRepoPlugin.parseDirectory(ConfigRepoPlugin.java:93)
	at com.thoughtworks.go.config.ConfigRepoPlugin.load(ConfigRepoPlugin.java:62)
	at com.thoughtworks.go.config.GoRepoConfigDataSource.onCheckoutComplete(GoRepoConfigDataSource.java:159)
	at com.thoughtworks.go.server.materials.ConfigMaterialUpdateListener.updateConfigurationFromCheckout(ConfigMaterialUpdateListener.java:102)
	at com.thoughtworks.go.server.materials.ConfigMaterialUpdateListener.onMessage(ConfigMaterialUpdateListener.java:79)
	at com.thoughtworks.go.server.materials.ConfigMaterialUpdateListener.onMessage(ConfigMaterialUpdateListener.java:37)
	at com.thoughtworks.go.server.messaging.activemq.JMSMessageListenerAdapter.runImpl(JMSMessageListenerAdapter.java:83)
	at com.thoughtworks.go.server.messaging.activemq.JMSMessageListenerAdapter.run(JMSMessageListenerAdapter.java:63)
	at java.base/java.lang.Thread.run(Unknown Source)

Code snippets/Screenshots

Any other info

[greuelpirat]

The time 1582060816566 is Tue Feb 18 2020 22:20:16 and there are no known changes from us. unfortunately Go-Service touches cruise-config.xml at restart so the last modified is not accurate.

[arvindsv]

The server restores bundled plugins upon a restart. That could explain it coming back. But, why it went away in the first place is more interesting. Do you have any anti-virus solution which might have quarantined / removed that plugin?

[greuelpirat]

Hm. You gave me the idea it could be due to the backup-system. I will have to investigate this. May take some time. Thank you.

[greuelpirat]

We do only have Windows Defender for anti virus scanning. Nothing else.

The GO server service is stopped before backup with command: sc stop "Go Server" and started again with sc start "Go Server"

there are no log entries at shutdown. (we tested this also with bin\stop-go-server-service.bat). is that true? so we can not tell if shutdown is correct.

here you have a log with failure from friday and a successful restart from today.

go-server-good.log
go-server-failed.log

[arvindsv]

@greuelpirat Thanks for this. It might be worth adding some log messages about which plugins are being loaded etc. A few questions:

1. When it fails to load, what are the plugins in the bundled directory?

2. When this happens, if you wait a minute or two, does it load those pipelines? I'm wondering if there's some kind of a time difference / race condition between the time it loads the plugins and when it tries to parse materials.

3. Was this working fine and then suddenly start happening? Or, was something changed?

4. Did this happen once or does it keep happening?

I'll look into adding logs.

[greuelpirat]

ad 1.
Content of Server/plugins/bundled:

gocd-filebased-authentication-plugin.jar
gocd-file-based-secrets-plugin.jar
gocd-json-config-plugin.jar
gocd-ldap-authentication-plugin.jar
gocd-yaml-config-plugin.jar
gocd-yum-repository-poller-plugin.jar
version.txt

In go/api/support the plugins are also listed as ACTIVE: plugins-from-support.json.txt

ad 2. No, there is no reload. The problem stays until restart. Yesterday the GO Server was restarted and the error message is from 24 Feb, 2020 at 22:21:39 Local Time. No pipelines appeared since and no changes were noticed. It seems that the error at this stage does prevent the reload mechanic.

ad 3. we did create a new setup with 20.1. I think it might still have something to do with our backup-routine, since GO Server always restarts about 22:30 when this error happens. But I have not tracked down the issue.

ad 4. It happend on friday, and yesterday and some days before. So it occurs pretty often.

[arvindsv]

Ok, I've added some logging in #7775 which might help understand this better. It'll be in release 20.2 (next release).

This is what I understand of the issue. Can you please validate it?

1. You have a backup routine which stops the GoCD server and brings it back up at around 22:30.

2. Everything works fine till around 22:30.

3. At around 22:30, after the backup and when it restarts, no pipelines show up and GoCD server says that the plugin is invalid.

4. If you restart GoCD server when it is in this state, all the pipelines show up again and the plugin would have loaded properly.

[arvindsv]

In case it helps: Experimental build 20.2.0-11256, which is available on https://www.gocd.org/download should have the logging change.

[greuelpirat]

Yes, thats right. I do sum up again, may be thats clearer:

22:11 Go Service stopped (everything fine)
22:17 Go Service startet (with errors in log)
...
next day:
I see the reported error on Go service and no pipelines.
06:56 Go Service stopped
06:56 Go Service started --> everything is fine again

[greuelpirat]

In case it helps: Experimental build 20.2.0-11256, which is available on https://www.gocd.org/download should have the logging change.

We are currently in a release phase. So this is not that welcome at the moment.

[arvindsv]

Ok. Will need to check once release 20.2.0 is out then (or whenver an upgrade happens).

[greuelpirat]

Sorry, for the late response. This issue did not occur for long time. So I can not reproduce it any more. If it comes again, I will reopen it.