Logging error causes Scrapli to crash

[jfakult]

Describe the bug
Current main branch code crashes on attempting to log Scrapli buffer reads.

Commenting out the following line in async_channel.py removes the issue:
74: self.logger.debug("read: %r", buf)
In file: https://github.com/carlmontanari/scrapli/blob/2024.07.30/scrapli/channel/async_channel.py

To Reproduce
Steps to reproduce the behavior:

1. Pull latest version of scrapli code or 2024.07.30
2. Enable logging (enable_basic_logging(file=True, level="debug)")
3. SSH into a device using one of AsyncIOSXRDriver, AsyncJunosDriver, AsyncIOSXEDriver, AsyncNXOSDriver
4. Send a command

Expected behavior
scrapli.log is populated with write and read output from the session

Stack Trace

2023 x86_64 x86_64 x86_64 GNU/Linux\n'
--- Logging error ---
Traceback (most recent call last):
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/site-packages/scrapli/driver/base/async_driver.py", line 47, in __aenter__
    await self.open()
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/site-packages/scrapli/driver/base/async_driver.py", line 109, in open
    await self.on_open(self)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/site-packages/scrapli/driver/core/juniper_junos/async_driver.py", line 26, in junos_on_open
    await conn.acquire_priv(desired_priv=conn.default_desired_privilege_level)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/site-packages/scrapli/driver/network/async_driver.py", line 165, in acquire_priv
    current_prompt = await self.channel.get_prompt()
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/site-packages/scrapli/decorators.py", line 199, in decorate
    return await asyncio.wait_for(wrapped_func(*args, **kwargs), timeout=timeout)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/asyncio/tasks.py", line 520, in wait_for
    return await fut
           ^^^^^^^^^
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/site-packages/scrapli/channel/async_channel.py", line 455, in get_prompt
    buf += await self.read()
           ^^^^^^^^^^^^^^^^^
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/site-packages/scrapli/channel/async_channel.py", line 77, in read
    self.logger.debug("read: %r", buf)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1918, in debug
    self.log(DEBUG, msg, *args, **kwargs)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1962, in log
    self.logger.log(level, msg, *args, **kwargs)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1609, in log
    self._log(level, msg, args, **kwargs)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1684, in _log
    self.handle(record)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1028, in handle
    self.emit(record)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/site-packages/scrapli/logging.py", line 226, in emit
    self._record_msg_buf = literal_eval(record.msg[self._read_msg_prefix_len :])  # noqa
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/ast.py", line 66, in literal_eval
    node_or_string = parse(node_or_string.lstrip(" \t"), mode='eval')
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/ast.py", line 52, in parse
    return compile(source, filename, mode, flags,
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "<unknown>", line 1
    %r
    ^
SyntaxError: invalid syntax

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1160, in emit
    msg = self.format(record)
          ^^^^^^^^^^^^^^^^^^^
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 999, in format
    return fmt.format(record)
           ^^^^^^^^^^^^^^^^^^
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 703, in format
    record.message = record.getMessage()
                     ^^^^^^^^^^^^^^^^^^^
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 392, in getMessage
    msg = msg % self.args
          ~~~~^~~~~~~~~~~
TypeError: not all arguments converted during string formatting
Call stack:
  File "/home/{USERNAME}/projects/show_command_runner/show_command_runner.py", line 981, in <module>
    asyncio.run( main_multithread(device_data, junos_commands, xr_commands, ios_commands, arris_commands) )
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/asyncio/runners.py", line 194, in run
    return runner.run(main)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/asyncio/base_events.py", line 671, in run_until_complete
    self.run_forever()
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/asyncio/base_events.py", line 638, in run_forever
    self._run_once()
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/asyncio/base_events.py", line 1971, in _run_once
    handle._run()
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/asyncio/events.py", line 84, in _run
    self._context.run(self._callback, *self._args)
  File "/home/{USERNAME}/projects/show_command_runner/show_command_runner.py", line 620, in run_commands
    response = await connect_juniper(device, junos_commands)
  File "/home/{USERNAME}/projects/show_command_runner/show_command_runner.py", line 140, in connect_juniper
    async with AsyncJunosDriver(**device) as conn:
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/site-packages/scrapli/driver/base/async_driver.py", line 49, in __aenter__
    self.logger.critical(
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1953, in critical
    self.log(CRITICAL, msg, *args, **kwargs)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1962, in log
    self.logger.log(level, msg, *args, **kwargs)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1609, in log
    self._log(level, msg, args, **kwargs)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1684, in _log
    self.handle(record)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/logging/__init__.py", line 1028, in handle
    self.emit(record)
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/site-packages/scrapli/logging.py", line 217, in emit
    self.emit_buffered()
  File "/home/{USERNAME}/.pyenv/versions/3.12.1/lib/python3.12/site-packages/scrapli/logging.py", line 194, in emit_buffered
    super().emit(record=self._record_buf)
Message: "read : b''"
Arguments: (b'Last login: Thu Oct  3 19:58:20 2024 from 2600::{IPV6}\n--- JUNOS 21.4R3-S5.9-EVO Linux (none) 4.8.28-WR2.2.1_standard-gea7287e #1 SMP PREEMPT Thu Sep 14 17:58:57 PDT 2023 x86_64 x86_64 x86_64 GNU/Linux\n',)
invalid syntax (<unknown>, line 1)

OS (please complete the following information):

$ uname -a
Linux {{ hostname }} 5.14.0-427.22.1.el9_4.x86_64 #1 SMP PREEMPT_DYNAMIC Wed Jun 19 17:35:04 
$ cat /etc/os-release 
NAME="Rocky Linux"
VERSION="9.4 (Blue Onyx)"

• Main branch currently (most recent non-main tag 2024.07.30

[carlmontanari]

yeah thats not awesome eh? could repro and pushed #350 that fixes. will test a bit more and if you could test that out and let us know if that works that'd be great. will close this and we can follow up over there! thanks a bunch @jfakult

[robwdwd]

The fix in #350 seems to have caused a new related issue.

--- Logging error ---
Traceback (most recent call last):
File "/usr/lib/python3.12/logging/init.py", line 1160, in emit
msg = self.format(record)
^^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/logging/init.py", line 999, in format
return fmt.format(record)
^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/logging/init.py", line 703, in format
record.message = record.getMessage()
^^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/logging/init.py", line 392, in getMessage
msg = msg % self.args
~~~~^~~~~~~~~~~
TypeError: not enough arguments for format string
Call stack:
File "/opt/pipx/bin/filtergenpush", line 8, in
sys.exit(cli())
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/click/core.py", line 1157, in call
return self.main(*args, **kwargs)
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/click/core.py", line 1078, in main
rv = self.invoke(ctx)
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/click/core.py", line 1434, in invoke
return ctx.invoke(self.callback, **ctx.params)
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/click/core.py", line 783, in invoke
return __callback(*args, **kwargs)
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/filtergenpush/cli.py", line 214, in cli
asyncio.run(runner(cfg))
File "/usr/lib/python3.12/asyncio/runners.py", line 194, in run
return runner.run(main)
File "/usr/lib/python3.12/asyncio/runners.py", line 118, in run
return self._loop.run_until_complete(task)
File "/usr/lib/python3.12/asyncio/base_events.py", line 674, in run_until_complete
self.run_forever()
File "/usr/lib/python3.12/asyncio/base_events.py", line 641, in run_forever
self._run_once()
File "/usr/lib/python3.12/asyncio/base_events.py", line 1987, in _run_once
handle._run()
File "/usr/lib/python3.12/asyncio/events.py", line 88, in _run
self._context.run(self._callback, *self._args)
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/filtergenpush/worker.py", line 113, in run
await device.run(self.prog_args)
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/filtergenpush/device/base.py", line 90, in run
await net_connect.send_configs(configs=save_cmds, privilege_level=prog_args["conf_priv_level"][self.platform], timeout_ops=120)
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/scrapli/driver/network/async_driver.py", line 540, in send_configs
responses = await super().send_commands(
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/scrapli/driver/generic/async_driver.py", line 266, in send_commands
response = await self._send_command(
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/scrapli/decorators.py", line 293, in decorate
driver_instance.timeout_ops = base_timeout_ops
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/scrapli/driver/base/base_driver.py", line 943, in timeout_ops
self.logger.debug(f"setting 'timeout_ops' value to '{value}'")
File "/usr/lib/python3.12/logging/init.py", line 1918, in debug
self.log(DEBUG, msg, *args, **kwargs)
File "/usr/lib/python3.12/logging/init.py", line 1962, in log
self.logger.log(level, msg, *args, **kwargs)
File "/usr/lib/python3.12/logging/init.py", line 1609, in log
self._log(level, msg, args, **kwargs)
File "/usr/lib/python3.12/logging/init.py", line 1684, in _log
self.handle(record)
File "/usr/lib/python3.12/logging/init.py", line 1700, in handle
self.callHandlers(record)
File "/usr/lib/python3.12/logging/init.py", line 1762, in callHandlers
hdlr.handle(record)
File "/usr/lib/python3.12/logging/init.py", line 1028, in handle
self.emit(record)
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/scrapli/logging.py", line 215, in emit
self.emit_buffered()
File "/opt/pipx/venvs/filtergenpush/lib/python3.12/site-packages/scrapli/logging.py", line 192, in emit_buffered
super().emit(record=self._record_buf)
Message: "read : b'%r%r'"
Arguments: (b'\n',)

[carlmontanari]

hey @robwdwd -- I did say "hopefully" fix 🤣

do you have a min reproducible example handy by any chance? I can try to take a peak this weekend!