Re: [knot-dns-users] Missing private keys in backup

Hi Thomas, It looks like /var/lib/knot/keys/keys/24991855db1c06b29b9e78ef8d6fddf7c5f07cd5.pem doesn't exist. What does keymgr say about this key? Daniel On 12/9/20 6:35 PM, Thomas E. wrote: > Hi Libor, > > you are right, I now started strace with the "-f" option. Now I have the > full trace. Sorry, working with strace has been a long time ago... > > I think this is interesting: > > This key is written to the backup: > > [pid 9783] openat(AT_FDCWD, > "/var/lib/knot/keys/keys/087cc573318e070befff1d9cbcf07e3b5cf5444d.pem", > O_RDONLY) = 23 > [pid 9783] lseek(23, 0, SEEK_END) = 1704 > [pid 9783] lseek(23, 0, SEEK_SET) = 0 > [pid 9783] read(23, "-----BEGIN PRIVATE KEY-----\nMIIE"..., 1704) = 1704 > [pid 9783] close(23) = 0 > [pid 9783] openat(AT_FDCWD, > "/tmp/backup/keys/keys/087cc573318e070befff1d9cbcf07e3b5cf5444d.pem", > O_WRONLY|O_CREAT|O_EXCL, 0640) = 23 > [pid 9783] write(23, "-----BEGIN PRIVATE KEY-----\nMIIE"..., 1704) = 1704 > [pid 9783] close(23) = 0 > > > This key has not been written: > > [pid 9783] openat(AT_FDCWD, > "/var/lib/knot/keys/keys/24991855db1c06b29b9e78ef8d6fddf7c5f07cd5.pem", > O_RDONLY) = -1 ENOENT (No such file or directory) > [pid 9783] munmap(0x7f53c042a000, 1142784) = 0 > [pid 9783] close(28) = 0 > [pid 9783] close(27) = 0 > [pid 9783] munmap(0x7f5909418000, 8192) = 0 > [pid 9783] close(26) = 0 > [pid 9783] close(24) = 0 > [pid 9783] unlink("/tmp/backup/knot.backup.lockfile") = > > > > Thanks a lot, > Thomas > > > > On 09.12.20 17:49, libor.peltan wrote: >> Thomas, don't you call strace in a way which only tracks one thread of >> knotd process? Knot is a multithreaded application and the backup is >> done by different threads than the one handling knotc requests. It's >> still visible that the straces you provided so far don't cover any key >> file copying etc... >> >> I'm not very surprised that on another machine the backup works. This is >> a nasty issue and therefore we need your help with debugging it on the >> exact environment it fails on. >> >> Thanks! >> >> Dne 09. 12. 20 v 17:17 Thomas E. napsal(a): >>> Hi Libor, >>> >>> >>> I performed the same actions on a test machine with 2 test zones. Same >>> Knot version, same OS. >>> >>> root@signer-test:/var/lib/knot/keys/keys# strace -p 3424 >>> >>> >>> strace: Process 3424 attached >>> restart_syscall(<... resuming interrupted poll ...>) = 1 >>> accept4(13, NULL, NULL, SOCK_NONBLOCK)  = 14 >>> recvmsg(14, {msg_namelen=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = -1 EAGAIN >>> (Resource temporarily unavailable) >>> poll([{fd=14, events=POLLIN}], 1, 5000) = 1 ([{fd=14, revents=POLLIN}]) >>> recvmsg(14, {msg_name=NULL, msg_namelen=0, >>> msg_iov=[{iov_base="\1\20\0\vzone-backup\21\0\0\32\0\v/tmp/backup"..., >>> iov_len=262144}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, >>> MSG_DONTWAIT|MSG_NOSIGNAL) = 37 >>> write(18, "2020-12-09T16:13:06+0000 info: c"..., 71) = 71 >>> stat("/var/lib/knot/catalog/data.mdb", 0x7ffd37b72bb0) = -1 ENOENT (No >>> such file or directory) >>> stat("/var/lib/knot/journal/data.mdb", {st_mode=S_IFREG|0660, >>> st_size=94208, ...}) = 0 >>> stat("/var/lib/knot/keys/data.mdb", {st_mode=S_IFREG|0660, >>> st_size=45056, ...}) = 0 >>> mkdir("/tmp/backup", 0770)              = 0 >>> openat(AT_FDCWD, "/tmp/backup/knot.backup.lockfile", >>> O_RDONLY|O_CREAT|O_EXCL, 0600) = 21 >>> mkdir("/tmp/backup", 0750)              = -1 EEXIST (File exists) >>> stat("/var/lib/knot/catalog/data.mdb", 0x7ffd37b72ac0) = -1 ENOENT (No >>> such file or directory) >>> futex(0x7ffd37b73400, FUTEX_WAKE_PRIVATE, 1) = 1 >>> futex(0x7ffd37b733b0, FUTEX_WAKE_PRIVATE, 1) = 1 >>> futex(0x7ffd37b73404, FUTEX_WAKE_PRIVATE, 1) = 1 >>> futex(0x7ffd37b733b0, FUTEX_WAKE_PRIVATE, 1) = 1 >>> sendmsg(14, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\3", >>> iov_len=1}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) >>> = 1 >>> recvmsg(14, {msg_namelen=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = -1 EAGAIN >>> (Resource temporarily unavailable) >>> poll([{fd=14, events=POLLIN}], 1, 5000) = 1 ([{fd=14, revents=POLLIN}]) >>> recvmsg(14, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0", >>> iov_len=262144}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, >>> MSG_DONTWAIT|MSG_NOSIGNAL) = 1 >>> >>> close(14)                               = 0 >>> poll([{fd=13, events=POLLIN}], 1, -1 >>> >>> >>> 2020-12-09T16:13:06+0000 info: control, received command 'zone-backup' >>> 2020-12-09T16:13:06+0000 info: [xx.de.] zone backed up to '/tmp/backup' >>> 2020-12-09T16:13:06+0000 info: [yy.de.] zone backed up to '/tmp/backup' >>> >>> All 4 keys have been successfully backed up. >>> >>> >>> >>> Thanks, >>> Thomas >>> >>> >>> On 09.12.20 16:05, libor.peltan wrote: >>>> Some explanation: zone backup or restore is performed as a zone "event". >>>> When zone events are invoked via the knotc interface, it typically works >>>> in the way that the event is planned to be performed later and "OK" is >>>> returned just as an info that the command has been registered. The event >>>> (zone backup in this case) happens per-zone and with some delay, when >>>> some background-worker becomes available, and the outcome appears in the >>>> log. On the contrary, if knotc is invoked with `-b` parameter, it waits >>>> for the event to be performed synchronously, and collects the outcome of >>>> the whole process (some error code handligs of this are currently >>>> subject to ongoing improvements by my colleagues). >>>> >>>> So, from the strace you sent me, I only see that some initialization has >>>> been done and that the early "OK" has been returned, but there are no >>>> traits of the backup process as such :( >>>> >>>> Could you please collect somewhat longer strace, by watching when the >>>> backup finishes in the logfile? >>>> >>>> Thanks! >>>> >>>> Libor >>>> >>>> Dne 09. 12. 20 v 15:56 Thomas E. napsal(a): >>>>> Hi Libor, >>>>> >>>>> yes, the backup command was executed and confirmed with "OK": >>>>> >>>>> root@signer-0:/# knotc zone-backup +backupdir /tmp/backup >>>>> OK >>>>> >>>>> I did it again and the output is the same. >>>>> >>>>> Thanks, >>>>> Thomas >>>>> >>>>> On 09.12.20 15:42, libor.peltan wrote: >>>>>> Hi Thomas, >>>>>> >>>>>> are you sure this strace has been collected while the issue was >>>>>> reproduced and half of the keys copied again? >>>>>> >>>>>> Maybe you just have deattached strace too early(?). >>>>>> >>>>>> Libor >>>>>> >>>>>> Dne 09. 12. 20 v 15:00 Thomas E. napsal(a): >>>>>>> Hi Libor, >>>>>>> >>>>>>> sure, here is the output: >>>>>>> >>>>>>> >>>>>>> root@signer-0:/tmp/backup/keys/keys# strace -p 9781 >>>>>>> strace: Process 9781 attached >>>>>>> restart_syscall(<... resuming interrupted restart_syscall ...>) = 1 >>>>>>> accept4(16, NULL, NULL, SOCK_NONBLOCK)  = 23 >>>>>>> recvmsg(23, {msg_namelen=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = -1 EAGAIN >>>>>>> (Resource temporarily unavailable) >>>>>>> poll([{fd=23, events=POLLIN}], 1, 5000) = 1 ([{fd=23, >>>>>>> revents=POLLIN}]) >>>>>>> recvmsg(23, {msg_name=NULL, msg_namelen=0, >>>>>>> msg_iov=[{iov_base="\1\20\0\vzone-backup\21\0\0\32\0\v/tmp/backup"..., >>>>>>> >>>>>>> iov_len=262144}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, >>>>>>> MSG_DONTWAIT|MSG_NOSIGNAL) = 37 >>>>>>> write(6, "2020-12-09T13:57:12+0000 info: c"..., 71) = 71 >>>>>>> stat("/var/lib/knot/catalog/data.mdb", 0x7ffd0fb9f090) = -1 ENOENT >>>>>>> (No >>>>>>> such file or directory) >>>>>>> stat("/var/lib/knot/journal/data.mdb", {st_mode=S_IFREG|0660, >>>>>>> st_size=9936896, ...}) = 0 >>>>>>> stat("/var/lib/knot/keys/data.mdb", {st_mode=S_IFREG|0660, >>>>>>> st_size=45056, ...}) = 0 >>>>>>> mkdir("/tmp/backup", 0770)              = 0 >>>>>>> openat(AT_FDCWD, "/tmp/backup/knot.backup.lockfile", >>>>>>> O_RDONLY|O_CREAT|O_EXCL, 0600) = 24 >>>>>>> mkdir("/tmp/backup", 0750)              = -1 EEXIST (File exists) >>>>>>> stat("/var/lib/knot/catalog/data.mdb", 0x7ffd0fb9efa0) = -1 ENOENT >>>>>>> (No >>>>>>> such file or directory) >>>>>>> futex(0x7ffd0fb9f8e0, FUTEX_WAKE_PRIVATE, 1) = 1 >>>>>>> futex(0x7ffd0fb9f890, FUTEX_WAKE_PRIVATE, 1) = 1 >>>>>>> futex(0x7ffd0fb9f8e4, FUTEX_WAKE_PRIVATE, 1) = 1 >>>>>>> futex(0x7ffd0fb9f890, FUTEX_WAKE_PRIVATE, 1) = 1 >>>>>>> sendmsg(23, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\3", >>>>>>> iov_len=1}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, >>>>>>> MSG_NOSIGNAL) = 1 >>>>>>> recvmsg(23, {msg_namelen=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = -1 EAGAIN >>>>>>> (Resource temporarily unavailable) >>>>>>> poll([{fd=23, events=POLLIN}], 1, 5000) = 1 ([{fd=23, >>>>>>> revents=POLLIN}]) >>>>>>> recvmsg(23, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0", >>>>>>> iov_len=262144}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, >>>>>>> MSG_DONTWAIT|MSG_NOSIGNAL) = 1 >>>>>>> close(23)                               = 0 >>>>>>> poll([{fd=16, events=POLLIN}], 1, -1 >>>>>>> >>>>>>> >>>>>>> Thomas >>>>>>> >>>>>>> >>>>>>> >>>>>>> On 09.12.20 13:34, libor.peltan wrote: >>>>>>>> Hi Thomas, >>>>>>>> >>>>>>>> would you try attaching `strace` to the running Knot and try the >>>>>>>> backup >>>>>>>> again, in order to see if some syscall(s) return error codes? >>>>>>>> >>>>>>>> Thanks much! >>>>>>>> >>>>>>>> Libor >>>>>>>> >>>>>>>> Dne 09. 12. 20 v 12:25 Thomas E. napsal(a): >>>>>>>>> Hi Libor, >>>>>>>>> >>>>>>>>> >>>>>>>>> # knotc -V >>>>>>>>> knotc (Knot DNS), version 3.0.2 >>>>>>>>> >>>>>>>>> >>>>>>>>> Thomas >>>>>>>>> >>>>>>>>> On 09.12.20 12:16, libor.peltan wrote: >>>>>>>>>> Hi Thomas, >>>>>>>>>> >>>>>>>>>> aren't you using Knot version 3.0.0 (thus lower than 3.0.1) ? >>>>>>>>>> >>>>>>>>>> Libor >>>>>>>>>> >>>>>>>>>> Dne 09. 12. 20 v 11:39 Thomas E. napsal(a): >>>>>>>>>>> Hi Libor, >>>>>>>>>>> >>>>>>>>>>> I deleted the backup directory a few times, but I receive the >>>>>>>>>>> same >>>>>>>>>>> error >>>>>>>>>>> every time: >>>>>>>>>>> >>>>>>>>>>> 2020-12-09T10:31:52+0000 info: control, received command >>>>>>>>>>> 'zone-backup' >>>>>>>>>>> 2020-12-09T10:31:52+0000 warning: [xxx.] zone backup failed (not >>>>>>>>>>> exists) >>>>>>>>>>> 2020-12-09T10:31:52+0000 error: [xxx.] zone event >>>>>>>>>>> 'backup/restore' >>>>>>>>>>> failed (not exists) >>>>>>>>>>> 2020-12-09T10:31:52+0000 warning: [yyy.] zone backup failed (not >>>>>>>>>>> exists) >>>>>>>>>>> 2020-12-09T10:31:52+0000 error: [yyy.] zone event >>>>>>>>>>> 'backup/restore' >>>>>>>>>>> failed (not exists) >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> One of the keys is the ZSK of zone xxx and the oterh the KSKS of >>>>>>>>>>> zone >>>>>>>>>>> yyy. >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> root@signer-0:/#  keymgr xxx list human | grep >>>>>>>>>>> 1fb3900b2e5ac72d30f927016ea4546ca561a5da >>>>>>>>>>> >>>>>>>>>>> 1fb3900b2e5ac72d30f927016ea4546ca561a5da ksk=no  zsk=yes >>>>>>>>>>> tag=39969 >>>>>>>>>>> algorithm=7  size=1024 public-only=no  pre-active=0 >>>>>>>>>>> publish=-1M3D17h49m4s ready=0 active=-1M3D17h49m4s >>>>>>>>>>> retire-active=0 >>>>>>>>>>> retire=0 post-active=0 revoke=0 remove=0 >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> root@signer-0:/#  keymgr yyy list human | grep >>>>>>>>>>> 087cc573318e070befff1d9cbcf07e3b5cf5444d >>>>>>>>>>> >>>>>>>>>>> 087cc573318e070befff1d9cbcf07e3b5cf5444d ksk=yes zsk=no >>>>>>>>>>> tag=37419 >>>>>>>>>>> algorithm=7  size=2048 public-only=no  pre-active=0 >>>>>>>>>>> publish=-1M3D18h11m7s ready=-1M3D18h11m7s active=-26D12h49m4s >>>>>>>>>>> retire-active=0 retire=0 post-active=0 revoke=0 remove=0 >>>>>>>>>>> >>>>>>>>>>> Best regards, >>>>>>>>>>> Thomas >>>>>>>>>>> >>>>>>>>>>> On 09.12.20 11:15, libor.peltan wrote: >>>>>>>>>>>> Hi Thomas, >>>>>>>>>>>> >>>>>>>>>>>> could you please try if this issue is reproducible: if whenever >>>>>>>>>>>> you >>>>>>>>>>>> attempt the backup (to a fresh empty target directory), it fails >>>>>>>>>>>> with >>>>>>>>>>>> "not exists"? >>>>>>>>>>>> >>>>>>>>>>>> Could you please check if the keys that happen to make it to the >>>>>>>>>>>> backup >>>>>>>>>>>> belong to the same zone, or that it's one from each zone? (You >>>>>>>>>>>> light use >>>>>>>>>>>> `keymgr list` to check which key ID belongs to which zone.) >>>>>>>>>>>> >>>>>>>>>>>> Thanks, >>>>>>>>>>>> >>>>>>>>>>>> Libor >>>>>>>>>>>> >>>>>>>>>>>> Dne 08. 12. 20 v 21:36 Thomas napsal(a): >>>>>>>>>>>>> Hi Libor, >>>>>>>>>>>>> >>>>>>>>>>>>> sorry, I was really too unspecific. >>>>>>>>>>>>> >>>>>>>>>>>>> I'm hosting 2 zones. These 4 keys are on the production >>>>>>>>>>>>> machine: >>>>>>>>>>>>> >>>>>>>>>>>>> root@signer-0:/var/lib/knot/keys/keys# ls -alh >>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> -rw-r----- 1 knot knot 1,7K Nov  5 16:22 >>>>>>>>>>>>> 087cc573318e070befff1d9cbcf07e3b5cf5444d.pem >>>>>>>>>>>>> -rw-r----- 1 knot knot  916 Nov  5 16:44 >>>>>>>>>>>>> 1fb3900b2e5ac72d30f927016ea4546ca561a5da.pem >>>>>>>>>>>>> -rw-r----- 1 knot knot  916 Nov  5 16:22 >>>>>>>>>>>>> 6ebb8eb3ec2ddaf150119b4bc11b47dcec91621a.pem >>>>>>>>>>>>> -rw-r----- 1 knot knot 1,7K Nov  5 16:44 >>>>>>>>>>>>> d7e47e2909f4d5947d8fb8684cb79ed06feb4b0a.pem >>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> Performing a backup with the following command: >>>>>>>>>>>>> >>>>>>>>>>>>> # knotc zone-backup +backupdir /tmp/backup >>>>>>>>>>>>> >>>>>>>>>>>>> Backup directory after performing the backup shows: >>>>>>>>>>>>> >>>>>>>>>>>>> root@signer-0:/tmp/backup/keys/keys# ls -ahl >>>>>>>>>>>>> >>>>>>>>>>>>> -rw-r----- 1 knot knot 1,7K Dez  8 20:21 >>>>>>>>>>>>> 087cc573318e070befff1d9cbcf07e3b5cf5444d.pem >>>>>>>>>>>>> -rw-r----- 1 knot knot  916 Dez  8 20:21 >>>>>>>>>>>>> 1fb3900b2e5ac72d30f927016ea4546ca561a5da.pem >>>>>>>>>>>>> >>>>>>>>>>>>> 2 keys are missing. >>>>>>>>>>>>> >>>>>>>>>>>>> Hhmm ok, there is an error in the log: >>>>>>>>>>>>> >>>>>>>>>>>>> 2020-12-08T20:26:43+0000 info: control, received command >>>>>>>>>>>>> 'zone-backup' >>>>>>>>>>>>> 2020-12-08T20:26:43+0000 warning: [xxx.] zone backup failed >>>>>>>>>>>>> (not >>>>>>>>>>>>> exists) >>>>>>>>>>>>> 2020-12-08T20:26:43+0000 error: [xxx.] zone event >>>>>>>>>>>>> 'backup/restore' >>>>>>>>>>>>> failed (not exists) >>>>>>>>>>>>> 2020-12-08T20:26:43+0000 warning: [yyy.] zone backup failed >>>>>>>>>>>>> (not >>>>>>>>>>>>> exists) >>>>>>>>>>>>> 2020-12-08T20:26:43+0000 error: [yyy.] zone event >>>>>>>>>>>>> 'backup/restore' >>>>>>>>>>>>> failed (not exists) >>>>>>>>>>>>> >>>>>>>>>>>>> I'm using the latest knot version. >>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> Best regards, >>>>>>>>>>>>> >>>>>>>>>>>>> Thomas >>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> Am 08.12.20 um 16:56 schrieb libor.peltan: >>>>>>>>>>>>>> Hi Thomas, >>>>>>>>>>>>>> >>>>>>>>>>>>>> could you be more specific about "half of private keys were >>>>>>>>>>>>>> in the >>>>>>>>>>>>>> backup" ? How many were, how many weren't, and was there some >>>>>>>>>>>>>> obvious >>>>>>>>>>>>>> difference between them? >>>>>>>>>>>>>> >>>>>>>>>>>>>> Could you share the log snippets covering the backup and the >>>>>>>>>>>>>> restore >>>>>>>>>>>>>> procedures? >>>>>>>>>>>>>> >>>>>>>>>>>>>> Thanks, >>>>>>>>>>>>>> >>>>>>>>>>>>>> Libor >>>>>>>>>>>>>> >>>>>>>>>>>>>> Dne 08. 12. 20 v 16:48 Thomas E. napsal(a): >>>>>>>>>>>>>>> Hi (again), >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> I was trying to backup and restore a server with the new >>>>>>>>>>>>>>> knotc >>>>>>>>>>>>>>> zone-backup/restore command. >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> I recognized that only half of the private keys were in the >>>>>>>>>>>>>>> backup, >>>>>>>>>>>>>>> which leads to an error: >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> 2020-12-08T14:44:00+0100 error: [xxx.] DNSSEC, failed to load >>>>>>>>>>>>>>> private >>>>>>>>>>>>>>> keys (not exists) >>>>>>>>>>>>>>> 2020-12-08T14:44:00+0100 error: [xxx.] DNSSEC, failed to load >>>>>>>>>>>>>>> keys >>>>>>>>>>>>>>> (not >>>>>>>>>>>>>>> exists) >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> Shouldn't the backup contain all private keys? >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> Thanks, >>>>>>>>>>>>>>> Thomas >