Problems about logging

[a4rcvv]

Describe the bug

There are some bugs about logging.

• self.awi.logdebug_agent()` does not work
• World logs are stored in the log files of each agent.

To Reproduce

Run this script

from negmas import Outcome, MechanismState, ResponseType
from scml import SCML2023OneShotWorld, GreedySyncAgent
from scml.oneshot import OneShotAgent


class MyAgent(OneShotAgent):
    def init(self):
        super().init()
        self.awi.logdebug_agent("agent!")
        self.awi.logdebug("world!")

    def propose(self, negotiator_id: str, state: MechanismState) -> Outcome:
        return tuple([1, 1, 1])

    def respond(
        self, negotiator_id: str, state: MechanismState, offer: Outcome
    ) -> ResponseType:
        return ResponseType.ACCEPT_OFFER


world = SCML2023OneShotWorld(
    **SCML2023OneShotWorld.generate(
        agent_types=[MyAgent] * 2,
        agent_processes=[0, 1],
        n_steps=3,
        n_processes=2,
        name="test",
    )
)

world.run()

Expected behavior

• "agent!" is logged in ~/negmas/logs/test/_agent_logs/00My@0.txt and 01My@1.txt
• world logs are logged in ~/negmas/logs/test/log.txt

actual behaviour

• "agent!" is not logged in any log files.
• 00My@0.txt and 01My@1.txt have logs as same as ~/negmas/logs/test/log.txt

(00My@0.txt)

2023-04-04 21:54:36,439 - DEBUG - 0/3 [0.00%]: world!
2023-04-04 21:54:36,439 - DEBUG - 0/3 [0.00%]: world!
2023-04-04 21:54:36,439 - INFO - 0/3 [0.00%]: 0 Negotiations/4 Agents
2023-04-04 21:54:36,440 - DEBUG - 0/3 [0.00%]: 01My@1 requested to buy 1 to 00My@0 q: (1, 10), u: (15, 16), t: (0, 0)
...

(log.txt)

2023-04-04 21:54:36,437 - INFO - 0/3 [0.00%]: test: World Created
2023-04-04 21:54:36,438 - INFO - 0/3 [0.00%]: 00My@0 joined
2023-04-04 21:54:36,438 - INFO - 0/3 [0.00%]: 01My@1 joined
2023-04-04 21:54:36,438 - INFO - 0/3 [0.00%]: SELLER joined
2023-04-04 21:54:36,438 - INFO - 0/3 [0.00%]: BUYER joined
2023-04-04 21:54:36,439 - DEBUG - 0/3 [0.00%]: world!
2023-04-04 21:54:36,439 - DEBUG - 0/3 [0.00%]: world!
2023-04-04 21:54:36,439 - INFO - 0/3 [0.00%]: 0 Negotiations/4 Agents
2023-04-04 21:54:36,440 - DEBUG - 0/3 [0.00%]: 01My@1 requested to buy 1 to 00My@0 q: (1, 10), u: (15, 16), t: (0, 0)

Desktop (please complete the following information):

• OS: macOS Ventura 13.2.1 (with M1)
• Python version: 3.10.10
• package versions:
  • negmas: 0.9.8
  • scml: 0.5.6
• Browser [e.g. chrome, safari]
• Version [e.g. 22]

Additional context

I think negmas.helpers.logging.create_loggers() (here) has some problems.

• Logs from each agent are sent to the root logger, which has the default logging level (=WARNING).
  • Debug level logs are ignored.
• World logs are sent to the "logging" logger, whose parent logger is the root logger.
  • World logs are propagated to the root logger. As the root logger has file log handlers associated with each agent, world logs are written to each agent's log file.

[yasserfarouk]

Thank you for submitting this issue and resolving it. We are testing the PR now and if it passes the tests will approve it ASAP.