toxiproxy: toxiproxy api hangs when trying to do anything after a long wait, run from inside testcontainers

Hello, I’m facing a weird behaviour: toxirpoxy doesn’t respond to API calls, the connection just hangs and nothing happens.

Here’s the setup I’m currently using toxyproxi in: There’re few containers run inside docker with testcontiners in a single docker network. Toxiproxy is used to create troubles communicating between components. So, basically, it’s between all components. And when the following scenario is used:

cut connection to the postgresql db for one of the components
wait for 60 seconds
restore the connection (or reset proxy or perform any other action by API, including GET requests).

Toxiproxy is run inside docker, tested with images shopify/toxiproxy:2.1.4 and shopify/toxiproxy:2.1.0. Below are the logs from the docker container. Please let me know if I can provide more information.

time="2019-06-19T12:09:40Z" level="info" msg="API HTTP server starting" host="0.0.0.0" port="8474" version="2.1.4"
time="2019-06-19T12:09:40Z" level="info" msg="Started proxy" name="postgres:5432" proxy="[::]:8666" upstream="postgres:5432"
time="2019-06-19T12:09:55Z" level="info" msg="Started proxy" proxy="[::]:8667" upstream="kafka:9093" name="kafka:9093"
time="2019-06-19T12:09:55Z" level="info" msg="Started proxy" name="kafka:9092" proxy="[::]:8668" upstream="kafka:9092"
time="2019-06-19T12:09:55Z" level="info" msg="Started proxy" name="zookeeper:2181" proxy="[::]:8669" upstream="zookeeper:2181"
time="2019-06-19T12:10:03Z" level="info" msg="Accepted client" client=192.168.16.5:38948 proxy="[::]:8669" upstream="zookeeper:2181" name="zookeeper:2181"
time="2019-06-19T12:10:03Z" level="warning" msg="Source terminated" err=read tcp 192.168.16.2:8669->192.168.16.5:38948: use of closed network connection name="zookeeper:2181" bytes=61
time="2019-06-19T12:10:04Z" level="info" msg="Accepted client" proxy="[::]:8669" upstream="zookeeper:2181" name="zookeeper:2181" client=192.168.16.5:38952
time="2019-06-19T12:10:06Z" level="info" msg="Accepted client" client=192.168.16.5:47974 proxy="[::]:8668" upstream="kafka:9092" name="kafka:9092"
time="2019-06-19T12:10:07Z" level="info" msg="Accepted client" upstream="kafka:9092" name="kafka:9092" client=192.168.16.5:47978 proxy="[::]:8668"
time="2019-06-19T12:10:07Z" level="info" msg="Accepted client" upstream="kafka:9092" name="kafka:9092" client=192.168.16.5:47982 proxy="[::]:8668"
time="2019-06-19T12:10:07Z" level="warning" msg="Source terminated" bytes=605 err=read tcp 192.168.16.2:53148->192.168.16.5:9092: use of closed network connection name="kafka:9092"
time="2019-06-19T12:10:07Z" level="warning" msg="Source terminated" name="kafka:9092" bytes=387 err=read tcp 192.168.16.2:53144->192.168.16.5:9092: use of closed network connection
time="2019-06-19T12:10:11Z" level="info" msg="Started proxy" upstream="schema-registry:8081" name="schema-registry:8081" proxy="[::]:8670"
time="2019-06-19T12:10:18Z" level="info" msg="Accepted client" proxy="[::]:8669" upstream="zookeeper:2181" name="zookeeper:2181" client=192.168.16.6:44368
time="2019-06-19T12:10:18Z" level="warning" msg="Source terminated" name="zookeeper:2181" bytes=61 err=read tcp 192.168.16.2:43454->192.168.16.4:2181: use of closed network connection
time="2019-06-19T12:10:19Z" level="info" msg="Accepted client" upstream="zookeeper:2181" name="zookeeper:2181" client=192.168.16.6:44372 proxy="[::]:8669"
time="2019-06-19T12:10:19Z" level="warning" msg="Source terminated" name="zookeeper:2181" bytes=61 err=read tcp 192.168.16.2:43458->192.168.16.4:2181: use of closed network connection
time="2019-06-19T12:10:19Z" level="info" msg="Accepted client" name="zookeeper:2181" client=192.168.16.6:44376 proxy="[::]:8669" upstream="zookeeper:2181"
time="2019-06-19T12:10:19Z" level="warning" msg="Source terminated" name="zookeeper:2181" bytes=625 err=read tcp 192.168.16.2:43462->192.168.16.4:2181: use of closed network connection
time="2019-06-19T12:10:19Z" level="info" msg="Accepted client" upstream="kafka:9092" name="kafka:9092" client=192.168.16.6:56448 proxy="[::]:8668"
time="2019-06-19T12:10:19Z" level="info" msg="Accepted client" name="kafka:9092" client=192.168.16.6:56452 proxy="[::]:8668" upstream="kafka:9092"
time="2019-06-19T12:10:20Z" level="warning" msg="Source terminated" name="kafka:9092" bytes=351 err=read tcp 192.168.16.2:53172->192.168.16.5:9092: use of closed network connection
time="2019-06-19T12:10:20Z" level="warning" msg="Source terminated" err=read tcp 192.168.16.2:53168->192.168.16.5:9092: use of closed network connection name="kafka:9092" bytes=351
time="2019-06-19T12:10:21Z" level="info" msg="Accepted client" name="zookeeper:2181" client=192.168.16.6:44388 proxy="[::]:8669" upstream="zookeeper:2181"
time="2019-06-19T12:10:22Z" level="warning" msg="Source terminated" name="zookeeper:2181" bytes=209 err=read tcp 192.168.16.2:43474->192.168.16.4:2181: use of closed network connection
time="2019-06-19T12:10:22Z" level="info" msg="Accepted client" client=192.168.16.6:44392 proxy="[::]:8669" upstream="zookeeper:2181" name="zookeeper:2181"
time="2019-06-19T12:10:22Z" level="info" msg="Accepted client" upstream="zookeeper:2181" name="zookeeper:2181" client=192.168.16.6:44396 proxy="[::]:8669"
time="2019-06-19T12:10:22Z" level="warning" msg="Source terminated" bytes=440 err=read tcp 192.168.16.2:43482->192.168.16.4:2181: use of closed network connection name="zookeeper:2181"
time="2019-06-19T12:10:22Z" level="info" msg="Accepted client" client=192.168.16.6:56468 proxy="[::]:8668" upstream="kafka:9092" name="kafka:9092"
time="2019-06-19T12:10:22Z" level="info" msg="Accepted client" name="kafka:9092" client=192.168.16.6:56472 proxy="[::]:8668" upstream="kafka:9092"
time="2019-06-19T12:10:22Z" level="warning" msg="Source terminated" bytes=520 err=read tcp 192.168.16.2:53192->192.168.16.5:9092: use of closed network connection name="kafka:9092"
time="2019-06-19T12:10:22Z" level="warning" msg="Source terminated" err=read tcp 192.168.16.2:53188->192.168.16.5:9092: use of closed network connection name="kafka:9092" bytes=351
time="2019-06-19T12:10:23Z" level="info" msg="Accepted client" upstream="kafka:9092" name="kafka:9092" client=192.168.16.6:56480 proxy="[::]:8668"
time="2019-06-19T12:10:23Z" level="info" msg="Accepted client" name="kafka:9092" client=192.168.16.6:56488 proxy="[::]:8668" upstream="kafka:9092"
time="2019-06-19T12:10:23Z" level="info" msg="Accepted client" name="kafka:9092" client=192.168.16.6:56492 proxy="[::]:8668" upstream="kafka:9092"
time="2019-06-19T12:10:23Z" level="info" msg="Accepted client" name="kafka:9092" client=192.168.16.6:56496 proxy="[::]:8668" upstream="kafka:9092"
time="2019-06-19T12:10:26Z" level="info" msg="Accepted client" upstream="postgres:5432" name="postgres:5432" client=192.168.16.1:54766 proxy="[::]:8666"
time="2019-06-19T12:10:26Z" level="info" msg="Accepted client" name="postgres:5432" client=192.168.16.1:54770 proxy="[::]:8666" upstream="postgres:5432"
time="2019-06-19T12:10:26Z" level="info" msg="Accepted client" client=192.168.16.1:54774 proxy="[::]:8666" upstream="postgres:5432" name="postgres:5432"
time="2019-06-19T12:10:26Z" level="info" msg="Accepted client" proxy="[::]:8666" upstream="postgres:5432" name="postgres:5432" client=192.168.16.1:54778
time="2019-06-19T12:10:26Z" level="info" msg="Accepted client" name="postgres:5432" client=192.168.16.1:54782 proxy="[::]:8666" upstream="postgres:5432"
time="2019-06-19T12:10:26Z" level="info" msg="Accepted client" client=192.168.16.1:54786 proxy="[::]:8666" upstream="postgres:5432" name="postgres:5432"
time="2019-06-19T12:10:26Z" level="info" msg="Accepted client" client=192.168.16.1:54790 proxy="[::]:8666" upstream="postgres:5432" name="postgres:5432"
time="2019-06-19T12:10:26Z" level="info" msg="Accepted client" name="postgres:5432" client=192.168.16.1:54794 proxy="[::]:8666" upstream="postgres:5432"
time="2019-06-19T12:10:26Z" level="info" msg="Accepted client" name="postgres:5432" client=192.168.16.1:54798 proxy="[::]:8666" upstream="postgres:5432"
time="2019-06-19T12:10:26Z" level="info" msg="Accepted client" upstream="postgres:5432" name="postgres:5432" client=192.168.16.1:54802 proxy="[::]:8666"
time="2019-06-19T12:10:29Z" level="info" msg="Accepted client" name="kafka:9093" client=192.168.16.1:33124 proxy="[::]:8667" upstream="kafka:9093"
time="2019-06-19T12:10:29Z" level="info" msg="Accepted client" name="kafka:9093" client=192.168.16.1:33128 proxy="[::]:8667" upstream="kafka:9093"
time="2019-06-19T12:10:29Z" level="warning" msg="Source terminated" name="kafka:9093" bytes=618 err=read tcp 192.168.16.2:45516->192.168.16.5:9093: use of closed network connection
time="2019-06-19T12:10:29Z" level="warning" msg="Source terminated" name="kafka:9093" bytes=351 err=read tcp 192.168.16.2:45512->192.168.16.5:9093: use of closed network connection
time="2019-06-19T12:10:29Z" level="info" msg="Accepted client" client=192.168.16.1:54814 proxy="[::]:8666" upstream="postgres:5432" name="postgres:5432"
time="2019-06-19T12:10:29Z" level="info" msg="Accepted client" proxy="[::]:8666" upstream="postgres:5432" name="postgres:5432" client=192.168.16.1:54818
time="2019-06-19T12:11:31Z" level="warning" msg="Source terminated" bytes=557 err=read tcp 192.168.16.2:8666->192.168.16.1:54814: use of closed network connection name="postgres:5432"
time="2019-06-19T12:11:31Z" level="warning" msg="Destination terminated" name="postgres:5432" bytes=479 err=readfrom tcp 192.168.16.2:45194->192.168.16.3:5432: write tcp 192.168.16.2:45194->192.168.16.3:5432: write: broken pipe

About this issue

Original URL
State: closed
Created 5 years ago
Reactions: 1
Comments: 18 (6 by maintainers)

Commits related to this issue

Reproducer for the Shopify/toxiproxy#254 — committed to kwart/test-app by kwart 2 years ago
Reproducer for the Shopify/toxiproxy#254 — committed to kwart/test-app by kwart 2 years ago

Most upvoted comments

Thank you @mikael-carlstedt and @kwart. It helped me to reproduce the problem.

miry on Sep 2, 2022

Here is a shell+docker version of my reproducer: reproducer.zip

kwart on Aug 30, 2022

It works in Hazelcast’s tests. Thank you for the fix, @miry.

kwart on Sep 10, 2022

I am experiencing the same issue with toxiproxy-server 2.3 running on a CentOS Linux ec2 instance, so no docker networking involved. Quite a lot of traffic going over that proxy at the time when the toxicity is removed, so that race condition identified by @kwart looks like a very promising lead.

mikael-carlstedt on Aug 26, 2022

We also hit this problem in one of Hazelcast enterprise tests. When we are deleting a toxic it hangs. (We are running the toxiproxy through the testcontainers.)

I spent some time investigating the issue and it seems as a race condition between https://github.com/Shopify/toxiproxy/blob/v2.4.0/link.go#L231

and https://github.com/Shopify/toxiproxy/blob/v2.4.0/toxics/toxic.go#L93-L99 (which is called from the https://github.com/Shopify/toxiproxy/blob/v2.4.0/link.go#L201)

kwart on Jul 29, 2022

Figured it out.

Seems like something might be wonky inside toxiproxy regarding url parsing and spaces when deleting a toxic…

I changed the name from kafka-1 downstream latency to downstream_latency and everything works great now. No hangs, everything working as expected. And yes, I was sending the name url encoded when making the DELETE request.

Hopefully someone finds this useful in their Googling and saves them a few days of their life 😉

adambair on Dec 6, 2019