search

voltrondata-labs / benchmarks

Language-independent Continuous Benchmarking (CB) for Apache Arrow
MIT License
10 stars 11 forks source link

error when POSTing benchmark results: Expected code 201, got 200 #139

Closed austin3dickey closed 1 year ago

austin3dickey commented 1 year ago

Example build: https://buildkite.com/apache-arrow/arrow-bci-benchmark-on-ec2-m5-4xlarge-us-east-2/builds/2347#018890c5-5406-469b-a411-3495092d1fe5

[230606-13:36:49.995] [22163] [benchclients.conbench] INFO: try to perform login
[230606-13:36:49.995] [22163] [benchclients.http] INFO: try: POST to https://conbench.ursa.dev/api/login/
[230606-13:36:50.132] [22163] [benchclients.http] INFO: POST request to https://conbench.ursa.dev/api/login/: took 0.1362 s, response status code: 204
[230606-13:36:50.132] [22163] [benchclients.conbench] INFO: ConbenchClient: initialized
[230606-13:36:50.132] [22163] [benchclients.http] DEBUG: POST request JSON body:
{
  "run_id": "fc27335fd7364cd0816346a148bee7f4",
  "batch_id": "fc27335fd7364cd0816346a148bee7f4-1n",
  "timestamp": "2023-06-06T13:36:49.725925+00:00",
  "context": {
    "arrow_compiler_flags": "-fvisibility-inlines-hidden -fmessage-length=0 -march=nocona -mtune=haswell -ftree-vectorize -fPIC -fstack-protector-strong -fno-plt -O2 -ffunction-sections -pipe -isystem /var/lib/buildkite-agent/.conda/envs/arrow-commit/include -fdiagnostics-color=always",
    "benchmark_language": "R"
  },
  "info": {
    "arrow_version": "13.0.0-SNAPSHOT",
    "arrow_compiler_id": "GNU",
    "arrow_compiler_version": "11.3.0",
    "benchmark_language_version": "R version 4.2.3 (2023-03-15)",
    "arrow_version_r": "12.0.0.9000"
  },
  "tags": {
    "cpu_count": null,
    "engine": "arrow",
    "memory_map": false,
    "query_id": "TPCH-01",
    "scale_factor": 1,
    "format": "native",
    "language": "R",
    "name": "tpch"
  },
  "optional_benchmark_info": {},
  "github": {
    "repository": "https://github.com/apache/arrow",
    "pr_number": null,
    "commit": "3d0172d40dfcf934308e6e1f4249a854004fe824"
  },
  "stats": {
    "data": [
      "0.396095",
      "0.458458",
      "0.453228"
    ],
    "times": [],
    "unit": "s",
    "time_unit": "s",
    "iterations": 3,
    "mean": "0.435927",
    "median": "0.453228",
    "min": "0.396095",
    "max": "0.458458",
    "stdev": "0.034595",
    "q1": "0.424661",
    "q3": "0.455843",
    "iqr": "0.031182"
  },
  "machine_info": {
    "name": "ec2-m5-4xlarge-us-east-2",
    "os_name": "Linux",
    "os_version": "4.14.248-189.473.amzn2.x86_64-x86_64-with-glibc2.10",
    "architecture_name": "x86_64",
    "kernel_name": "4.14.248-189.473.amzn2.x86_64",
    "memory_bytes": "65498251264",
    "cpu_model_name": "Intel(R) Xeon(R) Platinum 8259CL CPU @ 2.50GHz",
    "cpu_core_count": "8",
    "cpu_thread_count": "16",
    "cpu_l1d_cache_bytes": "32768",
    "cpu_l1i_cache_bytes": "32768",
    "cpu_l2_cache_bytes": "1048576",
    "cpu_l3_cache_bytes": "37486592",
    "cpu_frequency_max_hz": "0",
    "gpu_count": "0",
    "gpu_product_names": []
  },
  "run_name": "commit: 3d0172d40dfcf934308e6e1f4249a854004fe824",
  "run_reason": "commit"
}
[230606-13:36:50.132] [22163] [benchclients.http] INFO: try: POST to https://conbench.ursa.dev/api/benchmark-results
[230606-13:36:50.371] [22163] [benchclients.http] INFO: POST request to https://conbench.ursa.dev/api/benchmark-results: took 0.2394 s, response status code: 200
[230606-13:36:50.372] [22163] [benchclients.http] INFO: unexpected response. code: 200, body bytes: <[
  {
    "id": "0647f25ae7197cbf8000d16e33d1a4bf",
    "run_id": "d46b8964796e4429b39faf0dc15301ea",
    "batch_id": "1cdc3a9dc9d04d7782901ce831f34e85",
    "timestamp": "2023-06-06T12:21:00Z",
    "tags": {
      "name": "ReplaceWithMaskLowSelectivityBench",
      "suite": "arrow-compute-vector-replace-benchmark",
      "params": "16384/99",
      "source": "cpp-micro"
    },
    "optional_bench ...>
Traceback (most recent call last):
  File "/var/lib/buildkite-agent/.conda/envs/arrow-commit/bin/conbench", line 8, in <module>
    sys.exit(conbench())
  File "/var/lib/buildkite-agent/.conda/envs/arrow-commit/lib/python3.8/site-packages/click/core.py", line 1130, in __call__
    return self.main(*args, **kwargs)
  File "/var/lib/buildkite-agent/.conda/envs/arrow-commit/lib/python3.8/site-packages/click/core.py", line 1055, in main
    rv = self.invoke(ctx)
  File "/var/lib/buildkite-agent/.conda/envs/arrow-commit/lib/python3.8/site-packages/click/core.py", line 1657, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/var/lib/buildkite-agent/.conda/envs/arrow-commit/lib/python3.8/site-packages/click/core.py", line 1404, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/var/lib/buildkite-agent/.conda/envs/arrow-commit/lib/python3.8/site-packages/click/core.py", line 760, in invoke
    return __callback(*args, **kwargs)
  File "/var/lib/buildkite-agent/.conda/envs/arrow-commit/lib/python3.8/site-packages/conbench/cli.py", line 149, in _benchmark
    for result, output in benchmark().run(**kwargs):
  File "/var/lib/buildkite-agent/builds/aws-ec2-m5-4xlarge-us-east-2-i-09bd8650b4486e15b-1/apache-arrow/arrow-bci-benchmark-on-ec2-m5-4xlarge-us-east-2/benchmarks/benchmarks/tpch_benchmark.py", line 30, in run
    yield self.r_benchmark(command, tags, kwargs, case)
  File "/var/lib/buildkite-agent/builds/aws-ec2-m5-4xlarge-us-east-2-i-09bd8650b4486e15b-1/apache-arrow/arrow-bci-benchmark-on-ec2-m5-4xlarge-us-east-2/benchmarks/benchmarks/_benchmark.py", line 304, in r_benchmark
    return self.record(
  File "/var/lib/buildkite-agent/builds/aws-ec2-m5-4xlarge-us-east-2-i-09bd8650b4486e15b-1/apache-arrow/arrow-bci-benchmark-on-ec2-m5-4xlarge-us-east-2/benchmarks/benchmarks/_benchmark.py", line 150, in record
    benchmark, output = self.conbench.record(
  File "/var/lib/buildkite-agent/.conda/envs/arrow-commit/lib/python3.8/site-packages/conbench/runner.py", line 333, in record
    self.publish(benchmark_result)
  File "/var/lib/buildkite-agent/builds/aws-ec2-m5-4xlarge-us-east-2-i-09bd8650b4486e15b-1/apache-arrow/arrow-bci-benchmark-on-ec2-m5-4xlarge-us-east-2/benchmarks/benchmarks/_benchmark.py", line 83, in publish
    self.conbench_client.post("/benchmark-results", benchmark)
  File "/var/lib/buildkite-agent/.conda/envs/arrow-commit/lib/python3.8/site-packages/benchclients/http.py", line 164, in post
    resp = self._make_request("POST", self._abs_url_from_path(path), 201, json=json)
  File "/var/lib/buildkite-agent/.conda/envs/arrow-commit/lib/python3.8/site-packages/benchclients/http.py", line 205, in _make_request
    result = self._make_request_retry_until_deadline(
  File "/var/lib/buildkite-agent/.conda/envs/arrow-commit/lib/python3.8/site-packages/benchclients/http.py", line 266, in _make_request_retry_until_deadline
    result = self._make_request_retry_guts(
  File "/var/lib/buildkite-agent/.conda/envs/arrow-commit/lib/python3.8/site-packages/benchclients/http.py", line 393, in _make_request_retry_guts
    raise RetryingHTTPClientNonRetryableResponse(message=msg, error_response=resp)
benchclients.http.RetryingHTTPClientNonRetryableResponse: POST request to https://conbench.ursa.dev/api/benchmark-results: unexpected HTTP response. Expected code 201, got 200. Leading bytes of body: <[
  {
    "id": "0647f25ae7197cbf8000d16e33d1a4bf",
    "run_id": "d46b8964796e4429b39faf0dc15301ea",
    "batch_id": "1cdc3a9dc9d04d7782901ce831f34e8 ...>

stdout:
austin3dickey commented 1 year ago

Could not reproduce locally yet. 

from datetime import datetime
import os

from benchclients import ConbenchClient

os.environ["CONBENCH_URL"] = "https://127.0.0.1:5000"
os.environ["CONBENCH_EMAIL"] = "e@e.com"
os.environ["CONBENCH_PASSWORD"] = "test"

client = ConbenchClient()
client.post(
    "/benchmark-results",
    {
        "batch_id": "test",
        "context": {},
        "info": {},
        "run_id": "test",
        "tags": {"name": "test"},
        "timestamp": datetime.now().isoformat(),
        "cluster_info": {"name": "test", "info": {}, "optional_info": {}},
        "error": {},
    },
)
230606-10:20:49.113 INFO: try to perform login
230606-10:20:49.113 INFO: try: POST to http://127.0.0.1:5000/api/login/
230606-10:20:49.194 INFO: POST request to http://127.0.0.1:5000/api/login/: took 0.0805 s, response status code: 204
230606-10:20:49.194 INFO: ConbenchClient: initialized
230606-10:20:49.194 INFO: try: POST to http://127.0.0.1:5000/api/benchmark-results/
230606-10:20:49.208 INFO: POST request to http://127.0.0.1:5000/api/benchmark-results/: took 0.0142 s, response status code: 201

@jgehrcke pointed out that we are receiving a JSON array at the end of the logs; that is, we are probably being wrongly redirected to the GET /benchmark-results endpoint instead. I suspect the reason I can't reproduce locally is that it's not using HTTPS.

alistaire47 commented 1 year ago

we are probably being wrongly redirected to the GET /benchmark-results endpoint instead

Notably we're getting a list of results—this is the GET list endpoint, not the GET one. This kind of makes sense because the POST endpoint is on BenchmarkListAPI (not BenchmarkEntityAPI) even though it doesn't take a list because the endpoint is /api/benchmark-results, not /api/benchmark-results/<id>. Which I guess is fine, but BenchmarkListAPI is a bad name. (Also maybe we should accept a list of results in a single call, but that's another discussion.)

Not an answer, but maybe helpful for localizing the problem

jgehrcke commented 1 year ago

we are probably being wrongly redirected to the GET /benchmark-results endpoint instead. I suspect the reason I can't reproduce locally is that it's not using HTTPS.

What's happening is probably what I described in https://github.com/conbench/conbench/pull/1150#issuecomment-1518624190:

Flask emits a 308 redirect response with the idea to add the trailing slash, but it also sets the scheme to HTTP ALB sees HTTP scheme and is configured to emit a 301 redirect response for the HTTP->HTTPS redirect

Client then sees the 301 redirect and switches method to GET (which is what 301 demands, by standard -- the 308 would allow for the method to stay the same).

BenchmarkListAPI is a bad name

Yes. In RESTy terminology this is a "collection" (this is the better term, and I think "list" tried to be that). It's typical to

Something with BenchmarkResultCollection would be a better name :)

austin3dickey commented 1 year ago

Indeed, I tried the same script, using credentials for our staging environment, and turned up the verbosity of urllib3 logging. Here's the result:

230606-10:28:11.753 INFO: try to perform login
230606-10:28:11.753 INFO: try: POST to https://<staging>/api/login/
230606-10:28:11.846 DEBUG: Starting new HTTPS connection (1): <staging>:443
230606-10:28:12.152 DEBUG: https://<staging>:443 "POST /api/login/ HTTP/1.1" 204 0
230606-10:28:12.153 INFO: POST request to https://<staging>/api/login/: took 0.3994 s, response status code: 204
230606-10:28:12.153 INFO: ConbenchClient: initialized
230606-10:28:12.153 INFO: try: POST to https://<staging>/api/benchmark-results
230606-10:28:12.187 DEBUG: https://<staging>:443 "POST /api/benchmark-results HTTP/1.1" 308 299
230606-10:28:12.190 DEBUG: Starting new HTTP connection (1): <staging>:80
230606-10:28:12.240 DEBUG: http://<staging>:80 "POST /api/benchmark-results/ HTTP/1.1" 301 134
230606-10:28:12.453 DEBUG: https://<staging>:443 "GET /api/benchmark-results/ HTTP/1.1" 200 74641
230606-10:28:12.504 INFO: POST request to https://<staging>/api/benchmark-results: took 0.3505 s, response status code: 200
230606-10:28:12.504 INFO: unexpected response. code: 200, body bytes: <[
  {
    "id": "0647f3a122467d4880007fbbb90a1c83",
    "run_id": "e5ee699260464d039baeebd326b77de8",
    "batch_id": "dba73b4db49e4e2bb819bd087f446eac",
    "timestamp": "2023-06-06T13:52:16Z",
    "tags": {
      "name": "tpch-theseus",
      "ptds": "False",
      "query_id": "TPCH-01",
      "multi_nics": "disabled",
      "scale_factor": "1",
      "dataset_variant": "parquet-float64",
       ...>
Traceback (most recent call last):
  File "/Users/austin/Desktop/asd.py", line 14, in <module>
    client.post(
  File "/Users/austin/repos/conbench/benchclients/python/benchclients/http.py", line 164, in post
    resp = self._make_request("POST", self._abs_url_from_path(path), 201, json=json)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/austin/repos/conbench/benchclients/python/benchclients/http.py", line 205, in _make_request
    result = self._make_request_retry_until_deadline(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/austin/repos/conbench/benchclients/python/benchclients/http.py", line 266, in _make_request_retry_until_deadline
    result = self._make_request_retry_guts(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/austin/repos/conbench/benchclients/python/benchclients/http.py", line 393, in _make_request_retry_guts
    raise RetryingHTTPClientNonRetryableResponse(message=msg, error_response=resp)
benchclients.http.RetryingHTTPClientNonRetryableResponse: POST request to https://<staging>/api/benchmark-results: unexpected HTTP response. Expected code 201, got 200. Leading bytes of body: <[
  {
    "id": "0647f3a122467d4880007fbbb90a1c83",
    "run_id": "e5ee699260464d039baeebd326b77de8",
    "batch_id": "dba73b4db49e4e2bb819bd087f446ea ...>

So this happens:

  1. POST https://<staging>/api/benchmark-results. Receive 308 PERMANENT REDIRECT with Location: http://<staging>/api/benchmark-results/
  2. POST http://<staging>/api/benchmark-results/. Receive 301 Moved Permanently with Location: https://<staging>:443/api/benchmark-results/
  3. GET https://<staging>:443/api/benchmark-results/. Receive 200 OK with the wrong data.

This is heavily related to https://github.com/conbench/conbench/issues/1151. As we did before, we can temporarily solve it by adding a trailing slash to the URL path. I validated that this works locally.

jgehrcke commented 1 year ago

and turned up the verbosity of urllib3 logging. Here's the result:

nice! :heart:

austin3dickey commented 1 year ago

This did work. Now we're getting green builds again! https://buildkite.com/apache-arrow/arrow-bci-benchmark-on-ec2-t3-xlarge-us-east-2/builds/2987#01889168-ac0a-476c-bedd-b243a0a821e7/33-5400

[230606-16:43:20.389] [2043828] [benchclients.http] INFO: POST request to https://conbench.ursa.dev/api/benchmark-results/: took 0.0432 s, response status code: 201