Patch for issue #48 Enable logging of SQL statements

[fluffybeing]

@djmitche another way to do this is. Let me know which would be preferred.

import logging

logging.basicConfig()
logging.getLogger('sqlalchemy.engine').setLevel(logging.INFO)

[djmitche]

Ah, good find - that would get us logging instead of printing which would definitely be more readable. Do you want to switch the pull req to adopt your suggestion?

Looks like Travis noticed some pep8 failures, too. You can run ./validate.sh before pushing to double-check.

[djmitche]

And thanks, and welcome!

[fluffybeing]

@djmitche Ok I am making changes for second implementation.

[Callek]

nit: typo in comment

[fluffybeing]

@Callek oh I missed the spelling. Thanks

[djmitche]

If I run this as-is, then everything gets logged twice:

2015-01-29 08:27:44,685 172.16.1.10 - - [29/Jan/2015 08:27:44] "GET /tokenauth HTTP/1.1" 301 -
INFO:sqlalchemy.engine.base.Engine:SHOW VARIABLES LIKE 'sql_mode'
2015-01-29 08:27:44,742 SHOW VARIABLES LIKE 'sql_mode'
INFO:sqlalchemy.engine.base.Engine:()
2015-01-29 08:27:44,742 ()
INFO:sqlalchemy.engine.base.Engine:SELECT DATABASE()
2015-01-29 08:27:44,745 SELECT DATABASE()
INFO:sqlalchemy.engine.base.Engine:()
2015-01-29 08:27:44,745 ()
INFO:sqlalchemy.engine.base.Engine:show collation where `Charset` = 'utf8' and `Collation` = 'utf8_bin'
2015-01-29 08:27:44,746 show collation where `Charset` = 'utf8' and `Collation` = 'utf8_bin'
INFO:sqlalchemy.engine.base.Engine:()
2015-01-29 08:27:44,746 ()
INFO:sqlalchemy.engine.base.Engine:SELECT CAST('test plain returns' AS CHAR(60)) AS anon_1
2015-01-29 08:27:44,749 SELECT CAST('test plain returns' AS CHAR(60)) AS anon_1
INFO:sqlalchemy.engine.base.Engine:()
2015-01-29 08:27:44,749 ()
INFO:sqlalchemy.engine.base.Engine:SELECT CAST('test unicode returns' AS CHAR(60)) AS anon_1
2015-01-29 08:27:44,750 SELECT CAST('test unicode returns' AS CHAR(60)) AS anon_1
INFO:sqlalchemy.engine.base.Engine:()
2015-01-29 08:27:44,750 ()
INFO:sqlalchemy.engine.base.Engine:SELECT CAST('test collated returns' AS CHAR CHARACTER SET utf8) COLLATE utf8_bin AS anon_1
2015-01-29 08:27:44,752 SELECT CAST('test collated returns' AS CHAR CHARACTER SET utf8) COLLATE utf8_bin AS anon_1
INFO:sqlalchemy.engine.base.Engine:()
2015-01-29 08:27:44,752 ()
INFO:sqlalchemy.engine.base.Engine:BEGIN (implicit)
2015-01-29 08:27:44,754 BEGIN (implicit)
INFO:sqlalchemy.engine.base.Engine:SELECT auth_tokens.id AS auth_tokens_id, auth_tokens.description AS auth_tokens_description, auth_tokens._permissions AS auth_tokens__permissions 
FROM auth_tokens
2015-01-29 08:27:44,755 SELECT auth_tokens.id AS auth_tokens_id, auth_tokens.description AS auth_tokens_description, auth_tokens._permissions AS auth_tokens__permissions 
FROM auth_tokens
INFO:sqlalchemy.engine.base.Engine:()
2015-01-29 08:27:44,755 ()
INFO:sqlalchemy.engine.base.Engine:ROLLBACK
2015-01-29 08:27:44,770 ROLLBACK

The main issue here is that the logging configuration is done at the top level of the module, so that it only happens once, and before the app configuration is loaded.

In fact, setup of the Python logging module is already handled by RelengAPI: https://github.com/mozilla/build-relengapi/blob/master/relengapi/lib/subcommands.py#L12. It's just the last line of your suggestion (logging.getLogger('sqlalchemy.engine').setLevel(logging.INFO)) that needs to be added, with the level depending on the value of SQLALCHEMY_DB_LOG.

A few other minor notes:

• https://github.com/mozilla/build-relengapi/blob/master/relengapi/blueprints/base/__init__.py#L72 enables logging during test runs. Please double-check that tests still have queries logged after your patch
• the configuration variable should be in all caps - SQLALCHEMY_DB_LOG, not SQLAlchemy_DB_LOG
• needs tests -- in particular, I think there's no way to disable the logging with the patch as it stands
• needs documentation in https://github.com/mozilla/build-relengapi/blob/master/docs/deployment/@relengapi/config.rst

[djmitche]

@rahulrrixe I didn't mean to scare you away with all that!

[fluffybeing]

@djmitche haha 👍 BTW I am not scared. Yesterday I caught up with some work at University. The problem: I am facing is that I am not able to authenticate on api services and so not able to see the log and debug it. So can you help how can I setup the authentication to get admin rights.

Also while building docs I am getting this error

(releng)MC-INMU-DIM042L:build-relengapi rranjan$ relengapi build-docs
2015-01-31 03:01:49,372 Using default settings; to configure relengapi, set RELENGAPI_SETTINGS to point to your settings file
2015-01-31 03:01:49,830 registering blueprint badpenny
2015-01-31 03:01:49,832 registering blueprint base
2015-01-31 03:01:49,832 registering blueprint tokenauth
2015-01-31 03:01:49,834 The `SECRET_KEY` setting is not set; tokens will be signed with an insecure, static key
2015-01-31 03:01:49,834 registering blueprint auth
2015-01-31 03:01:49,835 registering blueprint docs
2015-01-31 03:01:49,977 docs have not been built
2015-01-31 03:01:49,978 setting per-process session key - sessions will be reset on process restart
Running Sphinx v1.3b2
Traceback (most recent call last):
  File "/Users/rranjan/.virtualenvs/releng/bin/relengapi", line 9, in <module>
    load_entry_point('relengapi==1.1.0', 'console_scripts', 'relengapi')()
  File "/Users/rranjan/.virtualenvs/releng/lib/python2.7/site-packages/relengapi-1.1.0-py2.7.egg/relengapi/lib/subcommands.py", line 62, in main
    args._subcommand.run(parser, args)
  File "/Users/rranjan/.virtualenvs/releng/lib/python2.7/site-packages/relengapi-1.1.0-py2.7.egg/relengapi/blueprints/docs/__init__.py", line 134, in run
    support.build()
  File "/Users/rranjan/.virtualenvs/releng/lib/python2.7/site-packages/Sphinx-1.3b2-py2.7.egg/sphinx/websupport/__init__.py", line 121, in build
    'websupport', status=self.status, warning=self.warning)
  File "/Users/rranjan/.virtualenvs/releng/lib/python2.7/site-packages/Sphinx-1.3b2-py2.7.egg/sphinx/application.py", line 125, in __init__
    confoverrides or {}, self.tags)
  File "/Users/rranjan/.virtualenvs/releng/lib/python2.7/site-packages/Sphinx-1.3b2-py2.7.egg/sphinx/config.py", line 236, in __init__
    with cd(dirname):
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/Users/rranjan/.virtualenvs/releng/lib/python2.7/site-packages/Sphinx-1.3b2-py2.7.egg/sphinx/util/osutil.py", line 210, in cd
    os.chdir(target_dir)
OSError: [Errno 2] No such file or directory: '/Users/rranjan/.virtualenvs/releng/relengapi-docs'

I think that target directory should be docs instead of relengapi-docs.

[djmitche]

To set up authentication, put something like this in your settings.py:

RELENGAPI_AUTHENTICATION = { 
    'type': 'browserid',
}

RELENGAPI_PERMISSIONS = { 
    'type': 'static',
    'permissions': {
        'youremail@yourdomain.com': [
            'base.tokens.view',
            'base.tokens.issue',
            'base.tokens.revoke',
            'base.badpenny.view',
        ],  
    },  
    'lifetime': 3,
}

Then you should be able to login using browserid.

I'm not sure what to make of the docs error, but let's get another issue on file to take care of that separately.

[djmitche]

@rahulrrixe how's this going?

[fluffybeing]

@djmitche sorry for this much delay, I had to join MIT media lab workshop for around one and half week and so I could't able to work on it as I returned back from there yesterday. I will complete this today and thank you for pinging me for this 👍

[fluffybeing]

I have added the different levels for log

[djmitche]

@rahulrrixe I haven't heard from you in three weeks or so -- any chance you'll get time to finish this up?

[fluffybeing]

@djmitche I am really sorry on this. I had kept this pr open for so long time.

[djmitche]

Closed in favor of #212