search

emqx / emqx-auth-ldap

EMQX LDAP Authentication Plugin
https://www.emqx.io
Apache License 2.0
7 stars 15 forks source link

Can't reconnect to LDAP service after network disabled and restored #126

Open SIMONCHEN96 opened 1 year ago

SIMONCHEN96 commented 1 year ago

Hello,

Background: There is a OpenLDAP service running on a PC (Windows 10), and if I disable and restore the network of this PC, the function of plugin emqx_auth_ldap is not working.

After network disabled and then restored, the following logs repeated:

2022-10-10T15:31:58.090513+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:31:58.097660+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:31:58.097660+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:31:58.097660+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:31:58.097660+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:31:58.097875+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:31:58.108580+08:00 [error] [LDAP] Can't connect to OpenLDAP server: "connect failed" 2022-10-10T15:31:58.111311+08:00 [error] [LDAP] Can't connect to OpenLDAP server: "connect failed" 2022-10-10T15:31:58.111347+08:00 [error] [LDAP] Can't connect to OpenLDAP server: "connect failed" 2022-10-10T15:31:58.111375+08:00 [error] [LDAP] Can't connect to OpenLDAP server: "connect failed" 2022-10-10T15:31:58.111380+08:00 [error] [LDAP] Can't connect to OpenLDAP server: "connect failed" 2022-10-10T15:31:58.111551+08:00 [error] [LDAP] Can't connect to OpenLDAP server: "connect failed" 2022-10-10T15:32:00.109455+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:32:00.112471+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:32:00.112464+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:32:00.112472+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:32:00.112530+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:32:00.112530+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:32:00.159156+08:00 [error] [LDAP] Can't connect to OpenLDAP server: "connect failed" 2022-10-10T15:32:00.159108+08:00 [error] [LDAP] Can't connect to OpenLDAP server: "connect failed" 2022-10-10T15:32:00.159242+08:00 [error] [LDAP] Can't connect to OpenLDAP server: "connect failed" 2022-10-10T15:32:00.159197+08:00 [error] [LDAP] Can't connect to OpenLDAP server: "connect failed" 2022-10-10T15:32:00.159373+08:00 [error] [LDAP] Can't connect to OpenLDAP server: "connect failed" 2022-10-10T15:32:00.159402+08:00 [error] [LDAP] Can't connect to OpenLDAP server: "connect failed"

There were no errors at last, but client can't connect to the broker:

2022-10-10T15:32:04.163528+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:32:04.163674+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:32:04.164540+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:32:04.164474+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:32:04.164601+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:32:04.164672+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:33:10.438274+08:00 [error] mqttx_c335fa89@172.16.100.230:38136 [LDAP] Search dn: "ou=people,dc=xxx,dc=com", filter: {equalityMatch,{'AttributeValueAssertion',"objectClass","mqttUser"}}, fail:ldap_closed 2022-10-10T15:33:10.438428+08:00 [error] mqttx_c335fa89@172.16.100.230:38136 [LDAP] Auth from ldap failed: username_or_password_error 2022-10-10T15:33:10.438534+08:00 [warning] mqttx_c335fa89@172.16.100.230:38136 [Channel] Client mqttx_c335fa89 (Username: 'demo') login failed for username_or_password_error 2022-10-10T15:33:10.438710+08:00 [debug] mqttx_c335fa89@172.16.100.230:38136 [MQTT] SEND CONNACK(Q0, R0, D0AckFlags=0, ReasonCode=135) 2022-10-10T15:33:10.438882+08:00 [info] mqttx_c335fa89@172.16.100.230:38136 file: emqx_connection.erl, line: 550, mfa: {emqx_connection,terminate,2}, msg: terminate, pid: <0.2747.0>, reason: {shutdown,not_authorized} 2022-10-10T15:33:12.053177+08:00 [error] mqttx_c335fa89@172.16.100.230:38142 [LDAP] Search dn: "ou=people,dc=xxx,dc=com", filter: {equalityMatch,{'AttributeValueAssertion',"objectClass","mqttUser"}}, fail:ldap_closed 2022-10-10T15:33:12.053637+08:00 [error] mqttx_c335fa89@172.16.100.230:38142 [LDAP] Auth from ldap failed: username_or_password_error 2022-10-10T15:33:12.054160+08:00 [warning] mqttx_c335fa89@172.16.100.230:38142 [Channel] Client mqttx_c335fa89 (Username: 'demo') login failed for username_or_password_error 2022-10-10T15:33:12.054562+08:00 [debug] mqttx_c335fa89@172.16.100.230:38142 [MQTT] SEND CONNACK(Q0, R0, D0AckFlags=0, ReasonCode=135) 2022-10-10T15:33:12.054876+08:00 [info] mqttx_c335fa89@172.16.100.230:38142 file: emqx_connection.erl, line: 550, mfa: {emqx_connection,terminate,2}, msg: terminate, pid: <0.2749.0>, reason: {shutdown,not_authorized}

Function works normally after restart plugin in EMQX Dashboard.

2022-10-10T15:36:11.645682+08:00 [notice] Application: emqx_auth_ldap. Exited: stopped. Type: temporary. 2022-10-10T15:36:11.645787+08:00 [info] [Plugins] Stop plugin emqx_auth_ldap successfully 2022-10-10T15:36:12.390865+08:00 [debug] Adding Defaults 2022-10-10T15:36:12.390946+08:00 [debug] Right Hand Side Substitutions 2022-10-10T15:36:12.391023+08:00 [debug] Applying Datatypes 2022-10-10T15:36:12.391318+08:00 [debug] Validation 2022-10-10T15:36:12.391376+08:00 [debug] Applied 1:1 Mappings 2022-10-10T15:36:12.391485+08:00 [debug] Running translation for emqx_auth_ldap.ldap 2022-10-10T15:36:12.391717+08:00 [debug] "emqx_auth_ldap.filters" in Translations to drop... 2022-10-10T15:36:12.391768+08:00 [debug] Applied Translations 2022-10-10T15:36:12.392240+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:36:13.369274+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:36:13.427156+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:36:14.152333+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:36:14.171795+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:36:14.222393+08:00 [debug] [LDAP] Connecting to OpenLDAP server: [{192,168,1,100}], Opts:[{port,1389},{timeout,30000}] ... 2022-10-10T15:36:14.244427+08:00 [info] [Plugins] Started plugins: [emqx_auth_ldap] 2022-10-10T15:36:14.244514+08:00 [info] [Plugins] Load plugin emqx_auth_ldap successfully 2022-10-10T15:55:52.893296+08:00 [debug] mqttx_c335fa89@172.16.100.230:38664 [Channel] RECV CONNECT(Q0, R0, D0ClientId=mqttx_c335fa89, ProtoName=MQTT, ProtoVsn=5, CleanStart=true, KeepAlive=60, Username=demo, Password=**) 2022-10-10T15:55:52.895814+08:00 [debug] mqttx_c335fa89@172.16.100.230:38664 client_id: <<"mqttx_c335fa89">>, file: emqx_cm.erl, line: 128, mfa: {emqx_cm,insert_channel_info,3}, msg: insert_channel_info, pid: <0.3237.0> 2022-10-10T15:55:52.896499+08:00 [debug] mqttx_c335fa89@172.16.100.230:38664 [MQTT] SEND CONNACK(Q0, R0, D0AckFlags=0, ReasonCode=0) 2022-10-10T15:55:53.147133+08:00 [debug] mqttx_c335fa89@172.16.100.230:38664 [MQTT] RECV <<130,12,250,236,0,0,6,100,101,109,111,47,35,2>> 2022-10-10T15:55:53.147295+08:00 [debug] mqttx_c335fa89@172.16.100.230:38664 [MQTT] RECV SUBSCRIBE(Q1, R0, D0PacketId=64236, TopicFilters=[{<<"demo/#">>,#{nl => 0,qos => 2,rap => 0,rh => 0}}]) 2022-10-10T15:55:53.147466+08:00 [debug] mqttx_c335fa89@172.16.100.230:38664 [LDAP] search dn:"ou=people,dc=xxx,dc=com" filter:{equalityMatch,{'AttributeValueAssertion',"objectClass","mqttUser"}}, attribute:"mqttSubscriptionTopic" 2022-10-10T15:55:53.165862+08:00 [info] mqttx_c335fa89@172.16.100.230:38664 mqttx_c335fa89 SUBSCRIBE demo/#: Options: #{nl => 0,qos => 2,rap => 0,rh => 0,sub_props => #{}} 2022-10-10T15:55:53.170255+08:00 [debug] mqttx_c335fa89@172.16.100.230:38664 [MQTT] SEND SUBACK(Q0, R0, D0PacketId=64236, ReasonCodes=[2])

If you could help, I really appreciate it!

keitsi commented 1 year ago

It looks like a bug that triggers when the network connection to the openldap server is drop. The entire cluster is down until the ldap plugin is manually restarted.