Uploaded image for project: 'Bitbucket Data Center'
  1. Bitbucket Data Center
  2. BSERV-7351

Backup client times out during backup, stash server continues

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Duplicate
    • Icon: Low Low
    • 3.9.1
    • None
    • None
    • None

      During work on STASH-7137 I came up with an artificial test for the backup client, which resulted in the client timing out while the server kept doing the backup.

      So, the configuration was a stash server with PostgreSQL DB, sta_shared_lob filled with data:

      do $$ declare str varchar(32000) := repeat('abcdefghijklmnopqrstuvwxyz012345', 1000); begin for i in 3..10000000 loop insert into sta_shared_lob values (i, str);  end loop; end; $$;

      The data is 10 million rows filled with the same string of 1000 repeated alphabet.

      logs from the client: 

      2015-04-30 10:19:06,237 INFO        Initializing
2015-04-30 10:19:07,752 INFO        Using Stash 3.10.0
2015-04-30 10:19:07,848 INFO        Contacting Stash
2015-04-30 10:19:07,972 INFO        Stash has been locked for maintenance. It may be unlocked with token: f28149fd4d950ced371940b503cdf1ce473b131a
2015-04-30 10:19:08,118 INFO        Starting database backup on Stash. It may be cancelled with token: 5b6abeb5910ef576d8a5e4350bfc7c38065631e3
2015-04-30 10:19:12,988 INFO  (11%) Verifying files in Stash home "/Users/rsabitov/src/stash/func-test/browser/target/stash/home"
2015-04-30 10:19:13,175 INFO  (11%) Verifying Stash home
2015-04-30 10:19:13,585 INFO  (11%) Backing up Stash home
2015-04-30 10:19:13,777 INFO  (11%) Waiting on Stash database backup to complete
2015-04-30 10:19:22,385 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:19:27,385 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:19:37,386 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:19:47,384 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:19:52,447 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:20:02,384 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:20:12,383 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:20:17,385 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:20:22,386 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:20:32,384 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:20:37,384 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:20:47,385 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:20:57,384 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:21:02,384 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:21:12,384 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:21:22,384 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:21:32,383 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:21:42,382 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:21:47,383 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:21:57,382 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:22:02,382 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:22:07,382 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:22:12,382 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:22:22,380 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:22:27,382 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:22:32,382 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:22:37,383 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:22:47,380 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:22:52,381 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:23:02,380 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:23:07,382 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:23:17,381 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:23:22,381 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:23:32,385 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:23:42,390 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:23:52,393 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:24:02,397 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:24:12,402 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:24:22,403 INFO  (61%) Waiting on Stash database backup to complete
2015-04-30 10:24:22,417 INFO  (61%) Cancelling database backup with code: 5b6abeb5910ef576d8a5e4350bfc7c38065631e3
2015-04-30 10:24:28,141 WARN  (61%) Error reporting progress to Stash
org.apache.wink.client.ClientRuntimeException: java.lang.RuntimeException: java.net.SocketTimeoutException: Read timed out
at org.apache.wink.client.internal.ResourceImpl.invoke(ResourceImpl.java:241) ~[wink-client-1.4.jar:1.4]
at org.apache.wink.client.internal.ResourceImpl.invoke(ResourceImpl.java:189) ~[wink-client-1.4.jar:1.4]
... 15 more frames available in the log file
2015-04-30 10:25:22,433 ERROR  (61%) Failed to cancel database backup: java.lang.RuntimeException: java.net.SocketTimeoutException: Read timed out
org.apache.wink.client.ClientRuntimeException: java.lang.RuntimeException: java.net.SocketTimeoutException: Read timed out
at org.apache.wink.client.internal.ResourceImpl.invoke(ResourceImpl.java:241) ~[wink-client-1.4.jar:1.4]
at org.apache.wink.client.internal.ResourceImpl.invoke(ResourceImpl.java:189) ~[wink-client-1.4.jar:1.4]
... 18 more frames available in the log file
2015-04-30 10:25:22,434 INFO  (61%) Unlocking Stash using token: f28149fd4d950ced371940b503cdf1ce473b131a
2015-04-30 10:26:22,441 ERROR  (61%) Failed to unlock Stash: java.lang.RuntimeException: java.net.SocketTimeoutException: Read timed out
org.apache.wink.client.ClientRuntimeException: java.lang.RuntimeException: java.net.SocketTimeoutException: Read timed out
at org.apache.wink.client.internal.ResourceImpl.invoke(ResourceImpl.java:241) ~[wink-client-1.4.jar:1.4]
at org.apache.wink.client.internal.ResourceImpl.invoke(ResourceImpl.java:189) ~[wink-client-1.4.jar:1.4]
... 15 more frames available in the log file
2015-04-30 10:26:22,448 ERROR  (61%) A backup could not be created. Reason: java.lang.RuntimeException: java.net.SocketTimeoutException: Read timed out

org.apache.wink.client.ClientRuntimeException: java.lang.RuntimeException: java.net.SocketTimeoutException: Read timed out
at org.apache.wink.client.internal.ResourceImpl.invoke(ResourceImpl.java:241) ~[wink-client-1.4.jar:1.4]
at org.apache.wink.client.internal.ResourceImpl.invoke(ResourceImpl.java:189) ~[wink-client-1.4.jar:1.4]
... 15 more frames available in the log file

Process finished with exit code 1

      Logs from the Stash server (I cut some lines in the middle):

      2015-04-30 10:19:12,680 INFO  [threadpool:thread-1] admin @ISRK65x619x446x0 127.0.0.1 "POST /mvc/admin/backups HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseMigrationDao Backing up sta_shared_lob table
2015-04-30 10:19:12,764 INFO  [threadpool:thread-1] admin @ISRK65x619x446x0 127.0.0.1 "POST /mvc/admin/backups HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseDao 0 rows processed
2015-04-30 10:19:31,075 INFO  [threadpool:thread-1] admin @ISRK65x619x446x0 127.0.0.1 "POST /mvc/admin/backups HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseDao 1000 rows processed
...
2015-04-30 13:42:42,077 INFO  [threadpool:thread-1] admin @ISRK65x619x446x0 127.0.0.1 "POST /mvc/admin/backups HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseDao 537000 rows processed
2015-04-30 13:43:07,461 INFO  [threadpool:thread-1] admin @ISRK65x619x446x0 127.0.0.1 "POST /mvc/admin/backups HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseDao 538000 rows processed
2015-04-30 13:43:33,376 INFO  [threadpool:thread-1] admin @ISRK65x619x446x0 127.0.0.1 "POST /mvc/admin/backups HTTP/1.1" c.a.s.i.b.l.DefaultLiquibaseDao 539000 rows processed

      Note Stash server kept processing until I killed it.

      My guess is that the test data is highly compressable and stash server doesn't flush buffer.

              Unassigned Unassigned
              rsabitov Renat Sabitov
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Created:
                Updated:
                Resolved: