Bug 182456 – Add logging to CacheStorageEngineConnection

• Status: RESOLVED
• Resolution: FIXED
• Component: Service Workers

[youenn fablet]

To help debugging

[Radar WebKit Bug Importer]

<rdar://problem/37181006>

[youenn fablet]

Created attachment 333025 [details]
Patch

[Chris Dumez]

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()

[youenn fablet]

Created attachment 333040 [details]
Patch

[Chris Dumez]

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?

[youenn fablet]

(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

[youenn fablet]

Created attachment 333088 [details]
Patch

[EWS Watchlist]

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.

[EWS Watchlist]

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

[EWS Watchlist]

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

[youenn fablet]

Patch is WK2 specific so WK1 failures are unrelated here.
Will fix the iOS-sim build error.

[youenn fablet]

Created attachment 333102 [details]
Patch

[EWS Watchlist]

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.

[Chris Dumez]

Comment on attachment 333102 [details]
Patch

r=me

[WebKit Commit Bot]

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

[WebKit Commit Bot]

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

[WebKit Commit Bot]

Comment on attachment 333102 [details]
Patch

Clearing flags on attachment: 333102

Committed r228116: <https://trac.webkit.org/changeset/228116>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Michael Catanzaro]

Committed r228157: <https://trac.webkit.org/changeset/228157>

[Michael Catanzaro]

(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!

[youenn fablet]

(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.