PostgreSQL accounting callingstationid field blank

Stoycho Ganev stoycho at ganev.org
Fri Jul 25 09:39:02 CEST 2014


Hello,

I'm using FreeRadius 2.1.12 (Debian stable) with PostgreSQL database to
do AAA for wifi (PEAP inner-tunnel) clients via Mikrotik (RouterOS) APs.

Everything works fine except that when accounting records are INSERTed
in the radacct table, the callingstationid field is left blank instead
of being populated with the MAC address of the calling station. This is
rather strange, because the Calling-Station-Id is present in the
Access-Request, and is the correct format (no wimax rubbish).

-- DEBUG --

rad_recv: Access-Request packet from host 192.168.13.4 port 41720, 
id=192, length=219
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 0x0200000c01636c6561766572
  Message-Authenticator = 0x434e50ee2a38b4327019b1f023d7006e
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 0 length 12
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[files] users: Matched entry DEFAULT at line 175
++[files] returns ok
[sql] expand: %{User-Name} -> cleaver
[sql] sql_set_user escaped user --> 'cleaver'
rlm_sql (sql): Reserving sql socket id: 4
[sql] expand: SELECT id, UserName, Attribute, Value, Op FROM radcheck 
WHERE Username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, UserName, 
Attribute, Value, Op FROM radcheck WHERE Username = 'cleaver' ORDER BY 
id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 2 , fields = 5
[sql] User found in radcheck table
[sql] expand: SELECT id, UserName, Attribute, Value, Op FROM radreply 
WHERE Username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, UserName, 
Attribute, Value, Op FROM radreply WHERE Username = 'cleaver' ORDER BY 
id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 5
[sql] expand: SELECT GroupName FROM radusergroup WHERE 
UserName='%{SQL-User-Name}' ORDER BY priority -> SELECT GroupName FROM 
radusergroup WHERE UserName='cleaver' ORDER BY priority
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 1
rlm_sql (sql): Released sql socket id: 4
++[sql] returns ok
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING: Auth-Type already set. Not setting to PAP
++[pap] returns noop
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type tls
[tls] Initiate
[tls] Start returned 1
++[eap] returns handled
Sending Access-Challenge of id 192 to 192.168.13.4 port 41720
  Session-Timeout := 1800
  EAP-Message = 0x010100061920
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0xed25053eed241cd2358f2aa5aaaf3fc2
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.13.4 port 59644, 
id=193, length=433
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  State = 0xed25053eed241cd2358f2aa5aaaf3fc2
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 
0x020100d01980000000c616030100c1010000bd030153d2019cb70c22292cf72fa06046597aa60d5c8a8c593674b564308f7a8eafeb000054c014c00ac022c02100390038c00fc0050035c012c008c01cc01b00160013c00dc003000ac013c009c01fc01e00330032c00ec004002fc011c007c00cc002000500040015001200090014001100080006000300ff01000040000b000403000102000a00340032000e000d0019000b000c00180009000a00160017000800060007001400150004000500120013000100020003000f00100011
  Message-Authenticator = 0xe7f541f1fe5aca909fd60af2ce86aa45
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 1 length 208
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
  TLS Length 198
[peap] Length Included
[peap] eaptls_verify returned 11
[peap] (other): before/accept initialization
[peap] TLS_accept: before/accept initialization
[peap] <<< TLS 1.0 Handshake [length 00c1], ClientHello
[peap] TLS_accept: SSLv3 read client hello A
[peap] >>> TLS 1.0 Handshake [length 0039], ServerHello
[peap] TLS_accept: SSLv3 write server hello A
[peap] >>> TLS 1.0 Handshake [length 1455], Certificate
[peap] TLS_accept: SSLv3 write certificate A
[peap] >>> TLS 1.0 Handshake [length 014b], ServerKeyExchange
[peap] TLS_accept: SSLv3 write key exchange A
[peap] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
[peap] TLS_accept: SSLv3 write server done A
[peap] TLS_accept: SSLv3 flush data
[peap] TLS_accept: Need to read more data: SSLv3 read client certificate 
A
In SSL Handshake Phase
In SSL Accept mode
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 193 to 192.168.13.4 port 59644
  EAP-Message = 
0x0102040019c0000015f1160301003902000035030153d2019c19456f2f53451c3160934c0e061b78cd24d0e8237107a07ad789e70a00c01400000dff01000100000b00040300010216030114550b00145100144e0006403082063c30820524a00302010202030eadac300d06092a864886f70d01010b050030818c310b300906035504061302494c31163014060355040a130d5374617274436f6d204c74642e312b3029060355040b1322536563757265204469676974616c204365727469666963617465205369676e696e67313830360603550403132f5374617274436f6d20436c6173732031205072696d61727920496e7465726d656469617465
  EAP-Message = 
0x20536572766572204341301e170d3134303232303138353131315a170d3135303232313133343733375a304e310b3009060355040613024247311a3018060355040313117261646975732e646174616d61782e62673123302106092a864886f70d01090116147765626d617374657240646174616d61782e626730820122300d06092a864886f70d01010105000382010f003082010a0282010100c0292ddae54021f9fe735191ff7292fb3eac929d3f958bb8c98aad1e040fbcbac519c7cfb9b64e8344fe7c7fba3c9447c9e6b1d9bdd86776a2343ab1ab141316f030740232147e896627594abab0e45cf4de79a82269e985aa374ba9e482ac351282
  EAP-Message = 
0x6618d71751108021ba0bc607cbb0c7616bd46c5e266db36faa8ccb063b2329866295968f9d7bd5ff6b83617b9780ef9a2c8668f52a90f9ed73d5308efc93360e6de3e21296b51c40164fc00c9fc4d61f18e759db66b1708362b51cbcbb2ee926a0a59118064cb9c4e8fad26541cb4da5480e654cb4c37a4b3354a22ffffc7f0655929fd1e9d4749950ab2f5a51f054e0851f814523d792b5e6e9fc7958eb0203010001a38202e2308202de30090603551d1304023000300b0603551d0f0404030203a830130603551d25040c300a06082b06010505070301301d0603551d0e04160414ddbc53b20d58f98e6db7e795176aab2ed8f5275d301f0603551d
  EAP-Message = 
0x23041830168014eb4234d098b0ab9ff41b6b08f7cc642eef0e2c4530280603551d110421301f82117261646975732e646174616d61782e6267820a646174616d61782e6267308201560603551d200482014d308201493008060667810c0102013082013b060b2b0601040181b5370102033082012a302e06082b060105050702011622687474703a2f2f7777772e737461727473736c2e636f6d2f706f6c6963792e7064663081f706082b060105050702023081ea302716205374617274436f6d2043657274696669636174696f6e20417574686f7269747930030201011a81be54686973206365727469666963617465207761732069737375656420
  EAP-Message = 0x6163636f7264696e6720746f
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0xed25053eec271cd2358f2aa5aaaf3fc2
Finished request 1.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.13.4 port 55690, 
id=194, length=231
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  State = 0xed25053eec271cd2358f2aa5aaaf3fc2
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 0x020200061900
  Message-Authenticator = 0xa8463c35eeecca48b017bdafe961171e
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 2 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake fragment handler
[peap] eaptls_verify returned 1
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 194 to 192.168.13.4 port 55690
  EAP-Message = 
0x010303fc19402074686520436c61737320312056616c69646174696f6e20726571756972656d656e7473206f6620746865205374617274436f6d20434120706f6c6963792c2072656c69616e6365206f6e6c7920666f722074686520696e74656e64656420707572706f736520696e20636f6d706c69616e6365206f66207468652072656c79696e67207061727479206f626c69676174696f6e732e30350603551d1f042e302c302aa028a0268624687474703a2f2f63726c2e737461727473736c2e636f6d2f637274312d63726c2e63726c30818e06082b06010505070101048181307f303906082b06010505073001862d687474703a2f2f6f6373
  EAP-Message = 
0x702e737461727473736c2e636f6d2f7375622f636c617373312f7365727665722f6361304206082b060105050730028636687474703a2f2f6169612e737461727473736c2e636f6d2f63657274732f7375622e636c617373312e7365727665722e63612e63727430230603551d12041c301a8618687474703a2f2f7777772e737461727473736c2e636f6d2f300d06092a864886f70d01010b050003820101005e7443be92a6e0ddc6b48e58d9a0e40059c6328814d556263095548d82d0ebe0f91d34feb0bb1aeaa5d8964fd244c2e6726b66e3a690e8e8156561cc3d75fd9126e726a4a6b00d0b9b0601ba144d2700ae0acd415c9050f7b74aaba7a9
  EAP-Message = 
0x2e72de4c98719c4845bf68eb2bdaacbb3a1e030f2d429cfa40cdc11fc338a3628beedd09fc2acb6cd6c73ddca416e6ce4d45fbc41d8ebfefb01b54e453e8e34efd6ee615636de6b286639cc44642d7253839632fff191c628d88943bbc3dc1aa3c54704e6fce6aee5958625c597c8ccfd024d96c313283c28eddc52f7fc5c0861cd4a0cd05bbdfc21a031851738200a5a96e8cadfebefa5f8d7a18c91d65b750e5a67f000638308206343082041ca003020102020118300d06092a864886f70d0101050500307d310b300906035504061302494c31163014060355040a130d5374617274436f6d204c74642e312b3029060355040b1322536563757265
  EAP-Message = 
0x204469676974616c204365727469666963617465205369676e696e6731293027060355040313205374617274436f6d2043657274696669636174696f6e20417574686f72697479301e170d3037313032343230353431375a170d3137313032343230353431375a30818c310b300906035504061302494c31163014060355040a130d5374617274436f6d204c74642e312b3029060355040b1322536563757265204469676974616c204365727469666963617465205369676e696e67313830360603550403132f5374617274436f6d20436c6173732031205072696d61727920496e7465726d6564696174652053657276657220434130820122300d06
  EAP-Message = 0x092a864886f70d01
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0xed25053eef261cd2358f2aa5aaaf3fc2
Finished request 2.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.13.4 port 44014, 
id=195, length=231
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  State = 0xed25053eef261cd2358f2aa5aaaf3fc2
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 0x020300061900
  Message-Authenticator = 0x55a162fc3d5e927e809dfa9f7a29e5dd
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 3 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake fragment handler
[peap] eaptls_verify returned 1
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 195 to 192.168.13.4 port 44014
  EAP-Message = 
0x010403fc1940010105000382010f003082010a0282010100b689c6acef09527807ac9263d0f44418188480561f91aee187fa3250b4d34706f0e6075f700e10f71dc0ce103634855a0f92ac83c6ac58523fba38e8fce7a724e240a60876c0926e9e2a6d4d3f6e61200adb59ded27d63b33e46fefa215118d7cd30a6ed076e3b7087b4f9faebee823c056f92f7a4dc0a301e9373fe07cad75f809d225852ae06da8b872369b0e42ad8ea83d2bdf371db705a280faf5a387045123f304dcd3baf17e50fcba0a95d48aab16150cb34cd3c5cc30be810c08c9bf0030362feb26c3e720eee1c432ac9480e5739c43121c810c12c87fe5495521f523c31129b7f
  EAP-Message = 
0xe7c0a0a559d5e28f3ef0d5a8e1d77031a9c4b3cfaf6d532f06f4a70203010001a38201ad308201a9300f0603551d130101ff040530030101ff300e0603551d0f0101ff040403020106301d0603551d0e04160414eb4234d098b0ab9ff41b6b08f7cc642eef0e2c45301f0603551d230418301680144e0bef1aa4405ba517698730ca346843d041aef2306606082b06010505070101045a3058302706082b06010505073001861b687474703a2f2f6f6373702e737461727473736c2e636f6d2f6361302d06082b060105050730028621687474703a2f2f7777772e737461727473736c2e636f6d2f73667363612e637274305b0603551d1f0454305230
  EAP-Message = 
0x27a025a0238621687474703a2f2f7777772e737461727473736c2e636f6d2f73667363612e63726c3027a025a0238621687474703a2f2f63726c2e737461727473736c2e636f6d2f73667363612e63726c3081800603551d20047930773075060b2b0601040181b5370102013066302e06082b060105050702011622687474703a2f2f7777772e737461727473736c2e636f6d2f706f6c6963792e706466303406082b060105050702011628687474703a2f2f7777772e737461727473736c2e636f6d2f696e7465726d6564696174652e706466300d06092a864886f70d010105050003820201002109493ea5886ee00b8b48da314d8ff75657a2e1d3
  EAP-Message = 
0x6257e9b556f38545753be5501f048be6a05a3ee700ae85d0fbff200364cbad02e1c69172f8a34dd6dee8cc3fa18aa2e37c37a7c64f8f35d6f4d66e067bdd21d9cf56ffcb302249fe8904f385e5aaf1e71fe875904dddf946f74234f745580c110d84b0c6da5d3ef9019ee7e1da5595be741c7bfc4d144fac7e55477d7bf4a50d491e95e8f712c1ccff76a62547d0f37535be97b75816ebaa5c786fec5330afea044dcca902e3f0b60412f630b1113d904e5664d7dc3c435f7339ef4baf87ebf6fe68884472ead207c669b0c1a18bef1749d761b145485f3b2021e95bb2ccf4d7e931f50b15613b7a94e3ebd9bc7f94ae6ae3626296a8647cb887f39932
  EAP-Message = 0x7e92a252bebbf865
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0xed25053eee211cd2358f2aa5aaaf3fc2
Finished request 3.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.13.4 port 33341, 
id=196, length=231
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  State = 0xed25053eee211cd2358f2aa5aaaf3fc2
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 0x020400061900
  Message-Authenticator = 0x3842e104ca596ede64f0b0be858ecbeb
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 4 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake fragment handler
[peap] eaptls_verify returned 1
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 196 to 192.168.13.4 port 33341
  EAP-Message = 
0x010503fc1940cfc9f230fc8bc1c2a696d75f89e15c3480f58f47072fb491bfb1a27e5f4b5ad05b9f248605515a690365434971c5e06f94346bf61bd8a9b04c7e53eb8f48dfca33b548fa364a1a53a6330cd089cd4915cd89313c90c072d7654b52358a461144b93d8e2865a63e799e5c084429adb035112e214eb8d2e7103e5d8483b3c3c2e4d2c6fd094b7409ddf1b3d3193e800da20b19f038e7c5c2afe223db61e29d5c6e2089492e236ab262c145b49faf8ba7f1223bf87de290d07a19fb4a4ce3d27d5f4a8303ed27d6239e6b8db459a2d9ef6c8229dd75193c3f4c108defbb7527d2ae83a7a8ce5ba70007cd308207c9308205b1a00302010202
  EAP-Message = 
0x0101300d06092a864886f70d0101050500307d310b300906035504061302494c31163014060355040a130d5374617274436f6d204c74642e312b3029060355040b1322536563757265204469676974616c204365727469666963617465205369676e696e6731293027060355040313205374617274436f6d2043657274696669636174696f6e20417574686f72697479301e170d3036303931373139343633365a170d3336303931373139343633365a307d310b300906035504061302494c31163014060355040a130d5374617274436f6d204c74642e312b3029060355040b1322536563757265204469676974616c20436572746966696361746520
  EAP-Message = 
0x5369676e696e6731293027060355040313205374617274436f6d2043657274696669636174696f6e20417574686f7269747930820222300d06092a864886f70d01010105000382020f003082020a0282020100c188db09bc6c467c789f957bb53390f27262d6c1362022245ecee977f2430aa20664a4cc8e36f838e623f06e6db13cdd72a3851ca1d33db4332bd32faffeeab0415967b6c4067d0a9e7485d6794c80377adf39055259f7f41b4643a4d28585d2c371f3756234ba2c8a7f1e8feeed34d011c796cd523dba33d6dd4dde0b3b4a4b9fc2262ffab5161c723577ca3c5de6cae1268b1a36765c01db741425feedb5a0880fdd78ca2d1f079730
  EAP-Message = 
0x012d7279fa46d6132aa8b9a6ab83491de5f2efdde4018e180a8f6353168562a90e193accb566a6c26b7407e42be1763eb46dd8f644e173621f3bc4bea05356256c5109f7aaabcabf76fd6d9bf39ddbbf3d66bc0c56aaaf9848953a4bdfa75850d93875a95bea430c02ff99ebe86c4d705b29659cddaa5dccaf0131ec0cebd28de8ea9c7be66ef727660c1a48d76e42e33fde213e7be10d70fb63aaa86c1a54b45c257ac9a2c98b16a6bb2c7e175e054d586e121d01ee12100dc6327f18fffcf4facd6e91e83649be1a48698bc2964d1a12b26917c10a90d6fa792248bfba7b69f870c7fa7a37d8d80dd2764f57ff90b7e391d2ddefc260b7673addfeaa
  EAP-Message = 0x9cf0d48b7f7222ce
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0xed25053ee9201cd2358f2aa5aaaf3fc2
Finished request 4.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.13.4 port 40019, 
id=197, length=231
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  State = 0xed25053ee9201cd2358f2aa5aaaf3fc2
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 0x020500061900
  Message-Authenticator = 0x1c4af62fc26823cf08d71d58cd5e3b37
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 5 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake fragment handler
[peap] eaptls_verify returned 1
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 197 to 192.168.13.4 port 40019
  EAP-Message = 
0x010603fc1940c69f97b6f8af8aa010a8d9fb18c6b6b55c523c89b6192a73010a0f03b31260f27a2f81dba36eff263097f58bdd8957b6ad3db3af2bc5b77602f0a5d62b9a86142a72f6e3338c5d094b13dfbb8c7413524b0203010001a38202523082024e300c0603551d13040530030101ff300b0603551d0f0404030201ae301d0603551d0e041604144e0bef1aa4405ba517698730ca346843d041aef230640603551d1f045d305b302ca02aa0288626687474703a2f2f636572742e7374617274636f6d2e6f72672f73667363612d63726c2e63726c302ba029a0278625687474703a2f2f63726c2e7374617274636f6d2e6f72672f73667363612d
  EAP-Message = 
0x63726c2e63726c3082015d0603551d2004820154308201503082014c060b2b0601040181b5370101013082013b302f06082b060105050702011623687474703a2f2f636572742e7374617274636f6d2e6f72672f706f6c6963792e706466303506082b060105050702011629687474703a2f2f636572742e7374617274636f6d2e6f72672f696e7465726d6564696174652e7064663081d006082b060105050702023081c330271620537461727420436f6d6d65726369616c20285374617274436f6d29204c74642e30030201011a81974c696d69746564204c696162696c6974792c2072656164207468652073656374696f6e202a4c6567616c204c
  EAP-Message = 
0x696d69746174696f6e732a206f6620746865205374617274436f6d2043657274696669636174696f6e20417574686f7269747920506f6c69637920617661696c61626c6520617420687474703a2f2f636572742e7374617274636f6d2e6f72672f706f6c6963792e706466301106096086480186f8420101040403020007303806096086480186f842010d042b16295374617274436f6d20467265652053534c2043657274696669636174696f6e20417574686f72697479300d06092a864886f70d01010505000382020100166c99f4660c34f5d0855e7d0aecda104e381c5edfa625054b9132c1e83bf13ddd44095b07498a29cb6602b7b19af72598
  EAP-Message = 
0x093c8e1be1dd36872b4bbb68d339663da026c7f239911d51ab827b7ed5ce5ae4e2035770699708f95e58a60adf8c069a451616380a5e57f662c77a0205e6bc1eb5f29ef4a92983f8b214e36e288744c3901ade38a93cac434d6445cedd28a95cf2737b04f817e8abb1f32e5c646e73313a12b8bcb311e47d8f81519a3b8d89f44d93667b3c03edd39a1d9af36550f5a0d0759f2faff0ea824398f8699c8979c4438e4672e3643612aff7251e388990777ec36b6ab9c3cb444bac78908be7c72c1e4b1144c8345227cd0a5d9f85c189d51a78f295105332dd80846675d9b56828fb612ebe84a838c0991286a51e6764ad062e2fa97085c7960f7c8965f5
  EAP-Message = 0x8e43540eabdda580
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0xed25053ee8231cd2358f2aa5aaaf3fc2
Finished request 5.
Going to the next request
Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 192.168.13.4 port 41337, 
id=198, length=231
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  State = 0xed25053ee8231cd2358f2aa5aaaf3fc2
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 0x020600061900
  Message-Authenticator = 0xe253ac1dbf0e01f0521a1e3b4c1374c6
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 6 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake fragment handler
[peap] eaptls_verify returned 1
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 198 to 192.168.13.4 port 41337
  EAP-Message = 
0x010702291900399460c034c996702ca312f51f487bbd1c7e6bb79d90f4223baef8fc2acafa8252a0efaf4b5593ebc1b5f0228bac344e262204a1872c754ab7e57d13d7b80c64c036d2c92f86128c2309c11b823b7349a36a578794e5d678c5994363e34de0772de165997269041a4709e60f015624fb1fbf0e79a9582eb9c409017e95ba6d00063eb2ea4a1039d8d02bf5bfec75bf9702c5091b08dc5537e281fb3784436220cae7564b65eafe6cc1249324a134eb05ff9a22ae9b7d3ff165510aa6306ab3f4881c800dfc728ae8835e160301014b0c00014703001741047e3580856cd5edf4f4abefd63bc85b6423cda233a8c0e45c47488bbcaeb217
  EAP-Message = 
0x2762be19884aa51fca0b9def15c868fb9c545b3700c30cc336d2abcfde87c2dece01003b878453bd62f496364a78ae88dcc832848ec534d060e2343af9f1f5f688b2c0cea2f2655534e52313738765fa800db99a33d1a7e5f58a54370f08bf9cb77a29a6ff09ceb6ba694b8ab033c3ee7bb307d4fe058d8cc19fb9287c950782d6d9450b1e93e3a8f1e1f64c8b5ed98e86524362d0ab4ca3551bd32d606eee37e1d33a73916fbf3a87f1f2fa21175e351f8227a2253dbddbac3ac6d55b5a279ddef8d82f8e11e7e6975f71fed931032f566e47e2d62d3b2e1a83a8c0ec2ada6559f4f659b372c6a8e3ff80f072ea5a4af4fa612bd20857dbb419130348
  EAP-Message = 
0x063cd372cf67ce5d60124666927a47f1eabd6e2d4ddd73740223398bb4e53ffc949610d302d516030100040e000000
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0xed25053eeb221cd2358f2aa5aaaf3fc2
Finished request 6.
Going to the next request
Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 192.168.13.4 port 52983, 
id=199, length=369
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  State = 0xed25053eeb221cd2358f2aa5aaaf3fc2
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 
0x020700901980000000861603010046100000424104058b9c5c1242b8575b45d5e832a09f6407a3b4b53375341b836b71ae6c439188dacd300428bfe2b83d3ae800551117332848d6a2bf086a011017ba361695109614030100010116030100306187693e81ba7869921c7b270631a94f20814177db82f30fc1546cf26b8d2f96140309976b5a0c5f023bcbc131e10994
  Message-Authenticator = 0x83f38d62342a7f24718fbcab145767dc
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 7 length 144
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
  TLS Length 134
[peap] Length Included
[peap] eaptls_verify returned 11
[peap] <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange
[peap] TLS_accept: SSLv3 read client key exchange A
[peap] <<< TLS 1.0 ChangeCipherSpec [length 0001]
[peap] <<< TLS 1.0 Handshake [length 0010], Finished
[peap] TLS_accept: SSLv3 read finished A
[peap] >>> TLS 1.0 ChangeCipherSpec [length 0001]
[peap] TLS_accept: SSLv3 write change cipher spec A
[peap] >>> TLS 1.0 Handshake [length 0010], Finished
[peap] TLS_accept: SSLv3 write finished A
[peap] TLS_accept: SSLv3 flush data
[peap] (other): SSL negotiation finished successfully
SSL Connection Established
[peap] eaptls_process returned 13
[peap] EAPTLS_HANDLED
++[eap] returns handled
Sending Access-Challenge of id 199 to 192.168.13.4 port 52983
  EAP-Message = 
0x01080041190014030100010116030100308cc8c199f323cc041f68e63f8a2f12b585c01804d096eee279062366279d8feee13fd3dfdb508487fbd475dbed8236dc
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0xed25053eea2d1cd2358f2aa5aaaf3fc2
Finished request 7.
Going to the next request
Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 192.168.13.4 port 60602, 
id=200, length=231
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  State = 0xed25053eea2d1cd2358f2aa5aaaf3fc2
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 0x020800061900
  Message-Authenticator = 0x475e745cc00cf27b19b89a29ca12c17b
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 8 length 6
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] Received TLS ACK
[peap] ACK handshake is finished
[peap] eaptls_verify returned 3
[peap] eaptls_process returned 3
[peap] EAPTLS_SUCCESS
[peap] Session established. Decoding tunneled attributes.
[peap] Peap state TUNNEL ESTABLISHED
++[eap] returns handled
Sending Access-Challenge of id 200 to 192.168.13.4 port 60602
  EAP-Message = 
0x0109002b19001703010020374e020851e52025f5d84f795b804a0a630e889fb780a25f3d880e1dde84c467
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0xed25053ee52c1cd2358f2aa5aaaf3fc2
Finished request 8.
Going to the next request
Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 192.168.13.4 port 54334, 
id=201, length=305
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  State = 0xed25053ee52c1cd2358f2aa5aaaf3fc2
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 
0x0209005019001703010020544f2f672ecbb7e80643c59adcf0eae044e137cbc08440550e933464a65dacf517030100204a4b03253c233a652a1f6319ab1f1efe70dfd3004b9b3167212592ee5e5a5111
  Message-Authenticator = 0x4eeadf3eeacefc6d290fe9e6949a9434
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 9 length 80
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established. Decoding tunneled attributes.
[peap] Peap state WAITING FOR INNER IDENTITY
[peap] Identity - cleaver
[peap] Got inner identity 'cleaver'
[peap] Setting default EAP type for tunneled EAP session.
[peap] Got tunneled request
  EAP-Message = 0x0209000c01636c6561766572
server {
[peap] Setting User-Name to cleaver
Sending tunneled request
  EAP-Message = 0x0209000c01636c6561766572
  FreeRADIUS-Proxied-To = 127.0.0.1
  User-Name = "cleaver"
  Service-Type = Framed-User
  Framed-MTU = 1400
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
server inner-tunnel {
# Executing section authorize from file 
/etc/freeradius/sites-enabled/inner-tunnel
+- entering group authorize {...}
[eap] EAP packet type response id 9 length 12
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[files] users: Matched entry DEFAULT at line 175
++[files] returns ok
[sql] expand: %{User-Name} -> cleaver
[sql] sql_set_user escaped user --> 'cleaver'
rlm_sql (sql): Reserving sql socket id: 3
[sql] expand: SELECT id, UserName, Attribute, Value, Op FROM radcheck 
WHERE Username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, UserName, 
Attribute, Value, Op FROM radcheck WHERE Username = 'cleaver' ORDER BY 
id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 2 , fields = 5
[sql] User found in radcheck table
[sql] expand: SELECT id, UserName, Attribute, Value, Op FROM radreply 
WHERE Username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, UserName, 
Attribute, Value, Op FROM radreply WHERE Username = 'cleaver' ORDER BY 
id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 5
[sql] expand: SELECT GroupName FROM radusergroup WHERE 
UserName='%{SQL-User-Name}' ORDER BY priority -> SELECT GroupName FROM 
radusergroup WHERE UserName='cleaver' ORDER BY priority
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 1
rlm_sql (sql): Released sql socket id: 3
++[sql] returns ok
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING: Auth-Type already set. Not setting to PAP
++[pap] returns noop
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/inner-tunnel
+- entering group authenticate {...}
[eap] EAP Identity
[eap] processing type mschapv2
rlm_eap_mschapv2: Issuing Challenge
++[eap] returns handled
} # server inner-tunnel
[peap] Got tunneled reply code 11
  Session-Timeout := 1800
  EAP-Message = 
0x010a00211a010a001c106f35422b2de0227f2c2b8d732d233bf0636c6561766572
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0x4c05f3034c0fe9a96e66b7b13f9be167
[peap] Got tunneled reply RADIUS code 11
  Session-Timeout := 1800
  EAP-Message = 
0x010a00211a010a001c106f35422b2de0227f2c2b8d732d233bf0636c6561766572
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0x4c05f3034c0fe9a96e66b7b13f9be167
[peap] Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 201 to 192.168.13.4 port 54334
  EAP-Message = 
0x010a004b19001703010040dc69c9263fc56ccb7d790c344b9076897269cf3715611e19ac8d357005f9bfa3cf33e84873ed6d12b96614786b43c80aab41e1a64f43db1bc9076c6d597ca674
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0xed25053ee42f1cd2358f2aa5aaaf3fc2
Finished request 9.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Access-Request packet from host 192.168.13.4 port 46152, 
id=202, length=369
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  State = 0xed25053ee42f1cd2358f2aa5aaaf3fc2
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 
0x020a0090190017030100202617cdd5e2cad6ab75d32a3c9c05c2d6d47e25af08b8d5abed9d06dd2a9649271703010060722908436bf9adae2c84e374bda4f228074e64be92d97421d081fd02c6c219bac6c1372d4579b41b5c85e1b68e9d51b2aa5dbdce53c8ec7af5aeccffa7aa9efeea3e094ff87d46dc35e63f1748b9fc495d89a59cc80b8984a004bc91ab59dcc0
  Message-Authenticator = 0x24d078ce9aecea7e3ba0be5332d544c2
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 10 length 144
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established. Decoding tunneled attributes.
[peap] Peap state phase2
[peap] EAP type mschapv2
[peap] Got tunneled request
  EAP-Message = 
0x020a00421a020a003d31610c5fb65f12ca5f9b3e38a96d0a16220000000000000000529d636d7c546dd5de8e76b5751ee13015ea1bfdcfa0ca5800636c6561766572
server {
[peap] Setting User-Name to cleaver
Sending tunneled request
  EAP-Message = 
0x020a00421a020a003d31610c5fb65f12ca5f9b3e38a96d0a16220000000000000000529d636d7c546dd5de8e76b5751ee13015ea1bfdcfa0ca5800636c6561766572
  FreeRADIUS-Proxied-To = 127.0.0.1
  User-Name = "cleaver"
  State = 0x4c05f3034c0fe9a96e66b7b13f9be167
  Service-Type = Framed-User
  Framed-MTU = 1400
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
server inner-tunnel {
# Executing section authorize from file 
/etc/freeradius/sites-enabled/inner-tunnel
+- entering group authorize {...}
[eap] EAP packet type response id 10 length 66
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[files] users: Matched entry DEFAULT at line 175
++[files] returns ok
[sql] expand: %{User-Name} -> cleaver
[sql] sql_set_user escaped user --> 'cleaver'
rlm_sql (sql): Reserving sql socket id: 2
[sql] expand: SELECT id, UserName, Attribute, Value, Op FROM radcheck 
WHERE Username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, UserName, 
Attribute, Value, Op FROM radcheck WHERE Username = 'cleaver' ORDER BY 
id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 2 , fields = 5
[sql] User found in radcheck table
[sql] expand: SELECT id, UserName, Attribute, Value, Op FROM radreply 
WHERE Username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, UserName, 
Attribute, Value, Op FROM radreply WHERE Username = 'cleaver' ORDER BY 
id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 5
[sql] expand: SELECT GroupName FROM radusergroup WHERE 
UserName='%{SQL-User-Name}' ORDER BY priority -> SELECT GroupName FROM 
radusergroup WHERE UserName='cleaver' ORDER BY priority
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 1
rlm_sql (sql): Released sql socket id: 2
++[sql] returns ok
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING: Auth-Type already set. Not setting to PAP
++[pap] returns noop
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/inner-tunnel
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/mschapv2
[eap] processing type mschapv2
[mschapv2] # Executing group from file 
/etc/freeradius/sites-enabled/inner-tunnel
[mschapv2] +- entering group MS-CHAP {...}
[mschap] Creating challenge hash with username: cleaver
[mschap] Told to do MS-CHAPv2 for cleaver with NT-Password
[mschap] adding MS-CHAPv2 MPPE keys
++[mschap] returns ok
MSCHAP Success
++[eap] returns handled
} # server inner-tunnel
[peap] Got tunneled reply code 11
  Session-Timeout := 1800
  EAP-Message = 
0x010b00331a030a002e533d36443735454438363231314442423730393235354437383530383330323446443046324236324139
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0x4c05f3034d0ee9a96e66b7b13f9be167
[peap] Got tunneled reply RADIUS code 11
  Session-Timeout := 1800
  EAP-Message = 
0x010b00331a030a002e533d36443735454438363231314442423730393235354437383530383330323446443046324236324139
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0x4c05f3034d0ee9a96e66b7b13f9be167
[peap] Got tunneled Access-Challenge
++[eap] returns handled
Sending Access-Challenge of id 202 to 192.168.13.4 port 46152
  EAP-Message = 
0x010b005b19001703010050cbb8af5543fab16b513a6374c93cc275f0680f64d183e2ec1bb7c71d3393b9c1331f0e67f02ee0b799d80940dc6a3d6f39c3bc96162323292ff0357a009f3acb32dbbb79735543a2f6897c0a2cd6c948
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0xed25053ee72e1cd2358f2aa5aaaf3fc2
Finished request 10.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Access-Request packet from host 192.168.13.4 port 55110, 
id=203, length=305
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  State = 0xed25053ee72e1cd2358f2aa5aaaf3fc2
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 
0x020b005019001703010020466fc6985c0987334d5c1acb554064d654956705af40cfc23f3587ecb3eb86941703010020de6fc4407f156d1dc4e9454d3d1da0627b69bb4748693f5caffb2a8caea79433
  Message-Authenticator = 0x6aecd12ca46c2ed0f2136abb95e278e1
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 11 length 80
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established. Decoding tunneled attributes.
[peap] Peap state phase2
[peap] EAP type mschapv2
[peap] Got tunneled request
  EAP-Message = 0x020b00061a03
server {
[peap] Setting User-Name to cleaver
Sending tunneled request
  EAP-Message = 0x020b00061a03
  FreeRADIUS-Proxied-To = 127.0.0.1
  User-Name = "cleaver"
  State = 0x4c05f3034d0ee9a96e66b7b13f9be167
  Service-Type = Framed-User
  Framed-MTU = 1400
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
server inner-tunnel {
# Executing section authorize from file 
/etc/freeradius/sites-enabled/inner-tunnel
+- entering group authorize {...}
[eap] EAP packet type response id 11 length 6
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
[files] users: Matched entry DEFAULT at line 175
++[files] returns ok
[sql] expand: %{User-Name} -> cleaver
[sql] sql_set_user escaped user --> 'cleaver'
rlm_sql (sql): Reserving sql socket id: 1
[sql] expand: SELECT id, UserName, Attribute, Value, Op FROM radcheck 
WHERE Username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, UserName, 
Attribute, Value, Op FROM radcheck WHERE Username = 'cleaver' ORDER BY 
id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 2 , fields = 5
[sql] User found in radcheck table
[sql] expand: SELECT id, UserName, Attribute, Value, Op FROM radreply 
WHERE Username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, UserName, 
Attribute, Value, Op FROM radreply WHERE Username = 'cleaver' ORDER BY 
id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 5
[sql] expand: SELECT GroupName FROM radusergroup WHERE 
UserName='%{SQL-User-Name}' ORDER BY priority -> SELECT GroupName FROM 
radusergroup WHERE UserName='cleaver' ORDER BY priority
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 1
rlm_sql (sql): Released sql socket id: 1
++[sql] returns ok
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING: Auth-Type already set. Not setting to PAP
++[pap] returns noop
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/inner-tunnel
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/mschapv2
[eap] processing type mschapv2
[eap] Freeing handler
++[eap] returns ok
# Executing section session from file 
/etc/freeradius/sites-enabled/inner-tunnel
+- entering group session {...}
[sql] expand: %{User-Name} -> cleaver
[sql] sql_set_user escaped user --> 'cleaver'
[sql] expand: SELECT COUNT(*) FROM radacct WHERE 
UserName='%{SQL-User-Name}' AND AcctStopTime IS NULL -> SELECT COUNT(*) 
FROM radacct WHERE UserName='cleaver' AND AcctStopTime IS NULL
rlm_sql (sql): Reserving sql socket id: 0
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 1 , fields = 1
rlm_sql (sql): Released sql socket id: 0
++[sql] returns ok
Login OK: [cleaver] (from client mikrotik03 port 0 cli CC-FA-00-C6-4A-A6 
via TLS tunnel)
  WARNING: Empty post-auth section. Using default return values.
# Executing section post-auth from file 
/etc/freeradius/sites-enabled/inner-tunnel
} # server inner-tunnel
[peap] Got tunneled reply code 2
  Session-Timeout := 1800
  MS-MPPE-Encryption-Policy = 0x00000001
  MS-MPPE-Encryption-Types = 0x00000006
  MS-MPPE-Send-Key = 0xe21015a00b64a87e6e02fc7698500f91
  MS-MPPE-Recv-Key = 0xe1a2a8b724972b4ba2b9f8e7f3790e3b
  EAP-Message = 0x030b0004
  Message-Authenticator = 0x00000000000000000000000000000000
  User-Name = "cleaver"
[peap] Got tunneled reply RADIUS code 2
  Session-Timeout := 1800
  MS-MPPE-Encryption-Policy = 0x00000001
  MS-MPPE-Encryption-Types = 0x00000006
  MS-MPPE-Send-Key = 0xe21015a00b64a87e6e02fc7698500f91
  MS-MPPE-Recv-Key = 0xe1a2a8b724972b4ba2b9f8e7f3790e3b
  EAP-Message = 0x030b0004
  Message-Authenticator = 0x00000000000000000000000000000000
  User-Name = "cleaver"
[peap] Tunneled authentication was successful.
[peap] SUCCESS
[peap] Saving tunneled attributes for later
++[eap] returns handled
Sending Access-Challenge of id 203 to 192.168.13.4 port 55110
  EAP-Message = 
0x010c002b190017030100204851eb10a5682951f8da0bb7072b7681914648dc4746b0eff3b6139ed68f542e
  Message-Authenticator = 0x00000000000000000000000000000000
  State = 0xed25053ee6291cd2358f2aa5aaaf3fc2
Finished request 11.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Access-Request packet from host 192.168.13.4 port 57335, 
id=204, length=305
  Service-Type = Framed-User
  Framed-MTU = 1400
  User-Name = "cleaver"
  State = 0xed25053ee6291cd2358f2aa5aaaf3fc2
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Calling-Station-Id = "CC-FA-00-C6-4A-A6"
  Called-Station-Id = "D4-CA-6D-F6-55-C1:datamax"
  EAP-Message = 
0x020c005019001703010020bc9a7815ca619d39bb6d1a7f30cfa319318f6da9a6996c50ecb209f5370b8e8717030100201fe12a0976816a84d7eff293d9ddd18b4a74843b7044fe0c52fe2dd5a74dc98e
  Message-Authenticator = 0x7841be02d6f1e4c97d52e2e9ce37412f
  NAS-Identifier = "MikroTik"
  NAS-IP-Address = 192.168.13.4
# Executing section authorize from file 
/etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[mschap] returns noop
[eap] EAP packet type response id 12 length 80
[eap] Continuing tunnel setup.
++[eap] returns ok
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/peap
[eap] processing type peap
[peap] processing EAP-TLS
[peap] eaptls_verify returned 7
[peap] Done initial handshake
[peap] eaptls_process returned 7
[peap] EAPTLS_OK
[peap] Session established. Decoding tunneled attributes.
[peap] Peap state send tlv success
[peap] Received EAP-TLV response.
[peap] Success
[peap] Using saved attributes from the original Access-Accept
  Session-Timeout := 1800
  User-Name = "cleaver"
[eap] Freeing handler
++[eap] returns ok
Login OK: [cleaver] (from client mikrotik03 port 0 cli 
CC-FA-00-C6-4A-A6)
  WARNING: Empty post-auth section. Using default return values.
# Executing section post-auth from file 
/etc/freeradius/sites-enabled/default
Sending Access-Accept of id 204 to 192.168.13.4 port 57335
  Session-Timeout := 1800
  User-Name = "cleaver"
  MS-MPPE-Recv-Key = 
0x752ff9b12af057a8ec7c4ec3ced5ab073e0f17efc28a92402da2e08eeb2f1751
  MS-MPPE-Send-Key = 
0x20f0a96db29944a3869a77df7fd6f6eeb84d2a7a62dbcd31fa441e93dcbc237d
  EAP-Message = 0x030c0004
  Message-Authenticator = 0x00000000000000000000000000000000
Finished request 12.
Going to the next request
Waking up in 4.7 seconds.
rad_recv: Accounting-Request packet from host 192.168.13.4 port 51157, 
id=205, length=153
  Service-Type = Framed-User
  NAS-Port-Id = "wlan1"
  NAS-Port-Type = Wireless-802.11
  User-Name = "cleaver"
  Acct-Session-Id = "82000027"
  Acct-Multi-Session-Id = 
"D4-CA-6D-F6-55-C1-CC-FA-00-C6-4A-A6-82-00-00-00-00-00-00-1F"
  Acct-Authentic = RADIUS
  Acct-Status-Type = Start
  NAS-Identifier = "MikroTik"
  Acct-Delay-Time = 0
  NAS-IP-Address = 192.168.13.4
# Executing section preacct from file 
/etc/freeradius/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port-Id = "wlan1",Client-IP-Address = 
192.168.13.4,NAS-IP-Address = 192.168.13.4,Acct-Session-Id = 
"82000027",User-Name = "cleaver"'
[acct_unique] Acct-Unique-Session-ID = "e27c8233063681bb".
++[acct_unique] returns ok
++[files] returns noop
# Executing section accounting from file 
/etc/freeradius/sites-enabled/default
+- entering group accounting {...}
[detail] expand: %{Packet-Src-IP-Address} -> 192.168.13.4
[detail] expand: 
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d 
-> /var/log/freeradius/radacct/192.168.13.4/detail-20140725
[detail] 
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d 
expands to /var/log/freeradius/radacct/192.168.13.4/detail-20140725
[detail] expand: %t -> Fri Jul 25 10:05:00 2014
++[detail] returns ok
[sql] expand: %{User-Name} -> cleaver
[sql] sql_set_user escaped user --> 'cleaver'
[sql] expand: %{NAS-Port} ->
[sql] ... expanding second conditional
[sql] expand: %{Acct-Delay-Time} -> 0
[sql] expand: INSERT INTO radacct (AcctSessionId, AcctUniqueId, 
UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, 
AcctAuthentic, ConnectInfo_start, CalledStationId, CallingStationId, 
ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, 
XAscendSessionSvrKey) VALUES('%{Acct-Session-Id}', 
'%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', NULLIF('%{Realm}', ''), 
'%{NAS-IP-Address}', %{%{NAS-Port}:-NULL}, '%{NAS-Port-Type}', 
('%S'::timestamp - '%{%{Acct-Delay-Time}:-0}'::interval), 
'%{Acct-Authentic}', '%{Connect-Info}', '%{Called-Station-Id}', 
'%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', 
NULLIF('%{Framed-IP-Address}', '')::inet, 0, 
'%{X-Ascend-Session-Svr-Key}') -> INSERT INTO radacct (AcctSessionId, 
AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, 
AcctStartTime, AcctAuthentic, ConnectInfo_start, CalledStationId, 
CallingStationId, ServiceType, FramedProtocol, FramedIPAddress, 
AcctStartDelay,
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: query affected rows = 1
rlm_sql (sql): Released sql socket id: 4
++[sql] returns ok
[attr_filter.accounting_response] expand: %{User-Name} -> cleaver
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 205 to 192.168.13.4 port 51157
Finished request 13.
Cleaning up request 13 ID 205 with timestamp +10
Going to the next request
Waking up in 4.6 seconds.

-- DEBUG --

I need the Calling-Station-Id in radacct for stale records cleaning and
it's important for me that this value is inserted correctly.

As you can see, the Calling-Station-Id = "CC-FA-00-C6-4A-A6" is passed
to the RADIUS server in Access-Request and

INSERT INTO radacct (AcctSessionId, AcctUniqueId, UserName, Realm, 
NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctAuthentic, 
ConnectInfo_start, CalledStationId, CallingStationId, ServiceType, 
FramedProtocol, FramedIPAddress, AcctStartDelay, XAscendSessionSvrKey) 
VALUES('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', 
'%{SQL-User-Name}', NULLIF('%{Realm}', ''), '%{NAS-IP-Address}', 
%{%{NAS-Port}:-NULL}, '%{NAS-Port-Type}', ('%S'::timestamp - 
'%{%{Acct-Delay-Time}:-0}'::interval), '%{Acct-Authentic}', 
'%{Connect-Info}', '%{Called-Station-Id}', '%{Calling-Station-Id}', 
'%{Service-Type}', '%{Framed-Protocol}', NULLIF('%{Framed-IP-Address}', 
'')::inet, 0, '%{X-Ascend-Session-Svr-Key}') -> INSERT INTO radacct 
(AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, 
NASPortType, AcctStartTime, AcctAuthentic, ConnectInfo_start, 
CalledStationId, CallingStationId, ServiceType, FramedProtocol, 
FramedIPAddress, AcctStartDelay,

seems correct except that it seems truncated.

I guess my problem is due to a configuration mistake, but I have not
been able to locate it so far. Any suggestions?

Thanks,
Stoycho


More information about the Freeradius-Users mailing list