search

rlidwka / sinopia-ldap

LDAP auth plugin for sinopia
18 stars 12 forks source link

Error: write after end #8

Closed justinmchase closed 8 years ago

justinmchase commented 9 years ago

I'm getting this interesting error and I'm not sure what is going wrong:

Error: write after end
  at writeAfterEnd (_stream_writable.js:130:12)
  at CleartextStream.Writable.write (_stream_writable.js:178:5)
  at Client._send (/usr/local/lib/node_modules/sinopia-ldap/node_modules/ldapjs/lib/client/client.js:914:17)
  at Client.bind (/usr/local/lib/node_modules/sinopia-ldap/node_modules/ldapjs/lib/client/client.js:367:15)
  at LdapAuth._adminBind (/usr/local/lib/node_modules/sinopia-ldap/node_modules/ldapauth-fork/lib/ldapauth.js:171:21) 
  at LdapAuth._search (/usr/local/lib/node_modules/sinopia-ldap/node_modules/ldapauth-fork/lib/ldapauth.js:193:8)
  at LdapAuth._findUser (/usr/local/lib/node_modules/sinopia-ldap/node_modules/ldapauth-fork/lib/ldapauth.js:242:8) 
  at LdapAuth.authenticate (/usr/local/lib/node_modules/sinopia-ldap/node_modules/ldapauth-fork/lib/ldapauth.js:298:8)
  at Auth.authenticate (/usr/local/lib/node_modules/sinopia-ldap/index.js:31:14)
  at next (/usr/local/lib/node_modules/sinopia/lib/auth.js:96:7)

Here is my config:

auth:
  ldap:
    type: ldap
    groupNameAttribute: 'cn'
    client_options:
      url: 'ldaps://...'
      adminDn: 'cn=admin,dc=evolvehq,dc=com'
      adminPassword: '...'
      searchBase: 'ou=users,dc=evolvehq,dc=com'
      searchFilter: '(uid={{username}})'
      cache: False
      searchAttributes:
        - "*"
        - memberOf
      tlsOptions:
        rejectUnauthorized: False

Do you have any hints as to what could be causing this error?

justinmchase commented 9 years ago

I think I figured it out. Basically it means that I can't connect. Turns out our ldap server is listening on a specific device. You can troubleshoot using the ldapsearch tool for anyone hitting a similar issue.

clux commented 9 years ago

I am seeing this as well on latest 0.10 branch of node, with a similar config.

sinopia-0 (out):  warn  --- LDAP error { message: 'write after end',
sinopia-0 (out):   name: 'Error',
sinopia-0 (out):   stack: 'Error: write after end\n    at writeAfterEnd (_stream_writable.js:133:12)\n    at CleartextStream.Writable.write (_stream_writable.js:181:5)\n    at Client._send (/home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapjs/lib/client/client.js:914:17)\n    at Client.search (/home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapjs/lib/client/client.js:678:15)\n    at /home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapauth-fork/lib/ldapauth.js:197:23\n    at LdapAuth._adminBind (/home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapauth-fork/lib/ldapauth.js:168:12)\n    at LdapAuth._search (/home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapauth-fork/lib/ldapauth.js:193:8)\n    at LdapAuth._findUser (/home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapauth-fork/lib/ldapauth.js:242:8)\n    at LdapAuth.authenticate (/home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapauth-fork/lib/ldapauth.js:298:8)\n    at Auth.authenticate (/home/debian/sinopia/node_modules/sinopia-ldap/index.js:31:14)',
sinopia-0 (out):   code: undefined,

Interestingly, my ldap authentication is working, I can use the ldapauth-fork client outside the process just fine, as well as login on the web interface of the sinopia server, but after about an hour of sinopia running, this error starts occurring and no logins are successfully made.

pm2 restart all fixes the problem on my sinopia server machine, but only temporarily.

I'll try to restart it a few times with some debug and see I i can find something during the next week.

clux commented 9 years ago

Seems the ldap connection is going down after about 30 minutes. It never seems to be able to recover from that without a restart.

rlidwka commented 9 years ago

Seems the ldap connection is going down after about 30 minutes.

I think it's this issue again: https://github.com/rlidwka/sinopia-ldap/pull/9 . We didn't have reconnecting in place.

Now it should connect to LDAP server for every request, thus if something disconnects, it'll recover. I published changes in sinopia-ldap@0.5.0., please check it out.

clux commented 9 years ago

I am still seeing the same error at the exact same line with 0.5.0 unfortunately. But now, upon restarting, the error persists and a few extra errors are thrown my way. Not sure if they are helpful, but enclosed here at any rate:

sinopia-0 (out):  warn  --- LDAP error { message: '10__ldaps://ldap.domain.com:636 closed',
sinopia-0 (out):   name: 'ConnectionError',
sinopia-0 (out):   stack: 'ConnectionError: 10__ldaps://ldap.domain.com:636 closed\n    at /home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapjs/lib/client/client.js:127:15\n    at Array.forEach (native)\n    at Socket.onClose (/home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapjs/lib/client/client.js:124:39)\n    at Socket.emit (events.js:117:20)\n    at TCP.close (net.js:466:12)',
sinopia-0 (out):   code: 128,
sinopia-0 (out):   signal: undefined }
sinopia-0 (out):  http  <-- 304, user: undefined, req: 'GET /-/static/fontello.woff?10872183', bytes: 0/0
sinopia-0 (out):  warn  --- LDAP error { message: '12__ldaps://ldap.domain.com:636 closed',
sinopia-0 (out):   name: 'ConnectionError',
sinopia-0 (out):   stack: 'ConnectionError: 12__ldaps://ldap.domain.com:636 closed\n    at /home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapjs/lib/client/client.js:127:15\n    at Array.forEach (native)\n    at Socket.onClose (/home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapjs/lib/client/client.js:124:39)\n    at Socket.emit (events.js:117:20)\n    at TCP.close (net.js:466:12)',
sinopia-0 (out):   code: 128,
sinopia-0 (out):   signal: undefined }
sinopia-0 (out):  http  <-- 304, user: undefined, req: 'GET /-/logo', bytes: 0/0
sinopia-0 (out):  warn  --- LDAP error { message: '14__ldaps://ldap.domain.com:636 closed',
sinopia-0 (out):   name: 'ConnectionError',
sinopia-0 (out):   stack: 'ConnectionError: 14__ldaps://ldap.domain.com:636 closed\n    at /home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapjs/lib/client/client.js:127:15\n    at Array.forEach (native)\n    at Socket.onClose (/home/debian/sinopia/node_modules/sinopia-ldap/node_modules/ldapjs/lib/client/client.js:124:39)\n    at Socket.emit (events.js:117:20)\n    at TCP.close (net.js:466:12)',
sinopia-0 (out):   code: 128,
sinopia-0 (out):   signal: undefined }
sinopia-0 (out):  http  <-- 304, user: undefined, req: 'GET /-/static/favicon.png', bytes: 0/0
sinopia-0 (out):  warn  --- config file  - /home/debian/sinopia/config.yaml
sinopia-0 (out):  warn  --- http address - http://0.0.0.0:4873/
sinopia-0 (err): {"name":"ldapjs","component":"client","hostname":"build-sinopia","pid":20519,"clazz":"Client","level":50,"message":{"messageID":0,"protocolOp":"LDAPResult","status":52,"matchedDN":"","errorMessage":"00000003: LdapErr: DSID-0C060463, comment: Error decrypting ldap message, data 0, v1db1\u0000","referrals":[],"responseName":"1.3.6.1.4.1.1466.20036","controls":[]},"msg":"unsolicited message","time":"2015-05-18T15:03:13.922Z","v":0}
sinopia-0 (err): {"name":"ldapjs","component":"client","hostname":"build-sinopia","pid":20519,"clazz":"Client","level":50,"message":{"messageID":0,"protocolOp":"LDAPResult","status":52,"matchedDN":"","errorMessage":"00000003: LdapErr: DSID-0C060463, comment: Error decrypting ldap message, data 0, v1db1\u0000","referrals":[],"responseName":"1.3.6.1.4.1.1466.20036","controls":[]},"msg":"unsolicited message","time":"2015-05-18T15:03:40.267Z","v":0}
sinopia-0 (err): {"name":"ldapjs","component":"client","hostname":"build-sinopia","pid":20519,"clazz":"Client","level":50,"message":{"messageID":0,"protocolOp":"LDAPResult","status":52,"matchedDN":"","errorMessage":"00000003: LdapErr: DSID-0C060463, comment: Error decrypting ldap message, data 0, v1db1\u0000","referrals":[],"responseName":"1.3.6.1.4.1.1466.20036","controls":[]},"msg":"unsolicited message","time":"2015-05-18T15:03:40.270Z","v":0}
sinopia-0 (err): {"name":"ldapjs","component":"client","hostname":"build-sinopia","pid":20546,"clazz":"Client","level":50,"message":{"messageID":0,"protocolOp":"LDAPResult","status":52,"matchedDN":"","errorMessage":"00000003: LdapErr: DSID-0C060463, comment: Error decrypting ldap message, data 0, v1db1\u0000","referrals":[],"responseName":"1.3.6.1.4.1.1466.20036","controls":[]},"msg":"unsolicited message","time":"2015-05-18T15:03:53.087Z","v":0}
sinopia-0 (err): {"name":"ldapjs","component":"client","hostname":"build-sinopia","pid":20546,"clazz":"Client","level":50,"message":{"messageID":0,"protocolOp":"LDAPResult","status":52,"matchedDN":"","errorMessage":"00000003: LdapErr: DSID-0C060463, comment: Error decrypting ldap message, data 0, v1db1\u0000","referrals":[],"responseName":"1.3.6.1.4.1.1466.20036","controls":[]},"msg":"unsolicited message","time":"2015-05-18T15:03:53.208Z","v":0}
sinopia-0 (err): {"name":"ldapjs","component":"client","hostname":"build-sinopia","pid":20546,"clazz":"Client","level":50,"message":{"messageID":0,"protocolOp":"LDAPResult","status":52,"matchedDN":"","errorMessage":"00000003: LdapErr: DSID-0C060463, comment: Error decrypting ldap message, data 0, v1db1\u0000","referrals":[],"responseName":"1.3.6.1.4.1.1466.20036","controls":[]},"msg":"unsolicited message","time":"2015-05-18T15:03:53.210Z","v":0}
sinopia-0 (err): {"name":"ldapjs","component":"client","hostname":"build-sinopia","pid":20546,"clazz":"Client","level":50,"message":{"messageID":0,"protocolOp":"LDAPResult","status":52,"matchedDN":"","errorMessage":"00000003: LdapErr: DSID-0C060463, comment: Error decrypting ldap message, data 0, v1db1\u0000","referrals":[],"responseName":"1.3.6.1.4.1.1466.20036","controls":[]},"msg":"unsolicited message","time":"2015-05-18T15:03:53.232Z","v":0}
sinopia-0 (err): {"name":"ldapjs","component":"client","hostname":"build-sinopia","pid":20546,"clazz":"Client","level":50,"message":{"messageID":0,"protocolOp":"LDAPResult","status":52,"matchedDN":"","errorMessage":"00000003: LdapErr: DSID-0C060463, comment: Error decrypting ldap message, data 0, v1db1\u0000","referrals":[],"responseName":"1.3.6.1.4.1.1466.20036","controls":[]},"msg":"unsolicited message","time":"2015-05-18T15:03:53.305Z","v":0}
sinopia-0 (err): {"name":"ldapjs","component":"client","hostname":"build-sinopia","pid":20587,"clazz":"Client","level":50,"message":{"messageID":0,"protocolOp":"LDAPResult","status":52,"matchedDN":"","errorMessage":"00000003: LdapErr: DSID-0C060463, comment: Error decrypting ldap message, data 0, v1db1\u0000","referrals":[],"responseName":"1.3.6.1.4.1.1466.20036","controls":[]},"msg":"unsolicited message","time":"2015-05-18T15:06:47.636Z","v":0}
sinopia-0 (err): {"name":"ldapjs","component":"client","hostname":"build-sinopia","pid":20587,"clazz":"Client","level":50,"message":{"messageID":0,"protocolOp":"LDAPResult","status":52,"matchedDN":"","errorMessage":"00000003: LdapErr: DSID-0C060463, comment: Error decrypting ldap message, data 0, v1db1\u0000","referrals":[],"responseName":"1.3.6.1.4.1.1466.20036","controls":[]},"msg":"unsolicited message","time":"2015-05-18T15:06:47.784Z","v":0}
sinopia-0 (err): {"name":"ldapjs","component":"client","hostname":"build-sinopia","pid":20587,"clazz":"Client","level":50,"message":{"messageID":0,"protocolOp":"LDAPResult","status":52,"matchedDN":"","errorMessage":"00000003: LdapErr: DSID-0C060463, comment: Error decrypting ldap message, data 0, v1db1\u0000","referrals":[],"responseName":"1.3.6.1.4.1.1466.20036","controls":[]},"msg":"unsolicited message","time":"2015-05-18T15:06:47.807Z","v":0}
sinopia-0 (err): {"name":"ldapjs","component":"client","hostname":"build-sinopia","pid":20655,"clazz":"Client","level":50,"message":{"messageID":0,"protocolOp":"LDAPResult","status":52,"matchedDN":"","errorMessage":"00000003: LdapErr: DSID-0C060463, comment: Error decrypting ldap message, data 0, v1db1\u0000","referrals":[],"responseName":"1.3.6.1.4.1.1466.20036","controls":[]},"msg":"unsolicited message","time":"2015-05-18T15:09:07.572Z","v":0}

Maybe the extra socket opens are not going down well with SAM.

rlidwka commented 9 years ago

@clux ,

LdapErr: DSID-0C060463, comment: Error decrypting ldap message

Googling shows that it's some kind of certificate error. Maybe something funny is going on with ldap server configuration. I have no idea though.

clux commented 9 years ago

Yeah, perhaps. After trying some more that particular error only appeared once - just thought I'd include the weird ones.

The main error is the connection error, which is triggered by every login attempt with 0.5.0.

This is weird because I have a small test for myself to check that I could authenticate with the ldap server by calling ldap.authenticate with the ldapauth-fork module embedded within sinopia-ldap using the same options as the client_options in my config. It succeeds with both versions of sinopia-ldap, unfortunately, but the connection error from sinopia is only there with 0.5.0.