[root@ip-XXX-XX-XX-XXX tomcat8]# tail -f catalina.out Sep 09, 2020 2:26:28 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms Sep 09, 2020 2:26:38 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: fetching new list of Forms Sep 09, 2020 2:26:38 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: incoming- last Fetch: -9992 [S: -895122 Eq: -895145 Fs: 4855] futureMillis: 4855 Sep 09, 2020 2:26:38 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: -fetched- last Fetch: 0 [S: -895122 Eq: -895145 Fs: 4855] futureMillis: -1 Sep 09, 2020 2:26:38 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms RUNNING WATCHDOG TASK IN TOMCAT Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkTasks INFO: ---------------------BEGIN Watchdog Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkUpload INFO: Checking upload for Google Spreadsheet fsc: uuid:c1d29d98-cd1e-4046-84c1-0c11286d1395 UPLOAD TASK IN TOMCAT Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkPersistentResults INFO: Checking all persistent results Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkPersistentResults INFO: Done checking persistent results Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkMiscTasks INFO: Checking miscellaneous tasks Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkMiscTasks INFO: Done checking miscellaneous tasks Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.tomcat.WatchdogImpl setFasterWatchdogCycleEnabled INFO: setFasterWatchdogCycleEnabled: CHANGING to: true Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.tomcat.WatchdogImpl createWatchdogTask INFO: Changing WatchdogWorker Executor to 30000ms intervals. KILL EXISTING WATCHDOG TASK IN TOMCAT SCHEDULE NEW WATCHDOG TASK IN TOMCAT RUNNING WATCHDOG TASK IN TOMCAT Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: incoming- last Fetch: -4897 [S: -18 Eq: -900042 Fs: -42] futureMillis: 30000 Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkTasks INFO: ---------------------BEGIN Watchdog Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: -fetched- last Fetch: 0 [S: -18 Eq: -900042 Fs: -42] futureMillis: -1 Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: Eq-update last Fetch: 0 [S: -18 Eq: 0 Fs: -42] futureMillis: 30000 requested: 30000 Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkTasks INFO: ---------------------END Watchdog EXITING WATCHDOG TASK IN TOMCAT Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.util.BackendActionsTable updateWatchdogStart WARNING: watchdog started early: 1599661603620 vs 1599661633597 Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.util.BackendActionsTable updateWatchdogStart WARNING: ---------------WATCHDOG SHOULD BE CULLED! Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkPersistentResults INFO: Checking all persistent results Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkPersistentResults INFO: Done checking persistent results Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkMiscTasks INFO: Checking miscellaneous tasks Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkMiscTasks INFO: Done checking miscellaneous tasks Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.tomcat.WatchdogImpl setFasterWatchdogCycleEnabled INFO: setFasterWatchdogCycleEnabled: CHANGING to: false Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.tomcat.WatchdogImpl createWatchdogTask INFO: Changing WatchdogWorker Executor to 900000ms intervals. KILL EXISTING WATCHDOG TASK IN TOMCAT SCHEDULE NEW WATCHDOG TASK IN TOMCAT RUNNING WATCHDOG TASK IN TOMCAT Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkTasks INFO: ---------------------END Watchdog EXITING WATCHDOG TASK IN TOMCAT Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkTasks INFO: ---------------------BEGIN Watchdog Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.util.BackendActionsTable updateWatchdogStart WARNING: watchdog started early: 1599661603637 vs 1599661633620 Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkPersistentResults INFO: Checking all persistent results Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkPersistentResults INFO: Done checking persistent results Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkMiscTasks INFO: Checking miscellaneous tasks Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkMiscTasks INFO: Done checking miscellaneous tasks Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.WatchdogWorkerImpl checkTasks INFO: ---------------------END Watchdog EXITING WATCHDOG TASK IN TOMCAT Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl uploadAllSubmissions INFO: Beginning UPLOAD service: uuid:c1fd4f83-e772-4af7-ab6b-cf04bc0fc927 form MS005_Comm_CPHP_Phone_Survey_ML_v03 Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: fetching new list of Forms Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: incoming- last Fetch: -90 [S: -68 Eq: -90 Fs: -132] futureMillis: 899910 Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: -fetched- last Fetch: 0 [S: -68 Eq: -90 Fs: -132] futureMillis: -1 Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: Fs-update last Fetch: 0 [S: -68 Eq: -90 Fs: 899910] futureMillis: 899910 requested: 899910 Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl uploadAllSubmissions INFO: Upload invoked when operational status is ACTIVE_RETRY Sep 09, 2020 2:26:43 PM org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl uploadSubmissions INFO: There are 10 submissions available for upload Sep 09, 2020 2:26:44 PM org.opendatakit.aggregate.externalservice.GoogleSpreadsheet insertData SEVERE: Unable to insert data into spreadsheet MY_PUBLISHED_FORM_WITH_REPEAT_GROUPS exception: null java.lang.NullPointerException Sep 09, 2020 2:26:44 PM org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl sendSubmissions SEVERE: Error org.opendatakit.aggregate.exception.ODKExternalServiceException: java.lang.NullPointerException at org.opendatakit.aggregate.externalservice.GoogleSpreadsheet.insertData(GoogleSpreadsheet.java:649) at org.opendatakit.aggregate.externalservice.AbstractExternalService.sendSubmission(AbstractExternalService.java:138) at org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl.sendSubmissions(UploadSubmissionsWorkerImpl.java:292) at org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl.uploadSubmissions(UploadSubmissionsWorkerImpl.java:254) at org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl.uploadAllSubmissions(UploadSubmissionsWorkerImpl.java:177) at org.opendatakit.aggregate.task.tomcat.UploadSubmissionsImpl$UploadSubmissionsRunner.run(UploadSubmissionsImpl.java:46) at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622) at java.lang.Thread.run(Thread.java:748) Caused by: java.lang.NullPointerException Sep 09, 2020 2:26:44 PM org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl uploadAllSubmissions SEVERE: External service error org.opendatakit.aggregate.exception.ODKExternalServiceException: java.lang.NullPointerException at org.opendatakit.aggregate.externalservice.GoogleSpreadsheet.insertData(GoogleSpreadsheet.java:649) at org.opendatakit.aggregate.externalservice.AbstractExternalService.sendSubmission(AbstractExternalService.java:138) at org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl.sendSubmissions(UploadSubmissionsWorkerImpl.java:292) at org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl.uploadSubmissions(UploadSubmissionsWorkerImpl.java:254) at org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl.uploadAllSubmissions(UploadSubmissionsWorkerImpl.java:177) at org.opendatakit.aggregate.task.tomcat.UploadSubmissionsImpl$UploadSubmissionsRunner.run(UploadSubmissionsImpl.java:46) at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622) at java.lang.Thread.run(Thread.java:748) Caused by: java.lang.NullPointerException Sep 09, 2020 2:26:44 PM org.opendatakit.common.persistence.engine.pgres.DatastoreImpl deleteEntity INFO: Executing DELETE FROM "odk_prod"."_task_lock" WHERE "_URI" = ? with key 5e93b14f-0a01-43af-94b4-cac0304f17ef by user aggregate.opendatakit.org:web-service org.opendatakit.aggregate.exception.ODKExternalServiceException: java.lang.NullPointerException at org.opendatakit.aggregate.externalservice.GoogleSpreadsheet.insertData(GoogleSpreadsheet.java:649) at org.opendatakit.aggregate.externalservice.AbstractExternalService.sendSubmission(AbstractExternalService.java:138) at org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl.sendSubmissions(UploadSubmissionsWorkerImpl.java:292) at org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl.uploadSubmissions(UploadSubmissionsWorkerImpl.java:254) at org.opendatakit.aggregate.task.UploadSubmissionsWorkerImpl.uploadAllSubmissions(UploadSubmissionsWorkerImpl.java:177) at org.opendatakit.aggregate.task.tomcat.UploadSubmissionsImpl$UploadSubmissionsRunner.run(UploadSubmissionsImpl.java:46) at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622) at java.lang.Thread.run(Thread.java:748) Caused by: java.lang.NullPointerException Sep 09, 2020 2:27:29 PM org.opendatakit.common.security.spring.RoleHierarchyImpl refreshReachableGrantedAuthorities INFO: Executing: refreshReachableGrantedAuthorities Sep 09, 2020 2:27:29 PM org.opendatakit.common.security.spring.UserServiceImpl reloadPermissions INFO: Executing: reloadPermissions Sep 09, 2020 2:27:29 PM org.opendatakit.aggregate.servlet.SubmissionServlet doHead INFO: Inside doHead Sep 09, 2020 2:27:29 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: fetching new list of Forms Sep 09, 2020 2:27:29 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: incoming- last Fetch: -45867 [S: -45935 Eq: -45957 Fs: 854043] futureMillis: 854043 Sep 09, 2020 2:27:29 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: -fetched- last Fetch: 0 [S: -45935 Eq: -45957 Fs: 854043] futureMillis: -1 Sep 09, 2020 2:27:29 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms Sep 09, 2020 2:27:29 PM org.opendatakit.common.persistence.engine.pgres.DatastoreImpl deleteEntity INFO: Executing DELETE FROM "odk_prod"."_task_lock" WHERE "_URI" = ? with key 2ef4ff21-ac67-46e8-b009-953597c37620 by user anonymousUser Sep 09, 2020 2:27:29 PM org.opendatakit.aggregate.servlet.SubmissionServlet doPost INFO: Successful OpenRosa submission Sep 09, 2020 2:27:30 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms Sep 09, 2020 2:27:30 PM org.opendatakit.common.persistence.engine.pgres.DatastoreImpl deleteEntity INFO: Executing DELETE FROM "odk_prod"."_task_lock" WHERE "_URI" = ? with key a36df820-b7f1-4ec3-b546-599a91801ccc by user anonymousUser Sep 09, 2020 2:27:30 PM org.opendatakit.aggregate.servlet.SubmissionServlet doPost INFO: Successful OpenRosa submission Sep 09, 2020 2:27:31 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms Sep 09, 2020 2:27:31 PM org.opendatakit.common.persistence.engine.pgres.DatastoreImpl deleteEntity INFO: Executing DELETE FROM "odk_prod"."_task_lock" WHERE "_URI" = ? with key 3ad1b27b-a8a5-421e-9417-1699952a6f88 by user anonymousUser Sep 09, 2020 2:27:31 PM org.opendatakit.aggregate.servlet.SubmissionServlet doPost INFO: Successful OpenRosa submission Sep 09, 2020 2:27:31 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms Sep 09, 2020 2:27:32 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms Sep 09, 2020 2:27:32 PM org.opendatakit.common.persistence.engine.pgres.DatastoreImpl deleteEntity INFO: Executing DELETE FROM "odk_prod"."_task_lock" WHERE "_URI" = ? with key a7be8027-d49b-44f3-9aa3-b89f70e93181 by user anonymousUser Sep 09, 2020 2:27:32 PM org.opendatakit.aggregate.servlet.SubmissionServlet doPost INFO: Successful OpenRosa submission Sep 09, 2020 2:27:32 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: fetching new list of Forms Sep 09, 2020 2:27:32 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: incoming- last Fetch: -3322 [S: -49257 Eq: -49279 Fs: 850721] futureMillis: 850721 Sep 09, 2020 2:27:32 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: -fetched- last Fetch: 0 [S: -49257 Eq: -49279 Fs: 850721] futureMillis: -1 Sep 09, 2020 2:27:34 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms Sep 09, 2020 2:27:35 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms Sep 09, 2020 2:27:36 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: fetching new list of Forms Sep 09, 2020 2:27:36 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: incoming- last Fetch: -3959 [S: -53216 Eq: -53238 Fs: 846762] futureMillis: 846762 Sep 09, 2020 2:27:36 PM org.opendatakit.aggregate.util.BackendActionsTable logValues INFO: -fetched- last Fetch: 0 [S: -53216 Eq: -53238 Fs: 846762] futureMillis: -1 Sep 09, 2020 2:27:37 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms Sep 09, 2020 2:27:37 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms Sep 09, 2020 2:27:38 PM org.opendatakit.aggregate.form.FormFactory internalGetForms INFO: FormCache: using cached list of Forms