Bugfixes to improve robustness.

- Don't keep admin connections open indefinitely -- when needed, open
  a connection, do work, close the connection.
- Don't reload or re-label VCL configs if already loaded or labelled.
- More verbose debug level logging.

cmd/controller/controller.go

@@ -381,7 +381,7 @@ func (ingc *IngressController) addOrUpdateIng(task Task,
 	ing extensions.Ingress) {
 
 	key := ing.ObjectMeta.Namespace + "/" + ing.ObjectMeta.Name
-	ingc.log.Infof("Adding or Updating Ingress: %v\n", key)
+	ingc.log.Infof("Adding or Updating Ingress: %v", key)
 
 	vclSpec, err := ingc.ing2VCLSpec(&ing)
 	if err != nil {
@@ -392,6 +392,8 @@ func (ingc *IngressController) addOrUpdateIng(task Task,
 		return
 	}
 
+	ingc.log.Debugf("Update Ingress key=%s uuid=%s: %+v", key,
+		string(ing.ObjectMeta.UID), vclSpec)
 	err = ingc.vController.Update(key, string(ing.ObjectMeta.UID), vclSpec)
 	if err != nil {
 		// XXX as above
@@ -400,6 +402,9 @@ func (ingc *IngressController) addOrUpdateIng(task Task,
 			"AddedOrUpdatedWithError",
 			"Configuration for %v was added or updated, but not "+
 				"applied: %v", key, err)
+	} else {
+		ingc.log.Debugf("Updated Ingress key=%s uuid=%s: %+v", key,
+			string(ing.ObjectMeta.UID), vclSpec)
 	}
 }
 

cmd/go.mod

 module code.uplex.de/uplex-varnish/k8s-ingress/cmd
 
 require (
-	code.uplex.de/uplex-varnish/varnishapi v0.0.0-20181129154850-be0a7893ac92
+	code.uplex.de/uplex-varnish/varnishapi v0.0.0-20181205222454-e67a0f88a279
 	github.com/emicklei/go-restful v2.8.0+incompatible // indirect
 	github.com/ghodss/yaml v1.0.0 // indirect
 	github.com/go-openapi/spec v0.17.2 // indirect

cmd/go.sum

 code.uplex.de/uplex-varnish/varnishapi v0.0.0-20181129154850-be0a7893ac92 h1:KBZnpstNIE+yoIx/qZy0Udl0Qwg9Qlj1eY70sIvhjLM=
 code.uplex.de/uplex-varnish/varnishapi v0.0.0-20181129154850-be0a7893ac92/go.mod h1:J0znUDkk1j5lNWKZZ6zfISZWbA2fXvsxCM+FpDUxG9g=
+code.uplex.de/uplex-varnish/varnishapi v0.0.0-20181205203203-20054d30408c h1:dDnkldbKT9fxuJrfEbG40ydbS/Q30oH7cvDpzwJkXoQ=
+code.uplex.de/uplex-varnish/varnishapi v0.0.0-20181205203203-20054d30408c/go.mod h1:J0znUDkk1j5lNWKZZ6zfISZWbA2fXvsxCM+FpDUxG9g=
+code.uplex.de/uplex-varnish/varnishapi v0.0.0-20181205221923-190a386386bc h1:fv3y7B7zaVH561OpjJgqDFAy1rINt7Xa8WhIlN8ZOU4=
+code.uplex.de/uplex-varnish/varnishapi v0.0.0-20181205221923-190a386386bc/go.mod h1:J0znUDkk1j5lNWKZZ6zfISZWbA2fXvsxCM+FpDUxG9g=
+code.uplex.de/uplex-varnish/varnishapi v0.0.0-20181205222454-e67a0f88a279 h1:8REUMrx0zvzsAZ/zKSsRrhYbftLSNQ0v2AYZljJqvcY=
+code.uplex.de/uplex-varnish/varnishapi v0.0.0-20181205222454-e67a0f88a279/go.mod h1:J0znUDkk1j5lNWKZZ6zfISZWbA2fXvsxCM+FpDUxG9g=
 github.com/PuerkitoBio/purell v1.1.0 h1:rmGxhojJlM0tuKtfdvliR84CFHljx9ag64t2xmVkjK4=
 github.com/PuerkitoBio/purell v1.1.0/go.mod h1:c11w/QuzBsJSee3cPx9rAFu61PvFxuPbtSwDGJws/X0=
 github.com/PuerkitoBio/urlesc v0.0.0-20170810143723-de5bf2ad4578 h1:d+Bc7a5rLufV/sSk/8dngufqelfh6jnri85riMAaF/M=

cmd/main.go

@@ -147,7 +147,6 @@ func handleTermination(log *logrus.Logger, ingc *controller.IngressController,
 	if !exited {
 		log.Info("Shutting down Varnish")
 		vc.Quit()
-		<-varnishDone
 	}
 
 	log.Info("Exiting with a status:", exitStatus)

cmd/varnish/varnish.go

@@ -101,8 +101,8 @@ type vclSpec struct {
 }
 
 type varnishSvc struct {
-	addr string
-	adm  *admin.Admin
+	addr   string
+	Banner string
 }
 
 type VarnishController struct {
@@ -124,6 +124,7 @@ func (vc *VarnishController) Start(errChan chan error) {
 	// XXX start a goroutine to ping etc and discard old VCL instances
 	vc.errChan = errChan
 	vc.log.Info("Starting Varnish controller")
+	fmt.Printf("Varnish controller logging at level: %s\n", vc.log.Level)
 }
 
 func (vc *VarnishController) getSrc() (string, error) {
@@ -137,23 +138,6 @@ func (vc *VarnishController) getSrc() (string, error) {
 func (vc *VarnishController) updateVarnishInstances(svcs []*varnishSvc) error {
 	var errs VarnishAdmErrors
 
-	for _, svc := range svcs {
-		var err error
-
-		if svc.adm != nil {
-			continue
-		}
-		svc.adm, err = admin.Dial(svc.addr, vc.admSecret, admTimeout)
-		if err != nil {
-			admErr := VarnishAdmError{addr: svc.addr, err: err}
-			errs = append(errs, admErr)
-			svc.adm = nil
-			continue
-		}
-		vc.log.Infof("Connected to Varnish admin endpoint at %s",
-			svc.addr)
-	}
-
 	if vc.spec == nil {
 		vc.log.Info("Update Varnish instances: Currently no Ingress " +
 			"defined")
@@ -171,33 +155,97 @@ func (vc *VarnishController) updateVarnishInstances(svcs []*varnishSvc) error {
 
 	vc.log.Infof("Update Varnish instances: load config %s", cfgName)
 	for _, svc := range svcs {
-		err = svc.adm.VCLInline(cfgName, vclSrc)
+		vc.log.Debugf("Connect to %s, timeout=%v", svc.addr, admTimeout)
+		adm, err := admin.Dial(svc.addr, vc.admSecret, admTimeout)
 		if err != nil {
 			admErr := VarnishAdmError{addr: svc.addr, err: err}
 			errs = append(errs, admErr)
 			continue
 		}
-		vc.log.Infof("Loaded config %s at Varnish endpoint %s", cfgName,
+		defer adm.Close()
+		svc.Banner = adm.Banner
+		vc.log.Infof("Connected to Varnish admin endpoint at %s",
 			svc.addr)
 
-		err = svc.adm.VCLLabel(regularLabel, cfgName)
+		loaded, labelled, ready := false, false, false
+		vc.log.Debugf("List VCLs at %s", svc.addr)
+		vcls, err := adm.VCLList()
 		if err != nil {
 			admErr := VarnishAdmError{addr: svc.addr, err: err}
 			errs = append(errs, admErr)
 			continue
 		}
-		vc.log.Infof("Labeled config %s as %s at Varnish endpoint %s",
-			cfgName, regularLabel, svc.addr)
+		vc.log.Debugf("VCL List at %s: %+v", svc.addr, vcls)
+		for _, vcl := range vcls {
+			if vcl.Name == cfgName {
+				loaded = true
+			}
+			if vcl.LabelVCL == cfgName &&
+				vcl.Name == regularLabel {
+				labelled = true
+			}
+			if vcl.LabelVCL == readyCfg &&
+				vcl.Name == readinessLabel {
+				ready = true
+			}
+		}
 
-		err = svc.adm.VCLLabel(readinessLabel, readyCfg)
-		if err != nil {
-			admErr := VarnishAdmError{addr: svc.addr, err: err}
-			errs = append(errs, admErr)
-			continue
+		if loaded {
+			vc.log.Infof("Config %s already loaded at instance %s",
+				cfgName, svc.addr)
+		} else {
+			vc.log.Debugf("Load config %s at %s", cfgName, svc.addr)
+			err = adm.VCLInline(cfgName, vclSrc)
+			if err != nil {
+				admErr := VarnishAdmError{
+					addr: svc.addr,
+					err:  err,
+				}
+				errs = append(errs, admErr)
+				continue
+			}
+			vc.log.Infof("Loaded config %s at Varnish endpoint %s",
+				cfgName, svc.addr)
+		}
+
+		if labelled {
+			vc.log.Infof("Config %s already labelled as regular "+
+				"at %s", cfgName, svc.addr)
+		} else {
+			vc.log.Debugf("Label config %s as %s at %s", cfgName,
+				regularLabel, svc.addr)
+			err = adm.VCLLabel(regularLabel, cfgName)
+			if err != nil {
+				admErr := VarnishAdmError{
+					addr: svc.addr,
+					err:  err,
+				}
+				errs = append(errs, admErr)
+				continue
+			}
+			vc.log.Infof("Labeled config %s as %s at Varnish "+
+				"endpoint %s", cfgName, regularLabel, svc.addr)
 		}
-		vc.log.Infof("Labeled config %s as %s at Varnish endpoint %s",
-			readyCfg, readinessLabel, svc.addr)
 
+		if ready {
+			vc.log.Infof("Config %s already labelled as ready "+
+				"at %s", readyCfg, svc.addr)
+		} else {
+			vc.log.Debugf("Label config %s as %s at %s", readyCfg,
+				readinessLabel, svc.addr)
+			err = adm.VCLLabel(readinessLabel, readyCfg)
+			if err != nil {
+				admErr := VarnishAdmError{
+					addr: svc.addr,
+					err:  err,
+				}
+				errs = append(errs, admErr)
+				continue
+			}
+			vc.log.Infof("Labeled config %s as %s at Varnish "+
+				"endpoint %s", readyCfg, readinessLabel,
+				svc.addr)
+		}
 	}
 	if len(errs) == 0 {
 		return nil
@@ -221,10 +269,21 @@ func (vc *VarnishController) removeVarnishInstances(svcs []*varnishSvc) error {
 	var errs VarnishAdmErrors
 
 	for _, svc := range svcs {
-		if svc.adm == nil {
+		vc.log.Debugf("Connect to %s, timeout=%v", svc.addr, admTimeout)
+		adm, err := admin.Dial(svc.addr, vc.admSecret, admTimeout)
+		if err != nil {
+			// This is not considered an error -- the Varnish
+			// instance may have already shut down.
+			vc.log.Warnf("Could not connect to %s: %v", svc.addr,
+				err)
 			continue
 		}
-		if err := svc.adm.VCLLabel(readinessLabel, notAvailCfg); err != nil {
+		defer adm.Close()
+		svc.Banner = adm.Banner
+		vc.log.Infof("Connected to Varnish admin endpoint at %s",
+			svc.addr)
+
+		if err := adm.VCLLabel(readinessLabel, notAvailCfg); err != nil {
 			if err == io.EOF {
 				continue
 			}
@@ -232,10 +291,6 @@ func (vc *VarnishController) removeVarnishInstances(svcs []*varnishSvc) error {
 			errs = append(errs, admErr)
 			continue
 		}
-		if err := svc.adm.Close(); err != nil {
-			admErr := VarnishAdmError{addr: svc.addr, err: err}
-			errs = append(errs, admErr)
-		}
 	}
 	if len(errs) == 0 {
 		return nil
@@ -276,10 +331,21 @@ func (vc *VarnishController) updateVarnishSvc(key string,
 	vc.varnishSvcs[key] = append(keepSvcs, newSvcs...)
 
 	for _, svc := range remSvcs {
-		if svc.adm == nil {
+		vc.log.Debugf("Connect to %s, timeout=%v", svc.addr, admTimeout)
+		adm, err := admin.Dial(svc.addr, vc.admSecret, admTimeout)
+		if err != nil {
+			// This is not considered an error -- the Varnish
+			// instance may have already shut down.
+			vc.log.Warnf("Could not connect to %s: %v", svc.addr,
+				err)
 			continue
 		}
-		if err := svc.adm.VCLLabel(readinessLabel, notAvailCfg); err != nil {
+		defer adm.Close()
+		svc.Banner = adm.Banner
+		vc.log.Infof("Connected to Varnish admin endpoint at %s",
+			svc.addr)
+
+		if err := adm.VCLLabel(readinessLabel, notAvailCfg); err != nil {
 			if err == io.EOF {
 				continue
 			}
@@ -368,10 +434,24 @@ func (vc *VarnishController) DeleteIngress(key string) error {
 	var errs VarnishAdmErrors
 	for _, svcs := range vc.varnishSvcs {
 		for _, svc := range svcs {
-			if svc.adm == nil {
+			vc.log.Debugf("Connect to %s, timeout=%v", svc.addr,
+				admTimeout)
+			adm, err := admin.Dial(svc.addr, vc.admSecret,
+				admTimeout)
+			if err != nil {
+				admErr := VarnishAdmError{
+					addr: svc.addr,
+					err:  err,
+				}
+				errs = append(errs, admErr)
 				continue
 			}
-			if err := svc.adm.VCLLabel(regularLabel, notAvailCfg); err != nil {
+			defer adm.Close()
+			svc.Banner = adm.Banner
+			vc.log.Infof("Connected to Varnish admin endpoint at "+
+				"%s", svc.addr)
+
+			if err := adm.VCLLabel(regularLabel, notAvailCfg); err != nil {
 				admErr := VarnishAdmError{
 					addr: svc.addr,
 					err:  err,
@@ -409,19 +489,5 @@ func (vc *VarnishController) DeleteAdmSecret() {
 }
 
 func (vc *VarnishController) Quit() {
-	for _, svcs := range vc.varnishSvcs {
-		for _, svc := range svcs {
-			if svc.adm == nil {
-				continue
-			}
-			if err := svc.adm.Close(); err != nil {
-				vc.log.Errorf("Failed to close admin "+
-					"connection at Varnish endpoint %s: %v",
-					svc.addr, err)
-				continue
-			}
-			vc.log.Infof("Closed admin connection at Varinsh "+
-				"endpoint %s", svc.addr)
-		}
-	}
+	vc.errChan <- nil
 }

deploy/controller.yaml

@@ -30,4 +30,4 @@ spec:
         args:
         # log-level default is info, so this can be left out.
         # Shown here to demonstrate setting options for the controller.
-        - -log-level=info
+        - -log-level=debug