[Kea-users] debug logging for HA heartbeat

Fri Jan 28 14:38:15 UTC 2022

Here is probably a hint for the problem as seen in the control agent logs:
HTTP_CLIENT_REQUEST_TIMEOUT_OCCURRED
and
HTTP_CONNECTION_STOP

Next question is : how/where is the timeout of "10" defined ?

2022-01-28 15:10:50.419 DEBUG [kea-ctrl-agent.http/17978.140214125492416] HTTP_CONNECTION_HANDSHAKE_START start TLS handshake with kea2 with timeout 10
2022-01-28 15:10:50.419 DEBUG [kea-ctrl-agent.http/17978.140214125492416] HTTP_CLIENT_REQUEST_TIMEOUT_OCCURRED HTTP request timeout occurred when communicating with (unknown address)
2022-01-28 15:10:50.419 DEBUG [kea-ctrl-agent.http/17978.140214125492416] HTTP_CONNECTION_STOP stopping HTTP connection from (unknown address)
2022-01-28 15:10:50.419 DEBUG [kea-ctrl-agent.http/17978.140214125492416] HTTP_CONNECTION_HANDSHAKE_START start TLS handshake with kea2 with timeout 10
2022-01-28 15:10:50.420 DEBUG [kea-ctrl-agent.http/17978.140214125492416] HTTP_CONNECTION_STOP stopping HTTP connection from (unknown address)
2022-01-28 15:10:50.421 INFO [kea-ctrl-agent.http/17978.140214125492416] HTTP_CONNECTION_HANDSHAKE_FAILED TLS handshake with (unknown address) failed with short read
2022-01-28 15:10:50.421 DEBUG [kea-ctrl-agent.http/17978.140214125492416] HTTP_CONNECTION_STOP stopping HTTP connection from (unknown address)
2022-01-28 15:10:50.494 DEBUG [kea-ctrl-agent.http/17978.140214125492416] HTTPS_REQUEST_RECEIVE_START start receiving request from kea2
2022-01-28 15:10:50.494 DEBUG [kea-ctrl-agent.http/17978.140214125492416] HTTP_DATA_RECEIVED received 146 bytes from kea2
2022-01-28 15:10:50.495 DEBUG [kea-ctrl-agent.http/17978.140214125492416] HTTP_CLIENT_REQUEST_RECEIVED received HTTP request from kea2
2022-01-28 15:10:50.495 DEBUG [kea-ctrl-agent.http/17978.140214125492416] HTTP_CLIENT_REQUEST_RECEIVED_DETAILS detailed information about well-formed request received from kea2:

> On 28/01/2022 13:11 Veronique Lefebure <veronique.lefebure at cern.ch> wrote:
> 
> 
> Hi,
> 
> I would like to get a DEBUG logging each time a server receives a heartbeat from its partner, in a HA setup.
> I have enabled DEBUG level 99 for kea-dhcp4.ha-hooks but it does not provide that info,
> 
> I am trying to understand why our standby server shows the following every 2 min:
> 
> 2022-01-28 13:02:30.869 WARN [kea-dhcp4.ha-hooks/22827.140145289767104] HA_HEARTBEAT_COMMUNICATIONS_FAILED failed to send heartbeat to kea1 (http://xx.253:9099/): Connection timed out
> 2022-01-28 13:02:30.869 WARN [kea-dhcp4.ha-hooks/22827.140145289767104] HA_COMMUNICATION_INTERRUPTED communication with kea1 is interrupted
> 
> 
> And the primary server then oscillates like this (we have only 1 client for now for test purpose):
> 
> 2022-01-28 13:06:31.887 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_STATE_TRANSITION server transitions from HOT-STANDBY to WAITING state, partner state is PARTNER-DOWN
> 2022-01-28 13:06:31.887 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_LEASE_UPDATES_DISABLED lease updates will not be sent to the partner while in WAITING state
> 2022-01-28 13:06:31.887 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_LOCAL_DHCP_DISABLE local DHCP service is disabled while the kea1 is in the WAITING state
> 2022-01-28 13:06:31.887 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_STATE_TRANSITION server transitions from WAITING to SYNCING state, partner state is PARTNER-DOWN
> 2022-01-28 13:06:31.887 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_LEASE_UPDATES_DISABLED lease updates will not be sent to the partner while in SYNCING state
> 2022-01-28 13:06:31.888 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_SYNC_START starting lease database synchronization with kea2
> 2022-01-28 13:06:31.972 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_LEASES_SYNC_LEASE_PAGE_RECEIVED received 1 leases from kea2
> 2022-01-28 13:06:31.972 DEBUG [kea-dhcp4.ha-hooks/12849.140566551173312] HA_LEASE_SYNC_STALE_LEASE4_SKIP skipping stale lease xx.xx.xx.xx in subnet 2156789248
> 2022-01-28 13:06:31.975 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_SYNC_SUCCESSFUL lease database synchronization with kea2 completed successfully in 87.082 ms
> 2022-01-28 13:06:31.976 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_STATE_TRANSITION server transitions from SYNCING to READY state, partner state is PARTNER-DOWN
> 2022-01-28 13:06:31.976 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_LEASE_UPDATES_DISABLED lease updates will not be sent to the partner while in READY state
> 
> 
> 
> 2022-01-28 13:06:52.532 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_STATE_TRANSITION server transitions from READY to HOT-STANDBY state, partner state is HOT-STANDBY
> 2022-01-28 13:06:52.532 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_LEASE_UPDATES_ENABLED lease updates will be sent to the partner while in HOT-STANDBY state
> 2022-01-28 13:06:52.532 INFO [kea-dhcp4.ha-hooks/12849.140566551173312] HA_LOCAL_DHCP_ENABLE local DHCP service is enabled while the kea1 is in the HOT-STANDBY state
> 
> Thanks.
> _______________________________________________
> ISC funds the development of this software with paid support subscriptions. Contact us at https://www.isc.org/contact/ for more information.
> 
> To unsubscribe visit https://lists.isc.org/mailman/listinfo/kea-users.
> 
> Kea-users mailing list
> Kea-users at lists.isc.org
> https://lists.isc.org/mailman/listinfo/kea-users
> 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.isc.org/pipermail/kea-users/attachments/20220128/f0b075cc/attachment-0001.htm>