Yandex Cloud S3 - "acquire semaphore during Download table data: context canceled" error during download

[SebastianPereiro]

Hi guys
We are using 1.4.7 version (also tried 1.5.2) and downloading remote backup from S3 compatible storage (Yandex Cloud Object Storage).
Last lines before failure:

2022/08/13 10:31:11.600603 debug start download from remote_backup_2022-08-12T08-37-45/shadow/default/position_in_category/default_20220618_0_27_2.tar
2022/08/13 10:31:11.688835 debug finish download from remote_backup_2022-08-12T08-37-45/shadow/default/position_in_category/default_20220609_0_27_2_29.tar
2022/08/13 10:31:11.688891 debug start download from remote_backup_2022-08-12T08-37-45/shadow/default/position_in_category/default_20220619_0_27_2.tar
2022/08/13 10:31:16.352004 debug finish download from remote_backup_2022-08-12T08-37-45/shadow/default/keyword_requests_info/default_20220722_0_16_2_25.tar
2022/08/13 10:31:16.947857 debug finish download from remote_backup_2022-08-12T08-37-45/shadow/default/keyword_requests_info/default_20220722_17_24_1_25.tar
2022/08/13 10:31:16.947891 debug start                     operation=downloadDiffParts table=default.keyword_requests_info
2022/08/13 10:31:16.948076  info done                      diff_parts=0 duration=0s operation=downloadDiffParts
2022/08/13 10:31:16.948105  info done                      backup=remote_backup_2022-08-12T08-37-45 duration=6m36.567s operation=download_data size=9.88GiB table=default.keyword_requests_info
2022/08/13 10:31:17.204457 debug finish download from remote_backup_2022-08-12T08-37-45/shadow/default/position_in_category/default_20220612_0_23_2_25.tar
2022/08/13 10:31:17.204532 debug start download from remote_backup_2022-08-12T08-37-45/shadow/default/position_in_category/default_20220620_0_27_2.tar
2022/08/13 10:31:17.210954 debug finish download from remote_backup_2022-08-12T08-37-45/shadow/default/position_in_category/default_20220613_0_27_2_29.tar
2022/08/13 10:31:17.210995 debug start download from remote_backup_2022-08-12T08-37-45/shadow/default/position_in_category/default_20220621_0_27_2.tar
2022/08/13 10:31:24.095454 debug finish download from remote_backup_2022-08-12T08-37-45/shadow/default/position_in_category/default_20220620_0_27_2.tar
2022/08/13 10:31:24.095513 debug start download from remote_backup_2022-08-12T08-37-45/shadow/default/position_in_category/default_20220622_0_27_2.tar
2022/08/13 10:31:24.272009 error can't acquire semaphore during downloadTableData: context canceled
2022/08/13 10:31:24.272031 debug start download from remote_backup_2022-08-12T08-37-45/shadow/default/position_in_category/default_20220623_0_27_2.tar
2022/08/13 10:31:37.739236 error one of Download go-routine return error: one of downloadTableData go-routine return error: handling file: /20220714_0_42464_395/views.bin: http2: server sent GOAWAY and closed the connection; LastStreamID=1657, ErrCode=NO_ERROR, debug=""

Config:

general:
  remote_storage: s3
  max_file_size: 0
  disable_progress_bar: true
  backups_to_keep_local: 4
  backups_to_keep_remote: 2
  log_level: warning
  allow_empty_backups: false
  download_concurrency: 10
  upload_concurrency: 30
  restore_schema_on_cluster: ""
  upload_by_part: true
  download_by_part: true
clickhouse:
  username: 
  password: 
  host: localhost
  port: 9000
  disk_mapping: {}
  skip_tables:
  - system.*
  - INFORMATION_SCHEMA.*
  - information_schema.*
  timeout: 5m
  freeze_by_part: false
  freeze_by_part_where: ""
  secure: false
  skip_verify: false
  sync_replicated_tables: false
  log_sql_queries: true
  config_dir: /etc/clickhouse-server/
  restart_command: systemctl restart clickhouse-server
  ignore_not_exists_error_during_freeze: true
  tls_key: ""
  tls_cert: ""
  tls_ca: ""
  debug: false
s3:
  access_key: 
  secret_key: 
  bucket: 
  endpoint: storage.yandexcloud.net
  region: us-east-1
  acl: private
  assume_role_arn: ""
  force_path_style: false
  path: ""
  disable_ssl: false
  compression_level: 1
  compression_format: tar
  sse: ""
  disable_cert_verification: false
  storage_class: STANDARD_IA
  concurrency: 1
  part_size: 0
  max_parts_count: 5000
  allow_multipart_download: false
  debug: false

Can we do something with that: "server sent GOAWAY and closed the connection"? Maybe tune some clickhouse-backup parameters?

[SebastianPereiro]

Additional info about Yandex Object Storage limits

[Slach]

yes, you can restrict your upload and download concurrency

general:
  download_concurrency: 4
  upload_concurrency: 4

to avoid storm of HTTP S3 requests

[SebastianPereiro]

@Slach please reopen
I've tested ver 1.5.2 with
general:
download_concurrency: 1
upload_concurrency: 1
And got the same error:
2022/08/21 15:26:45.254616 error can't acquire semaphore during downloadTableData: context canceled
2022/08/21 15:26:45.539502 error can't acquire semaphore during Download table data: context canceled backup=remote_backup_2022-08-20T14-22-04 operation=download
2022/08/21 15:27:10.610328 error one of Download go-routine return error: one of downloadTableData go-routine return error: handling file: /20220722_281595_326713_175/views.bin: http2: server sent GOAWAY and closed the connection; LastStreamID=3999, ErrCode=NO_ERROR, debug=""

[SebastianPereiro]

As a workaround I found that I can download remote backup using rclone and restore after using clickhouse-backup. But sure it's not so convenient.

[SebastianPereiro]

Thank you for reopening. Please let me know if I can give more additional information.

[SebastianPereiro]

The Yandex Cloud support service reported that they don't see any problems on their side

[Slach]

could you share full debug log

S3_DEBUG=true clickhouse-backup download remote_backup_2022-08-12T08-37-45

[SebastianPereiro]

S3_DEBUG=true Doesn't produce any additional logs with version 1.5.2. Maybe I should set logging level to debug too?

[SebastianPereiro]

s3debug001.log

[Slach]

-----------------------------------------------------
2022/08/21 18:06:41.716918  info DEBUG: Request s3/GetObject Details:
---[ REQUEST POST-SIGN ]-----------------------------
GET /remote_backup_2022-08-20T14-22-04/shadow/default/adv_full_keyword_stat/default_20220723_0_323058_236.tar HTTP/1.1
Host: clickhouse-1-1-backup.storage.yandexcloud.net
User-Agent: aws-sdk-go/1.43.0 (go1.19; linux; amd64)
Authorization: AWS4-HMAC-SHA256 Credential=removed/20220821/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=008b46310f446ccbc5a4729d0e7732b823370463364c22f15e6a149644046741
X-Amz-Content-Sha256: removed
X-Amz-Date: 20220821T160641Z
Accept-Encoding: gzip


-----------------------------------------------------
2022/08/21 18:06:41.886213  info DEBUG: Response s3/GetObject Details:
---[ RESPONSE ]--------------------------------------
HTTP/2.0 200 OK
Content-Length: 3676548608
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Sun, 21 Aug 2022 16:06:41 GMT
Etag: "633383347f884a0e9be19fb3920553bb-702"
Last-Modified: Sat, 20 Aug 2022 15:41:57 GMT
Server: nginx
X-Amz-Request-Id: baa1ed77799c6d93
X-Amz-Storage-Class: COLD
X-Amz-Version-Id: null

2022/08/21 18:08:44.410944 error one of Download go-routine return error: one of downloadTableData go-routine return error: handling file: /20220723_0_323058_236/views.null.bin: http2: server sent GOAWAY and closed the connection; LastStreamID=4007, ErrCode=NO_ERROR, debug=""

means sucessfull download started, but break from yandex server during streaming decompression
i don't see we break any yandex cloud limits

could you try share

DOWNLOAD_CONCURRENCY=1 S3_DEBUG=true LOG_LEVEL=debug clickhouse-backup download remote_backup_2022-08-12T08-37-45

[Slach]

moreover, little bit weird, why http2: in error message if aws sdk sent HTTP/1.1 in GetObject request ;(

[SebastianPereiro]

done:
s3debug002.log

[Slach]

are you sure you apply environment variable properly?

could you share

DOWNLOAD_CONCURRENCY=1 S3_DEBUG=true LOG_LEVEL=debug clickhouse-backup print-config