DEBUG output in docker is not working

[rcortez-la]

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]

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]

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]

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]

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]

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).