glibc double free error on snmp_sess_close
Hi, I have been trying to solve an annoying problem for a couple of months now - so was wondering if anyone has some fresh ideas or pointers on what to try next. I have an application using net-snmp 5.4.2.1 which after some time - seemingly proportional to the number of snmp requests - will terminate with a glibc double free error. The application is doing repetitive and simple SNMP_MSG_GET requests. After some time - could be a number of weeks, snmp_synch_response will return STAT_ERROR, and when snmp_close(ss) is called - the double free is detected after snmp_sess_close calls snmp_free_pdu. (full gdb output at the end). I have rewritten the code a number of times to no avail, and currently uses a similar structure to snmpwalk.c. I have a little script which records the VSIZE of the process over time, and there appears to be no memory leaking. I have used valgrind to try and detect memory problems, and although there are lots of reports none seem to be show-stoppers, and there are a lot in net-snmp itself (although am very new to valgrand, so am no expert). These problems started to occur around the time that I started to monitor a piece of equipment that can't cope with 32-bit requestIDs, so as a result I have the "16bitIDs" config parm set to "yes", but have so far not looked into the possibility of there being a 16bitIDs-related bug. I am guessing this would be unlikely? As mentioned - any ideas, pointers would be much appreciated. Many thanks, Craig Starting program: /etc/mon/mjs/wd/mjsnmppm1/tempgdb/mjsnmppm1 72 [Thread debugging using libthread_db enabled] [New Thread 0x2b066a67a5e0 (LWP 12859)] Detaching after fork from child process 12862. No log handling enabled - turning on stderr logging snmpwander: *** glibc detected *** /etc/mon/mjs/wd/mjsnmppm1/tempgdb/mjsnmppm1: double free or corruption (out): 0x089d4070 *** === Backtrace: = /lib64/libc.so.6[0x3d0de71ce2] /lib64/libc.so.6(cfree+0x8c)[0x3d0de7590c] /usr/local/lib/libnetsnmp.so.15(snmp_free_pdu+0x61)[0x2b066a17b8c1] /usr/local/lib/libnetsnmp.so.15(snmp_sess_close+0x85)[0x2b066a182355] /etc/mon/mjs/wd/mjsnmppm1/tempgdb/mjsnmppm1[0x430c18] /etc/mon/mjs/wd/mjsnmppm1/tempgdb/mjsnmppm1[0x431960] /etc/mon/mjs/wd/mjsnmppm1/tempgdb/mjsnmppm1[0x40dddc] /etc/mon/mjs/wd/mjsnmppm1/tempgdb/mjsnmppm1[0x40df6d] /usr/local/lib/libspread-core.so(E_handle_events+0xa8)[0x2b066a414e38] /etc/mon/mjs/wd/mjsnmppm1/tempgdb/mjsnmppm1[0x405fd7] /etc/mon/mjs/wd/mjsnmppm1/tempgdb/mjsnmppm1[0x431662] /lib64/libc.so.6(__libc_start_main+0xf4)[0x3d0de1d974] /etc/mon/mjs/wd/mjsnmppm1/tempgdb/mjsnmppm1(__gxx_personality_v0+0x269)[0x405b09] === Memory map: 0040-00468000 r-xp fd:00 45449228 /etc/mon/mjs/wd/mjsnmppm1/tempgdb/mjsnmppm1 00667000-00668000 rw-p 00067000 fd:00 45449228 /etc/mon/mjs/wd/mjsnmppm1/tempgdb/mjsnmppm1 00668000-00682000 rw-p 00668000 00:00 0 0894e000-089f5000 rw-p 0894e000 00:00 0 [heap] 3d0da0-3d0da1c000 r-xp fd:00 44236802 /lib64/ld-2.5.so 3d0dc1b000-3d0dc1c000 r--p 0001b000 fd:00 44236802 /lib64/ld-2.5.so 3d0dc1c000-3d0dc1d000 rw-p 0001c000 fd:00 44236802 /lib64/ld-2.5.so 3d0de0-3d0df4c000 r-xp fd:00 44236805 /lib64/libc-2.5.so 3d0df4c000-3d0e14c000 ---p 0014c000 fd:00 44236805 /lib64/libc-2.5.so 3d0e14c000-3d0e15 r--p 0014c000 fd:00 44236805 /lib64/libc-2.5.so 3d0e15-3d0e151000 rw-p 0015 fd:00 44236805 /lib64/libc-2.5.so 3d0e151000-3d0e156000 rw-p 3d0e151000 00:00 0 3d0e20-3d0e202000 r-xp fd:00 44236812 /lib64/libdl-2.5.so 3d0e202000-3d0e402000 ---p 2000 fd:00 44236812 /lib64/libdl-2.5.so 3d0e402000-3d0e403000 r--p 2000 fd:00 44236812 /lib64/libdl-2.5.so 3d0e403000-3d0e404000 rw-p 3000 fd:00 44236812 /lib64/libdl-2.5.so 3d0e60-3d0e682000 r-xp fd:00 44236822 /lib64/libm-2.5.so 3d0e682000-3d0e881000 ---p 00082000 fd:00 44236822 /lib64/libm-2.5.so 3d0e881000-3d0e882000 r--p 00081000 fd:00 44236822 /lib64/libm-2.5.so 3d0e882000-3d0e883000 rw-p 00082000 fd:00 44236822 /lib64/libm-2.5.so 3d0ea0-3d0ea16000 r-xp fd:00 44236811 /lib64/libpthread-2.5.so 3d0ea16000-3d0ec15000 ---p 00016000 fd:00 44236811 /lib64/libpthread-2.5.so 3d0ec15000-3d0ec16000 r--p 00015000 fd:00 44236811 /lib64/libpthread-2.5.so 3d0ec16000-3d0ec17000 rw-p 00016000 fd:00 44236811 /lib64/libpthread-2.5.so 3d0ec17000-3d0ec1b000 rw-p 3d0ec17000 00:00 0 3d0ee0-3d0ee14000 r-xp fd:00 14916464 /usr/lib64/libz.so.1.2.3 3d0ee14000-3d0f013000 ---p 00014000 fd:00 14916464 /usr/lib64/libz.so.1.2.3 3d0f013000-3d0f014000 rw-p 00013000 fd:00 14916464 /usr/lib64/libz.so.1.2.3 3d0fa0-3d0fa2 r-xp fd:00 14918977 /usr/lib64/libpq.so.4.1 3d0fa2-3d0fc2 ---p 0002 fd:00 14918977 /usr/lib64/libpq.so.4.1 3d0fc2-3d0fc22000 rw-p 0002 fd:00 14918977 /usr/lib64/libpq.so.4.1 3d0fe0-3d0fe0d000 r-xp fd:00 44236827 /lib64/libgcc_s-4.1.2-20080825.so.1 3d0fe0d000-3d1000d000 -
Re: glibc double free error on snmp_sess_close
Bart Van Assche wrote: > On Tue, Aug 4, 2009 at 4:06 PM, > [email protected] wrote: >> I have an application using net-snmp 5.4.2.1 which after some time - >> seemingly proportional to the number of snmp requests - will terminate >> with a glibc double free error. The application is doing repetitive and >> simple SNMP_MSG_GET requests. After some time - could be a number of >> weeks, snmp_synch_response will return STAT_ERROR, and when >> snmp_close(ss) is called - the double free is detected after >> snmp_sess_close calls snmp_free_pdu. (full gdb output at the end). > > Did you already try to analyze the process that triggers this behavior > with Valgrind (http://www.valgrind.org/) ? > > Bart. Hi Bart, yes - I did try to analyse the program - although it was the first time I have used valgrind, and at the time was looking for memory leaks, rather than anything else at the time. It was reporting an insignificant amount of memory lost. In hindsight I guess it is memory being freed when it shouldn't have - so maybe I need to go back and re-examine the warnings in more detail. Thanks for your reply, Craig __ Information from ESET Smart Security, version of virus signature database 4305 (20090804) __ The message was checked by ESET Smart Security. http://www.eset.com -- Let Crystal Reports handle the reporting - Free Crystal Reports 2008 30-Day trial. Simplify your report design, integration and deployment - and focus on what you do best, core application coding. Discover what's new with Crystal Reports now. http://p.sf.net/sfu/bobj-july ___ Net-snmp-coders mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/net-snmp-coders
Re: glibc double free error on snmp_sess_close
Bart Van Assche wrote: > On Tue, Aug 4, 2009 at 4:06 PM, > [email protected] wrote: >> I have an application using net-snmp 5.4.2.1 which after some time - >> seemingly proportional to the number of snmp requests - will terminate >> with a glibc double free error. The application is doing repetitive and >> simple SNMP_MSG_GET requests. After some time - could be a number of >> weeks, snmp_synch_response will return STAT_ERROR, and when >> snmp_close(ss) is called - the double free is detected after >> snmp_sess_close calls snmp_free_pdu. (full gdb output at the end). > > Did you already try to analyze the process that triggers this behavior > with Valgrind (http://www.valgrind.org/) ? > > Bart. Hi, I tried to eliminate all the valgrind errors in my code - there were only 5 to begin with, and 4 were trivial. The double free error is still being produced after the 4 minor errors were resolved. The 1 remaining valgrind error (reproduced at the end in full) is complaining about "socketcall.sendmsg(msg.msg_control) points to uninitialised byte(s)". This occurs every time an snmp request is sent. I tested with a simple standard comand line snmpget - and valgrind still issues the same error. Using my code, I placed a breakpoint in gdb at the point it is sent (netsnmp_udp_send [snmpUDPDoomain.c:184]) and checked to see what it could be complaining about. It looked to me like it could be complaining about an unitialised field cmsg.ipi.ipi_addr and possibly __cmsg_data. Here is the pertinent code: static int netsnmp_udp_sendto(int fd, struct in_addr *srcip, struct sockaddr *remote, void *data, int len) { struct iovec iov = { data, len }; struct { struct cmsghdr cm; struct in_pktinfo ipi; } cmsg; struct msghdr m; cmsg.cm.cmsg_len = sizeof(struct cmsghdr) + sizeof(struct in_pktinfo); cmsg.cm.cmsg_level = SOL_IP; cmsg.cm.cmsg_type = IP_PKTINFO; cmsg.ipi.ipi_ifindex = 0; cmsg.ipi.ipi_spec_dst.s_addr = (srcip ? srcip->s_addr : INADDR_ANY); m.msg_name = remote; m.msg_namelen = sizeof(struct sockaddr_in); m.msg_iov = &iov; m.msg_iovlen = 1; m.msg_control = &cmsg; m.msg_controllen = sizeof(cmsg); m.msg_flags= 0; return sendmsg(fd, &m, MSG_NOSIGNAL|MSG_DONTWAIT); } cmsghdr is declared in /usr/include/bits/socket.h: struct cmsghdr { size_t cmsg_len; /* Length of data in cmsg_data plus length of cmsghdr structure. !! The type should be socklen_t but the definition of the kernel is incompatible with this. */ int cmsg_level;/* Originating protocol. */ int cmsg_type; /* Protocol specific type. */ #if (!defined __STRICT_ANSI__ && __GNUC__ >= 2) || __STDC_VERSION__ >= 199901L __extension__ unsigned char __cmsg_data __flexarr; /* Ancillary data. */ #endif }; ip_pktinfo is declared in /usr/include/linux/in.h: struct in_pktinfo { int ipi_ifindex; struct in_addr ipi_spec_dst; struct in_addr ipi_addr; }; I changed the code to initialise the ipi_addr by adding the following line to netsnmp_udp_sendto: cmsg.ipi.ipi_addr.s_addr = 0; but still got the same valgrind error. __cmsg_data appears to be a zero-sized array, since sizeof(cmsghdr) is 16 - and once cmsg.ipi.ipi_ifindex is set, dbg shows that __cmsg_data is empty. This is what I get for cmsg after cmsg is initialised: (gdb) n 177 m.msg_name = remote; (gdb) print cmsg $7 = {cm = {cmsg_len = 28, cmsg_level = 0, cmsg_type = 8, __cmsg_data = 0x7fffa860c370 ""}, ipi = {ipi_ifindex = 0, ipi_spec_dst = {s_addr = 0}, ipi_addr = {s_addr = 0}}} Did I miss anything? The only thing I can think of is that cmsg.cm.cmsg_len is set to 28, but later whem m.msg_controllen is set to sizeof(cmsg) - its value is 32 - I assume due to some kind of 16/32bit padding for boundary alignment? Could this be a possible cause of the valgrind error? If not, what? Any opinions of whether this error could be causing my glibc double free errors, or whether it is a red-herring? valgrind error to follow. Many thanks in advance, Craig ==545== Memcheck, a memory error detector. ==545== Copyright (C) 2002-2008, and GNU GPL'd, by Julian Seward et al. ==545== Using LibVEX rev 1884, a library for dynamic binary translation. ==545== Copyright (C) 2004-2008, and GNU GPL'd, by OpenWorks LLP. ==545== Using valgrind-3.4.1, a dynamic binary instrumentation framework. ==545== Copyright (C) 2000-2008, and GNU GPL'd, by Julian Seward et al. ==545== For more details, rerun with: -v ==545== ==545== War
Re: glibc double free error on snmp_sess_close
Bart Van Assche wrote: > On Thu, Aug 6, 2009 at 12:02 PM, > [email protected] wrote: >> The 1 remaining valgrind error (reproduced at the end in full) is >> complaining about >> >> "socketcall.sendmsg(msg.msg_control) points to uninitialised byte(s)". > > Try to insert the statements "memset(&cmsg, 0, sizeof(cmsg)); > memset(&m, 0, sizeof(m));" just after the declaration of cmsg and m > and before the initialization of these structures starts. If this > makes the above message disappear, please post this change as a patch > on the Net-SNMP patch tracker. Hi Bart, I inserted the memsets - and the valgrind error disapeared. Thanks for that - I will post this change on the patch tracker. I will also re-test my code again, and try and get some more code to be hit, as you suggested. Many thanks, Craig __ Information from ESET Smart Security, version of virus signature database 4311 (20090806) __ The message was checked by ESET Smart Security. http://www.eset.com -- Let Crystal Reports handle the reporting - Free Crystal Reports 2008 30-Day trial. Simplify your report design, integration and deployment - and focus on what you do best, core application coding. Discover what's new with Crystal Reports now. http://p.sf.net/sfu/bobj-july ___ Net-snmp-coders mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/net-snmp-coders
Re: glibc double free error on snmp_sess_close
Bart Van Assche wrote:
> On Thu, Aug 6, 2009 at 12:02 PM,
>> Any opinions of whether this error could be causing my glibc double free
>> errors, or whether it is a red-herring?
>
> It is unlikely that the above message printed by Valgrind is related
> to the double free reported by glibc.
>
> Try to trigger as much code as you can in your application and in
> Net-SNMP and see whether this makes Valgrind report more errors.
>
> Bart.
Hi,
I left valgrind running for over 20 hours with the application doing
some simple snmpget-ing. After 8.5 hours and 29,664 SNMP gets - I got
the first valgrind errors - which were all from a single call to
snmp_free_pdu with a pdu that had already been freed after a
snmp_synch_response returned a STAT_ERROR. No other valgrind errors were
received.
Normally the application would crash, but it seems valgrind allows it to
continue - and the application ran for another 9 hours 22 minutes, and
32,767 SNMP gets with no valgrind errors, and then I got the same
valgrind errors complaining that the pdu had already been freed. The
only valgrind errors I could find where as a direct result of memory
being freed twice.
I have also noticed that if I do enough localhost snmpwalks - each
around 3000 SNMP gets - I can reproduce the same problem. It seems after
around 10 attempts on average, sometimes more, sometimes less. This may
be just a fluke, or my imagination...
The problem seems to come down to the PDU being freed once when a
STAT_ERROR is generated in snmp_synch_response_cb (snmp_client.c:1000):
999 if ((state->reqid = snmp_send(ss, pdu)) == 0) {
1000 snmp_free_pdu(pdu);
1001 state->status = STAT_ERROR;
1002 } else
1003 state->waiting = 1;
And once again when snmp_close() is called as a result of this error. In
snmp_sess_close() - the PDU that was freed above at snmp_client.c:1000
is still on the input request list associated with the session at
snmp_api.c:1886:
1847 /*
1848 * Close the input session. Frees all data allocated for the session,
1849 * dequeues any pending requests, and closes any sockets allocated for
1850 * the session. Returns 0 on error, 1 otherwise.
1851 */
1852 int
1853 snmp_sess_close(void *sessp)
1854 {
1855 struct session_list *slp = (struct session_list *) sessp;
1856 netsnmp_transport *transport;
1857 struct snmp_internal_session *isp;
1858 netsnmp_session *sesp = NULL;
1859 struct snmp_secmod_def *sptr;
1860
1861 if (slp == NULL) {
1862 return 0;
1863 }
1864
1865 if (slp->session != NULL &&
1866 (sptr = find_sec_mod(slp->session->securityModel)) != NULL &&
1867 sptr->session_close != NULL) {
1868 (*sptr->session_close) (slp->session);
1869 }
1870
1871 isp = slp->internal;
1872 slp->internal = 0;
1873
1874 if (isp) {
1875 netsnmp_request_list *rp, *orp;
1876
1877 SNMP_FREE(isp->packet);
1878
1879 /*
1880 * Free each element in the input request list.
1881 */
1882 rp = isp->requests;
1883 while (rp) {
1884 orp = rp;
1885 rp = rp->next_request;
1886 snmp_free_pdu(orp->pdu);
1887 free((char *) orp);
1888 }
1889
1890 free((char *) isp);
1891 }
...
The following is a dbg session for a standard snmpwalk - where you can
see the pdu 0x9050960 was freed at snmp_client.c:1000 and was still on
the request list at snmp_api.c:1885, and was freed again at
snmp_api.c:1886, causing the double free.
Is this a bug, or a symptom of some other issue?
Any ideas, suggestions for other things to try would be much appreciated
- as this problem is slowly driving me mad!
Many thanks,
Craig
# gdb /usr/local/bin/snmpwalk
GNU gdb Fedora (6.8-27.el5)
Copyright (C) 2008 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu"...
(gdb) set args -v2c -cpublic localhost
(gdb) b snmp_client.c:1000
No source file named snmp_client.c.
Make breakpoint pending on future shared library load? (y or [n]) y
Breakpoint 1 (snmp_client.c:1000) pending.
(gdb) run
Starting program: /usr/local/bin/snmpwalk -v2c -cpublic localhost
SNMPv2-MIB::sysDescr.0 = STRING: Linux *** 2.6.18-128.1.10.el5 #1 SMP
Thu May 7 10:35:59 EDT 2009 x86_64
SNMPv2-MIB::sysObjectID.0 = OID: NET-SNMP-MIB::netSnmpAgentOIDs.10
DISMAN-EVENT-MIB::sysUpTimeInstance = Timeticks: (7619945) 21:09:59.45
SNMPv2-MIB::sysContact.0 = STRING: ***
SNMPv2-MIB::sysName.0 = STRING: ***
SNMPv2-MIB::sysLocation.0 = STRING: Unknown
...
...
...
IP-MIB::ipSystemStatsInUnknownProtos.ipv4 = Counter32: 0
IP-MIB::ipSystemStatsInForwDatagrams.ipv4 = Counter32: 0
IP-MIB::ipSystemStatsHCInForwDatagrams
Re: glibc double free error on snmp_sess_close
Bart Van Assche wrote:
> Can you please create a bug report with the information you posted on
> the Net-SNMP coders mailing list, and also the messages printed by
> Valgrind, including the "Address ... is ... bytes inside a block of
> size ... alloc'd" information ? See also
> https://sourceforge.net/tracker/?group_id=12694&atid=112694.
>
> Bart.
Hi Bart,
yes will do. I had a deeper look into what is causing the STAT_ERROR to
be returned in the first place - and I think I found another bug - which
ties in with my "once every 30,000 gets" hunch.
snmp_synch_response_cb is returning STAT_ERROR and freeing the PDU
because a reqid of 0 is returned. Looks like snmp_get_next_reqid has
some rather fundamental bugs in the reqid wraparound logic (snmp_api.c:409)
409 long
410 snmp_get_next_reqid(void)
411 {
412 longretVal;
413 snmp_res_lock(MT_LIBRARY_ID, MT_LIB_REQUESTID);
414 retVal = 1 + Reqid; /*MTCRITICAL_RESOURCE */
415 if (!retVal)
416 retVal = 2;
417 Reqid = retVal;
418 snmp_res_unlock(MT_LIBRARY_ID, MT_LIB_REQUESTID);
419 if (netsnmp_ds_get_boolean(NETSNMP_DS_LIBRARY_ID,
NETSNMP_DS_LIB_16BIT_IDS))
420 return (retVal & 0x7fff); /* mask to 15 bits */
421 else
422 return (retVal & 0x7fff); /* mask to 31 bits */
423 }
As I mentioned before - I am having to use 16 bit request ids. This code
generates a requestid of 0 every 32,767 requests. For 32 bit request ids
- it generates a 0 every 0x requests (probably not an issue, but
still wrong).
It seems to have made assumptions about the sizeof long - for the
wrapping logic [ if (!retVal) ] which do not hold, and then forgotten
about 16 bit requestids. And having retVal as a signed long is confusing.
I guess I should post this as a bug too?
Many thanks,
Craig
__ Information from ESET Smart Security, version of virus signature
database 4328 (20090812) __
The message was checked by ESET Smart Security.
http://www.eset.com
--
Let Crystal Reports handle the reporting - Free Crystal Reports 2008 30-Day
trial. Simplify your report design, integration and deployment - and focus on
what you do best, core application coding. Discover what's new with
Crystal Reports now. http://p.sf.net/sfu/bobj-july
___
Net-snmp-coders mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/net-snmp-coders
Re: glibc double free error on snmp_sess_close
Dave Shield wrote:
> Good catch!
> Try the following tweak to the code, and see if it fixes the problem:
>
>> 419 if (netsnmp_ds_get_boolean(NETSNMP_DS_LIBRARY_ID,
>> NETSNMP_DS_LIB_16BIT_IDS))
>> 420 retVal &= 0x7fff; /* mask to 15 bits */
>> 421 else
>> 422 retVal &= 0x7fff; /* mask to 31 bits */
>
> if (!retVal) {
> retVal = 2;
> Reqid = retVal;
> }
> return retVal;
>
>
> (This really needs locking around the Reqid assignment,
> but let's see whether it works properly first).
>
> Dave
Hi Dave,
yes - this seems to work for the repeated snmpwalk tests (no failures
after 40 tests - previously got one every 5-15 tests). The original
application will have to run for 9 hours before I can verify that is
fixed too - but it is running fine now.
Many thanks,
Craig
__ Information from ESET Smart Security, version of virus signature
database 4329 (20090812) __
The message was checked by ESET Smart Security.
http://www.eset.com
--
Let Crystal Reports handle the reporting - Free Crystal Reports 2008 30-Day
trial. Simplify your report design, integration and deployment - and focus on
what you do best, core application coding. Discover what's new with
Crystal Reports now. http://p.sf.net/sfu/bobj-july
___
Net-snmp-coders mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/net-snmp-coders
Re: glibc double free error on snmp_sess_close
[email protected] wrote: > Dave Shield wrote: > Hi Dave, > > yes - this seems to work for the repeated snmpwalk tests (no failures > after 40 tests - previously got one every 5-15 tests). The original > application will have to run for 9 hours before I can verify that is > fixed too - but it is running fine now. > > Many thanks, > Craig Just to confirm - the application made it through the night, and the 16-bit reqid wraparound - currently on around 65,000 sends, so looks like the fix is good. Best regards, Craig __ Information from ESET Smart Security, version of virus signature database 4331 (20090813) __ The message was checked by ESET Smart Security. http://www.eset.com -- Let Crystal Reports handle the reporting - Free Crystal Reports 2008 30-Day trial. Simplify your report design, integration and deployment - and focus on what you do best, core application coding. Discover what's new with Crystal Reports now. http://p.sf.net/sfu/bobj-july ___ Net-snmp-coders mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/net-snmp-coders
