Opened 5 years ago

Closed 5 years ago

Last modified 5 years ago

#9395 closed bug (fixed)

Debug.Trace should not use %s for format string

Reported by: ezyang Owned by: ezyang
Priority: normal Milestone:
Component: Core Libraries Version: 7.8.2
Keywords: Cc: hvr, ekmett, core-libraries-committee@…
Operating System: Unknown/Multiple Architecture: Unknown/Multiple
Type of failure: Incorrect result at runtime Test Case:
Blocked By: Blocking:
Related Tickets: Differential Rev(s):
Wiki Page:

Description

The current implementation of traceIO in Debug.Trace is as follows:

traceIO :: String -> IO ()
traceIO msg = do
    withCString "%s\n" $ \cfmt ->
     withCString msg  $ \cmsg ->
      debugBelch cfmt cmsg

This is bad news: it means if the String has a null in it, the string will be silently truncated. For example, in GHC, this means that you cannot pretty-print FastString uniques, since the default printing algorithm often results in a null.

Probably the proper thing to do here is to also pass a length indicator for the CString. We should also fix unique pretty-printing to never generate nulls. A good test case would be:

main = trace "\0foo" (return ())

which should have non-empty output.

Change History (7)

comment:1 Changed 5 years ago by ezyang

Owner: set to ezyang

comment:2 Changed 5 years ago by ezyang

OK, it's a little trickier than just specifying a new format string; I forgot that

#include "stdio.h"
int main() {
    printf("%.*s", 4, "AA\0B");
    return 0;
}

only outputs AA, even with the length description. So we can't use debugBelch. This raises the question, why are we using debugBelch at all? Some archaeology later:

[project @ 2005-01-28 23:33:57 by krasimir]
- The output from uncaught exceptions handler is redirected to RTS's errorBelch.
- The output from Debug.Trace is redirected to RTS's debugBelch
- Usually errorBelch and debugBelch messages go to stderr except for
Windows GUI applications. For GUI applications the Debug.Trace output is
redirected to debug console and the exceptions message is displayed in message box.

It also seems like a good idea generally to bypass Haskell-lands buffering. Unfortunately, printf style output is a hard-coded assumption for RtsMsgFunction, so we can't easily swap it out without introducing another function for raw output.

Maybe, alternately, Debug.Trace should munge out null bytes?

comment:3 Changed 5 years ago by Edward Z. Yang <ezyang@…>

In d360d440b994c03d645603c50f25ef208700db02/ghc:

Filter out null bytes from trace, and warn accordingly, fixing #9395.

Summary:
Previously, if you ran trace "foo\0bar", the output was truncated so
that everything after the null byte was omitted.  This was terrible.
Now we filter out null bytes, and emit an extra trace saying that
null bytes were filtered out.

NB: we CANNOT fix debugBelch, because all printf variants *always*
respect null bytes, even if you're using string precision such as
%.*s.  The alternative would have been to introduce a new function
debugRawBelch which did not use format strings and took an explicit
string length, but I decided we generally should avoid putting null
bytes in our trace messages, and warn the user.

Signed-off-by: Edward Z. Yang <ezyang@cs.stanford.edu>

Test Plan: validate

Reviewers: hvr, austin

Subscribers: simonmar, relrod, ezyang, carter

Differential Revision: https://phabricator.haskell.org/D121

GHC Trac Issues: #9395

comment:4 Changed 5 years ago by ezyang

Status: newmerge

comment:5 Changed 5 years ago by thoughtpolice

Component: libraries/baseCore Libraries

Moving over to new owning component 'Core Libraries'.

comment:6 Changed 5 years ago by thoughtpolice

Cc: core-libraries-committee@… added
Resolution: fixed
Status: mergeclosed

Merged to ghc-7.8.

comment:7 Changed 5 years ago by Austin Seipp <austin@…>

In a82364c9410d35fa9cb5031d553212267c3628c5/ghc:

Don't truncate traceEvents to 512 bytes (#8309)

Summary:
Don't call postLogMsg to post a user msg, because it truncates messages to
512 bytes.

Rename traceCap_stderr and trace_stderr to vtraceCap_stderr and trace_stderr,
to signal that they take a va_list (similar to vdebugBelch vs debugBelch).

See #3874 for the original reason behind traceFormatUserMsg.

See the commit msg in #9395 (d360d440) for a discussion about using
null-terminated strings vs strings with an explicit length.

Test Plan:
Run `cabal install ghc-events` and inspect the result of `ghc-events show` on
an eventlog file created with `ghc -eventlog Test.hs` and `./Test +RTS -l`,
where Test.hs contains:

```
import Debug.Trace
main = traceEvent (replicate 510 'a' ++ "bcd") $ return ()
```

Depends on D655.

Reviewers: austin

Reviewed By: austin

Subscribers: thomie

Differential Revision: https://phabricator.haskell.org/D656

GHC Trac Issues: #8309
Note: See TracTickets for help on using tickets.