python-apt output does not go to log file

Bug #280291 reported by Till Kamppeter
4
Affects Status Importance Assigned to Milestone
Jockey
Invalid
Medium
Unassigned
jockey (Ubuntu)
Fix Released
Undecided
Martin Pitt

Bug Description

To get debug logging to track down problems one can restart Jockey in debug mode:

sudo killall jockey-backend
sudo /usr/share/jockey/jockey-backend --debug -l /tmp/jockey.log &

Jockey is now supposed to do a more verbose console output and redirect it to /tmp/jockey.log.

As Jockey is supposed to log into the given file and therefore not having console output, I have started Jockey to run in the background (the "&" in the end). So I can run client programs to do the actual test in the same terminal.

Now Jockey works as usual until it comes to installing or uninstalling a package. The console output (stdout, stderr) of apt-get and/or dpkg is not redirected into the file but still goes to the console. This makes the background process hanging until one takes it back to the foreground with the "fg" command.

Jockey should also redirect the output of sub programs to the log file, so that it runs smoothly in the background and also problems of the sub programs get captured.

Changed in jockey:
assignee: nobody → pitti
Martin Pitt (pitti)
Changed in jockey:
importance: Undecided → Medium
status: New → Triaged
Revision history for this message
Martin Pitt (pitti) wrote :

This affects both upstream bits, as well as the apt handler, thus adding ubuntu task as well.

Changed in jockey:
assignee: nobody → pitti
status: New → Triaged
Revision history for this message
Martin Pitt (pitti) wrote :

FYI, in Jaunty jockey now logs to /var/log/jockey.log by default, thus no need to restart it in debug mode.

Revision history for this message
Martin Pitt (pitti) wrote :

In fact the upstream code does not have this problem, all subprocess calls handle stderr appropriately.

Changed in jockey:
assignee: pitti → nobody
status: Triaged → Invalid
Revision history for this message
Martin Pitt (pitti) wrote :

Problem is that apt.Cache().commit() writes those messages to stdout/err itself; I consult Michael Vogt about this.

Revision history for this message
Martin Pitt (pitti) wrote :

Michael, any idea how I can stop apt.Cache().commit() from printing stuff to stdout/stderr? I'd like to retain the messages, ideally to a pipe or a StringIO object.

Revision history for this message
Martin Pitt (pitti) wrote :

Michael says I can overwrite the fork() method in apt.InstallProgress and use os.dup2().

Revision history for this message
Martin Pitt (pitti) wrote :

So I tried that: I overrode fork() and diverted stdout and stderr to a file in the child process. However, it doesn't work, python-apt still directly outputs to stdout/err.

Revision history for this message
Martin Pitt (pitti) wrote :

Note to self: This can be tested in the jockey branch with

sudo dpkg -P pmount; sudo rm /tmp/log; sudo PYTHONPATH=. python -c 'import apt, jockey.oslib, logging; logging.basicConfig(level=logging.DEBUG, filename="/tmp/log"); jockey.oslib.OSLib().install_package("pmount", lambda p, c, t: None)'; echo '------'; cat /tmp/log

Revision history for this message
Michael Vogt (mvo) wrote :
Revision history for this message
Martin Pitt (pitti) wrote :

Thanks, Michael. Turns out that TemporaryFile() works perfectly as well, I just stupidly rerouted the parent's stdout/err instead of the child's.

Changed in jockey (Ubuntu):
status: Triaged → In Progress
Revision history for this message
Martin Pitt (pitti) wrote :

jockey/ubuntu r325

Changed in jockey (Ubuntu):
status: In Progress → Fix Committed
Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package jockey - 0.5-0ubuntu5

---------------
jockey (0.5-0ubuntu5) jaunty; urgency=low

  * Add debian/watch.
  * Add bzr-builddeb configuration.
  * data/handlers/fglrx.py: Enable again, 2:8.600-0ubuntu1 works on Jaunty
    now.
  * Merge bug fixes from trunk:
    - Fix KernelModuleHandler.available() to return False when the handler
      package is not available. This fixes the situation that Jockey
      advertises e. g. the nvidia driver before apt-get update was run, or on
      "free software only" installs. (LP: #341647)
    - kde/jockey-kde.desktop.in: Do not run as root any more, PolicyKit-KDE
      exists now; update README.txt
    - kde/jockey-kde: Port to knotify4. UIF exception approval and original
      patch by Jonathan Riddell. Now properly i18n'ed and integrated into
      standard build system.
    - Update German translations.
  * debian/control: Add policykit-kde dependency to jockey-kde.
  * Add madwifi handler (merged from trunk). This now takes care of properly
    flipping the blacklisting between ath5k and ath_pci (LP: #323830), and
    fixes the description and freeness state (LP: #290264)
  * jockey/oslib.py: Overwrite apt.InstallProgress.fork() to capture the
    child's stdout/stderr into temporary files, and then send that to logging.
    Before this, apt/dpkg output was sent to oblivion, making it hard to
    remotely debug package installation problems. (LP: #280291)

 -- Martin Pitt <email address hidden> Wed, 18 Mar 2009 20:04:01 +0100

Changed in jockey:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.