Cannot race. too many values to unpack (expected 2) error while benchmarking

amitsa · March 7, 2023, 5:17pm

/ /_/ / __ `/ / / / / /
[pod/benchmark-rb8nf/benchmark]  / _, _/ /_/ / / / /_/ /
[pod/benchmark-rb8nf/benchmark] /_/ |_|\__,_/_/_/\__, /
[pod/benchmark-rb8nf/benchmark]                 /____/
[pod/benchmark-rb8nf/benchmark]
[pod/benchmark-rb8nf/benchmark] [ERROR] Cannot race. too many values to unpack (expected 2).
[pod/benchmark-rb8nf/benchmark]
[pod/benchmark-rb8nf/benchmark] ^[[1mGetting further help:^[[0m
[pod/benchmark-rb8nf/benchmark] *********************
[pod/benchmark-rb8nf/benchmark] * Check the log files in /rally/.rally/logs for errors.
[pod/benchmark-rb8nf/benchmark] * Read the documentation at ^[[4mhttps://esrally.readthedocs.io/en/2.7.0/^[[0m.
[pod/benchmark-rb8nf/benchmark] * Ask a question on the forum at ^[[4mhttps://discuss.elastic.co/tags/c/elastic-stack/elasticsearch/rally^[[0m.
[pod/benchmark-rb8nf/benchmark] * Raise an issue at ^[[4mhttps://github.com/elastic/rally/issues^[[0m and include the log files in /rally/.rally/logs.

I am passing track params as

--track-params='{
   "ingest_percentage":"${ES_INGEST_PERCENTAGE}",
   "bulk_size":"${ES_BULKSIZE}",
   "bulk_indexing_clients":"${ES_BULK_INDEXING_CLIENT}",
   "index_settings":{
      "index.codec":"${ES_CODEC}",
      "index.number_of_shards":"${ES_NO_OF_SHARDS}",
      "index.number_of_replicas":"${ES_NO_OF_REPLICAS}",
      "index.translog.flush_threshold_size":"${ES_TRANSLOG_FLUSH}",
      "index.merge.scheduler.max_merge_count":"${ES_MAX_MERGE_COUNT}",
      "index.refresh_interval":"${ES_REFRESH_INTERVAL}"
   }
}'

kindly help

Quentin_Pradet · March 8, 2023, 6:32am

Hello, can you please share the log written to ~/.rally/logs/rally.log, and specifically the lines around "too many values to unpack"? It's a Python error, and the traceback will tell us in which part of the code this happened.

amitsa · March 9, 2023, 1:44am

Hi @Quentin_Pradet

Please find rally log below.

2023-03-09 01:19:35,117 -not-actor-/PID:10 esrally.rally INFO OS [uname_result(system='Linux', node='benchmark-kg6mg', release='5.15.0-67-generic', version='#74-Ubuntu SMP Wed Feb 22 14:14:39 UTC 2023', machine='x86_64', processor='')]
2023-03-09 01:19:35,117 -not-actor-/PID:10 esrally.rally INFO Python [namespace(_multiarch='x86_64-linux-gnu', cache_tag='cpython-38', hexversion=50859504, name='cpython', version=sys.version_info(major=3, minor=8, micro=13, releaselevel='final', serial=0))]
2023-03-09 01:19:35,117 -not-actor-/PID:10 esrally.rally INFO Rally version [2.7.0]
2023-03-09 01:19:35,117 -not-actor-/PID:10 esrally.utils.net INFO Connecting directly to the Internet (no proxy support) for [all_proxy].
2023-03-09 01:19:35,117 -not-actor-/PID:10 esrally.utils.net INFO Connecting directly to the Internet (no proxy support) for [all_proxy].
2023-03-09 01:19:35,117 -not-actor-/PID:10 root INFO Cleaning track dependency directory [/rally/.rally/libs]...
2023-03-09 01:19:35,117 -not-actor-/PID:10 esrally.rally ERROR A fatal error occurred while running subcommand [race].
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/esrally/utils/opts.py", line 110, in to_dict
    return json.loads(arg)
  File "/usr/local/lib/python3.8/json/__init__.py", line 357, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.8/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/lib/python3.8/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 146 (char 145)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/esrally/rally.py", line 1093, in dispatch_sub_command
    configure_track_params(arg_parser, args, cfg)
  File "/usr/local/lib/python3.8/site-packages/esrally/rally.py", line 972, in configure_track_params
    cfg.add(config.Scope.applicationOverride, "track", "params", opts.to_dict(args.track_params))
  File "/usr/local/lib/python3.8/site-packages/esrally/utils/opts.py", line 112, in to_dict
    return default_parser(csv_to_list(arg))
  File "/usr/local/lib/python3.8/site-packages/esrally/utils/opts.py", line 99, in kv_to_map
    k, v = kv.split(":")
ValueError: too many values to unpack (expected 2)

I am running geopoint track

esrally race --offline --track-params='{"ingest_percentage":'${ES_INGEST_PERCENTAGE}',"bulk_size":'${ES_BULKSIZE}',"bulk_indexing_clients":'${ES_BULK_INDEXING_CLIENT}',"index_settings":{"index":{"codec":'${ES_CODEC}',"number_of_shards":'${ES_NO_OF_SHARDS}',"number_of_replicas":'${ES_NO_OF_REPLICAS}',"translog.flush_threshold_size":'${ES_TRANSLOG_FLUSH}',"merge.scheduler.max_merge_count":'${ES_MAX_MERGE_COUNT}',"refresh_interval":'${ES_REFRESH_INTERVAL}'}}}' --track-path=/rally/.rally/benchmarks/tracks/default/${ES_RALLY_RACE} --pipeline=benchmark-only --target-hosts=${ELASTIC_EP} ${ES_TESTMODE} --challenge=${ES_CHALLENGE} --client-options ${CLIENT_OPTIONS} --report-format=csv

Quentin_Pradet · March 9, 2023, 7:33am

The error is that Rally cannot parse your --track-params option as JSON.

Did you send this as a single line in your actual tests? That's OK, it's just that the Python JSON parser complains about column 146 on line 1, but I don't know where that is. Maybe you have quotes in ES_BULK_INDEXING_CLIENT or ES_CODEC?

amitsa · March 10, 2023, 7:40am

Hi @Quentin_Pradet

The problem is with ES_CODEC ....I am sending it to elastic cluster as
--track-params= {index_settings:{"index.codec": LZ4}}

with this approach it giving unpack error

or
--track-params= {index_settings:{"index.codec": "LZ4"}}
with above approach it gets stuck at check cluster health and in rally logs i see new connection error . Below i have shared

rally logs

2023-03-10 06:27:08,442 -not-actor-/PID:10 esrally.rally INFO OS [uname_result(system='Linux', node='benchmark-psbwg', release='5.15.0-67-generic', version='#74-Ubuntu SMP Wed Feb 22 14:14:39 UTC 2023', machine='x86_64', processor='')]
2023-03-10 06:27:08,442 -not-actor-/PID:10 esrally.rally INFO Python [namespace(_multiarch='x86_64-linux-gnu', cache_tag='cpython-38', hexversion=50859504, name='cpython', version=sys.version_info(major=3, minor=8, micro=13, releaselevel='final', serial=0))]
2023-03-10 06:27:08,442 -not-actor-/PID:10 esrally.rally INFO Rally version [2.7.0]
2023-03-10 06:27:08,442 -not-actor-/PID:10 esrally.utils.net INFO Connecting directly to the Internet (no proxy support) for [all_proxy].
2023-03-10 06:27:08,442 -not-actor-/PID:10 esrally.utils.net INFO Connecting directly to the Internet (no proxy support) for [all_proxy].
2023-03-10 06:27:08,442 -not-actor-/PID:10 root INFO Cleaning track dependency directory [/rally/.rally/libs]...
2023-03-10 06:27:08,443 -not-actor-/PID:10 esrally.rally INFO Actor system already running locally? [False]
2023-03-10 06:27:08,444 -not-actor-/PID:10 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-03-10 06:27:08,455 -not-actor-/PID:24 root INFO ++++ Actor System gen (3, 10) started, admin @ ActorAddr-(T|:1900)
2023-03-10 06:27:08,461 -not-actor-/PID:10 esrally.racecontrol INFO Race id is [ac7d1e5e-59ee-4b94-9e1f-9ad49967e433]
2023-03-10 06:27:08,461 -not-actor-/PID:10 esrally.racecontrol INFO User specified pipeline [benchmark-only].
2023-03-10 06:27:08,461 -not-actor-/PID:10 esrally.racecontrol INFO Using configured hosts [{'host': 'es-master', 'port': 9200, 'use_ssl': True}]
2023-03-10 06:27:08,461 -not-actor-/PID:10 esrally.actor INFO Joining already running actor system with system base [multiprocTCPBase].
2023-03-10 06:27:08,462 ActorAddr-(T|:1900)/PID:24 esrally.actor INFO 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, 8, 13, 'final', 0), 'Thespian Generation': (3, 10), 'Thespian Version': '1678429628449'}] match requirements [{'coordinator': True}].
2023-03-10 06:27:08,474 -not-actor-/PID:26 elasticsearch WARNING GET https://es-master:9200/ [status:N/A request:0.003s]
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 174, in _new_conn
    conn = connection.create_connection(
  File "/usr/local/lib/python3.8/site-packages/urllib3/util/connection.py", line 95, in create_connection
    raise err
  File "/usr/local/lib/python3.8/site-packages/urllib3/util/connection.py", line 85, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/elasticsearch/connection/http_urllib3.py", line 251, in perform_request
    response = self.pool.urlopen(
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 785, in urlopen
    retries = retries.increment(
  File "/usr/local/lib/python3.8/site-packages/urllib3/util/retry.py", line 525, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/lib/python3.8/site-packages/urllib3/packages/six.py", line 770, in reraise
    raise value
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 703, in urlopen
    httplib_response = self._make_request(
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 386, in _make_request
    self._validate_conn(conn)
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 1040, in _validate_conn
    conn.connect()
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 358, in connect
    self.sock = conn = self._new_conn()
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 186, in _new_conn
    raise NewConnectionError(
urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPSConnection object at 0x7fe41ed586d0>: Failed to establish a new connection: [Errno 111] Connection refused
2023-03-10 06:27:11,481 -not-actor-/PID:26 elasticsearch WARNING GET https://es-master:9200/ [status:N/A request:0.002s]
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 174, in _new_conn
    conn = connection.create_connection(
  File "/usr/local/lib/python3.8/site-packages/urllib3/util/connection.py", line 95, in create_connection
    raise err
  File "/usr/local/lib/python3.8/site-packages/urllib3/util/connection.py", line 85, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/elasticsearch/connection/http_urllib3.py", line 251, in perform_request
    response = self.pool.urlopen(
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 785, in urlopen
    retries = retries.increment(
  File "/usr/local/lib/python3.8/site-packages/urllib3/util/retry.py", line 525, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/lib/python3.8/site-packages/urllib3/packages/six.py", line 770, in reraise
    raise value
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 703, in urlopen
    httplib_response = self._make_request(
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 386, in _make_request
    self._validate_conn(conn)
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 1040, in _validate_conn
    conn.connect()
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 358, in connect
    self.sock = conn = self._new_conn()
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 186, in _new_conn
    raise NewConnectionError(
urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPSConnection object at 0x7fe41ed587c0>: Failed to establish a new connection: [Errno 111] Connection refused
2023-03-10 06:27:14,486 -not-actor-/PID:26 elasticsearch WARNING GET https://es-master:9200/ [status:N/A request:0.002s]
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 174, in _new_conn
    conn = connection.create_connection(
  File "/usr/local/lib/python3.8/site-packages/urllib3/util/connection.py", line 95, in create_connection
    raise err
  File "/usr/local/lib/python3.8/site-packages/urllib3/util/connection.py", line 85, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/elasticsearch/connection/http_urllib3.py", line 251, in perform_request
    response = self.pool.urlopen(
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 785, in urlopen
    retries = retries.increment(
  File "/usr/local/lib/python3.8/site-packages/urllib3/util/retry.py", line 525, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/lib/python3.8/site-packages/urllib3/packages/six.py", line 770, in reraise
    raise value
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 703, in urlopen
    httplib_response = self._make_request(
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 386, in _make_request
    self._validate_conn(conn)
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 1040, in _validate_conn
    conn.connect()
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 358, in connect
    self.sock = conn = self._new_conn()
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 186, in _new_conn
    raise NewConnectionError(
urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPSConnection object at 0x7fe41ed58a00>: Failed to establish a new connection: [Errno 111] Connection refused
2023-03-10 06:27:17,492 -not-actor-/PID:26 elasticsearch WARNING GET https://es-master:9200/ [status:N/A request:0.002s]
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 174, in _new_conn
    conn = connection.create_connection(
  File "/usr/local/lib/python3.8/site-packages/urllib3/util/connection.py", line 95, in create_connection
    raise err
  File "/usr/local/lib/python3.8/site-packages/urllib3/util/connection.py", line 85, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/elasticsearch/connection/http_urllib3.py", line 251, in perform_request
    response = self.pool.urlopen(
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 785, in urlopen
    retries = retries.increment(
  File "/usr/local/lib/python3.8/site-packages/urllib3/util/retry.py", line 525, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/lib/python3.8/site-packages/urllib3/packages/six.py", line 770, in reraise
    raise value
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 703, in urlopen
    httplib_response = self._make_request(
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 386, in _make_request
    self._validate_conn(conn)
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 1040, in _validate_conn
    conn.connect()
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 358, in connect
    self.sock = conn = self._new_conn()
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 186, in _new_conn
    raise NewConnectionError(
urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPSConnection object at 0x7fe41ed58bb0>: Failed to establish a new connection: [Errno 111] Connection refused
2023-03-10 06:27:08,467 ActorAddr-(T|:32993)/PID:26 esrally.client.factory INFO Creating ES client connected to [{'host': 'es-master', 'port': 9200, 'use_ssl': True}] with options [{'timeout': 240, 'basic_auth_user': 'rally', 'basic_auth_password': '*****', 'use_ssl': True, 'verify_certs': False, 'ca_certs': '/rally/cacert.pem'}]
2023-03-10 06:27:08,468 ActorAddr-(T|:32993)/PID:26 esrally.client.factory INFO SSL support: on
2023-03-10 06:27:08,470 ActorAddr-(T|:32993)/PID:26 esrally.client.factory INFO SSL certificate verification: off
2023-03-10 06:27:08,470 ActorAddr-(T|:32993)/PID:26 esrally.client.factory WARNING User has enabled SSL but disabled certificate verification. This is dangerous but may be ok for a benchmark. Disabling urllib warnings now to avoid a logging storm. See https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings for details.
2023-03-10 06:27:08,470 ActorAddr-(T|:32993)/PID:26 esrally.client.factory INFO SSL client authentication: off
2023-03-10 06:27:08,470 ActorAddr-(T|:32993)/PID:26 esrally.client.factory INFO Automatic creation of client API keys: off
2023-03-10 06:27:08,470 ActorAddr-(T|:32993)/PID:26 esrally.client.factory INFO HTTP basic authentication: on
2023-03-10 06:27:20,666 ActorAddr-(T|:42745)/PID:34 esrally.actor INFO Received signal from race control to start engine.
2023-03-10 06:27:20,667 ActorAddr-(T|:42745)/PID:34 esrally.actor INFO Cluster will not be provisioned by Rally.
2023-03-10 06:27:08,470 ActorAddr-(T|:32993)/PID:26 esrally.client.factory INFO HTTP compression: off
2023-03-10 06:27:20,627 ActorAddr-(T|:32993)/PID:26 esrally.client.factory INFO REST API is available for >= [1] nodes after [4] attempts.
2023-03-10 06:27:20,630 ActorAddr-(T|:32993)/PID:26 esrally.racecontrol INFO Automatically derived distribution version [8.5.2]
2023-03-10 06:27:20,631 ActorAddr-(T|:32993)/PID:26 esrally.track.loader INFO Reading track specification file [/rally

amitsa · March 10, 2023, 8:07am

I see in rally logs
create index operation is failing

023-03-10 07:56:23,142 ActorAddr-(T|:45401)/PID:305 esrally.client.factory INFO Creating ES client connected to [{'host': 'es-master', 'port': 9200, 'use_ssl': True}] with options [{'timeout': 240, 'basic_auth_user': 'rally', 'basic_auth_password': '*****', 'use_ssl': True, 'verify_certs': False, 'ca_certs': '/rally/cacert.pem'}]
2023-03-10 07:56:23,143 ActorAddr-(T|:45401)/PID:305 esrally.client.factory INFO SSL support: on
2023-03-10 07:56:23,143 ActorAddr-(T|:45401)/PID:305 esrally.client.factory INFO SSL certificate verification: off
2023-03-10 07:56:23,143 ActorAddr-(T|:45401)/PID:305 esrally.client.factory WARNING User has enabled SSL but disabled certificate verification. This is dangerous but may be ok for a benchmark. Disabling urllib warnings now to avoid a logging storm. See https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings for details.
2023-03-10 07:56:23,143 ActorAddr-(T|:45401)/PID:305 esrally.client.factory INFO SSL client authentication: off
2023-03-10 07:56:23,143 ActorAddr-(T|:45401)/PID:305 esrally.client.factory INFO Automatic creation of client API keys: off
2023-03-10 07:56:23,143 ActorAddr-(T|:45401)/PID:305 esrally.client.factory INFO HTTP basic authentication: on
2023-03-10 07:56:23,143 ActorAddr-(T|:45401)/PID:305 esrally.client.factory INFO HTTP compression: off
2023-03-10 07:56:23,158 -not-actor-/PID:305 elasticsearch WARNING PUT https://es-master:9200/osmgeopoints [status:400 request:0.014s]
2023-03-10 07:56:23,158 ActorAddr-(T|:45401)/PID:305 esrally.driver.driver INFO Total run duration: 0.014969 seconds.
2023-03-10 07:56:23,159 ActorAddr-(T|:45401)/PID:305 esrally.driver.driver INFO Total time to shutdown asyncgens: 0.000158 seconds.
2023-03-10 07:56:23,159 ActorAddr-(T|:45401)/PID:305 esrally.driver.driver INFO Total time to close transports: 0.000194 seconds.

Christian_Dahlqvist · March 10, 2023, 8:27am

"LZ4" is not a valid value for the index codec. See the docs for details.

amitsa · March 10, 2023, 8:54am

Thanks @Christian_Dahlqvist

I see its mentioned in above doc

Christian_Dahlqvist · March 10, 2023, 9:02am

From the docs:

The only accepted value is best_compression , which uses DEFLATE for a higher compression ratio but slower stored fields performance. To use the default LZ4 codec, omit this argument.

system · April 7, 2023, 9:02am

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