Issue #846 resolved

TypeError: <unloaded module 'LocalCache'> object is not callable

Anonymous created an issue

After upgrading our instance of rhodecode from 1.5.2 to 1.6.0rc1 we started getting error 500 on all repository summary pages

In the server logs we get [client 192.168.x.x] Error - <type 'exceptions.TypeError'>: <unloaded module 'LocalCache'> object is not callable

We are running on Debian Squeeze

Comments (25)

  1. mfutselaar

    The same error started occuring here as well. I changed the issuetrackers config bit in the ini file, restarted RhodeCode and all of the sudden I get a 500 Internal Error.

    Full dump of the log (masked some bits):

    Error - <type 'exceptions.TypeError'>: <unloaded module 'LocalCache'> object is not callable
    URL: http://mercurial.xxxxxx.xxxxxx.nl/xxxxxx-2013
    File '/usr/local/lib/python2.6/dist-packages/weberror/errormiddleware.py', line 162 in __call__
      app_iter = self.application(environ, sr_checker)
    File '/usr/local/lib/python2.6/dist-packages/beaker/middleware.py', line 155 in __call__
      return self.wrap_app(environ, session_start_response)
    File '/usr/local/lib/python2.6/dist-packages/routes/middleware.py', line 131 in __call__
      response = self.app(environ, start_response)
    File '/usr/local/lib/python2.6/dist-packages/pylons/wsgiapp.py', line 106 in __call__
      controller = self.resolve(environ, start_response)
    File '/usr/local/lib/python2.6/dist-packages/pylons/wsgiapp.py', line 239 in resolve
      return self.find_controller(controller)
    File '/usr/local/lib/python2.6/dist-packages/pylons/wsgiapp.py', line 272 in find_controller
      __import__(full_module_name)
    File '/usr/local/lib/python2.6/dist-packages/mercurial/demandimport.py', line 95 in _demandimport
      return _import(name, globals, locals, fromlist, level)
    File '/usr/local/lib/python2.6/dist-packages/rhodecode/controllers/summary.py', line 54 in <module>
      from rhodecode.lib.celerylib.tasks import get_commits_stats
    File '/usr/local/lib/python2.6/dist-packages/mercurial/demandimport.py', line 114 in _demandimport
      mod = _origimport(name, globals, locals)
    File '/usr/local/lib/python2.6/dist-packages/rhodecode/lib/celerylib/tasks.py', line 74 in <module>
      @task(ignore_result=True)
    File '/usr/local/lib/python2.6/dist-packages/celery/decorators.py', line 35 in task
      return _task.task(*args, **kwargs)
    File '/usr/local/lib/python2.6/dist-packages/mercurial/demandimport.py', line 86 in __getattribute__
      self._load()
    File '/usr/local/lib/python2.6/dist-packages/mercurial/demandimport.py', line 58 in _load
      mod = _origimport(head, globals, locals)
    File '/usr/local/lib/python2.6/dist-packages/celery/task/__init__.py', line 5 in <module>
      from celery.task.base import Task, PeriodicTask
    File '/usr/local/lib/python2.6/dist-packages/mercurial/demandimport.py', line 114 in _demandimport
      mod = _origimport(name, globals, locals)
    File '/usr/local/lib/python2.6/dist-packages/celery/task/base.py', line 726 in <module>
      Task = current_app.Task
    File '/usr/local/lib/python2.6/dist-packages/celery/local.py', line 56 in __getattr__
      return getattr(self._get_current_object(), name)
    File '/usr/local/lib/python2.6/dist-packages/kombu/utils/__init__.py', line 269 in __get__
      value = obj.__dict__[self.__name__] = self.__get(obj)
    File '/usr/local/lib/python2.6/dist-packages/celery/app/__init__.py', line 163 in Task
      return self.create_task_cls()
    File '/usr/local/lib/python2.6/dist-packages/celery/app/__init__.py', line 61 in create_task_cls
      class Task(BaseTask):
    File '/usr/local/lib/python2.6/dist-packages/celery/app/__init__.py', line 64 in Task
      backend = self.backend
    File '/usr/local/lib/python2.6/dist-packages/kombu/utils/__init__.py', line 269 in __get__
      value = obj.__dict__[self.__name__] = self.__get(obj)
    File '/usr/local/lib/python2.6/dist-packages/celery/app/base.py', line 312 in backend
      return self._get_backend()
    File '/usr/local/lib/python2.6/dist-packages/celery/app/base.py', line 297 in _get_backend
      return backend_cls(app=self)
    File '/usr/local/lib/python2.6/dist-packages/celery/backends/amqp.py', line 44 in __init__
      super(AMQPBackend, self).__init__(**kwargs)
    File '/usr/local/lib/python2.6/dist-packages/celery/backends/base.py', line 152 in __init__
      self.app.conf.CELERY_MAX_CACHED_RESULTS)
    File '/usr/local/lib/python2.6/dist-packages/mercurial/demandimport.py', line 82 in __call__
      raise TypeError("%s object is not callable" % repr(self))
    TypeError: <unloaded module 'LocalCache'> object is not callable
    
    
    CGI Variables
    -------------
      CONNECTION_TYPE: 'Keep-Alive'
      CONTENT_TYPE: '; charset="utf-8"'
      HTTP_ACCEPT: 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'
      HTTP_ACCEPT_ENCODING: 'gzip, deflate'
      HTTP_ACCEPT_LANGUAGE: 'en-US,en;q=0.5'
      HTTP_COOKIE: '__utma=144009388.485363567.1366814026.1368431339.1369204703.5; __utmz=144009388.1366814026.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none); rhodecode=9020e57ba0344ab69665cb5f1eabd118'
      HTTP_HOST: 'mercurial.xxxxxx.xxxxxx.nl'
      HTTP_REFERER: 'http://mercurial.xxxxxx.xxxxxx.nl/'
      HTTP_USER_AGENT: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:21.0) Gecko/20100101 Firefox/21.0'
      HTTP_X_FORWARDED_FOR: '192.168.2.5'
      HTTP_X_FORWARDED_HOST: 'mercurial.xxxxxx.xxxxxx.nl'
      HTTP_X_FORWARDED_SERVER: 'mercurial.xxxxxx.xxxxxx.nl'
      PATH_INFO: '/xxxxxx-2013'
      REMOTE_ADDR: '127.0.0.1'
      REQUEST_METHOD: 'GET'
      SERVER_NAME: 'localhost'
      SERVER_PORT: '5000'
      SERVER_PROTOCOL: 'HTTP/1.1'
      SERVER_SOFTWARE: 'waitress'
    
    
    WSGI Variables
    --------------
      application: <beaker.middleware.SessionMiddleware object at 0x38a4f50>
      beaker.get_session: <bound method SessionMiddleware._get_session of <beaker.middleware.SessionMiddleware object at 0x38a4f50>>
      beaker.session: {'_authentication_token': '85a6b33a370b11958c25d104ececd144587f2715', 'rhodecode_user': {'username': u'mathijs', 'is_authenticated': True, 'user_id': 2}, '_accessed_time': 1369317906.371666, '_creation_time': 1367498570.244827}
      paste.registry: <paste.registry.Registry object at 0x4197c50>
      paste.throw_errors: True
      pylons.environ_config: {'session': 'beaker.session', 'cache': 'beaker.cache'}
      pylons.pylons: <pylons.util.PylonsContext object at 0x3c5c590>
      pylons.routes_dict: {'action': u'index', 'controller': u'summary', 'repo_name': u'xxxxxx-2013'}
      routes.route: <routes.route.Route object at 0x35adbd0>
      routes.url: <routes.util.URLGenerator object at 0x428ea90>
      webob.adhoc_attrs: {'language': 'en-us'}
      wsgi process: 'Multithreaded'
      wsgi._org_proto: 'http'
      wsgi.file_wrapper: <class 'waitress.buffers.ReadOnlyFileBasedBuffer'>
      wsgiorg.routing_args: (<routes.util.URLGenerator object at 0x428ea90>, {'action': u'index', 'controller': u'summary', 'repo_name': u'xxxxxx-2013'})
    ------------------------------------------------------------
    2013-05-23 16:05:06.375 INFO  [rhodecode.RequestWrapper] IP: 192.168.2.5 Request to /xxxxxx-2013 time: 0.011s
    2013-05-23 16:05:06.419 INFO  [rhodecode.lib.base] IP: 192.168.2.5 User: <AuthUser('id:2:mathijs|True')> accessed /xxxxxx-2013
    2013-05-23 16:05:06.422 INFO  [rhodecode.RequestWrapper] IP: 192.168.2.5 Request to /xxxxxx-2013 time: 0.047s
    
  2. Marcin Kuzminski repo owner

    As a workaround fix you would need to put line into environment.py of rhodecode sources

    from mercurial import demandimport; demandimport.disable()
    

    Now i cannot reproduce this error. Could you help us debug this ? I quickly spoke with mercurial guys, and they said one should introduce a error inside mercurials demandimport library and check at what point it fails, so we could pinpoint what triggers the demandimport.

  3. Denis Blanchette

    Unfortunately that is the only line on our log concerning this error. How could I enable more logging so that I can get the full traceback?

    In my production.ini I have

    [app:main]
    use = egg:rhodecode
    full_stack = true
    

    Other errors usually returns the full traceback.

    I don't know if it is related but I also get this error :

    [Thu May 23 09:21:37 2013] [error] \x1b[0;31m2013-05-23 09:21:37.500 ERROR [rhodecode.controllers.changelog] Traceback (most recent call last):
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/rhodecode/controllers/changelog.py", line 75, in index
    [Thu May 23 09:21:37 2013] [error]     branch_name=branch_name)]
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 481, in get_changesets
    [Thu May 23 09:21:37 2013] [error]     if branch_name and cs.branch != branch_name:
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/rhodecode/lib/vcs/utils/lazy.py", line 40, in __get__
    [Thu May 23 09:21:37 2013] [error]     value = self._func(obj)
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/rhodecode/lib/vcs/backends/hg/changeset.py", line 36, in branch
    [Thu May 23 09:21:37 2013] [error]     return  safe_unicode(self._ctx.branch())
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/mercurial/context.py", line 199, in branch
    [Thu May 23 09:21:37 2013] [error]     return encoding.tolocal(self._changeset[5].get("branch"))
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/mercurial/util.py", line 246, in __get__
    [Thu May 23 09:21:37 2013] [error]     result = self.func(obj)
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/mercurial/context.py", line 146, in _changeset
    [Thu May 23 09:21:37 2013] [error]     return self._repo.changelog.read(self.rev())
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/mercurial/changelog.py", line 282, in read
    [Thu May 23 09:21:37 2013] [error]     text = self.revision(node)
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/mercurial/revlog.py", line 887, in revision
    [Thu May 23 09:21:37 2013] [error]     if self._cache[0] == node:
    [Thu May 23 09:21:37 2013] [error] TypeError: 'NoneType' object is unsubscriptable
    [Thu May 23 09:21:37 2013] [error] \x1b[0m
    [Thu May 23 09:21:37 2013] [error] \x1b[0;31m2013-05-23 09:21:37.500 ERROR [rhodecode.controllers.changelog] Traceback (most recent call last):
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/rhodecode/controllers/changelog.py", line 75, in index
    [Thu May 23 09:21:37 2013] [error]     branch_name=branch_name)]
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 481, in get_changesets
    [Thu May 23 09:21:37 2013] [error]     if branch_name and cs.branch != branch_name:
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/rhodecode/lib/vcs/utils/lazy.py", line 40, in __get__
    [Thu May 23 09:21:37 2013] [error]     value = self._func(obj)
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/rhodecode/lib/vcs/backends/hg/changeset.py", line 36, in branch
    [Thu May 23 09:21:37 2013] [error]     return  safe_unicode(self._ctx.branch())
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/mercurial/context.py", line 199, in branch
    [Thu May 23 09:21:37 2013] [error]     return encoding.tolocal(self._changeset[5].get("branch"))
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/mercurial/util.py", line 246, in __get__
    [Thu May 23 09:21:37 2013] [error]     result = self.func(obj)
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/mercurial/context.py", line 146, in _changeset
    [Thu May 23 09:21:37 2013] [error]     return self._repo.changelog.read(self.rev())
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/mercurial/changelog.py", line 282, in read
    [Thu May 23 09:21:37 2013] [error]     text = self.revision(node)
    [Thu May 23 09:21:37 2013] [error]   File "/usr/local/lib/python2.6/dist-packages/mercurial/revlog.py", line 887, in revision
    [Thu May 23 09:21:37 2013] [error]     if self._cache[0] == node:
    [Thu May 23 09:21:37 2013] [error] TypeError: 'NoneType' object is unsubscriptable
    
  4. Denis Blanchette

    Marcin Kuzminski It seems so. I was able to get the full traceback (It was being set by email to one of my colleague):

    Module mercurial.demandimport:95 in _demandimport
    >>  return _import(name, globals, locals, fromlist, level)
    Module ?:54 in <module>
    >>  from rhodecode.lib.celerylib.tasks import get_commits_stats
    Module mercurial.demandimport:114 in _demandimport
    >>  mod = _origimport(name, globals, locals)
    Module ?:74 in <module>
    >>  @task(ignore_result=True)
    Module celery.decorators:35 in task
    >>  return _task.task(*args, **kwargs)
    Module mercurial.demandimport:86 in __getattribute__
    >>  self._load()
    Module mercurial.demandimport:58 in _load
    >>  mod = _origimport(head, globals, locals)
    Module ?:5 in <module>
    >>  from celery.task.base import Task, PeriodicTask
    Module mercurial.demandimport:114 in _demandimport
    >>  mod = _origimport(name, globals, locals)
    Module ?:726 in <module>
    >>  Task = current_app.Task
    Module celery.local:56 in __getattr__
    >>  return getattr(self._get_current_object(), name)
    Module kombu.utils:269 in __get__
    >>  value = obj.__dict__[self.__name__] = self.__get(obj)
    Module celery.app:163 in Task
    >>  return self.create_task_cls()
    Module celery.app:61 in create_task_cls
    >>  class Task(BaseTask):
    Module celery.app:64 in Task
    >>  backend = self.backend
    Module kombu.utils:269 in __get__
    >>  value = obj.__dict__[self.__name__] = self.__get(obj)
    Module celery.app.base:312 in backend
    >>  return self._get_backend()
    Module celery.app.base:297 in _get_backend
    >>  return backend_cls(app=self)
    Module celery.backends.amqp:44 in __init__
    >>  super(AMQPBackend, self).__init__(**kwargs)
    Module celery.backends.base:152 in __init__
    >>  self.app.conf.CELERY_MAX_CACHED_RESULTS)
    Module mercurial.demandimport:82 in __call__
    >>  raise TypeError("%s object is not callable" % repr(self))
    TypeError: <unloaded module 'LocalCache'> object is not callable
    
  5. Nikolaj Šujskij

    Marcin Kuzminski, as far as I remember, I followed installation instructions. Could I check venv attributes somehow?

    Those repos are being accessed by other software as well (like hgweb and Trac). Problem is, trac-hg plugin doesn't work with >2.5, so I've downgraded already. But the issue hasn't returned.

    Denis Blanchette To sum my actions:

    1. RhodeCode 1.5 with mercurial 2.4.2 (in venv as well as in system), everything's fine
    2. Updated RhodeCode to 1.6.0, pulling in mercurial 2.5.4 in venv.
    3. This issue popped up.
    4. I've upgraded system mercurial to 2.5.4. Issue disappears.
    5. I've noticed broken Trac, and downgrade system mercurial to 2.4.2. Issue hasn't returned (yet).
  6. Marcin Kuzminski repo owner

    Seems that those solutions are not permanent. Can you try to make an error in demandimport.py module, to see what enables demandimport ?

    raise exception at module level is ok.

  7. Marcin Kuzminski repo owner

    ref issue on Mercurial bts: http://bz.selenic.com/show_bug.cgi?id=3952. It seems that it's not going to be fixed in Mercurial.

    This issue was introduced in mercurial 2.5.0, so either it's downgrading to 2.4.X or trying to fix it on RhodeCode side.

    Here's proposed patch for RhodeCode dev.

    diff --git a/rhodecode/lib/vcs/utils/hgcompat.py b/rhodecode/lib/vcs/utils/hgcompat.py
    --- a/rhodecode/lib/vcs/utils/hgcompat.py
    +++ b/rhodecode/lib/vcs/utils/hgcompat.py
    @@ -1,13 +1,16 @@
     """
     Mercurial libs compatibility
     """
    
     import mercurial
    +import mercurial.demandimport
    +## patch demandimport, due to bug in mercurial when it allways triggers demandimport.enable()
    +mercurial.demandimport.enable = lambda *args, **kwargs: 1
    
  8. Marcin Kuzminski repo owner

    Here's a diff for 1.6.0

    diff --git a/rhodecode/lib/vcs/utils/hgcompat.py b/rhodecode/lib/vcs/utils/hgcompat.py
    --- a/rhodecode/lib/vcs/utils/hgcompat.py
    +++ b/rhodecode/lib/vcs/utils/hgcompat.py
    @@ -1,12 +1,15 @@
     """
     Mercurial libs compatibility
     """
    -
    +import mercurial
    +import mercurial.demandimport
    +## patch demandimport, due to bug in mercurial when it allways triggers demandimport.enable()
    +mercurial.demandimport.enable = lambda *args, **kwargs: 1
     from mercurial import archival, merge as hg_merge, patch, ui
     from mercurial.commands import clone, nullid, pull
     from mercurial.context import memctx, memfilectx
     from mercurial.error import RepoError, RepoLookupError, Abort
     from mercurial.hgweb.common import get_contact
     from mercurial.localrepo import localrepository
     from mercurial.match import match
     from mercurial.mdiff import diffopts
    
  9. Log in to comment