TestImportHistoricalMessages test fails in Complement when using workers

[reivilibre]

Interesting piece of log:

    msc2716_test.go:64: Deploy times: 22.33672842s blueprints, 7.183656158s containers
    msc2716_test.go:1138: Making POST request to http://localhost:49765/_matrix/client/r0/register (4682ca3c5471aa40266ac9893e1a927bbba68489636821bbb71c6b414bb8b107)
    msc2716_test.go:1138: Request body: {"type":"m.login.application_service","username":"maria"}
    client.go:544: POST hs1/_matrix/client/r0/register => 401 Unauthorized (1.838055ms)
    msc2716_test.go:1138: HTTP/1.1 401 Unauthorized
        Transfer-Encoding: chunked
        Access-Control-Allow-Headers: X-Requested-With, Content-Type, Authorization, Date
        Access-Control-Allow-Methods: GET, HEAD, POST, PUT, DELETE, OPTIONS
        Access-Control-Allow-Origin: *
        Cache-Control: no-cache, no-store, must-revalidate
        Connection: keep-alive
        Content-Type: application/json
        Date: Fri, 20 May 2022 16:26:35 GMT
        Server: nginx/1.18.0
        
        55
        {"errcode":"M_UNKNOWN_TOKEN","error":"Unrecognised access token","soft_logout":false}
        0
        
    msc2716_test.go:1157: msc2716.ensureVirtualUserRegistered failed to register: (M_UNKNOWN_TOKEN) Unrecognised access token

Obtained with

COMPLEMENT_DEBUG=1 WORKERS=1 COMPLEMENT_DIR=../complement ./scripts-dev/complement.sh -run TestImportHistoricalMessages &> ../_misc/2022-05/compl-TestImportHistoricalMessages.log

Looks like it might just be a configuration problem (to add an appservice?)

[reivilibre]

After adding support for registering ASes, I get these scarier and dodgier looking errors:

synapse_federation_reader1 | 2022-05-20 17:14:23,473 - synapse.http.server - 183 - ERROR - GET-33 - Failed handle request via 'FederationBackfillServlet': <SynapseRequest at 0x7f57c447e5b0 method='GET' uri='/_matrix/federation/v1/backfill/%21UttPutiOeNiFTnuSYv%3Ahs1?v=%24SEk-YQMkk8gEWCuI3nTZFdcalGNYoZAVgkI9RkCGqKk&limit=100' clientproto='HTTP/1.0' site='18017'>
synapse_federation_reader1 | Traceback (most recent call last):
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/http/server.py", line 366, in _async_render_wrapper
synapse_federation_reader1 |     callback_return = await self._async_render(request)
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/http/server.py", line 572, in _async_render
synapse_federation_reader1 |     callback_return = await raw_callback_return
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/federation/transport/server/_base.py", line 348, in new_func
synapse_federation_reader1 |     response = await func(
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/federation/transport/server/federation.py", line 200, in on_GET
synapse_federation_reader1 |     return await self.handler.on_backfill_request(origin, room_id, versions, limit)
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/federation/federation_server.py", line 195, in on_backfill_request
synapse_federation_reader1 |     pdus = await self.handler.on_backfill_request(
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation.py", line 1064, in on_backfill_request
synapse_federation_reader1 |     events = await self.store.get_backfill_events(room_id, pdu_list, limit)
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/databases/main/event_federation.py", line 1141, in get_backfill_events
synapse_federation_reader1 |     event_ids = await self.db_pool.runInteraction(
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 832, in runInteraction
synapse_federation_reader1 |     return await delay_cancellation(_runInteraction())
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/twisted/internet/defer.py", line 1656, in _inlineCallbacks
synapse_federation_reader1 |     result = current_context.run(
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/twisted/python/failure.py", line 514, in throwExceptionIntoGenerator
synapse_federation_reader1 |     return g.throw(self.type, self.value, self.tb)
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 804, in _runInteraction
synapse_federation_reader1 |     result = await self.runWithConnection(
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 927, in runWithConnection
synapse_federation_reader1 |     return await make_deferred_yieldable(
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/twisted/python/threadpool.py", line 244, in inContext
synapse_federation_reader1 |     result = inContext.theWork()  # type: ignore[attr-defined]
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
synapse_federation_reader1 |     inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/twisted/python/context.py", line 117, in callWithContext
synapse_federation_reader1 |     return self.currentContext().callWithContext(ctx, func, *args, **kw)
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/twisted/python/context.py", line 82, in callWithContext
synapse_federation_reader1 |     return func(*args, **kw)
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
synapse_federation_reader1 |     result = func(conn, *args, **kw)
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 920, in inner_func
synapse_federation_reader1 |     return func(db_conn, *args, **kwargs)
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 668, in new_transaction
synapse_federation_reader1 |     r = func(cursor, *args, **kwargs)
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/databases/main/event_federation.py", line 1238, in _get_backfill_events
synapse_federation_reader1 |     self._get_connected_batch_event_backfill_results_txn(
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/databases/main/event_federation.py", line 1067, in _get_connected_batch_event_backfill_results_txn
synapse_federation_reader1 |     txn.execute(
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 350, in execute
synapse_federation_reader1 |     self._do_execute(self.txn.execute, sql, *args)
synapse_federation_reader1 |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 392, in _do_execute
synapse_federation_reader1 |     return func(sql, *args, **kwargs)
synapse_federation_reader1 | psycopg2.errors.AmbiguousColumn: common column name "event_id" appears more than once in left table

Unsure how we wouldn't have noticed this until now, but guess that's one for monday anyway.