search

matrix-org / synapse

Synapse: Matrix homeserver written in Python/Twisted.
https://matrix-org.github.io/synapse
Apache License 2.0
11.81k stars 2.13k forks source link

Testing with Complement has gotten so slow - 2 minutes to see test results #13204

Open MadLittleMods opened 2 years ago

MadLittleMods commented 2 years ago

I used to be able to make a change in Synapse and see Complement results after 20 seconds. Now it takes 1 minute 15 seconds just to build the Docker images at the start. And over 2 minutes to see the test results for running a single Complement test. This makes local dev such a pain :feelsgood:

Discussed at https://matrix.to/#/!alCakyySsFIAVfZLDL:matrix.org/$HuKnVFoLYs_uiDNbENnYs_ALqgQKjbhDrm3wbYYkLwI?via=matrix.org&via=element.io&via=termina.org.uk

Docker build is too slow

When I'm just doing feature work, I don't care about workers, I don't care about Postgres (whatever is new and making it slow).

1 minute 15 seconds of Docker building after changing Synapse:

Complement run ./scripts-dev/complement.sh ``` $ COMPLEMENT_ALWAYS_PRINT_SERVER_LOGS=1 COMPLEMENT_DIR=../complement ./scripts-dev/complement.sh -run TestJumpToDateEndpoint/parallel/federation/can_get_pagination_token_after_getting_remote_event_from_timestamp_to_event_endpoint [+] Building 22.0s (25/25) FINISHED => [internal] load build definition from Dockerfile 0.0s => => transferring dockerfile: 5.62kB 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 35B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.3s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:443aab4ca21183e069e7d8b2dc68006594f40bddf1b15bbd83f5137bd93e80e2 0.0s => [internal] load build definition from Dockerfile 0.0s => [internal] load .dockerignore 0.0s => [internal] load metadata for docker.io/library/python:3.9-slim 0.3s => [internal] load build context 0.3s => => transferring context: 7.35MB 0.3s => [requirements 1/6] FROM docker.io/library/python:3.9-slim@sha256:c01a2db78654c1923da84aa41b829f6162011e3a75db255c24ea16fa2ad563a0 0.0s => CACHED [builder 2/7] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq build-essential 0.0s => CACHED [requirements 2/6] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq git && rm -rf / 0.0s => CACHED [requirements 3/6] RUN --mount=type=cache,target=/root/.cache/pip pip install --user "poetry-core==1.1.0a7" "git+https://github.com/python-poetry/poetry.git@fb13b3a676f476177f7937ffa480ee5cff9a90a5" 0.0s => CACHED [requirements 4/6] WORKDIR /synapse 0.0s => CACHED [requirements 5/6] COPY pyproject.toml poetry.lock /synapse/ 0.0s => CACHED [requirements 6/6] RUN /root/.local/bin/poetry export --extras all -o /synapse/requirements.txt ${TEST_ONLY_SKIP_DEP_HASH_VERIFICATION:+--without-hashes} 0.0s => CACHED [builder 3/7] COPY --from=requirements /synapse/requirements.txt /synapse/ 0.0s => CACHED [builder 4/7] RUN --mount=type=cache,target=/root/.cache/pip pip install --prefix="/install" --no-deps --no-warn-script-location -r /synapse/requirements.txt 0.0s => [builder 5/7] COPY synapse /synapse/synapse/ 0.5s => [builder 6/7] COPY pyproject.toml README.rst /synapse/ 0.0s => [builder 7/7] RUN pip install --prefix="/install" --no-deps --no-warn-script-location /synapse 8.8s => CACHED [stage-2 2/5] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq curl gosu l 0.0s => [stage-2 3/5] COPY --from=builder /install /usr/local 2.6s => [stage-2 4/5] COPY ./docker/start.py /start.py 0.1s => [stage-2 5/5] COPY ./docker/conf /conf 0.1s => exporting to image 2.5s => => exporting layers 2.5s => => writing image sha256:cf22ee98c4023602eaa86fe9b09d8043f4f01138f2aec7c745387444d0d45249 0.0s => => naming to docker.io/matrixdotorg/synapse 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them [+] Building 15.3s (12/12) FINISHED => [internal] load build definition from Dockerfile-workers 0.0s => => transferring dockerfile: 1.45kB 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 35B 0.0s => [internal] load metadata for docker.io/matrixdotorg/synapse:latest 0.0s => [internal] load build context 0.1s => => transferring context: 30.16kB 0.0s => [stage-0 1/7] FROM docker.io/matrixdotorg/synapse:latest 0.6s => [stage-0 2/7] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && DEBIAN_FRONTEND=noninteractive apt-get install -y 8.5s => [stage-0 3/7] RUN --mount=type=cache,target=/root/.cache/pip pip install supervisor~=4.2 4.9s => [stage-0 4/7] RUN rm /etc/nginx/sites-enabled/default 0.4s => [stage-0 5/7] COPY ./docker/conf-workers/* /conf/ 0.0s => [stage-0 6/7] COPY ./docker/prefix-log /usr/local/bin/ 0.1s => [stage-0 7/7] COPY ./docker/configure_workers_and_start.py /configure_workers_and_start.py 0.0s => exporting to image 0.4s => => exporting layers 0.4s => => writing image sha256:0b0ae26a584d7ae58927a2daba3b508d61245e1a41d4ac9ba5b92371a96d5445 0.0s => => naming to docker.io/matrixdotorg/synapse-workers 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them [+] Building 42.5s (13/13) FINISHED => [internal] load build definition from Dockerfile 0.0s => => transferring dockerfile: 37B 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 2B 0.0s => [internal] load metadata for docker.io/matrixdotorg/synapse-workers:latest 0.0s => [internal] load build context 0.0s => => transferring context: 177B 0.0s => [1/8] FROM docker.io/matrixdotorg/synapse-workers:latest 0.2s => [2/8] RUN apt-get update && DEBIAN_FRONTEND=noninteractive apt-get install --no-install-recommends -yqq postgresql-13 34.7s => [3/8] RUN pg_ctlcluster 13 main start && su postgres -c "echo "ALTER USER postgres PASSWORD 'somesecret'; CREATE DATABASE synapse ENCODING 'UTF8' LC_COLLATE='C' LC_CTYPE='C' template=template0;" | p 3.8s => [4/8] RUN mv /conf/shared.yaml.j2 /conf/shared-orig.yaml.j2 0.4s => [5/8] COPY conf/workers-shared-extra.yaml.j2 /conf/shared.yaml.j2 0.1s => [6/8] WORKDIR /data 0.1s => [7/8] COPY conf/postgres.supervisord.conf /etc/supervisor/conf.d/postgres.conf 0.1s => [8/8] COPY conf/start_for_complement.sh / 0.1s => exporting to image 2.9s => => exporting layers 2.9s => => writing image sha256:df7d7a1d4443960b49dbb310bdbd4af323c33c7900d26bf291c3fad894683453 0.0s => => naming to docker.io/library/complement-synapse 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them Images built; running complement ... ```

Relevant code: https://github.com/matrix-org/synapse/blob/dcc7873700da4a818e84c44c6190525d39a854cb/scripts-dev/complement.sh#L89-L107

With cache, the Synapse build used to take ~10s seconds, https://github.com/matrix-org/synapse/pull/9610, which has now doubled to ~20 seconds. And the rest was trivial.

Complement being slow

@kegsay pointed out these couple issues which would also slow down single test runs (stopping and shutting down containers):

The deploys at the start seem noticeable now at 20 seconds:

=== RUN   TestJumpToDateEndpoint
2022/07/07 08:44:59 Sharing [SERVER_NAME=hs1 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container
2022/07/07 08:45:07 Sharing [SERVER_NAME=hs2 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container
2022/07/07 08:45:17 Sharing [SERVER_NAME=hs1 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container
2022/07/07 08:45:17 Sharing [SERVER_NAME=hs2 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container
    msc3030_test.go:24: Deploy times: 17.9124869s blueprints, 5.628477139s containers

Test output no longer streams as it runs

This is just a related extra.

The tests used to stream out what it was doing as it went instead of only barfing it all up at the end. This used to work until we got multiple packages in Complement (tests and csapi ), https://github.com/matrix-org/complement/issues/215. This doesn't help with making Complement go faster but it does help with the feeling of it doing something vs just waiting around arbitrarily.

The way I workaround it now is to remove the ... from the end of

https://github.com/matrix-org/synapse/blob/dcc7873700da4a818e84c44c6190525d39a854cb/scripts-dev/complement.sh#L164

so it only runs against the single tests package where the feature work I care about is in.

reivilibre commented 2 years ago

I definitely feel where you're coming from; Complement tests are currently painful to run to the point where it's easy to get distracted on something else whilst waiting for the results to come back.

Regarding 'Docker build is too slow': Wonder if we could build the image once and then mount the source tree into the container as an editable install, to avoid needing to rebuild every time? As long as you don't change dependencies, that should be OK.

Regarding 'Complement being slow': I'm not sure what to best do about this. We could consider our plan to use checkpointing to checkpoint a running container and then cheaply recreate those, rather than building everything up from scratch each time. That said, 20s sounds like a long time to deploy the simple-case image. This probably merits some investigation to see where the time is actually going.

Regarding 'Test output no longer streams as it runs': I don't remember this ever being the case. I'm not sure I consider it that important; personally I don't think I'd use the logs except for after they're done, but if you're aware of an easy way to solve that and it bothers you, then why not.

I think it would be great if running a single test took more like 5 seconds or less.

richvdh commented 2 years ago

Test output no longer streams as it runs

Try sticking -p 1 on the complement.sh commandline.

MadLittleMods commented 2 years ago

I think it would be great if running a single test took more like 5 seconds or less.

@reivilibre Great ideas and hope we can get to this point too!

Test output no longer streams as it runs

Try sticking -p 1 on the complement.sh commandline.

@richvdh Sweet! For some reason I missed this but I see the behavior commented in the relevant Go source code I linked in https://github.com/golang/go/issues/49195

richvdh commented 2 years ago

@MadLittleMods how are you finding this now that #13279 has landed?

richvdh commented 2 years ago

I hope https://github.com/matrix-org/synapse/pull/13447 will improve this too

MadLittleMods commented 2 years ago

how are you finding this now that https://github.com/matrix-org/synapse/pull/13279 has landed?

@richvdh It's a big improvement šŸ‘ I'm getting test results after 46s and the Docker build part is taking around 24s.

Complement run after #13279 ``` COMPLEMENT_ALWAYS_PRINT_SERVER_LOGS=1 COMPLEMENT_DIR=../complement ./scripts-dev/complement.sh -run TestJumpToDateEndpoint/parallel/federation/can_get_pagination_token_after_getting_remote_event_from_timestamp_to_event_endpoint [+] Building 10.8s (25/25) FINISHED => [internal] load build definition from Dockerfile 0.0s => => transferring dockerfile: 6.55kB 0.0s => [internal] load .dockerignore 0.1s => => transferring context: 35B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.4s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:443aab4ca21183e069e7d8b2dc68006594f40bddf1b15bbd83f5137bd93e80e2 0.0s => [internal] load .dockerignore 0.0s => [internal] load build definition from Dockerfile 0.0s => [internal] load metadata for docker.io/library/python:3.9-slim 0.3s => [internal] load build context 0.2s => => transferring context: 7.42MB 0.2s => [requirements 1/6] FROM docker.io/library/python:3.9-slim@sha256:685d3815d7add382e3e6f2a0cdfb76d94212d8c426bca91d95ed607e8e5c1c7e 0.0s => CACHED [builder 2/7] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq build-essential 0.0s => CACHED [requirements 2/6] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq build-esse 0.0s => CACHED [requirements 3/6] RUN --mount=type=cache,target=/root/.cache/pip pip install --user "poetry-core==1.1.0a7" "git+https://github.com/python-poetry/poetry.git@fb13b3a676f476177f7937ffa480ee5cff9a90a5" 0.0s => CACHED [requirements 4/6] WORKDIR /synapse 0.0s => CACHED [requirements 5/6] COPY pyproject.toml poetry.lock /synapse/ 0.0s => CACHED [requirements 6/6] RUN if [ -z "$TEST_ONLY_IGNORE_POETRY_LOCKFILE" ]; then /root/.local/bin/poetry export --extras all -o /synapse/requirements.txt ${TEST_ONLY_SKIP_DEP_HASH_VERIFICATION:+--without- 0.0s => CACHED [builder 3/7] COPY --from=requirements /synapse/requirements.txt /synapse/ 0.0s => CACHED [builder 4/7] RUN --mount=type=cache,target=/root/.cache/pip pip install --prefix="/install" --no-deps --no-warn-script-location -r /synapse/requirements.txt 0.0s => [builder 5/7] COPY synapse /synapse/synapse/ 0.1s => [builder 6/7] COPY pyproject.toml README.rst /synapse/ 0.0s => [builder 7/7] RUN if [ -z "$TEST_ONLY_IGNORE_POETRY_LOCKFILE" ]; then pip install --prefix="/install" --no-deps --no-warn-script-location /synapse[all]; else pip install --prefix="/install" --no-warn 5.7s => CACHED [stage-2 2/5] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq curl gosu l 0.0s => [stage-2 3/5] COPY --from=builder /install /usr/local 1.1s => [stage-2 4/5] COPY ./docker/start.py /start.py 0.0s => [stage-2 5/5] COPY ./docker/conf /conf 0.0s => exporting to image 1.5s => => exporting layers 1.4s => => writing image sha256:14fa517db087735b1f5a83428862c923f92d3c9e9c6ba535e60ebcf19f7b9ef5 0.0s => => naming to docker.io/matrixdotorg/synapse 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them [+] Building 7.7s (16/16) FINISHED => [internal] load build definition from Dockerfile-workers 0.0s => => transferring dockerfile: 1.48kB 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 35B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.3s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:443aab4ca21183e069e7d8b2dc68006594f40bddf1b15bbd83f5137bd93e80e2 0.0s => [internal] load .dockerignore 0.0s => [internal] load build definition from Dockerfile-workers 0.0s => [internal] load metadata for docker.io/matrixdotorg/synapse:latest 0.0s => [stage-0 1/7] FROM docker.io/matrixdotorg/synapse:latest 0.1s => [internal] load build context 0.1s => => transferring context: 30.16kB 0.0s => [stage-0 2/7] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && DEBIAN_FRONTEND=noninteractive apt-get install -y 3.7s => [stage-0 3/7] RUN --mount=type=cache,target=/root/.cache/pip pip install supervisor~=4.2 2.8s => [stage-0 4/7] RUN rm /etc/nginx/sites-enabled/default 0.2s => [stage-0 5/7] COPY ./docker/conf-workers/* /conf/ 0.0s => [stage-0 6/7] COPY ./docker/prefix-log /usr/local/bin/ 0.0s => [stage-0 7/7] COPY ./docker/configure_workers_and_start.py /configure_workers_and_start.py 0.0s => exporting to image 0.2s => => exporting layers 0.2s => => writing image sha256:3ce0ede77d47900082cb8a083d07d74a7092edda38aa5fe40844d83483f8c83c 0.0s => => naming to docker.io/matrixdotorg/synapse-workers 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them [+] Building 2.9s (25/25) FINISHED => [internal] load build definition from Dockerfile 0.0s => => transferring dockerfile: 37B 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 2B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.3s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:443aab4ca21183e069e7d8b2dc68006594f40bddf1b15bbd83f5137bd93e80e2 0.0s => [internal] load build definition from Dockerfile 0.0s => [internal] load .dockerignore 0.0s => [internal] load metadata for docker.io/matrixdotorg/synapse-workers:latest 0.0s => [internal] load metadata for docker.io/library/postgres:13-bullseye 0.3s => [postgres_base 1/4] FROM docker.io/library/postgres:13-bullseye@sha256:03652c675ae177af98ddd50f9f4b4b2cf8ad38d0e116aa68fe670fbc2cf250fc 0.0s => => resolve docker.io/library/postgres:13-bullseye@sha256:03652c675ae177af98ddd50f9f4b4b2cf8ad38d0e116aa68fe670fbc2cf250fc 0.0s => [stage-1 1/11] FROM docker.io/matrixdotorg/synapse-workers:latest 0.2s => [internal] load build context 0.1s => => transferring context: 177B 0.0s => CACHED [postgres_base 2/4] RUN gosu postgres initdb --locale=C --encoding=UTF-8 --auth-host password 0.0s => CACHED [postgres_base 3/4] RUN echo "ALTER USER postgres PASSWORD 'somesecret'" | gosu postgres postgres --single 0.0s => CACHED [postgres_base 4/4] RUN echo "CREATE DATABASE synapse" | gosu postgres postgres --single 0.0s => [stage-1 2/11] RUN adduser --system --uid 999 postgres --home /var/lib/postgresql 0.3s => [stage-1 3/11] COPY --from=postgres_base /var/lib/postgresql /var/lib/postgresql 0.2s => [stage-1 4/11] COPY --from=postgres_base /usr/lib/postgresql /usr/lib/postgresql 0.2s => [stage-1 5/11] COPY --from=postgres_base /usr/share/postgresql /usr/share/postgresql 0.1s => [stage-1 6/11] RUN mkdir /var/run/postgresql && chown postgres /var/run/postgresql 0.2s => [stage-1 7/11] RUN mv /conf/shared.yaml.j2 /conf/shared-orig.yaml.j2 0.2s => [stage-1 8/11] COPY conf/workers-shared-extra.yaml.j2 /conf/shared.yaml.j2 0.0s => [stage-1 9/11] WORKDIR /data 0.0s => [stage-1 10/11] COPY conf/postgres.supervisord.conf /etc/supervisor/conf.d/postgres.conf 0.0s => [stage-1 11/11] COPY conf/start_for_complement.sh / 0.0s => exporting to image 0.4s => => exporting layers 0.3s => => writing image sha256:426a4129feb0766dc3f2f119427011316ad074078eaa72dd80ac9fbb0423ab00 0.0s => => naming to docker.io/library/complement-synapse 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them Images built; running complement 2022/08/03 11:56:09 config: &{BaseImageURI:complement-synapse BaseImageArgs:[] DebugLoggingEnabled:false AlwaysPrintServerLogs:true BestEffort:false EnvVarsPropagatePrefix:PASS_ SpawnHSTimeout:30s KeepBlueprints:[] HostMounts:[] PackageNamespace:fed CACertificate:0xc000a64580 CAPrivateKey:0xc000021b00} === RUN TestJumpToDateEndpoint 2022/08/03 11:56:09 Sharing [SERVER_NAME=hs1 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container 2022/08/03 11:56:15 Sharing [SERVER_NAME=hs2 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container 2022/08/03 11:56:23 Sharing [SERVER_NAME=hs2 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container 2022/08/03 11:56:23 Sharing [SERVER_NAME=hs1 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container msc3030_test.go:25: Deploy times: 13.659762083s blueprints, 3.991031375s containers msc3030_test.go:38: WARNING: Deployment.Client - HS name 'hs1' - user ID '@the-bridge-user:hs1' - deviceID not found === RUN TestJumpToDateEndpoint/parallel === RUN TestJumpToDateEndpoint/parallel/federation 2022/08/03 11:56:28 ============================================ --- PASS: TestJumpToDateEndpoint (19.51s) --- PASS: TestJumpToDateEndpoint/parallel (0.00s) --- PASS: TestJumpToDateEndpoint/parallel/federation (0.00s) testing: warning: no tests to run PASS ok github.com/matrix-org/complement/tests 20.722s [no tests to run] 2022/08/03 11:56:09 config: &{BaseImageURI:complement-synapse BaseImageArgs:[] DebugLoggingEnabled:false AlwaysPrintServerLogs:true BestEffort:false EnvVarsPropagatePrefix:PASS_ SpawnHSTimeout:30s KeepBlueprints:[] HostMounts:[] PackageNamespace:csapi CACertificate:0xc000718000 CAPrivateKey:0xc000623860} testing: warning: no tests to run PASS ok github.com/matrix-org/complement/tests/csapi 1.068s [no tests to run] ```

With https://github.com/matrix-org/synapse/pull/13447, I'm seeing results after 45s and the Docker build part is taking around 22s.

Complement run after #13447 ``` COMPLEMENT_ALWAYS_PRINT_SERVER_LOGS=1 COMPLEMENT_DIR=../complement ./scripts-dev/complement.sh -run TestJumpToDateEndpoint/parallel/federation/can_get_pagination_token_after_getting_remote_event_from_timestamp_to_event_endpoint [+] Building 11.1s (25/25) FINISHED => [internal] load build definition from Dockerfile 0.0s => => transferring dockerfile: 6.55kB 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 35B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.4s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:443aab4ca21183e069e7d8b2dc68006594f40bddf1b15bbd83f5137bd93e80e2 0.0s => [internal] load .dockerignore 0.0s => [internal] load build definition from Dockerfile 0.0s => [internal] load metadata for docker.io/library/python:3.9-slim 0.3s => [internal] load build context 0.2s => => transferring context: 7.42MB 0.2s => [requirements 1/6] FROM docker.io/library/python:3.9-slim@sha256:685d3815d7add382e3e6f2a0cdfb76d94212d8c426bca91d95ed607e8e5c1c7e 0.0s => CACHED [builder 2/7] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq build-essential 0.0s => CACHED [requirements 2/6] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq build-esse 0.0s => CACHED [requirements 3/6] RUN --mount=type=cache,target=/root/.cache/pip pip install --user "poetry-core==1.1.0a7" "git+https://github.com/python-poetry/poetry.git@fb13b3a676f476177f7937ffa480ee5cff9a90a5" 0.0s => CACHED [requirements 4/6] WORKDIR /synapse 0.0s => CACHED [requirements 5/6] COPY pyproject.toml poetry.lock /synapse/ 0.0s => CACHED [requirements 6/6] RUN if [ -z "$TEST_ONLY_IGNORE_POETRY_LOCKFILE" ]; then /root/.local/bin/poetry export --extras all -o /synapse/requirements.txt ${TEST_ONLY_SKIP_DEP_HASH_VERIFICATION:+--without- 0.0s => CACHED [builder 3/7] COPY --from=requirements /synapse/requirements.txt /synapse/ 0.0s => CACHED [builder 4/7] RUN --mount=type=cache,target=/root/.cache/pip pip install --prefix="/install" --no-deps --no-warn-script-location -r /synapse/requirements.txt 0.0s => [builder 5/7] COPY synapse /synapse/synapse/ 0.1s => [builder 6/7] COPY pyproject.toml README.rst /synapse/ 0.0s => [builder 7/7] RUN if [ -z "$TEST_ONLY_IGNORE_POETRY_LOCKFILE" ]; then pip install --prefix="/install" --no-deps --no-warn-script-location /synapse[all]; else pip install --prefix="/install" --no-warn 5.6s => CACHED [stage-2 2/5] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq curl gosu l 0.0s => [stage-2 3/5] COPY --from=builder /install /usr/local 1.3s => [stage-2 4/5] COPY ./docker/start.py /start.py 0.0s => [stage-2 5/5] COPY ./docker/conf /conf 0.0s => exporting to image 1.5s => => exporting layers 1.5s => => writing image sha256:efd6ab8d13d8ede77cf79dc36f47bb5ae3016b5d55baec6bf4f771e4cc3b98c4 0.0s => => naming to docker.io/matrixdotorg/synapse 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them [+] Building 5.6s (28/28) FINISHED => [internal] load build definition from Dockerfile-workers 0.0s => => transferring dockerfile: 2.59kB 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 35B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.4s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:443aab4ca21183e069e7d8b2dc68006594f40bddf1b15bbd83f5137bd93e80e2 0.0s => [internal] load build definition from Dockerfile-workers 0.0s => [internal] load .dockerignore 0.0s => [internal] load metadata for docker.io/library/debian:bullseye-slim 0.3s => [internal] load metadata for docker.io/matrixdotorg/synapse:latest 0.0s => [internal] load metadata for docker.io/library/redis:6-bullseye 0.3s => [stage-2 1/14] FROM docker.io/matrixdotorg/synapse:latest 0.1s => CACHED [redis_base 1/1] FROM docker.io/library/redis:6-bullseye@sha256:bb68a5dcc8c03669be085343e3240983f6ebb7bb7cef0ab9a222b9b7cd33054e 0.0s => [deps_base 1/2] FROM docker.io/library/debian:bullseye-slim@sha256:a811e62769a642241b168ac34f615fb02da863307a14c4432cea8e5a0f9782b8 0.0s => [internal] load build context 0.1s => => transferring context: 30.16kB 0.0s => CACHED [deps_base 2/2] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && DEBIAN_FRONTEND=noninter 0.0s => [stage-2 2/14] RUN --mount=type=cache,target=/root/.cache/pip pip install supervisor~=4.2 2.9s => [stage-2 3/14] RUN mkdir -p /etc/supervisor/conf.d 0.2s => [stage-2 4/14] COPY --from=redis_base /usr/local/bin/redis-server /usr/local/bin 0.1s => [stage-2 5/14] COPY --from=deps_base /usr/sbin/nginx /usr/sbin 0.0s => [stage-2 6/14] COPY --from=deps_base /usr/share/nginx /usr/share/nginx 0.0s => [stage-2 7/14] COPY --from=deps_base /usr/lib/nginx /usr/lib/nginx 0.0s => [stage-2 8/14] COPY --from=deps_base /etc/nginx /etc/nginx 0.0s => [stage-2 9/14] RUN rm /etc/nginx/sites-enabled/default 0.2s => [stage-2 10/14] RUN mkdir /var/log/nginx /var/lib/nginx 0.2s => [stage-2 11/14] RUN chown www-data /var/log/nginx /var/lib/nginx 0.3s => [stage-2 12/14] COPY ./docker/conf-workers/* /conf/ 0.0s => [stage-2 13/14] COPY ./docker/prefix-log /usr/local/bin/ 0.0s => [stage-2 14/14] COPY ./docker/configure_workers_and_start.py /configure_workers_and_start.py 0.0s => exporting to image 0.2s => => exporting layers 0.2s => => writing image sha256:a58a618fddd26fdedc046e26f2832905d8d17f3847b4f02815c855cdc012e68e 0.0s => => naming to docker.io/matrixdotorg/synapse-workers 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them [+] Building 3.4s (25/25) FINISHED => [internal] load build definition from Dockerfile 0.0s => => transferring dockerfile: 37B 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 2B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.3s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:443aab4ca21183e069e7d8b2dc68006594f40bddf1b15bbd83f5137bd93e80e2 0.0s => [internal] load .dockerignore 0.0s => [internal] load build definition from Dockerfile 0.0s => [internal] load metadata for docker.io/library/postgres:13-bullseye 0.3s => [internal] load metadata for docker.io/matrixdotorg/synapse-workers:latest 0.0s => [stage-1 1/11] FROM docker.io/matrixdotorg/synapse-workers:latest 0.4s => [postgres_base 1/4] FROM docker.io/library/postgres:13-bullseye@sha256:03652c675ae177af98ddd50f9f4b4b2cf8ad38d0e116aa68fe670fbc2cf250fc 0.0s => => resolve docker.io/library/postgres:13-bullseye@sha256:03652c675ae177af98ddd50f9f4b4b2cf8ad38d0e116aa68fe670fbc2cf250fc 0.0s => [internal] load build context 0.1s => => transferring context: 177B 0.0s => CACHED [postgres_base 2/4] RUN gosu postgres initdb --locale=C --encoding=UTF-8 --auth-host password 0.0s => CACHED [postgres_base 3/4] RUN echo "ALTER USER postgres PASSWORD 'somesecret'" | gosu postgres postgres --single 0.0s => CACHED [postgres_base 4/4] RUN echo "CREATE DATABASE synapse" | gosu postgres postgres --single 0.0s => [stage-1 2/11] RUN adduser --system --uid 999 postgres --home /var/lib/postgresql 0.3s => [stage-1 3/11] COPY --from=postgres_base /var/lib/postgresql /var/lib/postgresql 0.2s => [stage-1 4/11] COPY --from=postgres_base /usr/lib/postgresql /usr/lib/postgresql 0.3s => [stage-1 5/11] COPY --from=postgres_base /usr/share/postgresql /usr/share/postgresql 0.1s => [stage-1 6/11] RUN mkdir /var/run/postgresql && chown postgres /var/run/postgresql 0.3s => [stage-1 7/11] RUN mv /conf/shared.yaml.j2 /conf/shared-orig.yaml.j2 0.4s => [stage-1 8/11] COPY conf/workers-shared-extra.yaml.j2 /conf/shared.yaml.j2 0.0s => [stage-1 9/11] WORKDIR /data 0.0s => [stage-1 10/11] COPY conf/postgres.supervisord.conf /etc/supervisor/conf.d/postgres.conf 0.0s => [stage-1 11/11] COPY conf/start_for_complement.sh / 0.0s => exporting to image 0.4s => => exporting layers 0.3s => => writing image sha256:32b547bd90633df28ce7e34f72435611848271f4b95f779b265f9b1739eaf241 0.0s => => naming to docker.io/library/complement-synapse 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them Images built; running complement 2022/08/03 12:01:35 config: &{BaseImageURI:complement-synapse BaseImageArgs:[] DebugLoggingEnabled:false AlwaysPrintServerLogs:true BestEffort:false EnvVarsPropagatePrefix:PASS_ SpawnHSTimeout:30s KeepBlueprints:[] HostMounts:[] PackageNamespace:fed CACertificate:0xc000b50000 CAPrivateKey:0xc0001330e0} === RUN TestJumpToDateEndpoint 2022/08/03 12:01:35 Sharing [SERVER_NAME=hs1 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container 2022/08/03 12:01:42 Sharing [SERVER_NAME=hs2 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container 2022/08/03 12:01:49 Sharing [SERVER_NAME=hs1 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container 2022/08/03 12:01:49 Sharing [SERVER_NAME=hs2 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container msc3030_test.go:25: Deploy times: 13.547335877s blueprints, 3.988464432s containers msc3030_test.go:38: WARNING: Deployment.Client - HS name 'hs1' - user ID '@the-bridge-user:hs1' - deviceID not found === RUN TestJumpToDateEndpoint/parallel === RUN TestJumpToDateEndpoint/parallel/federation 2022/08/03 12:01:54 ============================================ --- PASS: TestJumpToDateEndpoint (19.45s) --- PASS: TestJumpToDateEndpoint/parallel (0.00s) --- PASS: TestJumpToDateEndpoint/parallel/federation (0.00s) testing: warning: no tests to run PASS ok github.com/matrix-org/complement/tests 23.361s [no tests to run] 2022/08/03 12:01:35 config: &{BaseImageURI:complement-synapse BaseImageArgs:[] DebugLoggingEnabled:false AlwaysPrintServerLogs:true BestEffort:false EnvVarsPropagatePrefix:PASS_ SpawnHSTimeout:30s KeepBlueprints:[] HostMounts:[] PackageNamespace:csapi CACertificate:0xc000e00000 CAPrivateKey:0xc000096ba0} testing: warning: no tests to run PASS ok github.com/matrix-org/complement/tests/csapi 3.788s [no tests to run] ```

(just noticed they're both not running any actual tests since that test name has since changed slightly so that is all just Synapse/Complement doing things)

MadLittleMods commented 2 years ago

This has regressed hard (over 3 minutes to get results now). I'm getting test results after 193s and the Docker build part is taking around 160s.

Complement run (latest develop 0c853e09709d52783efd37060ed9e8f55a4fc704) ```sh COMPLEMENT_ALWAYS_PRINT_SERVER_LOGS=1 COMPLEMENT_DIR=../complement ./scripts-dev/complement.sh -run TestJumpToDateEndpoint/parallel/federation/can_get_pagination_token_after_getting_remote_event_from_timestamp_to_event [+] Building 132.2s (28/28) FINISHED => [internal] load build definition from Dockerfile 0.0s => => transferring dockerfile: 6.29kB 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 35B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.3s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:9ba7531bd80fb0a858632727cf7a112fbfd19b17e94c4e84ced81e24ef1a0dbc 0.0s => [internal] load build definition from Dockerfile 0.0s => [internal] load .dockerignore 0.0s => [internal] load metadata for docker.io/library/python:3.9-slim-bullseye 0.7s => [requirements 1/6] FROM docker.io/library/python:3.9-slim-bullseye@sha256:be8c64a08749503880e77755a1089272d4a201e395142aabd4bab54e7f547376 0.0s => => resolve docker.io/library/python:3.9-slim-bullseye@sha256:be8c64a08749503880e77755a1089272d4a201e395142aabd4bab54e7f547376 0.0s => [internal] load build context 0.3s => => transferring context: 7.80MB 0.3s => CACHED [builder 2/10] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq build-essential 0.0s => CACHED [builder 3/10] RUN mkdir /rust /cargo 0.0s => CACHED [builder 4/10] RUN curl -sSf https://sh.rustup.rs | sh -s -- -y --no-modify-path --default-toolchain stable 0.0s => CACHED [requirements 2/6] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq build-esse 0.0s => CACHED [requirements 3/6] RUN --mount=type=cache,target=/root/.cache/pip pip install --user "poetry==1.2.0" 0.0s => CACHED [requirements 4/6] WORKDIR /synapse 0.0s => CACHED [requirements 5/6] COPY pyproject.toml poetry.lock /synapse/ 0.0s => CACHED [requirements 6/6] RUN if [ -z "$TEST_ONLY_IGNORE_POETRY_LOCKFILE" ]; then /root/.local/bin/poetry export --extras all -o /synapse/requirements.txt ${TEST_ONLY_SKIP_DEP_HASH_VERIFICATION:+--without- 0.0s => CACHED [builder 5/10] COPY --from=requirements /synapse/requirements.txt /synapse/ 0.0s => CACHED [builder 6/10] RUN --mount=type=cache,target=/root/.cache/pip pip install --prefix="/install" --no-deps --no-warn-script-location -r /synapse/requirements.txt 0.0s => [builder 7/10] COPY synapse /synapse/synapse/ 0.3s => [builder 8/10] COPY rust /synapse/rust/ 0.1s => [builder 9/10] COPY pyproject.toml README.rst build_rust.py /synapse/ 0.1s => [builder 10/10] RUN if [ -z "$TEST_ONLY_IGNORE_POETRY_LOCKFILE" ]; then pip install --prefix="/install" --no-deps --no-warn-script-location /synapse[all]; else pip install --prefix="/install" --no- 119.4s => CACHED [stage-2 2/5] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq curl gosu l 0.0s => [stage-2 3/5] COPY --from=builder /install /usr/local 2.7s => [stage-2 4/5] COPY ./docker/start.py /start.py 0.1s => [stage-2 5/5] COPY ./docker/conf /conf 0.1s => exporting to image 3.4s => => exporting layers 3.4s => => writing image sha256:14c236db441a8ad234b6c9f946688210303b8f715c0f1587520584675187d2e4 0.0s => => naming to docker.io/matrixdotorg/synapse 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them [+] Building 9.9s (30/30) FINISHED => [internal] load build definition from Dockerfile-workers 0.0s => => transferring dockerfile: 2.71kB 0.0s => [internal] load .dockerignore 0.1s => => transferring context: 35B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.9s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:9ba7531bd80fb0a858632727cf7a112fbfd19b17e94c4e84ced81e24ef1a0dbc 0.0s => [internal] load build definition from Dockerfile-workers 0.0s => [internal] load .dockerignore 0.0s => [internal] load metadata for docker.io/matrixdotorg/synapse:latest 0.0s => [internal] load metadata for docker.io/library/redis:6-bullseye 0.4s => [internal] load metadata for docker.io/library/debian:bullseye-slim 0.4s => [internal] load build context 0.1s => => transferring context: 30.13kB 0.1s => CACHED [redis_base 1/1] FROM docker.io/library/redis:6-bullseye@sha256:a3824c5447368a08bba8b3aaa910a8c8f4550729b946efac0b378a7ad247040d 0.0s => => resolve docker.io/library/redis:6-bullseye@sha256:a3824c5447368a08bba8b3aaa910a8c8f4550729b946efac0b378a7ad247040d 0.0s => [deps_base 1/2] FROM docker.io/library/debian:bullseye-slim@sha256:b46fc4e6813f6cbd9f3f6322c72ab974cc0e75a72ca02730a8861e98999875c7 0.0s => => resolve docker.io/library/debian:bullseye-slim@sha256:b46fc4e6813f6cbd9f3f6322c72ab974cc0e75a72ca02730a8861e98999875c7 0.0s => [stage-2 1/16] FROM docker.io/matrixdotorg/synapse:latest 0.2s => CACHED [deps_base 2/2] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && DEBIAN_FRONTEND=noninter 0.0s => [stage-2 2/16] RUN --mount=type=cache,target=/root/.cache/pip pip install supervisor~=4.2 4.3s => [stage-2 3/16] RUN mkdir -p /etc/supervisor/conf.d 0.4s => [stage-2 4/16] COPY --from=redis_base /usr/local/bin/redis-server /usr/local/bin 0.1s => [stage-2 5/16] COPY --from=deps_base /usr/sbin/nginx /usr/sbin 0.1s => [stage-2 6/16] COPY --from=deps_base /usr/share/nginx /usr/share/nginx 0.1s => [stage-2 7/16] COPY --from=deps_base /usr/lib/nginx /usr/lib/nginx 0.1s => [stage-2 8/16] COPY --from=deps_base /etc/nginx /etc/nginx 0.1s => [stage-2 9/16] RUN rm /etc/nginx/sites-enabled/default 0.4s => [stage-2 10/16] RUN mkdir /var/log/nginx /var/lib/nginx 0.5s => [stage-2 11/16] RUN chown www-data /var/lib/nginx 0.4s => [stage-2 12/16] RUN ln -sf /dev/stdout /var/log/nginx/access.log 0.4s => [stage-2 13/16] RUN ln -sf /dev/stderr /var/log/nginx/error.log 0.3s => [stage-2 14/16] COPY ./docker/conf-workers/* /conf/ 0.1s => [stage-2 15/16] COPY ./docker/prefix-log /usr/local/bin/ 0.0s => [stage-2 16/16] COPY ./docker/configure_workers_and_start.py /configure_workers_and_start.py 0.0s => exporting to image 0.5s => => exporting layers 0.4s => => writing image sha256:d65dd0a77bda80710fbe9bb3abe2b9c0e04d2ed6656b1f92159e120588bbc102 0.0s => => naming to docker.io/matrixdotorg/synapse-workers 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them [+] Building 11.6s (24/24) FINISHED => [internal] load build definition from Dockerfile 0.0s => => transferring dockerfile: 37B 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 2B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.3s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:9ba7531bd80fb0a858632727cf7a112fbfd19b17e94c4e84ced81e24ef1a0dbc 0.0s => [internal] load .dockerignore 0.0s => [internal] load build definition from Dockerfile 0.0s => [internal] load metadata for docker.io/matrixdotorg/synapse-workers:latest 0.0s => [internal] load metadata for docker.io/library/postgres:13-bullseye 0.7s => CACHED FROM docker.io/library/postgres:13-bullseye@sha256:7cc1c1a6a9df06df9e775eccdd77e45a868cb197e8e0981e23a2a814aaf56906 0.0s => [internal] load build context 0.0s => => transferring context: 177B 0.0s => [stage-0 1/13] FROM docker.io/matrixdotorg/synapse-workers:latest 0.6s => [stage-0 2/13] RUN adduser --system --uid 999 postgres --home /var/lib/postgresql 0.4s => [stage-0 3/13] COPY --from=postgres:13-bullseye /usr/lib/postgresql /usr/lib/postgresql 0.3s => [stage-0 4/13] COPY --from=postgres:13-bullseye /usr/share/postgresql /usr/share/postgresql 0.1s => [stage-0 5/13] RUN mkdir /var/run/postgresql && chown postgres /var/run/postgresql 3.3s => [stage-0 6/13] RUN gosu postgres initdb --locale=C --encoding=UTF-8 --auth-host password 2.5s => [stage-0 7/13] RUN echo "ALTER USER postgres PASSWORD 'somesecret'" | gosu postgres postgres --single 0.5s => [stage-0 8/13] RUN echo "CREATE DATABASE synapse" | gosu postgres postgres --single 0.9s => [stage-0 9/13] RUN mv /conf/shared.yaml.j2 /conf/shared-orig.yaml.j2 0.4s => [stage-0 10/13] COPY conf/workers-shared-extra.yaml.j2 /conf/shared.yaml.j2 0.1s => [stage-0 11/13] WORKDIR /data 0.0s => [stage-0 12/13] COPY conf/postgres.supervisord.conf /etc/supervisor/conf.d/postgres.conf 0.0s => [stage-0 13/13] COPY conf/start_for_complement.sh / 0.0s => exporting to image 0.7s => => exporting layers 0.6s => => writing image sha256:54611a977f92935f5e5bbfe77a8e43937688a897853794979a9d16748f615dad 0.0s => => naming to docker.io/library/complement-synapse 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them Images built; running complement # github.com/matrix-org/complement/tests/csapi.test ld: warning: -no_pie is deprecated when targeting new OS versions # github.com/matrix-org/complement/tests.test ld: warning: -no_pie is deprecated when targeting new OS versions 2022/10/07 02:08:18 config: &{BaseImageURI:complement-synapse DebugLoggingEnabled:false AlwaysPrintServerLogs:true EnvVarsPropagatePrefix:PASS_ SpawnHSTimeout:30s KeepBlueprints:[] HostMounts:[] BaseImageURIs:map[] PackageNamespace:fed CACertificate:0xc0012f4000 CAPrivateKey:0xc000781200 BestEffort:false HostnameRunningComplement:host.docker.internal} === RUN TestJumpToDateEndpoint 2022/10/07 02:08:18 Sharing [SERVER_NAME=hs1 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container 2022/10/07 02:08:29 Sharing [SERVER_NAME=hs2 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container 2022/10/07 02:08:42 Sharing [SERVER_NAME=hs1 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container 2022/10/07 02:08:42 Sharing [SERVER_NAME=hs2 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container msc3030_test.go:25: Deploy times: 23.322896811s blueprints, 5.64588808s containers msc3030_test.go:38: WARNING: Deployment.Client - HS name 'hs1' - user ID '@the-bridge-user:hs1' - deviceID not found === RUN TestJumpToDateEndpoint/parallel === RUN TestJumpToDateEndpoint/parallel/federation 2022/10/07 02:08:48 ============================================ 2022/10/07 02:08:48 1ddbe36168b9dbb7ab84444d985c9c37648105d471b96565a6a44c5d760bb450 : Server logs: Complement Synapse launcher Args: Env: SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS= Generating RSA private key, 2048 bit long modulus (2 primes) .....+++++ .......................+++++ e is 65537 (0x010001) Signature ok subject=CN = hs2 Getting CA Private Key DNS:hs2 2022-10-07 07:08:43,591 INFO Included extra file "/etc/supervisor/conf.d/postgres.conf" during parsing 2022-10-07 07:08:43,591 INFO Included extra file "/etc/supervisor/conf.d/synapse.conf" during parsing 2022-10-07 07:08:43,591 INFO Set uid to user 0 succeeded 2022-10-07 07:08:43,593 INFO supervisord started with pid 1 2022-10-07 07:08:44,597 INFO spawned: 'synapse_main' with pid 25 2022-10-07 07:08:44,599 INFO spawned: 'nginx' with pid 26 2022-10-07 07:08:46,567 INFO success: synapse_main entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) 2022-10-07 07:08:46,567 INFO success: nginx entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) synapse_main | 2022-10-07 07:08:46,803 - root - 343 - WARNING - main - ***** STARTING SERVER ***** synapse_main | 2022-10-07 07:08:46,803 - root - 344 - WARNING - main - Server /usr/local/lib/python3.9/site-packages/synapse/app/homeserver.py version 1.69.0rc2 synapse_main | 2022-10-07 07:08:46,803 - root - 349 - INFO - main - Server hostname: hs2 synapse_main | 2022-10-07 07:08:46,803 - root - 350 - INFO - main - Instance name: master synapse_main | 2022-10-07 07:08:46,804 - synapse.app.homeserver - 372 - INFO - main - Setting up server synapse_main | 2022-10-07 07:08:46,804 - synapse.server - 307 - INFO - main - Setting up. synapse_main | 2022-10-07 07:08:46,810 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server synapse_main | 2022-10-07 07:08:46,810 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state'] synapse_main | 2022-10-07 07:08:46,810 - synapse.storage.prepare_database - 115 - INFO - main - ['main', 'state']: Checking existing schema version synapse_main | 2022-10-07 07:08:46,813 - synapse.storage.prepare_database - 119 - INFO - main - ['main', 'state']: Existing schema is 73 (+11 deltas) synapse_main | 2022-10-07 07:08:46,814 - synapse.storage.databases.main - 311 - INFO - main - Checking database for consistency with configuration... synapse_main | 2022-10-07 07:08:46,814 - synapse.storage.prepare_database - 411 - INFO - main - Applying schema deltas for v73 synapse_main | 2022-10-07 07:08:46,815 - synapse.storage.prepare_database - 546 - INFO - main - Schema now up to date synapse_main | 2022-10-07 07:08:46,820 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'main' database synapse_main | 2022-10-07 07:08:46,821 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_stream(stream_id): 2 synapse_main | 2022-10-07 07:08:46,822 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for user_signature_stream(stream_id): 1 synapse_main | 2022-10-07 07:08:46,822 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_outbound_pokes(stream_id): 1 synapse_main | 2022-10-07 07:08:46,822 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_changes_in_room(stream_id): 1 synapse_main | 2022-10-07 07:08:46,822 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for receipts_linearized(stream_id): 1 synapse_main | 2022-10-07 07:08:46,823 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): 1 synapse_main | 2022-10-07 07:08:46,823 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): -1 synapse_main | 2022-10-07 07:08:46,824 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for ex_outlier_stream(event_stream_ordering): -1 synapse_main | 2022-10-07 07:08:46,826 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_inbox(stream_id): 1 synapse_main | 2022-10-07 07:08:46,827 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for pushers(id): 1 synapse_main | 2022-10-07 07:08:46,827 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for deleted_pushers(stream_id): 1 synapse_main | 2022-10-07 07:08:46,828 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_stream(stream_id): 1 synapse_main | 2022-10-07 07:08:46,828 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_account_data(stream_id): 1 synapse_main | 2022-10-07 07:08:46,829 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_tags_revisions(stream_id): 1 synapse_main | 2022-10-07 07:08:46,829 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for e2e_cross_signing_keys(stream_id): 1 synapse_main | 2022-10-07 07:08:46,829 - synapse.storage.databases.main.event_push_actions - 1048 - INFO - main - Searching for stream ordering 1 month ago synapse_main | 2022-10-07 07:08:46,829 - synapse.storage.databases.main.event_push_actions - 1052 - INFO - main - Found stream ordering 1 month ago: it's 0 synapse_main | 2022-10-07 07:08:46,829 - synapse.storage.databases.main.event_push_actions - 1055 - INFO - main - Searching for stream ordering 1 day ago synapse_main | 2022-10-07 07:08:46,830 - synapse.storage.databases.main.event_push_actions - 1059 - INFO - main - Found stream ordering 1 day ago: it's 0 synapse_main | 2022-10-07 07:08:46,830 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules(id): 1 synapse_main | 2022-10-07 07:08:46,830 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_enable(id): 1 synapse_main | 2022-10-07 07:08:46,831 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for presence_stream(stream_id): 1 synapse_main | 2022-10-07 07:08:46,831 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for access_tokens(id): 2 synapse_main | 2022-10-07 07:08:46,832 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for refresh_tokens(id): 1 synapse_main | 2022-10-07 07:08:46,832 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for event_reports(id): 1 synapse_main | 2022-10-07 07:08:46,833 - synapse.storage.databases - 101 - INFO - main - [database config 'master']: Starting 'state' database synapse_main | 2022-10-07 07:08:46,834 - synapse.storage.databases - 116 - INFO - main - [database config 'master']: prepared synapse_main | 2022-10-07 07:08:46,834 - synapse.server - 310 - INFO - main - Finished setting up. synapse_main | 2022-10-07 07:08:46,846 - synapse.push.pusher - 38 - INFO - main - email enable notifs: False synapse_main | 2022-10-07 07:08:46,847 - synapse.federation.federation_server - 1397 - INFO - main - Registering federation EDU handler for 'm.device_list_update' synapse_main | 2022-10-07 07:08:46,848 - synapse.federation.federation_server - 1417 - INFO - main - Registering federation query handler for 'profile' synapse_main | 2022-10-07 07:08:46,849 - synapse.federation.federation_server - 1397 - INFO - main - Registering federation EDU handler for 'm.presence' synapse_main | 2022-10-07 07:08:46,849 - synapse.federation.federation_server - 1397 - INFO - main - Registering federation EDU handler for 'm.typing' synapse_main | 2022-10-07 07:08:46,850 - synapse.federation.federation_server - 1417 - INFO - main - Registering federation query handler for 'directory' synapse_main | 2022-10-07 07:08:46,852 - twisted - 274 - INFO - main - Redirected stdout/stderr to logs synapse_main | 2022-10-07 07:08:46,852 - synapse.app.homeserver - 165 - INFO - sentinel - Running synapse_main | 2022-10-07 07:08:46,855 - synapse.app.homeserver - 29 - INFO - sentinel - Set file limit to: 1048576 synapse_main | 2022-10-07 07:08:46,857 - synapse.handlers.deactivate_account - 230 - INFO - user_parter_loop-0 - Starting user parter synapse_main | 2022-10-07 07:08:46,864 - synapse.util.caches.lrucache - 225 - INFO - sentinel - Expiring LRU caches after 1800 seconds synapse_main | 2022-10-07 07:08:46,871 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/health' synapse_main | 2022-10-07 07:08:46,872 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/replication' synapse_main | 2022-10-07 07:08:46,872 - twisted - 274 - INFO - sentinel - SynapseSite starting on 9093 synapse_main | 2022-10-07 07:08:46,873 - synapse.app.homeserver - 172 - INFO - sentinel - Synapse now listening on TCP port 9093 synapse_main | 2022-10-07 07:08:46,889 - synapse.federation.federation_server - 1397 - INFO - sentinel - Registering federation EDU handler for 'm.receipt' synapse_main | 2022-10-07 07:08:46,889 - synapse.federation.federation_server - 1397 - INFO - sentinel - Registering federation EDU handler for 'm.signing_key_update' synapse_main | 2022-10-07 07:08:46,889 - synapse.federation.federation_server - 1397 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update' synapse_main | 2022-10-07 07:08:46,889 - synapse.federation.federation_server - 1417 - INFO - sentinel - Registering federation query handler for 'client_keys' synapse_main | 2022-10-07 07:08:46,890 - synapse.federation.federation_server - 1397 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device' synapse_main | 2022-10-07 07:08:46,899 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/health' synapse_main | 2022-10-07 07:08:46,899 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/client' synapse_main | 2022-10-07 07:08:46,899 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/.well-known' synapse_main | 2022-10-07 07:08:46,899 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/admin' synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/pick_idp' synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/pick_username' synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/new_user_consent' synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/sso_register' synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/unsubscribe' synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching FilePath('/usr/local/lib/python3.9/site-packages/synapse/static') to path b'/_matrix/static' synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/r0' synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/v3' synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/v1' synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/federation' synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/key/v2' 2022-10-07 07:08:48,553 WARN received SIGTERM indicating exit request 2022-10-07 07:08:48,554 INFO waiting for synapse_main, nginx to die nginx | 192.168.128.1 - - [07/Oct/2022:07:08:47 +0000] "GET /_matrix/client/versions HTTP/1.1" 200 293 "-" "Go-http-client/1.1" 2022-10-07 07:08:48,562 INFO stopped: nginx (exit status 0) 2022-10-07 07:08:48,562 INFO reaped unknown pid 31 (exit status 0) 2022-10-07 07:08:48,562 INFO reaped unknown pid 32 (exit status 0) synapse_main | 2022-10-07 07:08:46,901 - twisted - 274 - INFO - sentinel - SynapseSite starting on 8080 synapse_main | 2022-10-07 07:08:46,901 - synapse.app.homeserver - 172 - INFO - sentinel - Synapse now listening on TCP port 8080 synapse_main | 2022-10-07 07:08:46,902 - synapse.storage.database - 844 - WARNING - sentinel - Starting db txn 'count_daily_users' from sentinel context synapse_main | 2022-10-07 07:08:46,902 - synapse.storage.database - 909 - WARNING - sentinel - Starting db connection from sentinel context: metrics will be lost synapse_main | 2022-10-07 07:08:46,903 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-0 - User parter finished: stopping synapse_main | 2022-10-07 07:08:46,907 - synapse.push.pusherpool - 347 - INFO - start_pushers-0 - Started pushers synapse_main | 2022-10-07 07:08:46,970 - synapse.storage.background_updates - 288 - INFO - background_updates-0 - Starting background schema updates for database master synapse_main | 2022-10-07 07:08:47,551 - synapse.access.http.8080 - 459 - INFO - GET-1 - ::ffff:127.0.0.1 - 8080 - {None} Processed request: 0.001sec/0.001sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 281B 200 "GET /_matrix/client/versions HTTP/1.0" "Go-http-client/1.1" [0 dbevts] synapse_main | 2022-10-07 07:08:47,976 - synapse.storage.background_updates - 431 - INFO - background_updates-0 - Starting update batch on background update 'receipts_graph_unique_index' synapse_main | 2022-10-07 07:08:47,978 - synapse.storage.background_updates - 623 - INFO - background_updates-0 - Adding index receipts_graph_unique_index to receipts_graph synapse_main | 2022-10-07 07:08:47,987 - synapse.storage.background_updates - 474 - INFO - background_updates-0 - Running background update 'receipts_graph_unique_index'. Processed 1 items in 9ms. (total_rate=0.1111111111111111/ms, current_rate=0.11111111111111112/ms, total_updated=1, batch_size=100) synapse_main | 2022-10-07 07:08:48,563 - twisted - 274 - INFO - sentinel - Received SIGTERM, shutting down. synapse_main | 2022-10-07 07:08:48,564 - synapse.storage.databases.main.lock - 92 - INFO - LockStore._on_shutdown-0 - Dropping held locks due to shutdown synapse_main | 2022-10-07 07:08:48,564 - synapse.storage.databases.main.lock - 101 - INFO - LockStore._on_shutdown-0 - Dropped locks due to shutdown synapse_main | 2022-10-07 07:08:48,564 - synapse.handlers.presence - 766 - INFO - presence.on_shutdown-0 - Performing _on_shutdown. Persisting 0 unpersisted changes synapse_main | 2022-10-07 07:08:48,564 - synapse.handlers.presence - 779 - INFO - presence.on_shutdown-0 - Finished _on_shutdown synapse_main | 2022-10-07 07:08:48,565 - synapse.app._base - 492 - INFO - sentinel - Shutting down... synapse_main | 2022-10-07 07:08:48,565 - twisted - 274 - INFO - sentinel - (TCP Port 9093 Closed) synapse_main | 2022-10-07 07:08:48,565 - twisted - 274 - INFO - sentinel - (TCP Port 8080 Closed) synapse_main | 2022-10-07 07:08:48,567 - twisted - 274 - INFO - sentinel - Main loop terminated. 2022-10-07 07:08:48,605 INFO stopped: synapse_main (exit status 0) 2022-10-07 07:08:48,605 INFO reaped unknown pid 28 (exit status 0) 2022/10/07 02:08:48 ============== 1ddbe36168b9dbb7ab84444d985c9c37648105d471b96565a6a44c5d760bb450 : END LOGS ============== 2022/10/07 02:08:49 ============================================ 2022/10/07 02:08:49 6cdadf46f4980c587d2d4e276825fb5ecedfae69bc812f29dc3d80842f942584 : Server logs: Complement Synapse launcher Args: Env: SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS= Generating RSA private key, 2048 bit long modulus (2 primes) ...............................................................................................+++++ ..........................+++++ e is 65537 (0x010001) Signature ok subject=CN = hs1 Getting CA Private Key DNS:hs1 2022-10-07 07:08:43,838 INFO Included extra file "/etc/supervisor/conf.d/postgres.conf" during parsing 2022-10-07 07:08:43,838 INFO Included extra file "/etc/supervisor/conf.d/synapse.conf" during parsing 2022-10-07 07:08:43,839 INFO Set uid to user 0 succeeded 2022-10-07 07:08:43,840 INFO supervisord started with pid 1 2022-10-07 07:08:44,844 INFO spawned: 'synapse_main' with pid 23 2022-10-07 07:08:44,847 INFO spawned: 'nginx' with pid 24 2022-10-07 07:08:46,816 INFO success: synapse_main entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) 2022-10-07 07:08:46,816 INFO success: nginx entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) synapse_main | 2022-10-07 07:08:47,095 - root - 343 - WARNING - main - ***** STARTING SERVER ***** synapse_main | 2022-10-07 07:08:47,096 - root - 344 - WARNING - main - Server /usr/local/lib/python3.9/site-packages/synapse/app/homeserver.py version 1.69.0rc2 synapse_main | 2022-10-07 07:08:47,096 - root - 349 - INFO - main - Server hostname: hs1 synapse_main | 2022-10-07 07:08:47,096 - root - 350 - INFO - main - Instance name: master synapse_main | 2022-10-07 07:08:47,096 - synapse.app.homeserver - 372 - INFO - main - Setting up server synapse_main | 2022-10-07 07:08:47,096 - synapse.server - 307 - INFO - main - Setting up. synapse_main | 2022-10-07 07:08:47,101 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server synapse_main | 2022-10-07 07:08:47,102 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state'] synapse_main | 2022-10-07 07:08:47,102 - synapse.storage.prepare_database - 115 - INFO - main - ['main', 'state']: Checking existing schema version synapse_main | 2022-10-07 07:08:47,105 - synapse.storage.prepare_database - 119 - INFO - main - ['main', 'state']: Existing schema is 73 (+11 deltas) synapse_main | 2022-10-07 07:08:47,106 - synapse.storage.databases.main - 311 - INFO - main - Checking database for consistency with configuration... synapse_main | 2022-10-07 07:08:47,106 - synapse.storage.prepare_database - 411 - INFO - main - Applying schema deltas for v73 synapse_main | 2022-10-07 07:08:47,107 - synapse.storage.prepare_database - 546 - INFO - main - Schema now up to date synapse_main | 2022-10-07 07:08:47,111 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'main' database synapse_main | 2022-10-07 07:08:47,111 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_stream(stream_id): 3 synapse_main | 2022-10-07 07:08:47,111 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for user_signature_stream(stream_id): 1 synapse_main | 2022-10-07 07:08:47,111 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_outbound_pokes(stream_id): 1 synapse_main | 2022-10-07 07:08:47,112 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_changes_in_room(stream_id): 1 synapse_main | 2022-10-07 07:08:47,114 - synapse.config.appservice - 76 - INFO - main - Loaded application service: ApplicationService: {'token': '', 'url': 'http://localhost:9000', 'hs_token': '', 'sender': '@the-bridge-user:hs1', 'namespaces': {'users': [Namespace(exclusive=False, regex=re.compile('.*'))], 'aliases': [], 'rooms': []}, 'id': 'my_as_id', 'ip_range_whitelist': None, 'supports_ephemeral': False, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False} synapse_main | 2022-10-07 07:08:47,115 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for receipts_linearized(stream_id): 1 synapse_main | 2022-10-07 07:08:47,115 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): 1 synapse_main | 2022-10-07 07:08:47,116 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): -1 synapse_main | 2022-10-07 07:08:47,116 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for ex_outlier_stream(event_stream_ordering): -1 synapse_main | 2022-10-07 07:08:47,118 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_inbox(stream_id): 1 synapse_main | 2022-10-07 07:08:47,119 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for pushers(id): 1 synapse_main | 2022-10-07 07:08:47,119 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for deleted_pushers(stream_id): 1 synapse_main | 2022-10-07 07:08:47,120 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_stream(stream_id): 1 synapse_main | 2022-10-07 07:08:47,120 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_account_data(stream_id): 1 synapse_main | 2022-10-07 07:08:47,120 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_tags_revisions(stream_id): 1 synapse_main | 2022-10-07 07:08:47,121 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for e2e_cross_signing_keys(stream_id): 1 synapse_main | 2022-10-07 07:08:47,121 - synapse.storage.databases.main.event_push_actions - 1048 - INFO - main - Searching for stream ordering 1 month ago synapse_main | 2022-10-07 07:08:47,121 - synapse.storage.databases.main.event_push_actions - 1052 - INFO - main - Found stream ordering 1 month ago: it's 0 synapse_main | 2022-10-07 07:08:47,121 - synapse.storage.databases.main.event_push_actions - 1055 - INFO - main - Searching for stream ordering 1 day ago synapse_main | 2022-10-07 07:08:47,121 - synapse.storage.databases.main.event_push_actions - 1059 - INFO - main - Found stream ordering 1 day ago: it's 0 synapse_main | 2022-10-07 07:08:47,122 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules(id): 1 synapse_main | 2022-10-07 07:08:47,122 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_enable(id): 1 synapse_main | 2022-10-07 07:08:47,122 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for presence_stream(stream_id): 1 synapse_main | 2022-10-07 07:08:47,123 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for access_tokens(id): 3 synapse_main | 2022-10-07 07:08:47,123 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for refresh_tokens(id): 1 synapse_main | 2022-10-07 07:08:47,124 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for event_reports(id): 1 synapse_main | 2022-10-07 07:08:47,125 - synapse.storage.databases - 101 - INFO - main - [database config 'master']: Starting 'state' database synapse_main | 2022-10-07 07:08:47,125 - synapse.storage.databases - 116 - INFO - main - [database config 'master']: prepared synapse_main | 2022-10-07 07:08:47,126 - synapse.server - 310 - INFO - main - Finished setting up. synapse_main | 2022-10-07 07:08:47,136 - synapse.push.pusher - 38 - INFO - main - email enable notifs: False synapse_main | 2022-10-07 07:08:47,138 - synapse.federation.federation_server - 1397 - INFO - main - Registering federation EDU handler for 'm.device_list_update' synapse_main | 2022-10-07 07:08:47,138 - synapse.federation.federation_server - 1417 - INFO - main - Registering federation query handler for 'profile' synapse_main | 2022-10-07 07:08:47,140 - synapse.federation.federation_server - 1397 - INFO - main - Registering federation EDU handler for 'm.presence' synapse_main | 2022-10-07 07:08:47,140 - synapse.federation.federation_server - 1397 - INFO - main - Registering federation EDU handler for 'm.typing' synapse_main | 2022-10-07 07:08:47,141 - synapse.federation.federation_server - 1417 - INFO - main - Registering federation query handler for 'directory' synapse_main | 2022-10-07 07:08:47,142 - twisted - 274 - INFO - main - Redirected stdout/stderr to logs synapse_main | 2022-10-07 07:08:47,142 - synapse.app.homeserver - 165 - INFO - sentinel - Running synapse_main | 2022-10-07 07:08:47,146 - synapse.app.homeserver - 29 - INFO - sentinel - Set file limit to: 1048576 synapse_main | 2022-10-07 07:08:47,147 - synapse.handlers.deactivate_account - 230 - INFO - user_parter_loop-0 - Starting user parter synapse_main | 2022-10-07 07:08:47,153 - synapse.util.caches.lrucache - 225 - INFO - sentinel - Expiring LRU caches after 1800 seconds synapse_main | 2022-10-07 07:08:47,162 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/health' synapse_main | 2022-10-07 07:08:47,163 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/replication' synapse_main | 2022-10-07 07:08:47,164 - twisted - 274 - INFO - sentinel - SynapseSite starting on 9093 synapse_main | 2022-10-07 07:08:47,164 - synapse.app.homeserver - 172 - INFO - sentinel - Synapse now listening on TCP port 9093 synapse_main | 2022-10-07 07:08:47,180 - synapse.federation.federation_server - 1397 - INFO - sentinel - Registering federation EDU handler for 'm.receipt' synapse_main | 2022-10-07 07:08:47,181 - synapse.federation.federation_server - 1397 - INFO - sentinel - Registering federation EDU handler for 'm.signing_key_update' synapse_main | 2022-10-07 07:08:47,181 - synapse.federation.federation_server - 1397 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update' synapse_main | 2022-10-07 07:08:47,181 - synapse.federation.federation_server - 1417 - INFO - sentinel - Registering federation query handler for 'client_keys' synapse_main | 2022-10-07 07:08:47,182 - synapse.federation.federation_server - 1397 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device' synapse_main | 2022-10-07 07:08:47,191 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/health' synapse_main | 2022-10-07 07:08:47,191 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/client' synapse_main | 2022-10-07 07:08:47,191 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/.well-known' synapse_main | 2022-10-07 07:08:47,191 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/admin' synapse_main | 2022-10-07 07:08:47,191 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/pick_idp' synapse_main | 2022-10-07 07:08:47,191 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/pick_username' synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/new_user_consent' synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/sso_register' synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/unsubscribe' synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching FilePath('/usr/local/lib/python3.9/site-packages/synapse/static') to path b'/_matrix/static' synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/r0' synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/v3' 2022-10-07 07:08:49,199 WARN received SIGTERM indicating exit request 2022-10-07 07:08:49,200 INFO waiting for synapse_main, nginx to die nginx | 192.168.128.1 - - [07/Oct/2022:07:08:47 +0000] "GET /_matrix/client/versions HTTP/1.1" 200 293 "-" "Go-http-client/1.1" 2022-10-07 07:08:49,204 INFO stopped: nginx (exit status 0) 2022-10-07 07:08:49,204 INFO reaped unknown pid 29 (exit status 0) 2022-10-07 07:08:49,204 INFO reaped unknown pid 30 (exit status 0) synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/v1' 2022-10-07 07:08:49,243 INFO stopped: synapse_main (exit status 0) synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/federation' synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/key/v2' synapse_main | 2022-10-07 07:08:47,193 - twisted - 274 - INFO - sentinel - SynapseSite starting on 8080 synapse_main | 2022-10-07 07:08:47,193 - synapse.app.homeserver - 172 - INFO - sentinel - Synapse now listening on TCP port 8080 synapse_main | 2022-10-07 07:08:47,194 - synapse.storage.database - 844 - WARNING - sentinel - Starting db txn 'count_daily_users' from sentinel context synapse_main | 2022-10-07 07:08:47,194 - synapse.storage.database - 909 - WARNING - sentinel - Starting db connection from sentinel context: metrics will be lost synapse_main | 2022-10-07 07:08:47,195 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-0 - User parter finished: stopping synapse_main | 2022-10-07 07:08:47,198 - synapse.push.pusherpool - 347 - INFO - start_pushers-0 - Started pushers synapse_main | 2022-10-07 07:08:47,258 - synapse.storage.background_updates - 288 - INFO - background_updates-0 - Starting background schema updates for database master synapse_main | 2022-10-07 07:08:47,264 - synapse.storage.background_updates - 305 - INFO - background_updates-0 - No more background updates to do. Unscheduling background update task. synapse_main | 2022-10-07 07:08:47,725 - synapse.access.http.8080 - 459 - INFO - GET-1 - ::ffff:127.0.0.1 - 8080 - {None} Processed request: 0.001sec/0.001sec (0.001sec, 0.001sec) (0.000sec/0.000sec/0) 281B 200 "GET /_matrix/client/versions HTTP/1.0" "Go-http-client/1.1" [0 dbevts] synapse_main | 2022-10-07 07:08:49,205 - twisted - 274 - INFO - sentinel - Received SIGTERM, shutting down. synapse_main | 2022-10-07 07:08:49,206 - synapse.storage.databases.main.lock - 92 - INFO - LockStore._on_shutdown-0 - Dropping held locks due to shutdown synapse_main | 2022-10-07 07:08:49,206 - synapse.storage.databases.main.lock - 101 - INFO - LockStore._on_shutdown-0 - Dropped locks due to shutdown synapse_main | 2022-10-07 07:08:49,207 - synapse.handlers.presence - 766 - INFO - presence.on_shutdown-0 - Performing _on_shutdown. Persisting 0 unpersisted changes synapse_main | 2022-10-07 07:08:49,207 - synapse.handlers.presence - 779 - INFO - presence.on_shutdown-0 - Finished _on_shutdown synapse_main | 2022-10-07 07:08:49,208 - synapse.app._base - 492 - INFO - sentinel - Shutting down... synapse_main | 2022-10-07 07:08:49,208 - twisted - 274 - INFO - sentinel - (TCP Port 8080 Closed) synapse_main | 2022-10-07 07:08:49,208 - twisted - 274 - INFO - sentinel - (TCP Port 9093 Closed) synapse_main | 2022-10-07 07:08:49,210 - twisted - 274 - INFO - sentinel - Main loop terminated. 2022/10/07 02:08:49 ============== 6cdadf46f4980c587d2d4e276825fb5ecedfae69bc812f29dc3d80842f942584 : END LOGS ============== --- PASS: TestJumpToDateEndpoint (30.76s) --- PASS: TestJumpToDateEndpoint/parallel (0.00s) --- PASS: TestJumpToDateEndpoint/parallel/federation (0.00s) testing: warning: no tests to run PASS ok github.com/matrix-org/complement/tests 32.978s [no tests to run] 2022/10/07 02:08:18 config: &{BaseImageURI:complement-synapse DebugLoggingEnabled:false AlwaysPrintServerLogs:true EnvVarsPropagatePrefix:PASS_ SpawnHSTimeout:30s KeepBlueprints:[] HostMounts:[] BaseImageURIs:map[] PackageNamespace:csapi CACertificate:0xc0013cc000 CAPrivateKey:0xc000e8d0e0 BestEffort:false HostnameRunningComplement:host.docker.internal} testing: warning: no tests to run PASS ok github.com/matrix-org/complement/tests/csapi 2.057s [no tests to run] ```
richvdh commented 2 years ago

This has regressed hard (over 3 minutes to get results now). I'm getting test results after 193s and the Docker build part is taking around 160s.

This will be the rust build step, I guess. Maybe we can reorder the dockerfile to cache the rust build output? Otherwise I don't have any great ideas here.

DMRobertson commented 2 years ago

Out of interest, @MadLittleMods have you found #13735 to have improved this at all?

MadLittleMods commented 2 years ago

I'm getting test results after ~76s and the Docker build part is taking around ~45s.

Complement run (latest develop 755bfeee3a1ac7077045ab9e5a994b6ca89afba3) ``` COMPLEMENT_ALWAYS_PRINT_SERVER_LOGS=1 COMPLEMENT_DIR=../complement ./scripts-dev/complement.sh -run TestJumpToDateEndpoint/parallel/federation/can_get_pagination_token_after_getting_remote_event_from_timestamp_to_event [+] Building 22.0s (28/28) FINISHED => [internal] load build definition from Dockerfile 0.0s => => transferring dockerfile: 6.69kB 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 35B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.4s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:9ba7531bd80fb0a858632727cf7a112fbfd19b17e94c4e84ced81e24ef1a0dbc 0.0s => [internal] load build definition from Dockerfile 0.0s => [internal] load .dockerignore 0.0s => [internal] load metadata for docker.io/library/python:3.9-slim-bullseye 0.3s => [requirements 1/6] FROM docker.io/library/python:3.9-slim-bullseye@sha256:abae63851cda52addbf1efa19b8e6eec4a61724f0bb9ea1363d56791b5be59cb 0.0s => [internal] load build context 0.4s => => transferring context: 7.85MB 0.4s => CACHED [builder 2/10] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq build-essential 0.0s => CACHED [builder 3/10] RUN mkdir /rust /cargo 0.0s => CACHED [builder 4/10] RUN curl -sSf https://sh.rustup.rs | sh -s -- -y --no-modify-path --default-toolchain stable --profile minimal 0.0s => CACHED [requirements 2/6] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq build-esse 0.0s => CACHED [requirements 3/6] RUN --mount=type=cache,target=/root/.cache/pip pip install --user "poetry==1.2.0" 0.0s => CACHED [requirements 4/6] WORKDIR /synapse 0.0s => CACHED [requirements 5/6] COPY pyproject.toml poetry.lock /synapse/ 0.0s => CACHED [requirements 6/6] RUN if [ -z "$TEST_ONLY_IGNORE_POETRY_LOCKFILE" ]; then /root/.local/bin/poetry export --extras all -o /synapse/requirements.txt ${TEST_ONLY_SKIP_DEP_HASH_VERIFICATION:+--without- 0.0s => CACHED [builder 5/10] COPY --from=requirements /synapse/requirements.txt /synapse/ 0.0s => CACHED [builder 6/10] RUN --mount=type=cache,target=/root/.cache/pip pip install --prefix="/install" --no-deps --no-warn-script-location -r /synapse/requirements.txt 0.0s => [builder 7/10] COPY synapse /synapse/synapse/ 0.3s => [builder 8/10] COPY rust /synapse/rust/ 0.1s => [builder 9/10] COPY pyproject.toml README.rst build_rust.py Cargo.toml Cargo.lock /synapse/ 0.1s => [builder 10/10] RUN --mount=type=cache,target=/synapse/target,sharing=locked --mount=type=cache,target=/cargo/registry,sharing=locked if [ -z "$TEST_ONLY_IGNORE_POETRY_LOCKFILE" ]; then pip install -- 12.4s => CACHED [stage-2 2/5] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && apt-get install -yqq curl gosu l 0.0s => [stage-2 3/5] COPY --from=builder /install /usr/local 2.2s => [stage-2 4/5] COPY ./docker/start.py /start.py 0.1s => [stage-2 5/5] COPY ./docker/conf /conf 0.1s => exporting to image 3.4s => => exporting layers 3.4s => => writing image sha256:3e764c833dd23eb1808ad83ada8ffe5ec3bac7b7c592378251e9688ae52d86a9 0.0s => => naming to docker.io/matrixdotorg/synapse 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them [+] Building 9.2s (30/30) FINISHED => [internal] load build definition from Dockerfile-workers 0.0s => => transferring dockerfile: 2.71kB 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 35B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.4s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:9ba7531bd80fb0a858632727cf7a112fbfd19b17e94c4e84ced81e24ef1a0dbc 0.0s => [internal] load build definition from Dockerfile-workers 0.0s => [internal] load .dockerignore 0.0s => [internal] load metadata for docker.io/library/debian:bullseye-slim 0.3s => [internal] load metadata for docker.io/library/redis:6-bullseye 0.3s => [internal] load metadata for docker.io/matrixdotorg/synapse:latest 0.0s => [internal] load build context 0.1s => => transferring context: 31.94kB 0.1s => [deps_base 1/2] FROM docker.io/library/debian:bullseye-slim@sha256:b46fc4e6813f6cbd9f3f6322c72ab974cc0e75a72ca02730a8861e98999875c7 0.0s => => resolve docker.io/library/debian:bullseye-slim@sha256:b46fc4e6813f6cbd9f3f6322c72ab974cc0e75a72ca02730a8861e98999875c7 0.0s => [stage-2 1/16] FROM docker.io/matrixdotorg/synapse:latest 0.2s => CACHED [redis_base 1/1] FROM docker.io/library/redis:6-bullseye@sha256:a3824c5447368a08bba8b3aaa910a8c8f4550729b946efac0b378a7ad247040d 0.0s => => resolve docker.io/library/redis:6-bullseye@sha256:a3824c5447368a08bba8b3aaa910a8c8f4550729b946efac0b378a7ad247040d 0.0s => CACHED [deps_base 2/2] RUN --mount=type=cache,target=/var/cache/apt,sharing=locked --mount=type=cache,target=/var/lib/apt,sharing=locked apt-get update -qq && DEBIAN_FRONTEND=noninter 0.0s => [stage-2 2/16] RUN --mount=type=cache,target=/root/.cache/pip pip install supervisor~=4.2 4.4s => [stage-2 3/16] RUN mkdir -p /etc/supervisor/conf.d 0.4s => [stage-2 4/16] COPY --from=redis_base /usr/local/bin/redis-server /usr/local/bin 0.1s => [stage-2 5/16] COPY --from=deps_base /usr/sbin/nginx /usr/sbin 0.1s => [stage-2 6/16] COPY --from=deps_base /usr/share/nginx /usr/share/nginx 0.1s => [stage-2 7/16] COPY --from=deps_base /usr/lib/nginx /usr/lib/nginx 0.1s => [stage-2 8/16] COPY --from=deps_base /etc/nginx /etc/nginx 0.1s => [stage-2 9/16] RUN rm /etc/nginx/sites-enabled/default 0.4s => [stage-2 10/16] RUN mkdir /var/log/nginx /var/lib/nginx 0.4s => [stage-2 11/16] RUN chown www-data /var/lib/nginx 0.3s => [stage-2 12/16] RUN ln -sf /dev/stdout /var/log/nginx/access.log 0.4s => [stage-2 13/16] RUN ln -sf /dev/stderr /var/log/nginx/error.log 0.4s => [stage-2 14/16] COPY ./docker/conf-workers/* /conf/ 0.1s => [stage-2 15/16] COPY ./docker/prefix-log /usr/local/bin/ 0.1s => [stage-2 16/16] COPY ./docker/configure_workers_and_start.py /configure_workers_and_start.py 0.1s => exporting to image 0.4s => => exporting layers 0.4s => => writing image sha256:2373fd44d1415995ccc77ebff9de8a024056730070ff885650136dd7aede3249 0.0s => => naming to docker.io/matrixdotorg/synapse-workers 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them [+] Building 8.4s (24/24) FINISHED => [internal] load build definition from Dockerfile 0.0s => => transferring dockerfile: 37B 0.0s => [internal] load .dockerignore 0.0s => => transferring context: 2B 0.0s => resolve image config for docker.io/docker/dockerfile:1 0.3s => CACHED docker-image://docker.io/docker/dockerfile:1@sha256:9ba7531bd80fb0a858632727cf7a112fbfd19b17e94c4e84ced81e24ef1a0dbc 0.0s => [internal] load .dockerignore 0.0s => [internal] load build definition from Dockerfile 0.0s => [internal] load metadata for docker.io/matrixdotorg/synapse-workers:latest 0.0s => [internal] load metadata for docker.io/library/postgres:13-bullseye 0.3s => [stage-0 1/13] FROM docker.io/matrixdotorg/synapse-workers:latest 0.6s => [internal] load build context 0.0s => => transferring context: 177B 0.0s => CACHED FROM docker.io/library/postgres:13-bullseye@sha256:7cc1c1a6a9df06df9e775eccdd77e45a868cb197e8e0981e23a2a814aaf56906 0.0s => [stage-0 2/13] RUN adduser --system --uid 999 postgres --home /var/lib/postgresql 0.4s => [stage-0 3/13] COPY --from=postgres:13-bullseye /usr/lib/postgresql /usr/lib/postgresql 0.3s => [stage-0 4/13] COPY --from=postgres:13-bullseye /usr/share/postgresql /usr/share/postgresql 0.2s => [stage-0 5/13] RUN mkdir /var/run/postgresql && chown postgres /var/run/postgresql 0.5s => [stage-0 6/13] RUN gosu postgres initdb --locale=C --encoding=UTF-8 --auth-host password 2.6s => [stage-0 7/13] RUN echo "ALTER USER postgres PASSWORD 'somesecret'" | gosu postgres postgres --single 0.6s => [stage-0 8/13] RUN echo "CREATE DATABASE synapse" | gosu postgres postgres --single 1.0s => [stage-0 9/13] RUN mv /conf/shared.yaml.j2 /conf/shared-orig.yaml.j2 0.3s => [stage-0 10/13] COPY conf/workers-shared-extra.yaml.j2 /conf/shared.yaml.j2 0.1s => [stage-0 11/13] WORKDIR /data 0.1s => [stage-0 12/13] COPY conf/postgres.supervisord.conf /etc/supervisor/conf.d/postgres.conf 0.0s => [stage-0 13/13] COPY conf/start_for_complement.sh / 0.0s => exporting to image 0.6s => => exporting layers 0.5s => => writing image sha256:c2bac2fc0c47f61d622652e174a6a16fe99e2f1c9d01c4ca57b2e926ab73a47a 0.0s => => naming to docker.io/library/complement-synapse 0.0s Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them Images built; running complement # github.com/matrix-org/complement/tests/csapi.test ld: warning: -no_pie is deprecated when targeting new OS versions # github.com/matrix-org/complement/tests.test ld: warning: -no_pie is deprecated when targeting new OS versions 2022/10/20 11:32:20 config: &{BaseImageURI:complement-synapse DebugLoggingEnabled:false AlwaysPrintServerLogs:true EnvVarsPropagatePrefix:PASS_ SpawnHSTimeout:30s KeepBlueprints:[] HostMounts:[] BaseImageURIs:map[] PackageNamespace:fed CACertificate:0xc000e9c000 CAPrivateKey:0xc0000210e0 BestEffort:false HostnameRunningComplement:host.docker.internal} === RUN TestJumpToDateEndpoint 2022/10/20 11:32:20 Sharing [SERVER_NAME=hs1 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container 2022/10/20 11:32:30 Sharing [SERVER_NAME=hs2 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container 2022/10/20 11:32:43 Sharing [SERVER_NAME=hs1 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container 2022/10/20 11:32:43 Sharing [SERVER_NAME=hs2 SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS=] host environment variables with container msc3030_test.go:25: Deploy times: 22.690791061s blueprints, 5.675401543s containers msc3030_test.go:38: WARNING: Deployment.Client - HS name 'hs1' - user ID '@the-bridge-user:hs1' - deviceID not found === RUN TestJumpToDateEndpoint/parallel === RUN TestJumpToDateEndpoint/parallel/federation 2022/10/20 11:32:49 ============================================ 2022/10/20 11:32:49 4c910f2a8fbe9670ad9d887490f8c2a330d42986ba37a181a8c5d4dd4b357d0c : Server logs: Complement Synapse launcher Args: Env: SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS= Generating RSA private key, 2048 bit long modulus (2 primes) ......+++++ ............................................+++++ e is 65537 (0x010001) Signature ok subject=CN = hs2 Getting CA Private Key DNS:hs2 Starting supervisord 2022-10-20 16:32:44,495 INFO Included extra file "/etc/supervisor/conf.d/postgres.conf" during parsing 2022-10-20 16:32:44,495 INFO Included extra file "/etc/supervisor/conf.d/synapse.conf" during parsing 2022-10-20 16:32:44,495 INFO Set uid to user 0 succeeded 2022-10-20 16:32:44,497 INFO supervisord started with pid 1 2022-10-20 16:32:45,501 INFO spawned: 'synapse_main' with pid 24 2022-10-20 16:32:45,504 INFO spawned: 'nginx' with pid 25 2022-10-20 16:32:46,505 INFO success: synapse_main entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) 2022-10-20 16:32:46,506 INFO success: nginx entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) synapse_main | 2022-10-20 16:32:47,906 - root - 345 - WARNING - main - ***** STARTING SERVER ***** synapse_main | 2022-10-20 16:32:47,906 - root - 346 - WARNING - main - Server /usr/local/lib/python3.9/site-packages/synapse/app/homeserver.py version 1.70.0rc1 synapse_main | 2022-10-20 16:32:47,906 - root - 351 - INFO - main - Server hostname: hs2 synapse_main | 2022-10-20 16:32:47,906 - root - 352 - INFO - main - Instance name: master synapse_main | 2022-10-20 16:32:47,906 - root - 353 - INFO - main - Twisted reactor: EPollReactor synapse_main | 2022-10-20 16:32:47,906 - synapse.app.homeserver - 364 - INFO - main - Setting up server synapse_main | 2022-10-20 16:32:47,906 - synapse.server - 307 - INFO - main - Setting up. synapse_main | 2022-10-20 16:32:47,914 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server synapse_main | 2022-10-20 16:32:47,914 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state'] synapse_main | 2022-10-20 16:32:47,914 - synapse.storage.prepare_database - 115 - INFO - main - ['main', 'state']: Checking existing schema version synapse_main | 2022-10-20 16:32:47,918 - synapse.storage.prepare_database - 119 - INFO - main - ['main', 'state']: Existing schema is 73 (+12 deltas) synapse_main | 2022-10-20 16:32:47,918 - synapse.storage.databases.main - 311 - INFO - main - Checking database for consistency with configuration... synapse_main | 2022-10-20 16:32:47,918 - synapse.storage.prepare_database - 411 - INFO - main - Applying schema deltas for v73 synapse_main | 2022-10-20 16:32:47,920 - synapse.storage.prepare_database - 546 - INFO - main - Schema now up to date synapse_main | 2022-10-20 16:32:47,923 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'main' database synapse_main | 2022-10-20 16:32:47,924 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_stream(stream_id): 2 synapse_main | 2022-10-20 16:32:47,924 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for user_signature_stream(stream_id): 1 synapse_main | 2022-10-20 16:32:47,924 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_outbound_pokes(stream_id): 1 synapse_main | 2022-10-20 16:32:47,925 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_changes_in_room(stream_id): 1 synapse_main | 2022-10-20 16:32:47,925 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for receipts_linearized(stream_id): 1 synapse_main | 2022-10-20 16:32:47,926 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): 1 synapse_main | 2022-10-20 16:32:47,926 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): -1 synapse_main | 2022-10-20 16:32:47,927 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for ex_outlier_stream(event_stream_ordering): -1 synapse_main | 2022-10-20 16:32:47,929 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_inbox(stream_id): 1 synapse_main | 2022-10-20 16:32:47,931 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for pushers(id): 1 synapse_main | 2022-10-20 16:32:47,931 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for deleted_pushers(stream_id): 1 synapse_main | 2022-10-20 16:32:47,931 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_stream(stream_id): 1 synapse_main | 2022-10-20 16:32:47,932 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_account_data(stream_id): 1 synapse_main | 2022-10-20 16:32:47,932 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_tags_revisions(stream_id): 1 synapse_main | 2022-10-20 16:32:47,932 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for e2e_cross_signing_keys(stream_id): 1 synapse_main | 2022-10-20 16:32:47,932 - synapse.storage.databases.main.event_push_actions - 1151 - INFO - main - Searching for stream ordering 1 month ago synapse_main | 2022-10-20 16:32:47,933 - synapse.storage.databases.main.event_push_actions - 1155 - INFO - main - Found stream ordering 1 month ago: it's 0 synapse_main | 2022-10-20 16:32:47,933 - synapse.storage.databases.main.event_push_actions - 1158 - INFO - main - Searching for stream ordering 1 day ago synapse_main | 2022-10-20 16:32:47,933 - synapse.storage.databases.main.event_push_actions - 1162 - INFO - main - Found stream ordering 1 day ago: it's 0 synapse_main | 2022-10-20 16:32:47,934 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules(id): 1 synapse_main | 2022-10-20 16:32:47,934 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_enable(id): 1 synapse_main | 2022-10-20 16:32:47,934 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for presence_stream(stream_id): 1 synapse_main | 2022-10-20 16:32:47,935 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for access_tokens(id): 2 synapse_main | 2022-10-20 16:32:47,935 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for refresh_tokens(id): 1 synapse_main | 2022-10-20 16:32:47,936 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for event_reports(id): 1 synapse_main | 2022-10-20 16:32:47,937 - synapse.storage.databases - 101 - INFO - main - [database config 'master']: Starting 'state' database synapse_main | 2022-10-20 16:32:47,937 - synapse.storage.databases - 116 - INFO - main - [database config 'master']: prepared synapse_main | 2022-10-20 16:32:47,938 - synapse.server - 310 - INFO - main - Finished setting up. synapse_main | 2022-10-20 16:32:47,949 - synapse.push.pusher - 38 - INFO - main - email enable notifs: False synapse_main | 2022-10-20 16:32:47,951 - synapse.federation.federation_server - 1412 - INFO - main - Registering federation EDU handler for 'm.device_list_update' synapse_main | 2022-10-20 16:32:47,951 - synapse.federation.federation_server - 1432 - INFO - main - Registering federation query handler for 'profile' synapse_main | 2022-10-20 16:32:47,952 - synapse.federation.federation_server - 1412 - INFO - main - Registering federation EDU handler for 'm.presence' synapse_main | 2022-10-20 16:32:47,953 - synapse.federation.federation_server - 1412 - INFO - main - Registering federation EDU handler for 'm.typing' synapse_main | 2022-10-20 16:32:47,954 - synapse.federation.federation_server - 1432 - INFO - main - Registering federation query handler for 'directory' synapse_main | 2022-10-20 16:32:47,956 - twisted - 274 - INFO - main - Redirected stdout/stderr to logs synapse_main | 2022-10-20 16:32:47,956 - synapse.app.homeserver - 165 - INFO - sentinel - Running synapse_main | 2022-10-20 16:32:47,960 - synapse.app.homeserver - 29 - INFO - sentinel - Set file limit to: 1048576 synapse_main | 2022-10-20 16:32:47,963 - synapse.handlers.deactivate_account - 230 - INFO - user_parter_loop-0 - Starting user parter synapse_main | 2022-10-20 16:32:47,967 - synapse.util.caches.lrucache - 225 - INFO - sentinel - Expiring LRU caches after 1800 seconds synapse_main | 2022-10-20 16:32:47,976 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/health' synapse_main | 2022-10-20 16:32:47,976 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/replication' synapse_main | 2022-10-20 16:32:47,977 - twisted - 274 - INFO - sentinel - SynapseSite starting on 9093 synapse_main | 2022-10-20 16:32:47,977 - synapse.app.homeserver - 172 - INFO - sentinel - Synapse now listening on TCP port 9093 synapse_main | 2022-10-20 16:32:47,998 - synapse.federation.federation_server - 1412 - INFO - sentinel - Registering federation EDU handler for 'm.receipt' synapse_main | 2022-10-20 16:32:47,998 - synapse.federation.federation_server - 1412 - INFO - sentinel - Registering federation EDU handler for 'm.signing_key_update' synapse_main | 2022-10-20 16:32:47,998 - synapse.federation.federation_server - 1412 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update' synapse_main | 2022-10-20 16:32:47,998 - synapse.federation.federation_server - 1432 - INFO - sentinel - Registering federation query handler for 'client_keys' synapse_main | 2022-10-20 16:32:47,999 - synapse.federation.federation_server - 1412 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device' synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/health' synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/client' synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/.well-known' synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/admin' synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/pick_idp' synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/pick_username' synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/new_user_consent' synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/sso_register' synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/unsubscribe' synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching FilePath('/usr/local/lib/python3.9/site-packages/synapse/static') to path b'/_matrix/static' synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/r0' synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/v3' synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/v1' synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/federation' 2022-10-20 16:32:49,468 WARN received SIGTERM indicating exit request 2022-10-20 16:32:49,469 INFO waiting for synapse_main, nginx to die nginx | 172.29.0.1 - - [20/Oct/2022:16:32:48 +0000] "GET /_matrix/client/versions HTTP/1.1" 200 301 "-" "Go-http-client/1.1" 2022-10-20 16:32:49,489 INFO stopped: nginx (exit status 0) 2022-10-20 16:32:49,489 INFO reaped unknown pid 30 (exit status 0) 2022-10-20 16:32:49,490 INFO reaped unknown pid 31 (exit status 0) synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/key' synapse_main | 2022-10-20 16:32:48,014 - twisted - 274 - INFO - sentinel - SynapseSite starting on 8080 synapse_main | 2022-10-20 16:32:48,014 - synapse.app.homeserver - 172 - INFO - sentinel - Synapse now listening on TCP port 8080 synapse_main | 2022-10-20 16:32:48,015 - synapse.storage.database - 844 - WARNING - sentinel - Starting db txn 'count_daily_users' from sentinel context synapse_main | 2022-10-20 16:32:48,015 - synapse.storage.database - 909 - WARNING - sentinel - Starting db connection from sentinel context: metrics will be lost synapse_main | 2022-10-20 16:32:48,016 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-0 - User parter finished: stopping synapse_main | 2022-10-20 16:32:48,018 - synapse.push.pusherpool - 347 - INFO - start_pushers-0 - Started pushers synapse_main | 2022-10-20 16:32:48,080 - synapse.storage.background_updates - 288 - INFO - background_updates-0 - Starting background schema updates for database master synapse_main | 2022-10-20 16:32:48,467 - synapse.access.http.8080 - 460 - INFO - GET-1 - ::ffff:127.0.0.1 - 8080 - {None} Processed request: 0.001sec/0.001sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 289B 200 "GET /_matrix/client/versions HTTP/1.0" "Go-http-client/1.1" [0 dbevts] synapse_main | 2022-10-20 16:32:49,089 - synapse.storage.background_updates - 431 - INFO - background_updates-0 - Starting update batch on background update 'receipts_graph_unique_index' synapse_main | 2022-10-20 16:32:49,090 - synapse.storage.background_updates - 623 - INFO - background_updates-0 - Adding index receipts_graph_unique_index to receipts_graph synapse_main | 2022-10-20 16:32:49,099 - synapse.storage.background_updates - 474 - INFO - background_updates-0 - Running background update 'receipts_graph_unique_index'. Processed 1 items in 9ms. (total_rate=0.1111111111111111/ms, current_rate=0.11111111111111112/ms, total_updated=1, batch_size=100) synapse_main | 2022-10-20 16:32:49,490 - twisted - 274 - INFO - sentinel - Received SIGTERM, shutting down. synapse_main | 2022-10-20 16:32:49,491 - synapse.storage.databases.main.lock - 92 - INFO - LockStore._on_shutdown-0 - Dropping held locks due to shutdown synapse_main | 2022-10-20 16:32:49,491 - synapse.storage.databases.main.lock - 101 - INFO - LockStore._on_shutdown-0 - Dropped locks due to shutdown synapse_main | 2022-10-20 16:32:49,492 - synapse.handlers.presence - 766 - INFO - presence.on_shutdown-0 - Performing _on_shutdown. Persisting 0 unpersisted changes synapse_main | 2022-10-20 16:32:49,492 - synapse.handlers.presence - 779 - INFO - presence.on_shutdown-0 - Finished _on_shutdown synapse_main | 2022-10-20 16:32:49,492 - synapse.app._base - 495 - INFO - sentinel - Shutting down... synapse_main | 2022-10-20 16:32:49,492 - twisted - 274 - INFO - sentinel - (TCP Port 8080 Closed) synapse_main | 2022-10-20 16:32:49,493 - twisted - 274 - INFO - sentinel - (TCP Port 9093 Closed) 2022-10-20 16:32:49,526 INFO stopped: synapse_main (exit status 0) synapse_main | 2022-10-20 16:32:49,495 - twisted - 274 - INFO - sentinel - Main loop terminated. 2022-10-20 16:32:49,527 INFO reaped unknown pid 27 (exit status 0) 2022/10/20 11:32:49 ============== 4c910f2a8fbe9670ad9d887490f8c2a330d42986ba37a181a8c5d4dd4b357d0c : END LOGS ============== 2022/10/20 11:32:50 ============================================ 2022/10/20 11:32:50 e24e04a6c3af3ba17786e37708b52a87000b98fe0a752196374fc1ae856cc673 : Server logs: Complement Synapse launcher Args: Env: SYNAPSE_COMPLEMENT_DATABASE=sqlite SYNAPSE_COMPLEMENT_USE_WORKERS= Generating RSA private key, 2048 bit long modulus (2 primes) .......................................................................................................................+++++ ..........................................................................................................................+++++ e is 65537 (0x010001) Signature ok subject=CN = hs1 Getting CA Private Key DNS:hs1 Starting supervisord 2022-10-20 16:32:44,914 INFO Included extra file "/etc/supervisor/conf.d/postgres.conf" during parsing 2022-10-20 16:32:44,914 INFO Included extra file "/etc/supervisor/conf.d/synapse.conf" during parsing 2022-10-20 16:32:44,914 INFO Set uid to user 0 succeeded 2022-10-20 16:32:44,916 INFO supervisord started with pid 1 2022-10-20 16:32:45,919 INFO spawned: 'synapse_main' with pid 24 2022-10-20 16:32:45,922 INFO spawned: 'nginx' with pid 25 2022-10-20 16:32:46,924 INFO success: synapse_main entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) 2022-10-20 16:32:46,925 INFO success: nginx entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) synapse_main | 2022-10-20 16:32:48,282 - root - 345 - WARNING - main - ***** STARTING SERVER ***** synapse_main | 2022-10-20 16:32:48,282 - root - 346 - WARNING - main - Server /usr/local/lib/python3.9/site-packages/synapse/app/homeserver.py version 1.70.0rc1 synapse_main | 2022-10-20 16:32:48,282 - root - 351 - INFO - main - Server hostname: hs1 synapse_main | 2022-10-20 16:32:48,282 - root - 352 - INFO - main - Instance name: master synapse_main | 2022-10-20 16:32:48,282 - root - 353 - INFO - main - Twisted reactor: EPollReactor synapse_main | 2022-10-20 16:32:48,282 - synapse.app.homeserver - 364 - INFO - main - Setting up server synapse_main | 2022-10-20 16:32:48,282 - synapse.server - 307 - INFO - main - Setting up. synapse_main | 2022-10-20 16:32:48,288 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server synapse_main | 2022-10-20 16:32:48,288 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state'] synapse_main | 2022-10-20 16:32:48,289 - synapse.storage.prepare_database - 115 - INFO - main - ['main', 'state']: Checking existing schema version synapse_main | 2022-10-20 16:32:48,291 - synapse.storage.prepare_database - 119 - INFO - main - ['main', 'state']: Existing schema is 73 (+12 deltas) synapse_main | 2022-10-20 16:32:48,292 - synapse.storage.databases.main - 311 - INFO - main - Checking database for consistency with configuration... synapse_main | 2022-10-20 16:32:48,292 - synapse.storage.prepare_database - 411 - INFO - main - Applying schema deltas for v73 synapse_main | 2022-10-20 16:32:48,293 - synapse.storage.prepare_database - 546 - INFO - main - Schema now up to date synapse_main | 2022-10-20 16:32:48,297 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'main' database synapse_main | 2022-10-20 16:32:48,298 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_stream(stream_id): 3 synapse_main | 2022-10-20 16:32:48,298 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for user_signature_stream(stream_id): 1 synapse_main | 2022-10-20 16:32:48,298 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_outbound_pokes(stream_id): 1 synapse_main | 2022-10-20 16:32:48,298 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_changes_in_room(stream_id): 1 synapse_main | 2022-10-20 16:32:48,301 - synapse.config.appservice - 76 - INFO - main - Loaded application service: ApplicationService: {'token': '', 'url': 'http://localhost:9000', 'hs_token': '', 'sender': '@the-bridge-user:hs1', 'namespaces': {'users': [Namespace(exclusive=False, regex=re.compile('.*'))], 'aliases': [], 'rooms': []}, 'id': 'my_as_id', 'ip_range_whitelist': None, 'supports_ephemeral': False, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': False} synapse_main | 2022-10-20 16:32:48,301 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for receipts_linearized(stream_id): 1 synapse_main | 2022-10-20 16:32:48,302 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): 1 synapse_main | 2022-10-20 16:32:48,302 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): -1 synapse_main | 2022-10-20 16:32:48,302 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for ex_outlier_stream(event_stream_ordering): -1 synapse_main | 2022-10-20 16:32:48,304 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_inbox(stream_id): 1 synapse_main | 2022-10-20 16:32:48,306 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for pushers(id): 1 synapse_main | 2022-10-20 16:32:48,306 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for deleted_pushers(stream_id): 1 synapse_main | 2022-10-20 16:32:48,306 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_stream(stream_id): 1 synapse_main | 2022-10-20 16:32:48,307 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_account_data(stream_id): 1 synapse_main | 2022-10-20 16:32:48,307 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_tags_revisions(stream_id): 1 synapse_main | 2022-10-20 16:32:48,307 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for e2e_cross_signing_keys(stream_id): 1 synapse_main | 2022-10-20 16:32:48,308 - synapse.storage.databases.main.event_push_actions - 1151 - INFO - main - Searching for stream ordering 1 month ago synapse_main | 2022-10-20 16:32:48,308 - synapse.storage.databases.main.event_push_actions - 1155 - INFO - main - Found stream ordering 1 month ago: it's 0 synapse_main | 2022-10-20 16:32:48,308 - synapse.storage.databases.main.event_push_actions - 1158 - INFO - main - Searching for stream ordering 1 day ago synapse_main | 2022-10-20 16:32:48,309 - synapse.storage.databases.main.event_push_actions - 1162 - INFO - main - Found stream ordering 1 day ago: it's 0 synapse_main | 2022-10-20 16:32:48,309 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules(id): 1 synapse_main | 2022-10-20 16:32:48,310 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_enable(id): 1 synapse_main | 2022-10-20 16:32:48,310 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for presence_stream(stream_id): 1 synapse_main | 2022-10-20 16:32:48,311 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for access_tokens(id): 3 synapse_main | 2022-10-20 16:32:48,311 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for refresh_tokens(id): 1 synapse_main | 2022-10-20 16:32:48,312 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for event_reports(id): 1 synapse_main | 2022-10-20 16:32:48,313 - synapse.storage.databases - 101 - INFO - main - [database config 'master']: Starting 'state' database synapse_main | 2022-10-20 16:32:48,314 - synapse.storage.databases - 116 - INFO - main - [database config 'master']: prepared synapse_main | 2022-10-20 16:32:48,314 - synapse.server - 310 - INFO - main - Finished setting up. synapse_main | 2022-10-20 16:32:48,328 - synapse.push.pusher - 38 - INFO - main - email enable notifs: False synapse_main | 2022-10-20 16:32:48,330 - synapse.federation.federation_server - 1412 - INFO - main - Registering federation EDU handler for 'm.device_list_update' synapse_main | 2022-10-20 16:32:48,330 - synapse.federation.federation_server - 1432 - INFO - main - Registering federation query handler for 'profile' synapse_main | 2022-10-20 16:32:48,331 - synapse.federation.federation_server - 1412 - INFO - main - Registering federation EDU handler for 'm.presence' synapse_main | 2022-10-20 16:32:48,332 - synapse.federation.federation_server - 1412 - INFO - main - Registering federation EDU handler for 'm.typing' synapse_main | 2022-10-20 16:32:48,333 - synapse.federation.federation_server - 1432 - INFO - main - Registering federation query handler for 'directory' synapse_main | 2022-10-20 16:32:48,335 - twisted - 274 - INFO - main - Redirected stdout/stderr to logs synapse_main | 2022-10-20 16:32:48,335 - synapse.app.homeserver - 165 - INFO - sentinel - Running synapse_main | 2022-10-20 16:32:48,340 - synapse.app.homeserver - 29 - INFO - sentinel - Set file limit to: 1048576 synapse_main | 2022-10-20 16:32:48,341 - synapse.handlers.deactivate_account - 230 - INFO - user_parter_loop-0 - Starting user parter synapse_main | 2022-10-20 16:32:48,346 - synapse.util.caches.lrucache - 225 - INFO - sentinel - Expiring LRU caches after 1800 seconds synapse_main | 2022-10-20 16:32:48,356 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/health' synapse_main | 2022-10-20 16:32:48,356 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/replication' synapse_main | 2022-10-20 16:32:48,356 - twisted - 274 - INFO - sentinel - SynapseSite starting on 9093 synapse_main | 2022-10-20 16:32:48,357 - synapse.app.homeserver - 172 - INFO - sentinel - Synapse now listening on TCP port 9093 synapse_main | 2022-10-20 16:32:48,373 - synapse.federation.federation_server - 1412 - INFO - sentinel - Registering federation EDU handler for 'm.receipt' synapse_main | 2022-10-20 16:32:48,373 - synapse.federation.federation_server - 1412 - INFO - sentinel - Registering federation EDU handler for 'm.signing_key_update' synapse_main | 2022-10-20 16:32:48,373 - synapse.federation.federation_server - 1412 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update' synapse_main | 2022-10-20 16:32:48,373 - synapse.federation.federation_server - 1432 - INFO - sentinel - Registering federation query handler for 'client_keys' synapse_main | 2022-10-20 16:32:48,374 - synapse.federation.federation_server - 1412 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device' synapse_main | 2022-10-20 16:32:48,385 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/health' synapse_main | 2022-10-20 16:32:48,385 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/client' synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/.well-known' synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/admin' synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/pick_idp' synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/pick_username' synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/new_user_consent' synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/sso_register' synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/unsubscribe' synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching FilePath('/usr/local/lib/python3.9/site-packages/synapse/static') to path b'/_matrix/static' synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/r0' synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/v3' 2022-10-20 16:32:50,393 WARN received SIGTERM indicating exit request 2022-10-20 16:32:50,393 INFO waiting for synapse_main, nginx to die nginx | 172.29.0.1 - - [20/Oct/2022:16:32:48 +0000] "GET /_matrix/client/versions HTTP/1.1" 200 301 "-" "Go-http-client/1.1" 2022-10-20 16:32:50,400 INFO stopped: nginx (exit status 0) 2022-10-20 16:32:50,401 INFO reaped unknown pid 30 (exit status 0) 2022-10-20 16:32:50,401 INFO reaped unknown pid 31 (exit status 0) synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/v1' synapse_main | 2022-10-20 16:32:48,387 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/federation' synapse_main | 2022-10-20 16:32:48,387 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/key' synapse_main | 2022-10-20 16:32:48,387 - twisted - 274 - INFO - sentinel - SynapseSite starting on 8080 synapse_main | 2022-10-20 16:32:48,387 - synapse.app.homeserver - 172 - INFO - sentinel - Synapse now listening on TCP port 8080 synapse_main | 2022-10-20 16:32:48,388 - synapse.storage.database - 844 - WARNING - sentinel - Starting db txn 'count_daily_users' from sentinel context synapse_main | 2022-10-20 16:32:48,388 - synapse.storage.database - 909 - WARNING - sentinel - Starting db connection from sentinel context: metrics will be lost synapse_main | 2022-10-20 16:32:48,389 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-0 - User parter finished: stopping synapse_main | 2022-10-20 16:32:48,393 - synapse.push.pusherpool - 347 - INFO - start_pushers-0 - Started pushers synapse_main | 2022-10-20 16:32:48,463 - synapse.storage.background_updates - 288 - INFO - background_updates-0 - Starting background schema updates for database master 2022-10-20 16:32:50,436 INFO stopped: synapse_main (exit status 0) synapse_main | 2022-10-20 16:32:48,472 - synapse.storage.background_updates - 305 - INFO - background_updates-0 - No more background updates to do. Unscheduling background update task. synapse_main | 2022-10-20 16:32:48,695 - synapse.access.http.8080 - 460 - INFO - GET-1 - ::ffff:127.0.0.1 - 8080 - {None} Processed request: 0.001sec/0.001sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 289B 200 "GET /_matrix/client/versions HTTP/1.0" "Go-http-client/1.1" [0 dbevts] synapse_main | 2022-10-20 16:32:50,402 - twisted - 274 - INFO - sentinel - Received SIGTERM, shutting down. synapse_main | 2022-10-20 16:32:50,402 - synapse.storage.databases.main.lock - 92 - INFO - LockStore._on_shutdown-0 - Dropping held locks due to shutdown synapse_main | 2022-10-20 16:32:50,402 - synapse.storage.databases.main.lock - 101 - INFO - LockStore._on_shutdown-0 - Dropped locks due to shutdown synapse_main | 2022-10-20 16:32:50,403 - synapse.handlers.presence - 766 - INFO - presence.on_shutdown-0 - Performing _on_shutdown. Persisting 0 unpersisted changes synapse_main | 2022-10-20 16:32:50,403 - synapse.handlers.presence - 779 - INFO - presence.on_shutdown-0 - Finished _on_shutdown synapse_main | 2022-10-20 16:32:50,404 - synapse.app._base - 495 - INFO - sentinel - Shutting down... synapse_main | 2022-10-20 16:32:50,404 - twisted - 274 - INFO - sentinel - (TCP Port 9093 Closed) synapse_main | 2022-10-20 16:32:50,404 - twisted - 274 - INFO - sentinel - (TCP Port 8080 Closed) synapse_main | 2022-10-20 16:32:50,407 - twisted - 274 - INFO - sentinel - Main loop terminated. 2022/10/20 11:32:50 ============== e24e04a6c3af3ba17786e37708b52a87000b98fe0a752196374fc1ae856cc673 : END LOGS ============== --- PASS: TestJumpToDateEndpoint (30.38s) --- PASS: TestJumpToDateEndpoint/parallel (0.00s) --- PASS: TestJumpToDateEndpoint/parallel/federation (0.00s) testing: warning: no tests to run PASS ok github.com/matrix-org/complement/tests 32.132s [no tests to run] 2022/10/20 11:32:20 config: &{BaseImageURI:complement-synapse DebugLoggingEnabled:false AlwaysPrintServerLogs:true EnvVarsPropagatePrefix:PASS_ SpawnHSTimeout:30s KeepBlueprints:[] HostMounts:[] BaseImageURIs:map[] PackageNamespace:csapi CACertificate:0xc00137a000 CAPrivateKey:0xc0000210e0 BestEffort:false HostnameRunningComplement:host.docker.internal} testing: warning: no tests to run PASS ok github.com/matrix-org/complement/tests/csapi 2.097s [no tests to run] ```
DMRobertson commented 2 years ago

Thanks. That's heading in the right direction (but is still depressingly high).

kegsay commented 1 year ago

The recent Complement changes to enable dirty runs don't help here when you want to edit synapse and run a single test. Most of the time will be sunk into rebuilding from source every time.

Wonder if we could build the image once and then mount the source tree into the container as an editable install, to avoid needing to rebuild every time? As long as you don't change dependencies, that should be OK.

This is what Dendrite does for its local Complement image. It does rebuild the binary via go build but that is fast. It doesn't install dependencies/etc, instead it volume mounts the dependencies directly into the image. With python not even needing recompilation, it should be possible to do this for Synapse.

reivilibre commented 1 year ago

It should be noted that since #14548, if you use the complement.sh script for Synapse with the -e/--editable flag, it will do just that ā€” mount an editable install into the container and avoid rebuilding the container. You won't get any benefit on the first run as it has to build the base image, but subsequent runs should be OK ā€” unless you modify the Rust source, in which case a rebuild is needed again.