Subject: Re: bug#67041: [cuirass] cuirass-web crash

From: Ludovic Courtès <[email-masked]>
Date: Thu, 16 Nov 2023 17:09:49 +0100

Hi,

Maxim Cournoyer <[email-masked]> skribis:

> 2023-11-10 13:11:30 ice-9/boot-9.scm:1685:16: In procedure raise-exception:
> 2023-11-10 13:11:30 In procedure accept: Too many open files

Apparently there’s something that causes ‘cuirass web’ to leak file
descriptors, the number being otherwise stable around 50:

--8<---------------cut here---------------start------------->8---
2023-11-08 06:53:23 heap: 61.34 MiB; threads: 9; file descriptors: 50
2023-11-08 07:03:23 heap: 61.34 MiB; threads: 9; file descriptors: 50
2023-11-08 07:13:23 heap: 61.34 MiB; threads: 9; file descriptors: 50
2023-11-08 07:23:23 heap: 61.34 MiB; threads: 9; file descriptors: 50
2023-11-08 07:33:23 heap: 54.97 MiB; threads: 9; file descriptors: 50
2023-11-08 07:43:23 heap: 54.97 MiB; threads: 9; file descriptors: 50
2023-11-08 07:53:23 heap: 54.97 MiB; threads: 9; file descriptors: 50
2023-11-08 08:03:23 heap: 54.97 MiB; threads: 9; file descriptors: 50
2023-11-08 08:13:23 heap: 61.34 MiB; threads: 9; file descriptors: 50
2023-11-08 08:23:23 heap: 61.34 MiB; threads: 9; file descriptors: 50
2023-11-08 08:33:23 heap: 61.34 MiB; threads: 9; file descriptors: 50
2023-11-08 08:43:23 heap: 61.34 MiB; threads: 9; file descriptors: 50
2023-11-08 08:53:23 heap: 61.34 MiB; threads: 9; file descriptors: 50
2023-11-08 09:03:23 heap: 61.34 MiB; threads: 9; file descriptors: 51
2023-11-08 09:13:23 heap: 61.34 MiB; threads: 9; file descriptors: 154
2023-11-08 09:23:23 heap: 61.34 MiB; threads: 9; file descriptors: 232
2023-11-08 09:33:23 heap: 61.34 MiB; threads: 9; file descriptors: 282
2023-11-08 09:43:23 heap: 61.34 MiB; threads: 9; file descriptors: 385
2023-11-08 09:53:23 heap: 61.34 MiB; threads: 9; file descriptors: 489
2023-11-08 10:03:23 heap: 61.34 MiB; threads: 9; file descriptors: 608
2023-11-08 10:13:23 heap: 61.34 MiB; threads: 9; file descriptors: 665
2023-11-08 10:23:23 heap: 61.34 MiB; threads: 9; file descriptors: 706
2023-11-08 10:33:23 heap: 61.34 MiB; threads: 9; file descriptors: 760
2023-11-08 10:43:23 heap: 61.34 MiB; threads: 9; file descriptors: 802
2023-11-08 10:53:23 heap: 61.34 MiB; threads: 9; file descriptors: 865
2023-11-08 11:03:23 heap: 61.34 MiB; threads: 9; file descriptors: 969
2023-11-08 11:13:24 heap: 61.34 MiB; threads: 9; file descriptors: 0
2023-11-08 11:23:24 heap: 61.34 MiB; threads: 9; file descriptors: 0
--8<---------------cut here---------------end--------------->8---

Looking at the logs, the FD leak may come from this:

--8<---------------cut here---------------start------------->8---
2023-11-08 09:03:35 GET /eval/903503
2023-11-08 09:03:35 In cuirass/http.scm:
2023-11-08 09:03:35   1074:25 11 (url-handler _ _ _)
2023-11-08 09:03:35     295:4 10 (evaluation-html-page #<<evaluation-summary> id: 90350?> ?)
2023-11-08 09:03:35 In cuirass/logging.scm:
2023-11-08 09:03:35    111:18  9 (call-with-time-logging "builds request for evaluation?" ?)
2023-11-08 09:03:35 In ice-9/boot-9.scm:
2023-11-08 09:03:35   1752:10  8 (with-exception-handler _ _ #:unwind? _ # _)
2023-11-08 09:03:35 In cuirass/utils.scm:
2023-11-08 09:03:35     99:24  7 (_)
2023-11-08 09:03:35 In cuirass/database.scm:
2023-11-08 09:03:35    1503:2  6 (_ _)
2023-11-08 09:03:35   1439:28  5 (proc _)
2023-11-08 09:03:35 In ice-9/boot-9.scm:
2023-11-08 09:03:35   1685:16  4 (raise-exception _ #:continuable? _)
2023-11-08 09:03:35 In cuirass/utils.scm:
2023-11-08 09:03:35     96:12  3 (_ #<&compound-exception components: (#<&error> #<&orig?>)
2023-11-08 09:03:35 In fibers/operations.scm:
2023-11-08 09:03:35    154:10  2 (perform-operation _)
2023-11-08 09:03:35 In fibers/scheduler.scm:
2023-11-08 09:03:35     357:6  1 (suspend-current-task _)
2023-11-08 09:03:35 In ice-9/boot-9.scm:
2023-11-08 09:03:35   1685:16  0 (raise-exception _ #:continuable? _)
2023-11-08 09:03:35 Attempt to suspend fiber within continuation barrier
--8<---------------cut here---------------end--------------->8---

Fortunately, this is easy to reproduce:

--8<---------------cut here---------------start------------->8---
$ ./pre-inst-env guile
GNU Guile 3.0.9
Copyright (C) 1995-2023 Free Software Foundation, Inc.

Guile comes with ABSOLUTELY NO WARRANTY; for details type `,show w'.
This program is free software, and you are welcome to redistribute it
under certain conditions; type `,show c' for details.

Enter `,help' for help.
scheme@(guile-user)> ,use(fibers)
scheme@(guile-user)> ,use(cuirass utils)
scheme@(guile-user)> (run-fibers
(lambda ()
  (define pool (make-resource-pool (iota 10)))
  (with-resource-from-pool pool x (pk 'x x) (throw 'doh!))))

;;; (x 0)
Uncaught exception in task:
In fibers.scm:
   186:20  9 (_)
   145:21  8 (_)
In ice-9/boot-9.scm:
  1752:10  7 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _)
In cuirass/utils.scm:
    99:24  6 (_)
In current input:
     6:44  5 (_ _)
In ice-9/boot-9.scm:
  1685:16  4 (raise-exception _ #:continuable? _)
In cuirass/utils.scm:
    96:12  3 (_ #<&compound-exception components: (#<&error> #<&irritants irritants: ()> #<&exception-with-kind-and-args kind: doh! args: ()>)>)
In fibers/operations.scm:
   154:10  2 (perform-operation _)
In fibers/scheduler.scm:
    357:6  1 (suspend-current-task _)
In ice-9/boot-9.scm:
  1685:16  0 (raise-exception _ #:continuable? _)
ice-9/boot-9.scm:1685:16: In procedure raise-exception:
Attempt to suspend fiber within continuation barrier
--8<---------------cut here---------------end--------------->8---

To be continued…

Ludo’.