Error using: from twisted.python import log; log.startLogging(sys.stdout)

[w1z...@gmail.com]

Hi,

I get an error when using below with autobahn-python:

from twisted.python import log

log.startLogging(sys.stdout)

2016-05-01 20:48:53-0400 [-] Log opened.

2016-05-01 20:48:53-0400 [-] Warning: primary log target selected twice at </share/Dropbox/code/dev/motehub.com/venv/lib/python2.7/site-packages/txaio/tx.py:340> - previously selected at </share/Dropbox/code/dev/motehub.com/venv/lib/python2.7/site-packages/twisted/python/log.py:210>.  Remove one of the calls to beginLoggingTo.

2016-05-01T20:48:53-0400 Warning: primary log target selected twice at </share/Dropbox/code/dev/motehub.com/venv/lib/python2.7/site-packages/txaio/tx.py:340> - previously selected at </share/Dropbox/code/dev/motehub.com/venv/lib/python2.7/site-packages/twisted/python/log.py:210>.  Remove one of the calls to beginLoggingTo.

I get duplicate logs.

Is this a bug in our code or I use it in an wrong way?

Thanks,

Zhigang

---

$ venv/bin/crossbar version

     __  __  __  __  __  __      __     __

    /  `|__)/  \/__`/__`|__) /\ |__)  |/  \

    \__,|  \\__/.__/.__/|__)/~~\|  \. |\__/

                                        

 Crossbar.io        : 0.13.2

   Autobahn         : 0.14.0 (with JSON, MessagePack, CBOR)

   Twisted          : 16.1.1-EPollReactor

   LMDB             : 0.89/lmdb-0.9.18

   Python           : 2.7.11/CPython

 OS                 : Linux-4.4.6-300.fc23.x86_64-x86_64-with-fedora-23-Twenty_Three

 Machine            : x86_64

[Tobias Oberstein]

Hi,

not sure;)

Is this from an AutobahnPython/Twisted based WAMP component run under
Crossbar.io within a router or container worker?

fwiw, if you havent' checked:
http://txaio.readthedocs.io/en/latest/programming-guide.html#logging

Cheers,
/Tobias

[Zhigang Wang]

No crossbar, just AutobahnPython/Twisted based WAMP component running by ApplicationRunner().

To reproduce this:

1. Pull https://github.com/crossbario/autobahn-python/pull/669

2. Run autobahn-python/examples/twisted/wamp/app/serial2ws/serial2ws.py:

016-05-02 00:31:01-0400 [-] Warning: primary log target selected twice at </share/Dropbox/code/dev/motehub.com/venv/lib/python2.7/site-packages/txaio/tx.py:340> - previously selected at </share/Dropbox/code/dev/motehub.com/venv/lib/python2.7/site-packages/twisted/python/log.py:210>.  Remove one of the calls to beginLoggingTo.

2016-05-02T00:31:01-0400 Warning: primary log target selected twice at </share/Dropbox/code/dev/motehub.com/venv/lib/python2.7/site-packages/txaio/tx.py:340> - previously selected at </share/Dropbox/code/dev/motehub.com/venv/lib/python2.7/site-packages/twisted/python/log.py:210>.  Remove one of the calls to beginLoggingTo.

2016-05-02 00:31:01-0400 [-] failing WebSocket opening handshake ('WebSocket connection upgrade failed (200 - OK)')

2016-05-02T00:31:01-0400 failing WebSocket opening handshake ('WebSocket connection upgrade failed (200 - OK)')

Thanks,

Zhigang

--
You received this message because you are subscribed to a topic in the Google Groups "Autobahn" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/autobahnws/vxb4e03IUOQ/unsubscribe.
To unsubscribe from this group and all its topics, send an email to autobahnws+...@googlegroups.com.
To post to this group, send email to autob...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/autobahnws/5726D473.7080202%40gmail.com.
For more options, visit https://groups.google.com/d/optout.

[Tobias Oberstein]

Hi,

it's a only warning, but I've fixed it:

https://github.com/crossbario/autobahn-python/pull/672

Cheers,
/Tobias

Am 02.05.2016 um 06:35 schrieb Zhigang Wang:
> No crossbar, just AutobahnPython/Twisted based WAMP component running by
> ApplicationRunner().
>
> To reproduce this:
>
> 1. Pull https://github.com/crossbario/autobahn-python/pull/669
> 2. Run autobahn-python/examples/twisted/wamp/app/serial2ws/serial2ws.py:
>
> 016-05-02 00:31:01-0400 [-] Warning: primary log target selected twice at
> </share/Dropbox/code/dev/
> motehub.com/venv/lib/python2.7/site-packages/txaio/tx.py:340> - previously
> selected at </share/Dropbox/code/dev/
> motehub.com/venv/lib/python2.7/site-packages/twisted/python/log.py:210>.
> Remove one of the calls to beginLoggingTo.
> 2016-05-02T00:31:01-0400 Warning: primary log target selected twice at
> </share/Dropbox/code/dev/
> motehub.com/venv/lib/python2.7/site-packages/txaio/tx.py:340> - previously
> selected at </share/Dropbox/code/dev/

>>> motehub.com/venv/lib/python2.7/site-packages/txaio/tx.py:340>
>>> - previously selected at
>>> </share/Dropbox/code/dev/

>>> motehub.com/venv/lib/python2.7/site-packages/twisted/python/log.py:210>.
>>> Remove one of the calls to beginLoggingTo.
>>> 2016-05-01T20:48:53-0400 Warning: primary log target selected twice at
>>> </share/Dropbox/code/dev/

>>> motehub.com/venv/lib/python2.7/site-packages/txaio/tx.py:340>
>>> - previously selected at
>>> </share/Dropbox/code/dev/

[Zhigang Wang]

It's not only warning: the log get duplicated.

If I want to setup log.startLogging(sys.stdout), what is the right way to do it?

It seems our Authobahn Python code changed the behavior of twisted log.

Thanks,

Zhigang

To view this discussion on the web visit https://groups.google.com/d/msgid/autobahnws/5726EB2D.2070305%40gmail.com.

[Tobias Oberstein]

Am 02.05.2016 um 08:16 schrieb Zhigang Wang:
> It's not only warning: the log get duplicated.
>
> If I want to setup log.startLogging(sys.stdout), what is the right way to
> do it?

http://txaio.readthedocs.io/en/latest/programming-guide.html#logging

[Dave Thomas]

Hi Zhigang,

The issue is present for me too but it isn't due to changes in Autobahn, it's the txaio module that autobahn uses. When txaio creates a wrapper around the std lib logger module, it uses the root logger for everything and doesn't currently allow to specify a name for the logger so that it isn't created as root.

If you use std lib logging before OR after it looks like even though the docs state otherwise, AND your logging level is below the level you have set txaio's logger to (since it's the root logger, the log level you set get overwritten, and txaio uses info as default) then you either will see duplicate messages or none at all.

Naming your logger (and thus making it non-root), doesn't seem to do the trick unfortunately as I tried that too. Maybe I don't understand fully from the txaio docs but I have been trying to find a way to not have dup logging but I can't.

Trying to work my way around this too... I think I'll open a ticket on GitHub under txaio to see if we can have something like the below added:

# Name would allow for _TxaioLogWrapper to not call std lib logging.getLogger with no name thus defaulting to root logging instance 

def make_logger(name=None):

    logger = _TxaioLogWrapper(logging.getLogger(name))

    # remember this so we can set their levels properly once

    # start_logging is actually called

    _loggers.add(logger)

    return logger

def start_logging(name=None, out=_stdout, level='info'):

    """

    Begin logging.

    :param out: if provided, a file-like object to log to. By default, this is

                stdout.

    :param level: the maximum log-level to emit (a string)

    """

    global _log_level, _loggers, _started_logging     ****** I tried setting log level to "none" and that passes this test but isn't implemented and throws another error

    if level not in log_levels:

        raise RuntimeError(

            "Invalid log level '{0}'; valid are: {1}".format(

                level, ', '.join(log_levels)

            )

        )

    if _started_logging:

        return

    _started_logging = True

    _log_level = level

    handler = _TxaioFileHandler(out)

    logging.getLogger(name).addHandler(handler)   ****** Name here too so that root logger isn't used

    # note: Don't need to call basicConfig() or similar, because we've

    # now added at least one handler to the root logger

    logging.raiseExceptions = True  # FIXME

    level_to_stdlib = {

        'critical': logging.CRITICAL,

        'error': logging.ERROR,

        'warn': logging.WARNING,

        'info': logging.INFO,

        'debug': logging.DEBUG,

        'trace': logging.DEBUG,

    }

    logging.getLogger(name).setLevel(level_to_stdlib[level])   ****** Name here too so that root logger isn't used

    # make sure any loggers we created before now have their log-level

    # set (any created after now will get it from _log_level

    for logger in _loggers:

        logger._set_log_level(level)

[Zhigang Wang]

On Tue, May 3, 2016 at 4:03 PM, Dave Thomas <byte.l...@gmail.com> wrote:

Hi Zhigang,

The issue is present for me too but it isn't due to changes in Autobahn, it's the txaio module that autobahn uses. When txaio creates a wrapper around the std lib logger module, it uses the root logger for everything and doesn't currently allow to specify a name for the logger so that it isn't created as root.

Yes. It seems this is the root cause. 

I think autobahn-python/txaio should not configure the root logger unless been asked to. They are libraries, and how to log belongs to application. Maybe there is a reason there I don't know.

Thanks,

Zhigang

--
You received this message because you are subscribed to a topic in the Google Groups "Autobahn" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/autobahnws/vxb4e03IUOQ/unsubscribe.
To unsubscribe from this group and all its topics, send an email to autobahnws+...@googlegroups.com.
To post to this group, send email to autob...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/autobahnws/2a59ffcc-396e-4274-9847-4452c0f3d62a%40googlegroups.com.

[Gareth Bult]

I've also had a problem with this, I still get a warning on startup, but adding this sorted the actual logging issue, i.e. no duplicates ..

Just before calling reactor.run (or service.Application is you're running from twistd);

txaio.use_twisted()
txaio.start_logging(level='info')

Not entirely sure I recollect "how" this works (it seems to), but if there is an 'official' way to solve the problem I would be very interested to hear ...