add logging to client

client/TGSExchange.go

@@ -74,6 +74,7 @@ func (cl *Client) TGSExchange(tgsReq messages.TGSReq, kdcRealm string, tgt messa
 		tgsRep.DecryptedEncPart.RenewTill,
 		tgsRep.DecryptedEncPart.Key,
 	)
+	cl.Log("ticket added to cache for %s (EndTime: %v)", tgsRep.Ticket.SName.PrincipalNameString(), tgsRep.DecryptedEncPart.EndTime)
 	return tgsReq, tgsRep, err
 }
 

client/cache.go

@@ -78,6 +78,7 @@ func (cl *Client) GetCachedTicket(spn string) (messages.Ticket, types.Encryption
 	if e, ok := cl.cache.getEntry(spn); ok {
 		//If within time window of ticket return it
 		if time.Now().UTC().After(e.StartTime) && time.Now().UTC().Before(e.EndTime) {
+			cl.Log("ticket received from cache for %s", spn)
 			return e.Ticket, e.SessionKey, true
 		} else if time.Now().UTC().Before(e.RenewTill) {
 			e, err := cl.renewTicket(e)
@@ -104,5 +105,6 @@ func (cl *Client) renewTicket(e CacheEntry) (CacheEntry, error) {
 	if !ok {
 		return e, errors.New("ticket was not added to cache")
 	}
+	cl.Log("ticket renewed for %s (EndTime: %v)", spn.PrincipalNameString(), e.EndTime)
 	return e, nil
 }

client/client.go

@@ -229,4 +229,5 @@ func (cl *Client) Destroy() {
 	cl.sessions.destroy()
 	cl.cache.clear()
 	cl.Credentials = creds
+	cl.Log("client destroyed")
 }

client/session.go

@@ -76,8 +76,9 @@ func (cl *Client) addSession(tgt messages.Ticket, dep messages.EncKDCRepPart) {
 		// Not a TGT
 		return
 	}
+	realm := tgt.SName.NameString[len(tgt.SName.NameString)-1]
 	s := &session{
-		realm:                tgt.SName.NameString[len(tgt.SName.NameString)-1],
+		realm:                realm,
 		authTime:             dep.AuthTime,
 		endTime:              dep.EndTime,
 		renewTill:            dep.RenewTill,
@@ -87,6 +88,7 @@ func (cl *Client) addSession(tgt messages.Ticket, dep messages.EncKDCRepPart) {
 	}
 	cl.sessions.update(s)
 	cl.enableAutoSessionRenewal(s)
+	cl.Log("TGT session added for %s (EndTime: %v)", realm, dep.EndTime)
 }
 
 // update overwrites the session details with those from the TGT and decrypted encPart
@@ -156,6 +158,9 @@ func (cl *Client) enableAutoSessionRenewal(s *session) {
 			select {
 			case <-timer.C:
 				renewal, err := cl.refreshSession(s)
+				if err != nil {
+					cl.Log("error refreshing session: %v", err)
+				}
 				if !renewal && err == nil {
 					// end this goroutine as there will have been a new login and new auto renewal goroutine created.
 					return
@@ -178,10 +183,11 @@ func (cl *Client) renewTGT(s *session) error {
 	}
 	_, tgsRep, err := cl.TGSREQGenerateAndExchange(spn, cl.Credentials.Domain(), tgt, skey, true)
 	if err != nil {
-		return krberror.Errorf(err, krberror.KRBMsgError, "error renewing TGT")
+		return krberror.Errorf(err, krberror.KRBMsgError, "error renewing TGT for %s", realm)
 	}
 	s.update(tgsRep.Ticket, tgsRep.DecryptedEncPart)
 	cl.sessions.update(s)
+	cl.Log("TGT session renewed for %s (EndTime: %v)", realm, tgsRep.DecryptedEncPart.EndTime)
 	return nil
 }
 
@@ -192,6 +198,7 @@ func (cl *Client) refreshSession(s *session) (bool, error) {
 	realm := s.realm
 	renewTill := s.renewTill
 	s.mux.RUnlock()
+	cl.Log("refreshing TGT session for %s", realm)
 	if time.Now().UTC().Before(renewTill) {
 		err := cl.renewTGT(s)
 		return true, err

examples/longRunningClient.go

@@ -36,7 +36,7 @@ const (
 )
 
 func main() {
-	l := log.New(os.Stderr, "GOKRB5 Client: ", log.Ldate|log.Ltime|log.Lshortfile)
+	l := log.New(os.Stderr, "GOKRB5 Client: ", log.LstdFlags)
 
 	//defer profile.Start(profile.TraceProfile).Stop()
 	// Load the keytab