Version 4.6.0-1~debian12 runs into timeouts and increases I/O wait

Avast Business Avast Business for Linux
1

Hello,

I hope this is a proper channel for reporting an issue with the latest
version of avast for linux (running on debian).

with the recent update to version 4.6.0-1~debian12 we have had a few
reports of increased I/O wait and scanning taking too long and running
into a 5 minute timeout.

Downgrading to 4.5.1-1 seems to help.

Some further background information can be found in the Proxmox community
forum:

Are you aware of any regressions with the recent release?

Should this be the wrong channel I would be grateful for a pointer to the
right way to report this.

Thanks!
Stoiko Ivanov

P.S. the e-mail address listed in the changelog of the package seems to not be active (or reachable for me)

2

Hallo,

same here. Downgrade to Avast 4.5.1 does help, but isn’t an real solution. Any idea for an better solution?

Thanks,
Thomas

3

Hi, we are aware of this issue and investigating it. For the time being please keep using version 4.5.1. Sorry for the inconvenience.

4

Actually, let me rephrase that - we’re aware that Proxmox users have some issue. Trying to find what it could be. We were not able to reproduce it yet.

5

Hi,

Thanks for picking this up and the update!

Glad to provide additional information if you need any.
From the few cases we’ve seen in the community - the following information might help:

  • setting THREADS=X (with X>0 (e.g. 3 for a 4 cpu installation) seems to fix the issue of the hanging scan-processess (Proxmox Mail Gateway has a timeout (300 seconds) on the scanning)
  • from one instance where I saw the hanging scan processes - strace on both avast and one of the scan processes did not show any syscalls going on .
  • Proxmox Mail Gateway 8.X is based on Debian 12 bookworm (and most users should have the regular debian repositories and the security repositories enabled)

Should you need any further information - let me know.
Thanks!

6

The THREADS=0 should be the same as it was in previous versions. I.e. it never created additional threads and all scanning was blocking, in respect to one session (one scan process). This only allows to scan files in parallel, i.e. scan /some/directory will list the files and scan them in multiple threads (sequentially with THREADS=0). When scanning single file, it should not have any effect.

7

@sivanov If you (or other users) could provide me a stack trace of /usr/bin/avast when the scan processes were hanged, it might help.

I.e. sudo gdb -p <pid of avast>, and enter t apply all bt.

8

@sivanov I tried to find some code regarding the Avast integration in Proxmox, but wasn’t successful. Is it open source? Can you point me where to look?

I’m looking for how is the scan tool called and how is its output processed.

9

Regarding the stacktraces - sadly we did not have this reoccur - and for our test-installation it was only for a time-frame of 6 minutes on 11.02. - and ever since setting the THREADS higher afterwards it did not reoccur - I tried setting it back to the default (simply removing the option in avast.conf) and restarting avast - but in the short time since then no hanging scan processes occurred. - I’ll ask our community for the stack-trace if they run into the issue.

Would getting the stack-traces from /proc//stack also help (should be easier for our user-base)?

Regarding how scan is called within Proxmox Mail Gateway - see our git:
https://git.proxmox.com/?p=pmg-api.git;a=blob;f=src/PMG/Utils.pm;h=0b8945f245748138a1cd6b415d5d9ead6ec655af;hb=6bbc2221e977b6872f1362d557d9f3035d495efc#l519

(translates roughly to: scan /path/to/mail-file.eml - and the output of scan is then parsed for lines starting with /path/to/mail-file.eml)

10

Thanks. The perl script looks quite innocent. We still were not able to reproduce any issue (no hangs, no slowdown). Do I understand it correctly that it took few days for the issue to occur?

Not really, that’s some stack of calls inside kernel.
I’ve found this one-liner for gdb, which is easier to run, and the output can be redirected to a file:

sudo gdb -p $(cat /var/run/avast/avast.pid) -batch -ex 'thread apply all bt' -ex detach > avastbt.txt

Having this snapshot from a case when scans hanged up would help us, as it doesn’t seem easy to reproduce.

11

after running without explicitly set THREADS variable for more than 6 days I did not get any hanging scan processes - so I think the issue is either extremely difficult to reproduce, or it might have gone away with a virus-db update?

The increased I/O Wait is probably due to the new version running multiple threads now.
(We are planning to eventually display the pressure stats from /proc as a better measure of contention).

12

Hi @sivanov, thanks for the update. The THREADS option should not affect these scans at all, it applies only when enumerating directories. No additional threads are created when scanning just a single file. This did not change in 4.6.0 - it only exposed the setting, while the default is still the same.

Regarding the I/O wait - can you please describe what is this measuring? Can I do similar measurement with commandline tools like iostat, dstat, htop etc.? I tried that but again did not find any difference.

13

we still get reports every here an there about the issue, and
today I finally managed to catch this on a system here:

[New LWP 829]                                                                               
[New LWP 830]                                                                                                                                                                                                      
[New LWP 847]                                                                               
[New LWP 848]                                                                                                                                                                                                      
[New LWP 849]                                                                               
[New LWP 850]                                                                                                                                                                                                      
[New LWP 197547]                                                                            
[Thread debugging using libthread_db enabled]                                                                                                                                                                      
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".                                                                                                                                         
syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38                                                                                                                                                                                                                                                                                                                                                                           
                                                                                                         
Thread 8 (Thread 0x7d7a027fc6c0 (LWP 197547) "avast"):                                                                                                                                                             
#0  0x00007d7a2e83b21f in __GI___poll (fds=0x7d7a027fb9f0, nfds=1, timeout=1800000) at ../sysdeps/unix/sysv/linux/poll.c:29                                                                                                                                                                                                                                                                                                            
#1  0x00007d79ece98240 in ?? () from /var/lib/avast/defs/25031806/engine.so
#2  0x00007d79ece92e3a in ?? () from /var/lib/avast/defs/25031806/engine.so
#3  0x00007d79ece92fea in ?? () from /var/lib/avast/defs/25031806/engine.so
#4  0x00007d79ecc88845 in ?? () from /var/lib/avast/defs/25031806/engine.so
#5  0x00007d79ece5e216 in ?? () from /var/lib/avast/defs/25031806/engine.so
#6  0x00007d7a2e7c81f5 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#7  0x00007d7a2e84889c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 7 (Thread 0x7d7a11bfc6c0 (LWP 850) "avast"):
#0  0x00007d7a2e80e545 in __GI___clock_nanosleep (clock_id=clock_id@entry=0, flags=flags@entry=0, req=0x7d7a11bfba30, rem=0x7d7a11bfba60) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:48
#1  0x00007d7a2e812e53 in __GI___nanosleep (req=<optimized out>, rem=<optimized out>) at ../sysdeps/unix/sysv/linux/nanosleep.c:25
#2  0x000058aabde51d56 in ?? ()
#3  0x00007d7a2ead44a3 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x00007d7a2e7c81f5 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#5  0x00007d7a2e84889c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 6 (Thread 0x7d7a123fd6c0 (LWP 849) "avast"):
#0  __futex_abstimed_wait_common64 (private=0, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x58aabe0b6a28) at ./nptl/futex-internal.c:57
#1  __futex_abstimed_wait_common (futex_word=futex_word@entry=0x58aabe0b6a28, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=0, cancel=cancel@entry=true) at ./nptl/futex-internal.c:87
#2  0x00007d7a2e7c4f7b in __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x58aabe0b6a28, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=0) at ./nptl/futex-internal.c:139
#3  0x00007d7a2e7c75d8 in __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x58aabe0b6a40, cond=0x58aabe0b6a00) at ./nptl/pthread_cond_wait.c:503
#4  ___pthread_cond_wait (cond=0x58aabe0b6a00, mutex=0x58aabe0b6a40) at ./nptl/pthread_cond_wait.c:618
#5  0x000058aabde51c5b in ?? ()
#6  0x00007d7a2ead44a3 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#7  0x00007d7a2e7c81f5 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#8  0x00007d7a2e84889c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 5 (Thread 0x7d7a12bfe6c0 (LWP 848) "avast"):
#0  __futex_abstimed_wait_common64 (private=0, cancel=true, abstime=0x7d7a12bfda70, op=393, expected=0, futex_word=0x7d7a2953c8dc) at ./nptl/futex-internal.c:57
#1  __futex_abstimed_wait_common (futex_word=futex_word@entry=0x7d7a2953c8dc, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x7d7a12bfda70, private=private@entry=0, cancel=cancel@entry=true) at ./nptl/futex-internal.c:87
#2  0x00007d7a2e7c4f7b in __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x7d7a2953c8dc, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x7d7a12bfda70, private=private@entry=0) at ./nptl/futex-internal.c:139
#3  0x00007d7a2e7c78bc in __pthread_cond_wait_common (abstime=0x7d7a12bfda70, clockid=0, mutex=0x7d7a2953c8e0, cond=0x7d7a2953c8b0) at ./nptl/pthread_cond_wait.c:503
#4  ___pthread_cond_timedwait64 (cond=0x7d7a2953c8b0, mutex=0x7d7a2953c8e0, abstime=0x7d7a12bfda70) at ./nptl/pthread_cond_wait.c:643
#5  0x000058aabdf5ea8e in ?? ()
#6  0x000058aabdefe086 in ?? ()
#7  0x000058aabdefe129 in ?? ()
#8  0x000058aabdf60916 in ?? ()
#9  0x00007d7a2e7c81f5 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#10 0x00007d7a2e84889c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 4 (Thread 0x7d7a133ff6c0 (LWP 847) "avast"):
#0  0x00007d7a2e83b21f in __GI___poll (fds=0x7d7a133fe9f0, nfds=1, timeout=1800000) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007d7a27a981c0 in ?? () from /var/lib/avast/defs/25031700/engine.so
#2  0x00007d7a27a92dba in ?? () from /var/lib/avast/defs/25031700/engine.so
#3  0x00007d7a27a92f6a in ?? () from /var/lib/avast/defs/25031700/engine.so
#4  0x00007d7a27888815 in ?? () from /var/lib/avast/defs/25031700/engine.so
#5  0x00007d7a27a5e196 in ?? () from /var/lib/avast/defs/25031700/engine.so
#6  0x00007d7a2e7c81f5 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#7  0x00007d7a2e84889c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 3 (Thread 0x7d7a2d35a6c0 (LWP 830) "avast"):
#0  __futex_abstimed_wait_common64 (private=0, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x58aabe0b6afc) at ./nptl/futex-internal.c:57
#1  __futex_abstimed_wait_common (futex_word=futex_word@entry=0x58aabe0b6afc, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=0, cancel=cancel@entry=true) at ./nptl/futex-internal.c:87
#2  0x00007d7a2e7c4f7b in __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x58aabe0b6afc, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=0) at ./nptl/futex-internal.c:139
#3  0x00007d7a2e7c75d8 in __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x58aabe0b6aa8, cond=0x58aabe0b6ad0) at ./nptl/pthread_cond_wait.c:503
#4  ___pthread_cond_wait (cond=0x58aabe0b6ad0, mutex=0x58aabe0b6aa8) at ./nptl/pthread_cond_wait.c:618
#5  0x000058aabde532b3 in ?? ()
#6  0x000058aabde5349d in ?? ()
#7  0x00007d7a2ead44a3 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#8  0x00007d7a2e7c81f5 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#9  0x00007d7a2e84889c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 2 (Thread 0x7d7a2db5b6c0 (LWP 829) "avast"):
#0  __futex_abstimed_wait_common64 (private=0, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x58aac664cab8) at ./nptl/futex-internal.c:57
#1  __futex_abstimed_wait_common (futex_word=futex_word@entry=0x58aac664cab8, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=0, cancel=cancel@entry=true) at ./nptl/futex-internal.c:87
#2  0x00007d7a2e7c4f7b in __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x58aac664cab8, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=0) at ./nptl/futex-internal.c:139
#3  0x00007d7a2e7c75d8 in __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x58aac664ca68, cond=0x58aac664ca90) at ./nptl/pthread_cond_wait.c:503
#4  ___pthread_cond_wait (cond=0x58aac664ca90, mutex=0x58aac664ca68) at ./nptl/pthread_cond_wait.c:618
#5  0x000058aabde44155 in ?? ()
#6  0x000058aabde3eaf3 in ?? ()
#7  0x00007d7a2ead44a3 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#8  0x00007d7a2e7c81f5 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#9  0x00007d7a2e84889c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 1 (Thread 0x7d7a2db5ef80 (LWP 827) "avast"):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x000058aabe00ccc3 in ?? ()
#2  0x000058aabe00e51f in ?? ()
#3  0x000058aabde17749 in ?? ()
#4  0x000058aabde10774 in ?? ()
#5  0x00007d7a2e76624a in __libc_start_call_main (main=main@entry=0x58aabde10760, argc=argc@entry=2, argv=argv@entry=0x7fff3fa25018) at ../sysdeps/nptl/libc_start_call_main.h:58
#6  0x00007d7a2e766305 in __libc_start_main_impl (main=0x58aabde10760, argc=2, argv=0x7fff3fa25018, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fff3fa25008) at ../csu/libc-start.c:360
#7  0x000058aabde15501 in ?? ()
[Inferior 1 (process 827) detached]

strace output of the avast process - hangs at io_uring_enter:

root@pmgtest:~# strace -fp 827
strace: Process 827 attached with 8 threads
[pid 197547] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid   850] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid   849] futex(0x58aabe0b6a2c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid   848] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid   830] futex(0x58aabe0b6afc, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid   829] futex(0x58aac664cab8, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid   847] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid   827] io_uring_enter(6, 0, 1, IORING_ENTER_GETEVENTS, NULL, 0^Cstrace: Process 827 detached
 <detached ...>
strace: Process 829 detached
strace: Process 830 detached
strace: Process 847 detached
strace: Process 848 detached
strace: Process 849 detached
strace: Process 850 detached
strace: Process 197547 detached

Let me know if there’s anything else I could help with.
Thanks!

14

Thanks. Was it captured at the time when the scans were waiting or hanged? The io_uring_enter is blocking even normally, but yes, we suspect that io_uring is causing the troubles and will disable it in version 4.6.1, that will be released soon.

15

did not strace all scan processes - but there were quite a few (number of filter-processes started, and each had one scan child) - I did strace a few but did not record the strace output (they were inside a syscall, IIRC /proc//stack mentioned epoll - so maybe the 2-3 I straced were waiting.

I can try to reproduce this (yesterday I downgraded avast as it was interfering) - just let me know what would help you and how to see if it’s waiting or hanging.

Thanks!

Thanks for the heads up - I’ll try to install it asap and provide some feedback