3
\$\begingroup\$

This question is more-or-less code agnostic. Provided code analysis would be helpful though.

Background: I've never got along with logging too well - probably because I've never had a need to review the non-error level logs. I comply with logging practices on work projects, but I usually don't do any logging in personal projects.

Below is an exempt from the game server module. The class is a persistent connection with the client, and is responsible for receiving (responders) and sending (commands) information from and to the client. Please only analyze the logging.

class CommandProtocol(AMP):

    def __init__(self, factory):
        self.factory = factory

    def connectionMade(self):
        self.uid = str(id(self))
        self.factory.clients[self.uid] = self
        logging.info("Client '%s' is connected.", self.uid)

    #--------------------------------------------------------------------------
    # responders

    def queue_int(self, action, arg):
        self.factory.requests.add_request(self.uid, (action, arg))
        logging.debug(
                "Client '%s' queued int '%s' with value '%d'.",
                self.uid, action, arg)
        return {}
    commands.QueueInt.responder(queue_int)

    def queue_str(self, action, arg):
        self.factory.requests.add_request(self.uid, (action, arg))
        logging.debug(
                "Client '%s' queued str '%s' with value '%s'.",
                self.uid, action, arg)
        return {}
    commands.QueueStr.responder(queue_str)

    def queue_tuple_of_int(self, action, arg1, arg2):
        self.factory.requests.add_request(self.uid, (action, (arg1, arg2)))
        logging.debug(
                "Client '%s' queued tuple of int '%s' with value '(%d, %d)'.",
                self.uid, action, arg1, arg2)
        return {}
    commands.QueueTupleOfInt.responder(queue_tuple_of_int)

    def queue_tuple_of_str(self, action, arg1, arg2):
        self.factory.requests.add_request(self.uid, (action, (arg1, arg2)))
        logging.debug(
                "Client '%s' queued tuple of str '%s' with value '(%s, %s)'.",
                self.uid, action, arg1, arg2)
        return {}
    commands.QueueTupleOfStr.responder(queue_tuple_of_str)

    def query_equipment(self):
        equipment = self.factory.game.get_equipment(self.uid)
        amp_equipment = []
        for k, v in equipment.items():
            v = 'None' if v is None else v.get_name()
            amp_equipment.append({'slot': k, 'item': v})
        logging.debug("Client '%s' queried for equipment.", self.uid)
        return {'equipment': amp_equipment}
    commands.QueryEquipment.responder(query_equipment)

    def query_inventory(self):
        inventory = self.factory.game.get_inventory(self.uid)
        amp_inventory = []
        for item, qty in inventory.items():
            amp_inventory.append({'item': item.get_name(), 'qty': qty})
        logging.debug("Client '%s' queried for inventory.", self.uid)
        return {'inventory': amp_inventory}
    commands.QueryInventory.responder(query_inventory)

    #--------------------------------------------------------------------------
    # commands

    def add_chat_messages(self, messages):
        for i, m in enumerate(messages):
            messages[i] = {'message': m[0], 'type': m[1]}
        logging.debug("Pushed chat messages to client '%s'.", self.uid)
        return self.callRemote(commands.AddChatMessages, messages=messages)

    def set_bottom_status_bar(self, text):
        logging.debug("Set bottom status bar for client '%s'.", self.uid)
        return self.callRemote(commands.SetBottomStatusBar, text=text)

    def set_equipment(self, equipment):
        amp_equipment = []
        for k, v in equipment.items():
            v = 'None' if v is None else v.get_name()
            amp_equipment.append({'slot': k, 'item': v})
        logging.debug("Set equipment for client '%s'.", self.uid)
        return self.callRemote(commands.SetEquipment, equipment=amp_equipment)

    def set_inventory(self, inventory):
        amp_inventory = []
        for item, qty in inventory.items():
            amp_inventory.append({'item': item.get_name(), 'qty': qty})
        logging.debug("Set inventory for client '%s'.", self.uid)
        return self.callRemote(commands.SetInventory, inventory=amp_inventory)

    def set_look_pointer(self, (x, y)):
        logging.debug(
                "Set look pointer for client '%s' at (%d, %d).",
                self.uid, x, y)
        return self.callRemote(commands.SetLookPointer, x=x, y=y)

    def set_pilot(self, is_pilot):
        logging.debug(
                "Set pilot mode for client '%s' to '%r'.",
                self.uid, is_pilot)
        return self.callRemote(commands.SetPilot, is_pilot=is_pilot)

    def set_target(self, (x, y)):
        logging.debug(
                "Set target pointer for client '%s' at (%d, %d).",
                self.uid, x, y)
        return self.callRemote(commands.SetTarget, x=x, y=y)

    def set_top_status_bar(self, text):
        logging.debug("Set top status bar for client '%s'.", self.uid)
        return self.callRemote(commands.SetTopStatusBar, text=text)

    def set_view(self, view, colors):
        view = '\n'.join(view)
        c_colors = []
        for k, v in colors.items():
            c_colors.append(
                {'x': k[0], 'y': k[1], 'r': v[0], 'g': v[1], 'b': v[2]})
        logging.debug("Set view for client '%s'.", self.uid)
        return self.callRemote(commands.SetView, view=view, colors=c_colors)

    def unset_look_pointer(self):
        logging.debug("Unset look pointer for client '%s'.", self.uid)
        return self.callRemote(commands.UnsetLookPointer)

    def unset_target(self):
        logging.debug("Unset target pointer for client '%s'.", self.uid)
        return self.callRemote(commands.UnsetTarget)

Here's an example output:

INFO:root:Started server on port 12345.
INFO:root:Client '4352955472' is connected.
DEBUG:root:Client '4352955472' queued tuple of str 'connect' with value '(Mr Spaceman, Enterprise)'.
DEBUG:root:Set view for client '4352955472'.
DEBUG:root:Set bottom status bar for client '4352955472'.
DEBUG:root:Client '4352955472' queried for inventory.
DEBUG:root:Client '4352955472' queried for equipment.
DEBUG:root:Client '4352955472' queued tuple of int 'move' with value '(0, 1)'.
DEBUG:root:Set view for client '4352955472'.
DEBUG:root:Client '4352955472' queued tuple of int 'move' with value '(1, 0)'.
DEBUG:root:Set view for client '4352955472'.
DEBUG:root:Client '4352955472' queued tuple of int 'move' with value '(1, 0)'.
DEBUG:root:Set view for client '4352955472'.
DEBUG:root:Client '4352955472' queued tuple of int 'activate' with value '(1, 0)'.
DEBUG:root:Set view for client '4352955472'.
DEBUG:root:Set top status bar for client '4352955472'.
DEBUG:root:Client '4352955472' queued int 'quit' with value '1'.

How much information should I put into the log output? But I'm afraid my logs will contain too much information to easily comprehend what is going on. Should I consider looking into AOP for this? What are the good practices?

Feel free to suggest some good reading on a subject in addition to a code review.

\$\endgroup\$

2 Answers 2

Reset to default
2
\$\begingroup\$

The code in the methods seems repetitive. I suggest that you extract the logging and command registration aspects using decorators. That way, each method only contains the code for its core functionality.

command_decorators.py

from functools import wraps
import logging

def trace(f):
    @wraps(f)
    def logged_f(self, *args):
        logging.debug('Client %s called %s with %s', self, f.__name__, args)
        return f(self, *args)
    return logged_f

def responder_for(cmd):
    def real_decorator(f):
        cmd.responder(f)
        return f
    return real_decorator

command_protocol.py

from command_decorators import trace, responder_for

class CommandProtocol(object):

    @responder_for(commands.QueueInt)
    @trace
    def queue_int(self, action, arg):
        self.factory.requests.add_request(self.uid, (action, arg))
        return {}

    @responder_for(commands.QueueStr)
    @trace
    def queue_str(self, action, arg):
        self.factory.requests.add_request(self.uid, (action, arg))
        return {}

    @responder_for(commands.QueueTupleOfInt)
    @trace
    def queue_tuple_of_int(self, action, arg1, arg2):
        self.factory.requests.add_request(self.uid, (action, (arg1, arg2)))
        return {}

    …
\$\endgroup\$
3
\$\begingroup\$

my logs will contain too much information

Think of your log as a database of logged records. You might have all logged records contain the same number of fields (client#, action, result, etc) and each event decides which fields to fill in when generating the record. Or, you might have N different record layouts (connect event record, query event record, setgui event record, etc) and each event creates the record type specific to that event.

In either case, don't worry that you might have too many records or that records contain too much info, because what you also need to create is a log viewer/filter that allows only the records and contents of interest to be displayed or dumped.

The first logging option (all records contain the same number of fields, although many may be empty) is preferable, because lots of database tools can then be used.

For example, if your logging code creates a table of SQLite records, you can use SQLite to conveniently select and report only the logged events of interest.

\$\endgroup\$

You must log in to answer this question.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.