[bug#50040] [PATCH 0/2] publish: Always render nar/narinfo during backing.

[Mathieu Othacehe]

Hey,

I increased the bypass cache value on the Berlin publish server from 50
to 500 MiB to confirm that this patch will help. Turns out, there are
still some Cuirass errors.

Running this command:

--8<---------------cut here---------------start------------->8---
sudo strace -f  -s 10000 -e write -p 124867 -p 124868 -p 124869 -p
124870 -p 124871 -p 124872 -p 124873 -p 124874 -p 124875 -p 124876 -p
124877 -p 124878 -p 124879 -p 124880 -p 124881 -p 124882 -p 124883  2>&1
|grep narinfo
--8<---------------cut here---------------end--------------->8---

(The processes are all the Nginx workers)

Shows those errors:

--8<---------------cut here---------------start------------->8---
[pid 124867] write(4, "2021/08/21 22:17:40 [error] 124867#0: *16550606 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.167, server: ci.guix.gnu.org, request: \"GET 
/s03ydmlv5p7v206hvj5z1d4hn9nzsv2s.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/s03ydmlv5p7v206hvj5z1d4hn9nzsv2s.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124869] write(4, "2021/08/21 22:17:40 [error] 124869#0: *16550621 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.175, server: ci.guix.gnu.org, request: \"GET 
/kfzipc676in0ff2im8zprbsgv9idrc9j.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/kfzipc676in0ff2im8zprbsgv9idrc9j.narinfo\";, host: 
\"141.80.167.131\"\n", 355 <unfinished ...>
[pid 124867] write(4, "2021/08/21 22:17:41 [error] 124867#0: *16550771 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.158, server: ci.guix.gnu.org, request: \"GET 
/0mpspvh9h208vhrd3wxhw1165rz8mslb.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/0mpspvh9h208vhrd3wxhw1165rz8mslb.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124867] write(4, "2021/08/21 22:17:41 [error] 124867#0: *16550774 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.163, server: ci.guix.gnu.org, request: \"GET 
/4hy6nms1lzgbdrwslw5dlilvvjlrz95g.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/4hy6nms1lzgbdrwslw5dlilvvjlrz95g.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124867] write(4, "2021/08/21 22:17:42 [error] 124867#0: *16550628 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.173, server: ci.guix.gnu.org, request: \"GET 
/y9adqfkz8h3if17q3w801wfr0r91xdds.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/y9adqfkz8h3if17q3w801wfr0r91xdds.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124867] write(4, "2021/08/21 22:17:42 [error] 124867#0: *16550471 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.178, server: ci.guix.gnu.org, request: \"GET 
/d6vvg1rsqya8cnhi2mzqqvin55qax3xy.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/d6vvg1rsqya8cnhi2mzqqvin55qax3xy.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124867] write(4, "2021/08/21 22:17:42 [error] 124867#0: *16550606 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.167, server: ci.guix.gnu.org, request: \"GET 
/h3bd6psd2ijj5d9a8q46w2ldqsi135j0.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/h3bd6psd2ijj5d9a8q46w2ldqsi135j0.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124867] write(4, "2021/08/21 22:17:42 [error] 124867#0: *16550780 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.184, server: ci.guix.gnu.org, request: \"GET 
/8jvzhavq2zkychyjhs0ywnz2mpgp73qz.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/8jvzhavq2zkychyjhs0ywnz2mpgp73qz.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124868] write(4, "2021/08/21 22:17:43 [error] 124868#0: *16550782 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 127.0.0.1, server: ci.guix.gnu.org, request: \"GET 
/3wl6j74i18wgcyqwrvfjjcyag4w3ip3d.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/3wl6j74i18wgcyqwrvfjjcyag4w3ip3d.narinfo\";, host: 
\"127.0.0.1\"\n", 345) = 345
[pid 124868] write(4, "2021/08/21 22:17:43 [error] 124868#0: *16550784 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.161, server: ci.guix.gnu.org, request: \"GET 
/lf8lczjd7k55x2byql0rn5qpgibvl6kh.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/lf8lczjd7k55x2byql0rn5qpgibvl6kh.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124867] write(4, "2021/08/21 22:17:43 [error] 124867#0: *16550786 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.177, server: ci.guix.gnu.org, request: \"GET 
/fvddmn01gx8amxlh6kvv8j7pcm6dxddn.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/fvddmn01gx8amxlh6kvv8j7pcm6dxddn.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124867] write(4, "2021/08/21 22:17:44 [error] 124867#0: *16550788 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.183, server: ci.guix.gnu.org, request: \"GET 
/wcl4mlxpnn20q2f2mgc2hj7w21jf03iz.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/wcl4mlxpnn20q2f2mgc2hj7w21jf03iz.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124867] write(4, "2021/08/21 22:17:44 [error] 124867#0: *16550471 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.178, server: ci.guix.gnu.org, request: \"GET 
/hakhzv36jl50mas5am4pwk89p428wnrl.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/hakhzv36jl50mas5am4pwk89p428wnrl.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124867] write(4, "2021/08/21 22:17:44 [error] 124867#0: *16550606 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.167, server: ci.guix.gnu.org, request: \"GET 
/64fsv1vjf1mxkv6wv2wh3vkffzrgalyq.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/64fsv1vjf1mxkv6wv2wh3vkffzrgalyq.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124867] write(4, "2021/08/21 22:17:44 [error] 124867#0: *16550796 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.159, server: ci.guix.gnu.org, request: \"GET 
/skbvrqdl64lph6k1ba5gay31spdbkm04.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/skbvrqdl64lph6k1ba5gay31spdbkm04.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124867] write(4, "2021/08/21 22:17:45 [error] 124867#0: *16550799 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.164, server: ci.guix.gnu.org, request: \"GET 
/b9lrrh5zj7wjhgs93m1aaz0chbp7awzk.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/b9lrrh5zj7wjhgs93m1aaz0chbp7awzk.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
[pid 124867] write(4, "2021/08/21 22:17:45 [error] 124867#0: *16550802 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 127.0.0.1, server: ci.guix.gnu.org, request: \"GET 
/3sqsphfshnkpxk91zi38hh11ifq144n3.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/3sqsphfshnkpxk91zi38hh11ifq144n3.narinfo\";, host: 
\"127.0.0.1\"\n", 345) = 345
[pid 124867] write(4, "2021/08/21 22:17:45 [error] 124867#0: *16550804 upstream 
timed out (110: Connection timed out) while reading response header from 
upstream, client: 141.80.167.185, server: ci.guix.gnu.org, request: \"GET 
/f8ld4yvmsp5z1850gppy6sv0g59yamh8.narinfo HTTP/1.1\", upstream: 
\"http://127.0.0.1:3000/f8ld4yvmsp5z1850gppy6sv0g59yamh8.narinfo\";, host: 
\"141.80.167.131\"\n", 355) = 355
--8<---------------cut here---------------end--------------->8---

I think this is caused by the following lines in the Berlin Nginx
configuration:

--8<---------------cut here---------------start------------->8---
;; Do not tolerate slowness of hydra.gnu.org when fetching
;; narinfos: better return 504 quickly than wait forever.
"proxy_connect_timeout 2s;"
"proxy_read_timeout 2s;"
"proxy_send_timeout 2s;"
--8<---------------cut here---------------end--------------->8---

The narinfos that are not in cache yet are computed in the main thread,
slowing down the publish process. Under pressure, computing those
narinfo can exceed the 2s timeout resulting in the failures above.

Our best course of action here could be to merge the proposed patches,
extend the Nginx timeout to 10s and see if all the requests can be
handled quickly enough.

Thanks,

Mathieu