Auth failured with PAM_LDAP

Tue Sep 9 04:30:27 PDT 2014

I'm tring to config ocserv with LDAP server, which is success to auth
user to log in SSH. However, when I connect to ocserv with OpenConnect
(Android), the auth failed immediately after I entered my username
without asking my password.

I have no idea what happen even I start it in debug mode, it looks
like ocserv hand jobs to sec-mod, then hand to PAM-auth. While nslcd
return the username and group as what it does as I login, the PAM-Auth
return an error. The process stopped here, I haven't provide my
password, and ocserv is preparing to kick me out.

Here is my entire config. I've remove most parameter that were commented out.
------
auth = "pam"
session-control = false
use-seccomp = true
listen-host = MY_HOST_NAME
max-clients = 32
rate-limit-ms = 100
max-same-clients = 0
tcp-port = 4433
udp-port = 4433
keepalive = 32400
dpd = 90
mobile-dpd = 1800
try-mtu-discovery = true

server-cert = /etc/pki/tls/MY_HOST_NAME/ocserv.pem
server-key = /etc/pki/tls/MY_HOST_NAME/private.key
tls-priorities = "NORMAL:%SERVER_PRECEDENCE:%COMPAT"
#tls-priorities = "NORMAL:%SERVER_PRECEDENCE:%COMPAT:-RSA"

auth-timeout = 40
idle-timeout = 1200
mobile-idle-timeout = 2400
min-reauth-time = 5
cookie-timeout = 300
deny-roaming = false
rekey-time = 172800
rekey-method = ssl
use-utmp = true
use-occtl = true
pid-file = /var/run/ocserv.pid
socket-file = /var/run/ocserv-socket
#run-as-user = nobody
#run-as-group = nogroup
cgroup = "cpuset,cpu:test"

# The name to use for the tun device
device = vpns

predictable-ips = true
default-domain = MY_HOST_NAME
ipv4-network = 192.168.1.0
ipv4-netmask = 255.255.255.0
dns = 192.168.1.2
ping-leases = false
route = 192.168.1.0/255.255.255.0
route = 192.168.5.0/255.255.255.0
cisco-client-compat = true
------

Here is part of ocserv's log:
------
ocserv[16708]: worker: 175.96.129.217:2312 HTTP: Host: MY_HOST_NAME
ocserv[16708]: worker: 175.96.129.217:2312 HTTP: User-Agent:
OpenConnect VPN Agent (Java) v6.00-unknown
ocserv[16708]: worker: 175.96.129.217:2312 User-agent: 'OpenConnect
VPN Agent (Java) v6.00-unknown'
ocserv[16708]: worker: 175.96.129.217:2312 HTTP: Accept: */*
ocserv[16708]: worker: 175.96.129.217:2312 HTTP: Accept-Encoding: identity
ocserv[16708]: worker: 175.96.129.217:2312 HTTP: X-Transcend-Version: 1
ocserv[16708]: worker: 175.96.129.217:2312 HTTP: X-Aggregate-Auth: 1
ocserv[16708]: worker: 175.96.129.217:2312 HTTP: X-AnyConnect-Platform: android
ocserv[16708]: worker: 175.96.129.217:2312 HTTP: X-Pad:
00000000000000000000000000000000000000000000000
ocserv[16708]: worker: 175.96.129.217:2312 HTTP: Content-Type:
application/x-www-form-urlencoded
ocserv[16708]: worker: 175.96.129.217:2312 HTTP: Content-Length: 209
ocserv[16708]: worker: 175.96.129.217:2312 HTTP POST /auth
ocserv[16708]: worker: 175.96.129.217:2312 POST body: '<?xml
version="1.0" encoding="UTF-8"?>
<config-auth client="vpn" type="auth-reply"><version
who="vpn">v6.00-unknown</version><device-id>android</device-id><auth><username>MY_USER_NAME</username></auth></config-auth>
'
ocserv[16708]: worker: 175.96.129.217:2312 cannot find 'group-select'
in client XML message
ocserv[16708]: worker: 175.96.129.217:2312 failed reading groupname
ocserv[16708]: worker: 175.96.129.217:2312 sending message 'sm: auth
init' to secmod
ocserv[16697]: sec-mod: received request from pid 16708 and uid 0
ocserv[16697]: sec-mod: cmd [size=29] sm: auth init
ocserv[16697]: sec-mod: auth init for user 'MY_USER_NAME' (group:
'MY_USER_GROUP') from '175.96.129.217'
ocserv[16697]: PAM-auth: Authentication failure
ocserv[16697]: sec-mod: could not send reply auth cmd.
ocserv[16697]: sec-mod: error processing data for 'sm: auth init' command (-3)
ocserv[16708]: common.c:316: recvmsg returned zero
ocserv[16708]: worker: 175.96.129.217:2312 worker-auth.c:684: error
receiving auth reply message
ocserv[16708]: worker: 175.96.129.217:2312 worker-auth.c:1227: failed
authentication for 'pingu'
ocserv[16708]: TLS[<4>]: REC[0x1a01d60]: Preparing Packet Application
Data(23) with length: 62 and target length: 62
ocserv[16708]: TLS[<9>]: ENC[0x1a01d60]: cipher: AES-128-GCM, MAC:
AEAD, Epoch: 1
ocserv[16708]: TLS[<4>]: REC[0x1a01d60]: Sent Packet[3] Application
Data(23) in epoch 1 and length: 91
ocserv[16708]: TLS[<4>]: REC: Sending Alert[2|49] - Access was denied
ocserv[16708]: TLS[<4>]: REC[0x1a01d60]: Preparing Packet Alert(21)
with length: 2 and target length: 2
ocserv[16708]: TLS[<9>]: ENC[0x1a01d60]: cipher: AES-128-GCM, MAC:
AEAD, Epoch: 1
ocserv[16708]: TLS[<4>]: REC[0x1a01d60]: Sent Packet[4] Alert(21) in
epoch 1 and length: 31
ocserv[16708]: TLS[<4>]: REC[0x1a01d60]: Start of epoch cleanup
ocserv[16708]: TLS[<4>]: REC[0x1a01d60]: End of epoch cleanup
ocserv[16708]: TLS[<4>]: REC[0x1a01d60]: Epoch #1 freed
ocserv[16696]: main: 175.96.129.217:2312 main-misc.c:414: command socket closed
ocserv[16696]: main: 175.96.129.217:2312 removing client '' with id '16708'
------

And here is part of nslcd's log
------
nslcd: [495cff] DEBUG: connection from pid=16697 uid=0 gid=0
nslcd: [495cff] <passwd="MY_USER_NAME"> DEBUG:
myldap_search(base="dc=******,dc=******",
filter="(&(objectClass=posixAccount)(uid=MY_USER_NAME))")
nslcd: [495cff] <passwd="MY_USER_NAME"> DEBUG: ldap_result():
cn=MY_USER_NAME,ou=Users,dc=******,dc=******
nslcd: [495cff] <passwd="MY_USER_NAME"> DEBUG: ldap_result(): end of
results (1 total)
nslcd: [e8944a] DEBUG: connection from pid=16697 uid=0 gid=0
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG:
myldap_search(base="dc=******,dc=******",
filter="(&(objectClass=posixGroup)(gidNumber=MY_USER_GROUP))")
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG: ldap_initialize(ldap://127.0.0.1)
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG: ldap_set_rebind_proc()
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG:
ldap_set_option(LDAP_OPT_PROTOCOL_VERSION,3)
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG: ldap_set_option(LDAP_OPT_DEREF,0)
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG:
ldap_set_option(LDAP_OPT_TIMELIMIT,0)
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG: ldap_set_option(LDAP_OPT_TIMEOUT,0)
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG:
ldap_set_option(LDAP_OPT_NETWORK_TIMEOUT,0)
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG:
ldap_set_option(LDAP_OPT_REFERRALS,LDAP_OPT_ON)
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG:
ldap_set_option(LDAP_OPT_RESTART,LDAP_OPT_ON)
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG:
ldap_simple_bind_s(NULL,NULL) (uri="ldap://127.0.0.1")
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG: ldap_result():
cn=User,dc=******,dc=******
nslcd: [e8944a] <group=MY_USER_GROUP> DEBUG: ldap_result(): end of
results (1 total)
------

<pingu8007(a)gmail.com>