The backup on the server has become unresponsive and has not progressed in 300 seconds

Symptoms

The Stash backup client fails with the error The backup on the server has become unresponsive and has not progressed in 300 seconds.

The following log entries appear in the Backup client logs when it is set in DEBUG mode. Notice from the logs that the backup client doesn't get an update from the database backup happening on the server (it is stuck in 85%) for 5 minutes.

"progress":{"message":"Backing up Stash data","percentage":85},"state":"RUNNING","type":"BACKUP"},"db-state":"DRAINED","scm-state":"DRAINED"}

More details:

...
...
...
...
...
------------
{"task":{"id":"a3dfa62d0d54556997e4f5101a89c792c969c17f","progress":{"message":"Backing up Stash data","percentage":85},"state":"RUNNING","type":"BACKUP"},"db-state":"DRAINED","scm-state":"DRAINED"}
------------
2015-02-05 03:28:02,870 INFO  [main] c.a.s.i.b.client.DefaultBackupClient Waiting on Stash database backup to complete
2015-02-05 03:28:04,356 DEBUG [threadpool2] c.a.s.i.b.client.RestStashService Submitting client progress of 1x00 to http://<Stash_URL>/git/mvc/admin/backups/progress/client?token=9514f3028b1bd7591e63d34dd0da57aa9d85112c&percentage=100
2015-02-05 03:28:04,357 DEBUG [threadpool2] c.a.s.i.b.client.wink.LoggingHandler HTTP POST http://<Stash_URL>/git/mvc/admin/backups/progress/client?token=9514f3028b1bd7591e63d34dd0da57aa9d85112c&percentage=100, headers: [Accept:[application/json], Content-Length:[0], Content-Type:[application/json], User-Agent:[Wink Client v1.1.2], X-Atlassian-Maintenance-Token:[9514f3028b1bd7591e63d34dd0da57aa9d85112c]]
2015-02-05 03:28:04,361 DEBUG [threadpool2] c.a.s.i.b.client.wink.LoggingHandler -> 202 Accepted (@A91CNBx208x1294518x0)
2015-02-05 03:28:04,361 DEBUG [threadpool2] c.a.s.i.b.c.s.h.WinkClientHttpResponse HTTP status code: 202, status text: "Accepted", headers: [Content-Length:[0], Date:[Thu, 05 Feb 2015 02:28:04 GMT], Server:[Apache-Coyote/1.1], X-AREQUESTID:[@A91CNBx208x1294518x0], X-Content-Type-Options:[nosniff], X-Frame-Options:[SAMEORIGIN], X-XSS-Protection:[1; mode=block]]
2015-02-05 03:28:04,362 DEBUG [threadpool2] c.a.s.i.b.client.RestStashService Finished submitting client progress
2015-02-05 03:28:07,865 DEBUG [threadpool1] c.a.s.i.b.client.wink.LoggingHandler HTTP GET http://<Stash_URL>/git/mvc/maintenance, headers: [Accept:[application/json], User-Agent:[Wink Client v1.1.2], X-Atlassian-Maintenance-Token:[9514f3028b1bd7591e63d34dd0da57aa9d85112c]]
2015-02-05 03:28:07,868 DEBUG [threadpool1] c.a.s.i.b.client.wink.LoggingHandler -> 200 OK (@A91CNBx208x1294538x0)
2015-02-05 03:28:07,869 DEBUG [threadpool1] c.a.s.i.b.c.s.h.WinkClientHttpResponse HTTP status code: 200, status text: "OK", headers: [Cache-Control:[no-cache], Content-Length:[198], Content-Type:[application/json], Date:[Thu, 05 Feb 2015 02:28:07 GMT], Server:[Apache-Coyote/1.1], X-AREQUESTID:[@A91CNBx208x1294538x0], X-Content-Type-Options:[nosniff], X-Frame-Options:[SAMEORIGIN], X-XSS-Protection:[1; mode=block]]
2015-02-05 03:28:07,869 DEBUG [threadpool1] c.a.s.i.b.client.RestStashService GET http://<Stash_URL>/git/mvc/maintenance:
------------
{"task":{"id":"a3dfa62d0d54556997e4f5101a89c792c969c17f","progress":{"message":"Backing up Stash data","percentage":85},"state":"RUNNING","type":"BACKUP"},"db-state":"DRAINED","scm-state":"DRAINED"}
------------
2015-02-05 03:28:07,870 INFO  [main] c.a.s.i.b.client.DefaultBackupClient Waiting on Stash database backup to complete
2015-02-05 03:28:09,356 DEBUG [threadpool2] c.a.s.i.b.client.RestStashService Submitting client progress of 100 to http://<Stash_URL>/git/mvc/admin/backups/progress/client?token=9514f3028b1bd7591e63d34dd0da57aa9d85112c&percentage=100
2015-02-05 03:28:09,357 DEBUG [threadpool2] c.a.s.i.b.client.wink.LoggingHandler HTTP POST http://<Stash_URL>/git/mvc/admin/backups/progress/client?token=9514f3028b1bd7591e63d34dd0da57aa9d85112c&percentage=100, headers: [Accept:[application/json], Content-Length:[0], Content-Type:[application/json], User-Agent:[Wink Client v1.1.2], X-Atlassian-Maintenance-Token:[9514f3028b1bd7591e63d34dd0da57aa9d85112c]]
2015-02-05 03:28:09,361 DEBUG [threadpool2] c.a.s.i.b.client.wink.LoggingHandler -> 202 Accepted (@A91CNBx208x1294547x0)
2015-02-05 03:28:09,361 DEBUG [threadpool2] c.a.s.i.b.c.s.h.WinkClientHttpResponse HTTP status code: 202, status text: "Accepted", headers: [Content-Length:[0], Date:[Thu, 05 Feb 2015 02:28:08 GMT], Server:[Apache-Coyote/1.1], X-AREQUESTID:[@A91CNBx208x1294547x0], X-Content-Type-Options:[nosniff], X-Frame-Options:[SAMEORIGIN], X-XSS-Protection:[1; mode=block]]
2015-02-05 03:28:09,362 DEBUG [threadpool2] c.a.s.i.b.client.RestStashService Finished submitting client progress
2015-02-05 03:28:12,865 DEBUG [threadpool1] c.a.s.i.b.client.wink.LoggingHandler HTTP GET http://<Stash_URL>/git/mvc/maintenance, headers: [Accept:[application/json], User-Agent:[Wink Client v1.1.2], X-Atlassian-Maintenance-Token:[9514f3028b1bd7591e63d34dd0da57aa9d85112c]]
2015-02-05 03:28:12,868 DEBUG [threadpool1] c.a.s.i.b.client.wink.LoggingHandler -> 200 OK (@A91CNBx208x1294567x0)
2015-02-05 03:28:12,868 DEBUG [threadpool1] c.a.s.i.b.c.s.h.WinkClientHttpResponse HTTP status code: 200, status text: "OK", headers: [Cache-Control:[no-cache], Content-Length:[198], Content-Type:[application/json], Date:[Thu, 05 Feb 2015 02:28:12 GMT], Server:[Apache-Coyote/1.1], X-AREQUESTID:[@A91CNBx208x1294567x0], X-Content-Type-Options:[nosniff], X-Frame-Options:[SAMEORIGIN], X-XSS-Protection:[1; mode=block]]
2015-02-05 03:28:12,869 DEBUG [threadpool1] c.a.s.i.b.client.RestStashService GET http://<Stash_URL>/git/mvc/maintenance:
------------
{"task":{"id":"a3dfa62d0d54556997e4f5101a89c792c969c17f","progress":{"message":"Backing up Stash data","percentage":85},"state":"RUNNING","type":"BACKUP"},"db-state":"DRAINED","scm-state":"DRAINED"}
------------
2015-02-05 03:28:12,865 DEBUG [threadpool1] c.a.s.i.b.client.wink.LoggingHandler HTTP GET http://<Stash_URL>/git/mvc/maintenance, headers: [Accept:[application/json], User-Agent:[Wink Client v1.1.2], X-Atlassian-Maintenance-Token:[9514f3028b1bd7591e63d34dd0da57aa9d85112c]]
2015-02-05 03:28:12,868 DEBUG [threadpool1] c.a.s.i.b.client.wink.LoggingHandler -> 200 OK (@A91CNBx208x1294567x0)
2015-02-05 03:28:12,868 DEBUG [threadpool1] c.a.s.i.b.c.s.h.WinkClientHttpResponse HTTP status code: 200, status text: "OK", headers: [Cache-Control:[no-cache], Content-Length:[198], Content-Type:[application/json], Date:[Thu, 05 Feb 2015 02:28:12 GMT], Server:[Apache-Coyote/1.1], X-AREQUESTID:[@A91CNBx208x1294567x0], X-Content-Type-Options:[nosniff], X-Frame-Options:[SAMEORIGIN], X-XSS-Protection:[1; mode=block]]
2015-02-05 03:28:12,869 DEBUG [threadpool1] c.a.s.i.b.client.RestStashService GET http://<Stash_URL>/git/mvc/maintenance:
------------
{"task":{"id":"a3dfa62d0d54556997e4f5101a89c792c969c17f","progress":{"message":"Backing up Stash data","percentage":85},"state":"RUNNING","type":"BACKUP"},"db-state":"DRAINED","scm-state":"DRAINED"}
------------
 
2015-02-05 03:28:12,870 INFO  [main] c.a.s.i.b.client.DefaultBackupClient Waiting on Stash database backup to complete
2015-02-05 03:28:13,000 DEBUG [main] c.a.s.i.b.c.FixedRateProgressPublisher Progress publishing has stopped
2015-02-05 03:28:13,063 DEBUG [main] c.a.s.i.b.client.RestStashService Unhandled client exception encountered while Stash was performing a database backup
com.atlassian.stash.internal.backup.client.BackupTimedOutException: The backup on the server has become unresponsive and has not progressed in 300 seconds
	at com.atlassian.stash.internal.backup.client.CachedMaintenanceReporter.waitForStatus(CachedMaintenanceReporter.groovy:94) ~[stash-backup-client.jar:1.6.0]
	at com.atlassian.stash.internal.backup.client.DefaultBackupClient.waitForBackupTaskCompletion(DefaultBackupClient.groovy:215) [stash-backup-client.jar:1.6.0]
	at com.atlassian.stash.internal.backup.client.DefaultBackupClient.downloadDbZipOnBackupCompletion(DefaultBackupClient.groovy:97) [stash-backup-client.jar:1.6.0]
	at com.atlassian.stash.internal.backup.client.DefaultBackupClient.archiveHome(DefaultBackupClient.groovy:68) [stash-backup-client.jar:1.6.0]
	at com.atlassian.stash.internal.backup.client.FixedRateProgressPublisher.publishWhileExecuting(FixedRateProgressPublisher.groovy:34) ~[stash-backup-client.jar:1.6.0]
	at com.atlassian.stash.internal.backup.client.RestStashService.backup(RestStashService.groovy:62) [stash-backup-client.jar:1.6.0]
	at com.atlassian.stash.internal.backup.client.RestStashService.lock(RestStashService.groovy:170) [stash-backup-client.jar:1.6.0]
	at com.atlassian.stash.internal.backup.client.DefaultBackupClient.backup(DefaultBackupClient.groovy:47) [stash-backup-client.jar:1.6.0]
	at com.atlassian.stash.internal.backup.client.spring.SpringMain.run(SpringMain.groovy:28) [stash-backup-core-1.6.0.jar:na]
	at com.atlassian.stash.internal.backup.client.spring.SpringMain.run(SpringMain.groovy) [stash-backup-core-1.6.0.jar:na]
	at com.atlassian.stash.internal.backup.client.BackupMain.main(BackupMain.groovy:38) [stash-backup-client.jar:1.6.0]
	at com.atlassian.stash.internal.backup.client.JavaVersionCheckingShim.invokeClientClassMain(JavaVersionCheckingShim.java:71) [stash-backup-client.jar:1.6.0]
	at com.atlassian.stash.internal.backup.client.JavaVersionCheckingShim.run(JavaVersionCheckingShim.java:85) [stash-backup-client.jar:1.6.0]
	... 161 frames suppressed

The following appears in the atlassian-stash.log:

2015-02-05 03:28:13,155 INFO  [threadpool:thread-25748] dsp_dte @A91CNBx120x1266580x1 172.16.141.208 "POST /mvc/admin/backups HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseMigrationDao Backup process completed
2015-02-05 03:28:13,222 WARN  [threadpool:thread-25748] dsp_dte @A91CNBx120x1266580x1 172.16.141.208 "POST /mvc/admin/backups HTTP/1.1" c.a.s.i.m.DefaultMaintenanceTaskMonitor BACKUP maintenance has been canceled (Cause: CanceledBackupException: The backup has been canceled.)
com.atlassian.stash.internal.backup.CanceledBackupException: The backup has been canceled.
	at com.atlassian.stash.internal.maintenance.backup.AbstractBackupTask.run(AbstractBackupTask.java:88) ~[AbstractBackupTask.class:na]
	at com.atlassian.stash.internal.maintenance.DefaultMaintenanceTaskMonitor.run(DefaultMaintenanceTaskMonitor.java:183) ~[DefaultMaintenanceTaskMonitor.class:na]
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [na:1.7.0_60]
	at java.util.concurrent.FutureTask.run(Unknown Source) [na:1.7.0_60]
	at com.atlassian.stash.internal.concurrent.StateTransferringExecutor$StateTransferringRunnable.run(StateTransferringExecutor.java:69) [StateTransferringExecutor$StateTransferringRunnable.class:na]
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [na:1.7.0_60]
	at java.util.concurrent.FutureTask.run(Unknown Source) [na:1.7.0_60]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source) [na:1.7.0_60]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [na:1.7.0_60]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [na:1.7.0_60]
	at java.lang.Thread.run(Unknown Source) [na:1.7.0_60]
	... 1 frame trimmed

Cause

The logs on this example show that the server was busy creating the database backup. However, the backup client tracks the progress of the database backup on the server and will abort the backup process if the database backup appears to be 'stuck'. In this case, it is stuck in 85% for 5 minutes.

 Eventually, the backup client orders the server to cancel the database backup and the server logs `Backup process completed` immediately `Backup process canceled`.

Resolution

You can configure a longer timeout in the backup client's backup-config.properties using the following settings:

# Controls how long to wait when there is no backup progress from the server before giving up and failing the backup.
# Value is in SECONDS.
backup.server.timeout=300

The above is the default value.

Last modified on Mar 30, 2016

Was this helpful?

Yes
No
Provide feedback about this article
Powered by Confluence and Scroll Viewport.