Logging Not Outputting to Docker Logs

Using Django
1

Hi all,

I’ve run into an issue with only certain logs showing in docker-compose logs and was curious if someone here has had a similar experience.

Webserver logs work as expected (both gunicorn and default ‘manage.py runserver’) and continue to work properly as the container runs.
Any logs messages put in settings.py also show properly during initial startup of web server (and also show when I attempt to run a script).

After that, any log messages that I attempt to output via scripts (using django-extensions runscript) print to the console, but don’t show in docker-compose logs. In order to run these scripts, I’ll run an exec command like

docker-compose exec web python manage.py runscript scriptname

I have also tried abstracting away docker-compose, but the issue exists if I just use a Dockerfile and do a docker run/build. The behavior makes it seems as though unless Docker is explicitly responsible for the output of the logs via a command in docker-compose.yml, the logs won’t make it to the docker logs (this may just be a perceived cause).

I’ve tried a few logging settings within settings.py, including explicitly defining the console handler stream as sys.stdout or sys.stderr, but none have worked so far. The latest settings I’m using are below.

Logging to docker logs is desirable in order to get logs to show in kubernetes/AWS logging systems.

I would really appreciate any help if someone has any ideas. Been stuck on this one a while.

settings.py

import os
import logging.config
import sys

# Build paths inside the project like this: os.path.join(BASE_DIR, ...)
BASE_DIR = os.path.dirname(os.path.dirname(os.path.abspath(__file__)))

ENVIRONMENT = os.environ.get('ENVIRONMENT', default='production')


# Quick-start development settings - unsuitable for production
# See https://docs.djangoproject.com/en/3.0/howto/deployment/checklist/

# SECURITY WARNING: keep the secret key used in production secret!
SECRET_KEY = os.environ.get('SECRET_KEY')

# SECURITY WARNING: don't run with debug turned on in production!
DEBUG = int(os.environ.get('DEBUG', default=0))

ALLOWED_HOSTS = ['*']


# Application definition

INSTALLED_APPS = [
    'django.contrib.admin',
    'django.contrib.auth',
    'django.contrib.contenttypes',
    'django.contrib.sessions',
    'django.contrib.messages',
    'whitenoise.runserver_nostatic',
    'django.contrib.staticfiles',
    'django.contrib.sites',
    
    # Third Party
    'allauth',
    'allauth.account',
    'allauth.socialaccount',
    'allauth.socialaccount.providers.openid',
    'django_extensions',

    # Local
    'users.apps.UsersConfig',
    'pages.apps.PagesConfig',
    'meraki_rosie.apps.MerakiRosieConfig',
]

MIDDLEWARE = [
    'django.middleware.security.SecurityMiddleware',
    'whitenoise.middleware.WhiteNoiseMiddleware',
    'django.contrib.sessions.middleware.SessionMiddleware',
    'django.middleware.common.CommonMiddleware',
    'django.middleware.csrf.CsrfViewMiddleware',
    'django.contrib.auth.middleware.AuthenticationMiddleware',
    'django.contrib.messages.middleware.MessageMiddleware',
    'django.middleware.clickjacking.XFrameOptionsMiddleware',
]

ROOT_URLCONF = 'rosie.urls'

TEMPLATES = [
    {
        'BACKEND': 'django.template.backends.django.DjangoTemplates',
        'DIRS': [os.path.join(BASE_DIR, 'templates')],
        'APP_DIRS': True,
        'OPTIONS': {
            'context_processors': [
                'django.template.context_processors.debug',
                'django.template.context_processors.request',
                'django.contrib.auth.context_processors.auth',
                'django.contrib.messages.context_processors.messages',
            ],
        },
    },
]

WSGI_APPLICATION = 'rosie.wsgi.application'


# Database
# https://docs.djangoproject.com/en/3.0/ref/settings/#databases

DATABASES = {
    'default': {
        'ENGINE': 'django.db.backends.postgresql',
        'NAME': os.environ.get('DB_NAME'),
        'USER': os.environ.get('DB_USER'),
        'PASSWORD': os.environ.get('DB_PASSWORD'),
        'HOST': os.environ.get('DB_HOST'),
        'PORT': 5432
    }
}


# Password validation
# https://docs.djangoproject.com/en/3.0/ref/settings/#auth-password-validators

AUTH_PASSWORD_VALIDATORS = [
    {
        'NAME': 'django.contrib.auth.password_validation.UserAttributeSimilarityValidator',
    },
    {
        'NAME': 'django.contrib.auth.password_validation.MinimumLengthValidator',
    },
    {
        'NAME': 'django.contrib.auth.password_validation.CommonPasswordValidator',
    },
    {
        'NAME': 'django.contrib.auth.password_validation.NumericPasswordValidator',
    },
]


# Internationalization
# https://docs.djangoproject.com/en/3.0/topics/i18n/

LANGUAGE_CODE = 'en-us'

TIME_ZONE = 'UTC'

USE_I18N = True

USE_L10N = True

USE_TZ = True


# Static files (CSS, JavaScript, Images)
# https://docs.djangoproject.com/en/3.0/howto/static-files/

STATIC_URL = '/static/'
# Static files dev directory
STATICFILES_DIRS = [os.path.join(BASE_DIR, 'static'),]
# Static files prod directory
STATIC_ROOT = os.path.join(BASE_DIR, 'staticfiles')
STATICFILES_FINDERS = [
    'django.contrib.staticfiles.finders.FileSystemFinder',
    'django.contrib.staticfiles.finders.AppDirectoriesFinder',
]

# Set custom user model
AUTH_USER_MODEL = 'users.CustomUser'

# django-allauth config
LOGIN_REDIRECT_URL = 'home'
ACCOUNT_LOGOUT_URL = 'home'

SITE_ID = 1

AUTHENTICATION_BACKENDS = (
    'django.contrib.auth.backends.ModelBackend',
    'allauth.account.auth_backends.AuthenticationBackend',
)

EMAIL_BACKEND = 'django.core.mail.backends.console.EmailBackend'

ACCOUNT_SESSION_REMEMBER = True
ACCOUNT_USERNAME_REQUIRED = False
ACCOUNT_USERNAME_REQUIRED = False
ACCOUNT_AUTHENTICATION_METHOD = 'email'
ACCOUNT_EMAIL_REQUIRED = True
ACCOUNT_UNIQUE_EMAIL = True

# Production security settings
if ENVIRONMENT == 'production':
    # Cross site scripting
    SECURE_BROWSER_XSS_FILTER = True
    # Force HTTPS
    SECURE_SSL_REDIRECT = True
    # HSTS
    SECURE_HSTS_SECONDS = 3600
    SECURE_HSTS_INCLUDE_SUBDOMAINS = True
    SECURE_HSTS_PRELOAD = True
    SECURE_CONTENT_TYPE_NOSNIFF = True
    # Secure cookies
    SESSION_COOKIE_SECURE = True
    CSRF_COOKIE_SECURE = True
    # Referrer policy header
    SECURE_REFERRER_POLICY = 'origin-when-cross-origin'
    # Proxy header
    SECURE_PROXY_SSL_HEADER = ('HTTP_X_FORWARDED_PROTO', 'https')

# Logging Configuration

# Clear prev config
LOGGING_CONFIG = None

# Get loglevel from env
LOGLEVEL = os.getenv('DJANGO_LOGLEVEL', 'info').upper()

logging.config.dictConfig({
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'console': {
            'format': '%(asctime)s %(levelname)s [%(name)s:%(lineno)s] %(module)s %(process)d %(thread)d %(message)s',
        },
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'console',
        },
    },
    'loggers': {
        '': {
            'level': LOGLEVEL,
            'handlers': ['console',],
        },
    },
})

logger = logging.getLogger(__name__)

# These show in docker-compose logs
logging.critical('hello!')
logger.critical('hello again!')

docker-compose.yml

 version: '3.7'
    services:
    web:
        build: .
        # command: python /rosie/manage.py runserver 0.0.0.0:8000
        command: gunicorn rosie.wsgi -b 0.0.0.0:8000 --log-level=debug
        env_file: .env-dev
        volumes:
            - .:/rosie
        ports:
            - 8000:8000

docker-compose.yml

Dockerfile

# Pull base image
FROM python:3.8.1

# Set environment variables, console buffering and prevents python cache files being written
ENV PYTHONDONTWRITEBYTECODE 1
ENV PYTHONUNBUFFERED 1

# Set work directory
WORKDIR /rosie
VOLUME .:/rosie

# Install dependencies
COPY Pipfile Pipfile.lock /rosie/
RUN pip install pipenv && pipenv install --system

# Copy local project files to container
COPY . /rosie/

Sample Script

import logging

logger = logging.getLogger(__name__)

# prints to console, but doesn't show in docker-compose logs
logger.critical('this doesnt print')
logging.critical('nor does this')

def run():
    # same as above
    logger.critical('nor this')
    logger.critical('nor this')

Console Output

$ docker-compose exec web python manage.py runscript sample_script
2020-04-07 18:11:11,162 CRITICAL [root:294] settings 8 140175221380928 hello!
2020-04-07 18:11:11,162 CRITICAL [rosie.settings:295] settings 8 140175221380928 hello again!
2020-04-07 18:11:11,686 CRITICAL [meraki_rosie.scripts.sample_script:6] sample_script 8 140175221380928 this doesnt print
2020-04-07 18:11:11,686 CRITICAL [root:7] sample_script 8 140175221380928 nor does this
2020-04-07 18:11:11,686 CRITICAL [meraki_rosie.scripts.sample_script:12] sample_script 8 140175221380928 nor this
2020-04-07 18:11:11,686 CRITICAL [meraki_rosie.scripts.sample_script:13] sample_script 8 140175221380928 nor this
2020-04-07 18:11:11,686 DEBUG [asyncio:59] selector_events 8 140175221380928 Using selector: EpollSelector

docker-compose logs

Attaching to rosie_web_1
web_1  | [2020-04-07 18:10:59 +0000] [1] [DEBUG] Current configuration:
web_1  |   config: None
web_1  |   bind: ['0.0.0.0:8000']
web_1  |   backlog: 2048
web_1  |   workers: 1
web_1  |   worker_class: sync
web_1  |   threads: 1
web_1  |   worker_connections: 1000
web_1  |   max_requests: 0
web_1  |   max_requests_jitter: 0
web_1  |   timeout: 30
web_1  |   graceful_timeout: 30
web_1  |   keepalive: 2
web_1  |   limit_request_line: 4094
web_1  |   limit_request_fields: 100
web_1  |   limit_request_field_size: 8190
web_1  |   reload: False
web_1  |   reload_engine: auto
web_1  |   reload_extra_files: []
web_1  |   spew: False
web_1  |   check_config: False
web_1  |   preload_app: False
web_1  |   sendfile: None
web_1  |   reuse_port: False
web_1  |   chdir: /rosie
web_1  |   daemon: False
web_1  |   raw_env: []
web_1  |   pidfile: None
web_1  |   worker_tmp_dir: None
web_1  |   user: 0
web_1  |   group: 0
web_1  |   umask: 0
web_1  |   initgroups: False
web_1  |   tmp_upload_dir: None
web_1  |   secure_scheme_headers: {'X-FORWARDED-PROTOCOL': 'ssl', 'X-FORWARDED-PROTO': 'https', 'X-FORWARDED-SSL': 'on'}
web_1  |   forwarded_allow_ips: ['127.0.0.1']
web_1  |   accesslog: None
web_1  |   disable_redirect_access_to_syslog: False
web_1  |   access_log_format: %(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"
web_1  |   errorlog: -
web_1  |   loglevel: debug
web_1  |   capture_output: False
web_1  |   logger_class: gunicorn.glogging.Logger
web_1  |   logconfig: None
web_1  |   logconfig_dict: {}
web_1  |   syslog_addr: udp://localhost:514
web_1  |   syslog: False
web_1  |   syslog_prefix: None
web_1  |   syslog_facility: user
web_1  |   enable_stdio_inheritance: False
web_1  |   statsd_host: None
web_1  |   dogstatsd_tags: 
web_1  |   statsd_prefix: 
web_1  |   proc_name: None
web_1  |   default_proc_name: rosie.wsgi
web_1  |   pythonpath: None
web_1  |   paste: None
web_1  |   on_starting: <function OnStarting.on_starting at 0x7ff245b23dc0>
web_1  |   on_reload: <function OnReload.on_reload at 0x7ff245b23ee0>
web_1  |   when_ready: <function WhenReady.when_ready at 0x7ff245c3a040>
web_1  |   pre_fork: <function Prefork.pre_fork at 0x7ff245c3a160>
web_1  |   post_fork: <function Postfork.post_fork at 0x7ff245c3a280>
web_1  |   post_worker_init: <function PostWorkerInit.post_worker_init at 0x7ff245c3a3a0>
web_1  |   worker_int: <function WorkerInt.worker_int at 0x7ff245c3a4c0>
web_1  |   worker_abort: <function WorkerAbort.worker_abort at 0x7ff245c3a5e0>
web_1  |   pre_exec: <function PreExec.pre_exec at 0x7ff245c3a700>
web_1  |   pre_request: <function PreRequest.pre_request at 0x7ff245c3a820>
web_1  |   post_request: <function PostRequest.post_request at 0x7ff245c3a8b0>
web_1  |   child_exit: <function ChildExit.child_exit at 0x7ff245c3a9d0>
web_1  |   worker_exit: <function WorkerExit.worker_exit at 0x7ff245c3aaf0>
web_1  |   nworkers_changed: <function NumWorkersChanged.nworkers_changed at 0x7ff245c3ac10>
web_1  |   on_exit: <function OnExit.on_exit at 0x7ff245c3ad30>
web_1  |   proxy_protocol: False
web_1  |   proxy_allow_ips: ['127.0.0.1']
web_1  |   keyfile: None
web_1  |   certfile: None
web_1  |   ssl_version: 2
web_1  |   cert_reqs: 0
web_1  |   ca_certs: None
web_1  |   suppress_ragged_eofs: True
web_1  |   do_handshake_on_connect: False
web_1  |   ciphers: None
web_1  |   raw_paste_global_conf: []
web_1  |   strip_header_spaces: False
web_1  | [2020-04-07 18:10:59 +0000] [1] [INFO] Starting gunicorn 20.0.4
web_1  | [2020-04-07 18:10:59 +0000] [1] [DEBUG] Arbiter booted
web_1  | [2020-04-07 18:10:59 +0000] [1] [INFO] Listening at: http://0.0.0.0:8000 (1)
web_1  | [2020-04-07 18:10:59 +0000] [1] [INFO] Using worker: sync
web_1  | [2020-04-07 18:10:59 +0000] [7] [INFO] Booting worker with pid: 7
web_1  | [2020-04-07 18:10:59 +0000] [1] [DEBUG] 1 workers
web_1  | 2020-04-07 18:10:59,948 CRITICAL [root:294] settings 7 140678539028288 hello!
web_1  | 2020-04-07 18:10:59,948 CRITICAL [rosie.settings:295] settings 7 140678539028288 hello again!
1 Like
2

have you found the answer ? I’m having a similar issue :slight_smile:

3

I have the same issue as well.

5

Hey, I did find an answer, though it related more to my understanding of Kubernetes, cronjobs, and containers.

I grouped cronjobs using Kubernetes: CronJob | Kubernetes

Using this with django-extensions, there were scheduled tasks I grouped using django-extensions groups, like hourly, quarterhourly, etc.

These different cronjobs then run as their own separate containers with their own logs separate from the ‘standard’ web server that runs the persistent Django container that you use for interfacing with the website, admin, etc.

There’s a bit of syntax that needs to be accounted for in the cronjob setup. Specifically, you want to run the ‘run web server’ command detached as that command would otherwise never return. You then add the additional django-extension runjob commands related to that cronjob. It is THEN that you’ll see logs pertaining to that cronjob/container. Once the scripts finish, the container spins down until the next cronjob is scheduled.

That was probably all a bit confusing. Glad to elaborate with more specific examples if it helps, let me know.