The Case of the Disappearing Attribute

23 Sep 2015

      Hi

I am probably doing something wrong, but I can't figure out why I seem to
be loosing attributes during the processing of a DHCP request.

As I understand it, the snippet here shows that the attribute
DHCP-Your-IP-Address is added by rlm_perl and later on that the attribute
does not exist:

Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Your-IP-Address =
$RAD_REPLY{'DHCP-Your-IP-Address'} -> '10.200.0.50'
...
Wed Sep 23 08:46:42 2015 : Debug: (5) DHCP: Failed to find
DHCP-Client-IP-Address or DHCP-Your-IP-Address for request; not responding

What I can't understand is why the attribute cannot be found later on in
the processing of the request. This server is running the latest 3.0. and
it is successfully processing other DHCP packets. The only difference I can
see with this packet is that is from a locally attached client wheras the
other clients are behind relays.

I would be grateful for any help.

Here is the full debug:

Received DHCP-Discover of Id 35a1700b from 0.0.0.0:68 to 255.255.255.255:67
0: 01 01 06 00 35 a1 70 0b 00 00 80 00 00 00 00 00
16: 00 00 00 00 00 00 00 00 00 00 00 00 00 0c 29 06
32: ca 30 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 74 01 01 3d 07 01 00 0c 29 06 ca 30 32
256: 04 a9 fe 85 6a 0c 0f 68 6f 6d 65 2d 63 63 37 61
272: 64 34 37 61 34 31 3c 08 4d 53 46 54 20 35 2e 30
288: 37 0b 01 0f 03 06 2c 2e 2f 1f 21 f9 2b 2b 02 dc
304: 00 ff
        DHCP-Opcode = Client-Message
        DHCP-Hardware-Type = Ethernet
        DHCP-Hardware-Address-Length = 6
        DHCP-Hop-Count = 0
        DHCP-Transaction-Id = 899772427
        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:0c:29:06:ca:30
        DHCP-Message-Type = DHCP-Discover
        DHCP-Auto-Config = 1
        DHCP-Client-Identifier = 0x01000c2906ca30
        DHCP-Requested-IP-Address = 169.254.133.106
        DHCP-Hostname = "home-cc7ad47a41"
        DHCP-Vendor-Class-Identifier = 0x4d53465420352e30
        DHCP-Parameter-Request-List = DHCP-Subnet-Mask
        DHCP-Parameter-Request-List = DHCP-Domain-Name
        DHCP-Parameter-Request-List = DHCP-Router-Address
        DHCP-Parameter-Request-List = DHCP-Domain-Name-Server
        DHCP-Parameter-Request-List = DHCP-NETBIOS-Name-Servers
        DHCP-Parameter-Request-List = DHCP-NETBIOS-Node-Type
        DHCP-Parameter-Request-List = DHCP-NETBIOS
        DHCP-Parameter-Request-List = DHCP-Perform-Router-Discovery
        DHCP-Parameter-Request-List = DHCP-Static-Routes
        DHCP-Parameter-Request-List = DHCP-Site-specific-25
        DHCP-Parameter-Request-List = DHCP-Vendor
        DHCP-Vendor = 0xdc00
Wed Sep 23 08:46:42 2015 : Debug: (5) Received code 1025 Id 899772427 from
0.0.0.0:68 to 255.255.255.255:67 length 306
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Opcode = Client-Message
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Hardware-Type = Ethernet
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Hardware-Address-Length = 6
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Hop-Count = 0
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Transaction-Id = 899772427
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Number-of-Seconds = 0
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Flags = Broadcast
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Client-IP-Address = 0.0.0.0
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Your-IP-Address = 0.0.0.0
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Server-IP-Address = 0.0.0.0
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Gateway-IP-Address = 0.0.0.0
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Client-Hardware-Address =
00:0c:29:06:ca:30
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Message-Type = DHCP-Discover
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Auto-Config = 1
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Client-Identifier =
0x01000c2906ca30
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Requested-IP-Address =
169.254.133.106
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Hostname = "home-cc7ad47a41"
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Vendor-Class-Identifier =
0x4d53465420352e30
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Parameter-Request-List =
DHCP-Subnet-Mask
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Parameter-Request-List =
DHCP-Domain-Name
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Parameter-Request-List =
DHCP-Router-Address
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Parameter-Request-List =
DHCP-Domain-Name-Server
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Parameter-Request-List =
DHCP-NETBIOS-Name-Servers
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Parameter-Request-List =
DHCP-NETBIOS-Node-Type
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Parameter-Request-List =
DHCP-NETBIOS
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Parameter-Request-List =
DHCP-Perform-Router-Discovery
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Parameter-Request-List =
DHCP-Static-Routes
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Parameter-Request-List =
DHCP-Site-specific-25
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Parameter-Request-List =
DHCP-Vendor
Wed Sep 23 08:46:42 2015 : Debug: (5)   DHCP-Vendor = 0xdc00
Wed Sep 23 08:46:42 2015 : Debug: Trying sub-section dhcp DHCP-Discover
{...}
Wed Sep 23 08:46:42 2015 : Debug: (5)   dhcp DHCP-Discover {
Wed Sep 23 08:46:42 2015 : Debug: (5)     modsingle[post-auth]: calling
linelog-dhcp (rlm_linelog) for request 5
Wed Sep 23 08:46:42 2015 : Debug:
%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}
Wed Sep 23 08:46:42 2015 : Debug: Parsed xlat tree:
Wed Sep 23 08:46:42 2015 : Debug: if {
Wed Sep 23 08:46:42 2015 : Debug:       attribute --> DHCP-Message-Type
Wed Sep 23 08:46:42 2015 : Debug: }
Wed Sep 23 08:46:42 2015 : Debug: else {
Wed Sep 23 08:46:42 2015 : Debug:       attribute --> DHCP-Message-Type
Wed Sep 23 08:46:42 2015 : Debug: }
Wed Sep 23 08:46:42 2015 : Debug: (5) linelog-dhcp: EXPAND
%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}
Wed Sep 23 08:46:42 2015 : Debug: (5) linelog-dhcp:    --> DHCP-Discover
Wed Sep 23 08:46:42 2015 : Debug:
/usr/local/var/log/radius-dhcp/linelog-dhcp.log
Wed Sep 23 08:46:42 2015 : Debug: Parsed xlat tree:
Wed Sep 23 08:46:42 2015 : Debug: literal -->
/usr/local/var/log/radius-dhcp/linelog-dhcp.log
Wed Sep 23 08:46:42 2015 : Debug: (5) linelog-dhcp: EXPAND
/usr/local/var/log/radius-dhcp/linelog-dhcp.log
Wed Sep 23 08:46:42 2015 : Debug: (5) linelog-dhcp:    -->
/usr/local/var/log/radius-dhcp/linelog-dhcp.log
Wed Sep 23 08:46:42 2015 : Debug: %S --> Transaction-ID:
%{DHCP-Transaction-Id} DISCOVER: [%{DHCP-Client-Hardware-Address}] via
(%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay =
%{DHCP-Relay-Remote-Id}, Hostname =  %{DHCP-Hostname}
Wed Sep 23 08:46:42 2015 : Debug: Parsed xlat tree:
Wed Sep 23 08:46:42 2015 : Debug: percent --> S
Wed Sep 23 08:46:42 2015 : Debug: literal -->  --> Transaction-ID:
Wed Sep 23 08:46:42 2015 : Debug: attribute --> DHCP-Transaction-Id
Wed Sep 23 08:46:42 2015 : Debug: literal -->  DISCOVER: [
Wed Sep 23 08:46:42 2015 : Debug: attribute --> DHCP-Client-Hardware-Address
Wed Sep 23 08:46:42 2015 : Debug: literal --> ] via (
Wed Sep 23 08:46:42 2015 : Debug: attribute --> DHCP-Gateway-IP-Address
Wed Sep 23 08:46:42 2015 : Debug: literal --> ), hop count =
Wed Sep 23 08:46:42 2015 : Debug: attribute --> DHCP-Hop-Count
Wed Sep 23 08:46:42 2015 : Debug: literal --> , Relay =
Wed Sep 23 08:46:42 2015 : Debug: attribute --> DHCP-Relay-Remote-Id
Wed Sep 23 08:46:42 2015 : Debug: literal --> , Hostname =
Wed Sep 23 08:46:42 2015 : Debug: attribute --> DHCP-Hostname
Wed Sep 23 08:46:42 2015 : Debug: (5) linelog-dhcp: EXPAND %S -->
Transaction-ID: %{DHCP-Transaction-Id} DISCOVER:
[%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop
count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id}, Hostname =
%{DHCP-Hostname}
Wed Sep 23 08:46:42 2015 : Debug: (5) linelog-dhcp:    --> 2015-09-23
08:46:42 --> Transaction-ID: 899772427 DISCOVER: [00:0c:29:06:ca:30] via
(0.0.0.0), hop count = 0, Relay = , Hostname =  home-cc7ad47a41
Wed Sep 23 08:46:42 2015 : Debug: (5)     modsingle[post-auth]: returned
from linelog-dhcp (rlm_linelog) for request 5
Wed Sep 23 08:46:42 2015 : Debug: (5)     [linelog-dhcp] = ok
Wed Sep 23 08:46:42 2015 : Debug: (5)     update reply {
Wed Sep 23 08:46:42 2015 : Debug: (5)       &DHCP-DHCP-Server-Identifier =
10.200.0.1
Wed Sep 23 08:46:42 2015 : Debug: (5)       &DHCP-Flags = 0
Wed Sep 23 08:46:42 2015 : Debug: (5)     } # update reply = noop
Wed Sep 23 08:46:42 2015 : Debug: (5)     modsingle[post-auth]: calling
perl (rlm_perl) for request 5
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:   $RAD_REQUEST{'DHCP-Opcode'} =
&request:DHCP-Opcode -> 'Client-Message'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Hardware-Type'} = &request:DHCP-Hardware-Type ->
'Ethernet'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Hardware-Address-Length'} =
&request:DHCP-Hardware-Address-Length -> '6'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Hop-Count'} = &request:DHCP-Hop-Count -> '0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Transaction-Id'} = &request:DHCP-Transaction-Id ->
'899772427'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Number-of-Seconds'} = &request:DHCP-Number-of-Seconds ->
'0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:   $RAD_REQUEST{'DHCP-Flags'} =
&request:DHCP-Flags -> 'Broadcast'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Client-IP-Address'} = &request:DHCP-Client-IP-Address ->
'0.0.0.0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Your-IP-Address'} = &request:DHCP-Your-IP-Address ->
'0.0.0.0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Server-IP-Address'} = &request:DHCP-Server-IP-Address ->
'0.0.0.0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Gateway-IP-Address'} = &request:DHCP-Gateway-IP-Address
-> '0.0.0.0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Client-Hardware-Address'} =
&request:DHCP-Client-Hardware-Address -> '00:0c:29:06:ca:30'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:   $RAD_REQUEST{'DHCP-Hostname'}
= &request:DHCP-Hostname -> 'home-cc7ad47a41'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:   $RAD_REQUEST{'DHCP-Vendor'} =
&request:DHCP-Vendor -> '0xdc00'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Requested-IP-Address'} =
&request:DHCP-Requested-IP-Address -> '169.254.133.106'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Message-Type'} = &request:DHCP-Message-Type ->
'DHCP-Discover'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Parameter-Request-List'}[0] =
&request:DHCP-Parameter-Request-List -> 'DHCP-Subnet-Mask'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Parameter-Request-List'}[1] =
&request:DHCP-Parameter-Request-List -> 'DHCP-Domain-Name'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Parameter-Request-List'}[2] =
&request:DHCP-Parameter-Request-List -> 'DHCP-Router-Address'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Parameter-Request-List'}[3] =
&request:DHCP-Parameter-Request-List -> 'DHCP-Domain-Name-Server'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Parameter-Request-List'}[4] =
&request:DHCP-Parameter-Request-List -> 'DHCP-NETBIOS-Name-Servers'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Parameter-Request-List'}[5] =
&request:DHCP-Parameter-Request-List -> 'DHCP-NETBIOS-Node-Type'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Parameter-Request-List'}[6] =
&request:DHCP-Parameter-Request-List -> 'DHCP-NETBIOS'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Parameter-Request-List'}[7] =
&request:DHCP-Parameter-Request-List -> 'DHCP-Perform-Router-Discovery'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Parameter-Request-List'}[8] =
&request:DHCP-Parameter-Request-List -> 'DHCP-Static-Routes'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Parameter-Request-List'}[9] =
&request:DHCP-Parameter-Request-List -> 'DHCP-Site-specific-25'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Parameter-Request-List'}[10] =
&request:DHCP-Parameter-Request-List -> 'DHCP-Vendor'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Vendor-Class-Identifier'} =
&request:DHCP-Vendor-Class-Identifier -> '0x4d53465420352e30'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Client-Identifier'} = &request:DHCP-Client-Identifier ->
'0x01000c2906ca30'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REQUEST{'DHCP-Auto-Config'} = &request:DHCP-Auto-Config -> '1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:   $RAD_REPLY{'DHCP-Flags'} =
&reply:DHCP-Flags -> '0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
$RAD_REPLY{'DHCP-DHCP-Server-Identifier'} =
&reply:DHCP-DHCP-Server-Identifier -> '10.200.0.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Your-IP-Address =
$RAD_REQUEST{'DHCP-Your-IP-Address'} -> '0.0.0.0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Message-Type =
$RAD_REQUEST{'DHCP-Message-Type'} -> 'DHCP-Discover'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Vendor-Class-Identifier =
$RAD_REQUEST{'DHCP-Vendor-Class-Identifier'} -> '0x4d53465420352e30'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Hop-Count =
$RAD_REQUEST{'DHCP-Hop-Count'} -> '0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Number-of-Seconds
= $RAD_REQUEST{'DHCP-Number-of-Seconds'} -> '0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Client-IP-Address
= $RAD_REQUEST{'DHCP-Client-IP-Address'} -> '0.0.0.0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Gateway-IP-Address = $RAD_REQUEST{'DHCP-Gateway-IP-Address'}
-> '0.0.0.0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Hardware-Type =
$RAD_REQUEST{'DHCP-Hardware-Type'} -> 'Ethernet'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Flags =
$RAD_REQUEST{'DHCP-Flags'} -> 'Broadcast'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Hardware-Address-Length =
$RAD_REQUEST{'DHCP-Hardware-Address-Length'} -> '6'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Hostname =
$RAD_REQUEST{'DHCP-Hostname'} -> 'home-cc7ad47a41'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Opcode =
$RAD_REQUEST{'DHCP-Opcode'} -> 'Client-Message'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Transaction-Id =
$RAD_REQUEST{'DHCP-Transaction-Id'} -> '899772427'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Parameter-Request-List +=
$RAD_REQUEST{'DHCP-Parameter-Request-List'} -> 'DHCP-Subnet-Mask'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Parameter-Request-List +=
$RAD_REQUEST{'DHCP-Parameter-Request-List'} -> 'DHCP-Domain-Name'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Parameter-Request-List +=
$RAD_REQUEST{'DHCP-Parameter-Request-List'} -> 'DHCP-Router-Address'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Parameter-Request-List +=
$RAD_REQUEST{'DHCP-Parameter-Request-List'} -> 'DHCP-Domain-Name-Server'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Parameter-Request-List +=
$RAD_REQUEST{'DHCP-Parameter-Request-List'} -> 'DHCP-NETBIOS-Name-Servers'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Parameter-Request-List +=
$RAD_REQUEST{'DHCP-Parameter-Request-List'} -> 'DHCP-NETBIOS-Node-Type'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Parameter-Request-List +=
$RAD_REQUEST{'DHCP-Parameter-Request-List'} -> 'DHCP-NETBIOS'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Parameter-Request-List +=
$RAD_REQUEST{'DHCP-Parameter-Request-List'} ->
'DHCP-Perform-Router-Discovery'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Parameter-Request-List +=
$RAD_REQUEST{'DHCP-Parameter-Request-List'} -> 'DHCP-Static-Routes'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Parameter-Request-List +=
$RAD_REQUEST{'DHCP-Parameter-Request-List'} -> 'DHCP-Site-specific-25'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Parameter-Request-List +=
$RAD_REQUEST{'DHCP-Parameter-Request-List'} -> 'DHCP-Vendor'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Client-Hardware-Address =
$RAD_REQUEST{'DHCP-Client-Hardware-Address'} -> '00:0c:29:06:ca:30'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Server-IP-Address
= $RAD_REQUEST{'DHCP-Server-IP-Address'} -> '0.0.0.0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&request:DHCP-Requested-IP-Address =
$RAD_REQUEST{'DHCP-Requested-IP-Address'} -> '169.254.133.106'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Auto-Config =
$RAD_REQUEST{'DHCP-Auto-Config'} -> '1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Vendor =
$RAD_REQUEST{'DHCP-Vendor'} -> '0xdc00'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &request:DHCP-Client-Identifier
= $RAD_REQUEST{'DHCP-Client-Identifier'} -> '0x01000c2906ca30'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Your-IP-Address =
$RAD_REPLY{'DHCP-Your-IP-Address'} -> '10.200.0.50'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Domain-Name-Server
+= $RAD_REPLY{'DHCP-Domain-Name-Server'} -> '10.1.1.253'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Domain-Name-Server
+= $RAD_REPLY{'DHCP-Domain-Name-Server'} -> '10.1.1.254'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-WWW-Server-Address
= $RAD_REPLY{'DHCP-WWW-Server-Address'} -> 'www.censored'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Time-Offset =
$RAD_REPLY{'DHCP-Time-Offset'} -> '2'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-SMTP-Server-Address
= $RAD_REPLY{'DHCP-SMTP-Server-Address'} -> 'smtp.censored'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-POP3-Server-Address
= $RAD_REPLY{'DHCP-POP3-Server-Address'} -> 'mail.censored'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Site-specific-25 =
$RAD_REPLY{'DHCP-Site-specific-25'} ->
'0x100a010ac80001100a020ac80001100a0a0ac800010cac100ac800010cac200ac8000108ef0ac80032'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Boot-Filename =
$RAD_REPLY{'DHCP-Boot-Filename'} -> 'hydra.bin'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&reply:DHCP-IP-Address-Lease-Time =
$RAD_REPLY{'DHCP-IP-Address-Lease-Time'} -> '300'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Time-Server =
$RAD_REPLY{'DHCP-Time-Server'} -> 'time.censored'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&reply:DHCP-DHCP-Server-Identifier =
$RAD_REPLY{'DHCP-DHCP-Server-Identifier'} -> '10.200.0.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Subnet-Mask =
$RAD_REPLY{'DHCP-Subnet-Mask'} -> '255.255.255.0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-NNTP-Server-Address
= $RAD_REPLY{'DHCP-NNTP-Server-Address'} -> 'ntp.censored'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Router-Address =
$RAD_REPLY{'DHCP-Router-Address'} -> '10.200.0.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.1.1.5'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.200.0.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.1.2.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.200.0.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.2.2.7'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.200.0.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.2.2.8'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.200.0.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.2.2.9'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.200.0.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.2.2.11'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.200.0.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.1.1.250'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.200.0.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.1.1.252'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.200.0.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.1.1.254'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-Static-Routes +=
$RAD_REPLY{'DHCP-Static-Routes'} -> '10.200.0.1'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-IP-Forward-Enable =
$RAD_REPLY{'DHCP-IP-Forward-Enable'} -> '0'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl:
&reply:DHCP-Classless-Static-Route =
$RAD_REPLY{'DHCP-Classless-Static-Route'} ->
'0x100a010ac80001100a020ac80001100a0a0ac800010cac100ac800010cac200ac8000108ef0ac80032'
Wed Sep 23 08:46:42 2015 : Debug: (5) perl: &reply:DHCP-NTP-Servers =
$RAD_REPLY{'DHCP-NTP-Servers'} -> 'ntp.censored'
Wed Sep 23 08:46:42 2015 : Debug: (5)     modsingle[post-auth]: returned
from perl (rlm_perl) for request 5
Wed Sep 23 08:46:42 2015 : Debug: (5)     [perl] = ok
Wed Sep 23 08:46:42 2015 : Debug: (5)     if (ok) {
Wed Sep 23 08:46:42 2015 : Debug: (5)     if (ok)  -> TRUE
Wed Sep 23 08:46:42 2015 : Debug: (5)     if (ok)  {
Wed Sep 23 08:46:42 2015 : Debug: (5)       update reply {
Wed Sep 23 08:46:42 2015 : Debug: (5)         &DHCP-Message-Type =
DHCP-Offer
Wed Sep 23 08:46:42 2015 : Debug: (5)         &DHCP-Server-IP-Address =
10.200.0.1
Wed Sep 23 08:46:42 2015 : Debug: (5)       } # update reply = noop
Wed Sep 23 08:46:42 2015 : Debug: (5)     } # if (ok)  = noop
Wed Sep 23 08:46:42 2015 : Debug: (5)     ... skipping else for request 5:
Preceding "if" was taken
Wed Sep 23 08:46:42 2015 : Debug: (5)     modsingle[post-auth]: calling
linelog-dhcp (rlm_linelog) for request 5
Wed Sep 23 08:46:42 2015 : Debug:
%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}
Wed Sep 23 08:46:42 2015 : Debug: Parsed xlat tree:
Wed Sep 23 08:46:42 2015 : Debug: if {
Wed Sep 23 08:46:42 2015 : Debug:       attribute --> DHCP-Message-Type
Wed Sep 23 08:46:42 2015 : Debug: }
Wed Sep 23 08:46:42 2015 : Debug: else {
Wed Sep 23 08:46:42 2015 : Debug:       attribute --> DHCP-Message-Type
Wed Sep 23 08:46:42 2015 : Debug: }
Wed Sep 23 08:46:42 2015 : Debug: (5) linelog-dhcp: EXPAND
%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}
Wed Sep 23 08:46:42 2015 : Debug: (5) linelog-dhcp:    --> DHCP-Offer
Wed Sep 23 08:46:42 2015 : Debug:
/usr/local/var/log/radius-dhcp/linelog-dhcp.log
Wed Sep 23 08:46:42 2015 : Debug: Parsed xlat tree:
Wed Sep 23 08:46:42 2015 : Debug: literal -->
/usr/local/var/log/radius-dhcp/linelog-dhcp.log
Wed Sep 23 08:46:42 2015 : Debug: (5) linelog-dhcp: EXPAND
/usr/local/var/log/radius-dhcp/linelog-dhcp.log
Wed Sep 23 08:46:42 2015 : Debug: (5) linelog-dhcp:    -->
/usr/local/var/log/radius-dhcp/linelog-dhcp.log
Wed Sep 23 08:46:42 2015 : Debug: %S <-- Transaction-ID:
%{DHCP-Transaction-Id} OFFER: %{reply:DHCP-Your-IP-Address} to
[%{DHCP-Client-Hardware-Address}] ...
Wed Sep 23 08:46:42 2015 : Debug: Parsed xlat tree:
Wed Sep 23 08:46:42 2015 : Debug: percent --> S
Wed Sep 23 08:46:42 2015 : Debug: literal -->  <-- Transaction-ID:
Wed Sep 23 08:46:42 2015 : Debug: attribute --> DHCP-Transaction-Id
Wed Sep 23 08:46:42 2015 : Debug: literal -->  OFFER:
Wed Sep 23 08:46:42 2015 : Debug: attribute --> DHCP-Your-IP-Address
Wed Sep 23 08:46:42 2015 : Debug: literal -->  to [
Wed Sep 23 08:46:42 2015 : Debug: attribute --> DHCP-Client-Hardware-Address
Wed Sep 23 08:46:42 2015 : Debug: literal --> ] ...
Wed Sep 23 08:46:42 2015 : Debug: (5) linelog-dhcp: EXPAND %S <--
Transaction-ID: %{DHCP-Transaction-Id} OFFER: %{reply:DHCP-Your-IP-Address}
to [%{DHCP-Client-Hardware-Address}] ...
Wed Sep 23 08:46:42 2015 : Debug: (5) linelog-dhcp:    --> 2015-09-23
08:46:42 <-- Transaction-ID: 899772427 OFFER:  to [00:0c:29:06:ca:30] ...
Wed Sep 23 08:46:42 2015 : Debug: (5)     modsingle[post-auth]: returned
from linelog-dhcp (rlm_linelog) for request 5
Wed Sep 23 08:46:42 2015 : Debug: (5)     [linelog-dhcp] = ok
Wed Sep 23 08:46:42 2015 : Debug: (5)     modsingle[post-auth]: calling ok
(rlm_always) for request 5
Wed Sep 23 08:46:42 2015 : Debug: (5)     modsingle[post-auth]: returned
from ok (rlm_always) for request 5
Wed Sep 23 08:46:42 2015 : Debug: (5)     [ok] = ok
Wed Sep 23 08:46:42 2015 : Debug: (5)   } # dhcp DHCP-Discover = ok
Wed Sep 23 08:46:42 2015 : Debug: (5) DHCP: Failed to find
DHCP-Client-IP-Address or DHCP-Your-IP-Address for request; not responding
Wed Sep 23 08:46:42 2015 : Debug: (5) Not sending reply to client.
Wed Sep 23 08:46:42 2015 : Debug: (5) Finished request
Wed Sep 23 08:46:42 2015 : Debug: (5) Cleaning up request packet ID
899772427 with timestamp +39

The Case of the Disappearing Attribute

Бен Томпсон