Bug 214756

Summary: WebKit::setCrashReportApplicationSpecificInformation() should also log to WTFLogAlways()
Product: WebKit Reporter: David Kilzer (:ddkilzer) <ddkilzer>
Component: WebKit2Assignee: David Kilzer (:ddkilzer) <ddkilzer>
Status: RESOLVED FIXED    
Severity: Normal CC: achristensen, cdumez, darin, simon.fraser, webkit-bug-importer
Priority: P2 Keywords: InRadar
Version: Other   
Hardware: Unspecified   
OS: Unspecified   
See Also: https://bugs.webkit.org/show_bug.cgi?id=214713
https://bugs.webkit.org/show_bug.cgi?id=214954
https://bugs.webkit.org/show_bug.cgi?id=215026
Bug Depends on:    
Bug Blocks: 214906    
Attachments:
Description Flags
Patch v1
none
Patch v2
none
Patch v3
darin: review+
Patch for landing none

Description David Kilzer (:ddkilzer) 2020-07-24 12:50:35 PDT
WebKit::setCrashReportApplicationSpecificInformation() should also log to WTFLogAlways().

We should log to WTFLogAlways() since "Application Specific Information" doesn't always appear.

In the long term, we may simply replace WebKit::setCrashReportApplicationSpecificInformation() with WTFLogAlways().
Comment 1 David Kilzer (:ddkilzer) 2020-07-24 12:51:44 PDT
Created attachment 405168 [details]
Patch v1
Comment 2 Radar WebKit Bug Importer 2020-07-24 12:53:57 PDT
<rdar://problem/66069227>
Comment 3 David Kilzer (:ddkilzer) 2020-07-24 14:29:33 PDT
Comment on attachment 405168 [details]
Patch v1

Adding cq+ because all ports compiled, and this only adds logging when crashing, so it can't affect ios-wk2 layout test results.
Comment 4 EWS 2020-07-24 14:32:03 PDT
Committed r264858: <https://trac.webkit.org/changeset/264858>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 405168 [details].
Comment 5 Ryan Haddad 2020-07-24 16:43:00 PDT
Reverted r264858 for reason:

Caused spurious CRASHING TEST logging during layout test runs

Committed r264870: <https://trac.webkit.org/changeset/264870>
Comment 6 David Kilzer (:ddkilzer) 2020-07-24 16:44:21 PDT
Moving to RESOLVED/WONTFIX.  I'll change the way we log in the two methods in Source/WebKit that use CRASH_WITH_INFO() instead.
Comment 7 David Kilzer (:ddkilzer) 2020-07-24 19:13:00 PDT
Actually, I will use this to re-land the patch.  I'm going to clean up the different code paths that are used to set Application Specific Information, too.
Comment 8 Radar WebKit Bug Importer 2020-07-24 19:13:14 PDT
<rdar://problem/66085705>
Comment 9 David Kilzer (:ddkilzer) 2020-07-24 22:20:11 PDT
Created attachment 405222 [details]
Patch v2
Comment 10 David Kilzer (:ddkilzer) 2020-07-24 22:22:08 PDT
Created attachment 405223 [details]
Patch v3
Comment 11 David Kilzer (:ddkilzer) 2020-07-25 07:21:06 PDT
Comment on attachment 405223 [details]
Patch v3

View in context: https://bugs.webkit.org/attachment.cgi?id=405223&action=review

> Source/WebKit/Platform/cocoa/WKCrashReporter.mm:38
> -void setCrashReportApplicationSpecificInformation(CFStringRef infoString)
> +void setCrashReportApplicationSpecificInformation(const char* infoString)
>  {
> -    WTF::setCrashLogMessage([(__bridge NSString *)infoString UTF8String]);
> +    WTFLogAlways("%s", infoString);
> +    WTF::setCrashLogMessage(infoString);
>  }

Thinking about renaming this to WebKit::logAndSetCrashLogMessage().
Comment 12 Darin Adler 2020-07-25 08:57:02 PDT
Comment on attachment 405223 [details]
Patch v3

View in context: https://bugs.webkit.org/attachment.cgi?id=405223&action=review

Change looks fine.

> Source/WebKit/Platform/IPC/cocoa/ConnectionCocoa.mm:276
> +        WebKit::setCrashReportApplicationSpecificInformation([NSString stringWithFormat:@"Unhandled error code %x, message '%s' (%hu)", kr, description(message->messageName()), message->messageName()].UTF8String);

Now that we are trying to make a C string rather than an CFStringRef, we could use WebKit string formatting instead of NSString stuff. It’s easier to use correctly with more type safety. Something like this:

    auto name = message->messageName();
    auto string = makeString("Unhandled error code ", hex(kr, Lowercase) ", message '", description(name), " (", name, ')');
    WebKit::setCrashReportApplicationSpecificInformation(string.utf8().data());

> Source/WebKit/Platform/IPC/cocoa/ConnectionCocoa.mm:493
> +        WebKit::setCrashReportApplicationSpecificInformation([NSString stringWithFormat:@"Unhandled error code %x from mach_msg, receive port is %x", kr, machPort].UTF8String);

auto string = makeString("Unhandled error code ", hex(kr, Lowercase) ", from mach_msg, receive port is ", hex(machPort, Lowercase));
    WebKit::setCrashReportApplicationSpecificInformation(string.utf8().data());

> Source/WebKit/Shared/Cocoa/AuxiliaryProcessCocoa.mm:37
> +    setCrashReportApplicationSpecificInformation([NSString stringWithFormat:@"Received invalid message: '%s' (%hu)", description(messageName), messageName].UTF8String);

auto string = makeString("Received invalid message: '", description(messageName), "' (", messageName, ')');
    WebKit::setCrashReportApplicationSpecificInformation(string.utf8().data());

> Source/WebKit/Shared/EntryPointUtilities/Cocoa/XPCService/XPCServiceMain.mm:159
> +            setCrashReportApplicationSpecificInformation([NSString stringWithFormat:@"WebKit framework version mismatch: %s != %s", webKitBundleVersion.utf8().data(), expectedBundleVersion.utf8().data()].UTF8String);

auto string = makeString("WebKit framework version mismatch: ", webKitBundleVersion, " != ", expectedBundleVersion);
    WebKit::setCrashReportApplicationSpecificInformation(string.utf8().data());

> Tools/WebKitTestRunner/cocoa/CrashReporterInfo.mm:73
>          String message("CRASHING TEST: ");
>          message = message + testPath;

auto message = makeString("CRASHING TEST: ", testPath);
Comment 13 Darin Adler 2020-07-25 09:00:23 PDT
Comment on attachment 405223 [details]
Patch v3

View in context: https://bugs.webkit.org/attachment.cgi?id=405223&action=review

>> Source/WebKit/Platform/IPC/cocoa/ConnectionCocoa.mm:276
>> +        WebKit::setCrashReportApplicationSpecificInformation([NSString stringWithFormat:@"Unhandled error code %x, message '%s' (%hu)", kr, description(message->messageName()), message->messageName()].UTF8String);
> 
> Now that we are trying to make a C string rather than an CFStringRef, we could use WebKit string formatting instead of NSString stuff. It’s easier to use correctly with more type safety. Something like this:
> 
>     auto name = message->messageName();
>     auto string = makeString("Unhandled error code ", hex(kr, Lowercase) ", message '", description(name), " (", name, ')');
>     WebKit::setCrashReportApplicationSpecificInformation(string.utf8().data());

I think I might have left an "0x" out. Also, if we don’t insist on lowercase hex, then we could omit the Lowercase option. Also might have to include the StringConcatenateNumbers.h and HexNumber.h headers.

auto string = makeString("Unhandled error code 0x", hex(kr) ", message '", description(name), " (", name, ')');
Comment 14 Simon Fraser (smfr) 2020-07-25 10:38:34 PDT
Comment on attachment 405223 [details]
Patch v3

View in context: https://bugs.webkit.org/attachment.cgi?id=405223&action=review

> Source/WebKit/Platform/cocoa/WKCrashReporter.mm:36
> +    WTFLogAlways("%s", infoString);

This is called for every test, not just tests that crash, so this will log every time.
Comment 15 David Kilzer (:ddkilzer) 2020-07-27 11:00:14 PDT
Comment on attachment 405223 [details]
Patch v3

View in context: https://bugs.webkit.org/attachment.cgi?id=405223&action=review

>> Source/WebKit/Platform/cocoa/WKCrashReporter.mm:36
>> +    WTFLogAlways("%s", infoString);
> 
> This is called for every test, not just tests that crash, so this will log every time.

Yep, I found that out in Patch v1 when it caused all internal layout test bots to think every test crashed, but (surprisingly!) external layout tests bots did not fail due to this change.

This is no longer an issue as this patch changes DumpRenderTree and WebKitTestRunner to call WTF::setCrashLogMessage() directly now (scroll down to the end of the patch).
Comment 16 Darin Adler 2020-07-27 11:27:58 PDT
Seems to be there are two different possible uses of this function:

1) Calling when you know you are about to intentionally crash.

2) Calling to provide background information about context in case you crash, not knowing a crash will happen.

For (2), the proposed implementation is not right. For (1), it’s fine.
Comment 17 David Kilzer (:ddkilzer) 2020-07-27 15:24:38 PDT
(In reply to Darin Adler from comment #16)
> Seems to be there are two different possible uses of this function:
> 
> 1) Calling when you know you are about to intentionally crash.
> 
> 2) Calling to provide background information about context in case you
> crash, not knowing a crash will happen.
> 
> For (2), the proposed implementation is not right. For (1), it’s fine.

There are no instances of (2) after I changed DumpRenderTree and WebKitTestRunner to call WTF::setCrashLogMessage() directly. See Comment #15.

I'm also renaming setCrashReportApplicationSpecificInformation() to logAndSetCrashLogMessage() as mentioned in Comment #11.
Comment 18 David Kilzer (:ddkilzer) 2020-07-27 15:25:15 PDT
Created attachment 405314 [details]
Patch for landing
Comment 19 Darin Adler 2020-07-27 16:51:16 PDT
Comment on attachment 405314 [details]
Patch for landing

View in context: https://bugs.webkit.org/attachment.cgi?id=405314&action=review

> Source/WebKit/Platform/IPC/cocoa/ConnectionCocoa.mm:278
> +        auto messageNameValue = static_cast<std::underlying_type_t<IPC::MessageName>>(messageName);

Could add support for this to StringConcatenateNumbers.h so we don’t have to cast.

> Source/WebKit/Shared/Cocoa/AuxiliaryProcessCocoa.mm:37
> +    auto messageNameValue = static_cast<std::underlying_type_t<IPC::MessageName>>(messageName);

Ditto.

> Tools/DumpRenderTree/mac/DumpRenderTree.mm:1648
> +static void changeWindowScaleIfNeeded(const char* testPathOrUrl)

How about URL instead of Url?
Comment 20 David Kilzer (:ddkilzer) 2020-07-27 16:59:19 PDT
Comment on attachment 405314 [details]
Patch for landing

Marking cq+ with win bot orange and ios-wk2,mac-debug-wk1 layout tests unfinished because:

- The internal bot failures happened due to always logging from DRT and WKTR, and that code path has been fixed.  Ran accessibility tests internally and they were not all marked as crashing.
- This code path in WebKit2 is only used on crashing or (in one case) on a mach message error code path, which isn't something that is tested by layout tests.
Comment 21 EWS 2020-07-27 17:02:20 PDT
Committed r264957: <https://trac.webkit.org/changeset/264957>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 405314 [details].
Comment 22 David Kilzer (:ddkilzer) 2020-07-27 17:16:41 PDT
Comment on attachment 405314 [details]
Patch for landing

View in context: https://bugs.webkit.org/attachment.cgi?id=405314&action=review

>> Source/WebKit/Platform/IPC/cocoa/ConnectionCocoa.mm:278
>> +        auto messageNameValue = static_cast<std::underlying_type_t<IPC::MessageName>>(messageName);
> 
> Could add support for this to StringConcatenateNumbers.h so we don’t have to cast.

Using std::enable_if_t<std::is_enum<E>::value?  Honestly, I looked at StringConcatenate.h, but it wasn't obvious to me how POD values (like int, unsigned, etc.) were handled by the template code, let alone how to add support for generic enum values.

>> Tools/DumpRenderTree/mac/DumpRenderTree.mm:1648
>> +static void changeWindowScaleIfNeeded(const char* testPathOrUrl)
> 
> How about URL instead of Url?

I was going to use URL instead of Url, but then I felt compelled to change `localPathOrUrl` to match the parameter, and I wasn't even sure if anyone had a strong preference, and I didn't want to ask because it could to turn into bike shedding.

I can fix this as a follow-up if you feel strongly about it.
Comment 23 Darin Adler 2020-07-27 17:38:26 PDT
(In reply to David Kilzer (:ddkilzer) from comment #22)
> Using std::enable_if_t<std::is_enum<E>::value?

Yes.
Comment 24 Darin Adler 2020-07-27 17:40:41 PDT
(In reply to David Kilzer (:ddkilzer) from comment #22)
> I was going to use URL instead of Url, but then I felt compelled to change
> `localPathOrUrl` to match the parameter, and I wasn't even sure if anyone
> had a strong preference, and I didn't want to ask because it could to turn
> into bike shedding.

I think the WebKit coding style document specifically addresses this.
Comment 25 David Kilzer (:ddkilzer) 2020-07-28 08:57:56 PDT
(In reply to Darin Adler from comment #24)
> (In reply to David Kilzer (:ddkilzer) from comment #22)
> > I was going to use URL instead of Url, but then I felt compelled to change
> > `localPathOrUrl` to match the parameter, and I wasn't even sure if anyone
> > had a strong preference, and I didn't want to ask because it could to turn
> > into bike shedding.
> 
> I think the WebKit coding style document specifically addresses this.

It's kind of covered implicitly (when talking about lowercasing acronyms at the start of a variable name), but not explicitly in the middle or end of the variable.

<https://webkit.org/code-style-guidelines/#names>

And check-webkit-style doesn't have a check for it (which would be difficult in the general case, but "URL" is a pretty common acronym used in our variables):

$ ./Tools/Scripts/check-webkit-style Tools/DumpRenderTree/mac/DumpRenderTree.mm
Comment 26 David Kilzer (:ddkilzer) 2020-07-29 08:43:07 PDT
(In reply to David Kilzer (:ddkilzer) from comment #22)
> Comment on attachment 405314 [details]
> Patch for landing
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=405314&action=review
> 
> >> Source/WebKit/Platform/IPC/cocoa/ConnectionCocoa.mm:278
> >> +        auto messageNameValue = static_cast<std::underlying_type_t<IPC::MessageName>>(messageName);
> > 
> > Could add support for this to StringConcatenateNumbers.h so we don’t have to cast.
> 
> Using std::enable_if_t<std::is_enum<E>::value?  Honestly, I looked at
> StringConcatenate.h, but it wasn't obvious to me how POD values (like int,
> unsigned, etc.) were handled by the template code, let alone how to add
> support for generic enum values.

I was missing the existence of Source/WTF/wtf/text/StringConcatenateNumbers.h.

Bug 214906: WTF::makeString() should handle enum values
<https://bugs.webkit.org/show_bug.cgi?id=214906>
Comment 27 Alex Christensen 2020-07-29 09:41:24 PDT
Comment on attachment 405314 [details]
Patch for landing

View in context: https://bugs.webkit.org/attachment.cgi?id=405314&action=review

>>>> Source/WebKit/Platform/IPC/cocoa/ConnectionCocoa.mm:278
>>>> +        auto messageNameValue = static_cast<std::underlying_type_t<IPC::MessageName>>(messageName);
>>> 
>>> Could add support for this to StringConcatenateNumbers.h so we don’t have to cast.
>> 
>> Using std::enable_if_t<std::is_enum<E>::value?  Honestly, I looked at StringConcatenate.h, but it wasn't obvious to me how POD values (like int, unsigned, etc.) were handled by the template code, let alone how to add support for generic enum values.
> 
> I was missing the existence of Source/WTF/wtf/text/StringConcatenateNumbers.h.
> 
> Bug 214906: WTF::makeString() should handle enum values
> <https://bugs.webkit.org/show_bug.cgi?id=214906>

There is a generated function named description(MessageName) for this exact purpose.
Comment 28 Darin Adler 2020-07-29 09:43:30 PDT
(In reply to Alex Christensen from comment #27)
> There is a generated function named description(MessageName) for this exact
> purpose.

I think that's a different purpose, involving the *name* of the message. Formatting an enum as an integer when making a string is distinct, and not specific to IPC messages.
Comment 29 Alex Christensen 2020-07-29 13:29:43 PDT
What benefit does printing the invalid number have?  If we have a valid number, we will get a valid name, otherwise description will return "<invalid message name>" and I'm not sure knowing the number will help anything.
Comment 30 Darin Adler 2020-07-29 13:37:10 PDT
Maybe a good point. Printing the number isn’t new to this patch. Maybe it’s not valuable? I’m generally unclear on how we decided what to log and had assumed the number was valuable.
Comment 31 David Kilzer (:ddkilzer) 2020-07-29 23:23:56 PDT
(In reply to Alex Christensen from comment #29)
> What benefit does printing the invalid number have?  If we have a valid
> number, we will get a valid name, otherwise description will return
> "<invalid message name>" and I'm not sure knowing the number will help
> anything.

In this case, the number is going to both os_log() and to a register via CRASH_WITH_INFO().

So you’re saying there is no value in matching those up, or knowing that a particular generated enum has a given value?  I’d actually find it useful in some cases to know the value of the generated enum without having to rebuild the source to regenerate the value.

Is the only concern that someone might log an enum value thinking they were getting a string description instead?  (Most enums in WebKit aren’t generated, so that isn’t even a common issue.)  What’s the worst that could happen?  They would have to go change their logging statement later to add the text description?

Am I missing some other bad behavior?
Comment 32 Alex Christensen 2020-07-30 10:21:35 PDT
What I'm saying is that the description string is all the information you would need, and it's more useful than an integer value.  The only case where printing an integer would give you more information is if you got an invalid value, but I can't imagine needing to know which invalid value you get.  If it's invalid, something has gone horribly wrong and that's all you need to know.
Comment 33 David Kilzer (:ddkilzer) 2020-07-30 14:10:08 PDT
(In reply to Alex Christensen from comment #32)
> What I'm saying is that the description string is all the information you
> would need, and it's more useful than an integer value.  The only case where
> printing an integer would give you more information is if you got an invalid
> value, but I can't imagine needing to know which invalid value you get.  If
> it's invalid, something has gone horribly wrong and that's all you need to
> know.

What if the value is so horribly wrong that description() returns nothing?  Then I'd want the value, too.
Comment 34 Alex Christensen 2020-07-30 16:13:22 PDT
It will always return a valid value or "<invalid message name>", in which case I don't think there's anything useful to get from the invalid value.
Comment 35 Darin Adler 2020-07-30 17:03:06 PDT
Are you going to force me to find the other cases where we already log numeric values of enums? I believe I know how programmers think: I expect I will find them.

I think your position that this should never be done is an interesting proposal!
Comment 36 David Kilzer (:ddkilzer) 2020-07-31 11:42:05 PDT
(In reply to Alex Christensen from comment #34)
> It will always return a valid value or "<invalid message name>", in which
> case I don't think there's anything useful to get from the invalid value.

Alex, do you only object to logging IPC::MessageName specifically, or all enum values in general?  Because I don't think it's practical to write description() methods for any enum value that someone might want to log in the future.

Also, I disagree that an invalid value is not interesting.

- When debugging an IPC failure, it's only uninteresting until we understand why we got the invalid value in the first place.

- Also, we can't assume every invalid value would be exactly the same if "<invalid message name>" is returned.  We could get a group of invalid values that are different (such as with a memory smasher), and just logging "<invalid message name>" would be nearly useless other than to know that an invalid value was passed.  Conversely, a group of invalid values that are all the same tells us something different is probably happening other than a memory smasher.