[pkg-cryptsetup-devel] Bug#964187: cryptsetup: takes one minute to unlock the disk with a passphrase

Vincent Lefevre vincent at vinc17.net
Fri Jul 3 23:18:59 BST 2020


On 2020-07-03 16:12:49 +0200, Guilhem Moulin wrote:
> On Fri, 03 Jul 2020 at 12:53:17 +0200, Vincent Lefevre wrote:
> > I don't know really where the problem comes from, but it now takes
> > one minute to unlock the disk of my laptop with a passphrase. Well,
> > I'm not sure whether this comes from cryptsetup or something that
> > comes just after it, but at least the fact that cryptsetup doesn't
> > output any confirmation message doesn't help.
> 
> See https://wiki.debian.org/InitramfsDebug#Saving_debug_information to
> get debug output.  For further detailed debug output you can append `-x`
> to the shebang line of the boot script causing the delay.  See e.g.,
> https://cryptsetup-team.pages.debian.net/cryptsetup/README.debug.html .

I've attached the initramfs.debug file. But I don't know what
is blocking. The unlocking should have been completed before
the following lines appear (since at this time I had entered
the passphrase on the console).

IP-Config: eth0 hardware address 30:8d:99:25:ad:3f mtu 1500 DHCP RARP
IP-Config: no response after 6 secs - giving up
IP-Config: eth0 hardware address 30:8d:99:25:ad:3f mtu 1500 DHCP RARP
IP-Config: no response after 9 secs - giving up
IP-Config: eth0 hardware address 30:8d:99:25:ad:3f mtu 1500 DHCP RARP
IP-Config: no response after 16 secs - giving up
IP-Config: eth0 hardware address 30:8d:99:25:ad:3f mtu 1500 DHCP RARP
IP-Config: no response after 25 secs - giving up

Note that /usr/share/doc/dropbear-initramfs/README.initramfs
says at the end:

  This is non-blocking for the startup process, so when you are at the
  console you won't have to wait for the SSHd to complete its startup.

-- 
Vincent Lefèvre <vincent at vinc17.net> - Web: <https://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <https://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / AriC project (LIP, ENS-Lyon)
-------------- next part --------------
+ unset log_output
+ maybe_break top
+ run_scripts /scripts/init-top
+ initdir=/scripts/init-top
+ '[' '!' -d /scripts/init-top ]
+ shift
+ . /scripts/init-top/ORDER
+ /scripts/init-top/all_generic_ide
+ '[' -e /conf/param.conf ]
+ /scripts/init-top/blacklist
+ '[' -e /conf/param.conf ]
+ /scripts/init-top/keymap
+ '[' -e /conf/param.conf ]
+ /scripts/init-top/udev
+ '[' -e /conf/param.conf ]
+ maybe_break modules
+ '[' n '!=' y ]
+ log_begin_msg 'Loading essential drivers'
+ _log_msg 'Begin: %s ... ' 'Loading essential drivers'
+ '[' n '=' y ]
+ printf 'Begin: %s ... ' 'Loading essential drivers'
Begin: Loading essential drivers ... + '[' -n  ]
+ load_modules
+ '[' -e /conf/modules ]
+ read -r m
+ '[' -z e1000e ]
+ printf '%.1s' e1000e
+ com=e
+ '[' e '=' '#' ]
+ modprobe e1000e
+ read -r m
+ '[' n '!=' y ]
+ log_end_msg
+ _log_msg 'done.\n'
+ '[' n '=' y ]
+ printf 'done.\n'
done.
+ '['  ]
+ maybe_break premount
+ '[' n '!=' y ]
+ log_begin_msg 'Running /scripts/init-premount'
+ _log_msg 'Begin: %s ... ' 'Running /scripts/init-premount'
+ '[' n '=' y ]
+ printf 'Begin: %s ... ' 'Running /scripts/init-premount'
Begin: Running /scripts/init-premount ... + run_scripts /scripts/init-premount
+ initdir=/scripts/init-premount
+ '[' '!' -d /scripts/init-premount ]
+ shift
+ . /scripts/init-premount/ORDER
+ /scripts/init-premount/dropbear
+ '[' -e /conf/param.conf ]
+ '[' n '!=' y ]
+ log_end_msg
+ _log_msg 'done.\n'
+ '[' n '=' y ]
+ printf 'done.\n'
done.
+ maybe_break mount
+ log_begin_msg 'Mounting root file system'
+ _log_msg 'Begin: %s ... ' 'Mounting root file system'
+ '[' n '=' y ]
+ printf 'Begin: %s ... ' 'Mounting root file system'
Begin: Mounting root file system ... + . /scripts/local
+ . /scripts/nfs
+ . /scripts/local
+ parse_numeric /dev/mapper/zira--vg-root
+ return
+ maybe_break mountroot
+ mount_top
+ local_top
+ '['  '!=' yes ]
+ '[' n '!=' y ]
+ log_begin_msg 'Running /scripts/local-top'
+ _log_msg 'Begin: %s ... ' 'Running /scripts/local-top'
+ '[' n '=' y ]
+ printf 'Begin: %s ... ' 'Running /scripts/local-top'
Begin: Running /scripts/local-top ... + run_scripts /scripts/local-top
+ initdir=/scripts/local-top
+ '[' '!' -d /scripts/local-top ]
+ shift
+ . /scripts/local-top/ORDER
+ /scripts/local-top/cryptopensc
+ '[' -e /conf/param.conf ]
+ /scripts/local-top/lvm2
  Volume group "zira-vg" not found
  Cannot process volume group zira-vg
  Volume group "zira-vg" not found
  Cannot process volume group zira-vg
+ '[' -e /conf/param.conf ]
+ /scripts/local-top/cryptroot
Please unlock disk sda5_crypt: IP-Config: eth0 hardware address 30:8d:99:25:ad:3f mtu 1500 DHCP RARP
IP-Config: no response after 2 secs - giving up
IP-Config: eth0 hardware address 30:8d:99:25:ad:3f mtu 1500 DHCP RARP
IP-Config: no response after 3 secs - giving up
IP-Config: eth0 hardware address 30:8d:99:25:ad:3f mtu 1500 DHCP RARP
IP-Config: no response after 4 secs - giving up

cryptsetup: sda5_crypt: set up successfully
+ '[' -e /conf/param.conf ]
+ '[' n '!=' y ]
+ log_end_msg
+ _log_msg 'done.\n'
+ '[' n '=' y ]
+ printf 'done.\n'
done.
+ local_top_used=yes
+ '[' -z  ]
+ cat /proc/uptime
+ local_top_time='25.45 186.56'
+ local_top_time=25
+ local_top_time=26
+ export local_top_time
+ mount_premount
+ local_premount
+ '['  '!=' yes ]
+ '[' n '!=' y ]
+ log_begin_msg 'Running /scripts/local-premount'
+ _log_msg 'Begin: %s ... ' 'Running /scripts/local-premount'
+ '[' n '=' y ]
+ printf 'Begin: %s ... ' 'Running /scripts/local-premount'
Begin: Running /scripts/local-premount ... + run_scripts /scripts/local-premount
+ initdir=/scripts/local-premount
+ '[' '!' -d /scripts/local-premount ]
+ shift
+ . /scripts/local-premount/ORDER
+ /scripts/local-premount/ntfs_3g
+ '[' -e /conf/param.conf ]
+ /scripts/local-premount/resume
+ '[' -e /conf/param.conf ]
+ '[' n '!=' y ]
+ log_end_msg
+ _log_msg 'done.\n'
+ '[' n '=' y ]
+ printf 'done.\n'
done.
+ local_premount_used=yes
+ mountroot
+ local_mount_root
+ local_top
+ '[' yes '!=' yes ]
+ local_top_used=yes
+ '[' -z 26 ]
+ '[' -z /dev/mapper/zira--vg-root ]
+ local_device_setup /dev/mapper/zira--vg-root 'root file system'
+ local 'dev_id=/dev/mapper/zira--vg-root'
+ local 'name=root file system'
+ local 'may_panic=true'
+ local real_dev
+ local time_elapsed
+ local count
+ wait_for_udev 10
+ command -v udevadm
+ udevadm settle '--timeout=10'
+ '[' -n  ]
+ '[' /mapper/zira--vg-root '=' /dev/mapper/zira--vg-root ]
+ resolve_device /dev/mapper/zira--vg-root
+ DEV=/dev/mapper/zira--vg-root
+ '[' -e /dev/mapper/zira--vg-root ]
+ echo /dev/mapper/zira--vg-root
+ real_dev=/dev/mapper/zira--vg-root
+ get_fstype /dev/mapper/zira--vg-root
+ local FS FSTYPE
+ FS=/dev/mapper/zira--vg-root
+ FSTYPE=unknown
+ fstype /dev/mapper/zira--vg-root
+ eval 'FSTYPE=ext4
FSSIZE=491111055360'
+ FSTYPE=ext4
+ FSSIZE=491111055360
+ '[' ext4 '=' unknown ]
+ echo ext4
+ return 0
+ resolve_device /dev/mapper/zira--vg-root
+ DEV=/dev/mapper/zira--vg-root
+ '[' -e /dev/mapper/zira--vg-root ]
+ echo /dev/mapper/zira--vg-root
+ real_dev=/dev/mapper/zira--vg-root
+ get_fstype /dev/mapper/zira--vg-root
+ local FS FSTYPE
+ FS=/dev/mapper/zira--vg-root
+ FSTYPE=unknown
+ fstype /dev/mapper/zira--vg-root
+ eval 'FSTYPE=ext4
FSSIZE=491111055360'
+ FSTYPE=ext4
+ FSSIZE=491111055360
+ '[' ext4 '=' unknown ]
+ echo ext4
+ return 0
+ DEV=/dev/mapper/zira--vg-root
+ ROOT=/dev/mapper/zira--vg-root
+ '[' -z  ]
+ get_fstype /dev/mapper/zira--vg-root
+ local FS FSTYPE
+ FS=/dev/mapper/zira--vg-root
+ FSTYPE=unknown
+ fstype /dev/mapper/zira--vg-root
+ eval 'FSTYPE=ext4
FSSIZE=491111055360'
+ FSTYPE=ext4
+ FSSIZE=491111055360
+ '[' ext4 '=' unknown ]
+ echo ext4
+ return 0
+ FSTYPE=ext4
+ local_premount
+ '[' yes '!=' yes ]
+ local_premount_used=yes
+ '[' y '=' y ]
+ roflag=-r
+ checkfs /dev/mapper/zira--vg-root root ext4
+ _checkfs_once /dev/mapper/zira--vg-root root ext4
+ DEV=/dev/mapper/zira--vg-root
+ NAME=root
+ TYPE=ext4
+ '[' root '=' / ]
+ FSCK_LOGFILE=/run/initramfs/fsck.log
+ FSCK_STAMPFILE=/run/initramfs/fsck-root
+ '[' ext4 '=' auto ]
+ FSCKCODE=0
+ '[' -z ext4 ]
+ command -v fsck
+ '[' n '=' y ]
+ '[' n '=' y ]
+ force=
+ '['  '=' y ]
+ '['  '=' n ]
+ fix=-a
+ spinner=
+ '[' -z y ]
+ '[' n '=' n ]
+ log_begin_msg 'Will now check root file system'
+ _log_msg 'Begin: %s ... ' 'Will now check root file system'
+ '[' n '=' y ]
+ printf 'Begin: %s ... ' 'Will now check root file system'
Begin: Will now check root file system ... + logsave -a -s /run/initramfs/fsck.log fsck -a -V -t ext4 /dev/mapper/zira--vg-root
fsck from util-linux 2.35.2
[/sbin/fsck.ext4 (1) -- /dev/mapper/zira--vg-root] fsck.ext4 -a /dev/mapper/zira--vg-root 
/dev/mapper/zira--vg-root: clean, 1748250/29982720 files, 92983314/119900160 blocks
+ FSCKCODE=0
+ log_end_msg
+ _log_msg 'done.\n'
+ '[' n '=' y ]
+ printf 'done.\n'
done.
+ '[' 0 -eq 32 ]
+ '[' 0 -eq 4 ]
+ '[' 0 -gt 1 ]
+ true
+ return 0
+ mount -r -t ext4 /dev/mapper/zira--vg-root /root
+ log_end_msg
+ _log_msg 'done.\n'
+ '[' n '=' y ]
+ printf 'done.\n'
done.
+ read_fstab_entry /usr
+ found=1
+ '[' -f /root/etc/fstab ]
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ continue
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ continue
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ continue
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ continue
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ continue
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ continue
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ continue
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ '[' / '=' /usr ]
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ continue
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ '[' /boot '=' /usr ]
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ '[' none '=' /usr ]
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ '[' /media/cdrom0 '=' /usr ]
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ '[' /media/mem '=' /usr ]
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ '[' /media/mem '=' /usr ]
+ read -r MNT_FSNAME MNT_DIR MNT_TYPE MNT_OPTS MNT_FREQ MNT_PASS MNT_JUNK
+ return 1
+ mount_bottom
+ local_bottom
+ '[' yes '=' yes ]
+ '[' n '!=' y ]
+ log_begin_msg 'Running /scripts/local-bottom'
+ _log_msg 'Begin: %s ... ' 'Running /scripts/local-bottom'
+ '[' n '=' y ]
+ printf 'Begin: %s ... ' 'Running /scripts/local-bottom'
Begin: Running /scripts/local-bottom ... + run_scripts /scripts/local-bottom
+ initdir=/scripts/local-bottom
+ '[' '!' -d /scripts/local-bottom ]
+ shift
+ . /scripts/local-bottom/ORDER
+ /scripts/local-bottom/cryptgnupg-sc
+ '[' -e /conf/param.conf ]
+ /scripts/local-bottom/cryptopensc
+ '[' -e /conf/param.conf ]
+ /scripts/local-bottom/ntfs_3g
+ '[' -e /conf/param.conf ]
+ '[' n '!=' y ]
+ log_end_msg
+ _log_msg 'done.\n'
+ '[' n '=' y ]
+ printf 'done.\n'
done.
+ local_premount_used=no
+ local_top_used=no
+ unset local_top_time
+ nfs_bottom
+ '['  '=' yes ]
+ '['  '=' yes ]
+ nfs_premount_used=no
+ nfs_top_used=no
+ local_bottom
+ '[' no '=' yes ]
+ '[' no '=' yes ]
+ local_premount_used=no
+ local_top_used=no
+ unset local_top_time
+ maybe_break bottom
+ '[' n '!=' y ]
+ log_begin_msg 'Running /scripts/init-bottom'
+ _log_msg 'Begin: %s ... ' 'Running /scripts/init-bottom'
+ '[' n '=' y ]
+ printf 'Begin: %s ... ' 'Running /scripts/init-bottom'
Begin: Running /scripts/init-bottom ... + run_scripts /scripts/init-bottom
+ initdir=/scripts/init-bottom
+ '[' '!' -d /scripts/init-bottom ]
+ shift
+ . /scripts/init-bottom/ORDER
+ /scripts/init-bottom/dropbear
IP-Config: eth0 hardware address 30:8d:99:25:ad:3f mtu 1500 DHCP RARP
IP-Config: no response after 6 secs - giving up
IP-Config: eth0 hardware address 30:8d:99:25:ad:3f mtu 1500 DHCP RARP
IP-Config: no response after 9 secs - giving up
IP-Config: eth0 hardware address 30:8d:99:25:ad:3f mtu 1500 DHCP RARP
IP-Config: no response after 16 secs - giving up
IP-Config: eth0 hardware address 30:8d:99:25:ad:3f mtu 1500 DHCP RARP
IP-Config: no response after 25 secs - giving up
Begin: Bringing down eth0 ... done.
Begin: Bringing down lo ... done.
+ '[' -e /conf/param.conf ]
+ /scripts/init-bottom/udev
+ '[' -e /conf/param.conf ]
+ '[' n '!=' y ]
+ log_end_msg
+ _log_msg 'done.\n'
+ '[' n '=' y ]
+ printf 'done.\n'
done.
+ mount -n -o move /run /root/run
+ validate_init /sbin/init
+ run-init -n /root /sbin/init
+ validate_init /sbin/init
+ run-init -n /root /sbin/init
+ maybe_break init
+ unset debug
+ unset MODPROBE_OPTIONS
+ unset DPKG_ARCH
+ unset ROOTFLAGS
+ unset ROOTFSTYPE
+ unset ROOTDELAY
+ unset ROOT
+ unset IP
+ unset BOOT
+ unset BOOTIF
+ unset DEVICE
+ unset UBIMTD
+ unset blacklist
+ unset break
+ unset noresume
+ unset panic
+ unset quiet
+ unset readonly
+ unset resume
+ unset resume_offset
+ unset noresume
+ unset fastboot
+ unset forcefsck
+ unset fsckfix
+ mount -n -o move /sys /root/sys
+ mount -n -o move /proc /root/proc
+ exec run-init /root /sbin/init
IP-Config: eth0 hardware address 30:8d:99:25:ad:3f mtu 1500 DHCP RARP
IP-Config: no response after 36 secs - giving up
/scripts/init-premount/dropbear: line 261: ipconfig: not found
/scripts/init-premount/dropbear: line 261: ipconfig: not found
/scripts/init-premount/dropbear: .: line 279: can't open '/run/net-*.conf': No such file or directory


More information about the pkg-cryptsetup-devel mailing list