Unsure of linelog configuration
Hi I am trying to see all DHCP interactions (allocated, ack, remove, etc) and I have configured linelog. Radiusd -X shows all DHCP (lease time set to 7200 so I see an ACK every 2 hours). But my line log is only showing the first successful allocate. I have obviously mis-understood the syntax and positioning of linelog because it is basically working but not as I expected. Would welcome a pointer or two? I have this (and nothing else) in my linelog file: linelog linelog_dhcp{ filename = ${logdir}/dhcp.log escape_filenames = no permissions = 0600 format = "%t %{control:Module-Success-Message}" } … and this in my dhcp file: server dhcp { listen { # This is a dhcp socket. type = dhcp ipaddr = 192.168.1.1 src_ipaddr = 192.168.1.1 reply:DHCP-DHCP-Server-Identifier port = 67 interface = eth0 broadcast = no performance { skip_duplicate_checks = no } } dhcp DHCP-Discover { # The DHCP Server Identifier is set here since is returned in OFFERs update control { &DHCP-DHCP-Server-Identifier = 192.168.1.1 } dhcp_network dhcp_sqlippool linelog_dhcp update reply { DHCP-Message-Type = DHCP-Offer Packet-Dst-Port = 68 } } dhcp DHCP-Request { update control { &DHCP-DHCP-Server-Identifier = 192.168.1.1 } if (&request:DHCP-DHCP-Server-Identifier && \ &request:DHCP-DHCP-Server-Identifier != &control:DHCP-DHCP-Server-Identifier) { do_not_respond } update reply { &DHCP-Message-Type = DHCP-Ack Packet-Dst-Port = 68 } root@FreeRadius:/usr/local/etc/raddb/sites-enabled# cat dhcp # -*- text -*- server dhcp { listen { # This is a dhcp socket. type = dhcp ipaddr = 192.168.1.1 src_ipaddr = 192.168.1.1 reply:DHCP-DHCP-Server-Identifier port = 67 interface = eth0 broadcast = no performance { skip_duplicate_checks = no } } dhcp DHCP-Discover { # The DHCP Server Identifier is set here since is returned in OFFERs update control { &DHCP-DHCP-Server-Identifier = 192.168.1.1 } dhcp_network dhcp_sqlippool linelog_dhcp update reply { DHCP-Message-Type = DHCP-Offer Packet-Dst-Port = 68 } } dhcp DHCP-Request { update control { &DHCP-DHCP-Server-Identifier = 192.168.1.1 } if (&request:DHCP-DHCP-Server-Identifier && \ &request:DHCP-DHCP-Server-Identifier != &control:DHCP-DHCP-Server-Identifier) { do_not_respond } update reply { &DHCP-Message-Type = DHCP-Ack Packet-Dst-Port = 68 } dhcp_network dhcp_sqlippool_request linelog_dhcp } dhcp DHCP-Decline { dhcp_network update reply { &DHCP-Message-Type = DHCP-Do-Not-Respond } reject linelog_dhcp } dhcp DHCP-Inform { dhcp_network linelog_dhcp ok } # # For Windows 7 boxes # dhcp DHCP-Inform { update reply { Packet-Dst-Port = 68 DHCP-Message-Type = DHCP-ACK DHCP-DHCP-Server-Identifier = "%{Packet-Dst-IP-Address}" DHCP-Site-specific-28 = 0x0a00 } linelog_dhcp ok } dhcp DHCP-Release { dhcp_network update reply { &DHCP-Message-Type = DHCP-Do-Not-Respond } reject linelog_dhcp } dhcp DHCP-Lease-Query { if (&DHCP-Client-Hardware-Address) { } elsif (&DHCP-Your-IP-Address) { } elsif (&DHCP-Client-Identifier) { } else { update reply { &DHCP-Message-Type = DHCP-Lease-Unknown } ok return } if (notfound) { update reply { &DHCP-Message-Type = DHCP-Lease-Unknown } ok return } update reply { &DHCP-Message-Type = DHCP-Lease-Unassigned } linelog_dhcp } } Thank you David David Lake Visiting Professor 5G Innovation Centre (5GIC and 6GIC) Tel: +44 (0)7711 736784 Email: d.lake@surrey.ac.uk<mailto:%20d.lake@surrey.ac.uk> Web: surrey.ac.uk<http://www.surrey.ac.uk/?utm_medium=internal&utm_source=emailsignature&utm_campaign=reputation+50th+brand> [A blue text on a black background Description automatically generated]<http://www.surrey.ac.uk/?utm_source=emailsignature&utm_medium=internal&utm_campaign=emailsignature_1819&utm_content=emailsignature_homepage> James Clerk Maxwell Building, University of Surrey, Guildford, Surrey, GU2 7XH, UK
On 31/07/2025 12:14, David Lake via Freeradius-Users wrote:
But my line log is only showing the first successful allocate. I have obviously mis-understood the syntax and positioning of linelog because it is basically working but not as I expected. Would welcome a pointer or two?
A renewing DHCP client will send a direct request, so won't hit the discover section. Put the logging in the request section instead. -- Matthew
I thought I had put it in the Request section (section below) - dhcp DHCP-Request { update control { &DHCP-DHCP-Server-Identifier = 192.168.1.1 } if (&request:DHCP-DHCP-Server-Identifier && \ &request:DHCP-DHCP-Server-Identifier != &control:DHCP-DHCP-Server-Identifier) { do_not_respond } update reply { &DHCP-Message-Type = DHCP-Ack Packet-Dst-Port = 68 } dhcp_network dhcp_sqlippool_request linelog_dhcp } From: Freeradius-Users <freeradius-users-bounces+d.lake=surrey.ac.uk@lists.freeradius.org> on behalf of Matthew Newton via Freeradius-Users <freeradius-users@lists.freeradius.org> Date: Thursday, 31 July 2025 at 12:19 To: freeradius-users@lists.freeradius.org <freeradius-users@lists.freeradius.org> Cc: Matthew Newton <mcn@freeradius.org> Subject: Re: Unsure of linelog configuration On 31/07/2025 12:14, David Lake via Freeradius-Users wrote:
But my line log is only showing the first successful allocate. I have obviously mis-understood the syntax and positioning of linelog because it is basically working but not as I expected. Would welcome a pointer or two?
A renewing DHCP client will send a direct request, so won't hit the discover section. Put the logging in the request section instead. -- Matthew - List info/subscribe/unsubscribe? See https://eur02.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.freeradius.org%2Flist%2Fusers.html&data=05%7C02%7Cd.lake%40surrey.ac.uk%7C7b56928dd16845eb247f08ddd024216a%7C6b902693107440aa9e21d89446a2ebb5%7C0%7C0%7C638895575794961415%7CUnknown%7CTWFpbGZsb3d8eyJFbXB0eU1hcGkiOnRydWUsIlYiOiIwLjAuMDAwMCIsIlAiOiJXaW4zMiIsIkFOIjoiTWFpbCIsIldUIjoyfQ%3D%3D%7C0%7C%7C%7C&sdata=DhPAlyDzFCni2e2O5Jv1A1U%2BwiP5g7SYS9YHMofsqSk%3D&reserved=0<http://www.freeradius.org/list/users.html>
From radiusd -X.
For a new allocation following Discover I see this in the log: (4) dhcp_sqlippool: EXPAND DHCP: Allocated IP: %{reply:DHCP-Your-IP-Address} from %{control:Pool-Name} (cid %{DHCP-Client-Identifier} chaddr %{DHCP-Client-Hardware-Address} giaddr %{DHCP-Gateway-IP-Address}) (4) dhcp_sqlippool: --> DHCP: Allocated IP: 192.168.2.101 from ipoe (cid 0x010c3311bf0000 chaddr 0c:33:11:bf:00:00 giaddr 192.168.2.1) (4) [dhcp_sqlippool] = ok (4) linelog_dhcp: EXPAND %t %{control:Module-Success-Message} (4) linelog_dhcp: --> Thu Jul 31 12:32:31 2025 DHCP: Allocated IP: 192.168.2.101 from ipoe (cid 0x010c3311bf0000 chaddr 0c:33:11:bf:00:00 giaddr 192.168.2.1) (4) linelog_dhcp: EXPAND /usr/local/var/log/radius/dhcp.log (4) linelog_dhcp: --> /usr/local/var/log/radius/dhcp.log (4) [linelog_dhcp] = ok (4) update reply { (4) DHCP-Message-Type = DHCP-Offer (4) Packet-Dst-Port = 68 (4) } # update reply = noop (4) } # dhcp DHCP-Discover = ok After an ACK I see this: (5) dhcp_sqlippool: EXPAND %{control:DHCP-SQL-Option-Identifier} (5) dhcp_sqlippool: --> (5) dhcp_sqlippool: SQL-User-Name set to '' (5) dhcp_sqlippool: EXPAND UPDATE dhcpippool SET expiry_time = NOW() + INTERVAL 7200 SECOND, counter = counter + 1 WHERE pool_name = '%{control:Pool-Name}' AND pool_key = '%{%{DHCP-Client-Identifier}:-%{DHCP-Client-Hardware-Address}}' AND framedipaddress = '%{%{DHCP-Requested-IP-Address}:-%{DHCP-Client-IP-Address}}' (5) dhcp_sqlippool: --> UPDATE dhcpippool SET expiry_time = NOW() + INTERVAL 7200 SECOND, counter = counter + 1 WHERE pool_name = 'ipoe' AND pool_key = '0x010c3311bf0000' AND framedipaddress = '192.168.2.101' (5) dhcp_sqlippool: Executing query: UPDATE dhcpippool SET expiry_time = NOW() + INTERVAL 7200 SECOND, counter = counter + 1 WHERE pool_name = 'ipoe' AND pool_key = '0x010c3311bf0000' AND framedipaddress = '192.168.2.101' rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0 rlm_sql (dhcp_sql): Released connection (8) (5) [dhcp_sqlippool.accounting] = ok (5) update reply { (5) EXPAND %{%{DHCP-Requested-IP-Address}:-%{DHCP-Client-IP-Address}} (5) --> 192.168.2.101 (5) &DHCP-Your-IP-Address := 192.168.2.101 (5) } # update reply = noop (5) } # policy dhcp_sqlippool_request = ok (5) linelog_dhcp: EXPAND %t %{control:Module-Success-Message} (5) linelog_dhcp: --> Thu Jul 31 12:32:32 2025 (5) linelog_dhcp: EXPAND /usr/local/var/log/radius/dhcp.log (5) linelog_dhcp: --> /usr/local/var/log/radius/dhcp.log (5) [linelog_dhcp] = ok (5) } # dhcp DHCP-Request = ok In /usr/local/var/log/radius/dhcp.log I simply see the time/date printed, no DHCP information. David From: Matthew Newton <mcn@freeradius.org> Date: Thursday, 31 July 2025 at 12:28 To: Lake, David Dr (FEPS Faculty Admin) <d.lake@surrey.ac.uk>, FreeRadius users mailing list <freeradius-users@lists.freeradius.org> Subject: Re: Unsure of linelog configuration On 31/07/2025 12:25, David Lake wrote:
I thought I had put it in the Request section (section below) -
The top part of your email didn't show it in that section, but looking again it's truncated. As always, what does the FreeRADIUS debug log show? -- Matthew
On 31/07/2025 13:41, David Lake wrote:
(4) dhcp_sqlippool: --> DHCP: Allocated IP: 192.168.2.101 from ipoe (cid 0x010c3311bf0000 chaddr 0c:33:11:bf:00:00 giaddr 192.168.2.1) (4) [dhcp_sqlippool] = ok (4) linelog_dhcp: EXPAND %t %{control:Module-Success-Message} (4) linelog_dhcp: --> Thu Jul 31 12:32:31 2025 DHCP: Allocated IP: 192.168.2.101 from ipoe (cid 0x010c3311bf0000 chaddr 0c:33:11:bf:00:00 giaddr 192.168.2.1)
Ah, OK. dhcp_sqlippool calls the authorize method, which emits some logging information that ends up in Module-Success-Message.
After an ACK I see this:
(5) dhcp_sqlippool: --> UPDATE dhcpippool SET expiry_time = NOW() + INTERVAL 7200 SECOND, counter = counter + 1 WHERE pool_name = 'ipoe' AND pool_key = '0x010c3311bf0000' AND framedipaddress = '192.168.2.101' (5) dhcp_sqlippool: Executing query: UPDATE dhcpippool SET expiry_time = NOW() + INTERVAL 7200 SECOND, counter = counter + 1 WHERE pool_name = 'ipoe' AND pool_key = '0x010c3311bf0000' AND framedipaddress = '192.168.2.101' rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0 ...
(5) linelog_dhcp: EXPAND %t %{control:Module-Success-Message} (5) linelog_dhcp: --> Thu Jul 31 12:32:32 2025
dhcp_sqlippool_request calls the accounting method, which doesn't output any logging, so doesn't update the Module-Success-Message attribute. You'll be better to just log what you want, rather than using that attribute. Something like message="%t %{request:DHCP-Client-Hardware-Address} %{reply:DHCP-Your-IP-Address} from pool %{Pool-Name}" Add whatever attributes you need (you can call the `debug_all` policy before `linelog_dhcp` to show them all in the debug output if you're not sure what is available). -- Matthew
Perfect -thank you. I have a great standalone lab so now I understand the interaction I can start to play 😊 Thank you for the very quick and detailed explanation! David From: Freeradius-Users <freeradius-users-bounces+d.lake=surrey.ac.uk@lists.freeradius.org> on behalf of Matthew Newton via Freeradius-Users <freeradius-users@lists.freeradius.org> Date: Thursday, 31 July 2025 at 14:07 To: FreeRadius users mailing list <freeradius-users@lists.freeradius.org> Cc: Matthew Newton <mcn@freeradius.org> Subject: Re: Unsure of linelog configuration On 31/07/2025 13:41, David Lake wrote:
(4) dhcp_sqlippool: --> DHCP: Allocated IP: 192.168.2.101 from ipoe (cid 0x010c3311bf0000 chaddr 0c:33:11:bf:00:00 giaddr 192.168.2.1) (4) [dhcp_sqlippool] = ok (4) linelog_dhcp: EXPAND %t %{control:Module-Success-Message} (4) linelog_dhcp: --> Thu Jul 31 12:32:31 2025 DHCP: Allocated IP: 192.168.2.101 from ipoe (cid 0x010c3311bf0000 chaddr 0c:33:11:bf:00:00 giaddr 192.168.2.1)
Ah, OK. dhcp_sqlippool calls the authorize method, which emits some logging information that ends up in Module-Success-Message.
After an ACK I see this:
(5) dhcp_sqlippool: --> UPDATE dhcpippool SET expiry_time = NOW() + INTERVAL 7200 SECOND, counter = counter + 1 WHERE pool_name = 'ipoe' AND pool_key = '0x010c3311bf0000' AND framedipaddress = '192.168.2.101' (5) dhcp_sqlippool: Executing query: UPDATE dhcpippool SET expiry_time = NOW() + INTERVAL 7200 SECOND, counter = counter + 1 WHERE pool_name = 'ipoe' AND pool_key = '0x010c3311bf0000' AND framedipaddress = '192.168.2.101' rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0 ...
(5) linelog_dhcp: EXPAND %t %{control:Module-Success-Message} (5) linelog_dhcp: --> Thu Jul 31 12:32:32 2025
dhcp_sqlippool_request calls the accounting method, which doesn't output any logging, so doesn't update the Module-Success-Message attribute. You'll be better to just log what you want, rather than using that attribute. Something like message="%t %{request:DHCP-Client-Hardware-Address} %{reply:DHCP-Your-IP-Address} from pool %{Pool-Name}" Add whatever attributes you need (you can call the `debug_all` policy before `linelog_dhcp` to show them all in the debug output if you're not sure what is available). -- Matthew - List info/subscribe/unsubscribe? See https://eur02.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.freeradius.org%2Flist%2Fusers.html&data=05%7C02%7Cd.lake%40surrey.ac.uk%7C54b2b2f0ac554563878808ddd0332722%7C6b902693107440aa9e21d89446a2ebb5%7C0%7C0%7C638895640303736033%7CUnknown%7CTWFpbGZsb3d8eyJFbXB0eU1hcGkiOnRydWUsIlYiOiIwLjAuMDAwMCIsIlAiOiJXaW4zMiIsIkFOIjoiTWFpbCIsIldUIjoyfQ%3D%3D%7C0%7C%7C%7C&sdata=rykzPLKA42Vl%2Frs07wzbGQatPH9mNmvJ7Q7dvzWESC4%3D&reserved=0<http://www.freeradius.org/list/users.html>
participants (2)
-
David Lake -
Matthew Newton