Stop to work after some time #47

theundefined · 2018-10-10T16:47:36Z

I've configured verdaccio-ldap agains ldap from AD. It works fine few minutes after start, with configuration like

auth:
  ldap:
    type: ldap
    client_options:
      url: "ldaps://ldap.server"
    adminDn: "CN=user,OU=A,OU=B,OU=C,DC=D,DC=local"
    adminPassword: "XXX"
    searchBase: "OU=B,OU=C,DC=D,DC=local"
    searchFilter: "(sAMAccountName={{username}})"
    groupDnProperty: 'cn'
    groupSearchBase: 'OU=B,OU=C,DC=D,DC=local'
    searchAttributes: ['*', 'memberOf']
    cache: true
    reconnect: true

Unfortunately, after few login/logout it stop works, and i have in logs:

verdaccio_1 | warn --- LDAP error OperationsError: 000004DC: LdapErr: DSID-0C0907C2, comment: In order to perform this operation a successful bind must be completed on the connection., data 0, v2580
verdaccio_1 | http <-- 401, user: null(10.99.0.14), req: 'POST /-/verdaccio/login', error: bad username/password, access denied
verdaccio_1 | http <-- 401, user: null(10.99.0.14), req: 'POST /-/verdaccio/login', error: bad username/password, access denied

Any suggestions how to solve it?

The text was updated successfully, but these errors were encountered:

theundefined · 2018-10-15T15:14:24Z

I see, that it's probably connected with vesse/node-ldapauth-fork#67

iovcho · 2018-12-17T12:43:31Z

I have the same issue. The ldap authentication stop works after few hours. The connection to ldap is not lost.
ldapsearch -x -h my.ldap.server -b ou=People,dc=mydomain,dc=com.

and list all users in my ldap server.

The verdaccio is running on screen behand nginx proxy.
screen -d -m verdaccio

I am attach to this screen and I don't see any errors.
warn --- config file - /home/admin/.config/verdaccio/config.yaml
warn --- Plugin successfully loaded: ldap
warn --- Plugin successfully loaded: audit
warn --- http address - http://localhost:4873/ - verdaccio/3.10.0
http <-- 200, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /', bytes: 0/458
http <-- 304, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /-/static/0.style.2574da504448e30822aa.css', bytes: 0/0
http <-- 304, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /-/static/2.style.874023844ee48c18da0e.css', bytes: 0/0
http <-- 304, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /-/static/manifest.8173d9d7dc344bd24eda.js', bytes: 0/0
http <-- 304, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /-/static/vendors.8173d9d7dc344bd24eda.js', bytes: 0/0
http <-- 304, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /-/static/main.8173d9d7dc344bd24eda.js', bytes: 0/0
http <-- 304, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /-/static/1.8173d9d7dc344bd24eda.js', bytes: 0/0
http <-- 304, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /-/static/6.8173d9d7dc344bd24eda.js', bytes: 0/0
http <-- 304, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /-/verdaccio/logo', bytes: 0/0
http <-- 304, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /-/static/4.style.49d0a245af3136bdffe7.css', bytes: 0/0
http <-- 304, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /-/static/4.8173d9d7dc344bd24eda.js', bytes: 0/0
http <-- 304, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /-/static/logo.png', bytes: 0/0
http <-- 304, user: null(192.168.101.6 via 127.0.0.1), req: 'GET /-/verdaccio/packages', bytes: 0/0
http <-- 200, user: username(192.168.101.6 via 127.0.0.1), req: 'POST /-/verdaccio/login', bytes: 46/247
http <-- 304, user: username(192.168.101.6 via 127.0.0.1), req: 'GET /-/verdaccio/packages', bytes: 0/0

web-laborer · 2018-12-21T13:02:25Z

The same also for me.

chriswong · 2019-01-11T02:13:47Z

Same here. Log：

warn --- LDAP error Error: read ECONNRESET

Alexandre-io · 2019-01-12T10:41:02Z

The last ldapauth-fork seems to fix the issue. Could you try the latest release ?

lneveu · 2019-01-12T17:43:47Z

First, thanks @Alexandre-io for the update.!
I'm facing the same issue too. ~1 month ago, I've manually update the node-ldapauth-fork module in version 4.1.0 but it doesn't seem to be enough...
Maybe it's another unrelated issue? Can you please, @chriswong @the-buggatore @iovcho @theundefined, upgrade verdaccio-ldap to latest version and tell me if that fix it for you?

theundefined · 2019-01-12T21:54:34Z

Hi! I start using verdaccio-activedirectory project, which is enought for my needs and which works fine - so i can't reproduce it anymore.

iovcho · 2019-01-13T20:16:27Z

Hello @lneveu . Verdaccio and verdaccio-ldap are updated. I will keep you updated.
Best wishes.

[root@verdaccio-testlink ~]# sudo npm update -g verdaccio
/usr/bin/verdaccio -> /usr/lib/node_modules/verdaccio/bin/verdaccio

verdaccio@3.10.1
updated 3 packages in 8.599s
[root@verdaccio-testlink ~]# sudo npm update -g verdaccio-ldap
verdaccio-ldap@3.1.0
removed 1 package and updated 8 packages in 4.785s

chriswong · 2019-01-21T01:37:24Z

I had upgraded verdaccio-ldap to 3.1.0, but nothing changed.

The problem is still there after node-ldapauth-fork was upgraded to 4.2.0.

BTW: My Verdaccio version is 3.8.6.

Update: I have tested under node@8.14.0/node@10.15.0, and verdaccio@3.8.6/verdaccio@3.10.1, all with the same issue.

iovcho · 2019-01-21T09:27:22Z

Today the verdaccio ldap authentication was crashed again and not works. :(
verdaccio@3.10.1
verdaccio-ldap@3.1.0

chriswong · 2019-01-25T00:58:07Z

I'm using verdaccio-activedirectory now, thanks @theundefined.

iovcho · 2019-02-01T10:54:44Z

Hello. Last week, verdaccio ldap authentication stops works multiple times. Can you tell me how can I run it in debug mode ? After next crash I will sent the log here.

Thanks a lot.

nemca · 2019-03-13T12:56:31Z

@iovcho you can set trace log level in config file

logs:
  - {type: file, path: '/var/log/verdaccio/trace.log', level: trace}

nemca · 2019-03-13T13:12:11Z

Also I have the same problem.
verdaccio@3.11.6/verdaccio-ldap@3.1.0/ldapauth-fork@4.2.0
How can I help with this task? Can I provide some logs or something else?

lneveu · 2019-03-13T19:53:32Z

It seems to be related with LDAP bind requests and concurrency. I can reproduce the bug when multiple authentications are made "simultaneously" (try to disable cache to reproduce the issue more easily).
I think this pull request #46 can solved the problem by creating a new LdapAuth instance for each new authentication; but I haven't tested it yet.

iovcho · 2019-03-14T12:14:30Z

logs:

{type: file, path: '/var/log/verdaccio/trace.log', level: trace}

Done. I will sent you report on next crash.
Thanks.

iovcho · 2019-03-14T14:09:31Z

Hello @nemca . Here is the tracelog, before crash. I change my personal data in log (emails, username, passwords etc). Here is the output:

{"name":"verdaccio","hostname":"verdaccio.hostname","pid":7284,"sub":"in","level":35,"request":{"method":"GET","url":"/-/verdaccio/packages"},"user":null,"remoteIP":"192.168.101.3 via 127.0.0.1","status":304,"bytes":{"in":0,"out":0},"msg":"304, user: null(192.168.101.3 via 127.0.0.1), req: 'GET /-/verdaccio/packages', bytes: 0/0","time":"2019-03-14T13:50:15.051Z","v":0}
{"name":"verdaccio","hostname":"verdaccio.hostname","pid":7284,"sub":"in","level":30,"req":{"method":"POST","url":"/-/verdaccio/login","headers":{"host":"npm.mydomain.com:443","x-forwarded-for":"192.168.101.3","x-forwarded-proto":"https","connection":"close","content-length":"52","accept":"application/json","origin":"https://npm.mydomain.com","user-agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.121 Safari/537.36","content-type":"application/json","referer":"https://npm.mydomain.com/","accept-encoding":"gzip, deflate, br","accept-language":"en-GB,en-US;q=0.9,en;q=0.8,bg;q=0.7","cookie":""},"remoteAddress":"127.0.0.1","remotePort":35098},"ip":"127.0.0.1","msg":"127.0.0.1 requested 'POST /-/verdaccio/login'","time":"2019-03-14T13:50:20.115Z","v":0}
{"name":"verdaccio","hostname":"verdaccio.hostname","pid":7284,"sub":"auth","clazz":"Client","ldap_id":"1__ldap://ldap.mydomain.com","level":10,"msg":"sending request {"messageID":538,"protocolOp":"SearchRequest","baseObject":{"rdns":[{"attrs":{"ou":{"value":"People","name":"ou","order":0}},"spLead":0,"spTrail":0},{"attrs":{"dc":{"value":"mydomain","name":"dc","order":0}},"spLead":0,"spTrail":0},{"attrs":{"dc":{"value":"com","name":"dc","order":0}},"spLead":0,"spTrail":0}],"_format":{}},"scope":"sub","derefAliases":0,"sizeLimit":0,"timeLimit":10,"typesOnly":false,"filter":"(cn=myusername)","attributes":[],"controls":[]}","time":"2019-03-14T13:50:20.116Z","v":0}
{"name":"verdaccio","hostname":"verdaccio.hostname","pid":7284,"sub":"auth","clazz":"Client","level":10,"msg":"data event: <Buffer 30 82 01 17 02 02 02 1a 64 82 01 0f 04 2e 63 6e 3d 79 2e 76 6c 61 64 69 6d 69 72 6f 76 2c 6f 75 3d 50 65 6f 70 6c 65 2c 64 63 3d 61 77 64 2d 67 72 6f ... >","time":"2019-03-14T13:50:20.118Z","v":0}
{"name":"verdaccio","hostname":"verdaccio.hostname","pid":7284,"sub":"auth","clazz":"Client","level":10,"msg":"parse: data=<Buffer 04 2e 63 6e 3d 79 2e 76 6c 61 64 69 6d 69 72 6f 76 2c 6f 75 3d 50 65 6f 70 6c 65 2c 64 63 3d 61 77 64 2d 67 72 6f 75 70 2c 64 63 3d 74 65 63 68 30 81 ... >","time":"2019-03-14T13:50:20.118Z","v":0}
{"name":"verdaccio","hostname":"verdaccio.hostname","pid":7284,"sub":"auth","clazz":"Client","level":10,"msg":"Parsing done: {"messageID":538,"protocolOp":"SearchEntry","objectName":"cn=myusername,ou=People,dc=mydomain,dc=com","attributes":[{"type":"mail","vals":["myusername@mydomain.com"]},{"type":"userPassword","vals":["{SHA}6qMd03jJ0aEBBf+UpHJxIoBx26o="]},{"type":"displayName","vals":["FirstName Lastname"]},{"type":"givenName","vals":["FirstName
"]},{"type":"objectClass","vals":["inetOrgPerson"]},{"type":"sn","vals":["Lastname"]},{"type":"cn","vals":["myusername"]}],"controls":[]}","time":"2019-03-14T13:50:20.118Z","v":0}
{"name":"verdaccio","hostname":"verdaccio.hostname","pid":7284,"sub":"auth","clazz":"Client","ldap_id":"1__ldap://ldap.mydomain.com","level":10,"msg":"response received","time":"2019-03-14T13:50:20.118Z","v":0}
{"name":"verdaccio","hostname":"verdaccio.hostname","pid":7284,"sub":"auth","clazz":"Client","level":10,"msg":"parse: data=<Buffer 0a 01 00 04 00 04 00>","time":"2019-03-14T13:50:20.118Z","v":0}
{"name":"verdaccio","hostname":"verdaccio.hostname","pid":7284,"sub":"auth","clazz":"Client","level":10,"msg":"Parsing done: {"messageID":538,"protocolOp":"LDAPResult","status":0,"matchedDN":"","errorMessage":"","referrals":[],"controls":[]}","time":"2019-03-14T13:50:20.118Z","v":0}
{"name":"verdaccio","hostname":"verdaccio.hostname","pid":7284,"sub":"auth","clazz":"Client","ldap_id":"1__ldap://ldap.mydomain.com","level":10,"msg":"response received","time":"2019-03-14T13:50:20.118Z","v":0}
{"name":"verdaccio","hostname":"verdaccio.hostname","pid":7284,"sub":"auth","clazz":"Client","ldap_id":"2__ldap://ldap.mydomain.com","level":10,"msg":"sending request {"messageID":538,"protocolOp":"BindRequest","version":3,"name":"cn=myusername,ou=People,dc=mydomain,dc=com","authenticationType":"Simple","credentials":"password","controls":[]}","time":"2019-03-14T13:50:20.118Z","v":0}
{"name":"verdaccio","hostname":"verdaccio.hostname","pid":7284,"sub":"in","level":35,"request":{"method":"POST","url":"/-/verdaccio/login"},"user":null,"remoteIP":"192.168.101.3 via 127.0.0.1","status":200,"bytes":{"in":52,"out":0},"msg":"200, user: null(192.168.101.3 via 127.0.0.1), req: 'POST /-/verdaccio/login', bytes: 52/0","time":"2019-03-14T13:51:20.114Z","v":0}

nemca · 2019-03-15T08:29:02Z

I has merge #46 PR on my env and verdaccio don't stopping work more. But I see too many ESABLISHED connections to LDAP server (>2000), which verdaccio not close and not use.

lneveu · 2019-03-15T18:45:32Z

It seems like connections are never unbind (ldapClient.close is never called after each authentication). Could you try to add it and see if it fix it?

nemca · 2019-03-16T08:17:07Z

@lneveu I can add ldapClient.close, but I'm don't know where exactly (I'm not a programmer).
Can you help me, please?

lneveu · 2019-03-18T19:51:07Z

@nemca You can add it like that: (after the catch handler)

.catch((err) => {
  // 'No such user' is reported via error
  this._logger.warn({
    username: username,
    err: err,
  }, `verdaccio-ldap error ${err}`);

  return false; // indicates failure
})
.finally(() => {
  ldapClient.closeAsync()
    .catch((err) => {
      this._logger.warn({
        err: err
      }, `verdaccio-ldap error on close ${err}`);
    });
})
.asCallback(callback);

(note that close function doesn't work on Node 10 according to ldapjs/node-ldapjs#483)

nemca · 2019-03-19T08:40:43Z

# systemctl status verdaccio| fgrep ago
   Active: active (running) since Tue 2019-03-19 11:29:46 MSK; 8min ago
# lsof -Pp $(pgrep -x [v]erdaccio) 2>/dev/null|fgrep -e :636 | fgrep -e ESTABLISHED | wc -l
1595
# node --version
v10.15.1

This output after I'm added you code.

nemca · 2019-03-19T09:48:26Z

Finally!
I've added this code (discussion) and established connections was reduced to ~<100

YuLinXi · 2019-03-25T06:33:58Z

Can't this problem be solved?

wheelo · 2019-06-10T09:50:02Z

is this problem solved?

iovcho · 2019-06-10T13:27:19Z

is this problem solved?

Hi, No, the problem still exist. I have cronjob who restart Verdaccio each 20 minutes, but this is really ugly workaround. :)

Best wishes.

YuLinXi · 2019-06-18T04:09:02Z

is this problem solved?

Hi, No, the problem still exist. I have cronjob who restart Verdaccio each 20 minutes, but this is really ugly workaround. :)

Best wishes.

Ha ha ，me too

martin31821 · 2019-07-16T15:42:47Z

@Alexandre-io Can we have this in a bugfix release? We're seeing this behavior in production too.
Thanks in advance!

Alexandre-io · 2019-07-16T19:59:40Z

@martin31821 I just release the version 4.0.0. Could you try it and provide us a feedback please ?

martin31821 · 2019-07-17T07:44:46Z

Works fine, thank you!

martin31821 · 2019-09-20T20:34:17Z

@Alexandre-io the problem just reappeared on our production instance, is there anything I can do to help tracking down the real issue?
I have 1k open connections to the ldap server at the moment.

latel · 2020-08-06T14:22:13Z

4.0.1 problem still exists, connection lost after a while

 http <-- 200, user: null(10.230.10.147), req: 'POST /-/npm/v1/security/audits/quick', bytes: 75685/0
verdaccio    |  error--- unexpected error: read ECONNRESET
verdaccio    | Error: read ECONNRESET
verdaccio    |     at TLSWrap.onStreamRead (internal/stream_base_commons.js:205:27)
verdaccio    |  http <-- 500, user: null(10.230.10.147), req: 'POST /-/npm/v1/security/audits/quick', error: internal server error
verdaccio    |  warn --- verdaccio-ldap error Error: read ECONNRESET
verdaccio    |  warn --- verdaccio-ldap error ConnectionError: 2176__ldap://openldap closed
verdaccio    |  http <-- 200, user: null(10.230.10.147), req: 'GET /memory-fs/-/memory-fs-0.5.0.tgz', bytes: 0/4609
verdaccio    |  warn --- verdaccio-ldap error Error: read ECONNRESET
verdaccio    |  warn --- verdaccio-ldap error ConnectionError: 2178__ldap://openldap closed
verdaccio    |  http <-- 200, user: null(10.230.10.147), req: 'GET /browserify-aes/-/browserify-aes-1.2.0.tgz', bytes: 0/7794
verdaccio    |  warn --- verdaccio-ldap error Error: read ECONNRESET
verdaccio    |  warn --- verdaccio-ldap error ConnectionError: 2179__ldap://openldap closed
verdaccio    |  http <-- 200, user: null(10.230.10.147), req: 'GET /cache-loader/-/cache-loader-4.1.0.tgz', bytes: 0/7891
verdaccio    |  warn --- verdaccio-ldap error Error: read ECONNRESET
verdaccio    |  warn --- verdaccio-ldap error ConnectionError: 2181__ldap://openldap closed
verdaccio    |  http <-- 200, user: null(10.230.10.147), req: 'GET /enhanced-resolve/-/enhanced-resolve-4.3.0.tgz', bytes: 0/20514

Alexandre-io added the bug label Jan 12, 2019

lneveu mentioned this issue Jul 11, 2019

Fix authentication issues (fix #47) #60

Merged

Alexandre-io closed this as completed in fb87334 Jul 12, 2019

howardcox mentioned this issue Nov 6, 2019

Problems logging in after server running for a while verdaccio/verdaccio#1551

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Stop to work after some time #47

Stop to work after some time #47

theundefined commented Oct 10, 2018 •

edited

Loading

theundefined commented Oct 15, 2018

iovcho commented Dec 17, 2018 •

edited

Loading

web-laborer commented Dec 21, 2018

chriswong commented Jan 11, 2019

Alexandre-io commented Jan 12, 2019

lneveu commented Jan 12, 2019

theundefined commented Jan 12, 2019

iovcho commented Jan 13, 2019

chriswong commented Jan 21, 2019 •

edited

Loading

iovcho commented Jan 21, 2019

chriswong commented Jan 25, 2019

iovcho commented Feb 1, 2019

nemca commented Mar 13, 2019

nemca commented Mar 13, 2019

lneveu commented Mar 13, 2019

iovcho commented Mar 14, 2019

iovcho commented Mar 14, 2019

nemca commented Mar 15, 2019

lneveu commented Mar 15, 2019

nemca commented Mar 16, 2019

lneveu commented Mar 18, 2019

nemca commented Mar 19, 2019

nemca commented Mar 19, 2019

YuLinXi commented Mar 25, 2019

wheelo commented Jun 10, 2019

iovcho commented Jun 10, 2019

YuLinXi commented Jun 18, 2019

martin31821 commented Jul 16, 2019

Alexandre-io commented Jul 16, 2019

martin31821 commented Jul 17, 2019

martin31821 commented Sep 20, 2019

latel commented Aug 6, 2020 •

edited

Loading

Stop to work after some time #47

Stop to work after some time #47

Comments

theundefined commented Oct 10, 2018 • edited Loading

theundefined commented Oct 15, 2018

iovcho commented Dec 17, 2018 • edited Loading

web-laborer commented Dec 21, 2018

chriswong commented Jan 11, 2019

Alexandre-io commented Jan 12, 2019

lneveu commented Jan 12, 2019

theundefined commented Jan 12, 2019

iovcho commented Jan 13, 2019

chriswong commented Jan 21, 2019 • edited Loading

iovcho commented Jan 21, 2019

chriswong commented Jan 25, 2019

iovcho commented Feb 1, 2019

nemca commented Mar 13, 2019

nemca commented Mar 13, 2019

lneveu commented Mar 13, 2019

iovcho commented Mar 14, 2019

iovcho commented Mar 14, 2019

nemca commented Mar 15, 2019

lneveu commented Mar 15, 2019

nemca commented Mar 16, 2019

lneveu commented Mar 18, 2019

nemca commented Mar 19, 2019

nemca commented Mar 19, 2019

YuLinXi commented Mar 25, 2019

wheelo commented Jun 10, 2019

iovcho commented Jun 10, 2019

YuLinXi commented Jun 18, 2019

martin31821 commented Jul 16, 2019

Alexandre-io commented Jul 16, 2019

martin31821 commented Jul 17, 2019

martin31821 commented Sep 20, 2019

latel commented Aug 6, 2020 • edited Loading

theundefined commented Oct 10, 2018 •

edited

Loading

iovcho commented Dec 17, 2018 •

edited

Loading

chriswong commented Jan 21, 2019 •

edited

Loading

latel commented Aug 6, 2020 •

edited

Loading