Enable logs from chain elements regardless of EnableTracing

[d-uzlov]

Description

Currently all logs from chain elements are enabled or disabled by log.EnableTracing(true) call.

cmd apps do log.EnableTracing(level == logrus.TraceLevel), which means that we either have TRACE logs, or we don't have any logs at all.

This PR decouples logs from tracing:

• If logLevel == TRACE and log.EnableTracing(true), then we will get current behavior
• If logLevel == TRACE and log.EnableTracing(false), then we will get current behavior without request=, request-diff=, request-response= log entries (because calculating diffs is expensive)
• If logLevel == DEBUG and log.EnableTracing(false) then we will only get DEBUG level log and above, but we will still get them, from all chain elements

Example logs from forwarder with `DEBUG` log level

Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0mSetting env variable DLV_LISTEN_FORWARDER to a valid dlv '--listen' value will cause the dlv debugger to execute this binary and listen as directed.
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0mthere are 9 phases which will be executed followed by a success message:
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0mthe phases include:
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0m1: get config from environment
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0m2: run vpp and get a connection to it
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0m3: get SR-IOV config from file
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0m4: init pools
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0m5: start device plugin server
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0m6: retrieve spiffe svid
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0m7: create xconnect network service endpoint
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0m8: create grpc server and register xconnect
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0m9: register xconnectns with the registry
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0ma final success message with start time duration
Jun 27 09:05:52.939�[36m [INFO] [cmd:/bin/forwarder] �[0mexecuting phase 1: get config from environment (time since start: 56.396µs)
This application is configured via the environment. The following environment
variables can be used:

KEY                             TYPE                                           DEFAULT                                                                               REQUIRED    DESCRIPTION
NSM_NAME                        String                                         forwarder                                                                                         Name of Endpoint
NSM_LABELS                      Comma-separated list of String:String pairs    p2p:true                                                                                          Labels related to this forwarder-vpp instance
NSM_NSNAME                      String                                         forwarder                                                                                         Name of Network Service to Register with Registry
NSM_CONNECT_TO                  URL                                            unix:///connect.to.socket                                                                         url to connect to
NSM_LISTEN_ON                   URL                                            unix:///listen.on.socket                                                                          url to listen on
NSM_MAX_TOKEN_LIFETIME          Duration                                       10m                                                                                               maximum lifetime of tokens
NSM_REGISTRY_CLIENT_POLICIES    Comma-separated list of String                 etc/nsm/opa/common/.*.rego,etc/nsm/opa/registry/.*.rego,etc/nsm/opa/client/.*.rego                paths to files and directories that contain registry client policies
NSM_LOG_LEVEL                   String                                         INFO                                                                                              Log level
NSM_DIAL_TIMEOUT                Duration                                       100ms                                                                                             Timeout for the dial the next endpoint
NSM_OPENTELEMETRYENDPOINT       String                                         otel-collector.observability.svc.cluster.local:4317                                               OpenTelemetry Collector Endpoint
NSM_TUNNEL_IP                   String                                                                                                                                           IP to use for tunnels
NSM_VXLAN_PORT                  Unsigned Integer                               0                                                                                                 VXLAN port to use
NSM_VPP_API_SOCKET              String                                         /var/run/vpp/external/vpp-api.sock                                                                filename of socket to connect to existing VPP instance.  If empty a VPP instance is run in forwarder
NSM_VPP_INIT                    Func                                           AF_PACKET                                                                                         type of VPP initialization. Must be AF_XDP, AF_PACKET or NONE
NSM_RESOURCE_POLL_TIMEOUT       Duration                                       30s                                                                                               device plugin polling timeout
NSM_DEVICE_PLUGIN_PATH          String                                         /var/lib/kubelet/device-plugins/                                                                  path to the device plugin directory
NSM_POD_RESOURCES_PATH          String                                         /var/lib/kubelet/pod-resources/                                                                   path to the pod resources directory
NSM_DEVICE_SELECTOR_FILE        String                                                                                                                                           config file for device name to label matching
NSM_SRIOV_CONFIG_FILE           String                                                                                                                                           PCI resources config path
NSM_PCI_DEVICES_PATH            String                                         /sys/bus/pci/devices                                                                              path to the PCI devices directory
NSM_PCI_DRIVERS_PATH            String                                         /sys/bus/pci/drivers                                                                              path to the PCI drivers directory
NSM_CGROUP_PATH                 String                                         /host/sys/fs/cgroup/devices                                                                       path to the host cgroup directory
NSM_VFIO_PATH                   String                                         /host/dev/vfio                                                                                    path to the host VFIO directory
NSM_MECHANISM_PRIORITY          Comma-separated list of String                                                                                                                   sets priorities for mechanisms
Jun 27 09:05:52.940�[36m [INFO] [cmd:/bin/forwarder] �[0mConfig: &config.Config{Name:"forwarder-vpp-hln6k", Labels:map[string]string{"p2p":"true"}, NSName:"forwarder", ConnectTo:url.URL{Scheme:"unix", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/var/lib/networkservicemesh/nsm.io.sock", RawPath:"", ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}, ListenOn:url.URL{Scheme:"unix", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/listen.on.sock", RawPath:"", ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}, MaxTokenLifetime:600000000000, RegistryClientPolicies:[]string{"etc/nsm/opa/common/.*.rego", "etc/nsm/opa/registry/.*.rego", "etc/nsm/opa/client/.*.rego"}, LogLevel:"DEBUG", DialTimeout:100000000, OpenTelemetryEndpoint:"otel-collector.observability.svc.cluster.local:4317", TunnelIP:net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0xac, 0x12, 0x0, 0x2}, VxlanPort:0x0, VppAPISocket:"/var/run/vpp/external/vpp-api.sock", VppInit:vppinit.Func{f:(func(context.Context, api.Connection, net.IP) (net.IP, error))(0xde9e80)}, ResourcePollTimeout:30000000000, DevicePluginPath:"/var/lib/kubelet/device-plugins/", PodResourcesPath:"/var/lib/kubelet/pod-resources/", DeviceSelectorFile:"", SRIOVConfigFile:"", PCIDevicesPath:"/sys/bus/pci/devices", PCIDriversPath:"/sys/bus/pci/drivers", CgroupPath:"/host/sys/fs/cgroup/devices", VFIOPath:"/host/dev/vfio", MechanismPriority:[]string(nil)}
Jun 27 09:05:52.940�[36m [INFO] [cmd:/bin/forwarder] �[0mforce enable tracing
Jun 27 09:05:52.940�[36m [INFO] [cmd:/bin/forwarder] [duration:854.203µs] �[0mcompleted phase 1: get config from environment
Jun 27 09:05:52.940�[36m [INFO] [cmd:/bin/forwarder] �[0mexecuting phase 2: run vpp and get a connection to it (time since start: 932.239µs)
Jun 27 09:05:52.940�[36m [INFO] �[0mConfiguration file: "/etc/vpp/helper/vpp.conf" not found, using defaults
Jun 27 09:05:52.941�[36m [INFO] [cmd:/bin/forwarder] �[0mlocal vpp is being used
Jun 27 09:05:52.941�[36m [INFO] [cmd:/bin/forwarder] [duration:1.530601ms] �[0mcompleted phase 2: run vpp and get a connection to it
Jun 27 09:05:52.941�[33m [WARN] [cmd:/bin/forwarder] �[0mskipping phases 3-5: no PCI resources config
Jun 27 09:05:52.941�[33m [WARN] [cmd:/bin/forwarder] �[0mSR-IOV is not enabled
Jun 27 09:05:52.941�[36m [INFO] [cmd:/bin/forwarder] �[0mexecuting phase 6: retrieving svid, check spire agent logs if this is the last line you see (time since start: 2.493968ms)
Jun 27 09:05:53.650�[36m [INFO] [cmd:vpp] �[0mvpp[3483328]: clib_sysfs_prealloc_hugepages:262: pre-allocating 64 additional 2048K hugepages on numa node 0
Jun 27 09:05:53.650�[36m [INFO] [cmd:vpp] �[0mvpp[3483328]: buffer: numa[0] falling back to non-hugepage backed buffer pool (vlib_physmem_shared_map_create: pmalloc_map_pages: failed to mmap 64 pages at 0x1000000000 fd 5 numa 0 flags 0x11: Cannot allocate memory)
Jun 27 09:05:53.960�[36m [INFO] �[0mSVID: "spiffe://k8s.nsm/ns/nsm-system/pod/forwarder-vpp-hln6k"
Jun 27 09:05:53.960�[36m [INFO] [cmd:/bin/forwarder] [duration:1.018309815s] �[0mcompleted phase 6: retrieving svid
Jun 27 09:05:53.960�[36m [INFO] [cmd:/bin/forwarder] �[0mexecuting phase 7: create xconnect network service endpoint (time since start: 1.02082301s)
Jun 27 09:05:53.975�[36m [INFO] [cmd:vpp] �[0mvpp[3483328]: vnet_feature_arc_init:272: feature node 'ip6-lookup' not found (before 'pt', arc 'ip6-output')
Jun 27 09:05:54.089�[37m [DEBU] �[0m/var/run/vpp/api.sock was created after 1.147295754s
Jun 27 09:05:54.090�[37m [DEBU] �[0msuccessfully connected to /var/run/vpp/api.sock after 1.191936ms and 1 attempts
Jun 27 09:05:54.349�[37m [DEBU] [cmd:/bin/forwarder] [duration:389.338383ms] [flags:AF_PACKET_API_FLAG_VERSION_2] [hostIfName:eth0] [hwaddr:02:42:ac:12:00:02] [mode:AF_PACKET_API_MODE_ETHERNET] [swIfIndex:1] [vppapi:AfPacketCreateV3] �[0mcompleted
Jun 27 09:05:54.350�[37m [DEBU] [MTU:[1500 1500 1500 1500]] [cmd:/bin/forwarder] [duration:195.146µs] [swIfIndex:1] [vppapi:SwInterfaceSetMtu] �[0mcompleted
Jun 27 09:05:54.350�[37m [DEBU] [aclIndex:0] [cmd:/bin/forwarder] [duration:109.134µs] [vppapi:ACLAddReplace] �[0mcompleted
Jun 27 09:05:54.350�[37m [DEBU] [aclIndex:1] [cmd:/bin/forwarder] [duration:94.497µs] [vppapi:ACLAddReplace] �[0mcompleted
Jun 27 09:05:54.368�[37m [DEBU] [NInput:1] [acls:[0 1]] [cmd:/bin/forwarder] [duration:17.700422ms] [swIfIndex:1] [vppapi:ACLInterfaceSetACLList] �[0mcompleted
Jun 27 09:05:54.368�[37m [DEBU] [cmd:/bin/forwarder] [duration:151.344µs] [swIfIndex:1] [vppapi:SwInterfaceSetFlags] �[0mcompleted
Jun 27 09:05:54.368�[37m [DEBU] [cmd:/bin/forwarder] [duration:209.423µs] [ipAddress:172.18.0.4] [macAddress:02:42:ac:12:00:04] [swIfIndex:1] [vppapi:IPNeighborAddDel] �[0mcompleted
Jun 27 09:05:54.368�[37m [DEBU] [cmd:/bin/forwarder] [duration:105.267µs] [ipAddress:172.18.0.3] [macAddress:02:42:ac:12:00:03] [swIfIndex:1] [vppapi:IPNeighborAddDel] �[0mcompleted
Jun 27 09:05:54.368�[37m [DEBU] [cmd:/bin/forwarder] [duration:81.288µs] [ipAddress:172.18.0.1] [macAddress:02:42:90:9b:68:6b] [swIfIndex:1] [vppapi:IPNeighborAddDel] �[0mcompleted
Jun 27 09:05:54.369�[36m [INFO] [cmd:/bin/forwarder] �[0mhost link was added as a neighbor: IP: 10.244.2.1, MAC: 2e:4f:01:af:89:15
Jun 27 09:05:54.369�[36m [INFO] [cmd:/bin/forwarder] �[0mhost link was added as a neighbor: IP: 10.244.2.1, MAC: 8a:f6:42:b2:7e:ad
Jun 27 09:05:54.369�[36m [INFO] [cmd:/bin/forwarder] �[0mhost link was added as a neighbor: IP: 10.244.2.1, MAC: 8a:76:e5:ef:8d:2e
Jun 27 09:05:54.369�[37m [DEBU] [cmd:/bin/forwarder] [duration:271.058µs] [isAdd:true] [prefix:172.18.0.2/16] [swIfIndex:1] [vppapi:SwInterfaceAddDelAddress] �[0mcompleted
Jun 27 09:05:54.369�[37m [DEBU] [cmd:/bin/forwarder] [duration:98.455µs] [isAdd:true] [nh.address:172.18.0.1] [prefix:0.0.0.0/0] [swIfIndex:1] [vppapi:IPRouteAddDel] �[0mcompleted
Jun 27 09:05:54.369�[37m [DEBU] [cmd:/bin/forwarder] [duration:92.644µs] [isAdd:true] [nh.address:172.18.0.4] [prefix:10.244.0.0/24] [swIfIndex:1] [vppapi:IPRouteAddDel] �[0mcompleted
Jun 27 09:05:54.370�[37m [DEBU] [cmd:/bin/forwarder] [duration:99.075µs] [isAdd:true] [nh.address:172.18.0.3] [prefix:10.244.1.0/24] [swIfIndex:1] [vppapi:IPRouteAddDel] �[0mcompleted
Jun 27 09:05:54.370�[37m [DEBU] [cmd:/bin/forwarder] [duration:108.914µs] [isAdd:true] [nh.address:ac12:3::] [prefix:172.18.0.0/16] [swIfIndex:1] [vppapi:IPRouteAddDel] �[0mcompleted
Jun 27 09:05:54.370�[37m [DEBU] [cmd:/bin/forwarder] [duration:154.751µs] [isAdd:true] [nh.address:ac12:3::] [prefix:fc00:f853:ccd:e793::2/128] [swIfIndex:1] [vppapi:IPRouteAddDel] �[0mcompleted
Jun 27 09:05:54.370�[37m [DEBU] [cmd:/bin/forwarder] [duration:71.274µs] [isAdd:true] [nh.address:ac12:3::] [prefix:fc00:f853:ccd:e793::/64] [swIfIndex:1] [vppapi:IPRouteAddDel] �[0mcompleted
Jun 27 09:05:54.370�[37m [DEBU] [cmd:/bin/forwarder] [duration:93.475µs] [isAdd:true] [nh.address:ac12:3::] [prefix:fe80::42:acff:fe12:2/128] [swIfIndex:1] [vppapi:IPRouteAddDel] �[0mcompleted
Jun 27 09:05:54.370�[37m [DEBU] [cmd:/bin/forwarder] [duration:82.365µs] [isAdd:true] [nh.address:ac12:3::] [prefix:fe80::/64] [swIfIndex:1] [vppapi:IPRouteAddDel] �[0mcompleted
Jun 27 09:05:54.370�[37m [DEBU] [cmd:/bin/forwarder] [duration:86.803µs] [isAdd:true] [nh.address:ac12:3::] [prefix:ff00::/8] [swIfIndex:1] [vppapi:IPRouteAddDel] �[0mcompleted
Jun 27 09:05:54.370�[37m [DEBU] [cmd:/bin/forwarder] [duration:110.858µs] [isAdd:true] [nh.address:fc00:f853:ccd:e793::1] [prefix:::/0] [swIfIndex:1] [vppapi:IPRouteAddDel] �[0mcompleted
Jun 27 09:05:54.371�[36m [INFO] [cmd:/bin/forwarder] [duration:411.036944ms] �[0mcompleted phase 7: create xconnect network service endpoint
Jun 27 09:05:54.371�[36m [INFO] [cmd:/bin/forwarder] �[0mexecuting phase 8: create grpc server and register xconnect (time since start: 1.431882165s)
Jun 27 09:05:54.371�[36m [INFO] [cmd:/bin/forwarder] [duration:406.002µs] �[0mcompleted phase 8: create grpc server and register xconnect
Jun 27 09:05:54.371�[36m [INFO] [cmd:/bin/forwarder] �[0mexecuting phase 9: register forwarder with the registry (time since start: 1.432307853s)
Jun 27 09:05:54.371�[37m [DEBU] [type:registry] �[0m(7.2)         passed clientURL: unix:///var/lib/networkservicemesh/nsm.io.sock
Jun 27 09:05:54.454�[36m [INFO] [type:registry] �[0m(6.2)        policy passed
Jun 27 09:05:54.455�[36m [INFO] [type:registry] �[0m(6.3)        policy passed
Jun 27 09:05:54.456�[36m [INFO] [type:registry] �[0m(6.4)        policy passed
Jun 27 09:05:54.457�[36m [INFO] [type:registry] �[0m(6.5)        policy passed
Jun 27 09:05:54.457�[36m [INFO] [type:registry] �[0m(6.6)        policy passed
Jun 27 09:05:54.457�[37m [DEBU] [type:registry] �[0m(3.2)     passed clientURL: unix:///var/lib/networkservicemesh/nsm.io.sock
Jun 27 09:05:54.460�[36m [INFO] [cmd:/bin/forwarder] [duration:89.264738ms] �[0mcompleted phase 9: register forwarder with the registry
Jun 27 09:05:54.460�[36m [INFO] [cmd:/bin/forwarder] �[0mStartup completed in 1.521599602s
Jun 27 09:06:36.105�[37m [DEBU] [type:registry] �[0m(17.2)                   passed clientURL: unix:///var/lib/networkservicemesh/nsm.io.sock
Jun 27 09:06:36.112�[37m [DEBU] [type:registry] �[0m(18.2)                    passed clientURL: unix:///var/lib/networkservicemesh/nsm.io.sock
Jun 27 09:06:36.122�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [type:networkService] �[0m(12.1)              passed clientURL: tcp://[10.244.1.43]:5001
Jun 27 09:06:36.122�[36m [INFO] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:115.737µs] [type:networkService] [vppapi:WantInterfaceEvents] �[0m(14.1)                completed
Jun 27 09:06:36.126�[36m [INFO] [cmd:vpp] �[0mvpp[3483328]: vl_api_want_interface_events_t_handler:1636: pid 3483305: already enabled...
Jun 27 09:06:36.127�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [VNIclient:request] [mechSrcIp:172.18.0.2] [mechSrcPort:4789] [type:networkService] �[0m(66.1)                                                                    set mechanism src
Jun 27 09:06:36.353�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:399.92µs] [swIfIndex:1] [type:networkService] [vppapi:SwInterfaceDump] �[0m(81.1)                                                                                   found interface with ip 172.18.0.2
Jun 27 09:06:36.354�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:151.844µs] [swIfIndex:1] [type:networkService] [vppapi:ACLInterfaceListDump] �[0m(81.2)                                                                                   initiated
Jun 27 09:06:36.354�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [aclIndex:0] [duration:177.312µs] [type:networkService] [vppapi:ACLDump] �[0m(81.3)                                                                                   completed
Jun 27 09:06:36.354�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [aclIndex:1] [duration:96.271µs] [type:networkService] [vppapi:ACLDump] �[0m(81.4)                                                                                   completed
Jun 27 09:06:36.354�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [aclIndex:2] [duration:182.562µs] [type:networkService] [vppapi:ACLAddReplace] �[0m(81.5)                                                                                   completed
Jun 27 09:06:36.354�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [aclIndex:3] [duration:133.921µs] [type:networkService] [vppapi:ACLAddReplace] �[0m(81.6)                                                                                   completed
Jun 27 09:06:36.355�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [NInput:2] [acls:[2 0 3 1]] [duration:184.256µs] [swIfIndex:1] [type:networkService] [vppapi:ACLInterfaceSetACLList] �[0m(81.7)                                                                                   completed
Jun 27 09:06:36.358�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [NextIndex:3] [NextName:ethernet-input] [NodeName:vxlan4-input] [duration:128.35µs] [isAdd:true] [type:networkService] [vppapi:AddNodeNext] �[0m(64.2)                                                                  completed
time="2023-06-27T09:06:36Z" level=info msg="No subscription found for the notification message." msg_id=701 msg_size=19
Jun 27 09:06:36.358�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [DstAddress:172.18.0.3] [SrcAddress:172.18.0.2] [Vni:9832580] [duration:287.299µs] [isAdd:true] [swIfIndex:2] [type:networkService] [vppapi:VxlanAddDelTunnel] �[0m(64.3)                                                                  completed
Jun 27 09:06:36.358�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [type:networkService] [vxlan:addDel] �[0m(64.4)                                                                  not vxlan mechanism
Jun 27 09:06:36.359�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:75.501µs] [swIfIndex:2] [tag:a289aa05-90c5-4099-9199-57594cb43877] [type:networkService] [vppapi:SwInterfaceTagAddDel] �[0m(58.1)                                                            completed
Jun 27 09:06:36.359�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [MTU:[1446 1446 1446 1446]] [SwIfIndex:2] [duration:69.791µs] [type:networkService] [vppapi:SwInterfaceSetMtu] �[0m(57.1)                                                           completed
Jun 27 09:06:36.359�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:83.477µs] [swIfIndex:2] [type:networkService] [vppapi:SwInterfaceSetFlags] �[0m(55.1)                                                         completed
time="2023-06-27T09:06:36Z" level=info msg="No subscription found for the notification message." msg_id=701 msg_size=19
Jun 27 09:06:36.470�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [HostIfName:nsm-1] [HostNamespace:/proc/3483305/fd/19] [TapFlags:TapFlags(0)] [duration:108.214065ms] [swIfIndex:3] [type:networkService] [vppapi:TapCreateV2] �[0m(30.2)                                completed
Jun 27 09:06:36.470�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:90.51µs] [mode:RX_MODE_API_ADAPTIVE] [swIfIndex:3] [type:networkService] [vppapi:SwInterfaceSetRxMode] �[0m(30.3)                                completed
Jun 27 09:06:36.470�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:51.687µs] [link.Name:nsm-1] [netlink:LinkByName] [type:networkService] �[0m(30.4)                                completed
Jun 27 09:06:36.470�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [alias:server-f754269b-95d3-4955-ad3e-52b25e75d100] [duration:25.789µs] [link.Name:nsm-1] [netlink:LinkSetAlias] [type:networkService] �[0m(30.5)                                completed
Jun 27 09:06:36.470�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:7.143µs] [link.Name:nsm-1] [netlink:LinkSetUp] [type:networkService] �[0m(30.6)                                completed
Jun 27 09:06:36.471�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [MTU:[1446 1446 1446 1446]] [SwIfIndex:3] [duration:75.152µs] [type:networkService] [vppapi:SwInterfaceSetMtu] �[0m(28.2)                              completed
Jun 27 09:06:36.471�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:70.422µs] [swIfIndex:3] [tag:a289aa05-90c5-4099-9199-57594cb43877] [type:networkService] [vppapi:SwInterfaceTagAddDel] �[0m(27.1)                             completed
Jun 27 09:06:36.471�[36m [INFO] [id:a289aa05-90c5-4099-9199-57594cb43877] [type:networkService] �[0m(26.1)                            /proc/sys/net/ipv4/ping_group_range was set to 0 2147483647
Jun 27 09:06:36.471�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [Addr:172.16.1.101/32] [duration:45.475µs] [link.Name:nsm-1] [netlink:AddrAdd] [type:networkService] �[0m(24.1)                          completed
Jun 27 09:06:36.471�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [AddrUpdate.LinkAddress:{172.16.1.101 ffffffff}] [duration:11.952µs] [link.Name:nsm-1] [type:networkService] �[0m(24.2)                          complete
Jun 27 09:06:36.472�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [Dst:172.16.1.100/32] [Flags:0] [Gw:<nil>] [Scope:link] [duration:14.797µs] [link.Name:nsm-1] [netlink:RouteReplace] [type:networkService] �[0m(23.1)                         completed
Jun 27 09:06:36.472�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [Dst:172.16.1.100/32] [Flags:0] [Gw:<nil>] [Scope:universe] [duration:12.133µs] [link.Name:nsm-1] [netlink:RouteReplace] [type:networkService] �[0m(23.2)                         completed
Jun 27 09:06:36.472�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [MTU:1446] [duration:15.128µs] [link.Name:nsm-1] [netlink:LinkSetMTU] [type:networkService] �[0m(20.1)                      completed
Jun 27 09:06:36.578�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [Enable:true] [RxSwIfIndex:2] [TxSwIfIndex:3] [duration:105.322932ms] [type:networkService] [vppapi:SwInterfaceSetL2Xconnect] �[0m(16.1)                  completed
Jun 27 09:06:36.578�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [Enable:true] [RxSwIfIndex:3] [TxSwIfIndex:2] [duration:234.224µs] [type:networkService] [vppapi:SwInterfaceSetL2Xconnect] �[0m(16.2)                  completed
Jun 27 09:06:36.578�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:83.096µs] [swIfIndex:2] [type:networkService] [vppapi:SwInterfaceSetFlags] �[0m(14.2)                completed
time="2023-06-27T09:06:36Z" level=info msg="No subscription found for the notification message." msg_id=701 msg_size=19
Jun 27 09:06:36.578�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:203.667µs] [swIfIndex:3] [type:networkService] [vppapi:SwInterfaceSetFlags] �[0m(14.3)                completed
Jun 27 09:06:38.872�[37m [DEBU] [type:registry] �[0m(18.2)                    passed clientURL: unix:///var/lib/networkservicemesh/nsm.io.sock
Jun 27 09:06:38.882�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [type:networkService] �[0m(11.1)             passed clientURL: tcp://[10.244.1.43]:5001
Jun 27 09:06:38.975�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [VNIclient:request] [mechSrcIp:172.18.0.2] [mechSrcPort:4789] [type:networkService] �[0m(66.1)                                                                    set mechanism src
Jun 27 09:06:39.051�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:131.115µs] [swIfIndex:2] [tag:a289aa05-90c5-4099-9199-57594cb43877] [type:networkService] [vppapi:SwInterfaceTagAddDel] �[0m(58.1)                                                            completed
Jun 27 09:06:39.051�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [MTU:[1446 1446 1446 1446]] [SwIfIndex:2] [duration:118.543µs] [type:networkService] [vppapi:SwInterfaceSetMtu] �[0m(57.1)                                                           completed
Jun 27 09:06:39.051�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:63.99µs] [swIfIndex:2] [type:networkService] [vppapi:SwInterfaceSetFlags] �[0m(55.1)                                                         completed
Jun 27 09:06:39.054�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [MTU:[1446 1446 1446 1446]] [SwIfIndex:3] [duration:106.75µs] [type:networkService] [vppapi:SwInterfaceSetMtu] �[0m(28.1)                              completed
Jun 27 09:06:39.055�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:93.705µs] [swIfIndex:3] [tag:a289aa05-90c5-4099-9199-57594cb43877] [type:networkService] [vppapi:SwInterfaceTagAddDel] �[0m(27.1)                             completed
Jun 27 09:06:39.055�[36m [INFO] [id:a289aa05-90c5-4099-9199-57594cb43877] [type:networkService] �[0m(26.1)                            /proc/sys/net/ipv4/ping_group_range was set to 0 2147483647
Jun 27 09:06:39.056�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [Dst:172.16.1.100/32] [Flags:0] [Gw:<nil>] [Scope:link] [duration:24.346µs] [link.Name:nsm-1] [netlink:RouteReplace] [type:networkService] �[0m(23.1)                         completed
Jun 27 09:06:39.056�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [Dst:172.16.1.100/32] [Flags:0] [Gw:<nil>] [Scope:universe] [duration:11.501µs] [link.Name:nsm-1] [netlink:RouteReplace] [type:networkService] �[0m(23.2)                         completed
Jun 27 09:06:39.056�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [MTU:1446] [duration:5.861µs] [link.Name:nsm-1] [netlink:LinkSetMTU] [type:networkService] �[0m(20.1)                      completed
Jun 27 09:06:39.056�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [Enable:true] [RxSwIfIndex:2] [TxSwIfIndex:3] [duration:74.068µs] [type:networkService] [vppapi:SwInterfaceSetL2Xconnect] �[0m(16.1)                  completed
Jun 27 09:06:39.057�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [Enable:true] [RxSwIfIndex:3] [TxSwIfIndex:2] [duration:76.283µs] [type:networkService] [vppapi:SwInterfaceSetL2Xconnect] �[0m(16.2)                  completed
Jun 27 09:06:39.057�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:60.293µs] [swIfIndex:2] [type:networkService] [vppapi:SwInterfaceSetFlags] �[0m(14.1)                completed
Jun 27 09:06:39.057�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [duration:66.525µs] [swIfIndex:3] [type:networkService] [vppapi:SwInterfaceSetFlags] �[0m(14.2)                completed
Jun 27 09:07:14.692�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [connID:a289aa05-90c5-4099-9199-57594cb43877] [metadata:server] [type:networkService] �[0m(5.1)       metadata deleted
Jun 27 09:07:14.693�[37m [DEBU] [type:registry] �[0m(18.2)                    passed clientURL: unix:///var/lib/networkservicemesh/nsm.io.sock
Jun 27 09:07:14.705�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [type:networkService] �[0m(11.1)             passed clientURL: tcp://[10.244.1.43]:5001
Jun 27 09:07:14.706�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [Enable:false] [RxSwIfIndex:2] [TxSwIfIndex:3] [duration:90.129µs] [type:networkService] [vppapi:SwInterfaceSetL2Xconnect] �[0m(16.1)                  completed
Jun 27 09:07:14.706�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [Enable:false] [RxSwIfIndex:3] [TxSwIfIndex:2] [duration:63.338µs] [type:networkService] [vppapi:SwInterfaceSetL2Xconnect] �[0m(16.2)                  completed
Jun 27 09:07:14.707�[36m [INFO] [cmd:vpp] �[0mvpp[3483328]: capo_sw_interface_add_del:124: unconfiguring policies for if 3 deleted
Jun 27 09:07:14.707�[36m [INFO] [cmd:vpp] �[0mvpp[3483328]: capo_sw_interface_add_del:131: error deleting caiop (output): -2
Jun 27 09:07:14.707�[36m [INFO] [cmd:vpp] �[0mvpp[3483328]: capo_sw_interface_add_del:137: error deleting caiop (input): -2
time="2023-06-27T09:07:14Z" level=info msg="No subscription found for the notification message." msg_id=701 msg_size=19
Jun 27 09:07:14.918�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [SwIfIndex:3] [duration:211.15953ms] [type:networkService] [vppapi:TapDeleteV2] �[0m(30.1)                                completed
Jun 27 09:07:14.919�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [connID:a289aa05-90c5-4099-9199-57594cb43877] [metadata:client] [type:networkService] �[0m(36.1)                                      metadata deleted
Jun 27 09:07:14.923�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [NextIndex:3] [NextName:ethernet-input] [NodeName:vxlan4-input] [duration:117.891µs] [isAdd:false] [type:networkService] [vppapi:AddNodeNext] �[0m(64.1)                                                                  completed
Jun 27 09:07:14.923�[36m [INFO] [cmd:vpp] �[0mvpp[3483328]: capo_sw_interface_add_del:124: unconfiguring policies for if 2 deleted
Jun 27 09:07:14.923�[36m [INFO] [cmd:vpp] �[0mvpp[3483328]: capo_sw_interface_add_del:131: error deleting caiop (output): -2
Jun 27 09:07:14.923�[36m [INFO] [cmd:vpp] �[0mvpp[3483328]: capo_sw_interface_add_del:137: error deleting caiop (input): -2
time="2023-06-27T09:07:14Z" level=info msg="No subscription found for the notification message." msg_id=701 msg_size=19
Jun 27 09:07:14.923�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [DstAddress:172.18.0.3] [SrcAddress:172.18.0.2] [Vni:9832580] [duration:276.067µs] [isAdd:false] [swIfIndex:2] [type:networkService] [vppapi:VxlanAddDelTunnel] �[0m(64.2)                                                                  completed
Jun 27 09:07:14.923�[37m [DEBU] [id:a289aa05-90c5-4099-9199-57594cb43877] [type:networkService] [vxlan:addDel] �[0m(64.3)                                                                  not vxlan mechanism
Jun 27 09:12:34.400�[37m [DEBU] [type:registry] �[0m(7.2)         passed clientURL: unix:///var/lib/networkservicemesh/nsm.io.sock
Jun 27 09:12:34.424�[36m [INFO] [type:registry] �[0m(6.2)        policy passed
Jun 27 09:12:34.424�[36m [INFO] [type:registry] �[0m(6.3)        policy passed
Jun 27 09:12:34.424�[36m [INFO] [type:registry] �[0m(6.4)        policy passed
Jun 27 09:12:34.424�[36m [INFO] [type:registry] �[0m(6.5)        policy passed
Jun 27 09:12:34.424�[36m [INFO] [type:registry] �[0m(6.6)        policy passed
Jun 27 09:12:34.424�[37m [DEBU] [type:registry] �[0m(3.2)     passed clientURL: unix:///var/lib/networkservicemesh/nsm.io.sock
Jun 27 09:12:34.424�[31m [ERRO] [type:registry] �[0m(9.1)           rpc error: code = Canceled desc = context canceled
Jun 27 09:12:34.425�[31m [ERRO] [type:registry] �[0m(9.1)           rpc error: code = Canceled desc = context canceled
Jun 27 09:12:34.425�[31m [ERRO] [type:registry] �[0m(9.1)           rpc error: code = Canceled desc = context canceled
Jun 27 09:12:34.425�[31m [ERRO] [type:registry] �[0m(9.1)           rpc error: code = Canceled desc = context canceled
Jun 27 09:12:34.425�[31m [ERRO] [type:registry] �[0m(9.1)           rpc error: code = Canceled desc = context canceled
Jun 27 09:12:34.425�[31m [ERRO] [type:registry] �[0m(9.1)           rpc error: code = Canceled desc = context canceled
Jun 27 09:12:34.425�[31m [ERRO] [type:registry] �[0m(9.1)           rpc error: code = Canceled desc = context canceled

Issue link

• Missing log printouts in forwarder-vpp at DEBUG log level  deployments-k8s#9242

How Has This Been Tested?

• Added unit testing to cover
• Tested manually
• Tested by integration testing
• Have not tested

Types of changes

• Bug fix
• New functionality
• Documentation
• Refactoring
• CI

[codecov]

Codecov Report

❗ No coverage uploaded for pull request base (main@a8c394e). Click here to learn what that means.
Patch has no changes to coverable lines.

Additional details and impacted files

@@           Coverage Diff           @@
##             main    #1475   +/-   ##
=======================================
  Coverage        ?   70.42%           
=======================================
  Files           ?      248           
  Lines           ?    11184           
  Branches        ?        0           
=======================================
  Hits            ?     7876           
  Misses          ?     2807           
  Partials        ?      501           

☔ View full report in Codecov by Sentry.
📢 Do you have feedback about the report comment? Let us know in this issue.

[denis-tingaikin]

@ljkiraly Feel free to review it. We''re planning merge the PR this week

[ljkiraly]

I have no comments on code, but I have some questions:

• Can you tell some words about the race condition?
• Does the child count and level field is shown in trace printout?
  For e.g. in this printouts:
  [TRAC] [type:registry] �[0m(5) ⎆ sdk/pkg/registry/common/clienturl/clientURLNSEClient.Register()
  [DEBU] [type:registry] �[0m(5.2) passed clientURL: unix:///var/lib/networkservicemesh/nsm.io.soc
  What are the (5) and (5.2) ?