recent_logfile() causes a huge memory leak for large log files

Bug #984256 reported by Jeff Lane on 2012-04-17
12
This bug affects 1 person
Affects Status Importance Assigned to Milestone
apport (Ubuntu)
High
Martin Pitt
Precise
High
Martin Pitt

Bug Description

SRU TEST CASE: See comment 7

At some point, an apparent memory leak has been introduced into apport making it bring systems to a grinding halt while it tries to run.

I've noticed this over the last few days, so I suspect it's a fairly recent change. Today, I've tried filing a bug twice using apport, however, each time, the apport process chews through up to 3.5GB of RAM before it finally crashes. Here's the python trace generated after it finally runs out of memory:

bladernr@klaatu:~$ ubuntu-bug linux
ERROR: hook /usr/share/apport/package-hooks//source_linux.py crashed:
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/apport/report.py", line 768, in add_hooks_info
    symb['add_info'](self, ui)
  File "/usr/share/apport/package-hooks//source_linux.py", line 46, in add_info
    report['AcpiTables'] = root_command_output(['/usr/share/apport/dump_acpi_tables.py'])
  File "/usr/lib/python2.7/dist-packages/apport/hookutils.py", line 365, in root_command_output
    return command_output(_root_command_prefix() + command, input, stderr,
  File "/usr/lib/python2.7/dist-packages/apport/hookutils.py", line 340, in _root_command_prefix
    stderr=subprocess.PIPE) == 0 and \
  File "/usr/lib/python2.7/subprocess.py", line 493, in call
    return Popen(*popenargs, **kwargs).wait()
  File "/usr/lib/python2.7/subprocess.py", line 679, in __init__
    errread, errwrite)
  File "/usr/lib/python2.7/subprocess.py", line 1143, in _execute_child
    self.pid = os.fork()
OSError: [Errno 12] Cannot allocate memory
Traceback (most recent call last):
  File "/usr/share/apport/apport-gtk", line 507, in <module>
    app.run_argv()
  File "/usr/lib/python2.7/dist-packages/apport/ui.py", line 543, in run_argv
    return self.run_report_bug()
  File "/usr/lib/python2.7/dist-packages/apport/ui.py", line 348, in run_report_bug
    self.collect_info(symptom_script)
  File "/usr/lib/python2.7/dist-packages/apport/ui.py", line 861, in collect_info
    icthread.exc_raise()
  File "/usr/lib/python2.7/dist-packages/apport/REThread.py", line 34, in run
    self._retval = self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/python2.7/dist-packages/apport/ui.py", line 93, in thread_collect_info
    elif not apport.packaging.is_distro_package(report['Package'].split()[0]):
  File "/usr/lib/python2.7/dist-packages/apport/packaging_impl.py", line 144, in is_distro_package
    stdout=subprocess.PIPE)
  File "/usr/lib/python2.7/subprocess.py", line 679, in __init__
    errread, errwrite)
  File "/usr/lib/python2.7/subprocess.py", line 1143, in _execute_child
    self.pid = os.fork()
OSError: [Errno 12] Cannot allocate memory

Jeff Lane (bladernr) wrote :

My system is completely unusable while apport runs because of it's rampant memory consumption.

Martin Pitt (pitti) wrote :

I tried this under a current amd64 live desktop system in a VM with 1 GB RAM, and "apport-bug linux" works just fine. ps reports 513 MB VSZ and 63 MB RSS which certainly is more than it could be, but far from unreasonable. gedit (which is a C GTK program) uses almost the same VSZ (496 MB) and 25 MB RSS.

So let's dissect when things go wrong at your end. Does it only happen with the linux hook, or does it affect other packages as well? I. e. does "apport-bug coreutils" have that problem? (that does not have any package hooks). If not, does "apport-bug udisks" have? (that does some extra stuff).

Thanks!

Changed in apport:
status: New → Incomplete
Jeff Lane (bladernr) wrote :

Actually, now that I've dug a little further, this is still probably a bug, but not in the way I originally thought.

Can you confirm my guess that when apport runs and starts gathering logs, it actually reads those logs into memory in some manner?

What I discovered while looking at a completely different issue is that /var/log/syslog was 3.8GB in size. So now I'm thinking that the memory errors in the apport trace are due to apport simply trying to read that into memory and then dying horribly when it runs out of available memory.

Changed in apport:
status: Incomplete → New
Jeff Lane (bladernr) wrote :

What happened to expose this was this bug: #984273 which triggered a massive flood (several million lines of repeated messages) into syslog, causing it to grow in size almost instantly. At this point, logrotate has moved the 3.8+GB log out so if I run apport-bug at this point, I should be fine. I'll do so now to verify this is the case.

Martin Pitt (pitti) wrote :

Ah, a huge log file would indeed explain this, thanks!

affects: apport → apport (Ubuntu)
Changed in apport (Ubuntu):
status: New → Triaged
Martin Pitt (pitti) wrote :

So I guess the failure during /usr/share/apport/dump_acpi_tables.py was a red herring, and it already used up all available memory before.

Martin Pitt (pitti) wrote :

I let /var/log/syslog grow massively with

$ yes 'Apr 20 11:30:00 donald kernel: bogus message' | sudo tee -a /var/log/syslog >/dev/null

and ^Ced after it readed a Gigabyte. Running "apport-bug linux" then reproduces the bug.

The faulty function is attach_wifi() in /usr/share/apport/package-hooks/source_linux.py, which calls

  report['WifiSyslog'] = recent_syslog(re.compile(r'(NetworkManager|modem-manager|dhclient|kernel|wpa_supplicant)(\[\d+\])?:'))

and recent_syslog() has no rate limit.

summary: - Apport has a huge memory leak causing system problems
+ recent_syslog() causes a huge memory leak for large log filles
summary: - recent_syslog() causes a huge memory leak for large log filles
+ recent_logfile() causes a huge memory leak for large log files
Changed in apport (Ubuntu Precise):
assignee: nobody → Martin Pitt (pitti)
importance: Undecided → High
Martin Pitt (pitti) wrote :

Fixed in trunk r2295.

Changed in apport (Ubuntu Precise):
assignee: Martin Pitt (pitti) → nobody
status: Triaged → Fix Committed
assignee: nobody → Martin Pitt (pitti)
Martin Pitt (pitti) on 2012-04-20
description: updated

Hello Jeff, or anyone else affected,

Accepted apport into precise-proposed. The package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

tags: added: verification-needed
Jeff Lane (bladernr) wrote :

Martin, yeah, after I started looking into the other bug (among other things) is when I noticed finally that syslog was that big. After logrotate had moved the log on (and I'd made a snapshot of it just in case :) ) I did verify that apport was functioning fine with more reasonable sized log files.

So that led me to think, perhaps apport should have a prompt to let the submitter know that a log file is above a certain size... I don't know if that would be an arbitrary size or perhaps a calculated percentage of available RAM, and then warn the user that the log file is too big, and provide a mechanism to skip the upload of that one file.

Perhaps that could provide a message that would point the user to the specific file being skipped and maybe the advice to copy the log and trim out unnecessary stuff before manually adding it to the bug the user opened.

Anyway, it was a thought I had... not sure if what I encountered is something that would be encountered often enough to make that added functionality worthwhile... though I CAN easily see this being a good idea for some things, like .xsession-errors. On my system with the nVidia GT240M card, I have to routinely delete .xsession-errors as it very quickly grows to hundreds of gigabytes in size. It got to the point where I just had cron delete the file every week. Anyway, I digress, that was but an example.

Jeff Lane (bladernr) wrote :

Ok... so disregard my last comment thoughts. I actually sat down and decided to look at adding what I had suggested to apport and actually looked at the change made to resolve this bug. Thanks for the quick resolution, and I'm glad my weird situation was able to help make apport a little better :)

Martin Pitt (pitti) wrote :

Jeff, would you be able to test the version in -proposed? You can recreate the situation given the test case in comment 7. (We need verification for SRUs). Thanks!

Jeff Lane (bladernr) wrote :

Had to update python-apport as well as apport, but after doing so, using pitti's recreation steps above I was not able to trigger a failure.

I didn't actually file the fake kernel bug, but apport no longer crashes while parsing my giant syslog file. So I'd say it appears to be resolved in proposed!

Martin Pitt (pitti) on 2012-04-23
tags: added: verification-done
removed: verification-needed
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package apport - 2.0.1-0ubuntu6

---------------
apport (2.0.1-0ubuntu6) precise-proposed; urgency=low

  * Cherry-pick from trunk:
    - hookutils.py, recent_logfile(): Use a default limit of 10000 lines and
      call "tail" instead of reading the whole file. This protects against
      using up all memory when there are massive repeated log messages.
      (LP: #984256)
    - apport-gtk: Do not assume that an icon requested for size 42 actually
      delivers size 42; some themes do not have this available and deliver a
      smaller one instead, causing overflows. Also, copy the image as
      gtk_icon_theme_load_icon() returns a readonly result which we must not
      modify. Fixes crashes when using themes other than the standard Ubuntu
      ones. (LP: #937249)
 -- Martin Pitt <email address hidden> Fri, 20 Apr 2012 18:53:24 +0200

Changed in apport (Ubuntu Precise):
status: Fix Committed → Fix Released
Changed in apport (Ubuntu):
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers