Opened 8 years ago

Closed 8 years ago

Last modified 8 years ago

#1359 closed defect (fixed)

reference leak in python log wrapper

Reported by: jinmei Owned by: jinmei
Priority: medium Milestone: Sprint-20111122
Component: logging Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: Core Feature Depending on Ticket:
Estimated Difficulty: 4 Add Hours to Ticket: 0
Total Hours: 3.37 Internal?: no

Description

There seems to be (potential) reference leak in the C++ wrapper
for logging. For example, see this:

        PyObject *midO(PySequence_GetItem(args, start - 1));
        if (midO == NULL) {
            return (NULL);
        }
        string mid(objectToStr(midO, false));

(midO isn't used anywhere else). PySequence_GetItem acquires
a new reference to the extracted object, but it's not decremented.

BTW, the apparent remaining leak I mentioned in #1028 seems to be
related to logging. I experimentally replaced logger methods with
fake empty functions, and then b10-xfrin uses much less amount of
memory. So I quickly looked at logging related code and found this one.
But I suspect this reference leak is not the reason in my test case
because the logged messagees always consist of the same set of strings
(but this won't be the case in general so we should still fix this),
and the python interpreter should keep the same string object for the
same string.

We may have leak in the C++ liblog or in log4cplus. According to
this link log4cplus seems to have memory leaks:
http://stackoverflow.com/questions/696321/best-logging-framework-for-native-c

Subtickets

Change History (15)

comment:1 Changed 8 years ago by jelte

  • Estimated Difficulty changed from 0 to 4

comment:2 Changed 8 years ago by jelte

  • Milestone changed from Next-Sprint-Proposed to Sprint-20111122

comment:3 Changed 8 years ago by jinmei

  • Owner set to jinmei
  • Status changed from new to accepted

comment:4 Changed 8 years ago by jinmei

trac1359 is ready for review.

I've found a more critical leak in the log wrapper, and succesfully
reproduced clear memory leak with the following simple test code:

while True:
    name = isc.dns.Name('example.com')
    rrclass = isc.dns.RRClass('IN') 
    logger.info(XFRIN_XFR_TRANSFER_SUCCESS, 'AXFR',
                name.to_text(True) + '/' + str(rrclass))

(of course you'll need to import necessary modules and set PYTHONPATH, etc,
properly).

I've fixed the leak in this branch, and confirmed it completely solves
this type of memory leak.

Since the main fix is pretty small and (I believe) straightforward,
I've also made some additional cleanups (some of which are actually
not just for cleanness but fixes rare exception safety bugs). The
main fix is the first two commits. If the additional changes are
deemed to be beyond the scope of this ticket, I'm okay with deferring
them to a separate ticket.

This is the proposed changelog entry:

317.	[bug]		jinmei
	Fixed reference leak in the isc.log Python module.  Most of all
	BIND 10 Python programs had memory leak (even though the pace of
	leak may be slow) due to this bug.
	(Trac #1359, git TBD)

BTW, this is totally unrelated to this ticket, but I've been also
noticing that in the python log wrapper converts the expensive
conversion from objects to string for all log levels. I guess this
has non negligible performance impact even if performance is
relatively less crucial for python programs. I wonder whether we
should do the isXXXEnabled() check in Logger_debug(), etc, before
calling Logger_performOutput. Would that be worth trying, maybe
in a separate ticket?

Last edited 8 years ago by jinmei (previous) (diff)

comment:5 Changed 8 years ago by jinmei

  • Owner changed from jinmei to UnAssigned
  • Status changed from accepted to assigned

comment:6 Changed 8 years ago by jinmei

  • Status changed from assigned to reviewing

comment:7 Changed 8 years ago by vorner

  • Owner changed from UnAssigned to vorner

comment:8 follow-up: Changed 8 years ago by vorner

  • Owner changed from vorner to jinmei

Hello

The changes look OK themself. But I have a failing test:

======================================================================
ERROR: test_invalid_family (__main__.ParserTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/vorner/work/bind10/src/lib/python/isc/bind10/tests/sockcreator_test.py", line 289, in test_invalid_family
    addr, 42, socket.SOCK_DGRAM)
  File "/usr/lib64/python3.2/unittest/case.py", line 557, in assertRaises
    callableObj(*args, **kwargs)
  File "/home/vorner/work/bind10/src/lib/python/isc/bind10/sockcreator.py", line 111, in get_socket
    logger.info(BIND10_SOCKET_GET, address, port, socktype)
RuntimeError: Unexpected NULL PyObject, probably due to short memory

----------------------------------------------------------------------
Ran 16 tests in 0.009s

FAILED (errors=1)
make[7]: *** [check-local] Error 1
make[7]: Leaving directory `/home/vorner/work/bind10/src/lib/python/isc/bind10/tests'

The exception comes from the PyObjectContainer? and the previous code seemed to be able to handle the situation, but I don't know where the NULL comes from exactly. Would you have a look what it might be?

Thank you

comment:9 in reply to: ↑ 8 ; follow-up: Changed 8 years ago by jinmei

Replying to vorner:

Hello

The changes look OK themself. But I have a failing test:

[...]

The exception comes from the PyObjectContainer? and the previous code seemed to be able to handle the situation, but I don't know where the NULL comes from exactly. Would you have a look what it might be?

Ah, okay. I was lazy and naively assumed this change didn't affect other
part of the code. I fixed it, and confirmed all unit tests now passed.

comment:10 Changed 8 years ago by jinmei

  • Owner changed from jinmei to vorner

comment:11 Changed 8 years ago by stephen

BTW, this is totally unrelated to this ticket, but I've been also noticing that in the python log wrapper converts the expensive conversion from objects to string for all log levels. I guess this has non negligible performance impact even if performance is relatively less crucial for python programs. I wonder whether we should do the isXXXEnabled() check in Logger_debug(), etc, before calling Logger_performOutput. Would that be worth trying, maybe in a separate ticket?

I think so. In the C++ code we were worried about the overhead of evaluating the arguments passed to logger.debug() even if nothing was going to be output, since these may involve expensive operations (e.g. conversion to a string). That's why the LOG_XXX macros came about: these do precisely what you suggest, i.e. calling isXXXEnabled() and doing nothing (not even evaluating arguments) if it returns false.

comment:12 in reply to: ↑ 9 ; follow-up: Changed 8 years ago by vorner

  • Owner changed from vorner to jinmei

Hello

Replying to jinmei:

Replying to vorner:

Hello

The changes look OK themself. But I have a failing test:

[...]

The exception comes from the PyObjectContainer? and the previous code seemed to be able to handle the situation, but I don't know where the NULL comes from exactly. Would you have a look what it might be?

Ah, okay. I was lazy and naively assumed this change didn't affect other
part of the code. I fixed it, and confirmed all unit tests now passed.

OK, seems ready to merge.

Thank you

comment:13 in reply to: ↑ 12 Changed 8 years ago by jinmei

Replying to vorner:

The exception comes from the PyObjectContainer? and the previous code seemed to be able to handle the situation, but I don't know where the NULL comes from exactly. Would you have a look what it might be?

Ah, okay. I was lazy and naively assumed this change didn't affect other
part of the code. I fixed it, and confirmed all unit tests now passed.

OK, seems ready to merge.

Thanks, merge done, closing.

comment:14 Changed 8 years ago by jinmei

  • Resolution set to fixed
  • Status changed from reviewing to closed
  • Total Hours changed from 0 to 2.37

comment:15 Changed 8 years ago by vorner

  • Total Hours changed from 2.37 to 3.37
Note: See TracTickets for help on using tickets.