Bug 182456 - Add logging to CacheStorageEngineConnection
Summary: Add logging to CacheStorageEngineConnection
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: Service Workers (show other bugs)
Version: WebKit Nightly Build
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: youenn fablet
URL:
Keywords: InRadar
Depends on:
Blocks:
 
Reported: 2018-02-02 19:31 PST by youenn fablet
Modified: 2018-02-06 09:39 PST (History)
8 users (show)

See Also:


Attachments
Patch (8.22 KB, patch)
2018-02-02 19:35 PST, youenn fablet
no flags Details | Formatted Diff | Diff
Patch (8.37 KB, patch)
2018-02-03 18:35 PST, youenn fablet
no flags Details | Formatted Diff | Diff
Patch (8.35 KB, patch)
2018-02-05 09:43 PST, youenn fablet
no flags Details | Formatted Diff | Diff
Archive of layout-test-results from ews114 for mac-sierra (2.92 MB, application/zip)
2018-02-05 11:13 PST, EWS Watchlist
no flags Details
Patch (8.38 KB, patch)
2018-02-05 11:33 PST, youenn fablet
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description youenn fablet 2018-02-02 19:31:40 PST
To help debugging
Comment 1 Radar WebKit Bug Importer 2018-02-02 19:32:35 PST
<rdar://problem/37181006>
Comment 2 youenn fablet 2018-02-02 19:35:34 PST
Created attachment 333025 [details]
Patch
Comment 3 Chris Dumez 2018-02-03 14:34:51 PST
Comment on attachment 333025 [details]
Patch

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

> Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:41
> +#define RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(sessionID.isAlwaysOnLoggingAllowed(), CacheStorage, "%p - CacheStorageEngineConnection::" fmt, &m_connection.connection(), ##__VA_ARGS__)

Same comment for all your logging below:
- You do not need \n at the end
- The logging normally start with the method name, which is why this macro starts with "ClassName::".

On a side note, you may want a RELEASE_LOG_ERROR_IF_ALLOWED_IN_CALLBACK() that uses RELEASE_LOG_ERROR_IF(). You'd call it in case of error. It would make errors a lot of visible in your logs. Otherwise, all debug logging has same priority and you have to search for "success is 0".

> Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:62
> +    RELEASE_LOG_IF_ALLOWED("Request %llu to open cache\n", requestIdentifier);

You don't need \n at the end of all you logging.

> Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:64
> +        RELEASE_LOG_IF_ALLOWED_IN_CALLBACK("Finish removing cache request %llu, success is %d and cache identifier is %llu\n", requestIdentifier, result.has_value(), result.has_value() ? result.value().identifier : 0);

result.value_or(0) ?

Also Finish -> Finished ?

Also, why is this talking about removing. The method says "open".

> Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:74
> +        RELEASE_LOG_IF_ALLOWED_IN_CALLBACK("Finish removing cache request %llu, success is %d\n", requestIdentifier, result.has_value());

Finish -> Finished ?

Same comment in various places below.

> Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:83
> +        RELEASE_LOG_IF_ALLOWED_IN_CALLBACK("Finish getting caches request %llu, success is %d, caches size is %lu\n", requestIdentifier, result.has_value(), result.has_value() ? result.value().infos.size() : 0);

value_or()

> Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:92
> +        RELEASE_LOG_IF_ALLOWED_IN_CALLBACK("Finish getting records request %llu, success is %d, records size is %lu\n", requestIdentifier, result.has_value(), result.has_value() ? result.value().size() : 0);

value_or()
Comment 4 youenn fablet 2018-02-03 18:35:39 PST
Created attachment 333040 [details]
Patch
Comment 5 Chris Dumez 2018-02-04 13:13:06 PST
Comment on attachment 333040 [details]
Patch

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

> Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:43
> +#define RELEASE_LOG_FUNCTION_IF_ALLOWED_IN_CALLBACK(functionName, fmt, ...) \

Having a macro that relies on result.has_value() to do regular or error logging seems fine. I don't like that these macros take 2 string parameters though.

> Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:67
> +    RELEASE_LOG_FUNCTION_IF_ALLOWED("open", "");

Not sure I understand why these macros take several string parameters now. In any event, this looks pretty different from our usual release logging and I think it would be nice to be consistent.
Seems like this would not look worse with a simple RELEASE_LOG_IF_ALLOWED, would it?

> Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:69
> +        RELEASE_LOG_FUNCTION_IF_ALLOWED_IN_CALLBACK("open", "cache identifier  %llu", result.has_value() ? result.value().identifier : 0);

Why didn't you use value_or() here and below ? doesn't it work?
Comment 6 youenn fablet 2018-02-04 17:29:21 PST
(In reply to Chris Dumez from comment #5)
> Comment on attachment 333040 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=333040&action=review
> 
> > Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:43
> > +#define RELEASE_LOG_FUNCTION_IF_ALLOWED_IN_CALLBACK(functionName, fmt, ...) \
> 
> Having a macro that relies on result.has_value() to do regular or error
> logging seems fine. I don't like that these macros take 2 string parameters
> though.

It takes two strings so that the error message prints the function name and then a specific error code while the success message prints the function name and the second string to have a dedicated success message with some state.

> > Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:67
> > +    RELEASE_LOG_FUNCTION_IF_ALLOWED("open", "");
> 
> Not sure I understand why these macros take several string parameters now.
> In any event, this looks pretty different from our usual release logging and
> I think it would be nice to be consistent.
> Seems like this would not look worse with a simple RELEASE_LOG_IF_ALLOWED,
> would it?

RELEASE_LOG_FUNCTION_IF_ALLOWED is ensuring consistency with RELEASE_LOG_FUNCTION_IF_ALLOWED_IN_CALLBACK messages hence the current patch.

Replacing it would end up writing something like:
RELEASE_LOG_IF_ALLOWED("open (%llu)", requestIdentifier);
which is fine too.

> > Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:69
> > +        RELEASE_LOG_FUNCTION_IF_ALLOWED_IN_CALLBACK("open", "cache identifier  %llu", result.has_value() ? result.value().identifier : 0);
> 
> Why didn't you use value_or() here and below ? doesn't it work?

I guess it could be written with something like:
result.value_or(CacheIdentifierOperationResult { }).identifier
Comment 7 youenn fablet 2018-02-05 09:43:40 PST
Created attachment 333088 [details]
Patch
Comment 8 EWS Watchlist 2018-02-05 09:44:59 PST
Attachment 333088 [details] did not pass style-queue:


ERROR: Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:69:  More than one command on the same line  [whitespace/newline] [4]
ERROR: Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:78:  More than one command on the same line  [whitespace/newline] [4]
ERROR: Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:87:  More than one command on the same line  [whitespace/newline] [4]
ERROR: Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:96:  More than one command on the same line  [whitespace/newline] [4]
ERROR: Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:105:  More than one command on the same line  [whitespace/newline] [4]
ERROR: Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:114:  More than one command on the same line  [whitespace/newline] [4]
Total errors found: 6 in 3 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 9 EWS Watchlist 2018-02-05 11:13:29 PST
Comment on attachment 333088 [details]
Patch

Attachment 333088 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/6367360

New failing tests:
transitions/transition-display-property.html
Comment 10 EWS Watchlist 2018-02-05 11:13:30 PST
Created attachment 333099 [details]
Archive of layout-test-results from ews114 for mac-sierra

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews114  Port: mac-sierra  Platform: Mac OS X 10.12.6
Comment 11 youenn fablet 2018-02-05 11:32:10 PST
Patch is WK2 specific so WK1 failures are unrelated here.
Will fix the iOS-sim build error.
Comment 12 youenn fablet 2018-02-05 11:33:29 PST
Created attachment 333102 [details]
Patch
Comment 13 EWS Watchlist 2018-02-05 11:36:29 PST
Attachment 333102 [details] did not pass style-queue:


ERROR: Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:70:  More than one command on the same line  [whitespace/newline] [4]
ERROR: Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:79:  More than one command on the same line  [whitespace/newline] [4]
ERROR: Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:88:  More than one command on the same line  [whitespace/newline] [4]
ERROR: Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:97:  More than one command on the same line  [whitespace/newline] [4]
ERROR: Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:106:  More than one command on the same line  [whitespace/newline] [4]
ERROR: Source/WebKit/NetworkProcess/cache/CacheStorageEngineConnection.cpp:115:  More than one command on the same line  [whitespace/newline] [4]
Total errors found: 6 in 3 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 14 Chris Dumez 2018-02-05 11:46:28 PST
Comment on attachment 333102 [details]
Patch

r=me
Comment 15 WebKit Commit Bot 2018-02-05 12:16:46 PST
Comment on attachment 333102 [details]
Patch

Rejecting attachment 333102 [details] from commit-queue.

Failed to run "['/Volumes/Data/EWS/WebKit/Tools/Scripts/webkit-patch', '--status-host=webkit-queues.webkit.org', '--bot-id=webkit-cq-02', 'apply-attachment', '--no-update', '--non-interactive', 333102, '--port=mac']" exit_code: 1 cwd: /Volumes/Data/EWS/WebKit

Last 500 characters of output:
rdparty/autoinstalled/mechanize/_urllib2_fork.py", line 332, in _call_chain
    result = func(*args)
  File "/Volumes/Data/EWS/WebKit/Tools/Scripts/webkitpy/thirdparty/autoinstalled/mechanize/_urllib2_fork.py", line 1170, in https_open
    return self.do_open(conn_factory, req)
  File "/Volumes/Data/EWS/WebKit/Tools/Scripts/webkitpy/thirdparty/autoinstalled/mechanize/_urllib2_fork.py", line 1118, in do_open
    raise URLError(err)
urllib2.URLError: <urlopen error [Errno 60] Operation timed out>

Full output: http://webkit-queues.webkit.org/results/6369294
Comment 16 WebKit Commit Bot 2018-02-05 12:36:08 PST
Comment on attachment 333102 [details]
Patch

Rejecting attachment 333102 [details] from commit-queue.

Failed to run "['/Volumes/Data/EWS/WebKit/Tools/Scripts/webkit-patch', '--status-host=webkit-queues.webkit.org', '--bot-id=webkit-cq-02', 'apply-attachment', '--no-update', '--non-interactive', 333102, '--port=mac']" exit_code: 1 cwd: /Volumes/Data/EWS/WebKit

Last 500 characters of output:
rdparty/autoinstalled/mechanize/_urllib2_fork.py", line 332, in _call_chain
    result = func(*args)
  File "/Volumes/Data/EWS/WebKit/Tools/Scripts/webkitpy/thirdparty/autoinstalled/mechanize/_urllib2_fork.py", line 1170, in https_open
    return self.do_open(conn_factory, req)
  File "/Volumes/Data/EWS/WebKit/Tools/Scripts/webkitpy/thirdparty/autoinstalled/mechanize/_urllib2_fork.py", line 1118, in do_open
    raise URLError(err)
urllib2.URLError: <urlopen error [Errno 60] Operation timed out>

Full output: http://webkit-queues.webkit.org/results/6369580
Comment 17 WebKit Commit Bot 2018-02-05 13:04:02 PST
Comment on attachment 333102 [details]
Patch

Clearing flags on attachment: 333102

Committed r228116: <https://trac.webkit.org/changeset/228116>
Comment 18 WebKit Commit Bot 2018-02-05 13:04:04 PST
All reviewed patches have been landed.  Closing bug.
Comment 19 Michael Catanzaro 2018-02-06 06:50:07 PST
Committed r228157: <https://trac.webkit.org/changeset/228157>
Comment 20 Michael Catanzaro 2018-02-06 06:51:34 PST
(In reply to Michael Catanzaro from comment #19)
> Committed r228157: <https://trac.webkit.org/changeset/228157>

Remember uint64_t is unsigned long on Linux x86_64. We get a bunch of warnings whenever you try to print them as unsigned long long. Yay for silly platform differences!
Comment 21 youenn fablet 2018-02-06 09:39:32 PST
(In reply to Michael Catanzaro from comment #20)
> (In reply to Michael Catanzaro from comment #19)
> > Committed r228157: <https://trac.webkit.org/changeset/228157>
> 
> Remember uint64_t is unsigned long on Linux x86_64. We get a bunch of
> warnings whenever you try to print them as unsigned long long. Yay for silly
> platform differences!

Gasp... wonder whether lint would be able to catch these in cpp files.