Bug 1758072

Summary: teamd LACP runner sends debug messages even though log level is set to INFO
Product: Red Hat Enterprise Linux 7 Reporter: Renaud Métrich <rmetrich>
Component: libteamAssignee: Xin Long <lxin>
Status: CLOSED ERRATA QA Contact: LiLiang <liali>
Severity: high Docs Contact:
Priority: high    
Version: 7.7CC: brandon, d.bz-redhat, dhcpme, hunter86_bg, jmaxwell, lxin, network-qe, rgadani, rik.theys
Target Milestone: rc   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: libteam-1.29-2.el7 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-09-29 20:38:06 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Renaud Métrich 2019-10-03 08:08:36 UTC 
Description of problem:

teamd uses the libdaemon facility to send logs. When configuring a Team with LACP, customers can see 1 message from Debug level being printed every second, even though NetworkManager's log level (and teamd) is set to Info:

-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
eth1: lacp info state: XXX
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

This is very annoying and pollutes the journal.

It appears that when using libdaemon and syslog facility, *no* filtering is performed by the libdaemon library:

dlog.c:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
 35 static int daemon_verbosity_level = LOG_INFO;

 46 void daemon_logv(int prio, const char* template, va_list arglist) {
 47     int saved_errno;
 48 
 49     saved_errno = errno;
 50 
 51     if (daemon_log_use & DAEMON_LOG_SYSLOG) {
 52         openlog(daemon_log_ident ? daemon_log_ident : "UNKNOWN", LOG_PID, LOG_DAEMON);
 53         vsyslog(prio | LOG_DAEMON, template, arglist);
 54     }
 55 
 56     if (prio > daemon_verbosity_level)
 57         goto end_daemon_logv;
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

This is intended behaviour and the root cause of the issue:

dlog.h:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
 94 /** Setter for the verbosity level of standard output.
 95  *
 96  * @param verbosity_prio Minimum priority level for messages to output
 97  * on standard output/error
 98  *
 99  * Allows to decide which messages to output on standard output/error
100  * streams. All messages are logged to syslog and this setting does
101  * not influence that.
102  *
103  * The default value is LOG_WARNING.
104  *
105  * @since 0.14
106  * @see DAEMON_SET_VERBOSITY_AVAILABLE
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

See also BZ #1758066 related to libdaemon to clarify if this is really intented behaviour.
If so, then libteam needs to filter out unwanted levels.


Version-Release number of selected component (if applicable):

libteam


How reproducible:

Always


Steps to Reproduce:
1. Set up a team with LACP

  TEAM_CONFIG="{ \"device\": \"team0\", \"runner\": { \"name\": \"lacp\", \"active\": true, \"fast_rate\": true, \"tx_hash\": [\"eth\", \"ipv4\", \"ipv6\"] }, \"link_watch\": {\"name\": \"ethtool\"}, \"ports\": {\"eth1\": {}, \"eth2\": {}} }"

Actual results:

Message printed every second

Expected results:

No message
Comment 2 Hangbin Liu 2019-10-09 03:59:36 UTC 
Hi Xin,

Do you think this is a libteam issue? I saw the code

 910 static void lacp_port_actor_update(struct lacp_port *lacp_port)
 911 {
 912         uint8_t state = 0;
 913

[...]

 932         teamd_log_dbg("%s: lacp info state: 0x%02X.", lacp_port->tdport->ifname,
 933                                                       state);
 934         lacp_port->actor.state = state;
 935 }

It should only be printed with LOG_DEBUG level.
Comment 3 Xin Long 2019-10-09 11:58:47 UTC 
(In reply to Hangbin Liu from comment #2)
> Hi Xin,
> 
> Do you think this is a libteam issue? I saw the code
we need to check the log if there are other debug msgs printed or just this one?

I couldn't see the config file, we should also check if the NM's level works well for teamd.

> 
>  910 static void lacp_port_actor_update(struct lacp_port *lacp_port)
>  911 {
>  912         uint8_t state = 0;
>  913
> 
> [...]
> 
>  932         teamd_log_dbg("%s: lacp info state: 0x%02X.",
> lacp_port->tdport->ifname,
>  933                                                       state);
>  934         lacp_port->actor.state = state;
>  935 }
> 
> It should only be printed with LOG_DEBUG level.
Comment 4 Hangbin Liu 2019-10-14 07:59:45 UTC 
(In reply to Renaud Métrich from comment #0)
> Description of problem:
> 
> teamd uses the libdaemon facility to send logs. When configuring a Team with
> LACP, customers can see 1 message from Debug level being printed every
> second, even though NetworkManager's log level (and teamd) is set to Info: 
> 
> -------- 8< ---------------- 8< ---------------- 8< ---------------- 8<
> --------
> eth1: lacp info state: XXX
> -------- 8< ---------------- 8< ---------------- 8< ---------------- 8<

Hi Renaud,

Would you please help ask for a full log file, a teamd config file and env values from customer?
The "eth1: lacp info state: XXX" info is valued if enabled LOG_DEBUG.

I know there are two ways to set the eanble LOG_DEBUG. Not sure how NM set LOG_DEBUG yet.

1. set .debug_level in config file
2. set TEAM_LOG to debug in environment variables

Thanks
Hangbin
Comment 5 Renaud Métrich 2019-10-14 08:23:11 UTC 
Hi Hangbin,

You can reproduce very easily using the reproducer in description without enabling Debug nowhere, no need for a real LACP setup for that, just use additional eth1 and eth2 interfaces in a VM.
I digged into the code and found that NetworkManager was executing teamd with TEAM_LOG_OUTPUT=syslog in the environment, causing indirectly libdaemon to no filter "debug" messages.
Hence, the teamd "log" macro must be enhanced to filter out messages below expected log level.

I did propose a new (hacky) workaround to the customer: wrap teamd into a script setting TEAM_LOG_OUTPUT to "stderr", which will then make libdaemon filter out unwanted messages:

1. Create a /usr/sbin/teamd wrapper

/usr/sbin/teamd:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
#!/bin/sh
# Wrapper to disable "ethX: lacp info state: 0xXX" messages (SFDC 02470849)
export TEAM_LOG_OUTPUT=stderr
exec /usr/bin/teamd "${@:-}"
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

2. Make it executable and fix SELinux context

-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
# chmod +x /usr/sbin/teamd
# semanage fcontext -a -e /usr/bin/teamd /usr/sbin/teamd
# restorecon -Fv /usr/sbin/teamd
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

3. Reboot the system or restart NetworkManager

-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
# ifdown team0
# systemctl restart NetworkManager
# ifup team0
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------


This works because NetworkManager searches for "teamd" binary in /usr/sbin, then /usr/bin (where it is actually) hence we can add this /usr/sbin/teamd wrapper "transparently" and the wrapper will survive teamd updates.

Renaud.
Comment 6 Hangbin Liu 2019-10-18 08:46:34 UTC 
(In reply to Renaud Métrich from comment #5)
> Hi Hangbin,
> 
> You can reproduce very easily using the reproducer in description without
> enabling Debug nowhere, no need for a real LACP setup for that, just use
> additional eth1 and eth2 interfaces in a VM.
> I digged into the code and found that NetworkManager was executing teamd
> with TEAM_LOG_OUTPUT=syslog in the environment, causing indirectly libdaemon
> to no filter "debug" messages.
> Hence, the teamd "log" macro must be enhanced to filter out messages below
> expected log level.
> 

Hi Renaud,

I got what's the problem now. And I also saw you mentioned in bz1758066 that
this may be expected behaviour for libdaemon as it intends to log all messages
if we use syslog.

From my side, print the debug messages to syslog doesn't like to be a libteam
issue as we call libdaemon to log messages, like many other applications.
If libdaemon intend to do this, then this just what it works. 

A user could use `journalctl -p 6` to filter out the debug messages. 

What do you think?

Thanks
Hangbin
Comment 8 Renaud Métrich 2019-10-18 10:11:41 UTC 
Hi Hangbin,

All other daemons, including NetworkManager filter out unwanted levels when logging messages.
Hence, either libdaemon should do that (bz1758066) or libteam.

Renaud.
Comment 10 Hangbin Liu 2019-10-21 03:38:59 UTC 
(In reply to Renaud Métrich from comment #8)
> Hi Hangbin,
> 
> All other daemons, including NetworkManager filter out unwanted levels when
> logging messages.
> Hence, either libdaemon should do that (bz1758066) or libteam.

Hi, Renaud,

I just read the NetworkManager code, it has an own implemented logging method instead of using libdaemon.

For libteam, it use libdaemon to print logs and it has already filtered the log by
daemon_log(LOG_ERR, ##args), daemon_log(LOG_INFO, ##args), daemon_log(LOG_DEBUG, ##args) etc.
Since libdaemon has its own way to decide the log priority(via daemon_logv and daemon_verbosity_level).
Implement another priority filter on libteam looks like creating another wheel.

Let's see what libdaemon maintainer would say in bz1758066?

Thanks
Hangbin
Comment 11 Hangbin Liu 2019-10-25 09:55:53 UTC 
*** Bug 1761139 has been marked as a duplicate of this bug. ***
Comment 12 Hangbin Liu 2020-01-13 02:57:29 UTC 
Hi Xin Long,

We need these patches for this bug.

f32310b libteam: wapper teamd_log_dbg with teamd_log_dbgx
575edc0 teamd: fix build error in expansion of macro teamd_log_dbgx
4990a8c teamd/lacp: fix segfault due to NULL pointer dereference

Thanks
Hangbin
Comment 16 LiLiang 2020-05-11 03:44:40 UTC 
reproduced on libteam-1.29-1.el7.x86_64


cat <<EOF >lacp.json
{
    "device":"team0",
    "runner":{
                "name":"lacp",
                "active": false,
                "fast_rate": true,
                "tx_hash": ["eth", "ipv4", "ipv6"]},
    "link_watch": {"name": "ethtool"}
}
EOF

slave1=ens1f0
slave2=ens1f1

export TEAM_LOG=info
nmcli general logging level info

nmcli con add con-name team0 type team ifname team0 config lacp.json
nmcli device set $slave1 managed on
nmcli device set $slave2 managed on
nmcli con reload
nmcli con add type ethernet con-name $slave1 ifname $slave1 master team0 slave-type team
nmcli con add type ethernet con-name $slave2 ifname $slave2 master team0 slave-type team
nmcli con up team0


journalctl -fu NetworkManager
-- Logs begin at Sun 2020-05-10 18:46:17 EDT. --
May 10 23:41:26 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[3569]: ens1f1: lacp info state: 0x3E.
May 10 23:41:26 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[3569]: ens1f0: lacp info state: 0x3E.
May 10 23:41:27 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[3569]: ens1f1: lacp info state: 0x3E.
May 10 23:41:27 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[3569]: ens1f0: lacp info state: 0x3E.

[root@hp-dl380g9-06 ~]# rpm -q libteam
libteam-1.29-1.el7.x86_64
Comment 17 LiLiang 2020-05-11 03:53:48 UTC 
verified on libteam-1.29-2.el7.x86_64.

when log level is debug:
[root@hp-dl380g9-06 ~]# journalctl -fu NetworkManager
May 10 23:50:15 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <debug> [1589169015.4845] device[0x55db55bcaea0] (team0): ip6-config: update (commit=0, new-config=0x55db55aab830)
May 10 23:50:15 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <debug> [1589169015.4850] device[0x55db55bcaea0] (team0): ip6-config: update IP Config instance (/org/freedesktop/NetworkManager/IP6Config/28)
May 10 23:50:15 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <debug> [1589169015.4850] dns-mgr: (device_ip_config_changed): queueing DNS updates (1)
May 10 23:50:15 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <debug> [1589169015.4851] dns-mgr: (device_ip_config_changed): DNS configuration did not change
May 10 23:50:15 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <debug> [1589169015.4851] dns-mgr: (device_ip_config_changed): no DNS changes to commit (0)
May 10 23:50:15 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4643]: ens1f1: lacp info state: 0x3E.
May 10 23:50:15 hp-dl380g9-06.rhts.eng.pek2.redhat.com dhclient[4789]: XMT: Info-Request on team0, interval 1020ms.
May 10 23:50:16 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4643]: ens1f0: lacp info state: 0x3E.
May 10 23:50:16 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4643]: ens1f1: lacp info state: 0x3E.
May 10 23:50:16 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <debug> [1589169016.7558] platform: (team0) signal: address 6 changed: 2001::a67d:f4d9:bdca:8832/64 lft 86399sec pref 14399sec lifetime 1777-1776[14400,86400] dev 21 flags noprefixroute src kernel
May 10 23:50:16 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <debug> [1589169016.7559] device[0x55db55bcaea0] (team0): queued IP6 config change
May 10 23:50:16 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <debug> [1589169016.7560] device[0x55db55bcaea0] (team0): ip6-config: update (commit=0, new-config=0x55db55b856a0)
May 10 23:50:17 hp-dl380g9-06.rhts.eng.pek2.redhat.com dhclient[4789]: XMT: Info-Request on team0, interval 2110ms.
May 10 23:50:17 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4643]: ens1f0: lacp info state: 0x3E.
May 10 23:50:17 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4643]: ens1f1: lacp info state: 0x3E.
May 10 23:50:18 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4643]: ens1f0: lacp info state: 0x3E.

when log level is info:
[root@hp-dl380g9-06 ~]# journalctl -fu NetworkManager
-- Logs begin at Sun 2020-05-10 18:46:17 EDT. --
May 10 23:50:45 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169045.5312] device (ens1f0): state change: activated -> deactivating (reason 'dependency-failed', sys-iface-state: 'managed')
May 10 23:50:45 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169045.5513] device (ens1f1): state change: activated -> deactivating (reason 'dependency-failed', sys-iface-state: 'managed')
May 10 23:50:45 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169045.6006] device (team0): state change: disconnected -> unmanaged (reason 'user-requested', sys-iface-state: 'managed')
May 10 23:50:45 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169045.6019] device (ens1f0): state change: deactivating -> disconnected (reason 'dependency-failed', sys-iface-state: 'managed')
May 10 23:50:45 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169045.6065] device (ens1f1): state change: deactivating -> disconnected (reason 'dependency-failed', sys-iface-state: 'managed')
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.7779] agent-manager: req[0x55db55b62680, :1.170/nmcli-connect/0]: agent registered
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.7802] device (team0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: Daemon not running
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.8474] device (team0): state change: unavailable -> disconnected (reason 'user-requested', sys-iface-state: 'managed')
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.8754] device (team0): Activation: starting connection 'team0' (ad589084-a9c4-40f5-897c-61e07cf2b5d5)
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.8755] audit: op="connection-activate" uuid="ad589084-a9c4-40f5-897c-61e07cf2b5d5" name="team0" pid=4853 uid=0 result="success"
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.8758] device (team0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.8776] device (team0): Activation: (team) started teamd [pid 4891]...
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.8778] policy: auto-activating connection 'ens1f0' (e29189bc-8c5d-42d4-908d-6348ac60a538)
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.8780] policy: auto-activating connection 'ens1f1' (6dbbda5d-cff4-4700-a0aa-9f7f168eef57)
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.8785] device (ens1f0): Activation: starting connection 'ens1f0' (e29189bc-8c5d-42d4-908d-6348ac60a538)
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.8789] device (ens1f1): Activation: starting connection 'ens1f1' (6dbbda5d-cff4-4700-a0aa-9f7f168eef57)
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.8790] device (ens1f0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: This program is not intended to be run as root.
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.8798] device (ens1f1): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.8805] device (ens1f0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4891]: TX balancing disabled.
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.9044] device (ens1f1): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4891]: 1.29 successfully started.
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.9068] device (team0): teamd appeared on D-Bus
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.9076] device (team0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
May 10 23:50:53 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169053.9082] device (ens1f0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
May 10 23:50:55 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169055.1781] device (team0): enslaved team port ens1f0
May 10 23:50:55 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169055.1781] device (ens1f0): Activation: connection 'ens1f0' enslaved, continuing activation
May 10 23:50:55 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169055.1784] device (ens1f0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
May 10 23:50:55 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169055.1793] device (ens1f1): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169056.4746] device (team0): enslaved team port ens1f1
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169056.4747] device (ens1f1): Activation: connection 'ens1f1' enslaved, continuing activation
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169056.4749] device (ens1f1): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169056.4763] device (team0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169056.4764] device (team0): IPv4 config waiting until carrier is on
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169056.4764] device (team0): IPv6 config waiting until carrier is on
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169056.4765] device (ens1f0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169056.4768] device (ens1f1): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169056.4769] device (ens1f0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4891]: ens1f0: Changed port state: "disabled" -> "expired"
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4891]: ens1f0: Failed to find "enabled" option.
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4891]: ens1f0: ethtool-link went up.
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169056.4923] device (ens1f0): Activation: successful, device activated.
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169056.4927] device (ens1f1): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169056.5056] device (ens1f1): Activation: successful, device activated.
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4891]: ens1f1: Changed port state: "disabled" -> "expired"
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4891]: ens1f1: ethtool-link went up.
May 10 23:50:56 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4891]: ens1f1: Changed port state: "expired" -> "current"
May 10 23:50:57 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4891]: ens1f0: Changed port state: "expired" -> "current"
May 10 23:50:58 hp-dl380g9-06.rhts.eng.pek2.redhat.com teamd_team0[4891]: carrier changed to UP
May 10 23:50:58 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169058.6145] device (team0): carrier: link connected
May 10 23:50:58 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169058.6147] dhcp4 (team0): activation: beginning transaction (timeout in 45 seconds)
May 10 23:50:58 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169058.6167] dhcp4 (team0): dhclient started with pid 4978
May 10 23:50:58 hp-dl380g9-06.rhts.eng.pek2.redhat.com dhclient[4978]: DHCPREQUEST on team0 to 255.255.255.255 port 67 (xid=0x6cc6719f)
May 10 23:51:00 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169060.4774] dhcp6 (team0): activation: beginning transaction (timeout in 45 seconds)
May 10 23:51:00 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169060.4793] dhcp6 (team0): dhclient started with pid 4984
May 10 23:51:01 hp-dl380g9-06.rhts.eng.pek2.redhat.com dhclient[4984]: XMT: Info-Request on team0, interval 930ms.
May 10 23:51:02 hp-dl380g9-06.rhts.eng.pek2.redhat.com dhclient[4984]: XMT: Info-Request on team0, interval 1930ms.
May 10 23:51:02 hp-dl380g9-06.rhts.eng.pek2.redhat.com dhclient[4978]: DHCPREQUEST on team0 to 255.255.255.255 port 67 (xid=0x6cc6719f)
May 10 23:51:02 hp-dl380g9-06.rhts.eng.pek2.redhat.com dhclient[4978]: DHCPACK from 192.168.1.253 (xid=0x6cc6719f)
May 10 23:51:02 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169062.2411] dhcp4 (team0):   address 192.168.1.234
May 10 23:51:02 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169062.2411] dhcp4 (team0):   plen 24 (255.255.255.0)
May 10 23:51:02 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169062.2411] dhcp4 (team0):   lease time 3600
May 10 23:51:02 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169062.2411] dhcp4 (team0): state changed unknown -> bound
May 10 23:51:02 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169062.2420] device (team0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
May 10 23:51:02 hp-dl380g9-06.rhts.eng.pek2.redhat.com dhclient[4978]: bound to 192.168.1.234 -- renewal in 1593 seconds.
May 10 23:51:02 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169062.2427] device (team0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
May 10 23:51:02 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169062.2429] device (team0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
May 10 23:51:02 hp-dl380g9-06.rhts.eng.pek2.redhat.com NetworkManager[3076]: <info>  [1589169062.2563] device (team0): Activation: successful, device activated.
May 10 23:51:04 hp-dl380g9-06.rhts.eng.pek2.redhat.com dhclient[4984]: XMT: Info-Request on team0, interval 3890ms.
May 10 23:51:07 hp-dl380g9-06.rhts.eng.pek2.redhat.com dhclient[4984]: XMT: Info-Request on team0, interval 7900ms.
^C
Comment 20 brandon 2020-08-15 09:46:57 UTC 
Also occurs in RHEL 8 in libteam-1.29-1.el8.x86_64

Another example config that produces a lot of output, with log level at info:

{
    "runner": {
        "name": "lacp",
        "tx_balancer": {
            "name": "basic"
        },
        "tx_hash": [
            "ip"
        ],
        "active": true,
        "fast_rate": true,
        "agg_select_policy": "bandwidth"
    },
    "link_watch": {
        "name": "ethtool"
    }
}

Logs:
Aug 15 02:39:11 systemname teamd_team0[3212]: enp65s0f1: lacp info state: 0x3F.
Aug 15 02:39:11 systemname teamd_team0[3212]: stats update for port enp65s0f1: "10513080820".
Aug 15 02:39:11 systemname teamd_team0[3212]: stats update for port enp65s0f0: "6300819350".
Aug 15 02:39:11 systemname teamd_team0[3212]: stats update for hash "90": "3567357900".
Aug 15 02:39:11 systemname teamd_team0[3212]: stats update for hash "87": "2825964298".
Aug 15 02:39:11 systemname teamd_team0[3212]: stats update for hash "85": "2521242242".
Aug 15 02:39:11 systemname teamd_team0[3212]: stats update for hash "84": "7893543146".
Aug 15 02:39:11 systemname teamd_team0[3212]: Remapped hash "87" (delta 25982) to port enp65s0f0.
Aug 15 02:39:11 systemname teamd_team0[3212]: Port enp65s0f1 rebalanced, delta: 533166
Aug 15 02:39:11 systemname teamd_team0[3212]: Port enp65s0f0 rebalanced, delta: 42244
Aug 15 02:39:11 systemname teamd_team0[3212]: enp65s0f0: lacp info state: 0x3F.
Aug 15 02:39:12 systemname teamd_team0[3212]: enp65s0f1: lacp info state: 0x3F.
Aug 15 02:39:12 systemname teamd_team0[3212]: enp65s0f0: lacp info state: 0x3F.
Aug 15 02:39:13 systemname teamd_team0[3212]: enp65s0f1: lacp info state: 0x3F.
Aug 15 02:39:13 systemname teamd_team0[3212]: enp65s0f0: lacp info state: 0x3F.
Aug 15 02:39:14 systemname teamd_team0[3212]: enp65s0f1: lacp info state: 0x3F.
Aug 15 02:39:14 systemname teamd_team0[3212]: enp65s0f0: lacp info state: 0x3F.
Aug 15 02:39:15 systemname teamd_team0[3212]: enp65s0f1: lacp info state: 0x3F.
Aug 15 02:39:15 systemname teamd_team0[3212]: enp65s0f0: lacp info state: 0x3F.
Aug 15 02:39:16 systemname teamd_team0[3212]: enp65s0f1: lacp info state: 0x3F.
Aug 15 02:39:16 systemname teamd_team0[3212]: stats update for port enp65s0f1: "10513162742".
Aug 15 02:39:16 systemname teamd_team0[3212]: stats update for port enp65s0f0: "6303930428".
Aug 15 02:39:16 systemname teamd_team0[3212]: stats update for hash "90": "3570408060".
Aug 15 02:39:16 systemname teamd_team0[3212]: stats update for hash "87": "2826012592".
Aug 15 02:39:16 systemname teamd_team0[3212]: stats update for hash "85": "2521324046".
Aug 15 02:39:16 systemname teamd_team0[3212]: stats update for hash "84": "7893555652".
Aug 15 02:39:16 systemname teamd_team0[3212]: stats update for hash "82": "113862".
Aug 15 02:39:16 systemname teamd_team0[3212]: stats update for hash "80": "125104".
Aug 15 02:39:16 systemname teamd_team0[3212]: Remapped hash "90" (delta 3050160) to port enp65s0f1.
Aug 15 02:39:16 systemname teamd_team0[3212]: Remapped hash "85" (delta 81804) to port enp65s0f0.
Aug 15 02:39:16 systemname teamd_team0[3212]: Remapped hash "82" (delta 118) to port enp65s0f0.
Aug 15 02:39:16 systemname teamd_team0[3212]: Port enp65s0f1 rebalanced, delta: 3050160
Aug 15 02:39:16 systemname teamd_team0[3212]: Port enp65s0f0 rebalanced, delta: 142840
Aug 15 02:39:16 systemname teamd_team0[3212]: enp65s0f0: lacp info state: 0x3F.
Aug 15 02:39:17 systemname teamd_team0[3212]: enp65s0f1: lacp info state: 0x3F.
Aug 15 02:39:17 systemname teamd_team0[3212]: enp65s0f0: lacp info state: 0x3F.
Aug 15 02:39:18 systemname teamd_team0[3212]: enp65s0f1: lacp info state: 0x3F.
Aug 15 02:39:18 systemname teamd_team0[3212]: enp65s0f0: lacp info state: 0x3F.
Aug 15 02:39:19 systemname teamd_team0[3212]: enp65s0f1: lacp info state: 0x3F.
Aug 15 02:39:19 systemname teamd_team0[3212]: enp65s0f0: lacp info state: 0x3F.
Comment 22 errata-xmlrpc 2020-09-29 20:38:06 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (libteam bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2020:4020
Comment 23 brandon 2020-09-30 09:48:22 UTC 
That only specifically mentions RHEL 7. Does the fix apply to RHEL 8 as well?
Comment 24 Xin Long 2020-10-10 09:59:37 UTC 
(In reply to brandon from comment #23)
> That only specifically mentions RHEL 7. Does the fix apply to RHEL 8 as well?

yes, rhel 8 now is using version 1.31, while these pathes were on 1.30 release on upstream.