RPC errors in backup log

Summary

Recently, error messages like the following have started appearing in the daily backup log of my GitLab CE Omnibus instance running on Ubuntu 22.04.3. They seem harmless (the backup completes successfully after them), however they are annoying because the presence of the word “error” in the log of a successful backup makes it impossible to quickly check for problems by searching for “error”.

{"level":"info","msg":"[transport] [client-transport 0xc000988fc0] Closing: rpc error: code = Canceled desc = grpc: the client connection is closing","pid":198948,"system":"system","time":"2023-11-02T00:01:02.117Z"}
{"level":"info","msg":"[transport] [client-transport 0xc000988fc0] loopyWriter exiting with error: transport closed by client","pid":198948,"system":"system","time":"2023-11-02T00:01:02.117Z"}

(see full log below)

Specifically, with the update from 16.3.1 to 16.3.3, the “loopyWriter exiting with error” has started appearing ocasionally. With the update from 16.4.1 to 16.5.1, the “Closing: rpc error” has appeared and they both now occur almost every time.

I would appreciate if

• someone could confirm whether the errors are actually harmless as I suspect,
• if yes, they could be suppressed from the log output to avoid false alarms,
• if not, they could be fixed.

Steps to reproduce

1. /opt/gitlab/bin/gitlab-rake gitlab:backup:create

What is the current bug behavior?

The word “error” appears in the log of an (apparently) successful backup.

What is the expected correct behavior?

The word “error” only appears if something actually went wrong (unless I have a project name that contains the word or something stupid like that).

Relevant logs and/or screenshots

Output of /opt/gitlab/bin/gitlab-rake gitlab:backup:create:

2023-11-10 00:00:17 UTC -- Dumping database ... 
Dumping PostgreSQL database gitlabhq_production ... [DONE]
2023-11-10 00:00:20 UTC -- Dumping database ... done
2023-11-10 00:00:20 UTC -- Dumping repositories ... 
{"command":"create","gl_project_path":"walther/inixv-memdump","level":"info","msg":"started create","pid":2006789,"relative_path":"@hashed/4e/07/4e07408562bedb8b60ce05c1decfe3ad16b72230967de01f640b7e4729b49fce.git","storage_name":"default","time":"2023-11-10T00:00:20.773Z"}
{"level":"info","msg":"[core] [Channel #1] Channel created","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.775Z"}
{"level":"info","msg":"[core] [Channel #1] original dial target is: \"unix:/var/opt/gitlab/gitaly/gitaly.socket\"","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.778Z"}
{"level":"info","msg":"[core] [Channel #1] parsed dial target is: {URL:{Scheme:unix Opaque: User: Host: Path:/var/opt/gitlab/gitaly/gitaly.socket RawPath: OmitHost:true ForceQuery:false RawQuery: Fragment: RawFragment:}}","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.778Z"}
{"level":"info","msg":"[core] [Channel #1] Channel authority set to \"localhost\"","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.778Z"}
{"level":"info","msg":"[core] [Channel #1] Resolver state updated: {\n  \"Addresses\": [\n    {\n      \"Addr\": \"/var/opt/gitlab/gitaly/gitaly.socket\",\n      \"ServerName\": \"\",\n      \"Attributes\": {\n        \"\\u003c%!p(networktype.keyType=grpc.internal.transport.networktype)\\u003e\": \"unix\"\n      },\n      \"BalancerAttributes\": null,\n      \"Metadata\": null\n    }\n  ],\n  \"Endpoints\": [\n    {\n      \"Addresses\": [\n {\n          \"Addr\": \"/var/opt/gitlab/gitaly/gitaly.socket\",\n          \"ServerName\": \"\",\n          \"Attributes\": {\n            \"\\u003c%!p(networktype.keyType=grpc.internal.transport.networktype)\\u003e\": \"unix\"\n },\n          \"BalancerAttributes\": null,\n          \"Metadata\": null\n        }\n      ],\n      \"Attributes\": null\n    }\n  ],\n  \"ServiceConfig\": null,\n  \"Attributes\": null\n} (resolver returned new addresses)","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.779Z"}
{"level":"info","msg":"[core] [Channel #1] ignoring service config from resolver (\u003cnil\u003e) and applying the default because service config is disabled","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.779Z"}
{"level":"info","msg":"[core] [Channel #1] Channel switches to new LB policy \"round_robin\"","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.779Z"}
{"level":"info","msg":"[balancer] base.baseBalancer: got new ClientConn state:  {{[{Addr: \"/var/opt/gitlab/gitaly/gitaly.socket\", ServerName: \"\", Attributes: {\"\u003c%!p(networktype.keyType=grpc.internal.transport.networktype)\u003e\": \"unix\" }, }] [{[{Addr: \"/var/opt/gitlab/gitaly/gitaly.socket\", ServerName: \"\", Attributes: {\"\u003c%!p(networktype.keyType=grpc.internal.transport.networktype)\u003e\": \"unix\" }, }] \u003cnil\u003e}] \u003cnil\u003e \u003cnil\u003e} \u003cnil\u003e}","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.779Z"}
{"level":"info","msg":"[core] [Channel #1 SubChannel #2] Subchannel created","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.779Z"}
{"level":"info","msg":"[roundrobin] roundrobinPicker: Build called with info: {map[]}","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.779Z"}
{"level":"info","msg":"[core] [Channel #1] Channel Connectivity change to CONNECTING","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.779Z"}
{"level":"info","msg":"[core] [Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.779Z"}
{"level":"info","msg":"[core] [Channel #1 SubChannel #2] Subchannel picks a new address \"/var/opt/gitlab/gitaly/gitaly.socket\" to connect","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.779Z"}
{"level":"info","msg":"[balancer] base.baseBalancer: handle SubConn state change: 0xc0006bb590, CONNECTING","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.780Z"}
{"level":"info","msg":"[core] [Channel #1 SubChannel #2] Subchannel Connectivity change to READY","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.782Z"}
{"level":"info","msg":"[balancer] base.baseBalancer: handle SubConn state change: 0xc0006bb590, READY","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.782Z"}
{"level":"info","msg":"[roundrobin] roundrobinPicker: Build called with info: {map[SubConn(id:2):{{Addr: \"/var/opt/gitlab/gitaly/gitaly.socket\", ServerName: \"\", Attributes: {\"\u003c%!p(networktype.keyType=grpc.internal.transport.networktype)\u003e\": \"unix\" }, }}]}","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.782Z"}
{"level":"info","msg":"[core] [Channel #1] Channel Connectivity change to READY","pid":2006789,"system":"system","time":"2023-11-10T00:00:20.782Z"}
{"command":"create","gl_project_path":"walther/inixv-memdump","level":"info","msg":"completed create","pid":2006789,"relative_path":"@hashed/4e/07/4e07408562bedb8b60ce05c1decfe3ad16b72230967de01f640b7e4729b49fce.git","storage_name":"default","time":"2023-11-10T00:00:20.802Z"}

... (lots more repositories skipped) ...

{"command":"create","gl_project_path":"ziblot/ferksilv","level":"info","msg":"completed create","pid":2006789,"relative_path":"@hashed/36/35/3635a91e3da857f7847f68185a116a5260d2593f3913f6b1b66cc2d75b0d6ec0.git","storage_name":"default","time":"2023-11-10T00:01:02.500Z"}
{"level":"info","msg":"[core] [Channel #1] Channel Connectivity change to SHUTDOWN","pid":2006789,"system":"system","time":"2023-11-10T00:01:02.514Z"}
{"level":"info","msg":"[core] [Channel #1] ccBalancerWrapper: closing","pid":2006789,"system":"system","time":"2023-11-10T00:01:02.624Z"}
{"level":"info","msg":"[core] [Channel #1] Closing the name resolver","pid":2006789,"system":"system","time":"2023-11-10T00:01:02.638Z"}
{"level":"info","msg":"[core] [Channel #1 SubChannel #2] Subchannel Connectivity change to SHUTDOWN","pid":2006789,"system":"system","time":"2023-11-10T00:01:02.639Z"}
{"level":"info","msg":"[core] [Channel #1 SubChannel #2] Subchannel deleted","pid":2006789,"system":"system","time":"2023-11-10T00:01:02.646Z"}
{"level":"info","msg":"[transport] [client-transport 0xc0008e4000] Closing: rpc error: code = Canceled desc = grpc: the client connection is closing","pid":2006789,"system":"system","time":"2023-11-10T00:01:02.646Z"}
{"level":"info","msg":"[transport] [client-transport 0xc0008e4000] loopyWriter exiting with error: transport closed by client","pid":2006789,"system":"system","time":"2023-11-10T00:01:02.663Z"}
{"level":"info","msg":"[core] [Channel #1] Channel deleted","pid":2006789,"system":"system","time":"2023-11-10T00:01:02.663Z"}
2023-11-10 00:01:02 UTC -- Dumping repositories ... done
2023-11-10 00:01:02 UTC -- Dumping uploads ... 
2023-11-10 00:01:04 UTC -- Dumping uploads ... done
2023-11-10 00:01:04 UTC -- Dumping builds ... 
2023-11-10 00:01:04 UTC -- Dumping builds ... done
2023-11-10 00:01:04 UTC -- Dumping artifacts ... 
2023-11-10 00:01:04 UTC -- Dumping artifacts ... done
2023-11-10 00:01:04 UTC -- Dumping pages ... 
2023-11-10 00:01:04 UTC -- Dumping pages ... done
2023-11-10 00:01:04 UTC -- Dumping lfs objects ... 
2023-11-10 00:01:05 UTC -- Dumping lfs objects ... done
2023-11-10 00:01:05 UTC -- Dumping terraform states ... 
2023-11-10 00:01:05 UTC -- Dumping terraform states ... done
2023-11-10 00:01:05 UTC -- Dumping container registry images ... [DISABLED]
2023-11-10 00:01:05 UTC -- Dumping packages ... 
2023-11-10 00:01:37 UTC -- Dumping packages ... done
2023-11-10 00:01:37 UTC -- Dumping ci secure files ... 
2023-11-10 00:01:37 UTC -- Dumping ci secure files ... done
2023-11-10 00:01:38 UTC -- Creating backup archive: 1699574417_2023_11_10_16.5.1_gitlab_backup.tar ... 
2023-11-10 00:02:02 UTC -- Creating backup archive: 1699574417_2023_11_10_16.5.1_gitlab_backup.tar ... done
2023-11-10 00:02:02 UTC -- Uploading backup archive to remote storage  ... [SKIPPED]
2023-11-10 00:02:02 UTC -- Deleting old backups ... 
2023-11-10 00:02:02 UTC -- Deleting old backups ... done. (1 removed)
2023-11-10 00:02:02 UTC -- Deleting tar staging files ... 
2023-11-10 00:02:02 UTC -- Cleaning up /indel/backup/gitlab/backup_information.yml
2023-11-10 00:02:02 UTC -- Cleaning up /indel/backup/gitlab/db
2023-11-10 00:02:02 UTC -- Cleaning up /indel/backup/gitlab/repositories
2023-11-10 00:02:02 UTC -- Cleaning up /indel/backup/gitlab/uploads.tar.gz
2023-11-10 00:02:02 UTC -- Cleaning up /indel/backup/gitlab/builds.tar.gz
2023-11-10 00:02:02 UTC -- Cleaning up /indel/backup/gitlab/artifacts.tar.gz
2023-11-10 00:02:02 UTC -- Cleaning up /indel/backup/gitlab/pages.tar.gz
2023-11-10 00:02:02 UTC -- Cleaning up /indel/backup/gitlab/lfs.tar.gz
2023-11-10 00:02:02 UTC -- Cleaning up /indel/backup/gitlab/terraform_state.tar.gz
2023-11-10 00:02:02 UTC -- Cleaning up /indel/backup/gitlab/packages.tar.gz
2023-11-10 00:02:02 UTC -- Cleaning up /indel/backup/gitlab/ci_secure_files.tar.gz
2023-11-10 00:02:02 UTC -- Deleting tar staging files ... done
2023-11-10 00:02:02 UTC -- Deleting backups/tmp ... 
2023-11-10 00:02:02 UTC -- Deleting backups/tmp ... done
2023-11-10 00:02:02 UTC -- Warning: Your gitlab.rb and gitlab-secrets.json files contain sensitive data 
and are not included in this backup. You will need these files to restore a backup.
Please back them up manually.
2023-11-10 00:02:02 UTC -- Backup 1699574417_2023_11_10_16.5.1 is done.
2023-11-10 00:02:02 UTC -- Deleting backup and restore PID file ... done

Output of checks

Results of GitLab environment info

Expand for output related to GitLab environment info

System information
System:		Ubuntu 22.04
Current User:	git
Using RVM:	no
Ruby Version:	3.0.6p216
Gem Version:	3.4.19
Bundler Version:2.4.20
Rake Version:	13.0.6
Redis Version:	7.0.13
Sidekiq Version:6.5.7
Go Version:	unknown

GitLab information
Version:	16.5.1
Revision:	d59d7a49a1f
Directory:	/opt/gitlab/embedded/service/gitlab-rails
DB Adapter:	PostgreSQL
DB Version:	13.11
URL:		https://gitlab.indel.ch
HTTP Clone URL:	https://gitlab.indel.ch/some-group/some-project.git
SSH Clone URL:	git@gitlab.indel.ch:some-group/some-project.git
Using LDAP:	no
Using Omniauth:	yes
Omniauth Providers: 

GitLab Shell
Version:	14.29.0
Repository storages:
- default: 	unix:/var/opt/gitlab/gitaly/gitaly.socket
GitLab Shell path:		/opt/gitlab/embedded/service/gitlab-shell

Gitaly
- default Address: 	unix:/var/opt/gitlab/gitaly/gitaly.socket
- default Version: 	16.5.1
- default Git Version: 	2.42.0

Results of GitLab application Check

Expand for output related to the GitLab application check

Checking GitLab subtasks ...
Checking GitLab Shell ...
GitLab Shell: ... GitLab Shell version >= 14.29.0 ? ... OK (14.29.0)
Running /opt/gitlab/embedded/service/gitlab-shell/bin/check
Internal API available: OK
Redis available via internal API: OK
gitlab-shell self-check successful
Checking GitLab Shell ... Finished
Checking Gitaly ...
Gitaly: ... default ... OK
Checking Gitaly ... Finished
Checking Sidekiq ...
Sidekiq: ... Running? ... yes
Number of Sidekiq processes (cluster/worker) ... 1/1
Checking Sidekiq ... Finished
Checking Incoming Email ...
Incoming Email: ... Reply by email is disabled in config/gitlab.yml
Checking Incoming Email ... Finished
Checking LDAP ...
LDAP: ... LDAP is disabled in config/gitlab.yml
Checking LDAP ... Finished
Checking GitLab App ...
Database config exists? ... yes
Tables are truncated? ... skipped
All migrations up? ... yes
Database contains orphaned GroupMembers? ... no
GitLab config exists? ... yes
GitLab config up to date? ... yes
Cable config exists? ... yes
Resque config exists? ... yes
Log directory writable? ... yes
Tmp directory writable? ... yes
Uploads directory exists? ... yes
Uploads directory has correct permissions? ... yes
Uploads directory tmp has correct permissions? ... yes
Systemd unit files or init script exist? ... skipped (omnibus-gitlab has neither init script nor systemd units)
Systemd unit files or init script up-to-date? ... skipped (omnibus-gitlab has neither init script nor systemd units)
Projects have namespace: ...
5/3 ... yes
6/5 ... yes
7/6 ... yes
7/7 ... yes
7/8 ... yes
12/12 ... yes
7/13 ... yes
7/14 ... yes
3/16 ... yes
7/17 ... yes
7/18 ... yes
3/19 ... yes
7/20 ... yes
3/21 ... yes
7/22 ... yes
5/23 ... yes
12/24 ... yes
5/25 ... yes
5/26 ... yes
7/27 ... yes
12/29 ... yes
7/30 ... yes
7/31 ... yes
7/32 ... yes
5/34 ... yes
12/35 ... yes
7/36 ... yes
3/37 ... yes
7/38 ... yes
12/39 ... yes
7/40 ... yes
14/41 ... yes
7/42 ... yes
7/43 ... yes
3/44 ... yes
7/45 ... yes
7/46 ... yes
7/48 ... yes
12/49 ... yes
7/50 ... yes
7/51 ... yes
12/53 ... yes
14/54 ... yes
12/55 ... yes
7/56 ... yes
12/57 ... yes
7/58 ... yes
12/59 ... yes
12/60 ... yes
12/61 ... yes
12/62 ... yes
12/63 ... yes
7/64 ... yes
12/65 ... yes
12/66 ... yes
12/67 ... yes
12/68 ... yes
12/69 ... yes
12/70 ... yes
12/71 ... yes
12/72 ... yes
12/73 ... yes
12/74 ... yes
7/75 ... yes
7/76 ... yes
12/77 ... yes
3/78 ... yes
3/79 ... yes
14/80 ... yes
3/81 ... yes
14/82 ... yes
31/83 ... yes
31/84 ... yes
3/86 ... yes
3/87 ... yes
3/88 ... yes
3/89 ... yes
42/94 ... yes
3/95 ... yes
3/96 ... yes
3/98 ... yes
3/99 ... yes
12/101 ... yes
7/102 ... yes
3/103 ... yes
7/104 ... yes
14/105 ... yes
7/106 ... yes
45/107 ... yes
7/109 ... yes
7/110 ... yes
31/111 ... yes
14/112 ... yes
3/113 ... yes
3/114 ... yes
12/116 ... yes
7/117 ... yes
12/118 ... yes
3/119 ... yes
12/120 ... yes
12/121 ... yes
5/122 ... yes
52/123 ... yes
52/124 ... yes
52/125 ... yes
52/127 ... yes
31/128 ... yes
12/129 ... yes
12/130 ... yes
12/132 ... yes
12/133 ... yes
7/134 ... yes
12/135 ... yes
12/136 ... yes
12/137 ... yes
52/138 ... yes
31/139 ... yes
3/140 ... yes
12/141 ... yes
72/142 ... yes
12/143 ... yes
31/144 ... yes
3/145 ... yes
3/146 ... yes
3/147 ... yes
7/148 ... yes
52/150 ... yes
52/151 ... yes
52/153 ... yes
52/154 ... yes
12/155 ... yes
12/156 ... yes
64/157 ... yes
7/158 ... yes
64/159 ... yes
7/162 ... yes
64/163 ... yes
75/164 ... yes
12/165 ... yes
72/167 ... yes
64/168 ... yes
80/170 ... yes
64/172 ... yes
52/173 ... yes
74/179 ... yes
86/181 ... yes
86/182 ... yes
86/183 ... yes
86/185 ... yes
80/187 ... yes
80/188 ... yes
80/190 ... yes
64/191 ... yes
80/192 ... yes
64/193 ... yes
72/194 ... yes
7/196 ... yes
7/197 ... yes
7/198 ... yes
7/199 ... yes
50/200 ... yes
64/202 ... yes
72/206 ... yes
7/207 ... yes
7/209 ... yes
7/210 ... yes
12/211 ... yes
7/212 ... yes
3/213 ... yes
101/215 ... yes
7/216 ... yes
7/217 ... yes
4/219 ... yes
7/220 ... yes
7/221 ... yes
389/222 ... yes
389/225 ... yes
389/226 ... yes
106/227 ... yes
4/228 ... yes
7/229 ... yes
7/231 ... yes
90/232 ... yes
90/233 ... yes
5/234 ... yes
7/235 ... yes
7/236 ... yes
112/237 ... yes
113/241 ... yes
73/242 ... yes
73/243 ... yes
112/244 ... yes
73/245 ... yes
73/246 ... yes
64/247 ... yes
90/248 ... yes
12/249 ... yes
7/250 ... yes
12/251 ... yes
73/252 ... yes
64/253 ... yes
7/254 ... yes
64/255 ... yes
64/256 ... yes
112/257 ... yes
31/258 ... yes
50/259 ... yes
118/260 ... yes
7/261 ... yes
334/262 ... yes
50/263 ... yes
338/264 ... yes
118/265 ... yes
341/266 ... yes
343/267 ... yes
341/268 ... yes
12/269 ... yes
7/270 ... yes
101/271 ... yes
351/272 ... yes
90/273 ... yes
101/274 ... yes
112/275 ... yes
112/276 ... yes
112/277 ... yes
341/278 ... yes
351/279 ... yes
112/280 ... yes
112/281 ... yes
112/282 ... yes
112/283 ... yes
380/284 ... yes
Redis version >= 6.0.0? ... yes
Ruby version >= 3.0.6 ? ... yes (3.0.6)
Git user has default SSH configuration? ... yes
Active users: ... 106
Is authorized keys file accessible? ... yes
GitLab configured to store new projects in hashed storage? ... yes
All projects are in hashed storage? ... yes
Checking GitLab App ... Finished
Checking GitLab subtasks ... Finished