Introduce APICAST_LUA_SOCKET_KEEPALIVE_REQUESTS environment variable

[tkan145]

What

A patch for https://issues.redhat.com/browse/THREESCALE-11321

Verification steps

• Check out this branch
• Create a apicast-config.json file with the following content

cat <<EOF >apicast-config.json
{
    "services": [
        {
            "id": "1",
            "backend_version": "1",
            "proxy": {
                "hosts": [
                    "one"
                ],
                "api_backend": "https://echo-api.3scale.net:443",
                "backend": {
                    "endpoint": "http://127.0.0.1:8081",
                    "host": "backend"
                },
                "policy_chain": [
                    {
                        "name": "apicast.policy.apicast"
                    }
                ],
                "proxy_rules": [
                    {
                        "http_method": "GET",
                        "pattern": "/",
                        "metric_system_name": "hits",
                        "delta": 1,
                        "parameters": [],
                        "querystring_parameters": {}
                    }
                ]
            }
        }
    ]
} 
EOF

• Start development environment

make development
make dependencies

• Run apicast locally with APICAST_LUA_SOCKET_KEEPALIVE_REQUESTS=5

THREESCALE_DEPLOYMENT_ENV=staging APICAST_LOG_LEVEL=debug APICAST_WORKER=1 APICAST_CONFIGURATION_LOADER=lazy APICAST_CONFIGURATION_CACHE=0 APICAST_LUA_SOCKET_KEEPALIVE_REQUESTS=5 THREESCALE_CONFIG_FILE=apicast-config.json ./bin/apicast

• Capture apicast IP

APICAST_IP=$(docker inspect apicast_build_0-development-1 | yq e -P '.[0].NetworkSettings.Networks.apicast_build_0_default.IPAddress' -)

• Send a request

curl -i -k -H "Host: one" -H "Accept: application/json" "http://${APICAST_IP}:8080/?user_key="

• Note the following line in the log

 proxy.lua:26: new(): connection to 127.0.0.1:8081 established, reused times: 1

• Keep sending more requests, after the 5 request, the reused time should reset to 0

proxy.lua:26: new(): connection to 127.0.0.1:8081 established, reused times: 0,

[dfennessy]

I've added a couple of suggestions.

[MStokluska]

I've tried it following the verification steps and indeed, the connection re-used numbers are correct based on the connections I've made. Going to test on cluster.

Just a question re closing connections. Do we want to do this manually or as An explained to me, rely on the lua GC?

[tkan145]

😓 link check failed

[MStokluska]

Testing the image on a cluster in comparison to previous performance:

Roughly at 11:50, applying new APIcast image
Results: no big difference between what it was.

At around 12:00 setting the APICAST_LUA_SOCKET_KEEPALIVE_REQUESTS=5 flag
Result: big improvement in load balancing

During the rest of the test I was scaling traffic x5, x1, x10, x80 and results are pretty consistent and improved.

[eguzki]

😓 link check failed

Fixed as part of #1495

[eguzki]

LGTM

I have tested with dev env implemented in #1495, where backend is running in a different service. Configuring APICAST_LUA_SOCKET_KEEPALIVE_REQUESTS to 5, after he fifth request was responded, apicast closed the connection. The following shows logs from socat that monitors communication between apicast and backend listener.

backend  | > 2024/09/19 13:13:18.000271036  length=248 from=1240 to=1487
backend  | GET /transactions/authrep.xml?service_id=1&usage%5Bhits%5D=1&user_key=123 HTTP/1.1\r
backend  | User-Agent: APIcast/3.14.0 (Linux; x64; env:staging)\r
backend  | Connection: Keep-Alive\r
backend  | 3scale-Options: rejection_reason_header=1&limit_headers=1&no_body=1\r
backend  | Host: backend\r
backend  | \r
backend  | 2024/09/19 13:13:18 socat[7] I transferred 248 bytes from 6 to 5
backend  | < 2024/09/19 13:13:18.000274152  length=180 from=3045 to=3224
backend  | HTTP/1.1 200 OK\r
backend  | Content-Type: application/json\r
backend  | Server: WEBrick/1.6.1 (Ruby/2.7.4/2021-07-07)\r
backend  | Date: Thu, 19 Sep 2024 13:13:18 GMT\r
backend  | Content-Length: 429\r
backend  | Connection: Keep-Alive\r
backend  | \r
backend  | 2024/09/19 13:13:18 socat[7] I transferred 180 bytes from 5 to 6
backend  | < 2024/09/19 13:13:18.000274350  length=429 from=3225 to=3653
backend  | {
backend  |   "method": "GET",
backend  |   "path": "/transactions/authrep.xml",
backend  |   "query_string": "service_id=1&usage%5Bhits%5D=1&user_key=123",
backend  |   "body": "",
backend  |   "headers": {
backend  |     "User-Agent": "APIcast/3.14.0 (Linux; x64; env:staging)",
backend  |     "Connection": "Keep-Alive",
backend  |     "3scale-Options": "rejection_reason_header=1&limit_headers=1&no_body=1",
backend  |     "Host": "backend",
backend  |     "Version": "HTTP/1.1"
backend  |   },
backend  |   "uuid": "61ae0b51-50e3-49ff-a650-03f3c1a2d823"
backend  | }2024/09/19 13:13:18 socat[7] I transferred 429 bytes from 5 to 6
backend  | 2024/09/19 13:13:18 socat[7] N socket 1 (fd 6) is at EOF
backend  | 2024/09/19 13:13:18 socat[7] I shutdown(5, 1)
backend  | 2024/09/19 13:13:18 socat[7] N socket 2 (fd 5) is at EOF
backend  | 2024/09/19 13:13:18 socat[7] I shutdown(6, 1)
backend  | 2024/09/19 13:13:18 socat[7] I shutdown(6, 2)
backend  | 2024/09/19 13:13:18 socat[7] I shutdown(6, 2): Socket not connected
backend  | 2024/09/19 13:13:18 socat[7] I shutdown(5, 2)
backend  | 2024/09/19 13:13:18 socat[7] I shutdown(5, 2): Socket not connected
backend  | 2024/09/19 13:13:18 socat[7] N exiting with status 0
backend  | 2024/09/19 13:13:18 socat[1] N childdied(): handling signal 17
backend  | 2024/09/19 13:13:18 socat[1] I childdied(signum=17)
backend  | 2024/09/19 13:13:18 socat[1] I childdied(17): cannot identify child 7
backend  | 2024/09/19 13:13:18 socat[1] I waitpid(): child 7 exited with status 0
backend  | 2024/09/19 13:13:18 socat[1] I waitpid(-1, {}, WNOHANG): No child process
backend  | 2024/09/19 13:13:18 socat[1] I childdied() finished

Socket 1 is the connection between apicast and backend. Socket 1 has two file descriptors, 5 and 6. The file descriptor 5 belongs to the backend listener end and the file descriptor 6 belongs to the apicast end. In the logs it can be seen transferred 429 bytes from 5 to 6, which means that backend listener has sent data to apicast.

Right after the fifth request, fd 6 closed its end, hence APIcast initiated connection close.

[tkan145]

@dfennessy I need your approval as well

[dfennessy]

Suggested change

	impact on requests proxied via APIcast
	impact on requests proxied via APIcast.

[dfennessy]

@tkan145 One last minor edit and then LGTM!

[tkan145]

Thanks guys

[eguzki]

This needs to be backported to master branch