Summary: | Add logging of Ad Click Attribution errors and events to a dedicated channel | ||||||||||||||||||||||||
---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
Product: | WebKit | Reporter: | John Wilander <wilander> | ||||||||||||||||||||||
Component: | WebKit Misc. | Assignee: | John Wilander <wilander> | ||||||||||||||||||||||
Status: | RESOLVED FIXED | ||||||||||||||||||||||||
Severity: | Normal | CC: | bburg, benjamin, cdumez, cmarcelo, commit-queue, dbates, eric.carlson, esprehn+autocc, ews-watchlist, gyuyoung.kim, hi, japhet, joepeck, kangil.han, keith_miller, mark.lam, msaboff, rniwa, saam, youennf | ||||||||||||||||||||||
Priority: | P2 | Keywords: | InRadar | ||||||||||||||||||||||
Version: | WebKit Nightly Build | ||||||||||||||||||||||||
Hardware: | Unspecified | ||||||||||||||||||||||||
OS: | Unspecified | ||||||||||||||||||||||||
Attachments: |
|
Description
John Wilander
2019-04-26 16:42:24 PDT
Created attachment 368365 [details]
WiP-feedback-welcome
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. :/
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. 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 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
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 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
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. 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
Created attachment 368509 [details]
Patch
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? 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. 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? (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! (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! (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! (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! (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. Created attachment 368576 [details]
Patch
Created attachment 368585 [details]
Patch
Fix for the WPE build. Created attachment 368588 [details]
Patch
Another WPE fix. Created attachment 368589 [details]
Patch
A third WPE fix. :/ 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. (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? (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? (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? 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. (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! Created attachment 368645 [details]
Patch for landing
Comment on attachment 368645 [details] Patch for landing Clearing flags on attachment: 368645 Committed r244818: <https://trac.webkit.org/changeset/244818> All reviewed patches have been landed. Closing bug. |