Excessive contrail-vrouter-dpdk logs generation

[Veyis Ceylan]

The "contrail-vrouter-agent-dpdk" container is generating an excessive amount of logs.
And it causes all the disk partition to be filled. It generated around 20k entry per second in "/var/log/contrail/agent/contrail-vrouter-dpdk.log"

23896 2018-10-30 13:17:31
21098 2018-10-30 13:17:32
22490 2018-10-30 13:17:33
24540 2018-10-30 13:17:34
18441 2018-10-30 13:17:35
22626 2018-10-30 13:17:36
20283 2018-10-30 13:17:37

As seen above, the first column is the generated amount of log entries per second in the "contrail-vrouter-dpdk.log"

The workaround is to truncate the log file,However the disk partition is filled quite fast. It writes around 5GB log per hour.

[Florin Vinti (flo-vinti)]

Below timestamp is about when it started and the same line "error connecting uvhost socket FD 77 to /var/run/vrouter/uvh_vif_tap7a933bd5-7d" is printed at that rate 20k+/s:

2018-10-27 19:02:10,784 UVHOST: Client _tap7a933bd5-7d: handling message 18
2018-10-27 19:02:10,784 UVHOST: Client _tap7a933bd5-7d: setting vring 1 ready state 1
2018-10-27 19:02:14,898 UVHOST: error connecting uvhost socket FD 77 to /var/run/vrouter/uvh_vif_tap7a933bd5-7d: Transport endpoint is already connected (106)
2018-10-27 19:02:19,899 UVHOST: error connecting uvhost socket FD 77 to /var/run/vrouter/uvh_vif_tap7a933bd5-7d: Transport endpoint is already connected (106)
2018-10-27 19:02:24,899 UVHOST: error connecting uvhost socket FD 77 to /var/run/vrouter/uvh_vif_tap7a933bd5-7d: Transport endpoint is already connected (106)

[Florin Vinti (flo-vinti)]

VIF, socket and port file exist as well:

[heat-admin@compute ~]$ ls -las /var/run/vrouter/ | grep tap7a933bd5
0 srwxrwxr-x. 1 qemu qemu 0 Oct 27 21:01 uvh_vif_tap7a933bd5-7d

[heat-admin@compute ~]$ sudo docker exec contrail_vrouter_agent vif --list | grep tap7a933bd5-7d
vif0/6 PMD: tap7a933bd5-7d

[heat-admin@compute ~]$ sudo docker exec contrail_vrouter_agent vif --get 6
Vrouter Interface Table

Flags: P=Policy, X=Cross Connect, S=Service Chain, Mr=Receive Mirror
       Mt=Transmit Mirror, Tc=Transmit Checksum Offload, L3=Layer 3, L2=Layer 2
       D=DHCP, Vp=Vhost Physical, Pr=Promiscuous, Vnt=Native Vlan Tagged
       Mnp=No MAC Proxy, Dpdk=DPDK PMD Interface, Rfl=Receive Filtering Offload, Mon=Interface is Monitored
       Uuf=Unknown Unicast Flood, Vof=VLAN insert/strip offload, Df=Drop New Flows, L=MAC Learning Enabled
       Proxy=MAC Requests Proxied Always, Er=Etree Root, Mn=Mirror without Vlan Tag, Ig=Igmp Trap Enabled

vif0/6 PMD: tap7a933bd5-7d
            Type:Virtual HWaddr:00:00:5e:00:01:00 IPaddr:1.2.3.4
            Vrf:4 Mcast Vrf:4 Flags:PL3L2DEr QOS:-1 Ref:20
            RX port packets:2342018 errors:181943 syscalls:5688
            RX queue packets:55248 errors:0
            RX queue errors to lcore 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
            RX packets:2523961 bytes:115468916 errors:0
            TX packets:5499310 bytes:284985897 errors:0
            Drops:303
            TX port packets:5342659 errors:431 syscalls:360

[heat-admin@compute ~]$ sudo docker exec contrail_vrouter_agent ls -las /var/lib/contrail/ports | grep 7a933bd5
4 -rw-r--r--. 1 root root 577 Oct 15 21:24 7a933bd5-7d0c-4d05-a086-04c320142a4d

[Jeya ganesh babu J (jjeya)]

Possibly a duplicate of https://bugs.launchpad.net/juniperopenstack/+bug/1799547. Vinod to verify and close.

[Veyis Ceylan (veyisceylan)]

We are using the following build on the vrouter.

2018-10-16 16:57:09,698 VROUTER: vRouter version: {"build-info": [{"build-time": "2018-10-15 15:49:57.076324", "build-hostname": "4163260628c5", "build-user": "root", "build-version": "5.0.2"}]}

[Veyis Ceylan (veyisceylan)]

[root@overcloud63m-compdpdk-41 ~]# docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
47fbf34ad5f4 100.64.87.201:8787/contrail-vrouter-agent-dpdk:5.0.1-0.214-rhel-queens "/entrypoint.sh /u..." 32 minutes ago Up 26 minutes contrail-vrouter-agent-dpdk
d7c4ce970d51 100.64.87.201:8787/contrail-vrouter-agent:5.0.1-0.214-rhel-queens "/entrypoint.sh /u..." 4 weeks ago Up 25 minutes contrail_vrouter_agent
5a8e63dc4468 100.64.87.201:8787/contrail-nodemgr:5.0.1-0.214-rhel-queens "/entrypoint.sh /b..." 4 weeks ago Up 4 weeks contrail_vrouter_agent_nodemgr
bad7243091bb 100.64.87.201:8787/rhosp13/openstack-cron:13.0-59 "kolla_start" 4 weeks ago Up 4 weeks logrotate_crond
e5d7f07b9525 100.64.87.201:8787/rhosp13/openstack-nova-compute:13.0-60 "kolla_start" 4 weeks ago Up 4 weeks (healthy) nova_migration_target
749c9eb1f028 100.64.87.201:8787/rhosp13/openstack-nova-compute:13.0-60 "kolla_start" 4 weeks ago Up 4 weeks (healthy) nova_compute
5b1086983084 100.64.87.201:8787/rhosp13/openstack-nova-libvirt:13.0-62 "kolla_start" 4 weeks ago Up 4 weeks nova_libvirt
21e5fb27701d 100.64.87.201:8787/rhosp13/openstack-nova-libvirt:13.0-62 "kolla_start" 4 weeks ago Up 4 weeks nova_virtlogd
988268f33f10 100.64.87.201:8787/rhosp13/openstack-iscsid:13.0-53 "kolla_start" 5 weeks ago Up 5 weeks (healthy) iscsid
[root@overcloud63m-compdpdk-41 ~]#
[root@overcloud63m-compdpdk-41 ~]#
[root@overcloud63m-compdpdk-41 ~]#
[root@overcloud63m-compdpdk-41 ~]# contrail-status
Pod Service Original Name State Status
vrouter agent contrail-vrouter-agent running Up 25 minutes
vrouter agent-dpdk contrail-vrouter-agent-dpdk running Up 26 minutes
vrouter nodemgr contrail-nodemgr running Up 4 weeks

vrouter DPDK module is PRESENT
== Contrail vrouter ==
nodemgr: active
agent: active

[root@overcloud63m-compdpdk-41 ~]#