End2end encrypted mautrix-signal bridge fails with "Matrix connector: homeserver does not support appservice"

[xundeenergie]

Describe the bug
A clear and concise description of what the bug is.

I setup a new mautrix-signal bridge with end2end-encryption. I configured double-puppeting. All according to the docs from mautrix-bridge.

I changed from matrix-synapse with directly configured oidc and ldap authentication to matrix-authentication-service successfully. After that, my mautrix-signal bridge stopped working... so i setup a new bridge to test it for this bugreport.

I asked in the matrix-room for the mautrix-signal bridge and got pointed to this issue:
spantaleev/matrix-docker-ansible-deploy#3493

The conclusion there is, that my problem is probably with matrix-authentication-service.

What i did:

Created an example-config from the mautrix-signal directly and filled in the neccessary information from an old bridge, which worked before migration to MAS.

I activated end2end-encryption and double puppetting.

When i start the bridge, i get this in the bridge-log and combined the nginx-log for synapse/matrix with tail to those 2 logfiles:

==> /var/log/nginx/matrix.schuerz.at.access.log <==                                                                                                                                                                
127.0.0.0 - - [16/Sep/2024:00:25:13 +0200] "GET /_matrix/client/versions?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 343 "-" "mautrix-signal/0.7.0 mautrix-go/v0.20.0 go/1.22.6"                        
                                                                                                                                                                                                                   
==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"debug","req_id":1,"method":"GET","url":"https://matrix.schuerz.at/_matrix/client/versions?user_id=%40signalbotprimary%3Aschuerz.at","duration":57.545853,"status_code":200,"response_length":1038,"respon
se_mime":"application/json","time":"2024-09-16T00:25:13.949786427+02:00","message":"Request completed"}                                                                                                            
                                                                                                                                                                                                                   
==> /var/log/nginx/matrix.schuerz.at.access.log <==                                                                                                                                                                
127.0.0.0 - - [16/Sep/2024:00:25:13 +0200] "GET /_matrix/client/v3/account/whoami?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 79 "-" "mautrix-signal/0.7.0 mautrix-go/v0.20.0 go/1.22.6"                
                                                                                                                                                                                                                   
==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"debug","req_id":2,"method":"GET","url":"https://matrix.schuerz.at/_matrix/client/v3/account/whoami?user_id=%40signalbotprimary%3Aschuerz.at","duration":3.932288,"status_code":200,"response_length":59,"
response_mime":"application/json","time":"2024-09-16T00:25:13.958542735+02:00","message":"Request completed"}                                                                                                      
{"level":"debug","txn_id":"mautrix-go_1726439113959084878_1","time":"2024-09-16T00:25:13.965025656+02:00","message":"Received ping from homeserver"}                                                               
                                                                                                                                                                                                                   
==> /var/log/nginx/matrix.schuerz.at.access.log <==                                                                                                                                                                
127.0.0.0 - - [16/Sep/2024:00:25:13 +0200] "POST /_matrix/client/v1/appservice/signalprimary/ping?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 37 "-" "mautrix-signal/0.7.0 mautrix-go/v0.20.0 go/1.22.6"
                                                                                                                                                                                                                   
==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"debug","req_id":3,"method":"POST","url":"https://matrix.schuerz.at/_matrix/client/v1/appservice/signalprimary/ping?user_id=%40signalbotprimary%3Aschuerz.at","duration":11.486043,"status_code":200,"resp
onse_length":17,"response_mime":"application/json","req_body":{"transaction_id":"mautrix-go_1726439113959084878_1"},"time":"2024-09-16T00:25:13.970872465+02:00","message":"Request completed"}                    
{"level":"debug","txn_id":"mautrix-go_1726439113959084878_1","duration_ms":5,"time":"2024-09-16T00:25:13.9716988+02:00","message":"Homeserver -> bridge connection works"}                                         
{"level":"debug","component":"crypto","time":"2024-09-16T00:25:13.973128557+02:00","message":"Initializing end-to-bridge encryption..."}                                                                           
                                                                                                                                                                                                                   
==> /var/log/nginx/matrix.schuerz.at.access.log <==                                                                                                                                                                
127.0.0.0 - - [16/Sep/2024:00:25:13 +0200] "GET /_matrix/client/v1/media/config?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 47 "-" "mautrix-signal/0.7.0 mautrix-go/v0.20.0 go/1.22.6"                  
                                                                                                                                                                                                                   
==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"info","db_section":"crypto","current_version":15,"oldest_compatible_version":15,"latest_known_version":15,"time":"2024-09-16T00:25:13.984279511+02:00","message":"Database is up to date"}               
{"level":"debug","req_id":4,"method":"GET","url":"https://matrix.schuerz.at/_matrix/client/v1/media/config?user_id=%40signalbotprimary%3Aschuerz.at","duration":12.40641,"status_code":200,"response_length":27,"re
sponse_mime":"application/json","time":"2024-09-16T00:25:13.985897839+02:00","message":"Request completed"}                                                                                                        

==> /var/log/nginx/matrix.schuerz.at.access.log <==
127.0.0.0 - - [16/Sep/2024:00:25:13 +0200] "GET /_matrix/client/v3/login?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 114 "-" "mautrix-signal/0.7.0 mautrix-go/v0.20.0 go/1.22.6"

==> /var/log/mautrix-signal/primary/mautrix-signal.log <==
{"level":"debug","req_id":5,"method":"GET","url":"https://matrix.schuerz.at/_matrix/client/v3/login?user_id=%40signalbotprimary%3Aschuerz.at","duration":3.704204,"status_code":200,"response_length":114,"response_mime":"application/json","time":"2024-09-16T00:25:13.99217928+02:00","message":"Request completed"}
{"level":"fatal","error":"failed to start Matrix connector: homeserver does not support appservice login","time":"2024-09-16T00:25:13.993619278+02:00","message":"Failed to start bridge"}

At the same time in homeserver.log: no entries!!

Deactivate e2e-encryption in bridge config and restart bridge

==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"info","name":"mautrix-signal","version":"0.7.0","built_at":"2024-08-16T12:19:42Z","go_version":"go1.22.6","time":"2024-09-16T00:36:47.431264927+02:00","message":"Initializing bridge"}                  
{"level":"debug","time":"2024-09-16T00:36:47.432282894+02:00","message":"Initializing database connection"}                                                                                                        
{"level":"debug","time":"2024-09-16T00:36:47.433698235+02:00","message":"Bridge built with end-to-bridge encryption, but disabled in config"}                                                                      
{"level":"info","component":"signalmeow","component":"libsignal","target":"signal_ffi::logging","file":"rust/bridge/ffi/src/logging.rs","line":106,"time":"2024-09-16T00:36:47.434493613+02:00","message":"Initiali
zing libsignal version:0.55.0"}                                                                                                                                                                                    
{"level":"info","time":"2024-09-16T00:36:47.467733054+02:00","message":"Starting bridge"}                                                                                                                          
{"level":"info","db_section":"main","current_version":16,"oldest_compatible_version":9,"latest_known_version":16,"time":"2024-09-16T00:36:47.493552211+02:00","message":"Database is up to date"}                  
{"level":"info","time":"2024-09-16T00:36:47.494406687+02:00","message":"Starting Matrix connector"}                                                                                                                
{"level":"info","db_section":"matrix_state","current_version":6,"oldest_compatible_version":3,"latest_known_version":6,"time":"2024-09-16T00:36:47.506548348+02:00","message":"Database is up to date"}            
{"level":"debug","time":"2024-09-16T00:36:47.507406401+02:00","message":"Starting appservice HTTP server"}                                                                                                         
{"level":"info","address":"127.0.0.1:29328","time":"2024-09-16T00:36:47.508167126+02:00","message":"Starting HTTP listener"}                                                                                       
{"level":"debug","time":"2024-09-16T00:36:47.508079549+02:00","message":"Checking connection to homeserver"}                                                                                                       
                                                                                                                                                                                                                   
==> /var/log/nginx/matrix.schuerz.at.access.log <==                                                                                                                                                                
195.201.0.0 - - [16/Sep/2024:00:36:47 +0200] "PUT /_matrix/federation/v1/send/1726209072774 HTTP/1.1" 200 21 "-" "Synapse/1.114.0"                                                                                 
127.0.0.0 - - [16/Sep/2024:00:36:47 +0200] "GET /_matrix/client/versions?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 343 "-" "mautrix-signal/0.7.0 mautrix-go/v0.20.0 go/1.22.6"                        
                                                                                                                                                                                                                   
==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"debug","req_id":1,"method":"GET","url":"https://matrix.schuerz.at/_matrix/client/versions?user_id=%40signalbotprimary%3Aschuerz.at","duration":70.489057,"status_code":200,"response_length":1038,"respon
se_mime":"application/json","time":"2024-09-16T00:36:47.581615867+02:00","message":"Request completed"}                                                                                                            
                                                                                                                                                                                                                   
==> /var/log/nginx/matrix.schuerz.at.access.log <==                                                                                                                                                                
127.0.0.0 - - [16/Sep/2024:00:36:47 +0200] "GET /_matrix/client/v3/account/whoami?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 79 "-" "mautrix-signal/0.7.0 mautrix-go/v0.20.0 go/1.22.6"                
                                                                                                                                                                                                                   
==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"debug","req_id":2,"method":"GET","url":"https://matrix.schuerz.at/_matrix/client/v3/account/whoami?user_id=%40signalbotprimary%3Aschuerz.at","duration":5.895273,"status_code":200,"response_length":59,"
response_mime":"application/json","time":"2024-09-16T00:36:47.59306271+02:00","message":"Request completed"}                                                                                                       
{"level":"debug","txn_id":"mautrix-go_1726439807594125239_1","time":"2024-09-16T00:36:47.603980866+02:00","message":"Received ping from homeserver"}                                                               
                                                                                                                                                                                                                   
==> /var/log/nginx/matrix.schuerz.at.access.log <==                                                                                                                                                                
127.0.0.0 - - [16/Sep/2024:00:36:47 +0200] "POST /_matrix/client/v1/appservice/signalprimary/ping?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 37 "-" "mautrix-signal/0.7.0 mautrix-go/v0.20.0 go/1.22.6"
                                                                                                                                                                                                                   
==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"debug","req_id":3,"method":"POST","url":"https://matrix.schuerz.at/_matrix/client/v1/appservice/signalprimary/ping?user_id=%40signalbotprimary%3Aschuerz.at","duration":15.041505,"status_code":200,"resp
onse_length":17,"response_mime":"application/json","req_body":{"transaction_id":"mautrix-go_1726439807594125239_1"},"time":"2024-09-16T00:36:47.610116456+02:00","message":"Request completed"}                    
{"level":"debug","txn_id":"mautrix-go_1726439807594125239_1","duration_ms":7,"time":"2024-09-16T00:36:47.613841687+02:00","message":"Homeserver -> bridge connection works"}                                       
{"level":"info","time":"2024-09-16T00:36:47.615676144+02:00","message":"Starting network connector"}                                                                                                               

{"level":"debug","time":"2024-09-16T00:36:47.616195125+02:00","message":"Updating bot profile"}                                                                                                           [50/9021]
                                                                                                                                                                                                                   
==> /var/log/nginx/matrix.schuerz.at.access.log <==                                                                                                                                                                
127.0.0.0 - - [16/Sep/2024:00:36:47 +0200] "GET /_matrix/client/v1/media/config?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 47 "-" "mautrix-signal/0.7.0 mautrix-go/v0.20.0 go/1.22.6"                  
                                                                                                                                                                                                                   
==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"debug","req_id":4,"method":"GET","url":"https://matrix.schuerz.at/_matrix/client/v1/media/config?user_id=%40signalbotprimary%3Aschuerz.at","duration":9.072697,"status_code":200,"response_length":27,"re
sponse_mime":"application/json","time":"2024-09-16T00:36:47.626288541+02:00","message":"Request completed"}                                                                                                        
                                                                                                                                                                                                                   
==> /var/log/nginx/matrix.schuerz.at.access.log <==                                                                                                                                                                
127.0.0.0 - - [16/Sep/2024:00:36:47 +0200] "GET /_matrix/client/v3/profile/@signalbotprimary:schuerz.at/avatar_url?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 22 "-" "mautrix-signal/0.7.0 mautrix-go/v
0.20.0 go/1.22.6"                                                                                                                                                                                                  
                                                                                                                                                                                                                   
==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"debug","req_id":5,"method":"GET","url":"https://matrix.schuerz.at/_matrix/client/v3/profile/@signalbotprimary:schuerz.at/avatar_url?user_id=%40signalbotprimary%3Aschuerz.at","duration":8.993293,"status
_code":200,"response_length":2,"response_mime":"application/json","time":"2024-09-16T00:36:47.642621702+02:00","message":"Request completed"}                                                                      
{"level":"info","db_section":"signalmeow","current_version":0,"oldest_compatible_version":0,"latest_known_version":16,"time":"2024-09-16T00:36:47.645249352+02:00","message":"Preparing to update database schema"}
{"level":"info","db_section":"signalmeow","from":0,"to":16,"txn_mode":"on","description":"Latest revision","time":"2024-09-16T00:36:47.64573986+02:00","message":"Upgrading database"}                             
{"level":"debug","req_id":6,"method":"GET","url":"https://matrix.schuerz.at/_matrix/client/v1/media/download/maunium.net/wPJgTQbZOtpBFmDNkiNEMDUp?user_id=%40signalbotprimary%3Aschuerz.at","duration":15.425526,"s
tatus_code":200,"response_length":-1,"response_mime":"image/png","time":"2024-09-16T00:36:47.658797817+02:00","message":"Request completed"}                                                                       
                                                                                                                                                                                                                   
==> /var/log/nginx/matrix.schuerz.at.access.log <==                                                                                                                                                                
127.0.0.0 - - [16/Sep/2024:00:36:47 +0200] "GET /_matrix/client/v1/media/download/maunium.net/wPJgTQbZOtpBFmDNkiNEMDUp?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 15516 "-" "mautrix-signal/0.7.0 mautr
ix-go/v0.20.0 go/1.22.6"                                                                                                                                                                                           
127.0.0.0 - - [16/Sep/2024:00:36:47 +0200] "PUT /_matrix/client/v3/profile/@signalbotprimary:schuerz.at/avatar_url?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 22 "-" "mautrix-signal/0.7.0 mautrix-go/v
0.20.0 go/1.22.6"                                                                                                                                                                                                  
                                                                                                                                                                                                                   
==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"debug","req_id":7,"method":"PUT","url":"https://matrix.schuerz.at/_matrix/client/v3/profile/@signalbotprimary:schuerz.at/avatar_url?user_id=%40signalbotprimary%3Aschuerz.at","duration":27.334574,"statu
s_code":200,"response_length":2,"response_mime":"application/json","req_body":{"avatar_url":"mxc://maunium.net/wPJgTQbZOtpBFmDNkiNEMDUp"},"time":"2024-09-16T00:36:47.687190471+02:00","message":"Request completed
"}                                                                                                                                                                                                                 
                                                                                                                                                                                                                   
==> /var/log/nginx/matrix.schuerz.at.access.log <==                                                                                                                                                                
127.0.0.0 - - [16/Sep/2024:00:36:47 +0200] "GET /_matrix/client/v3/profile/@signalbotprimary:schuerz.at/displayname?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 54 "-" "mautrix-signal/0.7.0 mautrix-go/
v0.20.0 go/1.22.6"                                                                                                                                                                                                 
                                                                                                                                                                                                                   
==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"debug","req_id":8,"method":"GET","url":"https://matrix.schuerz.at/_matrix/client/v3/profile/@signalbotprimary:schuerz.at/displayname?user_id=%40signalbotprimary%3Aschuerz.at","duration":8.701781,"statu
s_code":200,"response_length":34,"response_mime":"application/json","time":"2024-09-16T00:36:47.697612841+02:00","message":"Request completed"}                                                                    
                                                                                                                                                                                                                   
==> /var/log/nginx/matrix.schuerz.at.access.log <==                                                                                                                                                                
127.0.0.0 - - [16/Sep/2024:00:36:47 +0200] "PUT /_matrix/client/v3/profile/@signalbotprimary:schuerz.at/displayname?user_id=%40signalbotprimary%3Aschuerz.at HTTP/2.0" 200 22 "-" "mautrix-signal/0.7.0 mautrix-go/
v0.20.0 go/1.22.6"                                                                                                                                                                                                 
                                                                                                                                                                                                                   
==> /var/log/mautrix-signal/primary/mautrix-signal.log <==                                                                                                                                                         
{"level":"debug","req_id":9,"method":"PUT","url":"https://matrix.schuerz.at/_matrix/client/v3/profile/@signalbotprimary:schuerz.at/displayname?user_id=%40signalbotprimary%3Aschuerz.at","duration":19.697832,"stat
us_code":200,"response_length":2,"response_mime":"application/json","req_body":{"displayname":"Signal bridge bot (Primary)"},"time":"2024-09-16T00:36:47.71806175+02:00","message":"Request completed"}            
{"level":"debug","component":"disappear loop","time":"2024-09-16T00:36:47.939561258+02:00","message":"Disappearing message loop starting"}
{"level":"info","time":"2024-09-16T00:36:47.948030436+02:00","message":"No user logins found"}
{"level":"debug","bridge_state":{"state_event":"UNCONFIGURED","timestamp":1726439807,"ttl":21600,"source":"bridge"},"time":"2024-09-16T00:36:47.948668794+02:00","message":"Sent new global bridge state"}
{"level":"info","time":"2024-09-16T00:36:47.948848033+02:00","message":"Bridge started"}

Now the bridge starts!!

To Reproduce
Steps to reproduce the behavior:

1. setup a new mautrix-signal bridge with end2end encryption and double puppeting
2. start bridge
3. see error
4. deactivate e2ee and restart bridge
5. see bridge starting.

Expected behavior
A end2end-encrypted, double-puppeting mautrix-signal-bridge working with synapse an matrix-authentication-service.

Additional context
Add any other context about the problem here.

[xundeenergie]

Just found this information
https://github.com/element-hq/matrix-authentication-service/blob/main/docs/as-login.md

This is not good...