When the output of package installations are logged to a file, the
progress counter updates while reading the database are distracting.

This is especially the case in Debian Installer where multiple package
installations are started and all are logged to the syslog. For an
example of the result, see the syslog attached in [1].

Another example is buildd logs, for example [2].

The attached patch adds an option --no-db-progress that allows to suppress
the progress updates in such situations.

If you'd like any changes (maybe a more generic name for the option?) or
if I've forgotten anything, then please let me know.

The patch is based on current git:
commit 173652e75fad004c42906608fe0ff4556be29b19
Author: Helge Kreutzmann <debian@helgefjell.de>
Date:   Thu Jul 30 18:38:57 2009 +0200
    Fix errors in a paragraph in the German man page translation.

[1]http://bugs.debian.org/538344#15 (see lines starting at 00:26:43)
[2]https://buildd.debian.org/fetch.cgi?pkg=clock-setup&arch=i386&ver=0.99&stamp=1249206304&file=log&as=raw

Hi!

It should only get updated if stdout is a tty. In the same way most other
programs do it, including apt for example.

I'm guessing this logging is taken from the tty directly instead of
redirecting stdout? If so, OOC what was the reason to do it that way?

Also you'll notice that in normal conditions this works just fine,
see 00:10:32, 00:10:39, etc. And when it does not work (on in-target) it
does not work only for dpkg but for other stuff as well, see 01:12:27.

On the build logs the same happens, some parts work ok, others not, I'm
guessing a similar issue with not just redirecting stdout.

Hmm, this options is too specific, and I'd like dpkg to automatically do
the right thing, OTOH most apps do fancier stuff when they know they are
running on a tty, and if one reads from the tty directly it's expected
to get garbage. That does not mean we could not add something like a
--quiet option, though, but I'd rather understand first what and why
of the current situation.

regards,
guillem

As far as I can tell, progress_step() isn't supposed to do anything if
stdout isn't a tty.  I'd expect that to be the case for buildd logs, at
least (don't know how this is handled by d-i).

Cheers,
Julien

Hi Guillem,

The reason is that we're running in a fairly complex environment there.
We're installing in a chroot and getting progress info through debconf,
with debconf info being passed from debconf in the chroot to cdebconf in
the D-I environment. So we already have endless fun redirections.

A program called log-output is used to do the eventual logging.

See debian-installer-utils [1] if you'd like to have a look at them.
A typical installation of a single package would use first apt-install,
which calls apt-get (through debconf-apt-progress with various options)
using in-target, which in turn sources chroot-setup.sh and uses
log-output...
At some point we also call tasksel, but the principle remains the same.

So, it's not all that strange that dpkg isn't able to tell where the
output ends up in the end. Colin Watson will be better able than me to
really explain the intricacies.

Yes, that's debootstrap which runs in a very different environment (though
also with a D-I wrapper).

True and it would be nice to get rid of that as well, but there's quite a
difference between 4 and 20 lines :-)

Yeah, I already thought you might prefer something like that. A
general --quiet option would be fine with me as long as we don't lose any
of the "real" info needed to debug installation failures.

Thanks,
FJP

[1]http://svn.debian.org/wsvn/d-i/trunk/packages/debian-installer-utils/#_trunk_packages_debian-installer-utils_

Ok, 776753 is the same bug as this one:

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=539617

Hi,

I've not read the entire thread, but it seems
to me that if the concern is being able to debug
broken package installation the solution is not
to force output to the terminal but to log
informative messages somewhere in the system logs.

Regards,

Karl <kop@meme.com>
Free Software:  "You don't pay back, you pay forward."
                 -- Robert A. Heinlein

Hi,
I have prepared some by hand upgrade recipe for fabric, where I have in
fabfile.py...

 def _ensure_perl_readline():
     rlname = run("""perl -MTerm::ReadLine -e 'print(Term::ReadLine->ReadLine())'""", quiet=True)
     if not rlname == "Term::ReadLine::Gnu":
         run('aptitude install -q -q libterm-readline-gnu-perl')

 @parallel
 def aptitude_update():
     run('aptitude update', quiet=True)

 def aptitude_upgrade():
     run('DEBIAN_FRONTEND=readline aptitude -q -q safe-upgrade')

 @task
 @runs_once
 def upgrade():
     _ensure_perl_readline()
     execute(aptitude_update)
     execute(aptitude_upgrade)

The output of dpkg is problem. I want to have tty because of debconf
interactive questions. Now the output is e.g.:

 zito@ser1:~/admin$ fab -H nsi1.brn.i.cz upgrade
 [nsi1.brn.i.cz] Executing task 'upgrade'
 [nsi1.brn.i.cz] run: aptitude install -q -q libterm-readline-gnu-perl
 [nsi1.brn.i.cz] out: The following NEW packages will be installed:
 [nsi1.brn.i.cz] out:   libterm-readline-gnu-perl
 [nsi1.brn.i.cz] out: 0 packages upgraded, 1 newly installed, 0 to remove and 1 not upgraded.
 [nsi1.brn.i.cz] out: Need to get 99.1 kB of archives. After unpacking 266 kB will be used.
 [nsi1.brn.i.cz] out: Selecting previously unselected package libterm-readline-gnu-perl.
 [nsi1.brn.i.cz] out: (Reading database ...
 [nsi1.brn.i.cz] out: (Reading database ... 5%
 [nsi1.brn.i.cz] out: (Reading database ... 10%
 [nsi1.brn.i.cz] out: (Reading database ... 15%
 [nsi1.brn.i.cz] out: (Reading database ... 20%
 [nsi1.brn.i.cz] out: (Reading database ... 25%
 [nsi1.brn.i.cz] out: (Reading database ... 30%
 [nsi1.brn.i.cz] out: (Reading database ... 35%
 [nsi1.brn.i.cz] out: (Reading database ... 40%
 [nsi1.brn.i.cz] out: (Reading database ... 45%
 [nsi1.brn.i.cz] out: (Reading database ... 50%
 [nsi1.brn.i.cz] out: (Reading database ... 55%
 [nsi1.brn.i.cz] out: (Reading database ... 60%
 [nsi1.brn.i.cz] out: (Reading database ... 65%
 [nsi1.brn.i.cz] out: (Reading database ... 70%
 [nsi1.brn.i.cz] out: (Reading database ... 75%
 [nsi1.brn.i.cz] out: (Reading database ... 80%
 [nsi1.brn.i.cz] out: (Reading database ... 85%
 [nsi1.brn.i.cz] out: (Reading database ... 90%
 [nsi1.brn.i.cz] out: (Reading database ... 95%
 [nsi1.brn.i.cz] out: (Reading database ... 100%
 [nsi1.brn.i.cz] out: (Reading database ... 44444 files and directories currently installed.)
 [nsi1.brn.i.cz] out: Preparing to unpack .../libterm-readline-gnu-perl_1.24-2+b1_amd64.deb ...
 [nsi1.brn.i.cz] out: Unpacking libterm-readline-gnu-perl (1.24-2+b1) ...
 [nsi1.brn.i.cz] out: Processing triggers for man-db (2.7.0.2-5) ...
 [nsi1.brn.i.cz] out: Setting up libterm-readline-gnu-perl (1.24-2+b1) ...
 [nsi1.brn.i.cz] out:

 [nsi1.brn.i.cz] Executing task 'aptitude_update'
 [nsi1.brn.i.cz] Executing task 'aptitude_upgrade'
 [nsi1.brn.i.cz] run: DEBIAN_FRONTEND=readline aptitude -q -q safe-upgrade
 [nsi1.brn.i.cz] out: The following packages will be upgraded:
 [nsi1.brn.i.cz] out:   linux-image-3.16.0-4-amd64
 [nsi1.brn.i.cz] out: 1 packages upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
 [nsi1.brn.i.cz] out: Need to get 0 B/33.8 MB of archives. After unpacking 1,024 B will be used.
 [nsi1.brn.i.cz] out: Do you want to continue? [Y/n/?]
 [nsi1.brn.i.cz] out: Preconfiguring packages ...
 [nsi1.brn.i.cz] out: (Reading database ...
 [nsi1.brn.i.cz] out: (Reading database ... 5%
 [nsi1.brn.i.cz] out: (Reading database ... 10%
 [nsi1.brn.i.cz] out: (Reading database ... 15%
 [nsi1.brn.i.cz] out: (Reading database ... 20%
 [nsi1.brn.i.cz] out: (Reading database ... 25%
 [nsi1.brn.i.cz] out: (Reading database ... 30%
 [nsi1.brn.i.cz] out: (Reading database ... 35%
 [nsi1.brn.i.cz] out: (Reading database ... 40%
 [nsi1.brn.i.cz] out: (Reading database ... 45%
 [nsi1.brn.i.cz] out: (Reading database ... 50%
 [nsi1.brn.i.cz] out: (Reading database ... 55%
 [nsi1.brn.i.cz] out: (Reading database ... 60%
 [nsi1.brn.i.cz] out: (Reading database ... 65%
 [nsi1.brn.i.cz] out: (Reading database ... 70%
 [nsi1.brn.i.cz] out: (Reading database ... 75%
 [nsi1.brn.i.cz] out: (Reading database ... 80%
 [nsi1.brn.i.cz] out: (Reading database ... 85%
 [nsi1.brn.i.cz] out: (Reading database ... 90%
 [nsi1.brn.i.cz] out: (Reading database ... 95%
 [nsi1.brn.i.cz] out: (Reading database ... 100%
 [nsi1.brn.i.cz] out: (Reading database ... 44468 files and directories currently installed.)
 [nsi1.brn.i.cz] out: Preparing to unpack .../linux-image-3.16.0-4-amd64_3.16.7-ckt20-1+deb8u3_amd64.deb ...
 [nsi1.brn.i.cz] out: Unpacking linux-image-3.16.0-4-amd64 (3.16.7-ckt20-1+deb8u3) over (3.16.7-ckt20-1+deb8u2) ...
 [nsi1.brn.i.cz] out: Setting up linux-image-3.16.0-4-amd64 (3.16.7-ckt20-1+deb8u3) ...
 [nsi1.brn.i.cz] out: /etc/kernel/postinst.d/initramfs-tools:
 [nsi1.brn.i.cz] out: update-initramfs: Generating /boot/initrd.img-3.16.0-4-amd64
 [nsi1.brn.i.cz] out: W: Possible missing firmware /lib/firmware/tigon/tg3_tso5.bin for module tg3
 [nsi1.brn.i.cz] out: W: Possible missing firmware /lib/firmware/tigon/tg3_tso.bin for module tg3
 [nsi1.brn.i.cz] out: W: Possible missing firmware /lib/firmware/tigon/tg3.bin for module tg3
 [nsi1.brn.i.cz] out: /etc/kernel/postinst.d/zz-update-grub:
 [nsi1.brn.i.cz] out: Generating grub configuration file ...
 [nsi1.brn.i.cz] out: Found linux image: /boot/vmlinuz-3.16.0-4-amd64
 [nsi1.brn.i.cz] out: Found initrd image: /boot/initrd.img-3.16.0-4-amd64
 [nsi1.brn.i.cz] out: done
 [nsi1.brn.i.cz] out:


 Done.
 Disconnecting from nsi1.brn.i.cz... done.


The option to suppress dpkg progress output could be very worth.
I want to have tty on output, because of debconf questions of course.
Thanks for your work
Regards

Hi,

stdout is not tty, but dpkg still produces a lot of output:


$ docker stop apt-quiet \
; docker run --rm --name apt-quiet -d cypress/base:12 sleep infinity \
&& docker exec apt-quiet sh -euxc '
    [ -t 1 ] && echo tty || echo non-tty
    && ps -efH
    && export DEBIAN_FRONTEND=noninteractive
    && apt-get -qq update
    && apt-get -qq install less
'

apt-quiet
10ff09dfe813df80917d6a4b180f616c54ecd78267739eb5e0c79927410e55a4
non-tty
+ [ -t 1 ]
+ echo non-tty
+ ps -efH
UID          PID    PPID  C STIME TTY          TIME CMD
root           7       0  0 13:08 ?        00:00:00 sh -euxc [ -t 1 ]
&& echo tty || echo non-tty && ps -efH && export
DEBIAN_FRONTEND=noninteractive && apt-get -qq update && apt-get -qq
install less
root          12       7  0 13:08 ?        00:00:00   ps -efH
root           1       0 28 13:08 ?        00:00:00 sleep infinity
+ export DEBIAN_FRONTEND=noninteractive
+ apt-get -qq update
+ apt-get -qq install less
debconf: delaying package configuration, since apt-utils is not installed
Selecting previously unselected package less.
(Reading database ...  (Reading database ... 5% (Reading database ...
10% (Reading database ... 15% (Reading database ... 20% (Reading
database ... 25% (Reading database ... 30% (Reading database ... 35%
(Reading database ... 40% (Reading database ... 45% (Reading database
... 50% (Reading database ... 55% (Reading database ... 60% (Reading
database ... 65% (Reading database ... 70% (Reading database ... 75%
(Reading database ... 80% (Reading database ... 85% (Reading database
... 90% (Reading database ... 95% (Reading database ... 100% (Reading
database ... 33231 files and directories currently installed.)
Preparing to unpack .../less_487-0.1+b1_amd64.deb ...
Unpacking less (487-0.1+b1) ...
Setting up less (487-0.1+b1) ...
Processing triggers for mime-support (3.62) ...


Regards,
Yuri

I stumbled upon this bug today. Clearly the reasoning for not accepting
the patch hasn't withstood the test of time, or at least hasn't produced
the way to make it reasonable.

This issue is still present, cluttering logs of CI jobs by a lot.