[sanesecurity] Re: clamd stability & fetch-sanesecurity-sigs

  • From: Bill Landry <bill@xxxxxxxxxxx>
  • To: sanesecurity@xxxxxxxxxxxxx
  • Date: Tue, 27 Jan 2009 11:16:20 -0800

Tomasz Kojm wrote:
> On Tue, 27 Jan 2009 12:59:51 +0000
> Gareth <list-mailscanner@xxxxxxxxxxxxxxx> wrote:
> 
>> On Mon, 2009-01-26 at 08:45, Steve Basford wrote:
>>> Everyone getting crashes, please read this, to help debug:
>>>
>>> http://www.clamav.net/bugs/lang-pref/en/
>>>
>>> And post results/info into this entry:
>>>
>>> https://wwws.clamav.net/bugzilla/show_bug.cgi?id=1370
>> I eventually got another crash and this time I had gdb running and was
>> able to do a backtrace. Bugzilla has been updated and I have also posted
>> the backtrace below incase anyone is interested.
>>
>> Program received signal SIGSEGV, Segmentation fault.
>> cli_ac_free (root=0xb58fe730) at matcher-ac.c:351
>> 351             patt->prefix ? free(patt->prefix) : free(patt->pattern);
>> (gdb) bt
>> #0  cli_ac_free (root=0xb58fe730) at matcher-ac.c:351
>> #1  0x00122880 in cl_free (engine=0xb7e00a48) at readdb.c:2131
>> #2  0x0804e91d in reload_db (engine=0xb09633f8, dboptions=26, copt=<value
>> optimized out>, do_check=0, ret=0xbfd25558) at server-th.c:243
>> #3  0x0804f265 in acceptloop_th (socketds=0xbfd2564c, nsockets=1,
>> engine=0xb7e00a48, dboptions=26, copt=0x8fbf5d8) at server-th.c:674
>> #4  0x0804d184 in main (argc=Cannot access memory at address 0x1
>> ) at clamd.c:479
> 
> Would it be possible for you to run clamd under valgrind and wait for another
> crash? (valgrind -v /usr/local/sbin/clamd) Hopefully this would provide us 
> more
> information about the nature of the problem

I'll post this to bugzilla, as well, once I receive my password via
email.  For what it's worth, every time I run valgrind it stops without
clamd crashing.  Anyway, here is the kind of output I am seeing:

valgrind -v --leak-check=full --trace-children=yes --time-stamp=yes
/usr/local/sbin/clamd                  ==00:00:00:00.000 8585==
Memcheck, a memory error detector.
==00:00:00:00.001 8585== Copyright (C) 2002-2007, and GNU GPL'd, by
Julian Seward et al.
==00:00:00:00.001 8585== Using LibVEX rev 1732, a library for dynamic
binary translation.
==00:00:00:00.002 8585== Copyright (C) 2004-2007, and GNU GPL'd, by
OpenWorks LLP.
==00:00:00:00.002 8585== Using valgrind-3.2.3, a dynamic binary
instrumentation framework.
==00:00:00:00.003 8585== Copyright (C) 2000-2007, and GNU GPL'd, by
Julian Seward et al.
==00:00:00:00.003 8585==
--00:00:00:00.004 8585-- Command line
--00:00:00:00.004 8585--    /usr/local/sbin/clamd
--00:00:00:00.004 8585-- Startup, with flags:
--00:00:00:00.004 8585--    -v
--00:00:00:00.004 8585--    --leak-check=full
--00:00:00:00.004 8585--    --trace-children=yes
--00:00:00:00.004 8585--    --time-stamp=yes
--00:00:00:00.004 8585-- Contents of /proc/version:
--00:00:00:00.004 8585--   Linux version 2.6.26.8-57.fc8
(mockbuild@xxxxxxxxxxxxxxxxxxxxxxxxxxx) (gcc version 4.1.2 20070925 (Red
Hat 4.1.2-33)) #1 SMP Thu Dec 18 19:19:45 EST 2008
--00:00:00:00.004 8585-- Arch and hwcaps: X86, x86-sse1
--00:00:00:00.004 8585-- Page sizes: currently 4096, max supported 4096
--00:00:00:00.005 8585-- Valgrind library directory: /usr/lib/valgrind
--00:00:00:00.006 8585-- Reading syms from /lib/ld-2.7.so (0x94D000)
--00:00:00:00.070 8585-- Reading debug info from
/usr/lib/debug/lib/ld-2.7.so.debug...
--00:00:00:00.147 8585-- Reading syms from /usr/local/sbin/clamd (0x8048000)
--00:00:00:00.164 8585-- Reading syms from
/usr/lib/valgrind/x86-linux/memcheck (0x38000000)
--00:00:00:00.191 8585--    object doesn't have a dynamic symbol table
--00:00:00:00.508 8585-- Reading suppressions file:
/usr/lib/valgrind/default.supp
--00:00:00:00.797 8585-- REDIR: 0x962BB0 (index) redirected to
0x38027F5F (vgPlain_x86_linux_REDIR_FOR_index)
--00:00:00:00.973 8585-- Reading syms from
/usr/lib/valgrind/x86-linux/vgpreload_core.so (0x4000000)
--00:00:00:01.022 8585-- Reading syms from
/usr/lib/valgrind/x86-linux/vgpreload_memcheck.so (0x4003000)
==00:00:00:01.027 8585== WARNING: new redirection conflicts with
existing -- ignoring it
--00:00:00:01.028 8585--     new: 0x00962BB0 (index     ) R-> 0x04006230
index
--00:00:00:01.071 8585-- REDIR: 0x962D50 (strlen) redirected to
0x40062E0 (strlen)
--00:00:00:01.109 8585-- Reading syms from
/usr/local/lib/libclamav.so.5.0.4 (0x4009000)
--00:00:00:01.296 8585-- Reading syms from
/usr/local/lib/libclamunrar_iface.so.5.0.4 (0x40BA000)
--00:00:00:01.366 8585-- Reading syms from /lib/libbz2.so.1.0.4 (0x3E5000)
--00:00:00:01.378 8585-- Reading debug info from
/usr/lib/debug/lib/libbz2.so.1.0.4.debug...
--00:00:00:01.410 8585-- Reading syms from /usr/lib/libgmp.so.3.4.2
(0x2B5000)
--00:00:00:01.443 8585-- Reading debug info from
/usr/lib/debug/usr/lib/libgmp.so.3.4.2.debug...
--00:00:00:01.628 8585-- Reading syms from
/usr/local/lib/libclamunrar.so.5.0.4 (0x40D0000)
--00:00:00:01.647 8585-- Reading syms from /lib/libz.so.1.2.3 (0xB14000)
--00:00:00:01.658 8585-- Reading debug info from
/usr/lib/debug/lib/libz.so.1.2.3.debug...
--00:00:00:01.689 8585-- Reading syms from /lib/libpthread-2.7.so (0xAF9000)
--00:00:00:01.705 8585-- Reading debug info from
/usr/lib/debug/lib/libpthread-2.7.so.debug...
--00:00:00:01.798 8585-- Reading syms from /lib/libc-2.7.so (0x96C000)
--00:00:00:01.814 8585-- Reading debug info from
/usr/lib/debug/lib/libc-2.7.so.debug...
--00:00:00:03.258 8585-- REDIR: 0x9DD3A0 (memset) redirected to
0x4006640 (memset)
--00:00:00:03.266 8585-- REDIR: 0x9DD890 (memcpy) redirected to
0x4007090 (memcpy)
--00:00:00:03.352 8585-- REDIR: 0x9DC4C0 (rindex) redirected to
0x4006110 (rindex)
--00:00:00:03.429 8585-- REDIR: 0x9D7810 (calloc) redirected to
0x40047CD (calloc)
--00:00:00:03.451 8585-- REDIR: 0x9DC120 (strlen) redirected to
0x40062C0 (strlen)
--00:00:00:03.481 8585-- REDIR: 0x9D7B00 (malloc) redirected to
0x40054A0 (malloc)
--00:00:00:03.500 8585-- REDIR: 0x9DBBC0 (strcmp) redirected to
0x4006390 (strcmp)
--00:00:00:03.642 8585-- REDIR: 0x9DCEA0 (memchr) redirected to
0x40064B0 (memchr)
--00:00:00:03.667 8585-- REDIR: 0x9DBA50 (index) redirected to 0x4006200
(index)
--00:00:00:03.681 8585-- REDIR: 0x9DC410 (strncpy) redirected to
0x4006930 (strncpy)
--00:00:00:03.704 8585-- REDIR: 0x9D9060 (free) redirected to 0x40050BA
(free)
--00:00:00:03.957 8585-- REDIR: 0x9DE220 (strchrnul) redirected to
0x40066F0 (strchrnul)
--00:00:00:03.982 8585-- REDIR: 0x9DD400 (mempcpy) redirected to
0x4006B70 (mempcpy)
--00:00:00:04.055 8585-- REDIR: 0x9DD590 (stpcpy) redirected to
0x4006850 (stpcpy)
--00:00:00:04.109 8585-- Reading syms from /lib/libnss_files-2.7.so
(0x41DD000)
--00:00:00:04.110 8585-- Reading debug info from
/usr/lib/debug/lib/libnss_files-2.7.so.debug...
--00:00:00:04.184 8585-- REDIR: 0x9DBC30 (strcpy) redirected to
0x40072F0 (strcpy)
--00:00:00:04.351 8585-- REDIR: 0x963110 (stpcpy) redirected to
0x40074D0 (stpcpy)
--00:00:00:04.472 8585-- REDIR: 0x9DE150 (rawmemchr) redirected to
0x4006720 (rawmemchr)
--00:00:00:04.822 8585-- REDIR: 0x9DC1D0 (strnlen) redirected to
0x4006290 (strnlen)
--00:00:00:05.048 8585-- REDIR: 0x9DC310 (strncmp) redirected to
0x4006320 (strncmp)
--00:00:00:05.057 8585-- REDIR: 0x9D9250 (realloc) redirected to
0x400554F (realloc)
--00:00:00:05.200 8585-- REDIR: 0x9DD330 (memmove) redirected to
0x4006670 (memmove)
--00:00:00:07.779 8585-- REDIR: 0x9DB8A0 (strcat) redirected to
0x40073E0 (strcat)
ERROR: LOCAL: Socket file /var/amavis/clamd.sock is in use by another
process.
--00:00:06:42.902 8585-- Discarding syms at 0x41DD000-0x41E9000 in
/lib/libnss_files-2.7.so due to munmap()
==00:00:06:43.003 8585==
==00:00:06:43.003 8585== ERROR SUMMARY: 0 errors from 0 contexts
(suppressed: 24 from 1)
--00:00:06:43.004 8585--
--00:00:06:43.004 8585-- supp:   24 dl-hack3
==00:00:06:43.794 8585== malloc/free: in use at exit: 75,935,203 bytes
in 2,041,852 blocks.
==00:00:06:43.795 8585== malloc/free: 2,240,788 allocs, 198,936 frees,
4,020,645,297 bytes allocated.
==00:00:06:43.795 8585==
==00:00:07:18.547 8585== searching for pointers to 2,041,852 not-freed
blocks.
==00:00:07:45.591 8585== checked 74,241,184 bytes.
==00:00:07:46.865 8585==
==00:00:07:46.865 8585== 23 bytes in 1 blocks are definitely lost in
loss record 1 of 16
==00:00:07:46.891 8585==    at 0x4005525: malloc (vg_replace_malloc.c:149)
==00:00:07:46.891 8585==    by 0x4019E5E: cli_malloc (others.c:355)
==00:00:07:46.892 8585==    by 0x401A5BB: cl_settempdir (others.c:470)
==00:00:07:46.893 8585==    by 0x804CFE7: main (clamd.c:288)
==00:00:07:46.893 8585==
==00:00:07:46.894 8585==
==00:00:07:46.894 8585== 6,908 (64 direct, 6,844 indirect) bytes in 1
blocks are definitely lost in loss record 2 of 16
==00:00:07:46.895 8585==    at 0x4004864: calloc (vg_replace_malloc.c:279)
==00:00:07:46.895 8585==    by 0x40199A5: cli_calloc (others.c:378)
==00:00:07:46.896 8585==    by 0x401B42F: cli_initengine (readdb.c:334)
==00:00:07:46.897 8585==    by 0x401F771: cl_load (readdb.c:1868)
==00:00:07:46.897 8585==    by 0x804D109: main (clamd.c:398)
==00:00:07:46.898 8585==
==00:00:07:46.898 8585==
==00:00:07:46.899 8585== 256 bytes in 1 blocks are possibly lost in loss
record 5 of 16
==00:00:07:46.899 8585==    at 0x4005525: malloc (vg_replace_malloc.c:149)
==00:00:07:46.900 8585==    by 0x40055AF: realloc (vg_replace_malloc.c:306)
==00:00:07:46.901 8585==    by 0x4019855: cli_realloc (others.c:398)
==00:00:07:46.901 8585==    by 0x406015B: p_bracket (regcomp.c:1052)
==00:00:07:46.902 8585==    by 0x4060CFA: ordinary (regcomp.c:896)
==00:00:07:46.903 8585==    by 0x40612A9: p_ere (regcomp.c:379)
==00:00:07:46.903 8585==    by 0x4061482: p_ere (regcomp.c:322)
==00:00:07:46.904 8585==    by 0x40625B4: cli_regcomp (regcomp.c:224)
==00:00:07:46.904 8585==    by 0x4077869: phishing_init (phishcheck.c:323)
==00:00:07:46.905 8585==    by 0x401B40A: cli_initengine (readdb.c:357)
==00:00:07:46.905 8585==    by 0x401F771: cl_load (readdb.c:1868)
==00:00:07:46.906 8585==    by 0x804D109: main (clamd.c:398)
==00:00:07:46.907 8585==
==00:00:07:46.907 8585==
==00:00:07:46.908 8585== 363,184 bytes in 13 blocks are possibly lost in
loss record 11 of 16
==00:00:07:46.908 8585==    at 0x4005622: realloc (vg_replace_malloc.c:306)
==00:00:07:46.909 8585==    by 0x4019855: cli_realloc (others.c:398)
==00:00:07:46.909 8585==    by 0x4014353: cli_ac_addpatt (matcher-ac.c:97)
==00:00:07:46.910 8585==    by 0x4014D39: cli_ac_addsig (matcher-ac.c:1419)
==00:00:07:46.911 8585==    by 0x401C52B: cli_parse_add (readdb.c:276)
==00:00:07:46.911 8585==    by 0x401E157: cli_loadndb (readdb.c:705)
==00:00:07:46.912 8585==    by 0x401E94B: cli_load (readdb.c:1708)
==00:00:07:46.912 8585==    by 0x4020BCC: cli_cvdload (cvd.c:287)
==00:00:07:46.913 8585==    by 0x401E6B6: cli_load (readdb.c:1666)
==00:00:07:46.913 8585==    by 0x401F2A9: cli_loaddbdir (readdb.c:1833)
==00:00:07:46.913 8585==    by 0x401F7E0: cl_load (readdb.c:1881)
==00:00:07:46.913 8585==    by 0x804D109: main (clamd.c:398)
==00:00:07:46.913 8585==
==00:00:07:46.913 8585==
==00:00:07:46.913 8585== 1,587,528 bytes in 12 blocks are possibly lost
in loss record 13 of 16
==00:00:07:46.913 8585==    at 0x4004864: calloc (vg_replace_malloc.c:279)
==00:00:07:46.914 8585==    by 0x40199A5: cli_calloc (others.c:378)
==00:00:07:46.914 8585==    by 0x4016FA9: cli_bm_init (matcher-bm.c:101)
==00:00:07:46.914 8585==    by 0x401A83A: cli_initroots (readdb.c:390)
==00:00:07:46.914 8585==    by 0x401D115: cli_loadldb (readdb.c:915)
==00:00:07:46.914 8585==    by 0x401E9DB: cli_load (readdb.c:1703)
==00:00:07:46.914 8585==    by 0x4020BCC: cli_cvdload (cvd.c:287)
==00:00:07:46.914 8585==    by 0x401E6B6: cli_load (readdb.c:1666)
==00:00:07:46.914 8585==    by 0x401F360: cli_loaddbdir (readdb.c:1788)
==00:00:07:46.914 8585==    by 0x401F7E0: cl_load (readdb.c:1881)
==00:00:07:46.914 8585==    by 0x804D109: main (clamd.c:398)
==00:00:07:46.914 8585==
==00:00:07:46.914 8585==
==00:00:07:46.914 8585== 2,245,506 bytes in 6 blocks are possibly lost
in loss record 14 of 16
==00:00:07:46.914 8585==    at 0x4005525: malloc (vg_replace_malloc.c:149)
==00:00:07:46.914 8585==    by 0x4019E5E: cli_malloc (others.c:355)
==00:00:07:46.915 8585==    by 0x4021D4A: cli_strtok (str.c:313)
==00:00:07:46.915 8585==    by 0x401B766: cli_loadmd (readdb.c:1470)
==00:00:07:46.915 8585==    by 0x401EAA2: cli_load (readdb.c:1714)
==00:00:07:46.915 8585==    by 0x4020BCC: cli_cvdload (cvd.c:287)
==00:00:07:46.915 8585==    by 0x401E6B6: cli_load (readdb.c:1666)
==00:00:07:46.915 8585==    by 0x401F360: cli_loaddbdir (readdb.c:1788)
==00:00:07:46.915 8585==    by 0x401F7E0: cl_load (readdb.c:1881)
==00:00:07:46.915 8585==    by 0x804D109: main (clamd.c:398)
==00:00:07:46.915 8585==
==00:00:07:46.915 8585== LEAK SUMMARY:
==00:00:07:46.915 8585==    definitely lost: 87 bytes in 2 blocks.
==00:00:07:46.915 8585==    indirectly lost: 6,844 bytes in 216 blocks.
==00:00:07:46.915 8585==      possibly lost: 4,196,474 bytes in 32 blocks.
==00:00:07:46.915 8585==    still reachable: 71,731,798 bytes in
2,041,602 blocks.
==00:00:07:46.915 8585==         suppressed: 0 bytes in 0 blocks.
==00:00:07:46.915 8585== Reachable blocks (those to which a pointer was
found) are not shown.
==00:00:07:46.916 8585== To see them, rerun with: --leak-check=full
--show-reachable=yes
--00:00:07:47.022 8585--  memcheck: sanity checks: 7850 cheap, 315 expensive
--00:00:07:47.023 8585--  memcheck: auxmaps: 0 auxmap entries (0k, 0M)
in use
--00:00:07:47.024 8585--  memcheck: auxmaps: 0 searches, 0 comparisons
--00:00:07:47.024 8585--  memcheck: SMs: n_issued      = 21002 (336032k,
328M)
--00:00:07:47.025 8585--  memcheck: SMs: n_deissued    = 18108 (289728k,
282M)
--00:00:07:47.025 8585--  memcheck: SMs: max_noaccess  = 65535
(1048560k, 1023M)
--00:00:07:47.026 8585--  memcheck: SMs: max_undefined = 15 (240k, 0M)
--00:00:07:47.026 8585--  memcheck: SMs: max_defined   = 56 (896k, 0M)
--00:00:07:47.027 8585--  memcheck: SMs: max_non_DSM   = 2927 (46832k, 45M)
--00:00:07:47.028 8585--  memcheck: max sec V bit nodes:    6 (0k, 0M)
--00:00:07:47.028 8585--  memcheck: set_sec_vbits8 calls: 16 (new: 6,
updates: 10)
--00:00:07:47.029 8585--  memcheck: max shadow mem size:   47136k, 46M
--00:00:07:47.032 8585-- translate:            fast SP updates
identified: 7,059 ( 89.5%)
--00:00:07:47.032 8585-- translate:   generic_known SP updates
identified: 557 (  7.0%)
--00:00:07:47.033 8585-- translate: generic_unknown SP updates
identified: 266 (  3.3%)
--00:00:07:47.033 8585--     tt/tc: 1,657,860 tt lookups requiring
1,658,643 probes
--00:00:07:47.034 8585--     tt/tc: 1,657,860 fast-cache updates, 4 flushes
--00:00:07:47.034 8585--  transtab: new        6,854 (143,310 ->
2,329,264; ratio 162:10) [0 scs]
--00:00:07:47.035 8585--  transtab: dumped     0 (0 -> ??)
--00:00:07:47.036 8585--  transtab: discarded  120 (2,139 -> ??)
--00:00:07:47.036 8585-- scheduler: 785,031,055 jumps (bb entries).
--00:00:07:47.037 8585-- scheduler: 7,850/4,018,413 major/minor sched
events.
--00:00:07:47.037 8585--    sanity: 7851 cheap, 315 expensive checks.
--00:00:07:47.038 8585--    exectx: 30,011 lists, 1,090 contexts (avg 0
per list)
--00:00:07:47.039 8585--    exectx: 2,439,726 searches, 2,438,996 full
compares (999 per 1000)
--00:00:07:47.039 8585--    exectx: 7,554,460 cmp2, 70 cmp4, 0 cmpAll

Let me know if there is anything else you would like me to try.

Bill


Other related posts: