[hsm] sign init: Unknown error, after idle

Errors and failure to sign zone after about an hour of idling.

Zone is supplied to opendnssec via AXFR (notify). On initial setup and multiple times
after, zone transfer and signing work fine. However, if opendnssec is left idling for about an hour,
next signing fails:
...
Jan 18 12:00:02 argo ods-signerd: [hsm] sign RRset[6] with key eaa1d22a5e0ec462e30cd2b98044b56c tag 194
Jan 18 12:00:02 argo ods-signerd: [hsm] sign init: Unknown error
..
Jan 18 12:00:02 argo ods-signerd: [worker[1]] somebody poked me, check completed jobs 1679 appointed, 1678 completed, 1 failed
Jan 18 12:00:02 argo ods-signerd: [worker[1]] sign zone lt failed: 1 of 1679 signatures failed
Jan 18 12:00:02 argo ods-signerd: [worker[1]] backoff task [read] for zone lt with 60 seconds
...

The signing is requested via NOTIFY and zone is transferred by opendnssec via AXFR in all cases,
SOA/Serial in kasp.xml is set to keep (zone generator updates serial).
Errors, and failure to sign zone can be fixed by restarting signed/enforcer (if not restarted, it fails
to sign zone during next tries too).

More output from logs:
—
Jan 18 11:40:42 argo ods-enforcerd: Disconnecting from Database...
Jan 18 11:40:42 argo ods-enforcerd: Sleeping for 3600 seconds.
Jan 18 12:00:02 argo ods-signerd: [cmdhandler] 1 clients in progress...
Jan 18 12:00:02 argo ods-signerd: [cmdhandler] accept client 6
Jan 18 12:00:02 argo ods-signerd: [cmdhandler] received command sign lt[7]
Jan 18 12:00:02 argo ods-signerd: [cmdhandler] sign zone command
Jan 18 12:00:02 argo ods-signerd: [scheduler] unschedule task [sign] for zone lt
Jan 18 12:00:02 argo ods-signerd: [cmdhandler] reschedule task for zone lt
Jan 18 12:00:02 argo ods-signerd: [scheduler] schedule task [read] for zone lt
Jan 18 12:00:02 argo ods-signerd: [cmdhandler] zone lt scheduled for immediate re-sign
Jan 18 12:00:02 argo ods-signerd: [engine] wake up workers
Jan 18 12:00:02 argo ods-signerd: [worker[1]] wake up
Jan 18 12:00:02 argo ods-signerd: [cmdhandler] done handling command sign lt[7]
Jan 18 12:00:02 argo ods-signerd: [worker[1]] report for duty
Jan 18 12:00:02 argo ods-signerd: [scheduler] pop task for zone lt
Jan 18 12:00:02 argo ods-signerd: [scheduler] unschedule task [read] for zone lt
Jan 18 12:00:02 argo ods-signerd: [worker[1]] start working on zone lt
Jan 18 12:00:02 argo ods-signerd: [worker[1]] perform task [read] for zone lt at 1326880802
Jan 18 12:00:02 argo ods-signerd: [worker[1]] read zone lt
Jan 18 12:00:02 argo ods-signerd: [tools] fetch zone lt
Jan 18 12:00:02 argo ods-signerd: [adapter] read zone lt from file input adapter /var/lib/opendnssec/unsigned/db.lt.unsigned
Jan 18 12:00:02 argo ods-signerd: [file] open file file=/var/lib/opendnssec/unsigned/db.lt.unsigned mode=reading
Jan 18 12:00:02 argo ods-signerd: [zone] zone lt set SOA TTL to 7200
Jan 18 12:00:02 argo ods-signerd: [zone] zone lt set SOA MINIMUM to 900
Jan 18 12:00:02 argo ods-signerd: [tools] commit updates for zone lt
Jan 18 12:00:02 argo ods-signerd: [worker[1]] nsecify zone lt
Jan 18 12:00:02 argo ods-signerd: [worker[1]] sign zone lt
Jan 18 12:00:02 argo ods-signerd: [data] update serial: in=1326880800 internal=1326877200 out=1326877200 now=1326880802
Jan 18 12:00:02 argo ods-signerd: [data] update serial: 1326877200 + 3600 = 1326880800
Jan 18 12:00:02 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:00:02 argo ods-signerd: [rrset] signature validity 583039 in range [522000 - 694800]
Jan 18 12:00:02 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:00:02 argo ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Jan 18 12:00:02 argo ods-signerd: [rrset] drop signatures for RRset[6]
Jan 18 12:00:02 argo ods-signerd: [rrset] signature validity 534377 in range [522000 - 694800]
Jan 18 12:00:02 argo ods-signerd: [hsm] sign RRset[6] with key eaa1d22a5e0ec462e30cd2b98044b56c tag 194
Jan 18 12:00:02 argo ods-signerd: [hsm] sign init: Unknown error
Jan 18 12:00:02 argo ods-signerd: [rrset] unable to sign RRset[6]: error creating RRSIG RR
Jan 18 12:00:02 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:00:02 argo ods-signerd: [rrset] signature validity 544774 in range [522000 - 694800]
....
Jan 18 12:00:07 argo ods-signerd: [rrset] signature validity 618661 in range [522000 - 694800]
Jan 18 12:00:07 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:00:07 argo ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Jan 18 12:00:07 argo ods-signerd: [rrset] signature validity 602586 in range [522000 - 694800]
Jan 18 12:00:07 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:00:07 argo ods-signerd: [rrset] signature validity 603492 in range [522000 - 694800]
Jan 18 12:00:07 argo ods-signerd: [drudger[1]] report for duty
....
Jan 18 12:00:07 argo ods-signerd: [rrset] signature validity 609868 in range [522000 - 694800]
Jan 18 12:00:07 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:00:07 argo ods-signerd: [rrset] signature validity 686183 in range [522000 - 694800]
Jan 18 12:00:07 argo ods-signerd: [drudger[1]] wake up chief[1], work is done
Jan 18 12:00:07 argo ods-signerd: [worker[1]] wake up
Jan 18 12:00:07 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:00:07 argo ods-signerd: [worker[1]] somebody poked me, check completed jobs 1679 appointed, 1678 completed, 1 failed
Jan 18 12:00:07 argo ods-signerd: [worker[1]] sign zone lt failed: 1 of 1679 signatures failed
Jan 18 12:00:07 argo ods-signerd: [worker[1]] backoff task [read] for zone lt with 120 seconds
Jan 18 12:00:07 argo ods-signerd: [worker[1]] finished working on zone lt
Jan 18 12:00:07 argo ods-signerd: [scheduler] schedule task [read] for zone lt
Jan 18 12:00:07 argo ods-signerd: [task] On Wed Jan 18 12:02:07 2012 I will [read] zone lt
Jan 18 12:00:07 argo ods-signerd: [worker[1]] report for duty
Jan 18 12:00:07 argo ods-signerd: [worker[1]] nothing to do
Jan 18 12:00:07 argo ods-signerd: [drudger[1]] nothing to do
Jan 18 12:02:07 argo ods-signerd: [worker[1]] report for duty

Here goes next NOTIFY without opendnssec restart:

Jan 18 12:00:07 argo ods-signerd: [drudger[1]] nothing to do
Jan 18 12:02:07 argo ods-signerd: [worker[1]] report for duty
Jan 18 12:02:07 argo ods-signerd: [scheduler] pop task for zone lt
Jan 18 12:02:07 argo ods-signerd: [scheduler] unschedule task [read] for zone lt
Jan 18 12:02:07 argo ods-signerd: [worker[1]] start working on zone lt
Jan 18 12:02:07 argo ods-signerd: [worker[1]] perform task [read] for zone lt at 1326880927
Jan 18 12:02:07 argo ods-signerd: [worker[1]] read zone lt
Jan 18 12:02:07 argo ods-signerd: [tools] fetch zone lt
Jan 18 12:02:07 argo ods-signerd: [adapter] read zone lt from file input adapter /var/lib/opendnssec/unsigned/db.lt.unsigned
Jan 18 12:02:07 argo ods-signerd: [file] open file file=/var/lib/opendnssec/unsigned/db.lt.unsigned mode=reading
Jan 18 12:02:07 argo ods-signerd: [zone] zone lt set SOA TTL to 7200
Jan 18 12:02:07 argo ods-signerd: [zone] zone lt set SOA MINIMUM to 900
Jan 18 12:02:07 argo ods-signerd: [tools] commit updates for zone lt
Jan 18 12:02:07 argo ods-signerd: [worker[1]] nsecify zone lt
Jan 18 12:02:07 argo ods-signerd: [worker[1]] sign zone lt
Jan 18 12:02:07 argo ods-signerd: [data] update serial: in=1326880801 internal=1326877200 out=1326877200 now=1326880927
Jan 18 12:02:07 argo ods-signerd: [data] update serial: 1326877200 + 3601 = 1326880801
Jan 18 12:02:07 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:02:07 argo ods-signerd: [rrset] signature validity 643032 in range [522000 - 694800]
Jan 18 12:02:07 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:02:07 argo ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Jan 18 12:02:07 argo ods-signerd: [rrset] drop signatures for RRset[6]
Jan 18 12:02:07 argo ods-signerd: [rrset] signature validity 547675 in range [522000 - 694800]
Jan 18 12:02:07 argo ods-signerd: [hsm] sign RRset[6] with key eaa1d22a5e0ec462e30cd2b98044b56c tag 194
Jan 18 12:02:07 argo ods-signerd: [hsm] sign init: CKR_SESSION_HANDLE_INVALID
Jan 18 12:02:07 argo ods-signerd: [rrset] unable to sign RRset[6]: error creating RRSIG RR
Jan 18 12:02:07 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:02:07 argo ods-signerd: [rrset] signature validity 558024 in range [522000 - 694800]
Jan 18 12:02:07 argo ods-signerd: [drudger[1]] report for duty
...
Jan 18 12:02:07 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:02:07 argo ods-signerd: [worker[1]] wait until drudgers are finished signing zone lt, 1679 signatures queued
Jan 18 12:02:07 argo ods-signerd: [rrset] signature validity 528819 in range [522000 - 694800]
Jan 18 12:02:07 argo ods-signerd: [drudger[1]] report for duty
....
Jan 18 12:02:07 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:02:07 argo ods-signerd: [drudger[1]] nothing to do
Jan 18 12:02:07 argo ods-signerd: [worker[1]] somebody poked me, check completed jobs 1679 appointed, 1678 completed, 1 failed
Jan 18 12:02:07 argo ods-signerd: [worker[1]] sign zone lt failed: 1 of 1679 signatures failed
Jan 18 12:02:07 argo ods-signerd: [worker[1]] backoff task [read] for zone lt with 240 seconds
Jan 18 12:02:07 argo ods-signerd: [worker[1]] finished working on zone lt
Jan 18 12:02:07 argo ods-signerd: [scheduler] schedule task [read] for zone lt
....

And after opendnssec restart and new NOTIFY (no files deleted from signed/unsigned or tmp directories, just restart):

Jan 18 12:02:51 argo ods-enforcerd: Received SIGTERM, exiting...
Jan 18 12:02:51 argo ods-enforcerd: all done! hsm_close result: 0
Jan 18 12:03:00 argo ods-signerd: [cmdhandler] done handling command verbosity 5[11]
Jan 18 12:03:00 argo ods-signerd: [parser] zone lt added
Jan 18 12:03:00 argo ods-signerd: [parser] no more zones
Jan 18 12:03:00 argo ods-signerd: [zonelist] merge two zone lists
Jan 18 12:03:00 argo ods-signerd: [zonelist] file /etc/opendnssec/zonelist.xml is modified since 2012-01-16 11:48:34
Jan 18 12:03:00 argo ods-signerd: [engine] signer started
Jan 18 12:03:00 argo ods-signerd: [file] open file file=lt.backup mode=reading
Jan 18 12:03:00 argo ods-signerd: [keys] add locator 2928e3319095e66eb5a8f6b10496fb00
Jan 18 12:03:00 argo ods-signerd: [keys] add locator eaa1d22a5e0ec462e30cd2b98044b56c
Jan 18 12:03:00 argo ods-signerd: [file] open file file=lt.inbound mode=reading
Jan 18 12:03:00 argo ods-signerd: [zone] zone lt set SOA TTL to 7200
Jan 18 12:03:00 argo ods-signerd: [zone] zone lt set SOA MINIMUM to 900
Jan 18 12:03:00 argo ods-enforcerd: HSM opened successfully.
Jan 18 12:03:00 argo ods-enforcerd: Reading config "/etc/opendnssec/conf.xml"
Jan 18 12:03:00 argo ods-enforcerd: Reading config schema "/usr/share/opendnssec/conf.rng"
Jan 18 12:03:00 argo ods-enforcerd: Communication Interval: 3600
Jan 18 12:03:00 argo ods-enforcerd: Rollover Notification Interval: 604800
Jan 18 12:03:00 argo ods-enforcerd: No DS Submit command supplied
Jan 18 12:03:00 argo ods-enforcerd: SQLite database set to: /var/lib/opendnssec/db/kasp.db
Jan 18 12:03:00 argo ods-enforcerd: Log User set to: local2
Jan 18 12:03:00 argo ods-enforcerd: Switched log facility to: local2
Jan 18 12:03:00 argo ods-enforcerd: Connecting to Database...
Jan 18 12:03:00 argo ods-enforcerd: Policy default found.
Jan 18 12:03:00 argo ods-enforcerd: zonelist filename set to /etc/opendnssec/zonelist.xml.
Jan 18 12:03:00 argo ods-enforcerd: Zone lt found.
Jan 18 12:03:00 argo ods-enforcerd: Policy for lt set to default.
Jan 18 12:03:00 argo ods-enforcerd: Config will be output to /etc/opendnssec/ltsignconf.xml.
Jan 18 12:03:00 argo ods-enforcerd: No change to: /etc/opendnssec/ltsignconf.xml
Jan 18 12:03:00 argo ods-enforcerd: Disconnecting from Database...
Jan 18 12:03:00 argo ods-enforcerd: Sleeping for 3600 seconds.
Jan 18 12:03:00 argo ods-signerd: [zone] zone lt set DNSKEY TTL to 7200
Jan 18 12:03:00 argo ods-signerd: [zone] zone lt set DNSKEY TTL to 7200
Jan 18 12:03:00 argo ods-signerd: [engine] set notify ns: /usr/sbin/rndc reload lt
Jan 18 12:03:00 argo ods-signerd: [scheduler] schedule task [sign] for zone lt
Jan 18 12:03:00 argo ods-signerd: [engine] recovered zone lt
Jan 18 12:03:00 argo ods-signerd: [engine] start workers
Jan 18 12:03:00 argo ods-signerd: [engine] start drudgers
Jan 18 12:03:00 argo ods-signerd: [worker[1]] report for duty
Jan 18 12:03:00 argo ods-signerd: [engine] taking a break
Jan 18 12:03:00 argo ods-signerd: [worker[1]] nothing to do
Jan 18 12:03:00 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:03:00 argo ods-signerd: [drudger[1]] nothing to do
Jan 18 12:03:20 argo ods-signerd: [cmdhandler] 1 clients in progress...
Jan 18 12:03:20 argo ods-signerd: [cmdhandler] accept client 6
Jan 18 12:03:20 argo ods-signerd: [cmdhandler] received command sign lt[7]
Jan 18 12:03:20 argo ods-signerd: [cmdhandler] sign zone command
Jan 18 12:03:20 argo ods-signerd: [scheduler] unschedule task [sign] for zone lt
Jan 18 12:03:20 argo ods-signerd: [cmdhandler] reschedule task for zone lt
Jan 18 12:03:20 argo ods-signerd: [scheduler] schedule task [read] for zone lt
Jan 18 12:03:20 argo ods-signerd: [cmdhandler] zone lt scheduled for immediate re-sign
Jan 18 12:03:20 argo ods-signerd: [engine] wake up workers
Jan 18 12:03:20 argo ods-signerd: [worker[1]] wake up
Jan 18 12:03:20 argo ods-signerd: [cmdhandler] done handling command sign lt[7]
Jan 18 12:03:20 argo ods-signerd: [worker[1]] report for duty
Jan 18 12:03:20 argo ods-signerd: [scheduler] pop task for zone lt
Jan 18 12:03:20 argo ods-signerd: [scheduler] unschedule task [read] for zone lt
Jan 18 12:03:20 argo ods-signerd: [worker[1]] start working on zone lt
Jan 18 12:03:20 argo ods-signerd: [worker[1]] perform task [read] for zone lt at 1326881000
Jan 18 12:03:20 argo ods-signerd: [worker[1]] read zone lt
Jan 18 12:03:20 argo ods-signerd: [tools] fetch zone lt
Jan 18 12:03:20 argo ods-signerd: [adapter] read zone lt from file input adapter /var/lib/opendnssec/unsigned/db.lt.unsigned
Jan 18 12:03:20 argo ods-signerd: [file] open file file=/var/lib/opendnssec/unsigned/db.lt.unsigned mode=reading
Jan 18 12:03:20 argo ods-signerd: [zone] zone lt set SOA TTL to 7200
Jan 18 12:03:20 argo ods-signerd: [zone] zone lt set SOA MINIMUM to 900
Jan 18 12:03:20 argo ods-signerd: [tools] commit updates for zone lt
Jan 18 12:03:20 argo ods-signerd: [worker[1]] nsecify zone lt
Jan 18 12:03:20 argo ods-signerd: [worker[1]] sign zone lt
Jan 18 12:03:20 argo ods-signerd: [data] update serial: in=1326881000 internal=1326877200 out=1326877200 now=1326881000
Jan 18 12:03:20 argo ods-signerd: [data] update serial: 1326877200 + 3800 = 1326881000
Jan 18 12:03:20 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:03:20 argo ods-signerd: [rrset] signature validity 606584 in range [522000 - 694800]
Jan 18 12:03:20 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:03:20 argo ods-signerd: [rrset] drop signatures for RRset[6]
Jan 18 12:03:20 argo ods-signerd: [rrset] signature validity 560087 in range [522000 - 694800]
Jan 18 12:03:20 argo ods-signerd: [hsm] sign RRset[6] with key eaa1d22a5e0ec462e30cd2b98044b56c tag 194
Jan 18 12:03:20 argo ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Jan 18 12:03:20 argo ods-signerd: [drudger[1]] report for duty
...
Jan 18 12:03:20 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:03:20 argo ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Jan 18 12:03:20 argo ods-signerd: [rrset] signature validity 643364 in range [522000 - 694800]
Jan 18 12:03:20 argo ods-signerd: [drudger[1]] report for duty
...
Jan 18 12:03:21 argo ods-signerd: [rrset] signature validity 561058 in range [522000 - 694800]
Jan 18 12:03:21 argo ods-signerd: [drudger[1]] wake up chief[1], work is done
Jan 18 12:03:21 argo ods-signerd: [worker[1]] wake up
Jan 18 12:03:21 argo ods-signerd: [drudger[1]] report for duty
Jan 18 12:03:21 argo ods-signerd: [worker[1]] somebody poked me, check completed jobs 1679 appointed, 1679 completed, 0 failed
Jan 18 12:03:21 argo ods-signerd: [worker[1]] sign zone lt ok: 1679 of 1679 signatures succeeded
Jan 18 12:03:21 argo ods-signerd: [worker[1]] audit zone lt
Jan 18 12:03:21 argo ods-signerd: [drudger[1]] nothing to do
Jan 18 12:03:21 argo ods-signerd: [file] open file file=lt.finalized mode=writing
Jan 18 12:03:21 argo ods-signerd: system call: /usr/bin/ods-auditor -c /etc/opendnssec/conf.xml -u /var/lib/opendnssec/tmp/lt.inbound -s /var/lib/opendnssec/tmp/lt.finalized -z lt > /dev/null
Jan 18 12:03:21 argo ods-auditor[11310]: Auditor started
Jan 18 12:03:21 argo ods-auditor[11310]: Auditor starting on lt
Jan 18 12:03:21 argo ods-auditor[11310]: Auditing lt zone : NSEC3 SIGNED
Jan 18 12:03:40 argo ods-auditor[11310]: Finished auditing lt zone
Jan 18 12:03:40 argo ods-signerd: [tools] audit passed for zone lt
Jan 18 12:03:40 argo ods-signerd: [worker[1]] write zone lt