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.