Bug 3953 - Traceback in server logs due to likely race condition
Summary: Traceback in server logs due to likely race condition
Status: RESOLVED FIXED
Alias: None
Product: Mercurial
Classification: Unclassified
Component: hgweb (show other bugs)
Version: 2.6.1
Hardware: PC Windows
: normal bug
Assignee: Bugzilla
URL:
Keywords: easy
Depends on:
Blocks:
 
Reported: 2013-06-04 15:43 UTC by Scott Palmer
Modified: 2014-01-06 10:49 UTC (History)
3 users (show)

See Also:
Python Version: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Scott Palmer 2013-06-04 15:43 UTC
CI system that polls multiple repos frequently and often simultaneously triggers the following backlogs

This one shows two tracebacks happening simultaneously:

[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209] mod_wsgi (pid=3116): Exception occurred processing WSGI script 'C:/Program Files/Apache Software Foundation/Apache2.2/cgi-bin/kayak-hgweb.wsgi'.
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209] mod_wsgi (pid=3116): Exception occurred processing WSGI script 'C:/Program Files/Apache Software Foundation/Apache2.2/cgi-bin/kayak-hgweb.wsgi'.
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209] Traceback (most recent call last):
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209] Traceback (most recent call last):
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]   File "C:\\Python27\\lib\\site-packages\\mercurial\\hgweb\\hgwebdir_mod.py", line 153, in __call__
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]   File "C:\\Python27\\lib\\site-packages\\mercurial\\hgweb\\hgwebdir_mod.py", line 153, in __call__
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]     return self.run_wsgi(req)
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]     return self.run_wsgi(req)
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]   File "C:\\Python27\\lib\\site-packages\\mercurial\\hgweb\\hgwebdir_mod.py", line 218, in run_wsgi
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]   File "C:\\Python27\\lib\\site-packages\\mercurial\\hgweb\\hgwebdir_mod.py", line 218, in run_wsgi
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]     return hgweb(repo).run_wsgi(req)
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]   File "C:\\Python27\\lib\\site-packages\\mercurial\\hgweb\\hgweb_mod.py", line 68, in __init__
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]     return hgweb(repo).run_wsgi(req)
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]   File "C:\\Python27\\lib\\site-packages\\mercurial\\hgweb\\hgweb_mod.py", line 68, in __init__
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]     self.repo.baseui.setconfig('ui', 'report_untrusted', 'off')
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]   File "C:\\Python27\\lib\\site-packages\\mercurial\\ui.py", line 163, in setconfig
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]     self.repo.baseui.setconfig('ui', 'report_untrusted', 'off')
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]   File "C:\\Python27\\lib\\site-packages\\mercurial\\ui.py", line 163, in setconfig
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]     self._ucfg.set(section, name, value)
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]   File "C:\\Python27\\lib\\site-packages\\mercurial\\config.py", line 95, in set
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]     self._ucfg.set(section, name, value)
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]   File "C:\\Python27\\lib\\site-packages\\mercurial\\config.py", line 95, in set
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]     self._data[section][item] = value
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]   File "C:\\Python27\\lib\\site-packages\\mercurial\\config.py", line 22, in __setitem__
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]     self._data[section][item] = value
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]   File "C:\\Python27\\lib\\site-packages\\mercurial\\config.py", line 22, in __setitem__
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]     self._list.remove(key)
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209] ValueError: list.remove(x): x not in list
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209]     self._list.remove(key)
[Tue Jun 04 15:00:47 2013] [error] [client 192.168.0.209] ValueError: list.remove(x): x not in list

Here is another similar traceback:
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229] mod_wsgi (pid=3116): Exception occurred processing WSGI script 'C:/Program Files/Apache Software Foundation/Apache2.2/cgi-bin/hgweb.wsgi'.
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229] Traceback (most recent call last):
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]   File "C:\\Python27\\lib\\site-packages\\mercurial\\hgweb\\hgwebdir_mod.py", line 153, in __call__
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]     return self.run_wsgi(req)
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]   File "C:\\Python27\\lib\\site-packages\\mercurial\\hgweb\\hgwebdir_mod.py", line 218, in run_wsgi
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]     return hgweb(repo).run_wsgi(req)
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]   File "C:\\Python27\\lib\\site-packages\\mercurial\\hgweb\\hgweb_mod.py", line 70, in __init__
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]     self.repo.baseui.setconfig('ui', 'nontty', 'true')
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]   File "C:\\Python27\\lib\\site-packages\\mercurial\\ui.py", line 163, in setconfig
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]     self._ucfg.set(section, name, value)
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]   File "C:\\Python27\\lib\\site-packages\\mercurial\\config.py", line 95, in set
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]     self._data[section][item] = value
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]   File "C:\\Python27\\lib\\site-packages\\mercurial\\config.py", line 22, in __setitem__
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]     self._list.remove(key)
[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229] ValueError: list.remove(x): x not in list

The version with self.repo.baseui.setconfig('ui', 'report_untrusted', 'off') seems to happen more frequently than the version with self.repo.baseui.setconfig('ui', 'nontty', 'true') if that could possibly be relevant.
Comment 1 Matt Mackall 2013-06-13 16:26 UTC
This line suggests a layering violation:

[Tue Jun 04 15:11:40 2013] [error] [client 192.168.0.229]     self.repo.baseui.setconfig('ui', 'nontty', 'true')

..and is probably to blame: our thread-safety relies on threads not sharing the same objects, but this is poking at one that is. We probably want to arrange for each thread to have a private copy of the UI object.
Comment 2 HG Bot 2013-12-16 15:00 UTC
Fixed by http://selenic.com/repo/hg/rev/d4be314b2071
Matt Mackall <mpm@selenic.com>
hgweb: avoid initialization race (issue3953)

(please test the fix)