Skip to content
Snippets Groups Projects

GHC-9.6.4 on FreeBSD: "ghcup: internal error: Ticker: read(timerfd) failed with Operation not supported and returned -1"

    • Closed Issue created by Julian Ospald @maerwald

    On FreeBSD: https://github.com/haskell/ghcup-hs/actions/runs/8686247192/job/23817595251#step:7:530

    During execution of ghcup install ghc 9.6.4.

    Similar issue from some time ago: #20132

    To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information

    Child items ...

    • Activity

    • ghc-triage-bot added needs triage label

      added needs triage label

    • Ben Gamari removed needs triage label

      removed needs triage label

    • Ben Gamari added Tbug label

      added Tbug label

    • Ben Gamari marked this issue as related to #20132

      marked this issue as related to #20132

    • Ben Gamari added FreeBSD Pnormal labels

      added FreeBSD Pnormal labels

    • Julian Ospald
      Julian Ospald @maerwald ·
      Author Developer

      This is a blocker for recommending 9.6.x series in ghcup.

      @arrowd do you know what could be the cause?

    • Cheng Shao
      Cheng Shao @TerrorJack ·
      Developer

      Does it still occur with +RTS -V0? That'll disable the ticker logic.

      • Ben Gamari
        Ben Gamari @bgamari ·
        Maintainer

        I have looked at this a bit. The general trajectory is:

        31872: timerfd_create(0x4,0x100000)              = 4 (0x4)
31872: timerfd_settime(0x4,0x0,0x8236ed4c0,0x0)  = 0 (0x0)
...
31872: close(4)                                  = 0 (0x0)
...
31872: kqueue()                                  = 4 (0x4)
...
31872: kevent(4,{ 5,EVFILT_READ,EV_ADD,0,0,0x0 },1,0x0,0,{ 0.000000000 }) = 0 (0x0)
31872: kevent(4,{ 7,EVFILT_READ,EV_ADD,0,0,0x0 },1,0x0,0,{ 0.000000000 }) = 0 (0x0)
...
31872: read(4,0x82c939fa8,8)                     ERR#45 'Operation not supported'
...
ghcup: internal error: 
Ticker: read(timerfd) failed with Operation not supported and returned -1

        That is, the timerfd is closed, the fd is reused as a kqueue, and then we nevertheless try reading (the number of expirations) from it.

        Edited by Ben Gamari
      • Gleb Popov
        Gleb Popov @arrowd ·
        Reporter

        The timerfd descriptor is read and closed in the same function rts/posix/ticker.c:itimer_thread_func(). I see no way how could it happen that the descriptor is read after closing. Except maybe if we have several itimer_thread_funcs running in different threads?

      • Sylvain Henry
        Sylvain Henry @hsyl20 ·
        Developer

        I'd be curious to know which close actually closed the timerfd. There is a chance it's not the one we would expect. @bgamari could you find it? Maybe with some breakpoint?

      • Gleb Popov
        Gleb Popov @arrowd ·
        Reporter

        Maybe try setting timerfd = -1; right after closing?

      • Julian Ospald
        Julian Ospald @maerwald ·
        Author Developer

        any updates?

      • Please register or sign in to reply
      • Divam Narula
        Divam Narula @dfordivam ·
        Developer

        @bgamari I debugged this, and now have a small reproducer. Note that in the reproducer the close does not happen on any FD as shown in the gdb log below. cc @maerwald

        module Main where

import Control.Concurrent
import qualified System.Posix.Process          as SPP

main = do
  print "before SPP.forkProcess"
  threadDelay (5*1000*1000)
  SPP.forkProcess $ pure ()
  threadDelay (5*1000*1000)
  print "after SPP.forkProcess"
        $ freebsd-version 
14.0-RELEASE
$ ghc --version
The Glorious Glasgow Haskell Compilation System, version 9.6.6
$ ghc app/Main.hs
[1 of 2] Compiling Main             ( app/Main.hs, app/Main.o ) [Control.Concurrent changed]
[2 of 2] Linking app/Main [Objects changed]
$ app/Main
"before SPP.forkProcess"
"after SPP.forkProcess"
$ ghc app/Main.hs -threaded
[2 of 2] Linking app/Main [Flags changed]
$ app/Main
"before SPP.forkProcess"
Main: internal error: Ticker: read(timerfd) failed with Operation not supported and returned -1
    (GHC version 9.6.6 for x86_64_portbld_freebsd)
    Please report this as a GHC bug:  https://www.haskell.org/ghc/reportabug
"after SPP.forkProcess"
        (gdb) b close
Breakpoint 1 at 0x404fb0
(gdb) r
Starting program: /home/divam/repos/dfordivam/various-codes/app/Main 
[New LWP 317623 of process 30417]
[New LWP 317624 of process 30417]
[New LWP 317625 of process 30417]
"before SPP.forkProcess"
[New LWP 317626 of process 30417]
[Detaching after fork from child process 30418]
Main: internal error: Ticker: read(timerfd) failed with Operation not supported and returned -1
    (GHC version 9.6.6 for x86_64_portbld_freebsd)
    Please report this as a GHC bug:  https://www.haskell.org/ghc/reportabug
"after SPP.forkProcess"
[Switching to LWP 317625 of process 30417]

Thread 4 "ghc_worker" hit Breakpoint 1, 0x0000000800cde4b4 in close () from /lib/libc.so.7
(gdb)
      • Gleb Popov
        Gleb Popov @arrowd ·
        Reporter

        Thank you for the reproducer! I think I understand what's going on.

        The timerfd descriptor is set to close-on-exec, so after forking the variable contains invalid value that is then gets occupied by another descriptor (the kqueue one) which does not support reading.

        I guess the correct fix is to remove TFD_CLOEXEC, but I'm not sure if this is correct.

      • Sylvain Henry
        Sylvain Henry @hsyl20 ·
        Developer

        I don't think your analysis is correct. After the fork, in the child, we reinit the ticker (initTimer) so it should set the timerfd variable to a proper timerfd descriptor before the ticker thread is created again.

        Note that we should probably close timerfd first in the child after the fork because currently we leak it as it remains valid after a fork (at least on Linux):

           fork(2) semantics
       After a fork(2), the child inherits a copy of the file descriptor
       created by timerfd_create().  The file descriptor refers to the
       same underlying timer object as the corresponding file descriptor
       in the parent, and read(2)s in the child will return information
       about expirations of the timer.

        @dfordivam Could you use strace to get a log of the syscalls? We would need to see the fd for the failing read and then scroll up to find the syscall that created it. It could give us a hint about what's going on.

      • Gleb Popov
        Gleb Popov @arrowd ·
        Reporter

        Here's the relevant piece:

        18957: fork()					 = 19187 (0x4af3)
19187: <new process>
19187: thr_self(0xdc543a12000)			 = 0 (0x0)
18957: _umtx_op(0xdc543a122c8,UMTX_OP_NWAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
18957: _umtx_op(0xdc54366a008,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
19187: mmap(0x0,3670016,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON|MAP_ALIGNED(12),-1,0x0) = 15140923637760 (0xdc545600000)
18957: write(10,"\^A\0\0\0\0\0\0\0",8)		 = 8 (0x8)
18957: poll({ 8/POLLIN 10/POLLIN },2,-1)	 = 1 (0x1)
19187: mmap(0x0,4194304,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON|MAP_ALIGNED(12),-1,0x0) = 15140927307776 (0xdc545980000)
18957: read(10,"\^A\0\0\0\0\0\0\0",8)		 = 8 (0x8)
19187: timerfd_create(0x4,0x100000)		 = 4 (0x4)
19187: timerfd_settime(0x4,0x0,0x820e378f0,0x0)	 = 0 (0x0)
19187: sigprocmask(SIG_SETMASK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGABRT|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
19187: mmap(0x0,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 15140890521600 (0xdc54366b000)
19187: mmap(0x800437000,2101248,PROT_READ|PROT_WRITE,MAP_STACK,-1,0x0) = 35050086400 (0x82925e000)
19187: mprotect(0x82925e000,4096,PROT_NONE)	 = 0 (0x0)
19187: thr_new(0x820e377c0,0x68)		 = 0 (0x0)
19187: <new thread 114371>
19187: sigprocmask(SIG_SETMASK,{ },0x0)		 = 0 (0x0)
18957: read(3,"\^A\0\0\0\0\0\0\0",8)		 = 8 (0x8)
19187: sigfastblock(0x1,0xdc543a13c38)		 = 0 (0x0)
19187: mmap(0x0,2097152,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON|MAP_ALIGNED(21),-1,0x0) = 15140932026368 (0xdc545e00000)
19187: close(4)					 = 0 (0x0)
19187: close(5)					 = 0 (0x0)
19187: close(6)					 = 0 (0x0)
19187: close(7)					 = 0 (0x0)
19187: kqueue()					 = 4 (0x4)
19187: mmap(0x0,2097152,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON|MAP_ALIGNED(12),-1,0x0) = 15140934123520 (0xdc546000000)
19187: pipe2(0x4200604218,0)			 = 0 (0x0)
19187: thr_set_name(114371,"ghc_ticker")	 = 0 (0x0)
19187: read(4,0x82945efa8,8)			 ERR#45 'Operation not supported'

        The timerfd is indeed gets created again, but it is then closed. The consecutive kqueue call takes the same fd, because it is now free. I'm lost again.

      • Gleb Popov
        Gleb Popov @arrowd ·
        Reporter

        And this is what closes it:

        (gdb) bt
#0  close (fd=4) at /usr/src/lib/libc/sys/close.c:43
#1  0x0000000000640948 in base_GHCziEventziKQueue_new4_info ()
#2  0x0000000000000000 in ?? ()
      • Sylvain Henry
        Sylvain Henry @hsyl20 ·
        Developer

        It looks similar to what this comment describes: #4449 (comment 48169) I.e. the IOManager is cleaning up some FDs that are no longer relevant and that have been reused for something else (here for timerfd).

        Maybe the following is enough:

        --- libraries/base/GHC/Event/Manager.hs
+++ libraries/base/GHC/Event/Manager.hs
@@ -239,10 +239,11 @@ finished mgr = (== Finished) `liftM` readIORef (emState mgr)

 cleanup :: EventManager -> IO ()
 cleanup EventManager{..} = do
-  writeIORef emState Finished
+  st <- atomicModifyIORef' emState $ \s -> (Finished, s)
   void $ tryPutMVar emLock ()
-  I.delete emBackend
-  closeControl emControl
+  when (st /= Finished) $ do
+    I.delete embackend
+    closeControl emControl

        If it doesn't work, apparently the fd returned by the kqueue isn't shared with the child, so perhaps we shouldn't close it at all after a fork? (I.e. comment out the I.delete in GHC.Event.Manager.{cleanup,newWith} to try)

      • Gleb Popov
        Gleb Popov @arrowd ·
        Reporter

        This proposed change does not fix the problem.

      • Sylvain Henry
        Sylvain Henry @hsyl20 ·
        Developer

        What if you just comment I.delete emBackend in this function?

        We mustn't try to close kqueue fds and this function is called from startIOManagerThread in the ThreadDied case.

      • Gleb Popov
        Gleb Popov @arrowd ·
        Reporter

        Commenting only this line makes the problem go away!

      • Sylvain Henry
        Sylvain Henry @hsyl20 ·
        Developer

        I'll try to make a patch then

      • Please register or sign in to reply
    • Sylvain Henry mentioned in merge request !13276 (closed)

      mentioned in merge request !13276 (closed)

    • Sylvain Henry
      Sylvain Henry @hsyl20 ·
      Developer

      I've opened an MR: !13276 (closed)

    • Sylvain Henry mentioned in issue #25280 (closed)

      mentioned in issue #25280 (closed)

    • Marge Bot mentioned in commit d4604efa

      mentioned in commit d4604efa

    • Marge Bot mentioned in commit 3e379148

      mentioned in commit 3e379148

    • Marge Bot closed with commit e7a26d7a

      closed with commit e7a26d7a

    • Marge Bot mentioned in commit e7a26d7a

      mentioned in commit e7a26d7a

    • Ben Gamari mentioned in commit 8f3d1a6a

      mentioned in commit 8f3d1a6a

    • Ben Gamari mentioned in merge request !13319 (merged)

      mentioned in merge request !13319 (merged)

    • Ben Gamari mentioned in commit 486b2702

      mentioned in commit 486b2702

    • Ben Gamari mentioned in commit bcfa1a51

      mentioned in commit bcfa1a51

    • Ben Gamari added backport needed:9.6 label

      added backport needed:9.6 label

    • Andreas Klebinger mentioned in issue #25433 (closed)

      mentioned in issue #25433 (closed)

    • Luite Stegeman mentioned in merge request !13740 (closed)

      mentioned in merge request !13740 (closed)

    • Luite Stegeman mentioned in commit 9177b8ed

      mentioned in commit 9177b8ed

    • Luite Stegeman mentioned in merge request !13841 (merged)

      mentioned in merge request !13841 (merged)

    • Andreas Klebinger mentioned in commit f166369b

      mentioned in commit f166369b

    • Andreas Klebinger mentioned in merge request !13861 (merged)

      mentioned in merge request !13861 (merged)

    • Andreas Klebinger mentioned in commit a610550e

      mentioned in commit a610550e

    Please register or sign in to reply