Use supervisord to supervise Postgres and Caddy in the Complement image.

[reivilibre]

This is still leading to corrupt Postgres databases, need to investigate.

[richvdh]

it looks like supervisord still isn't ending up as PID 1 within the container.

Try replacing the entrypoint with an explicit shell invocation:

ENTRYPOINT ["/bin/bash", "/start-complement-synapse-workers.sh"]

from https://docs.docker.com/engine/reference/builder/#entrypoint:

The shell form ... has the disadvantage that your ENTRYPOINT will be started as a subcommand of /bin/sh -c, which does not pass signals. This means that the executable will not be the container’s PID 1 - and will not receive Unix signals - so your executable will not receive a SIGTERM from docker stop <container>.

(TIL. We probably ought to do something similar in our other Dockerfiles)

[reivilibre]

It looks like supervisord is now PID 1 and the container stops within 4 seconds.
Postgres itself exits very rapidly, but supervisord stops processes with a higher priority before stopping it.
We could consider having supervisord SIGKILL Caddy, Redis and the Synapse workers if we really wanted to be as expedient as possible? Everything in there should be volatile, more or less, anyway. Do you think that sounds worthwhile?

stale

[richvdh]

Postgres itself exits very rapidly, but supervisord stops processes with a higher priority before stopping it.

Do we actually need postgres to be a higher prority than synapse? It's not like there's any guarantee that doing so will mean that postgres is ready before synapse starts.

We could consider having supervisord SIGKILL Caddy, Redis and the Synapse workers if we really wanted to be as expedient as possible? Everything in there should be volatile, more or less, anyway. Do you think that sounds worthwhile?

Is it just synapse that is slow? I could be persuaded that SIGKILLing it might be good. Think I'd make it a separate PR though.

[richvdh]

lgtm otherwise

[reivilibre]

Do we actually need postgres to be a higher prority than synapse? It's not like there's any guarantee that doing so will mean that postgres is ready before synapse starts.

No, though Synapse's configuration already defined it at priority 500 so it seemed like this was the intention.
(I just realised: The main Synapse process' priority is actually defined as 10; Redis' is 1. Postgres should probably be on the same level as Redis if we're going to have priority ordering?)
I would have thought that Postgres being up first might avoid some noisy errors in Synapse's logs.

Supervisor by default will check that a process is up for 1 second before considering it 'up' (see startsecs). Hence starting Postgres first is probably good enough for the intention of avoiding noisy connection errors.

I'm not sure, but if we give everything the same priority (or remove the option to use the 999 default), I imagine everything will start and stop concurrently?¹ What would you prefer?

Is it just synapse that is slow? I could be persuaded that SIGKILLing it might be good. Think I'd make it a separate PR though.

I couldn't remember, so I tried it again. This is the timeline of stopping:

2022-04-27 12:21:44,105 WARN received SIGTERM indicating exit request
2022-04-27 12:21:44,106 INFO waiting for redis, synapse_main, nginx, synapse_appservice1, synapse_background_worker1, synapse_event_creator1, synapse_event_persister1, synapse_event_persister2, synapse_federation_inbound1, synapse_federation_reader1, synapse_federation_sender1, synapse_frontend_proxy1, synapse_media_repository1, synapse_pusher1, synapse_synchrotron1, synapse_user_dir1, caddy, postgres to die
2022-04-27 12:21:44,219 INFO stopped: postgres (exit status 0)
2022-04-27 12:21:45,723 INFO stopped: caddy (exit status 0)
2022-04-27 12:21:45,776 INFO stopped: synapse_user_dir1 (exit status 0)
2022-04-27 12:21:45,799 INFO stopped: synapse_synchrotron1 (exit status 0)
2022-04-27 12:21:45,838 INFO stopped: synapse_pusher1 (exit status 0)
2022-04-27 12:21:45,875 INFO stopped: synapse_media_repository1 (exit status 0)
2022-04-27 12:21:45,916 INFO stopped: synapse_frontend_proxy1 (exit status 0)
2022-04-27 12:21:45,961 INFO stopped: synapse_federation_sender1 (exit status 0)
2022-04-27 12:21:46,006 INFO stopped: synapse_federation_reader1 (exit status 0)
2022-04-27 12:21:46,035 INFO stopped: synapse_federation_inbound1 (exit status 0)
2022-04-27 12:21:46,099 INFO stopped: synapse_event_persister2 (exit status 0)
2022-04-27 12:21:46,126 INFO stopped: synapse_event_persister1 (exit status 0)
2022-04-27 12:21:46,154 INFO stopped: synapse_event_creator1 (exit status 0)
2022-04-27 12:21:46,176 INFO stopped: synapse_background_worker1 (exit status 0)
2022-04-27 12:21:46,207 INFO stopped: synapse_appservice1 (exit status 0)
2022-04-27 12:21:46,210 INFO stopped: nginx (exit status 0)
2022-04-27 12:21:46,237 INFO stopped: synapse_main (exit status 0)
2022-04-27 12:21:46,293 INFO stopped: redis (exit status 0)

It seems faster than I was thinking, so maybe it's not a problem. (That's 2.1 seconds from stop signal to stopped.)
SIGKILLing all the Synapses would just mean we don't need to wait a short while for each of them to shut down.
(It'd also be interesting to know why there's both a Caddy and an nginx in there...)

Footnotes

1. I'm not sure, actually. Shutdown seems to be sequential even amongst Synapse workers which have the same priority. ↩

[richvdh]

following up on #12480 (comment):

Do we actually need postgres to be a higher prority than synapse? It's not like there's any guarantee that doing so will mean that postgres is ready before synapse starts.

No, though Synapse's configuration already defined it at priority 500 so it seemed like this was the intention.

I'm not sure the priority was particularly carefully chosen, tbh. (ftr, this bit came from #9162).

(I just realised: The main Synapse process' priority is actually defined as 10; Redis' is 1. Postgres should probably be on the same level as Redis if we're going to have priority ordering?)

If we're going to have priority ordering, then yes it ought to be lower than Synapse.

I would have thought that Postgres being up first might avoid some noisy errors in Synapse's logs.

If it actually manages to start up in 1 second, then yes maybe. TBH though I would optimise for fastest runtime rather than lack of noise in the logs.

[richvdh]

let's set this to be the same as Redis for now, and get this PR merged.

[richvdh]

oh you're way ahead of me

[richvdh]

Re SIGKILL:

It seems faster than I was thinking, so maybe it's not a problem. (That's 2.1 seconds from stop signal to stopped.)

In this case it looks like it's stopping postgres before synapse stops? Had you already changed the priorities? I can imagine that stopping postgres will encourage synapse to stop quickly. (I can also imagine the opposite...)

Let's leave this for now, either way.

[richvdh]

(It'd also be interesting to know why there's both a Caddy and an nginx in there...)

This was added in matrix-org/complement#62. My understanding is that the basic synapse-workers image uses an nginx to route between the workers. The Complement wrapper adds caddy to do the SSL termination (in particular, generating a TLS cert for the test server). Personally, I'd have used openssl commandline to sort out the certs instead, but caddy does the job.

[richvdh]

lgtm!

[reivilibre]

In this case it looks like it's stopping postgres before synapse stops? Had you already changed the priorities?

This was taken from Postgres not having an explicit priority (so priority 999), in which case it starts after Synapse and stops before it.

With priority = 1 (same as Redis):

$ COMPLEMENT_DEBUG=1 WORKERS=1 COMPLEMENT_ALWAYS_PRINT_SERVER_LOGS=1 COMPLEMENT_DIR=`pwd`/../complement ./scripts-dev/complement.sh -run TestInboundFederationKeys 2>&1 | tee /tmp/comlog
... (Use hacked complement that has a long sleep before actually stopping the container. Wait for it to say complement is running.)
$ docker stop -t 500 complement_fed.alice.hs1
$ docker logs complement_fed.alice.hs1 2>&1 | grep -E 'WARN rece|INFO stop|INFO wait'
2022-04-27 13:15:27,058 WARN received SIGTERM indicating exit request
2022-04-27 13:15:27,058 INFO waiting for postgres, redis, synapse_main, nginx, synapse_appservice1, synapse_background_worker1, synapse_event_creator1, synapse_event_persister1, synapse_event_persister2, synapse_federation_inbound1, synapse_federation_reader1, synapse_federation_sender1, synapse_frontend_proxy1, synapse_media_repository1, synapse_pusher1, synapse_synchrotron1, synapse_user_dir1, caddy to die
2022-04-27 13:15:28,561 INFO stopped: caddy (exit status 0)
2022-04-27 13:15:28,584 INFO stopped: synapse_user_dir1 (exit status 0)
2022-04-27 13:15:28,605 INFO stopped: synapse_synchrotron1 (exit status 0)
2022-04-27 13:15:28,627 INFO stopped: synapse_pusher1 (exit status 0)
2022-04-27 13:15:28,650 INFO stopped: synapse_media_repository1 (exit status 0)
2022-04-27 13:15:28,671 INFO stopped: synapse_frontend_proxy1 (exit status 0)
2022-04-27 13:15:28,694 INFO stopped: synapse_federation_sender1 (exit status 0)
2022-04-27 13:15:28,715 INFO stopped: synapse_federation_reader1 (exit status 0)
2022-04-27 13:15:28,738 INFO stopped: synapse_federation_inbound1 (exit status 0)
2022-04-27 13:15:28,762 INFO stopped: synapse_event_persister2 (exit status 0)
2022-04-27 13:15:28,783 INFO stopped: synapse_event_persister1 (exit status 0)
2022-04-27 13:15:28,805 INFO stopped: synapse_event_creator1 (exit status 0)
2022-04-27 13:15:28,828 INFO stopped: synapse_background_worker1 (exit status 0)
2022-04-27 13:15:28,850 INFO stopped: synapse_appservice1 (exit status 0)
2022-04-27 13:15:28,853 INFO stopped: nginx (exit status 0)
2022-04-27 13:15:28,873 INFO stopped: synapse_main (exit status 0)
2022-04-27 13:15:28,916 INFO stopped: redis (exit status 0)
2022-04-27 13:15:29,004 INFO stopped: postgres (exit status 0)

2 sec, so no likely difference to the other way around. I'll go with this for now since it makes most sense.

I can imagine that stopping postgres will encourage synapse to stop quickly. (I can also imagine the opposite...)

Good point.

[reivilibre]

The tests still fail:

--- FAIL: TestIsDirectFlagFederation (42.08s)
--- FAIL: TestEventAuth (19.81s)
--- FAIL: TestOutboundFederationProfile (22.62s)
    --- FAIL: TestOutboundFederationProfile/Outbound_federation_can_query_profile_data (10.02s)
--- FAIL: TestInboundFederationRejectsEventsWithRejectedAuthEvents (18.20s)
--- FAIL: TestGetMissingEventsGapFilling (20.82s)
--- FAIL: TestOutboundFederationIgnoresMissingEventWithBadJSONForRoomVersion6 (20.45s)
--- FAIL: TestFederationRejectInvite (65.22s)
--- FAIL: TestJoinViaRoomIDAndServerName (76.13s)
--- FAIL: TestJoinFederatedRoomWithUnverifiableEvents (49.18s)
    --- FAIL: TestJoinFederatedRoomWithUnverifiableEvents//send_join_response_missing_signatures_shouldn't_block_room_join (10.02s)
    --- FAIL: TestJoinFederatedRoomWithUnverifiableEvents//send_join_response_with_bad_signatures_shouldn't_block_room_join (10.01s)
    --- FAIL: TestJoinFederatedRoomWithUnverifiableEvents//send_join_response_with_unobtainable_keys_shouldn't_block_room_join (10.01s)
    --- FAIL: TestJoinFederatedRoomWithUnverifiableEvents//send_join_response_with_state_with_unverifiable_auth_events_shouldn't_block_room_join (10.01s)
--- FAIL: TestBannedUserCannotSendJoin (21.32s)
--- FAIL: TestCannotSendNonJoinViaSendJoinV1 (20.88s)
--- FAIL: TestCannotSendNonJoinViaSendJoinV2 (18.80s)
--- FAIL: TestCannotSendNonLeaveViaSendLeaveV1 (20.09s)
--- FAIL: TestCannotSendNonLeaveViaSendLeaveV2 (20.14s)
--- FAIL: TestSendJoinPartialStateResponse (19.84s)
--- FAIL: TestOutboundFederationSend (17.56s)
--- FAIL: TestUnrejectRejectedEvents (26.88s)
--- FAIL: TestKnocking (39.72s)
FAIL    github.com/matrix-org/complement/tests  602.251s
--- FAIL: TestCanRegisterAdmin (10.14s)
--- FAIL: TestServerNotices (6.49s)
--- FAIL: TestRegistration (8.52s)
    --- FAIL: TestRegistration/parallel (0.34s)
        --- FAIL: TestRegistration/parallel/POST_/_synapse/admin/v1/register_admin_with_shared_secret (0.01s)
        --- FAIL: TestRegistration/parallel/POST_/_synapse/admin/v1/register_with_shared_secret (0.01s)
        --- FAIL: TestRegistration/parallel/POST_/_synapse/admin/v1/register_with_shared_secret_disallows_symbols (0.01s)
        --- FAIL: TestRegistration/parallel/POST_/_synapse/admin/v1/register_with_shared_secret_downcases_capitals (0.01s)
--- FAIL: TestRoomImageRoundtrip (6.52s)
FAIL
FAIL    github.com/matrix-org/complement/tests/csapi    501.971s
FAIL

so there looks to be more work to do in further PRs.