Closed Bug 1627273 Opened 4 years ago Closed 3 years ago

firefox is very slow and crashes because of p11-kit-proxy.so

Categories

(Core :: Security: PSM, defect, P3)

Product:
Core
Component:
Security: PSM
Version:
74 Branch
Platform:
Unspecified
Linux
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME
Project Flags:
Performance Impact low
Tracking Flags:
Tracking Status
firefox-esr68 --- wontfix
firefox75 --- wontfix
firefox76 --- wontfix
firefox77 --- wontfix
firefox78 --- wontfix

People

(Reporter: stsp2, Unassigned)

Details

(Keywords: crash, perf:responsiveness, Whiteboard: [psm-backlog][psm-smartcard])

Attachments

(3 files)

Снимок экрана от 2020-04-22 23-05-10.png
111.00 KB, image/png
Details
logfile
3.57 KB, text/plain
Details
log-p11kit.txt
66.15 KB, text/plain
Details

User Agent: Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:74.0) Gecko/20100101 Firefox/74.0

Steps to reproduce:

I insert the USB eToken, in firefox
security devices I can see it under p11-kit-proxy.
It is identified as
"SafeNet eToken 5100 [eToken 5110 SC] 00 00".

Actual results:

The internet becomes very slow.
Most sites do not open from first attempt.
Since I didn't know this is related to eToken,
I was blaming my ISP and already requested
the change to new ISP... This problem is very
bad. I simply plugged the token and forgot,
and was waiting for a week for my ISP to recover,
but they had nothing to do with it.

I initially filled the bug here:
https://github.com/p11-glue/p11-kit/issues/287
but obviously they are not going to do anything.
And I myself do not know who is responsible for
the bug: firefox or pk11-kit.

Expected results:

Nothing!
Pure nothing.

Bugbug thinks this bug should belong to this component, but please revert this change in case of error.

Component: Untriaged → Networking
Product: Firefox → Core
Severity: normal → critical
Component: Networking → Security
Product: Core → Firefox

Are there any reports listed in about:crashes? Can you copy them here?

Flags: needinfo?(stsp2)

Looking at the crash stack networking on PSM seems like the better module for this.

Component: Security → Networking
Product: Firefox → Core

I see the top frames in comment 3 are in security/manager/ssl/ and libnss.
Is Security::PSM better? Or anything I missed?

Flags: needinfo?(jhofmann)

PSM is probably the right component.

Component: Networking → Security: PSM
Flags: needinfo?(jhofmann)
Whiteboard: [qf]
Priority: -- → P3
Whiteboard: [qf] → [qf][psm-backlog][psm-smartcard]
Whiteboard: [qf][psm-backlog][psm-smartcard] → [qf:p3:responsiveness][psm-backlog][psm-smartcard]

Yes, it works flawlessly fast, and doesn't crash.
I would even say that the problem is fixed, if
not for the fact that there is simply no p11-kit-proxy
in security devices of that nightly build. And,
by unloading p11-kit-proxy before inserting
eToken, I can get also the casual firefox build
to work.
So I don't think that counts as a success.

Flags: needinfo?(stsp2)

(In reply to Stas Sergeev from comment #8)

Yes, it works flawlessly fast, and doesn't crash.
I would even say that the problem is fixed, if
not for the fact that there is simply no p11-kit-proxy
in security devices of that nightly build. And,

That module isn't loaded automatically in versions of Firefox provided by Mozilla. It's a Fedora-specific feature.

by unloading p11-kit-proxy before inserting
eToken, I can get also the casual firefox build
to work.

Did you mean "by loading p11-kit-proxy"? As in, if you manually add that module, does Firefox work for your?

Flags: needinfo?(stsp2)

That module isn't loaded automatically in versions of Firefox provided by Mozilla. It's a Fedora-specific feature.

OKey.
Should I move that to fedora then?

Did you mean "by loading p11-kit-proxy"?

No, I need to unload it on a fedora build,
before inserting the token. Then firefox works
(token doesn't, but there are other tools to
work with the token, besides firefox, so at
least that is fine).

if you manually add that module

How would I do that?
If I just press "Load" button in Security Devices,
and enter /usr/lib/p11-kit-proxy.so then it just
says "Unable to add module".
But file with such path exists.

That file is at /usr/lib64/p11-kit-proxy.so on my version of Fedora - does it work if you try that?

It is slow as hell, and also looks weird,
here's the screenshot.

Flags: needinfo?(stsp2)

Yes, that worked for the first time, and
then, even after a restart, it no longer
works, because it seems to have remembered
that this module should be loaded.
While its fine by itself, it should write a
different message when the module is
already loaded, but it writes the same.

Anyway, its slow as a turtle again, and
is also looking weirdly, as in the above
screen-shot. 2 similar eTokens instead
of one, and also many blank lines that
seem to also represent something.

(In reply to Stas Sergeev from comment #13)

Yes, that worked for the first time, and
then, even after a restart, it no longer
works, because it seems to have remembered
that this module should be loaded.

When you add a module using this interface, it will be loaded the next time Firefox starts. This is expected behavior.

While its fine by itself, it should write a
different message when the module is
already loaded, but it writes the same.

I don't understand what you're saying here.

Anyway, its slow as a turtle again, and
is also looking weirdly, as in the above
screen-shot. 2 similar eTokens instead
of one, and also many blank lines that
seem to also represent something.

Can you use the profiler from https://profiler.firefox.com/ with the settings "Firefox Platform" to capture a profile?

Flags: needinfo?(stsp2)

I don't understand what you're saying here.

When I was loading the worng file, it was
saying "Unable to add module", and when
I was adding the right file, but not the first
time, it was saying the same thing. It could
say "Module already loaded" or something
like this, because I didn't recognize its
already loaded, because of those many
empty slots for devices and different name.
So I was about to write to you "no, that
still doesn't work even with that file".

Can you use the profiler from

Or well, lets try...

OK, I captured the Security Devices button
press, which alone took 5 seconds:
https://perfht.ml/3aBfrHr
But w/o profiler it takes sometimes 30 seconds.
And works immediately if the module is
not loaded.

Flags: needinfo?(stsp2)

I have a better idea.
I pressed the Security Devices button,
and, instead of waiting for 5 (or 30) seconds,
made a stack trace with gdb:

#0 0x00007ffff7f61f55 in nanosleep () at /lib64/libpthread.so.0
#1 0x00007fffcf20d2e1 in SYS_USleep () at /usr/lib64/libpcsclite.so.1
#2 0x00007fffcf209b23 in SCardEndTransaction () at /usr/lib64/libpcsclite.so.1
#3 0x00007fffcc950528 in pcsc_unlock () at /lib64/libopensc.so.6
#4 0x00007fffcc929459 in sc_unlock () at /lib64/libopensc.so.6
#5 0x00007fffcc932f2d in sc_transmit_apdu () at /lib64/libopensc.so.6
#6 0x00007fffcc9a0bf3 in cac_select_file_by_type () at /lib64/libopensc.so.6
#7 0x00007fffcc9a0f26 in cac_select_pki_applet () at /lib64/libopensc.so.6
#8 0x00007fffcc9a1889 in cac_find_and_initialize.part ()
at /lib64/libopensc.so.6
#9 0x00007fffcc9a2542 in cac_match_card () at /lib64/libopensc.so.6
#10 0x00007fffcc9286c9 in sc_connect_card () at /lib64/libopensc.so.6
#11 0x00007fffccb5b129 in card_detect () at /usr/lib64/pkcs11/opensc-pkcs11.so
#12 0x00007fffccb5b9be in card_detect_all ()
at /usr/lib64/pkcs11/opensc-pkcs11.so
#13 0x00007fffccb55255 in C_GetSlotInfo ()
at /usr/lib64/pkcs11/opensc-pkcs11.so
#14 0x00007fffcd4b882c in proxy_C_GetSlotInfo () at /usr/lib64/p11-kit-proxy.so
#15 0x00007ffff6ebbd20 in nssSlot_IsTokenPresent ()
at /home/stas/firefox/libnss3.so
#16 0x00007ffff6ef5994 in pk11_IsPresentCertLoad ()
at /home/stas/firefox/libnss3.so
#17 0x00007ffff162898d in nsNSSComponent::CheckForSmartCardChanges() ()
at /home/stas/firefox/libxul.so
#18 0x00007ffff1636dcf in nsPKCS11Module::ListSlots(nsISimpleEnumerator**) ()
at /home/stas/firefox/libxul.so
#19 0x00007fffedff93b2 in NS_InvokeByIndex () at /home/stas/firefox/libxul.so
#20 0x00007fffee8ef92a in XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) () at /home/stas/firefox/libxul.so
#21 0x00007fffee8f0e69 in XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) () at /home/stas/firefox/libxul.so
#22 0x00007ffff18ad92b in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) () at /home/stas/firefox/libxul.so
#23 0x00007ffff18a6f99 in Interpret(JSContext*, js::RunState&) ()
at /home/stas/firefox/libxul.so
#24 0x00007ffff189e34e in js::RunScript(JSContext*, js::RunState&) ()
at /home/stas/firefox/libxul.so
#25 0x00007ffff18ade89 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) () at /home/stas/firefox/libxul.so
#26 0x00007ffff18ae3a5 in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) () at /home/stas/firefox/libxul.so
#27 0x00007ffff1927b41 in JS::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) ()
at /home/stas/firefox/libxul.so
#28 0x00007fffef87444a in mozilla::dom::EventHandlerNonNull::Call(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, mozilla::dom::Event&, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&) () at /home/stas/firefox/libxul.so
#29 0x00007fffefcfd399 in mozilla::JSEventHandler::HandleEvent(mozilla::dom::Event*) () at /home/stas/firefox/libxul.so
#30 0x00007fffefce8151 in mozilla::EventListenerManager::HandleEventSubType(mozilla::EventListenerManager::Listener*, mozilla::dom::Event*, mozilla::dom::EventTarget*) () at /home/stas/firefox/libxul.so
#31 0x00007fffefce895e in mozilla::EventListenerManager::HandleEventInternal(nsPresContext*, mozilla::WidgetEvent*, mozilla::dom::Event**, mozilla::dom::EventTarget*, nsEventStatus*, bool) () at /home/stas/firefox/libxul.so
#32 0x00007fffefce247b in mozilla::EventTargetChainItem::HandleEvent(mozilla::EventChainPostVisitor&, mozilla::ELMCreationDetector&) ()
at /home/stas/firefox/libxul.so
#33 0x00007fffefce1c59 in mozilla::EventTargetChainItem::HandleEventTargetChain(nsTArray<mozilla::EventTargetChainItem>&, mozilla::EventChainPostVisitor&, mozilla::EventDispatchingCallback*, mozilla::ELMCreationDetector&) ()
at /home/stas/firefox/libxul.so
#34 0x00007fffefce38af in mozilla::EventDispatcher::Dispatch(nsISupports*, nsPresContext*, mozilla::WidgetEvent*, mozilla::dom::Event*, nsEventStatus*, mozilla::EventDispatchingCallback*, nsTArray<mozilla::dom::EventTarget*>) ()
at /home/stas/firefox/libxul.so
#35 0x00007ffff0816207 in nsDocumentViewer::LoadComplete(nsresult) ()
at /home/stas/firefox/libxul.so
#36 0x00007ffff148011f in nsDocShell::EndPageLoad(nsIWebProgress, nsIChannel*, nsresult) () at /home/stas/firefox/libxul.so
#37 0x00007ffff147fdfd in nsDocShell::OnStateChange(nsIWebProgress*, nsIRequest*
, unsigned int, nsresult) () at /home/stas/firefox/libxul.so
#38 0x00007ffff1481250 in non-virtual thunk to nsDocShell::OnStateChange(nsIWebProgress*, nsIRequest*, unsigned int, nsresult) ()
at /home/stas/firefox/libxul.so
#39 0x00007fffeea751fc in nsDocLoader::DoFireOnStateChange(nsIWebProgress*, nsIRequest*, int&, nsresult) () at /home/stas/firefox/libxul.so
#40 0x00007fffeea74d72 in nsDocLoader::doStopDocumentLoad(nsIRequest*, nsresult) () at /home/stas/firefox/libxul.so
#41 0x00007fffeea73b5c in nsDocLoader::DocLoaderIsEmpty(bool) ()
at /home/stas/firefox/libxul.so
#42 0x00007fffeea74847 in nsDocLoader::OnStopRequest(nsIRequest*, nsresult) ()
at /home/stas/firefox/libxul.so
#43 0x00007fffeea74c5d in non-virtual thunk to nsDocLoader::OnStopRequest(nsIRequest*, nsresult) () at /home/stas/firefox/libxul.so
#44 0x00007fffee0c1593 in mozilla::net::nsLoadGroup::NotifyRemovalObservers(nsIRequest*, nsresult) () at /home/stas/firefox/libxul.so
#45 0x00007fffee0c2292 in mozilla::net::nsLoadGroup::RemoveRequest(nsIRequest*, nsISupports*, nsresult) () at /home/stas/firefox/libxul.so
#46 0x00007fffef06650d in mozilla::dom::nsUnblockOnloadEvent::Run() ()
at /home/stas/firefox/libxul.so
#47 0x00007fffedfe839d in nsThread::ProcessNextEvent(bool, bool*) ()
at /home/stas/firefox/libxul.so
#48 0x00007fffedfeae68 in NS_ProcessNextEvent(nsIThread*, bool) ()
at /home/stas/firefox/libxul.so
#49 0x00007fffee53dbdb in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) () at /home/stas/firefox/libxul.so
#50 0x00007fffee4fb956 in MessageLoop::Run() () at /home/stas/firefox/libxul.so
#51 0x00007ffff06191e9 in nsBaseAppShell::Run() ()
at /home/stas/firefox/libxul.so
#52 0x00007ffff171f8e8 in nsAppStartup::Run() ()
at /home/stas/firefox/libxul.so
#53 0x00007ffff17e7e72 in XREMain::XRE_mainRun() ()
at /home/stas/firefox/libxul.so
#54 0x00007ffff17e85b6 in XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) () at /home/stas/firefox/libxul.so
#55 0x00007ffff17e88df in XRE_main(int, char**, mozilla::BootstrapConfig const&) () at /home/stas/firefox/libxul.so
#56 0x0000555555564161 in main ()

Does this ring some bells?

And yes, when firefox is "crawling", the
token is flashing, showing the activity.
So really firefox just keeps poking into
it as if there is no tomorrow.

It's querying the module for the slots it has. That shouldn't be a slow operation. When you use your token with other programs, is it slow?

Flags: needinfo?(stsp2)

No other program I have, pokes into
the token persistently. Maybe with other
software it is slow too, but I never notice,
because it is accessed only once.
With firefox it keeps flashing and flashing,
no matter what I do: browsing internet,
pressing "Security Devices" button or
just doing things in firefox UI.
Just how many times per second does
firefox need to query module for the slots?

Flags: needinfo?(stsp2)

And no, its not slow with chromium, for example.
It flashes periodically with chromium, there are
large delays in flashing. Unlike with wirefox,
where it flashes just always.

Just how many times per second does
firefox need to query module for the slots?

gprof-enabled build could help me figure.

I don't think Firefox is set up to be built with gprof. Would using perf work?

Flags: needinfo?(stsp2)

gdb seems to work.
I run firefox for 30 seconds with break-point
on SCardTransmit, and here are the stats:

2 breakpoint keep y 0x00007fffcf334c50 <SCardTransmit>
breakpoint already hit 2835 times

So it calls SCardTransmit() 100 times per second.
I am sure is also calls BeginTransaction, EndTransaction,
Lock, Unlock and whatever else, with the same rate,
and they all bother the poor eToken.

Flags: needinfo?(stsp2)

That's due to libpcsclite. To get a better idea of what Firefox is doing, see how often it calls C_GetSlotInfo or C_GetSlotList in opensc-pkcs11.so.

Flags: needinfo?(stsp2)

1 breakpoint keep y <MULTIPLE>
breakpoint already hit 89 times
1.1 y 0x00007fffcc4edf70 <C_GetSlotInfo>
1.2 y 0x00007fffcc7f5870 <C_GetSlotInfo>

Only 89 times in 30 seconds.
Not too much.

Oh crap, after it "closed unexpectedly", it
asked me to either "Refresh Nightly" or
"Start in safe mode", but not simply "Continue"!
Then it removed pk11-proxy and imported
some cookies out of nowhere, hope not
from my main firefox profile.
Could you please make it so that it allows
the user to just continue, rather than to
do "clever things"? :(

Flags: needinfo?(stsp2)

(In reply to Stas Sergeev from comment #27)

Oh crap, after it "closed unexpectedly", it
asked me to either "Refresh Nightly" or
"Start in safe mode", but not simply "Continue"!
Then it removed pk11-proxy and imported
some cookies out of nowhere, hope not
from my main firefox profile.
Could you please make it so that it allows
the user to just continue, rather than to
do "clever things"? :(

That's not something I work on. You could file a bug on that: https://bugzilla.mozilla.org/enter_bug.cgi?product=Firefox&component=Untriaged

Since this slow device isn't something Firefox can do much about, what do you want to happen here? Do you use that token with Firefox? Is the problem that Firefox on Fedora auto-loads that token?

Flags: needinfo?(stsp2)

Since this slow device isn't something Firefox can do much about

It definitely can, as no problem with chromium.
SCardTransmit() is called 100 times per second!
If its not a firefox bug, then is it a pcsc-lite bug?
Only saying that firefox can do nothing about
that, is quite unhelpful w/o also saying who can.

And after all, why to call C_GetSlotInfo() 3 times
per second? For what?

Is the problem that Firefox on Fedora auto-loads that token?

Of course I would like firefox to use the token.
Since it can't, I use chromium for that, but not
auto-loading is a quite strange work-around.
Also why does firefox and thunderbird both
crash when I remove the token? Is it also something
that firefox can't fix?

Flags: needinfo?(stsp2)

And even if it is an absolutely slow device
that must be constantly queried, I am sure
firefox have heard of threads. Why the slow
device would stall the UI thread, stall the
internet traffic and everything else?
Come on!

You're coming across as condescending and entitled. Keep in mind the participation guidelines: https://bugzilla.mozilla.org/page.cgi?id=etiquette.html

How does this build perform: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/SWTAx11NQ5-P4N_xPJfqcQ/runs/0/artifacts/public/build/target.tar.bz2 (you'll have to manually add the p11-kit-proxy module)

Flags: needinfo?(stsp2)

Got this crash on exit:
https://crash-stats.mozilla.org/report/index/7aa39047-c9b0-47ba-9287-2aae90200429

UI is still unresponsive.
Internet probably went better. Its more
difficult to measure than UI, as there are
many other factors that can make it slow,
and at least on the first glance I don't see
a big problem with that build.
What was changed?

(you'll have to manually add the p11-kit-proxy module)

Surprisingly I didn't have to.
I removed the previous firefox dir and
extracted the new build into a fresh dir,
but it already had the module loaded in.
I guess it stored the profile somewhere in
my home dir, but separately from the
"main" firefox I have.

There is something different when I remove
the token. Prev versions crashed. This one
just stops responding, and eventually the
gnome-shell pops up the window to forcibly
terminate.

Flags: needinfo?(stsp2)

(In reply to Stas Sergeev from comment #32)

Got this crash on exit:
https://crash-stats.mozilla.org/report/index/7aa39047-c9b0-47ba-9287-2aae90200429

Unfortunately it looks like there's a deadlock in NSS that can happen when a token gets removed.

UI is still unresponsive.

Can you be more specific? Is the entire UI unresponsive? Or just parts of it? (e.g. just the "security devices" panel?)

What was changed?

I removed the code that periodically queried tokens for changes.

Flags: needinfo?(stsp2)

Unfortunately it looks like there's a deadlock in NSS that can happen when a token gets removed.

But that particular hang was IIRC without
even removing the token. I've got a few
more unexpected hangs with that version,
and plus it seems to have replaced crashes
with hangs. So maybe something have regressed.

Can you be more specific? Is the entire UI unresponsive? Or just parts of it?

It can just stall for a 5 seconds or so
(I believe it doesn't matter what part
of UI I was using). For example here is
the stall at the start of firefox:

#0 0x00007ffff7b0ea6f in poll () at /lib64/libc.so.6
#1 0x00007fffcf431ded in MessageReceive () at /usr/lib64/libpcsclite.so.1
#2 0x00007fffcf42edd4 in SCardTransmit () at /usr/lib64/libpcsclite.so.1
#3 0x00007fffccba9aab in pcsc_internal_transmit () at /lib64/libopensc.so.6
#4 0x00007fffccba9d49 in pcsc_transmit () at /lib64/libopensc.so.6
#5 0x00007fffccb88d43 in sc_single_transmit () at /lib64/libopensc.so.6
#6 0x00007fffccb8920f in sc_transmit () at /lib64/libopensc.so.6
#7 0x00007fffccb89f03 in sc_transmit_apdu () at /lib64/libopensc.so.6
#8 0x00007fffccbfa455 in cac_select_file_by_type () at /lib64/libopensc.so.6
#9 0x00007fffccbfaa46 in cac_select_pki_applet () at /lib64/libopensc.so.6
#10 0x00007fffccbfaaa6 in cac_find_first_pki_applet () at /lib64/libopensc.so.6
#11 0x00007fffccbfafad in cac_match_card () at /lib64/libopensc.so.6
#12 0x00007fffccb7f6c9 in sc_connect_card () at /lib64/libopensc.so.6
#13 0x00007fffcf113129 in card_detect () at /usr/lib64/pkcs11/opensc-pkcs11.so
#14 0x00007fffcf1139be in card_detect_all ()
at /usr/lib64/pkcs11/opensc-pkcs11.so
#15 0x00007fffcf10ccc3 in C_GetSlotList ()
at /usr/lib64/pkcs11/opensc-pkcs11.so
#16 0x00007fffcd639e5b in proxy_list_slots () at /usr/lib64/p11-kit-proxy.so
#17 0x00007fffcd63a3ee in proxy_C_Initialize () at /usr/lib64/p11-kit-proxy.so
#18 0x00007ffff6eddb73 in secmod_ModuleInit () at /home/stas/firefox/libnss3.so
#19 0x00007ffff6ede374 in secmod_LoadPKCS11Module ()
at /home/stas/firefox/libnss3.so
#20 0x00007ffff6ee9916 in SECMOD_LoadModule () at /home/stas/firefox/libnss3.so
--Type <RET> for more, q to quit, c to continue without paging--
#21 0x00007ffff6ee9a42 in SECMOD_LoadModule () at /home/stas/firefox/libnss3.so
#22 0x00007ffff6eb7dd5 in nss_Init () at /home/stas/firefox/libnss3.so
#23 0x00007ffff6eb8096 in NSS_Initialize () at /home/stas/firefox/libnss3.so
#24 0x00007fffedfcca65 in mozilla::psm::InitializeNSS(nsTSubstring<char> const&, mozilla::psm::NSSDBConfig, mozilla::psm::PKCS11DBConfig) ()
at /home/stas/firefox/libxul.so
#25 0x00007ffff16e0104 in nsNSSComponent::InitializeNSS() ()
at /home/stas/firefox/libxul.so
#26 0x00007ffff16e1650 in nsNSSComponent::Init() ()
at /home/stas/firefox/libxul.so
#27 0x00007fffee05fc33 in mozilla::xpcom::CreateInstanceImpl(mozilla::xpcom::ModuleID, nsISupports*, nsID const&, void**) () at /home/stas/firefox/libxul.so
#28 0x00007fffee06cc3d in nsComponentManagerImpl::GetServiceLocked((anonymous namespace)::MutexLock&, (anonymous namespace)::EntryWrapper&, nsID const&, void**) () at /home/stas/firefox/libxul.so
#29 0x00007fffee069682 in nsComponentManagerImpl::GetServiceByContractID(char const*, nsID const&, void**) () at /home/stas/firefox/libxul.so
#30 0x00007fffee06eef7 in nsGetServiceByContractIDWithError::operator()(nsID const&, void**) const () at /home/stas/firefox/libxul.so
#31 0x00007fffedffc6bb in nsCOMPtr_base::assign_from_gs_contractid_with_error(nsGetServiceByContractIDWithError const&, nsID const&) ()
at /home/stas/firefox/libxul.so
#32 0x00007fffee16e2fb in net_EnsurePSMInit() ()
at /home/stas/firefox/libxul.so
--Type <RET> for more, q to quit, c to continue without paging--
#33 0x00007fffee3d691a in mozilla::net::nsHttpHandler::NewProxiedChannel(nsIURI*, nsIProxyInfo*, unsigned int, nsIURI*, nsILoadInfo*, nsIChannel**) ()
at /home/stas/firefox/libxul.so
#34 0x00007fffee155539 in mozilla::net::nsIOService::NewChannelFromURIWithProxyFlagsInternal(nsIURI*, nsIURI*, unsigned int, nsILoadInfo*, nsIChannel**) ()
at /home/stas/firefox/libxul.so
#35 0x00007fffee1552ab in mozilla::net::nsIOService::NewChannelFromURIWithProxyFlagsInternal(nsIURI*, nsIURI*, unsigned int, nsINode*, nsIPrincipal*, nsIPrincipal*, mozilla::Maybe<mozilla::dom::ClientInfo> const&, mozilla::Maybe<mozilla::dom::ServiceWorkerDescriptor> const&, unsigned int, unsigned int, unsigned int, nsIChannel**) () at /home/stas/firefox/libxul.so
#36 0x00007fffee1551d9 in mozilla::net::nsIOService::NewChannelFromURIWithClientAndController(nsIURI*, nsINode*, nsIPrincipal*, nsIPrincipal*, mozilla::Maybe<mozilla::dom::ClientInfo> const&, mozilla::Maybe<mozilla::dom::ServiceWorkerDescriptor> const&, unsigned int, unsigned int, unsigned int, nsIChannel**) ()
at /home/stas/firefox/libxul.so
#37 0x00007fffee16696f in NS_NewChannelInternal(nsIChannel**, nsIURI*, nsINode*, nsIPrincipal*, nsIPrincipal*, mozilla::Maybe<mozilla::dom::ClientInfo> const&, mozilla::Maybe<mozilla::dom::ServiceWorkerDescriptor> const&, unsigned int, unsigned int, nsICookieJarSettings*, mozilla::dom::PerformanceStorage*, nsILoadGroup*, nsIInterfaceRequestor*, unsigned int, nsIIOService*, unsigned int) ()
at /home/stas/firefox/libxul.so
#38 0x00007fffee16687b in NS_NewChannel(nsIChannel**, nsIURI*, nsIPrincipal*, unsigned int, unsigned int, nsICookieJarSettings*, mozilla::dom::PerformanceStorag--Type <RET> for more, q to quit, c to continue without paging--
e*, nsILoadGroup*, nsIInterfaceRequestor*, unsigned int, nsIIOService*, unsigned int) () at /home/stas/firefox/libxul.so
#39 0x00007ffff0590d13 in mozilla::dom::XMLHttpRequestMainThread::CreateChannel() () at /home/stas/firefox/libxul.so
#40 0x00007ffff0590a3a in mozilla::dom::XMLHttpRequestMainThread::Open(nsTSubstring<char> const&, nsTSubstring<char> const&, bool, nsTSubstring<char16_t> const&, nsTSubstring<char16_t> const&) () at /home/stas/firefox/libxul.so
#41 0x00007ffff05903ce in mozilla::dom::XMLHttpRequestMainThread::Open(nsTSubstring<char> const&, nsTSubstring<char16_t> const&, bool, nsTSubstring<char16_t> const&, nsTSubstring<char16_t> const&, mozilla::ErrorResult&) ()
at /home/stas/firefox/libxul.so
#42 0x00007fffef852c54 in mozilla::dom::XMLHttpRequest_Binding::open(JSContext*, JS::Handle<JSObject*>, void*, JSJitMethodCallArgs const&) ()
at /home/stas/firefox/libxul.so
#43 0x00007fffefb104c8 in bool mozilla::dom::binding_detail::GenericMethod<mozilla::dom::binding_detail::NormalThisPolicy, mozilla::dom::binding_detail::ThrowExceptions>(JSContext*, unsigned int, JS::Value*) ()
at /home/stas/firefox/libxul.so
#44 0x00007ffff196493b in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) () at /home/stas/firefox/libxul.so
#45 0x00007ffff195dfa9 in Interpret(JSContext*, js::RunState&) ()
at /home/stas/firefox/libxul.so
#46 0x00007ffff195535e in js::RunScript(JSContext*, js::RunState&) ()
at /home/stas/firefox/libxul.so
--Type <RET> for more, q to quit, c to continue without paging--
#47 0x00007ffff1964e99 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) () at /home/stas/firefox/libxul.so
#48 0x00007ffff19653b5 in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) () at /home/stas/firefox/libxul.so
#49 0x00007ffff19de37f in JS_CallFunctionValue(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) () at /home/stas/firefox/libxul.so
#50 0x00007fffee98dee8 in nsXPCWrappedJS::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) () at /home/stas/firefox/libxul.so
#51 0x00007fffee09572c in PrepareAndDispatch () at /home/stas/firefox/libxul.so
#52 0x00007fffee094b67 in SharedStub () at /home/stas/firefox/libxul.so
#53 0x00007fffee116678 in non-virtual thunk to mozilla::net::CaptivePortalService::Prepare() () at /home/stas/firefox/libxul.so
#54 0x00007fffee0949e2 in NS_InvokeByIndex () at /home/stas/firefox/libxul.so
#55 0x00007fffee99263a in XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) () at /home/stas/firefox/libxul.so
#56 0x00007fffee993b79 in XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) () at /home/stas/firefox/libxul.so
#57 0x00007ffff196493b in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) () at /home/stas/firefox/libxul.so
#58 0x00007ffff195dfa9 in Interpret(JSContext*, js::RunState&) ()
at /home/stas/firefox/libxul.so
#59 0x00007ffff195535e in js::RunScript(JSContext*, js::RunState&) ()
--Type <RET> for more, q to quit, c to continue without paging--
at /home/stas/firefox/libxul.so
#60 0x00007ffff1964e99 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) () at /home/stas/firefox/libxul.so
#61 0x00007ffff19653b5 in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) () at /home/stas/firefox/libxul.so
#62 0x00007ffff19de37f in JS_CallFunctionValue(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) () at /home/stas/firefox/libxul.so
#63 0x00007fffee98dee8 in nsXPCWrappedJS::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) () at /home/stas/firefox/libxul.so
#64 0x00007fffee09572c in PrepareAndDispatch () at /home/stas/firefox/libxul.so
#65 0x00007fffee094b67 in SharedStub () at /home/stas/firefox/libxul.so
#66 0x00007fffee115c14 in mozilla::net::CaptivePortalService::PerformCheck() ()
at /home/stas/firefox/libxul.so
#67 0x00007fffee1161f0 in mozilla::net::CaptivePortalService::RecheckCaptivePortal() () at /home/stas/firefox/libxul.so
#68 0x00007fffee0949e2 in NS_InvokeByIndex () at /home/stas/firefox/libxul.so
#69 0x00007fffee99263a in XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) () at /home/stas/firefox/libxul.so
#70 0x00007fffee993b79 in XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) () at /home/stas/firefox/libxul.so
#71 0x00007ffff196493b in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) () at /home/stas/firefox/libxul.so
--Type <RET> for more, q to quit, c to continue without paging--
#72 0x00007ffff195dfa9 in Interpret(JSContext*, js::RunState&) ()
at /home/stas/firefox/libxul.so
#73 0x00007ffff195535e in js::RunScript(JSContext*, js::RunState&) ()
at /home/stas/firefox/libxul.so
#74 0x00007ffff1964e99 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) () at /home/stas/firefox/libxul.so
#75 0x00007ffff1ecf50b in js::jit::DoCallFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICCall_Fallback*, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>) () at /home/stas/firefox/libxul.so

Flags: needinfo?(stsp2)

Here are the stats of about 10 seconds run:

Num Type Disp Enb Address What
1 breakpoint keep y <MULTIPLE>
breakpoint already hit 12 times
1.1 y 0x00007fffcd435fc0 <C_GetSlotList>
1.2 y 0x00007fffcee0cc30 <C_GetSlotList>
2 breakpoint keep y 0x00007fffcf706c50 <SCardTransmit>
breakpoint already hit 611 times

Note that the numbers are not exceptionally
large, even though its still not clear for me
why to query slots every second.
But for example see another random trace:

#0 0x00007ffff7f61f55 in nanosleep () at /lib64/libpthread.so.0
#1 0x00007fffd05082e1 in SYS_USleep () at /usr/lib64/libpcsclite.so.1
#2 0x00007fffd0504b23 in SCardEndTransaction () at /usr/lib64/libpcsclite.so.1
#3 0x00007fffcccd8528 in pcsc_unlock () at /lib64/libopensc.so.6
#4 0x00007fffcccb1459 in sc_unlock () at /lib64/libopensc.so.6
#5 0x00007fffcccbaf2d in sc_transmit_apdu () at /lib64/libopensc.so.6
#6 0x00007fffccd28bf3 in cac_select_file_by_type () at /lib64/libopensc.so.6
#7 0x00007fffccd29851 in cac_find_and_initialize.part ()

Very frequently the trace hits SYS_USleep(),
which means that it may not be a slow device,
but rather a large delays in libpcsclite.
Which brings in another question: would it
be possible the delays to not stall UI or internet,
but rather move them to a different thread?

Looks like that code is here: https://salsa.debian.org/rousseau/PCSC/-/blob/master/src/winscard_clnt.c#L1290

	/*
	 * This helps prevent starvation
	 */
	randnum = SYS_RandomInt(1000, 10000);
	(void)SYS_USleep(randnum);
	rv = scEndStruct.rv;

Assuming the random function is uniform, SCardEndTransaction will sleep for an expected 4.5 milliseconds each time it is called. Assuming each SCardTransmit corresponds to one SCardEndTransaction, calling it 611 times means we wait for an expected 2.7495 seconds, which seems like about what you're seeing.

Architecturally it would be incredibly difficult for these function calls to not block the networking thread. We are doing some work to avoid blocking the UI thread, but it's still in progress.

I think a more effective path forward in the meantime would be to investigate if it's still necessary to have that random delay in pcsc. Alternatively, perhaps opensc is being inefficient in how it uses pcsc.

Starting with pcsc, I filed https://salsa.debian.org/rousseau/PCSC/-/issues/17

That's really helpful, thanks!
But still, why C_GetSlotList() is called 12 times
in 10 seconds? If it would be called 1 time, I
wouldn't notice any delay at all.

Another thing to note is that every
C_GetSlotList() is translated into 50
scard transactions. I realize that the
smart-card protocol can be complex,
but at least in the cases I've seen, a
single (and long) handshake was
enough, after which, you could issue
just 1 apdu exchange per command.
I wonder if maybe C_GetSlotList()
does scard reset and starts an exchange
from the very beginning every time.
Just a guess of course.

Architecturally it would be incredibly difficult for these function calls to not block the networking thread.

You mean, specifically to firefox, or in general?
If you mean in general, then I wonder why
chromium works fine. If you mean specifically
to firefox... oh well, quite bad. :) At least then
perhaps it should be documented.

Looks like that code is here:

	 * This helps prevent starvation
 	 */
        randnum = SYS_RandomInt(1000, 10000); 
        (void)SYS_USleep(randnum);
        rv = scEndStruct.rv;
end:
 	(void)pthread_mutex_unlock(&currentContextMap->mMutex);

He sleeps under lock. Comment about
starvation implies this shouldn't be the
case.

This code: https://salsa.debian.org/rousseau/PCSC/-/blob/master/src/winscard_clnt.c#L2755

		(void)pthread_mutex_unlock(&currentContextMap->mMutex);
 		(void)SYS_USleep(PCSCLITE_LOCK_POLL_RATE);
 		goto retry;

unlocks before sleeping.

Status: still UNCONFIRMED though. :)

(In reply to Stas Sergeev from comment #38)

Architecturally it would be incredibly difficult for these function calls to not block the networking thread.

You mean, specifically to firefox, or in general?
If you mean in general, then I wonder why

Specific to Firefox, or at least anything that uses NSS to implement TLS (which Chrome does not). Some operations in NSS are tightly coupled with the aggregate state of all loaded PKCS#11 modules, so if any of them are slow, it can slow down NSS as a whole.

(In reply to Stas Sergeev from comment #40)

Status: still UNCONFIRMED though. :)

The way we use bugzilla, that field doesn't mean anything until the bug is fixed.

I fixed a problem in pcsc-lite. See https://ludovicrousseau.blogspot.com/2020/05/your-pcsc-application-200-faster.html

My change does not explain the crashes when the token is unplugged. Maybe there is another issue in OpenSC or p11-kit

Dana, thanks a lot for your investigation in the issue.

Stas, tell me if you need help to install the beta version of pcsc-lite to see if the problem is solved for you.
You can get the beta at http://ludovic.rousseau.free.fr/softwares/pcsc-lite/pcsc-lite-1.8.26-05d48e5.tar.bz2

Hmm, very strange results.
I used your latest code and Dana's
latest build. I can indeed confirm that
with gdb I no longer hit the SYS_Usleep()
in a stack trace, but the real delays
remained the same. How can this be?
Error on a user side? Seems not, as I
made a stat for a 10 seconds firefox
run, and it now looks like this:

4 breakpoint keep y <MULTIPLE>
breakpoint already hit 12 times
4.1 y 0x00007fffcd676fc0 <C_GetSlotList>
4.2 y 0x00007fffcf40cc30 <C_GetSlotList>
5 breakpoint keep y 0x00007fffcf734690 in SCardTransmit
at winscard_clnt.c:2664
breakpoint already hit 1215 times

All traces now look like this:

(gdb) bt
#0 0x00007ffff7b0ea6f in poll () at /lib64/libc.so.6
#1 0x00007fffcf60757e in MessageReceive
(buffer_void=buffer_void@entry=0x7fffffff57a0, buffer_size=buffer_size@entry=32, filedes=109) at winscard_msg.c:478
#2 0x00007fffcf604800 in SCardTransmit
(hCard=1534068866, pioSendPci=0x7fffffff5830, pbSendBuffer=0x7fffce48f120 "", cbSendLength=13, pioRecvPci=0x7fffffff5840, pbRecvBuffer=0x7fffd1340570 '\345' <repeats 199 times>, <incomplete sequence \345>..., pcbRecvLength=0x7fffffff5828) at winscard_clnt.c:2724
#3 0x00007fffcce5caab in pcsc_internal_transmit () at /lib64/libopensc.so.6

How can this be?
It seems we have the same 12 calls
to C_GetSlotList(), but the number of
corresponding SCardTransmit() doubled,
effectively leaving the delays on the same
mark!
Doesn't make any sense to me. :(

I fixed a problem in pcsc-lite.
But I can't change the way libpcsclite is used. Calling C_GetSlotList every second is wrong. I don't know if this call is made by Firefox or by p11-kit-proxy.
C_WaitForSlotEvent() should be used instead of an active polling.

Calling C_GetSlotList every second is wrong.

Yes, indeed, that was my point initially too.
But now I can see that the calling rate of
C_GetSlotList() did NOT change, but the
rate of calling SCardTransmit() doubled!
It is very strange that your fix made such effect.
Either there is a bug in /lib64/libopensc.so.6,
or maybe not all calls to SCardTransmit()
correspond to C_GetSlotList()?

I was wondering in this thread why
every C_GetSlotList() translates into
50 SCardTransmit(). It looked too much,
but now it takes whooping 100.
Really something is wrong in opensc
I suspect.

Stas, try this:

  • unload /usr/lib64/p11-kit-proxy.so from Firefox
  • load OpenSC PKCS#11 /usr/lib64/pkcs11/opensc-pkcs11.so instead

I am also surprised that your "SafeNet eToken 5100" is supported by OpenSC.
What is the result of "opensc-tool --name" as documented at https://github.com/OpenSC/OpenSC/wiki/Frequently-Asked-Questions#how-can-i-verify-that-my-card-is-supported-by-opensc

OK, done that.
The results are very strange again:

1 breakpoint keep y 0x00007fffcec0cc30 <C_GetSlotList>
breakpoint already hit 2 times
2 breakpoint keep y 0x00007fffcf60a690 in SCardTransmit
at winscard_clnt.c:2664
breakpoint already hit 986 times

So, C_GetSlotList() called only twice, but
SCardTransmit() is still around 1000!
So it seems no matter how fast you make
it or how much you reduce C_GetSlotList()
calls, some idiot just calls it in a tight loop
somewhere.

OK, I dig a bit deeper.
It seems, with all the suggested and made
changes, we have now:

  • 81 SCardTransmit() call per C_GetSlotList()
  • 162 SCardTransmit() calls per C_GetSlotInfo()
    Some other unidentified caller also adds up.
    Why so much transactions per every call?

$ opensc-tool --name
Using reader with a card: SafeNet eToken 5100 [eToken 5110 SC] 00 00
Unsupported card

81 SCardTransmit() calls per C_Initialize()

Yes, I forgot to mention that the
delays reduced about twice with the
switch to opensc-pkcs11.so compared
to p11-kit-proxy.so.
Combined with Dana changes, this
basically makes things at least acceptable
to work with.

10 seconds stat:

1 breakpoint keep y 0x00007fffcf60cc30 <C_GetSlotList>
breakpoint already hit 2 times
2 breakpoint keep y 0x00007fffcfa0a690 in SCardTransmit
at winscard_clnt.c:2664
breakpoint already hit 891 times
3 breakpoint keep y 0x00007fffcf60cf70 <C_GetSlotInfo>
breakpoint already hit 4 times
4 breakpoint keep y 0x00007fffcf60da40 <C_Initialize>
breakpoint already hit 1 time
(gdb) p 4162+281+81
$6 = 891

Bad formatting.

1       breakpoint     keep y   0x00007fffcf60cc30 <C_GetSlotList>
	breakpoint already hit 2 times
2       breakpoint     keep y   0x00007fffcfa0a690 in SCardTransmit 
                                                   at winscard_clnt.c:2664
	breakpoint already hit 891 times
3       breakpoint     keep y   0x00007fffcf60cf70 <C_GetSlotInfo>
	breakpoint already hit 4 times
4       breakpoint     keep y   0x00007fffcf60da40 <C_Initialize>
	breakpoint already hit 1 time
(gdb) p 4*162+2*81+81
$6 = 891

As for removing the token.
opensc-pkcs11.so doesn't seem to
crash, but it doesn't sense the removal.
I.e. in security devices the token is
present even after removal. I suppose
this is how it avoids the crash.

In either case, this is a quite usable
configuration. Much more to desire,
but is quite usable, thanks!

It still doesn't pop up the password
dialog for eToken when I go to teams.microsoft.com,
and therefore I still need to use chromium.
But getting to teams.microsoft.com w/o any
hang or crash is already a big progress.

It is not surprising that many SCardTransmit() are used.

Your token is NOT supported by OpenSC so you can unload it from Firefox.
I guess you have installed another PKCS#11 library to support your SafeNet eToken 5100 token. My guess is that you have SafeNet Authentication Client (SAC) installed.
You should use this instead of OpenSC in Firefox.

I also suspect that p11-kit-proxy.so is bogus and does stupid things like calling C_GetSlotList() every second. I never used this software p11-kit https://github.com/p11-glue/p11-kit

You should continue the discussion at https://github.com/p11-glue/p11-kit/issues/287

You should use this instead of OpenSC in Firefox.

Yes, that worked out perfectly, thanks!
No delays, password prompt - everything.
But why by default firefox can't just say
that the eToken is unsupported, and stop
using it, instead of breaking in all possible
ways? I am sure other people will not go
through all that pain, figuring out why
everything suddenly became slow/nonfunctional.

I don't think the problem is Firefox.
The problem is with p11-kit-proxy and with your distribution Fedora that installed it by default in Firefox.
As Dana wrote in comment 9 "That module isn't loaded automatically in versions of Firefox provided by Mozilla. It's a Fedora-specific feature."

You can report the problem to Fedora.

But why OpenSC floods the unsupported eToken
with some traffic? If its unsupported, it should
just tell so to the upper layers and give up.
Instead it is trying to do something bad, no?

I think the upper layer (p11-kit-proxy?) is asking again and again.
So OpenSC can just try again and say again: unsupported.
This discussion has nothing to do with Firefox now.

But even after replacing p11-kit with opensc,
the delays have reduced but not disappeared.
Still around 1000 transactions in 10 seconds!
And this is with Dana's build that "reduced"
the calls to SC.
It surprises me that just saying "unsupported"
to the upper layers, casts that much. :(
Should we test the normal build with opensc
then? I'll see how the normal build behaves
with opensc, before blaming p11-kit.

You can use OpenSC PKCS #11 Spy to see what Firefox is doing at the PKCS#11 level.
See https://github.com/OpenSC/OpenSC/wiki/Using-OpenSC#pkcs-11-spy

Attached file logfile —

Here is the log file from opensc spy.

Seems like not too many actions on an opensc level...
So it all boils down to many transactions I suppose.

GetSlotInfo() says CKF_TOKEN_PRESENT
C_GetTokenInfo() says CKR_TOKEN_NOT_PRESENT
And that seems to repeat a few times.

Attached file log-p11kit.txt —

p11-kit log seems much, much worse!

So yes, it seems like p11-kit just polls
in a tight loop, but opensc is still not
quite fast for the reasons yet unknown. :(

As you have seen, OpenSC (/usr/lib64/opensc-pkcs11.so) reports CKF_TOKEN_PRESENT for C_GetSlotInfo() and then CKR_TOKEN_NOT_PRESENT for C_GetTokenInfo().
This is wrong.

I think OpenSC should report CKR_TOKEN_NOT_RECOGNIZED instead of CKR_TOKEN_NOT_PRESENT and Firefox should then stop asking.
You should report the problem to OpenSC https://github.com/OpenSC/OpenSC

OK, thanks for info.
Will do.

In a mean time I did more debugging
with p11-kit to find out why it is not
actually much slower than opensc.
It appears, even though it does
much more C_GetSlotList() calls,
not all of them translate into 81
transactions. Only very few of the
calls go into 81 transactions, but
most - simply return w/o a single
transaction!
Also, it never calls C_GetSlotInfo(),
which is OpenSC takes 162 transactions.
So it seems too early to blame p11-kit.
Essentially I wonder why most of it
C_GetSlotList() calls do not cause
any transaction at all...

Filled this bug:
https://github.com/OpenSC/OpenSC/issues/2030

The bug was fixed:
https://github.com/OpenSC/OpenSC/commit/16456922e2a038ae38f58cffaa7696013a761b3b
CKR_TOKEN_NOT_RECOGNIZED is now correctly returned:
https://github.com/OpenSC/OpenSC/files/4652623/logfile.new.txt

Nothing else changed.
It is still called multiple times with
162 transactions each.

So it seems, we got a few bugs fixed
in an opensc stack, but the real problem
is still in firefox?

Dana, could you please take a look if
CKR_TOKEN_NOT_RECOGNIZED
actually checked as expected?
Maybe it wasn't working in opensc, and
because of that, firefox doesn't handle it?

Wow, 2 fixed bugs! Now we need to fix Firefox Fedora functionality!
BTW, https://ludovicrousseau.blogspot.com/2020/05/your-pcsc-application-200-faster.html this is CRAZY! Already in latest debian testing, works good on my EMV debit cards. Cool. So we are now testing this https://github.com/p11-glue/p11-kit/commit/c8f8053edc9098fdb36fbb34165b8d92ed596798 maybe it will fix smth!

"I also suspect that p11-kit-proxy.so is bogus and does stupid things like calling C_GetSlotList() every second. I never used this software p11-kit"
Maybe you can help, Ludovic?

https://github.com/p11-glue/p11-kit/commit/c8f8053edc9098fdb36fbb34165b8d92ed596798 maybe it will fix smth!

I confirm that it fixes crash.
Thank you.

"I also suspect that p11-kit-proxy.so is bogus and does stupid things like calling C_GetSlotList() every second. I never used this software p11-kit"
Maybe you can help, Ludovic?

Likely not.
I checked that, and there appears no
such bug in p11-kit. So the reason of
the slow-down is largely unknown.

Fixed problem by renaming p11-kit-proxy.so.

sudo mv /usr/lib64/p11-kit-proxy.so /usr/lib64/p11-kit-proxy.so2

And from Firefox -> Security Devices -> Load Module , added /usr/lib64/libeTPkcs11.so module instead.

It's not stupid if it works!

(In reply to Adrian Harabula from comment #73)

It's not stupid if it works!

What actually you tried to fix? If it is crash we/they fixed that (https://github.com/p11-glue/p11-kit/commit/c8f8053edc9098fdb36fbb34165b8d92ed596798)! If it not crash, IMHO, we fixed that also, but we need to wait
"Wait a second. OpenSC is not updated including that commit https://github.com/OpenSC/OpenSC/commit/16456922e2a038ae38f58cffaa7696013a761b3b when you compile p11-kit?? Of course it will not work, as p11-kit is using OpenSC in full!
You will need to first compile OpenSC including that commit and then link with those new binaries while compiling p11-kit!".

Its not that simple.
Firefox still (I believe) doesn't check the return
value properly. This change:
https://bugzilla.mozilla.org/show_bug.cgi?id=1627273#c33
by Dana was only to show how it will work
when the proper check is added.

Also having 81 SCardTransmit() calls per C_GetSlotList()
and 162 SCardTransmit() calls per C_GetSlotInfo()
is a problem by itself. You usually need only a
couple of apdu exchanges to find that the token
is not supported, and return an error. So OpenSC
does things repeatedly perhaps.

So no matter how many currently available
fixes you collect, the problem will only mildly
improve.

Dana :keeler, how difficult would be to add
the checks for CKR_TOKEN_NOT_RECOGNIZED?
Then we could continue with our debugging
quest.

To make sure I understand what you're proposing, are you saying that Firefox (NSS, really) should remember if C_GetTokenInfo returns CKR_TOKEN_NOT_RECOGNIZED and if so, never query that token again? What happens if a user removes the unrecognized token and inserts one that is recognized?

Flags: needinfo?(stsp2)

I thought you can get an events about
the token insert/removal, no?

But even if you can't - currently the token
just keeps blinking w/o any pause.
And it seems to depend on a traffic -
i.e. if I do not try to open any pages,
there seem to be no accesses to the
token, either.
After CKR_TOKEN_NOT_RECOGNIZED
maybe you can query it no quicker than
once a second, and independently from
any internet traffic? I.e. you can keep
query it in some thread, but the main
thing to achieve is to get the internet
traffic unaffected by that.
What do you think?

Flags: needinfo?(stsp2)

(In reply to Dana Keeler (she/her) (use needinfo) (:keeler for reviews) from comment #77)

inserts one that is recognized

It will return CKF_TOKEN_PRESENT NOW correctly.

Still happenning with the latest 80.0.1 FF, please change to CONFIRMED. FF slows to halt and becomes unusable.

(In reply to Stas Sergeev from comment #78)

...
What do you think?

Flags: needinfo?(dkeeler)
OS: Unspecified → Linux

(In reply to Daniel from comment #80)

Still happenning with the latest 80.0.1 FF, please change to CONFIRMED. FF slows to halt and becomes unusable.

Daniel, you still crash when using a newer version, and it is related to p11-kit-proxy.so ?

Flags: needinfo?(firefox)
Keywords: crash

I am on a different computer now with Firefox 83 and this does not happen, so I am unsure what helped. I am closing this.

Flags: needinfo?(firefox)

Or rather, I am unalbe to marked this as WORKSFORME.

(In reply to Stas Sergeev from comment #78)

I thought you can get an events about
the token insert/removal, no?

There is an API that allows Firefox to do this, but this needs to happen at the NSS level.

maybe you can query it no quicker than
once a second, and independently from
any internet traffic? I.e. you can keep
query it in some thread, but the main
thing to achieve is to get the internet
traffic unaffected by that.
What do you think?

Firefox already only queries tokens no more than once every 3 seconds. NSS, however, may do it more often, so again this is an issue at the NSS layer.

(In reply to Daniel from comment #84)

Or rather, I am unalbe to marked this as WORKSFORME.

Given this, I'm going to close this as worksforme in Firefox. If anyone is still having issues with this, I suggest opening up an NSS bug.

Status: UNCONFIRMED → RESOLVED
Closed: 3 years ago
Flags: needinfo?(dkeeler)
Resolution: --- → WORKSFORME
Performance Impact: --- → P3
Keywords: perf:responsiveness
Whiteboard: [qf:p3:responsiveness][psm-backlog][psm-smartcard] → [psm-backlog][psm-smartcard]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: