safing / portmaster

🏔 Love Freedom - ❌ Block Mass Surveillance
https://safing.io
GNU General Public License v3.0
9.17k stars 288 forks source link

High CPU use with 0.5.7/0.6.0 on Linux #197

Closed squalou closed 3 years ago

squalou commented 3 years ago

Please use this template when reporting a bug and provide as much info as possible. Not doing so may cause the bug to receive lower priority. You can remove any sections from this template that does not fit your issue.

Checklist:

I've read #155 so I was hoping performances issues fixed.

What happened:

Just installed using provided PKGBUILD

After 5 minutes use, portmaster-core was using around 50% of a quad core i7,which make it unusable

What you expected to happen:

Keep a 'reasonable' CPU use. Reasonable being what you could expect from a ittle-snitch, opensnitch, douane, or the like. (anything above 2 - 3 % IMHO make it a no-go on a modern machine)

How to reproduce it (as minimally and precisely as possible):

Install on arch, follow instructions, wait, launch top

Anything else we need to know?:

Environment:

ArchLinux kernel 5.8.12

Portmaster Version:

0.5.7

Operating System:

NAME="Arch Linux"
PRETTY_NAME="Arch Linux"
ID=arch
BUILD_ID=rolling
ANSI_COLOR="38;2;23;147;209"
HOME_URL="https://www.archlinux.org/"
DOCUMENTATION_URL="https://wiki.archlinux.org/"
SUPPORT_URL="https://bbs.archlinux.org/"
BUG_REPORT_URL="https://bugs.archlinux.org/"
LOGO=archlinux

`

dhaavi commented 3 years ago

This might be the filterlist prepping being in progress. The Portmaster normally operates quite efficiently, thus my guess is that the high CPU usage may just be bound to high I/O workload. Did the UI give you any hints?

A colleague runs the Portmaster on his Arch machine without problems. I'll ask him to chime in if we hit a wall.

For further analysis: What kind of storage was the Portmaster installed on / using? Can you supply logs of the incident?

squalou commented 3 years ago

Hi, thanks for the quick reply.

I have removed it for now, will reinstall this evening to check the logs and add them here. (it's on a laptop I use for work during day).

didn't see anyhting suspicious in the UI (but didn't realy know where to look I admit)

Storage is Nvme SSD.

BTW : PKGBUILD says it's using version 0.4.2-2, but then it does a kind of autoupdate if I'm right ? 0.5.7 is the version displayed in the UI, not in the package generated, it's a bit confusing. Linux packages should be updated through linux package managers only IMHO. This is to say : maybe I'm not runinng the version I think I do :-)

squalou commented 3 years ago

I had a quick look at logs, they are quite verbose, with LOTS of mesages regarding two apps.

But even when I stopped these two for a quick test, (then, logs became almost silent) portmaster-core stayed with 35 - 40 % cpu use in top.

Here's an extract

Station/CloudStation.app/bin/cloud-drive-ui:2431 -> 127.0.0.1, endpoint is not blocked (default=permit)
ESC[34m201124 08:46:01.679 connection:207 ▶ INFO 808ESC[0m filter: granting connection myuser:/home/myuser/.CloudStationBackup/CloudStation.app/bin/cloud-backup-ui:2432 -> 127.0.0.1, endpoint is not blocked (default=permit)
ESC[34m201124 08:46:01.706 connection:207 ▶ INFO 809ESC[0m filter: granting connection myuser:/home/myuser/.CloudStation/CloudStation.app/bin/cloud-drive-ui:2431 -> 127.0.0.1, endpoint is not blocked (default=permit)
ESC[34m201124 08:46:02.740 connection:207 ▶ INFO 810ESC[0m filter: granting connection myuser:/home/myuser/.CloudStationBackup/CloudStation.app/bin/cloud-backup-ui:2432 -> 127.0.0.1, endpoint is not blocked (default=permit)
ESC[34m201124 08:46:02.768 connection:207 ▶ INFO 811ESC[0m filter: granting connection myuser:/home/myuser/.CloudStation/CloudStation.app/bin/cloud-drive-ui:2431 -> 127.0.0.1, endpoint is not blocked (default=permit)
ESC[34m201124 08:46:03.804 connection:207 ▶ INFO 812ESC[0m filter: granting connection myuser:/home/myuser/.CloudStationBackup/CloudStation.app/bin/cloud-backup-ui:2432 -> 127.0.0.1, endpoint is not blocked (default=permit)
ESC[34m201124 08:46:03.838 connection:207 ▶ INFO 813ESC[0m filter: granting connection myuser:/home/myuser/.CloudStation/CloudStation.app/bin/cloud-drive-ui:2431 -> 127.0.0.1, endpoint is not blocked (default=permit)
ESC[34m201124 08:46:04.878 connection:207 ▶ INFO 814ESC[0m filter: granting connection myuser:/home/myuser/.CloudStationBackup/CloudStation.app/bin/cloud-backup-ui:2432 -> 127.0.0.1, endpoint is not blocked (default=permit)
ESC[34m201124 08:46:04.905 connection:207 ▶ INFO 815ESC[0m filter: granting connection myuser:/home/myuser/.CloudStation/CloudStation.app/bin/cloud-drive-ui:2431 -> 127.0.0.1, endpoint is not blocked (default=permit)
squalou commented 3 years ago

also, no error logs in "core" but lots in "app" 2000+ lines in a few minutes. They don't even look like errors.

351   │ http://127.0.0.1:817/ui/modules/monitor/js/app.18f611eb.js:1:365025: CONSOLE LOG #0: update network:tree/150560/PL/6-10.9.20.22-47088-10.9.3.3-6690
2352   │ http://127.0.0.1:817/ui/modules/monitor/js/app.18f611eb.js:1:365025: CONSOLE LOG #0: update network:tree/150560/PH/6-127.0.0.1-47762-127.0.0.1-1026
2353   │ http://127.0.0.1:817/ui/modules/monitor/js/app.18f611eb.js:1:365025: CONSOLE LOG #0: update network:tree/150609/PH/6-127.0.0.1-36626-127.0.0.1-1029
2354   │ http://127.0.0.1:817/ui/modules/monitor/js/app.18f611eb.js:1:365025: CONSOLE LOG #0: update network:tree/150560/PH/6-127.0.0.1-47758-127.0.0.1-1026
2355   │ http://127.0.0.1:817/ui/modules/monitor/js/app.18f611eb.js:1:365025: CONSOLE LOG #0: update network:tree/150609/PH/6-127.0.0.1-36626-127.0.0.1-1029
2356   │ http://127.0.0.1:817/ui/modules/monitor/js/app.18f611eb.js:1:365025: CONSOLE LOG #0: update network:tree/150560/PH/6-127.0.0.1-47758-127.0.0.1-1026
2357   │ http://127.0.0.1:817/ui/modules/monitor/js/app.18f611eb.js:1:365025: CONSOLE LOG #0: update network:tree/150609/PH/6-127.0.0.1-36638-127.0.0.1-1029
2358   │ http://127.0.0.1:817/ui/modules/monitor/js/app.18f611eb.js:1:365025: CONSOLE LOG #0: update network:tree/150609/PH/6-127.0.0.1-36638-127.0.0.1-1029
dhaavi commented 3 years ago

We have just released v0.6.0. There are loads of changes in there. Just to be sure, please install again with the new installer to see if the issue persists.

squalou commented 3 years ago

Well. ...

You made an incredible work with this version, I admit !

But in my case, issue is stillfar from fixed :

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                                                                                                 
 346026 myuser+   20   0 4587112 161548  96708 R  55,7   1,0   2:35.13 portmaster-app_                                                                                                                                                         
 345831 root      20   0 2599188 183640 111584 S  53,4   1,1   3:40.54 portmaster-core                                                                                                                                                         
 346020 myuser+   20   0  493684 107380  69180 R  45,2   0,7   1:38.87 portmaster-app_                                                                                                                                                         
   1060 root      20   0  954920 242860 211252 S  18,7   1,5 154:57.00 Xorg            
dhaavi commented 3 years ago

You made an incredible work with this version, I admit !

Thanks!

Also thank you for testing again so quickly. Now that the release pressure is gone, let's take a closer look:

PKGBUILD says it's using version 0.4.2-2

That is the version of the installer, which follows the version of portmaster-start our daemon handler. They are now at v0.5.0, while the Portmaster core is now at v0.6.0.

I had a quick look at logs, they are quite verbose, with LOTS of mesages regarding two apps.

That should not be a problem at all. That is nothing compared to the trace output - which we are going after now. I hope we can find something there.

Before you start, maybe close all applications you can in order to reduce clutter. Then, use the following command to start the core manually and get the full trace output. If there isn't anything sensitive in there, it would be great if you could upload the log to https://bin.privacytools.io/ - be sure to set the expiry to one week.

# stop the portmaster service
sudo systemctl stop portmaster

# manually start the core
sudo /var/lib/portmaster/updates/linux_amd64/core/portmaster-core_v0-6-0 --data /var/lib/portmaster -- --log trace

Also, while Portmaster is running that way and consuming lots of resources, do this to output a stack dump, this might also give a hint at what is going on:

sudo pkill -USR1 portmaster-core
squalou commented 3 years ago

Thank you for the explanations : it is all very clear now.

first : console output. Nothing weird, INFO messages only

There are some warnings to bein with, but they seem 'ok', copying them just so you know :

201125 16:03:20.795 sts/lookup:021 ▶ WARN 096 intel/filterlists: not searching for cache:intel/filterlists/lists/asn/16509 because filterlists not loaded

and now the stack dump : (after a few minutes, with cpu stabilized at aroud 45% of one core)

===== PRINTING STACK ON REQUEST =====
goroutine profile: total 49
4 @ 0x438d50 0x407b57 0x40781b 0xa9aac6 0xa99410 0xa99fa1 0xa980c0 0xa95cb4 0xa95a10 0xa9593e 0xaa3af0 0x466ff1
#   0xa9aac5    github.com/safing/portmaster/vendor/github.com/mdlayher/netlink.(*lockedNetNSGoroutine).run+0xb5    /home/user/go/src/github.com/safing/portmaster/vendor/github.com/mdlayher/netlink/conn_linux.go:771
#   0xa9940f    github.com/safing/portmaster/vendor/github.com/mdlayher/netlink.(*sysSocket).read+0xdf          /home/user/go/src/github.com/safing/portmaster/vendor/github.com/mdlayher/netlink/conn_linux.go:377
#   0xa99fa0    github.com/safing/portmaster/vendor/github.com/mdlayher/netlink.(*sysSocket).Recvmsg+0x170      /home/user/go/src/github.com/safing/portmaster/vendor/github.com/mdlayher/netlink/conn_linux.go:543
#   0xa980bf    github.com/safing/portmaster/vendor/github.com/mdlayher/netlink.(*conn).Receive+0xef            /home/user/go/src/github.com/safing/portmaster/vendor/github.com/mdlayher/netlink/conn_linux.go:147
#   0xa95cb3    github.com/safing/portmaster/vendor/github.com/mdlayher/netlink.(*Conn).receive+0x73            /home/user/go/src/github.com/safing/portmaster/vendor/github.com/mdlayher/netlink/conn.go:288
#   0xa95a0f    github.com/safing/portmaster/vendor/github.com/mdlayher/netlink.(*Conn).lockedReceive+0x3f      /home/user/go/src/github.com/safing/portmaster/vendor/github.com/mdlayher/netlink/conn.go:247
#   0xa9593d    github.com/safing/portmaster/vendor/github.com/mdlayher/netlink.(*Conn).Receive+0x7d            /home/user/go/src/github.com/safing/portmaster/vendor/github.com/mdlayher/netlink/conn.go:240
#   0xaa3aef    github.com/safing/portmaster/vendor/github.com/florianl/go-nfqueue.(*Nfqueue).socketCallback+0x33f  /home/user/go/src/github.com/safing/portmaster/vendor/github.com/florianl/go-nfqueue/nfqueue_gteq_1.12.go:146

4 @ 0x438d50 0x431cda 0x431245 0x497375 0x49aab6 0x49aa93 0x4a40b5 0xa9b25d 0xa9ccd0 0xa9da0d 0xa9d6ca 0x466ff1
#   0x431244    internal/poll.runtime_pollWait+0x54                                 /usr/local/go/src/runtime/netpoll.go:203
#   0x497374    internal/poll.(*pollDesc).wait+0x44                                 /usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#   0x49aab5    internal/poll.(*pollDesc).waitRead+0xf5                                 /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#   0x49aa92    internal/poll.(*FD).RawRead+0xd2                                    /usr/local/go/src/internal/poll/fd_unix.go:534
#   0x4a40b4    os.(*rawConn).Read+0x64                                         /usr/local/go/src/os/rawconn.go:31
#   0xa9b25c    github.com/safing/portmaster/vendor/github.com/mdlayher/netlink.fdread+0x9c             /home/user/go/src/github.com/safing/portmaster/vendor/github.com/mdlayher/netlink/fdcall_gteq_1.12.go:21
#   0xa9cccf    github.com/safing/portmaster/vendor/github.com/mdlayher/netlink.(*sysSocket).read.func1+0x3f        /home/user/go/src/github.com/safing/portmaster/vendor/github.com/mdlayher/netlink/conn_linux.go:378
#   0xa9da0c    github.com/safing/portmaster/vendor/github.com/mdlayher/netlink.(*lockedNetNSGoroutine).run.func1+0x4c  /home/user/go/src/github.com/safing/portmaster/vendor/github.com/mdlayher/netlink/conn_linux.go:769
#   0xa9d6c9    github.com/safing/portmaster/vendor/github.com/mdlayher/netlink.newLockedNetNSGoroutine.func1+0x179 /home/user/go/src/github.com/safing/portmaster/vendor/github.com/mdlayher/netlink/conn_linux.go:742

4 @ 0x438d50 0x448f13 0xb6a9fb 0x466ff1
#   0xb6a9fa    github.com/safing/spn/vendor/github.com/xtaci/kcp-go.(*TimedSched).sched+0x2ba  /home/user/go/src/github.com/safing/spn/vendor/github.com/xtaci/kcp-go/timedsched.go:67

2 @ 0x438d50 0x448f13 0x6572cc 0x53dd60 0x53d7a1 0x466ff1
#   0x6572cb    github.com/safing/portbase/database.(*Interface).DelayedCacheWriter+0x1cb   /home/user/go/src/github.com/safing/portbase/database/interface_cache.go:34
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f         /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140     /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

2 @ 0x438d50 0x448f13 0x892264 0x53dd60 0x53d7a1 0x466ff1
#   0x892263    github.com/safing/portbase/rng.(*Feeder).run+0x2c3          /home/user/go/src/github.com/safing/portbase/rng/entropy.go:119
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x40cf44 0x44dbbc 0x500e32 0x466ff1
#   0x44dbbb    os/signal.signal_recv+0x9b  /usr/local/go/src/runtime/sigqueue.go:147
#   0x500e31    os/signal.loop+0x21     /usr/local/go/src/os/signal/signal_unix.go:23

1 @ 0x438d50 0x407b57 0x40781b 0x87bbab 0x466ff1
#   0x87bbaa    github.com/safing/portmaster/vendor/github.com/godbus/dbus.newConn.func1+0x4a   /home/user/go/src/github.com/safing/portmaster/vendor/github.com/godbus/dbus/conn.go:253

1 @ 0x438d50 0x407b57 0x40781b 0xa75046 0x53dd60 0x53d7a1 0x466ff1
#   0xa75045    github.com/safing/portmaster/resolver.listenToMDNS+0x555        /home/user/go/src/github.com/safing/portmaster/resolver/resolver-mdns.go:129
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x431cda 0x431245 0x497375 0x49820b 0x4981ed 0x60296f 0x615ebe 0xa7730c 0xa841ca 0x53dd60 0x53d7a1 0x466ff1
#   0x431244    internal/poll.runtime_pollWait+0x54                 /usr/local/go/src/runtime/netpoll.go:203
#   0x497374    internal/poll.(*pollDesc).wait+0x44                 /usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#   0x49820a    internal/poll.(*pollDesc).waitRead+0x19a                /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#   0x4981ec    internal/poll.(*FD).Read+0x17c                      /usr/local/go/src/internal/poll/fd_unix.go:169
#   0x60296e    net.(*netFD).Read+0x4e                          /usr/local/go/src/net/fd_unix.go:202
#   0x615ebd    net.(*conn).Read+0x8d                           /usr/local/go/src/net/net.go:184
#   0xa7730b    github.com/safing/portmaster/resolver.listenForDNSPackets+0x8b      /home/user/go/src/github.com/safing/portmaster/resolver/resolver-mdns.go:331
#   0xa841c9    github.com/safing/portmaster/resolver.listenToMDNS.func1+0x49       /home/user/go/src/github.com/safing/portmaster/resolver/resolver-mdns.go:85
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x431cda 0x431245 0x497375 0x49820b 0x4981ed 0x60296f 0x615ebe 0xa7730c 0xa8423a 0x53dd60 0x53d7a1 0x466ff1
#   0x431244    internal/poll.runtime_pollWait+0x54                 /usr/local/go/src/runtime/netpoll.go:203
#   0x497374    internal/poll.(*pollDesc).wait+0x44                 /usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#   0x49820a    internal/poll.(*pollDesc).waitRead+0x19a                /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#   0x4981ec    internal/poll.(*FD).Read+0x17c                      /usr/local/go/src/internal/poll/fd_unix.go:169
#   0x60296e    net.(*netFD).Read+0x4e                          /usr/local/go/src/net/fd_unix.go:202
#   0x615ebd    net.(*conn).Read+0x8d                           /usr/local/go/src/net/net.go:184
#   0xa7730b    github.com/safing/portmaster/resolver.listenForDNSPackets+0x8b      /home/user/go/src/github.com/safing/portmaster/resolver/resolver-mdns.go:331
#   0xa84239    github.com/safing/portmaster/resolver.listenToMDNS.func2+0x49       /home/user/go/src/github.com/safing/portmaster/resolver/resolver-mdns.go:96
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x431cda 0x431245 0x497375 0x49820b 0x4981ed 0x60296f 0x615ebe 0xa7730c 0xa842aa 0x53dd60 0x53d7a1 0x466ff1
#   0x431244    internal/poll.runtime_pollWait+0x54                 /usr/local/go/src/runtime/netpoll.go:203
#   0x497374    internal/poll.(*pollDesc).wait+0x44                 /usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#   0x49820a    internal/poll.(*pollDesc).waitRead+0x19a                /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#   0x4981ec    internal/poll.(*FD).Read+0x17c                      /usr/local/go/src/internal/poll/fd_unix.go:169
#   0x60296e    net.(*netFD).Read+0x4e                          /usr/local/go/src/net/fd_unix.go:202
#   0x615ebd    net.(*conn).Read+0x8d                           /usr/local/go/src/net/net.go:184
#   0xa7730b    github.com/safing/portmaster/resolver.listenForDNSPackets+0x8b      /home/user/go/src/github.com/safing/portmaster/resolver/resolver-mdns.go:331
#   0xa842a9    github.com/safing/portmaster/resolver.listenToMDNS.func3+0x49       /home/user/go/src/github.com/safing/portmaster/resolver/resolver-mdns.go:107
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x431cda 0x431245 0x497375 0x49820b 0x4981ed 0x60296f 0x615ebe 0xa7730c 0xa8431a 0x53dd60 0x53d7a1 0x466ff1
#   0x431244    internal/poll.runtime_pollWait+0x54                 /usr/local/go/src/runtime/netpoll.go:203
#   0x497374    internal/poll.(*pollDesc).wait+0x44                 /usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#   0x49820a    internal/poll.(*pollDesc).waitRead+0x19a                /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#   0x4981ec    internal/poll.(*FD).Read+0x17c                      /usr/local/go/src/internal/poll/fd_unix.go:169
#   0x60296e    net.(*netFD).Read+0x4e                          /usr/local/go/src/net/fd_unix.go:202
#   0x615ebd    net.(*conn).Read+0x8d                           /usr/local/go/src/net/net.go:184
#   0xa7730b    github.com/safing/portmaster/resolver.listenForDNSPackets+0x8b      /home/user/go/src/github.com/safing/portmaster/resolver/resolver-mdns.go:331
#   0xa84319    github.com/safing/portmaster/resolver.listenToMDNS.func4+0x49       /home/user/go/src/github.com/safing/portmaster/resolver/resolver-mdns.go:118
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x431cda 0x431245 0x497375 0x498aaa 0x498a88 0x602c50 0x6241f1 0x622048 0x79c8a7 0x78723e 0x7847a3 0x78603f 0x784ebc 0xb9fe01 0x53dd60 0x53d7a1 0x466ff1
#   0x431244    internal/poll.runtime_pollWait+0x54                         /usr/local/go/src/runtime/netpoll.go:203
#   0x497374    internal/poll.(*pollDesc).wait+0x44                         /usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#   0x498aa9    internal/poll.(*pollDesc).waitRead+0x219                        /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#   0x498a87    internal/poll.(*FD).ReadMsg+0x1f7                           /usr/local/go/src/internal/poll/fd_unix.go:243
#   0x602c4f    net.(*netFD).readMsg+0x8f                               /usr/local/go/src/net/fd_unix.go:214
#   0x6241f0    net.(*UDPConn).readMsg+0x90                             /usr/local/go/src/net/udpsock_posix.go:59
#   0x622047    net.(*UDPConn).ReadMsgUDP+0x97                              /usr/local/go/src/net/udpsock.go:139
#   0x79c8a6    github.com/safing/portmaster/vendor/github.com/miekg/dns.ReadFromSessionUDP+0xb6    /home/user/go/src/github.com/safing/portmaster/vendor/github.com/miekg/dns/udp.go:42
#   0x78723d    github.com/safing/portmaster/vendor/github.com/miekg/dns.(*Server).readUDP+0xcd     /home/user/go/src/github.com/safing/portmaster/vendor/github.com/miekg/dns/server.go:653
#   0x7847a2    github.com/safing/portmaster/vendor/github.com/miekg/dns.defaultReader.ReadUDP+0x42 /home/user/go/src/github.com/safing/portmaster/vendor/github.com/miekg/dns/server.go:161
#   0x78603e    github.com/safing/portmaster/vendor/github.com/miekg/dns.(*Server).serveUDP+0x15e   /home/user/go/src/github.com/safing/portmaster/vendor/github.com/miekg/dns/server.go:470
#   0x784ebb    github.com/safing/portmaster/vendor/github.com/miekg/dns.(*Server).ListenAndServe+0x36b /home/user/go/src/github.com/safing/portmaster/vendor/github.com/miekg/dns/server.go:310
#   0xb9fe00    github.com/safing/portmaster/nameserver.start.func1+0x30                /home/user/go/src/github.com/safing/portmaster/nameserver/nameserver.go:49
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f             /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140         /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x431cda 0x431245 0x497375 0x498aaa 0x498a88 0x602c50 0x627d21 0x6259d8 0x8785ed 0x475287 0x878d98 0x878d58 0x85f420 0x466ff1
#   0x431244    internal/poll.runtime_pollWait+0x54                             /usr/local/go/src/runtime/netpoll.go:203
#   0x497374    internal/poll.(*pollDesc).wait+0x44                             /usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#   0x498aa9    internal/poll.(*pollDesc).waitRead+0x219                            /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#   0x498a87    internal/poll.(*FD).ReadMsg+0x1f7                               /usr/local/go/src/internal/poll/fd_unix.go:243
#   0x602c4f    net.(*netFD).readMsg+0x8f                                   /usr/local/go/src/net/fd_unix.go:214
#   0x627d20    net.(*UnixConn).readMsg+0x90                                    /usr/local/go/src/net/unixsock_posix.go:115
#   0x6259d7    net.(*UnixConn).ReadMsgUnix+0x97                                /usr/local/go/src/net/unixsock.go:143
#   0x8785ec    github.com/safing/portmaster/vendor/github.com/godbus/dbus.(*oobReader).Read+0x8c       /home/user/go/src/github.com/safing/portmaster/vendor/github.com/godbus/dbus/transport_unix.go:21
#   0x475286    io.ReadAtLeast+0x86                                     /usr/local/go/src/io/io.go:310
#   0x878d97    io.ReadFull+0x117                                       /usr/local/go/src/io/io.go:329
#   0x878d57    github.com/safing/portmaster/vendor/github.com/godbus/dbus.(*unixTransport).ReadMessage+0xd7    /home/user/go/src/github.com/safing/portmaster/vendor/github.com/godbus/dbus/transport_unix.go:91
#   0x85f41f    github.com/safing/portmaster/vendor/github.com/godbus/dbus.(*Conn).inWorker+0x3f        /home/user/go/src/github.com/safing/portmaster/vendor/github.com/godbus/dbus/conn.go:348

1 @ 0x438d50 0x431cda 0x431245 0x497375 0x499bb4 0x499b96 0x603222 0x620e72 0x61f7e4 0x908fdd 0x908d27 0x9de4dd 0x53dd60 0x53d475 0x9dc947 0x466ff1
#   0x431244    internal/poll.runtime_pollWait+0x54             /usr/local/go/src/runtime/netpoll.go:203
#   0x497374    internal/poll.(*pollDesc).wait+0x44             /usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#   0x499bb3    internal/poll.(*pollDesc).waitRead+0x1d3            /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#   0x499b95    internal/poll.(*FD).Accept+0x1b5                /usr/local/go/src/internal/poll/fd_unix.go:384
#   0x603221    net.(*netFD).accept+0x41                    /usr/local/go/src/net/fd_unix.go:238
#   0x620e71    net.(*TCPListener).accept+0x31                  /usr/local/go/src/net/tcpsock_posix.go:139
#   0x61f7e3    net.(*TCPListener).Accept+0x63                  /usr/local/go/src/net/tcpsock.go:261
#   0x908fdc    net/http.(*Server).Serve+0x25c                  /usr/local/go/src/net/http/server.go:2901
#   0x908d26    net/http.(*Server).ListenAndServe+0xb6              /usr/local/go/src/net/http/server.go:2830
#   0x9de4dc    github.com/safing/portbase/api.Serve.func1+0x2c         /home/user/go/src/github.com/safing/portbase/api/router.go:67
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d474    github.com/safing/portbase/modules.(*Module).RunWorker+0xb4 /home/user/go/src/github.com/safing/portbase/modules/worker.go:48
#   0x9dc946    github.com/safing/portbase/api.Serve+0x1b6          /home/user/go/src/github.com/safing/portbase/api/router.go:66

1 @ 0x438d50 0x448f13 0x530c75 0x5308b9 0x466ff1
#   0x530c74    github.com/safing/portbase/log.writer+0x364     /home/user/go/src/github.com/safing/portbase/log/output.go:155
#   0x5308b8    github.com/safing/portbase/log.writerManager+0x98   /home/user/go/src/github.com/safing/portbase/log/output.go:112

1 @ 0x438d50 0x448f13 0x537698 0x466ff1
#   0x537697    github.com/safing/portbase/modules.microTaskScheduler+0x197 /home/user/go/src/github.com/safing/portbase/modules/microtasks.go:185

1 @ 0x438d50 0x448f13 0x53cedd 0x466ff1
#   0x53cedc    github.com/safing/portbase/modules.taskQueueHandler+0x1ac   /home/user/go/src/github.com/safing/portbase/modules/tasks.go:441

1 @ 0x438d50 0x448f13 0x53d1b8 0x466ff1
#   0x53d1b7    github.com/safing/portbase/modules.taskScheduleHandler+0xe7 /home/user/go/src/github.com/safing/portbase/modules/tasks.go:491

1 @ 0x438d50 0x448f13 0x892574 0x53dd60 0x53d7a1 0x466ff1
#   0x892573    github.com/safing/portbase/rng.fullFeeder+0x153             /home/user/go/src/github.com/safing/portbase/rng/fullfeed.go:25
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x448f13 0x892f77 0x53dd60 0x53d7a1 0x466ff1
#   0x892f76    github.com/safing/portbase/rng.osFeeder+0x1d6               /home/user/go/src/github.com/safing/portbase/rng/osfeeder.go:27
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x448f13 0x893853 0x53dd60 0x53d7a1 0x466ff1
#   0x893852    github.com/safing/portbase/rng.tickFeeder+0x242             /home/user/go/src/github.com/safing/portbase/rng/tickfeeder.go:60
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x448f13 0x93659c 0x53dd60 0x53d7a1 0x466ff1
#   0x93659b    github.com/safing/portbase/notifications.cleaner+0x10b          /home/user/go/src/github.com/safing/portbase/notifications/cleaner.go:13
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x448f13 0x93fac3 0x53dd60 0x53d7a1 0x466ff1
#   0x93fac2    github.com/safing/portmaster/netenv.monitorNetworkChanges+0x152     /home/user/go/src/github.com/safing/portmaster/netenv/network-change.go:37
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x448f13 0x940fb7 0x53dd60 0x53d7a1 0x466ff1
#   0x940fb6    github.com/safing/portmaster/netenv.monitorOnlineStatus+0x136       /home/user/go/src/github.com/safing/portmaster/netenv/online-status.go:290
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x448f13 0x942409 0x53dd60 0x53d475 0x53f619 0x466ff1
#   0x942408    github.com/safing/portmaster/status.autoPilot+0xc8          /home/user/go/src/github.com/safing/portmaster/status/autopilot.go:16
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d474    github.com/safing/portbase/modules.(*Module).RunWorker+0xb4     /home/user/go/src/github.com/safing/portbase/modules/worker.go:48
#   0x53f618    github.com/safing/portbase/modules.(*Module).StartWorker.func1+0x58 /home/user/go/src/github.com/safing/portbase/modules/worker.go:27

1 @ 0x438d50 0x448f13 0xa5ba39 0x53dd60 0x53d7a1 0x466ff1
#   0xa5ba38    github.com/safing/portmaster/profile.cleanActiveProfiles+0x178      /home/user/go/src/github.com/safing/portmaster/profile/active.go:78
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x448f13 0xa667e8 0x53dd60 0x53d7a1 0x466ff1
#   0xa667e7    github.com/safing/portmaster/profile.startProfileUpdateChecker.func1+0xe7   /home/user/go/src/github.com/safing/portmaster/profile/database.go:52
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f         /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140     /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x448f13 0xa7557e 0xa8437e 0x53dd60 0x53d7a1 0x466ff1
#   0xa7557d    github.com/safing/portmaster/resolver.handleMDNSMessages+0xed       /home/user/go/src/github.com/safing/portmaster/resolver/resolver-mdns.go:136
#   0xa8437d    github.com/safing/portmaster/resolver.listenToMDNS.func5+0x3d       /home/user/go/src/github.com/safing/portmaster/resolver/resolver-mdns.go:125
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x448f13 0xa7a6e4 0xa79e5e 0x53dd60 0x53d7a1 0x466ff1
#   0xa7a6e3    github.com/safing/portmaster/resolver.(*tcpResolverConnMgr).waitForWork+0x433   /home/user/go/src/github.com/safing/portmaster/resolver/resolver-tcp.go:311
#   0xa79e5d    github.com/safing/portmaster/resolver.(*tcpResolverConnMgr).run+0x17d       /home/user/go/src/github.com/safing/portmaster/resolver/resolver-tcp.go:238
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f         /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140     /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x448f13 0xa85a8e 0x53dd60 0x53d7a1 0x466ff1
#   0xa85a8d    github.com/safing/portmaster/network.connectionCleaner+0xfd     /home/user/go/src/github.com/safing/portmaster/network/clean.go:24
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x448f13 0xa8a042 0x53dd60 0x53d7a1 0x466ff1
#   0xa8a041    github.com/safing/portmaster/network.openDNSRequestWriter+0x111     /home/user/go/src/github.com/safing/portmaster/network/dns.go:74
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d7a0    github.com/safing/portbase/modules.(*Module).runServiceWorker+0x140 /home/user/go/src/github.com/safing/portbase/modules/worker.go:80

1 @ 0x438d50 0x448f13 0xaa9486 0x466ff1
#   0xaa9485    github.com/safing/portmaster/firewall/interception.handleInterception+0x1e5 /home/user/go/src/github.com/safing/portmaster/firewall/interception/nfqueue_linux.go:298

1 @ 0x438d50 0x448f13 0xb6af0d 0x466ff1
#   0xb6af0c    github.com/safing/spn/vendor/github.com/xtaci/kcp-go.(*TimedSched).prepend+0x27c    /home/user/go/src/github.com/safing/spn/vendor/github.com/xtaci/kcp-go/timedsched.go:103

1 @ 0x438d50 0x448f13 0xb96c97 0x53dd60 0x53d475 0x53f619 0x466ff1
#   0xb96c96    github.com/safing/portmaster/firewall.packetHandler+0xf6        /home/user/go/src/github.com/safing/portmaster/firewall/interception.go:326
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d474    github.com/safing/portbase/modules.(*Module).RunWorker+0xb4     /home/user/go/src/github.com/safing/portbase/modules/worker.go:48
#   0x53f618    github.com/safing/portbase/modules.(*Module).StartWorker.func1+0x58 /home/user/go/src/github.com/safing/portbase/modules/worker.go:27

1 @ 0x438d50 0x448f13 0xb96f87 0x53dd60 0x53d475 0x53f619 0x466ff1
#   0xb96f86    github.com/safing/portmaster/firewall.statLogger+0x246          /home/user/go/src/github.com/safing/portmaster/firewall/interception.go:340
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d474    github.com/safing/portbase/modules.(*Module).RunWorker+0xb4     /home/user/go/src/github.com/safing/portbase/modules/worker.go:48
#   0x53f618    github.com/safing/portbase/modules.(*Module).StartWorker.func1+0x58 /home/user/go/src/github.com/safing/portbase/modules/worker.go:27

1 @ 0x438d50 0x448f13 0xb99e38 0x53dd60 0x53d475 0x53f619 0x466ff1
#   0xb99e37    github.com/safing/portmaster/firewall.portsInUseCleaner+0xd7        /home/user/go/src/github.com/safing/portmaster/firewall/ports.go:75
#   0x53dd5f    github.com/safing/portbase/modules.(*Module).runWorker+0x9f     /home/user/go/src/github.com/safing/portbase/modules/worker.go:121
#   0x53d474    github.com/safing/portbase/modules.(*Module).RunWorker+0xb4     /home/user/go/src/github.com/safing/portbase/modules/worker.go:48
#   0x53f618    github.com/safing/portbase/modules.(*Module).StartWorker.func1+0x58 /home/user/go/src/github.com/safing/portbase/modules/worker.go:27

1 @ 0x525a85 0x5258a0 0x52263a 0x540d35 0x540643 0xba0506 0x438972 0x466ff1
#   0x525a84    runtime/pprof.writeRuntimeProfile+0x94          /usr/local/go/src/runtime/pprof/pprof.go:694
#   0x52589f    runtime/pprof.writeGoroutine+0x9f           /usr/local/go/src/runtime/pprof/pprof.go:656
#   0x522639    runtime/pprof.(*Profile).WriteTo+0x3d9          /usr/local/go/src/runtime/pprof/pprof.go:329
#   0x540d34    github.com/safing/portbase/run.printStackTo+0x154   /home/user/go/src/github.com/safing/portbase/run/main.go:135
#   0x540642    github.com/safing/portbase/run.Run+0x192        /home/user/go/src/github.com/safing/portbase/run/main.go:70
#   0xba0505    main.main+0xa5                      /home/user/go/src/github.com/safing/portmaster/cmds/portmaster-core/main.go:27
#   0x438971    runtime.main+0x211                  /usr/local/go/src/runtime/proc.go:203

I hope it will help,

regards

dhaavi commented 3 years ago

Thanks for the information. We were able to reproduce the issue and a fix is in progress.

I forgot to answer about the auto updating: For average users this makes the Portmaster much easier and safer to use. The auto update system does not only deliver the software, but also lots of metadata as well as intelligence data.

If the demand is there, we will see if we can provide an option to switch updating the software parts via a common package repo.

squalou commented 3 years ago

Thank you, I'm glad I could help improve !

about the autoupdate ... it's debatable, personnaly your arguments convinced me, they make sense.

A "global installer" version managed by linux distribs, that will be versionned when needed, then hot updates sound neat for a security tool.

Few things to pay attention to though I think (but we may discuss this in another ticket or elsewhere :) )

dhaavi commented 3 years ago

when removing the package using distro install tool, everything sould go (right now, lots of files being created in /var/lib cause pacman to complain for instance). Which may be complicated if an autoupdate installs a new binary sometime, for instance.

Thanks! Noted.

logs are not in a "regular" place : how are log rotation being taken care of ? (I didn't dig into eventual logrotate)

Log management is still primitive, we will tackle that in the near- to mid-term future. The logs are made in a way that will allow the Portmaster to search and analyze them in order to assist the user in troubleshooting and also to report errors to us after confirmation by the user. These features don't exist yet.

squalou commented 3 years ago

One last thing that comes to mind regarding package manager : I think (to be checked though) that the fact that at runtime, portmaster creates things in the very path where package installs things causes the "issue". Maybe "just" (yeah, I know, probably said than done ;-) ) changing a bit the working directories as compared to install directories would solve this.

Or, install all in /usr then at first run copy things under /var

Anyway : you're right, focus on features first. The rest will come in due time.

dhaavi commented 3 years ago

One last thing that comes to mind regarding package manager : I think (to be checked though) that the fact that at runtime, portmaster creates things in the very path where package installs things causes the "issue". Maybe "just" (yeah, I know, probably said than done ;-) ) changing a bit the working directories as compared to install directories would solve this.

Yes, the separation of install and work dirs is something that Linux usually wants. For now, one directory is easier to handle, especially because the structure is the same on all supported platforms.

We've had some progress on the issue itself: We identified the original problem and fixed it. Unfortunately, it only got slighty better and now the profiling tool only lists Golang internal function stacks as the CPU chewers... which is weird and will take more time to investigate.

dhaavi commented 3 years ago

Ok. I found it. There was already a fix available in a dependent library. This will be resolved with the release next week.

dhaavi commented 3 years ago

This fix was just released with v0.6.1.

Please report back if you have any further issues.

squalou commented 3 years ago

Impressive! Still in the 8 - 10 % range in top, but since it does do things, it's normal. Less than any idle browser for instance. Finally usable, good work !

dhaavi commented 3 years ago

Thanks! Yes, if there is lots of stuff going on, 8-10% seems reasonable. If almost nothing is currently active, it should drop below 1% though.