[Kea-users] Kea-dhcp-ddns not logging debug info (OPEN)
Weisteen Per
per.weisteen at telenor.no
Thu May 12 08:47:26 UTC 2022
Hi,
Yes, the D2 server is configured and started. It actually worked ok for a while but then suddenly stopped taking new updates from dhcp4 server. That's why I wanted to turn on more debugging.
BTW this is a test-rig consisting of 3 cameras using 802.1x on a Cisco switch. If a camera fails authentication it's allocated to a "guest" VLAN on a different subnet. For testing purposes I've set leasetime to 3600, rebind-timer to 1800 and renew-timer to 900.
I configured logging like this for D2 yesterday :
"loggers": [
{
"name": "kea-dhcp-ddns",
"output_options": [
{
"output": "/var/log/kea/kea-ddns-debug.log",
"pattern": "%D{%Y-%m-%d %H:%M:%S.%q} %-5p %m\n",
"flush": true,
"maxsize": 204800,
"maxver": 8
}
],
"severity": "DEBUG",
"debuglevel": 40
},
{
"name": "kea-dhcp-ddns.dhcp-to-d2",
"output_options": [
{
"output": "/var/log/kea/kea-ddns-dhcp-to-d2.log",
"pattern": "%D{%Y-%m-%d %H:%M:%S.%q} %-5p %m\n",
"flush": true
}
],
"severity": "DEBUG",
"debuglevel": 40
},
{
"name": "kea-dhcp-ddns.d2-to-dns",
"output_options": [
{
"output": "/var/log/kea/kea-ddns-d2-to-dns.log",
"pattern": "%D{%Y-%m-%d %H:%M:%S.%q} %-5p %m\n",
"flush": true
}
],
"severity": "DEBUG",
"debuglevel": 40
}
]
For kea-dhcp4 I've set logging like this:
"loggers": [
{
"name": "kea-dhcp4",
"output_options": [{
"output": "/var/log/kea/kea-debug.log",
"pattern": "%D{%Y-%m-%d %H:%M:%S.%q} %-5p %m\n",
"flush": true,
"maxsize": 204800,
"maxver": 8
}],
"severity": "INFO",
"debuglevel": 0
},
{
"name": "kea-dhcp4.ddns",
"output_options": [{
"output": "/var/log/kea/kea-dhcp4-ddns.log",
"pattern": "%D{%Y-%m-%d %H:%M:%S.%q} %-5p %m\n",
"flush": true,
"maxsize": 204800,
"maxver": 8
}],
"severity": "DEBUG",
"debuglevel": 45
}
]
When I checked the logs this morning I discovered entries in kea-ddns-d2-to-dns.log :
2022-05-12 01:41:27.138 INFO DHCP_DDNS_REMOVE_SUCCEEDED DHCP_DDNS Request ID 0001010CADBD422F0ECA03C85AF1FE24EA2E630A1E190C345566795F1A7295CDBF7E26: successfully removed the DNS mapping addition for this request: Type: 1 (CHG_REMOVE)
Forward Change: yes
Reverse Change: yes
FQDN: [tst-ra005.cctv.telenor.net.]
IP Address: [10.41.64.4]
DHCID: [0001010CADBD422F0ECA03C85AF1FE24EA2E630A1E190C345566795F1A7295CDBF7E26]
Lease Expires On: 20220511230122
Lease Length: 1200
Conflict Resolution: yes
2022-05-12 01:42:46.340 INFO DHCP_DDNS_ADD_SUCCEEDED DHCP_DDNS Request ID 0001010CADBD422F0ECA03C85AF1FE24EA2E630A1E190C345566795F1A7295CDBF7E26: successfully added the DNS mapping addition for this request: Type: 0 (CHG_ADD)
Forward Change: yes
Reverse Change: yes
FQDN: [tst-ra005.cctv.telenor.net.]
IP Address: [10.41.64.4]
DHCID: [0001010CADBD422F0ECA03C85AF1FE24EA2E630A1E190C345566795F1A7295CDBF7E26]
Lease Expires On: 20220512000246
Lease Length: 1200
Conflict Resolution: yes
But when checking the kea-dhcp4-ddns.log the last entry for tst-ra005.cctv.telenor.net update is way back in time and none of the other DDNS updates (tst-ra001.cctv.telenor.net and 00-07-5f-b2-c8-e0-dns-ldh-rule.cctv.telenor.net) is reflected in the kea-ddns-d2-to-dns.log :
2022-05-11 11:01:16.020 DEBUG DHCP4_CLIENT_FQDN_PROCESS [hwtype=1 00:07:5f:ae:77:cb], cid=[01:00:07:5f:ae:77:cb], tid=0x3d06108f: processing Client FQDN option
2022-05-11 11:01:16.020 DEBUG DHCP4_CLIENT_FQDN_DATA [hwtype=1 00:07:5f:ae:77:cb], cid=[01:00:07:5f:ae:77:cb], tid=0x3d06108f: Client sent FQDN option: type=81 (CLIENT_FQDN), flags: (N=0, E=0, O=0, S=1), domain-name='tst-ra005.cctv.telenor.net.' (full)
2022-05-11 11:01:16.020 DEBUG DHCP4_RESPONSE_FQDN_DATA [hwtype=1 00:07:5f:ae:77:cb], cid=[01:00:07:5f:ae:77:cb], tid=0x3d06108f: including FQDN option in the server's response: type=81 (CLIENT_FQDN), flags: (N=0, E=0, O=0, S=1), domain-name='tst-ra005.cctv.telenor.net.' (full)
2022-05-11 11:01:16.020 DEBUG DHCP4_NCR_CREATE [hwtype=1 00:07:5f:ae:77:cb], cid=[01:00:07:5f:ae:77:cb], tid=0x3d06108f: DDNS updates enabled, therefore sending name change requests
2022-05-11 11:11:14.184 DEBUG DHCP4_CLIENT_FQDN_PROCESS [hwtype=1 00:07:5f:be:89:ee], cid=[01:00:07:5f:be:89:ee], tid=0x42206210: processing Client FQDN option
2022-05-11 11:11:14.185 DEBUG DHCP4_CLIENT_FQDN_DATA [hwtype=1 00:07:5f:be:89:ee], cid=[01:00:07:5f:be:89:ee], tid=0x42206210: Client sent FQDN option: type=81 (CLIENT_FQDN), flags: (N=0, E=0, O=0, S=1), domain-name='tst-ra001.cctv.telenor.net.' (full)
2022-05-11 11:11:14.185 DEBUG DHCP4_RESPONSE_FQDN_DATA [hwtype=1 00:07:5f:be:89:ee], cid=[01:00:07:5f:be:89:ee], tid=0x42206210: including FQDN option in the server's response: type=81 (CLIENT_FQDN), flags: (N=0, E=0, O=0, S=1), domain-name='tst-ra001.cctv.telenor.net.' (full)
2022-05-11 11:11:14.185 DEBUG DHCP4_NCR_CREATE [hwtype=1 00:07:5f:be:89:ee], cid=[01:00:07:5f:be:89:ee], tid=0x42206210: DDNS updates enabled, therefore sending name change requests
2022-05-11 11:12:42.124 DEBUG DHCP4_CLIENT_HOSTNAME_PROCESS [hwtype=1 00:07:5f:b2:c8:e0], cid=[01:00:07:5f:b2:c8:e0], tid=0x1c6b3981: processing client's Hostname option
2022-05-11 11:12:42.124 DEBUG DHCP4_CLIENT_HOSTNAME_DATA [hwtype=1 00:07:5f:b2:c8:e0], cid=[01:00:07:5f:b2:c8:e0], tid=0x1c6b3981: client sent Hostname option: 00-07-5f-b2-c8-e0-dns-ldh-rule
2022-05-11 11:12:42.124 DEBUG DHCP4_CLIENT_HOSTNAME_DATA [hwtype=1 00:07:5f:b2:c8:e0], cid=[01:00:07:5f:b2:c8:e0], tid=0x1c6b3981: client sent Hostname option: 00-07-5f-b2-c8-e0-dns-ldh-rule
2022-05-11 11:12:42.124 DEBUG DHCP4_RESPONSE_HOSTNAME_DATA [hwtype=1 00:07:5f:b2:c8:e0], cid=[01:00:07:5f:b2:c8:e0], tid=0x1c6b3981: including Hostname option in the server's response: 00-07-5f-b2-c8-e0-dns-ldh-rule.cctv.telenor.net
2022-05-11 11:12:42.125 DEBUG DHCP4_NCR_CREATE [hwtype=1 00:07:5f:b2:c8:e0], cid=[01:00:07:5f:b2:c8:e0], tid=0x1c6b3981: DDNS updates enabled, therefore sending name change requests
2022-05-11 11:16:16.018 DEBUG DHCP4_CLIENT_FQDN_PROCESS [hwtype=1 00:07:5f:ae:77:cb], cid=[01:00:07:5f:ae:77:cb], tid=0x3d06108f: processing Client FQDN option
2022-05-11 11:16:16.018 DEBUG DHCP4_CLIENT_FQDN_DATA [hwtype=1 00:07:5f:ae:77:cb], cid=[01:00:07:5f:ae:77:cb], tid=0x3d06108f: Client sent FQDN option: type=81 (CLIENT_FQDN), flags: (N=0, E=0, O=0, S=1), domain-name='tst-ra005.cctv.telenor.net.' (full)
2022-05-11 11:16:16.018 DEBUG DHCP4_RESPONSE_FQDN_DATA [hwtype=1 00:07:5f:ae:77:cb], cid=[01:00:07:5f:ae:77:cb], tid=0x3d06108f: including FQDN option in the server's response: type=81 (CLIENT_FQDN), flags: (N=0, E=0, O=0, S=1), domain-name='tst-ra005.cctv.telenor.net.' (full)
2022-05-11 11:16:16.018 DEBUG DHCP4_NCR_CREATE [hwtype=1 00:07:5f:ae:77:cb], cid=[01:00:07:5f:ae:77:cb], tid=0x3d06108f: DDNS updates enabled, therefore sending name change requests
And there is no entries in kea-ddns-dhcp-to-d2.log.
./PerW
-----Original Message-----
From: Oscar Carlsson <oscar at spindel.tax>
Sent: onsdag 11. mai 2022 13:06
To: Weisteen Per <per.weisteen at telenor.no>
Cc: kea-users at lists.isc.org
Subject: Re: [Kea-users] Kea-dhcp-ddns not logging debug info (INTERNAL)
Hi,
Is the D2 server configured and started? (systemctl status isc-kea-dhcp-ddns.service on my system)
And do you have logging setup in D2? Taken from my conf:
"loggers": [
{
"name": "kea-dhcp-ddns",
"output_options": [
{
"output": "stdout",
"pattern": "%-5p %m\n"
}
],
"severity": "INFO",
"debuglevel": 0
}
]
And is kea dhcp configured to use it? Taken from my conf:
{
"Dhcp4": {
[...]
"dhcp-ddns": {
"enable-updates": true,
"server-ip": "127.0.0.1",
"server-port":53001,
"sender-ip":"",
"sender-port":0,
"max-queue-size":1024,
"ncr-protocol":"UDP",
"ncr-format":"JSON"
},
"ddns-send-updates": true,
[...]
"subnet4": [
{
"subnet": "192.168.0.0/24",
"pools": [ { "pool": "192.168.0.100 -
192.168.0.200" } ],
"option-data": [
{ "name": "routers",
"data": "192.168.0.254",
"code": 3
},
{ "name": "domain-name-servers",
"data": "192.168.0.254",
"code": 6
},
{ "name": "domain-name",
"data": "clients.home.arpa",
"code": 15
}
],
"reservations": [
{ "hw-address": "38:d5:47:df:6e:50",
"ip-address": "192.168.0.10"
}
],
"ddns-qualifying-suffix": "clients.home.arpa"
},
Oscar
Weisteen Per <per.weisteen at telenor.no> writes:
> Hi,
>
> The 2.0.2 docs
> https://kea.readthedocs.io/en/kea-2.0.2-doc/arm/logging.html#the-name-
> string-logger
> states that
>
> "The loggers form a hierarchy. For each program in Kea, there is a
> "root" logger, named after the program (e.g. the root logger for
> kea-dhcp, the DHCPv4 server) is named kea-dhcp4. All other loggers are
> children of this logger and are named accordingly, e.g. the allocation
> engine in the DHCPv4 server logs messages using a logger called
> kea-dhcp4.alloc-engine.
>
> This relationship is important, as each child logger derives its
> default configuration from its parent root logger. In the typical
> case, the root logger configuration is the only logging configuration
> specified in the configuration file and so applies to all loggers. If
> an entry is made for a given logger, any attributes specified override
> those of the root logger, whereas any not specified are inherited from
> it."
>
> This led me to believe I could specify "root" logger for kea-dhcp-ddns
> like this :
>
> "loggers": [
> {
> "name": "kea-dhcp-ddns",
> "output_options": [
> {
> "output": "/var/log/kea/kea-ddns-debug.log",
> "pattern": "%D{%Y-%m-%d %H:%M:%S.%q} %-5p %m\n",
> "flush": true,
> "maxsize": 204800,
> "maxver": 8
> }
> ],
> "severity": "DEBUG",
> "debuglevel": 40
> },
>
> And then just add
>
> {
> "name": "kea-dhcp-ddns.dhcp-to-d2",
> "severity": "DEBUG",
> "debuglevel": 40
> },
> {
> "name": "kea-dhcp-ddns.d2-to-dns",
> "severity": "DEBUG",
> "debuglevel": 40
> }
> ]
>
> which would then inherit the output_options from the "root"
> logger.
> Kea-dhcp-ddns -t /path/to/file.conf returns ok without any errors but
> no relevant d2 logging occurs even if kea-dhcp4 seemingly logs that a
> name change is requested :
>
> 2022-05-11 09:12:41.937 DEBUG DHCP4_NCR_CREATE [hwtype=1
> 00:07:5f:b2:c8:e0], cid=[01:00:07:5f:b2:c8:e0], tid=0x1c6b3981:
> DDNS updates enabled, therefore sending name change requests
>
>
>
>
> ./PerW
>
>
> -----Original Message-----
> From: Oscar Carlsson <oscar at spindel.tax>
> Sent: onsdag 11. mai 2022 08:32
> To: Weisteen Per <per.weisteen at telenor.no>
> Cc: kea-users at lists.isc.org
> Subject: Re: [Kea-users] Kea-dhcp-ddns not logging debug info
> (OPEN)
>
> Hi,
>
> The documentation provides an example, this is what I think should be
> right:
>
> "loggers": [
> {
> "name": "kea-dhcp4.dhcp-to-d2",
> "output_options": [
> {
> "output": "stdout"
> }
> ],
> "severity": "DEBUG"
> }
> ]
>
> You can verify this with kea-dhcp4 -t /path/to/file.conf (-t for
> test)
> in case you are unsure it was right. I use this with Ansible to test
> all changes before putting them into effect, it's quite handy.
>
>
> Oscar
>
> Weisteen Per <per.weisteen at telenor.no> writes:
>
>> Hi, thanks for the suggestion.
>>
>> I'm a newbie regarding JSON syntax - does
>> kea-dhcp-ddns.dhcp-to-d2
>> need its own output_options section or could it use the same as the
>> kea-dhcp-ddns logger ?
>>
>> ./PerW
>>
>>
>> -----Original Message-----
>> From: Oscar Carlsson <oscar at spindel.tax>
>> Sent: tirsdag 10. mai 2022 15:43
>> To: Weisteen Per <per.weisteen at telenor.no>
>> Cc: kea-users at lists.isc.org
>> Subject: Re: [Kea-users] Kea-dhcp-ddns not logging debug info
>> (INTERNAL)
>>
>> Hi,
>>
>> There's a wealth of different loggers you can tune, when I had some
>> issues with ddns I used kea-dhcp-ddns.dhcp-to-d2 and
>> kea-dhcp-ddns.d2-to-dns (set to DEBUG) which was enough in that case.
>>
>>
>> https://kea.readthedocs.io/en/kea-1.6.2/arm/logging.html
>>
>>
>> Oscar
>>
>> Weisteen Per <per.weisteen at telenor.no> writes:
>>
>>> I'm testing DDNS an I've succeeded in doing updates. But the logs
>>> created from kea-dhcp-ddns doesn't seem to be consistent.
>>> During testing last week I got sensible information in logs from
>>> kea-dhcp-ddns but not during testing today.
>>>
>>> My logs from kea-dhcp4 regarding DNS updates tells me that updates
>>> is done :
>>>
>>> 2022-05-10 14:31:16.216 DEBUG DHCP4_CLIENT_FQDN_PROCESS
>>> [hwtype=1
>>> 00:07:5f:ae:77:cb], cid=[01:00:07:5f:ae:77:cb],
>>> tid=0x3d06108f:
>>> processing Client FQDN option
>>> 2022-05-10 14:31:16.216 DEBUG DHCP4_CLIENT_FQDN_DATA [hwtype=1
>>> 00:07:5f:ae:77:cb], cid=[01:00:07:5f:ae:77:cb],
>>> tid=0x3d06108f:
>>> Client
>>> sent FQDN option: type=81 (CLIENT_FQDN), flags: (N=0, E=0, O=0,
>>> S=1), domain-name='tst-ra005.cctv.telenor.net.' (full)
>>> 2022-05-10 14:31:16.217 DEBUG DHCP4_RESPONSE_FQDN_DATA
>>> [hwtype=1
>>> 00:07:5f:ae:77:cb], cid=[01:00:07:5f:ae:77:cb],
>>> tid=0x3d06108f:
>>> including FQDN option in the server's response: type=81
>>> (CLIENT_FQDN),
>>> flags: (N=0, E=0, O=0, S=1),
>>> domain-name='tst-ra005.cctv.telenor.net.'
>>> (full)
>>> 2022-05-10 14:31:16.217 DEBUG DHCP4_NCR_CREATE [hwtype=1
>>> 00:07:5f:ae:77:cb], cid=[01:00:07:5f:ae:77:cb],
>>> tid=0x3d06108f:
>>> DDNS
>>> updates enabled, therefore sending name change requests
>>>
>>> However kea-dhcp-ddns still doesn't seem to do anyting.
>>> I've enabled DEBUG logging at level 45 and restarted the daemon but
>>> there is no corresponding update info in the log. The last info
>>> logged
>>> is:
>>>
>>> 2022-05-10 14:03:38.179 DEBUG COMMAND_REGISTERED Command
>>> config-write registered
>>> 2022-05-10 14:03:38.179 DEBUG COMMAND_REGISTERED Command shutdown
>>> registered
>>> 2022-05-10 14:03:38.179 DEBUG COMMAND_REGISTERED Command status-get
>>> registered
>>> 2022-05-10 14:03:38.179 DEBUG COMMAND_REGISTERED Command version-get
>>> registered
>>> 2022-05-10 14:03:38.179 DEBUG COMMAND_REGISTERED Command
>>> statistic-get registered
>>> 2022-05-10 14:03:38.179 DEBUG COMMAND_REGISTERED Command
>>> statistic-get-all registered
>>> 2022-05-10 14:03:38.179 DEBUG COMMAND_REGISTERED Command
>>> statistic-reset registered
>>> 2022-05-10 14:03:38.179 DEBUG COMMAND_REGISTERED Command
>>> statistic-reset-all registered
>>> 2022-05-10 14:03:38.179 DEBUG
>>> DHCP_DDNS_QUEUE_MGR_RECONFIGURING
>>> application is reconfiguring the queue manager
>>> 2022-05-10 14:03:38.179 DEBUG DHCP_DDNS_QUEUE_MGR_STARTED
>>> application's queue manager has begun listening for requests.
>>>
>>>
>>> Version info:
>>> # kea-dhcp-ddns -V
>>> 2.0.1
>>> tarball
>>> linked with:
>>> log4cplus 1.2.0
>>> OpenSSL 1.1.1k FIPS 25 Mar 2021
>>>
>>> # kea-dhcp4 -V
>>> 2.0.1
>>> tarball
>>> linked with:
>>> log4cplus 1.2.0
>>> OpenSSL 1.1.1k FIPS 25 Mar 2021
>>> database:
>>> MySQL backend 12.0, library 10.5.5
>>> PostgreSQL backend 6.2, library 130003 Memfile backend 2.1
>>>
>>>
>>>
>>> ./PerW
More information about the Kea-users
mailing list