_out.log

x1c in /home/nrb/go/src/github.com/heptio/ark (git) master U
% GOOGLE_APPLICATION_CREDENTIALS=credentials-ark-gke ./_output/bin/linux/amd64/ark server --plugin-dir ./_output/bin/linux/amd64 --log-level debug
INFO[0000] setting log-level to DEBUG
INFO[0000] Starting Ark server v0.8.1-58-gaeb5f6d-dirty  logSource="pkg/cmd/server/server.go:95"
INFO[0000] Ensuring namespace exists for backups         logSource="pkg/cmd/server/server.go:264" namespace=heptio-ark
INFO[0000] Namespace already exists                      logSource="pkg/cmd/server/server.go:276" namespace=heptio-ark
INFO[0000] Retrieving Ark configuration                  logSource="pkg/cmd/server/server.go:281"
INFO[0000] Successfully retrieved Ark configuration      logSource="pkg/cmd/server/server.go:299"
INFO[0000] Using default resource priorities             logSource="pkg/cmd/server/server.go:334" priorities="[namespaces persistentvolumes persistentvolumeclaims secrets configmaps serviceaccounts limitranges]"
INFO[0000] Configuring cloud provider for backup service  logSource="pkg/cmd/server/server.go:385"
DEBU[0000] starting plugin                               args="[./_output/bin/linux/amd64/ark run-plugin cloudprovider gcp]" logSource="pkg/plugin/logrus_adapter.go:74" path=./_output/bin/linux/amd64/ark
DEBU[0000] waiting for RPC address                       logSource="pkg/plugin/logrus_adapter.go:74" path=./_output/bin/linux/amd64/ark
DEBU[0000] plugin address                                address=/tmp/plugin637093771 logSource="pkg/plugin/logrus_adapter.go:74" network=unix pluginName=ark
INFO[0000] Configuring cloud provider for snapshot service  logSource="pkg/cmd/server/server.go:401"
INFO[0001] Starting controllers                          logSource="pkg/cmd/server/server.go:452"
INFO[0001] Caching cloud backups every 30m0s             logSource="pkg/cmd/server/server.go:458"
DEBU[0001] refreshing all cached backup lists from object storage  logSource="pkg/cloudprovider/backup_cache.go:69"
INFO[0001] Running backup sync controller                logSource="pkg/controller/backup_sync_controller.go:70"
INFO[0001] Syncing backups from object storage           logSource="pkg/controller/backup_sync_controller.go:78"
DEBU[0001] Bucket is not in cache - doing a live lookup  bucket=nrb_ark logSource="pkg/cloudprovider/backup_cache.go:89"
INFO[0001] Got backups from object storage               backupCount=0 logSource="pkg/controller/backup_sync_controller.go:84"
INFO[0003] Starting BackupController                     logSource="pkg/controller/backup_controller.go:149"
INFO[0003] Waiting for caches to sync                    logSource="pkg/controller/backup_controller.go:152"
INFO[0003] Starting ScheduleController                   logSource="pkg/controller/schedule_controller.go:135"
INFO[0003] Waiting for caches to sync                    logSource="pkg/controller/schedule_controller.go:138"
INFO[0003] Starting controller                           controller=gc-controller logSource="pkg/controller/generic_controller.go:77"
INFO[0003] Waiting for caches to sync                    controller=gc-controller logSource="pkg/controller/generic_controller.go:80"
INFO[0003] Starting controller                           controller=backup-deletion logSource="pkg/controller/generic_controller.go:77"
INFO[0003] Waiting for caches to sync                    controller=backup-deletion logSource="pkg/controller/generic_controller.go:80"
INFO[0003] Starting DownloadRequestController            logSource="pkg/controller/download_request_controller.go:122"
INFO[0003] Waiting for caches to sync                    logSource="pkg/controller/download_request_controller.go:125"
INFO[0003] Starting RestoreController                    logSource="pkg/controller/restore_controller.go:154"
INFO[0003] Waiting for caches to sync                    logSource="pkg/controller/restore_controller.go:157"
DEBU[0004] Backup is not new, skipping                   backup=heptio-ark/all logSource="pkg/controller/backup_controller.go:112" phase=Completed
DEBU[0004] backup doesn't have deprecated finalizer - skipping  backup=heptio-ark/all logSource="pkg/cmd/server/server.go:639"
INFO[0004] Server started successfully                   logSource="pkg/cmd/server/server.go:616"
INFO[0004] Caches are synced                             logSource="pkg/controller/backup_controller.go:156"
INFO[0004] Caches are synced                             logSource="pkg/controller/schedule_controller.go:142"
INFO[0004] Caches are synced                             controller=gc-controller logSource="pkg/controller/generic_controller.go:84"
DEBU[0004] gcController.enqueueAllBackups                logSource="pkg/controller/gc_controller.go:88"
INFO[0004] Caches are synced                             controller=backup-deletion logSource="pkg/controller/generic_controller.go:84"
INFO[0004] Checking for expired DeleteBackupRequests     controller=backup-deletion logSource="pkg/controller/backup_deletion_controller.go:286"
INFO[0004] Done checking for expired DeleteBackupRequests  controller=backup-deletion logSource="pkg/controller/backup_deletion_controller.go:314"
DEBU[0004] Backup has not expired yet, skipping          backup=heptio-ark/all expiration="2018-06-20 14:44:14 -0400 EDT" logSource="pkg/controller/gc_controller.go:129"
INFO[0004] Caches are synced                             logSource="pkg/controller/download_request_controller.go:129"
DEBU[0004] Backup has not expired yet, skipping          backup=heptio-ark/all expiration="2018-06-20 14:44:14 -0400 EDT" logSource="pkg/controller/gc_controller.go:129"
INFO[0004] Caches are synced                             logSource="pkg/controller/restore_controller.go:161"
DEBU[0009] Running processItem                           controller=backup-deletion key=heptio-ark/all-ns4pz logSource="pkg/controller/backup_deletion_controller.go:104"
INFO[0009] Removing PV snapshots                         backup=all controller=backup-deletion logSource="pkg/controller/backup_deletion_controller.go:220" name=all-ns4pz namespace=heptio-ark
INFO[0009] Removing snapshot associated with backup      backup=all controller=backup-deletion logSource="pkg/controller/backup_deletion_controller.go:222" name=all-ns4pz namespace=heptio-ark snapshotID=gke-cluster-1-fb34eb19-pvc-33732649-84e6-4d63-b3ef-6c7a2a94a682
DEBU[0009] Backup has not expired yet, skipping          backup=heptio-ark/all expiration="2018-06-20 14:44:14 -0400 EDT" logSource="pkg/controller/gc_controller.go:129"
INFO[0009] Removing backup from object storage           backup=all controller=backup-deletion logSource="pkg/controller/backup_deletion_controller.go:229" name=all-ns4pz namespace=heptio-ark
INFO[0010] Removing restores                             backup=all controller=backup-deletion logSource="pkg/controller/backup_deletion_controller.go:235" name=all-ns4pz namespace=heptio-ark
DEBU[0010] Running processItem                           controller=backup-deletion key=heptio-ark/all-ns4pz logSource="pkg/controller/backup_deletion_controller.go:104"
DEBU[0010] Unable to find DeleteBackupRequest            controller=backup-deletion key=heptio-ark/all-ns4pz logSource="pkg/controller/backup_deletion_controller.go:113"
DEBU[0062] Backup has not expired yet, skipping          backup=heptio-ark/all expiration="0001-01-01 00:00:00 +0000 UTC" logSource="pkg/controller/gc_controller.go:129"
DEBU[0062] Running processBackup                         key=heptio-ark/all logSource="pkg/controller/backup_controller.go:206"
DEBU[0062] Getting backup                                key=heptio-ark/all logSource="pkg/controller/backup_controller.go:212"
DEBU[0062] Cloning backup                                key=heptio-ark/all logSource="pkg/controller/backup_controller.go:233"
DEBU[0062] Backup has not expired yet, skipping          backup=heptio-ark/all expiration="2018-06-20 14:49:35 -0400 EDT" logSource="pkg/controller/gc_controller.go:129"
DEBU[0062] Running backup                                key=heptio-ark/all logSource="pkg/controller/backup_controller.go:270"
INFO[0062] Starting backup                               backup=heptio-ark/all logSource="pkg/controller/backup_controller.go:331"
DEBU[0062] starting plugin                               args="[./_output/bin/linux/amd64/ark run-plugin backupitemaction pv]" logSource="pkg/plugin/logrus_adapter.go:74" path=./_output/bin/linux/amd64/ark
DEBU[0062] waiting for RPC address                       logSource="pkg/plugin/logrus_adapter.go:74" path=./_output/bin/linux/amd64/ark
DEBU[0062] plugin address                                address=/tmp/plugin436921555 logSource="pkg/plugin/logrus_adapter.go:74" network=unix pluginName=ark
DEBU[0062] starting plugin                               args="[./_output/bin/linux/amd64/ark run-plugin backupitemaction pod]" logSource="pkg/plugin/logrus_adapter.go:74" path=./_output/bin/linux/amd64/ark
DEBU[0062] waiting for RPC address                       logSource="pkg/plugin/logrus_adapter.go:74" path=./_output/bin/linux/amd64/ark
DEBU[0062] plugin address                                address=/tmp/plugin260760540 logSource="pkg/plugin/logrus_adapter.go:74" network=unix pluginName=ark
DEBU[0062] starting plugin                               args="[./_output/bin/linux/amd64/ark run-plugin backupitemaction serviceaccount]" logSource="pkg/plugin/logrus_adapter.go:74" path=./_output/bin/linux/amd64/ark
DEBU[0062] waiting for RPC address                       logSource="pkg/plugin/logrus_adapter.go:74" path=./_output/bin/linux/amd64/ark
DEBU[0062] plugin address                                address=/tmp/plugin023380565 logSource="pkg/plugin/logrus_adapter.go:74" network=unix pluginName=ark
DEBU[0149] In seekAndPutObject                           logSource="pkg/cloudprovider/backup_service.go:129"
DEBU[0149] calling out to PutObject                      logSource="pkg/cloudprovider/backup_service.go:140"
INFO[0149] Completed log file upload                     logSource="pkg/cloudprovider/backup_service.go:155"
DEBU[0149] In seekAndPutObject                           logSource="pkg/cloudprovider/backup_service.go:129"
DEBU[0149] calling out to PutObject                      logSource="pkg/cloudprovider/backup_service.go:140"
INFO[0149] Completed metadata upload                     logSource="pkg/cloudprovider/backup_service.go:172"
DEBU[0149] In seekAndPutObject                           logSource="pkg/cloudprovider/backup_service.go:129"
DEBU[0149] calling out to PutObject                      logSource="pkg/cloudprovider/backup_service.go:140"
INFO[0149] Completed backup upload                       logSource="pkg/cloudprovider/backup_service.go:182"
INFO[0149] Backup completed                              backup=heptio-ark/all logSource="pkg/controller/backup_controller.go:378"
DEBU[0150] Updating backup's final status                key=heptio-ark/all logSource="pkg/controller/backup_controller.go:278"
DEBU[0150] Backup has not expired yet, skipping          backup=heptio-ark/all expiration="2018-06-20 14:49:35 -0400 EDT" logSource="pkg/controller/gc_controller.go:129"

object_store.go

/*
Copyright 2017 the Heptio Ark contributors.

Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at

    http://www.apache.org/licenses/LICENSE-2.0

Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/

package gcp

import (
	"context"
	"io"
	"io/ioutil"
	"os"
	"strings"
	"time"

	"cloud.google.com/go/storage"
	"github.com/pkg/errors"
	"github.com/sirupsen/logrus"
	"golang.org/x/oauth2/google"
	"google.golang.org/api/iterator"
	"google.golang.org/api/option"

	"github.com/heptio/ark/pkg/cloudprovider"
)

const credentialsEnvVar = "GOOGLE_APPLICATION_CREDENTIALS"

type objectStore struct {
	client         *storage.Client
	googleAccessID string
	privateKey     []byte
	log            logrus.FieldLogger
}

func NewObjectStore(log logrus.FieldLogger) cloudprovider.ObjectStore {
	return &objectStore{log: log}
}

func (o *objectStore) Init(config map[string]string) error {
	o.log.Debug("Started object store")
	credentialsFile := os.Getenv(credentialsEnvVar)
	if credentialsFile == "" {
		return errors.Errorf("%s is undefined", credentialsEnvVar)
	}

	// Get the email and private key from the credentials file so we can pre-sign download URLs
	creds, err := ioutil.ReadFile(credentialsFile)
	if err != nil {
		return errors.WithStack(err)
	}
	jwtConfig, err := google.JWTConfigFromJSON(creds)
	if err != nil {
		return errors.WithStack(err)
	}
	if jwtConfig.Email == "" {
		return errors.Errorf("credentials file pointed to by %s does not contain an email", credentialsEnvVar)
	}
	if len(jwtConfig.PrivateKey) == 0 {
		return errors.Errorf("credentials file pointed to by %s does not contain a private key", credentialsEnvVar)
	}

	o.googleAccessID = jwtConfig.Email
	o.privateKey = jwtConfig.PrivateKey

	client, err := storage.NewClient(context.Background(), option.WithScopes(storage.ScopeReadWrite))
	if err != nil {
		o.log.Debug("Couldn't create an object store client")
		return errors.WithStack(err)
	}
	o.client = client
	o.log.Debug("Created object store client successfully")

	return nil
}

func (o *objectStore) PutObject(bucket string, key string, body io.Reader) error {
	o.log.Debug("Creating writer")
	w := o.client.Bucket(bucket).Object(key).NewWriter(context.Background())
	defer w.Close()

	written, err := io.Copy(w, body)
	o.log.Debug("Written: %s", written)
	o.log.Debug("Error with copy: %s", err)

	return errors.WithStack(err)
}

func (o *objectStore) GetObject(bucket string, key string) (io.ReadCloser, error) {
	r, err := o.client.Bucket(bucket).Object(key).NewReader(context.Background())
	if err != nil {
		return nil, errors.WithStack(err)
	}

	return r, nil
}

func (o *objectStore) ListCommonPrefixes(bucket string, delimiter string) ([]string, error) {
	q := &storage.Query{
		Delimiter: delimiter,
	}

	var res []string

	iter := o.client.Bucket(bucket).Objects(context.Background(), q)

	for {
		obj, err := iter.Next()
		if err == iterator.Done {
			return res, nil
		}
		if err != nil {
			return nil, errors.WithStack(err)
		}

		if obj.Prefix != "" {
			res = append(res, obj.Prefix[0:strings.LastIndex(obj.Prefix, delimiter)])
		}
	}
}

func (o *objectStore) ListObjects(bucket, prefix string) ([]string, error) {
	q := &storage.Query{
		Prefix: prefix,
	}

	var res []string

	iter := o.client.Bucket(bucket).Objects(context.Background(), q)

	for {
		obj, err := iter.Next()
		if err == iterator.Done {
			return res, nil
		}
		if err != nil {
			return nil, errors.WithStack(err)
		}

		res = append(res, obj.Name)
	}
}

func (o *objectStore) DeleteObject(bucket string, key string) error {
	return errors.Wrapf(o.client.Bucket(bucket).Object(key).Delete(context.Background()), "error deleting object %s", key)
}

func (o *objectStore) CreateSignedURL(bucket, key string, ttl time.Duration) (string, error) {
	return storage.SignedURL(bucket, key, &storage.SignedURLOptions{
		GoogleAccessID: o.googleAccessID,
		PrivateKey:     o.privateKey,
		Method:         "GET",
		Expires:        time.Now().Add(ttl),
	})
}