Opened 9 years ago
Closed 9 years ago
#12733 closed defect (cantfix)
OperationalError: terminating connection due to administrator commandSSL connection has been closed unexpectedly
Reported by: | Owned by: | Steffen Hoffmann | |
---|---|---|---|
Priority: | normal | Component: | AccountManagerPlugin |
Severity: | normal | Keywords: | |
Cc: | Trac Release: | 1.0 |
Description
How to Reproduce
While doing a GET operation on /browser
, Trac issued an internal error.
I had left a "Browse source" tab open overnight in Chrome. In the morning I clicked on the drop down of the default repository to select a branch I wished to view. When it started loading the new branch page the problem occurred.
The default repository is a Git one. There a total of three Git repositories associated with this Trac instance. There is also one Subversion (svn) repository. Last night the third Git repository was added.
That could have been between the time I first opened the tab and this morning when I tried accessing the branch. Request parameters:
{'path': '/'}
User agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.110 Safari/537.36
System Information
Trac | 1.0.9
|
Babel | 2.1.1
|
Docutils | 0.12
|
Genshi | 0.7 (without speedups)
|
GIT | 2.7.4
|
mod_wsgi | 3.4 (WSGIProcessGroup WSGIApplicationGroup %{GLOBAL})
|
psycopg2 | 2.6.1
|
Pygments | 2.0.2
|
Python | 2.7.6 (default, Jun 22 2015, 18:01:27) [GCC 4.8.2]
|
pytz | 2015.7
|
RPC | 1.1.5
|
setuptools | 18.8.1
|
Subversion | 1.8.8 (r1568071)
|
jQuery | 1.7.2
|
jQuery UI | 1.8.21
|
jQuery Timepicker | 1.0.1
|
Enabled Plugins
HudsonTrac | 0.5.post0
|
TracAccountManager | 0.4.4
|
TracAdvParseArgsPlugin | 0.4
|
TracExtractUrl | 0.3
|
TracIniAdminPanel | 1.0.1
|
TracMetrixPlugin | 0.1.8dev-r0
|
TracServerSideRedirectPlugin | 1.0.0
|
Tracticketstats | 3.0.0dev-r0
|
TracXMLRPC | 1.1.5
|
Python Traceback
Traceback (most recent call last): File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 554, in _dispatch_request dispatcher.dispatch(req) File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 212, in dispatch self._pre_process_request(req, chosen_handler) File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 375, in _pre_process_request chosen_handler = filter_.pre_process_request(req, chosen_handler) File "build/bdist.linux-x86_64/egg/acct_mgr/register.py", line 479, in pre_process_request if not req.session.authenticated: File "/usr/local/lib/python2.7/dist-packages/trac/web/api.py", line 355, in __getattr__ value = self.callbacks[name](self) File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 302, in _get_session return Session(self.env, req) File "/usr/local/lib/python2.7/dist-packages/trac/web/session.py", line 205, in __init__ if req.authname == 'anonymous': File "/usr/local/lib/python2.7/dist-packages/trac/web/api.py", line 355, in __getattr__ value = self.callbacks[name](self) File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 161, in authenticate authname = authenticator.authenticate(req) File "build/bdist.linux-x86_64/egg/acct_mgr/util.py", line 82, in wrap return func(self, *args, **kwds) File "build/bdist.linux-x86_64/egg/acct_mgr/web_ui.py", line 374, in authenticate return auth.LoginModule.authenticate(self, req) File "/usr/local/lib/python2.7/dist-packages/trac/web/auth.py", line 91, in authenticate req.incookie['trac_auth']) File "build/bdist.linux-x86_64/egg/acct_mgr/web_ui.py", line 448, in _get_name_for_cookie name = auth.LoginModule._get_name_for_cookie(self, req, cookie) File "/usr/local/lib/python2.7/dist-packages/trac/web/auth.py", line 244, in _get_name_for_cookie name = self._cookie_to_name(req, cookie) File "/usr/local/lib/python2.7/dist-packages/trac/web/auth.py", line 240, in _cookie_to_name for name, in self.env.db_query(sql, args): File "/usr/local/lib/python2.7/dist-packages/trac/db/api.py", line 124, in execute return db.execute(query, params) File "/usr/local/lib/python2.7/dist-packages/trac/db/util.py", line 128, in execute cursor.execute(query, params if params is not None else []) File "/usr/local/lib/python2.7/dist-packages/trac/db/util.py", line 72, in execute return self.cursor.execute(sql_escape_percent(sql), args) OperationalError: terminating connection due to administrator command SSL connection has been closed unexpectedly
Attachments (0)
Change History (8)
comment:1 Changed 9 years ago by
comment:2 Changed 9 years ago by
Can you repeatedly reproduce the issue?
No, I have not seen this issue repeat at all. I have not deliberately attempted to repeat it though so that statement is only based on observing everyday behaviour for the past week. I will try opening the Browse Source tab before home time again and see what happens in the morning.
comment:3 Changed 9 years ago by
I have just seen this issue again. It has been 7 weeks since I last spotted it.
This time all I did was open a new tab in Google Chrome, enter the URL http://trac/trac/wiki/ (using the remembered link from the search/address bar to help) and pressing enter to go to the page. I had no other Trac tabs open overnight.
So this might be repeatable (every month or two) but not often. Is there some diagnosis that I should attempt the next time this is hit?
Here is the output from the internal error report page. I don't think much should have changed with this system in the last two months. Best to record it while I have the option to though.
Python Traceback
File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 554, in _dispatch_request File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 212, in dispatch File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 375, in _pre_process_request File "build/bdist.linux-x86_64/egg/acct_mgr/register.py", line 479, in pre_process_request File "/usr/local/lib/python2.7/dist-packages/trac/web/api.py", line 355, in __getattr__ File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 302, in _get_session File "/usr/local/lib/python2.7/dist-packages/trac/web/session.py", line 205, in __init__ File "/usr/local/lib/python2.7/dist-packages/trac/web/api.py", line 355, in __getattr__ File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 161, in authenticate File "build/bdist.linux-x86_64/egg/acct_mgr/util.py", line 82, in wrap File "build/bdist.linux-x86_64/egg/acct_mgr/web_ui.py", line 374, in authenticate File "/usr/local/lib/python2.7/dist-packages/trac/web/auth.py", line 91, in authenticate File "build/bdist.linux-x86_64/egg/acct_mgr/web_ui.py", line 448, in _get_name_for_cookie File "/usr/local/lib/python2.7/dist-packages/trac/web/auth.py", line 244, in _get_name_for_cookie File "/usr/local/lib/python2.7/dist-packages/trac/web/auth.py", line 240, in _cookie_to_name File "/usr/local/lib/python2.7/dist-packages/trac/db/api.py", line 124, in execute File "/usr/local/lib/python2.7/dist-packages/trac/db/util.py", line 128, in execute File "/usr/local/lib/python2.7/dist-packages/trac/db/util.py", line 72, in execute
System information
User Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2661.102 Safari/537.36
Trac 1.0.9 Babel 2.1.1 Docutils 0.12 Genshi 0.7 (without speedups) GIT 2.8.2 mod_wsgi 3.4 (WSGIProcessGroup WSGIApplicationGroup %{GLOBAL}) psycopg2 2.6.1 Pygments 2.0.2 Python 2.7.6 (default, Jun 22 2015, 18:01:27) [GCC 4.8.2] pytz 2015.7 RPC 1.1.5 setuptools 18.8.1 Subversion 1.8.8 (r1568071) jQuery 1.7.2 jQuery UI 1.8.21 jQuery Timepicker 1.0.1
Enabled plugins
DiaVisViewPlugin 0.2.dev0 /usr/local/lib/python2.7/dist-packages/DiaVisViewPlugin-0.2.dev0-py2.7.egg HudsonTrac 0.5.post0 /usr/local/lib/python2.7/dist-packages/HudsonTrac-0.5.post0-py2.7.egg TracAccountManager 0.4.4 /srv/trac/projects/gittrac/plugins/TracAccountManager-0.4.4-py2.7.egg TracAdvParseArgsPlugin 0.4 /usr/local/lib/python2.7/dist-packages/TracAdvParseArgsPlugin-0.4-py2.7.egg TracExtractUrl 0.3 /usr/local/lib/python2.7/dist-packages/TracExtractUrl-0.3-py2.7.egg TracIniAdminPanel 1.0.1 /srv/trac/projects/gittrac/plugins/TracIniAdminPanel-1.0.1-py2.7.egg TracMetrixPlugin 0.1.8dev-r0 /srv/trac/projects/gittrac/plugins/TracMetrixPlugin-0.1.8dev_r0-py2.7.egg TracServerSideRedirectPlugin 1.0.0 /usr/local/lib/python2.7/dist-packages/TracServerSideRedirectPlugin-1.0.0-py2.7.egg Tracticketstats 3.0.0dev-r0 /usr/local/lib/python2.7/dist-packages/Tracticketstats-3.0.0dev_r0-py2.7.egg TracXMLRPC 1.1.5 /usr/local/lib/python2.7/dist-packages/TracXMLRPC-1.1.5-py2.7.egg
comment:4 Changed 9 years ago by
That is not a AccountManagerPlugin issue. I suppose that is a postgresql and/or psycopg2 issue. Please check log in your PostgreSQL or try to disable SSL in your PostgreSQL.
comment:5 Changed 9 years ago by
The postgresql-9.3-main.log files have the following in them from the past couple of days:
2016-05-19 09:29:13 BST LOG: database system was interrupted; last known up at 2016-05-18 16:55:37 BST 2016-05-19 09:29:13 BST LOG: incomplete startup packet 2016-05-19 09:29:14 BST FATAL: the database system is starting up 2016-05-19 09:29:14 BST FATAL: the database system is starting up 2016-05-19 09:29:15 BST FATAL: the database system is starting up 2016-05-19 09:29:15 BST FATAL: the database system is starting up 2016-05-19 09:29:16 BST FATAL: the database system is starting up 2016-05-19 09:29:16 BST FATAL: the database system is starting up 2016-05-19 09:29:17 BST FATAL: the database system is starting up 2016-05-19 09:29:17 BST FATAL: the database system is starting up 2016-05-19 09:29:18 BST FATAL: the database system is starting up 2016-05-19 09:29:05 BST FATAL: the database system is starting up 2016-05-19 09:29:05 BST FATAL: the database system is starting up 2016-05-19 09:29:05 BST LOG: incomplete startup packet 2016-05-19 09:29:35 BST LOG: database system was not properly shut down; automatic recovery in progress 2016-05-19 09:29:35 BST LOG: record with zero length at 0/10676668 2016-05-19 09:29:35 BST LOG: redo is not required 2016-05-19 09:29:36 BST LOG: MultiXact member wraparound protections are now enabled 2016-05-19 09:29:36 BST LOG: database system is ready to accept connections 2016-05-19 09:29:36 BST LOG: autovacuum launcher started 2016-05-24 06:27:56 BST LOG: received fast shutdown request 2016-05-24 06:27:56 BST LOG: aborting any active transactions 2016-05-24 06:27:56 BST FATAL: terminating connection due to administrator command 2016-05-24 06:27:56 BST FATAL: terminating connection due to administrator command 2016-05-24 06:27:56 BST LOG: autovacuum launcher shutting down 2016-05-24 06:27:56 BST LOG: shutting down 2016-05-24 06:27:56 BST LOG: database system is shut down 2016-05-24 06:28:13 BST LOG: database system was shut down at 2016-05-24 06:27:56 BST 2016-05-24 06:28:13 BST LOG: incomplete startup packet 2016-05-24 06:28:13 BST LOG: MultiXact member wraparound protections are now enabled 2016-05-24 06:28:13 BST LOG: database system is ready to accept connections 2016-05-24 06:28:13 BST LOG: autovacuum launcher started
I think the first bit of the log is from about the time we had a power cut and then a recovery power on. The second bit of that log is interesting though.
Looking in the syslog for that time I can see:
May 24 06:45:01 trac CRON[50485]: (root) CMD (if [ -x /etc/munin/plugins/apt_all ]; then /usr/sbin/munin-run apt_all update 7200 12 >/dev/null; elif [ -x /etc/munin/plugins/apt ]; then /usr/sbin/munin-run apt update 7200 12 >/dev/null; fi) May 24 06:49:47 trac Trac[main] ERROR: Internal Server Error: <RequestWithSession "GET '/login?referer=%2Ftrac%2Froadmap%3Fuser%3Duser.name%26format%3Dics'">, referrer None#012Traceback (most recent call last):#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 554, in _dispatch_request#012 dispatcher.dispatch(req)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 212, in dispatch#012 self._pre_process_request(req, chosen_handler)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 375, in _pre_process_request#012 chosen_handler = filter_.pre_process_request(req, chosen_handler)#012 File "build/bdist.linux-x86_64/egg/acct_mgr/register.py", line 479, in pre_process_request#012 if not req.session.authenticated:#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/api.py", line 355, in __getattr__#012 value = self.callbacks[name](self)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 302, in _get_session#012 return Session(self.env, req)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/session.py", line 211, in __init__#012 self.get_session(sid)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/session.py", line 238, in get_session#012 super(Session, self).get_session(sid, authenticated)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/session.py", line 86, in get_session#012 """, (sid, int(authenticated))):#012 File "/usr/local/lib/python2.7/dist-packages/trac/db/util.py", line 128, in execute#012 cursor.execute(query, params if params is not None else [])#012 File "/usr/local/lib/python2.7/dist-packages/trac/db/util.py", line 72, in execute#012 return self.cursor.execute(sql_escape_percent(sql), args)#012OperationalError: terminating connection due to administrator command#012SSL connection has been closed unexpectedly#012OperationalError: terminating connection due to administrator command#012SSL connection has been closed unexpectedly May 24 06:50:01 trac CRON[51491]: (root) CMD (if [ -x /etc/munin/plugins/apt_all ]; then /usr/sbin/munin-run apt_all update 7200 12 >/dev/null; elif [ -x /etc/munin/plugins/apt ]; then /usr/sbin/munin-run apt update 7200 12 >/dev/null; fi)
So something is doing a get request as me (I substituted my user name for user.name) for the roadmap at around 06:49. I am just getting out of bed at that time of day so I wonder what it is. Further on in the logs I can see the error which brought me back here too:
May 24 09:09:02 trac trac-admin_sync: Resyncing repository history for software-1... May 24 09:09:02 trac trac-admin_sync: 3072 revisions cached. May 24 09:09:02 trac trac-admin_sync: Done. May 24 09:10:01 trac CRON[13934]: (root) CMD (if [ -x /etc/munin/plugins/apt_all ]; then /usr/sbin/munin-run apt_all update 7200 12 >/dev/null; elif [ -x /etc/munin/plugins/apt ]; then /usr/sbin/munin-run apt update 7200 12 >/dev/null; fi) May 24 09:14:34 trac Trac[main] ERROR: Internal Server Error: <RequestWithSession "GET '/wiki/'">, referrer None#012Traceback (most recent call last):#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 554, in _dispatch_request#012 dispatcher.dispatch(req)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 212, in dispatch#012 self._pre_process_request(req, chosen_handler)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 375, in _pre_process_request#012 chosen_handler = filter_.pre_process_request(req, chosen_handler)#012 File "build/bdist.linux-x86_64/egg/acct_mgr/register.py", line 479, in pre_process_request#012 if not req.session.authenticated:#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/api.py", line 355, in __getattr__#012 value = self.callbacks[name](self)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 302, in _get_session#012 return Session(self.env, req)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/session.py", line 205, in __init__#012 if req.authname == 'anonymous':#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/api.py", line 355, in __getattr__#012 value = self.callbacks[name](self)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 161, in authenticate#012 authname = authenticator.authenticate(req)#012 File "build/bdist.linux-x86_64/egg/acct_mgr/util.py", line 82, in wrap#012 return func(self, *args, **kwds)#012 File "build/bdist.linux-x86_64/egg/acct_mgr/web_ui.py", line 374, in authenticate#012 return auth.LoginModule.authenticate(self, req)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/auth.py", line 91, in authenticate#012 req.incookie['trac_auth'])#012 File "build/bdist.linux-x86_64/egg/acct_mgr/web_ui.py", line 448, in _get_name_for_cookie#012 name = auth.LoginModule._get_name_for_cookie(self, req, cookie)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/auth.py", line 244, in _get_name_for_cookie#012 name = self._cookie_to_name(req, cookie)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/auth.py", line 240, in _cookie_to_name#012 for name, in self.env.db_query(sql, args):#012 File "/usr/local/lib/python2.7/dist-packages/trac/db/api.py", line 124, in execute#012 return db.execute(query, params)#012 File "/usr/local/lib/python2.7/dist-packages/trac/db/util.py", line 128, in execute#012 cursor.execute(query, params if params is not None else [])#012 File "/usr/local/lib/python2.7/dist-packages/trac/db/util.py", line 72, in execute#012 return self.cursor.execute(sql_escape_percent(sql), args)#012OperationalError: SSL connection has been closed unexpectedly#012OperationalError: SSL connection has been closed unexpectedly May 24 09:15:01 trac CRON[14941]: (root) CMD (if [ -x /etc/munin/plugins/apt_all ]; then /usr/sbin/munin-run apt_all update 7200 12 >/dev/null; elif [ -x /etc/munin/plugins/apt ]; then /usr/sbin/munin-run apt update 7200 12 >/dev/null; fi)
Hmm.. every hour the trac copy of an SVN repo is synchronized at 9 minutes past the hour. The other cron jobs on this machine are much earlier in the day, so the 6am time might be explained by them. Odd.
Looking in the logs has not made anything leap out at me so I will try to disable SSL. I can see that it is currently enabled.
comment:6 Changed 9 years ago by
Thanks for the investigating! It seems that is the same issue of trac:#4984.
comment:8 Changed 9 years ago by
Resolution: | → cantfix |
---|---|
Status: | new → closed |
I've seen similar issues in the logs, so I'm not sure this issue is specific to AccountManagerPlugin. Can you repeatedly reproduce the issue?