Logging authenticated_userid, effective_principals has side effects

[digitalresistor]

I have some views that don't require any permissions at all, and thus don't require access to any cookies or user authentication information.

I am using pyramid_authsanity, my authentication policy that tries to be a little smarter, such as automatically adding "Vary: Cookie" if the request may change because of the cookie.

Due to changes in pyramid_debugtoolbar<=2.5 authenticated_userid and effective_principals is grabbed from the request, this has my authentication policy add the vary using a response callback. This callback is called on the response I am sending back to the client, in my current case a FileResponse. This led to some head scratching because initially I didn't realise what was going on... since my view was definitely not touching my authentication/authorization yet I was seeing logs accessing those database tables.

Side note: This also leads to the interesting case whereby a new transaction is implicitly created, but never seems to be rolled back like all other transactions:

Starting server in PID 98782.
serving on http://0.0.0.0:6543
2016-05-18 22:55:43,554 DEBUG [fulgent:109][waitress] route matched for url http://alexandra.local:6543/api/v1.0/content/b5ae3d38-42c7-42db-b947-709d3b15474a; route_name: 'main', path_info: '/api/v1.0/content/b5ae3d38-42c7-42db-b947-709d3b15474a', pattern: '/*traverse', matchdict: {'traverse': ('api', 'v1.0', 'content', 'b5ae3d38-42c7-42db-b947-709d3b15474a')}, predicates: ''
2016-05-18 22:55:43,555 DEBUG [fulgent:351][waitress] debug_authorization of url http://alexandra.local:6543/api/v1.0/content/b5ae3d38-42c7-42db-b947-709d3b15474a (view name '' against context <fulgent.traversal.Object object at 0x10e9a1400>): Allowed (NO_PERMISSION_REQUIRED)
2016-05-18 22:55:43,569 INFO  [sqlalchemy.engine.base.Engine:1097][waitress] select version()
2016-05-18 22:55:43,570 INFO  [sqlalchemy.engine.base.Engine:1100][waitress] {}
2016-05-18 22:55:43,572 INFO  [sqlalchemy.engine.base.Engine:1097][waitress] select current_schema()
2016-05-18 22:55:43,572 INFO  [sqlalchemy.engine.base.Engine:1100][waitress] {}
2016-05-18 22:55:43,574 INFO  [sqlalchemy.engine.base.Engine:1192][waitress] SELECT CAST('test plain returns' AS VARCHAR(60)) AS anon_1
2016-05-18 22:55:43,574 INFO  [sqlalchemy.engine.base.Engine:1193][waitress] {}
2016-05-18 22:55:43,575 INFO  [sqlalchemy.engine.base.Engine:1192][waitress] SELECT CAST('test unicode returns' AS VARCHAR(60)) AS anon_1
2016-05-18 22:55:43,575 INFO  [sqlalchemy.engine.base.Engine:1193][waitress] {}
2016-05-18 22:55:43,576 INFO  [sqlalchemy.engine.base.Engine:1097][waitress] show standard_conforming_strings
2016-05-18 22:55:43,576 INFO  [sqlalchemy.engine.base.Engine:1100][waitress] {}
2016-05-18 22:55:43,577 INFO  [sqlalchemy.engine.base.Engine:646][waitress] BEGIN (implicit)
2016-05-18 22:55:43,578 INFO  [sqlalchemy.engine.base.Engine:1097][waitress] SELECT objects.id AS objects_id, objects.entity_id AS objects_entity_id, objects.path AS objects_path, objects.type AS objects_type, objects.created AS objects_created, objects.updated AS objects_updated 
FROM objects 
WHERE objects.id = %(param_1)s
2016-05-18 22:55:43,578 INFO  [sqlalchemy.engine.base.Engine:1100][waitress] {'param_1': UUID('b5ae3d38-42c7-42db-b947-709d3b15474a')}
2016-05-18 22:55:43,581 INFO  [sqlalchemy.engine.base.Engine:666][waitress] ROLLBACK
2016-05-18 22:55:43,585 INFO  [sqlalchemy.engine.base.Engine:646][waitress] BEGIN (implicit)
2016-05-18 22:55:43,587 INFO  [sqlalchemy.engine.base.Engine:1097][waitress] SELECT user_tickets.ticket AS user_tickets_ticket, user_tickets.user_id AS user_tickets_user_id, user_tickets.remote_addr AS user_tickets_remote_addr, user_tickets.created AS user_tickets_created, users_1.email AS users_1_email, users_1.id AS users_1_id, users_1.entity_id AS users_1_entity_id, users_1.name AS users_1_name, users_1.phone AS users_1_phone, users_1.credentials AS users_1_credentials, users_1.created AS users_1_created, users_1.updated AS users_1_updated 
FROM users, user_tickets LEFT OUTER JOIN users AS users_1 ON users_1.id = user_tickets.user_id 
WHERE users.email IS NULL AND user_tickets.ticket = %(ticket_1)s 
 LIMIT %(param_1)s
2016-05-18 22:55:43,587 INFO  [sqlalchemy.engine.base.Engine:1100][waitress] {'param_1': 1, 'ticket_1': 'None'}

This thus has the interesting side effect that with the debug toolbar in place, we have a whole bunch of open transactions on PostgreSQL when using pyramid_debugtoolbar>=2.5. After 4 requests, which is the amount of threads I have in waitress:

postgres=# select count(*) as cnt, usename from pg_stat_activity GROUP BY usename;
 cnt | usename  
-----+----------
   5 | xistence
(1 row)

[mmerickel]

Duplicate of #261.

[digitalresistor]

Sorry, didn't realise it was a dupe.