monitor: Support more verbosity levels

Make the default verbosity with `cilium monitor -v` print the CAPTURE /
DROP messages in the same format as without `-v` flag, along with DEBUG
messages. This avoids expanding / dissecting CAPTURE messages and
formatting them across multiple lines which can be harder to read.

Move the packet dissection into a new `cilium monitor -v -v` command
instead.

Signed-off-by: Joe Stringer <joe@cilium.io>

Documentation/cheatsheet.rst

@@ -202,6 +202,11 @@ Verbose output (including debug if enabled)
 
     cilium monitor -v
 
+Extra verbose output (including packet dissection)
+::
+
+    cilium monitor -v -v
+
 
 Filter for only the events related to endpoint
 ::
@@ -224,7 +229,7 @@ Show notifications only for dropped packet events
 Don't dissect packet payload, display payload in hex information
 ::
 
-    cilium monitor -v --hex
+    cilium monitor -v -v --hex
 
 
 

Documentation/cmdref/cilium_monitor.md

@@ -28,7 +28,7 @@ cilium monitor [flags]
       --related-to []uint16     Filter by either source or destination endpoint id
       --to []uint16             Filter by destination endpoint id
   -t, --type []string           Filter by event types [agent capture debug drop l7 policy-verdict trace]
-  -v, --verbose                 Enable verbose output
+  -v, --verbose bools[=false]   Enable verbose output (-v, -vv) (default [])
 ```
 
 ### Options inherited from parent commands

Documentation/contributing/development/dev_setup.rst

@@ -377,14 +377,35 @@ from the BPF based datapath. Debugging messages are sent if either the
 mode of the agent can be enabled by starting ``cilium-agent`` with the option
 ``--debug`` enabled or by running ``cilium config debug=true`` for an already
 running agent. Debugging of an individual endpoint can be enabled by running
-``cilium endpoint config ID debug=true``
-
-
-.. code:: bash
+``cilium endpoint config ID debug=true``. Running ``cilium monitor -v`` will
+print the normal form of monitor output along with debug messages:
+
+.. code:: shell-session
+
+   $ cilium endpoint config 731 debug=true
+   Endpoint 731 configuration updated successfully
+   $ cilium monitor -v
+   Press Ctrl-C to quit
+   level=info msg="Initializing dissection cache..." subsys=monitor
+   <- endpoint 745 flow 0x6851276 identity 4->0 state new ifindex 0 orig-ip 0.0.0.0: 8e:3c:a3:67:cc:1e -> 16:f9:cd:dc:87:e5 ARP
+   -> lxc_health: 16:f9:cd:dc:87:e5 -> 8e:3c:a3:67:cc:1e ARP
+   CPU 00: MARK 0xbbe3d555 FROM 0 DEBUG: Inheriting identity=1 from stack
+   <- host flow 0xbbe3d555 identity 1->0 state new ifindex 0 orig-ip 0.0.0.0: 10.11.251.76:57896 -> 10.11.166.21:4240 tcp ACK
+   CPU 00: MARK 0xbbe3d555 FROM 0 DEBUG: Successfully mapped daddr=10.11.251.76 to identity=1
+   CPU 00: MARK 0xbbe3d555 FROM 0 DEBUG: Attempting local delivery for container id 745 from seclabel 1
+   CPU 00: MARK 0xbbe3d555 FROM 745 DEBUG: Conntrack lookup 1/2: src=10.11.251.76:57896 dst=10.11.166.21:4240
+   CPU 00: MARK 0xbbe3d555 FROM 745 DEBUG: Conntrack lookup 2/2: nexthdr=6 flags=0
+   CPU 00: MARK 0xbbe3d555 FROM 745 DEBUG: CT entry found lifetime=21925, revnat=0
+   CPU 00: MARK 0xbbe3d555 FROM 745 DEBUG: CT verdict: Established, revnat=0
+   -> endpoint 745 flow 0xbbe3d555 identity 1->4 state established ifindex lxc_health orig-ip 10.11.251.76: 10.11.251.76:57896 -> 10.11.166.21:4240 tcp ACK
+
+Passing ``-v -v`` supports deeper detail, for example:
+
+.. code:: shell-session
 
     $ cilium endpoint config 3978 debug=true
     Endpoint 3978 configuration updated successfully
-    $ cilium monitor -v --hex
+    $ cilium monitor -v -v --hex
     Listening for events on 2 CPUs with 64x4096 of shared memory
     Press Ctrl-C to quit
     ------------------------------------------------------------------------------

cilium/cmd/monitor.go

@@ -1,4 +1,4 @@
-// Copyright 2017-2019 Authors of Cilium
+// Copyright 2017-2020 Authors of Cilium
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
@@ -56,6 +56,7 @@ programs attached to endpoints and devices. This includes:
 	}
 	printer    = format.NewMonitorFormatter(format.INFO)
 	socketPath = ""
+	verbosity  = []bool{}
 )
 
 func init() {
@@ -65,7 +66,8 @@ func init() {
 	monitorCmd.Flags().Var(&printer.FromSource, "from", "Filter by source endpoint id")
 	monitorCmd.Flags().Var(&printer.ToDst, "to", "Filter by destination endpoint id")
 	monitorCmd.Flags().Var(&printer.Related, "related-to", "Filter by either source or destination endpoint id")
-	monitorCmd.Flags().BoolVarP(&printer.Verbose, "verbose", "v", false, "Enable verbose output")
+	monitorCmd.Flags().BoolSliceVarP(&verbosity, "verbose", "v", nil, "Enable verbose output (-v, -vv)")
+	monitorCmd.Flags().Lookup("verbose").NoOptDefVal = "false"
 	monitorCmd.Flags().BoolVarP(&printer.JSONOutput, "json", "j", false, "Enable json output. Shadows -v flag")
 	monitorCmd.Flags().StringVar(&socketPath, "monitor-socket", "", "Configure monitor socket path")
 	viper.BindEnv("monitor-socket", "CILIUM_MONITOR_SOCK")
@@ -75,10 +77,15 @@ func init() {
 func setVerbosity() {
 	if printer.JSONOutput {
 		printer.Verbosity = format.JSON
-	} else if printer.Verbose {
-		printer.Verbosity = format.DEBUG
 	} else {
-		printer.Verbosity = format.INFO
+		switch len(verbosity) {
+		case 1:
+			printer.Verbosity = format.DEBUG
+		case 2:
+			printer.Verbosity = format.VERBOSE
+		default:
+			printer.Verbosity = format.INFO
+		}
 	}
 }
 

pkg/monitor/format/format.go

@@ -1,4 +1,4 @@
-// Copyright 2018-2019 Authors of Cilium
+// Copyright 2018-2020 Authors of Cilium
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
@@ -51,7 +51,6 @@ type MonitorFormatter struct {
 	FromSource Uint16Flags
 	ToDst      Uint16Flags
 	Related    Uint16Flags
-	Verbose    bool
 	Hex        bool
 	JSONOutput bool
 	Verbosity  Verbosity
@@ -65,7 +64,6 @@ func NewMonitorFormatter(verbosity Verbosity) *MonitorFormatter {
 		FromSource: Uint16Flags{},
 		ToDst:      Uint16Flags{},
 		Related:    Uint16Flags{},
-		Verbose:    false,
 		JSONOutput: false,
 		Verbosity:  verbosity,
 	}
@@ -98,7 +96,7 @@ func (m *MonitorFormatter) dropEvents(prefix string, data []byte) {
 	}
 	if m.match(monitorAPI.MessageTypeDrop, dn.Source, uint16(dn.DstID)) {
 		switch m.Verbosity {
-		case INFO:
+		case INFO, DEBUG:
 			dn.DumpInfo(data)
 		case JSON:
 			dn.DumpJSON(data, prefix)
@@ -118,7 +116,7 @@ func (m *MonitorFormatter) traceEvents(prefix string, data []byte) {
 	}
 	if m.match(monitorAPI.MessageTypeTrace, tn.Source, tn.DstID) {
 		switch m.Verbosity {
-		case INFO:
+		case INFO, DEBUG:
 			tn.DumpInfo(data)
 		case JSON:
 			tn.DumpJSON(data, prefix)
@@ -169,7 +167,7 @@ func (m *MonitorFormatter) captureEvents(prefix string, data []byte) {
 	}
 	if m.match(monitorAPI.MessageTypeCapture, dc.Source, 0) {
 		switch m.Verbosity {
-		case INFO:
+		case INFO, DEBUG:
 			dc.DumpInfo(data)
 		case JSON:
 			dc.DumpJSON(data, prefix)

test/helpers/cilium.go

@@ -348,7 +348,7 @@ func (s *SSHMeta) BasePath() string {
 // called the command will stop and monitor's output is saved on
 // `monitorLogFileName` file.
 func (s *SSHMeta) MonitorStart() func() error {
-	cmd := "cilium monitor -v | ts '[%Y-%m-%d %H:%M:%S]'"
+	cmd := "cilium monitor -vv | ts '[%Y-%m-%d %H:%M:%S]'"
 	ctx, cancel := context.WithCancel(context.Background())
 	res := s.ExecInBackground(ctx, cmd, ExecOptions{SkipLog: true})
 

test/helpers/kubectl.go

@@ -721,7 +721,7 @@ func (kub *Kubectl) Logs(namespace string, pod string) *CmdRes {
 // MonitorStart runs cilium monitor in the background and dumps the contents
 // into a log file for later debugging
 func (kub *Kubectl) MonitorStart(namespace, pod, filename string) func() error {
-	cmd := fmt.Sprintf("%s exec -n %s %s -- cilium monitor -v", KubectlCmd, namespace, pod)
+	cmd := fmt.Sprintf("%s exec -n %s %s -- cilium monitor -vv", KubectlCmd, namespace, pod)
 	ctx, cancel := context.WithCancel(context.Background())
 	res := kub.ExecInBackground(ctx, cmd, ExecOptions{SkipLog: true})
 

test/runtime/monitor.go

@@ -92,7 +92,7 @@ var _ = Describe("RuntimeMonitorTest", func() {
 			monitorConfig()
 
 			ctx, cancel := context.WithCancel(context.Background())
-			res := vm.ExecInBackground(ctx, "cilium monitor -v")
+			res := vm.ExecInBackground(ctx, "cilium monitor -vv")
 			defer cancel()
 
 			areEndpointsReady := vm.WaitEndpointsReady()
@@ -130,7 +130,7 @@ var _ = Describe("RuntimeMonitorTest", func() {
 
 				ctx, cancel := context.WithCancel(context.Background())
 				defer cancel()
-				res := vm.ExecInBackground(ctx, fmt.Sprintf("cilium monitor --type %s -v", k))
+				res := vm.ExecInBackground(ctx, fmt.Sprintf("cilium monitor --type %s -vv", k))
 
 				vm.ContainerExec(helpers.App1, helpers.Ping(helpers.Httpd1))
 				vm.ContainerExec(helpers.App3, helpers.Ping(helpers.Httpd1))
@@ -143,7 +143,7 @@ var _ = Describe("RuntimeMonitorTest", func() {
 			}
 
 			By("all types together")
-			command := "cilium monitor -v"
+			command := "cilium monitor -vv"
 			for k := range eventTypes {
 				command = command + " --type " + k
 			}
@@ -182,7 +182,7 @@ var _ = Describe("RuntimeMonitorTest", func() {
 			defer cancel()
 
 			res := vm.ExecInBackground(ctx, fmt.Sprintf(
-				"cilium monitor --type debug --from %s -v", endpoints[helpers.App1]))
+				"cilium monitor --type debug --from %s -vv", endpoints[helpers.App1]))
 			vm.ContainerExec(helpers.App1, helpers.Ping(helpers.Httpd1))
 
 			filter := fmt.Sprintf("FROM %s DEBUG:", endpoints[helpers.App1])
@@ -207,7 +207,7 @@ var _ = Describe("RuntimeMonitorTest", func() {
 			ctx, cancel := context.WithCancel(context.Background())
 			defer cancel()
 			res := vm.ExecInBackground(ctx, fmt.Sprintf(
-				"cilium monitor -v --to %s", endpoints[helpers.Httpd1]))
+				"cilium monitor -vv --to %s", endpoints[helpers.Httpd1]))
 
 			vm.ContainerExec(helpers.App1, helpers.Ping(helpers.Httpd1))
 			vm.ContainerExec(helpers.App2, helpers.Ping(helpers.Httpd1))
@@ -231,7 +231,7 @@ var _ = Describe("RuntimeMonitorTest", func() {
 			ctx, cancel := context.WithCancel(context.Background())
 			defer cancel()
 			res := vm.ExecInBackground(ctx, fmt.Sprintf(
-				"cilium monitor -v --related-to %s", endpoints[helpers.Httpd1]))
+				"cilium monitor -vv --related-to %s", endpoints[helpers.Httpd1]))
 
 			vm.WaitEndpointsReady()
 			vm.ContainerExec(helpers.App1, helpers.CurlFail("http://httpd1/public"))
@@ -310,7 +310,7 @@ var _ = Describe("RuntimeMonitorTest", func() {
 			ExpectPolicyEnforcementUpdated(vm, helpers.PolicyEnforcementAlways)
 
 			ctx, cancel := context.WithCancel(context.Background())
-			res := vm.ExecInBackground(ctx, "cilium monitor -v")
+			res := vm.ExecInBackground(ctx, "cilium monitor -vv")
 
 			vm.ContainerExec(helpers.App1, helpers.Ping(helpers.Httpd1))
 			vm.ContainerExec(helpers.Httpd1, helpers.Ping(helpers.App1))