Details
-
Bug
-
Resolution: Duplicate
-
Low
-
None
-
None
-
None
Description
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.
Attachments
Issue Links
- relates to
-
-
- Closed
-