search

kamax-matrix / mxisd

Federated Matrix Identity Server
GNU Affero General Public License v3.0
223 stars 115 forks source link

test discovery fail #35

Closed ghost closed 7 years ago

ghost commented 7 years ago

Hi, I tried inviting mxisd-lookup-test@kamax.io to a room using my own server, aliased here as https://testing.com and failed. Inviting @mxisd-lookup-test:kamax.io works fine, so my Synapse is working fine.

Partial output from sudo systemctl status mxisd:

k.m.l.p.RemoteIdentityServerFetcher : Looking up email 3PID mxisd-lookup-test@kamax.io using https://kamax.io:443
 k.m.l.p.RemoteIdentityServerFetcher : Found 3PID mapping: {"address":"mxisd-lookup-test@kamax.io","medium":"email","mxid":"@mxisd-lookup-test:kamax.io","not_after":25340230079
i.k.m.invitation.InvitationManager : Mapping for email:mxisd-lookup-test@kamax.io already exists, refusing to store invite
i.k.m.c.DefaultExceptionHandler : Request POST http://127.0.0.1:8090/_matrix/identity/api/v1/store-invite - Error M_ALREADY_EXISTS: A mapping already exists for this 3PID
i.k.m.c.i.v1.MappingController : Got single lookup request from [my ip] with client Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) 
l.s.RecursivePriorityLookupStrategy : Host [my ip] allowed for recursion: false
i.k.m.c.i.v1.MappingController : No mapping was found, return empty JSON object
maxidorius commented 7 years ago

Please provide all the output from the moment you start inviting in Riot please. The log itself is in syslog or equivalent.

ghost commented 7 years ago

From journalctl: 

Oct 05 13:15:39 [my server] mxisd[18236]: .089 INFO [nio-8090-exec-2]  i.k.m.invitation.InvitationManager : Handling invite for email:mxisd-lookup-test@kamax.io from [my ID] in room !CREwlZ
Oct 05 13:15:39 [my server] mxisd[18236]: .089 INFO [nio-8090-exec-2] l.s.RecursivePriorityLookupStrategy : Host Internal allowed for recursion: true
Oct 05 13:15:39 [my server] mxisd[18236]: .089 INFO [nio-8090-exec-2]  i.k.m.l.provider.DnsLookupProvider : Performing DNS lookup for mxisd-lookup-test@kamax.io
Oct 05 13:15:39 [my server] mxisd[18236]: .089 INFO [nio-8090-exec-2]  i.k.m.l.provider.DnsLookupProvider : Domain name for mxisd-lookup-test@kamax.io: kamax.io
Oct 05 13:15:39 [my server] mxisd[18236]: .089 INFO [nio-8090-exec-2]    i.k.m.matrix.IdentityServerUtils : kamax.io is not an URL, using as-is
Oct 05 13:15:39 [my server] mxisd[18236]: .090 INFO [nio-8090-exec-2]    i.k.m.matrix.IdentityServerUtils : Discovery Identity Server for kamax.io
Oct 05 13:15:39 [my server] mxisd[18236]: .090 INFO [nio-8090-exec-2]    i.k.m.matrix.IdentityServerUtils : Performing SRV lookup
Oct 05 13:15:39 [my server] mxisd[18236]: .090 INFO [nio-8090-exec-2]    i.k.m.matrix.IdentityServerUtils : Lookup name: _matrix-identity._tcp.kamax.io
Oct 05 13:15:39 [my server] mxisd[18236]: .091 INFO [nio-8090-exec-2]    i.k.m.matrix.IdentityServerUtils : Record: _matrix-identity._tcp.kamax.io.        3599        IN        SRV        0 5 443 k
Oct 05 13:15:39 [my server] mxisd[18236]: .092 INFO [nio-8090-exec-2]    i.k.m.matrix.IdentityServerUtils : Found Identity Server for domain kamax.io at https://kamax.io:443
Oct 05 13:15:39 [my server] mxisd[18236]: .092 INFO [nio-8090-exec-2] k.m.l.p.RemoteIdentityServerFetcher : Looking up email 3PID mxisd-lookup-test@kamax.io using https://kamax.io:443
Oct 05 13:15:39 [my server] mxisd[18236]: .657 INFO [nio-8090-exec-2] k.m.l.p.RemoteIdentityServerFetcher : Found 3PID mapping: {"address":"mxisd-lookup-test@kamax.io","medium":"email","mxid":"@mxi
Oct 05 13:15:39 [my server] mxisd[18236]: .658 INFO [nio-8090-exec-2]  i.k.m.invitation.InvitationManager : Mapping for email:mxisd-lookup-test@kamax.io already exists, refusing to store invite
Oct 05 13:15:39 [my server] mxisd[18236]: .659 INFO [nio-8090-exec-2]     i.k.m.c.DefaultExceptionHandler : Request POST http://127.0.0.1:8090/_matrix/identity/api/v1/store-invite - Error M_ALREADY
Oct 05 13:15:39 [my server] python[18300]: 2017-10-05 13:15:39,666 - synapse.http.server - 139 - ERROR - POST-185- Failed handle request synapse.http.server._async_render on <synapse.rest.ClientRes
Oct 05 13:15:39 [my server] python[18300]: Traceback (most recent call last):
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/http/server.py", line 116, in wrapped_request_handler
Oct 05 13:15:39 [my server] python[18300]:     yield request_handler(self, request, request_metrics)
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
Oct 05 13:15:39 [my server] python[18300]:     result = result.throwExceptionIntoGenerator(g)
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
Oct 05 13:15:39 [my server] python[18300]:     return g.throw(self.type, self.value, self.tb)
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/http/server.py", line 255, in _async_render
Oct 05 13:15:39 [my server] python[18300]:     callback_return = yield callback(request, **kwargs)
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
Oct 05 13:15:39 [my server] python[18300]:     result = result.throwExceptionIntoGenerator(g)
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
Oct 05 13:15:39 [my server] python[18300]:     return g.throw(self.type, self.value, self.tb)
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/rest/client/v1/room.py", line 607, in on_POST
Oct 05 13:15:39 [my server] python[18300]:     txn_id
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
Oct 05 13:15:39 [my server] python[18300]:     result = result.throwExceptionIntoGenerator(g)
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
Oct 05 13:15:39 [my server] python[18300]:     return g.throw(self.type, self.value, self.tb)
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/handlers/room_member.py", line 516, in do_3pid_invite
Oct 05 13:15:39 [my server] python[18300]:     txn_id=txn_id
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
Oct 05 13:15:39 [my server] python[18300]:     result = result.throwExceptionIntoGenerator(g)
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
Oct 05 13:15:39 [my server] python[18300]:     return g.throw(self.type, self.value, self.tb)
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/handlers/room_member.py", line 622, in _make_and_store_3pid_invite
Oct 05 13:15:39 [my server] python[18300]:     inviter_avatar_url=inviter_avatar_url
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1299, in _inlineCallbacks
Oct 05 13:15:39 [my server] python[18300]:     result = g.send(result)
Oct 05 13:15:39 [my server] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/handlers/room_member.py", line 728, in _ask_id_server_for_third_party_invite
Oct 05 13:15:39 [my server] python[18300]:     token = data["token"]
Oct 05 13:15:39 [my server] python[18300]: KeyError: 'token'
maxidorius commented 7 years ago

Please use the code formating for the logs (I've done it for you) or it's very hard to read. So the logs you show me still only contain the last part of the invite. At this point synapse tries to create an invite, instead of inviting the Matrix ID, so the issue is before this.

ghost commented 7 years ago

Oh okay, I'm new to this, sorry.

This is what comes after I typed the lookup detail right before I hit the "Start Chat" button:

Oct 05 13:29:04 [my server] mxisd[18236]: .272 INFO [nio-8090-exec-8]      i.k.m.c.i.v1.MappingController : Got single lookup request from [my ip] with client Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) 
Oct 05 13:29:04 [my server] mxisd[18236]: .272 INFO [nio-8090-exec-8] l.s.RecursivePriorityLookupStrategy : Host [my ip] allowed for recursion: false
Oct 05 13:29:04 [my server] mxisd[18236]: .272 INFO [nio-8090-exec-8]      i.k.m.c.i.v1.MappingController : No mapping was found, return empty JSON object
maxidorius commented 7 years ago

Inviting by e-mail using "Start Chat" is buggy in Riot, you should first create a room, then try to invite.

As for the logs, I would need everything from the moment you opened the "invite" room up to the failure please.

ghost commented 7 years ago

Okay, I created a room before inviting, and got this:

Traceback (most recent call last):
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/http/server.py", line 116, in wrapped_request_handler
Oct 05 13:36:02 [my hostname] python[18300]:     yield request_handler(self, request, request_metrics)
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
Oct 05 13:36:02 [my hostname] python[18300]:     result = result.throwExceptionIntoGenerator(g)
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
Oct 05 13:36:02 [my hostname] python[18300]:     return g.throw(self.type, self.value, self.tb)
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/http/server.py", line 255, in _async_render
Oct 05 13:36:02 [my hostname] python[18300]:     callback_return = yield callback(request, **kwargs)
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
Oct 05 13:36:02 [my hostname] python[18300]:     result = result.throwExceptionIntoGenerator(g)
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
Oct 05 13:36:02 [my hostname] python[18300]:     return g.throw(self.type, self.value, self.tb)
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/rest/client/v1/room.py", line 607, in on_POST
Oct 05 13:36:02 [my hostname] python[18300]:     txn_id
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
Oct 05 13:36:02 [my hostname] python[18300]:     result = result.throwExceptionIntoGenerator(g)
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
Oct 05 13:36:02 [my hostname] python[18300]:     return g.throw(self.type, self.value, self.tb)
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/handlers/room_member.py", line 516, in do_3pid_invite
Oct 05 13:36:02 [my hostname] python[18300]:     txn_id=txn_id
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
Oct 05 13:36:02 [my hostname] python[18300]:     result = result.throwExceptionIntoGenerator(g)
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
Oct 05 13:36:02 [my hostname] python[18300]:     return g.throw(self.type, self.value, self.tb)
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/handlers/room_member.py", line 622, in _make_and_store_3pid_invite
Oct 05 13:36:02 [my hostname] python[18300]:     inviter_avatar_url=inviter_avatar_url
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1299, in _inlineCallbacks
Oct 05 13:36:02 [my hostname] python[18300]:     result = g.send(result)
Oct 05 13:36:02 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/handlers/room_member.py", line 728, in _ask_id_server_for_third_party_invite
Oct 05 13:36:02 [my hostname] python[18300]:     token = data["token"]
Oct 05 13:36:02 [my hostname] python[18300]: KeyError: 'token'
maxidorius commented 7 years ago

Please show me the full log involving the invite, not part of it. If you're not sure what to give, restart mxisd before performing the invite then include everything from the start of it.

ghost commented 7 years ago

Restarted mxisd service and this is from the beginning:

Oct 05 13:41:15 [my hostname] systemd[1]: Started mxisd.
Oct 05 13:41:16 [my hostname] mxisd[18478]: .840 INFO [           main] k.m.MatrixIdentityServerApplication : Starting MatrixIdentityServerApplication on [my hostname] with PID 18496 (/usr/lib/mxisd/mxisd.jar started by mxisd in /usr/lib/mxisd)
Oct 05 13:41:16 [my hostname] mxisd[18478]: .845 INFO [           main] k.m.MatrixIdentityServerApplication : The following profiles are active: systemd
Oct 05 13:41:19 [my hostname] mxisd[18478]: .526 INFO [           main]       i.k.m.c.t.c.PhoneTwilioConfig : --- Phone SMS Twilio connector config ---
Oct 05 13:41:19 [my hostname] mxisd[18478]: .526 INFO [           main]       i.k.m.c.t.c.PhoneTwilioConfig : Account SID:
Oct 05 13:41:19 [my hostname] mxisd[18478]: .528 INFO [           main]       i.k.m.c.t.c.PhoneTwilioConfig : Sender number:
Oct 05 13:41:19 [my hostname] mxisd[18478]: .529 INFO [           main] i.k.m.t.c.p.PhoneSmsTwilioConnector : Twilio API has been initiated
Oct 05 13:41:19 [my hostname] mxisd[18478]: .549 INFO [           main]         i.k.m.c.t.c.EmailSmtpConfig : --- E-mail SMTP Connector config ---
Oct 05 13:41:19 [my hostname] mxisd[18478]: .550 INFO [           main]         i.k.m.c.t.c.EmailSmtpConfig : Host: smtp.example.org
Oct 05 13:41:19 [my hostname] mxisd[18478]: .550 INFO [           main]         i.k.m.c.t.c.EmailSmtpConfig : Port: 587
Oct 05 13:41:19 [my hostname] mxisd[18478]: .550 INFO [           main]         i.k.m.c.t.c.EmailSmtpConfig : TLS Mode: 1
Oct 05 13:41:19 [my hostname] mxisd[18478]: .550 INFO [           main]         i.k.m.c.t.c.EmailSmtpConfig : Login: matrix-identity@example.org
Oct 05 13:41:19 [my hostname] mxisd[18478]: .553 INFO [           main]         i.k.m.c.t.c.EmailSmtpConfig : Has password: true
Oct 05 13:41:19 [my hostname] mxisd[18478]: .584 INFO [           main]  io.kamax.mxisd.config.MatrixConfig : --- Matrix config ---
Oct 05 13:41:19 [my hostname] mxisd[18478]: .584 INFO [           main]  io.kamax.mxisd.config.MatrixConfig : Domain: [my server]
Oct 05 13:41:19 [my hostname] mxisd[18478]: .584 INFO [           main]  io.kamax.mxisd.config.MatrixConfig : Identity:
Oct 05 13:41:19 [my hostname] mxisd[18478]: .589 INFO [           main]  io.kamax.mxisd.config.MatrixConfig :         Servers: {"root":["https://matrix.org"]}
Oct 05 13:41:19 [my hostname] mxisd[18478]: .603 INFO [           main]  io.kamax.mxisd.config.ServerConfig : --- Server config ---
Oct 05 13:41:19 [my hostname] mxisd[18478]: .605 INFO [           main]  io.kamax.mxisd.config.ServerConfig : Name: [my server]
Oct 05 13:41:19 [my hostname] mxisd[18478]: .605 INFO [           main]  io.kamax.mxisd.config.ServerConfig : Port: 8090
Oct 05 13:41:19 [my hostname] mxisd[18478]: .605 INFO [           main]  io.kamax.mxisd.config.ServerConfig : Public URL: https://[my server]
Oct 05 13:41:19 [my hostname] mxisd[18478]: .648 INFO [           main]     i.k.m.c.t.c.EmailSendGridConfig : --- Email SendGrid connector config ---
Oct 05 13:41:19 [my hostname] mxisd[18478]: .648 INFO [           main]     i.k.m.c.t.c.EmailSendGridConfig : API key configured?: false
Oct 05 13:41:19 [my hostname] mxisd[18478]: .652 INFO [           main]     i.k.m.c.t.c.EmailSendGridConfig : Identity: {"from":"","name":""}
Oct 05 13:41:19 [my hostname] mxisd[18478]: .653 INFO [           main]     i.k.m.c.t.c.EmailSendGridConfig : Templates: {"invite":{"subject":"","body":{"text":"","html":""}},"session":{"local":{"body":{}},"remote":{"body":{}}}}
Oct 05 13:41:19 [my hostname] mxisd[18478]: .903 INFO [           main]     i.k.m.c.t.m.EmailTemplateConfig : --- SMS Generator templates config ---
Oct 05 13:41:19 [my hostname] mxisd[18478]: .903 INFO [           main]     i.k.m.c.t.m.EmailTemplateConfig : Invite: Built-in (threepids/sms/invite-template.txt)
Oct 05 13:41:19 [my hostname] mxisd[18478]: .904 INFO [           main]     i.k.m.c.t.m.EmailTemplateConfig : Session validation:
Oct 05 13:41:19 [my hostname] mxisd[18478]: .904 INFO [           main]     i.k.m.c.t.m.EmailTemplateConfig :         Local: Built-in (threepids/sms/validate-local-template.txt)
Oct 05 13:41:19 [my hostname] mxisd[18478]: .904 INFO [           main]     i.k.m.c.t.m.EmailTemplateConfig :         Remote: Built-in (threepids/sms/validate-remote-template.txt)
Oct 05 13:41:19 [my hostname] mxisd[18478]: .926 INFO [           main]        i.k.m.c.t.medium.PhoneConfig : --- Phone config ---
Oct 05 13:41:19 [my hostname] mxisd[18478]: .926 INFO [           main]        i.k.m.c.t.medium.PhoneConfig : Generator: template
Oct 05 13:41:19 [my hostname] mxisd[18478]: .926 INFO [           main]        i.k.m.c.t.medium.PhoneConfig : Connector: twilio
Oct 05 13:41:19 [my hostname] mxisd[18478]: .954 INFO [           main]     i.k.m.c.t.m.EmailTemplateConfig : --- E-mail Generator templates config ---
Oct 05 13:41:19 [my hostname] mxisd[18478]: .955 INFO [           main]     i.k.m.c.t.m.EmailTemplateConfig : Invite: Built-in (threepids/email/invite-template.eml)
Oct 05 13:41:19 [my hostname] mxisd[18478]: .955 INFO [           main]     i.k.m.c.t.m.EmailTemplateConfig : Session validation:
Oct 05 13:41:19 [my hostname] mxisd[18478]: .955 INFO [           main]     i.k.m.c.t.m.EmailTemplateConfig :         Local: Built-in (threepids/email/validate-local-template.eml)
Oct 05 13:41:19 [my hostname] mxisd[18478]: .955 INFO [           main]     i.k.m.c.t.m.EmailTemplateConfig :         Remote: Built-in (threepids/email/validate-remote-template.eml)
Oct 05 13:41:19 [my hostname] mxisd[18478]: .977 INFO [           main]        i.k.m.c.t.medium.EmailConfig : --- E-mail config ---
Oct 05 13:41:19 [my hostname] mxisd[18478]: .977 INFO [           main]        i.k.m.c.t.medium.EmailConfig : From: matrix-identity@example.org
Oct 05 13:41:19 [my hostname] mxisd[18478]: .978 INFO [           main]        i.k.m.c.t.medium.EmailConfig : Name: [my server] Identity Server
Oct 05 13:41:19 [my hostname] mxisd[18478]: .979 INFO [           main]        i.k.m.c.t.medium.EmailConfig : Generator: template
Oct 05 13:41:19 [my hostname] mxisd[18478]: .979 INFO [           main]        i.k.m.c.t.medium.EmailConfig : Connector: smtp
Oct 05 13:41:20 [my hostname] mxisd[18478]: .015 INFO [           main]  i.kamax.mxisd.config.SessionConfig : --- Session config ---
Oct 05 13:41:20 [my hostname] mxisd[18478]: .017 INFO [           main]  i.kamax.mxisd.config.SessionConfig : Global Policy: {"validation":{"enabled":true,"forLocal":{"enabled":true,"toLocal":true,"toRemote":{"enabled":true,"server":"root"}},"forR
Oct 05 13:41:20 [my hostname] mxisd[18478]: .030 INFO [           main]      i.k.m.c.t.n.NotificationConfig : --- Notification config ---
Oct 05 13:41:20 [my hostname] mxisd[18478]: .030 INFO [           main]      i.k.m.c.t.n.NotificationConfig : Handlers:
Oct 05 13:41:20 [my hostname] mxisd[18478]: .065 INFO [           main]  i.kamax.mxisd.config.sql.SqlConfig : --- Synapse SQL Provider config ---
Oct 05 13:41:20 [my hostname] mxisd[18478]: .066 INFO [           main]  i.kamax.mxisd.config.sql.SqlConfig : Enabled: false
Oct 05 13:41:20 [my hostname] mxisd[18478]: .090 INFO [           main]  i.kamax.mxisd.config.sql.SqlConfig : --- Generic SQL Provider config ---
Oct 05 13:41:20 [my hostname] mxisd[18478]: .091 INFO [           main]  i.kamax.mxisd.config.sql.SqlConfig : Enabled: false
Oct 05 13:41:20 [my hostname] mxisd[18478]: .106 INFO [           main]      i.k.m.c.rest.RestBackendConfig : --- REST backend config ---
Oct 05 13:41:20 [my hostname] mxisd[18478]: .107 INFO [           main]      i.k.m.c.rest.RestBackendConfig : Enabled: false
Oct 05 13:41:20 [my hostname] mxisd[18478]: .132 INFO [           main]    io.kamax.mxisd.config.ViewConfig : --- View config ---
Oct 05 13:41:20 [my hostname] mxisd[18478]: .133 INFO [           main]    io.kamax.mxisd.config.ViewConfig : Session: {"local":{"onTokenSubmit":{"failure":"session/local/tokenSubmitFailure","success":"session/local/tokenSubmitSuccess"}},"localRem
Oct 05 13:41:20 [my hostname] mxisd[18478]: .142 INFO [           main]     i.k.m.config.DnsOverwriteConfig : --- DNS Overwrite config ---
Oct 05 13:41:20 [my hostname] mxisd[18478]: .143 INFO [           main]     i.k.m.config.DnsOverwriteConfig : Homeserver:
Oct 05 13:41:20 [my hostname] mxisd[18478]: .143 INFO [           main]     i.k.m.config.DnsOverwriteConfig :         Client: []
Oct 05 13:41:20 [my hostname] mxisd[18478]: .144 INFO [           main]     i.k.m.config.DnsOverwriteConfig :         Federation: []
Oct 05 13:41:20 [my hostname] mxisd[18478]: .156 INFO [           main]     i.k.mxisd.config.FirebaseConfig : --- Firebase configuration ---
Oct 05 13:41:20 [my hostname] mxisd[18478]: .156 INFO [           main]     i.k.mxisd.config.FirebaseConfig : Enabled: false
Oct 05 13:41:20 [my hostname] mxisd[18478]: .169 INFO [           main] i.k.m.c.RecursiveLookupBridgeConfig : --- Bridge integration lookups config ---
Oct 05 13:41:20 [my hostname] mxisd[18478]: .169 INFO [           main] i.k.m.c.RecursiveLookupBridgeConfig : Enabled: false
Oct 05 13:41:20 [my hostname] mxisd[18478]: .212 INFO [           main]    i.k.mxisd.config.ldap.LdapConfig : --- LDAP Config ---
Oct 05 13:41:20 [my hostname] mxisd[18478]: .213 INFO [           main]    i.k.mxisd.config.ldap.LdapConfig : Enabled: false
Oct 05 13:41:20 [my hostname] mxisd[18478]: .302 INFO [           main]         i.k.m.n.NotificationManager : Found handler sendgrid for medium email
Oct 05 13:41:20 [my hostname] mxisd[18478]: .302 INFO [           main]         i.k.m.n.NotificationManager : Found handler raw for medium msisdn
Oct 05 13:41:20 [my hostname] mxisd[18478]: .303 INFO [           main]         i.k.m.n.NotificationManager : Found handler raw for medium email
Oct 05 13:41:20 [my hostname] mxisd[18478]: .303 INFO [           main]         i.k.m.n.NotificationManager : --- Notification handler ---
Oct 05 13:41:20 [my hostname] mxisd[18478]: .304 INFO [           main]         i.k.m.n.NotificationManager :         Handler for msisdn: raw
Oct 05 13:41:20 [my hostname] mxisd[18478]: .304 INFO [           main]         i.k.m.n.NotificationManager :         Handler for email: raw
Oct 05 13:41:20 [my hostname] mxisd[18478]: .374 INFO [           main]   com.j256.ormlite.table.TableUtils : creating table 'invite_3pid'
Oct 05 13:41:20 [my hostname] mxisd[18478]: .545 INFO [           main]   com.j256.ormlite.table.TableUtils : executed create table statement changed 0 rows: CREATE TABLE IF NOT EXISTS `invite_3pid` (`id` VARCHAR , `token` VARCHAR NOT NULL , `send
Oct 05 13:41:20 [my hostname] mxisd[18478]: .548 INFO [           main]   com.j256.ormlite.table.TableUtils : creating table 'session_3pid'
Oct 05 13:41:20 [my hostname] mxisd[18478]: .549 INFO [           main]   com.j256.ormlite.table.TableUtils : executed create table statement changed 0 rows: CREATE TABLE IF NOT EXISTS `session_3pid` (`id` VARCHAR , `creationTime` BIGINT NOT NULL 
Oct 05 13:41:20 [my hostname] mxisd[18478]: .590 INFO [g-Init-Reporter]             com.mchange.v2.log.MLog : MLog clients using slf4j logging.
Oct 05 13:41:20 [my hostname] mxisd[18478]: .631 INFO [           main]    com.mchange.v2.c3p0.C3P0Registry : Initializing c3p0-0.9.5.2 [built 08-December-2015 22:06:04 -0800; debug? true; trace: 10]
Oct 05 13:41:20 [my hostname] mxisd[18478]: .712 INFO [           main] l.s.RecursivePriorityLookupStrategy : Found 2 providers
Oct 05 13:41:20 [my hostname] mxisd[18478]: .713 INFO [           main] l.s.RecursivePriorityLookupStrategy :         - io.kamax.mxisd.lookup.provider.DnsLookupProvider
Oct 05 13:41:20 [my hostname] mxisd[18478]: .713 INFO [           main] l.s.RecursivePriorityLookupStrategy :         - io.kamax.mxisd.lookup.provider.ForwarderProvider
Oct 05 13:41:20 [my hostname] mxisd[18478]: .714 INFO [           main] l.s.RecursivePriorityLookupStrategy : Recursive lookup enabled: true
Oct 05 13:41:20 [my hostname] mxisd[18478]: .714 INFO [           main] l.s.RecursivePriorityLookupStrategy : 127.0.0.0/8 is allowed for recursion
Oct 05 13:41:20 [my hostname] mxisd[18478]: .715 INFO [           main] l.s.RecursivePriorityLookupStrategy : 10.0.0.0/8 is allowed for recursion
Oct 05 13:41:20 [my hostname] mxisd[18478]: .716 INFO [           main] l.s.RecursivePriorityLookupStrategy : 172.16.0.0/12 is allowed for recursion
Oct 05 13:41:20 [my hostname] mxisd[18478]: .716 INFO [           main] l.s.RecursivePriorityLookupStrategy : 192.168.0.0/16 is allowed for recursion
Oct 05 13:41:20 [my hostname] mxisd[18478]: .716 INFO [           main] l.s.RecursivePriorityLookupStrategy : ::1/128 is allowed for recursion
Oct 05 13:41:20 [my hostname] mxisd[18478]: .766 INFO [           main]  i.k.m.invitation.InvitationManager : Loading saved invites
Oct 05 13:41:20 [my hostname] mxisd[18478]: .781 INFO [           main]  i.k.m.invitation.InvitationManager : Setting up invitation mapping refresh timer
Oct 05 13:41:20 [my hostname] mxisd[18478]: .871 INFO [           main]    i.k.m.directory.DirectoryManager : Directory providers:
Oct 05 13:41:22 [my hostname] mxisd[18478]: .077 INFO [           main] k.m.MatrixIdentityServerApplication : Started MatrixIdentityServerApplication in 5.913 seconds (JVM running for 6.451)
Oct 05 13:41:28 [my hostname] sudo[18512]: pam_unix(sudo:session): session closed for user root
Oct 05 13:41:38 [my hostname] mxisd[18478]: .507 INFO [nio-8090-exec-1]      i.k.m.c.i.v1.MappingController : Got single lookup request from [client IP] with client Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) 
Oct 05 13:41:38 [my hostname] mxisd[18478]: .508 INFO [nio-8090-exec-1] l.s.RecursivePriorityLookupStrategy : Host [client IP] allowed for recursion: false
Oct 05 13:41:38 [my hostname] mxisd[18478]: .508 INFO [nio-8090-exec-1]      i.k.m.c.i.v1.MappingController : No mapping was found, return empty JSON object
Oct 05 13:41:41 [my hostname] mxisd[18478]: .379 INFO [nio-8090-exec-2]      i.k.m.c.i.v1.MappingController : Got single lookup request from [my IP] with client Synapse/0.23.0 - Is recursive? false
Oct 05 13:41:41 [my hostname] mxisd[18478]: .380 INFO [nio-8090-exec-2] l.s.RecursivePriorityLookupStrategy : Host [my IP] allowed for recursion: false
Oct 05 13:41:41 [my hostname] mxisd[18478]: .380 INFO [nio-8090-exec-2]      i.k.m.c.i.v1.MappingController : No mapping was found, return empty JSON object
Oct 05 13:41:41 [my hostname] mxisd[18478]: .420 INFO [nio-8090-exec-3]  i.k.m.invitation.InvitationManager : Handling invite for email:mxisd-lookup-test@kamax.io from @sgoh:[my server] in room !piIQptXDFnLYTiwxHK:[my server]
Oct 05 13:41:41 [my hostname] mxisd[18478]: .421 INFO [nio-8090-exec-3] l.s.RecursivePriorityLookupStrategy : Host Internal allowed for recursion: true
Oct 05 13:41:41 [my hostname] mxisd[18478]: .421 INFO [nio-8090-exec-3]  i.k.m.l.provider.DnsLookupProvider : Performing DNS lookup for mxisd-lookup-test@kamax.io
Oct 05 13:41:41 [my hostname] mxisd[18478]: .421 INFO [nio-8090-exec-3]  i.k.m.l.provider.DnsLookupProvider : Domain name for mxisd-lookup-test@kamax.io: kamax.io
Oct 05 13:41:41 [my hostname] mxisd[18478]: .423 INFO [nio-8090-exec-3]    i.k.m.matrix.IdentityServerUtils : kamax.io is not an URL, using as-is
Oct 05 13:41:41 [my hostname] mxisd[18478]: .423 INFO [nio-8090-exec-3]    i.k.m.matrix.IdentityServerUtils : Discovery Identity Server for kamax.io
Oct 05 13:41:41 [my hostname] mxisd[18478]: .423 INFO [nio-8090-exec-3]    i.k.m.matrix.IdentityServerUtils : Performing SRV lookup
Oct 05 13:41:41 [my hostname] mxisd[18478]: .423 INFO [nio-8090-exec-3]    i.k.m.matrix.IdentityServerUtils : Lookup name: _matrix-identity._tcp.kamax.io
Oct 05 13:41:41 [my hostname] mxisd[18478]: .499 INFO [nio-8090-exec-3]    i.k.m.matrix.IdentityServerUtils : Record: _matrix-identity._tcp.kamax.io.        344        IN        SRV        0 5 443 kamax.io.
Oct 05 13:41:41 [my hostname] mxisd[18478]: .501 INFO [nio-8090-exec-3]    i.k.m.matrix.IdentityServerUtils : Found Identity Server for domain kamax.io at https://kamax.io:443
Oct 05 13:41:41 [my hostname] mxisd[18478]: .501 INFO [nio-8090-exec-3] k.m.l.p.RemoteIdentityServerFetcher : Looking up email 3PID mxisd-lookup-test@kamax.io using https://kamax.io:443
Oct 05 13:41:42 [my hostname] mxisd[18478]: .085 INFO [nio-8090-exec-3] k.m.l.p.RemoteIdentityServerFetcher : Found 3PID mapping: {"address":"mxisd-lookup-test@kamax.io","medium":"email","mxid":"@mxisd-lookup-test:kamax.io","not_after":25340230079
Oct 05 13:41:42 [my hostname] mxisd[18478]: .087 INFO [nio-8090-exec-3]  i.k.m.invitation.InvitationManager : Mapping for email:mxisd-lookup-test@kamax.io already exists, refusing to store invite
Oct 05 13:41:42 [my hostname] mxisd[18478]: .090 INFO [nio-8090-exec-3]     i.k.m.c.DefaultExceptionHandler : Request POST http://127.0.0.1:8090/_matrix/identity/api/v1/store-invite - Error M_ALREADY_EXISTS: A mapping already exists for this 3PID
Oct 05 13:41:42 [my hostname] python[18300]: 2017-10-05 13:41:42,093 - synapse.http.server - 139 - ERROR - POST-345- Failed handle request synapse.http.server._async_render on <synapse.rest.ClientRestResource object at 0x7f854cf0ad90>: <SynapseReq
Oct 05 13:41:42 [my hostname] python[18300]: Traceback (most recent call last):
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/http/server.py", line 116, in wrapped_request_handler
Oct 05 13:41:42 [my hostname] python[18300]:     yield request_handler(self, request, request_metrics)
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
Oct 05 13:41:42 [my hostname] python[18300]:     result = result.throwExceptionIntoGenerator(g)
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
Oct 05 13:41:42 [my hostname] python[18300]:     return g.throw(self.type, self.value, self.tb)
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/http/server.py", line 255, in _async_render
Oct 05 13:41:42 [my hostname] python[18300]:     callback_return = yield callback(request, **kwargs)
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
Oct 05 13:41:42 [my hostname] python[18300]:     result = result.throwExceptionIntoGenerator(g)
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
Oct 05 13:41:42 [my hostname] python[18300]:     return g.throw(self.type, self.value, self.tb)
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/rest/client/v1/room.py", line 607, in on_POST
Oct 05 13:41:42 [my hostname] python[18300]:     txn_id
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
Oct 05 13:41:42 [my hostname] python[18300]:     result = result.throwExceptionIntoGenerator(g)
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
Oct 05 13:41:42 [my hostname] python[18300]:     return g.throw(self.type, self.value, self.tb)
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/handlers/room_member.py", line 516, in do_3pid_invite
Oct 05 13:41:42 [my hostname] python[18300]:     txn_id=txn_id
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1297, in _inlineCallbacks
Oct 05 13:41:42 [my hostname] python[18300]:     result = result.throwExceptionIntoGenerator(g)
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
Oct 05 13:41:42 [my hostname] python[18300]:     return g.throw(self.type, self.value, self.tb)
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/handlers/room_member.py", line 622, in _make_and_store_3pid_invite
Oct 05 13:41:42 [my hostname] python[18300]:     inviter_avatar_url=inviter_avatar_url
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1299, in _inlineCallbacks
Oct 05 13:41:42 [my hostname] python[18300]:     result = g.send(result)
Oct 05 13:41:42 [my hostname] python[18300]:   File "/usr/lib/python2.7/dist-packages/synapse/handlers/room_member.py", line 728, in _ask_id_server_for_third_party_invite
Oct 05 13:41:42 [my hostname] python[18300]:     token = data["token"]
Oct 05 13:41:42 [my hostname] python[18300]: KeyError: 'token'

Thanks a lot for working with me, I'm new to all this and it's used to circumvent censorship.

maxidorius commented 7 years ago

Since you're masking the IPs, I can't tell for sure, but my guess is that your homeserver is using some public IP to connect to mxisd, which is by default limited in terms of lookup. Only private IPs (10...., 172.16... 192.168.... etc.) can do recursive lookups to limite abuse.

If that's the case, you will need to provide a custom list of CIDR which are allowed to do recursive lookups by adding the following to your config file:

lookup:
  recursive:
    allowedCidr:
      - 'publicIpOfYourHomeserver/32'

If this work, you might want to consider adding back the default entries just after your HS entry. You would end up with something like this:

lookup:
  recursive:
    allowedCidr:
      - 'publicIpOfYourHomeserver/32'
      - '127.0.0.0/8'
      - '10.0.0.0/8'
      - '172.16.0.0/12'
      - '192.168.0.0/16'
      - '::1/128'
ghost commented 7 years ago

provide a custom list of CIDR adding back the default entries just after your HS entry

That worked! Thanks a lot, hope others find this useful too.

maxidorius commented 7 years ago

Yay! Now I'll think how to turn this into good documentation :)