Rally race crushes right after start

lokinehn · September 4, 2023, 11:40am

I want to run a benchmark for my existing 8.9.0 cluster (honestly I've already run tests on that cluster earlier, and everything was great) and i get error right after start.

Command i execute:
esrally race --track=sql --target-hosts=10.64.23.252:9200,10.64.17.157:9200,10.64.25.119:9200 --pipeline=benchmark-only

Error i get:



    ____        ____
   / __ \____ _/ / /_  __
  / /_/ / __ `/ / / / / /
 / _, _/ /_/ / / / /_/ /
/_/ |_|\__,_/_/_/\__, /
                /____/

[INFO] Race id is [db13a37e-0bda-4035-af26-1dab884ecaac]

[ERROR] Cannot race. Traceback (most recent call last):
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/actor.py", line 92, in guard
    return f(self, msg, sender)
           ^^^^^^^^^^^^^^^^^^^^
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/driver/driver.py", line 445, in receiveMsg_WakeupMessage
    self.logger.exception("Worker failed. Notifying parent...", exc_info=e)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1524, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1518, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1634, in _log
    self.handle(record)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1644, in handle
    self.callHandlers(record)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1706, in callHandlers
    hdlr.handle(record)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/thespian/system/logdirector.py", line 129, in handle
    excinfo = traceback.format_exception(record.exc_info[0],
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/traceback.py", line 139, in format_exception
    te = TracebackException(type(value), value, tb, limit=limit, compact=True)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/traceback.py", line 724, in __init__
    cause = TracebackException(
            ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/traceback.py", line 698, in __init__
    self.__notes__ = getattr(exc_value, '__notes__', None)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/tempfile.py", line 477, in __getattr__
    file = self.__dict__['file']
           ~~~~~~~~~~~~~^^^^^^^^
KeyError: 'file'


Getting further help:
*********************
* Check the log files in /home/tsimmerman/.rally/logs for errors.
* Read the documentation at https://esrally.readthedocs.io/en/2.9.0/.
* Ask a question on the forum at https://discuss.elastic.co/tags/c/elastic-stack/elasticsearch/rally.
* Raise an issue at https://github.com/elastic/rally/issues and include the log files in /home/tsimmerman/.rally/logs.

--------------------------------
[INFO] FAILURE (took 27 seconds)
--------------------------------

Log file fillment:

2023-09-04 11:31:10,158 ActorAddr-(T|:43157)/PID:32763 esrally.actor ERROR Main driver received a fatal exception from a load generator. Shutting down.
2023-09-04 11:31:10,160 -not-actor-/PID:32722 esrally.racecontrol ERROR A benchmark failure has occurred
2023-09-04 11:31:10,160 -not-actor-/PID:32722 esrally.racecontrol INFO Telling benchmark actor to exit.
2023-09-04 11:31:10,159 ActorAddr-(T|:42791)/PID:32742 esrally.actor INFO Received a benchmark failure from [ActorAddr-(T|:43157)] and will forward it now.
2023-09-04 11:31:10,159 ActorAddr-(T|:43157)/PID:32763 esrally.metrics INFO Closing metrics store.
2023-09-04 11:31:10,173 ActorAddr-(T|:43157)/PID:32763 esrally.actor INFO Main driver received ActorExitRequest and will terminate all load generators.
2023-09-04 11:31:13,167 -not-actor-/PID:32722 esrally.rally INFO Attempting to shutdown internal actor system.
2023-09-04 11:31:13,168 -not-actor-/PID:32741 root INFO ActorSystem Logging Shutdown
2023-09-04 11:31:13,171 -not-actor-/PID:32722 esrally.rally INFO Actor system is still running. Waiting...
2023-09-04 11:31:13,171 -not-actor-/PID:32740 root INFO ---- Actor System shutdown
2023-09-04 11:31:14,171 -not-actor-/PID:32722 esrally.rally INFO Shutdown completed.
2023-09-04 11:31:14,171 -not-actor-/PID:32722 esrally.rally ERROR Cannot run subcommand [race].
Traceback (most recent call last):
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/rally.py", line 1172, in dispatch_sub_command
    race(cfg, args.kill_running_processes)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/rally.py", line 920, in race
    with_actor_system(racecontrol.run, cfg)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/rally.py", line 950, in with_actor_system
    runnable(cfg)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/racecontrol.py", line 396, in run
    raise e
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/racecontrol.py", line 393, in run
    pipeline(cfg)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/racecontrol.py", line 72, in __call__
    self.target(cfg)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/racecontrol.py", line 332, in benchmark_only
    return race(cfg, external=True)
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/racecontrol.py", line 290, in race
    raise exceptions.RallyError(result.message, result.cause)
esrally.exceptions.RallyError: Traceback (most recent call last):
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/actor.py", line 92, in guard
    return f(self, msg, sender)
           ^^^^^^^^^^^^^^^^^^^^
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/driver/driver.py", line 445, in receiveMsg_WakeupMessage
    self.logger.exception("Worker failed. Notifying parent...", exc_info=e)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1524, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1518, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1634, in _log
    self.handle(record)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1644, in handle
    self.callHandlers(record)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1706, in callHandlers
    hdlr.handle(record)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/thespian/system/logdirector.py", line 129, in handle
    excinfo = traceback.format_exception(record.exc_info[0],
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/traceback.py", line 139, in format_exception
    te = TracebackException(type(value), value, tb, limit=limit, compact=True)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/traceback.py", line 724, in __init__
    cause = TracebackException(
            ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/traceback.py", line 698, in __init__
    self.__notes__ = getattr(exc_value, '__notes__', None)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/tempfile.py", line 477, in __getattr__
    file = self.__dict__['file']
           ~~~~~~~~~~~~~^^^^^^^^
KeyError: 'file'

I already tried to reinstall rally, and that didn't help.
One week before it worked fine, don't know what was happened

Quentin_Pradet · September 4, 2023, 11:49am

Hello! Thanks for your interest in Rally. Can you please share the complete log file (maybe by deleting it and starting a new race)? It would help diagnose the issue.

lokinehn · September 4, 2023, 11:55am

Full log:

2023-09-04 11:51:53,98 -not-actor-/PID:7607 esrally.rally INFO OS [uname_result(system='Linux', node='XXXXXXXXX', release='4.19.0-23-amd64', version='#1 SMP Debian 4.19.269-1 (2022-12-20)', machine='x86_64')]
2023-09-04 11:51:53,98 -not-actor-/PID:7607 esrally.rally INFO Python [namespace(name='cpython', cache_tag='cpython-311', version=sys.version_info(major=3, minor=11, micro=1, releaselevel='final', serial=0), hexversion=51053040, _multiarch='x86_64-linux-gnu')]
2023-09-04 11:51:53,98 -not-actor-/PID:7607 esrally.rally INFO Rally version [2.9.0]
2023-09-04 11:51:53,98 -not-actor-/PID:7607 esrally.utils.net INFO Connecting directly to the Internet (no proxy support) for [all_proxy].
2023-09-04 11:51:53,98 -not-actor-/PID:7607 esrally.utils.net INFO Connecting directly to the Internet (no proxy support) for [all_proxy].
2023-09-04 11:51:53,98 -not-actor-/PID:7607 esrally.rally INFO Cleaning track dependency directory [/home/tsimmerman/.rally/libs]...
2023-09-04 11:51:53,111 -not-actor-/PID:7607 esrally.rally INFO Actor system already running locally? [False]
2023-09-04 11:51:53,111 -not-actor-/PID:7607 esrally.actor INFO Starting actor system with system base [multiprocTCPBase] and capabilities [{'coordinator': True, 'ip': '127.0.0.1', 'Convention Address.IPv4': '127.0.0.1:1900'}].
2023-09-04 11:51:53,162 -not-actor-/PID:7625 root INFO ++++ Actor System gen (3, 10) started, admin @ ActorAddr-(T|:1900)
2023-09-04 11:51:53,186 -not-actor-/PID:7607 esrally.racecontrol INFO Race id is [f0372ccb-5861-4443-97e0-da537060fb11]
2023-09-04 11:51:53,187 -not-actor-/PID:7607 esrally.racecontrol INFO User specified pipeline [benchmark-only].
2023-09-04 11:51:53,187 -not-actor-/PID:7607 esrally.racecontrol INFO Using configured hosts [{'host': '10.64.23.252', 'port': 9200}, {'host': '10.64.17.157', 'port': 9200}, {'host': '10.64.25.119', 'port': 9200}]
2023-09-04 11:51:53,188 ActorAddr-(T|:1900)/PID:7625 esrally.actor DEBUG Capabilities [{'coordinator': True, 'ip': '127.0.0.1', 'Convention Address.IPv4': '127.0.0.1:1900', 'Thespian ActorSystem Name': 'multiprocTCPBase', 'Thespian ActorSystem Version': 2, 'Thespian Watch Supported': True, 'Python Version': (3, 11, 1, 'final', 0), 'Thespian Generation': (3, 10), 'Thespian Version': '1693828313142'}] match requirements [{'coordinator': True}].
2023-09-04 11:51:53,216 ActorAddr-(T|:46873)/PID:7627 esrally.client.factory INFO Creating ES client connected to [{'host': '10.64.23.252', 'port': 9200}, {'host': '10.64.17.157', 'port': 9200}, {'host': '10.64.25.119', 'port': 9200}] with options [{'timeout': 60}]
2023-09-04 11:51:53,346 ActorAddr-(T|:46873)/PID:7627 esrally.racecontrol INFO Automatically derived distribution flavor [default], version [8.9.0], and build hash [8aa461beb06aa0417a231c345a1b8c38fb498a0d]
2023-09-04 11:51:54,702 ActorAddr-(T|:46873)/PID:7627 esrally.utils.repo INFO Checking out [8.7] in [/home/tsimmerman/.rally/benchmarks/tracks/default] for distribution version [8.9.0].
2023-09-04 11:51:54,713 ActorAddr-(T|:46873)/PID:7627 esrally.utils.process INFO Already on '8.7'
Your branch is up to date with 'origin/8.7'.

2023-09-04 11:51:54,714 ActorAddr-(T|:46873)/PID:7627 esrally.utils.repo INFO Rebasing on [8.7] in [/home/tsimmerman/.rally/benchmarks/tracks/default] for distribution version [8.9.0].
2023-09-04 11:51:54,724 ActorAddr-(T|:46873)/PID:7627 esrally.utils.process INFO Already on '8.7'
Your branch is up to date with 'origin/8.7'.

2023-09-04 11:51:54,838 ActorAddr-(T|:34653)/PID:7648 esrally.actor INFO Received signal from race control to start engine.
2023-09-04 11:51:54,841 ActorAddr-(T|:34653)/PID:7648 esrally.actor INFO Cluster will not be provisioned by Rally.
2023-09-04 11:51:54,737 ActorAddr-(T|:46873)/PID:7627 esrally.utils.process INFO Current branch 8.7 is up to date.

2023-09-04 11:51:54,740 ActorAddr-(T|:46873)/PID:7627 esrally.track.loader INFO Reading track specification file [/home/tsimmerman/.rally/benchmarks/tracks/default/sql/track.json].
2023-09-04 11:51:54,789 ActorAddr-(T|:46873)/PID:7627 esrally.track.loader INFO Final rendered track for '/home/tsimmerman/.rally/benchmarks/tracks/default/sql/track.json' has been written to '/tmp/tmpi5i_iryl.json'.
2023-09-04 11:51:54,801 ActorAddr-(T|:46873)/PID:7627 esrally.track.loader INFO Loading template [definition for index weather-data-2016 in index.json].
2023-09-04 11:51:54,809 ActorAddr-(T|:46873)/PID:7627 esrally.metrics INFO Creating in-memory metrics store
2023-09-04 11:51:54,809 ActorAddr-(T|:46873)/PID:7627 esrally.metrics INFO Opening metrics store for race timestamp=[20230904T115153Z], track=[sql], challenge=[sql], car=[['external']]
2023-09-04 11:51:54,809 ActorAddr-(T|:46873)/PID:7627 esrally.metrics INFO Creating file race store
2023-09-04 11:51:54,809 ActorAddr-(T|:46873)/PID:7627 esrally.actor INFO Asking mechanic to start the engine.
2023-09-04 11:51:54,845 ActorAddr-(T|:46873)/PID:7627 esrally.actor INFO Mechanic has started engine successfully.
2023-09-04 11:51:54,847 ActorAddr-(T|:46873)/PID:7627 esrally.actor INFO Telling driver to prepare for benchmarking.
2023-09-04 11:51:54,867 ActorAddr-(T|:40049)/PID:7649 esrally.metrics INFO Creating in-memory metrics store
2023-09-04 11:51:54,875 ActorAddr-(T|:40049)/PID:7649 esrally.metrics INFO Opening metrics store for race timestamp=[20230904T115153Z], track=[sql], challenge=[sql], car=[['external']]
2023-09-04 11:51:54,875 ActorAddr-(T|:40049)/PID:7649 esrally.client.factory INFO Creating ES client connected to [{'host': '10.64.23.252', 'port': 9200}, {'host': '10.64.17.157', 'port': 9200}, {'host': '10.64.25.119', 'port': 9200}] with options [{'timeout': 60, 'retry_on_timeout': True}]
2023-09-04 11:51:54,877 ActorAddr-(T|:40049)/PID:7649 esrally.driver.driver INFO Checking if REST API is available.
2023-09-04 11:51:54,891 ActorAddr-(T|:40049)/PID:7649 esrally.driver.driver INFO REST API is available.
2023-09-04 11:51:54,896 ActorAddr-(T|:40049)/PID:7649 esrally.actor INFO Starting prepare track process on hosts [['localhost']]
2023-09-04 11:51:54,909 ActorAddr-(T|:34885)/PID:7650 esrally.actor INFO Track Preparator started
2023-09-04 11:51:56,27 ActorAddr-(T|:34885)/PID:7650 esrally.utils.repo INFO Checking current revision [437756e38a92989fdb1ba8b6362809d1cddd36ef] is equal to specified revision [437756e38a92989fdb1ba8b6362809d1cddd36ef].
2023-09-04 11:51:56,28 ActorAddr-(T|:34885)/PID:7650 esrally.track.loader INFO Reading track specification file [/home/tsimmerman/.rally/benchmarks/tracks/default/sql/track.json].
2023-09-04 11:51:56,78 ActorAddr-(T|:34885)/PID:7650 esrally.track.loader INFO Final rendered track for '/home/tsimmerman/.rally/benchmarks/tracks/default/sql/track.json' has been written to '/tmp/tmpjax8ezy3.json'.
2023-09-04 11:51:56,86 ActorAddr-(T|:34885)/PID:7650 esrally.track.loader INFO Loading template [definition for index weather-data-2016 in index.json].
2023-09-04 11:51:56,102 ActorAddr-(T|:34885)/PID:7650 esrally.actor INFO Preparing track [sql]
2023-09-04 11:51:56,103 ActorAddr-(T|:34885)/PID:7650 esrally.actor INFO Reloading track [sql] to ensure plugins are up-to-date.
2023-09-04 11:51:58,632 ActorAddr-(T|:34885)/PID:7650 esrally.utils.repo INFO Checking current revision [437756e38a92989fdb1ba8b6362809d1cddd36ef] is equal to specified revision [437756e38a92989fdb1ba8b6362809d1cddd36ef].
2023-09-04 11:51:58,633 ActorAddr-(T|:34885)/PID:7650 esrally.track.loader INFO Reading track specification file [/home/tsimmerman/.rally/benchmarks/tracks/default/sql/track.json].
2023-09-04 11:51:58,678 ActorAddr-(T|:34885)/PID:7650 esrally.track.loader INFO Final rendered track for '/home/tsimmerman/.rally/benchmarks/tracks/default/sql/track.json' has been written to '/tmp/tmppvts8jgp.json'.
2023-09-04 11:51:58,686 ActorAddr-(T|:34885)/PID:7650 esrally.track.loader INFO Loading template [definition for index weather-data-2016 in index.json].
2023-09-04 11:52:00,155 ActorAddr-(T|:34885)/PID:7650 esrally.utils.repo INFO Checking current revision [437756e38a92989fdb1ba8b6362809d1cddd36ef] is equal to specified revision [437756e38a92989fdb1ba8b6362809d1cddd36ef].
2023-09-04 11:52:15,320 ActorAddr-(T|:43129)/PID:7731 esrally.track.loader INFO Resolved data root directory for document corpus [noaa-sql] in track [sql] to [['/home/tsimmerman/.rally/benchmarks/data/noaa-sql']].
2023-09-04 11:52:15,320 ActorAddr-(T|:43129)/PID:7731 esrally.track.loader INFO Downloading data from [https://rally-tracks.elastic.co/noaa-sql/documents.json.bz2] (949 MB) to [/home/tsimmerman/.rally/benchmarks/data/noaa-sql/documents.json.bz2].
2023-09-04 11:52:20,323 ActorAddr-(T|:43129)/PID:7731 esrally.actor ERROR Error in task executor
Traceback (most recent call last):

  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/actor.py", line 92, in guard
    return f(self, msg, sender)
           ^^^^^^^^^^^^^^^^^^^^

  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/driver/driver.py", line 445, in receiveMsg_WakeupMessage
    self.logger.exception("Worker failed. Notifying parent...", exc_info=e)

  File "/usr/local/lib/python3.11/logging/__init__.py", line 1524, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)

  File "/usr/local/lib/python3.11/logging/__init__.py", line 1518, in error
    self._log(ERROR, msg, args, **kwargs)

  File "/usr/local/lib/python3.11/logging/__init__.py", line 1634, in _log
    self.handle(record)

  File "/usr/local/lib/python3.11/logging/__init__.py", line 1644, in handle
    self.callHandlers(record)

  File "/usr/local/lib/python3.11/logging/__init__.py", line 1706, in callHandlers
    hdlr.handle(record)

  File "/home/tsimmerman/.local/lib/python3.11/site-packages/thespian/system/logdirector.py", line 129, in handle
    excinfo = traceback.format_exception(record.exc_info[0],
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

  File "/usr/local/lib/python3.11/traceback.py", line 139, in format_exception
    te = TracebackException(type(value), value, tb, limit=limit, compact=True)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

  File "/usr/local/lib/python3.11/traceback.py", line 724, in __init__
    cause = TracebackException(
            ^^^^^^^^^^^^^^^^^^^

  File "/usr/local/lib/python3.11/traceback.py", line 698, in __init__
    self.__notes__ = getattr(exc_value, '__notes__', None)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

  File "/usr/local/lib/python3.11/tempfile.py", line 477, in __getattr__
    file = self.__dict__['file']
           ~~~~~~~~~~~~~^^^^^^^^

KeyError: 'file'

2023-09-04 11:52:20,331 ActorAddr-(T|:40049)/PID:7649 esrally.actor ERROR Main driver received a fatal exception from a load generator. Shutting down.
2023-09-04 11:52:20,332 ActorAddr-(T|:40049)/PID:7649 esrally.metrics INFO Closing metrics store.
2023-09-04 11:52:20,338 -not-actor-/PID:7607 esrally.racecontrol ERROR A benchmark failure has occurred
2023-09-04 11:52:20,338 -not-actor-/PID:7607 esrally.racecontrol INFO Telling benchmark actor to exit.
2023-09-04 11:52:20,333 ActorAddr-(T|:46873)/PID:7627 esrally.actor INFO Received a benchmark failure from [ActorAddr-(T|:40049)] and will forward it now.
2023-09-04 11:52:20,343 ActorAddr-(T|:40049)/PID:7649 esrally.actor INFO Main driver received ActorExitRequest and will terminate all load generators.
2023-09-04 11:52:23,341 -not-actor-/PID:7607 esrally.rally INFO Attempting to shutdown internal actor system.
2023-09-04 11:52:23,342 -not-actor-/PID:7626 root INFO ActorSystem Logging Shutdown
2023-09-04 11:52:23,344 -not-actor-/PID:7607 esrally.rally INFO Actor system is still running. Waiting...
2023-09-04 11:52:23,344 -not-actor-/PID:7625 root INFO ---- Actor System shutdown
2023-09-04 11:52:24,344 -not-actor-/PID:7607 esrally.rally INFO Shutdown completed.
2023-09-04 11:52:24,344 -not-actor-/PID:7607 esrally.rally ERROR Cannot run subcommand [race].
Traceback (most recent call last):
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/rally.py", line 1172, in dispatch_sub_command
    race(cfg, args.kill_running_processes)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/rally.py", line 920, in race
    with_actor_system(racecontrol.run, cfg)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/rally.py", line 950, in with_actor_system
    runnable(cfg)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/racecontrol.py", line 396, in run
    raise e
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/racecontrol.py", line 393, in run
    pipeline(cfg)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/racecontrol.py", line 72, in __call__
    self.target(cfg)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/racecontrol.py", line 332, in benchmark_only
    return race(cfg, external=True)
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/racecontrol.py", line 290, in race
    raise exceptions.RallyError(result.message, result.cause)
esrally.exceptions.RallyError: Traceback (most recent call last):
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/actor.py", line 92, in guard
    return f(self, msg, sender)
           ^^^^^^^^^^^^^^^^^^^^
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/esrally/driver/driver.py", line 445, in receiveMsg_WakeupMessage
    self.logger.exception("Worker failed. Notifying parent...", exc_info=e)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1524, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1518, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1634, in _log
    self.handle(record)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1644, in handle
    self.callHandlers(record)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1706, in callHandlers
    hdlr.handle(record)
  File "/home/tsimmerman/.local/lib/python3.11/site-packages/thespian/system/logdirector.py", line 129, in handle
    excinfo = traceback.format_exception(record.exc_info[0],
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/traceback.py", line 139, in format_exception
    te = TracebackException(type(value), value, tb, limit=limit, compact=True)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/traceback.py", line 724, in __init__
    cause = TracebackException(
            ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/traceback.py", line 698, in __init__
    self.__notes__ = getattr(exc_value, '__notes__', None)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/tempfile.py", line 477, in __getattr__
    file = self.__dict__['file']
           ~~~~~~~~~~~~~^^^^^^^^
KeyError: 'file'

lokinehn · September 5, 2023, 12:52pm

Has anyone ever faced with that type of errors?

Quentin_Pradet · September 6, 2023, 7:12am

Hello,

We are actually quite baffled by this and have never seen this in the past. The problem is the error we're logging is not the actual error. It says that we're failing to log, apparently because the temporary file we wanted to create was not created.

Can you please try those two things?

Check how much space is left on your sytem. It could be that Rally is trying to open a file but cannot because of a lack of space.
Add self.logger.info(repr(e)) just before line 445 in /home/tsimmerman/.local/lib/python3.11/site-packages/esrally/driver/driver.py, inside the receiveMsg_WakeupMessage function.

Also, what is the exact Rally invocation?

Thank you!

lokinehn · September 6, 2023, 8:36am

Do you mean exact rally command i try to execute?
In the first post. Rally version - 2.9.0, Python version - 3.11.1

Host has enough space, inodes are also in abundance.
I tried it. Nothing has changed, Error is the same

Also i tried to reinstall rally with superuser access, and start rally race by root user. Nothing has changed.

Quentin_Pradet · September 6, 2023, 10:09am

Sorry for not being clear: regarding the second thing to try, the ask is to run Rally again and send the full log again: this will add a new log entry to help us diagnose the issue.

And yes, I would be interested to have the full Rally invocation you used (esrally race ...), to see if we can reproduce.

lokinehn · September 6, 2023, 11:32am

The command I execute:

esrally race --track=sql --target-hosts=10.64.23.252:9200,10.64.17.157:9200,10.64.25.119:9200 --pipeline=benchmark-only

The log i get after adding self.logger.info(repr(e)) into driver.py:

2023-09-06 11:30:39,762 -not-actor-/PID:27900 esrally.rally INFO OS [uname_result(system='Linux', node='XXXXXX', release='4.19.0-23-amd64', version='#1 SMP Debian 4.19.269-1 (2022-12-20)', machine='x86_64')]
2023-09-06 11:30:39,762 -not-actor-/PID:27900 esrally.rally INFO Python [namespace(name='cpython', cache_tag='cpython-311', version=sys.version_info(major=3, minor=11, micro=1, releaselevel='final', serial=0), hexversion=51053040, _multiarch='x86_64-linux-gnu')]
2023-09-06 11:30:39,762 -not-actor-/PID:27900 esrally.rally INFO Rally version [2.9.0]
2023-09-06 11:30:39,762 -not-actor-/PID:27900 esrally.utils.net INFO Connecting directly to the Internet (no proxy support) for [all_proxy].
2023-09-06 11:30:39,762 -not-actor-/PID:27900 esrally.utils.net INFO Connecting directly to the Internet (no proxy support) for [all_proxy].
2023-09-06 11:30:39,762 -not-actor-/PID:27900 esrally.rally INFO Cleaning track dependency directory [/root/.rally/libs]...
2023-09-06 11:30:39,777 -not-actor-/PID:27900 esrally.rally INFO Actor system already running locally? [False]
2023-09-06 11:30:39,778 -not-actor-/PID:27900 esrally.actor INFO Starting actor system with system base [multiprocTCPBase] and capabilities [{'coordinator': True, 'ip': '127.0.0.1', 'Convention Address.IPv4': '127.0.0.1:1900'}].
2023-09-06 11:30:39,839 -not-actor-/PID:27909 root INFO ++++ Actor System gen (3, 10) started, admin @ ActorAddr-(T|:1900)
2023-09-06 11:30:39,862 -not-actor-/PID:27900 esrally.racecontrol INFO Race id is [89f0d07f-9ceb-4e24-a085-681a8715753b]
2023-09-06 11:30:39,862 -not-actor-/PID:27900 esrally.racecontrol INFO User specified pipeline [benchmark-only].
2023-09-06 11:30:39,863 -not-actor-/PID:27900 esrally.racecontrol INFO Using configured hosts [{'host': '10.64.23.252', 'port': 9200}, {'host': '10.64.17.157', 'port': 9200}, {'host': '10.64.25.119', 'port': 9200}]
2023-09-06 11:30:39,864 ActorAddr-(T|:1900)/PID:27909 esrally.actor DEBUG Capabilities [{'coordinator': True, 'ip': '127.0.0.1', 'Convention Address.IPv4': '127.0.0.1:1900', 'Thespian ActorSystem Name': 'multiprocTCPBase', 'Thespian ActorSystem Version': 2, 'Thespian Watch Supported': True, 'Python Version': (3, 11, 1, 'final', 0), 'Thespian Generation': (3, 10), 'Thespian Version': '1693999839826'}] match requirements [{'coordinator': True}].
2023-09-06 11:30:39,884 ActorAddr-(T|:35541)/PID:27911 esrally.client.factory INFO Creating ES client connected to [{'host': '10.64.23.252', 'port': 9200}, {'host': '10.64.17.157', 'port': 9200}, {'host': '10.64.25.119', 'port': 9200}] with options [{'timeout': 60}]
2023-09-06 11:30:40,9 ActorAddr-(T|:35541)/PID:27911 esrally.racecontrol INFO Automatically derived distribution flavor [default], version [8.9.0], and build hash [8aa461beb06aa0417a231c345a1b8c38fb498a0d]
2023-09-06 11:30:41,725 ActorAddr-(T|:35541)/PID:27911 esrally.utils.repo INFO Checking out [8.7] in [/root/.rally/benchmarks/tracks/default] for distribution version [8.9.0].
2023-09-06 11:30:41,735 ActorAddr-(T|:35541)/PID:27911 esrally.utils.process INFO Already on '8.7'
Your branch is up to date with 'origin/8.7'.

2023-09-06 11:30:41,735 ActorAddr-(T|:35541)/PID:27911 esrally.utils.repo INFO Rebasing on [8.7] in [/root/.rally/benchmarks/tracks/default] for distribution version [8.9.0].
2023-09-06 11:30:41,748 ActorAddr-(T|:35541)/PID:27911 esrally.utils.process INFO Already on '8.7'
Your branch is up to date with 'origin/8.7'.

2023-09-06 11:30:41,757 ActorAddr-(T|:35541)/PID:27911 esrally.utils.process INFO Current branch 8.7 is up to date.

2023-09-06 11:30:41,891 ActorAddr-(T|:37659)/PID:27940 esrally.actor INFO Received signal from race control to start engine.
2023-09-06 11:30:41,892 ActorAddr-(T|:37659)/PID:27940 esrally.actor INFO Cluster will not be provisioned by Rally.
2023-09-06 11:30:41,764 ActorAddr-(T|:35541)/PID:27911 esrally.track.loader INFO Reading track specification file [/root/.rally/benchmarks/tracks/default/sql/track.json].
2023-09-06 11:30:41,827 ActorAddr-(T|:35541)/PID:27911 esrally.track.loader INFO Final rendered track for '/root/.rally/benchmarks/tracks/default/sql/track.json' has been written to '/tmp/tmptxcilezr.json'.
2023-09-06 11:30:41,836 ActorAddr-(T|:35541)/PID:27911 esrally.track.loader INFO Loading template [definition for index weather-data-2016 in index.json].
2023-09-06 11:30:41,854 ActorAddr-(T|:35541)/PID:27911 esrally.metrics INFO Creating in-memory metrics store
2023-09-06 11:30:41,854 ActorAddr-(T|:35541)/PID:27911 esrally.metrics INFO Opening metrics store for race timestamp=[20230906T113039Z], track=[sql], challenge=[sql], car=[['external']]
2023-09-06 11:30:41,855 ActorAddr-(T|:35541)/PID:27911 esrally.metrics INFO Creating file race store
2023-09-06 11:30:41,855 ActorAddr-(T|:35541)/PID:27911 esrally.actor INFO Asking mechanic to start the engine.
2023-09-06 11:30:41,893 ActorAddr-(T|:35541)/PID:27911 esrally.actor INFO Mechanic has started engine successfully.
2023-09-06 11:30:41,906 ActorAddr-(T|:35541)/PID:27911 esrally.actor INFO Telling driver to prepare for benchmarking.
2023-09-06 11:30:41,939 ActorAddr-(T|:33447)/PID:27942 esrally.metrics INFO Creating in-memory metrics store
2023-09-06 11:30:41,953 ActorAddr-(T|:33447)/PID:27942 esrally.metrics INFO Opening metrics store for race timestamp=[20230906T113039Z], track=[sql], challenge=[sql], car=[['external']]
2023-09-06 11:30:41,953 ActorAddr-(T|:33447)/PID:27942 esrally.client.factory INFO Creating ES client connected to [{'host': '10.64.23.252', 'port': 9200}, {'host': '10.64.17.157', 'port': 9200}, {'host': '10.64.25.119', 'port': 9200}] with options [{'timeout': 60, 'retry_on_timeout': True}]
2023-09-06 11:30:41,955 ActorAddr-(T|:33447)/PID:27942 esrally.driver.driver INFO Checking if REST API is available.
2023-09-06 11:30:41,967 ActorAddr-(T|:33447)/PID:27942 esrally.driver.driver INFO REST API is available.
2023-09-06 11:30:41,972 ActorAddr-(T|:33447)/PID:27942 esrally.actor INFO Starting prepare track process on hosts [['localhost']]
2023-09-06 11:30:41,994 ActorAddr-(T|:39631)/PID:27943 esrally.actor INFO Track Preparator started
2023-09-06 11:30:42,758 ActorAddr-(T|:39631)/PID:27943 esrally.utils.repo INFO Checking current revision [437756e38a92989fdb1ba8b6362809d1cddd36ef] is equal to specified revision [437756e38a92989fdb1ba8b6362809d1cddd36ef].
2023-09-06 11:30:42,758 ActorAddr-(T|:39631)/PID:27943 esrally.track.loader INFO Reading track specification file [/root/.rally/benchmarks/tracks/default/sql/track.json].
2023-09-06 11:30:42,814 ActorAddr-(T|:39631)/PID:27943 esrally.track.loader INFO Final rendered track for '/root/.rally/benchmarks/tracks/default/sql/track.json' has been written to '/tmp/tmp6d7cnq6j.json'.
2023-09-06 11:30:42,824 ActorAddr-(T|:39631)/PID:27943 esrally.track.loader INFO Loading template [definition for index weather-data-2016 in index.json].
2023-09-06 11:30:42,836 ActorAddr-(T|:39631)/PID:27943 esrally.actor INFO Preparing track [sql]
2023-09-06 11:30:42,836 ActorAddr-(T|:39631)/PID:27943 esrally.actor INFO Reloading track [sql] to ensure plugins are up-to-date.
2023-09-06 11:30:43,306 ActorAddr-(T|:39631)/PID:27943 esrally.utils.repo INFO Checking current revision [437756e38a92989fdb1ba8b6362809d1cddd36ef] is equal to specified revision [437756e38a92989fdb1ba8b6362809d1cddd36ef].
2023-09-06 11:30:43,306 ActorAddr-(T|:39631)/PID:27943 esrally.track.loader INFO Reading track specification file [/root/.rally/benchmarks/tracks/default/sql/track.json].
2023-09-06 11:30:43,330 ActorAddr-(T|:39631)/PID:27943 esrally.track.loader INFO Final rendered track for '/root/.rally/benchmarks/tracks/default/sql/track.json' has been written to '/tmp/tmp4jd5vg17.json'.
2023-09-06 11:30:43,336 ActorAddr-(T|:39631)/PID:27943 esrally.track.loader INFO Loading template [definition for index weather-data-2016 in index.json].
2023-09-06 11:30:43,792 ActorAddr-(T|:39631)/PID:27943 esrally.utils.repo INFO Checking current revision [437756e38a92989fdb1ba8b6362809d1cddd36ef] is equal to specified revision [437756e38a92989fdb1ba8b6362809d1cddd36ef].
2023-09-06 11:30:58,845 ActorAddr-(T|:40179)/PID:27978 esrally.track.loader INFO Resolved data root directory for document corpus [noaa-sql] in track [sql] to [['/root/.rally/benchmarks/data/noaa-sql']].
2023-09-06 11:30:58,846 ActorAddr-(T|:40179)/PID:27978 esrally.track.loader INFO Downloading data from [https://rally-tracks.elastic.co/noaa-sql/documents.json.bz2] (949 MB) to [/root/.rally/benchmarks/data/noaa-sql/documents.json.bz2].
2023-09-06 11:31:03,849 ActorAddr-(T|:40179)/PID:27978 esrally.driver.driver INFO DataError('Could not download [https://rally-tracks.elastic.co/noaa-sql/documents.json.bz2] to [/root/.rally/benchmarks/data/noaa-sql/documents.json.bz2] (HTTP status: 403)')
2023-09-06 11:31:03,860 ActorAddr-(T|:33447)/PID:27942 esrally.actor ERROR Main driver received a fatal exception from a load generator. Shutting down.
2023-09-06 11:31:03,866 -not-actor-/PID:27900 esrally.racecontrol ERROR A benchmark failure has occurred
2023-09-06 11:31:03,867 -not-actor-/PID:27900 esrally.racecontrol INFO Telling benchmark actor to exit.
2023-09-06 11:31:03,865 ActorAddr-(T|:35541)/PID:27911 esrally.actor INFO Received a benchmark failure from [ActorAddr-(T|:33447)] and will forward it now.
2023-09-06 11:31:03,860 ActorAddr-(T|:33447)/PID:27942 esrally.metrics INFO Closing metrics store.
2023-09-06 11:31:03,878 ActorAddr-(T|:33447)/PID:27942 esrally.actor INFO Main driver received ActorExitRequest and will terminate all load generators.
2023-09-06 11:31:03,851 ActorAddr-(T|:40179)/PID:27978 esrally.actor ERROR Error in task executor
Traceback (most recent call last):

  File "/usr/local/lib/python3.11/site-packages/esrally/actor.py", line 92, in guard
    return f(self, msg, sender)
           ^^^^^^^^^^^^^^^^^^^^

  File "/usr/local/lib/python3.11/site-packages/esrally/driver/driver.py", line 446, in receiveMsg_WakeupMessage
    self.logger.exception("Worker failed. Notifying parent...", exc_info=e)

  File "/usr/local/lib/python3.11/logging/__init__.py", line 1524, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)

  File "/usr/local/lib/python3.11/logging/__init__.py", line 1518, in error
    self._log(ERROR, msg, args, **kwargs)

  File "/usr/local/lib/python3.11/logging/__init__.py", line 1634, in _log
    self.handle(record)

  File "/usr/local/lib/python3.11/logging/__init__.py", line 1644, in handle
    self.callHandlers(record)

  File "/usr/local/lib/python3.11/logging/__init__.py", line 1706, in callHandlers
    hdlr.handle(record)

  File "/usr/local/lib/python3.11/site-packages/thespian/system/logdirector.py", line 129, in handle
    excinfo = traceback.format_exception(record.exc_info[0],
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

  File "/usr/local/lib/python3.11/traceback.py", line 139, in format_exception
    te = TracebackException(type(value), value, tb, limit=limit, compact=True)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

  File "/usr/local/lib/python3.11/traceback.py", line 724, in __init__
    cause = TracebackException(
            ^^^^^^^^^^^^^^^^^^^

  File "/usr/local/lib/python3.11/traceback.py", line 698, in __init__
    self.__notes__ = getattr(exc_value, '__notes__', None)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

  File "/usr/local/lib/python3.11/tempfile.py", line 477, in __getattr__
    file = self.__dict__['file']
           ~~~~~~~~~~~~~^^^^^^^^

KeyError: 'file'

2023-09-06 11:31:06,869 -not-actor-/PID:27900 esrally.rally INFO Attempting to shutdown internal actor system.
2023-09-06 11:31:06,870 -not-actor-/PID:27910 root INFO ActorSystem Logging Shutdown
2023-09-06 11:31:06,872 -not-actor-/PID:27909 root INFO ---- Actor System shutdown
2023-09-06 11:31:06,872 -not-actor-/PID:27900 esrally.rally INFO Actor system is still running. Waiting...
2023-09-06 11:31:07,873 -not-actor-/PID:27900 esrally.rally INFO Shutdown completed.
2023-09-06 11:31:07,873 -not-actor-/PID:27900 esrally.rally ERROR Cannot run subcommand [race].
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/esrally/rally.py", line 1172, in dispatch_sub_command
    race(cfg, args.kill_running_processes)
  File "/usr/local/lib/python3.11/site-packages/esrally/rally.py", line 920, in race
    with_actor_system(racecontrol.run, cfg)
  File "/usr/local/lib/python3.11/site-packages/esrally/rally.py", line 950, in with_actor_system
    runnable(cfg)
  File "/usr/local/lib/python3.11/site-packages/esrally/racecontrol.py", line 396, in run
    raise e
  File "/usr/local/lib/python3.11/site-packages/esrally/racecontrol.py", line 393, in run
    pipeline(cfg)
  File "/usr/local/lib/python3.11/site-packages/esrally/racecontrol.py", line 72, in __call__
    self.target(cfg)
  File "/usr/local/lib/python3.11/site-packages/esrally/racecontrol.py", line 332, in benchmark_only
    return race(cfg, external=True)
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/esrally/racecontrol.py", line 290, in race
    raise exceptions.RallyError(result.message, result.cause)
esrally.exceptions.RallyError: Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/esrally/actor.py", line 92, in guard
    return f(self, msg, sender)
           ^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/esrally/driver/driver.py", line 446, in receiveMsg_WakeupMessage
    self.logger.exception("Worker failed. Notifying parent...", exc_info=e)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1524, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1518, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1634, in _log
    self.handle(record)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1644, in handle
    self.callHandlers(record)
  File "/usr/local/lib/python3.11/logging/__init__.py", line 1706, in callHandlers
    hdlr.handle(record)
  File "/usr/local/lib/python3.11/site-packages/thespian/system/logdirector.py", line 129, in handle
    excinfo = traceback.format_exception(record.exc_info[0],
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/traceback.py", line 139, in format_exception
    te = TracebackException(type(value), value, tb, limit=limit, compact=True)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/traceback.py", line 724, in __init__
    cause = TracebackException(
            ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/traceback.py", line 698, in __init__
    self.__notes__ = getattr(exc_value, '__notes__', None)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/tempfile.py", line 477, in __getattr__
    file = self.__dict__['file']
           ~~~~~~~~~~~~~^^^^^^^^
KeyError: 'file'

Thank you for help, btw

gareth-ellis · September 6, 2023, 12:07pm

Hello,

The issue seems to be you're getting a 403 when downloading the track data.
This line below shows this:

2023-09-06 11:31:03,849 ActorAddr-(T|:40179)/PID:27978 esrally.driver.driver INFO DataError('Could not download [https://rally-tracks.elastic.co/noaa-sql/documents.json.bz2] to [/root/.rally/benchmarks/data/noaa-sql/documents.json.bz2] (HTTP status: 403)')

The data should be publicly available, so I am a little unsure why you are being presented a 403.

Could you run the following commands and supply the output?

curl -I https://rally-tracks.elastic.co/noaa-sql/documents.json.bz2

and

python -c 'import urllib3; import certifi; http = urllib3.PoolManager(ca_certs=certifi.where()); r = http.request("HEAD", "https://rally-tracks.elastic.co/noaa-sql/documents.json.bz2"); print(r.status); print(r.headers)'

Thanks!

lokinehn · September 6, 2023, 2:25pm

gareth-ellis, thanks a lot for your respond, I've discovered the problem.
Topic may be closed

Thanks to all

Quentin_Pradet · September 6, 2023, 4:32pm

Glad that fixed it! Would you mind sharing what the issue was in broad terms? So that we can help users faster in the future. Thanks, but no worries if you can't.

system · October 4, 2023, 4:32pm

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.