Bug 2002713: Add millisecond resolution to OVN logs

[creydr]

Currently OVN databases and ovn-northd are started with '-vconsole:${OVN_LOG_LEVEL} -vfile:off'. This means that logs are going only to the console. But console (unlike files) has no millisecond resolution by default. This makes it hard to debug time-sensitive issues.

This PR adds the millisecond resolution to console logs of ovn components.

How to verify:

1. Start a cluster with this patch (e.g. via clusterbot: launch openshift/cluster-network-operator#1196 ovn)
2. Check the logs of ovn components, e.g. nbdb:

oc -n openshift-ovn-kubernetes logs ovnkube-master-n6gnc -c nbdb
...
+ exec /usr/share/ovn/scripts/ovn-ctl --db-nb-cluster-local-port=9643 --db-nb-cluster-local-addr=10.0.148.9 --no-monitor --db-nb-cluster-local-proto=ssl --ovn-nb-db-ssl-key=/ovn-cert/tls.key --ovn-nb-db-ssl-cert=/ovn-cert/tls.crt --ovn-nb-db-ssl-ca-cert=/ovn-ca/ca-bundle.crt '--ovn-nb-log=-vconsole:info -vfile:off -vPATTERN:console:%D{%Y-%m-%dT%H:%M:%S.###Z}|%05N|%c%T|%p|%m' run_nb_ovsdb
Creating cluster database /etc/ovn/ovnnb_db.db.
2021-09-15T10:59:33.684Z|00001|vlog|INFO|opened log file /var/log/ovn/ovsdb-server-nb.log
ovn-nbctl: unix:/var/run/ovn/ovnnb_db.sock: database connection failed (No such file or directory)
2021-09-15T10:59:33.685Z|00002|raft|INFO|term 1: 114062 ms timeout expired, starting election
2021-09-15T10:59:33.685Z|00003|raft|INFO|term 1: elected leader by 1+ of 1 servers
2021-09-15T10:59:33.685Z|00004|raft|INFO|local server ID is 625f
2021-09-15T10:59:33.688Z|00005|ovsdb_server|INFO|ovsdb-server (Open vSwitch) 2.16.1
2021-09-15T10:59:33Z|00001|reconnect|INFO|unix:/var/run/ovn/ovnnb_db.sock: connecting...
2021-09-15T10:59:33Z|00002|reconnect|INFO|unix:/var/run/ovn/ovnnb_db.sock: connected
Waiting for OVN_Northbound to come up.
2021-09-15T10:59:33.764Z|00006|raft|INFO|Election timer changed from 1000 to 2000
2021-09-15T10:59:33.767Z|00007|raft|INFO|Election timer changed from 2000 to 4000
2021-09-15T10:59:33.770Z|00008|raft|INFO|Election timer changed from 4000 to 8000
2021-09-15T10:59:33.773Z|00009|raft|INFO|Election timer changed from 8000 to 10000

Hint for reviewers:

• Descriptions of the parameters for the log pattern can be found here (these are for ovs-appctl, but commandline pattern is the same.

[openshift-ci]

Skipping CI for Draft Pull Request.
If you want CI signal for your change, please convert it to an actual PR.
You can still manually trigger a test run with /test all

[openshift-ci]

@creydr: This pull request references Bugzilla bug 2002713, which is invalid:

• expected the bug to target the "4.10.0" release, but it targets "---" instead

Comment /bugzilla refresh to re-evaluate validity if changes to the Bugzilla bug are made, or edit the title of this pull request to link to a different bug.

In response to this:

Bug 2002713: Add millisecond resolution to OVN logs

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[creydr]

/bugzilla refresh
/test all

[openshift-ci]

@creydr: This pull request references Bugzilla bug 2002713, which is invalid:

• expected the bug to target the "4.10.0" release, but it targets "4.9.z" instead

Comment /bugzilla refresh to re-evaluate validity if changes to the Bugzilla bug are made, or edit the title of this pull request to link to a different bug.

In response to this:

/bugzilla refresh
/test all

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[creydr]

/bugzilla refresh

[openshift-ci]

@creydr: This pull request references Bugzilla bug 2002713, which is valid. The bug has been moved to the POST state. The bug has been updated to refer to the pull request using the external bug tracker.

3 validation(s) were run on this bug

• bug is open, matching expected state (open)
• bug target release (4.10.0) matches configured target release for branch (4.10.0)
• bug is in the state NEW, which is one of the valid states (NEW, ASSIGNED, ON_DEV, POST, POST)

No GitHub users were found matching the public email listed for the QA contact in Bugzilla (anusaxen@redhat.com), skipping review request.

In response to this:

/bugzilla refresh

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[openshift-ci]

@creydr: This pull request references Bugzilla bug 2002713, which is valid. The bug has been moved to the POST state.

3 validation(s) were run on this bug

• bug is open, matching expected state (open)
• bug target release (4.10.0) matches configured target release for branch (4.10.0)
• bug is in the state ASSIGNED, which is one of the valid states (NEW, ASSIGNED, ON_DEV, POST, POST)

No GitHub users were found matching the public email listed for the QA contact in Bugzilla (anusaxen@redhat.com), skipping review request.

In response to this:

Bug 2002713: Add millisecond resolution to OVN logs

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[creydr]

/retest-required

[creydr]

/retest-required

[creydr]

/retest

[creydr]

/retest

[creydr]

/retest

[astoycos]

Can you just declare this pattern as a constant in https://github.com/openshift/cluster-network-operator/blob/master/pkg/network/ovn_kubernetes.go#L46

rather than re declaring it for each container? Otherwise LGTM

[creydr]

Sure. Yes this is way better! I updated it...

[creydr]

/retest-required

[creydr]

/retest

[astoycos]

/lgtm

[creydr]

/retest

[openshift-ci]

@creydr: The following tests failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name	Commit	Details	Required	Rerun command
ci/prow/e2e-openstack-ovn	48c6482	link	false	/test e2e-openstack-ovn
ci/prow/e2e-gcp-ovn-upgrade	48c6482	link	false	/test e2e-gcp-ovn-upgrade
ci/prow/e2e-azure-ovn	48c6482	link	false	/test e2e-azure-ovn

Full PR test history. Your PR dashboard.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

[creydr]

/retest-required

[creydr]

/assign @JacobTanenbaum

[dcbw]

/approve

[openshift-ci]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: astoycos, creydr, dcbw

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

• OWNERS [dcbw]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

[openshift-ci]

@creydr: All pull requests linked via external trackers have merged:

• openshift/cluster-network-operator#1196

Bugzilla bug 2002713 has been moved to the MODIFIED state.

In response to this:

Bug 2002713: Add millisecond resolution to OVN logs

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.