- Freeradius-Users - lists.freeradius.org

The Class attributed is missing in some accounting packets sent from the same NAS.
by Selahattin Cilek 07 Feb '17

07 Feb '17

I have been experimenting with the Class attribute to obtain the user's true identity in order to do accounting and I realised that accounting packets arriving from some users do not have this attribute. User DIALLO is one: # tcpdump -n -vvv -i igb0_vlan1 src host 192.168.0.38 and dst host 192.168.0.1 and dst port 1813 tcpdump: listening on igb0_vlan1, link-type EN10MB (Ethernet), capture size 65535 bytes 18:53:55.223923 IP (tos 0x0, ttl 64, id 11875, offset 0, flags [none], proto UDP (17), length 239) 192.168.0.38.58259 > 192.168.0.1.1813: [udp sum ok] RADIUS, length: 211 Accounting Request (4), id: 0x23, Authenticator: 665d040e38bcb72f122fdd6dcd9276de Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-00000067 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3036 0x0010: 37 Accounting Status Attribute (40), length: 6, Value: Interim-Update 0x0000: 0000 0003 Accounting Authentication Attribute (45), length: 6, Value: RADIUS 0x0000: 0000 0001 Username Attribute (1), length: 8, Value: DIALLO 0x0000: 4449 414c 4c4f NAS ID Attribute (32), length: 16, Value: KAT_8_MERDIVEN 0x0000: 4b41 545f 385f 4d45 5244 4956 454e Called Station Attribute (30), length: 27, Value: DC-9F-DB-34-CF-B4:TDV.NET 0x0000: 4443 2d39 462d 4442 2d33 342d 4346 2d42 0x0010: 343a 5444 562e 4e45 54 NAS Port Type Attribute (61), length: 6, Value: Wireless - IEEE 802.11 0x0000: 0000 0013 NAS Port Attribute (5), length: 6, Value: 0 0x0000: 0000 0000 Calling Station Attribute (31), length: 19, Value: B0-E0-3C-7D-5F-1C 0x0000: 4230 2d45 302d 3343 2d37 442d 3546 2d31 0x0010: 43 Connect Info Attribute (77), length: 23, Value: CONNECT 0Mbps 802.11b 0x0000: 434f 4e4e 4543 5420 304d 6270 7320 3830 0x0010: 322e 3131 62 Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-00000067 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3036 0x0010: 37 Accounting Session Time Attribute (46), length: 6, Value: 20:00 min 0x0000: 0000 04b0 Accounting Input Packets Attribute (47), length: 6, Value: 824 0x0000: 0000 0338 Accounting Output Packets Attribute (48), length: 6, Value: 609 0x0000: 0000 0261 Accounting Input Octets Attribute (42), length: 6, Value: 122272 0x0000: 0001 dda0 Accounting Output Octets Attribute (43), length: 6, Value: 267901 0x0000: 0004 167d Event Timestamp Attribute (55), length: 6, Value: Tue Feb 7 18:53:55 2017 0x0000: 5899 ed93 18:55:34.027533 IP (tos 0x0, ttl 64, id 11888, offset 0, flags [none], proto UDP (17), length 221) 192.168.0.38.58259 > 192.168.0.1.1813: [udp sum ok] RADIUS, length: 193 Accounting Request (4), id: 0x30, Authenticator: b00abcd321185eb862b8caad7b1978ef Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-00000075 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3037 0x0010: 35 Accounting Status Attribute (40), length: 6, Value: Start 0x0000: 0000 0001 Accounting Authentication Attribute (45), length: 6, Value: RADIUS 0x0000: 0000 0001 Username Attribute (1), length: 13, Value: 99709507736 0x0000: 3939 3730 3935 3037 3733 36 NAS ID Attribute (32), length: 16, Value: KAT_8_MERDIVEN 0x0000: 4b41 545f 385f 4d45 5244 4956 454e Called Station Attribute (30), length: 27, Value: DC-9F-DB-34-CF-B4:TDV.NET 0x0000: 4443 2d39 462d 4442 2d33 342d 4346 2d42 0x0010: 343a 5444 562e 4e45 54 NAS Port Type Attribute (61), length: 6, Value: Wireless - IEEE 802.11 0x0000: 0000 0013 NAS Port Attribute (5), length: 6, Value: 0 0x0000: 0000 0000 Calling Station Attribute (31), length: 19, Value: EC-9B-F3-48-BD-70 0x0000: 4543 2d39 422d 4633 2d34 382d 4244 2d37 0x0010: 30 Connect Info Attribute (77), length: 23, Value: CONNECT 0Mbps 802.11b 0x0000: 434f 4e4e 4543 5420 304d 6270 7320 3830 0x0010: 322e 3131 62 Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-00000075 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3037 0x0010: 35 Class Attribute (25), length: 13, Value: 99709507736 0x0000: 3939 3730 3935 3037 3733 36 18:58:34.913045 IP (tos 0x0, ttl 64, id 11889, offset 0, flags [none], proto UDP (17), length 255) 192.168.0.38.58259 > 192.168.0.1.1813: [udp sum ok] RADIUS, length: 227 Accounting Request (4), id: 0x31, Authenticator: 28c4e93aeb5f31d38dd70b203cc3c397 Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-0000006E 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3036 0x0010: 45 Accounting Status Attribute (40), length: 6, Value: Interim-Update 0x0000: 0000 0003 Accounting Authentication Attribute (45), length: 6, Value: RADIUS 0x0000: 0000 0001 Username Attribute (1), length: 11, Value: anonymous 0x0000: 616e 6f6e 796d 6f75 73 NAS ID Attribute (32), length: 16, Value: KAT_8_MERDIVEN 0x0000: 4b41 545f 385f 4d45 5244 4956 454e Called Station Attribute (30), length: 27, Value: DC-9F-DB-34-CF-B4:TDV.NET 0x0000: 4443 2d39 462d 4442 2d33 342d 4346 2d42 0x0010: 343a 5444 562e 4e45 54 NAS Port Type Attribute (61), length: 6, Value: Wireless - IEEE 802.11 0x0000: 0000 0013 NAS Port Attribute (5), length: 6, Value: 0 0x0000: 0000 0000 Calling Station Attribute (31), length: 19, Value: 74-C6-3B-36-29-59 0x0000: 3734 2d43 362d 3342 2d33 362d 3239 2d35 0x0010: 39 Connect Info Attribute (77), length: 23, Value: CONNECT 0Mbps 802.11b 0x0000: 434f 4e4e 4543 5420 304d 6270 7320 3830 0x0010: 322e 3131 62 Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-0000006E 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3036 0x0010: 45 Class Attribute (25), length: 13, Value: 99820339216 0x0000: 3939 3832 3033 3339 3231 36 Accounting Session Time Attribute (46), length: 6, Value: 20:00 min 0x0000: 0000 04b0 Accounting Input Packets Attribute (47), length: 6, Value: 86528 0x0000: 0001 5200 Accounting Output Packets Attribute (48), length: 6, Value: 170084 0x0000: 0002 9864 Accounting Input Octets Attribute (42), length: 6, Value: 8723193 0x0000: 0085 1af9 Accounting Output Octets Attribute (43), length: 6, Value: 246200999 0x0000: 0eac baa7 Event Timestamp Attribute (55), length: 6, Value: Tue Feb 7 18:58:34 2017 0x0000: 5899 eeaa 19:03:55.228054 IP (tos 0x0, ttl 64, id 11890, offset 0, flags [none], proto UDP (17), length 239) 192.168.0.38.58259 > 192.168.0.1.1813: [udp sum ok] RADIUS, length: 211 Accounting Request (4), id: 0x32, Authenticator: 8bfa38999488fd0e02b3c2218d27536c Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-00000067 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3036 0x0010: 37 Accounting Status Attribute (40), length: 6, Value: Interim-Update 0x0000: 0000 0003 Accounting Authentication Attribute (45), length: 6, Value: RADIUS 0x0000: 0000 0001 Username Attribute (1), length: 8, Value: DIALLO 0x0000: 4449 414c 4c4f NAS ID Attribute (32), length: 16, Value: KAT_8_MERDIVEN 0x0000: 4b41 545f 385f 4d45 5244 4956 454e Called Station Attribute (30), length: 27, Value: DC-9F-DB-34-CF-B4:TDV.NET 0x0000: 4443 2d39 462d 4442 2d33 342d 4346 2d42 0x0010: 343a 5444 562e 4e45 54 NAS Port Type Attribute (61), length: 6, Value: Wireless - IEEE 802.11 0x0000: 0000 0013 NAS Port Attribute (5), length: 6, Value: 0 0x0000: 0000 0000 Calling Station Attribute (31), length: 19, Value: B0-E0-3C-7D-5F-1C 0x0000: 4230 2d45 302d 3343 2d37 442d 3546 2d31 0x0010: 43 Connect Info Attribute (77), length: 23, Value: CONNECT 0Mbps 802.11b 0x0000: 434f 4e4e 4543 5420 304d 6270 7320 3830 0x0010: 322e 3131 62 Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-00000067 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3036 0x0010: 37 Accounting Session Time Attribute (46), length: 6, Value: 30:00 min 0x0000: 0000 0708 Accounting Input Packets Attribute (47), length: 6, Value: 1035 0x0000: 0000 040b Accounting Output Packets Attribute (48), length: 6, Value: 720 0x0000: 0000 02d0 Accounting Input Octets Attribute (42), length: 6, Value: 143517 0x0000: 0002 309d Accounting Output Octets Attribute (43), length: 6, Value: 283570 0x0000: 0004 53b2 Event Timestamp Attribute (55), length: 6, Value: Tue Feb 7 19:03:55 2017 0x0000: 5899 efeb 19:04:21.718225 IP (tos 0x0, ttl 64, id 11896, offset 0, flags [none], proto UDP (17), length 208) 192.168.0.38.58259 > 192.168.0.1.1813: [udp sum ok] RADIUS, length: 180 Accounting Request (4), id: 0x38, Authenticator: c8eb8e5b65aaddedfceb8025ceecb296 Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-00000076 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3037 0x0010: 36 Accounting Status Attribute (40), length: 6, Value: Start 0x0000: 0000 0001 Accounting Authentication Attribute (45), length: 6, Value: RADIUS 0x0000: 0000 0001 Username Attribute (1), length: 13, Value: 11947606194 0x0000: 3131 3934 3736 3036 3139 34 NAS ID Attribute (32), length: 16, Value: KAT_8_MERDIVEN 0x0000: 4b41 545f 385f 4d45 5244 4956 454e Called Station Attribute (30), length: 27, Value: DC-9F-DB-34-CF-B4:TDV.NET 0x0000: 4443 2d39 462d 4442 2d33 342d 4346 2d42 0x0010: 343a 5444 562e 4e45 54 NAS Port Type Attribute (61), length: 6, Value: Wireless - IEEE 802.11 0x0000: 0000 0013 NAS Port Attribute (5), length: 6, Value: 0 0x0000: 0000 0000 Calling Station Attribute (31), length: 19, Value: 9C-5C-F9-4B-C2-E1 0x0000: 3943 2d35 432d 4639 2d34 422d 4332 2d45 0x0010: 31 Connect Info Attribute (77), length: 23, Value: CONNECT 0Mbps 802.11b 0x0000: 434f 4e4e 4543 5420 304d 6270 7320 3830 0x0010: 322e 3131 62 Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-00000076 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3037 0x0010: 36 And user 11947606194 : 19:05:09.093536 IP (tos 0x0, ttl 64, id 11897, offset 0, flags [none], proto UDP (17), length 250) 192.168.0.38.58259 > 192.168.0.1.1813: [udp sum ok] RADIUS, length: 222 Accounting Request (4), id: 0x39, Authenticator: 0fdcd6d168cbd93aa971cba850d62d21 Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-00000076 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3037 0x0010: 36 Accounting Status Attribute (40), length: 6, Value: Stop 0x0000: 0000 0002 Accounting Authentication Attribute (45), length: 6, Value: RADIUS 0x0000: 0000 0001 Username Attribute (1), length: 13, Value: 11947606194 0x0000: 3131 3934 3736 3036 3139 34 NAS ID Attribute (32), length: 16, Value: KAT_8_MERDIVEN 0x0000: 4b41 545f 385f 4d45 5244 4956 454e Called Station Attribute (30), length: 27, Value: DC-9F-DB-34-CF-B4:TDV.NET 0x0000: 4443 2d39 462d 4442 2d33 342d 4346 2d42 0x0010: 343a 5444 562e 4e45 54 NAS Port Type Attribute (61), length: 6, Value: Wireless - IEEE 802.11 0x0000: 0000 0013 NAS Port Attribute (5), length: 6, Value: 0 0x0000: 0000 0000 Calling Station Attribute (31), length: 19, Value: 9C-5C-F9-4B-C2-E1 0x0000: 3943 2d35 432d 4639 2d34 422d 4332 2d45 0x0010: 31 Connect Info Attribute (77), length: 23, Value: CONNECT 0Mbps 802.11b 0x0000: 434f 4e4e 4543 5420 304d 6270 7320 3830 0x0010: 322e 3131 62 Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-00000076 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3037 0x0010: 36 Accounting Session Time Attribute (46), length: 6, Value: 47 secs 0x0000: 0000 002f Accounting Input Packets Attribute (47), length: 6, Value: 412 0x0000: 0000 019c Accounting Output Packets Attribute (48), length: 6, Value: 263 0x0000: 0000 0107 Accounting Input Octets Attribute (42), length: 6, Value: 97791 0x0000: 0001 7dff Accounting Output Octets Attribute (43), length: 6, Value: 156484 0x0000: 0002 6344 Event Timestamp Attribute (55), length: 6, Value: Tue Feb 7 19:05:09 2017 0x0000: 5899 f035 Accounting Termination Cause Attribute (49), length: 6, Value: User Request 0x0000: 0000 0001 19:05:34.031487 IP (tos 0x0, ttl 64, id 11898, offset 0, flags [none], proto UDP (17), length 257) 192.168.0.38.58259 > 192.168.0.1.1813: [udp sum ok] RADIUS, length: 229 Accounting Request (4), id: 0x3a, Authenticator: fbfa93257081e2964aae2b0f46445dd1 Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-00000075 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3037 0x0010: 35 Accounting Status Attribute (40), length: 6, Value: Interim-Update 0x0000: 0000 0003 Accounting Authentication Attribute (45), length: 6, Value: RADIUS 0x0000: 0000 0001 Username Attribute (1), length: 13, Value: 99709507736 0x0000: 3939 3730 3935 3037 3733 36 NAS ID Attribute (32), length: 16, Value: KAT_8_MERDIVEN 0x0000: 4b41 545f 385f 4d45 5244 4956 454e Called Station Attribute (30), length: 27, Value: DC-9F-DB-34-CF-B4:TDV.NET 0x0000: 4443 2d39 462d 4442 2d33 342d 4346 2d42 0x0010: 343a 5444 562e 4e45 54 NAS Port Type Attribute (61), length: 6, Value: Wireless - IEEE 802.11 0x0000: 0000 0013 NAS Port Attribute (5), length: 6, Value: 0 0x0000: 0000 0000 Calling Station Attribute (31), length: 19, Value: EC-9B-F3-48-BD-70 0x0000: 4543 2d39 422d 4633 2d34 382d 4244 2d37 0x0010: 30 Connect Info Attribute (77), length: 23, Value: CONNECT 0Mbps 802.11b 0x0000: 434f 4e4e 4543 5420 304d 6270 7320 3830 0x0010: 322e 3131 62 Accounting Session ID Attribute (44), length: 19, Value: 5899CA79-00000075 0x0000: 3538 3939 4341 3739 2d30 3030 3030 3037 0x0010: 35 Class Attribute (25), length: 13, Value: 99709507736 0x0000: 3939 3730 3935 3037 3733 36 Accounting Session Time Attribute (46), length: 6, Value: 10:00 min 0x0000: 0000 0258 Accounting Input Packets Attribute (47), length: 6, Value: 4316 0x0000: 0000 10dc Accounting Output Packets Attribute (48), length: 6, Value: 4462 0x0000: 0000 116e Accounting Input Octets Attribute (42), length: 6, Value: 400013 0x0000: 0006 1a8d Accounting Output Octets Attribute (43), length: 6, Value: 5071812 0x0000: 004d 63c4 Event Timestamp Attribute (55), length: 6, Value: Tue Feb 7 19:05:34 2017 0x0000: 5899 f04e Does anyone have any idea why this is happening? --- This email has been checked for viruses by Avast antivirus software. https://www.avast.com/antivirus

3 8

Option to respond with a different pool in Freeradius DHCP based on interface
by Nataniel Klug 07 Feb '17

07 Feb '17

Hello, I am running a Freeradius DHCP and I want to use the same Freeradius server to serve different pools on different interfaces but I am not seeing a way to make that happen. I was thinking on use the update-control but I was not able to find a way to make it. Scenario is like this: eth1 - 10.192.0.0/10 (pool name "dhcp_ftth") - working just fine eth2 - 10.10.0.024 (pool name "management") Both pools are in a MySQL database. Any ideas on how to make it? Bellow I am posting the result of the "radiusd -Xx" for a request I received: Tue Feb 7 11:35:37 2017 : Debug: radiusd: #### Opening IP addresses and Ports #### Tue Feb 7 11:35:37 2017 : Debug: listen { Tue Feb 7 11:35:37 2017 : Debug: type = "dhcp" Tue Feb 7 11:35:37 2017 : Debug: ipaddr = * Tue Feb 7 11:35:37 2017 : Debug: port = 67 Tue Feb 7 11:35:37 2017 : Debug: } Tue Feb 7 11:35:37 2017 : Debug: Listening on dhcp interface eth1 address * port 67 bound to server dhcp Tue Feb 7 11:35:37 2017 : Info: Ready to process requests Received DHCP-Discover of Id 130b66cc from 0.0.0.0:68 to 255.255.255.255:67 0: 01 01 06 00 13 0b 66 cc 00 00 80 00 00 00 00 00 16: 00 00 00 00 00 00 00 00 00 00 00 00 00 50 56 b8 32: 2c 62 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 01 37 06 01 79 03 21 06 2a 0c 08 4d 69 6b 256: 72 6f 54 69 6b 3d 07 01 00 50 56 b8 2c 62 ff 00 272: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 288: 00 00 00 00 00 00 00 00 00 00 00 00 DHCP-Opcode = Client-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 0 DHCP-Transaction-Id = 319514316 DHCP-Number-of-Seconds = 0 DHCP-Flags = Broadcast DHCP-Client-IP-Address = 0.0.0.0 DHCP-Your-IP-Address = 0.0.0.0 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 0.0.0.0 DHCP-Client-Hardware-Address = 00:50:56:b8:2c:62 DHCP-Message-Type = DHCP-Discover DHCP-Parameter-Request-List = DHCP-Subnet-Mask DHCP-Parameter-Request-List = DHCP-Classless-Static-Route DHCP-Parameter-Request-List = DHCP-Router-Address DHCP-Parameter-Request-List = DHCP-Static-Routes DHCP-Parameter-Request-List = DHCP-Domain-Name-Server DHCP-Parameter-Request-List = DHCP-NTP-Servers DHCP-Hostname = "MikroTik" DHCP-Client-Identifier = 0x01005056b82c62 Tue Feb 7 11:35:41 2017 : Debug: (0) Received code 1025 Id 319514316 from 0.0.0.0:68 to 255.255.255.255:67 length 300 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Opcode = Client-Message Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Hardware-Type = Ethernet Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Hardware-Address-Length = 6 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Hop-Count = 0 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Transaction-Id = 319514316 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Number-of-Seconds = 0 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Flags = Broadcast Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Client-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Your-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Server-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Gateway-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Client-Hardware-Address = 00:50:56:b8:2c:62 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Message-Type = DHCP-Discover Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Parameter-Request-List = DHCP-Subnet-Mask Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Parameter-Request-List = DHCP-Classless-Static-Route Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Parameter-Request-List = DHCP-Router-Address Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Parameter-Request-List = DHCP-Static-Routes Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Parameter-Request-List = DHCP-Domain-Name-Server Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Parameter-Request-List = DHCP-NTP-Servers Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Hostname = "MikroTik" Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Client-Identifier = 0x01005056b82c62 Tue Feb 7 11:35:41 2017 : Debug: Trying sub-section dhcp DHCP-Discover {...} Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp DHCP-Discover { Tue Feb 7 11:35:41 2017 : Debug: (0) update reply { Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Message-Type = DHCP-Offer Tue Feb 7 11:35:41 2017 : Debug: (0) } # update reply = noop Tue Feb 7 11:35:41 2017 : Debug: (0) update reply { Tue Feb 7 11:35:41 2017 : Debug: (0) &DHCP-Domain-Name-Server = 186.251.148.22 Tue Feb 7 11:35:41 2017 : Debug: (0) &DHCP-Domain-Name-Server += 186.251.148.21 Tue Feb 7 11:35:41 2017 : Debug: (0) &DHCP-Subnet-Mask = 255.192.0.0 Tue Feb 7 11:35:41 2017 : Debug: (0) &DHCP-Router-Address = 10.192.0.1 Tue Feb 7 11:35:41 2017 : Debug: (0) &DHCP-IP-Address-Lease-Time = 86400 Tue Feb 7 11:35:41 2017 : Debug: (0) &DHCP-DHCP-Server-Identifier = 10.192.0.5 Tue Feb 7 11:35:41 2017 : Debug: (0) &DHCP-NTP-Servers = 186.251.148.3 Tue Feb 7 11:35:41 2017 : Debug: (0) &DHCP-NTP-Servers += 186.251.148.2 Tue Feb 7 11:35:41 2017 : Debug: (0) } # update reply = noop Tue Feb 7 11:35:41 2017 : Debug: (0) update control { Tue Feb 7 11:35:41 2017 : Debug: (0) &Pool-Name := "dhcp_ftth" Tue Feb 7 11:35:41 2017 : Debug: (0) } # update control = noop Tue Feb 7 11:35:41 2017 : Debug: (0) policy dhcp_sqlippool.post-auth { Tue Feb 7 11:35:41 2017 : Debug: (0) update request { Tue Feb 7 11:35:41 2017 : Debug: (0) EXPAND DHCP-%{DHCP-Client-Hardware-Address} Tue Feb 7 11:35:41 2017 : Debug: (0) --> DHCP-00:50:56:b8:2c:62 Tue Feb 7 11:35:41 2017 : Debug: (0) &User-Name = DHCP-00:50:56:b8:2c:62 Tue Feb 7 11:35:41 2017 : Debug: (0) EXPAND %{DHCP-Client-Hardware-Address} Tue Feb 7 11:35:41 2017 : Debug: (0) --> 00:50:56:b8:2c:62 Tue Feb 7 11:35:41 2017 : Debug: (0) &Calling-Station-Id = 00:50:56:b8:2c:62 Tue Feb 7 11:35:41 2017 : Debug: (0) EXPAND %{%{DHCP-Gateway-IP-Address}:-127.0.0.1} Tue Feb 7 11:35:41 2017 : Debug: (0) --> 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (0) &NAS-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (0) &Acct-Status-Type = Start Tue Feb 7 11:35:41 2017 : Debug: (0) } # update request = noop Tue Feb 7 11:35:41 2017 : Debug: (0) modsingle[post-auth]: calling dhcp_sqlippool (rlm_sqlippool) Tue Feb 7 11:35:41 2017 : Debug: rlm_sql (sql): Reserved connection (0) Tue Feb 7 11:35:41 2017 : Debug: START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: Parsed xlat tree: Tue Feb 7 11:35:41 2017 : Debug: literal --> START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: EXPAND START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: --> START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: Executing query: START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: UPDATE dhcp SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NOW() WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress = '%{Nas-IP-Address}' Tue Feb 7 11:35:41 2017 : Debug: Parsed xlat tree: Tue Feb 7 11:35:41 2017 : Debug: literal --> UPDATE dhcp SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NOW() WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> NAS-IP-Address Tue Feb 7 11:35:41 2017 : Debug: literal --> ' Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: EXPAND UPDATE dhcp SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NOW() WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress = '%{Nas-IP-Address}' Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: --> UPDATE dhcp SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NOW() WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress = '0.0.0.0' Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: Executing query: UPDATE dhcp SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NOW() WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress = '0.0.0.0' Tue Feb 7 11:35:41 2017 : Debug: rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0 Tue Feb 7 11:35:41 2017 : Debug: COMMIT Tue Feb 7 11:35:41 2017 : Debug: Parsed xlat tree: Tue Feb 7 11:35:41 2017 : Debug: literal --> COMMIT Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: EXPAND COMMIT Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: --> COMMIT Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: Executing query: COMMIT Tue Feb 7 11:35:41 2017 : Debug: START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: Parsed xlat tree: Tue Feb 7 11:35:41 2017 : Debug: literal --> START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: EXPAND START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: --> START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: Executing query: START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: SELECT framedipaddress FROM dhcp WHERE pool_name = '%{control:Pool-Name}' AND (callingstationid = '%{Calling-Station-Id}' or callingstationid = '') ORDER BY (callingstationid <> '%{Calling-Station-Id}'), expiry_time LIMIT 1 FOR UPDATE Tue Feb 7 11:35:41 2017 : Debug: Parsed xlat tree: Tue Feb 7 11:35:41 2017 : Debug: literal --> SELECT framedipaddress FROM dhcp WHERE pool_name = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> Pool-Name Tue Feb 7 11:35:41 2017 : Debug: literal --> ' AND (callingstationid = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> Calling-Station-Id Tue Feb 7 11:35:41 2017 : Debug: literal --> ' or callingstationid = '') ORDER BY (callingstationid <> ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> Calling-Station-Id Tue Feb 7 11:35:41 2017 : Debug: literal --> '), expiry_time LIMIT 1 FOR UPDATE Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: EXPAND SELECT framedipaddress FROM dhcp WHERE pool_name = '%{control:Pool-Name}' AND (callingstationid = '%{Calling-Station-Id}' or callingstationid = '') ORDER BY (callingstationid <> '%{Calling-Station-Id}'), expiry_time LIMIT 1 FOR UPDATE Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: --> SELECT framedipaddress FROM dhcp WHERE pool_name = 'dhcp_ftth' AND (callingstationid = '00:50:56:b8:2c:62' or callingstationid = '') ORDER BY (callingstationid <> '00:50:56:b8:2c:62'), expiry_time LIMIT 1 FOR UPDATE Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: Executing select query: SELECT framedipaddress FROM dhcp WHERE pool_name = 'dhcp_ftth' AND (callingstationid = '00:50:56:b8:2c:62' or callingstationid = '') ORDER BY (callingstationid <> '00:50:56:b8:2c:62'), expiry_time LIMIT 1 FOR UPDATE Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: Allocated IP 10.192.1.1 Tue Feb 7 11:35:41 2017 : Debug: UPDATE dhcp SET nasipaddress = '%{NAS-IP-Address}', pool_key = '%{Calling-Station-Id}', callingstationid = '%{Calling-Station-Id}', username = '%{User-Name}', expiry_time = NOW() + INTERVAL 86400 SECOND WHERE framedipaddress = '10.192.1.1' Tue Feb 7 11:35:41 2017 : Debug: Parsed xlat tree: Tue Feb 7 11:35:41 2017 : Debug: literal --> UPDATE dhcp SET nasipaddress = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> NAS-IP-Address Tue Feb 7 11:35:41 2017 : Debug: literal --> ', pool_key = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> Calling-Station-Id Tue Feb 7 11:35:41 2017 : Debug: literal --> ', callingstationid = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> Calling-Station-Id Tue Feb 7 11:35:41 2017 : Debug: literal --> ', username = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> User-Name Tue Feb 7 11:35:41 2017 : Debug: literal --> ', expiry_time = NOW() + INTERVAL 86400 SECOND WHERE framedipaddress = '10.192.1.1' Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: EXPAND UPDATE dhcp SET nasipaddress = '%{NAS-IP-Address}', pool_key = '%{Calling-Station-Id}', callingstationid = '%{Calling-Station-Id}', username = '%{User-Name}', expiry_time = NOW() + INTERVAL 86400 SECOND WHERE framedipaddress = '10.192.1.1' Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: --> UPDATE dhcp SET nasipaddress = '0.0.0.0', pool_key = '00:50:56:b8:2c:62', callingstationid = '00:50:56:b8:2c:62', username = 'DHCP-00:50:56:b8:2c:62', expiry_time = NOW() + INTERVAL 86400 SECOND WHERE framedipaddress = '10.192.1.1' Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: Executing query: UPDATE dhcp SET nasipaddress = '0.0.0.0', pool_key = '00:50:56:b8:2c:62', callingstationid = '00:50:56:b8:2c:62', username = 'DHCP-00:50:56:b8:2c:62', expiry_time = NOW() + INTERVAL 86400 SECOND WHERE framedipaddress = '10.192.1.1' Tue Feb 7 11:35:41 2017 : Debug: rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0 Tue Feb 7 11:35:41 2017 : Debug: COMMIT Tue Feb 7 11:35:41 2017 : Debug: Parsed xlat tree: Tue Feb 7 11:35:41 2017 : Debug: literal --> COMMIT Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: EXPAND COMMIT Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: --> COMMIT Tue Feb 7 11:35:41 2017 : Debug: (0) dhcp_sqlippool: Executing query: COMMIT Tue Feb 7 11:35:41 2017 : Debug: rlm_sql (sql): Released connection (0) Tue Feb 7 11:35:41 2017 : Info: rlm_sql (sql): Need 5 more connections to reach 10 spares Tue Feb 7 11:35:41 2017 : Info: rlm_sql (sql): Opening additional connection (5), 1 of 27 pending slots used Tue Feb 7 11:35:41 2017 : Debug: rlm_sql_mysql: Starting connect to MySQL server Tue Feb 7 11:35:41 2017 : Debug: rlm_sql_mysql: Connected to database 'acs' on 172.31.255.63 via TCP/IP, server version 5.5.5-10.0.0 2.0.3-maxscale, protocol version 10 Tue Feb 7 11:35:41 2017 : Debug: (0) modsingle[post-auth]: returned from dhcp_sqlippool (rlm_sqlippool) Tue Feb 7 11:35:41 2017 : Debug: (0) [dhcp_sqlippool] = ok Tue Feb 7 11:35:41 2017 : Debug: (0) if (ok) { Tue Feb 7 11:35:41 2017 : Debug: (0) if (ok) -> TRUE Tue Feb 7 11:35:41 2017 : Debug: (0) if (ok) { Tue Feb 7 11:35:41 2017 : Debug: (0) update reply { Tue Feb 7 11:35:41 2017 : Debug: (0) EXPAND %{reply:Framed-IP-Address} Tue Feb 7 11:35:41 2017 : Debug: (0) --> 10.192.1.1 Tue Feb 7 11:35:41 2017 : Debug: (0) &DHCP-Your-IP-Address = 10.192.1.1 Tue Feb 7 11:35:41 2017 : Debug: (0) } # update reply = noop Tue Feb 7 11:35:41 2017 : Debug: (0) } # if (ok) = noop Tue Feb 7 11:35:41 2017 : Debug: (0) } # policy dhcp_sqlippool.post-auth = ok Tue Feb 7 11:35:41 2017 : Debug: (0) modsingle[post-auth]: calling ok (rlm_always) Tue Feb 7 11:35:41 2017 : Debug: (0) modsingle[post-auth]: returned from ok (rlm_always) Tue Feb 7 11:35:41 2017 : Debug: (0) [ok] = ok Tue Feb 7 11:35:41 2017 : Debug: (0) } # dhcp DHCP-Discover = ok Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP: Reply will be broadcast Tue Feb 7 11:35:41 2017 : Debug: (0) Sent code 1026 Id 319514316 from 10.192.0.5:67 to 255.255.255.255:68 length 0 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Message-Type = DHCP-Offer Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Domain-Name-Server = 186.251.148.22 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Domain-Name-Server += 186.251.148.21 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Subnet-Mask = 255.192.0.0 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Router-Address = 10.192.0.1 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-IP-Address-Lease-Time = 86400 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-DHCP-Server-Identifier = 10.192.0.5 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-NTP-Servers = 186.251.148.3 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-NTP-Servers += 186.251.148.2 Tue Feb 7 11:35:41 2017 : Debug: (0) Framed-IP-Address = 10.192.1.1 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Your-IP-Address = 10.192.1.1 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Opcode = Server-Message Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Hardware-Type = Ethernet Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Hardware-Address-Length = 6 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Hop-Count = 0 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Transaction-Id = 319514316 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Flags = Broadcast Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Client-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Gateway-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (0) DHCP-Client-Hardware-Address = 00:50:56:b8:2c:62 DHCP-Opcode = Server-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 0 DHCP-Transaction-Id = 319514316 DHCP-Number-of-Seconds = 0 DHCP-Flags = Broadcast DHCP-Client-IP-Address = 0.0.0.0 DHCP-Your-IP-Address = 10.192.1.1 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 0.0.0.0 DHCP-Client-Hardware-Address = 00:50:56:b8:2c:62 DHCP-Server-Host-Name = "" DHCP-Boot-Filename = "" DHCP-Subnet-Mask = 255.192.0.0 DHCP-Router-Address = 10.192.0.1 DHCP-Domain-Name-Server = 186.251.148.22 DHCP-Domain-Name-Server += 186.251.148.21 DHCP-NTP-Servers = 186.251.148.3 DHCP-NTP-Servers += 186.251.148.2 DHCP-IP-Address-Lease-Time = 86400 DHCP-DHCP-Server-Identifier = 10.192.0.5 DHCP Sending 300 bytes 0: 02 01 06 00 13 0b 66 cc 00 00 80 00 00 00 00 00 16: 0a c0 01 01 00 00 00 00 00 00 00 00 00 50 56 b8 32: 2c 62 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 02 01 04 ff c0 00 00 03 04 0a c0 00 01 06 256: 08 ba fb 94 16 ba fb 94 15 2a 08 ba fb 94 03 ba 272: fb 94 02 33 04 00 01 51 80 36 04 0a c0 00 05 ff 288: 00 00 00 00 00 00 00 00 00 00 00 00 Sending DHCP-Offer Id 130b66cc from 10.192.0.5:67 to 255.255.255.255:68 Tue Feb 7 11:35:41 2017 : Debug: (0) Finished request Tue Feb 7 11:35:41 2017 : Debug: (0) Cleaning up request packet ID 319514316 with timestamp +4 Tue Feb 7 11:35:41 2017 : Info: Ready to process requests Received DHCP-Request of Id 130b66cc from 0.0.0.0:68 to 255.255.255.255:67 0: 01 01 06 00 13 0b 66 cc 00 00 80 00 00 00 00 00 16: 00 00 00 00 00 00 00 00 00 00 00 00 00 50 56 b8 32: 2c 62 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 03 36 04 0a c0 00 05 32 04 0a c0 01 01 37 256: 06 01 79 03 21 06 2a 0c 08 4d 69 6b 72 6f 54 69 272: 6b 3d 07 01 00 50 56 b8 2c 62 ff 00 00 00 00 00 288: 00 00 00 00 00 00 00 00 00 00 00 00 DHCP-Opcode = Client-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 0 DHCP-Transaction-Id = 319514316 DHCP-Number-of-Seconds = 0 DHCP-Flags = Broadcast DHCP-Client-IP-Address = 0.0.0.0 DHCP-Your-IP-Address = 0.0.0.0 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 0.0.0.0 DHCP-Client-Hardware-Address = 00:50:56:b8:2c:62 DHCP-Message-Type = DHCP-Request DHCP-DHCP-Server-Identifier = 10.192.0.5 DHCP-Requested-IP-Address = 10.192.1.1 DHCP-Parameter-Request-List = DHCP-Subnet-Mask DHCP-Parameter-Request-List = DHCP-Classless-Static-Route DHCP-Parameter-Request-List = DHCP-Router-Address DHCP-Parameter-Request-List = DHCP-Static-Routes DHCP-Parameter-Request-List = DHCP-Domain-Name-Server DHCP-Parameter-Request-List = DHCP-NTP-Servers DHCP-Hostname = "MikroTik" DHCP-Client-Identifier = 0x01005056b82c62 Tue Feb 7 11:35:41 2017 : Debug: (1) Received code 1027 Id 319514316 from 0.0.0.0:68 to 255.255.255.255:67 length 300 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Opcode = Client-Message Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Hardware-Type = Ethernet Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Hardware-Address-Length = 6 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Hop-Count = 0 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Transaction-Id = 319514316 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Number-of-Seconds = 0 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Flags = Broadcast Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Client-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Your-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Server-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Gateway-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Client-Hardware-Address = 00:50:56:b8:2c:62 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Message-Type = DHCP-Request Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-DHCP-Server-Identifier = 10.192.0.5 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Requested-IP-Address = 10.192.1.1 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Parameter-Request-List = DHCP-Subnet-Mask Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Parameter-Request-List = DHCP-Classless-Static-Route Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Parameter-Request-List = DHCP-Router-Address Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Parameter-Request-List = DHCP-Static-Routes Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Parameter-Request-List = DHCP-Domain-Name-Server Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Parameter-Request-List = DHCP-NTP-Servers Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Hostname = "MikroTik" Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Client-Identifier = 0x01005056b82c62 Tue Feb 7 11:35:41 2017 : Debug: Trying sub-section dhcp DHCP-Request {...} Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp DHCP-Request { Tue Feb 7 11:35:41 2017 : Debug: (1) update reply { Tue Feb 7 11:35:41 2017 : Debug: (1) &DHCP-Message-Type = DHCP-Ack Tue Feb 7 11:35:41 2017 : Debug: (1) } # update reply = noop Tue Feb 7 11:35:41 2017 : Debug: (1) update reply { Tue Feb 7 11:35:41 2017 : Debug: (1) &DHCP-Domain-Name-Server = 186.251.148.22 Tue Feb 7 11:35:41 2017 : Debug: (1) &DHCP-Domain-Name-Server += 186.251.148.21 Tue Feb 7 11:35:41 2017 : Debug: (1) &DHCP-Subnet-Mask = 255.192.0.0 Tue Feb 7 11:35:41 2017 : Debug: (1) &DHCP-Router-Address = 10.192.0.1 Tue Feb 7 11:35:41 2017 : Debug: (1) &DHCP-IP-Address-Lease-Time = 86400 Tue Feb 7 11:35:41 2017 : Debug: (1) &DHCP-DHCP-Server-Identifier = 10.192.0.5 Tue Feb 7 11:35:41 2017 : Debug: (1) &DHCP-NTP-Servers = 186.251.148.3 Tue Feb 7 11:35:41 2017 : Debug: (1) &DHCP-NTP-Servers += 186.251.148.2 Tue Feb 7 11:35:41 2017 : Debug: (1) } # update reply = noop Tue Feb 7 11:35:41 2017 : Debug: (1) update control { Tue Feb 7 11:35:41 2017 : Debug: (1) &Pool-Name := "dhcp_ftth" Tue Feb 7 11:35:41 2017 : Debug: (1) } # update control = noop Tue Feb 7 11:35:41 2017 : Debug: (1) policy dhcp_sqlippool.post-auth { Tue Feb 7 11:35:41 2017 : Debug: (1) update request { Tue Feb 7 11:35:41 2017 : Debug: (1) EXPAND DHCP-%{DHCP-Client-Hardware-Address} Tue Feb 7 11:35:41 2017 : Debug: (1) --> DHCP-00:50:56:b8:2c:62 Tue Feb 7 11:35:41 2017 : Debug: (1) &User-Name = DHCP-00:50:56:b8:2c:62 Tue Feb 7 11:35:41 2017 : Debug: (1) EXPAND %{DHCP-Client-Hardware-Address} Tue Feb 7 11:35:41 2017 : Debug: (1) --> 00:50:56:b8:2c:62 Tue Feb 7 11:35:41 2017 : Debug: (1) &Calling-Station-Id = 00:50:56:b8:2c:62 Tue Feb 7 11:35:41 2017 : Debug: (1) EXPAND %{%{DHCP-Gateway-IP-Address}:-127.0.0.1} Tue Feb 7 11:35:41 2017 : Debug: (1) --> 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (1) &NAS-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (1) &Acct-Status-Type = Start Tue Feb 7 11:35:41 2017 : Debug: (1) } # update request = noop Tue Feb 7 11:35:41 2017 : Debug: (1) modsingle[post-auth]: calling dhcp_sqlippool (rlm_sqlippool) Tue Feb 7 11:35:41 2017 : Debug: rlm_sql (sql): Reserved connection (1) Tue Feb 7 11:35:41 2017 : Debug: START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: Parsed xlat tree: Tue Feb 7 11:35:41 2017 : Debug: literal --> START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: EXPAND START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: --> START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: Executing query: START TRANSACTION Tue Feb 7 11:35:41 2017 : Debug: SELECT framedipaddress FROM dhcp WHERE pool_name = '%{control:Pool-Name}' AND (callingstationid = '%{Calling-Station-Id}' or callingstationid = '') ORDER BY (callingstationid <> '%{Calling-Station-Id}'), expiry_time LIMIT 1 FOR UPDATE Tue Feb 7 11:35:41 2017 : Debug: Parsed xlat tree: Tue Feb 7 11:35:41 2017 : Debug: literal --> SELECT framedipaddress FROM dhcp WHERE pool_name = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> Pool-Name Tue Feb 7 11:35:41 2017 : Debug: literal --> ' AND (callingstationid = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> Calling-Station-Id Tue Feb 7 11:35:41 2017 : Debug: literal --> ' or callingstationid = '') ORDER BY (callingstationid <> ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> Calling-Station-Id Tue Feb 7 11:35:41 2017 : Debug: literal --> '), expiry_time LIMIT 1 FOR UPDATE Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: EXPAND SELECT framedipaddress FROM dhcp WHERE pool_name = '%{control:Pool-Name}' AND (callingstationid = '%{Calling-Station-Id}' or callingstationid = '') ORDER BY (callingstationid <> '%{Calling-Station-Id}'), expiry_time LIMIT 1 FOR UPDATE Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: --> SELECT framedipaddress FROM dhcp WHERE pool_name = 'dhcp_ftth' AND (callingstationid = '00:50:56:b8:2c:62' or callingstationid = '') ORDER BY (callingstationid <> '00:50:56:b8:2c:62'), expiry_time LIMIT 1 FOR UPDATE Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: Executing select query: SELECT framedipaddress FROM dhcp WHERE pool_name = 'dhcp_ftth' AND (callingstationid = '00:50:56:b8:2c:62' or callingstationid = '') ORDER BY (callingstationid <> '00:50:56:b8:2c:62'), expiry_time LIMIT 1 FOR UPDATE Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: Allocated IP 10.192.1.1 Tue Feb 7 11:35:41 2017 : Debug: UPDATE dhcp SET nasipaddress = '%{NAS-IP-Address}', pool_key = '%{Calling-Station-Id}', callingstationid = '%{Calling-Station-Id}', username = '%{User-Name}', expiry_time = NOW() + INTERVAL 86400 SECOND WHERE framedipaddress = '10.192.1.1' Tue Feb 7 11:35:41 2017 : Debug: Parsed xlat tree: Tue Feb 7 11:35:41 2017 : Debug: literal --> UPDATE dhcp SET nasipaddress = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> NAS-IP-Address Tue Feb 7 11:35:41 2017 : Debug: literal --> ', pool_key = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> Calling-Station-Id Tue Feb 7 11:35:41 2017 : Debug: literal --> ', callingstationid = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> Calling-Station-Id Tue Feb 7 11:35:41 2017 : Debug: literal --> ', username = ' Tue Feb 7 11:35:41 2017 : Debug: attribute --> User-Name Tue Feb 7 11:35:41 2017 : Debug: literal --> ', expiry_time = NOW() + INTERVAL 86400 SECOND WHERE framedipaddress = '10.192.1.1' Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: EXPAND UPDATE dhcp SET nasipaddress = '%{NAS-IP-Address}', pool_key = '%{Calling-Station-Id}', callingstationid = '%{Calling-Station-Id}', username = '%{User-Name}', expiry_time = NOW() + INTERVAL 86400 SECOND WHERE framedipaddress = '10.192.1.1' Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: --> UPDATE dhcp SET nasipaddress = '0.0.0.0', pool_key = '00:50:56:b8:2c:62', callingstationid = '00:50:56:b8:2c:62', username = 'DHCP-00:50:56:b8:2c:62', expiry_time = NOW() + INTERVAL 86400 SECOND WHERE framedipaddress = '10.192.1.1' Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: Executing query: UPDATE dhcp SET nasipaddress = '0.0.0.0', pool_key = '00:50:56:b8:2c:62', callingstationid = '00:50:56:b8:2c:62', username = 'DHCP-00:50:56:b8:2c:62', expiry_time = NOW() + INTERVAL 86400 SECOND WHERE framedipaddress = '10.192.1.1' Tue Feb 7 11:35:41 2017 : Debug: rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0 Tue Feb 7 11:35:41 2017 : Debug: COMMIT Tue Feb 7 11:35:41 2017 : Debug: Parsed xlat tree: Tue Feb 7 11:35:41 2017 : Debug: literal --> COMMIT Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: EXPAND COMMIT Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: --> COMMIT Tue Feb 7 11:35:41 2017 : Debug: (1) dhcp_sqlippool: Executing query: COMMIT Tue Feb 7 11:35:41 2017 : Debug: rlm_sql (sql): Released connection (1) Tue Feb 7 11:35:41 2017 : Debug: (1) modsingle[post-auth]: returned from dhcp_sqlippool (rlm_sqlippool) Tue Feb 7 11:35:41 2017 : Debug: (1) [dhcp_sqlippool] = ok Tue Feb 7 11:35:41 2017 : Debug: (1) if (ok) { Tue Feb 7 11:35:41 2017 : Debug: (1) if (ok) -> TRUE Tue Feb 7 11:35:41 2017 : Debug: (1) if (ok) { Tue Feb 7 11:35:41 2017 : Debug: (1) update reply { Tue Feb 7 11:35:41 2017 : Debug: (1) EXPAND %{reply:Framed-IP-Address} Tue Feb 7 11:35:41 2017 : Debug: (1) --> 10.192.1.1 Tue Feb 7 11:35:41 2017 : Debug: (1) &DHCP-Your-IP-Address = 10.192.1.1 Tue Feb 7 11:35:41 2017 : Debug: (1) } # update reply = noop Tue Feb 7 11:35:41 2017 : Debug: (1) } # if (ok) = noop Tue Feb 7 11:35:41 2017 : Debug: (1) } # policy dhcp_sqlippool.post-auth = ok Tue Feb 7 11:35:41 2017 : Debug: (1) modsingle[post-auth]: calling ok (rlm_always) Tue Feb 7 11:35:41 2017 : Debug: (1) modsingle[post-auth]: returned from ok (rlm_always) Tue Feb 7 11:35:41 2017 : Debug: (1) [ok] = ok Tue Feb 7 11:35:41 2017 : Debug: (1) } # dhcp DHCP-Request = ok Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP: Reply will be broadcast Tue Feb 7 11:35:41 2017 : Debug: (1) Sent code 1029 Id 319514316 from 10.192.0.5:67 to 255.255.255.255:68 length 0 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Message-Type = DHCP-Ack Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Domain-Name-Server = 186.251.148.22 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Domain-Name-Server += 186.251.148.21 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Subnet-Mask = 255.192.0.0 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Router-Address = 10.192.0.1 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-IP-Address-Lease-Time = 86400 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-DHCP-Server-Identifier = 10.192.0.5 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-NTP-Servers = 186.251.148.3 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-NTP-Servers += 186.251.148.2 Tue Feb 7 11:35:41 2017 : Debug: (1) Framed-IP-Address = 10.192.1.1 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Your-IP-Address = 10.192.1.1 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Opcode = Server-Message Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Hardware-Type = Ethernet Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Hardware-Address-Length = 6 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Hop-Count = 0 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Transaction-Id = 319514316 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Flags = Broadcast Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Client-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Gateway-IP-Address = 0.0.0.0 Tue Feb 7 11:35:41 2017 : Debug: (1) DHCP-Client-Hardware-Address = 00:50:56:b8:2c:62 DHCP-Opcode = Server-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 0 DHCP-Transaction-Id = 319514316 DHCP-Number-of-Seconds = 0 DHCP-Flags = Broadcast DHCP-Client-IP-Address = 0.0.0.0 DHCP-Your-IP-Address = 10.192.1.1 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 0.0.0.0 DHCP-Client-Hardware-Address = 00:50:56:b8:2c:62 DHCP-Server-Host-Name = "" DHCP-Boot-Filename = "" DHCP-Subnet-Mask = 255.192.0.0 DHCP-Router-Address = 10.192.0.1 DHCP-Domain-Name-Server = 186.251.148.22 DHCP-Domain-Name-Server += 186.251.148.21 DHCP-NTP-Servers = 186.251.148.3 DHCP-NTP-Servers += 186.251.148.2 DHCP-IP-Address-Lease-Time = 86400 DHCP-DHCP-Server-Identifier = 10.192.0.5 DHCP Sending 300 bytes 0: 02 01 06 00 13 0b 66 cc 00 00 80 00 00 00 00 00 16: 0a c0 01 01 00 00 00 00 00 00 00 00 00 50 56 b8 32: 2c 62 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 05 01 04 ff c0 00 00 03 04 0a c0 00 01 06 256: 08 ba fb 94 16 ba fb 94 15 2a 08 ba fb 94 03 ba 272: fb 94 02 33 04 00 01 51 80 36 04 0a c0 00 05 ff 288: 00 00 00 00 00 00 00 00 00 00 00 00 Sending DHCP-Ack Id 130b66cc from 10.192.0.5:67 to 255.255.255.255:68 Tue Feb 7 11:35:41 2017 : Debug: (1) Finished request Tue Feb 7 11:35:41 2017 : Debug: (1) Cleaning up request packet ID 319514316 with timestamp +4 Tue Feb 7 11:35:41 2017 : Info: Ready to process requests Atenciosamente, *Nataniel Klug* | nataniel.klug(a)gmail.com

2 4

Problem making certs
by Joe Price 07 Feb '17

07 Feb '17

Hello: I'm new to Freeradius and to Linux (Ubuntu Server 16.04) as well. I've got my first server up and running Freeradius v3 and can successfully authorize users on my network with a username and password. Works great and was easy to do. My AXis ipCCTV cameras require EAP-TLS and this is where I'm stuck. My clients require a CA Certificate, a Client cert and private key, an EAP identity and Private key password for the EAP identity. I'm not exactly sure where all this comes from. I can't get "make" or "make client" to do anything other than give me a "No targets specified and no makefile found" error. How do I complete the jump to EAP-TLS? Any guides online? Thanks, Joe

4 3

buffered-sql problem
by Jouni Soini 07 Feb '17

07 Feb '17

there seems to be a problem with buffered-sql it sometimes doesn't pick the accounting request from detail file and just skip it. this happens once in a few million requests and I had to debug and monitor this for several days to find one (looking for a user who remains online) nothing special exists in debug logs. the accounting request is logged to detail file but the sql statement part doesn't exits. following is the debug logs as you can see the accounting request is logged to detail file (in my tests to two separate files for extra monitoring) but it is not sent to sql database tested with 3.0.12 version on Ubuntu 16.04 as you can see the sql query for user 'test1' is skipped (494090) Wed Jan 25 12:04:10 2017: Debug: Received Accounting-Request Id 188 from 82.21.11.91:28850 to 82.21.11.50:1813 length 107 (494090) Wed Jan 25 12:04:10 2017: Debug: User-Name = "test1" (494090) Wed Jan 25 12:04:10 2017: Debug: NAS-IP-Address = 82.21.11.91 (494090) Wed Jan 25 12:04:10 2017: Debug: NAS-Port = 23449 (494090) Wed Jan 25 12:04:10 2017: Debug: Acct-Status-Type = Stop (494090) Wed Jan 25 12:04:10 2017: Debug: Framed-IP-Address = 10.8.0.98 (494090) Wed Jan 25 12:04:10 2017: Debug: Acct-Input-Gigawords = 0 (494090) Wed Jan 25 12:04:10 2017: Debug: Acct-Input-Octets = 8323 (494090) Wed Jan 25 12:04:10 2017: Debug: Acct-Output-Octets = 8111 (494090) Wed Jan 25 12:04:10 2017: Debug: Acct-Session-Id = "68r3xt2pb8y8" (494090) Wed Jan 25 12:04:10 2017: Debug: Acct-Output-Gigawords = 0 (494090) Wed Jan 25 12:04:10 2017: Debug: Calling-Station-Id = "127.0.0.1" (494090) Wed Jan 25 12:04:10 2017: Debug: # Executing section preacct from file /etc/freeradius/sites-enabled/default (494090) Wed Jan 25 12:04:10 2017: Debug: preacct { (494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[preacct]: calling preprocess (rlm_preprocess) (494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[preacct]: returned from preprocess (rlm_preprocess) (494090) Wed Jan 25 12:04:10 2017: Debug: [preprocess] = ok (494090) Wed Jan 25 12:04:10 2017: Debug: policy acct_unique { (494090) Wed Jan 25 12:04:10 2017: Debug: update request { (494090) Wed Jan 25 12:04:10 2017: Debug: Tmp-String-9 := "ai:" (494090) Wed Jan 25 12:04:10 2017: Debug: } # update request = noop (494090) Wed Jan 25 12:04:10 2017: Debug: if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { (494090) Wed Jan 25 12:04:10 2017: Debug: EXPAND %{hex:&Class} (494090) Wed Jan 25 12:04:10 2017: Debug: --> (494090) Wed Jan 25 12:04:10 2017: Debug: EXPAND ^%{hex:&Tmp-String-9} (494090) Wed Jan 25 12:04:10 2017: Debug: --> ^61693a (494090) Wed Jan 25 12:04:10 2017: Debug: if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE (494090) Wed Jan 25 12:04:10 2017: Debug: else { (494090) Wed Jan 25 12:04:10 2017: Debug: update request { (494090) Wed Jan 25 12:04:10 2017: Debug: EXPAND %{md5:%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} (494090) Wed Jan 25 12:04:10 2017: Debug: --> b1cbd13cc01616d5f451e33b24aeb893 (494090) Wed Jan 25 12:04:10 2017: Debug: &Acct-Unique-Session-Id := b1cbd13cc01616d5f451e33b24aeb893 (494090) Wed Jan 25 12:04:10 2017: Debug: } # update request = noop (494090) Wed Jan 25 12:04:10 2017: Debug: } # else = noop (494090) Wed Jan 25 12:04:10 2017: Debug: } # policy acct_unique = noop (494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[preacct]: calling suffix (rlm_realm) (494090) Wed Jan 25 12:04:10 2017: Debug: suffix: Checking for suffix after "@" (494090) Wed Jan 25 12:04:10 2017: Debug: suffix: No '@' in User-Name = "test1", looking up realm NULL (494090) Wed Jan 25 12:04:10 2017: Debug: suffix: No such realm "NULL" (494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[preacct]: returned from suffix (rlm_realm) (494090) Wed Jan 25 12:04:10 2017: Debug: [suffix] = noop (494090) Wed Jan 25 12:04:10 2017: Debug: } # preacct = ok (494090) Wed Jan 25 12:04:10 2017: Debug: # Executing section accounting from file /etc/freeradius/sites-enabled/default (494090) Wed Jan 25 12:04:10 2017: Debug: accounting { (494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: calling detail (rlm_detail) (494090) Wed Jan 25 12:04:10 2017: Debug: detail: EXPAND /var/log/freeradius/radacct/detail-%Y%m%d (494090) Wed Jan 25 12:04:10 2017: Debug: detail: --> /var/log/freeradius/radacct/detail-20170125 (494090) Wed Jan 25 12:04:10 2017: Debug: detail: /var/log/freeradius/radacct/detail-%Y%m%d expands to /var/log/freeradius/radacct/detail-20170125 (494090) Wed Jan 25 12:04:10 2017: Debug: detail: EXPAND %t (494090) Wed Jan 25 12:04:10 2017: Debug: detail: --> Wed Jan 25 12:04:10 2017 (494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: returned from detail (rlm_detail) (494090) Wed Jan 25 12:04:10 2017: Debug: [detail] = ok (494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: calling detail2 (rlm_detail) (494090) Wed Jan 25 12:04:10 2017: Debug: detail2: EXPAND /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d (494090) Wed Jan 25 12:04:10 2017: Debug: detail2: --> /var/log/freeradius/radacct/debug/82.21.11.91/detail-20170125 (494090) Wed Jan 25 12:04:10 2017: Debug: detail2: /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/freeradius/radacct/debug/82.21.11.91/detail-20170125 (494090) Wed Jan 25 12:04:10 2017: Debug: detail2: EXPAND %t (494090) Wed Jan 25 12:04:10 2017: Debug: detail2: --> Wed Jan 25 12:04:10 2017 (494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: returned from detail2 (rlm_detail) (494090) Wed Jan 25 12:04:10 2017: Debug: [detail2] = ok (494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: calling exec (rlm_exec) (494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: returned from exec (rlm_exec) (494090) Wed Jan 25 12:04:10 2017: Debug: [exec] = noop (494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter) (494090) Wed Jan 25 12:04:10 2017: Debug: attr_filter.accounting_response: EXPAND %{User-Name} (494090) Wed Jan 25 12:04:10 2017: Debug: attr_filter.accounting_response: --> test1 (494090) Wed Jan 25 12:04:10 2017: Debug: attr_filter.accounting_response: Matched entry DEFAULT at line 12 (494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter) (494090) Wed Jan 25 12:04:10 2017: Debug: [attr_filter.accounting_response] = updated (494090) Wed Jan 25 12:04:10 2017: Debug: } # accounting = updated (494090) Wed Jan 25 12:04:10 2017: Debug: Sent Accounting-Response Id 188 from 82.21.11.50:1813 to 82.21.11.91:28850 length 0 (494090) Wed Jan 25 12:04:10 2017: Debug: Finished request (494091) Wed Jan 25 12:04:10 2017: Debug: Received Accounting-Request Id 189 from 82.21.11.91:57448 to 82.21.11.50:1813 length 79 ... logs for next request "test2" ... (494090) Wed Jan 25 12:04:10 2017: Debug: Cleaning up request packet ID 188 with timestamp +243824 (494091) Wed Jan 25 12:04:10 2017: Debug: Cleaning up request packet ID 189 with timestamp +243824 (494092) Wed Jan 25 12:04:11 2017: Debug: Empty preacct section in virtual server "buffered-sql". Using default return values. (494092) Wed Jan 25 12:04:11 2017: Debug: # Executing section accounting from file /etc/freeradius/sites-enabled/buffered-sql (494092) Wed Jan 25 12:04:11 2017: Debug: accounting { (494092) Wed Jan 25 12:04:11 2017: Debug: modsingle[accounting]: calling sql (rlm_sql) (494092) Wed Jan 25 12:04:11 2017: Debug: sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (494092) Wed Jan 25 12:04:11 2017: Debug: sql: --> type.start.query (494092) Wed Jan 25 12:04:11 2017: Debug: sql: Using query template 'query' (494092) Wed Jan 25 12:04:11 2017: Debug: sql: EXPAND %{User-Name} (494092) Wed Jan 25 12:04:11 2017: Debug: sql: --> test2

3 24

Check Password Against External DB
by David Teston 07 Feb '17

07 Feb '17

Hi All, My company runs an application that hashes/encrypts user passwords in a central postgres DB. I have a bash script that can be run remotely to check a username and password against it: ./script.sh <user> <plaintext_pass> The end goal is to store the username and encrypted password on the local FR postgres DB, but always/only check the password against the central DB. This will account for any password/permissions changes that occur on the application DB. My fear is that I will not be able to use EAP or CHAP (and their various sub-types) because of client-side password hashing. It seems that PAP will be the only usable solution because it would still provide the server with a plaintext password to be passed into the script. But I run into security issues with PAP. Does anyone know of a proper method that would allow me to check all user credentials against the external DB while still remaining secure throughout the entire process? Thanks in advance, David -- David Teston PINES System Administrator

3 2

Additional request information in radius.log
by douglas eseng 07 Feb '17

07 Feb '17

Is it possible to have additional request attributes log into radius.log? Like the log entries below, other than a request number or ID. Maybe also log some of the radius attributes. Fri Feb 3 08:24:15 2017 : Error: Rejecting request 16044 (proxy Id 223) due to lack of any response from home server NAS02 port 1813 Fri Feb 3 08:25:34 2017 : Error: Discarding duplicate request from client NAS14 port 1645 - ID: 66 due to unfinished request 16900 in component <core> module <queue>. It would be helpful when tracing through packets capture from tcpdump. Thanks.

3 3

TACACS+ is now in the v4.0.x branch
by Alan DeKok 06 Feb '17

06 Feb '17

I've just committed a patch to add TACACS+ to the v4.0.x branch: https://github.com/FreeRADIUS/freeradius-server/commit/6a59647304955d984f2e… It's experimental, and works in basic tests. Minor things in the configuration are likely to change as we update v4, but the basic TACACS+ functionality should remain the same. Thanks to Alexander Clouter for doing the work. He had to read the TACACS+ proposed standard document, and figure out what it said: not much... The implementation is inter-operable with the switches we have access to, but you never now. People interested in trying the bleeding edge can now use TACACS+ in the v4 branch. Alan DeKok.

4 6

limiting fail timeout for an LDAP module
by Zenon Mousmoulas 06 Feb '17

06 Feb '17

Hi, I am working with a peculiar LDAP backend which, from time to time, will take upwards of 10 seconds to respond to a search request. I know that is what needs fixing, but let's say I have to live with it for now. There is a second LDAP backend which I can use a backup when the first one goes nuts. So I'm thinking let's setup two LDAP module instances and use them in a redundant group. For this to be usable for EAP authentication however, I need to make sure freeradius fails the first LDAP module within some (short) time limit. I have thus been trying to tweak the first LDAP module instance settings in order to achieve that. After experimenting with these settings: options.res_timeout options.srv_timelimit pool.start I found that if I set pool.start=0 and, say, options.res_timeout=2 freeradius reconnects (retrying the search once) and fails the module after a total of 4 seconds: Fri Feb 3 18:29:43 2017 : Debug: (1) ldap_first_bad: Waiting for search result... Fri Feb 3 18:29:44 2017 : Debug: Waking up in 0.4 seconds. Fri Feb 3 18:29:44 2017 : Debug: Waking up in 0.7 seconds. Fri Feb 3 18:29:45 2017 : Debug: Waking up in 1.1 seconds. Fri Feb 3 18:29:45 2017 : Debug: rlm_ldap: Closing libldap handle 0x7fa240000cb0 Fri Feb 3 18:29:45 2017 : Debug: rlm_ldap (ldap_first_bad): Reconnecting (0) Fri Feb 3 18:29:45 2017 : Debug: rlm_ldap (ldap_first_bad): Connecting to ldaps://xxxxxxxx Fri Feb 3 18:29:45 2017 : Debug: rlm_ldap (ldap_first_bad): New libldap handle 0x7fa238000da0 Fri Feb 3 18:29:45 2017 : Debug: rlm_ldap (ldap_first_bad): Waiting for bind result... Fri Feb 3 18:29:45 2017 : Debug: rlm_ldap (ldap_first_bad): Bind successful Fri Feb 3 18:29:45 2017 : WARNING: (1) ldap_first_bad: Search failed: Timed out while waiting for server to respond. Got new socket, retrying... Fri Feb 3 18:29:45 2017 : Debug: (1) ldap_first_bad: Waiting for search result... Fri Feb 3 18:29:46 2017 : Debug: Waking up in 1.6 seconds. Fri Feb 3 18:29:47 2017 : Debug: rlm_ldap: Closing libldap handle 0x7fa238000da0 Fri Feb 3 18:29:47 2017 : Debug: rlm_ldap (ldap_first_bad): Reconnecting (0) Fri Feb 3 18:29:47 2017 : Debug: rlm_ldap (ldap_first_bad): Connecting to ldaps://xxxxxxxx Fri Feb 3 18:29:47 2017 : Debug: rlm_ldap (ldap_first_bad): New libldap handle 0x7fa238000da0 Fri Feb 3 18:29:47 2017 : Debug: rlm_ldap (ldap_first_bad): Waiting for bind result... Fri Feb 3 18:29:47 2017 : Debug: rlm_ldap (ldap_first_bad): Bind successful Fri Feb 3 18:29:47 2017 : WARNING: (1) ldap_first_bad: Search failed: Timed out while waiting for server to respond. Got new socket, retrying... Fri Feb 3 18:29:47 2017 : Debug: (1) ldap_first_bad: Waiting for search result... Fri Feb 3 18:29:48 2017 : Debug: Waking up in 2.5 seconds. Fri Feb 3 18:29:48 2017 : Error: (1) Ignoring duplicate packet from client localhost port 34423 - ID: 11 due to unfinished request in component authorize module ldap_first_bad Fri Feb 3 18:29:48 2017 : Debug: Waking up in 1.9 seconds. Fri Feb 3 18:29:49 2017 : Debug: rlm_ldap: Closing libldap handle 0x7fa238000da0 Fri Feb 3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): Reconnecting (0) Fri Feb 3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): Connecting to ldaps://xxxxxxxx Fri Feb 3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): New libldap handle 0x7fa238000da0 Fri Feb 3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): Waiting for bind result... Fri Feb 3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): Bind successful Fri Feb 3 18:29:49 2017 : WARNING: (1) ldap_first_bad: Search failed: Timed out while waiting for server to respond. Got new socket, retrying... Fri Feb 3 18:29:49 2017 : ERROR: (1) ldap_first_bad: Hit reconnection limit Fri Feb 3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): Released connection (0) Fri Feb 3 18:29:49 2017 : Info: rlm_ldap (ldap_first_bad): Need 1 more connections to reach 10 spares Fri Feb 3 18:29:49 2017 : Info: rlm_ldap (ldap_first_bad): Opening additional connection (2), 1 of 30 pending slots used Fri Feb 3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): Connecting to ldaps://xxxxxxxx Fri Feb 3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): New libldap handle 0x7fa2380215b0 Fri Feb 3 18:29:50 2017 : Debug: rlm_ldap (ldap_first_bad): Waiting for bind result... Fri Feb 3 18:29:50 2017 : Debug: rlm_ldap (ldap_first_bad): Bind successful Fri Feb 3 18:29:50 2017 : Debug: (1) modsingle[authorize]: returned from ldap_first_bad (rlm_ldap) Fri Feb 3 18:29:50 2017 : Debug: (1) [ldap_first_bad] = fail Fri Feb 3 18:29:50 2017 : Debug: (1) modsingle[authorize]: calling ldap_backup (rlm_ldap) I am wondering if this is as good as it gets or if there are other things to tweak or to try, to get a shorter timeout in this particular case, perhaps avoiding the side effect of start=0 documented therein (Set to 0 to allow the server to start without the directory being available). This is on freeradius 3.0.12. Thanks for any insight, Z.

3 4

Accounting Packets and Anonymous Identity
by Selahattin Cilek 05 Feb '17

05 Feb '17

I have been checking the traffic between NASes and FreeRADIUS (2.2.9) and I have come across accounting packets with the User-Name field set to "anonymous." Sun Nov 13 02:41:50 2016 Acct-Session-Id = "57B6F41F-000014D2" Acct-Status-Type = Start Acct-Authentic = RADIUS User-Name = "anonymous" NAS-Identifier = "KAT_8_MERDIVEN" Called-Station-Id = "DC-9F-DB-34-CF-B4:TDV.NET" NAS-Port-Type = Wireless-802.11 NAS-Port = 0 Calling-Station-Id = "F8-16-54-1E-AB-2C" Connect-Info = "CONNECT 0Mbps 802.11b" Acct-Session-Id = "57B6F41F-000014D2" NAS-IP-Address = 192.168.0.38 FreeRADIUS-Acct-Session-Start-Time = "Nov 13 2016 02:41:50 EET" Acct-Unique-Session-Id = "6c4322c41296866a" Timestamp = 1478997710 1. This server does not use MySQL and keeps the accounting data in plain text files. If I were using MySQL as the back-end, would I still see the user's name as "anonymous" in the "radacct.username" field? 2. Is it possible to find the true identity of the user by means of reading some files or an SQL query and using the other data provided in the packet such as Acct-Session-Id, Calling-Station-Id or Acct-Unique-Session-Id etc? --- This email has been checked for viruses by Avast antivirus software. https://www.avast.com/antivirus

7 13

v3.0.12 crashed (load testing)
by Chris Howley 05 Feb '17

05 Feb '17

Hi, I'm load testing freeradius 3.0.12 using GNU parallel and eapol_test. I'm trying to integrate freeradius with Active Directory. After ten hours of testing the freeradius server crashed (see below). The system is using the following: CentOS Linux release 7.2.1511 parallel-20160222-1.el7.noarch wpa_supplicant-2.0-17.el7_1.x86_64 samba-common-4.2.10-7 freeradius-3.0.12-2.el7 (built RPMS using gcc version 4.8.5) I can share the output from the debugger off-list. Help in fixing this issue would appreciated. Thanks, Chris Howley Sat Feb 4 20:01:47 2017 : Error: ASSERT FAILED src/main/connection.c[827]: pool->active == pool->num CAUGHT SIGNAL: Aborted Backtrace of last 39 frames: /usr/lib64/freeradius/libfreeradius-radius.so(fr_fault+0xa7)[0x7f48dabb0397] /usr/lib64/freeradius/libfreeradius-server.so(rad_assert_fail+0x29)[0x7f48dae09b59] /usr/sbin/radiusd[0x42c80c] /usr/lib64/freeradius/rlm_mschap.so(do_auth_wbclient+0x11a)[0x7f48d3f160aa] /usr/lib64/freeradius/rlm_mschap.so(+0x2301)[0x7f48d3f12301] /usr/lib64/freeradius/rlm_mschap.so(+0x4bc1)[0x7f48d3f14bc1] /usr/sbin/radiusd[0x426faf] /usr/sbin/radiusd[0x427ad9] /usr/sbin/radiusd[0x42688e] /usr/sbin/radiusd[0x427ad9] /usr/sbin/radiusd[0x42688e] /usr/sbin/radiusd(modcall+0x56)[0x427b96] /usr/sbin/radiusd(indexed_modcall+0xad)[0x42238d] /usr/lib64/freeradius/rlm_eap_mschapv2.so(+0x1dfb)[0x7f48cfa6edfb] /usr/lib64/freeradius/rlm_eap.so(+0x3795)[0x7f48d5dc4795] /usr/lib64/freeradius/rlm_eap.so(eap_method_select+0xb9)[0x7f48d5dc4b09] /usr/lib64/freeradius/rlm_eap.so(+0x2b36)[0x7f48d5dc3b36] /usr/sbin/radiusd[0x426faf] /usr/sbin/radiusd[0x427ad9] /usr/sbin/radiusd[0x42688e] /usr/sbin/radiusd(modcall+0x56)[0x427b96] /usr/sbin/radiusd(indexed_modcall+0xad)[0x42238d] /usr/sbin/radiusd(rad_authenticate+0x7be)[0x4112de] /usr/sbin/radiusd(rad_virtual_server+0x272)[0x411802] /usr/lib64/freeradius/rlm_eap_peap.so(eappeap_process+0x6d3)[0x7f48cfc75833] /usr/lib64/freeradius/rlm_eap_peap.so(+0x1c0a)[0x7f48cfc73c0a] /usr/lib64/freeradius/rlm_eap.so(+0x3795)[0x7f48d5dc4795] /usr/lib64/freeradius/rlm_eap.so(eap_method_select+0xb9)[0x7f48d5dc4b09] /usr/lib64/freeradius/rlm_eap.so(+0x2b36)[0x7f48d5dc3b36] /usr/sbin/radiusd[0x426faf] /usr/sbin/radiusd[0x427ad9] /usr/sbin/radiusd[0x42688e] /usr/sbin/radiusd(modcall+0x56)[0x427b96] /usr/sbin/radiusd(indexed_modcall+0xad)[0x42238d] /usr/sbin/radiusd(rad_authenticate+0x7be)[0x4112de] /usr/sbin/radiusd[0x4374c3] /usr/sbin/radiusd[0x42f443] /lib64/libpthread.so.0(+0x7dc5)[0x7f48d947edc5] /lib64/libc.so.6(clone+0x6d)[0x7f48d8d2eced] Calling: gdb -silent -x /etc/raddb/panic.gdb /usr/sbin/radiusd 47031 2>&1 | tee /var/log/radius/gdb-radiusd-47031.log Temporarily setting PR_DUMPABLE to 1 Resetting PR_DUMPABLE to 0 Panic action exited with 0 _EXIT(0) CALLED src/lib/debug.c[743]

2 1