locustio / locust

Write scalable load tests in plain Python 🚗💨
https://locust.cloud
MIT License
25.06k stars 3k forks source link

DEBUG output in docker is not working #1337

Closed rcortez-la closed 4 years ago

rcortez-la commented 4 years ago

Describe the bug

Using the DEBUG option in a docker-compose file is not very verbose on the terminal. Same results without DEBUG

Expected behavior

With this option and a few print("something") lines the terminal output shows important information.

Actual behavior

This is what I see using the latest build in docker with a print("access token")

ubuntu@ip-10-22-194-7:~/randlex-locust$ sudo docker-compose logs
Attaching to standalone
standalone    | Starting Locust in standalone mode...
standalone    | $ locust --web-port 8089 --loglevel DEBUG -f /mnt/locust/locustfile.py -H http://asite.org
standalone    | [2020-04-18 01:29:13,417] standalone/INFO/locust.main: Starting web monitor at http://*:8089
standalone    | [2020-04-18 01:29:13,417] standalone/INFO/locust.main: Starting Locust 0.14.5
standalone    | [2020-04-18 01:29:27,774] standalone/INFO/locust.runners: Hatching and swarming 3 users at the rate 1 users/s (0 users already running)...
standalone    | [2020-04-18 01:29:27,776] standalone/DEBUG/urllib3.connectionpool: Starting new HTTP connection (1): asite.org:80
standalone    | [2020-04-18 01:29:27,931] standalone/DEBUG/urllib3.connectionpool: http://asite.org:80 "POST /api/security/auth/token/obtain/ HTTP/1.1" 200 571
standalone    | [2020-04-18 01:29:27,932] standalone/INFO/stdout: eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJ0b2tlbl90eXBlIjoiYWNjZXNzIiwiZXhwIjoxNTg3MTc2OTY3LCJqdGkiOiI0ZWMxZmVmZmZhOWQ0NTJjYmE5MGUwZDBmNDRmYWQ5NiIsInVzZXJfaWQiOjE2LCJvcmlnaW5hbF9pYXQiOjE1ODcxNzMzNjcsInJlZnJlc2hfaW50ZXJ2YWwiOjEyMH0.dmrtk6z2Ln5T66ERmQwbDWoKNW6SW9sk-GCj0H_XC0E

Using locustio/lociust:master

ubuntu@ip-10-22-194-7:~/randlex-locust$ sudo docker-compose logs
Attaching to standalone
standalone    | Starting Locust in standalone mode...
standalone    | $ locust --web-port 8089 -f /mnt/locust/locustfile.py -H http://asite.org
standalone    | [2020-04-18 01:43:18,047] standalone/INFO/locust.main: Starting web monitor at http://*:8089
standalone    | [2020-04-18 01:43:18,056] standalone/INFO/locust.main: Starting Locust 1.0.0
standalone    | [2020-04-18 01:43:28,940] standalone/INFO/locust.runners: Hatching and swarming 3 users at the rate 1 users/s (0 users already running)...
standalone    | [2020-04-18 01:43:30,942] standalone/INFO/locust.runners: All locusts hatched: WebsiteUser: 3 (0 already running)

Steps to reproduce

docker pull locustio/locust:master lauch docker-compose ``` version: '3' services: standalone: image: "locustio/locust:master" container_name: standalone hostname: standalone ports: - "80:8089" environment: LOCUSTFILE_PATH: /mnt/locust/locustfile.py TARGET_URL: http://asite.org LOCUST_MODE: standalone LOCUST_OPTS: "--web-port 8089 --loglevel DEBUG" volumes: - ./locust-scripts:/mnt/locust ``` ### Environment - OS: ubuntu 18 and docker 18 - Python version: - Locust version: locustio/locust:master - Locust command line that you ran: sudo docker-compose up -d - Locust file contents (anonymized if necessary): I'm experimenting with SequentialTaskSet since I was having problems with @seq_task. ``` from locust import HttpLocust, SequentialTaskSet, TaskSet, task, between """from locust.exception import StopLocust""" class Keyness(SequentialTaskSet): def on_start(self): """ on_start is called when a Locust start before any task is scheduled """ """self.client.verify = False""" self.login() def on_stop(self): """ on_stop is called when the TaskSet is stopping """ self.logout() def login(self): self.response = self.client.post("/api/security/auth/token/obtain/", {"username":"loadtester", "password":"Password1"}, headers = {"Connection": "Keep-Alive"}) js = self.response.json() self.rspAcs = js["access"] print(self.rspAcs, ' ') def logout(self): self.client.post("/api/security/auth/token/obtain/", {"username":"loadtester", "password":"Password1"}) @task(1) def projects(self): self.client.get("/api/analysis/project/project/", headers= {"Authorization": "Bearer " + self.rspAcs, "Connection": "Keep-Alive"}) print(self.rspAcs, ' ') @task(1) def new_project(self): self.client.post("/api/analysis/project/project/", headers= {"Authorization": "Bearer " + self.rspAcs, "Connection": "Keep-Alive"}, json= {"project_name":"new_project"}) print(self.rspAcs, ' ') """@task def stop(self): self.interrupt()""" @task def done(self): raise StopLocust() class WebsiteUser(HttpLocust): tasks = [Keyness] wait_time = between(5, 9) ```
heyman commented 4 years ago

I've managed to reproduce this. It's caused by python's buffering of stdout. A workaround would be to set environment variable PYTHONUNBUFFERED to "1".

This should definitely be the default.

rcortez-la commented 4 years ago

I've managed to reproduce this. It's caused by python's buffering of stdout. A workaround would be to set environment variable PYTHONUNBUFFERED to "1".

This should definitely be the default.

Better with PYTHONUNBUFFERED: 1 in the environment: section in my docker-compose.yml. But only the print(self.rspAcs, ' ') where the details of GET and POST are missing.

heyman commented 4 years ago

But only the print(self.rspAcs, ' ') where the details of GET and POST are missing.

Sorry, I don't understand what you mean. Is there still some print that is missing?

rcortez-la commented 4 years ago

But only the print(self.rspAcs, ' ') where the details of GET and POST are missing.

Sorry, I don't understand what you mean. Is there still some print that is missing?

The print is fine. For reference using the latest image on docker hub, with DEBUG set, the line above the print output is valuable, example below. That line is missing when using the :master image from docker hub, although I haven't pulled the :master image since yesterday afternoon.

standalone    | [2020-04-18 01:29:27,931] standalone/DEBUG/urllib3.connectionpool: http://asite.org:80 "POST /api/security/auth/token/obtain/ HTTP/1.1" 200 571
standalone    | [2020-04-18 01:29:27,932] standalone/INFO/stdout: eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJ0b2tlbl90eXBlIjoiYWNjZXNzIiwiZXhwIjoxNTg3MTc2OTY3LCJqdGkiOiI0ZWMxZmVmZmZhOWQ0NTJjYmE5MGUwZDBmNDRmYWQ5NiIsInVzZXJfaWQiOjE2LCJvcmlnaW5hbF9pYXQiOjE1ODcxNzMzNjcsInJlZnJlc2hfaW50ZXJ2YWwiOjEyMH0.dmrtk6z2Ln5T66ERmQwbDWoKNW6SW9sk-GCj0H_XC0E

What I see now for example;

standalone    | [2020-04-18 22:30:32,204] standalone/INFO/locust.runners: Hatching and swarming 3 users at the rate 1 users/s (0 users already running)...
standalone    | eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJ0b2tlbl90eXBlIjoiYWNjZXNzIiwiZXhwIjoxNTg3MjUyNjMyLCJqdGkiOiJhYzU0NDJiOTFlZDA0Y2M5YjkzZjRkN2JlYTM0YTI2NiIsInVzZXJfaWQiOjE2LCJvcmlnaW5hbF9pYXQiOjE1ODcyNDkwMzIsInJlZnJlc2hfaW50ZXJ2YWwiOjEyMH0.Pn6udPQCvYzy77_5YVSvaZmiW3nkzAbCAa9O3wDVTjk  
standalone    | eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJ0b2tlbl90eXBlIjoiYWNjZXNzIiwiZXhwIjoxNTg3MjUyNjMyLCJqdGkiOiJhYzU0NDJiOTFlZDA0Y2M5YjkzZjRkN2JlYTM0YTI2NiIsInVzZXJfaWQiOjE2LCJvcmlnaW5hbF9pYXQiOjE1ODcyNDkwMzIsInJlZnJlc2hfaW50ZXJ2YWwiOjEyMH0.Pn6udPQCvYzy77_5YVSvaZmiW3nkzAbCAa9O3wDVTjk  

I actually have not used print("something") in the locustfile without DEBUG set in the environment, so maybe these are 2 different problems.

heyman commented 4 years ago

Ah, I see what you mean now

I believe I've fixed it in master (it'll probably take a few minutes before a new Docker image is built).