[Samba] Samba Member NT_STATUS_NETWORK_SESSION_EXPIRED

Mon Oct 3 16:54:45 UTC 2016

On Mon, 3 Oct 2016 17:56:07 +0200
Oliver Werner <oliver.werner at kontrast.de> wrote:

> hey,
> 
> now after observe last changes on the weekend… i have also the issue.
> 
> After 10 hours i can’t connect to the shares on my member server.
> 
> On Log of DC i found this:
> 
> [2016/10/02 20:35:45.601265,
> 3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
> Kerberos: AS-REQ PL0024$@HQ.KONTRAST from ipv4:<member-ip>:55578 for
> krbtgt/HQ.KONTRAST at HQ.KONTRAST [2016/10/02 20:35:45.605069,
> 3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
> Kerberos: No preauth found, returning PREAUTH-REQUIRED --
> PL0024$@HQ.KONTRAST [2016/10/02 20:35:45.605960,
> 3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
> Kerberos: AS-REQ PL0024$@HQ.KONTRAST from ipv4:<member-ip>:52659 for
> krbtgt/HQ.KONTRAST at HQ.KONTRAST [2016/10/02 20:35:45.610083,
> 3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
> Kerberos: Client sent patypes: encrypted-timestamp [2016/10/02
> 20:35:45.610128,
> 3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
> Kerberos: Looking for PKINIT pa-data -- PL0024$@HQ.KONTRAST
> [2016/10/02 20:35:45.610144,
> 3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
> Kerberos: Looking for ENC-TS pa-data -- PL0024$@HQ.KONTRAST
> [2016/10/02 20:35:45.610200,
> 3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
> Kerberos: ENC-TS Pre-authentication succeeded -- PL0024$@HQ.KONTRAST
> using arcfour-hmac-md5 [2016/10/02 20:35:45.617582,
> 3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
> Kerberos: AS-REQ authtime: 2016-10-02T20:35:45 starttime: unset
> endtime: 2016-10-03T06:35:45 renew till: 2016-10-09T20:35:45
> [2016/10/02 20:35:45.617699,
> 3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
> Kerberos: Client supported enctypes: aes256-cts-hmac-sha1-96,
> aes128-cts-hmac-sha1-96, des3-cbc-sha1, des3-cbc-md5,
> arcfour-hmac-md5, using arcfour-hmac-md5/arcfou r-hmac-md5
> [2016/10/02 20:35:45.617748,
> 3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
> Kerberos: Requested flags: renewable, forwardable [2016/10/02
> 20:35:45.619243,
> 3] ../source4/smbd/service_stream.c:66(stream_terminate_connection)
> Terminating connection - 'ldapsrv_call_loop:
> tstream_read_pdu_blob_recv() - NT_STATUS_CONNECTION_DISCONNECTED‘
> 
> 
> That looks ok, yes? When i see it means my member got a new ticket?
> But i found this on member:
> 
> [2016/10/03 17:50:03.311002, 10, pid=26714, effective(0, 0), real(0,
> 0),
> class=winbind] ../source3/winbindd/winbindd_dual.c:512(child_process_request)
> child_process_request: request fn NDRCMD [2016/10/03 17:50:03.311015,
> 10, pid=26714, effective(0, 0), real(0, 0),
> class=winbind] ../source3/winbindd/winbindd_dual_ndr.c:315(winbindd_dual_ndrcmd)
> winbindd_dual_ndrcmd: Running command WBINT_LOOKUPNAME (HQKONTRAST)
> [2016/10/03 17:50:03.311064, 10, pid=26714, effective(0, 0), real(0,
> 0),
> class=winbind] ../source3/winbindd/winbindd_cache.c:467(fetch_cache_seqnum)
> fetch_cache_seqnum: success [HQKONTRAST][4294967295 @ 1475509803]
> [2016/10/03 17:50:03.311081,  3, pid=26714, effective(0, 0), real(0,
> 0),
> class=winbind] ../source3/winbindd/winbindd_ads.c:1493(sequence_number)
> ads: fetch sequence_number for HQKONTRAST [2016/10/03
> 17:50:03.311119, 10, pid=26714, effective(0, 0), real(0, 0),
> class=winbind] ../source3/winbindd/winbindd_ads.c:230(ads_cached_connection)
> ads_cached_connection [2016/10/03 17:50:03.311191,
> 3] ../source3/libsmb/namequery.c:3117(get_dc_list) get_dc_list:
> preferred server list: "vl0227.hq.kontrast, *" [2016/10/03
> 17:50:03.321144,  3] ../source3/libads/ldap.c:618(ads_connect)
> Successfully contacted LDAP server  <DC-IP> [2016/10/03
> 17:50:03.321230,  3] ../source3/libsmb/namequery.c:3117(get_dc_list)
> get_dc_list: preferred server list: "vl0227.hq.kontrast,
> *" [2016/10/03 17:50:03.323699,
> 3] ../source3/libsmb/namequery.c:3117(get_dc_list) get_dc_list:
> preferred server list: "vl0227.hq.kontrast, *" [2016/10/03
> 17:50:03.328830,  3] ../source3/libsmb/namequery.c:3117(get_dc_list)
> get_dc_list: preferred server list: "vl0227.hq.kontrast,
> *" [2016/10/03 17:50:03.332100,
> 3] ../source3/libads/ldap.c:618(ads_connect) Successfully contacted
> LDAP server <DC-IP> [2016/10/03 17:50:03.332177,
> 3] ../source3/libsmb/namequery.c:3117(get_dc_list) get_dc_list:
> preferred server list: "vl0227.hq.kontrast, *" [2016/10/03
> 17:50:03.335277,  3] ../source3/libsmb/namequery.c:3117(get_dc_list)
> get_dc_list: preferred server list: "vl0227.hq.kontrast,
> *" [2016/10/03 17:50:03.343177,
> 3] ../source3/libads/ldap.c:618(ads_connect) Successfully contacted
> LDAP server  <DC-IP>5 [2016/10/03 17:50:03.343268,
> 3] ../source3/libads/ldap.c:661(ads_connect) Connected to LDAP server
> vl0227.hq.kontrast [2016/10/03 17:50:03.350195,
> 3] ../source3/libads/sasl.c:733(ads_sasl_spnego_bind)
> ads_sasl_spnego_bind: got OID=1.2.840.48018.1.2.2 [2016/10/03
> 17:50:03.350226,
> 3] ../source3/libads/sasl.c:733(ads_sasl_spnego_bind)
> ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2 [2016/10/03
> 17:50:03.350238,
> 3] ../source3/libads/sasl.c:733(ads_sasl_spnego_bind)
> ads_sasl_spnego_bind: got OID=1.3.6.1.4.1.311.2.2.10 [2016/10/03
> 17:50:03.379973,
> 0] ../source3/librpc/crypto/gse.c:341(gse_get_client_auth_token)
> gss_init_sec_context failed with [ The context has expired: Success]
> [2016/10/03 17:50:03.380079,
> 1] ../auth/gensec/spnego.c:623(gensec_spnego_create_negTokenInit)
> SPNEGO(gse_krb5) creating NEG_TOKEN_INIT failed:
> NT_STATUS_INTERNAL_ERROR [2016/10/03 17:50:03.380131,
> 0] ../source3/libads/sasl.c:785(ads_sasl_spnego_bind) kinit succeeded
> but ads_sasl_spnego_gensec_bind(KRB5) failed: An internal error
> occurred. [2016/10/03 17:50:03.380176,  1, pid=26714, effective(0,
> 0), real(0, 0),
> class=winbind] ../source3/winbindd/winbindd_ads.c:136(ads_cached_connection_connect)
> ads_connect for domain HQKONTRAST failed: An internal error occurred.
> [2016/10/03 17:50:03.380272,  3, pid=26714, effective(0, 0), real(0,
> 0),
> class=winbind] ../source3/winbindd/winbindd_ads.c:1493(sequence_number)
> ads: fetch sequence_number for HQKONTRAST [2016/10/03
> 17:50:03.380291, 10, pid=26714, effective(0, 0), real(0, 0),
> class=winbind] ../source3/winbindd/winbindd_ads.c:230(ads_cached_connection)
> ads_cached_connection
> 
> 
> may this helps to find the problem :/

I have searched the logs on my DCs and a domain member and do not have
anything like the above in any of them.

It is now 19 days uptime on the domain member and this isn't unusual,
it only went down last time because of a power problem.

I repeat, I do not have this problem and the only difference between
your setup and mine (as far as I can see) is the PAM setup.

Rowland 