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

Related content

  • No related content found

Still need help?

The Atlassian Community is here for you.

Ask the community

Symptoms

The Bitbucket Server 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 Bitbucket Server data","percentage":85},"state":"RUNNING","type":"BACKUP"},"db-state":"DRAINED","scm-state":"DRAINED"}

More details:

...
...
...
...
...
------------
{"task":{"id":"a3dfa62d0d54556997e4f5101a89c792c969c17f","progress":{"message":"Backing up Bitbucket Server 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 Bitbucket Server database backup to complete
2015-02-05 03:28:04,356 DEBUG [threadpool2] c.a.s.i.b.client.RestBitbucket ServerService Submitting client progress of 1x00 to http://<Bitbucket Server_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://<Bitbucket Server_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.RestBitbucket ServerService Finished submitting client progress
2015-02-05 03:28:07,865 DEBUG [threadpool1] c.a.s.i.b.client.wink.LoggingHandler HTTP GET http://<Bitbucket Server_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.RestBitbucket ServerService GET http://<Bitbucket Server_URL>/git/mvc/maintenance:
------------
{"task":{"id":"a3dfa62d0d54556997e4f5101a89c792c969c17f","progress":{"message":"Backing up Bitbucket Server 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 Bitbucket Server database backup to complete
2015-02-05 03:28:09,356 DEBUG [threadpool2] c.a.s.i.b.client.RestBitbucket ServerService Submitting client progress of 100 to http://<Bitbucket Server_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://<Bitbucket Server_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.RestBitbucket ServerService Finished submitting client progress
2015-02-05 03:28:12,865 DEBUG [threadpool1] c.a.s.i.b.client.wink.LoggingHandler HTTP GET http://<Bitbucket Server_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.RestBitbucket ServerService GET http://<Bitbucket Server_URL>/git/mvc/maintenance:
------------
{"task":{"id":"a3dfa62d0d54556997e4f5101a89c792c969c17f","progress":{"message":"Backing up Bitbucket Server 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://<Bitbucket Server_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.RestBitbucket ServerService GET http://<Bitbucket Server_URL>/git/mvc/maintenance:
------------
{"task":{"id":"a3dfa62d0d54556997e4f5101a89c792c969c17f","progress":{"message":"Backing up Bitbucket Server 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 Bitbucket Server 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.RestBitbucket ServerService Unhandled client exception encountered while Bitbucket Server was performing a database backup
com.atlassian.bitbucket.internal.backup.client.BackupTimedOutException: The backup on the server has become unresponsive and has not progressed in 300 seconds
	at com.atlassian.bitbucket.internal.backup.client.CachedMaintenanceReporter.waitForStatus(CachedMaintenanceReporter.groovy:94) ~[bitbucket-backup-client.jar:1.6.0]
	at com.atlassian.bitbucket.internal.backup.client.DefaultBackupClient.waitForBackupTaskCompletion(DefaultBackupClient.groovy:215) [bitbucket-backup-client.jar:1.6.0]
	at com.atlassian.bitbucket.internal.backup.client.DefaultBackupClient.downloadDbZipOnBackupCompletion(DefaultBackupClient.groovy:97) [bitbucket-backup-client.jar:1.6.0]
	at com.atlassian.bitbucket.internal.backup.client.DefaultBackupClient.archiveHome(DefaultBackupClient.groovy:68) [bitbucket-backup-client.jar:1.6.0]
	at com.atlassian.bitbucket.internal.backup.client.FixedRateProgressPublisher.publishWhileExecuting(FixedRateProgressPublisher.groovy:34) ~[bitbucket-backup-client.jar:1.6.0]
	at com.atlassian.bitbucket.internal.backup.client.RestBitbucket ServerService.backup(RestBitbucket ServerService.groovy:62) [bitbucket-backup-client.jar:1.6.0]
	at com.atlassian.bitbucket.internal.backup.client.RestBitbucket ServerService.lock(RestBitbucket ServerService.groovy:170) [bitbucket-backup-client.jar:1.6.0]
	at com.atlassian.bitbucket.internal.backup.client.DefaultBackupClient.backup(DefaultBackupClient.groovy:47) [bitbucket-backup-client.jar:1.6.0]
	at com.atlassian.bitbucket.internal.backup.client.spring.SpringMain.run(SpringMain.groovy:28) [bitbucket-backup-core-1.6.0.jar:na]
	at com.atlassian.bitbucket.internal.backup.client.spring.SpringMain.run(SpringMain.groovy) [bitbucket-backup-core-1.6.0.jar:na]
	at com.atlassian.bitbucket.internal.backup.client.BackupMain.main(BackupMain.groovy:38) [bitbucket-backup-client.jar:1.6.0]
	at com.atlassian.bitbucket.internal.backup.client.JavaVersionCheckingShim.invokeClientClassMain(JavaVersionCheckingShim.java:71) [bitbucket-backup-client.jar:1.6.0]
	at com.atlassian.bitbucket.internal.backup.client.JavaVersionCheckingShim.run(JavaVersionCheckingShim.java:85) [bitbucket-backup-client.jar:1.6.0]
	... 161 frames suppressed

The following appears in the atlassian-bitbucket.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.bitbucket.internal.backup.CanceledBackupException: The backup has been canceled.
	at com.atlassian.bitbucket.internal.maintenance.backup.AbstractBackupTask.run(AbstractBackupTask.java:88) ~[AbstractBackupTask.class:na]
	at com.atlassian.bitbucket.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.bitbucket.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

Related content

  • No related content found
Powered by Confluence and Scroll Viewport.