"New event from client" message in terminal appears twice #445

msabramo · 2012-04-21T15:22:09Z

I send a single message to Sentry with raven-php with the captureMessage method.

The count in the Raven web UI increments by one, as expected.

But my terminal window, which is running Sentry in the foreground, shows:

New event from client 'raven-php/0.1' (id=780576c190264ef3b65445d00c51dc6c)
New event from client 'raven-php/0.1' (id=780576c190264ef3b65445d00c51dc6c)

I thought that perhaps the message was being sent to both stdout and stderr, but according to this run with annotate, both messages are going to stderr:

(sentry)[last: 0] marca@SCML-MarcA:/www/sentry$ annotate sentry start
10:55:40 I: Started sentry start
10:55:41 E: 2012-04-22 17:55:41 [2281] [INFO] Starting gunicorn 0.13.4
10:55:41 E: Starting gunicorn 0.13.4
10:55:41 E: 2012-04-22 17:55:41 [2281] [INFO] Listening at: http://0.0.0.0:9000 (2281)
10:55:41 E: Listening at: http://0.0.0.0:9000 (2281)
10:55:41 E: 2012-04-22 17:55:41 [2281] [INFO] Using worker: sync
10:55:41 E: Using worker: sync
10:55:41 E: 2012-04-22 17:55:41 [2285] [INFO] Booting worker with pid: 2285
10:55:41 E: Booting worker with pid: 2285
10:55:41 E: 2012-04-22 17:55:41 [2287] [INFO] Booting worker with pid: 2287
10:55:41 E: Booting worker with pid: 2287
10:55:41 E: 2012-04-22 17:55:41 [2289] [INFO] Booting worker with pid: 2289
10:55:41 E: Booting worker with pid: 2289
10:55:45 E: New event from client 'raven-php/0.1' (id=e20154a7cd8543868de0f5b461c935a2)
10:55:45 E: New event from client 'raven-php/0.1' (id=e20154a7cd8543868de0f5b461c935a2)

Here's where the line is being emitted:

(sentry)[last: 0] marca@SCML-MarcA:/www/sentry$ ack --nopager 'New event from client'
lib/python2.7/site-packages/sentry/web/api.py
113:        logging.info('New event from client %r (id=%%s)' % client, data['event_id'])

Here's what the printout method of logging_tree has to say:

<--""
   Level INFO
   Handler Stream <open file '<stderr>', mode 'w' at 0x100254270>
   Handler <raven.contrib.django.handlers.SentryHandler object at 0x1016ff750>
   Handler Stream <open file '<stderr>', mode 'w' at 0x100254270>
   |
   o<--[/www/sentry/lib/python2]
   |   |
   |   o<--[/www/sentry/lib/python2.7/site-packages/sentry/services/udp]
   |       |
   |       o<--"/www/sentry/lib/python2.7/site-packages/sentry/services/udp.pyc"
   |
   o<--"CSSUTILS"
   |   Level INFO
   |   Handler Stream <open file '<stderr>', mode 'w' at 0x100254270>
   |
   o<--"django"
   |   Handler <logging.NullHandler object at 0x1016ff710>
   |   |
   |   o<--[django.db]
   |   |   |
   |   |   o<--"django.db.backends"
   |   |
   |   o<--"django.request"
   |       Level ERROR
   |       Handler <django.utils.log.AdminEmailHandler object at 0x1006b5a50>
   |
   o   "gunicorn"
   |   Propagate OFF
   |   Handler Stream <open file '<stderr>', mode 'w' at 0x100254270>
   |   |
   |   o<--"gunicorn.access"
   |   |   Level INFO
   |   |
   |   o<--"gunicorn.error"
   |   |   Level INFO
   |   |   Handler Stream <open file '<stderr>', mode 'w' at 0x100254270>
   |   |
   |   o<--[gunicorn.http]
   |       |
   |       o<--"gunicorn.http.wsgi"
   |
   o   "raven"
   |   Propagate OFF
   |   Handler Stream <open file '<stderr>', mode 'w' at 0x100254270>
   |   |
   |   o<--[raven.contrib]
   |       |
   |       o<--[raven.contrib.django]
   |           |
   |           o<--[raven.contrib.django.client]
   |               |
   |               o<--"raven.contrib.django.client.DjangoClient"
   |
   o<--[sentry]
   |   |
   |   o<--[sentry.api]
   |   |   |
   |   |   o<--"sentry.api.http"
   |   |
   |   o   "sentry.errors"
   |   |   Propagate OFF
   |   |   Handler Stream <open file '<stderr>', mode 'w' at 0x100254270>
   |   |   |
   |   |   o<--[sentry.errors.api]
   |   |   |   |
   |   |   |   o<--"sentry.errors.api.http"
   |   |   |
   |   |   o<--"sentry.errors.client"
   |   |   |   |
   |   |   |   o<--"sentry.errors.client.django"
   |   |   |
   |   |   o<--"sentry.errors.coreapi"
   |   |
   |   o<--[sentry.utils]
   |       |
   |       o<--"sentry.utils.models"
   |
   o   "south"
       Propagate OFF
       Handler Stream <open file '<stderr>', mode 'w' at 0x100254270>
       Handler <south.logger.NullHandler object at 0x1021f1510>

It looks like the root logger has two StreamHandlers for stderr?

The text was updated successfully, but these errors were encountered:

msabramo · 2012-04-23T15:50:45Z

Something I don't quite understand is going on here. Somehow the code in the module sentry.conf.server is executed twice even though imported modules are typically only evaluated once (see http://stackoverflow.com/questions/2029523/how-to-prevent-a-module-from-being-imported-twice). Not sure what's going on here (cyclical imports?)

The following illustrates the problem (the print output appears twice) and fixes the problem by hacking an environment variable (using a regular global variable didn't seem to work, which is possibly a clue) so as not to set up the root logger twice:

(sentry)[last: 7] marca@SCML-MarcA:/www/sentry$ diff -u lib/python2.7/site-packages/sentry/conf/server.py.2012-04-22-114734 lib/python2.7/site-packages/sentry/conf/server.py
--- lib/python2.7/site-packages/sentry/conf/server.py.2012-04-22-114734 2012-04-22 08:41:35.000000000 -0700
+++ lib/python2.7/site-packages/sentry/conf/server.py   2012-04-23 08:52:04.000000000 -0700
@@ -162,23 +162,28 @@
 from raven.contrib.django.handlers import SentryHandler
 import logging

-# Configure root logger
-logger = logging.getLogger()
-logger.setLevel(logging.INFO)
-
-handler = logging.StreamHandler()
-handler.setLevel(logging.INFO)
-logger.addHandler(handler)
-
-# Disable django.request as it's generally useless
-logger = logging.getLogger('django.request')
-logger.propagate = False
-logger.addHandler(handler)
-
-# Configure default sentry logging
-sentry_handler = SentryHandler()
-sentry_handler.setLevel(logging.ERROR)
-setup_logging(sentry_handler)
+print '***** Here we are in sentry.conf.server %s' % (__file__)
+
+if not os.environ.get('LOGGING_CONFIGURED', False):
+    # Configure root logger
+    logger = logging.getLogger()
+    logger.setLevel(logging.INFO)
+
+    handler = logging.StreamHandler()
+    handler.setLevel(logging.INFO)
+    logger.addHandler(handler)
+
+    # Disable django.request as it's generally useless
+    logger = logging.getLogger('django.request')
+    logger.propagate = False
+    logger.addHandler(handler)
+
+    # Configure default sentry logging
+    sentry_handler = SentryHandler()
+    sentry_handler.setLevel(logging.ERROR)
+    setup_logging(sentry_handler)
+
+    os.environ['LOGGING_CONFIGURED'] = 'TRUE'

 # Configure celery
 import djcelery

Here's the output I get:

(sentry)[last: 0] marca@SCML-MarcA:/www/sentry$ sentry start
***** Here we are in sentry.conf.server /www/sentry/lib/python2.7/site-packages/sentry/conf/server.py
***** Here we are in sentry.conf.server /www/sentry/lib/python2.7/site-packages/sentry/conf/../conf/server.pyc
...
New event from client 'raven-php/0.1' (id=5134a7f56f774c48bf8ec38e71fd8118)
...

msabramo · 2012-04-23T16:00:32Z

Here are the two stack traces for the two ways that this code gets evaluated.

First

(sentry)[last: 1] marca@SCML-MarcA:/www/sentry$ sentry start
***** Here we are in sentry.conf.server /www/sentry/lib/python2.7/site-packages/sentry/conf/server.py
Traceback (most recent call last):
  File "/www/sentry/bin/sentry", line 8, in <module>
    load_entry_point('sentry==4.0.14', 'console_scripts', 'sentry')()
  File "/www/sentry/lib/python2.7/site-packages/sentry/utils/runner.py", line 93, in main
    initializer=initialize_app,
  File "/www/sentry/lib/python2.7/site-packages/logan/runner.py", line 123, in run_app
    settings_mod = import_module(default_settings)
  File "/www/sentry/lib/python2.7/site-packages/django/utils/importlib.py", line 35, in import_module
    __import__(name)
  File "/www/sentry/lib/python2.7/site-packages/sentry/conf/server.py", line 166, in <module>
    raise Exception('Here I am')
Exception: Here I am

Second

(sentry)[last: 0] marca@SCML-MarcA:/www/sentry$ sentry start
***** Here we are in sentry.conf.server /www/sentry/lib/python2.7/site-packages/sentry/conf/server.py
***** Here we are in sentry.conf.server /www/sentry/lib/python2.7/site-packages/sentry/conf/../conf/server.pyc
Traceback (most recent call last):
  File "/www/sentry/bin/sentry", line 8, in <module>
    load_entry_point('sentry==4.0.14', 'console_scripts', 'sentry')()
  File "/www/sentry/lib/python2.7/site-packages/sentry/utils/runner.py", line 93, in main
    initializer=initialize_app,
  File "/www/sentry/lib/python2.7/site-packages/logan/runner.py", line 126, in run_app
    add_settings(settings_mod)
  File "/www/sentry/lib/python2.7/site-packages/logan/settings.py", line 61, in add_settings
    setattr(settings, setting, setting_value)
  File "/www/sentry/lib/python2.7/site-packages/django/utils/functional.py", line 285, in __setattr__
    self._setup()
  File "/www/sentry/lib/python2.7/site-packages/django/conf/__init__.py", line 42, in _setup
    self._wrapped = Settings(settings_module)
  File "/www/sentry/lib/python2.7/site-packages/django/conf/__init__.py", line 87, in __init__
    mod = importlib.import_module(self.SETTINGS_MODULE)
  File "/www/sentry/lib/python2.7/site-packages/django/utils/importlib.py", line 35, in import_module
    __import__(name)
  File "/www/sentry/lib/python2.7/site-packages/sentry/conf/../conf/server.py", line 167, in <module>
    raise Exception('Here I am again')
Exception: Here I am again

msabramo · 2012-04-23T16:11:02Z

I suspect the problem is in logan.

If I do this:

(sentry)[last: 2] marca@SCML-MarcA:/www/sentry$ diff /www/sentry/lib/python2.7/site-packages/logan/runner.py.2012-04-23-090856 /www/sentry/lib/python2.7/site-packages/logan/runner.py                  
122a123
>         print "*** About to import_module(%r)" % default_settings
123a125
>         print "*** Imported module(%r)" % default_settings
125a128
>         print "*** Adding settings - %r" % settings_mod
126a130
>         print "*** Added settings"

then I get:

(sentry)[last: 0] marca@SCML-MarcA:/www/sentry$ sentry start*** About to import_module('sentry.conf.server')
***** Here we are in sentry.conf.server /www/sentry/lib/python2.7/site-packages/sentry/conf/server.pyc
*** Imported module('sentry.conf.server')
*** Adding settings - <module 'sentry.conf.server' from '/www/sentry/lib/python2.7/site-packages/sentry/conf/server.pyc'>
***** Here we are in sentry.conf.server /www/sentry/lib/python2.7/site-packages/sentry/conf/../conf/server.pyc
...

so logan/runner.py:123 causes the first evaluation of sentry.conf.server and then logan/runner.py:126 triggers the second evaluation.

msabramo · 2012-04-30T22:03:00Z

I think that this change to logan will fix the problem:

dcramer/logan#4

msabramo · 2012-04-30T22:42:41Z

Confirmed that dcramer/logan#4 or installing logan-0.2.2 fixes the problem.

msabramo closed this as completed Apr 30, 2012

github-actions bot locked and limited conversation to collaborators Dec 19, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

"New event from client" message in terminal appears twice #445

"New event from client" message in terminal appears twice #445

msabramo commented Apr 21, 2012

msabramo commented Apr 23, 2012

msabramo commented Apr 23, 2012

msabramo commented Apr 23, 2012

msabramo commented Apr 30, 2012

msabramo commented Apr 30, 2012

"New event from client" message in terminal appears twice #445

"New event from client" message in terminal appears twice #445

Comments

msabramo commented Apr 21, 2012

msabramo commented Apr 23, 2012

msabramo commented Apr 23, 2012

msabramo commented Apr 23, 2012

msabramo commented Apr 30, 2012

msabramo commented Apr 30, 2012