[Opendnssec-user] manual key rollover results in "1970-01-01

[Dennis Baaten]

In order to test if the migration from ODS 1.4 to ODS 2.1 was successful, I
decided to manually roll over the keys from a domain that I'm not actively
using anymore. I executed the following commands:



ods-enforcer key rollover -z dennisbaaten.com -t KSK

ods-enforcer key rollover -z dennisbaaten.com -t ZSK



After this, the key list shows the following:

Zone: Keytype: State: Date of next transition:

dennisbaaten.com ZSK retire 1970-01-01 01:00:00

dennisbaaten.com ZSK active 1970-01-01 01:00:00

dennisbaaten.com KSK active 1970-01-01 01:00:00

dennisbaaten.com ZSK publish 1970-01-01 01:00:00



I was expecting values in the 'date of next transition' field.

Does this mean trouble?



--

Dennis

[Yuri Schaeffer]

dennisbaaten.com                ZSK      retire    1970-01-01 01:00:00
I was expecting values in the ‘date of next transition’ field.
Does this mean trouble?

Not sure what happened exactly, but I'm looking in to this today.
It is not a reason to worry. These values are for the user only (to keep
the output compatible with 1.4), no operational decisions are based on
these timestamps.

//Yuri

[Yuri Schaeffer]

I was expecting values in the ‘date of next transition’ field.

I have looked at the code and it don't make much sense to me. Since you
did a rollover the timestamps should be set in the database. Even if
these values where not properly set I would expect to see "-" or "now"
instead of the timestamp.

It kind of looks like a call to localtime_r fails to convert a timestamp
from a time_t and I don't see why that would happen. Do you have other
issues on that machine regarding time? localtime_r will do some trickery
with timezones. Is that set correctly? Does timedatectl output something
strange?

//Yuri

[Dennis Baaten]

Post by Yuri Schaeffer
It kind of looks like a call to localtime_r fails to convert a timestamp

from a time_t and I don't see why that would happen. Do you have other
issues on that machine regarding time? localtime_r will do some trickery
with timezones. Is that set correctly? Does timedatectl output something
strange?

No other issues with the time. The output of timedatectl looks fine to me:

Local time: Wed 2017-11-08 15:27:14 CET
Universal time: Wed 2017-11-08 14:27:14 UTC
RTC time: Wed 2017-11-08 14:27:14
Time zone: Europe/Amsterdam (CET, +0100)
Network time on: yes
NTP synchronized: yes
RTC in local TZ: no

In an attempt to locate anomalies in my database, the following value is
different (domain "dennisbaaten.com" in the table "zone"):
nextChange: "0"

Not sure if this is related to this issue, but other domains have this value
set to a specific unix time stamp.

--
Dennis

[Yuri Schaeffer]

Post by Dennis Baaten
In an attempt to locate anomalies in my database, the following value is
nextChange: "0"

Ah. That explains some of it. I discovered a bug that causes this value
not to be written some time. (and for a couple more timestamps that are
also for display only) I'll fix that in a next release.

//Yuri

[Casper Gielen]

Post by Yuri Schaeffer

Post by Dennis Baaten
In an attempt to locate anomalies in my database, the following value is
nextChange: "0"

Ah. That explains some of it. I discovered a bug that causes this value
not to be written some time. (and for a couple more timestamps that are
also for display only) I'll fix that in a next release.

Dennis and I seem to be working in parallel. I just ran into this on my
test system.

I have one zone that has the same problem (1970-01-01 01:00:00) and also
nextChange = 0. (I guess that's the same value). It does happen to be
the zone that I use for most of my testing.


***@metagross:~# ods-enforcer key list --zone scpdata.org
Keys:
Zone: Keytype: State: Date of next transition:
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org ZSK retire 1970-01-01 01:00:00
scpdata.org ZSK retire 1970-01-01 01:00:00
scpdata.org ZSK active 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK ready waiting for ds-seen
key list completed in 1 seconds.


The large number of KSKs is due to testing. This zone uses fairly
aggressive KASP timings to speed up testing.

Anything I can do to help?

[Dennis Baaten]

When I look at the ods-enforcer output for my other domains, I notice that
most of the domains all have the same "Date of next transition". This date
seems to be equal to the exact moment I finished the migration to ODS 2.x
(using ods-migrate).

ZSK retire 2017-11-04 10:47:37
ZSK retire 2017-11-04 10:47:37
ZSK retire 2017-11-04 10:47:37
ZSK retire 2017-11-04 10:47:37
ZSK active 2017-11-04 10:47:37
ZSK active 2017-11-04 10:47:37
ZSK active 2017-11-04 10:47:37
ZSK active 2017-11-04 10:47:37
KSK active 2017-11-04 10:47:37
KSK active 2017-11-04 10:47:37
KSK active 2017-11-04 10:47:37
KSK active 2017-11-04 10:47:37
ZSK publish 2017-11-04 10:47:37
ZSK publish 2017-11-04 10:47:37
ZSK publish 2017-11-04 10:47:37
ZSK publish 2017-11-04 10:47:37

I find it also strange that these dates are all in the past, and nothing
seems to be happening. It gives me the feeling that ODS is not working.

--
Dennis

[Dennis Baaten]

I discovered a problem, and this might get me closer to a solution. I'm running Debian stable (stretch) and installed opendnssec from Debian testing (buster). I did this with the command "apt-get install opendnssec/testing", but this command installs opendnssec from testing (2.1.3 release) and gets it's dependencies from stable (2.0 release) including opendnssec-common which contains older versions of ods-signer and ods-enforcer (from the 2.0 release). In order to correct this I ran "apt-get -t testing install opendnssec-common", which installs dependencies from testing as well. So now all application files are from the 2.1.3 release.

The 1970 is gone.

***@traxotic [/var/lib/opendnssec/signconf]$ ods-enforcer key list --verbose | grep dennisbaaten
key list completed in 0 seconds.
dennisbaaten.com ZSK retire 2017-11-14 14:36:34 2048 8 ce3507796d7c176695bbfdc18f100fc6 SoftHSM 52924
dennisbaaten.com ZSK active 2017-11-14 14:36:34 2048 8 49bad7794a2e2c4d5f44755f33317982 SoftHSM 11619
dennisbaaten.com KSK active 2017-11-14 14:36:34 4096 8 f82e46fa26d4772c3b09db259aa41a30 SoftHSM 59792
dennisbaaten.com ZSK retire 2017-11-14 14:36:34 2048 8 75602642359504fa4d1decc0d7ab37e4 SoftHSM 40563
dennisbaaten.com KSK publish 2017-11-14 14:36:34 4096 8 27384557fb5980c2b8fff0139e0d76e9 SoftHSM 32179
dennisbaaten.com ZSK publish 2017-11-14 14:36:34 2048 8 925276e53f3ac23420b34ed5f24d4892 SoftHSM 58128

and there seems to be something in the queue:

***@traxotic [/var/lib/opendnssec/signconf]$ ods-enforcer queue
There is 1 task scheduled.
It is now Mon Nov 13 14:15:36 2017 (1510578936 seconds since epoch)
Next task scheduled Mon Nov 13 14:16:06 2017 (1510578966 seconds since epoch)
On Mon Nov 13 14:16:06 2017 I will [enforce] next zone
queue completed in 0 seconds.

However;
The DB 2006 error in syslog persists. Not sure if this is causing troubles at this moment.
The signconf file is not updated after ods-enforcer enforce (timestamp still the same).
The signed zone files are also not updated (same timestamp).

My initial guess is that tomorrow at the "Date of next transition" the rollovers will actually take place. If not, I will report back to the mailinglist.

--
Dennis

[Yuri Schaeffer]

Post by Dennis Baaten
There is 1 task scheduled.
It is now Mon Nov 13 14:15:36 2017 (1510578936 seconds since epoch)
Next task scheduled Mon Nov 13 14:16:06 2017 (1510578966 seconds since epoch)
On Mon Nov 13 14:16:06 2017 I will [enforce] next zone
queue completed in 0 seconds.

Based on this I believe you are still running a 2.0/2.1 hybrid. If you
where really on 2.1.3 I would expect the output:

"On Mon Nov 13 14:16:06 2017 I will enforce zone dennisbaaten.com"

Post by Dennis Baaten
However;
The DB 2006 error in syslog persists. Not sure if this is causing troubles at this moment.

Yes this is absolutely critical. You must sort out your database issues
first. Without proper access to the database the Enforcer won't work
correctly.

Post by Dennis Baaten
My initial guess is that tomorrow at the "Date of next transition" the rollovers will actually take place. If not, I will report back to the mailinglist.

Please very all your packages and binaries running are of the correct
and same version. Also make sure the enforcer has rights to update the
database. Check the timeout settings of your database /etc/mysql/my.cnf

//Yuri

[Dennis Baaten]

You are right. I still did have some old packages installed. I checked them all manually and now have the following versions installed.

***@traxotic [/var/lib/opendnssec/signconf]$ dpkg-query -l | grep opendnssec
ii opendnssec 1:2.1.3-0.2 all dependency package to install full OpenDNSSEC suite
ii opendnssec-common 1:2.1.3-0.2 all common configuration files for OpenDNSSEC suite
ii opendnssec-enforcer 1:2.1.3-0.2 all tool to prepare DNSSEC keys (common package)
ii opendnssec-enforcer-mysql 1:2.1.3-0.2 amd64 tool to prepare DNSSEC keys (MySQL backend)
ii opendnssec-signer 1:2.1.3-0.2 amd64 daemon to sign DNS zone files periodically
***@traxotic [/var/lib/opendnssec/signconf]$ dpkg-query -l | grep softhsm
ii libsofthsm2 2.2.0-3.1 amd64 cryptographic store accessible through a PKCS #11
ii softhsm 2.2.0-3.1 all cryptographic store accessible through a PKCS #11 (dummy)
ii softhsm2 2.2.0-3.1 amd64 cryptographic store accessible through a PKCS #11
ii softhsm2-common 2.2.0-3.1 amd64 cryptographic store accessible through a PKCS #11

The 2006 DB error is now gone.
The signconf files have been updated.
The zone files have been updated.
The queue actually reports 7 tasks, including: "On Tue Nov 14 14:36:34 2017 I will enforce zone dennisbaaten.com"

I'm quite optimistic at this moment. Output of commands seems logical again.

[Yuri Schaeffer]

Hi Casper,

Post by Casper Gielen
I have one zone that has the same problem (1970-01-01 01:00:00) and also
nextChange = 0. (I guess that's the same value). It does happen to be
the zone that I use for most of my testing.
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org ZSK retire 1970-01-01 01:00:00
scpdata.org ZSK retire 1970-01-01 01:00:00
scpdata.org ZSK active 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK retire 1970-01-01 01:00:00
scpdata.org KSK ready waiting for ds-seen
key list completed in 1 seconds.
The large number of KSKs is due to testing. This zone uses fairly
aggressive KASP timings to speed up testing.
Anything I can do to help?

Is this a KASP with automatic or manual rolling KSK's? If it is manual
there is nothing to do ever (nothing needs to be scheduled) since it is
waiting for user input.

Therefore These values are never updated (due to the aforementioned
bug). But if we really want to know if opendnssec is working correctly
it is necessary to look at its output. These timestamps are display only.

Please take a look at the signconf file it produces for this zone and
the signed zonefile the signer produces and make sure the correct keys
are being used.

//Yuri

[Dennis Baaten]

When running 'ods-enforcer enforce' the queue remains empty and the signconf remains unchanged (file date: Nov 3 11:13).

Syslog states the following. Notice the "DB prepare Err 2006"

Nov 13 12:37:34 traxotic ods-enforcerd: [scheduler] SIGALRM received
Nov 13 12:37:34 traxotic ods-enforcerd: [worker[4]]: report for duty
Nov 13 12:37:34 traxotic ods-enforcerd: [scheduler] no alarm set
Nov 13 12:37:34 traxotic ods-enforcerd: [worker[4]] start working
Nov 13 12:37:34 traxotic ods-enforcerd: [worker[4]]: perform task [enforce] for next zone
Nov 13 12:37:34 traxotic ods-enforcerd: SELECT zone.id, zone.rev, zone.policyId, zone.name, zone.signconfNeedsWriting, zone.signconfPath, zone.nextChange, zone.ttlEndDs, zone.ttlEndDk, zone.ttlEndRs, zone.rollKskNow, zone.rollZskNow, zone.rollCskNow, zone.inputAdapterType, zone.inputAdapterUri, zone.outputAdapterType, zone.outputAdapterUri, zone.nextKskRoll, zone.nextZskRoll, zone.nextCskRoll FROM zone
Nov 13 12:37:34 traxotic ods-enforcerd: DB prepare SQL SELECT zone.id, zone.rev, zone.policyId, zone.name, zone.signconfNeedsWriting, zone.signconfPath, zone.nextChange, zone.ttlEndDs, zone.ttlEndDk, zone.ttlEndRs, zone.rollKskNow, zone.rollZskNow, zone.rollCskNow, zone.inputAdapterType, zone.inputAdapterUri, zone.outputAdapterType, zone.outputAdapterUri, zone.nextKskRoll, zone.nextZskRoll, zone.nextCskRoll FROM zone
Nov 13 12:37:34 traxotic ods-enforcerd: DB prepare Err 2006: MySQL server has gone away
Nov 13 12:37:34 traxotic ods-enforcerd: [enforce_task] zonelist NULL
Nov 13 12:37:34 traxotic ods-enforcerd: [worker[4]] finished working
Nov 13 12:37:34 traxotic ods-enforcerd: [worker[4]]: report for duty
Nov 13 12:37:48 traxotic ods-enforcerd: [cmdhandler] 2 clients in progress...
Nov 13 12:37:48 traxotic ods-enforcerd: [cmdhandler] accept client 5
Nov 13 12:37:48 traxotic ods-enforcerd: received command queue[5]
Nov 13 12:37:48 traxotic ods-enforcerd: [cmdhandler] queue command
Nov 13 12:37:48 traxotic ods-enforcerd: [queue_cmd] list tasks command
Nov 13 12:37:48 traxotic ods-enforcerd: [cmdhandler] done handling command queue[5]

After the migration, I did several restarts, because I ran into some permission issues (https://lists.opendnssec.org/pipermail/opendnssec-user/2017-November/004140.html).

--
Dennis