Modify displayed exception type

@michaelpj

Intro

Hello, this is a follow-up to the accepted (unmerged gitlab MR) proposal: #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 / #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

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:33:16 in main:Main

All backtraces off

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

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:33: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

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

All backtraces off

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

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

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

Proposed change

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

Expand example

Default (HasCallStack only)

λ. ./Main
Main: Exception:

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:33:16 in main:Main

All backtraces off

λ. ./Main
Main: Exception:

thread blocked indefinitely in an MVar operation

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

All backtraces on (except DWARF)

λ. ./Main
Main: Exception:

thread blocked indefinitely in an MVar operation

Package: ghc-internal
Module: GHC.Internal.IO.Exception
Type: 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:33: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

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?

@adamgundry

@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.

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!

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.

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.

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.

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.

Update tests

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.

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

#261 (comment) 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.)

Update tests

@michaelpj

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:

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.
Add Exception: header message to default handler. This isn't as interesting as originally envisioned, but the comments in Modify displayed exception type #261 (comment) and Modify displayed exception type #261 (comment) 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.

@tbidne

@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?

Update tests

+1

@angerman

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

+1

Thanks all, that's enough votes to approve.

Update test output for exception CLC proposals

Thanks everyone!

Update test output for exception CLC proposals

Print exception metadata in default handler

Navigation Menu

Repository navigation

Modify displayed exception type #261

Intro

Status quo

Current proposal

Proposed change

Implementation

11 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Modify displayed exception type #261

Description

Intro

Status quo

Current proposal

Proposed change

Implementation

Activity

adamgundry commented on Mar 13, 2024

tbidne commented on Mar 13, 2024

mixphix commented on Mar 13, 2024

tbidne commented on Mar 14, 2024

adamgundry commented on Mar 14, 2024

parsonsmatt commented on Mar 14, 2024

tbidne commented on Mar 15, 2024

tbidne commented on Mar 15, 2024

adamgundry commented on Mar 18, 2024

tbidne commented on Mar 28, 2024

Bodigrim commented on Jun 22, 2024

11 remaining items

tomjaguarpaw commented on Jun 29, 2024

parsonsmatt commented on Jun 29, 2024

Bodigrim commented on Jul 2, 2024

velveteer commented on Jul 2, 2024

Bodigrim commented on Jul 4, 2024

tbidne commented on Jul 5, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions