[macsec] Macsec docker crashes when configuring an interface

Azarack commented 6 months ago

Description

When configuring an interface to use macsec the macsec docker container is crashing causing unexpected behavior.

Steps to reproduce the issue:

sudo config macsec port add Ethernet16 MSP1-AES-XPN-256

show logging | grep macsec | tail -n 50

Feb 21 20:29:29.296657 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet108'
Feb 21 20:29:29.296790 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet112'
Feb 21 20:29:29.297069 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet116'
Feb 21 20:29:29.297214 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet12'
Feb 21 20:29:29.297323 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet120'
Feb 21 20:29:29.297409 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet124'
Feb 21 20:29:29.297484 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet16'
Feb 21 20:29:29.297556 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet20'
Feb 21 20:29:29.297628 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet24'
Feb 21 20:29:29.297699 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet28'
Feb 21 20:29:29.298578 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet32'
Feb 21 20:29:29.298760 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet36'
Feb 21 20:29:29.298852 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet4'
Feb 21 20:29:29.298991 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet40'
Feb 21 20:29:29.299076 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet44'
Feb 21 20:29:29.299155 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet48'
Feb 21 20:29:29.299234 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet52'
Feb 21 20:29:29.299311 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet56'
Feb 21 20:29:29.299389 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet60'
Feb 21 20:29:29.299468 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet64'
Feb 21 20:29:29.299546 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet68'
Feb 21 20:29:29.299624 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet72'
Feb 21 20:29:29.299704 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet76'
Feb 21 20:29:29.299798 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet8'
Feb 21 20:29:29.299881 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet80'
Feb 21 20:29:29.299960 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet84'
Feb 21 20:29:29.300038 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet88'
Feb 21 20:29:29.300115 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet92'
Feb 21 20:29:29.300208 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec was not enabled on the port 'Ethernet96'
Feb 21 20:29:30.292059 vlab-t2-01 INFO macsec#supervisord 2024-02-21 20:29:30,290 INFO success: macsecmgrd entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Feb 21 20:29:31.323486 vlab-t2-01 INFO macsec#supervisord 2024-02-21 20:29:31,322 INFO exited: dependent-startup (exit status 0; expected)
Feb 21 20:31:43.563823 vlab-t2-01 NOTICE macsec#macsecmgrd: :- loadProfile: The MACsec profile 'MSP1-AES-XPN-256' is loaded
Feb 21 20:33:47.302058 vlab-t2-01 INFO macsec#supervisord: macsecmgrd Failed to connect to wpa_supplicant global interface: /var/run/Ethernet16  error: No such file or directory
Feb 21 20:33:47.341726 vlab-t2-01 NOTICE macsec#wpa_supplicant[16]: Successfully initialized wpa_supplicant
Feb 21 20:33:47.541703 vlab-t2-01 NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec profile 'MSP1-AES-XPN-256' on the port 'Ethernet16' is removed
Feb 21 20:33:47.542478 vlab-t2-01 ERR macsec#macsecmgrd: :- main: Runtime error: stoi
Feb 21 20:33:47.615183 vlab-t2-01 INFO macsec#supervisord 2024-02-21 20:33:47,608 INFO exited: macsecmgrd (exit status 255; not expected)
Feb 21 20:33:48.658712 vlab-t2-01 INFO macsec#supervisor-proc-exit-listener: Process 'macsecmgrd' exited unexpectedly. Terminating supervisor 'macsec'
Feb 21 20:33:48.662987 vlab-t2-01 INFO macsec#supervisord 2024-02-21 20:33:48,660 WARN received SIGTERM indicating exit request
Feb 21 20:33:48.663550 vlab-t2-01 INFO macsec#supervisord 2024-02-21 20:33:48,660 INFO waiting for supervisor-proc-exit-listener, rsyslogd to die
Feb 21 20:33:50.039003 vlab-t2-01 INFO container: docker cmd: wait for macsec
Feb 21 20:33:50.149021 vlab-t2-01 NOTICE root: Fast boot flag: macsec false.
Feb 21 20:33:50.157195 vlab-t2-01 NOTICE root: Warm boot flag: macsec false.
Feb 21 20:33:50.164813 vlab-t2-01 NOTICE root: Stopping macsec service...
Feb 21 20:33:50.490752 vlab-t2-01 DEBUG container: read_data: config:True feature:macsec fields:[('set_owner', 'local'), ('no_fallback_to_local', False), ('state', 'disabled')] val:['local', False, 'enabled']
Feb 21 20:33:50.493706 vlab-t2-01 DEBUG container: read_data: config:False feature:macsec fields:[('current_owner', 'none'), ('remote_state', 'none'), ('container_id', '')] val:['none', 'none', '']
Feb 21 20:33:50.497631 vlab-t2-01 DEBUG container: container_stop: macsec: set_owner:local current_owner:none remote_state:none docker_id:macsec
Feb 21 20:33:50.543550 vlab-t2-01 INFO container: docker cmd: stop for macsec
Feb 21 20:33:50.586399 vlab-t2-01 NOTICE root: Stopped macsec service...
Feb 21 20:33:50.594808 vlab-t2-01 INFO systemd[1]: macsec.service: Succeeded.

docker ps

CONTAINER ID   IMAGE                                COMMAND                  CREATED          STATUS          PORTS     NAMES
1d108fb39db7   docker-snmp:latest                   "/usr/local/bin/supe…"   22 minutes ago   Up 8 minutes              snmp
e5cc1e833fe4   docker-sonic-mgmt-framework:latest   "/usr/local/bin/supe…"   22 minutes ago   Up 8 minutes              mgmt-framework
514e36e723cd   docker-sonic-telemetry:latest        "/usr/local/bin/supe…"   22 minutes ago   Up 8 minutes              telemetry
cd5382ef1e0a   docker-lldp:latest                   "/usr/bin/docker-lld…"   24 minutes ago   Up 8 minutes              lldp
b0acb236c84e   docker-router-advertiser:latest      "/usr/bin/docker-ini…"   24 minutes ago   Up 8 minutes              radv
b92e705ebe97   docker-gbsyncd-vs:latest             "/usr/local/bin/supe…"   24 minutes ago   Up 8 minutes              gbsyncd
6d49d8b482da   docker-teamd:latest                  "/usr/local/bin/supe…"   24 minutes ago   Up 8 minutes              teamd
314f9ab592ac   docker-syncd-vs:latest               "/usr/local/bin/supe…"   24 minutes ago   Up 8 minutes              syncd
68f9100bc884   docker-fpm-frr:latest                "/usr/bin/docker_ini…"   24 minutes ago   Up 8 minutes              bgp
601ccd7c7b9d   docker-platform-monitor:latest       "/usr/bin/docker_ini…"   24 minutes ago   Up 9 minutes              pmon
3ca625818952   docker-orchagent:latest              "/usr/bin/docker-ini…"   25 minutes ago   Up 8 minutes              swss
9859e77094e8   docker-database:latest               "/usr/local/bin/dock…"   25 minutes ago   Up 25 minutes             database

Describe the results you received: Macsec docker crashes and further macsec commands fail.

Describe the results you expected: Interface to be configured and use macsec.

Additional information you deem important:

**Output of `show version`:**

SONiC Software Version: SONiC.202205.482527-1923cae0e
SONiC OS Version: 11
Distribution: Debian 11.8
Kernel: 5.10.0-23-2-amd64
Build commit: 1923cae0e
Build date: Wed Feb 21 11:45:00 UTC 2024
Built by: AzDevOps@vmss-soni0034QB

Platform: x86_64-kvm_x86_64-r0
HwSKU: Force10-S6000
ASIC: vs
ASIC Count: 1
Serial Number: N/A
Model Number: N/A
Hardware Revision: N/A
Uptime: 21:05:45 up 57 min,  1 user,  load average: 0.20, 0.59, 1.16
Date: Wed 21 Feb 2024 21:05:45

Docker images:
REPOSITORY                    TAG                       IMAGE ID       SIZE
docker-orchagent              202205.482527-1923cae0e   699b9b7bee34   350MB
docker-orchagent              latest                    699b9b7bee34   350MB
docker-fpm-frr                202205.482527-1923cae0e   b23d45946713   362MB
docker-fpm-frr                latest                    b23d45946713   362MB
docker-teamd                  202205.482527-1923cae0e   f7dcf2bd7519   332MB
docker-teamd                  latest                    f7dcf2bd7519   332MB
docker-macsec                 latest                    f058f10843ed   334MB
docker-dhcp-relay             latest                    796d7773c07b   324MB
docker-gbsyncd-vs             202205.482527-1923cae0e   b61647d26179   362MB
docker-gbsyncd-vs             latest                    b61647d26179   362MB
docker-snmp                   202205.482527-1923cae0e   93bb60e54854   366MB
docker-snmp                   latest                    93bb60e54854   366MB
docker-sonic-telemetry        202205.482527-1923cae0e   331e84114833   397MB
docker-sonic-telemetry        latest                    331e84114833   397MB
docker-platform-monitor       202205.482527-1923cae0e   024bb69a9d8a   441MB
docker-platform-monitor       latest                    024bb69a9d8a   441MB
docker-lldp                   202205.482527-1923cae0e   0f2b5c901e48   358MB
docker-lldp                   latest                    0f2b5c901e48   358MB
docker-database               202205.482527-1923cae0e   90eecddf6d8d   316MB
docker-database               latest                    90eecddf6d8d   316MB
docker-mux                    202205.482527-1923cae0e   0c159d4b746c   365MB
docker-mux                    latest                    0c159d4b746c   365MB
docker-router-advertiser      202205.482527-1923cae0e   963ae793036d   316MB
docker-router-advertiser      latest                    963ae793036d   316MB
docker-nat                    202205.482527-1923cae0e   84035ed7f55f   305MB
docker-nat                    latest                    84035ed7f55f   305MB
docker-sflow                  202205.482527-1923cae0e   b39d0382d92e   303MB
docker-sflow                  latest                    b39d0382d92e   303MB
docker-sonic-mgmt-framework   202205.482527-1923cae0e   9e9d2dcd2333   432MB
docker-sonic-mgmt-framework   latest                    9e9d2dcd2333   432MB
docker-syncd-vs               202205.482527-1923cae0e   87423168ec9a   300MB
docker-syncd-vs               latest                    87423168ec9a   300MB

The same behavior was seen with the master image as well.

**Attach debug file `sudo generate_dump`:**

```
(paste your output here)
```

sonic_dump_vlab-t2-01_20240221_210623.tar.gz

rlhui commented 6 months ago

@judyjoseph would you be able to take a tab on this? Thanks.

judyjoseph commented 6 months ago

@Azarack can you share the profile MSP1-AES-XPN-256 which you used. I shall take a look further as it is failing to parse the CAK key in profile.

Azarack commented 6 months ago

@judyjoseph I don't have that profile handy, but I do have this one which encountered the same issue: {'profile': {'priority': 64, 'cipher_suite': 'GCM-AES-XPN-256', 'primary_cak': '207b757a60617745504e5a20747a7c76725e524a450d0d01040a0c75297822227e07554155500e5d5157786d6c2a3d2031425a5e577e7e727f6b6c033124322627', 'primary_ckn': '6162636465666768696A6B6C6D6E6F707172737475767778797A303132333435', 'policy': 'security', 'send_sci': 'true', 'rekey_period': 240, 'name': '256_XPN_SCI'}, 'ctrl_links': defaultdict(<class 'dict'>, {'Ethernet16': {'name': 'ARISTA01T3', 'host': , 'port': 'Ethernet1', 'dut_name': 'vlab-t2-01'}, 'Ethernet20': {'name': 'ARISTA01T3', 'host': , 'port': 'Ethernet2', 'dut_name': 'vlab-t2-01'}, 'Ethernet32': {'name': 'ARISTA03T3', 'host': , 'port': 'Ethernet1', 'dut_name': 'vlab-t2-01'}, 'Ethernet104': {'name': 'ARISTA04T3', 'host': , 'port': 'Ethernet1', 'dut_name': 'vlab-t2-01'}, 'Ethernet108': {'name': 'ARISTA04T3', 'host': , 'port': 'Ethernet2', 'dut_name': 'vlab-t2-01'}, 'Ethernet92': {'name': 'ARISTA06T3', 'host': , 'port': 'Ethernet1', 'dut_name': 'vlab-t2-01'}}), 'macsec_duthost': , 'macsec_profile': {'priority': 64, 'cipher_suite': 'GCM-AES-XPN-256', 'primary_cak': '207b757a60617745504e5a20747a7c76725e524a450d0d01040a0c75297822227e07554155500e5d5157786d6c2a3d2031425a5e577e7e727f6b6c033124322627', 'primary_ckn': '6162636465666768696A6B6C6D6E6F707172737475767778797A303132333435', 'policy': 'security', 'send_sci': 'true', 'rekey_period': 240, 'name': '256_XPN_SCI'}

Azarack commented 5 months ago

Issue is resolved in 202305 build.

kamalsahu0001 commented 2 months ago

@judyjoseph I am still seeing the issue in latest 202305 branch with different vendor platforms on T0/T1 switches.

Jul 11 16:37:44.349180 sonic NOTICE macsec#macsecmgrd: :- loadProfile: The MACsec profile 'macsecdebug3' is loaded Jul 11 16:38:09.663608 sonic NOTICE python3: :- publish: EVENT_PUBLISHED: {"sonic-events-host:event-down-ctr":{"ctr_name":"gnmi","timestamp":"2024-07-11T16:38:09.662458Z"}} Jul 11 16:39:01.239133 sonic WARNING swss#orchagent: :- parsePortConfig: Unknown field(macsec): skipping ... Jul 11 16:39:01.260015 sonic NOTICE swss#portmgrd: :- doTask: Configure Ethernet64 MTU to 9100 Jul 11 16:39:01.273261 sonic NOTICE swss#portmgrd: :- doTask: Configure Ethernet64 admin status to up Jul 11 16:39:01.282037 sonic INFO macsec#supervisord: macsecmgrd Failed to connect to wpa_supplicant global interface: /var/run/Ethernet64 error: No such file or directory Jul 11 16:39:01.295881 sonic NOTICE macsec#wpa_supplicant[32]: Successfully initialized wpa_supplicant Jul 11 16:39:01.447411 sonic ERR macsec#wpa_supplicant[32]: Line 0: Invalid MKA-CAK 'eP##003Ӏˀ@#017k#016ퟻ�jO!-ïżTa6'. Jul 11 16:39:01.448059 sonic WARNING macsec#macsecmgrd: :- configureMACsec: Enable MACsec fail : Wpa_cli command : /sbin/wpa_cli -g /var/run/Ethernet64 IFNAME=Ethernet64 set_network 0 mka_cak eP##003Ӏˀ@#017k#016ퟻ�jO!-ïżTa6 Jul 11 16:39:01.448204 sonic WARNING macsec#macsecmgrd: :- enableMACsec: The MACsec profile 'macsecdebug3' on the port 'Ethernet64' loading fail Jul 11 16:39:01.509824 sonic NOTICE macsec#macsecmgrd: :- disableMACsec: The MACsec profile 'macsecdebug3' on the port 'Ethernet64' is removed

SONiC Software Version: SONiC.202305.592529-f2c7544bf SONiC OS Version: 11 Distribution: Debian 11.8 Kernel: 5.10.0-23-2-amd64 Build commit: f2c7544bf Build date: Thu Jul 11 12:52:33 UTC 2024 Built by: cloudtest@ac55a016c000007

judyjoseph commented 2 months ago

@kamalsahu0001 The support for macsec was enabled for devices in SpineRouter role, i.e T2. Could you try it on a T2 device ?

kamalsahu0001 commented 1 month ago

@judyjoseph So, support is not available for T0/T1 switches?

sonic-net / sonic-mgmt

[macsec] Macsec docker crashes when configuring an interface #11750