[Samba] "Ticket not yet valid" message - further info

[Peter McFarlane]

Hi,

Thanks to all who responded to my initial post to the list regarding
"Ticket not yet valid" messages in my samba logs.

I neglected to include this in my initial post - we had already
suspected clock synchronisation problems, and all of our servers (AIX
Samba server and windows clients) are all synchronised to the AD DC,
which is sychronised to an internet atomic clock in Melbourne.

And we still get the messages in our logs for the first connection
attempt of the day (either browse or drive mapping). The event and
security logs on the DC show nothing.

I have compiled 3.0.1 Samba code and will attempt to get that into
production as soon as possible.

Any other suggestions or areas to look at would be much appreciated.

Best regards,

Peter

Original post follows:
I'm having a problem with Samba 3 in AD mode. For some reason, the first
time (usually first thing in the morning) a user tries to map a drive to
my samba 3 server, the log shows a message "Ticket not yet valid". The
user is prompted for username/password (they've already logged on to the
windows domain, so they shouldn't be prompted.

The user then waits for a minute or so, tries again, and the drive is
mapped ok. Subsequent browses or mappings work for the rest of the day.
Something seems to expire over night - next morning, first attempt to
browse or map a drive will prompt user for password. If they cancel,
wait a minute or so, next time it's ok.

Unfortunately, there are some processes on other windows servers which
map drives on the samba server without user intervention - their first
attempt fails, which is a big problem - an administrator has to check if
the connection(s) worked or not.

The following is an exerpt from the log:

[2004/01/06 11:14:43, 3] smbd/oplock.c:init_oplocks(1226)
  open_oplock_ipc: opening loopback UDP socket.
[2004/01/06 11:14:43, 3] smbd/oplock.c:init_oplocks(1257)
  open_oplock ipc: pid = 93296, global_oplock_port = 34441
[2004/01/06 11:14:43, 3] lib/access.c:check_access(313)
  check_access: no hostnames in host allow/deny list.
[2004/01/06 11:14:43, 2] lib/access.c:check_access(324)
  Allowed connection from  (192.168.40.13)
[2004/01/06 11:14:43, 3] smbd/process.c:process_smb(890)
  Transaction 0 of length 137
[2004/01/06 11:14:43, 3] smbd/process.c:switch_message(685)
  switch message SMBnegprot (pid 93296)
[2004/01/06 11:14:43, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2004/01/06 11:14:43, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [PC NETWORK PROGRAM 1.0]
[2004/01/06 11:14:43, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [LANMAN1.0]
[2004/01/06 11:14:43, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [Windows for Workgroups 3.1a]
[2004/01/06 11:14:43, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [LM1.2X002]
[2004/01/06 11:14:43, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [LANMAN2.1]
[2004/01/06 11:14:43, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [NT LM 0.12]
[2004/01/06 11:14:43, 3] smbd/negprot.c:reply_nt1(329)
  using SPNEGO
[2004/01/06 11:14:43, 3] smbd/negprot.c:reply_negprot(532)
  Selected protocol NT LM 0.12
[2004/01/06 11:14:43, 3] smbd/process.c:process_smb(890)
  Transaction 1 of length 1404
[2004/01/06 11:14:43, 3] smbd/process.c:switch_message(685)
  switch message SMBsesssetupX (pid 93296)
[2004/01/06 11:14:43, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2004/01/06 11:14:43, 3] smbd/sesssetup.c:reply_sesssetup_and_X(579)
  wct=12 flg2=0xc807
[2004/01/06 11:14:43, 2] smbd/sesssetup.c:setup_new_vc_session(535)
  setup_new_vc_session: New VC == 0, if NT4.x compatible we would close
all old resources.
[2004/01/06 11:14:43, 3]
smbd/sesssetup.c:reply_sesssetup_and_X_spnego(476)
  Doing spnego session setup
[2004/01/06 11:14:43, 3]
smbd/sesssetup.c:reply_sesssetup_and_X_spnego(500)
  NativeOS=[Windows 2000 2195] NativeLanMan=[Windows 2000 5.0]
[2004/01/06 11:14:43, 3] smbd/sesssetup.c:reply_spnego_negotiate(385)
  Got OID 1 2 840 48018 1 2 2
[2004/01/06 11:14:43, 3] smbd/sesssetup.c:reply_spnego_negotiate(385)
  Got OID 1 2 840 113554 1 2 2
[2004/01/06 11:14:43, 3] smbd/sesssetup.c:reply_spnego_negotiate(385)
  Got OID 1 3 6 1 4 1 311 2 2 10
[2004/01/06 11:14:43, 3] smbd/sesssetup.c:reply_spnego_negotiate(388)
  Got secblob of size 1202
[2004/01/06 11:14:43, 3] libads/kerberos_verify.c:ads_verify_ticket(310)
  ads_verify_ticket: enc type [23] failed to decrypt with error Ticket
not yet valid
[2004/01/06 11:14:43, 3] libads/kerberos_verify.c:ads_verify_ticket(317)
  ads_verify_ticket: krb5_rd_req with auth failed (Bad encryption type)
[2004/01/06 11:14:43, 1] smbd/sesssetup.c:reply_spnego_kerberos(172)
  Failed to verify incoming ticket!
[2004/01/06 11:14:43, 3] smbd/error.c:error_packet(94)
  error string = No such file or directory
[2004/01/06 11:14:43, 3] smbd/error.c:error_packet(113)
  error packet at smbd/sesssetup.c(173) cmd=115 (SMBsesssetupX)
NT_STATUS_LOGON_FAILURE

The Samba 3.0.0 is compiled on AIX 4.3.3 ML 9, with Kerberos 1.3.1,
OpenLDAP  2.1.22, libiconv 1.9.1 and Berkeley DB 4.1.25.
AD is 2003 mixed mode.

Any help on why this is happening (or where to look) would be much
appreciated.