Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Modify displayed exception type #261

Open
tbidne opened this issue Mar 13, 2024 · 10 comments
Open

Modify displayed exception type #261

tbidne opened this issue Mar 13, 2024 · 10 comments

Comments

@tbidne
Copy link

tbidne commented Mar 13, 2024

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



  1. All backtraces off
λ. ./Main
Main: thread blocked indefinitely in an MVar operation



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

  1. All backtraces off
λ. ./Main
Main: thread blocked indefinitely in an MVar operation

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

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



  1. All backtraces off
λ. ./Main
Main: Exception:

thread blocked indefinitely in an MVar operation

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


  1. 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
Copy link
Member

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
Copy link
Author

tbidne commented Mar 13, 2024

@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
Copy link
Collaborator

mixphix commented Mar 13, 2024

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
Copy link
Author

tbidne commented Mar 14, 2024

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
Copy link
Member

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
Copy link

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
Copy link
Author

tbidne commented Mar 15, 2024

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 added a commit to tbidne/stm that referenced this issue Mar 15, 2024
tbidne added a commit to tbidne/stm that referenced this issue Mar 15, 2024
@tbidne
Copy link
Author

tbidne commented Mar 15, 2024

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
Copy link
Member

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

tbidne added a commit to tbidne/stm that referenced this issue Mar 24, 2024
@tbidne
Copy link
Author

tbidne commented Mar 28, 2024

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants