Open Bug 1604386 Opened 4 years ago Updated 3 months ago

Intermittent /webauthn/webauthn-testdriver-basic.https.html | Create a credential - promise_test: Unhandled rejection with value: object "NotAllowedError: The request is not allowed by the user agent or the platform in the current context, possibly becaus

Categories

(Core :: DOM: Web Authentication, defect, P5)

defect

Tracking

()

REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, leave-open, Whiteboard: [stockwell unknown])

Attachments

(2 files)

Filed by: ccoroiu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=281461937&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/L_DLoqqAQFyt2qJ6kJdqmQ/runs/0/artifacts/public/logs/live_backing.log


[task 2019-12-17T01:50:23.687Z] 01:50:23 INFO - TEST-START | /webauthn/webauthn-testdriver-basic.https.html
[task 2019-12-17T01:50:23.745Z] 01:50:23 INFO - Closing window 39
[task 2019-12-17T01:50:23.890Z] 01:50:23 INFO - PID 6428 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-12-17T01:50:23.890Z] 01:50:23 INFO - PID 6428 | [Parent 5464, Main Thread] WARNING: IPC message discarded: actor cannot send: file z:/build/build/src/ipc/glue/ProtocolUtils.cpp, line 481
[task 2019-12-17T01:50:23.890Z] 01:50:23 INFO - PID 6428 | [Parent 5464, Main Thread] WARNING: Error sending reply: file z:/build/build/src/obj-firefox/ipc/ipdl/PContentParent.cpp, line 11225
[task 2019-12-17T01:50:23.895Z] 01:50:23 INFO - PID 6428 | [Parent 5464, Main Thread] WARNING: IPC message discarded: actor cannot send: file z:/build/build/src/ipc/glue/ProtocolUtils.cpp, line 481
[task 2019-12-17T01:50:23.895Z] 01:50:23 INFO - PID 6428 | [Parent 5464, Main Thread] WARNING: Error sending reply: file z:/build/build/src/obj-firefox/ipc/ipdl/PContentParent.cpp, line 11225
[task 2019-12-17T01:50:23.913Z] 01:50:23 INFO - PID 6428 | [Child 652, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file z:/build/build/src/layout/base/nsPresContext.cpp, line 848
[task 2019-12-17T01:50:24.198Z] 01:50:24 INFO - PID 6428 | DLL blocklist was unable to intercept AppInit DLLs.
[task 2019-12-17T01:50:24.216Z] 01:50:24 INFO - PID 6428 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1576540200\appdata\local\temp\tmp_znyrq.mozrunner\runtests_leaks_2792_tab_pid3976.log
[task 2019-12-17T01:50:24.235Z] 01:50:24 INFO - PID 6428 | [Child 3976, Main Thread] WARNING: No CID found when attempting to map contract ID: file z:/build/build/src/xpcom/components/nsComponentManager.cpp, line 727
[task 2019-12-17T01:50:24.511Z] 01:50:24 INFO - PID 6428 | [Child 652, Main Thread] WARNING: '!aWin', file z:/build/build/src/dom/base/Document.cpp, line 1385
[task 2019-12-17T01:50:24.511Z] 01:50:24 INFO - PID 6428 | [Child 652, Main Thread] WARNING: '!aWin', file z:/build/build/src/dom/base/Document.cpp, line 1385
[task 2019-12-17T01:50:24.521Z] 01:50:24 INFO - PID 6428 | [Child 10036, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file z:/build/build/src/xpcom/base/nsCycleCollector.cpp, line 3361
[task 2019-12-17T01:50:24.648Z] 01:50:24 INFO - PID 6428 | [Parent 5464, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file z:/build/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2019-12-17T01:50:24.648Z] 01:50:24 INFO - PID 6428 | [Child 652, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file z:/build/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 63
[task 2019-12-17T01:50:24.870Z] 01:50:24 INFO - PID 6428 | nsStringStats
[task 2019-12-17T01:50:24.870Z] 01:50:24 INFO - PID 6428 | => mAllocCount: 7489
[task 2019-12-17T01:50:24.870Z] 01:50:24 INFO - PID 6428 | => mReallocCount: 0
[task 2019-12-17T01:50:24.870Z] 01:50:24 INFO - PID 6428 | => mFreeCount: 7489
[task 2019-12-17T01:50:24.870Z] 01:50:24 INFO - PID 6428 | => mShareCount: 8752
[task 2019-12-17T01:50:24.870Z] 01:50:24 INFO - PID 6428 | => mAdoptCount: 453
[task 2019-12-17T01:50:24.871Z] 01:50:24 INFO - PID 6428 | => mAdoptFreeCount: 457
[task 2019-12-17T01:50:24.871Z] 01:50:24 INFO - PID 6428 | => Process ID: 10036, Thread ID: 2704
[task 2019-12-17T01:50:25.823Z] 01:50:25 WARNING - Action add_virtual_authenticator not implemented
[task 2019-12-17T01:50:26.555Z] 01:50:26 INFO - PID 6428 | [Parent 5464, Main Thread] WARNING: IPC message discarded: actor cannot send: file z:/build/build/src/ipc/glue/ProtocolUtils.cpp, line 481
[task 2019-12-17T01:50:26.555Z] 01:50:26 INFO - PID 6428 | [Parent 5464, Main Thread] WARNING: Error sending reply: file z:/build/build/src/obj-firefox/ipc/ipdl/PContentParent.cpp, line 11225
[task 2019-12-17T01:50:26.574Z] 01:50:26 INFO - PID 6428 | [Parent 5464, Main Thread] WARNING: IPC message discarded: actor cannot send: file z:/build/build/src/ipc/glue/ProtocolUtils.cpp, line 481
[task 2019-12-17T01:50:26.574Z] 01:50:26 INFO - PID 6428 | [Parent 5464, Main Thread] WARNING: Error sending reply: file z:/build/build/src/obj-firefox/ipc/ipdl/PContentParent.cpp, line 11225
[task 2019-12-17T01:50:26.579Z] 01:50:26 INFO - PID 6428 | [Parent 5464, Main Thread] WARNING: IPC message discarded: actor cannot send: file z:/build/build/src/ipc/glue/ProtocolUtils.cpp, line 481
[task 2019-12-17T01:50:26.579Z] 01:50:26 INFO - PID 6428 | [Parent 5464, Main Thread] WARNING: Error sending reply: file z:/build/build/src/obj-firefox/ipc/ipdl/PContentParent.cpp, line 11225
[task 2019-12-17T01:50:56.161Z] 01:50:56 INFO -
[task 2019-12-17T01:50:56.161Z] 01:50:56 INFO - TEST-FAIL | /webauthn/webauthn-testdriver-basic.https.html | Set up the test environment - promise_test: Unhandled rejection with value: "error: Action add_virtual_authenticator not implemented"
[task 2019-12-17T01:50:56.161Z] 01:50:56 INFO - @https://web-platform.test:8443/webauthn/webauthn-testdriver-basic.https.html:13:13
[task 2019-12-17T01:50:56.161Z] 01:50:56 INFO - TEST-UNEXPECTED-FAIL | /webauthn/webauthn-testdriver-basic.https.html | Create a credential - promise_test: Unhandled rejection with value: object "NotAllowedError: The request is not allowed by the user agent or the platform in the current context, possibly because the user denied permission."
[task 2019-12-17T01:50:56.161Z] 01:50:56 INFO - @https://web-platform.test:8443/webauthn/webauthn-testdriver-basic.https.html:23:13
[task 2019-12-17T01:50:56.161Z] 01:50:56 INFO - TEST-INFO | expected TIMEOUT
[task 2019-12-17T01:50:56.162Z] 01:50:56 INFO -
[task 2019-12-17T01:50:56.162Z] 01:50:56 INFO - TEST-UNEXPECTED-FAIL | /webauthn/webauthn-testdriver-basic.https.html | Get an assertion - promise_test: Unhandled rejection with value: object "TypeError: credential is undefined"
[task 2019-12-17T01:50:56.162Z] 01:50:56 INFO - @https://web-platform.test:8443/webauthn/webauthn-testdriver-basic.https.html:57:13
[task 2019-12-17T01:50:56.162Z] 01:50:56 INFO - TEST-INFO | expected NOTRUN

Assignee: nobody → malexandru
Status: NEW → ASSIGNED

It looks like this isn't quite a permafail, so the patch is probably not going to eliminate the failures.

Flags: needinfo?(james)
Assignee: malexandru → nobody
Status: ASSIGNED → NEW
Flags: needinfo?(jjones)
Whiteboard: [stockwell needswork:owner]
Assignee: nobody → malexandru
Status: NEW → ASSIGNED
Flags: needinfo?(jjones)
Pushed by csabou@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/1f1fb1afb965
Restore expectations for webauthn-testdriver-basic.https.html. r=jgraham
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla74
Pushed by csabou@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/31bb28cde5eb
Restore expectations for webauthn-testdriver-basic.https.html. r=Aryx
Keywords: leave-open

The bug assignee is inactive on Bugzilla, so the assignee is being reset.

Assignee: malexandru → nobody
Severity: normal → S3

I encounter this exact problem with Firefox 122 under Linux (Ubuntu 20.03). Firefox installed without Snap from https://packages.mozilla.org/apt (same problem when coming from Mozilla Team PPA).

I have tested on a fresh profile on https://webauthn.bin.coffee/ and it gives the following error message : "NotAllowedError: The request is not allowed by the user agent or the platform in the current context, possibly because the user denied permission.".

All security.webauthn flags are enabled under about:config.

As I was thinking that perhaps AppArmor was the problem, I set Firefox in complain mode instead of the normal enforce one (aa-complain /usr/lib/firefox/firefox-bin), with no more success.

The tests made with both snapped Chromium and Microsoft Edge browser worked on the aforementioned page.

I have also tested the authenticator-rs package, cloning the main branch (commit 110b691, coming after v0.3.1 tag) and launching it through Cargo. It works and it detect the Yubikey plugged in my laptop.

I haven't tested with the snapped version of Firefox as, like all others snapped browser, PIV protocol is still broken and I also need it.

I haven't found a way to have relevant logs on this authentication module part of Firefox through the docs or about:logging. I'm highly interested in knowing if it's possible, to be able to provide further information to this bug report.

I don't really understand this part of the error message "possibly because the user denied permission". I haven't found any setting allowing or denying such permission, except in about:config where everything is set to true.

Surprisingly, I have found very few other people complaining about this exact same problem. This bug report is one of the rare resources on the Web talking about this error message.

What model of Yubikey are you using? Does the device info page of about:webauthn provide any information?

All security.webauthn flags are enabled under about:config.

The security.webauth.webauthn_enable_softtoken preference is only meant to be enabled in tests, and having it set to true in regular browsing would result in a NotAllowed error. So make sure that one is set to false.

You might also try setting security.webauthn.ctap2 to false.

I have also tested the authenticator-rs package, cloning the main branch (commit 110b691, coming after v0.3.1 tag) and launching it through Cargo. It works and it detect the Yubikey plugged in my laptop

Can you try the ctap2-2021 branch instead?

It's a Yubikey 5 Nano.

security.webauth.webauthn_enable_softtoken was indeed already set to false as I read that it was for virtual debugging purpose.

security.webauthn.ctap2 no more luck with this set to false.

I'll try ctap2-2021 and will tell you the outcome, but I currently get a compile error when running ctap2 on this branch (error: failed to run custom build command fornss-gk-api v0.3.0`). Investigating.

Last thing that I didn't mention: while standardizing our corporate Linux distro, I switched from Fedora to Ubuntu and Firefox WebAuthN was working in Fedora.

Results of authenticator-rs runs on the ctap2-2021 branch with both cryto_nss and crypto_openssl backends, both seems to work flawlessly with the Yubikey. No clue on why it doesn't in Firefox…

$ cargo run --example ctap2 --target x86_64-unknown-linux-gnu --features crypto_nss --no-default-features
    Finished dev [unoptimized + debuginfo] target(s) in 0.15s
     Running `target/x86_64-unknown-linux-gnu/debug/examples/ctap2`
Using 25s as the timeout
Asking a security key to register now...
Enter PIN: 
STATUS: waiting for user presence
Ok!
Register result: MakeCredentialsResult ...
$ cargo run --example ctap2 --target x86_64-unknown-linux-gnu --features crypto_openssl --no-default-features
    Finished dev [unoptimized + debuginfo] target(s) in 0.15s
     Running `target/x86_64-unknown-linux-gnu/debug/examples/ctap2`
Using 25s as the timeout
Asking a security key to register now...
Enter PIN: 
STATUS: waiting for user presence
Ok!
Register result: MakeCredentialsResult ...

You might get some useful information by running firefox from a terminal with the MOZ_LOG environment variable set to MOZ_LOG=authenticator::*:5.

  • Firefox started with firefox -no-remote -profile /tmp/tmp-profile -MOZ_LOG="timestamp,rotate:200,authenticator::*:5" -MOZ_LOG_FILE=/tmp/firefox-log.txt,
  • tail -f /tmp/firefox-log.txt.moz_log.0 and tail -f /tmp/firefox-log.txt.child-1.moz_log.0 to check logs,
  • Test on https://webauthn.bin.coffee/ with Create Credential,
  • No log produced.

To check that log writing is OK, I test with timestamp,rotate:200,nsHttp:5 and I got some logs.

Additional information: opening about:webauthn gives the following message: Please connect a security token.

I got some logs by making the necessary stuff in about:logging:

/tmp/firefox-log.txt.moz_log.0:2024-02-02 11:41:55.985563 UTC - [Parent 1983450: Main Thread]: I/authenticator::* [authenticator::statemachine] Statemachine was cancelled. Cancelling transaction now.
/tmp/firefox-log.txt.moz_log.0:2024-02-02 11:41:55.985590 UTC - [Parent 1983450: Main Thread]: I/authenticator::* [authenticator::transport::platform::transaction] Transaction was cancelled.

That's the only log popping out.

Searching for this error message, I fall on bug 1836722, bug 1827748 and https://github.com/mozilla/authenticator-rs/issues/242. Seems fixed in some latest version of Firefox (114 and 119 branches targeted in bug reports). Don't get any clue on why it's still popping for me.

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: