We recently updated DHIS2 from v2.39.3.1 to v2.39.4.1. Before the patch update, the Analytics tables rebuild would take about 6 hours, but now its taking about 14 hours and in the image. There were no changes done to system aprt from the war file, both Tomcat and PostgreSQL versions remained the same.
Any leads to what could have changed in the latest patch and if there is a solution? I tried turning off Analytics wal logs but doesnt seem to help at all.
1 Like
Hi @WaluQ
Would it by any chance be possible to compare between the Catalina.out log in the previous version and the latest update when analytics export tables run?
I think it’s worthwhile to investigate this so I’m wondering what more info you could provide. You mentioned that Tomcat and PostgreSQL versions are the same, the system configurations and infrastructure is the same, the ‘data’ itself is the same, but the only change was running the update?
If the data is the same and the only change in the whole system was to update, could it be that this happens only the first couple of runs?
Thanks!
1 Like
The update was on the 23rd of February. Below is Catalina log from 21st.
20-Feb-2024 22:01:05.457 INFO [https-jsse-nio-8-exec-524] org.apache.tomcat.util.http.parser.Cookie.logInvalidHeader A cookie header was received [/cevERpYUzkCjpuRIhcGga1sBIJ492g3y/d0WAglKcbt+0r3htZGUoe/G+oFbtAUbxcOL1862y+lzB5iS1u8iJF40mYfSYdoi1eY0kgK4A1tQXdZ3+3c5BxWLGhDbIiEHAUHrNpUzhWVRPbfX+HdAzEicDSVtip2sqJgMQ2PNfikZ6inD2lsPh9K35Er3xPCTbwQjCmjPOItoBTDUVIi+OTmRQcxHaHVGflWSUJWxTPaQX5ZHOAzcBZL02kU2M50j80DK47DNCrM+xmWY1t+RaeEOqhVVW5xY4CepL+2v922/dMcSDaL7zwrpy2DOIKrl+WXUqptqvAyxLhjLUA==] that contained an invalid cookie. That cookie will be ignored.
Note: further occurrences of this error will be logged at DEBUG level.
20-Feb-2024 22:01:33.833 INFO [https-jsse-nio-8-exec-547] org.apache.coyote.http11.Http11Processor.service Error parsing HTTP request header
Note: further occurrences of HTTP request parsing errors will be logged at DEBUG level.
java.lang.IllegalArgumentException: Request header is too large
at org.apache.coyote.http11.Http11InputBuffer.fill(Http11InputBuffer.java:795)
at org.apache.coyote.http11.Http11InputBuffer.parseHeader(Http11InputBuffer.java:958)
at org.apache.coyote.http11.Http11InputBuffer.parseHeaders(Http11InputBuffer.java:619)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:533)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1673)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:834)
20-Feb-2024 22:02:26.479 INFO [https-jsse-nio-8-exec-581] org.apache.coyote.http11.Http11Processor.service Error parsing HTTP request header
Note: further occurrences of HTTP request parsing errors will be logged at DEBUG level.
java.lang.IllegalArgumentException: Request header is too large
at org.apache.coyote.http11.Http11InputBuffer.fill(Http11InputBuffer.java:795)
at org.apache.coyote.http11.Http11InputBuffer.parseHeader(Http11InputBuffer.java:958)
at org.apache.coyote.http11.Http11InputBuffer.parseHeaders(Http11InputBuffer.java:619)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:533)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1673)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:834)
21-Feb-2024 19:25:55.695 INFO [https-jsse-nio-8-exec-590] org.apache.coyote.http11.Http11Processor.service Error parsing HTTP request header
Note: further occurrences of HTTP request parsing errors will be logged at DEBUG level.
java.lang.IllegalArgumentException: Request header is too large
at org.apache.coyote.http11.Http11InputBuffer.fill(Http11InputBuffer.java:795)
at org.apache.coyote.http11.Http11InputBuffer.parseHeader(Http11InputBuffer.java:958)
at org.apache.coyote.http11.Http11InputBuffer.parseHeaders(Http11InputBuffer.java:619)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:533)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1673)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:834)
and then 24th
24-Feb-2024 02:15:28.514 INFO [https-jsse-nio-8-exec-39] org.apache.coyote.http11.Http11Processor.service Error parsing HTTP request header
Note: further occurrences of HTTP request parsing errors will be logged at DEBUG level.
java.lang.IllegalArgumentException: Invalid character found in method name [{"method":"login","params":{"login":"XXXXXXXXXXXXXXXXXXXXXXXXXXXXX","pass":"xxoo","agent":"xmr-stak-cpu/1.3.0-1.5.0"},"id":1}0x0a...]. HTTP method names must be tokens
at org.apache.coyote.http11.Http11InputBuffer.parseRequestLine(Http11InputBuffer.java:434)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:511)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1673)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:834)
24-Feb-2024 17:36:19.679 INFO [https-jsse-nio-8-exec-101] org.apache.coyote.http11.Http11Processor.service Error parsing HTTP request header
Note: further occurrences of HTTP request parsing errors will be logged at DEBUG level.
java.lang.IllegalArgumentException: Invalid character found in the request target [/index.php?lang=../../../../../../../../usr/local/lib/php/pearcmd&+config-create+/&/<?echo(md5("hi"));?>+/var/tmp/index1.php ]. The valid characters are defined in RFC 7230 and RFC 3986
at org.apache.coyote.http11.Http11InputBuffer.parseRequestLine(Http11InputBuffer.java:509)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:511)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1673)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:834)
And from dhis-analytics-table.log, the problem seem to start from this sectin:
INFO 2024-02-29T18:01:41,508 Get tables using earliest: Wed Jan 01 00:00:00 CAT 2020, spatial support: true (JdbcEventAnalyticsTableManager.java [taskScheduler-15])
* INFO 2024-03-01T03:44:52,935 Table update start: analytics_event, earliest: 2020-01-01T00:00:00, parameters: AnalyticsTableUpdateParams{last years=5, skip resource tables=false, skip table types=[], skip programs=[], start time=2024-02-29T18:00:00}: 09:43:10.691 (Clock.java [taskScheduler-15])
* INFO 2024-03-01T03:44:52,935 Performed pre-create table work EVENT: 09:43:10.692 (Clock.java [taskScheduler-15])
* INFO 2024-03-01T03:44:52,951 Dropped temp tables: 09:43:10.707 (Clock.java [taskScheduler-15])
Dear Muyunda,
Can you please help us with the size of your database and the allocated RAM to the postgres? Thank you very much for the log. I will review it and get back to you.
This is a very small database and even the 6 hours was too much for such a size.
Hello Muyunda
Can you post the full dhis-analytics-table-log for the analytics run? Or put it somewhere with a link to it.
The snippets of catalina.out you shared dont seem relevant to the problem. Some random scripts trying (probably unsuccessfully) to hack your system.
Regards
Bob
2 Likes