[Avcheck] Warning: bad AVP behaviour
Michael Tokarev
mjt@tls.msk.ru
Mon, 20 Aug 2001 14:39:15 +0400
I traced the problem down to a bug in AvpDaemon
Version 3.0 build 135.3 at least (version I currently
use, the latest one called AvpDaemon, with ability
to scan mails in trial/demo mode). I don't know
if this bug still exists in never kavdaemon.
I provided a test file that can reproduce this
problem almost 100% reliable, it is available
at
ftp://ftp.corpit.ru/pub/avpcheck/hidden/bugmail
This is a message addressed to me from one of
DrWeb developers, that contains developer version
of DrWeb. The funny thing is that DrWeb is a competitor
for AVP, and avp just crashes when processing this
file... ;)
Here is strace of a "session", that also shows other
avp's problems. I omitted some details.
# select loop and accepting command from client.
select(1024, [0], NULL, NULL, NULL) = 1 (in [0])
read(1024, 0xbffff060, 2048) = -1 EBADF (Bad file descriptor)
accept(0, {sin_family=AF_UNIX,
path=@
000030f5}, [11]) = 2
# note filedescriptor #2: client's control socket, not closed in parent!
select(1024, [0 2], NULL, NULL, NULL) = 1 (in [2])
read(2, "<0>Aug 20 14:19:32:/tst/13952.tm"..., 2048) = 33
fork() = 13953
# a child. How it was helpful... ;) Note: avp forks twice per request!
[pid 31577] wait4(13953, <unfinished ...>
# another fork. pid 13954 is actual server that will perform a scan for us.
[pid 13953] fork() = 13954
[pid 13953] munmap(0x400fa000, 4096) = 0
[pid 13953] munmap(0x40000000, 4096) = 0
[pid 13953] _exit(0) = ?
[pid 31577] <... wait4 resumed> [WIFEXITED(s) && WEXITSTATUS(s) == 0], 0, NULL) = 13953
[pid 31577] --- SIGCHLD (Child exited) ---
[pid 31577] select(1024, [0 2], NULL, NULL, NULL <unfinished ...>
...
[pid 13954] getuid() = 54
[pid 13954] time(NULL) = 998302772
[pid 13954] lstat("/tst/13952.tmp", {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lstat("/tst/13952.tmp", {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] open("/tst/13952.tmp", O_RDONLY|0x40000000) = 3
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 0, SEEK_SET) = 0
[pid 13954] read(3, "Return-Path: <root@corpit.ru>\nDe"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 110592, SEEK_SET) = 110592
[pid 13954] read(3, "bKtGA4dFA+G9r2m3/C18G+\njkZe9OKri"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 114688, SEEK_SET) = 114688
[pid 13954] read(3, "97fRf9f\nO9jdu19FvOregwe7xv9/Ddim"..., 4096) = 592
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 4096, SEEK_SET) = 4096
[pid 13954] read(3, "Ysg3oIWzjFz7BIzNHMF66LrTFG6\nCpGW"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 106496, SEEK_SET) = 106496
[pid 13954] read(3, "K+hnR6tT9oJZczHvSftADaFUbZMNA40j"..., 4096) = 4096
[pid 13954] brk(0x8315000) = 0x8315000
[pid 13954] time(NULL) = 998302772
[pid 13954] access("/tmp/AVP0e434.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 8192, SEEK_SET) = 8192
[pid 13954] read(3, "0FDClm3Ppram\nFKLdeb6TGlXn6e1+GA/"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 12288, SEEK_SET) = 12288
[pid 13954] read(3, "+ED25Qg1Qkp94IwQOD9mo011TvRvjvql"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 16384, SEEK_SET) = 16384
[pid 13954] read(3, "iKGZrpo5lddDYxfId4G3Mm/b29/gSniP"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 20480, SEEK_SET) = 20480
[pid 13954] read(3, "cyp14nhQYvLFUSsubToeWSiy2UChvVh1"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 24576, SEEK_SET) = 24576
[pid 13954] read(3, "GD8sDcO1RhWPLw0K3j3MvGxe2xXsZ\nTj"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 28672, SEEK_SET) = 28672
[pid 13954] read(3, "s1oDcufVBicJ7p\nGphAQUa0a+4X8LJR4"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 32768, SEEK_SET) = 32768
[pid 13954] read(3, "xl328B6gh/fEMkX8VuL6bA9yZP+9eSzw"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 36864, SEEK_SET) = 36864
[pid 13954] read(3, "ewIYLvcee/6COtp+44te0uz8whg0XGgp"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 40960, SEEK_SET) = 40960
[pid 13954] read(3, "euxAJ8Pzy1Huyte4+85s3rY/0RoeeDAX"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 45056, SEEK_SET) = 45056
[pid 13954] read(3, "GpOCpcKB32Fm9wsmyR7q7w6lSd0+Ybn\n"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 49152, SEEK_SET) = 49152
[pid 13954] read(3, "hsQIcdCWW+h6AwOz\ni1YxYKuonnCuMdP"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 53248, SEEK_SET) = 53248
[pid 13954] read(3, "G\nMIkBWUmMkvnF2QW7Xwe9rveYUJiNaP"..., 4096) = 4096
[pid 13954] brk(0x831a000) = 0x831a000
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 57344, SEEK_SET) = 57344
[pid 13954] read(3, "i7L7He77cXp6cPDwymZ3jM7MDhH5ekm5"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 61440, SEEK_SET) = 61440
[pid 13954] read(3, "uIqGUgCatwCZUFa2KY2VTYRoRAWUd1Kh"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 65536, SEEK_SET) = 65536
[pid 13954] read(3, "89/bqVaRtsdyXupI4xnBJeGgBc1cn1s5"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 69632, SEEK_SET) = 69632
[pid 13954] read(3, "ic3R9lj9itm1EuI8VA\nUYfJ0p5qsU5wh"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 73728, SEEK_SET) = 73728
[pid 13954] read(3, "hGU\ndOA/s5OzOdWYga+o3h9fcvTlHhHs"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 77824, SEEK_SET) = 77824
[pid 13954] read(3, "kmXYK+Jj64QBabQWto4Oglw7bkS7c5Z9"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 81920, SEEK_SET) = 81920
[pid 13954] read(3, "ZkMqI9GcyGv7D0RFZsrXkaSddtVUmjjW"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 86016, SEEK_SET) = 86016
[pid 13954] read(3, "kfjc/bElXmTLXcUjXbSH7HvwvTzEmeQy"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 90112, SEEK_SET) = 90112
[pid 13954] read(3, "0r31VaEkw7dP4f8vuQh9\n6VLK2BN2Zzf"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 94208, SEEK_SET) = 94208
[pid 13954] read(3, "bdTvV\nVtiGRh2px6P0bbF1KX6nSYJuhB"..., 4096) = 4096
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 98304, SEEK_SET) = 98304
[pid 13954] read(3, "UuGWgXZTCuhnZNkHaLxtTIPmZmmtvnom"..., 4096) = 4096
[pid 13954] brk(0x831f000) = 0x831f000
[pid 13954] fstat(3, {st_mode=S_IFREG|0640, st_size=115280, ...}) = 0
[pid 13954] lseek(3, 102400, SEEK_SET) = 102400
[pid 13954] read(3, "BqLlPUaTgFd7SDbdMASCBZQJYT/oNeus"..., 4096) = 4096
[pid 13954] brk(0x8328000) = 0x8328000
[pid 13954] access("/tmp/AVP0e435.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] brk(0x832c000) = 0x832c000
[pid 13954] brk(0x832e000) = 0x832e000
[pid 13954] brk(0x8333000) = 0x8333000
[pid 13954] brk(0x8338000) = 0x8338000
[pid 13954] brk(0x833d000) = 0x833d000
[pid 13954] brk(0x833f000) = 0x833f000
[pid 13954] brk(0x8344000) = 0x8344000
[pid 13954] brk(0x8349000) = 0x8349000
[pid 13954] brk(0x834e000) = 0x834e000
[pid 13954] brk(0x8353000) = 0x8353000
[pid 13954] brk(0x8358000) = 0x8358000
[pid 13954] brk(0x835d000) = 0x835d000
[pid 13954] brk(0x8362000) = 0x8362000
[pid 13954] brk(0x8367000) = 0x8367000
[pid 13954] brk(0x836c000) = 0x836c000
[pid 13954] brk(0x8371000) = 0x8371000
[pid 13954] brk(0x8376000) = 0x8376000
[pid 13954] brk(0x837b000) = 0x837b000
[pid 13954] brk(0x8380000) = 0x8380000
[pid 13954] brk(0x8385000) = 0x8385000
[pid 13954] brk(0x838a000) = 0x838a000
[pid 13954] brk(0x838f000) = 0x838f000
[pid 13954] brk(0x8394000) = 0x8394000
[pid 13954] brk(0x8399000) = 0x8399000
[pid 13954] brk(0x839e000) = 0x839e000
[pid 13954] brk(0x83a3000) = 0x83a3000
[pid 13954] access("/tmp/AVP0e436.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] brk(0x83a8000) = 0x83a8000
[pid 13954] brk(0x83ad000) = 0x83ad000
[pid 13954] brk(0x83b2000) = 0x83b2000
[pid 13954] brk(0x83bb000) = 0x83bb000
[pid 13954] access("/tmp/AVP0e437.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] brk(0x83c0000) = 0x83c0000
[pid 13954] brk(0x83c9000) = 0x83c9000
[pid 13954] access("/tmp/AVP0e438.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] brk(0x83ce000) = 0x83ce000
[pid 13954] access("/tmp/AVP0e439.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] brk(0x83d3000) = 0x83d3000
[pid 13954] brk(0x83d8000) = 0x83d8000
[pid 13954] access("/tmp/AVP0e43a.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] brk(0x83dd000) = 0x83dd000
[pid 13954] brk(0x83e2000) = 0x83e2000
[pid 13954] access("/tmp/AVP0e43b.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] brk(0x83e4000) = 0x83e4000
[pid 13954] brk(0x83e9000) = 0x83e9000
[pid 13954] brk(0x83ee000) = 0x83ee000
[pid 13954] brk(0x83f3000) = 0x83f3000
[pid 13954] brk(0x83f8000) = 0x83f8000
[pid 13954] brk(0x83fd000) = 0x83fd000
[pid 13954] brk(0x8402000) = 0x8402000
[pid 13954] brk(0x8407000) = 0x8407000
[pid 13954] access("/tmp/AVP0e43c.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] brk(0x840c000) = 0x840c000
[pid 13954] brk(0x8411000) = 0x8411000
[pid 13954] brk(0x8416000) = 0x8416000
[pid 13954] brk(0x841b000) = 0x841b000
[pid 13954] brk(0x8420000) = 0x8420000
[pid 13954] brk(0x8425000) = 0x8425000
[pid 13954] brk(0x842a000) = 0x842a000
[pid 13954] brk(0x842f000) = 0x842f000
[pid 13954] brk(0x8434000) = 0x8434000
[pid 13954] brk(0x8439000) = 0x8439000
..... [ tons of brk() calls deleted ]
[pid 13954] brk(0x880d000) = 0x880d000
[pid 13954] brk(0x8812000) = 0x8812000
[pid 13954] access("/tmp/AVP0e43d.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] brk(0x8817000) = 0x8817000
[pid 13954] access("/tmp/AVP0e43d.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] access("/tmp/AVP0e43e.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] access("/tmp/AVP0e43e.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] access("/tmp/AVP0e43f.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] access("/tmp/AVP0e43f.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] access("/tmp/AVP0e440.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] access("/tmp/AVP0e440.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] access("/tmp/AVP0e441.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] access("/tmp/AVP0e441.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] access("/tmp/AVP0e442.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 13954] access("/tmp/AVP0e442.tmp", F_OK) = -1 ENOENT (No such file or directory)
[pid 13954] --- SIGSEGV (Segmentation fault) ---
# now, child died. It's death is NOT noticied by parent, since double-fork
# was done before (how helpful!).
# Note that filedescriptor 2 still opened by parent (main avpdaemon), so
# our avcheck still waits in a read() call. It will never end!
# Now, I hit Ctrl+C, terminating avcheck. Select in parent returned:
<... select resumed> ) = 1 (in [2])
read(2, "", 2048) = 0
close(2) = 0
select(1024, [0], NULL, NULL, NULL <unfinished>
# no I exited strace
Before the above SIGSEGV, it spends about 1 minute on our i486 machine.
A conclusion? Well, I leave it as an excercise for a reader... ;)
Regards,
Michael.