[Samba] S4-Winbind dumping core on password

Tue Sep 17 16:31:59 MDT 2013

Samba4-winbind (sernet-samba-4.0.9) on RHEL 6.4 dumps core on password authentication for a domain user (su/sudo), and so domain password authentication fails.  The machine is a standalone server in a Windows AD (2008R2) domain.

PuTTY logins using GSSAPI work fine, kdestroy/kinit succeeds with AD password, but su'ing to the userid from a puttty session fails. The issue seems to be related to the following line from /var/log/secure:
pam_winbind(su:auth): request wbcLogonUser failed: WBC_ERR_AUTH_ERROR, 
PAM error: PAM_SYSTEM_ERR (4), NTSTATUS: NT_STATUS_IO_DEVICE_ERROR, 
Error message was: NT_STATUS_IO_DEVICE_ERROR

Adding pam_krb5 before pam_winbind avoids the issue of winbind dumping core, but then winbind does not refresh tickets, which is a requirement.  (Switching back to samba-3.6 works, but that takes away the shiny new features of samba-4 - winbind seems to communicate faster with AD, and we are testing smb2/smb3 performance improvements.)

It appears that the problem can be replicated reliably by using authconfig to enable Winbind authentication and to disable Kerberos authentication in RHEL 6.4.  Enabling both Winbind and Kerberos avoids the core dumping/domain password failures, but tickets are not refreshed.

Question is, are changes in samba 4.1RC likely to fix this issue, or does a separate bug need filing?  

Additional information follows:

Relevant lines from /var/log/secure:
myhostname sshd[10170]: pam_unix(sshd:session): session opened for user MYUSERNAME by (uid=0)
myhostname su: pam_unix(su:auth): authentication failure; logname=MYUSERNAME uid=1099990999 euid=0 tty=pts/0 ruser=MYUSERNAME rhost=  user=MYUSERNAME
myhostname su: pam_winbind(su:auth): getting password (0x00000390)
myhostname su: pam_winbind(su:auth): pam_get_item returned a password
myhostname su: pam_winbind(su:auth): request wbcLogonUser failed: WBC_ERR_AUTH_ERROR, PAM error: PAM_SYSTEM_ERR (4), NTSTATUS: NT_STATUS_IO_DEVICE_ERROR, Error message was: NT_STATUS_IO_DEVICE_ERROR
myhostname su: pam_winbind(su:auth): internal module error (retval = PAM_SYSTEM_ERR(4), user = 'MYUSERNAME')

Winbind configuration from smb.conf:

idmap config * : backend = hash
idmap config * : range = 100000000-100000000000

template homedir = /srv/misc/%D/%U
template shell = /bin/bash
winbind use default domain = Yes
allow trusted domains = No
winbind enum groups = No
winbind enum users = No
winbind nested groups = Yes
winbind refresh tickets = Yes
winbind offline logon = Yes
kerberos method = secrets and keytab

Relevant lines from log.wb-<domain> (data have been modified in minor ways to protect the innocent):

[2013/09/17 17:52:27.866486, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cm.c:499(set_domain_online_request)
  set_domain_online_request: called for domain MYDOMAIN
[2013/09/17 17:52:27.866525, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cm.c:534(set_domain_online_request)
  set_domain_online_request: domain MYDOMAIN was globally offline.
[2013/09/17 17:52:27.866558, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cm.c:499(set_domain_online_request)
  set_domain_online_request: called for domain MYDOMAIN
[2013/09/17 17:52:27.866604, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:874(account_lockout_policy_handler)
  account_lockout_policy_handler called
[2013/09/17 17:52:27.866648,  5, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:167(get_cache)
  get_cache: Setting ADS methods for domain MYDOMAIN
[2013/09/17 17:52:27.866701, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:459(fetch_cache_seqnum)
  fetch_cache_seqnum: success [MYDOMAIN][123469999 @ 1379459999]
[2013/09/17 17:52:27.866728, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:583(refresh_sequence_number)
  refresh_sequence_number: MYDOMAIN seq number is now 123469999
[2013/09/17 17:52:27.866794, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:624(centry_expired)
  centry_expired: Key LOC_POL/MYDOMAIN for domain MYDOMAIN is good.
[2013/09/17 17:52:27.866819, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:732(wcache_fetch)
  wcache_fetch: returning entry LOC_POL/MYDOMAIN for domain MYDOMAIN
[2013/09/17 17:52:27.866842, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:2910(lockout_policy)
  lockout_policy: [Cached] - cached info for domain MYDOMAIN status: NT_STATUS_OK
[2013/09/17 17:52:27.866910,  4, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:1549(fork_domain_child)
  child daemon request 13
[2013/09/17 17:52:27.866938, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:440(child_process_request)
  child_process_request: request fn PAM_AUTH
[2013/09/17 17:52:27.866962,  3, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_pam.c:1611(winbindd_dual_pam_auth)
  [10057]: dual pam auth MYDOMAIN\myusername
[2013/09/17 17:52:27.866990, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_pam.c:1653(winbindd_dual_pam_auth)
  winbindd_dual_pam_auth: domain: MYDOMAIN last was online
[2013/09/17 17:52:27.867012, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_pam.c:1097(winbindd_dual_pam_auth_kerberos)
  winbindd_dual_pam_auth_kerberos
[2013/09/17 17:52:27.867057, 10, pid=10086, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_pam.c:531(generate_krb5_ccache)
  using ccache: FILE:/tmp/krb5cc_1099990999
[2013/09/17 17:52:27.867202, 10, pid=10086, effective(1099990999, 0), real(1099990999, 0), class=winbind] ../source3/winbindd/winbindd_pam.c:634(winbindd_raw_kerberos_login)
  winbindd_raw_kerberos_login: uid is 1099990999
[2013/09/17 17:52:28.699693,  0] ../lib/util/fault.c:72(fault_report)
  ===============================================================
[2013/09/17 17:52:28.699727,  0] ../lib/util/fault.c:73(fault_report)
  INTERNAL ERROR: Signal 11 in pid 10086 (4.0.9-SerNet-RedHat-5.el6)
  Please read the Trouble-Shooting section of the Samba HOWTO
[2013/09/17 17:52:28.699756,  0] ../lib/util/fault.c:75(fault_report)
  ===============================================================
[2013/09/17 17:52:28.699779,  0] ../source3/lib/util.c:810(smb_panic_s3)
  PANIC (pid 10086): internal error
[2013/09/17 17:52:28.700255,  0] ../source3/lib/util.c:921(log_stack_trace)
  BACKTRACE: 25 stack frames:
   #0 /usr/lib64/samba/libsmbconf.so.0(log_stack_trace+0x2f) [0x7f8bca670e76]
   #1 /usr/lib64/samba/libsmbconf.so.0(smb_panic_s3+0x69) [0x7f8bca670fa4]
   #2 /usr/lib64/samba/libsamba-util.so.0(smb_panic+0x2d) [0x7f8bcf83ba11]
   #3 /usr/lib64/samba/libsamba-util.so.0(+0x19d3e) [0x7f8bcf83bd3e]
   #4 /lib64/libpthread.so.0(+0x3499a0f500) [0x7f8bcfc6c500]
   #5 /usr/lib64/samba/libkrb5-samba4.so.26(krb5_storage_free+0x18) [0x7f8bcd11104d]
   #6 /usr/lib64/samba/libkrb5-samba4.so.26(+0x3f80d) [0x7f8bcd0f980d]
   #7 /usr/lib64/samba/libkrb5-samba4.so.26(krb5_kt_end_seq_get+0x3a) [0x7f8bcd0f813e]
   #8 /usr/lib64/samba/libgse.so(+0x8fe2) [0x7f8bcb412fe2]
   #9 /usr/lib64/samba/libgse.so(gse_krb5_get_server_keytab+0x409) [0x7f8bcb41342d]
   #10 /usr/lib64/samba/libgse.so(+0xaf37) [0x7f8bcb414f37]
   #11 /usr/lib64/samba/libgensec.so.0(gensec_start_mech+0x122) [0x7f8bcc461b75]
   #12 /usr/lib64/samba/libgensec.so.0(gensec_start_mech_by_oid+0xe1) [0x7f8bcc463453]
   #13 /usr/sbin/winbindd(kerberos_return_pac+0x632) [0x7f8bd00c7ade]
   #14 /usr/sbin/winbindd(winbindd_dual_pam_auth+0x70a) [0x7f8bd00dcecf]
   #15 /usr/sbin/winbindd(+0x58546) [0x7f8bd00f4546]
   #16 /usr/sbin/winbindd(+0x587f1) [0x7f8bd00f47f1]
   #17 /usr/lib64/samba/libtevent.so.0(+0x4b0b) [0x7f8bcefdbb0b]
   #18 /usr/lib64/samba/libtevent.so.0(tevent_common_loop_immediate+0x133) [0x7f8bcefdb5e3]
   #19 /usr/lib64/samba/libsmbconf.so.0(run_events_poll+0x4c) [0x7f8bca691369]
   #20 /usr/lib64/samba/libsmbconf.so.0(+0x479b7) [0x7f8bca6919b7]
   #21 /usr/lib64/samba/libtevent.so.0(_tevent_loop_once+0x91) [0x7f8bcefda639]
   #22 /usr/sbin/winbindd(main+0xd02) [0x7f8bd00cae7e]
   #23 /lib64/libc.so.6(__libc_start_main+0xfd) [0x7f8bc8f49cdd]
   #24 /usr/sbin/winbindd(+0x22389) [0x7f8bd00be389]
[2013/09/17 17:52:28.700508,  0] ../source3/lib/dumpcore.c:317(dump_core)
  dumping core in /var/log/samba/cores/winbindd

Output of winbindd -V:
Version 4.0.9-SerNet-RedHat-5.el6

This machine was recently upgraded from Samba 3.6, having been joined to the domain using Samba 3.6.  After some initial failures, the server was stopped and restarted with only secrets.tdb retained from the 3.6 installation to 4.0.  The issue still persists.

This seems like a regression from Samba 3.6 to Samba 4.0, and a fix would be much appreciated.  As noted above, I am wondering if the changes in 4.1 are expected to fix this issue, or a separate bug needs filing. 

Thanks,
    Murthy