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:

.. code:: python

   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:

.. code:: python

   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

.. code:: ipython3

    !rm -r ~/negmas/logs/test_world


.. parsed-literal::

    rm: /Users/yasser/negmas/logs/test_world: No such file or directory


.. code:: ipython3

    from scml import SCML2023World
    from scml import DecentralizingAgent, 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

.. code:: ipython3

    !tree ~/negmas/logs/test_world


.. parsed-literal::

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

    2 directories, 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

.. code:: ipython3

    from pathlib import Path

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


.. parsed-literal::

    2024-03-02 15:02:39,396 - INFO - 0/10 [0.00%]: test_world: World Created

    2024-03-02 15:02:39,396 - INFO - 0/10 [0.00%]: 00Do@0 joined

    2024-03-02 15:02:39,402 - INFO - 0/10 [0.00%]: 01Do@0 joined

    2024-03-02 15:02:39,406 - INFO - 0/10 [0.00%]: 02Do@0 joined

    2024-03-02 15:02:39,411 - INFO - 0/10 [0.00%]: 03Do@0 joined

    2024-03-02 15:02:39,419 - INFO - 0/10 [0.00%]: 04Do@1 joined

    2024-03-02 15:02:39,422 - INFO - 0/10 [0.00%]: 05Do@1 joined

    2024-03-02 15:02:39,425 - INFO - 0/10 [0.00%]: SELLER joined

    2024-03-02 15:02:39,430 - INFO - 0/10 [0.00%]: BUYER joined

    2024-03-02 15:02:39,433 - INFO - 0/10 [0.00%]: This is a test message



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:

.. code:: ipython3

    !rm -r ~/negmas/logs/test_world

.. code:: ipython3

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

.. code:: ipython3

    !tree ~/negmas/logs/test_world


.. parsed-literal::

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

    2 directories, 7 files


.. code:: ipython3

    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]]


.. parsed-literal::

    2024-03-02 15:02:40,796 - DEBUG - 0/10 [0.00%]: End step:

    {'_balance': 1517,

     '_input_inventory': 13,

     '_output_inventory': 0,

     'buy_negotiations': [],

     'execution_fraction': 0.9782608695652174,

     'expected_inputs': array([23, 18, 19, 10, 10, 10, 10, 10, 10, 10]),

     'expected_outputs': array([10, 10, 10, 10, 10, 10, 10, 10, 10, 10]),

     'input_cost': array([10, 10, 10, 10, 10, 10, 10, 10, 10, 10]),

     'inputs_needed': array([10, 10, 10, 10, 10, 10, 10, 10, 10,  0]),



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:

.. code:: ipython3

    !rm -r ~/negmas/logs/test_world

.. code:: ipython3

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

.. code:: ipython3

    !tree ~/negmas/logs/test_world


.. parsed-literal::

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

    2 directories, 14 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:

.. code:: ipython3

    !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


.. parsed-literal::

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

    2 directories, 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                 | Maximum number of negotiations that an agent    |
| g_quota_simulation | 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                  | The total real-time allowed for receiving a     |
| eg_step_time_limit | 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             | The period between successive financial reports |
| ial_reports_period | 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             | Number of exceptions that happened during       |
| tiation_exceptions | negotiation. These are usually bugs in the      |
|                    | negotiators/utility functions                   |
+--------------------+-------------------------------------------------+
| n_c                | Number of exceptions that happened during       |
| ontract_exceptions | contract executions. Any number above zero here |
|                    | is a bug                                        |
+--------------------+-------------------------------------------------+
| n_sim              | Number of exceptions everywhere else in the     |
| ulation_exceptions | 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_              | Spot market parameter (See                      |
| market_global_loss | http://www.yasserm.com/scml/scml2020.pdf)       |
+--------------------+-------------------------------------------------+
| spot_multiplier    | Spot market parameter (See                      |
|                    | http://www.yasserm.com/scml/scml2020.pdf)       |
+--------------------+-------------------------------------------------+
| trad               | Trading price estimation parameter (See         |
| ing_price_discount | http://www.yasserm.com/scml/scml2020.pdf)       |
+--------------------+-------------------------------------------------+
| consumers          | All consumers of every product                  |
+--------------------+-------------------------------------------------+
| suppliers          | All suppliers of every product                  |
+--------------------+-------------------------------------------------+
| publ               | Whether to make trading prices public           |
| ish_trading_prices | information in the bulletin board               |
+--------------------+-------------------------------------------------+
| publish_exogenou   | Whether to make the summary for exogeonus       |
| s_contract_summary | 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:

.. code:: python

   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 :download:`Notebook<notebooks/06.logs_and_stats.ipynb>`.