[IEC-16] [IEC][SEBA][PONSim] ONU has been validated - Authentication denied Created: 25/Jul/19  Updated: 23/Oct/19  Resolved: 20/Sep/19

Status: Done
Project: Integrated Edge Cloud
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Medium
Reporter: Ciprian Barbu Assignee: Ciprian Barbu
Resolution: Done Votes: 0
Labels: Release_2
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Relates
relates to IEC-23 [IEC][SEBA][PONSim] ONU authenticatio... To Do

 Description   

Running the tests for SEBA-in-a-Box with PONSim will fail with Authentication denied on aarch64 pods. There is no clear indication as to the cause, but there are several logs in ONOS that need to be checked



 Comments   
Comment by Ciprian Barbu [ 20/Sep/19 ]

This was in effect fixed by this change, which updates the commit id in iecedge/seba_charts:

https://gerrit.akraino.org/r/#/c/iec/+/1549/

Comment by Ciprian Barbu [ 30/Aug/19 ]

I managed to test with a modified Docker image based on the iecedge/freeradius:2.2.8. I simply commented out the sql option in the post-auth section and I was able to pass the authentication step.

I pushed a change to the corresponding repo:
https://github.com/iecedge/freeradius/commit/0d7310f8d631ff0c921752e013fa27e82e39c56c

I also pushed the modified docker image, overwriting the old version:
https://hub.docker.com/r/iecedge/freeradius/tags

There might still be an issue with the DHCP request step, I will have to investigate it further, maybe create a new card as well.

Comment by Ciprian Barbu [ 26/Aug/19 ]

Looking at the freeradius config file /etc/freeradius/sites-enabled/default, the post-auth section has the sql option enabled, unlike on the x86 pod, where is commented. So perhaps the Mysql error does have a role, but in this case indicates it does not belong there.

I will need to track down where the config is generated and modify it in order to test.

Comment by Ciprian Barbu [ 26/Aug/19 ]

On the freeradius side, on x86 we have:
rad_recv: Access-Request packet from host 100.100.0.73 port 1812, id=2, length=61rad_recv: Access-Request packet from host 100.100.0.73 port 1812, id=2, length=61 User-Name = "user" NAS-IP-Address = 10.128.9.244 EAP-Message = 0x020100090175736572 Message-Authenticator = 0xc8326151a000a08cf154a104937a4136# Executing section authorize from file /etc/freeradius/sites-enabled/default+group authorize

{ ....... +}

# group authenticate = ok+} # group authenticate = okLogin OK: [user] (from client 0.0.0.0/0 port 0)# Executing section post-auth from file /etc/freeradius/sites-enabled/default+group post-auth {+[exec] = noop} # group post-auth = noopSending Access-Accept of id 3 to 100.100.0.73 port 1812 EAP-Message = 0x03020004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "user"Finished request 1.Going to the next request

 

On the aarch64 pod:

rad_recv: Access-Request packet from host 100.100.236.199 port 1812, id=2, length=61rad_recv: Access-Request packet from host 100.100.236.199 port 1812, id=2, length=61 User-Name = "user" NAS-IP-Address = 10.128.9.244 EAP-Message = 0x020100090175736572 Message-Authenticator = 0x8a260065a4e048cfbbe8297ebf204b1d# Executing section authorize from file /etc/freeradius/sites-enabled/default+group authorize

{ ........ +}

# group authenticate = ok+} # group authenticate = okLogin OK: [user] (from client 0.0.0.0/0 port 0)# Executing section post-auth from file /etc/freeradius/sites-enabled/default+group post-auth {[sql] expand: %

{User-Name}

-> user[sql] sql_set_user escaped user --> 'user'[sql] expand: %{User-Password} -> [sql] ... expanding second conditional[sql] expand: %{Chap-Password} -> [sql] expand: INSERT INTO radpostauth                           (username, pass, reply, authdate, mac)                           VALUES (                           '%{User-Name}',                           '%{%

{User-Password}

:-%{Chap-Password}}',                           '%{reply:Packet-Type}', '%S', '%{Calling-Station-Id}') -> INSERT INTO radpostauth                           (username, pass, reply, authdate, mac)                           VALUES (                           'user',                           '',                           'Access-Accept', '2019-08-26 17:15:24', '')rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth                           (username, pass, reply, authdate, mac)                           VALUES (                           'user',                           '',                           'Access-Accept', '2019-08-26 17:15:24', '')rlm_sql (sql): Trying to (re)connect unconnected handle 31..rlm_sql (sql): Attempting to connect rlm_sql_mysql #31rlm_sql_mysql: Starting connect to MySQL server for #31rlm_sql_mysql: Couldn't connect socket to MySQL server radius@localhost:radiusrlm_sql_mysql: Mysql error 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)'rlm_sql (sql): Failed to connect DB handle #31rlm_sql (sql): Ignoring unconnected handle 31..

 

So something is different when executing the post-auth section. The Mysql error might nor might not be meaningful, the socket doesn't seem to exist on the x86 pod either.

Comment by Ciprian Barbu [ 26/Aug/19 ]

Update.

I haven't been able to make much progress on this because I kept getting into other issues with either SEBA or even PONSim, some of which I will detail in other related cards.

However, today I managed to spend some quality time on a pod which has deployed correctly and I managed to get some interesting information, also by comparing against a working x86 pod.

First of all here is the onos log showing logs from AAA:
onos> log:tail | grep opencord.aaa
2019-08-26 17:15:24,235 | INFO | 00.230.146:42080 | StateMachine | 187 - org.opencord.aaa - 1.8.0 | Creating a new state machine for of:0000aabbccddeeff128
2019-08-26 17:15:24,236 | INFO | 00.230.146:42080 | StateMachine$Idle | 187 - org.opencord.aaa - 1.8.0 | Moving from IDLE state to STARTED state.
2019-08-26 17:15:24,239 | INFO | 00.230.146:42080 | AaaManager | 187 - org.opencord.aaa - 1.8.0 | Auth event STARTED for of:0000aabbccddeeff/128
2019-08-26 17:15:24,240 | INFO | 00.230.146:42080 | StateMachine | 187 - org.opencord.aaa - 1.8.0 | Current State 1
2019-08-26 17:15:24,503 | INFO | 00.230.146:42080 | StateMachine$Started | 187 - org.opencord.aaa - 1.8.0 | Moving from STARTED state to PENDING state.
2019-08-26 17:15:24,505 | INFO | 00.230.146:42080 | AaaManager | 187 - org.opencord.aaa - 1.8.0 | Auth event REQUESTED for of:0000aabbccddeeff/128
2019-08-26 17:15:24,506 | INFO | 00.230.146:42080 | StateMachine | 187 - org.opencord.aaa - 1.8.0 | Current State 2
2019-08-26 17:15:25,708 | WARN | AAA-radius-0 | AaaManager | 187 - org.opencord.aaa - 1.8.0 | Send EAP failure message to supplicant 0A:58:0A:16:00:03
2019-08-26 17:15:25,711 | INFO | AAA-radius-0 | StateMachine$Pending | 187 - org.opencord.aaa - 1.8.0 | Moving from PENDING state to UNAUTHORIZED state.
2019-08-26 17:15:25,712 | INFO | AAA-radius-0 | StateMachine | 187 - org.opencord.aaa - 1.8.0 | Current State 4
2019-08-26 17:15:25,714 | INFO | AAA-radius-0 | AaaManager | 187 - org.opencord.aaa - 1.8.0 | Auth event DENIED for of:0000aabbccddeeff/128

By comparison, on the x86 pod:
2019-08-14 15:25:19,096 | INFO | p-app-activation | SocketBasedRadiusCommunicator | 188 - org.opencord.aaa - 1.8.0 | Remote RADIUS Server: /10.128.10.4:1812
2019-08-14 15:25:19,098 | INFO | p-app-activation | AaaManager | 188 - org.opencord.aaa - 1.8.0 | Started
2019-08-14 15:25:19,100 | INFO | p-app-activation | ApplicationManager | 130 - org.onosproject.onos-core-net - 1.13.5 | Application org.opencord.aaa has been activated
2019-08-14 15:25:19,097 | INFO | AAA-radius-0 | SocketBasedRadiusCommunicator | 188 - org.opencord.aaa - 1.8.0 | UDP listener thread starting up
2019-08-20 13:59:19,920 | WARN | tive-installer-3 | PacketManager | 130 - org.onosproject.onos-core-net - 1.13.5 | Failed to install packet request DefaultPacketRequest{selector=DefaultTrafficSelector

{criteria=[ETH_TYPE:eapol]}

, priority=40000, appId=DefaultApplicationId{id=169, name=org.opencord.aaa}, nodeId=100.100.0.73, applies to=all} to of:0000aabbccddeeff: BADPARAMS
2019-08-20 16:25:14,392 | INFO | 0.100.0.86:34122 | StateMachine | 188 - org.opencord.aaa - 1.8.0 | Creating a new state machine for of:0000aabbccddeeff128
2019-08-20 16:25:14,392 | INFO | 0.100.0.86:34122 | StateMachine$Idle | 188 - org.opencord.aaa - 1.8.0 | Moving from IDLE state to STARTED state.
2019-08-20 16:25:14,393 | INFO | 0.100.0.86:34122 | AaaManager | 188 - org.opencord.aaa - 1.8.0 | Auth event STARTED for of:0000aabbccddeeff/128
2019-08-20 16:25:14,393 | INFO | 0.100.0.86:34122 | StateMachine | 188 - org.opencord.aaa - 1.8.0 | Current State 1
2019-08-20 16:25:14,475 | INFO | 0.100.0.86:34122 | StateMachine$Started | 188 - org.opencord.aaa - 1.8.0 | Moving from STARTED state to PENDING state.
2019-08-20 16:25:14,475 | INFO | 0.100.0.86:34122 | AaaManager | 188 - org.opencord.aaa - 1.8.0 | Auth event REQUESTED for of:0000aabbccddeeff/128
2019-08-20 16:25:14,475 | INFO | 0.100.0.86:34122 | StateMachine | 188 - org.opencord.aaa - 1.8.0 | Current State 2
2019-08-20 16:25:14,570 | INFO | AAA-radius-0 | AaaManager | 188 - org.opencord.aaa - 1.8.0 | Send EAP success message to supplicant 0A:58:0A:16:00:02
2019-08-20 16:25:14,570 | INFO | AAA-radius-0 | StateMachine$Pending | 188 - org.opencord.aaa - 1.8.0 | Moving from PENDING state to AUTHORIZED state.
2019-08-20 16:25:14,570 | INFO | AAA-radius-0 | StateMachine | 188 - org.opencord.aaa - 1.8.0 | Current State 3
2019-08-20 16:25:14,570 | INFO | AAA-radius-0 | AaaManager | 188 - org.opencord.aaa - 1.8.0 | Auth event APPROVED for of:0000aabbccddeeff/128
2019-08-20 18:11:16,452 | INFO | 0.100.0.86:34122 | StateMachine$Authorized | 188 - org.opencord.aaa - 1.8.0 | Moving from AUTHORIZED state to STARTED state.
2019-08-20 18:11:16,452 | INFO | 0.100.0.86:34122 | AaaManager | 188 - org.opencord.aaa - 1.8.0 | Auth event STARTED for of:0000aabbccddeeff/128
2019-08-20 18:11:16,452 | INFO | 0.100.0.86:34122 | StateMachine | 188 - org.opencord.aaa - 1.8.0 | Current State 1
2019-08-20 18:11:16,598 | INFO | 0.100.0.86:34122 | StateMachine$Started | 188 - org.opencord.aaa - 1.8.0 | Moving from STARTED state to PENDING state.
2019-08-20 18:11:16,598 | INFO | 0.100.0.86:34122 | AaaManager | 188 - org.opencord.aaa - 1.8.0 | Auth event REQUESTED for of:0000aabbccddeeff/128
2019-08-20 18:11:16,598 | INFO | 0.100.0.86:34122 | StateMachine | 188 - org.opencord.aaa - 1.8.0 | Current State 2
2019-08-20 18:11:16,648 | INFO | AAA-radius-0 | AaaManager | 188 - org.opencord.aaa - 1.8.0 | Send EAP success message to supplicant 0A:58:0A:16:00:02
2019-08-20 18:11:16,649 | INFO | AAA-radius-0 | StateMachine$Pending | 188 - org.opencord.aaa - 1.8.0 | Moving from PENDING state to AUTHORIZED state.
2019-08-20 18:11:16,649 | INFO | AAA-radius-0 | StateMachine | 188 - org.opencord.aaa - 1.8.0 | Current State 3
2019-08-20 18:11:16,649 | INFO | AAA-radius-0 | AaaManager | 188 - org.opencord.aaa - 1.8.0 | Auth event APPROVED for of:0000aabbccddeeff/128

Then I also looked in the freeradius pod logs:

rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
rlm_sql (sql): Attempting to connect to radius@localhost:3306/radius
rlm_sql (sql): starting 0
rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
rlm_sql_mysql: Starting connect to MySQL server for #0
rlm_sql_mysql: Couldn't connect socket to MySQL server radius@localhost:radius
rlm_sql_mysql: Mysql error 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)'
rlm_sql (sql): Failed to connect DB handle #0
rlm_sql (sql): starting 1

 

So for now the freeradius logs look interesting, I will continue on this track.

Generated at Sat Feb 10 06:02:09 UTC 2024 using Jira 9.4.5#940005-sha1:e3094934eac4fd8653cf39da58f39364fb9cc7c1.