Add option to print server logs when running against Dendrite

[MadLittleMods]

Add option to print server logs when running against Dendrite

Spawned from #1009

Dev notes

See https://github.com/matrix-org/dendrite/blob/master/docs/sytest.md#manually-setting-up-sytest

• psql: Open the postgres CLI
• \l: List databases
• DROP DATABASE IF EXISTS dendrite0;: Drop dendrite0 database
• \q -> enter: To quit/exit
• \dt: list tables

random trials

Can't get this to run successfully

$ POSTGRES=1 ./run-tests.pl -I Dendrite::Monolith -d ../dendrite/bin -W ../dendrite/sytest-whitelist tests/10apidoc/30room-create.pl -vvvv
Running tests/10apidoc/30room-create.pl...
 # Starting test POST /createRoom makes a public room
 # Starting fixture local_user_fixture
 # Starting fixture FIXTURE-7
 # Starting fixture HOMESERVER_0
 # Starting fixture FIXTURE-0
  Testing if: POST /createRoom makes a public room...
Tests: 0 / 10 | OKSignature ok
subject=/CN=localhost
 # Starting fixture FIXTURE-3
 # Starting fixture FIXTURE-1
 # Fixture FIXTURE-1 now ready
 # Starting fixture FIXTURE-2
 # Fixture FIXTURE-2 now ready
 # Starting fixture FIXTURE-49
 # Fixture FIXTURE-49 now ready
 # Started test HTTPS Server at localhost:57448
 # Started test SMTP Server at localhost:57449
 # Fixture FIXTURE-3 now ready
 ** HOMESERVER_0: input fixture failed with Connection closed at ./run-tests.pl line 567.
 ** FIXTURE-7: input fixture failed with Connection closed at ./run-tests.pl line 567.
 ** local_user_fixture: input fixture failed with Connection closed at ./run-tests.pl line 567.
 ** Fixture failed with Connection closed at ./run-tests.pl line 736.
 ** Destroying unresponded HTTP request to /http_server_self_test at /Users/eric/perl5/perlbrew/perls/perl-5.32.0/lib/site_perl/5.32.0/Net/Async/HTTP/Server/Protocol.pm line 53.
  Testing if: POST /createRoom makes a public room... FAIL:
 | fixture failed - Connection closed
 +----------------------
 # Starting test POST /createRoom makes a private room
 ** Fixture failed with Connection closed at ./run-tests.pl line 736.
  Testing if: POST /createRoom makes a private room... FAIL:
 | fixture failed - Connection closed
 +----------------------
 # Starting test POST /createRoom makes a private room with invites
  Testing if: POST /createRoom makes a private room with invites... SKIP due to lack of can_create_private_room
 # Starting test POST /createRoom makes a room with a name
  Testing if: POST /createRoom makes a room with a name... SKIP due to lack of can_create_private_room
 # Starting test POST /createRoom makes a room with a topic
  Testing if: POST /createRoom makes a room with a topic... SKIP due to lack of can_create_private_room
 # Starting test Can /sync newly created room
 ** Fixture failed with Connection closed at ./run-tests.pl line 736.
  Testing if: Can /sync newly created room... FAIL:
 | fixture failed - Connection closed
 +----------------------
 # Starting test POST /createRoom creates a room with the given version
 ** Fixture failed with Connection closed at ./run-tests.pl line 736.
  Testing if: POST /createRoom creates a room with the given version... FAIL:
 | fixture failed - Connection closed
 +----------------------
 # Starting test POST /createRoom rejects attempts to create rooms with numeric versions
  Testing if: POST /createRoom rejects attempts to create rooms with numeric versions... SKIP due to lack of can_create_versioned_room
 # Starting test POST /createRoom rejects attempts to create rooms with unknown versions
  Testing if: POST /createRoom rejects attempts to create rooms with unknown versions... SKIP due to lack of can_create_versioned_room
 # Starting test POST /createRoom ignores attempts to set the room version via creation_content
 ** Fixture failed with Connection closed at ./run-tests.pl line 736.
  Testing if: POST /createRoom ignores attempts to set the room version via creation_content... FAIL:
 | fixture failed - Connection closed
 +----------------------

5 tests FAILED

The Docker image always prints server logs regardless 🤷‍♀️

docker run --rm --name sytest -v "/Users/eric/Documents/github/element/sytest:/sytest" \
	-v "/Users/eric/Documents/github/element/dendrite:/src" -v "/Users/eric/Downloads/logs:/logs" \
	-v "/Users/eric/.gvm/pkgsets/go1.16.6/global/:/gopath" -e "POSTGRES=1" -e "DENDRITE_TRACE_HTTP=1" \
	matrixdotorg/sytest-dendrite:latest tests/50federation/40devicelists.pl

[richvdh]

I'm a bit confused about what this is trying to do? It seems we set SyTest::Homeserver::Dendrite::print_output, but then don't do anything with it?

[MadLittleMods]

Sorry, it has been a while since I touched #1009 and I didn't actually try this out when I split it out into this PR 🙇

It looks like when running against Dendrite, it already has the server logs at the end 🤷‍♀️

$ POSTGRES=1 ./run-tests.pl -I Dendrite::Monolith -d ../dendrite/bin -W ../dendrite/sytest-whitelist tests/31sync/01filter.pl
Running tests/31sync/01filter.pl...
  Testing if: Can create filter...
Tests: 0 / 2 | OKSignature ok
subject=/CN=localhost
 # Started test SMTP Server at localhost:57387
 # Started test HTTPS Server at localhost:57388
 # Starting Homeserver using SyTest::HomeserverFactory::Dendrite::Monolith=HASH(0x7f8fde80af90)
 # Starting server-0
 # Clearing Pg database dendrite0 on '127.0.0.1'
 # Starting monolith server
 ** Use of uninitialized value $ENV{"API"} in numeric eq (==) at lib/SyTest/Homeserver/Dendrite.pm line 376.
 # Starting Dendrite with: ../dendrite/bin/dendrite-monolith-server --config /Users/eric/Documents/github/element/sytest/server-0/dendrite.yaml --http-bind-address localhost:8801 --https-bind-address localhost:8800 --api-bind-address localhost:18801 --tls-cert /Users/eric/Documents/github/element/sytest/server-0/server.crt --tls-key /Users/eric/Documents/github/element/sytest/server-0/server.key
 # Connecting to server 8800
 # Connected to server 8800
 # Started monolith server
 # Started server-0
  Testing if: Can create filter... PASS
  Testing if: Can download filter... PASS
 # Killing process server
[server]: time="2021-07-29T23:27:13.910391000Z" level=info msg="Sending device list update message to []" func="onMessage\n\t" file=" [keychange.go:132]"
[server]: time="2021-07-29T23:27:13.913042000Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=H1l84rYQz0ZK req.method=POST req.path="/_matrix/client/r0/user/@anon-20210729_232712-2:localhost:8800/filter"
[server]: time="2021-07-29T23:27:13.917538000Z" level=trace msg="Responding (17 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=H1l84rYQz0ZK req.method=POST req.path="/_matrix/client/r0/user/@anon-20210729_232712-2:localhost:8800/filter"
[server]: time="2021-07-29T23:27:13.919579000Z" level=trace msg="Incoming request" func="RequestWithLogging\n\t" file=" [json.go:123]" req.id=p1ioJ729Jql0 req.method=GET req.path="/_matrix/client/r0/user/@anon-20210729_232712-2:localhost:8800/filter/2"
[server]: time="2021-07-29T23:27:13.920326000Z" level=trace msg="Responding (192 bytes)" func="respond\n\t" file=" [json.go:173]" code=200 req.id=p1ioJ729Jql0 req.method=GET req.path="/_matrix/client/r0/user/@anon-20210729_232712-2:localhost:8800/filter/2"
[server]: time="2021-07-29T23:27:13.921600000Z" level=warning msg="Shutdown signal received" func="WaitForShutdown\n\t" file=" [base.go:470]"
[server]: time="2021-07-29T23:27:13.921649000Z" level=info msg="Stopped consumer for \"federationsender/roomserver\" topic \"DendriteOutputRoomEvent\"" func="func1\n\t" file=" [consumers.go:114]"
[server]: time="2021-07-29T23:27:13.921671000Z" level=info msg="Stopped consumer for \"syncapi/eduserver/receipt\" topic \"DendriteOutputReceiptEvent\"" func="func1\n\t" file=" [consumers.go:114]"
[server]: time="2021-07-29T23:27:13.921695000Z" level=info msg="Stopped consumer for \"eduserver/receipt\" topic \"DendriteOutputReceiptEvent\"" func="func1\n\t" file=" [consumers.go:114]"
[server]: time="2021-07-29T23:27:13.921698000Z" level=info msg="Stopped consumer for \"syncapi/roomserver\" topic \"DendriteOutputRoomEvent\"" func="func1\n\t" file=" [consumers.go:114]"
[server]: time="2021-07-29T23:27:13.921718000Z" level=info msg="Stopped consumer for \"syncapi/eduserver/typing\" topic \"DendriteOutputTypingEvent\"" func="func1\n\t" file=" [consumers.go:114]"
[server]: time="2021-07-29T23:27:13.921761000Z" level=info msg="Stopped consumer for \"eduserver/typing\" topic \"DendriteOutputTypingEvent\"" func="func1\n\t" file=" [consumers.go:114]"
[server]: time="2021-07-29T23:27:13.921795000Z" level=info msg="Stopped external HTTP listener" func="1\n\t" file=" [base.go:434]"
[server]: time="2021-07-29T23:27:13.921789000Z" level=info msg="Stopped HTTP listeners" func="SetupAndServeHTTP\n\t" file=" [base.go:461]"
[server]: time="2021-07-29T23:27:13.921838000Z" level=info msg="Stopped HTTP listeners" func="SetupAndServeHTTP\n\t" file=" [base.go:461]"
[server]: time="2021-07-29T23:27:13.921877000Z" level=info msg="Stopped external Monolith listener on localhost:8800" func="func2\n\t" file=" [base.go:450]"
[server]: time="2021-07-29T23:27:13.921732000Z" level=info msg="Stopped consumer for \"syncapi/eduserver/sendtodevice\" topic \"DendriteOutputSendToDeviceEvent\"" func="func1\n\t" file=" [consumers.go:114]"
[server]: time="2021-07-29T23:27:13.921912000Z" level=info msg="Stopped external HTTP listener" func="1\n\t" file=" [base.go:434]"
[server]: time="2021-07-29T23:27:13.921941000Z" level=warning msg="Dendrite is exiting now" func="WaitForShutdown\n\t" file=" [base.go:480]"
[server]: time="2021-07-29T23:27:13.921797000Z" level=info msg="Stopped consumer for \"federationsender/keychange\" topic \"DendriteOutputKeyChangeEvent\"" func="func1\n\t" file=" [consumers.go:114]"

All tests PASSED (with 2 passes)