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

Logs dont show up if running in Kubernetes #1130

Open
richstokes opened this issue Feb 21, 2019 · 12 comments
Open

Logs dont show up if running in Kubernetes #1130

richstokes opened this issue Feb 21, 2019 · 12 comments

Comments

@richstokes
Copy link

Really strange. I see all the logs/output from bottle when running on a local docker container. Running the same image on Kubernetes and the bottle output is hidden. Other output from my python shows up fine.

Any ideas why this would happen?

@oz123
Copy link
Contributor

oz123 commented Feb 21, 2019

hmm... this is a kubernetes problem probably and not a bottle problem. Can you post your docker file and your deployment ?

It's not clear if it is just crush logs or all logs. My initial guess was that it's k8s, but I think now that it's a problem of python configuration or logging. It's not clear how logs are output.

@richstokes
Copy link
Author

Sure, dockerfile is:

FROM python:3.7-alpine

RUN apk update
RUN apk upgrade
RUN apk add dumb-init git bash

RUN pip install boto3 pymysql bottle
ADD code.py /

ENTRYPOINT ["/usr/bin/dumb-init", "--"]
CMD [ "python", "./code.py" ]

The kubernetes deployment is very straight forward - just loads the image and exposes a service.

It's really strange. Sometimes I get some logs out of the app but not others. I read that setting an env var PYTHONUNBUFFERED to 0 may help, but this made no difference.

@oz123
Copy link
Contributor

oz123 commented Feb 22, 2019

Why do you need dump init? Just run bottle with uwsgi in the front and you should see all the logs.

Here is a container I use with bottle and uwsgi

https://github.com/oz123/docker-pypi

@BeardOverflow
Copy link

As oz123 said, this is a Kubernetes problem. The Kubernetes console is buffering the output of your application. This buffer will release as soon as a operation flush is invoked or reach its size limit. In order to deal it, specify an environment variable PYTHONUNBUFFERED=1 for forcing stdout/stderr to be totallty unbuffered. Or wrap your sys.stdout and sys.stderr in another object like ps_mem.py.
Also, I would suggest to set PYTHONIOENCODING=UTF-8 considering that some Docker images doesn't ship any locale and your application could raise an UnicodeEncodeError. In other words, by default LANG=C is set instead of a subset of UTF-8 as LANG=en_US.UTF-8. (If you are using an official Debian/Ubuntu image, remember to install locales and locales-all packages).

More info at:
[1] https://eklitzke.org/stdout-buffering
[2] https://gist.github.com/opera443399/0fb9b7b4ce3f37045fdd33639279e6a1
[3] https://github.com/sclorg/s2i-python-container/blob/master/3.7/Dockerfile.fedora
[4] sclorg/s2i-python-container#157
[5] https://docs.python.org/2/using/cmdline.html#envvar-PYTHONUNBUFFERED
[6] https://raw.githubusercontent.com/pixelb/ps_mem/master/ps_mem.py

@abitrolly
Copy link

This is most likely a Python 3 problem and not of Kubernetes. The Python 3 is probably buffering stdout if the stdout is not attached to terminal.

https://stackoverflow.com/questions/29663459/python-app-does-not-print-anything-when-running-detached-in-docker
https://unix.stackexchange.com/questions/182537/write-python-stdout-to-file-immediately

The official docs are missing this topic. The only bit of info I could find is https://docs.python.org/3.8/using/cmdline.html?#cmdoption-u and it missing the description of the Python 3 when stdout is redirected. There is a change message.

Changed in version 3.7: The text layer of the stdout and stderr streams now is unbuffered.

But I have no idea what is the text layer of stdout and stderr.

@abitrolly
Copy link

Filled the bug upstream https://bugs.python.org/issue41449

@oz123
Copy link
Contributor

oz123 commented Jul 31, 2020

Without any code for the logging configuration or the application it is hard to say. I run multiple (>20) bottle based apps in k8s for a good while now and I don't have this problem.
I'm using the normal logging framework from the STL.

@abitrolly
Copy link

@oz123 can you show the Dockerfile for those apps?

@oz123
Copy link
Contributor

oz123 commented Jul 31, 2020

The docker file alone is useless, you need also the configuration of the WSGI server. I use uWSGI, see the option --log-master

$ cat ../docker/Dockerfile
FROM docker.io/python:3.6-alpine AS base
MAINTAINER  Oz Tiram <[email protected]>

RUN apk update && \
    apk add g++ libffi-dev git openssl-dev && \
    pip3 install --upgrade pip && \
    pip3 install pipenv

ARG ENV
#
ENV YOUR_ENV=${YOUR_ENV} \
  PYTHONFAULTHANDLER=1 \
  PYTHONUNBUFFERED=1 \
  PYTHONHASHSEED=random \
  PIP_NO_CACHE_DIR=off \
  PIP_DISABLE_PIP_VERSION_CHECK=on \
  PIP_DEFAULT_TIMEOUT=100
#
#
WORKDIR /run/app
#
#
ADD requirements.txt /run/app/
RUN python -m venv venv
RUN /run/app/venv/bin/pip install -r /run/app/requirements.txt
RUN /run/app/venv/bin/pip install uwsgi
#
FROM python:3.6-alpine as smallimage
COPY --from=base /run/app /run/app
#
WORKDIR /run/app
#
RUN deluser xfs # remove uid 33 which is www-data in debian
RUN adduser -D app --uid 33 && \
	test -d /var/lib/app/db || mkdir -pv /var/lib/app/db && \
	chown -vR app:app /var/lib/app/

ADD docker/entrypoint.sh /usr/bin/
ADD tiny /run/app/tiny
ADD apps /run/app/apps/
ADD manage.py /run/app/
ADD app.wsgi /run/app/

# Note: SQLite requires this directory to be writable by uid 33
VOLUME ["/var/lib/app/db"]
#
EXPOSE 9001
USER app
#
CMD ["/usr/bin/entrypoint.sh"]

$ cat ./docker/entrypoint.sh 
#!/bin/sh

UWSGI_PORT="${UWSGI_PORT:-9001}"
UWSGI_PROCS=${UWSGI_PROCS:-4}
UWSGI_THREADS=${UWSGI_THREADS:-4}

export APP_INSTALL_DIR=/run/app/
export PRODUCTION_DB=${PRODUCTION_DB:-/var/lib/app/db/production.db}
chdir /run/app

# if you want to use python's reference server ...
# good for debugging, don't use in production
#exec python3 swaet.py serve -p 9001
export PATH=/run/app/venv/bin:$PATH

exec uwsgi --need-app \
	--honour-stdin \
	--pythonpath /run/app \
	--processes "${UWSGI_PROCS}" \
	--threads "${UWSGI_THREADS}" --http-socket 0.0.0.0:"${UWSGI_PORT}" \
	--wsgi-file=/run/app/app.wsgi --callable=wsgi_app --master \
	--static-map /static/front=/run/app/apps/front/assets \
	--log-master \
	--logformat 'pid: %(pid)|app: -|req: -/-] %(var.HTTP_X_REAL_IP) (%(user)) {%(vars) vars in %(pktsize) bytes} [%(ctime)] %(method) %(uri) => generated %(rsize) bytes in %(msecs) msecs (%(proto) %(status)) %(headers) headers in %(hsize) bytes (%(switches) switches on core %(core))'

@abitrolly
Copy link

PYTHONUNBUFFERED=1 \

I would remove this and see what happens.

@oz123
Copy link
Contributor

oz123 commented Jul 31, 2020

If I remove this the stdout is unbuffered. So text is immediately flushed to output. Having a buffered output, just makes the text flush later.
Also note: that as version 3.7 the streams are unbuffered by default.
Let me quote:

Setting PYTHONUNBUFFERED=TRUE or PYTHONUNBUFFERED=1 (they are equivalent) allows for log messages to be immediately dumped to the stream instead of being buffered. This is useful for receiving timely log messages and avoiding situations where the application crashes without emitting a relevant message due to the message being "stuck" in a buffer.

Since the OP uses python3.7 I assume that stderr and stdout aren't buffered.
@richstokes are you simply using print or are you using logging

@abitrolly
Copy link

If I remove this the stdout is unbuffered.

@oz123 that's strange. If PYTHONUNBUFFERED=1 is removed, the stdout should become buffered and text should not be immediately visible.

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

No branches or pull requests

4 participants