← Back to team overview

yellow team mailing list archive

  1. yellow team
  2. Mailing list archive
  3. Message #00991

One more thought...

  Thread Previous • Date Previous • • Thread Next 
Hey Stuart.  Benji and I did a bit more hunting for the bug I talked
about last time.  If you recall, rarely/intermittently we see errors in
lp.services.webapp.tests.test_error.TestDatabaseErrorViews.

It turns out that when the test fails, the log output does look very
different than when it succeeds.  Specifically, the log shows a lot of
repetition of essentially the bits in the chunk I show below.

The part I want to call attention to you is the first part: the mention
of bug 504291.  The store has been left in a disconnected state, it seems.

The code that Robert shows in comment 11 of that bug still exists in the
tree, but the repair code (store.rollback()) doesn't seem to work. We
keep getting the problem over and over again, which as I understand it
is a characteristic of that broken state not being repaired.

I tried putting in some more transaction.abort() calls in seemingly
strategic places, per Jeroen's comment #5 that some aborts might help
(though see my comment #6 indicating that we are already aborting when
he suggests, via transaction.begin()), but I still see the problem.

At this point, I'm particularly interested in two things from you.

(1) Is there a more reliable way to unbreak the seemingly persistent
disconnected state, or another way that you'd suggest I try?

(2) Do you see anything in the log blather after the first thing I quote
for you below that suggests to you that I (and the traceback) are
misidentifying the problem as associated with 504291?

Thanks

Gary


oops-97: {{{
Oops-Id: OOPS-6b5061f6cab233a7d3a9c3b4bd01a5e8
Exception-Type: AssertionError
Exception-Value: Bug #504291: Store left in a disconnected state.
Date: 2012-07-04T21:38:26.284113+00:00
Page-Id: RootObject:index.html
Branch: db-devel
Revision: 11737
User: unauthenticated, Anonymous, Anonymous, Anonymous User
URL: http://launchpad.dev/index.html
Duration: -1
Oops-Reporter: T

HTTP_ACCEPT_ENCODING=identity
HTTP_CONNECTION=close
HTTP_HOST=launchpad.dev
HTTP_USER_AGENT=Python-urllib/2.6
PATH_INFO=/
QUERY_STRING=
REMOTE_ADDR=127.0.0.1
REQUEST_METHOD=GET
SCRIPT_NAME=
SERVER_NAME=launchpad.dev
SERVER_PORT=80
SERVER_PROTOCOL=HTTP/1.1%0D%0A
launchpad.nonpythonactions=%3Chidden%3E
launchpad.pageid=%3Chidden%3E
launchpad.requestduration=%3Chidden%3E
launchpad.userid=%3Chidden%3E
wsgi.errors=%3Chidden%3E
wsgi.input=%3Chidden%3E
wsgi.multiprocess=%3Chidden%3E
wsgi.multithread=%3Chidden%3E
wsgi.run_once=%3Chidden%3E
wsgi.url_scheme=%3Chidden%3E
wsgi.version=%3Chidden%3E


Traceback (most recent call last):
  Module lp.services.webapp.publication, line 762, in endRequest
    "Bug #504291: Store left in a disconnected state.")
AssertionError: Bug #504291: Store left in a disconnected state.
}}}

oops-98: {{{
Oops-Id: OOPS-070d57ebc91799f79b8a8986e9057408
Exception-Type: DisconnectionError
Exception-Value: could not connect to server: No such file or directory
Is the server running locally and accepting connections on Unix domain
socket "/var/run/postgresql/.s.PGSQL.57323"?
Date: 2012-07-04T21:38:26.286518+00:00
Page-Id: RootObject:index.html
Branch: db-devel
Revision: 11737
User: unauthenticated, Anonymous, Anonymous, Anonymous User
URL: http://launchpad.dev/index.html
Duration: -1
Oops-Reporter: T

HTTP_ACCEPT_ENCODING=identity
HTTP_CONNECTION=close
HTTP_HOST=launchpad.dev
HTTP_USER_AGENT=Python-urllib/2.6
PATH_INFO=/
QUERY_STRING=
REMOTE_ADDR=127.0.0.1
REQUEST_METHOD=GET
SCRIPT_NAME=
SERVER_NAME=launchpad.dev
SERVER_PORT=80
SERVER_PROTOCOL=HTTP/1.1%0D%0A
launchpad.nonpythonactions=%3Chidden%3E
launchpad.pageid=%3Chidden%3E
launchpad.requestduration=%3Chidden%3E
launchpad.userid=%3Chidden%3E
wsgi.errors=%3Chidden%3E
wsgi.input=%3Chidden%3E
wsgi.multiprocess=%3Chidden%3E
wsgi.multithread=%3Chidden%3E
wsgi.run_once=%3Chidden%3E
wsgi.url_scheme=%3Chidden%3E
wsgi.version=%3Chidden%3E


Traceback (most recent call last):
  Module zope.publisher.publish, line 134, in publish
    result = publication.callObject(request, obj)
  Module lp.services.webapp.publication, line 499, in callObject
    return mapply(ob, request.getPositionalArguments(), request)
  Module zope.publisher.publish, line 109, in mapply
    return debug_call(obj, args)
   - __traceback_info__: <security proxied
zope.browserpage.metaconfigure.SimpleViewClass from
/var/lib/buildbot/slaves/slave/lucid-db-devel/build/lib/lp/app/browser/../templates/root-index.pt
instance at 0x1265910c>
  Module zope.publisher.publish, line 115, in debug_call
    return obj(*args)
  Module lp.services.webapp.publisher, line 425, in __call__
    return self.render()
  Module lp.services.webapp.publisher, line 410, in render
    return self.template()
  Module zope.app.pagetemplate.viewpagetemplatefile, line 83, in __call__
    return self.im_func(im_self, *args, **kw)
  Module zope.app.pagetemplate.viewpagetemplatefile, line 51, in __call__
    sourceAnnotations=getattr(debug_flags, 'sourceAnnotations', 0),
  Module zope.pagetemplate.pagetemplate, line 113, in pt_render
    strictinsert=0, sourceAnnotations=sourceAnnotations)()
  Module zope.tal.talinterpreter, line 271, in __call__
    self.interpret(self.program)
  Module zope.tal.talinterpreter, line 343, in interpret
    handlers[opcode](self, args)
  Module zope.tal.talinterpreter, line 888, in do_useMacro
    self.interpret(macro)
  Module zope.tal.talinterpreter, line 343, in interpret
    handlers[opcode](self, args)
  Module zope.tal.talinterpreter, line 533, in do_optTag_tal
    self.do_optTag(stuff)
  Module zope.tal.talinterpreter, line 518, in do_optTag
    return self.no_tag(start, program)
  Module zope.tal.talinterpreter, line 513, in no_tag
    self.interpret(program)
  Module zope.tal.talinterpreter, line 343, in interpret
    handlers[opcode](self, args)
  Module zope.tal.talinterpreter, line 531, in do_optTag_tal
    self.no_tag(stuff[-2], stuff[-1])
  Module zope.tal.talinterpreter, line 513, in no_tag
    self.interpret(program)
  Module zope.tal.talinterpreter, line 343, in interpret
    handlers[opcode](self, args)
  Module zope.tal.talinterpreter, line 583, in do_setLocal_tal
    self.engine.setLocal(name, self.engine.evaluateValue(expr))
  Module zope.tales.tales, line 696, in evaluate
    return expression(self)
   -
/var/lib/buildbot/slaves/slave/lucid-db-devel/build/lib/lp/app/browser/../templates/base-layout.pt
   - Line 128, Column 14
   - Expression: <PathExpr standard:u'request/notifications'>
   - Names:
      {'args': (),
       'context': <lp.services.webapp.publisher.RootObject object at
0xa4cdf2c>,
       'default': <object object at 0xf738d700>,
       'loop': {},
       'nothing': None,
       'options': {},
       'repeat': {},
       'request': <lp.services.webapp.servers.LaunchpadBrowserRequest
instance URL=http://launchpad.dev/index.html>,
       'template': <z3c.ptcompat.ViewPageTemplateFile object at 0x108e844c>,
       'view': <zope.browserpage.metaconfigure.SimpleViewClass from
/var/lib/buildbot/slaves/slave/lucid-db-devel/build/lib/lp/app/browser/../templates/root-index.pt
object at 0x1265910c>,
       'views': <zope.app.pagetemplate.viewpagetemplatefile.ViewMapper
object at 0xe70656c>}
  Module zope.tales.expressions, line 217, in __call__
    return self._eval(econtext)
  Module zope.tales.expressions, line 194, in _eval
    ob = self._subexprs[-1](econtext)
  Module zope.tales.expressions, line 124, in _eval
    ob = self._traverser(ob, element, econtext)
  Module zope.pagetemplate.engine, line 66, in __call__
    request=request)
  Module zope.traversing.adapters, line 138, in traversePathElement
    return traversable.traverse(nm, further_path)
   - __traceback_info__:
(<lp.services.webapp.servers.LaunchpadBrowserRequest instance
URL=http://launchpad.dev/index.html>, 'notifications')
  Module zope.traversing.adapters, line 44, in traverse
    attr = getattr(subject, name, _marker)
   - __traceback_info__:
(<lp.services.webapp.servers.LaunchpadBrowserRequest instance
URL=http://launchpad.dev/index.html>, 'notifications', [])
  Module lp.services.webapp.notifications, line 75, in notifications
    return INotificationResponse(self).notifications
  Module lp.services.webapp.notifications, line 195, in notifications
    session = ISession(self)[SESSION_KEY]
  Module zope.session.session, line 433, in __getitem__
    sd = sdc[self.client_id]
  Module lp.services.webapp.pgsession, line 74, in __getitem__
    return PGSessionData(self, client_id)
  Module lp.services.webapp.pgsession, line 104, in __init__
    self.store.execute(query, (self.client_id,), noresult=True)
  Module storm.store, line 108, in execute
    return self._connection.execute(statement, params, noresult)
  Module storm.databases.postgres, line 266, in execute
    return Connection.execute(self, statement, params, noresult)
  Module storm.database, line 230, in execute
    self._ensure_connected()
  Module storm.database, line 352, in _ensure_connected
    raise DisconnectionError(str(exc))
DisconnectionError: could not connect to server: No such file or directory
	Is the server running locally and accepting
	connections on Unix domain socket "/var/run/postgresql/.s.PGSQL.57323"?
}}}

oops-99: {{{
Oops-Id: OOPS-c4830a4b0b410f64360cdd5126eb800e
Exception-Type: DisconnectionError
Exception-Value: could not connect to server: No such file or directory
Is the server running locally and accepting connections on Unix domain
socket "/var/run/postgresql/.s.PGSQL.57323"?
Date: 2012-07-04T21:38:26.327515+00:00
Page-Id: RootObject:index.html
Branch: db-devel
Revision: 11737
User: unauthenticated, Anonymous, Anonymous, Anonymous User
URL: http://launchpad.dev/index.html
Duration: -1
Oops-Reporter: T

HTTP_ACCEPT_ENCODING=identity
HTTP_CONNECTION=close
HTTP_HOST=launchpad.dev
HTTP_USER_AGENT=Python-urllib/2.6
PATH_INFO=/
QUERY_STRING=
REMOTE_ADDR=127.0.0.1
REQUEST_METHOD=GET
SCRIPT_NAME=
SERVER_NAME=launchpad.dev
SERVER_PORT=80
SERVER_PROTOCOL=HTTP/1.1%0D%0A
launchpad.nonpythonactions=%3Chidden%3E
launchpad.pageid=%3Chidden%3E
launchpad.requestduration=%3Chidden%3E
launchpad.userid=%3Chidden%3E
wsgi.errors=%3Chidden%3E
wsgi.input=%3Chidden%3E
wsgi.multiprocess=%3Chidden%3E
wsgi.multithread=%3Chidden%3E
wsgi.run_once=%3Chidden%3E
wsgi.url_scheme=%3Chidden%3E
wsgi.version=%3Chidden%3E


Traceback (most recent call last):
  Module zope.publisher.publish, line 134, in publish
    result = publication.callObject(request, obj)
  Module lp.services.webapp.publication, line 499, in callObject
    return mapply(ob, request.getPositionalArguments(), request)
  Module zope.publisher.publish, line 109, in mapply
    return debug_call(obj, args)
   - __traceback_info__: <security proxied
zope.browserpage.metaconfigure.SimpleViewClass from
/var/lib/buildbot/slaves/slave/lucid-db-devel/build/lib/lp/app/browser/../templates/root-index.pt
instance at 0x1265910c>
  Module zope.publisher.publish, line 115, in debug_call
    return obj(*args)
  Module lp.services.webapp.publisher, line 425, in __call__
    return self.render()
  Module lp.services.webapp.publisher, line 410, in render
    return self.template()
  Module zope.app.pagetemplate.viewpagetemplatefile, line 83, in __call__
    return self.im_func(im_self, *args, **kw)
  Module zope.app.pagetemplate.viewpagetemplatefile, line 51, in __call__
    sourceAnnotations=getattr(debug_flags, 'sourceAnnotations', 0),
  Module zope.pagetemplate.pagetemplate, line 113, in pt_render
    strictinsert=0, sourceAnnotations=sourceAnnotations)()
  Module zope.tal.talinterpreter, line 271, in __call__
    self.interpret(self.program)
  Module zope.tal.talinterpreter, line 343, in interpret
    handlers[opcode](self, args)
  Module zope.tal.talinterpreter, line 888, in do_useMacro
    self.interpret(macro)
  Module zope.tal.talinterpreter, line 343, in interpret
    handlers[opcode](self, args)
  Module zope.tal.talinterpreter, line 533, in do_optTag_tal
    self.do_optTag(stuff)
  Module zope.tal.talinterpreter, line 518, in do_optTag
    return self.no_tag(start, program)
  Module zope.tal.talinterpreter, line 513, in no_tag
    self.interpret(program)
  Module zope.tal.talinterpreter, line 343, in interpret
    handlers[opcode](self, args)
  Module zope.tal.talinterpreter, line 531, in do_optTag_tal
    self.no_tag(stuff[-2], stuff[-1])
  Module zope.tal.talinterpreter, line 513, in no_tag
    self.interpret(program)
  Module zope.tal.talinterpreter, line 343, in interpret
    handlers[opcode](self, args)
  Module zope.tal.talinterpreter, line 583, in do_setLocal_tal
    self.engine.setLocal(name, self.engine.evaluateValue(expr))
  Module zope.tales.tales, line 696, in evaluate
    return expression(self)
   -
/var/lib/buildbot/slaves/slave/lucid-db-devel/build/lib/lp/app/browser/../templates/base-layout.pt
   - Line 128, Column 14
   - Expression: <PathExpr standard:u'request/notifications'>
   - Names:
      {'args': (),
       'context': <lp.services.webapp.publisher.RootObject object at
0xa4cdf2c>,
       'default': <object object at 0xf738d700>,
       'loop': {},
       'nothing': None,
       'options': {},
       'repeat': {},
       'request': <lp.services.webapp.servers.LaunchpadBrowserRequest
instance URL=http://launchpad.dev/index.html>,
       'template': <z3c.ptcompat.ViewPageTemplateFile object at 0x108e844c>,
       'view': <zope.browserpage.metaconfigure.SimpleViewClass from
/var/lib/buildbot/slaves/slave/lucid-db-devel/build/lib/lp/app/browser/../templates/root-index.pt
object at 0x1265910c>,
       'views': <zope.app.pagetemplate.viewpagetemplatefile.ViewMapper
object at 0xe70656c>}
  Module zope.tales.expressions, line 217, in __call__
    return self._eval(econtext)
  Module zope.tales.expressions, line 194, in _eval
    ob = self._subexprs[-1](econtext)
  Module zope.tales.expressions, line 124, in _eval
    ob = self._traverser(ob, element, econtext)
  Module zope.pagetemplate.engine, line 66, in __call__
    request=request)
  Module zope.traversing.adapters, line 138, in traversePathElement
    return traversable.traverse(nm, further_path)
   - __traceback_info__:
(<lp.services.webapp.servers.LaunchpadBrowserRequest instance
URL=http://launchpad.dev/index.html>, 'notifications')
  Module zope.traversing.adapters, line 44, in traverse
    attr = getattr(subject, name, _marker)
   - __traceback_info__:
(<lp.services.webapp.servers.LaunchpadBrowserRequest instance
URL=http://launchpad.dev/index.html>, 'notifications', [])
  Module lp.services.webapp.notifications, line 75, in notifications
    return INotificationResponse(self).notifications
  Module lp.services.webapp.notifications, line 195, in notifications
    session = ISession(self)[SESSION_KEY]
  Module zope.session.session, line 433, in __getitem__
    sd = sdc[self.client_id]
  Module lp.services.webapp.pgsession, line 74, in __getitem__
    return PGSessionData(self, client_id)
  Module lp.services.webapp.pgsession, line 104, in __init__
    self.store.execute(query, (self.client_id,), noresult=True)
  Module storm.store, line 108, in execute
    return self._connection.execute(statement, params, noresult)
  Module storm.databases.postgres, line 266, in execute
    return Connection.execute(self, statement, params, noresult)
  Module storm.database, line 230, in execute
    self._ensure_connected()
  Module storm.database, line 352, in _ensure_connected
    raise DisconnectionError(str(exc))
DisconnectionError: could not connect to server: No such file or directory
	Is the server running locally and accepting
	connections on Unix domain socket "/var/run/postgresql/.s.PGSQL.57323"?
}}}

output: {{{
2012-07-05 03:08:11.889 8422 LOG File descriptor limit: 1024 (H:1024),
max_client_conn: 100, max fds possible: 15950
2012-07-05 03:08:11.889 8422 LOG listening on 127.0.0.1:57323
2012-07-05 03:08:11.890 8422 LOG listening on unix:/tmp/.s.PGSQL.57323
2012-07-05 03:08:11.988 8422 LOG C-0x871f530:
(nodb)/(nouser)@127.0.0.1:35285 closing because: client unexpected eof
(age=0)
2012-07-05 03:08:11.994 8422 LOG C-0x871f530:
launchpad_ftest_6769/launchpad_main@127.0.0.1:35286 login successful:
db=launchpad_ftest_6769 user=launchpad_main
2012-07-05 03:08:11.994 8422 LOG S-0x873c768:
launchpad_ftest_6769/launchpad_main@127.0.0.1:5432 new connection to server
2012-07-05 03:08:12.256 8422 LOG C-0x871f620:
launchpad_ftest_6769/launchpad_main@127.0.0.1:35323 login successful:
db=launchpad_ftest_6769 user=launchpad_main
2012-07-05 03:08:12.256 8422 LOG S-0x873c858:
launchpad_ftest_6769/launchpad_main@127.0.0.1:5432 new connection to server
2012-07-05 03:09:11.890 8422 LOG Stats: 3 req/s, in 28710 b/s, out 54444
b/s,query 146410 us
}}}

Follow ups

  Thread Previous • Date Previous • • Thread Next