Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Improve packet logging #216

Merged
merged 7 commits into from
Jul 13, 2023
Merged

Improve packet logging #216

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
053fcc2
Fix wait fp tests
DanG100 Jul 11, 2023
f3a547d
Improve fp test script
DanG100 Jul 12, 2023
33d1199
Use structured logging for packet with custom levels
DanG100 Jul 12, 2023
47a64c9
ci fixes
DanG100 Jul 13, 2023
1eb494e
lint fix
DanG100 Jul 13, 2023
33dfd27
test fix
DanG100 Jul 13, 2023
babc456
feedback
DanG100 Jul 13, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion bgp/tests/proto/policyval/policy_validation.pb.go
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

8 changes: 4 additions & 4 deletions cloudbuild/fp-test.sh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,13 +9,13 @@ rc=0
while read -r test_path; do
echo "$test_path"
kne_topology="$(pwd)/topologies/kne/openconfig/lemming/topology.textproto"
kne create "${kne_topology}"
kne create "${kne_topology}" --stderrthreshold error
if ! go test "./$test_path" -kne-topo "${kne_topology}" -alsologtostderr; then
rc=$?
rc=1
kubectl cluster-info dump --output-directory "/tmp/cluster-log/${test_path/\//-}" --namespaces openconfig-lemming
fi
kne delete "${kne_topology}"
sleep 10 # Give namespace time to be deleted
kne delete "${kne_topology}" --stderrthreshold error
kubectl wait --for=delete namespace/openconfig-lemming --timeout=60s
done < ../fp-tests

exit "$rc"
4 changes: 2 additions & 2 deletions dataplane/forwarding/fwd.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -803,13 +803,13 @@ func (e *Server) PacketInject(_ context.Context, request *fwdpb.PacketInjectRequ

packet.Debug(request.GetDebug())
if len(pre) != 0 {
packet.Logf(fwdpacket.LogDesc, fmt.Sprintf("%v: Preprocess %v", ctx.ID, port.ID()))
packet.Log().WithValues("context", ctx.ID, "port", port.ID())
state, err := fwdaction.ProcessPacket(packet, pre, port)
if state != fwdaction.CONTINUE || err != nil {
log.Errorf("%v: preprocessing failed, state %v, err %v", port.ID(), state, err)
return
}
packet.Logf(fwdpacket.LogDebugFrame, "injecting packet")
packet.Log().V(1).Info("injecting packet", "frame", fwdpacket.IncludeFrameInLog)
}
fwdport.Process(port, packet, request.GetAction(), ctx, "Control")
}()
Expand Down
3 changes: 2 additions & 1 deletion dataplane/forwarding/fwdaction/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@ go_test(
"//dataplane/forwarding/infra/fwdobject",
"//dataplane/forwarding/infra/fwdpacket",
"//proto/forwarding",
"@com_github_golang_mock//gomock",
"@com_github_go_logr_logr//testr",
"@org_uber_go_mock//gomock",
],
)
12 changes: 7 additions & 5 deletions dataplane/forwarding/fwdaction/action.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,7 @@ import (
"github.com/openconfig/lemming/dataplane/forwarding/infra/fwdcontext"
"github.com/openconfig/lemming/dataplane/forwarding/infra/fwdobject"
"github.com/openconfig/lemming/dataplane/forwarding/infra/fwdpacket"

fwdpb "github.com/openconfig/lemming/proto/forwarding"
)

Expand Down Expand Up @@ -219,9 +220,9 @@ func evaluatePacket(packet fwdpacket.Packet, actions Actions, counters fwdobject
curr++

var next Actions
packet.Logf(fwdpacket.LogDebugMessage, "curr action %v", a)
packet.Log().V(3).Info("evaluate current", "action", a)
next, state = a.action.Process(packet, counters)
packet.Logf(fwdpacket.LogDebugMessage, "result state %v action %v", state, next)
packet.Log().V(3).Info("evaluate result", "state", state, "action", next)
exec++

// Any intervening "EVALUATE" is treated as a "CONTINUE".
Expand Down Expand Up @@ -268,15 +269,16 @@ func ProcessPacket(packet fwdpacket.Packet, actions Actions, counters fwdobject.

// If the action is tagged as onEvaluate, append it to the evaluate list.
if a.onEvaluate {
packet.Logf(fwdpacket.LogDebugMessage, "defer action %v", a)
packet.Log().Info("process defer", "action", a)

evaluate = append(evaluate, a)
continue
}

var next Actions
packet.Logf(fwdpacket.LogDebugMessage, "curr action %v", a)
packet.Log().V(3).Info("process current", "action", a)
next, state = a.action.Process(packet, counters)
packet.Logf(fwdpacket.LogDebugMessage, "result state %v action %v", state, next)
packet.Log().V(3).Info("process result", "state", state, "action", next)
exec++

// If the state is Evaluate, then evaluate the packet by running the
Expand Down
61 changes: 38 additions & 23 deletions dataplane/forwarding/fwdaction/action_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,10 @@ import (
"fmt"
"testing"

"github.com/golang/mock/gomock"
"go.uber.org/mock/gomock"

"github.com/go-logr/logr/testr"

"github.com/openconfig/lemming/dataplane/forwarding/fwdaction/mock_fwdpacket"
"github.com/openconfig/lemming/dataplane/forwarding/infra/fwdcontext"
"github.com/openconfig/lemming/dataplane/forwarding/infra/fwdobject"
Expand Down Expand Up @@ -93,7 +96,7 @@ func validateAllocate(t *testing.T, builder *testBuilder) {

// TestActions tests the creation of various action sets.
func TestActions(t *testing.T) {
var tests = []struct {
tests := []struct {
count int
actions []fwdpb.ActionType
}{
Expand Down Expand Up @@ -188,7 +191,7 @@ func TestPacketProcessing(t *testing.T) {
}
infinite.next = []*ActionAttr{NewActionAttr(infinite, false)}

var processingTests = []struct {
processingTests := []struct {
count int
err bool
result State
Expand All @@ -198,7 +201,8 @@ func TestPacketProcessing(t *testing.T) {
{0, false, CONTINUE, nil},

// Test a packet with one action.
{1, false, CONTINUE,
{
1, false, CONTINUE,
[]*ActionAttr{
NewActionAttr(&recordAction{
id: 0,
Expand All @@ -209,7 +213,8 @@ func TestPacketProcessing(t *testing.T) {
},

// Test a packet with multiple actions (last terminating).
{3, false, DROP,
{
3, false, DROP,
[]*ActionAttr{
NewActionAttr(
&recordAction{
Expand All @@ -231,7 +236,8 @@ func TestPacketProcessing(t *testing.T) {
},

// Test a packet with multiple actions (last terminating).
{3, false, OUTPUT,
{
3, false, OUTPUT,
[]*ActionAttr{
NewActionAttr(&recordAction{
id: 0,
Expand All @@ -252,7 +258,8 @@ func TestPacketProcessing(t *testing.T) {
},

// Test a packet with multiple actions (middle terminating).
{2, false, CONSUME,
{
2, false, CONSUME,
[]*ActionAttr{
NewActionAttr(&recordAction{
id: 0,
Expand All @@ -273,7 +280,8 @@ func TestPacketProcessing(t *testing.T) {
},

// Test a packet with multiple actions (middle terminating).
{2, false, OUTPUT,
{
2, false, OUTPUT,
[]*ActionAttr{
NewActionAttr(&recordAction{
id: 0,
Expand All @@ -294,7 +302,8 @@ func TestPacketProcessing(t *testing.T) {
},

// Test a packet with multiple actions (complex).
{7, false, DROP,
{
7, false, DROP,
[]*ActionAttr{
NewActionAttr(&recordAction{
id: 0,
Expand Down Expand Up @@ -349,7 +358,8 @@ func TestPacketProcessing(t *testing.T) {
},

// Test a packet with multiple actions (complex).
{9, false, CONTINUE,
{
9, false, CONTINUE,
[]*ActionAttr{
NewActionAttr(&recordAction{
id: 0,
Expand Down Expand Up @@ -407,7 +417,8 @@ func TestPacketProcessing(t *testing.T) {
{50, true, DROP, []*ActionAttr{NewActionAttr(infinite, false)}},

// Test a packet with one onEvaluate action.
{0, false, CONTINUE,
{
0, false, CONTINUE,
[]*ActionAttr{
NewActionAttr(&recordAction{
id: 0,
Expand All @@ -418,7 +429,8 @@ func TestPacketProcessing(t *testing.T) {
},

// Test a packet with one Evaluate action.
{1, false, CONTINUE,
{
1, false, CONTINUE,
[]*ActionAttr{
NewActionAttr(&recordAction{
id: 0,
Expand All @@ -429,7 +441,8 @@ func TestPacketProcessing(t *testing.T) {
},

// Test a packet with multiple actions, two onevaluate and no evaluate.
{1, false, DROP,
{
1, false, DROP,
[]*ActionAttr{
NewActionAttr(
&recordAction{
Expand All @@ -452,7 +465,8 @@ func TestPacketProcessing(t *testing.T) {

// Test a packet with multiple actions, two onevaluate and one drop
// before evaluate.
{1, false, DROP,
{
1, false, DROP,
[]*ActionAttr{
NewActionAttr(
&recordAction{
Expand Down Expand Up @@ -480,7 +494,8 @@ func TestPacketProcessing(t *testing.T) {

// Test a packet with multiple actions, two onevaluate and no drop
// before evaluate.
{4, false, CONTINUE,
{
4, false, CONTINUE,
[]*ActionAttr{
NewActionAttr(
&recordAction{
Expand Down Expand Up @@ -513,8 +528,7 @@ func TestPacketProcessing(t *testing.T) {

packet := mock_fwdpacket.NewMockPacket(ctrl)
packet.EXPECT().Length().Return(100).AnyTimes()
packet.EXPECT().Logf(gomock.Any(), gomock.Any(), gomock.Any()).AnyTimes()
packet.EXPECT().Logf(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()).AnyTimes()
packet.EXPECT().Log().Return(testr.New(t)).AnyTimes()
state, err := ProcessPacket(packet, test.actions, nil)
switch {
case err != nil && test.err:
Expand Down Expand Up @@ -549,7 +563,7 @@ func TestActionsEquality(t *testing.T) {
newTestBuilder(1, fwdpb.ActionType_ACTION_TYPE_OUTPUT)

// Run tests of various inputs.
var tests = []struct {
tests := []struct {
first []*fwdpb.ActionDesc
second []*fwdpb.ActionDesc
wantEqual bool // true if we expect them to be equal
Expand Down Expand Up @@ -583,11 +597,12 @@ func TestActionsEquality(t *testing.T) {
}, {
ActionType: fwdpb.ActionType_ACTION_TYPE_DROP,
}},
second: []*fwdpb.ActionDesc{{
ActionType: fwdpb.ActionType_ACTION_TYPE_DROP,
}, {
ActionType: fwdpb.ActionType_ACTION_TYPE_OUTPUT,
},
second: []*fwdpb.ActionDesc{
{
ActionType: fwdpb.ActionType_ACTION_TYPE_DROP,
}, {
ActionType: fwdpb.ActionType_ACTION_TYPE_OUTPUT,
},
},
wantEqual: false,
},
Expand Down
3 changes: 2 additions & 1 deletion dataplane/forwarding/fwdaction/actions/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -71,6 +71,7 @@ go_test(
"//dataplane/forwarding/protocol/metadata",
"//dataplane/forwarding/protocol/opaque",
"//proto/forwarding",
"@com_github_golang_mock//gomock",
"@com_github_go_logr_logr//testr",
"@org_uber_go_mock//gomock",
],
)
2 changes: 1 addition & 1 deletion dataplane/forwarding/fwdaction/actions/debug_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@ package actions
import (
"testing"

"github.com/golang/mock/gomock"
"go.uber.org/mock/gomock"

"github.com/openconfig/lemming/dataplane/forwarding/fwdaction"
"github.com/openconfig/lemming/dataplane/forwarding/fwdaction/mock_fwdpacket"
Expand Down
2 changes: 1 addition & 1 deletion dataplane/forwarding/fwdaction/actions/drop_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@ package actions
import (
"testing"

"github.com/golang/mock/gomock"
"go.uber.org/mock/gomock"

"github.com/openconfig/lemming/dataplane/forwarding/fwdaction"
"github.com/openconfig/lemming/dataplane/forwarding/fwdaction/mock_fwdpacket"
Expand Down
2 changes: 1 addition & 1 deletion dataplane/forwarding/fwdaction/actions/flowcounter_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@ package actions
import (
"testing"

"github.com/golang/mock/gomock"
"go.uber.org/mock/gomock"

"github.com/openconfig/lemming/dataplane/forwarding/fwdaction"
"github.com/openconfig/lemming/dataplane/forwarding/fwdaction/mock_fwdpacket"
Expand Down
2 changes: 1 addition & 1 deletion dataplane/forwarding/fwdaction/actions/lookup_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@ package actions
import (
"testing"

"github.com/golang/mock/gomock"
"go.uber.org/mock/gomock"

"github.com/openconfig/lemming/dataplane/forwarding/fwdaction"
"github.com/openconfig/lemming/dataplane/forwarding/fwdaction/mock_fwdpacket"
Expand Down
6 changes: 3 additions & 3 deletions dataplane/forwarding/fwdaction/actions/mirror.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -96,8 +96,8 @@ func (m *mirror) Process(packet fwdpacket.Packet, counters fwdobject.Counters) (
if err != nil {
return fmt.Errorf("actions: mirror actions failed to get output port, err %v", err)
}
packet.Logf(fwdpacket.LogDebugMessage, "transmitting packet to %q", out.ID())
packet.Logf(fwdpacket.LogDesc, fmt.Sprintf("%v: Transmit %v", m.ctx.ID, out.ID()))
packet.Log().Info("transmitting packet", "port", out.ID())
packet.Log().WithValues("context", m.ctx.ID, "port", out.ID())
DanG100 marked this conversation as resolved.
Show resolved Hide resolved
fwdport.Output(out, cp, fwdpb.PortAction_PORT_ACTION_OUTPUT, m.ctx)

case fwdaction.CONTINUE:
Expand All @@ -114,7 +114,7 @@ func (m *mirror) Process(packet fwdpacket.Packet, counters fwdobject.Counters) (
// Note that if the mirror fails, we increment counters and log the error.
// However the packet processing is continued for the original packet.
if err != nil {
packet.Logf(fwdpacket.LogErrorFrame, "mirrored packet failed, %v", err)
packet.Log().Error(err, "mirrored packet failed, %v")
counters.Increment(fwdpb.CounterId_COUNTER_ID_MIRROR_PACKETS, 1)
counters.Increment(fwdpb.CounterId_COUNTER_ID_MIRROR_OCTETS, uint32(packet.Length()))
}
Expand Down
12 changes: 6 additions & 6 deletions dataplane/forwarding/fwdaction/actions/mirror_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,9 @@ import (
"fmt"
"testing"

"github.com/golang/mock/gomock"
"go.uber.org/mock/gomock"

"github.com/go-logr/logr/testr"

"github.com/openconfig/lemming/dataplane/forwarding/fwdaction"
"github.com/openconfig/lemming/dataplane/forwarding/fwdaction/mock_fwdpacket"
Expand Down Expand Up @@ -193,10 +195,8 @@ func TestMirror(t *testing.T) {
mirrored.EXPECT().Frame().Return(orgFrame).AnyTimes()
}
mirrored.EXPECT().Attributes().Return(nil).AnyTimes()
mirrored.EXPECT().Logf(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()).AnyTimes()
mirrored.EXPECT().Logf(gomock.Any(), gomock.Any()).AnyTimes()
mirrored.EXPECT().Logf(gomock.Any(), gomock.Any(), gomock.Any()).AnyTimes()
mirrored.EXPECT().Log().Return(nil).AnyTimes()
mirrored.EXPECT().Log().Return(testr.New(t)).AnyTimes()
mirrored.EXPECT().LogMsgs().Return(nil).AnyTimes()
mirrored.EXPECT().Update(opFID, fwdpacket.OpSet, gomock.Any()).Return(nil).AnyTimes()
mirrored.EXPECT().Update(inFID, fwdpacket.OpSet, gomock.Any()).Return(nil).AnyTimes()
mirrored.EXPECT().Update(fwdpacket.NewFieldIDFromNum(fwdpb.PacketFieldNum_PACKET_FIELD_NUM_ETHER_MAC_DST, 0),
Expand All @@ -209,7 +209,7 @@ func TestMirror(t *testing.T) {
original.EXPECT().Frame().Return(orgFrame).AnyTimes()
original.EXPECT().Mirror(fields).Return(mirrored, nil).AnyTimes()
original.EXPECT().Attributes().Return(nil).AnyTimes()
original.EXPECT().Logf(gomock.Any(), gomock.Any(), gomock.Any()).AnyTimes()
original.EXPECT().Log().Return(testr.New(t)).AnyTimes()
original.EXPECT().Field(opFID).Return(make([]byte, protocol.SizeUint64), nil).AnyTimes()
original.EXPECT().Field(inFID).Return(make([]byte, protocol.SizeUint64), nil).AnyTimes()

Expand Down
2 changes: 1 addition & 1 deletion dataplane/forwarding/fwdaction/actions/ratelimit_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,7 @@ import (
"testing"
"time"

"github.com/golang/mock/gomock"
"go.uber.org/mock/gomock"

"github.com/openconfig/lemming/dataplane/forwarding/fwdaction"
"github.com/openconfig/lemming/dataplane/forwarding/fwdaction/mock_fwdpacket"
Expand Down
2 changes: 1 addition & 1 deletion dataplane/forwarding/fwdaction/actions/reparse_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@ package actions
import (
"testing"

"github.com/golang/mock/gomock"
"go.uber.org/mock/gomock"

"github.com/openconfig/lemming/dataplane/forwarding/fwdaction"
"github.com/openconfig/lemming/dataplane/forwarding/fwdaction/mock_fwdpacket"
Expand Down
Loading