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

Log services as they run (start capturing output immediately) #43

Merged
merged 1 commit into from
Feb 7, 2022

Conversation

ScottFreeCode
Copy link
Contributor

@ScottFreeCode ScottFreeCode commented Feb 4, 2022

Fixes #36 by asking Docker to pipe the logs to a file as the next action after attempting to start the container.

The disadvantage of this approach is that, as long as we're using docker container logs --follow instead of piping the container run command itself to the file, there's a remote possibility that a startup failure could be missed if it is literally faster than the time it takes for Docker+Python to finish the run CLI command and execute the logs command.

That could theoretically be fixed by changing the strategy internal to __run_image. EDIT: or by combining this with #42! I outsmarted myself apparently.

See also #42

@@ -94,14 +94,18 @@ def __build_env_str(self, environment_vars: List[Tuple[str, str]] = []) -> str:
additional_params += f' -e {var}="{value}"'
return additional_params[1:]

def __run_image(self, additional_params: str, image: str, hostname: str = None) -> str:
def __run_image(self, additional_params: str, image: str, log_path: Optional[str], hostname: str = None) -> str:
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The use of Optional is patterned after __execute_image (line 111/115, below) but requires the parameter to be before hostname, meaning the __run_image call (line 52, above) has to add log_path as the second-last parameter rather than the last. We could instead use log_path: str = None and make it the last parameter. I am not deeply familiar with Optional in Python, couldn't say why __execute_image used it.

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe the use of Optional here was to convey that log_path is a required param, but could be None if logging is disabled

Comment on lines 104 to 111
result = subprocess.run(command, shell=True, stdout=subprocess.DEVNULL)
if log_path:
common.logger.debug(f'Writing container logs: {log_path}')
with open(log_path, 'w') as file:
subprocess.Popen(['docker', 'container', 'logs', '--follow', container_id], stdout=file)
if result.returncode is not 0:
raise exceptions.ContainerException(
f'Container image {image} could not be started. Ensure Docker is running and ports are not already in '
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of running docker container logs … we could alter the docker run call as follows:

  • subprocess.Popen instead of subprocess.run to enable it to continue in the background.
  • Remove -d from the command so Docker will print the logs.
  • If there is a logfile then pipe stdout of the container itself to the file.

However, this would require a change from the returncode strategy for throwing an exception if Docker itself cannot even start. I am not sure how to handle that.

If we can solve that problem, then we can make it so that there is zero risk of the container dying before we can capture its logs. (Right now the risk is small. I got the logs when I tested by adding the availability_endpoint parameter and adding an exception to the Python app/main.py, which was how I tested the log capturing with a failure to become healthy on both PRs.)

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good idea. I think this is a solid solution for the time being, but if we start to see containers fail without logs we can re-evaluate

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I hadn't planned on both PRs being merged together, thinking of them as alternatives to each other with different tradeoffs; but now that I look at the result of combining them, not autoremoving the container (the other PR) also eliminates the risk here that the container could die faster than we can connect to it for log output. So essentially we've now got the best of both worlds: logs begin writing immediately and cannot be missed!

@shanejansen shanejansen changed the base branch from master to 1.4.1 February 7, 2022 02:46
@shanejansen shanejansen merged commit cd28383 into shanejansen:1.4.1 Feb 7, 2022
@ScottFreeCode ScottFreeCode deleted the fix-36/log-from-start branch February 7, 2022 11:20
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 this pull request may close these issues.

Service logs do not cover immediate startup failures
2 participants