Files
@ cec84c4675ce
Branch filter:
Location: kallithea/scripts/logformat.py - annotation
cec84c4675ce
1.8 KiB
text/x-python
tests: remove race condition in test_forgot_password
One in so many times, test_forgot_password failed with:
kallithea/tests/functional/test_login.py:427: in test_forgot_password
assert '\n%s\n' % token in body
E assert ('\n%s\n' % 'd71ad3ed3c6ca637ad00b7098828d33c56579201') in
"Password Reset Request\n\nHello passwd reset,\n\nWe have received a
request to reset the password for your account.\n\nTo
s...7e89326ca372ade1d424dafb106d824cddb\n\nIf it weren't you who
requested the password reset, just disregard this message.\n"
i.e. the expected token is not the one in the email.
The token is calculated based on a timestamp (among others). And the token
is calculated twice: once in the real code and once in the test, each time
on a slightly different timestamp. Even though there is flooring of the
timestamp to a second resolution, there will always be a race condition
where the two timestamps floor to a different second, e.g. 4.99 vs 5.01.
The problem can be reproduced reliably by adding a sleep of e.g. 2 seconds
before generating the password reset mail (after the test has already
calculated the expected token).
Solve this problem by mocking the time.time() used to generate the
timestamp, so that the timestamp used for the real token is the same as the
one used for the expected token in the test.
One in so many times, test_forgot_password failed with:
kallithea/tests/functional/test_login.py:427: in test_forgot_password
assert '\n%s\n' % token in body
E assert ('\n%s\n' % 'd71ad3ed3c6ca637ad00b7098828d33c56579201') in
"Password Reset Request\n\nHello passwd reset,\n\nWe have received a
request to reset the password for your account.\n\nTo
s...7e89326ca372ade1d424dafb106d824cddb\n\nIf it weren't you who
requested the password reset, just disregard this message.\n"
i.e. the expected token is not the one in the email.
The token is calculated based on a timestamp (among others). And the token
is calculated twice: once in the real code and once in the test, each time
on a slightly different timestamp. Even though there is flooring of the
timestamp to a second resolution, there will always be a race condition
where the two timestamps floor to a different second, e.g. 4.99 vs 5.01.
The problem can be reproduced reliably by adding a sleep of e.g. 2 seconds
before generating the password reset mail (after the test has already
calculated the expected token).
Solve this problem by mocking the time.time() used to generate the
timestamp, so that the timestamp used for the real token is the same as the
one used for the expected token in the test.
8bc8366a6874 8bc8366a6874 a8e6bb9ee9ea a8e6bb9ee9ea 8bc8366a6874 8bc8366a6874 8bc8366a6874 0a277465fddf 8bc8366a6874 8bc8366a6874 8bc8366a6874 8bc8366a6874 8bc8366a6874 8bc8366a6874 8bc8366a6874 8bc8366a6874 8bc8366a6874 4473f1094d3d 4473f1094d3d 8bc8366a6874 8bc8366a6874 63b548dd5ef3 8bc8366a6874 63b548dd5ef3 8bc8366a6874 63b548dd5ef3 8bc8366a6874 63b548dd5ef3 8bc8366a6874 63b548dd5ef3 8bc8366a6874 8bc8366a6874 4473f1094d3d 4473f1094d3d 665dfa112f2c 8bc8366a6874 8bc8366a6874 665dfa112f2c 4473f1094d3d 4473f1094d3d 4473f1094d3d 4473f1094d3d a8e6bb9ee9ea a8e6bb9ee9ea a8e6bb9ee9ea 4473f1094d3d 4473f1094d3d 4473f1094d3d 4473f1094d3d | #!/usr/bin/env python2
from __future__ import print_function
import re
import sys
logre = r'''
(log\.(?:error|info|warning|debug)
[(][ \n]*
)
%s
(
[ \n]*[)]
)
'''
res = [
# handle % () - keeping spaces around the old %
(re.compile(logre % r'''("[^"]*"|'[^']*') ([\n ]*) % ([\n ]*) \( ( (?:[^()]|\n)* (?: \( (?:[^()]|\n)* \) (?:[^()]|\n)* )* ) \) ''', flags=re.MULTILINE | re.VERBOSE), r'\1\2,\3\4\5\6'),
# handle % without () - keeping spaces around the old %
(re.compile(logre % r'''("[^"]*"|'[^']*') ([\n ]*) % ([\n ]*) ( (?:[^()]|\n)* (?: \( (?:[^()]|\n)* \) (?:[^()]|\n)* )* ) ''', flags=re.MULTILINE | re.VERBOSE), r'\1\2,\3\4\5\6'),
# remove extra space if it is on next line
(re.compile(logre % r'''("[^"]*"|'[^']*') , (\n [ ]) ([ ][\n ]*) ( (?:[^()]|\n)* (?: \( (?:[^()]|\n)* \) (?:[^()]|\n)* )* ) ''', flags=re.MULTILINE | re.VERBOSE), r'\1\2,\3\4\5\6'),
# remove extra space if it is on same line
(re.compile(logre % r'''("[^"]*"|'[^']*') , [ ]+ () ( [\n ]+) ( (?:[^()]|\n)* (?: \( (?:[^()]|\n)* \) (?:[^()]|\n)* )* ) ''', flags=re.MULTILINE | re.VERBOSE), r'\1\2,\3\4\5\6'),
# remove trailing , and space
(re.compile(logre % r'''("[^"]*"|'[^']*') , () ( [\n ]*) ( (?:[^()]|\n)* (?: \( (?:[^()]|\n)* \) (?:[^()]|\n)* )* [^(), \n] ) [ ,]*''', flags=re.MULTILINE | re.VERBOSE), r'\1\2,\3\4\5\6'),
]
def rewrite(f):
s = open(f).read()
for r, t in res:
s = r.sub(t, s)
open(f, 'w').write(s)
if __name__ == '__main__':
if len(sys.argv) < 2:
print('Cleanup of superfluous % formatting of log statements.')
print('Usage:')
print(''' hg revert `hg loc '*.py'|grep -v logformat.py` && scripts/logformat.py `hg loc '*.py'` && hg diff''')
raise SystemExit(1)
for f in sys.argv[1:]:
rewrite(f)
|