connect: Implement NeedsLogger interface for CA providers (#6556)

* add NeedsLogger to Provider interface

* implements NeedsLogger in default provider

* pass logger through to provider

* test for proper operation of NeedsLogger

* remove public testServer function

* Switch test to actually assert on logging output rather than reflection.

--amend

* Ooops actually set the logger in all the places we need it - CA config set wasn't and causing segfault

* Fix all the other places in tests where we set the logger

* Add TODO comment

agent/connect/ca/provider.go

@@ -2,6 +2,7 @@ package ca
 
 import (
 	"crypto/x509"
+	"log"
 )
 
 //go:generate mockery -name Provider -inpkg
@@ -74,3 +75,11 @@ type Provider interface {
 	// created for an intermediate CA.
 	Cleanup() error
 }
+
+// NeedsLogger is an optional interface that allows a CA provider to use the
+// Consul logger to output diagnostic messages.
+type NeedsLogger interface {
+	// SetLogger will pass a configured Logger to the provider.
+	// TODO(hclog) convert this to an hclog.Logger.
+	SetLogger(logger *log.Logger)
+}

agent/connect/ca/provider_consul.go

@@ -9,6 +9,7 @@ import (
 	"encoding/pem"
 	"errors"
 	"fmt"
+	"log"
 	"math/big"
 	"net/url"
 	"sync"
@@ -29,6 +30,7 @@ type ConsulProvider struct {
 	clusterID string
 	isRoot    bool
 	spiffeID  *connect.SpiffeIDSigning
+	logger    *log.Logger
 
 	sync.RWMutex
 }
@@ -106,6 +108,9 @@ func (c *ConsulProvider) Configure(clusterID string, isRoot bool, rawConfig map[
 		return err
 	}
 
+	c.logger.Printf("[DEBUG] consul CA provider configured ID=%s isRoot=%v",
+		c.id, c.isRoot)
+
 	return nil
 }
 
@@ -546,8 +551,8 @@ func (c *ConsulProvider) CrossSignCA(cert *x509.Certificate) (string, error) {
 // getState returns the current provider state from the state delegate, and returns
 // ErrNotInitialized if no entry is found.
 func (c *ConsulProvider) getState() (uint64, *structs.CAConsulProviderState, error) {
-	state := c.Delegate.State()
+	stateStore := c.Delegate.State()
-	idx, providerState, err := state.CAProviderState(c.id)
+	idx, providerState, err := stateStore.CAProviderState(c.id)
 	if err != nil {
 		return 0, nil, err
 	}
@@ -576,8 +581,8 @@ func (c *ConsulProvider) incrementProviderIndex(providerState *structs.CAConsulP
 
 // generateCA makes a new root CA using the current private key
 func (c *ConsulProvider) generateCA(privateKey string, sn uint64) (string, error) {
-	state := c.Delegate.State()
+	stateStore := c.Delegate.State()
-	_, config, err := state.CAConfig(nil)
+	_, config, err := stateStore.CAConfig(nil)
 	if err != nil {
 		return "", err
 	}
@@ -631,3 +636,8 @@ func (c *ConsulProvider) generateCA(privateKey string, sn uint64) (string, error
 
 	return buf.String(), nil
 }
+
+// SetLogger implements the NeedsLogger interface so the provider can log important messages.
+func (c *ConsulProvider) SetLogger(logger *log.Logger) {
+	c.logger = logger
+}

agent/connect/ca/provider_consul_test.go

@@ -83,7 +83,7 @@ func TestConsulCAProvider_Bootstrap(t *testing.T) {
 	conf := testConsulCAConfig()
 	delegate := newMockDelegate(t, conf)
 
-	provider := &ConsulProvider{Delegate: delegate}
+	provider := TestConsulProvider(t, delegate)
 	require.NoError(provider.Configure(conf.ClusterID, true, conf.Config))
 	require.NoError(provider.GenerateRoot())
 
@@ -116,7 +116,7 @@ func TestConsulCAProvider_Bootstrap_WithCert(t *testing.T) {
 	}
 	delegate := newMockDelegate(t, conf)
 
-	provider := &ConsulProvider{Delegate: delegate}
+	provider := TestConsulProvider(t, delegate)
 	require.NoError(provider.Configure(conf.ClusterID, true, conf.Config))
 	require.NoError(provider.GenerateRoot())
 
@@ -138,7 +138,7 @@ func TestConsulCAProvider_SignLeaf(t *testing.T) {
 			conf.Config["PrivateKeyBits"] = tc.KeyBits
 			delegate := newMockDelegate(t, conf)
 
-			provider := &ConsulProvider{Delegate: delegate}
+			provider := TestConsulProvider(t, delegate)
 			require.NoError(provider.Configure(conf.ClusterID, true, conf.Config))
 			require.NoError(provider.GenerateRoot())
 
@@ -242,7 +242,7 @@ func TestConsulCAProvider_CrossSignCA(t *testing.T) {
 
 			conf1 := testConsulCAConfig()
 			delegate1 := newMockDelegate(t, conf1)
-			provider1 := &ConsulProvider{Delegate: delegate1}
+			provider1 := TestConsulProvider(t, delegate1)
 			conf1.Config["PrivateKeyType"] = tc.SigningKeyType
 			conf1.Config["PrivateKeyBits"] = tc.SigningKeyBits
 			require.NoError(provider1.Configure(conf1.ClusterID, true, conf1.Config))
@@ -251,7 +251,7 @@ func TestConsulCAProvider_CrossSignCA(t *testing.T) {
 			conf2 := testConsulCAConfig()
 			conf2.CreateIndex = 10
 			delegate2 := newMockDelegate(t, conf2)
-			provider2 := &ConsulProvider{Delegate: delegate2}
+			provider2 := TestConsulProvider(t, delegate2)
 			conf2.Config["PrivateKeyType"] = tc.CSRKeyType
 			conf2.Config["PrivateKeyBits"] = tc.CSRKeyBits
 			require.NoError(provider2.Configure(conf2.ClusterID, true, conf2.Config))
@@ -360,7 +360,7 @@ func TestConsulProvider_SignIntermediate(t *testing.T) {
 
 			conf1 := testConsulCAConfig()
 			delegate1 := newMockDelegate(t, conf1)
-			provider1 := &ConsulProvider{Delegate: delegate1}
+			provider1 := TestConsulProvider(t, delegate1)
 			conf1.Config["PrivateKeyType"] = tc.SigningKeyType
 			conf1.Config["PrivateKeyBits"] = tc.SigningKeyBits
 			require.NoError(provider1.Configure(conf1.ClusterID, true, conf1.Config))
@@ -369,7 +369,7 @@ func TestConsulProvider_SignIntermediate(t *testing.T) {
 			conf2 := testConsulCAConfig()
 			conf2.CreateIndex = 10
 			delegate2 := newMockDelegate(t, conf2)
-			provider2 := &ConsulProvider{Delegate: delegate2}
+			provider2 := TestConsulProvider(t, delegate2)
 			conf2.Config["PrivateKeyType"] = tc.CSRKeyType
 			conf2.Config["PrivateKeyBits"] = tc.CSRKeyBits
 			require.NoError(provider2.Configure(conf2.ClusterID, false, conf2.Config))
@@ -451,7 +451,7 @@ func TestConsulCAProvider_MigrateOldID(t *testing.T) {
 	require.NoError(err)
 	require.NotNil(providerState)
 
-	provider := &ConsulProvider{Delegate: delegate}
+	provider := TestConsulProvider(t, delegate)
 	require.NoError(provider.Configure(conf.ClusterID, true, conf.Config))
 	require.NoError(provider.GenerateRoot())
 

agent/connect/ca/provider_vault_test.go

@@ -288,7 +288,7 @@ func TestVaultProvider_SignIntermediateConsul(t *testing.T) {
 
 		conf := testConsulCAConfig()
 		delegate := newMockDelegate(t, conf)
-		provider2 := &ConsulProvider{Delegate: delegate}
+		provider2 := TestConsulProvider(t, delegate)
 		require.NoError(t, provider2.Configure(conf.ClusterID, false, conf.Config))
 
 		testSignIntermediateCrossDC(t, provider1, provider2)
@@ -298,7 +298,7 @@ func TestVaultProvider_SignIntermediateConsul(t *testing.T) {
 	t.Run("pri=consul,sec=vault", func(t *testing.T) {
 		conf := testConsulCAConfig()
 		delegate := newMockDelegate(t, conf)
-		provider1 := &ConsulProvider{Delegate: delegate}
+		provider1 := TestConsulProvider(t, delegate)
 		require.NoError(t, provider1.Configure(conf.ClusterID, true, conf.Config))
 		require.NoError(t, provider1.GenerateRoot())
 

agent/connect/ca/testing.go

@@ -2,8 +2,11 @@ package ca
 
 import (
 	"fmt"
+	"io/ioutil"
+	"log"
 
 	"github.com/hashicorp/consul/agent/connect"
+	"github.com/mitchellh/go-testing-interface"
 )
 
 // KeyTestCases is a list of the important CA key types that we should test
@@ -61,3 +64,12 @@ func CASigningKeyTypeCases() []CASigningKeyTypes {
 	}
 	return cases
 }
+
+// TestConsulProvider creates a new ConsulProvider, taking care to stub out it's
+// Logger so that logging calls don't panic. If logging output is important
+// SetLogger can be called again with another logger to capture logs.
+func TestConsulProvider(t testing.T, d ConsulProviderStateDelegate) *ConsulProvider {
+	provider := &ConsulProvider{Delegate: d}
+	provider.SetLogger(log.New(ioutil.Discard, "", 0))
+	return provider
+}

agent/consul/leader_connect.go

@@ -102,14 +102,22 @@ func parseCARoot(pemValue, provider, clusterID string) (*structs.CARoot, error)
 
 // createProvider returns a connect CA provider from the given config.
 func (s *Server) createCAProvider(conf *structs.CAConfiguration) (ca.Provider, error) {
+	var p ca.Provider
 	switch conf.Provider {
 	case structs.ConsulCAProvider:
-		return &ca.ConsulProvider{Delegate: &consulCADelegate{s}}, nil
+		p = &ca.ConsulProvider{Delegate: &consulCADelegate{s}}
 	case structs.VaultCAProvider:
-		return &ca.VaultProvider{}, nil
+		p = &ca.VaultProvider{}
 	default:
 		return nil, fmt.Errorf("unknown CA provider %q", conf.Provider)
 	}
+
+	// If the provider implements NeedsLogger, we give it our logger.
+	if needsLogger, ok := p.(ca.NeedsLogger); ok {
+		needsLogger.SetLogger(s.logger)
+	}
+
+	return p, nil
 }
 
 func (s *Server) getCAProvider() (ca.Provider, *structs.CARoot) {

agent/consul/server_test.go

@@ -1,6 +1,7 @@
 package consul
 
 import (
+	"bytes"
 	"fmt"
 	"log"
 	"net"
@@ -10,6 +11,8 @@ import (
 	"testing"
 	"time"
 
+	"github.com/hashicorp/consul/agent/connect/ca"
+
 	"github.com/hashicorp/consul/agent/connect"
 	"github.com/hashicorp/consul/agent/metadata"
 	"github.com/hashicorp/consul/agent/structs"
@@ -1119,3 +1122,36 @@ func TestServer_RPC_RateLimit(t *testing.T) {
 		}
 	})
 }
+
+func TestServer_CALogging(t *testing.T) {
+	t.Parallel()
+	dir1, conf1 := testServerConfig(t)
+
+	// Setup dummy logger to catch output
+	var buf bytes.Buffer
+	logger := log.New(&buf, "", log.LstdFlags)
+
+	c, err := tlsutil.NewConfigurator(conf1.ToTLSUtilConfig(), nil)
+	require.NoError(t, err)
+	s1, err := NewServerLogger(conf1, logger, new(token.Store), c)
+	if err != nil {
+		t.Fatalf("err: %v", err)
+	}
+	defer os.RemoveAll(dir1)
+	defer s1.Shutdown()
+	testrpc.WaitForLeader(t, s1.RPC, "dc1")
+
+	if _, ok := s1.caProvider.(ca.NeedsLogger); !ok {
+		t.Fatalf("provider does not implement NeedsLogger")
+	}
+
+	// Wait til CA root is setup
+	retry.Run(t, func(r *retry.R) {
+		var out structs.IndexedCARoots
+		r.Check(s1.RPC("ConnectCA.Roots", structs.DCSpecificRequest{
+			Datacenter: conf1.Datacenter,
+		}, &out))
+	})
+
+	require.Contains(t, buf.String(), "consul CA provider configured")
+}