pseudoclient failing - Githubissues

mitra42 commented 4 years ago

In feature/testing_performance it freezes every time when running against the internally created server e.g.

PYTHON_BIN=python3 pytest --log-cli-level info tests/test_pseudoclient.py

BUT if I uncomment line 171 in run_server and run it against a local server started with

python3 ./server.py --config_file sample_global_config.ini

then it runs fine.

If you hit ctrl-C in the failing case it give some useful debugging that suggests it fails at the end of the resolving of the functions.

danaronson commented 4 years ago

hmm, works for me. Can you try from command line?

On Sun, May 3, 2020 at 2:20 AM Mitra Ardron notifications@github.com wrote:

In feature/testing_performance it freezes every time when running against the internally created server e.g.

PYTHON_BIN=python3 pytest --log-cli-level info tests/test_pseudoclient.py

BUT if I uncomment line 171 in run_server and run it against a local server started with

python3 ./server.py --config_file sample_global_config.ini

then it runs fine.

If you hit ctrl-C in the failing case it give some useful debugging that suggests it fails at the end of the resolving of the functions.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/mitra42/bct-server/issues/100, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAAYRXBQBSGOM7L75AKPAELRPUZOPANCNFSM4MYBO22Q .

mitra42 commented 4 years ago

Sure - just tested it - on that branch feature/testing_performance which I checked is pushed.

My terminal wind is frozen at ...

INFO     tests:__init__.py:54 Sending /status/scan: {'locations': [{'min_lat': -0.01, 'min_long': -0.01, 'max_lat': 0.0, 'max_long': 0.0}], 'contact_prefixes': ['2EBE3F74'], 'since': '2020-05-03T22:08:49.938480Z'}
INFO     root:test_pseudoclient.py:85 poll result: {'since': '2020-05-03T22:08:49.938480Z', 'contact_ids': [], 'locations': [{'lat': 0, 'long': 0, 'update_token': 'C1A39104AFD58147D202', 'status': 2}, {'lat': 0, 'long': 0, 'update_token': '96F9AC7D4E7E58E1AD1B', 'status': 4, 'replaces': '47f5604c5fac88a7d4fea9ec981eacefb601e0bb'}, {'lat': 0, 'long': 0, 'update_token': '5F42A44BA4A72D791810', 'status': 2, 'replaces': '5eb15a96c748182cb2e68756e7e2f7fe5e74b87c'}, {'lat': -0.0001, 'long': -0.0001, 'update_token': '9BC29640607286D12F50', 'status': 2}, {'lat': -0.0001, 'long': -0.0001, 'update_token': 'A6B2D4B92FFCCDFB6621', 'status': 4, 'replaces': '12a153f5b79ae592d3d2e6f61fb4d3d8ad63dbf5'}, {'lat': -0.0, 'long': -0.0001, 'update_token': 'EF693C624E95CE7D389F', 'status': 2, 'replaces': '766c8a5a9c44edb9d80378ade9c08f15a5e59e53'}, {'lat': -0.0001, 'long': -0.0, 'update_token': '6F969AD56D575B7452FD', 'status': 2}, {'lat': -0.0001, 'long': -0.0, 'update_token': '6F969AD56D575B7452FD', 'status': 2}, {'lat': -0.0001, 'long': -0.0, 'update_token': 'D201D56494132012E113', 'status': 4, 'replaces': '4e55e5c0e5ed12345ef122143b13f0e225ebf9d4'}, {'lat': -0.0001, 'long': -0.0, 'update_token': 'D201D56494132012E113', 'status': 4, 'replaces': '4e55e5c0e5ed12345ef122143b13f0e225ebf9d4'}], 'until': '2020-05-03T22:08:50.060913Z'}
INFO     tests:__init__.py:54 Sending /status/update: {'update_tokens': ['86A483A756479FFC7BD8', 'CB8791158D3FBBAA7A5B', '6763FB2D30674A73C3AE', 'E080BEACB0C158B117EB', '3F8CDFA4952419757E35'], 'status': 3, 'replaces': '0ec99dbb4ff6f0a40c62f65b22d0eacfc3233cc2', 'length': 5}
INFO     root:test_pseudoclient.py:152 status/update result: {'status': 'ok'}
INFO     root:test_pseudoclient.py:236 1: walked to -0.00012N,-0.00003W
INFO     tests:__init__.py:54 Sending /status/scan: {'locations': [{'min_lat': -0.01, 'min_long': -0.01, 'max_lat': 0.0, 'max_long': 0.0}], 'contact_prefixes': ['605408E2'], 'since': '2020-05-03T22:08:49.971086Z'}

and if I hit ctrl-C I get

INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:08:50+1000 [-] INFO:__main__:path is /status/update\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:08:50+1000 [-] INFO:contacts:in status_update\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b"2020-05-04 08:08:50+1000 [-] INFO:contacts:writing {'lat': 0, 'long': 0, 'update_token': '86A483A756479FFC7BD8', 'status': 3, 'replaces': '76e3d92e9fa37242d64d1f3a22fec1e7eac81015'} to /var/folders/dc/5n762d7x75d8mfpn4_s54zmm0000gp/T/tmpnvblgjho/spatial_dict/JS/YV/SK/JSYVSKEVER:1588543730.077007.data\n"
INFO     tests:__init__.py:177 http://localhost:50084 output: b"2020-05-04 08:08:50+1000 [-] INFO:contacts:writing {'lat': -0.0, 'long': -0.0001, 'update_token': 'CB8791158D3FBBAA7A5B', 'status': 3, 'replaces': '19fec494f8bc38ee6ec0fc2e4bcfb04877953f02'} to /var/folders/dc/5n762d7x75d8mfpn4_s54zmm0000gp/T/tmpnvblgjho/spatial_dict/BI/YE/I1/BIYEI13AHK:1588543730.077007.data\n"
INFO     tests:__init__.py:177 http://localhost:50084 output: b"2020-05-04 08:08:50+1000 [-] INFO:__main__:legal return is {'status': 'ok'}\n"
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:08:50+1000 [-] "127.0.0.1" - - [03/May/2020:22:08:49 +0000] "POST /status/update HTTP/1.1" 200 16 "-" "python-requests/2.22.0"\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b"2020-05-04 08:08:50+1000 [-] INFO:__main__:in render, request: <Request at 0x10d02cb90 method=POST uri=/status/scan clientproto=HTTP/1.1>, postpath is [b'status', b'scan']\n"
INFO     tests:__init__.py:177 http://localhost:50084 output: b"2020-05-04 08:08:50+1000 [-] INFO:__main__:request content: {'locations': [{'min_lat': -0.01, 'min_long': -0.01, 'max_lat': 0.0, 'max_long': 0.0}], 'contact_prefixes': ['605408E2'], 'since': '2020-05-03T22:08:49.971086Z'}\n"
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:08:50+1000 [-] INFO:__main__:path is /status/scan\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b"2020-05-04 08:08:50+1000 [-] INFO:contacts:_map_over_matching_contacts called with 605408E2, dict_keys(['DA', '1E'])\n"
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:08:50+1000 [-] INFO:contacts:contact file_paths = []\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b"2020-05-04 08:08:50+1000 [-] INFO:contacts:spatial file_paths = ['JS/YV/SK/JSYVSKEVER:1588543729.984899.data', 'JS/YV/SK/JSYVSKEVER:1588543730.028938.data', 'JS/YV/SK/JSYVSKEVER:1588543730.077007.data', 'BS/TY/AO/BSTYAOFZIL:1588543729.984899.data', 'BI/YE/I1/BIYEI13AHK:1588543730.028938.data', 'BI/YE/I1/BIYEI13AHK:1588543730.077007.data', 'QV/V3/NE/QVV3NE34MK:1588543729.984899.data', 'QV/V3/NE/QVV3NE34MK:1588543729.984899.data']\n"
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:08:50+1000 [-] INFO:__main__:found a function for key contact_ids, running as a deferred\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:08:50+1000 [-] INFO:__main__:legal return is 1\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:08:50+1000 [-] INFO:root:in thread, running <function Contacts.scan_status.<locals>.get_contact_id_data at 0x10d02f560>\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:08:50+1000 [-] INFO:root:ran, result is []\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:08:50+1000 [-] INFO:__main__:got result for key contact_ids of []\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:08:50+1000 [-] INFO:__main__:found a function for key locations, running as a deferred\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:08:50+1000 [-] INFO:root:in thread, running <function Contacts.scan_status.<locals>.get_location_id_data at 0x10d02ff80>\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b"2020-05-04 08:08:50+1000 [-] INFO:root:ran, result is [{'lat': 0, 'long': 0, 'update_token': '96F9AC7D4E7E58E1AD1B', 'status': 4, 'replaces': '47f5604c5fac88a7d4fea9ec981eacefb601e0bb'}, {'lat': 0, 'long': 0, 'update_token': '5F42A44BA4A72D791810', 'status': 2, 'replaces': '5eb15a96c748182cb2e68756e7e2f7fe5e74b87c'}, {'lat': 0, 'long': 0, 'update_token': '86A483A756479FFC7BD8', 'status': 3, 'replaces': '76e3d92e9fa37242d64d1f3a22fec1e7eac81015'}, {'lat': -0.0001, 'long': -0.0001, 'update_token': 'A6B2D4B92FFCCDFB6621', 'status': 4, 'replaces': '12a153f5b79ae592d3d2e6f61fb4d3d8ad63dbf5'}, {'lat': -0.0, 'long': -0.0001, 'update_token': 'EF693C624E95CE7D389F', 'status': 2, 'replaces': '766c8a5a9c44edb9d80378ade9c08f15a5e59e53'}, {'lat': -0.0, 'long': -0.0001, 'update_token': 'CB8791158D3FBBAA7A5B', 'status': 3, 'replaces': '19fec494f8bc38ee6ec0fc2e4bcfb04877953f02'}, {'lat': -0.0001, 'long': -0.0, 'update_token': 'D201D56494132012E113', 'status': 4, 'replaces': '4e55e5c0e5ed12345ef122143b13f0e225ebf9d4'}, {'lat': -0.0001, 'long': -0.0, 'update_token': 'D201D56494132012E113', 'status': 4, 'replaces': '4e55e5c0e5ed12345ef122143b13f0e225ebf9d4'}]\n"
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:10:53+1000 [-] Received SIGINT, shutting down.\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b"2020-05-04 08:10:54+1000 [-] INFO:__main__:got result for key locations of [{'lat': 0, 'long': 0, 'update_token': '96F9AC7D4E7E58E1AD1B', 'status': 4, 'replaces': '47f5604c5fac88a7d4fea9ec981eacefb601e0bb'}, {'lat': 0, 'long': 0, 'update_token': '5F42A44BA4A72D791810', 'status': 2, 'replaces': '5eb15a96c748182cb2e68756e7e2f7fe5e74b87c'}, {'lat': 0, 'long': 0, 'update_token': '86A483A756479FFC7BD8', 'status': 3, 'replaces': '76e3d92e9fa37242d64d1f3a22fec1e7eac81015'}, {'lat': -0.0001, 'long': -0.0001, 'update_token': 'A6B2D4B92FFCCDFB6621', 'status': 4, 'replaces': '12a153f5b79ae592d3d2e6f61fb4d3d8ad63dbf5'}, {'lat': -0.0, 'long': -0.0001, 'update_token': 'EF693C624E95CE7D389F', 'status': 2, 'replaces': '766c8a5a9c44edb9d80378ade9c08f15a5e59e53'}, {'lat': -0.0, 'long': -0.0001, 'update_token': 'CB8791158D3FBBAA7A5B', 'status': 3, 'replaces': '19fec494f8bc38ee6ec0fc2e4bcfb04877953f02'}, {'lat': -0.0001, 'long': -0.0, 'update_token': 'D201D56494132012E113', 'status': 4, 'replaces': '4e55e5c0e5ed12345ef122143b13f0e225ebf9d4'}, {'lat': -0.0001, 'long': -0.0, 'update_token': 'D201D56494132012E113', 'status': 4, 'replaces': '4e55e5c0e5ed12345ef122143b13f0e225ebf9d4'}]\n"
INFO     tests:__init__.py:177 http://localhost:50084 output: b"2020-05-04 08:10:54+1000 [-] INFO:__main__:writing HTTP result of {'since': '2020-05-03T22:08:49.971086Z', 'contact_ids': [], 'locations': [{'lat': 0, 'long': 0, 'update_token': '96F9AC7D4E7E58E1AD1B', 'status': 4, 'replaces': '47f5604c5fac88a7d4fea9ec981eacefb601e0bb'}, {'lat': 0, 'long': 0, 'update_token': '5F42A44BA4A72D791810', 'status': 2, 'replaces': '5eb15a96c748182cb2e68756e7e2f7fe5e74b87c'}, {'lat': 0, 'long': 0, 'update_token': '86A483A756479FFC7BD8', 'status': 3, 'replaces': '76e3d92e9fa37242d64d1f3a22fec1e7eac81015'}, {'lat': -0.0001, 'long': -0.0001, 'update_token': 'A6B2D4B92FFCCDFB6621', 'status': 4, 'replaces': '12a153f5b79ae592d3d2e6f61fb4d3d8ad63dbf5'}, {'lat': -0.0, 'long': -0.0001, 'update_token': 'EF693C624E95CE7D389F', 'status': 2, 'replaces': '766c8a5a9c44edb9d80378ade9c08f15a5e59e53'}, {'lat': -0.0, 'long': -0.0001, 'update_token': 'CB8791158D3FBBAA7A5B', 'status': 3, 'replaces': '19fec494f8bc38ee6ec0fc2e4bcfb04877953f02'}, {'lat': -0.0001, 'long': -0.0, 'update_token': 'D201D56494132012E113', 'status': 4, 'replaces': '4e55e5c0e5ed12345ef122143b13f0e225ebf9d4'}, {'lat': -0.0001, 'long': -0.0, 'update_token': 'D201D56494132012E113', 'status': 4, 'replaces': '4e55e5c0e5ed12345ef122143b13f0e225ebf9d4'}], 'until': '2020-05-03T22:08:50.089425Z'}\n"
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:10:54+1000 [-] "127.0.0.1" - - [03/May/2020:22:10:52 +0000] "POST /status/scan HTTP/1.1" 200 1218 "-" "python-requests/2.22.0"\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:10:54+1000 [-] Unhandled Error\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\tTraceback (most recent call last):\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\t  File "server.py", line 230, in <module>\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\t    reactor.run()\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\t  File "/usr/local/lib/python3.7/site-packages/twisted/internet/base.py", line 1283, in run\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\t    self.mainLoop()\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\t  File "/usr/local/lib/python3.7/site-packages/twisted/internet/base.py", line 1292, in mainLoop\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\t    self.runUntilCurrent()\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\t--- <exception caught here> ---\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\t  File "/usr/local/lib/python3.7/site-packages/twisted/internet/base.py", line 886, in runUntilCurrent\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\t    f(*a, **kw)\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\t  File "/usr/local/lib/python3.7/site-packages/twisted/internet/base.py", line 647, in stop\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\t    "Can\'t stop reactor that isn\'t running.")\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b"\ttwisted.internet.error.ReactorNotRunning: Can't stop reactor that isn't running.\n"
INFO     tests:__init__.py:177 http://localhost:50084 output: b'\t\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:10:54+1000 [twisted.web.server.Site] (TCP Port 50084 Closed)\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:10:54+1000 [-] Stopping factory <twisted.web.server.Site object at 0x10cfeb150>\n'
INFO     tests:__init__.py:177 http://localhost:50084 output: b'2020-05-04 08:10:54+1000 [-] Main loop terminated.\n'
INFO     tests:__init__.py:178 terminated

mitra42 commented 4 years ago

Notice that this error came AFTER the SIGINT

danaronson commented 4 years ago

fixed

Safe2COVIDApp / bct-server

pseudoclient failing #100