Modify

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: Thomas.Thorne@… 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 Ryan J Ollos

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?

2016-04-12 23:29:37,270 Trac[main] ERROR: Internal Server Error: <RequestWithSession "GET '/search?q=xsltmacro'">, referrer 'https://trac-hacks.org/'
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/main.py", line 554, in _dispatch_request
    dispatcher.dispatch(req)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/main.py", line 212, in dispatch
    self._pre_process_request(req, chosen_handler)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/main.py", line 375, in _pre_process_request
    chosen_handler = filter_.pre_process_request(req, chosen_handler)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/acct_mgr/api.py", line 476, in pre_process_request
    if not req.session.authenticated or \
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/api.py", line 355, in __getattr__
    value = self.callbacks[name](self)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/main.py", line 302, in _get_session
    return Session(self.env, req)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/session.py", line 210, in __init__
    self.get_session(sid)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/session.py", line 237, in get_session
    super(Session, self).get_session(sid, authenticated)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/session.py", line 85, in get_session
    """, (sid, int(authenticated))):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/db/util.py", line 128, in execute
    cursor.execute(query, params if params is not None else [])
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-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
OperationalError: terminating connection due to administrator command
SSL connection has been closed unexpectedly
2016-04-12 23:29:37,239 Trac[main] ERROR: Exception caught while post-processing request: 
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/main.py", line 277, in dispatch
    self._post_process_request(req)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/main.py", line 390, in _post_process_request
    f.post_process_request(req, *(None,)*extra_arg_count)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracwikiextras/phrases.py", line 91, in post_process_request
    add_stylesheet(req, 'wikiextras/css/phrases.css')
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/chrome.py", line 149, in add_stylesheet
    add_link(req, 'stylesheet', href, mimetype=mimetype, media=media)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/chrome.py", line 127, in add_link
    linkset = req.chrome.setdefault('linkset', set())
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/api.py", line 355, in __getattr__
    value = self.callbacks[name](self)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/chrome.py", line 763, in prepare_request
    if req.locale is not None and str(req.locale) != 'en_US':
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/api.py", line 355, in __getattr__
    value = self.callbacks[name](self)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/main.py", line 310, in _get_locale
    preferred = req.session.get('language')
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/api.py", line 355, in __getattr__
    value = self.callbacks[name](self)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/main.py", line 302, in _get_session
    return Session(self.env, req)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/session.py", line 210, in __init__
    self.get_session(sid)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/session.py", line 237, in get_session
    super(Session, self).get_session(sid, authenticated)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/session.py", line 85, in get_session
    """, (sid, int(authenticated))):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/db/util.py", line 128, in execute
    cursor.execute(query, params if params is not None else [])
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-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
OperationalError: terminating connection due to administrator command
SSL connection has been closed unexpectedly
2016-04-12 23:29:36,140 Trac[main] ERROR: Internal Server Error: <RequestWithSession "GET '/timeline?from=2009-03-05T10%3A47%3A39%2B01%3A00&precision=second'">, referrer None
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/main.py", line 554, in _dispatch_request
    dispatcher.dispatch(req)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/main.py", line 267, in dispatch
    iterable=chrome.use_chunked_encoding)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/chrome.py", line 1114, in render_template
    encoding='utf-8')
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/core.py", line 183, in render
    return encode(generator, method=method, encoding=encoding, out=out)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/output.py", line 58, in encode
    for chunk in iterator:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/output.py", line 339, in __call__
    for kind, data, pos in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/output.py", line 826, in __call__
    for kind, data, pos in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/output.py", line 670, in __call__
    for kind, data, pos in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/output.py", line 771, in __call__
    for kind, data, pos in chain(stream, [(None, None, None)]):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/output.py", line 586, in __call__
    for ev in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/core.py", line 288, in _ensure
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/core.py", line 288, in _ensure
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/chrome.py", line 1320, in _strip_accesskeys
    for kind, data, pos in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/core.py", line 288, in _ensure
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/web/chrome.py", line 1309, in _generate
    for kind, data, pos in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/core.py", line 288, in _ensure
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/core.py", line 288, in _ensure
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/filters/transform.py", line 686, in _unmark
    for mark, event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/filters/transform.py", line 1145, in __call__
    for mark, event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/filters/transform.py", line 714, in __call__
    for mark, event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/filters/transform.py", line 682, in _mark
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/core.py", line 288, in _ensure
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/filters/transform.py", line 686, in _unmark
    for mark, event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/filters/transform.py", line 1081, in __call__
    for mark, event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/filters/transform.py", line 117, in __iter__
    event = self.stream.next()
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/filters/transform.py", line 714, in __call__
    for mark, event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/filters/transform.py", line 682, in _mark
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/base.py", line 605, in _include
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/markup.py", line 378, in _match
    ctxt, start=idx + 1, **vars):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/markup.py", line 378, in _match
    ctxt, start=idx + 1, **vars):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/markup.py", line 327, in _match
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/base.py", line 545, in _flatten
    for kind, data, pos in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/core.py", line 288, in _ensure
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/path.py", line 588, in _generate
    subevent = next()
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/base.py", line 605, in _include
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/markup.py", line 316, in _strip
    event = next()
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/base.py", line 545, in _flatten
    for kind, data, pos in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/core.py", line 288, in _ensure
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/path.py", line 588, in _generate
    subevent = next()
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/base.py", line 605, in _include
    for event in stream:
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/markup.py", line 316, in _strip
    event = next()
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/base.py", line 565, in _flatten
    result = _eval_expr(data, ctxt, vars)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/base.py", line 277, in _eval_expr
    retval = expr.evaluate(ctxt)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/genshi/template/eval.py", line 178, in evaluate
    return eval(self.code, _globals, {'__data__': data})
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/timeline/templates/timeline.html", line 68, in <Expression u"event.render('description', context)">
    ${event.render('description', context)}
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/timeline/web_ui.py", line 366, in <lambda>
    provider.render_timeline_event(context, field, event)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/versioncontrol/web_ui/changeset.py", line 975, in render_timeline_event
    for chg in c.get_changes():
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/versioncontrol/cache.py", line 499, in get_changes
    """, (self.repos.id, self.repos.db_rev(self.rev)))):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/db/api.py", line 124, in execute
    return db.execute(query, params)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/db/util.py", line 128, in execute
    cursor.execute(query, params if params is not None else [])
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-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
OperationalError: terminating connection due to administrator command
SSL connection has been closed unexpectedly

comment:2 Changed 9 years ago by Thomas.Thorne@…

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 Thomas.Thorne@…

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
Last edited 9 years ago by Jun Omae (previous) (diff)

comment:4 Changed 9 years ago by Jun Omae

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.

Last edited 9 years ago by Jun Omae (previous) (diff)

comment:5 Changed 9 years ago by Thomas.Thorne@…

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 Jun Omae

Thanks for the investigating! It seems that is the same issue of trac:#4984.

comment:7 Changed 9 years ago by Jun Omae

I've posted proposed patch at trac:comment:21:ticket:4984.

comment:8 Changed 9 years ago by Ryan J Ollos

Resolution: cantfix
Status: newclosed

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Steffen Hoffmann.
The resolution will be deleted. Next status will be 'reopened'.

Add Comment


E-mail address and name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.