Invalid character in Last-Modified header tomcat8 with ODK Aggregate

Hello!

We had a setup running with:

  • Apache2, mysql
  • tomcat6
  • ODK Aggregate 1.4.11
  • Apache2 and tomcat8 communicate via AJP.

For about 4-5 months everything was fine. We had a few forms/surveys with images working. We could browse data and view submitted images through ODK Aggregate.

Then all of a sudden any images we had in our forms were not showing up when browsing the data through ODK Aggregate.

Apache was returning an internal server error only when trying to load the images through a browser. Everything else was loading and showing fine. We checked the mysql DB and the images are there.

The apache log files showed:

[Fri Jul 21 23:27:23.638957 2017] [http:error] [pid 1513] [client ...:52402] AH02429: Response header name 'Last-Modified:' contains invalid characters, aborting request, referer: htps://***********/ODKAggregate/Aggregate.html

Full log is below.

We tried upgrading to mysql5.7, Apache2 with AJP communicating to tomcat8 and running ODK Aggregate 1.4.15... but the problem still persists.

We enabled header output in tomcat to the logs... and this is what we found:

"Last-Modified:=Wed, 31 May 2017 09:07:18 GMT"

... See that ':=' there after the word 'Modified'... we think that is the problem.

Apache does not like having both a colon and an equals sign there and just refuses to allow the response to complete back to the web browser.

  • We tried turning turning on ProxyBadHeader in our apache configuration, but that didn't work.
  • We tried the upgrade to latest versions as mentioned above but that did not help.
  • Why was this working for a few months, but then stopped?
  • Where is that coming from? Is that tomcat8? Is it ODK Aggregate?
  • Any suggestions on what we can try?

We would prefer to keep running apache instead of having tomcat directly exposed/servicing everything.

Thank you so much!

Martin.

Here is the full log from apache:
==> odk.error.log <==
[Fri Jul 21 23:27:23.555686 2017] [ssl:info] [pid 1513] [client 0.0.0.0:52402] AH01964: Connection to child 6 established (server myserver:443)
[Fri Jul 21 23:27:23.555990 2017] [ssl:debug] [pid 1513] ssl_engine_kernel.c(2096): [client 0.0.0.0:52402] AH02043: SSL virtual host for servername myserver found
[Fri Jul 21 23:27:23.556051 2017] [core:debug] [pid 1513] protocol.c(2208): [client 0.0.0.0:52402] select protocol from , choices=h2,http/1.1 for server myserver
[Fri Jul 21 23:27:23.556096 2017] [ssl:debug] [pid 1513] ssl_engine_kernel.c(2096): [client 0.0.0.0:52402] AH02043: SSL virtual host for servername myserver found
[Fri Jul 21 23:27:23.586081 2017] [ssl:debug] [pid 1513] ssl_engine_kernel.c(2023): [client 0.0.0.0:52402] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
[Fri Jul 21 23:27:23.586178 2017] [ssl:debug] [pid 1513] ssl_engine_kernel.c(354): [client 0.0.0.0:52402] AH02034: Initial (No.1) HTTPS request received for child 6 (server myserver:443), referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.586254 2017] [authz_core:debug] [pid 1513] mod_authz_core.c(835): [client 0.0.0.0:52402] AH01628: authorization result: granted (no directives), referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.586312 2017] [proxy:debug] [pid 1513] mod_proxy.c(1160): [client 0.0.0.0:52402] AH01143: Running scheme ajp handler (attempt 0), referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.586349 2017] [proxy_ajp:debug] [pid 1513] mod_proxy_ajp.c(743): [client 0.0.0.0:52402] AH00895: serving URL ajp://localhost/ODKAggregate/view/binaryData?blobKey=ct_notes_dummy-20161220%5B%40version%3Dnull+and+%40uiVersion%3Dnull%5D%2Fct_notes_dummy-20161220%5B%40key%3Duuid%3Adce5a0a5-d59b-4df2-9cf6-0ccd4a1e56b5%5D%2Fct_notes_image, referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.586389 2017] [proxy:debug] [pid 1513] proxy_util.c(2160): AH00942: AJP: has acquired connection for (localhost)
[Fri Jul 21 23:27:23.586426 2017] [proxy:debug] [pid 1513] proxy_util.c(2213): [client 0.0.0.0:52402] AH00944: connecting ajp://localhost/ODKAggregate/view/binaryData?blobKey=ct_notes_dummy-20161220%5B%40version%3Dnull+and+%40uiVersion%3Dnull%5D%2Fct_notes_dummy-20161220%5B%40key%3Duuid%3Adce5a0a5-d59b-4df2-9cf6-0ccd4a1e56b5%5D%2Fct_notes_image to localhost:8009, referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.586466 2017] [proxy:debug] [pid 1513] proxy_util.c(2422): [client 0.0.0.0:52402] AH00947: connected /ODKAggregate/view/binaryData?blobKey=ct_notes_dummy-20161220%5B%40version%3Dnull+and+%40uiVersion%3Dnull%5D%2Fct_notes_dummy-20161220%5B%40key%3Duuid%3Adce5a0a5-d59b-4df2-9cf6-0ccd4a1e56b5%5D%2Fct_notes_image to localhost:8009, referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.586561 2017] [proxy_ajp:debug] [pid 1513] mod_proxy_ajp.c(269): [client 0.0.0.0:52402] AH00872: APR_BUCKET_IS_EOS, referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.586609 2017] [proxy_ajp:debug] [pid 1513] mod_proxy_ajp.c(275): [client 0.0.0.0:52402] AH00873: data to read (max 8186 at 4), referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.586647 2017] [proxy_ajp:debug] [pid 1513] mod_proxy_ajp.c(289): [client 0.0.0.0:52402] AH00875: got 0 bytes of data, referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.638957 2017] [htp:error] [pid 1513] [client 0.0.0.0:52402] AH02429: Response header name 'Last-Modified:' contains invalid characters, aborting request, referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.663051 2017] [proxy_ajp:debug] [pid 1513] mod_proxy_ajp.c(551): [client 0.0.0.0:52402] AH00888: error processing end, referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.663133 2017] [proxy_ajp:debug] [pid 1513] mod_proxy_ajp.c(611): [client 0.0.0.0:52402] AH00890: Processing of request failed backend: 0, client: 1, referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.663162 2017] [proxy_ajp:error] [pid 1513] [client 0.0.0.0:52402] AH02822: dialog with client 0.0.0.0:52402 failed, referer: htps://myserver/ODKAggregate/Aggregate.html
[Fri Jul 21 23:27:23.663229 2017] [proxy:debug] [pid 1513] proxy_util.c(2175): AH00943: AJP: has released connection for (localhost)

This is a hard one, Martin.

My guess is that the problem is with Apache2. It's strange that this just started happening. Is it possible something changed on the server (maybe a security update)?

What I'd do is try to get this down to the minimal reproducible configuration. Start with the form and get to the minimal form that has the problem. Try different devices and connections to sanity check that it isn't the device.

Then spin up a fresh server with the versions you are running in production and see if you can reproduce the problem there. Now try a fresh server with the latest versions of things. Does the problem still exist? Now what about a server with just Tomcat/MySQL? Add Apache2 and see if the problem changes.

For the server tests, look at using Vagrant/Ansible so you can quickly spin up and shut down the test servers. I've got an Aggregate build at https://github.com/nafundi/odk-aggregate-box that's a good place to start from.

Hello! Thank you for the response and your suggestions! These are very helpful.

We figured out that apache2 was now allowing the images through because the http response headers were not correct and but we couldn't figure out how to disable that 'protection' ('ProxyBadHeader ignore' did not work).

Today we ended up having tomcat directly work on port 443 with authbind and the problem is "gone". The web browsers are now able to load the images. To us this means the core problem was not apache or ajp... but something either tomcat/odk/db related.

As an experiment, I loaded up the developer tools in the browser with this working setup (just tomcat on 443) and looked at the raw headers when I clicked on the images in ODK Aggregate. They is still something funny with them... there is an extra ':' this time. The browsers seem more friendly to broken headers. Apache specifically had a module we couldn't figure how to turn off that would reject broken headers.

For the thumbnail image:
"Expires: : Tue, 25 Jul 2017 23:16:37 GMT
Last-Modified: : Thu, 13 Jul 2017 11:28:29 GMT
Content-Type: image/jpeg
Content-Length: 1676
Date: Tue, 25 Jul 2017 22:16:37 GMT"

For the actual image:
"Last-Modified: : Thu, 13 Jul 2017 11:28:29 GMT
Content-Type: image/jpeg
Content-Length: 2444370
Date: Tue, 25 Jul 2017 21:58:00 GMT"

We are just going to stick with this setup for now where tomcat is directly serving on 443 with authbind.

If we decide to again at some point try out apache or nginx proxy-ing to tomcat, we will start with a fresh DB and fresh surveys to see if this issue keeps showing up (we expect to flush our DB in the next few weeks anyways).

If you or anyone happens to have a little time and have a survey loaded in your DB with some images, can you see if the raw headers have some extra chars in the last-modified field?

Thank you so much again for the response! It was very helpful and we appreciate it very much!

Martin.

Hi Guys,
I had the same issue and after researching the error I could find that, it is an issue in apache web server 2.4.6 that it is resolved in 2.4.10, but since I have it installed in Centos 7 (apache ws version 2.4.6) and no update released yet to 2.4.10, then I only added "HttpProtocolOptions unsafe" to the end of httpd.conf file and it magically worked. Please check this link to know more about it:
https://www.debian.org/security/2017/dsa-3796

4 Likes