Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

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

Open
MadLittleMods opened this issue Jul 6, 2022 · 13 comments
Open

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

MadLittleMods opened this issue Jul 6, 2022 · 13 comments
Labels
A-Testing Issues related to testing in complement, synapse, etc T-Task Refactoring, removal, replacement, enabling or disabling functionality, other engineering tasks. Z-Dev-Wishlist Makes developers' lives better, but doesn't have direct user impact

Comments

@MadLittleMods
Copy link
Contributor

MadLittleMods commented Jul 6, 2022 •
edited
Loading

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:

synapse/scripts-dev/complement.sh

Lines 89 to 107 in dcc7873

if [ -z "$skip_docker_build" ]; then
# Build the base Synapse image from the local checkout
echo_if_github "::group::Build Docker image: matrixdotorg/synapse"
docker build -t matrixdotorg/synapse \
--build-arg TEST_ONLY_SKIP_DEP_HASH_VERIFICATION \
-f "docker/Dockerfile" .
echo_if_github "::endgroup::"
# Build the workers docker image (from the base Synapse image we just built).
echo_if_github "::group::Build Docker image: matrixdotorg/synapse-workers"
docker build -t matrixdotorg/synapse-workers -f "docker/Dockerfile-workers" .
echo_if_github "::endgroup::"
# Build the unified Complement image (from the worker Synapse image we just built).
echo_if_github "::group::Build Docker image: complement/Dockerfile"
docker build -t complement-synapse \
-f "docker/complement/Dockerfile" "docker/complement"
echo_if_github "::endgroup::"
fi

With cache, the Synapse build used to take ~10s seconds, #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 ), matrix-org/complement#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

synapse/scripts-dev/complement.sh

Line 164 in dcc7873

go test -v -tags $test_tags -count=1 "${extra_test_args[@]}" "$@" ./tests/...

so it only runs against the single tests package where the feature work I care about is in.
@MadLittleMods MadLittleMods added z-testing T-Task Refactoring, removal, replacement, enabling or disabling functionality, other engineering tasks. labels Jul 6, 2022
@reivilibre
Copy link
Contributor

reivilibre commented Jul 7, 2022 •
edited
Loading

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
Copy link
Member

richvdh commented Jul 7, 2022

Test output no longer streams as it runs

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

@MadLittleMods
Copy link
Contributor Author

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 golang/go#49195

@MadLittleMods MadLittleMods mentioned this issue Jul 11, 2022
Merged
5 tasks
@richvdh richvdh mentioned this issue Jul 14, 2022
Merged
@richvdh
Copy link
Member

richvdh commented Aug 1, 2022

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

@MadLittleMods MadLittleMods mentioned this issue Aug 1, 2022
Closed
@richvdh
Copy link
Member

richvdh commented Aug 3, 2022

I hope #13447 will improve this too

@MadLittleMods
Copy link
Contributor Author

MadLittleMods commented Aug 3, 2022 •
edited
Loading

how are you finding this now that #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 #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 MadLittleMods mentioned this issue Aug 22, 2022
Merged
@richvdh richvdh added A-Testing Issues related to testing in complement, synapse, etc and removed z-testing labels Aug 25, 2022
@MadLittleMods MadLittleMods mentioned this issue Sep 22, 2022
Merged
4 tasks
@MadLittleMods MadLittleMods mentioned this issue Oct 5, 2022
Open
@MadLittleMods
Copy link
Contributor Author

MadLittleMods commented Oct 7, 2022 •
edited
Loading

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 0c853e0) 
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 <synapse.rest.health.HealthResource object at 0x7fe02220e940> to path b'/health'
synapse_main | 2022-10-07 07:08:46,872 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.replication.http.ReplicationRestResource object at 0x7fe02220ea60> 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 <synapse.rest.health.HealthResource object at 0x7fe0222173a0> to path b'/health'
synapse_main | 2022-10-07 07:08:46,899 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.EncodingResourceWrapper object at 0x7fe0211deb80> to path b'/_matrix/client'
synapse_main | 2022-10-07 07:08:46,899 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7fe0211debe0> to path b'/.well-known'
synapse_main | 2022-10-07 07:08:46,899 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.admin.AdminRestResource object at 0x7fe0211dedc0> to path b'/_synapse/admin'
synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.pick_idp.PickIdpResource object at 0x7fe0211ef790> to path b'/_synapse/client/pick_idp'
synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7fe0211ef6d0> to path b'/_synapse/client/pick_username'
synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.new_user_consent.NewUserConsentResource object at 0x7fe0211efac0> to path b'/_synapse/client/new_user_consent'
synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.sso_register.SsoRegisterResource object at 0x7fe0211efaf0> to path b'/_synapse/client/sso_register'
synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.unsubscribe.UnsubscribeResource object at 0x7fe0211efd90> 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 <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7fe0211efdc0> to path b'/_matrix/media/r0'
synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7fe0211efdc0> to path b'/_matrix/media/v3'
synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7fe0211efdc0> to path b'/_matrix/media/v1'
synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.federation.transport.server.TransportLayerServer object at 0x7fe0211eff70> to path b'/_matrix/federation'
synapse_main | 2022-10-07 07:08:46,900 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.key.v2.KeyApiV2Resource object at 0x7fe0211fa040> 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': '<redacted>', 'url': 'http://localhost:9000', 'hs_token': '<redacted>', '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 <synapse.rest.health.HealthResource object at 0x7fac5cfd5c40> to path b'/health'
synapse_main | 2022-10-07 07:08:47,163 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.replication.http.ReplicationRestResource object at 0x7fac5cfd5d60> 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 <synapse.rest.health.HealthResource object at 0x7fac5cfea130> to path b'/health'
synapse_main | 2022-10-07 07:08:47,191 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.EncodingResourceWrapper object at 0x7fac5c7b3160> to path b'/_matrix/client'
synapse_main | 2022-10-07 07:08:47,191 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7fac5c7b31c0> to path b'/.well-known'
synapse_main | 2022-10-07 07:08:47,191 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.admin.AdminRestResource object at 0x7fac5c7b33a0> to path b'/_synapse/admin'
synapse_main | 2022-10-07 07:08:47,191 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.pick_idp.PickIdpResource object at 0x7fac5c7b9d30> to path b'/_synapse/client/pick_idp'
synapse_main | 2022-10-07 07:08:47,191 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7fac5c7b9c70> to path b'/_synapse/client/pick_username'
synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.new_user_consent.NewUserConsentResource object at 0x7fac5c7c40a0> to path b'/_synapse/client/new_user_consent'
synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.sso_register.SsoRegisterResource object at 0x7fac5c7c40d0> to path b'/_synapse/client/sso_register'
synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.unsubscribe.UnsubscribeResource object at 0x7fac5c7c4370> 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 <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7fac5c7c43a0> to path b'/_matrix/media/r0'
synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7fac5c7c43a0> 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 <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7fac5c7c43a0> 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 <synapse.federation.transport.server.TransportLayerServer object at 0x7fac5c7c4550> to path b'/_matrix/federation'
synapse_main | 2022-10-07 07:08:47,192 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.key.v2.KeyApiV2Resource object at 0x7fac5c7c45e0> 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
Copy link
Member

richvdh commented Oct 7, 2022

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.

@erikjohnston erikjohnston mentioned this issue Oct 11, 2022
Merged
@DMRobertson DMRobertson mentioned this issue Oct 11, 2022
Closed
@DMRobertson
Copy link
Contributor

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

@MadLittleMods
Copy link
Contributor Author

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

Complement run (latest develop 755bfee) 
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 <synapse.rest.health.HealthResource object at 0x7f3e138c2ca0> to path b'/health'
synapse_main | 2022-10-20 16:32:47,976 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.replication.http.ReplicationRestResource object at 0x7f3e138c2dc0> 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 <synapse.rest.health.HealthResource object at 0x7f3e138cbfa0> to path b'/health'
synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.EncodingResourceWrapper object at 0x7f3e1301c4f0> to path b'/_matrix/client'
synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7f3e1301c550> to path b'/.well-known'
synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.admin.AdminRestResource object at 0x7f3e1301c730> to path b'/_synapse/admin'
synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.pick_idp.PickIdpResource object at 0x7f3e130300a0> to path b'/_synapse/client/pick_idp'
synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7f3e130300d0> to path b'/_synapse/client/pick_username'
synapse_main | 2022-10-20 16:32:48,012 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.new_user_consent.NewUserConsentResource object at 0x7f3e13030430> to path b'/_synapse/client/new_user_consent'
synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.sso_register.SsoRegisterResource object at 0x7f3e13030460> to path b'/_synapse/client/sso_register'
synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.unsubscribe.UnsubscribeResource object at 0x7f3e13030700> 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 <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7f3e13030730> to path b'/_matrix/media/r0'
synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7f3e13030730> to path b'/_matrix/media/v3'
synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7f3e13030730> to path b'/_matrix/media/v1'
synapse_main | 2022-10-20 16:32:48,013 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.federation.transport.server.TransportLayerServer object at 0x7f3e13030dc0> 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 <synapse.rest.key.v2.KeyResource object at 0x7f3e13030e50> 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': '<redacted>', 'url': 'http://localhost:9000', 'hs_token': '<redacted>', '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 <synapse.rest.health.HealthResource object at 0x7eff0e479f70> to path b'/health'
synapse_main | 2022-10-20 16:32:48,356 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.replication.http.ReplicationRestResource object at 0x7eff0e4810d0> 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 <synapse.rest.health.HealthResource object at 0x7eff0dc0e490> to path b'/health'
synapse_main | 2022-10-20 16:32:48,385 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.EncodingResourceWrapper object at 0x7eff0cfc45b0> to path b'/_matrix/client'
synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7eff0cfc4610> to path b'/.well-known'
synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.admin.AdminRestResource object at 0x7eff0cfc47f0> to path b'/_synapse/admin'
synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.pick_idp.PickIdpResource object at 0x7eff0cfd6190> to path b'/_synapse/client/pick_idp'
synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7eff0cfd6100> to path b'/_synapse/client/pick_username'
synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.new_user_consent.NewUserConsentResource object at 0x7eff0cfd64f0> to path b'/_synapse/client/new_user_consent'
synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.sso_register.SsoRegisterResource object at 0x7eff0cfd6520> to path b'/_synapse/client/sso_register'
synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.unsubscribe.UnsubscribeResource object at 0x7eff0cfd67c0> 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 <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7eff0cfd67f0> to path b'/_matrix/media/r0'
synapse_main | 2022-10-20 16:32:48,386 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7eff0cfd67f0> 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 <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7eff0cfd67f0> to path b'/_matrix/media/v1'
synapse_main | 2022-10-20 16:32:48,387 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.federation.transport.server.TransportLayerServer object at 0x7eff0cfd6e80> to path b'/_matrix/federation'
synapse_main | 2022-10-20 16:32:48,387 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.key.v2.KeyResource object at 0x7eff0cfd6f10> 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
Copy link
Contributor

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

@MadLittleMods MadLittleMods mentioned this issue Oct 28, 2022
Open
@DMRobertson DMRobertson removed their assignment Nov 10, 2022
@reivilibre reivilibre self-assigned this Nov 25, 2022
@reivilibre reivilibre mentioned this issue Nov 25, 2022
Merged
@MadLittleMods MadLittleMods added the Z-Dev-Wishlist Makes developers' lives better, but doesn't have direct user impact label May 22, 2023
@kegsay
Copy link
Member

kegsay commented Oct 18, 2023

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
Copy link
Contributor

reivilibre commented Oct 18, 2023 •
edited
Loading

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.

This was referenced Dec 21, 2023
Open
Open
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
A-Testing Issues related to testing in complement, synapse, etc T-Task Refactoring, removal, replacement, enabling or disabling functionality, other engineering tasks. Z-Dev-Wishlist Makes developers' lives better, but doesn't have direct user impact
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@MadLittleMods @richvdh @kegsay @DMRobertson @reivilibre