Error while reading host reservations
Hi,
we are facing a problem reading the host reservations in Stork 0.19.0 with the kea premium hook host_cmds library (tested with compiled kea 1.8.2 and 1.9.11). Using the API, multiple hosts reservations were successfully added to a MySQL database backend. The Library is successfully loaded, the kea server is registered in stork and the agent is running, so everything looks fine until here. At the DHCP host reservation page in stork no reservations are displayed. At this time, an Error is logged in stork and kea, please have a look at the logs below. In both Kea versions they are looking the same and the error is reproducible.
Please let me know, if you need any additional informations, any help would be appreciated.
Kind regards, Fabian
Environment:
- Kea version: 1.8.2 / 1.9.11 with Stork 0.19.0
- OS: Ubuntu 18.04 Docker Container
- Which hooks where loaded in: libdhcp_host_cmds.so, libdhcp_stat_cmds.so, libdhcp_lease_cmds.so
Logs:
The reservation-add command logs looks like:
INFO COMMAND_RECEIVED Received command 'reservation-add'
INFO HOST_CMDS_RESERV_ADD reservation-add command successful (parameters: { "reservation": { "boot-file-name": "bootfile.efi", "hostname": "HOST1", "hw-address": "00:11:22:33:44:55", "ip-address": "192.168.10.100", "subnet-id": 10, "user-context": "{key': 'value'}" } })
INFO CTRL_AGENT_COMMAND_FORWARDED command reservation-add successfully forwarded to the service dhcp4
Kea Server:
ERROR HOOKS_CALLOUT_ERROR error returned by callout on hook $reservation_get_page registered by library with index 3 (callout address 0x7ff88302e410) (callout duration 18.124 ms)
Stork Server:
INFO[2021-09-03 07:38:44] eventcenter.go:117 event 'communication with <daemon id="12" name="dhcp4" appId="3" appType="kea"> of <app id="3" name="kea@172.17.0.3" type="kea" version="1.9.11"> failed'
ERRO[2021-09-03 07:38:44] host.go:87 error occurred while fetching hosts from app 3: error returned by Kea in response to reservation-get-page command
isc.org/stork/server/apps/kea.(*HostDetectionIterator).sendReservationGetPage
/tmp/build/backend/server/apps/kea/host.go:254
isc.org/stork/server/apps/kea.(*HostDetectionIterator).DetectHostsPageFromHostCmds
/tmp/build/backend/server/apps/kea/host.go:356
isc.org/stork/server/apps/kea.updateHostsFromHostCmds
/tmp/build/backend/server/apps/kea/host.go:536
isc.org/stork/server/apps/kea.(*HostsPuller).pullData
/tmp/build/backend/server/apps/kea/host.go:84
isc.org/stork/server/agentcomm.(*PeriodicPuller).pullerLoop
/tmp/build/backend/server/agentcomm/puller.go:169
runtime.goexit
/tmp/build/tools/1.15.5/go/src/runtime/asm_amd64.s:1374
problem with sending reservation-get-page command upon attempt to detect host reservations over the host_cmds hooks library
INFO[2021-09-03 07:38:44] host.go:100 completed pulling hosts from Kea apps: 0/1 succeeded
ERRO[2021-09-03 07:38:44] puller.go:172 errors were encountered while pulling data from apps: error returned by Kea in response to reservation-get-page command
isc.org/stork/server/apps/kea.(*HostDetectionIterator).sendReservationGetPage
/tmp/build/backend/server/apps/kea/host.go:254
isc.org/stork/server/apps/kea.(*HostDetectionIterator).DetectHostsPageFromHostCmds
/tmp/build/backend/server/apps/kea/host.go:356
isc.org/stork/server/apps/kea.updateHostsFromHostCmds
/tmp/build/backend/server/apps/kea/host.go:536
isc.org/stork/server/apps/kea.(*HostsPuller).pullData
/tmp/build/backend/server/apps/kea/host.go:84
isc.org/stork/server/agentcomm.(*PeriodicPuller).pullerLoop
/tmp/build/backend/server/agentcomm/puller.go:169
runtime.goexit
/tmp/build/tools/1.15.5/go/src/runtime/asm_amd64.s:1374
problem with sending reservation-get-page command upon attempt to detect host reservations over the host_cmds hooks library
INFO[2021-09-03 06:37:47] eventcenter.go:117 event 'communication with <daemon id="3" name="dhcp4" appId="1" appType="kea"> of <app id="1" name="kea@172.17.0.3" type="kea" version="1.8.2"> failed'
ERRO[2021-09-03 06:37:47] host.go:87 error occurred while fetching hosts from app 1: error returned by Kea in response to reservation-get-page command
isc.org/stork/server/apps/kea.(*HostDetectionIterator).sendReservationGetPage
/tmp/build/backend/server/apps/kea/host.go:254
isc.org/stork/server/apps/kea.(*HostDetectionIterator).DetectHostsPageFromHostCmds
/tmp/build/backend/server/apps/kea/host.go:356
isc.org/stork/server/apps/kea.updateHostsFromHostCmds
/tmp/build/backend/server/apps/kea/host.go:536
isc.org/stork/server/apps/kea.(*HostsPuller).pullData
/tmp/build/backend/server/apps/kea/host.go:84
isc.org/stork/server/agentcomm.(*PeriodicPuller).pullerLoop
/tmp/build/backend/server/agentcomm/puller.go:169
runtime.goexit
/tmp/build/tools/1.15.5/go/src/runtime/asm_amd64.s:1374
problem with sending reservation-get-page command upon attempt to detect host reservations over the host_cmds hooks library
INFO[2021-09-03 06:37:47] host.go:100 completed pulling hosts from Kea apps: 0/1 succeeded
ERRO[2021-09-03 06:37:47] puller.go:172 errors were encountered while pulling data from apps: error returned by Kea in response to reservation-get-page command
isc.org/stork/server/apps/kea.(*HostDetectionIterator).sendReservationGetPage
/tmp/build/backend/server/apps/kea/host.go:254
isc.org/stork/server/apps/kea.(*HostDetectionIterator).DetectHostsPageFromHostCmds
/tmp/build/backend/server/apps/kea/host.go:356
isc.org/stork/server/apps/kea.updateHostsFromHostCmds
/tmp/build/backend/server/apps/kea/host.go:536
isc.org/stork/server/apps/kea.(*HostsPuller).pullData
/tmp/build/backend/server/apps/kea/host.go:84
isc.org/stork/server/agentcomm.(*PeriodicPuller).pullerLoop
/tmp/build/backend/server/agentcomm/puller.go:169
runtime.goexit
/tmp/build/tools/1.15.5/go/src/runtime/asm_amd64.s:1374
problem with sending reservation-get-page command upon attempt to detect host reservations over the host_cmds hooks library
Edit: Here's a more verbose (debuglevel 99) output from the kea server:
WARN[2021-09-07 13:32:42] promkeaexporter.go:368 problem with connecting to dhcp daemon: unable to forward command to the dhcp6 service: No such file or directory. The server is likely to be offline
DEBUG DHCPSRV_TIMERMGR_RUN_TIMER_OPERATION running operation for timer: reclaim-expired-leases
DEBUG ALLOC_ENGINE_V4_LEASES_RECLAMATION_START starting reclamation of expired leases (limit = 100 leases or 250 milliseconds)
DEBUG DHCPSRV_MYSQL_GET_EXPIRED4 obtaining maximum 101 of expired IPv4 leases
DEBUG ALLOC_ENGINE_V4_LEASES_RECLAMATION_COMPLETE reclaimed 0 leases in 0.581 ms
DEBUG ALLOC_ENGINE_V4_NO_MORE_EXPIRED_LEASES all expired leases have been reclaimed
DEBUG DHCPSRV_TIMERMGR_START_TIMER starting timer: reclaim-expired-leases
DEBUG DHCPSRV_TIMERMGR_RUN_TIMER_OPERATION running operation for timer: flush-reclaimed-leases
DEBUG ALLOC_ENGINE_V4_RECLAIMED_LEASES_DELETE begin deletion of reclaimed leases expired more than 3600 seconds ago
DEBUG DHCPSRV_MYSQL_DELETE_EXPIRED_RECLAIMED4 deleting reclaimed IPv4 leases that expired more than 3600 seconds ago
DEBUG DHCPSRV_MYSQL_DELETED_EXPIRED_RECLAIMED deleted 0 reclaimed leases from the database
DEBUG ALLOC_ENGINE_V4_RECLAIMED_LEASES_DELETE_COMPLETE successfully deleted 0 expired-reclaimed leases
DEBUG DHCPSRV_TIMERMGR_START_TIMER starting timer: flush-reclaimed-leases
INFO COMMAND_RECEIVED Received command 'reservation-get-page'
DEBUG COMMAND_SOCKET_CONNECTION_OPENED Opened socket 23 for incoming command connection
DEBUG COMMAND_SOCKET_READ Received 128 bytes over command socket 23
INFO COMMAND_RECEIVED Received command 'reservation-get-page'
DEBUG HOOKS_CALLOUTS_BEGIN begin all callouts for hook $reservation_get_page
DEBUG HOOKS_CALLOUT_CALLED hooks library with index 3 has called a callout on hook $reservation_get_page that has address 0x7f176473c4a0 (callout duration: 4.296 ms)
DEBUG HOOKS_CALLOUTS_COMPLETE completed callouts for hook $reservation_get_page (total callouts duration: 4.296 ms)
DEBUG COMMAND_SOCKET_WRITE Sent response of 92 bytes (0 bytes left to send) over command socket 23
INFO CTRL_AGENT_COMMAND_FORWARDED command reservation-get-page successfully forwarded to the service dhcp4
DEBUG COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 23 for existing command connection
INFO[2021-09-07 13:32:50] agent.go:375 Compressing response from 96 B to 108 B, ratio 112%
INFO COMMAND_RECEIVED Received command 'stat-lease4-get'
DEBUG COMMAND_SOCKET_CONNECTION_OPENED Opened socket 23 for incoming command connection
DEBUG COMMAND_SOCKET_READ Received 56 bytes over command socket 23
INFO COMMAND_RECEIVED Received command 'stat-lease4-get'
DEBUG HOOKS_CALLOUTS_BEGIN begin all callouts for hook $stat_lease4_get
INFO STAT_CMDS_LEASE4_GET stat-lease4-get command successful, parameters: [all subnets] rows found: 1
DEBUG HOOKS_CALLOUT_CALLED hooks library with index 2 has called a callout on hook $stat_lease4_get that has address 0x7f17649600c0 (callout duration: 0.431 ms)
DEBUG HOOKS_CALLOUTS_COMPLETE completed callouts for hook $stat_lease4_get (total callouts duration: 0.431 ms)
INFO CTRL_AGENT_COMMAND_FORWARDED command stat-lease4-get successfully forwarded to the service dhcp4
DEBUG COMMAND_SOCKET_WRITE Sent response of 303 bytes (0 bytes left to send) over command socket 23
DEBUG COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 23 for existing command connection
INFO[2021-09-07 13:32:50] agent.go:375 Compressing response from 307 B to 212 B, ratio 69%
INFO COMMAND_RECEIVED Received command 'statistic-get'
DEBUG COMMAND_SOCKET_CONNECTION_OPENED Opened socket 23 for incoming command connection
DEBUG COMMAND_SOCKET_READ Received 96 bytes over command socket 23
INFO COMMAND_RECEIVED Received command 'statistic-get'
DEBUG COMMAND_SOCKET_WRITE Sent response of 90 bytes (0 bytes left to send) over command socket 23
DEBUG COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 23 for existing command connection
INFO CTRL_AGENT_COMMAND_FORWARDED command statistic-get successfully forwarded to the service dhcp4
INFO[2021-09-07 13:32:50] agent.go:375 Compressing response from 94 B to 110 B, ratio 117%
INFO COMMAND_RECEIVED Received command 'reservation-get-page'
DEBUG COMMAND_SOCKET_CONNECTION_OPENED Opened socket 23 for incoming command connection
DEBUG COMMAND_SOCKET_READ Received 129 bytes over command socket 23
INFO COMMAND_RECEIVED Received command 'reservation-get-page'
DEBUG HOOKS_CALLOUTS_BEGIN begin all callouts for hook $reservation_get_page
ERROR HOOKS_CALLOUT_ERROR error returned by callout on hook 3 registered by library with index $reservation_get_page (callout address 0x7f176473c4a0) (callout duration 15.274 ms)
DEBUG HOOKS_CALLOUTS_COMPLETE completed callouts for hook $reservation_get_page (total callouts duration: 15.274 ms)
INFO CTRL_AGENT_COMMAND_FORWARDED command reservation-get-page successfully forwarded to the service dhcp4
DEBUG COMMAND_SOCKET_WRITE Sent response of 657 bytes (0 bytes left to send) over command socket 23
DEBUG COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 23 for existing command connection
INFO[2021-09-07 13:32:50] agent.go:375 Compressing response from 661 B to 365 B, ratio 55%
INFO COMMAND_RECEIVED Received command 'statistic-get-all'
DEBUG COMMAND_SOCKET_CONNECTION_OPENED Opened socket 23 for incoming command connection
DEBUG COMMAND_SOCKET_READ Received 86 bytes over command socket 23
INFO COMMAND_RECEIVED Received command 'statistic-get-all'
DEBUG COMMAND_SOCKET_WRITE Sent response of 1759 bytes (0 bytes left to send) over command socket 23
DEBUG COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 23 for existing command connection
INFO CTRL_AGENT_COMMAND_FORWARDED command statistic-get-all successfully forwarded to the service dhcp4
WARN[2021-09-07 13:32:52] promkeaexporter.go:368 problem with connecting to dhcp daemon: unable to forward command to the dhcp6 service: No such file or directory. The server is likely to be offline
DEBUG DHCPSRV_TIMERMGR_RUN_TIMER_OPERATION running operation for timer: reclaim-expired-leases
DEBUG ALLOC_ENGINE_V4_LEASES_RECLAMATION_START starting reclamation of expired leases (limit = 100 leases or 250 milliseconds)
DEBUG DHCPSRV_MYSQL_GET_EXPIRED4 obtaining maximum 101 of expired IPv4 leases
DEBUG ALLOC_ENGINE_V4_LEASES_RECLAMATION_COMPLETE reclaimed 0 leases in 1.478 ms
DEBUG ALLOC_ENGINE_V4_NO_MORE_EXPIRED_LEASES all expired leases have been reclaimed
DEBUG DHCPSRV_TIMERMGR_START_TIMER starting timer: reclaim-expired-leases
INFO COMMAND_RECEIVED Received command 'version-get'
INFO[2021-09-07 13:32:59] agent.go:375 Compressing response from 116 B to 125 B, ratio 107%
INFO COMMAND_RECEIVED Received command 'config-get'
INFO[2021-09-07 13:32:59] agent.go:375 Compressing response from 683 B to 314 B, ratio 45%
INFO COMMAND_RECEIVED Received command 'version-get'
DEBUG COMMAND_SOCKET_CONNECTION_OPENED Opened socket 23 for incoming command connection
DEBUG COMMAND_SOCKET_READ Received 67 bytes over command socket 23
INFO COMMAND_RECEIVED Received command 'version-get'
DEBUG COMMAND_SOCKET_WRITE Sent response of 205 bytes (0 bytes left to send) over command socket 23
DEBUG COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 23 for existing command connection
INFO CTRL_AGENT_COMMAND_FORWARDED command version-get successfully forwarded to the service dhcp4
INFO[2021-09-07 13:32:59] agent.go:375 Compressing response from 482 B to 273 B, ratio 56%
INFO COMMAND_RECEIVED Received command 'status-get'
DEBUG COMMAND_SOCKET_CONNECTION_OPENED Opened socket 23 for incoming command connection
DEBUG COMMAND_SOCKET_READ Received 60 bytes over command socket 23
INFO COMMAND_RECEIVED Received command 'status-get'
DEBUG COMMAND_SOCKET_WRITE Sent response of 107 bytes (0 bytes left to send) over command socket 23
DEBUG COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 23 for existing command connection
INFO CTRL_AGENT_COMMAND_FORWARDED command status-get successfully forwarded to the service dhcp4
INFO[2021-09-07 13:32:59] agent.go:375 Compressing response from 249 B to 196 B, ratio 78%
INFO COMMAND_RECEIVED Received command 'config-get'
DEBUG COMMAND_SOCKET_CONNECTION_OPENED Opened socket 23 for incoming command connection
DEBUG COMMAND_SOCKET_READ Received 66 bytes over command socket 23
INFO COMMAND_RECEIVED Received command 'config-get'
DEBUG COMMAND_SOCKET_WRITE Sent response of 3167 bytes (0 bytes left to send) over command socket 23
DEBUG COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 23 for existing command connection
INFO CTRL_AGENT_COMMAND_FORWARDED command config-get successfully forwarded to the service dhcp4
WARN[2021-09-07 13:32:59] kea.go:69 skipped refreshing viewable log files because config-get returned non success result
WARN[2021-09-07 13:32:59] kea.go:69 skipped refreshing viewable log files because config-get returned non success result
INFO[2021-09-07 13:32:59] agent.go:375 Compressing response from 3444 B to 1296 B, ratio 37%
INFO COMMAND_RECEIVED Received command 'statistic-get-all'
DEBUG COMMAND_SOCKET_CONNECTION_OPENED Opened socket 23 for incoming command connection
DEBUG COMMAND_SOCKET_READ Received 86 bytes over command socket 23
INFO COMMAND_RECEIVED Received command 'statistic-get-all'
DEBUG COMMAND_SOCKET_WRITE Sent response of 1759 bytes (0 bytes left to send) over command socket 23
DEBUG COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 23 for existing command connection
INFO CTRL_AGENT_COMMAND_FORWARDED command statistic-get-all successfully forwarded to the service dhcp4
WARN[2021-09-07 13:33:02] promkeaexporter.go:368 problem with connecting to dhcp daemon: unable to forward command to the dhcp6 service: No such file or directory. The server is likely to be offline
DEBUG DHCPSRV_TIMERMGR_RUN_TIMER_OPERATION running operation for timer: reclaim-expired-leases
DEBUG ALLOC_ENGINE_V4_LEASES_RECLAMATION_START starting reclamation of expired leases (limit = 100 leases or 250 milliseconds)
DEBUG DHCPSRV_MYSQL_GET_EXPIRED4 obtaining maximum 101 of expired IPv4 leases
DEBUG ALLOC_ENGINE_V4_LEASES_RECLAMATION_COMPLETE reclaimed 0 leases in 0.633 ms
DEBUG ALLOC_ENGINE_V4_NO_MORE_EXPIRED_LEASES all expired leases have been reclaimed
DEBUG DHCPSRV_TIMERMGR_START_TIMER starting timer: reclaim-expired-leases
INFO COMMAND_RECEIVED Received command 'statistic-get-all'
DEBUG COMMAND_SOCKET_CONNECTION_OPENED Opened socket 23 for incoming command connection
DEBUG COMMAND_SOCKET_READ Received 86 bytes over command socket 23
INFO COMMAND_RECEIVED Received command 'statistic-get-all'
DEBUG COMMAND_SOCKET_WRITE Sent response of 1759 bytes (0 bytes left to send) over command socket 23
DEBUG COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 23 for existing command connection
INFO CTRL_AGENT_COMMAND_FORWARDED command statistic-get-all successfully forwarded to the service dhcp4
WARN[2021-09-07 13:33:12] promkeaexporter.go:368 problem with connecting to dhcp daemon: unable to forward command to the dhcp6 service: No such file or directory. The server is likely to be offline
DEBUG DHCPSRV_TIMERMGR_RUN_TIMER_OPERATION running operation for timer: flush-reclaimed-leases
DEBUG ALLOC_ENGINE_V4_RECLAIMED_LEASES_DELETE begin deletion of reclaimed leases expired more than 3600 seconds ago
DEBUG DHCPSRV_MYSQL_DELETE_EXPIRED_RECLAIMED4 deleting reclaimed IPv4 leases that expired more than 3600 seconds ago
DEBUG DHCPSRV_MYSQL_DELETED_EXPIRED_RECLAIMED deleted 0 reclaimed leases from the database
DEBUG ALLOC_ENGINE_V4_RECLAIMED_LEASES_DELETE_COMPLETE successfully deleted 0 expired-reclaimed leases
DEBUG DHCPSRV_TIMERMGR_START_TIMER starting timer: flush-reclaimed-leases
DEBUG DHCPSRV_TIMERMGR_RUN_TIMER_OPERATION running operation for timer: reclaim-expired-leases
DEBUG ALLOC_ENGINE_V4_LEASES_RECLAMATION_START starting reclamation of expired leases (limit = 100 leases or 250 milliseconds)
DEBUG DHCPSRV_MYSQL_GET_EXPIRED4 obtaining maximum 101 of expired IPv4 leases
DEBUG ALLOC_ENGINE_V4_LEASES_RECLAMATION_COMPLETE reclaimed 0 leases in 0.626 ms
DEBUG ALLOC_ENGINE_V4_NO_MORE_EXPIRED_LEASES all expired leases have been reclaimed
DEBUG DHCPSRV_TIMERMGR_START_TIMER starting timer: reclaim-expired-leases
INFO COMMAND_RECEIVED Received command 'statistic-get-all'
DEBUG COMMAND_SOCKET_CONNECTION_OPENED Opened socket 23 for incoming command connection
DEBUG COMMAND_SOCKET_READ Received 86 bytes over command socket 23
INFO COMMAND_RECEIVED Received command 'statistic-get-all'
DEBUG COMMAND_SOCKET_WRITE Sent response of 1759 bytes (0 bytes left to send) over command socket 23
DEBUG COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 23 for existing command connection
INFO CTRL_AGENT_COMMAND_FORWARDED command statistic-get-all successfully forwarded to the service dhcp4
WARN[2021-09-07 13:33:22] promkeaexporter.go:368 problem with connecting to dhcp daemon: unable to forward command to the dhcp6 service: No such file or directory. The server is likely to be offline