Logging

18 Dec 2015

      Hi,

/(Excu//se my English after that time./)

FR version: 3.0.10

I have two linelog instances for access ("linelog") and accounting
("log_accounting"). I put the "linelog" in innert-tunnel's post-auth
section instead of default for Access-Accept and Access-Reject with
inner identity and it seems like that:/

//Thu Dec 17 15:26:58 2015 Access accepted: ///1234567890/@realm-is-here
NAS-IP-Address: 10.109.50.207 Called-Station-Id: A0-48-1C-56-C6-A1
Packet-Src-IP-Address: 80.251.40.29 Calling-Station-Id: C0-BD-D1-89-0B-90//
//Thu Dec 17 15:27:30 2015 Access accepted:
//1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.185
Called-Station-Id: A0-48-1C-56-C6-9D Packet-Src-IP-Address: 80.251.40.29
Calling-Station-Id: C0-BD-D1-89-0B-90//
//Thu Dec 17 15:27:44 2015 Access accepted:
//1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.202
Called-Station-Id: A0-48-1C-56-C6-A0 Packet-Src-IP-Address: 80.251.40.29
Calling-Station-Id: C0-BD-D1-89-0B-90//
//Thu Dec 17 15:30:42 2015 Access accepted:
//1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.201
Called-Station-Id: 14-58-D0-66-E6-55 Packet-Src-IP-Address: 80.251.40.29
Calling-Station-Id: C0-BD-D1-89-0B-90//
//Thu Dec 17 15:31:38 2015 Access accepted:
//1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.206
Called-Station-Id: 14-58-D0-66-B6-51 Packet-Src-IP-Address: 80.251.40.29
Calling-Station-Id: C0-BD-D1-89-0B-90//
//Thu Dec 17 15:32:43 2015 Access accepted:
//1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.222
Called-Station-Id: 14-58-D0-66-B6-9C Packet-Src-IP-Address: 80.251.40.29
Calling-Station-Id: C0-BD-D1-89-0B-90//
//Thu Dec 17 15:32:50 2015 Access accepted:
//1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.192
Called-Station-Id: 14-58-D0-66-C6-7A Packet-Src-IP-Address: 80.251.40.29
Calling-Station-Id: C0-BD-D1-89-0B-90//
//Thu Dec 17 15:32:51 2015 Access accepted:
1234567890//@realm-is-here//NAS-IP-Address: 10.109.50.205
Called-Station-Id: 14-58-D0-66-C6-56 Packet-Src-IP-Address: 80.251.40.29
Calling-Station-Id: C0-BD-D1-89-0B-90/

As shown above, i can get the inner user identities but also i get
multiple "Accept" lines for the same user after first login (15:26:58)
although there is no attempt by the user for login.
I see the same thing in the accounting log file too:
/
//Thu Dec 17 15:26:58 2015 Connect: 1234567890@realm-is-here sessId:
93e63906-0000077e called: A0-48-1C-56-C6-A1 calling: C0-BD-D1-89-0B-90
port: 1385 ip:
Thu Dec 17 15:27:14 2015 Connect: 1234567890@realm-is-here sessId:
e85fb0d5-00000289 called: 14-58-D0-66-B6-51 calling: C0-BD-D1-89-0B-90
port: 533 ip:
Thu Dec 17 15:27:16 2015 Connect: 1234567890@realm-is-here sessId:
758f27c1-000001e1 called: 14-58-D0-66-E6-55 calling: C0-BD-D1-89-0B-90
port: 397 ip:
Thu Dec 17 15:27:19 2015 Disconnect: 1234567890@realm-is-here sessId:
758f27c1-000001e1 called: 14-58-D0-66-E6-55 calling: C0-BD-D1-89-0B-90
port: 397 ip:  sessTime: 3 seconds input: 569B output: 967B
Thu Dec 17 15:27:30 2015 Connect: 1234567890@realm-is-here sessId:
32b8e9e6-0000048e called: A0-48-1C-56-C6-9D calling: C0-BD-D1-89-0B-90
port: 841 ip:
Thu Dec 17 15:27:42 2015 Disconnect: 1234567890@realm-is-here sessId:
15f28421-00000256 called: 14-58-D0-66-B6-E1 calling: C0-BD-D1-89-0B-90
port: 474 ip: 92.61.7.155 sessTime:  seconds input: 6096B output: 7868B
Thu Dec 17 15:27:44 2015 Connect: 1234567890@realm-is-here sessId:
6ee0534b-00001696 called: A0-48-1C-56-C6-A0 calling: C0-BD-D1-89-0B-90
port: 4162 ip:
Thu Dec 17 15:27:52 2015 Disconnect: 1234567890@realm-is-here sessId:
ba48b418-00000360 called: 14-58-D0-66-C6-61 calling: C0-BD-D1-89-0B-90
port: 634 ip: 92.61.7.155 sessTime:  seconds input: 54571B output: 96205B
Thu Dec 17 15:28:11 2015 Disconnect: 1234567890@realm-is-here sessId:
e85fb0d5-00000289 called: 14-58-D0-66-B6-51 calling: C0-BD-D1-89-0B-90
port: 533 ip: 92.61.7.155 sessTime:  seconds input: 569B output: 1183B
Thu Dec 17 15:28:17 2015 Connect: 1234567890@realm-is-here sessId:
192aa670-00000e35 called: A0-48-1C-56-C6-A6 calling: C0-BD-D1-89-0B-90
port: 2558 ip:
Thu Dec 17 15:28:22 2015 Disconnect: 1234567890@realm-is-here sessId:
93e63906-0000077e called: A0-48-1C-56-C6-A1 calling: C0-BD-D1-89-0B-90
port: 1385 ip: 92.61.7.155 sessTime:  seconds input: 4371B output: 3351B
Thu Dec 17 15:29:13 2015 Disconnect: 1234567890@realm-is-here sessId:
32b8e9e6-0000048e called: A0-48-1C-56-C6-9D calling: C0-BD-D1-89-0B-90
port: 841 ip: 92.61.7.155 sessTime:  seconds input: 94910B output: 28777B
Thu Dec 17 15:29:14 2015 Disconnect: 1234567890@realm-is-here sessId:
6ee0534b-00001696 called: A0-48-1C-56-C6-A0 calling: C0-BD-D1-89-0B-90
port: 4162 ip: 92.61.7.155 sessTime:  seconds input: 26866B output: 9369B
Thu Dec 17 15:30:42 2015 Connect: 1234567890@realm-is-here sessId:
90649829-000001e3 called: 14-58-D0-66-E6-55 calling: C0-BD-D1-89-0B-90
port: 399 ip:
Thu Dec 17 15:30:43 2015 Disconnect: 1234567890@realm-is-here sessId:
192aa670-00000e35 called: A0-48-1C-56-C6-A6 calling: C0-BD-D1-89-0B-90
port: 2558 ip: 92.61.7.155 sessTime:  seconds input: 7238B output: 7872B
Thu Dec 17 15:31:38 2015 Connect: 1234567890@realm-is-here sessId:
88a18c10-0000028b called: 14-58-D0-66-B6-51 calling: C0-BD-D1-89-0B-90
port: 535 ip:
Thu Dec 17 15:31:56 2015 Connect: 1234567890@realm-is-here sessId:
7d5f1897-0000077f called: A0-48-1C-56-C6-A1 calling: C0-BD-D1-89-0B-90
port: 1386 ip:
Thu Dec 17 15:32:06 2015 Connect: 1234567890@realm-is-here sessId:
68d0d39a-00000366 called: 14-58-D0-66-C6-61 calling: C0-BD-D1-89-0B-90
port: 639 ip:
Thu Dec 17 15:32:36 2015 Disconnect: 1234567890@realm-is-here sessId:
90649829-000001e3 called: 14-58-D0-66-E6-55 calling: C0-BD-D1-89-0B-90
port: 399 ip: 92.61.7.155 sessTime:  seconds input: 55755B output: 34278B
Thu Dec 17 15:32:43 2015 Connect: 1234567890@realm-is-here sessId:
2e5136a5-0000018c called: 14-58-D0-66-B6-9C calling: C0-BD-D1-89-0B-90
port: 293 ip:
Thu Dec 17 15:32:45 2015 Connect: 1234567890@realm-is-here sessId:
80a8748c-000001be called: 14-58-D0-66-56-1E calling: C0-BD-D1-89-0B-90
port: 351 ip:
Thu Dec 17 15:32:48 2015 Disconnect: 1234567890@realm-is-here sessId:
80a8748c-000001be called: 14-58-D0-66-56-1E calling: C0-BD-D1-89-0B-90
port: 351 ip: 92.61.7.155 sessTime: 3 seconds input: 4892B output: 2684B
Thu Dec 17 15:32:50 2015 Connect: 1234567890@realm-is-here sessId:
e767e76d-00000143 called: 14-58-D0-66-C6-7A calling: C0-BD-D1-89-0B-90
port: 262 ip:
Thu Dec 17 15:32:51 2015 Connect: 1234567890@realm-is-here sessId:
d9b51d3b-00000230 called: 14-58-D0-66-C6-56 calling: C0-BD-D1-89-0B-90
port: 442 ip:
Thu Dec 17 15:32:51 2015 Disconnect: 1234567890@realm-is-here sessId:
88a18c10-0000028b called: 14-58-D0-66-B6-51 calling: C0-BD-D1-89-0B-90
port: 535 ip: 92.61.7.155 sessTime:  seconds input: 5743B output: 3632B
/
Why do i get that much lines even when there is no login-logout attempt
by the user?

There is another issue with accounting. I can get the inner user name
sometimes (As shown above both files look like okay) but sometimes I can't.
That's the log (Some part of it actually that about the case for the
user *1639**5**905204*/@realm-is-here/):

(And again there is no attempt to login or logout by the user at all.)
Access Accept/Reject:
Thu Dec 17 17:26:20 2015 Access accepted: 16395905204@realm-is-here
NAS-IP-Address: 10.50.43.204 Called-Station-Id: 00-03-52-0B-2B-93
Packet-Src-IP-Address: 80.251.40.40 Calling-Station-Id: 8C-00-6D-07-3B-9A

Accounting:
Thu Dec 17 17:24:50 2015 Disconnect: 16395905204@realm-is-here sessId:
9e57770c-0000010d called: 00-03-52-0B-2B-93 calling: 8C-00-6D-07-3B-9A
port: 238 ip: 185.22.249.217 sessTime: 481 seconds input: 29613B output:
22215B
Thu Dec 17 17:26:20 2015 Connect: 16395905204@realm-is-here sessId:
1f605712-0000010e called: 00-03-52-0B-2B-93 calling: 8C-00-6D-07-3B-9A
port: 239 ip:

Debug:

(13337) Received Accounting-Request Id 62 from 80.251.40.40:54942 to
80.251.40.8:1813 length 364
(13337)   Acct-Multi-Session-Id =
"00-03-52-A6-A3-70-8C-00-6D-07-3B-9A-56-72-D1-E3-00-0E-DF-CA"
(13337)   Acct-Session-Id = "9e57770c-0000010d"
(13337)   NAS-Port = 238
(13337)   NAS-Port-Type = Wireless-802.11
(13337)   NAS-Identifier = "AU-MSC-5500-1"
(13337)   NAS-IP-Address = 10.50.43.204
(13337)   Framed-MTU = 1496
(13337)   Framed-IP-Address = 185.22.249.217
(13337)   User-Name = "16395905204@realm-is-here"
(13337)   Calling-Station-Id = "8C-00-6D-07-3B-9A"
(13337)   Called-Station-Id = "00-03-52-0B-2B-93"
(13337)   Acct-Status-Type = Stop
(13337)   Acct-Session-Time = 481
(13337)   Acct-Input-Packets = 102
(13337)   Acct-Output-Packets = 217
(13337)   Acct-Input-Octets = 29613
(13337)   Acct-Output-Octets = 22215
(13337)   Acct-Delay-Time = 0
(13337)   Colubris-AVPair = "ssid=AU WiFi Net"
(13337)   Colubris-AVPair = "incoming-vlan-id=51"
(13337)   Colubris-AVPair = "group=TND-Yerleske"
(13337)   Colubris-AVPair = "phytype=IEEE802dot11g"
(13337)   Attr-26.8744.250 = 0x00000001
(13337)   Attr-26.8744.249 = 0x50fb2808
(13337) # Executing section preacct from file
/usr/local/etc/raddb/sites-enabled/default
(13337)   preacct {
(13337)     [preprocess] = ok
(13337)     policy acct_unique {
(13337)       if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) {
(13337)       EXPAND %{string:Class}
(13337)          -->
(13337)       if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i)  -> FALSE
(13337)       else {
(13337)         update request {
(13337)           EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(13337)              --> c6f70635bf1e4b14ea52406bac73b3ee
(13337)           &Acct-Unique-Session-Id :=
c6f70635bf1e4b14ea52406bac73b3ee
(13337)         } # update request = noop
(13337)       } # else = noop
(13337)     } # policy acct_unique = noop
(13337) suffix: Checking for suffix after "@"
(13337) suffix: Looking up realm "ankara.edu.tr" for User-Name =
"16395905204@realm-is-here"
(13337) suffix: Found realm "ankara.edu.tr"
(13337) suffix: Adding Stripped-User-Name = "16395905204"
(13337) suffix: Adding Realm = "ankara.edu.tr"
(13337) suffix: Accounting realm is LOCAL
(13337)     [suffix] = ok
(13337)     [files] = noop
(13337)   } # preacct = ok
(13337) # Executing section accounting from file
/usr/local/etc/raddb/sites-enabled/default
(13337)   accounting {
(13337) detail: EXPAND
/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/%Y/%m/%d/detail-%H00
(13337) detail:    -->
/usr/local/var/log/radius/radacct/80.251.40.40/2015/12/17/detail-1700
(13337) detail:
/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/%Y/%m/%d/detail-%H00
expands to
/usr/local/var/log/radius/radacct/80.251.40.40/2015/12/17/detail-1700
(13337) detail: EXPAND %t
(13337) detail:    --> Thu Dec 17 17:24:50 2015
(13337)     [detail] = ok
(13337) log_accounting: EXPAND
Accounting-Request.%{%{Acct-Status-Type}:-unknown}
(13337) log_accounting:    --> Accounting-Request.Stop
(13337) log_accounting: EXPAND /usr/local/var/log/radius/linelog-accounting
(13337) log_accounting:    --> /usr/local/var/log/radius/linelog-accounting
(13337) log_accounting: EXPAND %t Disconnect: %{User-Name} sessId:
%{Acct-Session-Id} called: %{Called-Station-Id} calling:
%{Calling-Station-Id} port: %{NAS-Port} ip: %{Framed-IP-Address}
sessTime: %{Acct-Session-Time} seconds input: %{Acct-Input-Octets}B
output: %{Acct-Output-Octets}B
(13337) log_accounting:    --> Thu Dec 17 17:24:50 2015 Disconnect:
16395905204@realm-is-here sessId: 9e57770c-0000010d called:
00-03-52-0B-2B-93 calling: 8C-00-6D-07-3B-9A port: 238 ip:
185.22.249.217 sessTime: 481 seconds input: 29613B output: 22215B
(13337)     [log_accounting] = ok
(13337)     [exec] = noop
(13337) attr_filter.accounting_response: EXPAND %{User-Name}
(13337) attr_filter.accounting_response:    --> 16395905204@realm-is-here
(13337) attr_filter.accounting_response: Matched entry DEFAULT at line 12
(13337)     [attr_filter.accounting_response] = updated
(13337)   } # accounting = updated
(13337) Sent Accounting-Response Id 62 from 80.251.40.8:1813 to
80.251.40.40:54942 length 0
(13337) Finished request
(13337) Cleaning up request packet ID 62 with timestamp +369
Waking up in 0.5 seconds.

Above lines look like okay but then (at 17:26:20):

(16180) Received Access-Request Id 135 from 80.251.40.40:54942 to
80.251.40.8:1812 length 368
(16180)   Acct-Multi-Session-Id =
"00-03-52-A6-A3-70-8C-00-6D-07-3B-9A-56-72-D4-1E-00-0D-4B-44"
(16180)   Acct-Session-Id = "1f605712-0000010e"
(16180)   NAS-Port = 239
(16180)   NAS-Port-Type = Wireless-802.11
(16180)   NAS-Identifier = "AU-MSC-5500-1"
(16180)   NAS-IP-Address = 10.50.43.204
(16180)   Framed-MTU = 1496
(16180)   User-Name = "anonymous@realm-is-here"
(16180)   Calling-Station-Id = "8C-00-6D-07-3B-9A"
(16180)   Called-Station-Id = "00-03-52-0B-2B-93"
(16180)   Service-Type = Framed-User
(16180)   EAP-Message =
0x02f8001c01616e6f6e796d6f757340616e6b6172612e6564752e7472
(16180)   Colubris-AVPair = "ssid=AU WiFi Net"
(16180)   Colubris-AVPair = "incoming-vlan-id=51"
(16180)   Colubris-AVPair = "group=TND-Yerleske"
(16180)   Colubris-AVPair = "phytype=IEEE802dot11g"
(16180)   Attr-26.8744.250 = 0x00000001
(16180)   Attr-26.8744.249 = 0x50fb2808
(16180)   Message-Authenticator = 0x66886b75dae87c711e75232ce6e36114
(16180) # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
(16180)   authorize {
(16180)     policy filter_username {
(16180)       if (!&User-Name) {
(16180)       if (!&User-Name)  -> FALSE
(16180)       if (&User-Name =~ / /) {
(16180)       if (&User-Name =~ / /)  -> FALSE
(16180)       if (&User-Name =~ /@.*@/ ) {
(16180)       if (&User-Name =~ /@.*@/ )  -> FALSE
(16180)       if (&User-Name =~ /\.\./ ) {
(16180)       if (&User-Name =~ /\.\./ )  -> FALSE
(16180)       if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {
(16180)       if ((&User-Name =~ /@/) && (&User-Name !~
/@(.+)\.(.+)$/))   -> FALSE
(16180)       if (&User-Name =~ /\.$/)  {
(16180)       if (&User-Name =~ /\.$/)   -> FALSE
(16180)       if (&User-Name =~ /@\./)  {
(16180)       if (&User-Name =~ /@\./)   -> FALSE
(16180)     } # policy filter_username = notfound
(16180)     [preprocess] = ok
(16180)     if ("%{User-Name}" == "eduroamtest@ulakbim.gov.tr") {
(16180)     if ("%{User-Name}" == "eduroamtest@ulakbim.gov.tr")  -> FALSE
(16180)     elsif ("%{User-Name}" =~ /^(.+)@realm-is-here$/ &&
NAS-Identifier =~ /^AU-MSC-5500-(.+)$/) {
(16180)     EXPAND %{User-Name}
(16180)        --> anonymous@realm-is-here
(16180)     elsif ("%{User-Name}" =~ /^(.+)@realm-is-here$/ &&
NAS-Identifier =~ /^AU-MSC-5500-(.+)$/)  -> TRUE
(16180)     elsif ("%{User-Name}" =~ /^(.+)@realm-is-here$/ &&
NAS-Identifier =~ /^AU-MSC-5500-(.+)$/)  {
(16180)       if (Colubris-AVPair == "ssid=eduroam") {
(16180)       if (Colubris-AVPair == "ssid=eduroam")  -> FALSE
(16180)       else {
(16180)         [noop] = noop
(16180)       } # else = noop
(16180)     } # elsif ("%{User-Name}" =~ /^(.+)@realm-is-here$/ &&
NAS-Identifier =~ /^AU-MSC-5500-(.+)$/)  = noop
(16180)     ... skipping elsif for request 16180: Preceding "if" was taken
(16180)     ... skipping elsif for request 16180: Preceding "if" was taken
(16180)     ... skipping elsif for request 16180: Preceding "if" was taken
(16180) auth_log: EXPAND
/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/%Y/%m/%d/auth-detail-%H00
(16180) auth_log:    -->
/usr/local/var/log/radius/radacct/80.251.40.40/2015/12/17/auth-detail-1700
(16180) auth_log:
/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/%Y/%m/%d/auth-detail-%H00
expands to
/usr/local/var/log/radius/radacct/80.251.40.40/2015/12/17/auth-detail-1700
(16180) auth_log: EXPAND %t
(16180) auth_log:    --> Thu Dec 17 17:26:20 2015
(16180)     [auth_log] = ok
(16180)     [chap] = noop
(16180)     [mschap] = noop
(16180)     [digest] = noop
(16180) eap: Peer sent EAP Response (code 2) ID 248 length 28
(16180) eap: EAP-Identity reply, returning 'ok' so we can short-circuit
the rest of authorize
(16180)     [eap] = ok
(16180)   } # authorize = ok
(16180) Found Auth-Type = EAP
(16180) # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
(16180)   authenticate {
(16180) eap: Peer sent packet with method EAP Identity (1)
(16180) eap: Calling submodule eap_ttls to process data
(16180) eap_ttls: Initiating new EAP-TLS session
(16180) eap_ttls: [eaptls start] = request
(16180) eap: Sending EAP Request (code 1) ID 249 length 6
(16180) eap: EAP session adding &reply:State = 0xb7828561b77b903c
(16180)     [eap] = handled
(16180)   } # authenticate = handled
(16180) Using Post-Auth-Type Challenge
(16180) Post-Auth-Type sub-section not found.  Ignoring.
(16180) # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
(16180) Sent Access-Challenge Id 135 from 80.251.40.8:1812 to
80.251.40.40:54942 length 0
(16180)   EAP-Message = 0x01f900061520
(16180)   Message-Authenticator = 0x00000000000000000000000000000000
(16180)   State = 0xb7828561b77b903c4f6473e0f27d0e52
(16180) Finished request
Waking up in 0.2 seconds.

Thanks.

Logging

Süleyman Düzdaban