Logging and Statistics

In this tutorial we will describe how to utilize the logging facilities provided in the NegMAS library for developing SCML agents and analyzing their behavior.

Most of the data in this tutorial apply equally to SCML2020, SCML2021 and SCML-OneShot simulations.

Types of Logs

NegMAS provides two main types of logs:

  • System Logs These types of logs all go to a single log file. System logs are recorded using loginfo/debug/warning/error methods of the world/agent-world-interface.

  • Agent Logs Go to a dedicated file for each agent. Agent logs are recoreded using the **log*_agent** family of functions in the world/agent-world interface.

For example, you can log a debug method to the agent log using:

self.awi.logdebug_agent("My Message")

You can also log a system debug message (that goes to the central log file of the world) using:

self.awi.logdebug("My Message")

Primer on logging in negmas

Logs are generated by default whenever you run a world simulation in NegMAS (and SCML). Let’s just run a simulation to see where are logs stored

!rm -r ~/negmas/logs/test_world

from scml import SCML2023World
from scml import DecentralizingAgent, RandomAgent, DoNothingAgent, DecentralizingAgentWithLogging

# create and run the world
world = SCML2023World(
    **SCML2023World.generate(
        agent_types=[DoNothingAgent],
        n_steps=10,
        n_processes=2,
        name="test_world"
    )
)
world.loginfo("This is a test message")

where there any logs generated and where are they?

By defaults, all logs for SCML 2020 world simulations go to the folder ~/negmas/logs/{world_name} and all logs and statistics for tournaments go to ~/negmas/tournament/scml/scml2020/{tournament_name} with logs and statistics for specific worlds going to ~/negmas/tournament/scml/scml2020/{tournament_name}/{world_name}

Let’s check our logs

!tree ~/negmas/logs/test_world

/Users/yasser/negmas/logs/test_world
├── _agent_logs
├── events.json
└── log.txt

1 directory, 2 files

As you can see, there is a folder called **_agent_logs** that will store all agent logs (in dedicated files) if the agents save logs. Moreover, there is a log.txt file which contains the global logs. Let’s just check what is in it

Now we have agent logs. We can inspect one of them

from pathlib import Path
with open(Path.home() /"negmas" / "logs" / world.name / "log.txt", "r") as f:
    [print(_) for _ in f.readlines()[:10]]

2023-03-07 16:34:41,382 - INFO - 0/10 [0.00%]: test_world: World Created

2023-03-07 16:34:41,383 - INFO - 0/10 [0.00%]: 00Do@0 joined

2023-03-07 16:34:41,388 - INFO - 0/10 [0.00%]: 01Do@0 joined

2023-03-07 16:34:41,389 - INFO - 0/10 [0.00%]: 02Do@0 joined

2023-03-07 16:34:41,392 - INFO - 0/10 [0.00%]: 03Do@0 joined

2023-03-07 16:34:41,394 - INFO - 0/10 [0.00%]: 04Do@1 joined

2023-03-07 16:34:41,394 - INFO - 0/10 [0.00%]: 05Do@1 joined

2023-03-07 16:34:41,395 - INFO - 0/10 [0.00%]: 06Do@1 joined

2023-03-07 16:34:41,395 - INFO - 0/10 [0.00%]: 07Do@1 joined

2023-03-07 16:34:41,395 - INFO - 0/10 [0.00%]: SELLER joined

All log entries start with a time-stamp followed by the log type (INFO/DEBUG/WARNING/ERROR/CRITICAL) and the step number (day) then the number of steps and the percentage of the simulation steps passed and finally the message.

The world keeps some basic logs like who joined but near the end we can see our message.

Most likely you will not need to save directly the system logs but can save debugging information in the agent logs. Some builtin agents do that (e.g. DecentralizingAgent). Let’s check an exmple:

!rm -r ~/negmas/logs/test_world

SCML2023World(
    **SCML2023World.generate(
        agent_types=[DecentralizingAgentWithLogging],
        n_steps=10,
        n_processes=2,
        name="test_world"
    )
).run()

!tree ~/negmas/logs/test_world

/Users/yasser/negmas/logs/test_world
├── _agent_logs
│   ├── 00DWL@0.txt
│   ├── 01DWL@0.txt
│   ├── 02DWL@0.txt
│   ├── 03DWL@0.txt
│   ├── 04DWL@1.txt
│   ├── 05DWL@1.txt
│   └── 06DWL@1.txt
└── events.json

1 directory, 8 files

from pathlib import Path
with open(Path.home() /"negmas" / "logs" / world.name / "_agent_logs" / "00DWL@0.txt", "r") as f:
    [print(_) for _ in f.readlines()[:10]]

2023-03-07 16:34:41,843 - DEBUG - 0/10 [0.00%]: 01DWL@0 requested to sell 1 to 04DWL@1 q: (1, 10), u: (8, 26), t: (1, 6)

2023-03-07 16:34:41,844 - INFO - 0/10 [0.00%]: 01DWL@0 requested negotiation with ['01DWL@0', '04DWL@1'] (ID 11d47784-44a9-4c1a-93b6-ae74fe8026eb)

2023-03-07 16:34:41,844 - INFO - 0/10 [0.00%]: 01DWL@0 request was accepted

2023-03-07 16:34:41,844 - DEBUG - 0/10 [0.00%]: 01DWL@0 requested to sell 1 to 05DWL@1 q: (1, 10), u: (8, 26), t: (1, 6)

2023-03-07 16:34:41,844 - INFO - 0/10 [0.00%]: 01DWL@0 requested negotiation with ['01DWL@0', '05DWL@1'] (ID 64aa28eb-ce25-4d9d-9039-a2954c9bc9cd)

2023-03-07 16:34:41,845 - INFO - 0/10 [0.00%]: 01DWL@0 request was accepted

2023-03-07 16:34:41,845 - DEBUG - 0/10 [0.00%]: 01DWL@0 requested to sell 1 to 06DWL@1 q: (1, 10), u: (8, 26), t: (1, 6)

2023-03-07 16:34:41,845 - INFO - 0/10 [0.00%]: 01DWL@0 requested negotiation with ['01DWL@0', '06DWL@1'] (ID 3231f970-b4e4-4141-b2b3-255dd906800a)

2023-03-07 16:34:41,845 - INFO - 0/10 [0.00%]: 01DWL@0 request was accepted

2023-03-07 16:34:41,846 - DEBUG - 0/10 [0.00%]: 01DWL@0 requested to sell 1 to 04DWL@1 q: (1, 10), u: (8, 26), t: (2, 7)

The format is familiar with the same header information at every line plus the message (which can span multiple lines).

SCML2020Agent class defines a property called internal_state which is just a dict. Several builtin strategies (e.g. TradningStrategy, NegotiationManager) log debugging information by just dumping this internal-state to file. You can hook into this mechanism by adding your own key-value pairs to the internal-state. An example can be seen in the TradingStrategy class.

You do not need to use this internal-state mechanism. You can just use logdebug_agent for example to log information into your agent log file.

Controlling logging

You can control several aspects of logging using log_* parameters of the world constructor. These parameters can also be passed to world generation method (SCML2023World.generate) and to all tournament creation functions (i.e. anac2023std, anac2023collusion, tournament, etc).

This is a full list of these parameters:

  • compact If true, it will prevent all logs except errors among other optmizations to speedup the simulation and reduce the memory-footprint. Default is False when running a single world and True when running a tournament

  • no_logs If true, it stops all logging. It overrides everything else. Default is False

  • log_folder Gives a folder to save the logs (default is ~/negmas/logs). Note that – by default – that is alse where all statistics are saved.

  • log_to_file: If false, will disable the system log (but not agent logs). Default is True

  • log_file_name: Name of the system log file. By default it is “log.txt”

  • event_file_name: Name of the a file to store events (structured logs) to. By default it is “events.json”

  • log_file_level: The minimum log-level to save to file (WARNING, ERROR, INFO, DEBUG, CRITICAL, …). Default is DEGUG to save everything

  • log_ufuns: Log utility functions. If True, all utility functions will be saved to a folder inside the log_folder (experimental and extremely slow). Default is False

  • log_negotiations: Log all negotiation events (e.g. all exchagned offers and counter offers). This will slow down the simulation and increase the memory-footprint considerably if enabled. Default is False.

  • log_to_screen: If True, some logs (controlled by log_screen_level ) will be printed to the screen. Default is False.

  • log_screen_level: The log-level to show on screen (WARNING, ERROR, INFO, DEBUG, CRITICAL, …) if log_to_screen is True. Default is ERROR.

  • log_stats_every: If nonzero and positive, the period of saving statistics to the log_folder. Default is zero leading to no auto-saving of statistics.

  • construct_graphs: If true, information needed to draw graphs using draw method are kept. Default is False.

Let’s try changing some of these:

!rm -r ~/negmas/logs/test_world

SCML2023World(
    **SCML2023World.generate(
        agent_types=[DecentralizingAgentWithLogging],
        n_steps=10,
        n_processes=2,
        name="test_world",
        log_stats_every=2,
    )
).run()

!tree ~/negmas/logs/test_world

/Users/yasser/negmas/logs/test_world
├── _agent_logs
│   ├── 00DWL@0.txt
│   ├── 01DWL@0.txt
│   ├── 02DWL@0.txt
│   ├── 03DWL@0.txt
│   ├── 04DWL@1.txt
│   └── 05DWL@1.txt
├── agents.json
├── breaches.csv
├── contracts.csv
├── events.json
├── info.json
├── negotiations.csv
├── params.json
├── stats.csv
└── stats.csv.csv

1 directory, 15 files

Now we can see that many more files are created in the log folder. These files keep a wealth of information to understand what happened in this world. You can save the same files using negmas builtin save_stats method without needing to enable periodic saving using log_stats_every. Here is an example:

!rm -r ~/negmas/logs/test_world
from negmas import save_stats
world = SCML2023World(
    **SCML2023World.generate(
        agent_types=[DecentralizingAgent],
        n_steps=10,
        n_processes=2,
        name="test_world"
    )
)
world.run()
save_stats(world, world.log_folder)
!tree ~/negmas/logs/test_world

/Users/yasser/negmas/logs/test_world
├── _agent_logs
├── agents.json
├── breaches.csv
├── contracts.csv
├── events.json
├── info.json
├── negotiations.csv
├── params.json
├── stats.csv
└── stats.json

1 directory, 9 files

Getting infromation about a simulation

Let’s examine each of the files save_stats saves in your log_folder in turn:

  • World information

    • params.json The parameters passed to the world constructor (SCML2020World.__init__).

    • info.json Information about the world. You can pass extra information to be saved here while constructing the world through the info parameter of the contractor as a dictionary of key-value pairs (all keys must be strings).

    • stats.csv/stats.json CSV and JSON versions of world statistics.

  • Contracts and Negotiations

    • negotiations.csv Stores information about all the negotiations conducted during the simulation.

    • contracts.csv Stores every contract concluded during the simulation.

    • breaches.csv Stores information about every breach that occurred during the simulation.

  • Detailed Events

    • events.json A list of events in JSON format. Notice that you need to prepend it with open bracket and replace the last comma with closed pracket to get a well formatted JSON list

World Information

The system stores two types of information about the simulation:

  • Static information in params.json and info.json. This information does not change during the simulation (e.g. number of steps, agent types). You will find that params.json stores some other information that is not strictly static.

  • Dynamic information in stats.csv and stats.json. This includes world statistics, statistics for every agent and for every product.

Let’s check each of them in turn:

params.json

This is just a copy of all the paramters used to create the world. These are mostly not specific to SCML worlds.

Here are some of the most important parameters stored in this file:

Key

Meaning

name

The world name

mechanisms

Allowed mechanism types and their parameters

compact

Whether this is a compact run (see Logging Primer earlier)

n_steps

Number of simulated days.

time_limit

The total real-time allowed for the simulation

neg_n_steps

Maximum number of rounds per negotiation

ne g_quota_simulation

Maximum number of negotiations that an agent can initiate during the whole simulation

neg_quota_step

Maximum number of of negotiations that an agent can initiate during a single day (simulation step)

n eg_step_time_limit

The total real-time allowed for receiving a response from a negotiator

neg_time_limit

The total real-time allowed for a negotiation

negotiation_speed

The number of negotiation rounds in a single simulation step

financ ial_reports_period

The period between successive financial reports in steps

agent_unique_types

A unique identifier of the agent type for every agent in the simulation

exogenous_horizon

The number of steps in advance within which exogenous contracts are revealed

n_agent_exceptions

Number of agent exceptions. These are the results of bugs in the agents most likely.

n_nego tiation_exceptions

Number of exceptions that happened during negotiation. These are usually bugs in the negotiators/utility functions

n_c ontract_exceptions

Number of exceptions that happened during contract executions. Any number above zero here is a bug

n_sim ulation_exceptions

Number of exceptions everywhere else in the simulation. These are also bugs in the platform

igno re_agent_exception

ignore_contract_ex ecution_exceptions

ignore_nego tiation_exceptions

ignore_sim ulation_exceptions

n_processes

Number of processes in the world

n_products

Number of products in the world

spot_discount

Spot market parameter (See http://www.yasserm.com/scml/scml2020.pdf)

spot_ market_global_loss

Spot market parameter (See http://www.yasserm.com/scml/scml2020.pdf)

spot_multiplier

Spot market parameter (See http://www.yasserm.com/scml/scml2020.pdf)

trad ing_price_discount

Trading price estimation parameter (See http://www.yasserm.com/scml/scml2020.pdf)

consumers

All consumers of every product

suppliers

All suppliers of every product

publ ish_trading_prices

Whether to make trading prices public information in the bulletin board

publish_exogenou s_contract_summary

Whether to make the summary for exogeonus contracts public information in the bulletin board

You can check any of these parameters by loading the json file:

info.json

All the information in this file is specific to SCML2020. This information describes all intermediate variables used during the creation of the world configuration (See http://www.yasserm.com/scml/scml2020.pdf Appendix B for details).

stats.csv and stats.json

These two files have the same information in json and csv forms and provides one record for each simulation step (day). The same information can be accessed in real-time using:

world.stats
world.stats_df

They can be divided into three categories: world statistics, product statistics, and agent statistics. - World statistics reveal information about the state of the world after every simulation step. Names of these statistics are self-explanatory

  • Product statsitics all end with *_{p}* where p is the product number:

    • trading_price_{p} The trading price of the product at the end of every simulation step.

    • sold_quantity_{p} The quantity sold/bought of that product at every simulation step.

    • unit_price+{p} The average unit price of the product at every simulation step (if its sold_quantity was nonzero).

  • Agent statsitics all end with *_{a}* (or have *_{a}* in the middle) where a is the agent ID:

    • balance_{a} The balance of the agent.

    • **inventory_{a}_input** The number of units of the agent’s input product currently available in its inventory

    • **inventory_{a}_output** The number of units of the agent’s output product currently available in its inventory

    • assets_{a} The value of the agent’s inventory.

    • score_{a} The score of the agent which is a combination of its balance and assets value according to SCML2020 rules.

    • productivity_{a} The fraction of production lines of the agent’s factory that are active during every simulation step.

    • bankrupt_{a} Whether the agent is bankrupt

    • spot_market_quantity_{a} The quantity the agent bought from the spot market (of its output product).

    • spot_market_loss_{a} The personalized spot market loss of the agent.

Contracts and Negotiations

These files save information about every simulation, contract and breach.

negotiations.csv

This file stores a record for each negotiation. The most important fields are:

  • partners: Gives the names of the partners

  • partner_ids The IDs of the partners

  • partner_types The types of the agents to which the partners belong

  • issues Negotiation Issues

  • caller The name of the agent that initated the negotiation

  • requested_at: The time at which the negotiation was requested

  • relative_time The relative time (between zero and one) at which the negotiation ended

  • has_errors: Indicates whether one of the partners broke the protocol rules

  • current_proposer: The negotiator that sent the last offer

  • current_offer The last offer

  • agreement The agreement if any (or None if the negotiation ended with no agreement)

  • step The step at which the negotiation ended

  • broken Will be true if one partner ended the negotiation

  • timedout will be true if the negotiation timed out

  • current_proposer_agent The agent to which the current_proposer negotiator belongs

  • new_offers The offers exchanged in the last negotiation round

  • new_offer_agents The agents generating the offers exchanged in the last round

contracts.csv

This file has a record for every contract negotiated (as well as exogenous contracts). signed_contracts.csv and cancelled_contracts.csv have a subset of these records with signed and cancelled contracts only respectively. These are all the fields stored for every contract:

Partner information:

  • product, product_name: The product index and name

  • seller, seller_name, seller_type: Seller ID, name, and type

  • seller, buyer_name, buyer_type: Buyer ID, name and type

Agenda:

  • caller: Who requested the negotiation

  • issues: Negotiation issues

  • is_buy

Agreement (will be nan if there is no agreement)

  • delivery_time

  • quantity

  • unit_price

Contract Life (-1 means the event did not happen):

  • concluded_at: when was the negotiation leadign to this contract concluded

  • signed_at: when was the contract signed

  • executed_at: when was it executed (will be the same as delivery_time

  • nullified_at: If nulliied due to bankruptcy of one of the partners, when

  • erred_at: Should never happen.

  • dropped_at: The system will drop all contract that have delivery times in the past or at a day by the end of that day

Other Information:

  • id: The unique ID of this contract

  • signatures: Will be the IDs of the two partners if the contract was signed

  • n_neg_steps: Number of negotaition steps that lead to this contract

  • breaches: List of breaches if any

breaches.csv

Saves information about all breaches (will always be empty in SCML-OneShot simulations):

  • id A unique ID for this breach

  • contract, contract_id The contract that was breached

  • type The breach type (inventory or funds)

  • level The breach level (a number between zero and one)

  • perpetrator, perpetrator_type The ID and name of the agent that committed the breach

  • victims Will always be a single string giving the ID of the victim

  • step The step at which the breach happens

  • resolved Will always be false in SCML2020

Download Notebook.