Filtering Log Messages on Ryu OpenFlow Controller

Often times, when I have to prototype quickly an OpenFlow application or if I need to test a specific match condition on OpenFlow, I usually stick with Ryu, since it has support even for OpenFlow 1.5, it’s completely written in Python and it has some amazing test suites. However, if you’ve never run Ryu controller before, you’ll realize that sometimes you’ll have to dig into the code to figure out a way to accomplish whatever you want and also, most likely if you’re running multiple applications you’ll certainly want to have a proper logging configuration in place to trace which application (or Python module) sent which message and correlate the events, otherwise you’ll probably get lost in a storm of messages depending on what you’re testing or debugging. So, on this post I’ll briefly show to you how to set a simple logging.ini file in order to address these points.

Logging generic

First, if you just want to have an overall overview, starting with a root filter and setting up the logging level to DEBUG will show you all the messages. So, from this point you can start narrowing down to the logging level or even to narrow down to just a single or multiple Python modules that you’re interested in. A simple logging.ini configuration file looks like this:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
[formatters]
keys: console
[handlers]
keys: console
[loggers]
keys: root
[formatter_console]
format: %(asctime)s - %(levelname)s [%(name)s] (%(threadName)-10s) %(message)s
[handler_console]
class: StreamHandler
args:[sys.stdout]
formatter: console
[logger_root]
level: DEBUG
handlers: console

Info
You can find more information about Python logging configuration file here.

Let’s run two Ryu applications, but before I do that let me first decrease the level of the root logger to INFO on logging.ini file, otherwise the output would be too lengthy for this post (you can proceed with level DEBUG as an exercise):

1
2
3
4
5
6
7
8
9
10
11
diff --git a/logging.ini b/logging.ini
index cd2db85d..6f5d48e0 100644
--- a/logging.ini
+++ b/logging.ini
@@ -16,5 +16,5 @@ args:[sys.stdout]
formatter: console
[logger_root]
-level: DEBUG
+level: INFO
handlers: console

Starting both simple_switch_13 and ofctl_rest Ryu applications:

1
ryu-manager --log-config-file logging.ini ryu/app/ofctl_rest.py ryu/app/simple_switch_13.py

As you can see bellow, there are three threads as a result, MainThread, GreenThread-1 and GreenThread-2:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
2018-01-01 18:21:47,202 - INFO [ryu.base.app_manager] (MainThread) loading app ryu/app/ofctl_rest.py
2018-01-01 18:21:47,206 - INFO [ryu.base.app_manager] (MainThread) loading app ryu/app/simple_switch_13.py
2018-01-01 18:21:47,206 - INFO [ryu.base.app_manager] (MainThread) loading app ryu.controller.ofp_handler
2018-01-01 18:21:47,207 - INFO [ryu.base.app_manager] (MainThread) instantiating app None of DPSet
2018-01-01 18:21:47,207 - INFO [ryu.base.app_manager] (MainThread) creating context dpset
2018-01-01 18:21:47,207 - INFO [ryu.base.app_manager] (MainThread) creating context wsgi
2018-01-01 18:21:47,207 - INFO [ryu.base.app_manager] (MainThread) instantiating app ryu/app/ofctl_rest.py of RestStatsApi
2018-01-01 18:21:47,208 - INFO [ryu.base.app_manager] (MainThread) instantiating app ryu/app/simple_switch_13.py of SimpleSwitch13
2018-01-01 18:21:47,208 - INFO [ryu.base.app_manager] (MainThread) instantiating app ryu.controller.ofp_handler of OFPHandler
2018-01-01 18:21:47,210 - INFO [ryu.lib.hub] (GreenThread-1) (24364) wsgi starting up on http://0.0.0.0:8080
2018-01-01 18:21:53,055 - INFO [SimpleSwitch13] (GreenThread-2) packet in 1 8e:ca:6a:27:f2:69 ff:ff:ff:ff:ff:ff 1
2018-01-01 18:21:53,056 - INFO [SimpleSwitch13] (GreenThread-2) packet in 2 8e:ca:6a:27:f2:69 ff:ff:ff:ff:ff:ff 2
2018-01-01 18:21:53,057 - INFO [SimpleSwitch13] (GreenThread-2) packet in 2 56:36:d0:ca:26:ee 8e:ca:6a:27:f2:69 1
2018-01-01 18:21:53,060 - INFO [SimpleSwitch13] (GreenThread-2) packet in 1 56:36:d0:ca:26:ee 8e:ca:6a:27:f2:69 2
2018-01-01 18:21:53,061 - INFO [SimpleSwitch13] (GreenThread-2) packet in 1 8e:ca:6a:27:f2:69 56:36:d0:ca:26:ee 1
2018-01-01 18:21:53,062 - INFO [SimpleSwitch13] (GreenThread-2) packet in 2 8e:ca:6a:27:f2:69 56:36:d0:ca:26:ee 2
2018-01-01 18:21:58,286 - INFO [ryu.lib.hub] (GreenThread-1) (24364) accepted ('127.0.0.1', 58154)
2018-01-01 18:21:58,294 - INFO [ryu.lib.hub] (MainThread) 127.0.0.1 - - [01/Jan/2018 18:21:58]"GET /stats/switches HTTP/1.1" 200 113 0.007763

Logging selective

Assuming that you just want to see events of the SimpleSwitch13 and ryu.base.app_manager modules, let’s make these changes:

1 - Add two extra loggers, logger_SimpleSwitch13 and logger_ryu.base.app_manager, and set their levels to INFO.
2 - Decrease the root logger logging level to ERROR, just so all the other modules only show errors and nothing else.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
diff --git a/logging.ini b/logging.ini
index cd2db85d..385e988c 100644
--- a/logging.ini
+++ b/logging.ini
@@ -5,7 +5,7 @@ keys: console
keys: console
[loggers]
-keys: root
+keys: root,SimpleSwitch13,ryu.base.app_manager
[formatter_console]
format: %(asctime)s - %(levelname)s [%(name)s] (%(threadName)-10s) %(message)s
@@ -15,6 +15,17 @@ class: StreamHandler
args:[sys.stdout]
formatter: console
+[logger_SimpleSwitch13]
+level: INFO
+handlers: console
+qualname: SimpleSwitch13
+
+[logger_ryu.base.app_manager]
+level: INFO
+handlers: console
+qualname: ryu.base.app_manager
+propagate: 1
+
[logger_root]
-level: INFO
+level: ERROR
handlers: console

This is the final logging.ini file with after applying these changes:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
[formatters]
keys: console
[handlers]
keys: console
[loggers]
keys: root,SimpleSwitch13,ryu.base.app_manager
[formatter_console]
format: %(asctime)s - %(levelname)s [%(name)s] (%(threadName)-10s) %(message)s
[handler_console]
class: StreamHandler
args:[sys.stdout]
formatter: console
[logger_SimpleSwitch13]
level: INFO
handlers: console
qualname: SimpleSwitch13
[logger_ryu.base.app_manager]
level: INFO
handlers: console
qualname: ryu.base.app_manager
propagate: 1
[logger_root]
level: ERROR
handlers: console

This is the final result on the terminal, as you can see, there’s no ryu.lib.hub being logged anymore, only ryu.base.app_manager (MainThread) and the other green thread of SimplesSwitch13 (which now is GreenThread-1):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
2018-01-01 18:23:14,511 - INFO [ryu.base.app_manager] (MainThread) loading app ryu/app/ofctl_rest.py
2018-01-01 18:23:14,511 - INFO [ryu.base.app_manager] (MainThread) loading app ryu/app/ofctl_rest.py
2018-01-01 18:23:14,514 - INFO [ryu.base.app_manager] (MainThread) loading app ryu/app/simple_switch_13.py
2018-01-01 18:23:14,514 - INFO [ryu.base.app_manager] (MainThread) loading app ryu/app/simple_switch_13.py
2018-01-01 18:23:14,515 - INFO [ryu.base.app_manager] (MainThread) loading app ryu.controller.ofp_handler
2018-01-01 18:23:14,515 - INFO [ryu.base.app_manager] (MainThread) loading app ryu.controller.ofp_handler
2018-01-01 18:23:14,515 - INFO [ryu.base.app_manager] (MainThread) creating context wsgi
2018-01-01 18:23:14,515 - INFO [ryu.base.app_manager] (MainThread) creating context wsgi
2018-01-01 18:23:14,516 - INFO [ryu.base.app_manager] (MainThread) instantiating app None of DPSet
2018-01-01 18:23:14,516 - INFO [ryu.base.app_manager] (MainThread) instantiating app None of DPSet
2018-01-01 18:23:14,516 - INFO [ryu.base.app_manager] (MainThread) creating context dpset
2018-01-01 18:23:14,516 - INFO [ryu.base.app_manager] (MainThread) creating context dpset
2018-01-01 18:23:14,516 - INFO [ryu.base.app_manager] (MainThread) instantiating app ryu/app/ofctl_rest.py of RestStatsApi
2018-01-01 18:23:14,516 - INFO [ryu.base.app_manager] (MainThread) instantiating app ryu/app/ofctl_rest.py of RestStatsApi
2018-01-01 18:23:14,517 - INFO [ryu.base.app_manager] (MainThread) instantiating app ryu/app/simple_switch_13.py of SimpleSwitch13
2018-01-01 18:23:14,517 - INFO [ryu.base.app_manager] (MainThread) instantiating app ryu/app/simple_switch_13.py of SimpleSwitch13
2018-01-01 18:23:14,517 - INFO [ryu.base.app_manager] (MainThread) instantiating app ryu.controller.ofp_handler of OFPHandler
2018-01-01 18:23:14,517 - INFO [ryu.base.app_manager] (MainThread) instantiating app ryu.controller.ofp_handler of OFPHandler
2018-01-01 18:23:52,221 - INFO [SimpleSwitch13] (GreenThread-1) packet in 1 a6:17:45:1d:f9:50 ff:ff:ff:ff:ff:ff 1
2018-01-01 18:23:52,221 - INFO [SimpleSwitch13] (GreenThread-1) packet in 1 a6:17:45:1d:f9:50 ff:ff:ff:ff:ff:ff 1
2018-01-01 18:23:52,223 - INFO [SimpleSwitch13] (GreenThread-1) packet in 2 a6:17:45:1d:f9:50 ff:ff:ff:ff:ff:ff 2
2018-01-01 18:23:52,223 - INFO [SimpleSwitch13] (GreenThread-1) packet in 2 a6:17:45:1d:f9:50 ff:ff:ff:ff:ff:ff 2
2018-01-01 18:23:52,224 - INFO [SimpleSwitch13] (GreenThread-1) packet in 2 8e:a3:dd:75:d0:89 a6:17:45:1d:f9:50 1
2018-01-01 18:23:52,224 - INFO [SimpleSwitch13] (GreenThread-1) packet in 2 8e:a3:dd:75:d0:89 a6:17:45:1d:f9:50 1
2018-01-01 18:23:52,227 - INFO [SimpleSwitch13] (GreenThread-1) packet in 1 8e:a3:dd:75:d0:89 a6:17:45:1d:f9:50 2
2018-01-01 18:23:52,227 - INFO [SimpleSwitch13] (GreenThread-1) packet in 1 8e:a3:dd:75:d0:89 a6:17:45:1d:f9:50 2
2018-01-01 18:23:52,229 - INFO [SimpleSwitch13] (GreenThread-1) packet in 1 a6:17:45:1d:f9:50 8e:a3:dd:75:d0:89 1
2018-01-01 18:23:52,229 - INFO [SimpleSwitch13] (GreenThread-1) packet in 1 a6:17:45:1d:f9:50 8e:a3:dd:75:d0:89 1
2018-01-01 18:23:52,232 - INFO [SimpleSwitch13] (GreenThread-1) packet in 2 a6:17:45:1d:f9:50 8e:a3:dd:75:d0:89 2
2018-01-01 18:23:52,232 - INFO [SimpleSwitch13] (GreenThread-1) packet in 2 a6:17:45:1d:f9:50 8e:a3:dd:75:d0:89 2

Bottom line

Ryu is written in Python so, you can set the logging module whoever you feel is more convenient to help you to troubleshoot the problem. Usually, I’d recommend that you start with full DEBUG at the root level and narrow down accordingly.