Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unusually high memory usage #11879

Closed
eigerzoom opened this issue Jan 15, 2020 · 64 comments
Closed

Unusually high memory usage #11879

eigerzoom opened this issue Jan 15, 2020 · 64 comments

Comments

@eigerzoom
Copy link

qBittorrent version and Operating System

qb 4.2.1 x64
Win10 LTSC x64

What is the problem

Unusually high memory usage

What is the expected behavior

Less

Steps to reproduce

Upgrade to 4.2.1 from 4.1.9.1
I tried to downgrade back to 4.2.0 and found same issue.
Upon trying to revert to 4.1.9.1 ran into the known 'recheck all files' and I did not test.
Generally if i restart the program memory usage is low for some amount of time.
When I check task manager after a few hours or so it will remain over 1gb of memory.
No further testing

Extra info(if any)

Screenshot of task manager
https://i.imgur.com/vUza229.png

@mrxdst
Copy link

mrxdst commented Jan 18, 2020

I have also experienced much higher memory usage after updating to 4.2.1 from 4.1.9

OS: Arch Linux
Number of torrents: 200 ish.

Memory usage keeps increasing for a couple of hours until the system freezes and finally gets killed by the OOM killer.

13 GB memory usage after a few hours.
mem

In version 4.1.9 the memory usage was constant and it could run indefinitely without any issues.

I have also noticed that every time i select Edit -> Pause all/Resume all, the memory usage jumps about 100 MB.

@eigerzoom
Copy link
Author

I reverted to 4.1.9.1, rechecked all files, restarted qb and still had the memory issue, kind of strange.

@FranciscoPombal
Copy link
Member

Everyone in this thread please see https://github.com/qbittorrent/qBittorrent/blob/master/CONTRIBUTING.md.

Try to provide more data such as the qBittorrent logs, as well as testing if you can reproduce this on a clean install of qBittorrent (since you all mention this started happening after upgrading/reverting).

"Clean installing qBittorrent" means deleting the .conf/qBittorrent and .local/share/data/qBittorrent directories on Linux and the %LocalAppData%\qBittorrent folder on Windows. Note that this will cause qBittorrent to "forget" all your added torrents (no file data will be deleted though), so be sure to back them up (at least the BT_backup folder) when testing the full re-installation.

@mrxdst
Copy link

mrxdst commented Jan 22, 2020

I renamed the folders.

Then I added a couple of new torrents. But after seeding for about 2 hours I did not notice any increase in memory at all. Toggling Pause all/Resume all didn't cause any increase in memory either.

Log: qbittorrent.log


I renamed the folders again. But restored the original BT_backup folder (otherwise completely fresh). And the memory problem was back.

Log: qbittorrent_2.log


Not sure how to proceed from here as I don't want to share my BT_backup folder.

@FranciscoPombal
Copy link
Member

@mrxdst

I renamed the folders.

Then I added a couple of new torrents. But after seeding for about 2 hours I did not notice any increase in memory at all. Toggling Pause all/Resume all didn't cause any increase in memory either.

Log: qbittorrent.log

That log looks a bit strange still, because of the qBittorrent v4.2.1 started entries between adding each torrent. Did you actually restart the client between each addition an truncated those parts of the log? Because I don't think that should be happening. Other than that, everything looks fine.

Also, in addition to the backup folder, did you reset the settings as well when testing? Just for completeness, it would be good to be able to rule that out.

I renamed the folders again. But restored the original BT_backup folder (otherwise completely fresh). And the memory problem was back.

Log: qbittorrent_2.log

That log looks fine, assuming torrent restored x 202 was successful for all torrents.

Not sure how to proceed from here as I don't want to share my BT_backup folder.

Understandable. At this point, the memory leak could be due to the differences between .fastresume files (unless, of course, like mentioned above, the settings play a role).

I am not sure how you would go about "cleanly" regenerating the .fastresume files. The obvious approach is to delete all the .fastresume files, add all the torrents back manually and force recheck if needed. This is not feasible unless you have a really trivial setup with no categories or tags and everything always saved in the same folder.

@glassez @arvidn Ideas? How can one regenerate the .fastresume files without losing every customization? How can a memory leak due to the change in .fastresume file format be diagnosed here? Any idea where it could be coming from?

@mrxdst
Copy link

mrxdst commented Jan 22, 2020

@FranciscoPombal

I added the torrents by directly opening the .torrent files from chrome's download bar. Probably why it says started multiple times.

I have 202 torrents and the log didn't mention any error for any of them when restoring.

For the second test i had renamed both .config/qBittorrent and .local/share/data/qBittorrent again. So all settings was reset. I created a new .local/share/data/qBittorrent folder and put my original BT_backup in it.


I ran less *.fastresume in BT_backup and stepped thru all 202 files. For 2 of them less told me that they "May be a binary file". But comparing them to other fastresume files, I could not see any obvious corruption. I deleted the 2 effected torrents and restarted qBittorrent but the issue still persisted.


I can try deleting the .fastresume files. I only have minor customizations. But I would prefer to do it only as a last step.

@arvidn
Copy link
Contributor

arvidn commented Jan 22, 2020

In my experience, the simplest way to diagnose memory leaks is to run a build with symbols and ideally some debug information, and -fno-omit-framepointers.

Then, LD_PRELOAD the google performance tools, libprofiler.so into the process on startup. Compare the heap dumps it spits out to see where the majority of the memory is allocated from.

@FranciscoPombal
Copy link
Member

@mrxdst want to try the suggestion above? I can't reproduce the problem right now, so if you could help that would be great.

With your help, we might be able to pinpoint the cause of the issue and perhaps come up with a fix.

@mrxdst
Copy link

mrxdst commented Jan 23, 2020

I had a go at it. I'm not familiar with c++ development but i think i figured it out.
The following is what I did:

git checkout release-4.2.1
./configure --enable-debug
CXXFLAGS="-fno-omit-framepointers" make -j$(nproc)
sudo make install

# Test 1 - Run for 10 minutes and exit
LD_PRELOAD="/usr/lib/libtcmalloc.so" HEAPCHECK=normal PPROF_PATH="/usr/bin/pprof" /usr/local/bin/qbittorrent

# Test 2 - Run for 10 minutes and exit
LD_PRELOAD="/usr/lib/libtcmalloc.so" HEAPPROFILE="test2.hprof" /usr/local/bin/qbittorrent

# Test 3 - Pause/Resume all a bunch of times
LD_PRELOAD="/usr/lib/libtcmalloc.so" HEAPCHECK=normal PPROF_PATH="/usr/bin/pprof" /usr/local/bin/qbittorrent

# Test 4 - Pause/Resume all a bunch of times
LD_PRELOAD="/usr/lib/libtcmalloc.so" HEAPPROFILE="test4.hprof" /usr/local/bin/qbittorrent

Full test results:
Test 1: test1.txt
Test 2: test2.txt
Test 3: test3.txt
Test 4: test4.txt

From what I can tell, the following appears to use 80% of all memory: (From test 4)

Total: 9385.0 MB
  3755.9  40.0%  40.0%   3755.9  40.0% BIO_new_accept
  3755.9  40.0%  80.0%   3755.9  40.0% boost::asio::ssl::detail::stream_core::stream_core

BIO_new_accept has something to do with OpenSSL?
For the record my OpenSSL version is: 1.1.1.d from Arch Linux repositories.

@FranciscoPombal
Copy link
Member

@mrxdst

I had a go at it. I'm not familiar with c++ development but i think i figured it out.
The following is what I did:

git checkout release-4.2.1
./configure --enable-debug
CXXFLAGS="-fno-omit-framepointers" make -j$(nproc)
sudo make install

# Test 1 - Run for 10 minutes and exit
LD_PRELOAD="/usr/lib/libtcmalloc.so" HEAPCHECK=normal PPROF_PATH="/usr/bin/pprof" /usr/local/bin/qbittorrent

# Test 2 - Run for 10 minutes and exit
LD_PRELOAD="/usr/lib/libtcmalloc.so" HEAPPROFILE="test2.hprof" /usr/local/bin/qbittorrent

# Test 3 - Pause/Resume all a bunch of times
LD_PRELOAD="/usr/lib/libtcmalloc.so" HEAPCHECK=normal PPROF_PATH="/usr/bin/pprof" /usr/local/bin/qbittorrent

# Test 4 - Pause/Resume all a bunch of times
LD_PRELOAD="/usr/lib/libtcmalloc.so" HEAPPROFILE="test4.hprof" /usr/local/bin/qbittorrent

Full test results:
Test 1: test1.txt
Test 2: test2.txt
Test 3: test3.txt
Test 4: test4.txt

From what I can tell, the following appears to use 80% of all memory: (From test 4)

Total: 9385.0 MB
  3755.9  40.0%  40.0%   3755.9  40.0% BIO_new_accept
  3755.9  40.0%  80.0%   3755.9  40.0% boost::asio::ssl::detail::stream_core::stream_core

BIO_new_accept has something to do with OpenSSL?
For the record my OpenSSL version is: 1.1.1.d from Arch Linux repositories.

Excellent job, thanks for testing. I assume you used the problematic .fastresumes in this test?
Anyway, the results are kind of weird - I don't see how OpenSSL could be involved in the .fastresume logic.

@mrxdst
Copy link

mrxdst commented Jan 24, 2020

@FranciscoPombal
Yes I used the original BT_backup.
Might not be the .fastresume files themself that is the problem. Could maybe be a tracker or peer that sends malformed ssl data or something. I'll try later, If reannouncing to trackers is whats causing the memory leak. It could explain why the memory leaks so heavily then pausing/resuming all torrents as I assume it will reannounce to all trackers when resuming.

@mrxdst
Copy link

mrxdst commented Jan 24, 2020

I was right. Selecting all torrents and choosing Force reannounce causes the memory usage to leak about 100MB instantly every time.
If i pause all torrents Force reannounce causes no memory leak.
If I disconnect from the network Force reannounce causes no memory leak.

After that i changed the following settings:

  • Disabled DHT, Peer Exchange and Local Peer Discovery.
  • Set rate limit to 1KiB/s
  • Global maximum connections: 2

It let me keep all torrents resumed, hopefully without any other traffic.

Force reannounce still leaks memory.

I tried narrowing it down to see if it could be a specific tracker but I was unfortunately unable to get any consistent results. I don't see a way to remove a single tracker from all torrents at once, So I tried a much smaller set of torrents. However it made i much harder to notice the leaks consistently. When using a smaller it didn't leak every time, only sometimes. But with a larger set it always leaked consistently.

Also. this might not be a 4.1.9 -> 4.2.1 issue. Could just be that a tracker started misbehaving about the same time that 4.2.1 was released.

@xavier2k6
Copy link
Member

@arvidn @FranciscoPombal a quick memory pressure analysis report of any use?! (this is with a 4.2.1 test build)

Leak_Rule_Targetsqbittorrent.exe__PID__21420__Date__01_24_2020__Time_12_01_13PM__995__Manual Dump_MemoryAnalysis.zip

@FranciscoPombal
Copy link
Member

FranciscoPombal commented Jan 25, 2020

@mrxdst

Ok, so looks like the .fastresume files and their format upgrade were not the problem after all. Instead, when you removed them and loaded other torrents, you must have inadvertently removed .fastresumes corresponding to torrents that connect to trackers that trigger the leak.

See if you can narrow it down to a specific tracker, or at least a specific tracker type (http, https or udp). Since the leak apparently has to do with openssl, I'm expecting that it only happens with https trackers.

@FranciscoPombal
Copy link
Member

@xavier2k6
What is that report supposed to show? Was it collected with qBittorrent exhibiting the same leaky behavior described above? I think otherwise things look good, most allocated memory comes from the libtorrent disk cache which I believe is expected.

P.S. - a more standard file format would have been preferred - I had to spin up my Windows VM to read that report.

@mrxdst
Copy link

mrxdst commented Jan 25, 2020

I've tried removing all https trackers and keeping only https trackers. But I can only do it with a small sample size if torrents because it's just way to tedious to do it with all. But with a small set it refuses to reproduce consistently. It's just weird.

Best bet would probably be to compare trackers to someone else having the same issue, but for now it appears to be only me, so not much use.

I'm considering just deleting all trackers from all torrents and starting fresh. Should probably fix it, but then we won't know what exactly caused it.
I'll of course be keeping a backup of my BT_backup folder in case of any further testing at a later point.

@xavier2k6
Copy link
Member

xavier2k6 commented Jan 25, 2020

@FranciscoPombal

What is that report supposed to show?

It is a report with leaktrack attached to qbittorrent process for the potential of seeing any memory leaks.
qBittorrent in one instance has a probability of 95% chance & 50% in another.
it points out the possible source of an issue/cause of this.

Was it collected with qBittorrent exhibiting the same leaky behavior described above?

qBittorrent was running with 20+ torrents that have seperate re-announce to trackers times, none were forced though & had a combinantion of http/https & udp trackers on each torrent.....

I think otherwise things look good, most allocated memory comes from the libtorrent disk cache which I believe is expected.

This may be so & the basis of the report is to just show if there is a potential leak problem/serve as a basic guideline...(It may or may not be insightful, but hey - anything is better than nothing)

It shows a potential probability......whether that is acceptable within the confines of the code/parameters - I can't say....(so could very well be a false positive so to speak.)

P.S. - a more standard file format would have been preferred - I had to spin up my Windows VM to read that report.

Unfortunately that's the format Debug Diag Analysis uses to generate it's reports.

@FranciscoPombal
Copy link
Member

@xavier2k6

The leak probability is only a suggestion really. Otherwise, I guess this is a good way of generating such reports on Windows (I don't know of a better solution myself). Maybe you can create a wiki page detailing the process?

Unfortunately that's the format Debug Diag Analysis uses to generate it's reports.

If you cannot select a different output type, it is possible at least to use Internet Explorer to Save As... -> webpage, full (or something similar). This will save it as a normal html document.

@mrxdst

Can you try running qBittorrent with the problematic BT_backup under valgrind's tools like memcheck, massif and callgrind? I think the reports will include more useful information (mainly the call stack leading up to the leak). Warning: it will be a bit slow.

valgrind --tool=memcheck --verbose --leak-check=full --show-leak-kinds=all --track-origins=yes --log-file=valgrind_output.mem qbittorrent
valgrind --tool=massif --verbose --massif-out-file=massif_output.mass qbittorrent
# start with instrumentation off for faster startup
valgrind --tool=callgrind --verbose --log-file=callgrind.log --instr-atstart=no --dump-instr=yes --cache-sim=yes --cacheuse=yes qbittorrent
# from a different terminal, once program has finished starting:
callgrind_control -i on # turn on instrumentation
# after triggering the leaky behavior and seeing memory consumption go up, dump data:
callgrind_control -d qbittorrent
# callgrind will also generate and additional dump on exit

@eigerzoom
Copy link
Author

eigerzoom commented Jan 25, 2020

If this issue seems to be related to https trackers, then I can update with what would have caused it on my machine. I found some long term stored torrents I have were using the sites old http tracker that now has an https tracker. These are all on a single private tracker that upgraded to an https tracker sometime since I added the files to qb years ago. I decided to update all the http trackers to https. This was over 125 torrents. All the private keys in the addresses were still the same, the only thing that changed was adding https. So maybe it has something to do with the fact that all these original torrents have never been associated with the https tracker and how the site is handling the requests/announces. Or that the original trackers are no longer available as I do not store any torrents since I migrated to qb and just use qb's built in resume files strictly. All these torrents are really small in size, as they are only stored to provide a ratio boost on the site which gives a bonus for each completed torrent seeded. Its just under 7gb of files over 175 total torrents for this site. I visit the site at the end of each year and sort all their torrents by size and scan the list looking for any torrents from the current year that are smaller in size to reduce the long term storage footprint. I can redownload all the torrents and they will use their old tracker. So I guess thats my plan for now to hopefully solve the issue until a potential resolution is found. I don't believe I had memory issues after making the changes on 4.1.9.1 at the close of 2019 and that the issue did only surface after updating to 4.2.0. Thanks for everyones efforts.

@FranciscoPombal
Copy link
Member

FranciscoPombal commented Jan 25, 2020

@eigerzoom
I would not recommend using http announces with private trackers. This means your passkey will be transmitted in plain text through the internet.

@eigerzoom
Copy link
Author

I agree, thats why I updated them, but they were on http for an ungodly amount of time anyway so if it solves the memory leak temporarily I will sacrifice a little security for functionality. Maybe simply redownloading all the torrents will override the issue and I can update them all to https again. I will do some testing and report back if it helps.

@eigerzoom
Copy link
Author

eigerzoom commented Jan 25, 2020

Currently back on 4.1.9.1. So I removed all the manually updated torrents, restarted qb, and monitored memory usage, it didn't rise above 100mb or so (expected memory usage). I re-added all the torrents directly from trackers website and they all used the newer https tracker. Memory increased dramatically. Restarted qb and memory kept rising up over 1gb. I added an xtra 25 torrents from the site as well. I should add that I store all these torrents in a category/subfolder and are all auto-managed by qb.

@FranciscoPombal
Copy link
Member

Ok so now you just have to repeat the same thing but with the http tracker and compare memory usage.
By the way, what value did you set the disk cache to?

@eigerzoom
Copy link
Author

disk cache is set to 1000 MiB

@FranciscoPombal
Copy link
Member

disk cache is set to 1000 MiB

Then you should expect qbittorrent to consume 1 GIB of ram just because of that. By the way, that is an excessive value. Just set it to auto.

@eigerzoom
Copy link
Author

The disk cache set to auto seems to have solved it on its own, it never used this much memory before though for the record. Thanks.

@eigerzoom
Copy link
Author

Back on 4.2.1 with the same behavior. What I do notice is that if I do not increase the disk cache manually public torrent transfers suffer on large swarms and do not achieve quality transfer speeds. Would this have to do with nic settings or possibly a combination of qb settings? Thanks for any insight.

@mrxdst
Copy link

mrxdst commented Jan 26, 2020

@FranciscoPombal

I set up the test like this:
Debug build of qbittorrent.
Fresh config.
Original BT_backup.
Resumed all torrents.
Disabled DHT, Peer Exchange and Local Peer Discovery.
Set rate limit to 1KiB/s, Global maximum connections: 2.

I ran the test like this:
Start -> wait a short while -> force reannounce all torrents -> wait a short while -> exit

Results:
valgrind_output.mem.txt
massif_output.mass.txt
callgrind.log.zip

@FranciscoPombal
Copy link
Member

@mrxdst

Results:
valgrind_output.mem.txt
massif_output.mass.txt
callgrind.log.zip

Thank you for this. My analysis:

  1. Memcheck

==643473== in use at exit: 1,133,305 bytes in 11,201 blocks
==643473== total heap usage: 36,957,579 allocs, 36,946,378 frees, 6,112,490,645 bytes allocated

This means 6 GiB were allocated in total, but at exit only about 1 MiB is potentially leaking. This means the main memory leak we're hunting does not make it all the way to program exit. At some point, that memory is correctly free'd. Though it does not mean that the peak memory consumption was 6 GiB either.

  1. Massif

It shows a peak of about 780 MiB heap usage. Is this consistent with the usage you saw on some sort of task manager when executing?

leak

Anyway, it confirms the leak has to do with either libcrypto, or the way that libtorrent is using it. Perhaps you can repeat this test but with libtorrent debug symbols as well, so that @arvidn can weigh in? Make sure to specify what version commit of libtorrent you use. Also, I wonder if arvidn/libtorrent#4286 has anything to do with this.

  1. Callgrind

Output was not as useful as I'd hoped for, since there were no debug symbols for libtorrent.

Overall the massif report seems to be the most useful in this case.
If you're up for it, you can also try dhat. It is similar to massif, but different enough that it may provide yet more useful info.

Thanks again for the effort you're putting into this.

@arvidn
Copy link
Contributor

arvidn commented Jan 26, 2020

if there's an option in qBitTorrent to disable SSL torrents (settings_pack::ssl_listen = 0), please try do that.

@FranciscoPombal
Copy link
Member

@mrxdst Excellent work!

@xavier2k6

For me, only one of those trackers in that list show as working, the rest are not & only one of those not working shows a message of "not found"

I wonder how valid these findings are. IIRC, "Not working" in qBittorrent's status column does not necessarily mean that the tracker is not working or not working correctly. It just means the tracker does not know about that particular torrent you added them to. Some trackers report a "Not found"/"Unregistered torrent" or equivalent, but that is optional and depends on the software they are running.

@arvidn Not currently. I grep'd the code base for torrent_log_notification and torrent_log_alert, no results found. I could prepare a quick patch to enable that though.

@FranciscoPombal
Copy link
Member

@mrxdst @arvidn

Ok here is the patch to enable qbittorrent to log torrent_log_alerts to the log file on disk (on top of the current master commit c78604c). From my testing I noticed this produces very verbose log files. I recommend either deactivating the Preferences-Behaviour->Backup the log file after... setting in qBittorrent or cranking it to a large value like 10 MiB to avoid generating lots of separate files.

The PKGBUILD can be modified to apply the patch: https://wiki.archlinux.org/index.php/Patching_packages#Applying_patches

diff --git a/src/base/bittorrent/session.cpp b/src/base/bittorrent/session.cpp
index 0000dc029..9a468ae65 100644
--- a/src/base/bittorrent/session.cpp
+++ b/src/base/bittorrent/session.cpp
@@ -1064,6 +1064,7 @@ void Session::configureComponents()
 void Session::initializeNativeSession()
 {
     const LTAlertCategory alertMask = lt::alert::error_notification
+        | lt::alert::torrent_log_notification
         | lt::alert::file_progress_notification
         | lt::alert::ip_block_notification
         | lt::alert::peer_notification
@@ -4289,6 +4290,9 @@ void Session::handleAlert(const lt::alert *a)
         case lt::external_ip_alert::alert_type:
             handleExternalIPAlert(static_cast<const lt::external_ip_alert*>(a));
             break;
+        case lt::torrent_log_alert::alert_type:
+            handleTorrentLogAlert(static_cast<const lt::torrent_log_alert*>(a));
+            break;
 #if (LIBTORRENT_VERSION_NUM >= 10200)
         case lt::alerts_dropped_alert::alert_type:
             handleAlertsDroppedAlert(static_cast<const lt::alerts_dropped_alert *>(a));
@@ -4418,6 +4422,11 @@ void Session::handleTorrentDeletedAlert(const lt::torrent_deleted_alert *p)
     m_removingTorrents.erase(removingTorrentDataIter);
 }
 
+void Session::handleTorrentLogAlert(const lt::torrent_log_alert *p)
+{
+    LogMsg(tr("torrent_log_alert: '%1'").arg(QString::fromStdString(p->message()), Log::INFO));
+}
+
 void Session::handleTorrentDeleteFailedAlert(const lt::torrent_delete_failed_alert *p)
 {
     const InfoHash infoHash {p->info_hash};
diff --git a/src/base/bittorrent/session.h b/src/base/bittorrent/session.h
index a139e9d95..31c9e2c56 100644
--- a/src/base/bittorrent/session.h
+++ b/src/base/bittorrent/session.h
@@ -579,6 +579,7 @@ namespace BitTorrent
         void handleListenFailedAlert(const lt::listen_failed_alert *p);
         void handleExternalIPAlert(const lt::external_ip_alert *p);
         void handleSessionStatsAlert(const lt::session_stats_alert *p);
+        void handleTorrentLogAlert(const lt::torrent_log_alert *p);
 #if (LIBTORRENT_VERSION_NUM >= 10200)
         void handleAlertsDroppedAlert(const lt::alerts_dropped_alert *p) const;
 #endif

@arvidn
Copy link
Contributor

arvidn commented Feb 2, 2020

yes, that will be quite verbose. actually, it occurred to me that there should have been a tracker_error_alert as well. They are not as verbose, but I didn't see any in the logs @mrxdst posted. They are enabled by either of tracker_notification or error_notification. Is it possible those alerts are not logged?

@mrxdst
Copy link

mrxdst commented Feb 2, 2020

@FranciscoPombal
I tried the patch but unfortunatly it didnt work out that well.
It ran for about 10s, produced about 440 MB logs, and crashed on receiving a SIGABRT signal.

I deleted half of the torrents in BT_backup. No luck. I was only able to successfully run with 10 torrents.
Still produced 1 GB of logs.

@arvidn I''ll email you the logs. Maybe they are useful.

I'll happily try again if a patch is needed for tracker_error_alert.

Also:
I tried just opening each tracker url in Chrome and one of them https://open.kickasstracker.com:443/announce has a SSL certificate error: NET::ERR_CERT_COMMON_NAME_INVALID. Could that maybe be it?

@arvidn
Copy link
Contributor

arvidn commented Feb 2, 2020

the naming of the log files don't seem to be chronological. I did this to stitch them back together:

cat logs/* | sort >qbt-logs.txt

The problem is that the first column is (N), (W) or (I), which messes a bit with the order. but almost everything seems to be (N) anyway.

@arvidn
Copy link
Contributor

arvidn commented Feb 2, 2020

@mrxdst it looks like you have a lot of duplicate entries for all your trackers. is that the case? I'm not done analyzing the logs yet, but it looks like one of the trackers has more than 50 duplicate entries.

@mrxdst
Copy link

mrxdst commented Feb 2, 2020

@arvidn
That doesn't seem right. I have used a trackerlist at some point before so some torrents might have 10-20 trackers. But there shouldn't be 50 duplicates. At least that isn't what the UI in qBittorrent shows.

@arvidn
Copy link
Contributor

arvidn commented Feb 2, 2020

I see. I think I know a bit more about what's going on. I think at least some of this has been addressed already in libtorrent-1.2.4 (which hasn't been released yet, but lives in the RC_1_2 branch).

All of the "duplicates" I see in the log are caused by you ending up having a lot of listen endpoints (which is one of the main issues in libtorrent-1.2.x that was recently fixed). My logging isn't great right now either, I'll improve that.

I'll also look into the issue you pointed out about the common name of the SSL cert failing. It's possible that this failure hasn't seen a lot of testing.

@FranciscoPombal
Copy link
Member

FranciscoPombal commented Feb 3, 2020

@arvidn

yes, that will be quite verbose. actually, it occurred to me that there should have been a tracker_error_alert as well. They are not as verbose, but I didn't see any in the logs @mrxdst posted. They are enabled by either of tracker_notification or error_notification. Is it possible those alerts are not logged?

qBittorrent currently does add both of those notifications to the alert mask. However, nothing is logged for the tracker_error_alerts. I can make another patch to include that, if needed.

I tried testing with just one torrent (some linux distro) and adding the problematic trackers list posted above: https://github.com/qbittorrent/qBittorrent/files/4142696/https_trackers.txt

This was enough to produce pretty big logs with lots of errors, and may be enough to reproduce the problem in the same way, without having to deal with many torrent s and hundreds of MiBs/GiBs of logs.

@FranciscoPombal
Copy link
Member

@arvidn
I tried a similar patch for tracker_error_alert, but accessing message() leads to a seg fault. It appears to be null/access stuff that is null. error_message() does not have this problem. Ideas?

@arvidn
Copy link
Contributor

arvidn commented Feb 3, 2020

@FranciscoPombal that sounds like an ABI incompatibility with boost.system. Make sure everything is built with the same version of C++, including boost.system.

@FranciscoPombal
Copy link
Member

FranciscoPombal commented Feb 4, 2020

EDIT: turns out this patch was failing for unrelated reasons. In statements like LogMsg(tr("torrent_log_alert: '%1'").arg(QString::fromStdString(p->message()), Log::INFO)); the parens were wrong, such that Log::INFO was being passed as a second argument for arg() and not for LogMsg().

@arvidn
I made sure to compile boost (latest 1.72 release from official site), libtorrent (204b1ddb95b033b1734a9364095ed9b1a274d366) and qbittorrent (c78604c) with std=gnu++14 (gcc 7.4.0), but the problem persists.

Here is the backtrace obtained in gdb:

Thread 1 "qbittorrent-nox" received signal SIGSEGV, Segmentation fault.
0x00007ffff7632107 in boost::system::error_code::message[abi:cxx11]() const (this=0x7fffe40150f8) at /opt/boost/include/boost/system/error_code.hpp:641
641	        return cat_->message( value() );
(gdb) backtrace
#0  0x00007ffff7632107 in boost::system::error_code::message[abi:cxx11]() const (this=0x7fffe40150f8) at /opt/boost/include/boost/system/error_code.hpp:641
#1  libtorrent::tracker_error_alert::message[abi:cxx11]() const (this=this@entry=0x7fffe4015060) at /home/francisco/Documents/libtorrent/src/alert.cpp:345
#2  0x000055555560b63a in BitTorrent::Session::handleTrackerErrorAlert (this=this@entry=0x555555dee180, p=p@entry=0x7fffe4015060) at base/bittorrent/session.cpp:4433
#3  0x000055555560c4c3 in BitTorrent::Session::handleAlert (this=this@entry=0x555555dee180, a=0x7fffe4015060) at base/bittorrent/session.cpp:4241
#4  0x000055555560c68b in BitTorrent::Session::readAlerts (this=0x555555dee180) at base/bittorrent/session.cpp:4224
#5  0x00007ffff66171b2 in QObject::event(QEvent*) () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#6  0x00007ffff65e79b1 in QCoreApplication::notifyInternal2(QObject*, QEvent*) () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#7  0x00007ffff65ea13d in QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#8  0x00007ffff6641353 in ?? () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#9  0x00007ffff4249417 in g_main_context_dispatch () from /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#10 0x00007ffff4249650 in ?? () from /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#11 0x00007ffff42496dc in g_main_context_iteration () from /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#12 0x00007ffff664097f in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#13 0x00007ffff65e59fa in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#14 0x00007ffff65eeaa4 in QCoreApplication::exec() () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#15 0x00005555555d399d in Application::exec (this=0x555555dc2d80, params=...) at app/application.cpp:614
#16 0x00005555555cd658 in main (argc=<optimized out>, argv=0x7fffffffde98) at app/main.cpp:273

cat_ appears to be null for some reason.

handleTrackerErrorAlert is similar to the previous patch, here is the full patch I am attempting:

diff --git a/src/base/bittorrent/session.cpp b/src/base/bittorrent/session.cpp
index 0000dc029..5a537eb69 100644
--- a/src/base/bittorrent/session.cpp
+++ b/src/base/bittorrent/session.cpp
@@ -1064,6 +1064,7 @@ void Session::configureComponents()
 void Session::initializeNativeSession()
 {
     const LTAlertCategory alertMask = lt::alert::error_notification
+        | lt::alert::torrent_log_notification
         | lt::alert::file_progress_notification
         | lt::alert::ip_block_notification
         | lt::alert::peer_notification
@@ -4237,6 +4238,7 @@ void Session::handleAlert(const lt::alert *a)
         case lt::torrent_paused_alert::alert_type:
         case lt::torrent_resumed_alert::alert_type:
         case lt::tracker_error_alert::alert_type:
+            handleTrackerErrorAlert(static_cast<const lt::tracker_error_alert*>(a));
         case lt::tracker_reply_alert::alert_type:
         case lt::tracker_warning_alert::alert_type:
         case lt::fastresume_rejected_alert::alert_type:
@@ -4289,6 +4291,9 @@ void Session::handleAlert(const lt::alert *a)
         case lt::external_ip_alert::alert_type:
             handleExternalIPAlert(static_cast<const lt::external_ip_alert*>(a));
             break;
+        case lt::torrent_log_alert::alert_type:
+            handleTorrentLogAlert(static_cast<const lt::torrent_log_alert*>(a));
+            break;
 #if (LIBTORRENT_VERSION_NUM >= 10200)
         case lt::alerts_dropped_alert::alert_type:
             handleAlertsDroppedAlert(static_cast<const lt::alerts_dropped_alert *>(a));
@@ -4418,6 +4423,16 @@ void Session::handleTorrentDeletedAlert(const lt::torrent_deleted_alert *p)
     m_removingTorrents.erase(removingTorrentDataIter);
 }
 
+void Session::handleTorrentLogAlert(const lt::torrent_log_alert *p)
+{
+    LogMsg(tr("torrent_log_alert: '%1'").arg(QString::fromStdString(p->message()), Log::INFO));
+}
+
+void Session::handleTrackerErrorAlert(const lt::tracker_error_alert* p)
+{
+    LogMsg(tr("tracker_error_alert: '%1'").arg(QString::fromStdString(p->message()), Log::INFO));
+}
+
 void Session::handleTorrentDeleteFailedAlert(const lt::torrent_delete_failed_alert *p)
 {
     const InfoHash infoHash {p->info_hash};
diff --git a/src/base/bittorrent/session.h b/src/base/bittorrent/session.h
index a139e9d95..6fdc965f8 100644
--- a/src/base/bittorrent/session.h
+++ b/src/base/bittorrent/session.h
@@ -579,6 +579,8 @@ namespace BitTorrent
         void handleListenFailedAlert(const lt::listen_failed_alert *p);
         void handleExternalIPAlert(const lt::external_ip_alert *p);
         void handleSessionStatsAlert(const lt::session_stats_alert *p);
+        void handleTorrentLogAlert(const lt::torrent_log_alert *p);
+        void handleTrackerErrorAlert(const lt::tracker_error_alert *p);
 #if (LIBTORRENT_VERSION_NUM >= 10200)
         void handleAlertsDroppedAlert(const lt::alerts_dropped_alert *p) const;
 #endif

Full gdb backtrace in case it is useful:

(gdb) bt full
#0  0x00007ffff7632107 in boost::system::error_code::message[abi:cxx11]() const (this=0x7fffe40150f8) at /opt/boost/include/boost/system/error_code.hpp:641
No locals.
#1  libtorrent::tracker_error_alert::message[abi:cxx11]() const (this=this@entry=0x7fffe4015060) at /home/francisco/Documents/libtorrent/src/alert.cpp:345
        ret = "`\342\335UUU\000\000@\234\334UUU\000\000\070r\252\366\377\177\000\000\352ca\366\377\177\000\000p\260\001\344\377\177\000\000\360%y\366\377\177\000\000\313\336qUUU\000\000P\243\265UUU\000\000\240\326\335UUU\000\000\377\377\377\377UU\000\000\070\325\377\377\377\177\000\000 \000\000\344\003\000\000\000@\234\334UUU\000\000\b", '\000' <repeats 15 times>, "Ҩ@\366\377\177\000\000\031\000\000\000\000\000\000\000@\325\377\377\377\177\000\000\031\000\000\000\000\000\000\000\223\024H\366\377\177\000\000 \257\334UUU\000\000HJ\001\344\377\177\000\000@\325\377\377\377\177\000\000\344\237d\366\377\177\000\000\350\325\377\377\377\177\000\000@"...
#2  0x000055555560b63a in BitTorrent::Session::handleTrackerErrorAlert (this=this@entry=0x555555dee180, p=p@entry=0x7fffe4015060) at base/bittorrent/session.cpp:4433
No locals.
#3  0x000055555560c4c3 in BitTorrent::Session::handleAlert (this=this@entry=0x555555dee180, a=0x7fffe4015060) at base/bittorrent/session.cpp:4241
        __PRETTY_FUNCTION__ = "void BitTorrent::Session::handleAlert(const libtorrent::alert*)"
#4  0x000055555560c68b in BitTorrent::Session::readAlerts (this=0x555555dee180) at base/bittorrent/session.cpp:4224
        a = <optimized out>
        __for_range = std::vector of length 6, capacity 8 = {0x7fffe4014e60, 0x7fffe4014ec0, 0x7fffe4014f28, 0x7fffe4014f90, 0x7fffe4014ff8, 0x7fffe4015060}
        __for_begin = <optimized out>
        __for_end = <optimized out>
        alerts = std::vector of length 6, capacity 8 = {0x7fffe4014e60, 0x7fffe4014ec0, 0x7fffe4014f28, 0x7fffe4014f90, 0x7fffe4014ff8, 0x7fffe4015060}
#5  0x00007ffff66171b2 in QObject::event(QEvent*) () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
No symbol table info available.
#6  0x00007ffff65e79b1 in QCoreApplication::notifyInternal2(QObject*, QEvent*) () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
No symbol table info available.
#7  0x00007ffff65ea13d in QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
No symbol table info available.
#8  0x00007ffff6641353 in ?? () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
No symbol table info available.
#9  0x00007ffff4249417 in g_main_context_dispatch () from /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
No symbol table info available.
#10 0x00007ffff4249650 in ?? () from /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
No symbol table info available.
#11 0x00007ffff42496dc in g_main_context_iteration () from /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
No symbol table info available.
#12 0x00007ffff664097f in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
No symbol table info available.
#13 0x00007ffff65e59fa in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
No symbol table info available.
#14 0x00007ffff65eeaa4 in QCoreApplication::exec() () from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
No symbol table info available.
#15 0x00005555555d399d in Application::exec (this=0x555555dc2d80, params=...) at app/application.cpp:614
        pref = <optimized out>
        mesg = {static null = {<No data fields>}, d = 0x555555e309a0}
#16 0x00005555555cd658 in main (argc=<optimized out>, argv=0x7fffffffde98) at app/main.cpp:273
        appId = {static null = {<No data fields>}, d = 0x555555dc2d30}
        app = std::unique_ptr<Application> = {get() = 0x555555dc2d80}
        params = {showHelp = false, relativeFastresumePaths = false, skipChecking = false, sequential = false, firstLastPiecePriority = false, showVersion = false, shouldDaemonize = false, webUiPort = -1, addPaused = {static Undefined = {
              static Undefined = <same as static member of an already seen type>, static False = {static Undefined = <same as static member of an already seen type>, static False = <same as static member of an already seen type>, static True = {
                  static Undefined = <same as static member of an already seen type>, static False = <same as static member of an already seen type>, static True = <same as static member of an already seen type>, m_value = 1 '\001'}, m_value = 0 '\000'}, 
              static True = <same as static member of an already seen type>, m_value = -1 '\377'}, static False = <same as static member of an already seen type>, static True = <same as static member of an already seen type>, m_value = -1 '\377'}, skipDialog = {
            static Undefined = {static Undefined = <same as static member of an already seen type>, static False = {static Undefined = <same as static member of an already seen type>, static False = <same as static member of an already seen type>, static True = {
                  static Undefined = <same as static member of an already seen type>, static False = <same as static member of an already seen type>, static True = <same as static member of an already seen type>, m_value = 1 '\001'}, m_value = 0 '\000'}, 
              static True = <same as static member of an already seen type>, m_value = -1 '\377'}, static False = <same as static member of an already seen type>, static True = <same as static member of an already seen type>, m_value = -1 '\377'}, 
          torrents = {<QList<QString>> = {<QListSpecialMethods<QString>> = {<No data fields>}, {p = {static shared_null = {ref = {atomic = {_q_value = {<std::__atomic_base<int>> = {static _S_alignment = 4, _M_i = -1}, <No data fields>}}}, alloc = 0, begin = 0, 
                    end = 0, array = {0x0}}, d = 0x7ffff66d77c0 <QListData::shared_null>}, d = 0x7ffff66d77c0 <QListData::shared_null>}}, <No data fields>}, profileDir = {static null = {<No data fields>}, d = 0x7ffff66d56e0 <QArrayData::shared_null>}, 
          configurationName = {static null = {<No data fields>}, d = 0x7ffff66d56e0 <QArrayData::shared_null>}, savePath = {static null = {<No data fields>}, d = 0x7ffff66d56e0 <QArrayData::shared_null>}, category = {static null = {<No data fields>}, 
            d = 0x7ffff66d56e0 <QArrayData::shared_null>}, unknownParameter = {static null = {<No data fields>}, d = 0x7ffff66d56e0 <QArrayData::shared_null>}}
        isOneArg = <optimized out>
        __PRETTY_FUNCTION__ = "int main(int, char**)"

@Fixer-007
Copy link

Fixer-007 commented Feb 28, 2020

I have the same problem, qbittorrent suddenly started eating 500+mb of RAM (was loaded in background I did not do anything with it), disk cache is default at 64mb, at most 3-5 active torrents and everything else is idling, feels like it leaks memory when active/uploading, from 100mb at cold boot and consistently rising up to 500mb and beyond, 4.2.1 on Win7

@eigerzoom
Copy link
Author

Well i hate to say this in the face of my beloved qb maintainers, but this issue summons cryptomining sentiments in my heart, which saddens me.

@FranciscoPombal
Copy link
Member

Well i hate to say this in the face of my beloved qb maintainers, but this issue summons cryptomining sentiments in my heart, which saddens me.

This is some kind of bug in a specific version that people are using of the cryptographic library or maybe libtorrent is using it in a way that causes this. It has nothing to do with cryptominers, or are you implying that these well-known and heavily scrutinized open-source projects have sneaked one into your system? The code is out there for you or anyone else to check and even compile yourself if you want.

@eigerzoom
Copy link
Author

eigerzoom commented Feb 28, 2020

I know very little about code, and made that statement on pure speculation as a self admitted pebkac. I am self aware however, and realize that code doesn't generally operate on feelings (unless the chips get hot and start bitflipping). I am more than happy to be sorry for bringing it up. Very Disrespectful

@FranciscoPombal
Copy link
Member

I know very little about code, and made that statement on pure speculation as a self admitted pebkac. I am self aware however, and realize that code doesn't generally operate on feelings (unless the chips get hot and start bitflipping). I am more than happy to be sorry for bringing it up. Very Disrespectful

No problem, just keep cool and keep the discussion on topic.

@FranciscoPombal
Copy link
Member

Continued at: #12326

@qbittorrent qbittorrent locked and limited conversation to collaborators May 18, 2020
@FranciscoPombal FranciscoPombal removed their assignment Jul 1, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

6 participants