[Pkg-swan-devel] Bug#744858: strongswan: xauth-pam fails in libcharon-extra-plugins (5.1.2-4~bpo70+1

Tue Apr 15 14:59:49 UTC 2014

Package: strongswan
Version: 5.1.0-3~bpo70+1
Severity: normal

Dear Maintainer,

After upgrading to strongswan 5.1.2-4~bpo70+1 and installing libcharon-extra-plugins package 
which  provides the xauth-pam functions, it's not possible to authenticate with xauth-pam

Log files show 

/var/log/syslog

Apr 15 13:30:25 spycatcher charon: 16[ENC] parsed ID_PROT request 0 [ SA V V V V V V V V ]
Apr 15 13:30:25 spycatcher charon: 16[IKE] received NAT-T (RFC 3947) vendor ID
Apr 15 13:30:25 spycatcher charon: 16[IKE] received draft-ietf-ipsec-nat-t-ike-02 vendor ID
Apr 15 13:30:25 spycatcher charon: 16[IKE] received draft-ietf-ipsec-nat-t-ike-02\n vendor ID
Apr 15 13:30:25 spycatcher charon: 16[IKE] received draft-ietf-ipsec-nat-t-ike-00 vendor ID
Apr 15 13:30:25 spycatcher charon: 16[IKE] received XAuth vendor ID
Apr 15 13:30:25 spycatcher charon: 16[IKE] received Cisco Unity vendor ID
Apr 15 13:30:25 spycatcher charon: 16[IKE] received FRAGMENTATION vendor ID
Apr 15 13:30:25 spycatcher charon: 16[IKE] received DPD vendor ID
Apr 15 13:30:25 spycatcher charon: 16[IKE] 149.254.xxx.xxx is initiating a Main Mode IKE_SA
Apr 15 13:30:25 spycatcher charon: 16[ENC] generating ID_PROT response 0 [ SA V V V ]
Apr 15 13:30:25 spycatcher charon: 16[NET] sending packet: from 194.82.xxx.xxx[500] to 149.254.xxx.xxx[887] (136 bytes)
Apr 15 13:30:25 spycatcher charon: 04[NET] received packet: from 149.254.xxx.xxx[887] to 194.82.xxx.xxx[500] (228 bytes)
Apr 15 13:30:25 spycatcher charon: 04[ENC] parsed ID_PROT request 0 [ KE No NAT-D NAT-D ]
Apr 15 13:30:25 spycatcher charon: 04[IKE] remote host is behind NAT
Apr 15 13:30:25 spycatcher charon: 04[IKE] sending cert request for "C=CH, O=Work, CN=Work strongSwan CA"
Apr 15 13:30:25 spycatcher charon: 04[ENC] generating ID_PROT response 0 [ KE No CERTREQ NAT-D NAT-D ]
Apr 15 13:30:25 spycatcher charon: 04[NET] sending packet: from 194.82.xxx.xxx[500] to 149.254.xxx.xxx[887] (309 bytes)
Apr 15 13:30:26 spycatcher charon: 03[NET] received packet: from 149.254.xxx.xxx[37144] to 194.82.xxx.xxx[4500] (1260 bytes)
Apr 15 13:30:26 spycatcher charon: 03[ENC] parsed ID_PROT request 0 [ ID CERT SIG CERTREQ ]
Apr 15 13:30:26 spycatcher charon: 03[IKE] ignoring certificate request without data
Apr 15 13:30:26 spycatcher charon: 03[IKE] received end entity cert "C=CH, O=Work, CN=aed-nexus4"
Apr 15 13:30:26 spycatcher charon: 03[CFG] looking for XAuthInitRSA peer configs matching 194.82.xxx.xxx...149.254.xxx.xxx[C=CH, O=strongSwa
n, CN=aed-nexus4]
Apr 15 13:30:26 spycatcher charon: 03[CFG] selected peer config "ipad"
Apr 15 13:30:26 spycatcher charon: 03[CFG]   using certificate "C=CH, O=Work, CN=aed-nexus4"
Apr 15 13:30:26 spycatcher charon: 03[CFG]   using trusted ca certificate "C=CH, O=Work, CN=Work strongSwan CA"
Apr 15 13:30:26 spycatcher charon: 03[CFG] checking certificate status of "C=CH, O=Work, CN=aed-nexus4"
Apr 15 13:30:26 spycatcher charon: 03[CFG] certificate status is not available
Apr 15 13:30:26 spycatcher charon: 03[CFG]   reached self-signed root ca with a path length of 0
Apr 15 13:30:26 spycatcher charon: 03[IKE] authentication of 'C=CH, O=Work, CN=aed-nexus4' with RSA successful
Apr 15 13:30:26 spycatcher charon: 03[IKE] authentication of 'C=CH, O=Work, CN=vpn1.Work' (myself) successful
Apr 15 13:30:26 spycatcher charon: 03[IKE] sending end entity cert "C=CH, O=Work, CN=vpn1.Work"
Apr 15 13:30:26 spycatcher charon: 03[ENC] generating ID_PROT response 0 [ ID CERT SIG ]
Apr 15 13:30:26 spycatcher charon: 03[NET] sending packet: from 194.82.xxx.xxx[4500] to 149.254.xxx.xxx[37144] (1244 bytes)
Apr 15 13:30:26 spycatcher charon: 03[ENC] generating TRANSACTION request 1708039773 [ HASH CPRQ(X_USER X_PWD) ]
Apr 15 13:30:26 spycatcher charon: 03[NET] sending packet: from 194.82.xxx.xxx[4500] to 149.254.xxx.xxx[37144] (76 bytes)
Apr 15 13:30:26 spycatcher charon: 02[NET] received packet: from 149.254.xxx.xxx[37144] to 194.82.xxx.xxx[4500] (108 bytes)
Apr 15 13:30:26 spycatcher charon: 02[ENC] parsed INFORMATIONAL_V1 request 2643138295 [ HASH N(INITIAL_CONTACT) ]
Apr 15 13:30:26 spycatcher charon: 01[NET] received packet: from 149.254.xxx.xxx[37144] to 194.82.xxx.xxx[4500] (108 bytes)
Apr 15 13:30:26 spycatcher charon: 01[ENC] parsed TRANSACTION response 1708039773 [ HASH CPRP(X_USER X_PWD) ]
Apr 15 13:30:29 spycatcher charon: 01[IKE] XAuth pam_authenticate for 'dawsona' failed: Authentication failure
Apr 15 13:30:29 spycatcher charon: 01[IKE] XAuth authentication of 'dawsona' failed
Apr 15 13:30:29 spycatcher charon: 01[ENC] generating TRANSACTION request 761923766 [ HASH CPS(X_STATUS) ]
Apr 15 13:30:29 spycatcher charon: 01[NET] sending packet: from 194.82.xxx.xxx[4500] to 149.254.xxx.xxx[37144] (76 bytes)
Apr 15 13:30:32 spycatcher charon: 12[NET] received packet: from 149.254.xxx.xxx[37144] to 194.82.xxx.xxx[4500] (92 bytes)
Apr 15 13:30:32 spycatcher charon: 12[ENC] parsed TRANSACTION response 761923766 [ HASH CPA(X_STATUS) ]
Apr 15 13:30:32 spycatcher charon: 12[IKE] destroying IKE_SA after failed XAuth authentication

And from /var/log/auth.log

After downgrading to 

strongswan 5.1.0-3~bpo70+1

xauth-pam authentication works again.

I'm using pam_winbind, but no changes have been made to pam_winbind and all tests with wbinfo report success.

After downgrading 

/var/log/syslog shows

Apr 15 15:34:07 spycatcher charon: 10[NET] received packet: from 149.254.xxx.xxx[865] to 194.82.xxx.xxx[500] (476 bytes)
Apr 15 15:34:07 spycatcher charon: 10[ENC] parsed ID_PROT request 0 [ SA V V V V V V V V ]
Apr 15 15:34:07 spycatcher charon: 10[IKE] received NAT-T (RFC 3947) vendor ID
Apr 15 15:34:07 spycatcher charon: 10[IKE] received draft-ietf-ipsec-nat-t-ike-02 vendor ID
Apr 15 15:34:07 spycatcher charon: 10[IKE] received draft-ietf-ipsec-nat-t-ike-02\n vendor ID
Apr 15 15:34:07 spycatcher charon: 10[IKE] received draft-ietf-ipsec-nat-t-ike-00 vendor ID
Apr 15 15:34:07 spycatcher charon: 10[IKE] received XAuth vendor ID
Apr 15 15:34:07 spycatcher charon: 10[IKE] received Cisco Unity vendor ID
Apr 15 15:34:07 spycatcher charon: 10[IKE] received FRAGMENTATION vendor ID
Apr 15 15:34:07 spycatcher charon: 10[IKE] received DPD vendor ID
Apr 15 15:34:07 spycatcher charon: 10[IKE] 149.254.xxx.xxx is initiating a Main Mode IKE_SA
Apr 15 15:34:07 spycatcher charon: 10[ENC] generating ID_PROT response 0 [ SA V V V ]
Apr 15 15:34:07 spycatcher charon: 10[NET] sending packet: from 194.82.xxx.xxx[500] to 149.254.xxx.xxx[865] (136 bytes)
Apr 15 15:34:07 spycatcher charon: 11[NET] received packet: from 149.254.xxx.xxx[865] to 194.82.xxx.xxx[500] (228 bytes)
Apr 15 15:34:07 spycatcher charon: 11[ENC] parsed ID_PROT request 0 [ KE No NAT-D NAT-D ]
Apr 15 15:34:07 spycatcher charon: 11[IKE] remote host is behind NAT
Apr 15 15:34:07 spycatcher charon: 11[IKE] sending cert request for "C=CH, O=Work, CN=Work strongSwan CA"
Apr 15 15:34:07 spycatcher charon: 11[ENC] generating ID_PROT response 0 [ KE No CERTREQ NAT-D NAT-D ]
Apr 15 15:34:07 spycatcher charon: 11[NET] sending packet: from 194.82.xxx.xxx[500] to 149.254.xxx.xxx[865] (309 bytes)
Apr 15 15:34:08 spycatcher charon: 01[NET] received packet: from 149.254.xxx.xxx[61698] to 194.82.xxx.xxx[4500] (1260 bytes)
Apr 15 15:34:08 spycatcher charon: 01[ENC] parsed ID_PROT request 0 [ ID CERT SIG CERTREQ ]
Apr 15 15:34:08 spycatcher charon: 01[IKE] ignoring certificate request without data
Apr 15 15:34:08 spycatcher charon: 01[IKE] received end entity cert "C=CH, O=Work, CN=aed-nexus4"
Apr 15 15:34:08 spycatcher charon: 01[CFG] looking for XAuthInitRSA peer configs matching 194.82.xxx.xxx...149.254.xxx.xxx[C=CH, O=Work, CN=aed-nexus4]
Apr 15 15:34:08 spycatcher charon: 01[CFG] selected peer config "ipad"
Apr 15 15:34:08 spycatcher charon: 01[CFG]   using certificate "C=CH, O=Work, CN=aed-nexus4"
Apr 15 15:34:08 spycatcher charon: 01[CFG]   using trusted ca certificate "C=CH, O=Work, CN=Work strongSwan CA"
Apr 15 15:34:08 spycatcher charon: 01[CFG] checking certificate status of "C=CH, O=Work, CN=aed-nexus4"
Apr 15 15:34:08 spycatcher charon: 01[CFG] certificate status is not available
Apr 15 15:34:08 spycatcher charon: 01[CFG]   reached self-signed root ca with a path length of 0
Apr 15 15:34:08 spycatcher charon: 01[IKE] authentication of 'C=CH, O=Work, CN=aed-nexus4' with RSA successful
Apr 15 15:34:08 spycatcher charon: 01[IKE] authentication of 'C=CH, O=Work, CN=vpn1.Work' (myself) successful
Apr 15 15:34:08 spycatcher charon: 01[IKE] sending end entity cert "C=CH, O=Work, CN=vpn1.Work"
Apr 15 15:34:08 spycatcher charon: 01[ENC] generating ID_PROT response 0 [ ID CERT SIG ]
Apr 15 15:34:08 spycatcher charon: 01[NET] sending packet: from 194.82.xxx.xxx[4500] to 149.254.xxx.xxx[61698] (1244 bytes)
Apr 15 15:34:08 spycatcher charon: 01[ENC] generating TRANSACTION request 858908818 [ HASH CP ]
Apr 15 15:34:08 spycatcher charon: 01[NET] sending packet: from 194.82.xxx.xxx[4500] to 149.254.xxx.xxx[61698] (76 bytes)
Apr 15 15:34:08 spycatcher charon: 04[NET] received packet: from 149.254.xxx.xxx[61698] to 194.82.xxx.xxx[4500] (108 bytes)
Apr 15 15:34:08 spycatcher charon: 04[ENC] parsed INFORMATIONAL_V1 request 4246005032 [ HASH N(INITIAL_CONTACT) ]
Apr 15 15:34:08 spycatcher charon: 13[NET] received packet: from 149.254.xxx.xxx[61698] to 194.82.xxx.xxx[4500] (108 bytes)
Apr 15 15:34:08 spycatcher charon: 13[ENC] parsed TRANSACTION response 858908818 [ HASH CP ]
Apr 15 15:34:09 spycatcher charon: 13[IKE] PAM authentication of 'dawsona' successful
Apr 15 15:34:09 spycatcher charon: 13[IKE] XAuth authentication of 'dawsona' successful
Apr 15 15:34:09 spycatcher charon: 13[IKE] deleting duplicate IKE_SA for peer 'dawsona' due to uniqueness policy
Apr 15 15:34:09 spycatcher charon: 13[IKE] deleting IKE_SA ipad[2] between 194.82.xxx.xxx[C=CH, O=Work, CN=vpn1.Work]...149.254.xxx.xxx[C=CH, O=Work, CN=aed-nexus4]
Apr 15 15:34:09 spycatcher charon: 13[IKE] sending DELETE for IKE_SA ipad[2]
Apr 15 15:34:09 spycatcher charon: 13[ENC] generating INFORMATIONAL_V1 request 3401085219 [ HASH D ]
Apr 15 15:34:09 spycatcher charon: 13[NET] sending packet: from 194.82.xxx.xxx[4500] to 149.254.xxx.xxx[61698] (92 bytes)
Apr 15 15:34:09 spycatcher charon: 13[CFG] lease 10.128.13.1 by 'dawsona' went offline
Apr 15 15:34:09 spycatcher charon: 13[ENC] generating TRANSACTION request 703485922 [ HASH CP ]
Apr 15 15:34:09 spycatcher charon: 13[NET] sending packet: from 194.82.xxx.xxx[4500] to 149.254.xxx.xxx[61698] (76 bytes)
Apr 15 15:34:09 spycatcher charon: 15[NET] received packet: from 149.254.xxx.xxx[61698] to 194.82.xxx.xxx[4500] (92 bytes)
Apr 15 15:34:09 spycatcher charon: 15[ENC] parsed TRANSACTION response 703485922 [ HASH CP ]
Apr 15 15:34:09 spycatcher charon: 15[IKE] IKE_SA ipad[3] established between 194.82.xxx.xxx[C=CH, O=Work, CN=vpn1.Work]...149.254.xxx.xxx[C=CH, O=Work, CN=aed-nexus4]
Apr 15 15:34:09 spycatcher charon: 12[NET] received packet: from 149.254.xxx.xxx[61698] to 194.82.xxx.xxx[4500] (124 bytes)
Apr 15 15:34:09 spycatcher charon: 12[ENC] parsed TRANSACTION request 3056136644 [ HASH CP ]
Apr 15 15:34:09 spycatcher charon: 12[IKE] peer requested virtual IP %any
Apr 15 15:34:09 spycatcher charon: 12[CFG] reassigning offline lease to 'dawsona'
Apr 15 15:34:09 spycatcher charon: 12[IKE] assigning virtual IP 10.128.13.1 to peer 'dawsona'
Apr 15 15:34:09 spycatcher charon: 12[ENC] generating TRANSACTION response 3056136644 [ HASH CP ]
Apr 15 15:34:09 spycatcher charon: 12[NET] sending packet: from 194.82.xxx.xxx[4500] to 149.254.xxx.xxx[61698] (92 bytes)
Apr 15 15:34:10 spycatcher charon: 05[NET] received packet: from 149.254.xxx.xxx[61698] to 194.82.xxx.xxx[4500] (364 bytes)
Apr 15 15:34:10 spycatcher charon: 05[ENC] parsed QUICK_MODE request 4260544190 [ HASH SA No ID ID ]
Apr 15 15:34:10 spycatcher charon: 05[IKE] received 28800s lifetime, configured 0s
Apr 15 15:34:10 spycatcher charon: 05[IKE] detected rekeying of CHILD_SA ipad{2}
Apr 15 15:34:10 spycatcher charon: 05[ENC] generating QUICK_MODE response 4260544190 [ HASH SA No ID ID ]
Apr 15 15:34:10 spycatcher charon: 05[NET] sending packet: from 194.82.xxx.xxx[4500] to 149.254.xxx.xxx[61698] (172 bytes)
Apr 15 15:34:10 spycatcher charon: 16[NET] received packet: from 149.254.xxx.xxx[61698] to 194.82.xxx.xxx[4500] (76 bytes)
Apr 15 15:34:10 spycatcher charon: 16[ENC] parsed QUICK_MODE request 4260544190 [ HASH ]
Apr 15 15:34:10 spycatcher charon: 16[IKE] CHILD_SA ipad{2} established with SPIs c06c1e4f_i 098919a1_o and TS 0.0.0.0/0 === 10.128.13.1/32

And 

/var/log/auth.log shows

Apr 15 15:33:41 spycatcher charon: 16[IKE] 149.254.xxx.xxx is initiating a Main Mode IKE_SA
Apr 15 15:33:42 spycatcher charon: pam_unix(login:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost=  user=dawsona
Apr 15 15:33:42 spycatcher charon: pam_winbind(login:auth): Verify user 'dawsona'
Apr 15 15:33:42 spycatcher charon: pam_winbind(login:auth): PAM config: krb5_ccache_type 'FILE'
Apr 15 15:33:42 spycatcher charon: pam_winbind(login:auth): user 'dawsona' granted access
Apr 15 15:33:42 spycatcher charon: pam_winbind(login:auth): Returned user was 'dawsona'
Apr 15 15:33:44 spycatcher charon: 01[IKE] IKE_SA ipad[2] established between 194.82.xxx.xxx[C=CH, O=Work, CN=vpn1.Work]...149.254.xxx.xxx[C=CH, O=Work, CN=aed-nexus4]
Apr 15 15:33:46 spycatcher charon: 05[IKE] CHILD_SA ipad{2} established with SPIs cd46bc6c_i 080588bf_o and TS 0.0.0.0/0 === 10.128.13.1/32 
Apr 15 15:34:07 spycatcher charon: 10[IKE] 149.254.xxx.xxx is initiating a Main Mode IKE_SA
Apr 15 15:34:08 spycatcher charon: pam_unix(login:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost=  user=dawsona
Apr 15 15:34:08 spycatcher charon: pam_winbind(login:auth): Verify user 'dawsona'
Apr 15 15:34:08 spycatcher charon: pam_winbind(login:auth): PAM config: krb5_ccache_type 'FILE'
Apr 15 15:34:09 spycatcher charon: pam_winbind(login:auth): user 'dawsona' granted access
Apr 15 15:34:09 spycatcher charon: pam_winbind(login:auth): Returned user was 'dawsona'
Apr 15 15:34:09 spycatcher charon: 13[IKE] deleting IKE_SA ipad[2] between 194.82.xxx.xxx[C=CH, O=Work, CN=vpn1.Work]...149.254.xxx.xxx[C=CH, O=Work, CN=aed-nexus4]
Apr 15 15:34:09 spycatcher charon: 15[IKE] IKE_SA ipad[3] established between 194.82.xxx.xxx[C=CH, O=Work, CN=vpn1.Work]...149.254.xxx.xxx[C=CH, O=Work, CN=aed-nexus4]
Apr 15 15:34:10 spycatcher charon: 16[IKE] CHILD_SA ipad{2} established with SPIs c06c1e4f_i 098919a1_o and TS 0.0.0.0/0 === 10.128.13.1/32

-- System Information:
Debian Release: 7.4
  APT prefers stable
  APT policy: (500, 'stable')
Architecture: i386 (i686)

Kernel: Linux 3.2.0-4-686-pae (SMP w/1 CPU core)
Locale: LANG=en_GB.UTF-8, LC_CTYPE=en_GB.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash

-- no debconf information