Demo scripts don't fail to start if `poetry install` hasn't been run

[anoadragon453]

I got a bit confused today while running the demo scripts. I received an internal server error in my client, which was remedied by remembering to run poetry install after git pulling develop.

We made Synapse fail to start if there was a pending poetry install in #13759. It would be nice if a similar error appeared when trying to run the demo scripts.

[reivilibre]

Do you have logs? I'm wondering why the server would even start at all and get as far as giving you internal server errors if you hadn't poetry installed beforehand.

[anoadragon453]

I have poetry install'd before, but hadn't done so in a while. Thus I suspect it was running new python code but old rust code. This was the error:

2022-10-31 13:49:20,011 - synapse.http.server - 124 - ERROR - GET-191 - Failed handle request via 'PushRuleRestServlet': <XForwarded>
Traceback (most recent call last):
  File "/home/work/.cache/pypoetry/virtualenvs/matrix-synapse-184cEDun-py3.10/lib/python3.10/site-packages/twisted/internet/defer.py>
    result = context.run(gen.send, result)
  File "/home/work/code/synapse/synapse/storage/databases/main/push_rule.py", line 168, in get_push_rules_for_user
    return _load_rules(rows, enabled_map, self.hs.config.experimental)
  File "/home/work/code/synapse/synapse/storage/databases/main/push_rule.py", line 86, in _load_rules
    filtered_rules = FilteredPushRules(
TypeError: FilteredPushRules.__new__() got an unexpected keyword argument 'msc3664_enabled'

(truncated in length, I'm afraid). It looks like the error occurred when Element attempted to log in a user, rather than immediately on server start.

After poetry installing, no more error.

[reivilibre]

(I wonder if this is just unfortunate timing and would now be fixed by the Rust source hash verification at import time? If not, it probably should ...?)

[anoadragon453]

the Rust source hash verification at import time?

Hm? What's this?

[reivilibre]

the Rust source hash verification at import time?

Hm? What's this?

https://github.com/matrix-org/synapse/pull/13759/files makes it so the Rust library has, embedded within it, a hash of the source files it was compiled from. For editable installs, the Python code in Synapse checks this hash matches the files on disk at import time.
I can't see how the demo scripts would bypass this mechanism, so my only guess is that this mechanism didn't exist when you ran into the problem? (if it is actually broken by the demo script, it would be useful to put some print statements into https://github.com/matrix-org/synapse/pull/13759/files#diff-bcd0248ee6210ff2315a5728748a1e831c02794f01411492c97ed6019d63f8cdR23 to figure out why it's accepting it when it shouldn't).

[anoadragon453]

I can reproduce it with the following steps:

1. Checkout some point in the git tree before a change to the rust code (but that includes Check if Rust lib needs rebuilding. #13759, added in v1.68.0): git checkout v1.70.0.

2. Run poetry install --extras all

3. Checkout a later point that makes changes to the rust code (I chose Implementation for MSC3664: Pushrules for relations #11804): git checkout 2d0ba3f89aaf9545d81c4027500e543ec70b68a6

4. Attempt to start Synapse normally - this will fail \o/: synctl start

5. Attempt to start Synapse via the demo scripts - this will succeed /o\: ./demo/start.sh

   • The homeserver should respond when running curl http://localhost:8080/_matrix/client/versions

6. However, if we try to do something that would require the rust code changes in Implementation for MSC3664: Pushrules for relations #11804, we get an error:

   curl 'http://localhost:8080/_matrix/client/r0/pushrules/' -H 'Authorization: Bearer xxx'
   {"errcode":"M_UNKNOWN","error":"Internal server error"}
   

   The corresponding homeserver logs:

   2022-11-01 15:57:12,471 - synapse.access.http.8080 - 460 - INFO - GET-100 - 127.0.0.1 - 8080 - {@admin:localhost:8480} Processed request: 0.003sec/0.001sec (0.002sec, 0.000sec) (0.001sec/0.000sec/2) 55B 500 "GET /_matrix/client/r0/pushrules/ HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64; rv:106.0) Gecko/20100101 Firefox/106.0" [0 dbevts]
   2022-11-01 15:57:17,482 - synapse.access.http.8080 - 460 - INFO - GET-101 - 127.0.0.1 - 8080 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 781B 200 "GET /_matrix/client/versions HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64; rv:106.0) Gecko/20100101 Firefox/106.0" [0 dbevts]
   2022-11-01 15:57:17,492 - synapse.http.server - 124 - ERROR - GET-103 - Failed handle request via 'PushRuleRestServlet': <XForwardedForRequest at 0x7f4f9448a290 method='GET' uri='/_matrix/client/r0/pushrules/' clientproto='HTTP/1.1' site='8080'>
   Traceback (most recent call last):
     File "/home/work/.cache/pypoetry/virtualenvs/matrix-synapse-184cEDun-py3.10/lib/python3.10/site-packages/twisted/internet/defer.py", line 1696, in _inlineCallbacks
       result = context.run(gen.send, result)
     File "/home/work/code/synapse/synapse/storage/databases/main/push_rule.py", line 168, in get_push_rules_for_user
       return _load_rules(rows, enabled_map, self.hs.config.experimental)
     File "/home/work/code/synapse/synapse/storage/databases/main/push_rule.py", line 86, in _load_rules
       filtered_rules = FilteredPushRules(
   TypeError: FilteredPushRules.__new__() got an unexpected keyword argument 'msc3664_enabled'
   

   Nothing interesting is printed when starting the server, just the usual warning about default config options.

7. Run poetry install --extras all again and restart the demo homeservers: ./demo/stop.sh && ./demo/start.sh

8. curl 'http://localhost:8080/_matrix/client/r0/pushrules/' -H 'Authorization: Bearer xxx' now returns with a 200.

[DMRobertson]

I would add logging to https://github.com/matrix-org/synapse/pull/13759/files#diff-bcd0248ee6210ff2315a5728748a1e831c02794f01411492c97ed6019d63f8cdR23-R46 and rerun the demo script.

I would guess that the demo scripts launch synapse with a different PWD, meaning that they don't find pyproject.toml and don't run the check.

[DMRobertson]

In fact, from the comment it looks like it's supposed to be looking for pyproject.toml in the synapse_root dir?