Add logging verbosity to configuring OVN logs

[freedge]

When updating a large number of address_set, logs get flooded with "Configuring OVN" which cannot be reduced.
Also klog shows up in the profiling data as a source of CPU consumption of ovnkube-master.

We make it configurable and assign it a verbosity of 4 which is default on OpenShift.

Signed-off-by: François Rigault frigo@amadeus.com

[tssurya]

/lgtm
keeping it at 4 sgtm; functionally we will still have the logs by default in openshift and in upstream default is 5 so we are good. That way if someone doesn't want these logs they can set the level to < 4. However note that without these configuring OVN logs it's hard to catch the transactions in the logs (might make debugging life harder).

[coveralls]

Coverage decreased (-0.07%) to 52.438% when pulling 9690955 on freedge:logging into 0590d6a on ovn-org:master.

[dcbw]

/lgtm

@trozet ?

[tssurya]

thanks @freedge ! LGTM
@dcbw or @trozet for approve

[freedge]

Sharing the result now, with sample logs:

$ kubectl logs -n ovn-kubernetes -l name=ovnkube-master -c ovnkube-master  --tail=100 | grep -P 'Configuring OVN|transact'
# with default OVNKUBE_LOGLEVEL=5 in kind:
I0923 15:55:46.719888      46 transact.go:41] Configuring OVN: [{Op:mutate Table:Address_Set Row:map[] Rows:[] Columns:[] Mutations:[{Column:addresses Mutator:insert Value:{GoSet:[10.96.0.1]}}] Timeout:<nil> Where:[where column _uuid == {aa9c9735-0d59-40a6-8236-aaeaea0e2d5a}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:}]
I0923 15:55:46.719990      46 client.go:781]  "msg"="transacting operations"  "database"="OVN_Northbound" "operations"="[{Op:mutate Table:Address_Set Row:map[] Rows:[] Columns:[] Mutations:[{Column:addresses Mutator:insert Value:{GoSet:[10.96.0.1]}}] Timeout:<nil> Where:[where column _uuid == {aa9c9735-0d59-40a6-8236-aaeaea0e2d5a}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:}]"
I0923 15:55:46.724040      46 transact.go:41] Configuring OVN: [{Op:insert Table:Address_Set Row:map[external_ids:{GoMap:map[name:default.anetpol.egress.0_v4]} name:a14210109120856362935] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996269}]
I0923 15:55:46.727842      46 client.go:781]  "msg"="transacting operations"  "database"="OVN_Northbound" "operations"="[{Op:insert Table:Address_Set Row:map[external_ids:{GoMap:map[name:default.anetpol.egress.0_v4]} name:a14210109120856362935] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996269}]"
I0923 15:55:46.734854      46 transact.go:41] Configuring OVN: [{Op:insert Table:ACL Row:map[action:allow-related direction:to-lport external_ids:{GoMap:map[Ingress_num:0 ipblock_cidr:false l4Match:None namespace:default policy:anetpol policy_type:Ingress]} log:false match:ip4.src == {$a16717216580116695873} && outport == @a667506796558246944 meter:{GoSet:[acl-logging]} name:{GoSet:[default_anetpol_0]} priority:1001] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996270} {Op:insert Table:ACL Row:map[action:allow-related direction:from-lport external_ids:{GoMap:map[Egress_num:0 ipblock_cidr:false l4Match:None namespace:default policy:anetpol policy_type:Egress]} log:false match:ip4.dst == {$a14210109120856362935} && inport == @a667506796558246944 meter:{GoSet:[acl-logging]} name:{GoSet:[default_anetpol_0]} options:{GoMap:map[apply-after-lb:true]} priority:1001] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996271} {Op:insert Table:Port_Group Row:map[acls:{GoSet:[{GoUUID:u2596996270} {GoUUID:u2596996271}]} external_ids:{GoMap:map[name:default_anetpol]} name:a667506796558246944] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996272}]
I0923 15:55:46.735073      46 client.go:781]  "msg"="transacting operations"  "database"="OVN_Northbound" "operations"="[{Op:insert Table:ACL Row:map[action:allow-related direction:to-lport external_ids:{GoMap:map[Ingress_num:0 ipblock_cidr:false l4Match:None namespace:default policy:anetpol policy_type:Ingress]} log:false match:ip4.src == {$a16717216580116695873} && outport == @a667506796558246944 meter:{GoSet:[acl-logging]} name:{GoSet:[default_anetpol_0]} priority:1001] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996270} {Op:insert Table:ACL Row:map[action:allow-related direction:from-lport external_ids:{GoMap:map[Egress_num:0 ipblock_cidr:false l4Match:None namespace:default policy:anetpol policy_type:Egress]} log:false match:ip4.dst == {$a14210109120856362935} && inport == @a667506796558246944 meter:{GoSet:[acl-logging]} name:{GoSet:[default_anetpol_0]} options:{GoMap:map[apply-after-lb:true]} priority:1001] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996271} {Op:insert Table:Port_Group Row:map[acls:{GoSet:[{GoUUID:u2596996270} {GoUUID:u2596996271}]} external_ids:{GoMap:map[name:default_anetpol]} name:a667506796558246944] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996272}]"


# with loglevel 4:
I0923 15:58:27.965702      37 client.go:781]  "msg"="transacting operations"  "database"="OVN_Northbound" "operations"="[{Op:update Table:Logical_Router Row:map[external_ids:{GoMap:map[k8s-cluster-router:yes k8s-ovn-topo-version:5]}] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[where column _uuid == {289a8eb5-1b85-46b0-970f-cfe69824809e}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:}]"
I0923 15:58:28.024210      37 client.go:781]  "msg"="transacting operations"  "database"="OVN_Northbound" "operations"="[{Op:update Table:Load_Balancer Row:map[external_ids:{GoMap:map[k8s.ovn.org/kind:Service k8s.ovn.org/owner:default/kubernetes]} name:Service_default/kubernetes_TCP_node_router_ovn-control-plane options:{GoMap:map[event:false reject:true skip_snat:false]} protocol:{GoSet:[tcp]} selection_fields:{GoSet:[]} vips:{GoMap:map[10.96.0.1:443:169.254.169.2:6443]}] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[where column _uuid == {78fa4a8f-c625-4b05-8d7f-69f60d5268c3}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:} {Op:update Table:Load_Balancer Row:map[external_ids:{GoMap:map[k8s.ovn.org/kind:Service k8s.ovn.org/owner:default/kubernetes]} name:Service_default/kubernetes_TCP_node_switch_ovn-control-plane_merged options:{GoMap:map[event:false reject:true skip_snat:false]} protocol:{GoSet:[tcp]} selection_fields:{GoSet:[]} vips:{GoMap:map[10.96.0.1:443:10.89.0.4:6443]}] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[where column _uuid == {689e16e0-9c95-4883-8130-236becc3506b}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:}]"
I0923 15:58:28.024485      37 client.go:781]  "msg"="transacting operations"  "database"="OVN_Northbound" "operations"="[{Op:update Table:Load_Balancer Row:map[external_ids:{GoMap:map[k8s.ovn.org/kind:Service k8s.ovn.org/owner:kube-system/kube-dns]} name:Service_kube-system/kube-dns_TCP_cluster options:{GoMap:map[event:false reject:true skip_snat:false]} protocol:{GoSet:[tcp]} selection_fields:{GoSet:[]} vips:{GoMap:map[10.96.0.10:53:10.244.2.3:53,10.244.2.4:53 10.96.0.10:9153:10.244.2.3:9153,10.244.2.4:9153]}] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[where column _uuid == {be5c6363-08cc-4594-90ae-0538861db144}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:} {Op:update Table:Load_Balancer Row:map[external_ids:{GoMap:map[k8s.ovn.org/kind:Service k8s.ovn.org/owner:kube-system/kube-dns]} name:Service_kube-system/kube-dns_UDP_cluster options:{GoMap:map[event:false reject:true skip_snat:false]} protocol:{GoSet:[udp]} selection_fields:{GoSet:[]} vips:{GoMap:map[10.96.0.10:53:10.244.2.3:53,10.244.2.4:53]}] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[where column _uuid == {d95a5f04-4ecf-484c-a834-55693b5f9bdb}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:}]"
I0923 15:58:57.389855      37 client.go:781]  "msg"="transacting operations"  "database"="OVN_Northbound" "operations"="[{Op:update Table:NB_Global Row:map[options:{GoMap:map[e2e_timestamp:1663948737 mac_prefix:f6:8f:34 max_tunid:16711680 northd_internal_version:22.06.1-20.23.0-63.4 northd_probe_interval:5000 svc_monitor_mac:9e:fd:1a:3e:0a:a4 use_logical_dp_groups:true]}] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[where column _uuid == {4ad50c6f-3742-4ec0-bfa6-0b22dc77e641}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:}]"
I0923 15:59:27.389921      37 client.go:781]  "msg"="transacting operations"  "database"="OVN_Northbound" "operations"="[{Op:update Table:NB_Global Row:map[options:{GoMap:map[e2e_timestamp:1663948767 mac_prefix:f6:8f:34 max_tunid:16711680 northd_internal_version:22.06.1-20.23.0-63.4 northd_probe_interval:5000 svc_monitor_mac:9e:fd:1a:3e:0a:a4 use_logical_dp_groups:true]}] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[where column _uuid == {4ad50c6f-3742-4ec0-bfa6-0b22dc77e641}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:}]"
I0923 15:59:43.390526      37 client.go:781]  "msg"="transacting operations"  "database"="OVN_Northbound" "operations"="[{Op:insert Table:Address_Set Row:map[external_ids:{GoMap:map[name:default.anetpol2.ingress.0_v4]} name:a9805728995585820393] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996163}]"
I0923 15:59:43.391410      37 client.go:781]  "msg"="transacting operations"  "database"="OVN_Northbound" "operations"="[{Op:mutate Table:Address_Set Row:map[] Rows:[] Columns:[] Mutations:[{Column:addresses Mutator:insert Value:{GoSet:[10.96.0.1]}}] Timeout:<nil> Where:[where column _uuid == {d902b3bd-38dd-4485-861f-c876077e0581}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:}]"
I0923 15:59:43.392119      37 client.go:781]  "msg"="transacting operations"  "database"="OVN_Northbound" "operations"="[{Op:insert Table:Address_Set Row:map[external_ids:{GoMap:map[name:default.anetpol2.egress.0_v4]} name:a16944770706892486991] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996164}]"
I0923 15:59:43.400612      37 client.go:781]  "msg"="transacting operations"  "database"="OVN_Northbound" "operations"="[{Op:insert Table:ACL Row:map[action:allow-related direction:to-lport external_ids:{GoMap:map[Ingress_num:0 ipblock_cidr:false l4Match:None namespace:default policy:anetpol2 policy_type:Ingress]} log:false match:ip4.src == {$a9805728995585820393} && outport == @a13908635468188289686 meter:{GoSet:[acl-logging]} name:{GoSet:[default_anetpol2_0]} priority:1001] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996165} {Op:insert Table:ACL Row:map[action:allow-related direction:from-lport external_ids:{GoMap:map[Egress_num:0 ipblock_cidr:false l4Match:None namespace:default policy:anetpol2 policy_type:Egress]} log:false match:ip4.dst == {$a16944770706892486991} && inport == @a13908635468188289686 meter:{GoSet:[acl-logging]} name:{GoSet:[default_anetpol2_0]} options:{GoMap:map[apply-after-lb:true]} priority:1001] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996166} {Op:insert Table:Port_Group Row:map[acls:{GoSet:[{GoUUID:u2596996165} {GoUUID:u2596996166}]} external_ids:{GoMap:map[name:default_anetpol2]} name:a13908635468188289686] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996167}]"


# with loglevel3:
<empty>

before this commit, with loglevel=3, the Configuring OVN was still logged

I0923 16:23:11.628363      38 transact.go:41] Configuring OVN: [{Op:insert Table:Address_Set Row:map[external_ids:{GoMap:map[name:default.anetpol2.ingress.0_v4]} name:a9805728995585820393] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996169}]
I0923 16:23:11.630260      38 transact.go:41] Configuring OVN: [{Op:mutate Table:Address_Set Row:map[] Rows:[] Columns:[] Mutations:[{Column:addresses Mutator:insert Value:{GoSet:[10.96.0.1]}}] Timeout:<nil> Where:[where column _uuid == {91a74c19-7906-469b-874c-9c4d7f315075}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:}]
I0923 16:23:11.631101      38 transact.go:41] Configuring OVN: [{Op:insert Table:Address_Set Row:map[external_ids:{GoMap:map[name:default.anetpol2.egress.0_v4]} name:a16944770706892486991] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996170}]
I0923 16:23:11.634361      38 transact.go:41] Configuring OVN: [{Op:insert Table:ACL Row:map[action:allow-related direction:to-lport external_ids:{GoMap:map[Ingress_num:0 ipblock_cidr:false l4Match:None namespace:default policy:anetpol2 policy_type:Ingress]} log:false match:ip4.src == {$a9805728995585820393} && outport == @a13908635468188289686 meter:{GoSet:[acl-logging]} name:{GoSet:[default_anetpol2_0]} priority:1001] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996171} {Op:insert Table:ACL Row:map[action:allow-related direction:from-lport external_ids:{GoMap:map[Egress_num:0 ipblock_cidr:false l4Match:None namespace:default policy:anetpol2 policy_type:Egress]} log:false match:ip4.dst == {$a16944770706892486991} && inport == @a13908635468188289686 meter:{GoSet:[acl-logging]} name:{GoSet:[default_anetpol2_0]} options:{GoMap:map[apply-after-lb:true]} priority:1001] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996172} {Op:insert Table:Port_Group Row:map[acls:{GoSet:[{GoUUID:u2596996171} {GoUUID:u2596996172}]} external_ids:{GoMap:map[name:default_anetpol2]} name:a13908635468188289686] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2596996173}]

[freedge]

superseded by pr above

[tssurya]

We need to get this PR in and its separate from other refactors happening. @freedge : hope this is ok with you, I am not sure why you closed this PR.

[freedge]

I thought you were thinking of a more thorough redesign, and didn't want to add extra burden on you.