Mastering the logging system¶
Pypot used the Python’s builtin logging module for logging. For details on how to use this module please refer to Python’s own documentation or the one on django webstite. Here, we will only describe what pypot is logging and how it is organised (see section Logging structure). We will also present a few examples on how to use pypot logging and parse the information (see section Using Pypot’s logging).
Logging structure¶
Pypot is logging information at all different levels:
- low-level dynamixel IO
- motor and robot abstraction
- within each primitive
- each request received by the server
Note
As you probably do not want to log everything (pypot is sending a lot of messages!!!), you have to select in the logging structure what is relevant in your program and define it in your logging configuration.
Pypot’s logging naming convention is following pypot’s architecture. Here is the detail of what pypot is logging with the associated logger’s name:
- The logger’s name pypot.dynamixel.io is logging information related to opening/closing port (INFO) and each sent/received package (DEBUG). The communication and timeout error are also logged (WARNING). This logger always provides you the port name, the baudrate and timout of your connection as extra information.
- The logger pypot.dynamixel.motor is logging each time a register of a motor is set (DEBUG). The name of the register, the name of the motor and the set value are given in the message.
- pypot.robot.config is logging information regarding the creation of a robot through a config dictionary. A message is sent for each motor, controller and alias added (INFO). A WARNING message is also sent when the angle limits of a motor are changed. We provide as extra the entire config dictionary.
- The logger pypot.robot.robot is logging when the synchronization is started/stopped (INFO) and when a primitive is attached (INFO).
- pypot.primitive.primitive logs a message when the primitive is started/stopped and paused/resumed (INFO). Eeach
update()
of a LoopPrimitive is also logged (DEBUG). Each time a primitive sets a value to a register a message is also logged (DEBUG). - pypot.primitive.manager provides you information on how the values sent within primitives were combined (DEBUG).
- pypot.server logs when the server is started (INFO) and each handled request (DEBUG).
Using Pypot’s logging¶
As an example of what you can do with the logging system, here is how you can check the “real” update frequency of a loop primitive.
First, you have to define a logging config. As you can see, here we specify that we only want the log coming form ‘pypot.primitive’ and the message is formatted so we only keep the timestamp:
LOGGING = {
'version': 1,
'disable_existing_loggers': True,
'formatters': {
'time': {
'format': '%(asctime)s',
},
},
'handlers': {
'file': {
'level': 'DEBUG',
'class': 'logging.FileHandler',
'filename': 'pypot.log',
'formatter': 'time',
},
},
'loggers': {
'pypot.primitive': {
'handlers': ['file', ],
'level': 'DEBUG',
},
},
}
Then, we just have to write a simple program, where for instance we run our dummy primitive for ten seconds:
import pypot.robot
[...]
if __name__ == '__main__':
logging.config.dictConfig(LOGGING)
r = pypot.robot.from_config(ergo_config)
class DummyPrimitive(LoopPrimitive):
pass
p = DummyPrimitive(r, 50)
p.start()
time.sleep(10)
p.stop()
The execution of the program above will create a file named ‘pypot.log’ where each line corresponds to the timestamp of each primitive update. This file can then be easily parsed:
t = []
with open('pypot.log') as f:
for l in f.readlines():
d = datetime.datetime.strptime('%Y-%m-%d %H:%M:%S,%f\n')
t.append(d)
t = numpy.array(t)
dt = map(lambda dt: dt.total_seconds(), numpy.diff(t))
dt = numpy.array(dt) * 1000
print(numpy.mean(dt), numpy.std(dt))
plot(dt)
show()