Hi,
I've recently noticed that my sync server appears to be broken, and have
determined that the cause of this was an upgrade to the latest mod_wsgi.
I'm using apache-2.4.10 with mod_wsgi and Python-2.7.8 on Gentoo Linux.
I've tested downgrading mod_wsgi to 3.5 and things appear to work OK.
But with mod_wsgi 4.2.7 sync fails, with this logged on the server side
in the apache error logs:
[Sat Aug 30 20:20:57.926151 2014] [wsgi:error] [pid 29354]
INFO:requests.packages.urllib3.connectionpool:Resetting dropped
connection: verifier.accounts.firefox.com
[Sat Aug 30 20:20:57.927108 2014] [wsgi:error] [pid 29354]
ERROR:mozsvc:Uncaught exception while processing request:
[Sat Aug 30 20:20:57.927161 2014] [wsgi:error] [pid 29354] GET
https://sync-server.reub.net/token/1.0/sync/1.5
[Sat Aug 30 20:20:57.927171 2014] [wsgi:error] [pid 29354] Uncaught
exception:
[Sat Aug 30 20:20:57.927177 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/mozsvc/tweens.py",
line 59, in log_uncaught_exceptions_tween
[Sat Aug 30 20:20:57.927182 2014] [wsgi:error] [pid 29354] return
handler(request)
[Sat Aug 30 20:20:57.927187 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/mozsvc/tweens.py",
line 26, in catch_backend_errors_tween
[Sat Aug 30 20:20:57.927194 2014] [wsgi:error] [pid 29354] return
handler(request)
[Sat Aug 30 20:20:57.927198 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/tweens.py",
line 21, in excview_tween
[Sat Aug 30 20:20:57.927203 2014] [wsgi:error] [pid 29354] response
= handler(request)
[Sat Aug 30 20:20:57.927208 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/router.py",
line 163, in handle_request
[Sat Aug 30 20:20:57.927212 2014] [wsgi:error] [pid 29354] response
= view_callable(context, request)
[Sat Aug 30 20:20:57.927217 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/config/views.py",
line 596, in __call__
[Sat Aug 30 20:20:57.927222 2014] [wsgi:error] [pid 29354] return
view(context, request)
[Sat Aug 30 20:20:57.927226 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/config/views.py",
line 329, in attr_view
[Sat Aug 30 20:20:57.927231 2014] [wsgi:error] [pid 29354] return
view(context, request)
[Sat Aug 30 20:20:57.927235 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/config/views.py",
line 305, in predicate_wrapper
[Sat Aug 30 20:20:57.927240 2014] [wsgi:error] [pid 29354] return
view(context, request)
[Sat Aug 30 20:20:57.927244 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/config/views.py",
line 355, in rendered_view
[Sat Aug 30 20:20:57.927259 2014] [wsgi:error] [pid 29354] result =
view(context, request)
[Sat Aug 30 20:20:57.927263 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/config/views.py",
line 501, in _requestonly_view
[Sat Aug 30 20:20:57.927268 2014] [wsgi:error] [pid 29354] response
= view(request)
[Sat Aug 30 20:20:57.927272 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/cornice/service.py",
line 506, in wrapper
[Sat Aug 30 20:20:57.927276 2014] [wsgi:error] [pid 29354]
validator(request)
[Sat Aug 30 20:20:57.927280 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/tokenserver/views.py",
line 82, in valid_assertion
[Sat Aug 30 20:20:57.927284 2014] [wsgi:error] [pid 29354] assertion
= verifier.verify(assertion)
[Sat Aug 30 20:20:57.927288 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/tokenserver/verifiers.py",
line 99, in verify
[Sat Aug 30 20:20:57.927292 2014] [wsgi:error] [pid 29354]
headers=headers)
[Sat Aug 30 20:20:57.927296 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/sessions.py",
line 425, in post
[Sat Aug 30 20:20:57.927300 2014] [wsgi:error] [pid 29354] return
self.request('POST', url, data=data, **kwargs)
[Sat Aug 30 20:20:57.927304 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/sessions.py",
line 383, in request
[Sat Aug 30 20:20:57.927308 2014] [wsgi:error] [pid 29354] resp =
self.send(prep, **send_kwargs)
[Sat Aug 30 20:20:57.927311 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/sessions.py",
line 486, in send
[Sat Aug 30 20:20:57.927315 2014] [wsgi:error] [pid 29354] r =
adapter.send(request, **kwargs)
[Sat Aug 30 20:20:57.927319 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/adapters.py",
line 330, in send
[Sat Aug 30 20:20:57.927323 2014] [wsgi:error] [pid 29354]
timeout=timeout
[Sat Aug 30 20:20:57.927327 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/packages/urllib3/connectionpool.py",
line 475, in urlopen
[Sat Aug 30 20:20:57.927331 2014] [wsgi:error] [pid 29354] conn =
self._get_conn(timeout=pool_timeout)
[Sat Aug 30 20:20:57.927335 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/packages/urllib3/connectionpool.py",
line 215, in _get_conn
[Sat Aug 30 20:20:57.927340 2014] [wsgi:error] [pid 29354] conn.close()
[Sat Aug 30 20:20:57.927344 2014] [wsgi:error] [pid 29354] File
"/usr/lib64/python2.7/httplib.py", line 795, in close
[Sat Aug 30 20:20:57.927349 2014] [wsgi:error] [pid 29354]
self.sock.close() # close it manually... there may be other refs
[Sat Aug 30 20:20:57.927353 2014] [wsgi:error] [pid 29354] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/packages/urllib3/contrib/pyopenssl.py",
line 326, in close
[Sat Aug 30 20:20:57.927358 2014] [wsgi:error] [pid 29354] return
self.connection.shutdown()
[Sat Aug 30 20:20:57.927361 2014] [wsgi:error] [pid 29354] File
"/usr/lib64/python2.7/site-packages/OpenSSL/SSL.py", line 1157, in shutdown
[Sat Aug 30 20:20:57.927365 2014] [wsgi:error] [pid 29354]
_raise_current_error()
[Sat Aug 30 20:20:57.927369 2014] [wsgi:error] [pid 29354] File
"/usr/lib64/python2.7/site-packages/OpenSSL/_util.py", line 22, in
exception_from_error_queue
[Sat Aug 30 20:20:57.927377 2014] [wsgi:error] [pid 29354] raise
exceptionType(errors)
[Sat Aug 30 20:20:57.927381 2014] [wsgi:error] [pid 29354] <class
'OpenSSL.SSL.Error'>
[Sat Aug 30 20:20:57.927384 2014] [wsgi:error] [pid 29354] Error([],)
[Sat Aug 30 20:20:57.927388 2014] [wsgi:error] [pid 29354]
[Sat Aug 30 20:20:57.927562 2014] [wsgi:error] [pid 29354]
INFO:mozsvc.metrics:{"code": 999, "request_time": 0.0033919811248779297,
"remoteAddressChain": ["101.175.184.152"], "agent": "Mozilla/5.0
(Windows NT 6.3; WOW64; rv:31.0) Gecko/20100101 Firefox/31.0",
"tokenserver.assertion.verify": 0.001940011978149414, "path":
"https://sync-server.reub.net/token/1.0/sync/1.5";, "method": "GET"}
[Sat Aug 30 20:20:57.927616 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] mod_wsgi (pid=29354): Exception occurred processing
WSGI script
'/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/syncserver.wsgi'.
[Sat Aug 30 20:20:57.927660 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] Traceback (most recent call last):
[Sat Aug 30 20:20:57.927684 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/router.py",
line 242, in __call__
[Sat Aug 30 20:20:57.927716 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] response = self.invoke_subrequest(request,
use_tweens=True)
[Sat Aug 30 20:20:57.927733 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/router.py",
line 217, in invoke_subrequest
[Sat Aug 30 20:20:57.927755 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] response = handle_request(request)
[Sat Aug 30 20:20:57.927769 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/tokenserver/tweens.py",
line 15, in set_x_timestamp_header_tween
[Sat Aug 30 20:20:57.927832 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] response = handler(request)
[Sat Aug 30 20:20:57.927853 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/syncstorage/tweens.py",
line 120, in convert_non_json_responses_tween
[Sat Aug 30 20:20:57.927877 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] response = handler(request)
[Sat Aug 30 20:20:57.927891 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/syncstorage/tweens.py",
line 96, in convert_cornice_errors_to_respcodes_tween
[Sat Aug 30 20:20:57.927910 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] response = handler(request)
[Sat Aug 30 20:20:57.927923 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/syncstorage/tweens.py",
line 52, in set_default_accept_header_tween
[Sat Aug 30 20:20:57.927942 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] return handler(request)
[Sat Aug 30 20:20:57.927957 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/syncstorage/tweens.py",
line 29, in set_x_timestamp_header_tween
[Sat Aug 30 20:20:57.927976 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] response = handler(request)
[Sat Aug 30 20:20:57.927992 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/mozsvc/tweens.py",
line 94, in fuzz_backoff_headers_tween
[Sat Aug 30 20:20:57.928012 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] response = handler(request)
[Sat Aug 30 20:20:57.928034 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/mozsvc/tweens.py",
line 59, in log_uncaught_exceptions_tween
[Sat Aug 30 20:20:57.928058 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] return handler(request)
[Sat Aug 30 20:20:57.928074 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/mozsvc/tweens.py",
line 26, in catch_backend_errors_tween
[Sat Aug 30 20:20:57.928093 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] return handler(request)
[Sat Aug 30 20:20:57.928108 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/tweens.py",
line 21, in excview_tween
[Sat Aug 30 20:20:57.928130 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] response = handler(request)
[Sat Aug 30 20:20:57.928145 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/router.py",
line 163, in handle_request
[Sat Aug 30 20:20:57.928167 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] response = view_callable(context, request)
[Sat Aug 30 20:20:57.928182 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/config/views.py",
line 596, in __call__
[Sat Aug 30 20:20:57.928204 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] return view(context, request)
[Sat Aug 30 20:20:57.928220 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/config/views.py",
line 329, in attr_view
[Sat Aug 30 20:20:57.928240 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] return view(context, request)
[Sat Aug 30 20:20:57.928254 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/config/views.py",
line 305, in predicate_wrapper
[Sat Aug 30 20:20:57.928275 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] return view(context, request)
[Sat Aug 30 20:20:57.928290 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/config/views.py",
line 355, in rendered_view
[Sat Aug 30 20:20:57.928310 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] result = view(context, request)
[Sat Aug 30 20:20:57.928325 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/pyramid/config/views.py",
line 501, in _requestonly_view
[Sat Aug 30 20:20:57.928346 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] response = view(request)
[Sat Aug 30 20:20:57.928361 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/cornice/service.py",
line 506, in wrapper
[Sat Aug 30 20:20:57.928380 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] validator(request)
[Sat Aug 30 20:20:57.928396 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/tokenserver/views.py",
line 82, in valid_assertion
[Sat Aug 30 20:20:57.928418 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] assertion = verifier.verify(assertion)
[Sat Aug 30 20:20:57.928440 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/tokenserver/verifiers.py",
line 99, in verify
[Sat Aug 30 20:20:57.928463 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] headers=headers)
[Sat Aug 30 20:20:57.928478 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/sessions.py",
line 425, in post
[Sat Aug 30 20:20:57.928499 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] return self.request('POST', url, data=data, **kwargs)
[Sat Aug 30 20:20:57.928514 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/sessions.py",
line 383, in request
[Sat Aug 30 20:20:57.928535 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] resp = self.send(prep, **send_kwargs)
[Sat Aug 30 20:20:57.928549 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/sessions.py",
line 486, in send
[Sat Aug 30 20:20:57.928569 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] r = adapter.send(request, **kwargs)
[Sat Aug 30 20:20:57.928628 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/adapters.py",
line 330, in send
[Sat Aug 30 20:20:57.928660 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] timeout=timeout
[Sat Aug 30 20:20:57.928677 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/packages/urllib3/connectionpool.py",
line 475, in urlopen
[Sat Aug 30 20:20:57.928699 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] conn = self._get_conn(timeout=pool_timeout)
[Sat Aug 30 20:20:57.928714 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/packages/urllib3/connectionpool.py",
line 215, in _get_conn
[Sat Aug 30 20:20:57.928734 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] conn.close()
[Sat Aug 30 20:20:57.928787 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File "/usr/lib64/python2.7/httplib.py", line 795,
in close
[Sat Aug 30 20:20:57.928815 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] self.sock.close() # close it manually... there
may be other refs
[Sat Aug 30 20:20:57.928867 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/requests/packages/urllib3/contrib/pyopenssl.py",
line 326, in close
[Sat Aug 30 20:20:57.928934 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] return self.connection.shutdown()
[Sat Aug 30 20:20:57.928991 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/usr/lib64/python2.7/site-packages/OpenSSL/SSL.py", line 1157, in shutdown
[Sat Aug 30 20:20:57.929020 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] _raise_current_error()
[Sat Aug 30 20:20:57.929072 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] File
"/usr/lib64/python2.7/site-packages/OpenSSL/_util.py", line 22, in
exception_from_error_queue
[Sat Aug 30 20:20:57.929100 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] raise exceptionType(errors)
[Sat Aug 30 20:20:57.929175 2014] [wsgi:error] [pid 29354] [remote
101.175.184.152:4] Error: []
I'm not sure if this is a mod_wsgi bug or a problem with syncserver.wsgi
though so any advice would be welcome.
Thanks,
Reuben
_______________________________________________
Sync-dev mailing list
[email protected]
https://mail.mozilla.org/listinfo/sync-dev
