[Opendnssec-user] kaspConnect() causes ods-enforcer brittleness

[Havard Eidnes]

> the ods-enforcer daemon loops, periodically looking for things
> which need to be done / scheduled.  Inside its service loop it
> has this piece of code:
>
>         log_msg(config, LOG_INFO, "Connecting to Database...");
>         kaspConnect(config, &dbhandle);
>
> followed by misleadingly-indented code (that's a minor issue).
> 
> However...  What happens if an administrator just happens to run
> "ods-ksmutil key list ..." at exactly that time when the enforcer
> wants to connect to the database?  This is what the log can tell:
>
> Dec  8 08:32:43 hugin ods-enforcerd: Connecting to Database...
> Dec  8 08:32:43 hugin ods-enforcerd: ERROR: error executing SQL - database is locked
>
> and this time it looks like ods-enforcerd really means that this
> is an error, because kaspConnect() doesn't return an error but
> does an exit() if connecting to the database fails:

Another variant of this problem of database locking just happened
to me.  On the hourly run, the enforcer logged:

Mar 18 07:30:03 hugin ods-enforcerd: HSM connection open.
Mar 18 07:30:03 hugin ods-enforcerd: Reading config "/usr/pkg/etc/opendnssec/conf.xml"
Mar 18 07:30:03 hugin ods-enforcerd: Reading config schema "/usr/pkg/share/opendnssec/conf.rng"
Mar 18 07:30:03 hugin ods-enforcerd: Communication Interval: 3600
Mar 18 07:30:03 hugin ods-enforcerd: No DS Submit command supplied
Mar 18 07:30:03 hugin ods-enforcerd: SQLite database set to: /var/db/opendnssec/kasp.db
Mar 18 07:30:03 hugin ods-enforcerd: Log User set to: local0
Mar 18 07:30:03 hugin ods-enforcerd: Switched log facility to: local0
Mar 18 07:30:03 hugin ods-enforcerd: Connecting to Database...
Mar 18 07:30:03 hugin ods-enforcerd: Policy default found.
Mar 18 07:30:03 hugin ods-enforcerd: Key sharing is Off.
Mar 18 07:30:03 hugin ods-enforcerd: 369 zone(s) found on policy "default" 
Mar 18 07:30:04 hugin ods-enforcerd: Predict we need 369 KSKs
Mar 18 07:30:04 hugin ods-enforcerd: Have 369 KSK keys in queue
Mar 18 07:30:04 hugin ods-enforcerd: Need 0 new KSK keys
Mar 18 07:30:04 hugin ods-enforcerd: No new KSKs need to be created. 
Mar 18 07:30:04 hugin ods-enforcerd: Predict we need 369 new ZSK keys
Mar 18 07:30:04 hugin ods-enforcerd: Have 369 ZSK keys in queue
Mar 18 07:30:04 hugin ods-enforcerd: Need 0 new ZSK keys
Mar 18 07:30:04 hugin ods-enforcerd: No new ZSKs need to be created. 
Mar 18 07:30:04 hugin ods-enforcerd: Purging keys...
Mar 18 07:30:04 hugin ods-enforcerd: zonelist filename set to /usr/pkg/etc/opendnssec/zonelist.xml.
Mar 18 07:30:04 hugin ods-enforcerd: Zone 156.193.in-addr.arpa found.
Mar 18 07:30:04 hugin ods-enforcerd: Policy for 156.193.in-addr.arpa set to default.
Mar 18 07:30:04 hugin ods-enforcerd: Config will be output to /var/opendnssec/signconf/156.193.in-addr.arpa.xml.
Mar 18 07:30:04 hugin ods-enforcerd: No change to: /var/opendnssec/signconf/156.193.in-addr.arpa.xml
Mar 18 07:30:04 hugin ods-enforcerd: Zone 157.193.in-addr.arpa found.
Mar 18 07:30:04 hugin ods-enforcerd: Policy for 157.193.in-addr.arpa set to default.
Mar 18 07:30:04 hugin ods-enforcerd: Config will be output to /var/opendnssec/signconf/157.193.in-addr.arpa.xml.
Mar 18 07:30:04 hugin ods-enforcerd: ERROR: error executing SQL - database is locked
Mar 18 07:30:04 hugin ods-enforcerd: No change to: /var/opendnssec/signconf/157.193.in-addr.arpa.xml

and then subseqently apparently for every zone:

Mar 18 07:30:04 hugin ods-enforcerd: Zone 91.78.in-addr.arpa found.
Mar 18 07:30:04 hugin ods-enforcerd: Policy for 91.78.in-addr.arpa set to default.
Mar 18 07:30:04 hugin ods-enforcerd: Config will be output to /var/opendnssec/signconf/91.78.in-addr.arpa.xml.
Mar 18 07:30:04 hugin ods-enforcerd: ERROR: error executing SQL - cannot start a transaction within a transaction
Mar 18 07:30:04 hugin ods-enforcerd: ERROR: database operation failed - cannot start a transaction within a transaction
Mar 18 07:30:04 hugin ods-enforcerd: KsmRequestKeys returned: 71691
Mar 18 07:30:04 hugin ods-enforcerd: Signconf not written for 91.78.in-addr.arpa

and then on the next hourly run it appears to have stumbled in
its own feet:

Mar 18 08:32:11 hugin ods-enforcerd: HSM connection open.
Mar 18 08:32:11 hugin ods-enforcerd: Reading config "/usr/pkg/etc/opendnssec/con
f.xml"
Mar 18 08:32:11 hugin ods-enforcerd: Reading config schema "/usr/pkg/share/opend
nssec/conf.rng"
Mar 18 08:32:11 hugin ods-enforcerd: Communication Interval: 3600
Mar 18 08:32:11 hugin ods-enforcerd: No DS Submit command supplied
Mar 18 08:32:11 hugin ods-enforcerd: SQLite database set to: /var/db/opendnssec/
kasp.db
Mar 18 08:32:11 hugin ods-enforcerd: Log User set to: local0
Mar 18 08:32:11 hugin ods-enforcerd: Switched log facility to: local0
Mar 18 08:32:11 hugin ods-enforcerd: Connecting to Database...
Mar 18 08:32:11 hugin ods-enforcerd: ERROR: error executing SQL - database is lo
cked

which is an instance of the problem quoted above, and which will
cause the enforcer to exit(-1).

I suspect once again that what caused this problem was that one
of my scripts which runs periodically e.g. to list all the zones
handled by OpenDNSSEC via "ods-ksmutil zone list" ran at about
the same time, causing the initial problem, because the script
which ran from cron produced this output, submitted at 07:31:00:

'ods-ksmutil zone list' failed, retrying
'ods-ksmutil zone list' failed, retrying
ERROR: error executing SQL - database is locked
'ods-ksmutil zone list' failed, retrying
ERROR: error executing SQL - database is locked
'ods-ksmutil zone list' failed, retrying
ERROR: error executing SQL - database is locked
'ods-ksmutil zone list' failed, retrying
ERROR: error executing SQL - database is locked
'ods-ksmutil zone list' failed, giving up

I'm not sure what caused the first ods-ksmutil failure in this
script, there's apparently no error message attached in the above
output, although the "sh -x" output from the script lists all 6
identical error messages.

Just restarting the enforcer appears to at least temporarily have
restored my OpenDNSSEC installation to working order.

Regards,

- Håvard