Logging

Because it provides an incredible breadth and depth of functionality for managing program output, Cicada uses Python’s builtin logging module to report messages from the library. Thus, you should always initialize Python’s logging system at the beginning of a Cicada program, even if you don’t plan to use logging yourself:

import logging
logging.basicConfig(level=logging.INFO)

Tip

We strongly recommend that you get to know the Python logging module, which can benefit all of your programming projects!

By default, Cicada is configured to only log warning messages, so you won’t see any output during normal operation:

from cicada.communicator import SocketCommunicator

def main(communicator):
    print(f"Hello from player {communicator.rank}!")

SocketCommunicator.run(world_size=2, fn=main);

Hello from player 1!Hello from player 0!

If you want greater visibility into what the library is doing (particularly to setup communication), you can adjust log levels accordingly:

logging.getLogger("cicada.communicator").setLevel(logging.INFO)

SocketCommunicator.run(world_size=2, fn=main)

logging.getLogger("cicada.communicator").setLevel(logging.WARNING) # Put things back the way they were

INFO:cicada.communicator.socket.connect:Comm world player 0 listening to tcp://127.0.0.1:65298 for connections.
INFO:cicada.communicator.socket.connect:Comm world player 1 listening to tcp://127.0.0.1:65300 for connections.
INFO:cicada.communicator.socket.connect:Comm world player 1 direct connect with ['tcp://127.0.0.1:65298', 'tcp://127.0.0.1:65300'].
INFO:cicada.communicator.socket.connect:Comm world player 0 direct connect with ['tcp://127.0.0.1:65298', 'tcp://127.0.0.1:65300'].
INFO:cicada.communicator.socket.connect:Comm world player 0 tcp://127.0.0.1:65298 accepted connection from tcp://127.0.0.1:65304
INFO:cicada.communicator.socket.connect:Comm world player 1 tcp://127.0.0.1:65304 connected to player 0 tcp://127.0.0.1:65298
INFO:cicada.communicator.socket:Comm world player 0 communicator ready.
INFO:cicada.communicator.socket:Comm world player 1 communicator ready.

Hello from player 0!Hello from player 1!

INFO:cicada.communicator.socket:Comm world player 1 communicator freed.
INFO:cicada.communicator.socket:Comm world player 0 communicator freed.
INFO:cicada.communicator.socket:Comm world player 0 result: None
INFO:cicada.communicator.socket:Comm world player 1 result: None

Application Logging

For application output from your MPC programs, Cicada provides its own Logger class, which wraps a standard Python logging.Logger and uses a Communicator to coordinate player output.

When you use Cicada’s Logger, player outputs will appear in rank order without interleaving or stepping on one another (compare the following output with the preceeding examples):

from cicada.logging import Logger

def main(communicator):
    log = Logger(logger=logging.getLogger(), communicator=communicator)
    log.info(f"Hello from player {communicator.rank}!")

SocketCommunicator.run(world_size=2, fn=main);

INFO:root:Hello from player 0!
INFO:root:Hello from player 1!

Just like Python’s builtin logging.Logger, Cicada’s Logger supports higher-priority messages:

def main(communicator):
    log = Logger(logger=logging.getLogger(), communicator=communicator)
    log.warning(f"Warning message from player {communicator.rank}!")

SocketCommunicator.run(world_size=2, fn=main);

WARNING:root:Warning message from player 0!
WARNING:root:Warning message from player 1!

def main(communicator):
    log = Logger(logger=logging.getLogger(), communicator=communicator)
    log.error(f"Error message from player {communicator.rank}!")

SocketCommunicator.run(world_size=2, fn=main);

ERROR:root:Error message from player 0!
ERROR:root:Error message from player 1!

def main(communicator):
    log = Logger(logger=logging.getLogger(), communicator=communicator)
    log.critical(f"Critical message from player {communicator.rank}!")

SocketCommunicator.run(world_size=2, fn=main);

CRITICAL:root:Critical message from player 0!
CRITICAL:root:Critical message from player 1!

Logger also supports lower-priority messages for debugging, but be sure to set the appropriate log level, or you won’t see any output:

logging.getLogger().setLevel(logging.DEBUG) # Don't filter DEBUG messages

def main(communicator):
    log = Logger(logger=logging.getLogger(), communicator=communicator)
    log.debug(f"Debug message from player {communicator.rank}!")

SocketCommunicator.run(world_size=2, fn=main);

DEBUG:root:Debug message from player 0!
DEBUG:root:Debug message from player 1!

You should keep in mind that Logger methods are collective operations that must be called by every player, because they use Communication Patterns to coordinate among the players.

If you only want to log a message from a single player you can do so, but every player still has to participate in the collective operation:

def main(communicator):
    log = Logger(logger=logging.getLogger(), communicator=communicator)
    log.info(f"Hello only from player {communicator.rank}!", src=1)

SocketCommunicator.run(world_size=5, fn=main);

INFO:root:Hello only from player 1!

You can also limit output to a subset of players:

def main(communicator):
    log = Logger(logger=logging.getLogger(), communicator=communicator)
    log.info(f"Hello only from player {communicator.rank}!", src=[0, 2, 4])

SocketCommunicator.run(world_size=5, fn=main);

INFO:root:Hello only from player 0!
INFO:root:Hello only from player 2!
INFO:root:Hello only from player 4!

It’s important to keep in mind that coordinated logging requires communication among the players at runtime, which can have important ramifications. As an example, you might not want to use it in a nested loop, where it could seriously impact the performance of an algorithm.

Furthermore, coordinated logging is only useful when multiple players are writing to the same console, as is typical when developing and debugging your programs using run() or the cicada run command. Once you’re ready to run your program on separate hosts (or in separate terminal sessions on the same host), then the overhead of coordinated logging becomes superflous, since the output is already separated by player.

In this case where you’re transitioning your progam from development to production, you can disable coordinated logging in a Cicada Logger at runtime with the sync parameter, so that it behaves like a “normal” Python Logger with minimal overhead:

def main(communicator):
    log = Logger(logger=logging.getLogger(), communicator=communicator, sync=False)
    log.info(f"Hello from player {communicator.rank}!")

SocketCommunicator.run(world_size=2, fn=main);

INFO:root:Hello from player 0!
INFO:root:Hello from player 1!

It’s also important to consider that coordinated logging could raise an exception at any time, if a player fails. Because coordinated logging requires communication among all players, you cannot use it when a failure has occurred - for example, during an error recovery phase or after a communicator has been revoked.

Let’s see what happens if we try to continue using coordinated logging when a failure has occurred:

def main(communicator):
    log = Logger(logger=logging.getLogger(), communicator=communicator)

    try:
        log.info(f"Player {communicator.rank} starting ...")

        # Wait for a message that never arrives ...
        if communicator.rank == 1:
            payload = communicator.recv(src=0, tag=42)

    except Exception as e:
        log.error(f"Player {communicator.rank} exception: {e}")

SocketCommunicator.run(world_size=2, fn=main);

INFO:root:Player 0 starting ...
INFO:root:Player 1 starting ...
ERROR:cicada.communicator.socket:Comm world player 1 failed: Timeout('Tag LOGSYNC from player 0 timed-out after 5s')

In this case, player 1 waits for a message from player 0 that never arrives, because player 0 has already exited. This raises a Timeout exception (as it should), but player 1 tries to use the logger in the exception handler; this raises a second exception, because the logger is trying to synchronize its output with a nonexistent player!

To handle this case correctly, players can (temporarily or permanently) disable synchronization at any time after the logger has been created using the sync property:

def main(communicator):
    log = Logger(logger=logging.getLogger(), communicator=communicator)

    try:
        log.info(f"Player {communicator.rank} starting ...")

        # Wait for a message that will neve arrives
        if communicator.rank == 0:
            payload = communicator.recv(src=1, tag=42)

    except Exception as e:
        log.sync = False # Disable coordinated logging
        log.error(f"Player {communicator.rank} exception: {e}")

SocketCommunicator.run(world_size=2, fn=main);

INFO:root:Player 0 starting ...
INFO:root:Player 1 starting ...
ERROR:root:Player 0 exception: Tag 42 from player 1 timed-out after 5s

After disabling synchronization it’s safe to use the logger in the exception handler, since it no longer tries to communicate with the other players.

See also

Transcripts