Bug#439763: debconf: hangs on puppet installs on preseed install

[John Morrissey]

On Tue, Dec 18, 2007 at 05:16:03PM +0000, Colin Watson wrote:
> On Mon, Aug 27, 2007 at 10:42:41AM +0100, Adrian Bridgett wrote:
> > When postfix.config runs /usr/share/debconf/confmodules, at line 45 it
> > complains that FD3 is a bad file descriptor. Listing /proc/$$/fd
> > shows that FD3 doesn't exist. FD2 points to the overall stderr, FD1
> > is a pipe back to FD8 of dpkg-preconfigure. FD0 is FD7 from
> > dpkg-preconfigure.
> >
> > FD3 exists and DEBCONF_REDIR is set when ConfModule::startup() is
> > called, however it looks like FD3 does not persist into the open2()
> > call.
>
> On the other hand, it might be something completely different. I note
> that both sysstat and postfix call db_stop. I don't think this should
> actually break the cdebconf instance way down at the bottom of the
> stack, but it's possible that it will confuse the debconf running
> debconf-apt-progress. If you could run the whole install under
> DEBCONF_DEBUG=developer (you did something like this earlier), then this
> might shed some light on exactly which debconf frontend is seeing what
> commands.
[snip]
> I think I'd rather figure out the underlying problem. It may be that we
> need to ignore db_stop in some circumstances.

I came across this with d-i wheezy beta1. I have a late_command that runs
Puppet in /target, and most package installations were failing due to EBADF
on fd3, mostly when handling man-db triggers. man-db.postinst fails when the
first db_* tries to write to fd3. Adding an lsof to man-db.postinst shows
that fd3 isn't present.

I can reproduce with something as simple as 'chroot /target apt-get -y
install php5-cli' in late_command.

I've posted the d-i syslog with DEBCONF_DEBUG=developer, late_command, and
env/lsof/strace output at http://horde.net/~jwm/debian/bug439763/ .

Could someone more knowledgable about debconf internals take a look at this,
please? I'm happy to help debug further, but I'm at a loss on how to
continue.

john
--
John Morrissey _o /\ ---- __o
j...@horde.net _-< \_ / \ ---- < \,
www.horde.net/ __(_)/_(_)________/ \_______(_) /_(_)__


--
To UNSUBSCRIBE, email to debian-bugs-...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org

[Christian PERRIER]

Quoting John Morrissey (j...@horde.net):

> I've posted the d-i syslog with DEBCONF_DEBUG=developer, late_command, and
> env/lsof/strace output at http://horde.net/~jwm/debian/bug439763/ .

May I suggest you to create a tarball, compress it with xz, and send
it to this bug? That would guarantee that the data is available over
time if someone comes over this bug report in the future.

The size is not a big problem.

[Juan Carlos Moreno [ackstorm]]

Hi there,

same problem here, using puppet and installing mysql-server, solved (for
me) redirecting puppet log to syslog: puppet apply --logdest syslog
XXXXX

Hope that helps someone
Regards

--

Un saludo.
Juan Carlos Moreno
juancarl...@ackstorm.es
Project Manager

-----------------------------------------------------------------

[Juan Carlos Moreno [ackstorm]]

Oppsss, sorry! I have made a lot of changes...

Redirecting puppet logdest is not the solution but setting
'DEBCONF_REDIR' to empty, it works!

This is how I call puppet, and it works for me (now):

[..]
env = environ.copy()
env['DEBCONF_DEBUG']='developer'
env['DEBCONF_REDIR']=''
p = Popen(['puppet', 'apply', '--detailed-exitcodes',
'--debug','--apply', data_pson],
cwd=cwd, stdin=None, env=env)
stdout, stderr = p.communicate()
[..]

On Thu, 2012-08-23 at 11:14 +0200, Juan Carlos Moreno [ackstorm] wrote:
> Hi there,
>
> same problem here, using puppet and installing mysql-server, solved (for
> me) redirecting puppet log to syslog: puppet apply --logdest syslog
> XXXXX
>
> Hope that helps someone
> Regards
>

--

Un saludo.
Juan Carlos Moreno
juancarl...@ackstorm.es
Project Manager

Oficina central: 902 888 345

ACK STORM, S.L.
ISO 9001:2008 (Cert.nº. 536932)
http://ackstorm.es

Este mensaje electrónico contiene información de ACK STORM, S.L. que es
privada y confidencial, siendo para el uso exclusivo de la persona(s) o
entidades arriba mencionadas. Si usted no es el destinatario señalado,
le informamos que cualquier divulgación, copia, distribución o uso de los
contenidos está prohibida. Si usted ha recibido este mensaje por error,
por favor borre su contenido y comuníquenoslo en la dirección
acks...@ackstorm.es

[John Morrissey]

On Thu, Aug 23, 2012 at 11:42:44AM +0200, Juan Carlos Moreno [ackstorm] wrote:
> Oppsss, sorry! I have made a lot of changes...
>
> Redirecting puppet logdest is not the solution but setting
> 'DEBCONF_REDIR' to empty, it works!
>
> This is how I call puppet, and it works for me (now):
>
> [..]
> env = environ.copy()
> env['DEBCONF_DEBUG']='developer'
> env['DEBCONF_REDIR']=''
> p = Popen(['puppet', 'apply', '--detailed-exitcodes',
> '--debug','--apply', data_pson],
> cwd=cwd, stdin=None, env=env)
> stdout, stderr = p.communicate()
> [..]

Thanks for the info, Juan.

At least for me with d-i wheezy beta1, if I only unset DEBCONF_REDIR,
scripts in the chroot still try to communicate with the d-i debconf frontend
(outside the chroot), and block because something seems amiss with the file
descriptor manipulation. I suspect this is because DEBCONF_HAS_FRONTEND is
still set, so confmodule doesn't spawn a different frontend.

As a result, man-db.postinst's call to db_version emits the debconf command
to stdout, where it gets caught by log-output (if I chroot my script with
in-target, the same blocked postinst happens if I simply chroot my script):

Aug 23 16:55:01 log-output: VERSION 2.0

And the postinst blocks on reading the unchrooted debconf frontend's
response, since the frontend never got the request:

root 12444 0.1 5.2 62140 26556 tty1 S+ 16:54 0:00
\_ apt-get -y install php5-cli
root 12461 0.0 2.1 29580 10760 tty1 S+ 16:55 0:00
\_ /usr/bin/dpkg --status-fd 22 --unpack --auto-deconfigure /var/cache/apt/archives/php5-common_5.4.4-4_amd64.deb /var/cache/apt/archives/php5-cli_5.4.4-4_amd64.deb
root 12483 0.0 0.1 4164 628 tty1 S+ 16:55 0:00
\_ /bin/sh -e /var/lib/dpkg/info/man-db.postinst triggered /usr/share/man

root@debian:/# strace -p 12483
Process 12483 attached - interrupt to quit
read(0, ^C <unfinished ...>
root@debian:/# lsof -p 12483 | grep 0[rwu]
man-db.po 12483 root 0r FIFO 0,8 0t0 3215 pipe

root 235 1.1 3.9 50268 20180 tty1 S+ 16:39 0:14 debconf -o d-i /usr/bin/main-menu

root@debian:/# lsof -p 235 | grep 3125
debconf 235 root 4w FIFO 0,8 0t0 3215 pipe


I also tried unsetting DEBIAN_HAS_FRONTEND, so a separate debconf frontend
gets spawned in the chroot. Unfortunately, the chrooted frontend apparently
can't interact with the console, since its 0 and 1 FDs are still pipes to
the unchrooted debconf frontend.

If I unset DEBCONF_REDIR and DEBIAN_HAS_FRONTEND, then use 'debconf-disconnect
chroot /target myscript', Puppet package installations still get EBADF when
trying to interact with file descriptor 3.

john
--
John Morrissey _o /\ ---- __o
j...@horde.net _-< \_ / \ ---- < \,
www.horde.net/ __(_)/_(_)________/ \_______(_) /_(_)__

[Michael Prokop]

* John Morrissey [Thu Aug 23, 2012 at 10:33:02AM -0700]:

[...]

> As a result, man-db.postinst's call to db_version emits the debconf command
> to stdout, where it gets caught by log-output (if I chroot my script with
> in-target, the same blocked postinst happens if I simply chroot my script):

[...]

Sadly I'm still seeing this on Debian/wheezy systems
(puppet, screen + man-db all being from wheezy - package
installation running via puppet agent):

,---- [ rewrapped c/p from puppet dashboard log ]
| Unpacking screen (from .../screen_4.1.0~20120320gitdb59704-7_amd64.deb) ...
| Processing triggers for install-info ...
| Processing triggers for man-db ...
| /var/lib/dpkg/info/man-db.postinst: 44: /var/lib/dpkg/info/man-db.postinst: 3: Bad file descriptor
| dpkg: error processing man-db (--unpack): subprocess installed post-installation script returned error exit status 2
| Errors were encountered while processing: man-db E: Sub-process /usr/bin/dpkg returned an error code (1)
`----

Has anyone made any further progress on this issue?

regards,
-mika-