Skip to content

Django freezes when using Stackdriver logging #3088

@briandeheus

Description

@briandeheus

OS: MacOS 10.11.6
Python: Python 2.7.10
Package:

Name: google-cloud-logging
Version: 0.23.1
Summary: Python Client for Stackdriver Logging
Home-page: https://github.com/GoogleCloudPlatform/google-cloud-python
Author: Google Cloud Platform
Author-email: jjg+google-cloud-python@google.com
License: Apache 2.0
Location: /Users/briandeheus/.virtualenvs/proj/lib/python2.7/site-packages
Requires: gapic-google-cloud-logging-v2, google-cloud-core, grpcio

Steps to reproduce

  1. start a new Django project
  2. set up your logging as follows:
LOGGING = {
    'version': 1,
    'handlers': {
        'stackdriver': {
            'class': 'google.cloud.logging.handlers.CloudLoggingHandler',
            'client': logging.Client()
        }
    },
    'loggers': {
        '': {
            'handlers': ['stackdriver'],
            'level': 'INFO',
            'propagate': True,
        }
}

Your app will freeze after a few seconds. I've narrowed it down by adding some print statements to the stackdriver module:

_start: Starting
_start: Started
_Run: RUN WORKER
_Run: NOT STOPPING
_Run: WAIT
[2017-03-02 08:18:44,595] DEBUG Skipping environment variable credential check because profile name was explicitly set.
Enqueue: Acquiring
Enqueue: Acquired
Enqueue: Notifying
Enqueue: Notified
Enqueue: Releasing
Enqueue: Released
[2017-03-02 08:18:44,595] DEBUG Looking for credentials via: env
_Run: COMMITING
Commit: BATCH COMMIT
 Enqueue: Acquiring
Commit: WRITE ENTRIES

The Worker class has some modified methods to achieve this:

    def _run(self):
        """The entry point for the worker thread.

        Loops until ``stopping`` is set to :data:`True`, and commits batch
        entries written during :meth:`enqueue`.
        """
        try:
            self._entries_condition.acquire()
            self.started = True
            print "_Run: RUN WORKER"
            while not self.stopping:
                print "_Run: NOT STOPPING"
                if len(self.batch.entries) == 0:
                    print "_Run: WAIT"
                    # branch coverage of this code extremely flaky
                    self._entries_condition.wait()  # pragma: NO COVER

                if len(self.batch.entries) > 0:
                    print "_Run: COMMITING"
                    self.batch.commit()

            print "_Run: STOPPING"
        finally:
            print "_Run: RELEASING"
            self._entries_condition.release()

        # main thread may be waiting for worker thread to finish writing its
        # final entries. here we signal that it's done.
        self._stop_condition.acquire()
        self._stop_condition.notify()
        self._stop_condition.release()

    def _start(self):
        """Called by this class's constructor

        This method is responsible for starting the thread and registering
        the exit handlers.
        """
        try:
            print "_start: Starting"
            self._entries_condition.acquire()
            self._thread = threading.Thread(
                target=self._run, name=self.name)
            self._thread.setDaemon(False)
            self._thread.start()
            print "_start: Started"
        finally:
            self._entries_condition.release()
            atexit.register(self._stop)

    def enqueue(self, record, message):
        """Queues up a log entry to be written by the background thread."""
        try:
            print "Enqueue: Acquiring"
            self._entries_condition.acquire()
            if self.stopping:
                print "Enqueue: Stopping"
                return
            print "Enqueue: Acquired"
            info = {'message': message, 'python_logger': record.name}
            self.batch.log_struct(info, severity=record.levelname)
            print "Enqueue: Notifying"
            self._entries_condition.notify()
            print "Enqueue: Notified"
        finally:
            print "Enqueue: Releasing"
            self._entries_condition.release()
            print "Enqueue: Released"

I've tried both the SyncTransport and the BackgroundThreadTransport but both lock up. Whether running your project in the Django development mode or using uWSGI, the end result is always the same.

Metadata

Metadata

Assignees

Labels

api: loggingIssues related to the Cloud Logging API.priority: p1Important issue which blocks shipping the next release. Will be fixed prior to next release.

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions