MS-CHAPv2 change password not working in master

16 Nov 2012

      Hi,

I downloaded git master yesterday to test the new MS-CHAPv2 change
password functionality.

My setup is a Cisco router with "passwd-expiry" setup with Cisco VPN
client for login, with FreeRadius to Windows AD through Winbind.

MS-CHAPv2 authentication works fine. Winbind and AD setup is right.
But testing the new passchange functionality by selecting "User must
change password at next logon" in the Windows user, the New password
windows popup in Cisco VPN client, but the change password process fails:
ntlm_auth said: Password-Change: No Password-Change-Error: Wrong
Password . .

Winbind logs also shows:
NT_STATUS_WRONG_PASSWORD

Looking into code I suppose the problem is something with the old NT
hash, but not an expert here. Any help would be apreciated.

In these logs the user is "NIMASTELECOM\testpw".
The current password is "y58R41ut8W" (expired).
And the new password used was "H6eEWu7r65tw38ert1".

Some radius logs:
===
# radiusd -X
radiusd: FreeRADIUS Version 3.0.0, for host x86_64-unknown-linux-gnu,
built on Nov 16 2012 at 01:46:19
Copyright (C) 1999-2012 The FreeRADIUS server project and contributors.
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE.
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License.
For more information about these matters, see the file named COPYRIGHT.
Starting - reading configuration files ...
......................................
Ready to process requests.
rad_recv: Access-Request packet from host 10.112.14.2 port 1645, id=127,
length=202
        User-Name = "NIMASTELECOM\\testpw"
        Calling-Station-Id = "217.126.166.195"
        MS-CHAP-Challenge = 0xdd2a98d3c3c69fb959df2f561d50d025
        MS-CHAP2-Response =
0x01007b0896de80c7098bac5566313c61d1b200000000000000003cc2724e1d2be6d1868df97bd0607859441dc99b5ef37af0
        NAS-Port-Type = Virtual
        Cisco-NAS-Port = "85.112.6.36"
        NAS-Port = 0
        NAS-Port-Id = "85.112.6.36"
        Service-Type = Login-User
        NAS-IP-Address = 10.112.14.2
        Event-Timestamp = "Nov 16 2012 10:39:06 CET"
(0) # Executing section authorize from file
/etc/raddb/sites-enabled/vpn_nimas_tk
(0)   group authorize {
(0)  - entering group authorize {...}
(0) mschap-vpn_nimas_tk : Found MS-CHAP attributes.  Setting 'Auth-Type 
= mschap-vpn_nimas_tk'
(0)   [mschap-vpn_nimas_tk] = ok
(0)   ? if (!control:Auth-Type)
(0) ? Evaluating !(control:Auth-Type) -> FALSE
(0)   ? if (!control:Auth-Type) -> FALSE
(0) detail-vpn_nimas_tk-auth :  expand:
/var/log/radius/radacct/vpn_nimas_tk-auth-%Y%m%d ->
/var/log/radius/radacct/vpn_nimas_tk-auth-20121116
(0) detail-vpn_nimas_tk-auth :
/var/log/radius/radacct/vpn_nimas_tk-auth-%Y%m%d expands to
/var/log/radius/radacct/vpn_nimas_tk-auth-20121116
(0) detail-vpn_nimas_tk-auth :  expand: %t -> Fri Nov 16 10:39:06 2012
(0)   [detail-vpn_nimas_tk-auth] = ok
(0) Found Auth-Type = MSCHAP
(0) # Executing group from file /etc/raddb/sites-enabled/vpn_nimas_tk
(0)   group MS-CHAP {
(0)  - entering group MS-CHAP {...}
(0) mschap-vpn_nimas_tk : Creating challenge hash with username: testpw
(0) mschap-vpn_nimas_tk : Client is using MS-CHAPv2 for testpw, we need
NT-Password
(0) mschap-vpn_nimas_tk :       expand:
--username=%{mschap-vpn_nimas_tk:User-Name} -> --username=testpw
(0) mschap-vpn_nimas_tk :       expand:
--domain=%{mschap-vpn_nimas_tk:NT-Domain} -> --domain=NIMASTELECOM
(0) mschap-vpn_nimas_tk : Creating challenge hash with username: testpw
(0) mschap-vpn_nimas_tk :       expand:
--challenge=%{mschap-vpn_nimas_tk:Challenge:-00} ->
--challenge=3550f7bf5746677f
(0) mschap-vpn_nimas_tk :       expand:
--nt-response=%{mschap-vpn_nimas_tk:NT-Response:-00} ->
--nt-response=3cc2724e1d2be6d1868df97bd0607859441dc99b5ef37af0
Exec-Program output: Must change password (0xc0000224)
Exec-Program-Wait: plaintext: Must change password (0xc0000224)
Exec-Program: returned: 1
(0) mschap-vpn_nimas_tk : ntlm_auth says Must change password (0xc0000224)
(0)   [mschap-vpn_nimas_tk] = reject
(0) Failed to authenticate the user.
(0) Login incorrect: [NIMASTELECOM\\testpw] (from client RMADTKNIMAS01
port 0 cli 217.126.166.195)
(0) Using Post-Auth-Type Reject
(0)   WARNING: Unknown value specified for Post-Auth-Type.  Cannot
perform requested action.
(0) Finished request 0.
Waking up in 0.9 seconds.
(0) Sending delayed reject
Sending Access-Reject of id 127 from 85.112.8.156 port 1812 to
10.112.14.2 port 1645
        MS-CHAP-Error = "\001E=648 R=0
C=47763c0a72e4fb2d546c9a413245f87b V=3 M=Password Expired"
Waking up in 4.9 seconds.
(0) Cleaning up request packet ID 127 with timestamp +14
Ready to process requests.
rad_recv: Access-Request packet from host 10.112.14.2 port 1645, id=128,
length=755
        User-Name = "NIMASTELECOM\\testpw"
        MS-CHAP-Challenge = 0xf42a98d3c3c69fb959df2f561d50d025
        MS-CHAP2-CPW =
0x070100000000000000000000000000000000b79a22699ae1dedc832935c8f5c5d7880000000000000000b0bfd263d6c0bbc0b2b28e085c072676857cf1f7c6f88a300000
        MS-CHAP-NT-Enc-PW =
0x0601000176116065c54f9ef590a62a9e5d90a75e906e19b76954e1ff0deeb5f3a5212f64e16adf48e0f1e3bb2cd3c3889dac2d67b6584725b87c28d1612fdedf8268e3af3096a2c596ea8efb16697a10b5e726a86e457a84669c6ec82cfc67a301ff9d329b0ef45b96084d099823105412e0779971079efc9260b6ab1805df81b10f3fa65d4aa859beeaae01f0a2311f51bfc9c84f0168b595fa80273b6a08180e83ec63f03a6face5015ccb52114017
        MS-CHAP-NT-Enc-PW =
0x060100025ddd392405df3b0952a11ad2158f1c26398cdd6f2eb4be40607ff1fe81fc1e4f335e9b1a8a8a4a081f4b6834fe8e8d024ae1c80da758057f9505f8dff2a0211dd68d67fea4cb6de33f582be526fb0698669878264cb7ab61883a4caa4e4bc60f5421496218319c3ad4c0210383edc4daf25f43a55002d8014c287659c32cdbc6a43e0dc01c2c2effc7aa43267a0cf5c2100b4d25de0408559dd012496716837562ff79032b2f1671cd85d582
        MS-CHAP-NT-Enc-PW =
0x060100030c2cb9971bac6562e7e0615b9d89c703e7bbd4e0765af7c420590cd3b6d0149ab90d95b03f56e543759da80aea68ca44bf4b7514a1f2550fa2be6571c1639fd67738d2351a248f43f7ce4e1c552cf769416be4b6b78e7c1f49b32e5f2b7421acebab117a2009ccb87e0170cd30b31024a331920c5c2891a939ec22061af7fad85140a0bd99e89c3c6d56a3e9eb3a8025d5ef968ba7523c78f11bb43cd49936d2b28d289788d164b507a76fb6
        NAS-Port-Type = Virtual
        Cisco-NAS-Port = "85.112.6.36"
        NAS-Port = 0
        NAS-Port-Id = "85.112.6.36"
        Service-Type = Login-User
        NAS-IP-Address = 10.112.14.2
        Event-Timestamp = "Nov 16 2012 10:39:20 CET"
(1) # Executing section authorize from file
/etc/raddb/sites-enabled/vpn_nimas_tk
(1)   group authorize {
(1)  - entering group authorize {...}
(1) mschap-vpn_nimas_tk : Found MS-CHAP attributes.  Setting 'Auth-Type 
= mschap-vpn_nimas_tk'
(1)   [mschap-vpn_nimas_tk] = ok
(1)   ? if (!control:Auth-Type)
(1) ? Evaluating !(control:Auth-Type) -> FALSE
(1)   ? if (!control:Auth-Type) -> FALSE
(1) detail-vpn_nimas_tk-auth :  expand:
/var/log/radius/radacct/vpn_nimas_tk-auth-%Y%m%d ->
/var/log/radius/radacct/vpn_nimas_tk-auth-20121116
(1) detail-vpn_nimas_tk-auth :
/var/log/radius/radacct/vpn_nimas_tk-auth-%Y%m%d expands to
/var/log/radius/radacct/vpn_nimas_tk-auth-20121116
(1) detail-vpn_nimas_tk-auth :  expand: %t -> Fri Nov 16 10:39:20 2012
(1)   [detail-vpn_nimas_tk-auth] = ok
(1) Found Auth-Type = MSCHAP
(1) # Executing group from file /etc/raddb/sites-enabled/vpn_nimas_tk
(1)   group MS-CHAP {
(1)  - entering group MS-CHAP {...}
(1) mschap-vpn_nimas_tk : MS-CHAPv2 password change request received
(1) mschap-vpn_nimas_tk : Password change payload valid
(1) mschap-vpn_nimas_tk : Doing MS-CHAPv2 password change via ntlm_auth
helper
(1) mschap-vpn_nimas_tk :       expand: username:
%{mschap-vpn_nimas_tk:User-Name} -> username: testpw
(1) mschap-vpn_nimas_tk :       expand: nt-domain:
%{mschap-vpn_nimas_tk:NT-Domain} -> nt-domain: NIMASTELECOM
(1) mschap-vpn_nimas_tk : ntlm_auth said: Password-Change: No
Password-Change-Error: Wrong Password . .
(1) mschap-vpn_nimas_tk : ntlm auth password change failed:
Password-Change-Error: Wrong Password
(1) mschap-vpn_nimas_tk : Password change failed
(1)   [mschap-vpn_nimas_tk] = reject
(1) Failed to authenticate the user.
(1) Login incorrect: [NIMASTELECOM\\testpw] (from client RMADTKNIMAS01
port 0)
(1) Using Post-Auth-Type Reject
(1)   WARNING: Unknown value specified for Post-Auth-Type.  Cannot
perform requested action.
(1) Finished request 1.
Waking up in 0.2 seconds.
Waking up in 0.7 seconds.
(1) Sending delayed reject
Sending Access-Reject of id 128 from 85.112.8.156 port 1812 to
10.112.14.2 port 1645
        MS-CHAP-Error = "\001E=709 R=0 M=Password change failed"
Waking up in 4.9 seconds.
(1) Cleaning up request packet ID 128 with timestamp +28
Ready to process requests.
===

The mschap derived module is simple:
===
mschap mschap-vpn_nimas_tk {
        with_ntdomain_hack = yes
        ntlm_auth = "/usr/bin/ntlm_auth --request-nt-key
--username=%{mschap-vpn_nimas_tk:User-Name}
--domain=%{mschap-vpn_nimas_tk:NT-Domain}
--challenge=%{mschap-vpn_nimas_tk:Challenge:-00}
--nt-response=%{mschap-vpn_nimas_tk:NT-Response:-00}"

        passchange {
                ntlm_auth = "/usr/bin/ntlm_auth -d 10 -l /var/log/samba
--helper-protocol=ntlm-change-password-1"
                ntlm_auth_username = "username:
%{mschap-vpn_nimas_tk:User-Name}"
                ntlm_auth_domain = "nt-domain:
%{mschap-vpn_nimas_tk:NT-Domain}"
        retry_msg = "Re-enter (or reset) the password"
}
===

Winbind logs:
===
[2012/11/16 10:39:06.810639,  6] winbindd/winbindd.c:794(new_connection)
  accepted socket 25
[2012/11/16 10:39:06.810793, 10] winbindd/winbindd.c:644(process_request)
  process_request: request fn INTERFACE_VERSION
[2012/11/16 10:39:06.810841,  3]
winbindd/winbindd_misc.c:384(winbindd_interface_version)
  [ 9918]: request interface version
[2012/11/16 10:39:06.810906, 10]
winbindd/winbindd.c:740(winbind_client_response_written)
  winbind_client_response_written[9918:INTERFACE_VERSION]: delivered
response to client
[2012/11/16 10:39:06.810964, 10] winbindd/winbindd.c:644(process_request)
  process_request: request fn WINBINDD_PRIV_PIPE_DIR
[2012/11/16 10:39:06.811002,  3]
winbindd/winbindd_misc.c:417(winbindd_priv_pipe_dir)
  [ 9918]: request location of privileged pipe
[2012/11/16 10:39:06.811068, 10]
winbindd/winbindd.c:740(winbind_client_response_written)
  winbind_client_response_written[9918:WINBINDD_PRIV_PIPE_DIR]:
delivered response to client
[2012/11/16 10:39:06.811117,  6]
winbindd/winbindd.c:842(winbind_client_request_read)
  closing socket 25, client exited
[2012/11/16 10:39:06.811171,  6] winbindd/winbindd.c:794(new_connection)
  accepted socket 25
[2012/11/16 10:39:06.811227, 10] winbindd/winbindd.c:617(process_request)
  process_request: Handling async request 9918:PAM_AUTH_CRAP
[2012/11/16 10:39:06.811266,  3]
winbindd/winbindd_pam_auth_crap.c:56(winbindd_pam_auth_crap_send)
  [ 9918]: pam auth crap domain: [NIMASTELECOM] user: testpw
[2012/11/16 10:39:07.071142, 10] winbindd/winbindd.c:679(wb_request_done)
  wb_request_done[9918:PAM_AUTH_CRAP]: NT_STATUS_PASSWORD_MUST_CHANGE
[2012/11/16 10:39:07.071243, 10]
winbindd/winbindd.c:740(winbind_client_response_written)
  winbind_client_response_written[9918:PAM_AUTH_CRAP]: delivered
response to client
[2012/11/16 10:39:07.071320,  6]
winbindd/winbindd.c:842(winbind_client_request_read)
  closing socket 25, client exited
[2012/11/16 10:39:20.825567,  6] winbindd/winbindd.c:794(new_connection)
  accepted socket 25
[2012/11/16 10:39:20.825731, 10] winbindd/winbindd.c:644(process_request)
  process_request: request fn INTERFACE_VERSION
[2012/11/16 10:39:20.825780,  3]
winbindd/winbindd_misc.c:384(winbindd_interface_version)
  [ 9957]: request interface version
[2012/11/16 10:39:20.825851, 10]
winbindd/winbindd.c:740(winbind_client_response_written)
  winbind_client_response_written[9957:INTERFACE_VERSION]: delivered
response to client
[2012/11/16 10:39:20.825916, 10] winbindd/winbindd.c:644(process_request)
  process_request: request fn WINBINDD_PRIV_PIPE_DIR
[2012/11/16 10:39:20.825960,  3]
winbindd/winbindd_misc.c:417(winbindd_priv_pipe_dir)
  [ 9957]: request location of privileged pipe
[2012/11/16 10:39:20.826035, 10]
winbindd/winbindd.c:740(winbind_client_response_written)
  winbind_client_response_written[9957:WINBINDD_PRIV_PIPE_DIR]:
delivered response to client
[2012/11/16 10:39:20.826106,  6]
winbindd/winbindd.c:842(winbind_client_request_read)
  closing socket 25, client exited
[2012/11/16 10:39:20.826169,  6] winbindd/winbindd.c:794(new_connection)
  accepted socket 25
[2012/11/16 10:39:20.826235, 10] winbindd/winbindd.c:644(process_request)
  process_request: request fn DOMAIN_NAME
[2012/11/16 10:39:20.826279,  3]
winbindd/winbindd_misc.c:394(winbindd_domain_name)
  [ 9957]: request domain name
[2012/11/16 10:39:20.826341, 10]
winbindd/winbindd.c:740(winbind_client_response_written)
  winbind_client_response_written[9957:DOMAIN_NAME]: delivered response
to client
[2012/11/16 10:39:20.826497, 10] winbindd/winbindd.c:617(process_request)
  process_request: Handling async request 9957:PAM_CHNG_PSWD_AUTH_CRAP
[2012/11/16 10:39:20.826544,  3]
winbindd/winbindd_pam_chng_pswd_auth_crap.c:57(winbindd_pam_chng_pswd_auth_crap_send)
  [ 9957]: pam change pswd auth crap domain: NIMASTELECOM user: testpw
[2012/11/16 10:39:20.856407, 10] winbindd/winbindd.c:679(wb_request_done)
  wb_request_done[9957:PAM_CHNG_PSWD_AUTH_CRAP]: NT_STATUS_WRONG_PASSWORD
[2012/11/16 10:39:20.856498, 10]
winbindd/winbindd.c:740(winbind_client_response_written)
  winbind_client_response_written[9957:PAM_CHNG_PSWD_AUTH_CRAP]:
delivered response to client
[2012/11/16 10:39:20.856674,  6]
winbindd/winbindd.c:842(winbind_client_request_read)
  closing socket 25, client exited
===

Regards,
Carlos Velasco