Closed Bug 1333485 Opened 3 years ago Closed 3 years ago

Remove LogUtils.jsm from services/crypto/modules/

Categories

(Cloud Services :: General, defect)

defect
Not set

Tracking

(firefox54 fixed)

RESOLVED FIXED
Tracking Status
firefox54 --- fixed

People

(Reporter: stefanh, Assigned: stefanh)

References

Details

Attachments

(1 file)

In bug 1313045, I'm moving a couple of files from toolkit/identity to services/crypto. One of them is LogUtils.jsm, which could be removed if logging in jwcrypto.jsm is replaced by Log.jsm logging.
I'm looking at this. The plan is to have a patch for review next week.
Assignee: nobody → stefanh
Status: NEW → ASSIGNED
This went faster than I thought :-) Note that I’m not very familiar with the code, so bear with me if I misunderstood something. I’ve picked the debug level for everything, but there could be places where it’s more appropriate to use another level. I now noticed this which might be better logging as an error?
-      log("ERROR: signer.sign failed");
+      log.debug("ERROR: signer.sign failed");



I noticed https://hg.mozilla.org/mozilla-central/rev/d1f3d30546a1 (backed out), so I’m including the switch to ’do_print’ logging in test_jwcrypto.js. I haven’t investigated this, but never get any log output in these 2 places (I doubt the code inside the inner functions run properly - I can see the js error ”TypeError: do_check_neq is not a function” when I run the tests locally. Possibly a scope issue?).

I’ve tested the log output locally by running services/tests/unit/test_crypto_service.js, services/crypto/tests/unit/test_jwcrypto.js and services/fxaccounts/tests/xpcshell/test_accounts.js. It seems to work fine, the only thing I’ve noticed is that I seem to get the same output 2 times in test_accounts.js, but I guess that could be because of how the tests are run.

Example output:
LOG: Thread-1 INFO (xpcshell/head.js) | test test_getOAuthToken_unknown_error pending (2)
PROCESS_OUTPUT: Thread-1 (pid:28108) "1485723606303	FirefoxAccounts	DEBUG	FxAccountsOAuthGrantClient Initialized"
PROCESS_OUTPUT: Thread-1 (pid:28108) "1485723606303	FirefoxAccounts	DEBUG	setSignedInUser - aborting any existing flows"
LOG: Thread-1 INFO (xpcshell/head.js) | test run_next_test 36 finished (2)
PROCESS_OUTPUT: Thread-1 (pid:28108) "1485723606305	FirefoxAccounts	DEBUG	Notifying observers of fxaccounts:onlogin"
PROCESS_OUTPUT: Thread-1 (pid:28108) "1485723606305	FirefoxAccounts	DEBUG	getOAuthToken enter"
PROCESS_OUTPUT: Thread-1 (pid:28108) "1485723606306	FirefoxAccounts	DEBUG	getOAuthToken fetching new token from: http://example.com/v1"
PROCESS_OUTPUT: Thread-1 (pid:28108) "1485723606307	FirefoxAccounts	DEBUG	enter getAssertion()"
PROCESS_OUTPUT: Thread-1 (pid:28108) "1485723606308	identity.jwcrypto	DEBUG	generating"
PROCESS_OUTPUT: Thread-1 (pid:28108) "1485723606308	identity.jwcrypto	DEBUG	generating"
PROCESS_OUTPUT: Thread-1 (pid:28108) "1485723606309	identity.jwcrypto	DEBUG	Generate key pair; alg = DS160"
PROCESS_OUTPUT: Thread-1 (pid:28108) "1485723606309	identity.jwcrypto	DEBUG	Generate key pair; alg = DS160"
Attachment #8831569 - Flags: review?(MattN+bmo)
Comment on attachment 8831569 [details] [diff] [review]
Remove LogUtils.jsm and fix test logging

Review of attachment 8831569 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks Stefan,

Redirecting to Mark since I don't know services/ and Log.jsm (I prefer Console.jsm in new code) conventions very well.
Attachment #8831569 - Flags: review?(MattN+bmo) → review?(markh)
I now see that services/fxaccounts/tests/mochitest/test_invalidEmailCase.html used to set the toolkit.identity.debug pref to true (https://hg.mozilla.org/mozilla-central/rev/7f4f047cfc54#l3.12). But I'm unsure if that test triggers any logging in jwcrypto.jsm.
Comment on attachment 8831569 [details] [diff] [review]
Remove LogUtils.jsm and fix test logging

Review of attachment 8831569 [details] [diff] [review]:
-----------------------------------------------------------------

This looks good to me, thanks. Please upload a new version with the requested changes and we'll get it landed!

::: services/crypto/modules/jwcrypto.jsm
@@ +25,5 @@
>  
> +const PREF_LOG_LEVEL = "services.crypto.jwcrypto.log.level";
> +
> +XPCOMUtils.defineLazyGetter(this, "log", function() {
> +  let log = Log.repository.getLogger("identity.jwcrypto");

I think we should have the log name be "Services.Crypto.jwcrypto" to better match other log names under services/, and so the pref name and log name are somewhat consistent.

@@ +91,5 @@
>  
>  function sign(aPayload, aKeypair, aCallback) {
>    aKeypair._kp.sign(aPayload, function(rv, signature) {
>      if (!Components.isSuccessCode(rv)) {
> +      log.debug("ERROR: signer.sign failed");

as you mention, I think this should be a log.error call (and remove the "ERROR: " prefix)

@@ +179,5 @@
>      };
>      var payloadBytes = IdentityCryptoService.base64UrlEncode(
>                            JSON.stringify(payload));
>  
> +    log.debug("payload bytes " + JSON.stringify(payload) + " " + payloadBytes);

rewriting this as:

  log.debug("payload", { payload, payloadBytes });

will be more efficient when debug logging isn't enabled and will still magically JSON.stringify things.
Attachment #8831569 - Flags: review?(markh) → review+
(In reply to Mark Hammond [:markh] from comment #5)
 > This looks good to me, thanks. Please upload a new version with the
> requested changes and we'll get it landed!

Thanks for the fast response. Just one question: Do you want to take a look at the updated patch? Otherwise I can just push an updated version to m-i myself :-)
Talked to Mark, and I'll push this on wednesday.
(In reply to Stefan [:stefanh] from comment #6)
> Just one question: Do you want to take a look at the updated patch? 
Always good to have the patch attached that reflects what's being pushed, no?
(In reply to Jorg K (GMT+1) from comment #8)
> (In reply to Stefan [:stefanh] from comment #6)
> > Just one question: Do you want to take a look at the updated patch? 
> Always good to have the patch attached that reflects what's being pushed, no?

That often didn't happen before reviewboard - developers would fix commit comments and push without re-uploading. The commit into hg, which is always included in the bug, is the canonical representation of what was committed.

(mozreview has changed this for many - it's often easier to update the patch to mozreview and use autoland to get it checked in)
Pushed by stefanh@inbox.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e0026c3d1302
Remove LogUtils.jsm from services/crypto/modules/. r=markh.
https://hg.mozilla.org/mozilla-central/rev/e0026c3d1302
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.