[Samba] After Update to 4.2, Samba is unusuable as member server / No user and goup resolution

Patrick G. Stoesser lists at pgs-info.de
Sat Apr 16 21:18:56 UTC 2016


Hello again,

no change here. But in the menatime I looked through the logfiles. 
Sorry, many of those lines are just cryptic to me. But maybe someone has 
an idea.

Thank you.

Again anonymized (domain names and IPs). Samba machine specific log seel 
below.

Connecting the passwd server and WINS seems to work.

Appearently errors:

Failed to setup SPNEGO negTokenInit request: NT_STATUS_INTERNAL_ERROR
ads reopen failed after error Time limit exceeded
enum_dom_groups ads_search: Time limit exceeded
Negative name query response, rcode 0x03: The name requested does not exist.


************************************************************************
log.wb-AD
************************************************************************

   Reopening ads connection to realm 'AD.TEST.LOC' after error Time 
limit exceeded
[2016/04/16 22:54:21.289277,  3] 
../source3/libsmb/namequery.c:3133(get_dc_list)
   get_dc_list: preferred server list: "dc5.ad.test.loc, dc5.ad.test.loc"
[2016/04/16 22:54:21.290348,  3] ../source3/libads/ldap.c:541(ads_connect)
   Successfully contacted LDAP server 129.206.15.144
[2016/04/16 22:54:21.290447,  3] 
../source3/libsmb/namequery.c:3133(get_dc_list)
   get_dc_list: preferred server list: "dc5.ad.test.loc, dc5.ad.test.loc"
[2016/04/16 22:54:21.290578,  3] 
../source3/libsmb/namequery.c:3133(get_dc_list)
   get_dc_list: preferred server list: "dc5.ad.test.loc, dc5.ad.test.loc"
[2016/04/16 22:54:21.292312,  3] ../source3/libads/ldap.c:541(ads_connect)
   Successfully contacted LDAP server 129.206.15.144
[2016/04/16 22:54:21.292408,  3] ../source3/libads/ldap.c:584(ads_connect)
   Connected to LDAP server dc5.ad.test.loc
[2016/04/16 22:54:21.294816,  3] 
../source3/libads/sasl.c:723(ads_sasl_spnego_bind)
   ads_sasl_spnego_bind: got OID=1.2.840.48018.1.2.2
[2016/04/16 22:54:21.294856,  3] 
../source3/libads/sasl.c:723(ads_sasl_spnego_bind)
   ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2
[2016/04/16 22:54:21.294878,  3] 
../source3/libads/sasl.c:723(ads_sasl_spnego_bind)
   ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2.3
[2016/04/16 22:54:21.294898,  3] 
../source3/libads/sasl.c:723(ads_sasl_spnego_bind)
   ads_sasl_spnego_bind: got OID=1.3.6.1.4.1.311.2.2.10
[2016/04/16 22:54:21.513455,  3] 
../source3/libads/ldap.c:904(ads_do_paged_search_args)
   ads_do_paged_search_args: 
ldap_search_with_timeout((&(objectCategory=group)(&(groupType:dn:1.2.840.113556.1.4.803:=-2147483648)(!(groupType:dn:1.2.840.113556.1.4.803:=1))))) 
-> Time limit exceeded
[2016/04/16 22:54:21.513684,  1] 
../source3/libads/ldap_utils.c:135(ads_do_search_retry_internal)
   ads reopen failed after error Time limit exceeded
[2016/04/16 22:54:21.513710,  1] 
../source3/winbindd/winbindd_ads.c:479(enum_dom_groups)
   enum_dom_groups ads_search: Time limit exceeded
[2016/04/16 22:54:51.549243,  3] 
../source3/winbindd/winbindd_cm.c:1947(connection_ok)
   connection_ok: Connection to dc5.ad.test.loc for domain AD is not 
connected
[2016/04/16 22:54:51.549486,  3] 
../source3/lib/util_sock.c:636(open_socket_out_send)
   Connecting to 129.206.15.144 at port 445
[2016/04/16 22:54:51.551095,  3] 
../source3/libsmb/cliconnect.c:1817(cli_session_setup_spnego_send)
   Doing spnego session setup (blob length=108)
[2016/04/16 22:54:51.551188,  3] 
../source3/libsmb/cliconnect.c:1844(cli_session_setup_spnego_send)
   got OID=1.2.840.48018.1.2.2
   got OID=1.2.840.113554.1.2.2
   got OID=1.2.840.113554.1.2.2.3
   got OID=1.3.6.1.4.1.311.2.2.10
[2016/04/16 22:54:51.551240,  3] 
../source3/libsmb/cliconnect.c:1854(cli_session_setup_spnego_send)
   got principal=not_defined_in_RFC4178 at please_ignore
[2016/04/16 22:54:51.551269,  3] 
../source3/libsmb/cliconnect.c:1721(cli_session_setup_get_principal)
   cli_session_setup_spnego: using target hostname not SPNEGO principal
[2016/04/16 22:54:51.551298,  3] 
../source3/libsmb/cliconnect.c:1736(cli_session_setup_get_principal)
   cli_session_setup_spnego: guessed server 
principal=cifs/dc5.ad.test.loc at AD.test.loc
[2016/04/16 22:58:01.571796,  3] 
../source3/winbindd/winbindd_msrpc.c:252(msrpc_name_to_sid)
   msrpc_name_to_sid: name=AD\ROOT
[2016/04/16 22:58:01.571853,  3] 
../source3/winbindd/winbindd_msrpc.c:266(msrpc_name_to_sid)
   name_to_sid [rpc] AD\ROOT for domain AD
[2016/04/16 22:58:01.575599,  3] 
../source3/lib/util_sock.c:636(open_socket_out_send)
   Connecting to 129.206.15.144 at port 135
[2016/04/16 22:58:01.577977,  3] 
../source3/lib/util_sock.c:636(open_socket_out_send)
   Connecting to 129.206.15.144 at port 49155
[2016/04/16 22:58:01.580495,  3] 
../source3/winbindd/winbindd_ads.c:1007(lookup_usergroups)
[2016/04/16 22:58:01.580495,  3] 
../source3/winbindd/winbindd_ads.c:1007(lookup_usergroups)
   ads: lookup_usergroups
[2016/04/16 22:58:01.580522,  3] 
../source3/winbindd/winbindd_util.c:1119(lookup_usergroups_cached)
   : lookup_usergroups_cached
[2016/04/16 22:58:01.580783,  3] 
../source3/libsmb/namequery.c:3133(get_dc_list)
   get_dc_list: preferred server list: "dc5.ad.test.loc, dc5.ad.test.loc"
[2016/04/16 22:58:01.580844,  3] 
../source3/libsmb/namequery.c:2296(resolve_lmhosts)
   resolve_lmhosts: Attempting lmhosts lookup for name dc5.ad.test.loc<0x20>
[2016/04/16 22:58:01.580862,  3] 
../libcli/nbt/lmhosts.c:185(resolve_lmhosts_file_as_sockaddr)
   resolve_lmhosts: Attempting lmhosts lookup for name dc5.ad.test.loc<0x20>
[2016/04/16 22:58:01.580933,  3] 
../source3/libsmb/namequery.c:2163(resolve_wins_send)
   resolve_wins: using WINS server 123.456.789.208 and tag '*'
[2016/04/16 22:58:01.580976,  3] 
../source3/libsmb/namequery.c:2163(resolve_wins_send)
   resolve_wins: using WINS server 129.206.15.144 and tag '*'
[2016/04/16 22:58:01.581009,  3] 
../lib/util/charset/convert_string.c:305(convert_string_handle)
   E2BIG: convert_string(UTF-8,CP850): srclen=25 destlen=16 - 
'DC5.AD.test.loc'
[2016/04/16 22:58:03.582397,  3] 
../lib/util/charset/convert_string.c:305(convert_string_handle)
   E2BIG: convert_string(UTF-8,CP850): srclen=25 destlen=16 - 
'DC5.AD.test.loc'
[2016/04/16 22:58:03.583259,  3] 
../source3/libsmb/namequery.c:1328(name_query_validator)
   Negative name query response, rcode 0x03: The name requested does not 
exist.
[2016/04/16 22:58:03.583338,  3] 
../source3/libsmb/namequery.c:2353(resolve_hosts)
   resolve_hosts: Attempting host lookup for name dc5.ad.test.loc<0x20>
[2016/04/16 22:58:03.585184,  3] ../source3/libads/ldap.c:541(ads_connect)
   Successfully contacted LDAP server 129.206.15.144
[2016/04/16 22:58:03.585288,  3] 
../source3/libsmb/namequery.c:3133(get_dc_list)
   get_dc_list: preferred server list: "dc5.ad.test.loc, dc5.ad.test.loc"
[2016/04/16 22:58:03.585394,  3] 
../source3/libsmb/namequery.c:3133(get_dc_list)
   get_dc_list: preferred server list: "dc5.ad.test.loc, dc5.ad.test.loc"
[2016/04/16 22:58:03.586266,  3] 
../source3/libsmb/namequery.c:3133(get_dc_list)
   get_dc_list: preferred server list: "dc5.ad.test.loc, dc5.ad.test.loc"
[2016/04/16 22:58:03.587052,  3] ../source3/libads/ldap.c:541(ads_connect)
   Successfully contacted LDAP server 129.206.15.144
[2016/04/16 22:58:03.587140,  3] 
../source3/libsmb/namequery.c:3133(get_dc_list)
   get_dc_list: preferred server list: "dc5.ad.test.loc, dc5.ad.test.loc"
[2016/04/16 22:58:03.587240,  3] 
../source3/libsmb/namequery.c:3133(get_dc_list)
   get_dc_list: preferred server list: "dc5.ad.test.loc, dc5.ad.test.loc"
[2016/04/16 22:58:03.588712,  3] ../source3/libads/ldap.c:541(ads_connect)
   Successfully contacted LDAP server 129.206.15.144
[2016/04/16 22:58:03.588814,  3] ../source3/libads/ldap.c:584(ads_connect)
   Connected to LDAP server dc5.ad.test.loc
[2016/04/16 22:58:03.591107,  3] 
../source3/libads/sasl.c:723(ads_sasl_spnego_bind)
   ads_sasl_spnego_bind: got OID=1.2.840.48018.1.2.2
[2016/04/16 22:58:03.591153,  3] 
../source3/libads/sasl.c:723(ads_sasl_spnego_bind)
   ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2
[2016/04/16 22:58:03.591176,  3] 
../source3/libads/sasl.c:723(ads_sasl_spnego_bind)
   ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2.3
[2016/04/16 22:58:03.591197,  3] 
../source3/libads/sasl.c:723(ads_sasl_spnego_bind)
   ads_sasl_spnego_bind: got OID=1.3.6.1.4.1.311.2.2.10
[2016/04/16 22:58:03.606696,  1] 
../auth/gensec/spnego.c:664(gensec_spnego_create_negTokenInit)
   Failed to setup SPNEGO negTokenInit request: NT_STATUS_INTERNAL_ERROR
[2016/04/16 22:58:03.871767,  3] 
../source3/winbindd/winbindd_ads.c:1132(lookup_usergroups)
   ads lookup_usergroups (tokenGroups) succeeded for 
sid=S-1-5-21-977923109-2952828257-175163757-50444
[2016/04/16 22:59:18.328783,  3] 
../source3/winbindd/winbindd_misc.c:161(winbindd_dual_list_trusted_domains)
   [ 3313]: list trusted domains
[2016/04/16 22:59:18.328860,  3] 
../source3/winbindd/winbindd_ads.c:1456(trusted_domains)
   ads: trusted_domains
[2016/04/16 23:04:18.428994,  3] 
../source3/winbindd/winbindd_misc.c:161(winbindd_dual_list_trusted_domains)
   [ 3313]: list trusted domains
[2016/04/16 23:04:18.429092,  3] 
../source3/winbindd/winbindd_ads.c:1456(trusted_domains)
   ads: trusted_domains
****************************************************************************************

And here is what happens, when a user tries to connect (Samba machine 
specific log). Appearently fails to match the user to the AD.


****************************************************************************************
Got user=[ur067] domain=[AD] workstation=[DWIRT-WISO-183] len1=24 len2=402
[2016/04/16 17:59:20.159563,  3] 
../source3/param/loadparm.c:3636(lp_load_ex)
   lp_load_ex: refreshing parameters
[2016/04/16 17:59:20.159609,  3] 
../source3/param/loadparm.c:527(init_globals)
   Initialising global parameters
[2016/04/16 17:59:20.159675,  3] 
../source3/param/loadparm.c:2579(lp_do_section)
   Processing section "[global]"
[2016/04/16 17:59:20.159848,  3] 
../source3/param/loadparm.c:1476(lp_add_ipc)
   adding IPC service
[2016/04/16 17:59:20.160041,  3] 
../source3/auth/auth.c:178(auth_check_ntlm_password)
   check_ntlm_password:  Checking password for unmapped user 
[AD]\[ur067]@[DWIRT-WISO-183] with the new password interface
[2016/04/16 17:59:20.160055,  3] 
../source3/auth/auth.c:181(auth_check_ntlm_password)
   check_ntlm_password:  mapped user is: [AD]\[ur067]@[DWIRT-WISO-183]
[2016/04/16 17:59:20.162558,  3] 
../source3/auth/auth_util.c:1229(check_account)
   Failed to find authenticated user AD\ur067 via getpwnam(), denying 
access.
[2016/04/16 17:59:20.162578,  2] 
../source3/auth/auth.c:315(auth_check_ntlm_password)
   check_ntlm_password:  Authentication for user [ur067] -> [ur067] 
FAILED with error NT_STATUS_NO_SUCH_USER
[2016/04/16 17:59:20.162597,  2] 
../auth/gensec/spnego.c:708(gensec_spnego_server_negTokenTarg)
   SPNEGO login failed: NT_STATUS_NO_SUCH_USER
[2016/04/16 17:59:20.198682,  3] 
../auth/ntlmssp/ntlmssp_util.c:69(debug_ntlmssp_flags)
   Got NTLMSSP neg_flags=0xe2088297
[2016/04/16 17:59:20.199641,  3] 
../auth/ntlmssp/ntlmssp_server.c:449(ntlmssp_server_preauth)
   Got user=[ur067] domain=[AD] workstation=[DWIRT-WISO-183] len1=24 
len2=402
[2016/04/16 17:59:20.199682,  3] 
../source3/param/loadparm.c:3636(lp_load_ex)
   lp_load_ex: refreshing parameters
[2016/04/16 17:59:20.199727,  3] 
../source3/param/loadparm.c:527(init_globals)
   Initialising global parameters
[2016/04/16 17:59:20.199793,  3] 
../source3/param/loadparm.c:2579(lp_do_section)
   Processing section "[global]"
[2016/04/16 17:59:20.199965,  3] 
../source3/param/loadparm.c:1476(lp_add_ipc)
   adding IPC service
[2016/04/16 17:59:20.200158,  3] 
../source3/auth/auth.c:178(auth_check_ntlm_password)
   check_ntlm_password:  Checking password for unmapped user 
[AD]\[ur067]@[DWIRT-WISO-183] with the new password interface
[2016/04/16 17:59:20.200171,  3] 
../source3/auth/auth.c:181(auth_check_ntlm_password)
   check_ntlm_password:  mapped user is: [AD]\[ur067]@[DWIRT-WISO-183]
[2016/04/16 17:59:20.202567,  3] 
../source3/auth/auth_util.c:1229(check_account)
   Failed to find authenticated user AD\ur067 via getpwnam(), denying 
access.
[2016/04/16 17:59:20.202595,  2] 
../source3/auth/auth.c:315(auth_check_ntlm_password)
   check_ntlm_password:  Authentication for user [ur067] -> [ur067] 
FAILED with error NT_STATUS_NO_SUCH_USER
[2016/04/16 17:59:20.202614,  2] 
../auth/gensec/spnego.c:708(gensec_spnego_server_negTokenTarg)
   SPNEGO login failed: NT_STATUS_NO_SUCH_USER
****************************************************************************************




More information about the samba mailing list