| Message ID | 20180703183218.32329-1-blp@ovn.org |
|---|---|
| State | Accepted |
| Headers | show |
| Series | [ovs-dev] ofproto-macros: Ignore "Dropped # log messages" in check_logs. | expand |
On Tue, 3 Jul 2018 11:32:18 -0700 Ben Pfaff <blp@ovn.org> wrote: > check_logs ignores some log messages, but it wasn't smart enough to > ignore the messages that said that the ignored messages had been > rate-limited. This fixes the problem. > > It's OK to ignore all rate-limiting messages because they only appear > if at least one message was not rate-limited, which check_logs will > catch anyway. > > Reported-by: Timothy Redaelli <tredaelli@redhat.com> > Reported-at: > https://mail.openvswitch.org/pipermail/ovs-discuss/2018-July/046978.html > Signed-off-by: Ben Pfaff <blp@ovn.org> --- > tests/ofproto-macros.at | 6 ++++++ > 1 file changed, 6 insertions(+) > > diff --git a/tests/ofproto-macros.at b/tests/ofproto-macros.at > index 7388a20a2236..2a56ae6e2f3e 100644 > --- a/tests/ofproto-macros.at > +++ b/tests/ofproto-macros.at > @@ -400,6 +400,11 @@ check_logs () { > # all "connection reset" warning logs for similar reasons > (either EPIPE or # ECONNRESET can be returned on a send depending on > whether the peer had # unconsumed data when it closed the socket). > + # > + # We also ignore "Dropped # log messages..." messages. > Otherwise, even if > + # we ignore the messages that were rate-limited, we can end up > failing just > + # because of the announcement that rate-limiting happened (and > in a racy, > + # timing-dependent way, too). > sed -n "$1 > /reset by peer/d > /Broken pipe/d > @@ -408,6 +413,7 @@ check_logs () { > /timeval.*disk: [[0-9]]* reads, [[0-9]]* writes/d > /timeval.*context switches: [[0-9]]* voluntary, [[0-9]]* > involuntary/d /ovs_rcu.*blocked [[0-9]]* ms waiting for .* to > quiesce/d +/Dropped [[0-9]]* log messages/d > /|WARN|/p > /|ERR|/p > /|EMER|/p" ${logs} Hi, tested on Fedora Rawhide. I still have "2018-07-04T13:54:27.012Z|00038|jsonrpc|WARN|Dropped 14 log messages in last 8 seconds (most recently, 2 seconds ago) due to excessive rate", but test doesn't fail anymore. Tested-By: Timothy Redaelli <tredaelli@redhat.com>
On Wed, Jul 04, 2018 at 04:00:26PM +0200, Timothy Redaelli wrote: > On Tue, 3 Jul 2018 11:32:18 -0700 > Ben Pfaff <blp@ovn.org> wrote: > > > check_logs ignores some log messages, but it wasn't smart enough to > > ignore the messages that said that the ignored messages had been > > rate-limited. This fixes the problem. > > > > It's OK to ignore all rate-limiting messages because they only appear > > if at least one message was not rate-limited, which check_logs will > > catch anyway. > > > > Reported-by: Timothy Redaelli <tredaelli@redhat.com> > > Reported-at: > > https://mail.openvswitch.org/pipermail/ovs-discuss/2018-July/046978.html > > Signed-off-by: Ben Pfaff <blp@ovn.org> --- > > tests/ofproto-macros.at | 6 ++++++ > > 1 file changed, 6 insertions(+) > > > > diff --git a/tests/ofproto-macros.at b/tests/ofproto-macros.at > > index 7388a20a2236..2a56ae6e2f3e 100644 > > --- a/tests/ofproto-macros.at > > +++ b/tests/ofproto-macros.at > > @@ -400,6 +400,11 @@ check_logs () { > > # all "connection reset" warning logs for similar reasons > > (either EPIPE or # ECONNRESET can be returned on a send depending on > > whether the peer had # unconsumed data when it closed the socket). > > + # > > + # We also ignore "Dropped # log messages..." messages. > > Otherwise, even if > > + # we ignore the messages that were rate-limited, we can end up > > failing just > > + # because of the announcement that rate-limiting happened (and > > in a racy, > > + # timing-dependent way, too). > > sed -n "$1 > > /reset by peer/d > > /Broken pipe/d > > @@ -408,6 +413,7 @@ check_logs () { > > /timeval.*disk: [[0-9]]* reads, [[0-9]]* writes/d > > /timeval.*context switches: [[0-9]]* voluntary, [[0-9]]* > > involuntary/d /ovs_rcu.*blocked [[0-9]]* ms waiting for .* to > > quiesce/d +/Dropped [[0-9]]* log messages/d > > /|WARN|/p > > /|ERR|/p > > /|EMER|/p" ${logs} > > Hi, > tested on Fedora Rawhide. > I still have "2018-07-04T13:54:27.012Z|00038|jsonrpc|WARN|Dropped 14 > log messages in last 8 seconds (most recently, 2 seconds ago) due to > excessive rate", but test doesn't fail anymore. > > Tested-By: Timothy Redaelli <tredaelli@redhat.com> Thanks for testing. I applied this to master and branch-2.9.
diff --git a/tests/ofproto-macros.at b/tests/ofproto-macros.at index 7388a20a2236..2a56ae6e2f3e 100644 --- a/tests/ofproto-macros.at +++ b/tests/ofproto-macros.at @@ -400,6 +400,11 @@ check_logs () { # all "connection reset" warning logs for similar reasons (either EPIPE or # ECONNRESET can be returned on a send depending on whether the peer had # unconsumed data when it closed the socket). + # + # We also ignore "Dropped # log messages..." messages. Otherwise, even if + # we ignore the messages that were rate-limited, we can end up failing just + # because of the announcement that rate-limiting happened (and in a racy, + # timing-dependent way, too). sed -n "$1 /reset by peer/d /Broken pipe/d @@ -408,6 +413,7 @@ check_logs () { /timeval.*disk: [[0-9]]* reads, [[0-9]]* writes/d /timeval.*context switches: [[0-9]]* voluntary, [[0-9]]* involuntary/d /ovs_rcu.*blocked [[0-9]]* ms waiting for .* to quiesce/d +/Dropped [[0-9]]* log messages/d /|WARN|/p /|ERR|/p /|EMER|/p" ${logs}
check_logs ignores some log messages, but it wasn't smart enough to ignore the messages that said that the ignored messages had been rate-limited. This fixes the problem. It's OK to ignore all rate-limiting messages because they only appear if at least one message was not rate-limited, which check_logs will catch anyway. Reported-by: Timothy Redaelli <tredaelli@redhat.com> Reported-at: https://mail.openvswitch.org/pipermail/ovs-discuss/2018-July/046978.html Signed-off-by: Ben Pfaff <blp@ovn.org> --- tests/ofproto-macros.at | 6 ++++++ 1 file changed, 6 insertions(+)