Help with more detailed logs from 400 bad request thrown by org.eclipse.jetty.http on GoCD Server

[Bob Shazbot]

I am working with Gomatic so I can define my GoCD config from code, since updating GoCD to version 20.2 (from 19.12) I am getting a 400 response when updating certain templates and pipelines, most are going through OK which is odd and the config that I am sending via Gomatic is the same between the 2 GoCD versions.

I am trying to debug the issue so I can figure what Gomatic is doing wrong, all I can get in the logs on server is this:

2020-08-07 07:08:40,627 DEBUG [qtp958443548-28] FilterChainProxy:325 - /api/admin/config.xml at pos
ition 11 of 11 in additional filter chain; firing Filter: 'FlashLoadingFilter'
2020-08-07 07:08:40,628 DEBUG [qtp958443548-28] FilterChainProxy:310 - /api/admin/config.xml reache
d end of additional filter chain; proceeding with original chain
2020-08-07 07:08:40,629 WARN  [qtp958443548-28] HttpChannel:587 - handleException /go/api/admin/config.xml org.eclipse.jetty.http.BadMessageException: 400: Unable to parse form content

This is with the following logback config:

<?xml version="1.0" encoding="UTF-8"?>
<included>
    <logger name="org.eclipse.jetty.server.RequestLog" level="TRACE" />
    <logger name="com.thoughtworks.go.server.Rails" level="TRACE" />
    <logger name="com.thoughtworks.studios.shine" level="TRACE" />
    <logger name="org.springframework" level="TRACE" />
    <logger name="org.apache.velocity" level="TRACE" />
    <logger name="com.microsoft.tfs.core" level="TRACE" />
    <logger name="com.thoughtworks.go.tfssdk14" level="TRACE" />
    <logger name="com.thoughtworks.go.domain.materials.dependency" level="TRACE" />
    <logger name="com.thoughtworks.go.domain.materials.git" level="TRACE" />
    <logger name="com.thoughtworks.go.domain.materials.mercurial" level="TRACE" />
    <logger name="com.thoughtworks.go.domain.materials.packagematerial" level="TRACE" />
    <logger name="com.thoughtworks.go.domain.materials.perforce" level="TRACE" />
    <logger name="com.thoughtworks.go.domain.materials.scm" level="TRACE" />
    <logger name="com.thoughtworks.go.domain.materials.svn" level="TRACE" />
    <logger name="com.thoughtworks.go.domain.materials.tfs" level="TRACE" />
</included>

I cannot seem to get any more info on what is wrong with the request to /go/api/admin/config.xml, is there a way to get a more detailed error message so I can what the issue is?

[Bob Shazbot]

Small correction, the previous version was 19.9, something has changed in GoCD between 19.9 and 20.2 which has resulted in this issue.

[Ketan Padegaonkar]

Are you attempting at posting the same config as you used in 19.9? The config file structure and schema changes between releases. So posting the same file will be expected to not work.

- Ketan

On Fri, Aug 7, 2020 at 3:07 PM Bob Shazbot <lobst...@gmail.com> wrote:

Small correction, the previous version was 19.9, something has changed in GoCD between 19.9 and 20.2 which has resulted in this issue.

--
You received this message because you are subscribed to the Google Groups "go-cd" group.
To unsubscribe from this group and stop receiving emails from it, send an email to go-cd+un...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/go-cd/b0d9f856-f7fb-4336-bb61-ff12ba9ab8b8o%40googlegroups.com.

[Bob Shazbot]

Yep Gomatic has not changed for a while, so that is probably the reason, do you know if there have been any specific changes between 19.9 and 20.2? I have attempted a diff but there are over 8000 files changed between the two releases.

On Friday, 7 August 2020 10:52:23 UTC+1, Ketan Padegaonkar wrote:

Are you attempting at posting the same config as you used in 19.9? The config file structure and schema changes between releases. So posting the same file will be expected to not work.

- Ketan

On Fri, Aug 7, 2020 at 3:07 PM Bob Shazbot <lobst...@gmail.com> wrote:

Small correction, the previous version was 19.9, something has changed in GoCD between 19.9 and 20.2 which has resulted in this issue.

--
You received this message because you are subscribed to the Google Groups "go-cd" group.

To unsubscribe from this group and stop receiving emails from it, send an email to go...@googlegroups.com.

[Ketan Padegaonkar]

Look for the `schemaVersion` field in the XML that gomatic is generating and the version that GoCD has (I'm no longer a core commiter on GoCD, so I can't tell you at the top of my head what changes have happened)

- Ketan

To unsubscribe from this group and stop receiving emails from it, send an email to go-cd+un...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/go-cd/ecea2f6e-8a65-46ad-ac3c-b2d0e5335216o%40googlegroups.com.

[Bob Shazbot]

Actually I don't think this is the issue, Gomatic dumps the XML that it is going to post, I can take this XML and enter it directly into GoCD via the UI without error, it just doesn't work when POST'd to the config.yml endpoint.

[Bob Shazbot]

The schemaVersion is 136 both in GoCD's UI for the config and in the XML that Gomatic POSTs.

To view this discussion on the web visit https://groups.google.com/d/msgid/go-cd/ecea2f6e-8a65-46ad-ac3c-b2d0e5335216o%40googlegroups.com.

[Aravind SV]

Hello Bob, ,

Actually I don’t think this is the issue, Gomatic dumps the XML that it is
going to post, I can take this XML and enter it directly into GoCD via the
UI without error, it just doesn’t work when POST’d to the config.yml
endpoint.

Yes, I found something similar in https://github.com/gocd/gocd/issues/7991. But, I found that I could post it via curl as well, and it was ok.

It doesn’t look like a GoCD issue but something wrong with how it is POSTed? Can you make sure that you used the POST just as I did in that issue, using the md5 param, etc.

Cheers,
Aravind

[Bob Shazbot]

The strange thing is that I am sending several config changes to GoCD via Gomatic, most of them work but a few fail and I cannot figure out why, this was all working fine with version 19.9.

For example, I have a bit of code that ensures a few templates exist in GoCD, each template is ensured in GoCD individually (so the config is sent for each template), about 5 of these templates are POST'd to GoCD without issue but 2 of them fail with a 400 BadMessage error in the logs. I can take the XML generated by Gomatic and pop it straight into the UI without issue, but when sent via POST to the config.xml endpoint I get the 400 bad request error.

I have used tcpdump to get the entire request sent to the server and it looks fine, nothing is truncated or anything like, yet GoCD throws the error; I have even extracted the XML from the request that I captured via tcpdump and popped that into the UI and it saved without issue.

Is there anyway to see more detail on the error thrown by the server?

[Bob Shazbot]

I think I am narrowing in on the issue a bit, the size of the config.xml file might be a factor here when submitted to the config.xml endpoint.

I spun up a local version of GoCD 20.2 using Docker, I copied over the config.xml from my production GoCD (cleaning up where needed) and applied my Gomatic config, I got the same errors locally as in production. I then deleted a large amount of config that is not controlled by Gomatic and then re-ran my Gomatic config, this time everything worked without error. I then started adding some dummy pipeline groups to config.xml via the GoCD UI, after I had added a few hundred extras lines Gomatic started to fail again.

As I said earlier all of this worked just fine in version 19.9, so have there been any changes to how the data is parsed for the config.yml endpoint? Limitations on the field sizes or anything along those lines?

Here is the relevant code in Gomatic that handles saving the config to GoCD:

• https://github.com/gocd-contrib/gomatic/blob/master/gomatic/go_cd_configurator.py#L296
• https://github.com/gocd-contrib/gomatic/blob/master/gomatic/go_cd_configurator.py#L358

[Aravind SV]

Hello Bob,

As I said earlier all of this worked just fine in version 19.9, so have there been any changes to how the data is parsed for the config.yml endpoint? Limitations on the field sizes or anything along those lines?

Nothing comes to mind in that area. There were likely some changes around Jetty / TLS though, which might have had some effect.

If it is reproducible though, via a gomatic script you have, we can open an issue and look into it. Or, we can reopen: https://github.com/gocd/gocd/issues/7991

If you have such a script, please add a comment in https://github.com/gocd/gocd/issues/7991 and I will reopen it. Or, open a new issue.

Thank you,
Aravind

[Bob Shazbot]

Sure thing, I will re-open that issue now and come up with something reproducable that doesn't leak my secrets :D.

[Bob Shazbot]

I have narrowed the issue down to version 20.2 specifically, 20.1 is fine. I am still in the process of putting together steps that guarantee reproducability.

[Dinesh kumar]

Hi lobst.

Have you figured out this facing same issue.

[Dinesh kumar]

Assuming there is something wrong with config or size is too big. It should give some useful message.
Like size is too big or unable to parse because of this line number or something.