Access/print services logs

[arnuschky]

It would be really useful if we could access the logs of the services so that we can print those logs in case of a test failure. Without this, debugging is really hard.

Any idea how to implement this?

[AndreLouisCaron]

I'd be glad to see such a feature in pytest-docker!

Assuming you are using the default log driver, getting the logs is rather easy, simply run "docker-compose logs xyz" and capture the output to get the logs.

The part I'm not sure about is hooking into the right place to dump the output. There are several pytest logging plugins you might be able to draw inspiration from.

What flow do you have in mind? Dump all logs from all containers? What about spawning containers as a session fixture?

[arnuschky]

The linked PR simply dumps all the logs from all the registered services. Possible to be more sophisticated, but this serves my purpose for the moment. Logs are simply output to logging.debug, so users can simply filter logs using the normal Python logging package.

[AndreLouisCaron]

Thanks for taking the time to send a PR :-)

This is a good first step, but I would be somewhat inconvenienced by the dumping of all my containers' logs at the end of the test suite.

I'd be willing to merge a contribution if it had a better Pytest integration. At the moment, you can easily achieve the same result using your own fixture in conf.py.

Let me sit on this for a day or two so I can do some research on Pytest output plugins.

[arnuschky]

Sure. For me it suits me well as the logs are only dumped under the pytest-docker logger in debug level. Easy to shut up. Also, I always capture the logs, so I only get the logs displayed in case a test fails. But I understand that this isn't the default usage.

Somehow making this functionality smarter - ie dump logs only in case of test failure, or allow the user to specify/filter logs - would make sense.

[butla]

Giving my 2 cents here, as I'm also having problems by not immediately seeing what went wrong in a container when a test fails.

I'd be OK with just dumping all the output produced by docker-compose up to console when pytest fails. This may be configurable... I'll try to prepare a competing PR :)

[butla]

Ok, I've made something that works perfectly for me - https://github.com/butla/pytest-docker/commit/c37ac821360a135c0cc7502c308df1f9526d02ad But my code is awful. I need to refactor. I'll try to get a PR together in the coming weeks.

@AndreLouisCaron Is it OK if a separate stuff out to multiple files? And maybe use a bit more closures instead of classes?

[AndreLouisCaron]

Hi @butla! I'm open to all kinds of contributions and I'm not really picky for coding styles. However, I do want to make sure I understand what problems people are trying to solve before merging anything.

I looked at the code you referenced and I'm not sure how it's related to the issue reported here. Would you mind explaining why you are polling on docker-compose port and how that is related to dumping output from containers?

[arnuschky]

Rather than dumping the logs of all containers, I added the following method to Services:

    def get_logs(self, service):
        return self._docker_compose.execute('logs {}'.format(service))

That way I can selective print logs in my test fixture. For example, what I do is something along these lines:

@pytest.fixture(scope='session')
def base_scenario(docker_ip, docker_services):
    # initialize my services and check that they are up
    scenario = dict(
         service_1=...,
         service_2=....,
    )
    yield scenario

    # print logs of relevant services
    logs = docker_services.get_logs('service_2')
    for line in logs.split('\n'):
        log.info(str(line))

Then I only see the relevant logs (eg, not the ones of the db and redis, but the ones of my own code). I can freely chose what to log and how to display it (logging, prints, etc) If the test succeeds I can chose not to see anything using pytests log capturing.

[AndreLouisCaron]

@arnuschky That get_logs() method looks pretty useful and general enough to let people customize their log output. If you can prepare a PR, I'd definitely merge that.

[AndreLouisCaron]

Since capturing and showing logs in all tests (only to have them silenced by the logging module) could potentially have prohibitive overhead in some projects, I've been digging around to see if we can fetch the container logs only when tests fail.

There is a recipe in the pytest docs for checking if tests failed from within a fixture (see making test result information available in fixtures).

pytest-dev/pytest#230 is an outstanding request to make this easier. The comments contain instructions for a simplified version that is very similar to what's requested here (show logs only on test failure).

If anybody has ideas on how to piece all this together to fetch and display only relevant output, I'm all ears.

[AndreLouisCaron]

FYI, this StackOverflow answer also suggests an interesting trick: https://stackoverflow.com/a/43268134/313063.

[butla]

@AndreLouisCaron my solution does exactly that. I'm starting "docker-compose up" without "-d" and I'm not waiting for the output. With that, the output streams from compose will be joined with the main process's output. So that pytest will simply show you the output on failing tests.

Because of the way I run compose up, we need to wait for a container to appear before getting its port. I chose checking port as a function we wait for out of laziness - it was already there. But I want to refactor the code.

Please just see what happens when a test fails with my version. It may also be satisfactory for @arnuschky, and it doesn't require writing any fixtures. I feel that it goes along with pytest's spirit

[AndreLouisCaron]

@butla Ah OK, I understand now. You're using Popen to run docker-compose in foreground mode and letting it write directly to standard output. When doing this, you don't know when docker run has been invoked by docker-compose and poll until the container exists. I totally missed this when I looked at your code the first time around.

I like the idea!

Please just see what happens when a test fails with my version.

I'll make sure to try it out, but there any many different output configurations and I cannot try them all.

I'm really happy that pytest-docker is useful to other people, but I'm a bit reluctant to merge something that can have side-effects for other users because I have little time to commit to fixing this plug-in when it breaks something.

In order to get a better grasp of what you're proposing, I have a few questions:

1. Have you observed any cases of strange output interleaving? For example, pytest's output being mixed in weird ways with your container's output?
2. Have you tried combining this with a mix of capsys, capfd or other output plug-ins?
3. @arnuschky seemed to be interested in getting the output from his app, but not from databases. Do you think we can somehow filter the output using your method?

[arnuschky]

Re 3.: Yes, I realized this after my first version that simply dumped everything. I have a setup with 7-8 containers, and only half of them are relevant for debugging. I wrote the second version because it allows users to chose a) where to log to and b) from which containers to log, and c) when to log, for example using that hook implementation @AndreLouisCaron linked after one determined the test actually failed.

[butla]

@AndreLouisCaron 1) Nope it was fine. Pytest would give the output from a container on failures in the proper "Output captured during tests" section. 2) I haven't.

I haven't thought about people that may need to check the output while running Docker Compose. And that's probably wrong. I'm using pytest-docker for testing web APIs, so that's a type of application that doesn't produce any meaningful output for the user... But I see how that wouldn't be the case if you were working on some CLI tool that talks with some services.

Anyhow, I think that my approach could be the default one, since probably most people using Docker Compose in tests are in fact doing web stuff. But it should be easy to turn that off as part of configuration, and use @arnuschky's approach instead.

Of course, a good README update is warranted for these features :)

[gyermolenko]

Hi all. What is the preferred solution to see services logs atm?

[butla]

I'm not using pytest-docker at the moment, so I'll stay out of the conversation.

[tumbl3w33d]

I'm just doing my first steps with pytest(-docker) and this wish also came up in me quite early. My service didn't get ready at all and it took me a while to figure out why. I monkey-patched the plugin.py like this to get what I want and would like to see something comparable added to the lib:

    def wait_until_responsive(self, check, timeout, pause, clock=timeit.default_timer):
        """Wait until a service is responsive."""

        ref = clock()
        now = ref
        while (now - ref) < timeout:
            if check():
                return
            time.sleep(pause)
            now = clock()

        # get container logs to provide info about failure
        output = self._docker_compose.execute("logs").decode("utf-8")

        raise WaitTimeoutException(container_logs=output)

class WaitTimeoutException(Exception):

    def __init__(self, container_logs, message="Timeout reached while waiting on service!"):
        self.container_logs = container_logs
        super().__init__(message)

allows me to do

    try:
        docker_services.wait_until_responsive(
            timeout=5.0, pause=0.2, check=lambda: is_responsive(url)
        )
    except WaitTimeoutException as ex:
        logging.error(ex.container_logs)

Main motivation is to get quick feedback in CI logs when my app's .dockerignore lacks some whitelisted elements without manual local fiddling.

[awkspace]

+1 from me. If I can't see my application's logs, I can't see what's gone wrong, particularly in a CI job.

[mapattacker]

I highly concur with @awkspace, I spent 3 days trying to debug in my CI why the request keep timing-out~ In the end had to use normal docker-compose in the CI to debug the problem before resetting back to pytest-docker again.

This issue has been opened for awhile, and the solution as pointed out by @tumbl3w33d, and others, appears to be a simple one.

Is there any pending concerns, I will be happy to help address and submit a PR so that my team & I can use this lib as part of our standard integration test within our CI.

[ColeDCrawford]

Did any of these methods to dump logs ever get added to pytest-docker? Trying to debug a Github Actions run that stopped working recently and think I will need the container logs to resolve.

[kuza55]

Here is a workaround we have setup. In our conftest.py we have this fixture:

@pytest.fixture(scope="session", autouse=True)
def print_logs(docker_services):
    yield None

    print("\n")
    subprocess.run(
        f"docker compose logs <container name>",
        shell=True,
    )