Not working with latest Synapse

[UAnton]

Hi,
every time get error:

2022-01-18 22:11:46,919 - synapse.app.homeserver - 171 - INFO - sentinel - Synapse now listening on TCP port 8008
2022-01-18 22:11:47,002 - synapse.storage.background_updates - 264 - INFO - background_updates-0 - Starting background schema updates
2022-01-18 22:11:47,003 - synapse.handlers.deactivate_account - 215 - INFO - user_parter_loop-0 - User parter finished: stopping
2022-01-18 22:11:47,004 - synapse.push.pusherpool - 314 - INFO - start_pushers-0 - Started pushers
2022-01-18 22:11:47,006 - synapse.storage.background_updates - 272 - INFO - background_updates-0 - No more background updates to do. Unscheduling background update task.
2022-01-18 22:11:52,131 - synapse.http.site - 507 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
2022-01-18 22:11:52,134 - synapse.rest.client.login - 278 - INFO - POST-0 - Got login request with identifier: {'type': 'm.id.user', 'user': 'ldap'}, medium: None, address: None, user: None
2022-01-18 22:11:52,140 - ldap_auth_provider - 588 - INFO - sentinel - LDAP search returned no results for '[('sAMAccountName', 'ldap')]'
2022-01-18 22:11:52,141 - synapse.handlers.auth - 2177 - WARNING - sentinel - Wrong type returned by module API callback <function load_single_legacy_password_auth_provider.<locals>.async_wrapper.<locals>.wrapped_check_auth at 0x7fc41f372af0>: False, expected Optional[Tuple[str, Optional[Callable]]]
2022-01-18 22:11:52,141 - synapse.storage.database - 737 - WARNING - sentinel - Starting db txn 'get_users_by_id_case_insensitive' from sentinel context
2022-01-18 22:11:52,141 - synapse.storage.database - 785 - WARNING - sentinel - Starting db connection from sentinel context: metrics will be lost
2022-01-18 22:11:52,142 - synapse.handlers.auth - 1037 - WARNING - sentinel - Attempted to login as @ldap:matrix.service-asdf.com but they do not exist
2022-01-18 22:11:52,142 - synapse.http.server - 95 - INFO - sentinel - <XForwardedForRequest at 0x7fc4253b13a0 method='POST' uri='/_matrix/client/r0/login' clientproto='HTTP/1.0' site='8008'> SynapseError: 403 - Invalid password
2022-01-18 22:11:52,142 - synapse.logging.context - 948 - WARNING - sentinel - Calling defer_to_threadpool from sentinel context: metrics will be lost

[reivilibre]

Hi!
Please can you give some more details? — are you sure the password is correct?

2022-01-18 22:11:52,141 - synapse.handlers.auth - 2177 - WARNING - sentinel - Wrong type returned by module API callback <function load_single_legacy_password_auth_provider.<locals>.async_wrapper.<locals>.wrapped_check_auth at 0x7fc41f372af0>: False, expected Optional[Tuple[str, Optional[Callable]]]

This error is expected but harmless (it's being fixed in the next version of the module) — if you see this, then login failed . As you can see,

LDAP search returned no results for '[('sAMAccountName', 'ldap')]'

says that no results were found in LDAP.

It's hard to diagnose anything but it sounds like the module itself is working fine (though perhaps it's not been configured to search LDAP correctly),

Was this setup working before? Has anything changed that might have caused it to break?

[Half-Shot]

We've just seen this in EMS land too, ftr.

[reivilibre]

We've just seen this in EMS land too, ftr.

(I believe this refers only to the warning, after a message or two out of band)

[mightymop]

I had installed the latest synapse and ldap addon too and could not login via ldap
Server: Raspi 4
LDAP Server: Windows Server 2012 R2
Client: Riot Webclient (https://riot.im/app/#/login)

login via local created users works, but not for ldap users

config:

password_providers:
 - module: "ldap_auth_provider.LdapAuthProvider"
   config:
     enabled: true
     uri:
        - "ldap://192.168.178.220:389"
     start_tls: false
     mode: "search"
     #mode: "simple"
     base: "dc=poldom,dc=local"
     # active_directory: true
     # Optional. Users from this domain may log in without specifying the domain part
     # default_domain: poldom.local
     attributes:
        uid: "sAMAccountName"
        mail: "mail"
        name: "displayName"
     bind_dn: CN=ldapservice2,CN=Users,DC=poldom,DC=local
     bind_password: Pa$$w0rd
     filter: "(&(objectClass=user)(mail=*@poldom.local))"
     #tls_options:
     #  validate: true
     #  local_certificate_file: foo.crt
     #  local_private_key_file: bar.pem
     #  local_private_key_password: secret

logs:

2022-02-14 13:55:50,595 - synapse.access.https.8448 - 427 - INFO - POST-15 - 5.28.74.210 - 8448 - {None} Processed request: 2.079sec/0.003sec (0.006sec, 0.000sec) (0.000sec/0.000sec/0) 52B 403 "POST /_matrix/client/r0/login HTTP/1.1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.87 Safari/537.36" [0 dbevts]
2022-02-14 13:58:24,730 - synapse.storage.databases.main.metrics - 471 - INFO - generate_user_daily_visits-0 - Calling _generate_user_daily_visits
2022-02-14 13:59:08,872 - synapse.rest.client.login - 278 - INFO - POST-17 - Got login request with identifier: {'type': 'm.id.user', 'user': 'USERNAME'}, medium: None, address: None, user: None
2022-02-14 13:59:08,873 - ldap_auth_provider - 107 - DEBUG - POST-17 - Attempting LDAP connection with ['ldap://192.168.178.220:389']
2022-02-14 13:59:08,875 - ldap_auth_provider - 471 - DEBUG - sentinel - Established LDAP connection in simple bind mode: ldap://192.168.178.220:389 - cleartext - user: CN=ldapservice2,CN=Users,DC=poldom,DC=local - not lazy - unbound - closed - <no socket> - tls not started - not listening - SyncStrategy - internal decoder
2022-02-14 13:59:09,018 - ldap_auth_provider - 487 - DEBUG - sentinel - LDAP Bind successful in simple bind mode.
2022-02-14 13:59:09,018 - ldap_auth_provider - 549 - DEBUG - sentinel - LDAP search filter: (&(sAMAccountName=USERNAME)(&(objectClass=user)(mail=*@poldom.local)))
2022-02-14 13:59:09,083 - ldap_auth_provider - 574 - DEBUG - sentinel - LDAP search found dn: CN=USER,CN=Users,DC=poldom,DC=local
2022-02-14 13:59:09,087 - ldap_auth_provider - 471 - DEBUG - sentinel - Established LDAP connection in simple bind mode: ldap://192.168.178.220:389 - cleartext - user: CN=USER,CN=Users,DC=poldom,DC=local - not lazy - bound - open - <local: 192.168.1.3:36879 - remote: 192.168.178.220:389> - tls not started - listening - SyncStrategy - internal decoder
2022-02-14 13:59:09,275 - ldap_auth_provider - 487 - DEBUG - sentinel - LDAP Bind successful in simple bind mode.
2022-02-14 13:59:09,279 - ldap_auth_provider - 134 - DEBUG - sentinel - LDAP auth method authenticated search returned: True (conn: ldap://192.168.178.220:389 - cleartext - user: CN=USER,CN=Users,DC=poldom,DC=local - not lazy - bound - open - <local: 192.168.1.3:36879 - remote: 192.168.178.220:389> - tls not started - listening - SyncStrategy - internal decoder)
2022-02-14 13:59:09,279 - ldap_auth_provider - 150 - INFO - sentinel - User authenticated against LDAP server: ldap://192.168.178.220:389 - cleartext - user: CN=USER,CN=Users,DC=poldom,DC=local - not lazy - bound - open - <local: 192.168.1.3:36879 - remote: 192.168.178.220:389> - tls not started - listening - SyncStrategy - internal decoder
2022-02-14 13:59:09,280 - synapse.storage.database - 739 - WARNING - sentinel - Starting db txn 'get_users_by_id_case_insensitive' from sentinel context
2022-02-14 13:59:09,281 - synapse.storage.database - 790 - WARNING - sentinel - Starting db connection from sentinel context: metrics will be lost
2022-02-14 13:59:09,284 - synapse.handlers.auth - 1037 - WARNING - sentinel - Attempted to login as @USERNAME:www1.DOMAIN but they do not exist
2022-02-14 13:59:09,287 - ldap_auth_provider - 471 - DEBUG - sentinel - Established LDAP connection in simple bind mode: ldap://192.168.178.220:389 - cleartext - user: CN=ldapservice2,CN=Users,DC=poldom,DC=local - not lazy - unbound - closed - <no socket> - tls not started - not listening - SyncStrategy - internal decoder
2022-02-14 13:59:09,443 - ldap_auth_provider - 487 - DEBUG - sentinel - LDAP Bind successful in simple bind mode.
2022-02-14 13:59:09,443 - ldap_auth_provider - 549 - DEBUG - sentinel - LDAP search filter: (&(sAMAccountName=USERNAME)(&(objectClass=user)(mail=*@poldom.local)))
2022-02-14 13:59:09,491 - ldap_auth_provider - 574 - DEBUG - sentinel - LDAP search found dn: CN=USER,CN=Users,DC=poldom,DC=local
2022-02-14 13:59:09,495 - ldap_auth_provider - 471 - DEBUG - sentinel - Established LDAP connection in simple bind mode: ldap://192.168.178.220:389 - cleartext - user: CN=USER,CN=Users,DC=poldom,DC=local - not lazy - bound - open - <local: 192.168.1.3:48987 - remote: 192.168.178.220:389> - tls not started - listening - SyncStrategy - internal decoder
2022-02-14 13:59:09,615 - ldap_auth_provider - 487 - DEBUG - sentinel - LDAP Bind successful in simple bind mode.
2022-02-14 13:59:09,615 - synapse.storage.database - 739 - WARNING - sentinel - Starting db txn 'get_users_by_id_case_insensitive' from sentinel context
2022-02-14 13:59:09,618 - synapse.storage.database - 790 - WARNING - sentinel - Starting db connection from sentinel context: metrics will be lost
2022-02-14 13:59:09,621 - synapse.handlers.auth - 1037 - WARNING - sentinel - Attempted to login as @USERNAME:www1.DOMAIN but they do not exist
2022-02-14 13:59:09,622 - synapse.module_api - 548 - WARNING - sentinel - Using deprecated ModuleApi.register which creates a dummy user device.
2022-02-14 13:59:09,623 - synapse.storage.database - 739 - WARNING - sentinel - Starting db txn 'get_users_by_id_case_insensitive' from sentinel context
2022-02-14 13:59:09,624 - synapse.storage.database - 790 - WARNING - sentinel - Starting db connection from sentinel context: metrics will be lost
2022-02-14 13:59:09,627 - synapse.handlers.auth - 2183 - WARNING - sentinel - Failed to run module API callback <function load_single_legacy_password_auth_provider.<locals>.async_wrapper.<locals>.wrapped_check_auth at 0x7f95c85820>: 400: Numeric user IDs are reserved for guest users.
2022-02-14 13:59:09,628 - synapse.storage.database - 739 - WARNING - sentinel - Starting db txn 'get_users_by_id_case_insensitive' from sentinel context
2022-02-14 13:59:09,629 - synapse.storage.database - 790 - WARNING - sentinel - Starting db connection from sentinel context: metrics will be lost
2022-02-14 13:59:09,632 - synapse.handlers.auth - 1037 - WARNING - sentinel - Attempted to login as @USERNAME:www1.DOMAIN but they do not exist
2022-02-14 13:59:09,633 - synapse.http.server - 95 - INFO - sentinel - <SynapseRequest at 0x7f942a3550 method='POST' uri='/_matrix/client/r0/login' clientproto='HTTP/1.1' site='8448'> SynapseError: 403 - Invalid password
2022-02-14 13:59:09,634 - synapse.logging.context - 948 - WARNING - sentinel - Calling defer_to_threadpool from sentinel context: metrics will be lost

[squahtx]

2022-02-14 13:59:09,627 - synapse.handlers.auth - 2183 - WARNING - sentinel - Failed to run module API callback <function load_single_legacy_password_auth_provider.<locals>.async_wrapper.<locals>.wrapped_check_auth at 0x7f95c85820>: 400: Numeric user IDs are reserved for guest users.

@mightymop It looks like your issue is different to UAnton's. What username are you trying to log in with? Synapse does not allow numeric user IDs.

[mightymop]

2022-02-14 13:59:09,627 - synapse.handlers.auth - 2183 - WARNING - sentinel - Failed to run module API callback <function load_single_legacy_password_auth_provider.<locals>.async_wrapper.<locals>.wrapped_check_auth at 0x7f95c85820>: 400: Numeric user IDs are reserved for guest users.

@mightymop It looks like your issue is different to UAnton's. What username are you trying to log in with? Synapse does not allow numeric user IDs.

ah thanks... i have changed from sAMAccountName to mailNickname... now it runs...

[reivilibre]

This warning should now be fixed (by #148). If it's not, please come back and reopen.