Call to api with Enforced timeout returns a 500 "There was a problem proxying the request" instead of a 504

Hi mates @Tyk !

I’m facing an issue while testing enforced timeouts.
In fact I think it might be a solution to enforce bigger timeouts on few specific calls (multipart with file upload for instance).

For my tests I’m currently using a local (docker) installation with a sample Hello-World api to validate my tyk.conf and api configuration, and basically when defining a hard_timeout in the extended_paths, though the request actually is stopped after the defined timeout (here 4 sec) I’m receiving a 500 http status code with an error “There was a problem proxying the request”

Here are the config to reproduce it:

tyk-compose.yml:

version: '4.3'
services:
  tyk-gateway:
    image: docker.tyk.io/tyk-gateway/tyk-gateway:v5.1.0
    ports:
      - 8080:8080
    networks:
      - tyk
    volumes:
      - ./tyk.standalone.conf:/opt/tyk-gateway/tyk.conf
      - ./apps:/opt/tyk-gateway/apps
      - ./middleware:/opt/tyk-gateway/middleware
      - ./certs:/opt/tyk-gateway/certs
      - ./policies:/opt/tyk-gateway/policies
    environment:
      - TYK_GW_SECRET=foo
    depends_on:
      - tyk-redis
  tyk-redis:
    image: redis:6.2.7-alpine
    networks:
      - tyk
    ports:
      - 6379:6379

networks:
  tyk:

Hello-World api definition:

{
  "name": "Hello-World",
  "slug": "hello-world",
  "listen_port": 0,
  "protocol": "",
  "enable_proxy_protocol": false,
  "api_id": "Hello-World",
  "org_id": "1",
  "use_keyless": true,
  "use_oauth2": false,
  "external_oauth": {
    "enabled": false,
    "providers": null
  },
  "use_openid": false,
  "openid_options": {
    "providers": null,
    "segregate_by_client": false
  },
  "oauth_meta": {
    "allowed_access_types": null,
    "allowed_authorize_types": null,
    "auth_login_redirect": ""
  },
  "auth": {
    "name": "",
    "use_param": false,
    "param_name": "",
    "use_cookie": false,
    "cookie_name": "",
    "disable_header": false,
    "auth_header_name": "Authorization",
    "use_certificate": false,
    "validate_signature": false,
    "signature": {
      "algorithm": "",
      "header": "",
      "use_param": false,
      "param_name": "",
      "secret": "",
      "allowed_clock_skew": 0,
      "error_code": 0,
      "error_message": ""
    }
  },
  "auth_configs": null,
  "use_basic_auth": false,
  "basic_auth": {
    "disable_caching": false,
    "cache_ttl": 0,
    "extract_from_body": false,
    "body_user_regexp": "",
    "body_password_regexp": ""
  },
  "use_mutual_tls_auth": false,
  "client_certificates": null,
  "upstream_certificates": null,
  "pinned_public_keys": null,
  "enable_jwt": false,
  "use_standard_auth": false,
  "use_go_plugin_auth": false,
  "enable_coprocess_auth": false,
  "custom_plugin_auth_enabled": false,
  "jwt_signing_method": "",
  "jwt_source": "",
  "jwt_identity_base_field": "",
  "jwt_client_base_field": "",
  "jwt_policy_field_name": "",
  "jwt_default_policies": null,
  "jwt_issued_at_validation_skew": 0,
  "jwt_expires_at_validation_skew": 0,
  "jwt_not_before_validation_skew": 0,
  "jwt_skip_kid": false,
  "scopes": {
    "jwt": {},
    "oidc": {}
  },
  "jwt_scope_to_policy_mapping": null,
  "jwt_scope_claim_name": "",
  "notifications": {
    "shared_secret": "",
    "oauth_on_keychange_url": ""
  },
  "enable_signature_checking": false,
  "hmac_allowed_clock_skew": 0,
  "hmac_allowed_algorithms": null,
  "request_signing": {
    "is_enabled": false,
    "secret": "",
    "key_id": "",
    "algorithm": "",
    "header_list": null,
    "certificate_id": "",
    "signature_header": ""
  },
  "base_identity_provided_by": "",
  "definition": {
    "enabled": false,
    "name": "",
    "default": "",
    "location": "header",
    "key": "x-api-version",
    "strip_path": false,
    "strip_versioning_data": false,
    "versions": null
  },
  "version_data": {
    "not_versioned": true,
    "default_version": "",
    "versions": {
      "Default": {
        "name": "Default",
        "expires": "",
        "paths": {
          "white_list": null,
          "black_list": null
        },
        "use_extended_paths": true,
        "extended_paths": {
          "persist_graphql": null,
          "hard_timeouts": [{
            "method": "GET",
            "path": "/{delay}",
            "timeout": 4 
          }]
        },
        "global_headers": null,
        "global_headers_remove": null,
        "global_response_headers": null,
        "global_response_headers_remove": null,
        "ignore_endpoint_case": false,
        "global_size_limit": 0,
        "override_target": ""
      }
    }
  },
  "uptime_tests": {
    "check_list": null,
    "config": {
      "expire_utime_after": 0,
      "service_discovery": {
        "use_discovery_service": false,
        "query_endpoint": "",
        "use_nested_query": false,
        "parent_data_path": "",
        "data_path": "",
        "port_data_path": "",
        "target_path": "",
        "use_target_list": false,
        "cache_disabled": false,
        "cache_timeout": 0,
        "endpoint_returns_list": false
      },
      "recheck_wait": 0
    }
  },
  "proxy": {
    "preserve_host_header": false,
    "listen_path": "/delay/",
    "target_url": "http://httpbin.org/delay/",
    "disable_strip_slash": false,
    "strip_listen_path": true,
    "enable_load_balancing": false,
    "target_list": null,
    "check_host_against_uptime_tests": false,
    "service_discovery": {
      "use_discovery_service": false,
      "query_endpoint": "",
      "use_nested_query": false,
      "parent_data_path": "",
      "data_path": "",
      "port_data_path": "",
      "target_path": "",
      "use_target_list": false,
      "cache_disabled": false,
      "cache_timeout": 0,
      "endpoint_returns_list": false
    },
    "transport": {
      "ssl_insecure_skip_verify": false,
      "ssl_ciphers": null,
      "ssl_min_version": 0,
      "ssl_max_version": 0,
      "ssl_force_common_name_check": false,
      "proxy_url": ""
    }
  },
  "disable_rate_limit": false,
  "disable_quota": false,
  "custom_middleware": {
    "pre": null,
    "post": null,
    "post_key_auth": null,
    "auth_check": {
      "disabled": false,
      "name": "",
      "path": "",
      "require_session": false,
      "raw_body_only": false
    },
    "response": null,
    "driver": "",
    "id_extractor": {
      "disabled": false,
      "extract_from": "",
      "extract_with": "",
      "extractor_config": null
    }
  },
  "custom_middleware_bundle": "",
  "custom_middleware_bundle_disabled": false,
  "cache_options": {
    "cache_timeout": 0,
    "enable_cache": false,
    "cache_all_safe_requests": false,
    "cache_response_codes": null,
    "enable_upstream_cache_control": false,
    "cache_control_ttl_header": "",
    "cache_by_headers": null
  },
  "session_lifetime": 0,
  "active": true,
  "internal": false,
  "auth_provider": {
    "name": "",
    "storage_engine": "",
    "meta": null
  },
  "session_provider": {
    "name": "",
    "storage_engine": "",
    "meta": null
  },
  "event_handlers": {
    "events": null
  },
  "enable_batch_request_support": false,
  "enable_ip_whitelisting": false,
  "allowed_ips": null,
  "enable_ip_blacklisting": false,
  "blacklisted_ips": null,
  "dont_set_quota_on_create": false,
  "expire_analytics_after": 0,
  "response_processors": null,
  "CORS": {
    "enable": false,
    "allowed_origins": null,
    "allowed_methods": null,
    "allowed_headers": null,
    "exposed_headers": null,
    "allow_credentials": false,
    "max_age": 0,
    "options_passthrough": false,
    "debug": false
  },
  "domain": "",
  "certificates": null,
  "do_not_track": false,
  "enable_context_vars": false,
  "config_data": null,
  "config_data_disabled": false,
  "tag_headers": null,
  "global_rate_limit": {
    "rate": 0,
    "per": 0
  },
  "strip_auth_data": false,
  "enable_detailed_recording": false,
  "graphql": {
    "enabled": false,
    "execution_mode": "",
    "version": "",
    "schema": "",
    "type_field_configurations": null,
    "playground": {
      "enabled": false,
      "path": ""
    },
    "engine": {
      "field_configs": null,
      "data_sources": null
    },
    "proxy": {
      "auth_headers": null,
      "request_headers": null
    },
    "subgraph": {
      "sdl": ""
    },
    "supergraph": {
      "subgraphs": null,
      "merged_sdl": "",
      "global_headers": null,
      "disable_query_batching": false
    }
  },
  "analytics_plugin": {},
  "tags": null
}

cURL call:

curl -v http://localhost:8080/delay/10
*   Trying 127.0.0.1:8080...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /delay/10 HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.81.0
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 500 Internal Server Error
< Content-Type: application/json
< X-Generator: tyk.io
< Date: Wed, 10 Jul 2024 14:59:17 GMT
< Content-Length: 59
< 
{
    "error": "There was a problem proxying the request"
}

Tyk Gateway logs:

time="Jul 10 14:59:13" level=debug msg=Started api_id=Hello-World api_name=Hello-World mw=VersionCheck org_id=1 origin=172.22.0.1 path=/delay/10 ts=1720623553045062823
time="Jul 10 14:59:13" level=debug msg=Finished api_id=Hello-World api_name=Hello-World code=200 mw=VersionCheck ns=34098 org_id=1 origin=172.22.0.1 path=/delay/10
time="Jul 10 14:59:13" level=debug msg=Started api_id=Hello-World api_name=Hello-World mw=RateCheckMW org_id=1 origin=172.22.0.1 path=/delay/10 ts=1720623553045107201
time="Jul 10 14:59:13" level=debug msg=Finished api_id=Hello-World api_name=Hello-World code=200 mw=RateCheckMW ns=9603 org_id=1 origin=172.22.0.1 path=/delay/10
time="Jul 10 14:59:13" level=debug msg="Started proxy"
time="Jul 10 14:59:13" level=debug msg="Stripping proxy listen path: /delay/"
time="Jul 10 14:59:13" level=debug msg="Upstream path is: /10"
time="Jul 10 14:59:13" level=debug msg=Started api_id=Hello-World api_name=Hello-World mw=ReverseProxy org_id=1 ts=1720623553045132530
time="Jul 10 14:59:13" level=debug msg="Upstream request URL: /10" api_id=Hello-World api_name=Hello-World mw=ReverseProxy org_id=1
time="Jul 10 14:59:13" level=debug msg="Outbound request URL: http://httpbin.org/delay/10" api_id=Hello-World api_name=Hello-World mw=ReverseProxy org_id=1
time="Jul 10 14:59:17" level=error msg="http: proxy error: dial tcp: lookup httpbin.org: i/o timeout" api_id=Hello-World api_name=Hello-World mw=ReverseProxy org_id=1 prefix=proxy server_name=httpbin.org user_id=-- user_ip=172.22.0.1 user_name=
time="Jul 10 14:59:17" level=debug msg=Finished api_id=Hello-World api_name=Hello-World mw=ReverseProxy ns=4000975289 org_id=1
time="Jul 10 14:59:17" level=debug msg="Upstream request took (ms): 4001.006729"
time="Jul 10 14:59:17" level=debug msg="Done proxy"

Here is the cURL call behavior when the default proxy timeout is set (“proxy_default_timeout”: 2 in tyk.conf):

curl -v http://localhost:8080/delay/10
*   Trying 127.0.0.1:8080...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /delay/10 HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.81.0
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 504 Gateway Timeout
< Content-Type: application/json
< X-Generator: tyk.io
< Date: Wed, 10 Jul 2024 13:52:30 GMT
< Content-Length: 57
< 
{
    "error": "Upstream service reached hard timeout."
}

Can you tell me if it’s a bug? or sthg I may be doing wrong ?
Thx a lot for your help !

FYI, if I’m upgrading the tyk gw image to v5.2.5, I’m now having other behavior:

With same API definition (hard timeout set to 4 sec)
I’m getting these logs:

time="Jul 10 15:25:09" level=debug msg="Started proxy"
time="Jul 10 15:25:09" level=debug msg="Stripping proxy listen path: /delay/"
time="Jul 10 15:25:09" level=debug msg="Upstream path is: /10"
time="Jul 10 15:25:09" level=debug msg=Started api_id=Hello-World api_name=Hello-World mw=ReverseProxy org_id=1 ts=1720625109649212737
time="Jul 10 15:25:09" level=debug msg="Upstream request URL: /10" api_id=Hello-World api_name=Hello-World mw=ReverseProxy org_id=1
time="Jul 10 15:25:09" level=debug msg="Outbound request URL: http://httpbin.org/delay/10" api_id=Hello-World api_name=Hello-World mw=ReverseProxy org_id=1
time="Jul 10 15:25:09" level=debug msg="Creating new transport" api_id=Hello-World api_name=Hello-World mw=ReverseProxy org_id=1
time="Jul 10 15:25:09" level=debug msg="Setting timeout for outbound request to: 30"
time="Jul 10 15:25:09" level=debug msg="Out request url: http://httpbin.org/delay/10" api_id=Hello-World api_name=Hello-World mw=ReverseProxy org_id=1
time="Jul 10 15:25:13" level=debug msg="Primary instance set, I am master" prefix=host-check-mgr
time="Jul 10 15:25:23" level=debug msg="Primary instance set, I am master" prefix=host-check-mgr
time="Jul 10 15:25:24" level=debug msg=Finished api_id=Hello-World api_name=Hello-World mw=ReverseProxy ns=14405567833 org_id=1
time="Jul 10 15:25:24" level=debug msg="Upstream request took (ms): 14405.627836"
time="Jul 10 15:25:24" level=debug msg="Done proxy"

with a (default ?) timeout set to 30 (see “Setting timeout for outbound request to: 30”) while still having a proxy_default_timeout set to 0 in my tyk.standalone.conf …

as you can see that time, I’ve no request “cut” after 4sec but it waits until my upstream answers

in fact there seems to be a regression somewhere between 5.1.0 and 5.2.5
a regression for which using 0 for proxy_default_timeout is now being equivalent to using 30, and no more “infinite wait” as it used to be

in addition, in 5.2.5 I don’t succeed in making the hard_timeouts work …

Hi,

This response is caused by the error below it

The gateway was unable to connect to the dns service to lookup httpbin.org so returned a 500 error.

I get quite different logs. In particular I see this one which shows that the hard timeout is in force.

time="Jul 16 09:16:33" level=debug msg="HARD TIMEOUT ENFORCED: 4" api_id=Hello-World api_name=Hello-World mw=ReverseProxy org_id=6696391a411022008d62f609

There have been some defects in the past where the hard timeouts misbehaved when there were a number of different ones defined for different end points on the same API. Those issues should be resolved in the stable releases (5.0.12 and 5.3.2) so it would be great to test with them.

Also please check that you don’t have two APIs listening on /delay/ because which one loaded and used can be random.

This is mentioned in the v5.2.2 release notes

I’m sorry to hear that, but when I deploy the given API definition to a fresh deployment of 5.2.5 it gives this result:

$ curl https://10.0.0.24:5002/delay/10
{
    "error": "Upstream service reached hard timeout."
}

Cheers,
Pete

Ok for the release notes, I did not understand it the same way
" The default value of proxy_default_timeout is now set to 30s. It previously used to wait forever."

I did understand that 30 was the default when not specified, while it was meant to say “using 0 => 30sec”