Bug 197332 – Add logging of Ad Click Attribution errors and events to a dedicated channel

• Component: WebKit Misc.
• Status: RESOLVED FIXED

[John Wilander]

We should add dedicated logging for Ad Click Attribution.

[John Wilander]

<rdar://problem/49918800>

[John Wilander]

Created attachment 368365 [details]
WiP-feedback-welcome

[John Wilander]

Comment on attachment 368365 [details]
WiP-feedback-welcome

Not ready for formal review yet, but I'd like some feedback and help.

I'm trying to pipe my log messages in WebKit::AdClickAttributionManager to show up in Web Inspector, similar to how the developer can enable WebRTC logging. Something is wrong. I get the syslog output but nothing in Web Inspector. :/

[EWS Watchlist]

This patch modifies the inspector protocol generator. Please ensure that you have rebaselined any generator test results (i.e., by running `Tools/Scripts/run-inspector-generator-tests --reset-results`)

This patch modifies the inspector protocol. Please ensure that any frontend changes appropriately use feature checks for new protocol features.

[EWS Watchlist]

Comment on attachment 368365 [details]
WiP-feedback-welcome

Attachment 368365 [details] did not pass mac-ews (mac):
Output: https://webkit-queues.webkit.org/results/12010738

New failing tests:
inspector/console/webcore-logging.html

[EWS Watchlist]

Created attachment 368371 [details]
Archive of layout-test-results from ews102 for mac-highsierra

The attached test failures were seen while running run-webkit-tests on the mac-ews.
Bot: ews102  Port: mac-highsierra  Platform: Mac OS X 10.13.6

[EWS Watchlist]

Comment on attachment 368365 [details]
WiP-feedback-welcome

Attachment 368365 [details] did not pass mac-wk2-ews (mac-wk2):
Output: https://webkit-queues.webkit.org/results/12010814

New failing tests:
inspector/console/webcore-logging.html

[EWS Watchlist]

Created attachment 368375 [details]
Archive of layout-test-results from ews106 for mac-highsierra-wk2

The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews.
Bot: ews106  Port: mac-highsierra-wk2  Platform: Mac OS X 10.13.6

[EWS Watchlist]

Comment on attachment 368365 [details]
WiP-feedback-welcome

Attachment 368365 [details] did not pass mac-debug-ews (mac):
Output: https://webkit-queues.webkit.org/results/12012154

Number of test failures exceeded the failure limit.

[EWS Watchlist]

Created attachment 368386 [details]
Archive of layout-test-results from ews117 for mac-highsierra

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews117  Port: mac-highsierra  Platform: Mac OS X 10.13.6

[John Wilander]

Created attachment 368509 [details]
Patch

[Chris Dumez]

Comment on attachment 368509 [details]
Patch

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

> Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:54
> +#if !RELEASE_LOG_DISABLED

We should not have to do this at call sites. I think the only reason you need to is because the person who added RELEASE_LOG_INFO_IF() forgot to add a dummy implementation for when #if RELEASE_LOG_DISABLED in Assertions.h. Please fix this so that call sites do not have to look so ugly.

> Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:76
> +    auto conversionData = conversion.data;

auto& to avoid copying?

> Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:77
> +    auto conversionPriority = conversion.priority;

ditto.

> Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:177
> +#if !RELEASE_LOG_DISABLED

I would feel a lot safer if the lambda checked weakThis right away and returned early:
if (!weakThis)
    return;

Otherwise, somebody might add code at the end of your lambda and fail to check weakThis.

> Source/WebKit/Shared/WebPreferences.yaml:1421
> +    category: experimental

Shouldn't this be internal?

[Eric Carlson]

Comment on attachment 368509 [details]
Patch

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

> Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:243
> +            RELEASE_LOG_INFO_IF(weakThis && debugModeEnabled(), AdClickAttribution, "Removing expired ad click from source: %{public}s to destination: %{public}s.", keyAndValue.value.source().registrableDomain.string().utf8().data(), keyAndValue.value.destination().registrableDomain.string().utf8().data());

Ditto.

[youenn fablet]

Comment on attachment 368509 [details]
Patch

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

> Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:69
> +    if (!conversion.isValid()) {

Shouldn't this logging be done in AdClickAttribution::parseConversionRequest or at its call site so that it is done at the time of conversion and with potentially more information about the failure?

> Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:201
> +        if (*earliestTimeToSend <= now || m_isRunningTest || debugModeEnabled()) {

So debugMode will wait 60 seconds and test runner willl wait 0 seconds.
Should we merge both and use 0 seconds for both cases?
If this is targeted at web developer, 60 seconds might be long to wait.

> Source/WebKit/NetworkProcess/AdClickAttributionManager.h:50
> +    AdClickAttributionManager(PAL::SessionID sessionID)

explicit.

> Source/WebKit/NetworkProcess/NetworkProcess.cpp:309
> +    WebCore::RuntimeEnabledFeatures::sharedFeatures().setAdClickAttributionDebugModeEnabled(parameters.enableAdClickAttributionDebugMode);

If this is an experimental feature, user will have to relaunch the whole application so that the network process gets the new value.
Is this good enough?

[John Wilander]

(In reply to Chris Dumez from comment #12)
> Comment on attachment 368509 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=368509&action=review
> 
> > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:54
> > +#if !RELEASE_LOG_DISABLED
> 
> We should not have to do this at call sites. I think the only reason you
> need to is because the person who added RELEASE_LOG_INFO_IF() forgot to add
> a dummy implementation for when #if RELEASE_LOG_DISABLED in Assertions.h.
> Please fix this so that call sites do not have to look so ugly.

Got it. Yes, it does look ugly.

> > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:76
> > +    auto conversionData = conversion.data;
> 
> auto& to avoid copying?

Will fix.

> > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:77
> > +    auto conversionPriority = conversion.priority;
> 
> ditto.

Will fix.

> > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:177
> > +#if !RELEASE_LOG_DISABLED
> 
> I would feel a lot safer if the lambda checked weakThis right away and
> returned early:
> if (!weakThis)
>     return;

Agreed.

> Otherwise, somebody might add code at the end of your lambda and fail to
> check weakThis.
> 
> > Source/WebKit/Shared/WebPreferences.yaml:1421
> > +    category: experimental
> 
> Shouldn't this be internal?

Actually not. This is intended for developers too since they'll want debug info and a quicker turnaround than 24-48 hours to check whether they got it right or not. :)

Thanks, Chris!

[John Wilander]

(In reply to Eric Carlson from comment #13)
> Comment on attachment 368509 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=368509&action=review
> 
> > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:243
> > +            RELEASE_LOG_INFO_IF(weakThis && debugModeEnabled(), AdClickAttribution, "Removing expired ad click from source: %{public}s to destination: %{public}s.", keyAndValue.value.source().registrableDomain.string().utf8().data(), keyAndValue.value.destination().registrableDomain.string().utf8().data());
> 
> Ditto.

I assume you mean the early weakThis check. Will fix.

Thanks, Eric!

[John Wilander]

(In reply to youenn fablet from comment #14)
> Comment on attachment 368509 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=368509&action=review
> 
> > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:69
> > +    if (!conversion.isValid()) {
> 
> Shouldn't this logging be done in AdClickAttribution::parseConversionRequest
> or at its call site so that it is done at the time of conversion and with
> potentially more information about the failure?

I considered that but it'll use a different log channel, declared in WebCore. Maybe that's not an issue.

> > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:201
> > +        if (*earliestTimeToSend <= now || m_isRunningTest || debugModeEnabled()) {
> 
> So debugMode will wait 60 seconds and test runner willl wait 0 seconds.
> Should we merge both and use 0 seconds for both cases?
> If this is targeted at web developer, 60 seconds might be long to wait.

60 seconds might be long but there needs to be a significant delay in debug mode. Conversion events can have priorities and replace earlier conversions. To be able to test that on your site, you need to be able to covert multiple times before the request is sent out.

In layout tests we want zero delay.

> > Source/WebKit/NetworkProcess/AdClickAttributionManager.h:50
> > +    AdClickAttributionManager(PAL::SessionID sessionID)
> 
> explicit.

Got it.

> > Source/WebKit/NetworkProcess/NetworkProcess.cpp:309
> > +    WebCore::RuntimeEnabledFeatures::sharedFeatures().setAdClickAttributionDebugModeEnabled(parameters.enableAdClickAttributionDebugMode);
> 
> If this is an experimental feature, user will have to relaunch the whole
> application so that the network process gets the new value.
> Is this good enough?

For now, I think so. I still want this to go into the Web Inspector. So hopefully I can find time to do the plumbing or can convince the Inspector team to set up some generic plumbing.

Thanks, Youenn!

[John Wilander]

(In reply to John Wilander from comment #15)
> (In reply to Chris Dumez from comment #12)
> > Comment on attachment 368509 [details]
> > Patch
> > 
> > View in context:
> > https://bugs.webkit.org/attachment.cgi?id=368509&action=review
> > 
> > > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:54
> > > +#if !RELEASE_LOG_DISABLED
> > 
> > We should not have to do this at call sites. I think the only reason you
> > need to is because the person who added RELEASE_LOG_INFO_IF() forgot to add
> > a dummy implementation for when #if RELEASE_LOG_DISABLED in Assertions.h.
> > Please fix this so that call sites do not have to look so ugly.
> 
> Got it. Yes, it does look ugly.

Assertions.h has this:

/* RELEASE_LOG */

#if RELEASE_LOG_DISABLED
…
#define RELEASE_LOG_IF(isAllowed, channel, ...) ((void)0)


> > > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:76
> > > +    auto conversionData = conversion.data;
> > 
> > auto& to avoid copying?
> 
> Will fix.
> 
> > > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:77
> > > +    auto conversionPriority = conversion.priority;
> > 
> > ditto.
> 
> Will fix.
> 
> > > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:177
> > > +#if !RELEASE_LOG_DISABLED
> > 
> > I would feel a lot safer if the lambda checked weakThis right away and
> > returned early:
> > if (!weakThis)
> >     return;
> 
> Agreed.
> 
> > Otherwise, somebody might add code at the end of your lambda and fail to
> > check weakThis.
> > 
> > > Source/WebKit/Shared/WebPreferences.yaml:1421
> > > +    category: experimental
> > 
> > Shouldn't this be internal?
> 
> Actually not. This is intended for developers too since they'll want debug
> info and a quicker turnaround than 24-48 hours to check whether they got it
> right or not. :)
> 
> Thanks, Chris!

[Chris Dumez]

(In reply to John Wilander from comment #18)
> (In reply to John Wilander from comment #15)
> > (In reply to Chris Dumez from comment #12)
> > > Comment on attachment 368509 [details]
> > > Patch
> > > 
> > > View in context:
> > > https://bugs.webkit.org/attachment.cgi?id=368509&action=review
> > > 
> > > > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:54
> > > > +#if !RELEASE_LOG_DISABLED
> > > 
> > > We should not have to do this at call sites. I think the only reason you
> > > need to is because the person who added RELEASE_LOG_INFO_IF() forgot to add
> > > a dummy implementation for when #if RELEASE_LOG_DISABLED in Assertions.h.
> > > Please fix this so that call sites do not have to look so ugly.
> > 
> > Got it. Yes, it does look ugly.
> 
> Assertions.h has this:
> 
> /* RELEASE_LOG */
> 
> #if RELEASE_LOG_DISABLED
> …
> #define RELEASE_LOG_IF(isAllowed, channel, ...) ((void)0)

Well I know but it is missing the dummy implementation for RELEASE_LOG_INFO_IF. Please fix.

[John Wilander]

Created attachment 368576 [details]
Patch

[John Wilander]

Created attachment 368585 [details]
Patch

[John Wilander]

Fix for the WPE build.

[John Wilander]

Created attachment 368588 [details]
Patch

[John Wilander]

Another WPE fix.

[John Wilander]

Created attachment 368589 [details]
Patch

[John Wilander]

A third WPE fix. :/

[youenn fablet]

Comment on attachment 368589 [details]
Patch

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

> Source/WebCore/loader/AdClickAttribution.cpp:62
> +        RELEASE_LOG_INFO_IF(debugModeEnabled(), AdClickAttribution, "Conversion was not accepted because the URL path: %{public}s did not start with %{public}s.", path.utf8().data(), adClickAttributionPathPrefix);

I know this is debug mode only, but do we want to enable logging the URLs there and below?

> Source/WebCore/loader/AdClickAttribution.cpp:70
> +            RELEASE_LOG_INFO_IF(debugModeEnabled(), AdClickAttribution, "Conversion was not accepted because the conversion data could not be parsed or was higher than the allowed maximum of %{public}u.", MaxEntropy);

Probably do not need %{public} here and below.

> Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:67
> +        RELEASE_LOG_INFO_IF(debugModeEnabled(), AdClickAttribution, "Conversion was not accepted because the HTTP redirect from: %{public}s to: %{public}s was not same-site.", redirectDomain.string().utf8().data(), requestURL.string().utf8().data());

Since this is an error case, it should probably be RELEASE_LOG_ERROR_IF
Might be applicable elsewhere.

> Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:-139
> -        UNUSED_PARAM(error);

You might want to keep it in case of compiling without release logging.

[John Wilander]

(In reply to youenn fablet from comment #27)
> Comment on attachment 368589 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=368589&action=review
> 
> > Source/WebCore/loader/AdClickAttribution.cpp:62
> > +        RELEASE_LOG_INFO_IF(debugModeEnabled(), AdClickAttribution, "Conversion was not accepted because the URL path: %{public}s did not start with %{public}s.", path.utf8().data(), adClickAttributionPathPrefix);
> 
> I know this is debug mode only, but do we want to enable logging the URLs
> there and below?

Do you mean log the full URL too?

> > Source/WebCore/loader/AdClickAttribution.cpp:70
> > +            RELEASE_LOG_INFO_IF(debugModeEnabled(), AdClickAttribution, "Conversion was not accepted because the conversion data could not be parsed or was higher than the allowed maximum of %{public}u.", MaxEntropy);
> 
> Probably do not need %{public} here and below.

Oh, I thought we needed that for any conversion specifiers.

> > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:67
> > +        RELEASE_LOG_INFO_IF(debugModeEnabled(), AdClickAttribution, "Conversion was not accepted because the HTTP redirect from: %{public}s to: %{public}s was not same-site.", redirectDomain.string().utf8().data(), requestURL.string().utf8().data());
> 
> Since this is an error case, it should probably be RELEASE_LOG_ERROR_IF
> Might be applicable elsewhere.

The reason why I stick with INFO is to make sure these log statements are never persisted. If we wanted to have an ERROR log statement, it would have to be without URL information.

> > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:-139
> > -        UNUSED_PARAM(error);
> 
> You might want to keep it in case of compiling without release logging.

OK.

Anything else?

[youenn fablet]

(In reply to John Wilander from comment #28)
> (In reply to youenn fablet from comment #27)
> > Comment on attachment 368589 [details]
> > Patch
> > 
> > View in context:
> > https://bugs.webkit.org/attachment.cgi?id=368589&action=review
> > 
> > > Source/WebCore/loader/AdClickAttribution.cpp:62
> > > +        RELEASE_LOG_INFO_IF(debugModeEnabled(), AdClickAttribution, "Conversion was not accepted because the URL path: %{public}s did not start with %{public}s.", path.utf8().data(), adClickAttributionPathPrefix);
> > 
> > I know this is debug mode only, but do we want to enable logging the URLs
> > there and below?
> 
> Do you mean log the full URL too?

Usually, we do not log full URLs.
I know this is optional logging so maybe that is fine.
It would feel better if this logging would go to the web inspector but not the console. 
 
> > > Source/WebCore/loader/AdClickAttribution.cpp:70
> > > +            RELEASE_LOG_INFO_IF(debugModeEnabled(), AdClickAttribution, "Conversion was not accepted because the conversion data could not be parsed or was higher than the allowed maximum of %{public}u.", MaxEntropy);
> > 
> > Probably do not need %{public} here and below.
> 
> Oh, I thought we needed that for any conversion specifiers.
> 
> > > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:67
> > > +        RELEASE_LOG_INFO_IF(debugModeEnabled(), AdClickAttribution, "Conversion was not accepted because the HTTP redirect from: %{public}s to: %{public}s was not same-site.", redirectDomain.string().utf8().data(), requestURL.string().utf8().data());
> > 
> > Since this is an error case, it should probably be RELEASE_LOG_ERROR_IF
> > Might be applicable elsewhere.
> 
> The reason why I stick with INFO is to make sure these log statements are
> never persisted. If we wanted to have an ERROR log statement, it would have
> to be without URL information.

I am not sure info/error are that of a difference here since you use debugModeEnabled().
In any case, having in a default release log that a conversion did not go through is good to have.
I would add such logging without logging the URL.

An alternative might be to log an identifier of the corresponding ad click attribution (or just a pointer) so that URL logging does not happen in various places, but potentially just in one place and off by default.

Then you could use info/error appropriately.

> > > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:-139
> > > -        UNUSED_PARAM(error);
> > 
> > You might want to keep it in case of compiling without release logging.
> 
> OK.
> 
> Anything else?

[John Wilander]

(In reply to youenn fablet from comment #29)
> (In reply to John Wilander from comment #28)
> > (In reply to youenn fablet from comment #27)
> > > Comment on attachment 368589 [details]
> > > Patch
> > > 
> > > View in context:
> > > https://bugs.webkit.org/attachment.cgi?id=368589&action=review
> > > 
> > > > Source/WebCore/loader/AdClickAttribution.cpp:62
> > > > +        RELEASE_LOG_INFO_IF(debugModeEnabled(), AdClickAttribution, "Conversion was not accepted because the URL path: %{public}s did not start with %{public}s.", path.utf8().data(), adClickAttributionPathPrefix);
> > > 
> > > I know this is debug mode only, but do we want to enable logging the URLs
> > > there and below?
> > 
> > Do you mean log the full URL too?
> 
> Usually, we do not log full URLs.
> I know this is optional logging so maybe that is fine.
> It would feel better if this logging would go to the web inspector but not
> the console.

Oh, I'm very well aware of our policy to not log URLs. That's why this only happens if the user enables the Develop menu and opts in, and the log statements are always ephemeral which means that they only stay in the memory ring buffer for a little while.

My original patch tried to log through the Web Inspector but it turned out to be a major effort to get that working. My code resides in the network process which has no direct connection to Web Inspector. The inspector is tied to a webpage which isn't really a thing for some of my logging, especially the ping load that's unrelated to any page and uses its own NSURLSession.

> > > > Source/WebCore/loader/AdClickAttribution.cpp:70
> > > > +            RELEASE_LOG_INFO_IF(debugModeEnabled(), AdClickAttribution, "Conversion was not accepted because the conversion data could not be parsed or was higher than the allowed maximum of %{public}u.", MaxEntropy);
> > > 
> > > Probably do not need %{public} here and below.
> > 
> > Oh, I thought we needed that for any conversion specifiers.
> > 
> > > > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:67
> > > > +        RELEASE_LOG_INFO_IF(debugModeEnabled(), AdClickAttribution, "Conversion was not accepted because the HTTP redirect from: %{public}s to: %{public}s was not same-site.", redirectDomain.string().utf8().data(), requestURL.string().utf8().data());
> > > 
> > > Since this is an error case, it should probably be RELEASE_LOG_ERROR_IF
> > > Might be applicable elsewhere.
> > 
> > The reason why I stick with INFO is to make sure these log statements are
> > never persisted. If we wanted to have an ERROR log statement, it would have
> > to be without URL information.
> 
> I am not sure info/error are that of a difference here since you use
> debugModeEnabled().

INFO level logs go to the in-memory ring buffer and not to persistent storage.

> In any case, having in a default release log that a conversion did not go
> through is good to have.
> I would add such logging without logging the URL.

I can add an extra ERROR log call without URL info.

> An alternative might be to log an identifier of the corresponding ad click
> attribution (or just a pointer) so that URL logging does not happen in
> various places, but potentially just in one place and off by default.
> 
> Then you could use info/error appropriately.
> 
> > > > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:-139
> > > > -        UNUSED_PARAM(error);
> > > 
> > > You might want to keep it in case of compiling without release logging.
> > 
> > OK.
> > 
> > Anything else?

[youenn fablet]

Comment on attachment 368589 [details]
Patch

I would tend for now to not log the URLs since in most cases except clearExpired, there is an ongoing load that a web developer can see that should relate to the ad clicks.

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

> Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:95
> +    auto& conversionPriority = conversion.priority;

Why not inlining these in below RELEASE_LOG_INFO_IF.

[John Wilander]

(In reply to youenn fablet from comment #31)
> Comment on attachment 368589 [details]
> Patch
> 
> I would tend for now to not log the URLs since in most cases except
> clearExpired, there is an ongoing load that a web developer can see that
> should relate to the ad clicks.

OK, I'll land without any URLs in the log statements for now.

> View in context:
> https://bugs.webkit.org/attachment.cgi?id=368589&action=review
> 
> > Source/WebKit/NetworkProcess/AdClickAttributionManager.cpp:95
> > +    auto& conversionPriority = conversion.priority;
> 
> Why not inlining these in below RELEASE_LOG_INFO_IF.

It's because I use those variables in log calls after I've moved the Conversion object.

Thanks for the review, Youenn!

[John Wilander]

Created attachment 368645 [details]
Patch for landing

[WebKit Commit Bot]

Comment on attachment 368645 [details]
Patch for landing

Clearing flags on attachment: 368645

Committed r244818: <https://trac.webkit.org/changeset/244818>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.