Attachment 12555 Details for Bug 12369 – gss_init_sec_context failed with [ The context has expired: Success]

gss_init_sec_context failed with [ The context has expired: Success]

samba-4.4.6-gss_init_sec_context failed.log (text/x-log), 7.68 KB, created by Klaus Braun on 2016-10-08 12:57:11 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Klaus Braun

Created: 2016-10-08 12:57:11 UTC

Size: 7.68 KB

patch

obsolete

>[2016/10/08 14:03:29.778723, 10, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:70(sitename_store)
>  sitename_store: realm = [MYDOMAIN], sitename = [Default-First-Site-Name], expire = [2085923199]
>[2016/10/08 14:03:29.778738, 10, pid=31418, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:308(gencache_set_data_blob)
>  Did not store value for AD_SITENAME/DOMAIN/MYDOMAIN, we already got it
>[2016/10/08 14:03:29.778745, 10, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:70(sitename_store)
>  sitename_store: realm = [mydomain.ads...], sitename = [Default-First-Site-Name], expire = [2085923199]
>[2016/10/08 14:03:29.778753, 10, pid=31418, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:308(gencache_set_data_blob)
>  Did not store value for AD_SITENAME/DOMAIN/MYDOMAIN.ADS..., we already got it
>[2016/10/08 14:03:29.778762,  3, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:618(ads_connect)
>  Successfully contacted LDAP server 10.3.4.18
>[2016/10/08 14:03:29.778769, 10, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:73(ldap_open_with_timeout)
>  Opening connection to LDAP server '10.3.4.18:389', timeout 15 seconds
>[2016/10/08 14:03:29.778794, 10, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:108(ldap_open_with_timeout)
>  Initialized connection for LDAP server 'ldap://10.3.4.18:389'
>[2016/10/08 14:03:29.778808,  3, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:661(ads_connect)
>  Connected to LDAP server pub-dc08.mydomain.ads...
>[2016/10/08 14:03:29.778814, 10, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:212(ads_closest_dc)
>  ads_closest_dc: NBT_SERVER_CLOSEST flag set
>[2016/10/08 14:03:29.778822, 10, pid=31418, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:88(saf_store)
>  saf_store: domain = [MYDOMAIN], server = [pub-dc08.mydomain.ads...], expire = [1475929109]
>[2016/10/08 14:03:29.778830, 10, pid=31418, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:308(gencache_set_data_blob)
>  Did not store value for SAF/DOMAIN/MYDOMAIN, we already got it
>[2016/10/08 14:03:29.778837, 10, pid=31418, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:88(saf_store)
>  saf_store: domain = [mydomain.ads...], server = [pub-dc08.mydomain.ads...], expire = [1475929109]
>[2016/10/08 14:03:29.778844, 10, pid=31418, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:308(gencache_set_data_blob)
>  Did not store value for SAF/DOMAIN/MYDOMAIN.ADS..., we already got it
>[2016/10/08 14:03:29.779861,  4, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:2980(ads_current_time)
>  KDC time offset is 0 seconds
>[2016/10/08 14:03:29.780245,  4, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:1105(ads_sasl_bind)
>  Found SASL mechanism GSS-SPNEGO
>[2016/10/08 14:03:29.780818,  3, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:733(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.3.6.1.4.1.311.2.2.30
>[2016/10/08 14:03:29.780829,  3, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:733(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.2.840.48018.1.2.2
>[2016/10/08 14:03:29.780834,  3, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:733(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2
>[2016/10/08 14:03:29.780838,  3, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:733(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2.3
>[2016/10/08 14:03:29.780843,  3, pid=31418, effective(0, 0), real(0, 0)] ../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/08 14:03:29.780912, 10, pid=31418, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:228(kerberos_kinit_password_ext)
>  kerberos_kinit_password: as CLIENT$@MYDOMAIN.ADS... using [MEMORY:ads_sasl_spnego_bind] as ccache and config [/usr/local/samba/var/lock/smb_krb5/krb5.conf.MYDOMAIN]
>[2016/10/08 14:03:29.935185,  5, pid=31418, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:680(gensec_start_mech)
>  Starting GENSEC mechanism spnego
>[2016/10/08 14:03:29.935228,  5, pid=31418, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:680(gensec_start_mech)
>  Starting GENSEC submechanism gse_krb5
>[2016/10/08 14:03:29.935909,  0, pid=31418, effective(0, 0), real(0, 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/08 14:03:29.936134,  1, pid=31418, effective(0, 0), real(0, 0)] ../auth/gensec/spnego.c:622(gensec_spnego_create_negTokenInit)
>  SPNEGO(gse_krb5) creating NEG_TOKEN_INIT failed: NT_STATUS_INTERNAL_ERROR
>[2016/10/08 14:03:29.936153, 10, pid=31418, effective(0, 0), real(0, 0)] ../auth/gensec/spnego.c:675(gensec_spnego_create_negTokenInit)
>  Failed to setup SPNEGO negTokenInit request: NT_STATUS_INTERNAL_ERROR
>[2016/10/08 14:03:29.936166,  0, pid=31418, effective(0, 0), real(0, 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/08 14:03:29.936188,  1, pid=31418, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_ads.c:136(ads_cached_connection_connect)
>  ads_connect for domain MYDOMAIN failed: An internal error occurred.
>[2016/10/08 14:03:29.936268, 10, pid=31418, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:575(refresh_sequence_number)
>  refresh_sequence_number: failed with NT_STATUS_UNSUCCESSFUL
>[2016/10/08 14:03:29.936291, 10, pid=31418, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:500(wcache_store_seqnum)
>  wcache_store_seqnum: success [MYDOMAIN][4294967295 @ 1475928209]
>[2016/10/08 14:03:29.936297, 10, pid=31418, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:587(refresh_sequence_number)
>  refresh_sequence_number: MYDOMAIN seq number is now -1
>[2016/10/08 14:03:29.936308, 10, pid=31418, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:397(wcache_server_down)
>  wcache_server_down: server for Domain MYDOMAIN down
>[2016/10/08 14:03:29.936314, 10, pid=31418, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:628(centry_expired)
>  centry_expired: Key NS/MYDOMAIN/USER for domain MYDOMAIN is good.
>[2016/10/08 14:03:29.936319, 10, pid=31418, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:736(wcache_fetch)
>  wcache_fetch: returning entry NS/MYDOMAIN/USER for domain MYDOMAIN
>[2016/10/08 14:03:29.936328, 10, pid=31418, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:1835(wcache_name_to_sid)
>  name_to_sid: [Cached] - cached name for domain MYDOMAIN status: NT_STATUS_OK
>[2016/10/08 14:03:29.936335,  1, pid=31418, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug)
>       wbint_LookupName: struct wbint_LookupName
>          out: struct wbint_LookupName
>              type                     : *
>                  type                     : SID_NAME_USER (1)
>              sid                      : *
>                  sid                      : S-1-5-21-....................................
>              result                   : NT_STATUS_OK
>[2016/10/08 14:03:29.936373,  4, pid=31418, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:1397(child_handler)
>  Finished processing child request 59
>[2016/10/08 14:03:29.936379, 10, pid=31418, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:104(child_write_response)
>  Writing 3532 bytes to parent

Actions: View

Attachments on bug 12369: 12555 | 12560 | 12565 | 12566 | 12567