Modify displayed exception type

[tbidne]

Intro

Hello, this is a follow-up to the accepted (unmerged gitlab MR) proposal: https://github.com/haskell/core-libraries-committee/issues/231.

If you will recall, that issue adds the following exception metadata to the default handler:

Main: thread blocked indefinitely in an MVar operation
HasCallStack backtrace:
CallStack (from HasCallStack):
  collectBacktraces, called at libraries/base/GHC/Exception.hs:67:13 in base:GHC.Exception
  toExceptionWithBacktrace, called at libraries/base/GHC/IO.hs:278:11 in base:GHC.IO
  throwIO, called at Main.hs:15:16 in main:Main
  
-- the below is new

Package: base
Module: GHC.IO.Exception
Name: BlockedIndefinitelyOnMVar

On the issue tracker, @michaelpj observes that the message could be clearer still, with references to other programming languages. At the time I thought this was a good suggestion but didn't think it important enough to warrant the churn of another CLC-proposal and possible interference with the rest of the exceptions work. Now that the "callstacks are part of displayException" work has been merged, however, I think that has changed. In particular, the output with multiple stacktraces / https://github.com/haskell/core-libraries-committee/issues/231 is complicated enough that I think getting other opinions would be wise.

Status quo

As of now, here is what the exception output currently looks like:

Expand example

1. Default (HasCallStack only)

λ. ./Main
Main: thread blocked indefinitely in an MVar operation
HasCallStack backtrace:
  collectBacktraces, called at libraries/ghc-internal/src/GHC/Internal/Exception.hs:92:13 in ghc-internal:GHC.Internal.Exception
  toExceptionWithBacktrace, called at libraries/ghc-internal/src/GHC/Internal/IO.hs:260:11 in ghc-internal:GHC.Internal.IO
  throwIO, called at Main.hs:40:16 in main:Main

2. All backtraces off

λ. ./Main
Main: thread blocked indefinitely in an MVar operation

3. All backtraces on (except DWARF, since that adds an error message w/o other changes)

λ. ./Main
Main: thread blocked indefinitely in an MVar operation
Cost-centre stack backtrace:
IPE backtrace:
HasCallStack backtrace:
  collectBacktraces, called at libraries/ghc-internal/src/GHC/Internal/Exception.hs:92:13 in ghc-internal:GHC.Internal.Exception
  toExceptionWithBacktrace, called at libraries/ghc-internal/src/GHC/Internal/IO.hs:260:11 in ghc-internal:GHC.Internal.IO
  throwIO, called at Main.hs:40:16 in main:Main

(the trailing newlines are due to there being a "blank" annotation that nonetheless is rendered with separating newlines.)

Current proposal

With the accepted proposal, this looks like:

Expand example

1. Default (HasCallStack only)

λ. ./Main
Main: thread blocked indefinitely in an MVar operation
HasCallStack backtrace:
  collectBacktraces, called at libraries/ghc-internal/src/GHC/Internal/Exception.hs:92:13 in ghc-internal:GHC.Internal.Exception
  toExceptionWithBacktrace, called at libraries/ghc-internal/src/GHC/Internal/IO.hs:260:11 in ghc-internal:GHC.Internal.IO
  throwIO, called at Main.hs:40:16 in main:Main

Package: ghc-internal
Module: GHC.Internal.IO.Exception
Name: BlockedIndefinitelyOnMVar

2. All backtraces off

λ. ./Main
Main: thread blocked indefinitely in an MVar operation

Package: ghc-internal
Module: GHC.Internal.IO.Exception
Name: BlockedIndefinitelyOnMVar

3. All backtraces on

λ. ./Main
Main: thread blocked indefinitely in an MVar operation
Cost-centre stack backtrace:
IPE backtrace:
HasCallStack backtrace:
  collectBacktraces, called at libraries/ghc-internal/src/GHC/Internal/Exception.hs:92:13 in ghc-internal:GHC.Internal.Exception
  toExceptionWithBacktrace, called at libraries/ghc-internal/src/GHC/Internal/IO.hs:260:11 in ghc-internal:GHC.Internal.IO
  throwIO, called at Main.hs:40:16 in main:Main

Package: ghc-internal
Module: GHC.Internal.IO.Exception
Name: BlockedIndefinitelyOnMVar

Possible change

Taking inspiration from @michaelpj's suggestion, this could instead look like:

Expand example

1. Default (HasCallStack only)

λ. ./Main
Main: Exception:

thread blocked indefinitely in an MVar operation

Package: ghc-internal
Module: GHC.Internal.IO.Exception
Name: BlockedIndefinitelyOnMVar

HasCallStack backtrace:
  collectBacktraces, called at libraries/ghc-internal/src/GHC/Internal/Exception.hs:92:13 in ghc-internal:GHC.Internal.Exception
  toExceptionWithBacktrace, called at libraries/ghc-internal/src/GHC/Internal/IO.hs:260:11 in ghc-internal:GHC.Internal.IO
  throwIO, called at Main.hs:40:16 in main:Main

2. All backtraces off

λ. ./Main
Main: Exception:

thread blocked indefinitely in an MVar operation

Package: ghc-internal
Module: GHC.Internal.IO.Exception
Name: BlockedIndefinitelyOnMVar

3. All backtraces on

λ. ./Main
Main: Exception:

thread blocked indefinitely in an MVar operation

Package: ghc-internal
Module: GHC.Internal.IO.Exception
Name: BlockedIndefinitelyOnMVar

Cost-centre stack backtrace:
IPE backtrace:
HasCallStack backtrace:
  collectBacktraces, called at libraries/ghc-internal/src/GHC/Internal/Exception.hs:92:13 in ghc-internal:GHC.Internal.Exception
  toExceptionWithBacktrace, called at libraries/ghc-internal/src/GHC/Internal/IO.hs:260:11 in ghc-internal:GHC.Internal.IO
  throwIO, called at Main.hs:40:16 in main:Main

Notice that there is a new line Exception: and the exception type info precedes the possibly backtrace info.

The type info could also be more compact e.g. ghc-internal:GHC.Internal.IO.Exception:BlockedIndefinitelyOnMVar.

Implementation

Moving the exception type info before the backtrace info requires implementing the former in SomeException's displayException, not the default handler, in contrast to the accepted proposal. This seems plausible to me, as I could imagine a user wanting to override the handler (e.g. to log exceptions to a file) without losing the displayed type info.

Draft MR

Thanks!

CC @tomjaguarpaw @bgamari

[adamgundry]

I don't think "Terminated with exception" makes sense in displayException, because it may be called in other contexts. By all means let's add the type information to displayException though. (And perhaps "exception type" is better than "name" because it isn't clear that "name" refers to a type name rather than e.g. a data constructor name.)

We could add "terminated with exception" to the start of the message printed by the default handler, before the exception gets rendered at all, but am I right in thinking that even the default uncaught exception handler won't be followed by termination if the exception occurred on a non-main thread?

[tbidne]

@adamgundry

I don't think "Terminated with exception" makes sense in displayException, because it may be called in other contexts. By all means let's add the type information to displayException though. (And perhaps "exception type" is better than "name" because it isn't clear that "name" refers to a type name rather than e.g. a data constructor name.)

Good point.

We could add "terminated with exception" to the start of the message printed by the default handler, before the exception gets rendered at all, but am I right in thinking that even the default uncaught exception handler won't be followed by termination if the exception occurred on a non-main thread?

Ah good catch, you are right. The following program:

main :: IO ()
main = do
  putStrLn "main: before fork"
  _ <- forkIO throwEx
  putStrLn "main: after fork"

  threadDelay 1_000_000
  putStrLn "after delay"
  where
    throwEx = do
      putStrLn "in throwEx"
      throwIO $
        IOError
          { ioe_handle = Nothing,
            ioe_type = OtherError,
            ioe_location = "throwEx",
            ioe_description = "Some error",
            ioe_errno = Nothing,
            ioe_filename = Nothing
          }

prints:

λ. ./Main
main: before fork
main: after fork
in throwEx
Main: Terminated with exception:

throwEx: failed (Some error)

Package: ghc-internal
Module: GHC.Internal.IO.Exception
Type: IOException

HasCallStack backtrace:
  collectBacktraces, called at libraries/ghc-internal/src/GHC/Internal/Exception.hs:92:13 in ghc-internal:GHC.Internal.Exception
  toExceptionWithBacktrace, called at libraries/ghc-internal/src/GHC/Internal/IO.hs:260:11 in ghc-internal:GHC.Internal.IO
  throwIO, called at Main.hs:44:7 in main:Main


after delay

So probably "Termination" is not a good idea. Perhaps a header like Uncaught exception:, if the consensus is that some header is helpful.

[mixphix]

I agree that "Uncaught exception" has a nicer ring to it, though an "uncaught" exception is one that, by definition, terminates the program, no?

In any case I view this as a positive change. I personally would prefer the name of the exception to be printed before the backtraces, as I find they can sometimes get quite long!

[tbidne]

I agree that "Uncaught exception" has a nicer ring to it, though an "uncaught" exception is one that, by definition, terminates the program, no?

I think it is debatable (directly uncaught by the user vs. the rts), but you raise a good point that this could run up against reasonable intuition. Anticipating all use-cases is tricky!

I agree that moving the type metadata before the stacktraces is the most important part of this change.

As to a potential header in the handler, maybe the least likely to confuse is simply Exception:. This addresses the original comment that the message should mention the word Exception somewhere, which is not otherwise guaranteed unless it shows up in the name of the type or message. The Java example that lists the thread is interesting, and we could do something similar here:

tid <- myThreadId
let msg = "Exception in thread: " ++ show (fromThreadId tid) ++ "\n\n" ++ exMsg

λ. ./Main
Main: Exception in thread: 1

thread blocked indefinitely in an MVar operation

Package: ghc-internal
Module: GHC.Internal.IO.Exception
Type: BlockedIndefinitelyOnMVar

HasCallStack backtrace:
  collectBacktraces, called at libraries/ghc-internal/src/GHC/Internal/Exception.hs:92:13 in ghc-internal:GHC.Internal.Exception
  toExceptionWithBacktrace, called at libraries/ghc-internal/src/GHC/Internal/IO.hs:260:11 in ghc-internal:GHC.Internal.IO
  throwIO, called at Main.hs:37:9 in main:Main

But I don't know how useful that is.

[adamgundry]

Adding the thread ID is an interesting idea, it's potentially useful if one can correlate it with the eventlog or other debugging information. What about using threadLabel to retrieve and display the thread's label, if there is one? I don't know how widely used labelThread is, but printing it in the uncaught exception handler could be motivation to use it.

[parsonsmatt]

Would we want a stack of ThreadId? Consider async exceptions: thrown in one thread, received in another, and potentially bubbling up to main via async and link.

[tbidne]

Adding the thread ID is an interesting idea, it's potentially useful if one can correlate it with the eventlog or other debugging information. What about using threadLabel to retrieve and display the thread's label, if there is one? I don't know how widely used labelThread is, but printing it in the uncaught exception handler could be motivation to use it.

Neat, I didn't know about labels. With something like:

myThreadIdAndLabel :: IO String
myThreadIdAndLabel = do
  tid <- myThreadId
  mLabel <- threadLabel tid
    `catchAny` \_ -> pure (Just "<error retrieving thread label>")

  let idMsg = "id: " ++ showThreadId tid

  pure $ case mLabel of
    Nothing -> idMsg
    Just label -> idMsg ++ ", label: " ++ label

We can have Exception in thread with id: ThreadId 1 or Exception in thread id: ThreadId 1, label: main.

The latter requires adding lines like flip labelThread "main" =<< myThreadId, but it's definitely worth it to me to possibly get a better error message.

Would we want a stack of ThreadId? Consider async exceptions: thrown in one thread, received in another, and potentially bubbling up to main via async and link.

Interesting idea, though I worry about complexity. Do you have an idea for implementation?

Also, I opened a draft MR to make discussion easier.

[tbidne]

I've stumbled upon one downside of the thread ids: non-determinism. 1 of the 130 affected GHC tests failed on CI since it received a different thread id (7) than my local machine (8). On the one hand, that ratio isn't bad, and I think the trade-off is worth it. But this could definitely annoy someone.

A possible mitigation could be to ignore the id when the label exists.

[adamgundry]

Good point about non-determinism. That suggests not adding the thread IDs to the message printed by default IMHO.

https://github.com/haskell/core-libraries-committee/issues/261#issuecomment-1997563277 is a good point. It does seem that "Exception in thread with id: ThreadId 1" may be misleading if the exception occurred in a different thread and was subsequently re-thrown. What about making the thread ID or label into an exception annotation (like a very poor-resolution backtrace)? That would mean capturing it when backtraces are collected, in the thread on which it occurs, rather than in the top-level handler. (Perhaps we might worry that an exception could keep a ThreadId and hence a thread alive when it would otherwise by GCd, though.)

[tbidne]

Okay, I have been convinced that mentioning threads by default is a bad idea.

The annotation idea is interesting. I presume this would involve adding a new instance to ExceptionAnnotation. This is worth exploring, but for now I'd like to table it in this PR, since it is independent of the main thrust of this proposal (move type metadata from handler to SomeException), and could possibly be investigated in some library outside of base (e.g. ghc-experimental or something bespoke).

In light of that, this PR contains two changes:

1. Move type metadata from default handler to SomeException's displayException. IMO the resultant output is clearer, and it means people will still receive type info even if they override the handler.
2. Add Exception: header message to default handler. This isn't as interesting as originally envisioned, but the comments in https://github.com/haskell/core-libraries-committee/issues/261#issuecomment-1993767358 and https://github.com/haskell/core-libraries-committee/issues/261#issuecomment-1994251331 do a good job of showing that coming up with anything more precise (yet not misleading!) is hard. Unless anyone (@michaelpj?) has a better idea here, I'm fine with it as-is.

The MR, then, is up-to-date. The test updates give a good idea of what it looks like.

[Bodigrim]

@tbidne sorry for the wait. Now that GHC 9.10 is released people should have more hands-on experience with backtrace annotations to evaluate the changes.

@adamgundry @michaelpj @bgamari @tomjaguarpaw @mixphix @parsonsmatt are you happy with the proposal now?

[tbidne]

No problem @Bodigrim, thanks for the ping.

---

Just so no one is surprised: CI is almost green, though about a month ago the size_hello_artifact test on fedora started failing:

                        Test Metric         value     New value Change    
--------------------------------------------------------------------------
 size_hello_artifact(normal)   size     1,145,880     2,265,736 +97.7% BAD

My assumption is that this is not relevant to design discussions here (CI was fine for months before this failure came out of nowhere), hence can be resolved on the issue tracker. But I wanted to highlight this issue here (and if anyone has ideas / advice please do comment on the trac; unfortunately I have not been able to make much headway).

[tomjaguarpaw]

Looks good to me

[parsonsmatt]

Looks great to me, thanks for putting this together!

[Bodigrim]

My assumption is that this is not relevant to design discussions here (CI was fine for months before this failure came out of nowhere), hence can be resolved on the issue tracker. But I wanted to highlight this issue here (and if anyone has ideas / advice please do comment on the trac; unfortunately I have not been able to make much headway).

Could it be related to https://gitlab.haskell.org/ghc/ghc/-/issues/24504? Feels like because of additional imports a dependency on Read crawled back again.

[tbidne]

Thanks for the link @Bodigrim, I believe you are correct. The issue has been resolved (the extra imports do not seem necessary anymore).

[Bodigrim]

@tbidne could you please update the top post to bring it in line with the latest proposal as implemented in the MR? (Or is it already up to date?)

[tbidne]

The OP is up to date (I'll update the description to make this more clear).

[Bodigrim]

Unless there are more comments / suggestions, I'll open the vote soon.

[Bodigrim]

Dear CLC members, let's vote on the proposal to modify displayed exception metadata. This is a follow up on #231, which we approved earlier, improving it in two aspects: a) there is a new line Exception: to be clear about the purpose, b) the exception type info precedes backtrace info (which is available since GHC 9.10). Please refer to the examples in the top post, comparing output under "Current proposal" and "Proposed change" sections.

@tomjaguarpaw @parsonsmatt @hasufell @mixphix @angerman @velveteer

---

+1 from me. I'm all for better, more detailed error messages. It has long been a pain point for me to decipher provenance of IO exceptions.

[hasufell]

+1

[tomjaguarpaw]

+1

[parsonsmatt]

+1

[Bodigrim]

@angerman @velveteer @mixphix just a gentle reminder to vote.

[velveteer]

+1

[Bodigrim]

Thanks all, that's enough votes to approve.

[tbidne]

Thanks everyone!