search

LudovicRousseau / pyscard

pyscard smartcard library for python
http://pyscard.sourceforge.net/
GNU Lesser General Public License v2.1
383 stars 110 forks source link

CardMonitor memory leak. #37

Closed valdur55 closed 7 years ago

valdur55 commented 7 years ago

My program which uses heavily pyscard CardMonitor leaks memory. Atm i am using pyscad 1.9.4.

Memory leak occurs with raspbian (raspberrypi). With computer i can't reproduce memory leak.

Minimal code for code leaking, is this:https://paste.debian.net/911098/

Application have runned one day and pmap output is: http://pastebin.com/K3hexCrZ Basically Monitoring smartcard insertion/removal example.

Suspicios parts are: XXXXX 2048K rw--- [ anon ]

And content inside them: http://pastebin.com/Aa8J7SVW I looked more parts of it and there are same repeating pattern.

And there is pmap output after application restart: http://pastebin.com/E9Uwce0W

Installation log: http://paste.debian.net/911086/

I wrote down 2048K parts own at every half hour.

2017-01-16 00:30:01 ; 0 ; 2017-01-16 01:00:01 ; 0 ; 2017-01-16 01:30:01 ; 0 ; 2017-01-16 02:00:01 ; 1 ; 2017-01-16 02:30:01 ; 1 ; 2017-01-16 03:00:02 ; 1 ; 2017-01-16 03:30:01 ; 2 ; 2017-01-16 04:00:01 ; 2 ; 2017-01-16 04:30:01 ; 2 ; 2017-01-16 05:00:01 ; 3 ; 2017-01-16 05:30:01 ; 3 ; 2017-01-16 06:00:01 ; 3 ; 2017-01-16 06:30:01 ; 4 ; 2017-01-16 07:00:01 ; 4 ; 2017-01-16 07:30:01 ; 4 ; 2017-01-16 08:00:01 ; 5 ; 2017-01-16 08:30:01 ; 5 ; 2017-01-16 09:00:02 ; 6 ; 2017-01-16 09:15:01 ; 6 ;

I digged even deeper and collecked more fequently and other statistic about pmap output. Found a interesting behaviour, memory leak has steps. At first 1024K is captured and next step is 2048K.

LudovicRousseau commented 7 years ago

How do you interpret the fact that the memory leak occurs on a RaspberryPi and not with a "real" computer?

valdur55 commented 7 years ago

I runned same code on computer.

And there is result:

time ; anon 2048K; total user mem, anon parts count ; pmap output lines count 2017-01-21 23:05:23 ; 0 ; 290256K ; 31 ; 125 2017-01-21 23:09:23 ; 0 ; 290256K ; 31 ; 125 2017-01-21 23:15:01 ; 0 ; 290256K ; 31 ; 125 2017-01-21 23:30:01 ; 0 ; 290256K ; 31 ; 125 2017-01-21 23:45:01 ; 0 ; 290256K ; 31 ; 125 2017-01-22 00:00:01 ; 0 ; 290256K ; 31 ; 125 2017-01-22 00:15:01 ; 0 ; 290256K ; 31 ; 125 2017-01-22 00:30:01 ; 0 ; 290256K ; 31 ; 125 2017-01-22 00:45:01 ; 0 ; 290256K ; 31 ; 125 2017-01-22 01:00:01 ; 0 ; 290256K ; 31 ; 125 2017-01-22 01:15:01 ; 0 ; 290256K ; 31 ; 125 2017-01-22 01:30:01 ; 0 ; 290256K ; 31 ; 125 2017-01-22 01:45:01 ; 0 ; 290256K ; 31 ; 125 2017-01-22 02:00:01 ; 0 ; 290256K ; 31 ; 125

Maybe it is distro and version specific. Atm i am using Ubuntu 16.04.

For monitoring i used this script: http://paste.debian.net/911224/

And at crontab side: 0,15,30,45 * * * * /home/pi/monitor.sh

I forgot to mention that a leak occurs when reader is connected.

miohtama commented 7 years ago

Here is some information how to diagnose potential memory leaks in Python:

http://chase-seibert.github.io/blog/2013/08/03/diagnosing-memory-leaks-python.html

Because it is a long running process you can make it to dump Python object statistics to a log file regularly.

I suggest you set up a Python debug build and use Heapy. If Heapy/objgraph doesn't report leaks, the leak is most likely on the driver/application side and not within the Python code.

In any case, an insight what objects are being createad and not reclaimed by gc() in Python is needed.

LudovicRousseau commented 7 years ago

@valdur55 if you do not have a memory leak on Ubuntu 16.04 then I guess there is no memory leak.

The problem may be RapsberryPi specific and not in pyscard code. No?

valdur55 commented 7 years ago

Looks like i need give more time to computer... I used my mom's old computer and catched memory leak:

CPU AMD Athlon(tm) Processor TF-20 inux mint 4.4.0-31-generic #50-Ubuntu SMP Wed Jul 13 00:06:14 UTC 2016 i686 athlon i686 GNU/Linux Runned my program.

2017-02-07 19:51:40 ; 0 ; 43768K ; 21 ; 72 2017-02-07 20:00:01 ; 0 ; 44792K ; 22 ; 73 2017-02-07 20:15:01 ; 0 ; 44792K ; 22 ; 73 2017-02-07 20:30:01 ; 1 ; 45816K ; 23 ; 74 2017-02-07 20:45:02 ; 1 ; 45816K ; 23 ; 74 2017-02-07 21:00:01 ; 1 ; 45816K ; 23 ; 74 2017-02-07 21:15:01 ; 1 ; 46840K ; 23 ; 74 2017-02-07 21:30:01 ; 1 ; 46840K ; 23 ; 74 2017-02-07 21:45:01 ; 2 ; 47864K ; 24 ; 75 2017-02-07 22:00:01 ; 2 ; 47864K ; 24 ; 75 2017-02-07 22:15:01 ; 2 ; 48888K ; 24 ; 75 2017-02-07 22:30:01 ; 2 ; 48888K ; 24 ; 75 2017-02-07 22:45:01 ; 2 ; 48888K ; 24 ; 75

I used Objgraph and gc.collect in PI (10h). Data save interval was 5 minutes. Raw data: http://pastebin.com/9X5QDGwa And items which changed on that time:

dict ['1138', '1146'] list ['263', '268'] Event ['3', '6'] Condition ['3', '6'] method ['26', '22'] builtin_function_or_method ['683', '689', '690', '689'] frame ['12', '9', '12', '9'] tuple ['1207', '1200', '934', '933', '934'] deque ['3', '6'] weakref ['756', '757']

Next time i will remove gc.collect().

I runned my program with gc.collect() at every two hours, and result:

2017-02-02 21:38:36 ; 0 ; 50928K ; 30 ; 100 2017-02-02 21:45:01 ; 0 ; 50928K ; 30 ; 100 2017-02-02 22:00:02 ; 0 ; 50928K ; 30 ; 100 2017-02-02 22:15:01 ; 0 ; 50928K ; 30 ; 100 2017-02-02 22:30:01 ; 0 ; 50928K ; 30 ; 100 2017-02-02 22:45:02 ; 0 ; 51952K ; 31 ; 101 2017-02-02 23:00:01 ; 0 ; 51952K ; 31 ; 101 2017-02-02 23:15:01 ; 0 ; 51952K ; 31 ; 101 2017-02-02 23:30:01 ; 0 ; 52976K ; 31 ; 101 2017-02-02 23:45:01 ; 0 ; 52976K ; 31 ; 101 2017-02-03 00:00:01 ; 0 ; 52976K ; 31 ; 101 2017-02-03 00:15:01 ; 0 ; 52976K ; 31 ; 101 2017-02-03 00:30:01 ; 1 ; 54000K ; 32 ; 102 2017-02-03 00:45:01 ; 1 ; 54000K ; 32 ; 102 2017-02-03 01:00:01 ; 1 ; 54000K ; 32 ; 102 2017-02-03 01:15:01 ; 1 ; 54000K ; 32 ; 102 2017-02-03 01:30:01 ; 1 ; 55024K ; 32 ; 102 2017-02-03 01:45:01 ; 1 ; 55024K ; 32 ; 102 2017-02-03 02:00:01 ; 1 ; 55024K ; 32 ; 102 2017-02-03 02:15:01 ; 2 ; 55024K ; 31 ; 101 2017-02-03 02:30:01 ; 2 ; 56048K ; 33 ; 103 2017-02-03 02:45:01 ; 2 ; 56048K ; 33 ; 103 2017-02-03 03:00:01 ; 2 ; 56048K ; 33 ; 103 2017-02-03 03:15:01 ; 2 ; 57072K ; 33 ; 103 2017-02-03 03:30:01 ; 2 ; 57072K ; 33 ; 103 2017-02-03 03:45:01 ; 2 ; 57072K ; 33 ; 103 2017-02-03 04:00:01 ; 2 ; 57072K ; 33 ; 103 2017-02-03 04:15:01 ; 3 ; 58096K ; 34 ; 104 2017-02-03 04:30:01 ; 3 ; 58096K ; 34 ; 105 2017-02-03 04:45:01 ; 3 ; 58096K ; 34 ; 104 2017-02-03 05:00:01 ; 3 ; 58096K ; 34 ; 104 2017-02-03 05:15:01 ; 3 ; 59120K ; 34 ; 104 2017-02-03 05:30:01 ; 3 ; 59120K ; 34 ; 104 2017-02-03 05:45:01 ; 3 ; 59120K ; 34 ; 104 2017-02-03 06:00:01 ; 4 ; 60144K ; 35 ; 105 2017-02-03 06:15:01 ; 4 ; 60144K ; 35 ; 105 2017-02-03 06:30:01 ; 4 ; 60144K ; 35 ; 105 2017-02-03 06:45:01 ; 4 ; 60144K ; 35 ; 105 2017-02-03 07:00:02 ; 4 ; 61168K ; 35 ; 105 2017-02-03 07:15:01 ; 4 ; 61168K ; 35 ; 105 2017-02-03 07:30:01 ; 4 ; 61168K ; 35 ; 105 2017-02-03 07:45:01 ; 4 ; 61168K ; 35 ; 105

valdur55 commented 7 years ago

I talked with my firend @kiik ( https://github.com/kiik). And he suggested to save memory as birany files and check if fragments differs.

I used this script: http://serverfault.com/a/408929

Fragments got binary difference.

I runned strings over leaked fragment and got wall of this:

Feitian R502 [R502 Contact Reader] (C29A4D780600011C) 01 00 Feitian R502 [R502 Contactless Reader] (C29A4D780600011C) 00 00 Feitian R502 [R502 SAM1 Reader] (C29A4D780600011C) 02 00 00E

It is my reader!!!!

LudovicRousseau commented 7 years ago

Maybe a leak in pcsc-lite? I tried to read your sample code again but https://paste.debian.net/911098/ is now a dead link.

Can you please include your code here or use services that will not expire.

valdur55 commented 7 years ago

Long living paste: http://pastebin.com/cTYCizHx Pasting code here failed because markdown detects some patterns...

  #! /usr/bin/env python
"""
Sample script that monitors smartcard insertion/removal.

__author__ = "http://www.gemalto.com"

Copyright 2001-2012 gemalto
Author: Jean-Daniel Aussel, mailto:jean-daniel.aussel@gemalto.com

This file is part of pyscard.

pyscard is free software; you can redistribute it and/or modify
it under the terms of the GNU Lesser General Public License as published by
the Free Software Foundation; either version 2.1 of the License, or
(at your option) any later version.

pyscard is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU Lesser General Public License for more details.

You should have received a copy of the GNU Lesser General Public License
along with pyscard; if not, write to the Free Software
Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
"""

from __future__ import print_function
from time import sleep

from smartcard.CardMonitoring import CardMonitor, CardObserver
from smartcard.util import toHexString

# a simple card observer that prints inserted/removed cards
class PrintObserver(CardObserver):
    """A simple card observer that is notified
    when cards are inserted/removed from the system and
    prints the list of cards
    """

    def update(self, observable, actions):
        (addedcards, removedcards) = actions
        for card in addedcards:
            print("+Inserted: ", toHexString(card.atr))
        for card in removedcards:
            print("-Removed: ", toHexString(card.atr))

if __name__ == '__main__':
    print("Insert or remove a smartcard in the system.")
    print("This program will run forever")
    print("")
    cardmonitor = CardMonitor()
    cardobserver = PrintObserver()
    cardmonitor.addObserver(cardobserver)

    while True:
        sleep(1)

    # don't forget to remove observer, or the
    # monitor will poll forever...
    cardmonitor.deleteObserver(cardobserver)

    import sys
    if 'win32' == sys.platform:
        print('press Enter to continue')
        sys.stdin.read(6000)

EDIT: Removed gc.collect stuff.

LudovicRousseau commented 7 years ago

You just let the program run? You do not connect or disconnect the reader? or insert/remove a card?

valdur55 commented 7 years ago

Yes i let the program run. Reader is always connected.

Created new leak analyzer: http://pastebin.com/ChWwg7av

I runned a script every minute and reader counting is by mem fragments:

 K veebr  8 20:23:10 EET 2017
24987-7f9c0c000000-7f9c0c021000.dump ; 236
24987-7f9c10de9000-7f9c1168a000.dump ; 2
24987-7f9c11894000-7f9c11895000.dump ; 1
24987-7f9c13195000-7f9c1331a000.dump ; 1
K veebr  8 20:24:01 EET 2017
24987-7f9c0c000000-7f9c0c021000.dump ; 636
24987-7f9c10de9000-7f9c1168a000.dump ; 2
24987-7f9c11894000-7f9c11895000.dump ; 1
24987-7f9c13195000-7f9c1331a000.dump ; 1
K veebr  8 20:24:18 EET 2017
24987-7f9c0c000000-7f9c0c021000.dump ; 700
24987-7f9c10de9000-7f9c1168a000.dump ; 2
24987-7f9c11894000-7f9c11895000.dump ; 1
24987-7f9c13195000-7f9c1331a000.dump ; 1
K veebr  8 20:25:01 EET 2017
24987-7f9c0c000000-7f9c0c021000.dump ; 1033
24987-7f9c10de9000-7f9c1168a000.dump ; 2
24987-7f9c11894000-7f9c11895000.dump ; 1
24987-7f9c13195000-7f9c1331a000.dump ; 1
K veebr  8 20:26:01 EET 2017
24987-7f9c0c000000-7f9c0c027000.dump ; 1535
24987-7f9c10de9000-7f9c1168a000.dump ; 2
24987-7f9c11894000-7f9c11895000.dump ; 1
24987-7f9c13195000-7f9c1331a000.dump ; 1
K veebr  8 20:27:01 EET 2017
24987-7f9c0c000000-7f9c0c032000.dump ; 2021
24987-7f9c10de9000-7f9c1168a000.dump ; 2
24987-7f9c11894000-7f9c11895000.dump ; 1
24987-7f9c13195000-7f9c1331a000.dump ; 1
K veebr  8 20:28:01 EET 2017
24987-7f9c0c000000-7f9c0c03e000.dump ; 2524
24987-7f9c10de9000-7f9c1168a000.dump ; 2
24987-7f9c11894000-7f9c11895000.dump ; 1
24987-7f9c13195000-7f9c1331a000.dump ; 1
K veebr  8 20:29:01 EET 2017
24987-7f9c0c000000-7f9c0c04a000.dump ; 3027
24987-7f9c10de9000-7f9c1168a000.dump ; 2
24987-7f9c11894000-7f9c11895000.dump ; 1
24987-7f9c13195000-7f9c1331a000.dump ; 1
K veebr  8 20:30:01 EET 2017
24987-7f9c0c000000-7f9c0c056000.dump ; 3529
24987-7f9c10de9000-7f9c1168a000.dump ; 2
24987-7f9c11894000-7f9c11895000.dump ; 1
24987-7f9c13195000-7f9c1331a000.dump ; 1
K veebr  8 20:31:01 EET 2017
24987-7f9c0c000000-7f9c0c061000.dump ; 4004
24987-7f9c10de9000-7f9c1168a000.dump ; 2
24987-7f9c11894000-7f9c11895000.dump ; 1
24987-7f9c13195000-7f9c1331a000.dump ; 1
K veebr  8 20:32:01 EET 2017
24987-7f9c0c000000-7f9c0c06d000.dump ; 4509
24987-7f9c10de9000-7f9c1168a000.dump ; 2
24987-7f9c11894000-7f9c11895000.dump ; 1
24987-7f9c13195000-7f9c1331a000.dump ; 1
K veebr  8 20:33:01 EET 2017
24987-7f9c0c000000-7f9c0c078000.dump ; 5002
24987-7f9c10de9000-7f9c1168a000.dump ; 2
24987-7f9c11894000-7f9c11895000.dump ; 1
24987-7f9c13195000-7f9c1331a000.dump ; 1

Atm last count is 23350 at first part and every minute i get +500 (maybe at first parts i had connected other reader which caused pyscard reader status loop slowdown)

EDIT: I disconnecter cardreader and waited some minutes. Stats didn't change and saw a change in output: Got one 1 part instead of two 1 parts.

/tmp/minimal-leak/24987-7f9c0c000000-7f9c0c243000.dump ; 24571
/tmp/minimal-leak/24987-7f9c10de9000-7f9c1168a000.dump ; 2
/tmp/minimal-leak/24987-7f9c13195000-7f9c1331a000.dump ; 1

EDIT: Looks like somewhere is += instead of =.

valdur55 commented 7 years ago

Used pympler (https://pythonhosted.org/Pympler/) and after 30 second of a launch pympler doesn't see changes. Looks like python side is OK.

I tested pcsc_scan and ReaderMonitor example. Both are ok.

Btw. After i started reading memory i can see leak aslo in my computer.

Have u reproduced this leak successfully?

LudovicRousseau commented 7 years ago

No, I have not yet reproduce the leak.

Can you elaborate "After i started reading memory i can see leak also in my computer."?

valdur55 commented 7 years ago

Take ubuntu-server 16.04.1 iso. Run command apt-get install python3-pyscard gdb pcsc-tools pcscd to install dependencies.

Take http://pastebin.com/ChWwg7av . change those vars: pcsc_scan will show reader name (u can use full reader name or part of it)

reader='Hewlett-Packard Company HP USB Smart Card Keyboard' logfile='/home/valdur55/0-mem-minimal-leak.log'

Take http://pastebin.com/cTYCizHx and save it as mon.py

Attach reader to virtual machine. Run mon.py (u can run i on background).

Run leak-analyzer.sh as super user (otherwise u get premission denied error)

Look what is in logfile. (u can use tail -f 0-mem-minimal-leak.log)

'reading memory' - used gdb to save memory parts as binary file and runned strings over it and grep -c for getting a count

How do you know the memory is leaking?

When count of readername in memory increases, then we have leak. In longer time, when program uses to much memory (all), it's process will be killed. And it has happened multible times.

Btw. pcsc_scan doesn't leak.

LudovicRousseau commented 7 years ago

I can reproduce the memory leak using your scripts. I will try to reproduce it using the low level PySCard functions.

LudovicRousseau commented 7 years ago

You can get a better "performance" for the memory leak by changing the value self.pollinginterval at https://github.com/LudovicRousseau/pyscard/blob/master/smartcard/pcsc/PCSCCardRequest.py#L73

For example you can use self.pollinginterval = 0.0001

LudovicRousseau commented 7 years ago

It looks like the memory leak is with SCardGetStatusChange() Python wrapper.

I get a rapid memory consumption increase with the following sample code:

#!/usr/bin/env python3

from smartcard.scard import *
from smartcard.pcsc.PCSCExceptions import *

hresult, hcontext = SCardEstablishContext(SCARD_SCOPE_USER)
if hresult != SCARD_S_SUCCESS:
    raise EstablishContextException(hresult)

hresult, readers = SCardListReaders(hcontext, [])
if hresult != SCARD_S_SUCCESS:
    raise ListReadersException(hresult)
print('PC/SC Readers:', readers)

readerstates = {}
for reader in readers:
    readerstates[reader] = (reader, SCARD_STATE_UNAWARE)

i = 0
while True:
    i += 1

    hresult, newstates = SCardGetStatusChange(hcontext, 0,
            list(readerstates.values()))
    if hresult != SCARD_S_SUCCESS and hresult != SCARD_E_TIMEOUT:
        raise BaseSCardException(hresult)
    print(i, newstates)
    for readerState in newstates:
        readername, eventstate, atr = readerState
        readerstates[readername] = (readername, eventstate)

hresult = SCardReleaseContext(hcontext)
print(SCardGetErrorMessage(hresult))
LudovicRousseau commented 7 years ago

Fixed in https://github.com/LudovicRousseau/pyscard/commit/2c5f763dd1da94630dbc41e04159cc0b23a2c75c

Thanks