Schedule Analytics tables updating causing deadlock?

linxd · 8 September 2021 07:24

I got the following error （not allways）, can’t login, system stop response:

INFO 2021-09-08T14:46:12,471 Analytics tables updated: 00:00:00.959 (NotificationLoggerUtil.java [taskScheduler-13])
INFO 2021-09-08T14:46:12,477 ‘system-process’ update org.hisp.dhis.schedulinedulbConfiguration, name: shorttime_update , uid: wP2viSaWahc (AuditLogUtil.java [taskSch
er-13])
WARN 2021-09-08T14:55:18,982 com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@22f2ccda – APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks! (Slf4jMLog.java [C3P0PooledConnectionPoolManager[identityToken->1bqrxewaj1cxc6wyz791l6|56e0106e]-AdminTaskTimer])
WARN 2021-09-08T14:58:34,604 com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@22f2ccda – APPARENT DEADLOCK!!! Complete Status:
Managed Threads: 3
Active Threads: 3
Active Tasks:
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@19662bc2
on thread: C3P0PooledConnectionPoolManager[identityToken->1bqrxewaj1cxc6wyz791l6|56e0106e]-HelperThread-#2
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@2101892f
on thread: C3P0PooledConnectionPoolManager[identityToken->1bqrxewaj1cxc6wyz791l6|56e0106e]-HelperThread-#0
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@214d0f87
on thread: C3P0PooledConnectionPoolManager[identityToken->1bqrxewaj1cxc6wyz791l6|56e0106e]-HelperThread-#1
Pending Tasks:
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@70b6d0a1
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@5826cd4e
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@75437f94
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@3cbb778c
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@7ace8b62
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@14ec65c8
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@7a3d171e
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@1d5d18c2
Pool thread stack traces:
Thread[C3P0PooledConnectionPoolManager[identityToken->1bqrxewaj1cxc6wyz791l6|56e0106e]-HelperThread-#2,1,main]
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:720)
Thread[C3P0PooledConnectionPoolManager[identityToken->1bqrxewaj1cxc6wyz791l6|56e0106e]-HelperThread-#0,1,main]
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:720)
Thread[C3P0PooledConnectionPoolManager[identityToken->1bqrxewaj1cxc6wyz791l6|56e0106e]-HelperThread-#1,1,main]
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:720)
(Slf4jMLog.java [C3P0PooledConnectionPoolManager[identityToken->1bqrxewaj1cxc6wyz791l6|56e0106e]-AdminTaskTimer])
INFO 2021-09-08T14:59:01,065 ‘system-process’ update org.hisp.dhis.schedulinedulbConfiguration, name: shorttime_update , uid: wP2viSaWahc (AuditLogUtil.java [taskSch
er-3])

Gassim · 8 September 2021 08:28

Hey @linxd,
Please see if you have any long running queries or deadlocks in the DB? And, please share the dhis.conf for the db thread pool.

linxd · 8 September 2021 09:41

dhis.conf has no specifial db pool setting.

Gassim · 8 September 2021 10:05

Then it’s the default setting which I think is good, so you’ll have to check the DB.

Hobbes · 22 April 2023 02:42

Alright, I might be experiencing a similar issue.

I’m trying to collect the logs to see what was happening before the crash, but having trouble interpreting things.

Would anyone be willing to share what they would look for in a situation where their DHIS2 instance crashed. (Seems like it has something to do with my analytics schedule, but also seems to only crash randomly. Currently like once a month)

Currently I have the scheduler running the analytics table update every hour.
Analytics Analytics table Every hour

On my 3-27-2023 crash I found the following errors in the cat out log:

* ERROR 2023-03-27T17:00:17,251 StatementCallback; bad SQL grammar [drop table if exists analytics_2023 cascade;alter table analytics_temp_2023 rename to analytics_2023;]; nested exception is org.postgresql.util.PSQLException: ERROR: relation "analytics_temp_2023" does not exist (AbstractJdbcTableManager.java [taskScheduler-21]) UID:JVeXza506XJ

* ERROR 2023-03-27T17:00:17,270 StatementCallback; bad SQL grammar [drop table if exists analytics cascade;alter table analytics_temp rename to analytics;]; nested exception is org.postgresql.util.PSQLException: ERROR: relation "analytics_temp" does not exist (AbstractJdbcTableManager.java [taskScheduler-21]) UID:JVeXza506XJ

 

* ERROR 2023-03-27T17:00:17,792 StatementCallback; bad SQL grammar [drop table if exists analytics_completeness_2022 cascade;alter table analytics_completeness_temp_2022 rename to analytics_completeness_2022;]; nested exception is org.postgresql.util.PSQLException: ERROR: relation "analytics_completeness_temp_2022" does not exist (AbstractJdbcTableManager.java [taskScheduler-21]) UID:JVeXza506XJ

* ERROR 2023-03-27T17:00:17,805 StatementCallback; bad SQL grammar [drop table if exists analytics_completeness_2023 cascade;alter table analytics_completeness_temp_2023 rename to analytics_completeness_2023;]; nested exception is org.postgresql.util.PSQLException: ERROR: relation "analytics_completeness_temp_2023" does not exist (AbstractJdbcTableManager.java [taskScheduler-21]) UID:JVeXza506XJ

* ERROR 2023-03-27T17:00:17,815 StatementCallback; bad SQL grammar [drop table if exists analytics_completeness cascade;alter table analytics_completeness_temp rename to analytics_completeness;]; nested exception is org.postgresql.util.PSQLException: ERROR: relation "analytics_completeness_temp" does not exist (AbstractJdbcTableManager.java [taskScheduler-21]) UID:JVeXza506XJ

 

* ERROR 2023-03-27T17:00:17,875 StatementCallback; bad SQL grammar [drop table if exists analytics_completenesstarget cascade;alter table analytics_completenesstarget_temp rename to analytics_completenesstarget;]; nested exception is org.postgresql.util.PSQLException: ERROR: relation "analytics_completenesstarget_temp" does not exist (AbstractJdbcTableManager.java [taskScheduler-21]) UID:JVeXza506XJ

 

* ERROR 2023-03-27T17:00:17,905 StatementCallback; bad SQL grammar [drop table if exists analytics_orgunittarget cascade;alter table analytics_orgunittarget_temp rename to analytics_orgunittarget;]; nested exception is org.postgresql.util.PSQLException: ERROR: relation "analytics_orgunittarget_temp" does not exist (AbstractJdbcTableManager.java [taskScheduler-21]) UID:JVeXza506XJ

On the 4-12-2023 crash was where I saw the deadlock comment before seeing the output from my startup

Welcome to Ubuntu 18.04.6 LTS (GNU/Linux 5.4.0-1099-aws x86_64)

 * Documentation:  https://help.ubuntu.com
 * Management:     https://landscape.canonical.com
 * Support:        https://ubuntu.com/advantage

  System information as of Wed Apr 12 12:37:44 PDT 2023

  System load:  0.8               Processes:           139
  Usage of /:   61.3% of 7.57GB   Users logged in:     0
  Memory usage: 57%               
  Swap usage:   0%

 * Ubuntu Pro delivers the most comprehensive open source security and
   compliance features.

   https://ubuntu.com/aws/pro

15 updates can be applied immediately.
1 of these updates is a standard security update.
To see these additional updates run: apt list --upgradable


Last login: Mon Mar 27 20:24:43 2023
ubuntu@ip:~$ sudo tail -n 300 /home/dhis/tomcat-dhis/logs/catalina.out
* INFO  2023-04-12T10:01:15,665 Org unit data set association map SQL: select ou.uid as ou_uid, array_agg(ds.uid) as ds_uid from datasetsource d inner join organisationunit ou on ou.organisationunitid=d.sourceid inner join dataset ds on ds.datasetid=d.datasetid where (ou.path like '/I3bQd1JkL5U/kHxrPY1PU2L/KYZImY2C0RQ%' ) and ds.datasetid in (163) group by ou_uid (HibernateOrganisationUnitStore.java [http-nio-8080-exec-1]) ID3cQiuy6P9epunS2gtFqBxAcFfO+C7/ajHaYQCauAijE=
* WARN  2023-04-12T11:14:46,124 com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@40de7ea3 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks! (Slf4jMLog.java [C3P0PooledConnectionPoolManager[identityToken->1br9qnzavambrend7in22|77e5ee0b]-AdminTaskTimer])
12-Apr-2023 11:46:47.321 WARNING [http-nio-8080-exec-5] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [3,642,107] milliseconds.
NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
12-Apr-2023 12:36:04.010 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/home/dhis/tomcat-dhis/common/classes], exists: [false], isDirectory: [false], canRead: [false]
12-Apr-2023 12:36:04.017 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/home/dhis/tomcat-dhis/common], exists: [false], isDirectory: [false], canRead: [false]
12-Apr-2023 12:36:04.017 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/usr/share/tomcat8/common/classes], exists: [false], isDirectory: [false], canRead: [false]
12-Apr-2023 12:36:04.019 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/usr/share/tomcat8/common], exists: [false], isDirectory: [false], canRead: [false]
12-Apr-2023 12:36:04.029 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/home/dhis/tomcat-dhis/server/classes], exists: [false], isDirectory: [false], canRead: [false]
12-Apr-2023 12:36:04.029 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/home/dhis/tomcat-dhis/server], exists: [false], isDirectory: [false], canRead: [false]
12-Apr-2023 12:36:04.029 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/usr/share/tomcat8/server/classes], exists: [false], isDirectory: [false], canRead: [false]
12-Apr-2023 12:36:04.030 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/usr/share/tomcat8/server], exists: [false], isDirectory: [false], canRead: [false]
12-Apr-2023 12:36:04.031 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/home/dhis/tomcat-dhis/shared/classes], exists: [false], isDirectory: [false], canRead: [false]
12-Apr-2023 12:36:04.031 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/home/dhis/tomcat-dhis/shared], exists: [false], isDirectory: [false], canRead: [false]
12-Apr-2023 12:36:04.032 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/usr/share/tomcat8/shared/classes], exists: [false], isDirectory: [false], canRead: [false]
12-Apr-2023 12:36:04.033 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/usr/share/tomcat8/shared], exists: [false], isDirectory: [false], canRead: [false]
12-Apr-2023 12:36:06.298 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version:        Apache Tomcat/8.5.39 (Ubuntu)
12-Apr-2023 12:36:06.299 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Sep 9 2019 19:47:51 UTC
12-Apr-2023 12:36:06.299 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number:         8.5.39.0
12-Apr-2023 12:36:06.299 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
12-Apr-2023 12:36:06.299 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            5.4.0-1099-aws
12-Apr-2023 12:36:06.300 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
12-Apr-2023 12:36:06.301 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/lib/jvm/java-11-openjdk-amd64
12-Apr-2023 12:36:06.301 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           11.0.18+10-post-Ubuntu-0ubuntu118.04.1
12-Apr-2023 12:36:06.302 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Ubuntu
12-Apr-2023 12:36:06.302 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /home/dhis/tomcat-dhis
12-Apr-2023 12:36:06.302 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /usr/share/tomcat8
12-Apr-2023 12:36:06.305 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
12-Apr-2023 12:36:06.306 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
12-Apr-2023 12:36:06.306 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
12-Apr-2023 12:36:06.306 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/home/dhis/tomcat-dhis/conf/logging.properties
12-Apr-2023 12:36:06.311 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
12-Apr-2023 12:36:06.314 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xmx2056m
12-Apr-2023 12:36:06.314 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xms2056m
12-Apr-2023 12:36:06.314 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
12-Apr-2023 12:36:06.314 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
12-Apr-2023 12:36:06.315 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
12-Apr-2023 12:36:06.315 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
12-Apr-2023 12:36:06.315 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/home/dhis/tomcat-dhis
12-Apr-2023 12:36:06.315 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/share/tomcat8
12-Apr-2023 12:36:06.316 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/home/dhis/tomcat-dhis/temp
12-Apr-2023 12:36:06.316 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [/usr/java/packages/lib:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib]
12-Apr-2023 12:36:06.396 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
12-Apr-2023 12:36:06.436 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
12-Apr-2023 12:36:06.462 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 2176 ms

Gassim · 26 April 2023 10:07

What version of dhis2 are you using?

Please try to clear server cache, Data Administration app → Maintenance view → Clear application cache, reload apps

Hobbes · 30 April 2023 16:30

Trying the cache clearing now. Here’s the version info

Version	2.38.2.1-SNAPSHOT
Build revision	e590bdc
Build date	December 5, 2022 at 12:21
Jasper reports version	6.18.1
User agent	Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:109.0) Gecko/20100101 Firefox/112.0
Server date	April 30, 2023 at 09:14
Last analytics table generation	April 30, 2023 at 09:00
Time since last analytics table generation	14 m, 21 s
Last analytics table runtime	00:00:16.152
Environment variable	DHIS2_HOME
System ID	25e4b148-d2c4-4ae2-87f7-5e918bfa4b34
Last monitoring success	Never
External configuration directory	/home/dhis/config
File store provider	filesystem
Java opts	-Xmx2056m -Xms2056m -Djdk.tls.ephemeralDHKeySize=2048 -Djava.protocol.handler.pkgs=org.apache.catalina.webresources -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
Java version	11.0.18
Java vendor	Ubuntu
OS name	Linux
OS architecture	amd64
OS version	5.4.0-1100-aws
Memory info	Mem Total in JVM: 2056 Free in JVM: 1472 Max Limit: 2056
CPU cores	2
Calendar	iso8601

Here’s a clip of the latest crash log:

* INFO  2023-04-27T04:00:16,045 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Populating analytics tables COMPLETENESS (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,045 Populate table task number: 2 (DefaultAnalyticsTableService.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,064 Populate analytics_completeness_temp_2022 in: 0.017345 sec. (AbstractJdbcTableManager.java [ForkJoinPool-1757-worker-1])  
* INFO  2023-04-27T04:00:16,065 Populate analytics_completeness_temp_2023 in: 0.019015 sec. (AbstractJdbcTableManager.java [ForkJoinPool-1757-worker-3])  
* INFO  2023-04-27T04:00:16,066 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.021s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,066 Populated analytics tables: 00:00:00.044 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,066 Invoking analytics table hooks COMPLETENESS (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,066 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Invoking analytics table hooks COMPLETENESS (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,067 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.001s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,067 Invoked analytics table hooks: 00:00:00.045 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,069 Applied aggregation levels: 00:00:00.047 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,069 Creating indexes COMPLETENESS (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,069 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Creating indexes COMPLETENESS (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,069 No of analytics table indexes: 50 (DefaultAnalyticsTableService.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,182 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.113s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,183 Created indexes: 00:00:00.161 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,183 Analyzing analytics tables COMPLETENESS (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,183 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Analyzing analytics tables COMPLETENESS (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,189 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.006s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,189 Analyzed tables: 00:00:00.167 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,190 Drop SQL views (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,190 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Drop SQL views (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,190 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,190 Swapping analytics tables COMPLETENESS (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,190 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Swapping analytics tables COMPLETENESS (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,192 Swapping table, master table exists: 'true', skip master table: 'false' (AbstractJdbcTableManager.java [taskScheduler-12]) UID:JVeXza506XJ 
* ERROR 2023-04-27T04:00:16,201 StatementCallback; bad SQL grammar [drop table if exists analytics_completeness_2022 cascade;alter table analytics_completeness_temp_2022 rename to analytics_completeness_2022;]; nested exception is org.postgresql.util.PSQLException: ERROR: relation "analytics_completeness_temp_2022" does not exist (AbstractJdbcTableManager.java [taskScheduler-12]) UID:JVeXza506XJ 
* ERROR 2023-04-27T04:00:16,210 StatementCallback; bad SQL grammar [drop table if exists analytics_completeness_2023 cascade;alter table analytics_completeness_temp_2023 rename to analytics_completeness_2023;]; nested exception is org.postgresql.util.PSQLException: ERROR: relation "analytics_completeness_temp_2023" does not exist (AbstractJdbcTableManager.java [taskScheduler-12]) UID:JVeXza506XJ 
* ERROR 2023-04-27T04:00:16,218 StatementCallback; bad SQL grammar [drop table if exists analytics_completeness cascade;alter table analytics_completeness_temp rename to analytics_completeness;]; nested exception is org.postgresql.util.PSQLException: ERROR: relation "analytics_completeness_temp" does not exist (AbstractJdbcTableManager.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,218 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.028s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,219 Create SQL views (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,219 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Create SQL views (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,219 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,219 Table update done: analytics_completeness: 00:00:00.198 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,220 Analytics table update parameters: AnalyticsTableUpdateParams{last years=null, skip resource tables=false, skip table types=[], skip programs=[], start time=2023-04-27T04:00:00} (DefaultAnalyticsTableService.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,220 Starting update of type: COMPLETENESS_TARGET, table name: 'analytics_completenesstarget', processes: 2: 00:00:00.000 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,220 Validating Analytics Table COMPLETENESS_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,220 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Validating Analytics Table COMPLETENESS_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,220 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,222 Table update start: analytics_completenesstarget, earliest: null, parameters: AnalyticsTableUpdateParams{last years=null, skip resource tables=false, skip table types=[], skip programs=[], start time=2023-04-27T04:00:00}: 00:00:00.002 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,222 Performing pre-create table work (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,223 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Performing pre-create table work (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,223 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,223 Performed pre-create table work COMPLETENESS_TARGET: 00:00:00.002 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,223 Dropping temp tables (if any) COMPLETENESS_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,223 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Dropping temp tables (if any) COMPLETENESS_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,223 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,223 Dropped temp tables: 00:00:00.003 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,223 Creating analytics tables COMPLETENESS_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,223 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Creating analytics tables COMPLETENESS_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,223 Creating table: 'analytics_completenesstarget_temp', columns: '9' (AbstractJdbcTableManager.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,225 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.002s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,225 Created analytics tables: 00:00:00.005 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,225 Populating analytics tables COMPLETENESS_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,225 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Populating analytics tables COMPLETENESS_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,226 Populate table task number: 1 (DefaultAnalyticsTableService.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,230 Populate analytics_completenesstarget_temp in: 0.004463 sec. (AbstractJdbcTableManager.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,231 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.006s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,231 Populated analytics tables: 00:00:00.010 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,231 Invoking analytics table hooks COMPLETENESS_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,231 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Invoking analytics table hooks COMPLETENESS_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,232 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.001s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,232 Invoked analytics table hooks: 00:00:00.012 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,234 Applied aggregation levels: 00:00:00.014 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,234 Creating indexes COMPLETENESS_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,234 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Creating indexes COMPLETENESS_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,234 No of analytics table indexes: 9 (DefaultAnalyticsTableService.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,257 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.023s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,257 Created indexes: 00:00:00.037 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,257 Analyzing analytics tables COMPLETENESS_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,258 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Analyzing analytics tables COMPLETENESS_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,260 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.002s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,260 Analyzed tables: 00:00:00.040 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,260 Drop SQL views (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,260 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Drop SQL views (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,260 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,261 Swapping analytics tables COMPLETENESS_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,261 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Swapping analytics tables COMPLETENESS_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,262 Swapping table, master table exists: 'true', skip master table: 'false' (AbstractJdbcTableManager.java [taskScheduler-12]) UID:JVeXza506XJ 
* ERROR 2023-04-27T04:00:16,269 StatementCallback; bad SQL grammar [drop table if exists analytics_completenesstarget cascade;alter table analytics_completenesstarget_temp rename to analytics_completenesstarget;]; nested exception is org.postgresql.util.PSQLException: ERROR: relation "analytics_completenesstarget_temp" does not exist (AbstractJdbcTableManager.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,269 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.008s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,269 Create SQL views (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,269 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Create SQL views (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,270 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.001s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,270 Table update done: analytics_completenesstarget: 00:00:00.049 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,270 Analytics table update parameters: AnalyticsTableUpdateParams{last years=null, skip resource tables=false, skip table types=[], skip programs=[], start time=2023-04-27T04:00:00} (DefaultAnalyticsTableService.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,270 Starting update of type: ORG_UNIT_TARGET, table name: 'analytics_orgunittarget', processes: 2: 00:00:00.000 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,270 Validating Analytics Table ORG_UNIT_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,270 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Validating Analytics Table ORG_UNIT_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,270 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,270 Table update start: analytics_orgunittarget, earliest: null, parameters: AnalyticsTableUpdateParams{last years=null, skip resource tables=false, skip table types=[], skip programs=[], start time=2023-04-27T04:00:00}: 00:00:00.000 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,270 Performing pre-create table work (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,271 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Performing pre-create table work (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,271 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.001s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,271 Performed pre-create table work ORG_UNIT_TARGET: 00:00:00.000 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,271 Dropping temp tables (if any) ORG_UNIT_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,271 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Dropping temp tables (if any) ORG_UNIT_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,272 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,272 Dropped temp tables: 00:00:00.001 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,272 Creating analytics tables ORG_UNIT_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,272 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Creating analytics tables ORG_UNIT_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,272 Creating table: 'analytics_orgunittarget_temp', columns: '4' (AbstractJdbcTableManager.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,273 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.001s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,273 Created analytics tables: 00:00:00.003 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,273 Populating analytics tables ORG_UNIT_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,274 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Populating analytics tables ORG_UNIT_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,274 Populate table task number: 1 (DefaultAnalyticsTableService.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,275 analytics_orgunittarget_temp in: 0.000882 sec. (AbstractJdbcTableManager.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,276 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.002s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,276 Populated analytics tables: 00:00:00.005 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,276 Invoking analytics table hooks ORG_UNIT_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,276 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Invoking analytics table hooks ORG_UNIT_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,277 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.001s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,277 Invoked analytics table hooks: 00:00:00.006 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,279 Applied aggregation levels: 00:00:00.009 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,279 Creating indexes ORG_UNIT_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,279 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Creating indexes ORG_UNIT_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,279 No of analytics table indexes: 4 (DefaultAnalyticsTableService.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,297 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.018s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,297 Created indexes: 00:00:00.026 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,297 Analyzing analytics tables ORG_UNIT_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,297 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Analyzing analytics tables ORG_UNIT_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,299 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.002s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,299 Analyzed tables: 00:00:00.029 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,305 Drop SQL views (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,305 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Drop SQL views (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,305 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,305 Swapping analytics tables ORG_UNIT_TARGET (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,305 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Swapping analytics tables ORG_UNIT_TARGET (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,307 Swapping table, master table exists: 'true', skip master table: 'false' (AbstractJdbcTableManager.java [taskScheduler-12]) UID:JVeXza506XJ 
* ERROR 2023-04-27T04:00:16,311 StatementCallback; bad SQL grammar [drop table if exists analytics_orgunittarget cascade;alter table analytics_orgunittarget_temp rename to analytics_orgunittarget;]; nested exception is org.postgresql.util.PSQLException: ERROR: relation "analytics_orgunittarget_temp" does not exist (AbstractJdbcTableManager.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,311 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.006s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,312 Create SQL views (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,312 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Create SQL views (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,312 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0s (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,312 Table update done: analytics_orgunittarget: 00:00:00.042 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,312 Analytics table update parameters: AnalyticsTableUpdateParams{last years=null, skip resource tables=false, skip table types=[], skip programs=[], start time=2023-04-27T04:00:00} (DefaultAnalyticsTableService.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,312 Starting update of type: EVENT, table name: 'analytics_event', processes: 2: 00:00:00.000 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,313 Validating Analytics Table EVENT (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,313 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Validating Analytics Table EVENT (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,313 No events exist, not updating event analytics tables (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,313 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0s: No events exist, not updating event analytics tables (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,313 Analytics table update parameters: AnalyticsTableUpdateParams{last years=null, skip resource tables=false, skip table types=[], skip programs=[], start time=2023-04-27T04:00:00} (DefaultAnalyticsTableService.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,313 Starting update of type: VALIDATION_RESULT, table name: 'analytics_validationresult', processes: 2: 00:00:00.000 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,314 Validating Analytics Table VALIDATION_RESULT (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,314 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Validating Analytics Table VALIDATION_RESULT (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,314 No validation results exist, not updating validation result analytics tables (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,314 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0s: No validation results exist, not updating validation result analytics tables (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,314 Analytics table update parameters: AnalyticsTableUpdateParams{last years=null, skip resource tables=false, skip table types=[], skip programs=[], start time=2023-04-27T04:00:00} (DefaultAnalyticsTableService.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,314 Starting update of type: ENROLLMENT, table name: 'analytics_enrollment', processes: 2: 00:00:00.000 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,314 Validating Analytics Table ENROLLMENT (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,314 [ANALYTICS_TABLE JVeXza506XJ] Stage started: Validating Analytics Table ENROLLMENT (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,315 No events exist, not updating event analytics tables (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,315 [ANALYTICS_TABLE JVeXza506XJ] Stage completed after 0.001s: No events exist, not updating event analytics tables (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,315 Analytics tables updated: 00:00:16.191 (Clock.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,315 Analytics tables updated: 00:00:16.191 (NotificationLoggerUtil.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,315 [ANALYTICS_TABLE JVeXza506XJ] Process completed after 16.172s: Analytics tables updated: 00:00:16.191 (ControlledJobProgress.java [taskScheduler-12]) UID:JVeXza506XJ 
* INFO  2023-04-27T04:00:16,325 Analytics cache cleared (AnalyticsCache.java [taskScheduler-12]) UID:JVeXza506XJ 
27-Apr-2023 04:33:41.753 WARNING [http-nio-8080-exec-8] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [12,078] milliseconds.
27-Apr-2023 04:33:41.664 WARNING [http-nio-8080-exec-4] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [18,545] milliseconds.
* WARN  2023-04-27T04:36:15,340 com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@405b8ad1 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks! (Slf4jMLog.java [C3P0PooledConnectionPoolManager[identityToken->1br9qnzavx0crwg1p1h80a|328392b9]-AdminTaskTimer])  
NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED

Gassim · 1 May 2023 08:46

Please use latest version dhis2-stable-2.38.3.1 instead of SNAPSHOT.

Hobbes · 24 May 2023 06:14

Awesome, found time to run this update on a test server. I’ll follow up in a month or 2 if this fixed our issue.

Version	2.38.3.1
Build revision	0339321
Build date	April 14, 2023 at 14:13
Jasper reports version	6.18.1
User agent	Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:109.0) Gecko/20100101 Firefox/113.0
Server date	May 23, 2023 at 23:08
Last analytics table generation	May 23, 2023 at 21:00
Time since last analytics table generation	2 h, 8 m, 59 s
Last analytics table runtime	00:00:17.032
Environment variable	DHIS2_HOME
System ID	25e4b148-d2c4-4ae2-87f7-5e918bfa4b34
Last monitoring success	Never
External configuration directory	/home/dhis/config
File store provider	filesystem
Java opts	-Xmx2056m -Xms2056m -Djdk.tls.ephemeralDHKeySize=2048 -Djava.protocol.handler.pkgs=org.apache.catalina.webresources -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
Java version	11.0.19
Java vendor	Ubuntu
OS name	Linux
OS architecture	amd64
OS version	5.4.0-1101-aws
Memory info	Mem Total in JVM: 2056 Free in JVM: 1842 Max Limit: 2056
CPU cores	2
Calendar	iso8601

Wanted to share a kudos to this post by moses because I couldn’t easily find a good backup command until I stumbled upon his post.

Just because I partially use this forum for my own personal reference (and in hopes that my notes can help others) here’s the commands I used to perform the upgrade. Looks good so far, and will likely run the upgrade on the production server next month just to stay away from the reporting deadline.

Made sure the latest was still the latest:
https://releases.dhis2.org/

2023-04-14 14:43:58
https://releases.dhis2.org/2.38/dhis2-stable-2.38.3.1.war

cd /home/dhis/
sudo -u dhis tomcat-dhis/bin/shutdown.sh

cd ~
sudo -u postgres pg_dump -T analytics_* -T aggregated* -T completeness* -O -x dhis2 | gzip > 2023-05-27_dhis2_database_backup.sql.gz

cd /home/dhis/
sudo wget https://releases.dhis2.org/2.38/dhis2-stable-2.38.3.1.war

sudo mv dhis2-stable-2.38.3.1.war /home/dhis/tomcat-dhis/webapps/ROOT.war

sudo -u dhis /home/dhis/tomcat-dhis/bin/startup.sh

Gassim · 1 June 2023 05:11

Thank you for sharing with the community!