Bug#987704: webext-foxyproxy: 100% cpu stalling

[Christoph Anton Mitterer]

Hey.

I think this might be the same than:
#986567
#986027

and not just affecting foxyproxy... but rather all extensions.

Cheers,
Chris.

Bug#987704: webext-foxyproxy: 100% cpu stalling

[Uwe Kleine-König]

On Wed, Apr 28, 2021 at 09:00:47AM +0200, Uwe Kleine-König wrote:
> Package: webext-foxyproxy
> Version: 7.5.1+dfsg-1
> Severity: normal
> 
> Hello,
> 
> occationally (I didn't find the trigger yet) a subprocess of firefox
> occupies one complete cpu. There is no functional problem, all seems to
> work just fine.
> 
> It was not clear to me what part of firefox is responsible for it, but
> now I think it is foxyproxy. I started a new profile and the problem
> didn't occur until I enabled foxyproxy. Today I looked in more detail
> into the process' status before closing firefox (which cures the
> problem):
> 
> According to strace the process (with pid 16443) does:
> 
> read(8, "\372", 1)  = 1
> recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
> temporarily unavailable)
> recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
> temporarily unavailable)
> poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
> events=POLLIN}], 3, 0) = 0 (Timeout)
> write(9, "\372", 1) = 1
> recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
> temporarily unavailable)
> recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
> temporarily unavailable)
> poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
> events=POLLIN}], 3, 0) = 1 ([{fd=8, revents=POLLIN}])
>
> in a tight loop.

I checked now what that WebExtensions process does directly after
starting, there it looks like following:

09:26:10.657028 restart_syscall(<... resuming interrupted read ...>) = 1
09:26:11.155145 read(8, "\372", 1)  = 1
09:26:11.155647 futex(0x7ff2ccf2aeb4, FUTEX_WAKE_PRIVATE, 1) = 1
09:26:11.156104 write(9, "\372", 1) = 1
09:26:11.156379 recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
09:26:11.156848 poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 1 ([{fd=8, revents=POLLIN}])
09:26:11.157099 read(8, "\372", 1)  = 1
09:26:11.157342 recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
09:26:11.157457 poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 0 (Timeout)
09:26:11.157786 recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
09:26:11.157940 poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 0 (Timeout)
09:26:11.158081 write(15, "\0", 1)  = 1
09:26:11.158385 recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
09:26:11.158535 poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 1 ([{fd=8, revents=POLLIN}])
09:26:11.158652 read(8, "\372", 1)  = 1
09:26:11.158754 recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
09:26:11.158852 poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 0 (Timeout)
09:26:11.158974 write(9, "\372", 1) = 1
09:26:11.159077 recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
09:26:11.159174 poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 1 ([{fd=8, revents=POLLIN}])
09:26:11.159284 read(8, "\372", 1)  = 1
09:26:11.159395 recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
09:26:11.159496 poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 0 (Timeout)
09:26:11.159964 futex(0x7ff2ddd32404, FUTEX_WAKE_PRIVATE, 1) = 1
09:26:11.160060 futex(0x7ff2ddd323a8, FUTEX_WAKE_PRIVATE, 1) = 1
09:26:11.160201 write(15, "\0", 1)  = 1
09:26:11.160340 recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
09:26:11.160554 poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 0 (Timeout)
09:26:11.160786 recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
09:26:11.160990 poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 0 (Timeout)
09:26:11.161118 recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
09:26:11.161218 poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 0 (Timeout)
09:26:11.161320 recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
09:26:11.161416 poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, -1) = 1 ([{fd=8, revents=POLLIN}])
09:26:15.812258 read(8, "\372", 1)  = 1
09:26:15.812513 write(15, "\0", 1)  = 1
09:26:15.812724 write(9, "\372", 1) = 1
09:26:15.813013 recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
09:26:15.813422 poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 1 ([{fd=8, revents=POLLIN}])
09:26:15.813761 read(8, "\372", 1)  = 1
09:26:15.813968 recvmsg(17, 

Bug#987704: webext-foxyproxy: 100% cpu stalling

[Daniel Baumann]

Hi Uwe,

thanks for your report.

On 4/28/21 9:00 AM, Uwe Kleine-König wrote:
> I have no idea how to further debug that.

me neither :)

I'll open a issue in the upstream repo on github..

Regards,
Daniel

Bug#987704: webext-foxyproxy: 100% cpu stalling

[Uwe Kleine-König]

Package: webext-foxyproxy
Version: 7.5.1+dfsg-1
Severity: normal

Hello,

occationally (I didn't find the trigger yet) a subprocess of firefox
occupies one complete cpu. There is no functional problem, all seems to
work just fine.

It was not clear to me what part of firefox is responsible for it, but
now I think it is foxyproxy. I started a new profile and the problem
didn't occur until I enabled foxyproxy. Today I looked in more detail
into the process' status before closing firefox (which cures the
problem):

According to strace the process (with pid 16443) does:

read(8, "\372", 1)  = 1
recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 0 (Timeout)
write(9, "\372", 1) = 1
recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
recvmsg(17, {msg_namelen=0}, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
poll([{fd=8, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, 
events=POLLIN}], 3, 0) = 1 ([{fd=8, revents=POLLIN}])

in a tight loop.

ls /proc/16443 contains:
lrwxrwxrwx   1 uwe  uwe  0 Apr 28 08:25 cwd -> '/proc/16444/fdinfo (deleted)'
lrwxrwxrwx   1 uwe  uwe  0 Apr 28 08:25 root -> '/proc/16444/fdinfo (deleted)'

and after I killed the process, normal web surfing is unaffected, and
foxyproxy doesn't work any more. (That is, the icon still appears in the
address bar and I can reconfigure foxyproxy, but when I access a site
that requires to pick a non-default proxy setting, firefox tries to
access it directly.)

I clicked a bit around in the developer console, looking for service
workers, but didn't find anything.
In the console there are a few messages:

Promise resolved after context unloaded
background.js:53
Object { mode: "patterns", proxySettings: (2) […] }
 activeSettings in patterns mode background.js:176:13
background.js: loaded proxy settings from storage. background.js:105:11
Promise resolved after context unloaded
vapi-background.js:1456
The Components object is deprecated. It will soon be removed. 
regex.js:12:20

I have no idea how to further debug that.

Best regards
Uwe

-- System Information:
Debian Release: bullseye/sid
  APT prefers testing-debug
  APT policy: (700, 'testing-debug'), (700, 'stable-updates'), (700, 
'testing'), (700, 'stable'), (600, 'unstable'), (500, 'unstable-debug'), (500, 
'stable-debug'), (500, 'oldstable'), (499, 'experimental')
Architecture: amd64 (x86_64)
Foreign Architectures: i386, armhf, arm64

Kernel: Linux 5.10.0-6-amd64 (SMP w/4 CPU threads)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages webext-foxyproxy depends on:
ii  fonts-font-awesome  5.0.10+really4.7.0~dfsg-4

Versions of packages webext-foxyproxy recommends:
ii  firefox  88.0-1
ii  firefox-esr  78.10.0esr-1

webext-foxyproxy suggests no packages.

-- no debconf information