Logs dont show up if running in Kubernetes

[richstokes]

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]

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]

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]

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]

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]

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]

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

[oz123]

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]

@oz123 can you show the Dockerfile for those apps?

[oz123]

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]

PYTHONUNBUFFERED=1 \

I would remove this and see what happens.

[oz123]

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]

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.