Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Access/print services logs #13

Open
arnuschky opened this issue Oct 9, 2017 · 22 comments · May be fixed by #112
Open

Access/print services logs #13

arnuschky opened this issue Oct 9, 2017 · 22 comments · May be fixed by #112

Comments

@arnuschky
Copy link

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
Copy link
Contributor

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
Copy link
Author

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
Copy link
Contributor

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
Copy link
Author

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
Copy link

butla commented Nov 17, 2017

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
Copy link

butla commented Nov 17, 2017

Ok, I've made something that works perfectly for me - butla@c37ac82
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
Copy link
Contributor

AndreLouisCaron commented Nov 18, 2017

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
Copy link
Author

arnuschky commented Nov 19, 2017

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
Copy link
Contributor

@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
Copy link
Contributor

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
Copy link
Contributor

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

@butla
Copy link

butla commented Nov 19, 2017

@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
Copy link
Contributor

@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
Copy link
Author

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
Copy link

butla commented Nov 20, 2017

@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
Copy link

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

@butla
Copy link

butla commented Mar 10, 2020

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

@tumbl3w33d
Copy link

tumbl3w33d commented Jul 17, 2020

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
Copy link

+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
Copy link

mapattacker commented Oct 3, 2021

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
Copy link

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
Copy link

kuza55 commented May 14, 2024

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

9 participants