Recorder Memory leak: Investigate valgrind output

[hoffie]

Describe the bug

valgrind shows that memory is leaked. It might be related to the jam recorder.
This is an attempt to reproduce the real-world memleaks as observed by @genesisproject2020 (~1GB RAM within ~25 hours) in #923 (comment)
valgrind ran ~10 minutes and the server had 7 clients connected (all sending silence).

To Reproduce

$ valgrind --leak-check=full ./Jamulus -s -n -p 10001 -e localhost:10000 -l /tmp/log -R /tmp/recordings -o 'Private Server;Stockholm;205' -m /tmp/jam.dat -u 40 -T -w 'Welcome!'
==129778== Memcheck, a memory error detector
==129778== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==129778== Using Valgrind-3.16.1 and LibVEX; rerun with -h for copyright info
==129778== Command: ./Jamulus -s -n -p 10001 -e localhost:10000 -l /tmp/log -R /tmp/recordings -o Private\ Server;Stockholm;205 -m /tmp/jam.dat -u 40 -T -w Welcome!
==129778== 
- server mode chosen
- no GUI mode chosen
- selected port number: 10001
- central server: localhost:10000
- logging file name: /tmp/log
- recording directory name: /tmp/recordings
- server info: Private Server;Stockholm;205
- HTML status file name: /tmp/jam.dat
- maximum number of channels: 40
- using multithreading
- welcome message: Welcome!
Recording state: enabled
 *** Jamulus, Version 3.6.2dev-83d5f0cf
 *** Internet Jam Session Software
 *** Released under the GNU General Public License (GPL)
Server Registration Status update: Registration requested
Server Registration Status update: Registered
2021-02-18 23:36:37, 127.0.0.1, connected (1)
2021-02-18 23:36:38, 127.0.0.1, connected (2)
2021-02-18 23:36:47, 127.0.0.1, connected (3)
2021-02-18 23:36:50, 127.0.0.1, connected (5)
2021-02-18 23:36:54, 127.0.0.1, connected (7)
2021-02-18 23:36:59, 127.0.0.1, connected (7)
2021-02-18 23:37:09, 127.0.0.1, connected (7)
^C2021-02-18 23:47:50,, server idling -------------------------------------
Session RPP: "/tmp/recordings/Jam-20210218-223637790/Jam-20210218-223637790.rpp"
Session LOF: "/tmp/recordings/Jam-20210218-223637790/Jam-20210218-223637790.lof"
Server Registration Status update: Registration requested
OnHandledSignal: 2
Server Registration Status update: Unregistered
==129778== 
==129778== HEAP SUMMARY:
==129778==     in use at exit: 8,563,566 bytes in 1,266 blocks
==129778==   total heap usage: 12,369,339 allocs, 12,368,073 frees, 3,617,858,812 bytes allocated
==129778== 
==129778== 352 bytes in 1 blocks are possibly lost in loss record 115 of 165
==129778==    at 0x483CB65: calloc (vg_replace_malloc.c:760)
==129778==    by 0x40142EB: _dl_allocate_tls (in /usr/lib/ld-2.32.so)
==129778==    by 0x48C913C: pthread_create@@GLIBC_2.2.5 (in /usr/lib/libpthread-2.32.so)
==129778==    by 0x58D79A2: QThread::start(QThread::Priority) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x15B782: CServer::CServer(int, QString const&, unsigned short, QString const&, QString const&, QString const&, QString const&, QString const&, QString const&, QString const&, bool, bool, bool, bool, ELicenceType) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x13BD6F: main (in /home/christian/Projects/jamulus/Jamulus)
==129778== 
==129778== 352 bytes in 1 blocks are possibly lost in loss record 116 of 165
==129778==    at 0x483CB65: calloc (vg_replace_malloc.c:760)
==129778==    by 0x40142EB: _dl_allocate_tls (in /usr/lib/ld-2.32.so)
==129778==    by 0x48C913C: pthread_create@@GLIBC_2.2.5 (in /usr/lib/libpthread-2.32.so)
==129778==    by 0x58D79A2: QThread::start(QThread::Priority) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x155EFF: CServer::Start() (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x5AEC4BE: QObject::event(QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5ABFA4F: QCoreApplication::notifyInternal2(QObject*, QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5AC2572: QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5B190A3: ??? (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x7147A83: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x719B9B0: ??? (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x71462B0: g_main_context_iteration (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778== 
==129778== 392 bytes in 7 blocks are definitely lost in loss record 118 of 165
==129778==    at 0x483ADEF: operator new(unsigned long) (vg_replace_malloc.c:342)
==129778==    by 0x1AD536: recorder::CJamClient::CJamClient(long long, int, QString, CHostAddress, QDir) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x1AEAB7: recorder::CJamSession::Frame(int, QString, CHostAddress, int, CVector<short>, int) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x1B18C6: recorder::CJamRecorder::OnFrame(int, QString, CHostAddress, int, CVector<short>) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x155B5A: QtPrivate::QSlotObject<void (recorder::CJamRecorder::*)(int, QString, CHostAddress, int, CVector<short>), QtPrivate::List<int, QString, CHostAddress, int, CVector<short> >, void>::impl(int, QtPrivate::QSlotObjectBase*, QObject*, void**, bool*) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x5AEC581: QObject::event(QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5ABFA4F: QCoreApplication::notifyInternal2(QObject*, QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5AC2572: QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5B190A3: ??? (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x7147A83: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x719B9B0: ??? (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x71462B0: g_main_context_iteration (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778== 
==129778== 438 (88 direct, 350 indirect) bytes in 1 blocks are definitely lost in loss record 120 of 165
==129778==    at 0x483ADEF: operator new(unsigned long) (vg_replace_malloc.c:342)
==129778==    by 0x5AF54E5: QObject::QObject(QObject*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x1ADF21: recorder::CJamSession::DisconnectClient(int) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x1AE1A8: recorder::CJamRecorder::OnDisconnected(int) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x5AEC581: QObject::event(QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5ABFA4F: QCoreApplication::notifyInternal2(QObject*, QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5AC2572: QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5B190A3: ??? (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x7147A83: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x719B9B0: ??? (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x71462B0: g_main_context_iteration (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x5B186FB: QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) (in /usr/lib/libQt5Core.so.5.15.2)
==129778== 
==129778== 876 (112 direct, 764 indirect) bytes in 2 blocks are definitely lost in loss record 129 of 165
==129778==    at 0x483ADEF: operator new(unsigned long) (vg_replace_malloc.c:342)
==129778==    by 0x1ADF14: recorder::CJamSession::DisconnectClient(int) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x1AE1A8: recorder::CJamRecorder::OnDisconnected(int) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x5AEC581: QObject::event(QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5ABFA4F: QCoreApplication::notifyInternal2(QObject*, QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5AC2572: QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5B190A3: ??? (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x7147A83: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x719B9B0: ??? (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x71462B0: g_main_context_iteration (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x5B186E0: QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5ABE3FB: QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) (in /usr/lib/libQt5Core.so.5.15.2)
==129778== 
==129778== 1,056 bytes in 3 blocks are possibly lost in loss record 136 of 165
==129778==    at 0x483CB65: calloc (vg_replace_malloc.c:760)
==129778==    by 0x40142EB: _dl_allocate_tls (in /usr/lib/ld-2.32.so)
==129778==    by 0x48C913C: pthread_create@@GLIBC_2.2.5 (in /usr/lib/libpthread-2.32.so)
==129778==    by 0x58D79A2: QThread::start(QThread::Priority) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x58DA754: QThreadPoolPrivate::startThread(QRunnable*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x58DBB13: QThreadPoolPrivate::tryStart(QRunnable*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x58DC327: QThreadPool::start(QRunnable*, int) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x19171F: QFuture<void> QtConcurrent::run<void, CServer, int, int, int, int, int, int>(CServer*, void (CServer::*)(int, int, int), int const&, int const&, int const&) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x159343: CServer::OnTimer() (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x5AEC581: QObject::event(QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5ABFA4F: QCoreApplication::notifyInternal2(QObject*, QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5AC2572: QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778== 
==129778== 1,744 (352 direct, 1,392 indirect) bytes in 4 blocks are definitely lost in loss record 146 of 165
==129778==    at 0x483ADEF: operator new(unsigned long) (vg_replace_malloc.c:342)
==129778==    by 0x5AF54E5: QObject::QObject(QObject*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x1ADF21: recorder::CJamSession::DisconnectClient(int) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x1AE1A8: recorder::CJamRecorder::OnDisconnected(int) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x5AEC581: QObject::event(QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5ABFA4F: QCoreApplication::notifyInternal2(QObject*, QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5AC2572: QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5B190A3: ??? (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x7147A83: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x719B9B0: ??? (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x71462B0: g_main_context_iteration (in /usr/lib/libglib-2.0.so.0.6600.4)
==129778==    by 0x5B186E0: QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) (in /usr/lib/libQt5Core.so.5.15.2)
==129778== 
==129778== 1,824 (16 direct, 1,808 indirect) bytes in 1 blocks are definitely lost in loss record 147 of 165
==129778==    at 0x483ADEF: operator new(unsigned long) (vg_replace_malloc.c:342)
==129778==    by 0x154EE1: recorder::CJamController::SetRecordingDir(QString, int, bool) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x15A749: CServer::CServer(int, QString const&, unsigned short, QString const&, QString const&, QString const&, QString const&, QString const&, QString const&, QString const&, bool, bool, bool, bool, ELicenceType) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x13BD6F: main (in /home/christian/Projects/jamulus/Jamulus)
==129778== 
==129778== 9,856 bytes in 28 blocks are possibly lost in loss record 162 of 165
==129778==    at 0x483CB65: calloc (vg_replace_malloc.c:760)
==129778==    by 0x40142EB: _dl_allocate_tls (in /usr/lib/ld-2.32.so)
==129778==    by 0x48C913C: pthread_create@@GLIBC_2.2.5 (in /usr/lib/libpthread-2.32.so)
==129778==    by 0x58D79A2: QThread::start(QThread::Priority) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x58DA754: QThreadPoolPrivate::startThread(QRunnable*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x58DBB13: QThreadPoolPrivate::tryStart(QRunnable*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x58DC327: QThreadPool::start(QRunnable*, int) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x19171F: QFuture<void> QtConcurrent::run<void, CServer, int, int, int, int, int, int>(CServer*, void (CServer::*)(int, int, int), int const&, int const&, int const&) (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x158FC5: CServer::OnTimer() (in /home/christian/Projects/jamulus/Jamulus)
==129778==    by 0x5AEC581: QObject::event(QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5ABFA4F: QCoreApplication::notifyInternal2(QObject*, QEvent*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778==    by 0x5AC2572: QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) (in /usr/lib/libQt5Core.so.5.15.2)
==129778== 
==129778== LEAK SUMMARY:
==129778==    definitely lost: 960 bytes in 15 blocks
==129778==    indirectly lost: 4,314 bytes in 31 blocks
==129778==      possibly lost: 11,616 bytes in 33 blocks
==129778==    still reachable: 8,546,676 bytes in 1,187 blocks
==129778==         suppressed: 0 bytes in 0 blocks
==129778== Reachable blocks (those to which a pointer was found) are not shown.
==129778== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==129778== 
==129778== For lists of detected and suppressed errors, rerun with: -s
==129778== ERROR SUMMARY: 9 errors from 9 contexts (suppressed: 0 from 0)

Expected behavior
No leak.

Operating system

Arch Linux, Linux wuechoo 5.10.9-arch1-1 #1 SMP PREEMPT Tue, 19 Jan 2021 22:06:06 +0000 x86_64 GNU/Linux

Version of Jamulus
3.6.2dev-83d5f0cf

[softins]

@hoffie I think you're right. I've just had a quick look, and noticed the following items:

1. The function CJamClient::Disconnect() needs a delete out; before setting out = nullptr;. C++ doesn't have garbage collection!
2. There is no destructor ~CJamSession to delete the items pointed to by jamClientConnections, and maybe also vecptrJamClients.

EDIT: actually, vecptrJamClients is ok. Deleted in CJamSession::DisconnectClient.

But I see you self-assigned this, so I don't want to duplicate work you are already doing. But happy to assist if required!

[hoffie]

@softins Thanks for analyzing this further! Feel free to assign to you if you want, I can only start working on that again on Saturday/Sunday I guess. Just wanted to assign this to someone to avoid adding to the pool of unassigned issues. :)

[softins]

Ok, that's cool. I have some time today, so I'll carry on looking at it. Really appreciate the valgrind output you posted!

[genesisproject2020]

Just give me a message if you want me to test something.

[softins]

Well this is looking promising:

==14656== Memcheck, a memory error detector
==14656== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==14656== Using Valgrind-3.15.0 and LibVEX; rerun with -h for copyright info
==14656== Command: ./Jamulus -s -n -p 10001 -e private.jamulus.io -l /tmp/log -R /tmp/recordings -o Private\ Server;Winchester;224 -m /tmp/jam.dat -u 40 -T -w Welcome!
==14656==
- server mode chosen
- no GUI mode chosen
- selected port number: 10001
- central server: private.jamulus.io
- logging file name: /tmp/log
- recording directory name: /tmp/recordings
- server info: Private Server;Winchester;224
- HTML status file name: /tmp/jam.dat
- maximum number of channels: 40
- using multithreading
- welcome message: Welcome!
Recording state: enabled
 *** Jamulus, Version 3.6.2dev-c8bfa4f
 *** Internet Jam Session Software
 *** Released under the GNU General Public License (GPL)
Server Registration Status update: Registration requested
Server Registration Status update: Registered
2021-02-20 10:38:37, 192.168.20.14, connected (1)
2021-02-20 10:42:24, 192.168.20.190, connected (1)
2021-02-20 10:42:41,, server idling -------------------------------------
^CServer Registration Status update: Unregistered
==14656==
==14656== HEAP SUMMARY:
==14656==     in use at exit: 2,122,608 bytes in 86 blocks
==14656==   total heap usage: 5,633,363 allocs, 5,633,277 frees, 2,029,840,553 bytes allocated
==14656==
==14656== LEAK SUMMARY:
==14656==    definitely lost: 0 bytes in 0 blocks
==14656==    indirectly lost: 0 bytes in 0 blocks
==14656==      possibly lost: 0 bytes in 0 blocks
==14656==    still reachable: 2,122,608 bytes in 86 blocks
==14656==         suppressed: 0 bytes in 0 blocks
==14656== Reachable blocks (those to which a pointer was found) are not shown.
==14656== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==14656==
==14656== For lists of detected and suppressed errors, rerun with: -s
==14656== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)

This is on a headless build.

[softins]

Although the recorder leaks appear to have been found, it appears there are others. I'm particularly suspicious of the OnTimer calls in your valgrind output. More investigation needed!

[hoffie]

Although the recorder leaks appear to have been found

Very cool :)

I'm particularly suspicious of the OnTimer calls in your valgrind output. More investigation needed!

Have opened #1083 with fresh valgrind output to avoid getting lost in details. I suggest that we close this issue (#1019) once the PR is merged.