maxmustermann/pulumi
1
0
Fork 0
Code Issues Pull requests Projects Releases Wiki Activity

plugin install investigation

Browse source
This commit is contained in:
evanboyle 2021-05-27 16:28:28 -07:00
parent ed9124972c
commit dc2488426b
3 changed files with 86 additions and 1 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

31
sdk/go/common/resource/plugin/plugin.go
View file

@ -124,12 +124,16 @@ func newPlugin(ctx *Context, pwd, bin, prefix string, args, env []string) (*plug
logging.V(9).Infof("Launching plugin '%v' from '%v' with args: %v", prefix, bin, argstr)
}
t := time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("execing plugin, %v, %v", prefix, t)
// Try to execute the binary.
plug, err := execPlugin(bin, args, pwd, env)
if err != nil {
return nil, errors.Wrapf(err, "failed to load plugin %s", bin)
}
contract.Assert(plug != nil)
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("done newing plugin, %v, %v", prefix, t)
// If we did not successfully launch the plugin, we still need to wait for stderr and stdout to drain.
defer func() {
@ -138,6 +142,9 @@ func newPlugin(ctx *Context, pwd, bin, prefix string, args, env []string) (*plug
}
}()
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("setup plugin io, %v, %v", prefix, t)
outStreamID := atomic.AddInt32(&nextStreamID, 1)
errStreamID := atomic.AddInt32(&nextStreamID, 1)
@ -178,6 +185,12 @@ func newPlugin(ctx *Context, pwd, bin, prefix string, args, env []string) (*plug
plug.stderrDone = stderrDone
go runtrace(plug.Stderr, true, stderrDone)
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("done setup plugin io, %v, %v", prefix, t)
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("reading plugin port, %v, %v", prefix, t)
// Now that we have a process, we expect it to write a single line to STDOUT: the port it's listening on. We only
// read a byte at a time so that STDOUT contains everything after the first newline.
var port string
@ -213,11 +226,23 @@ func newPlugin(ctx *Context, pwd, bin, prefix string, args, env []string) (*plug
err, "%v plugin [%v] wrote a non-numeric port to stdout ('%v')", prefix, bin, port)
}
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("done reading plugin port, %v, %v", prefix, t)
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("adding plugin stdout io, %v, %v", prefix, t)
// After reading the port number, set up a tracer on stdout just so other output doesn't disappear.
stdoutDone := make(chan bool)
plug.stdoutDone = stdoutDone
go runtrace(plug.Stdout, false, stdoutDone)
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("done adding plugin stdout io, %v, %v", prefix, t)
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("creating grpc plugin client, %v, %v", prefix, t)
// Now that we have the port, go ahead and create a gRPC client connection to it.
conn, err := grpc.Dial(
"127.0.0.1:"+port,
@ -229,6 +254,9 @@ func newPlugin(ctx *Context, pwd, bin, prefix string, args, env []string) (*plug
return nil, errors.Wrapf(err, "could not dial plugin [%v] over RPC", bin)
}
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("done creating grpc plugin client, %v, %v", prefix, t)
// Now wait for the gRPC connection to the plugin to become ready.
// TODO[pulumi/pulumi#337]: in theory, this should be unnecessary. gRPC's default WaitForReady behavior
// should auto-retry appropriately. On Linux, however, we are observing different behavior. In the meantime
@ -271,6 +299,9 @@ func newPlugin(ctx *Context, pwd, bin, prefix string, args, env []string) (*plug
}
}
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("grpc plugin client alive, %v, %v", prefix, t)
// Done; store the connection and return the plugin info.
plug.Conn = conn
return plug, nil

9
sdk/go/common/resource/plugin/provider_plugin.go
View file

@ -21,6 +21,7 @@ import (
"io"
"os"
"strings"
"time"
"github.com/blang/semver"
pbempty "github.com/golang/protobuf/ptypes/empty"
@ -72,6 +73,8 @@ type provider struct {
func NewProvider(host Host, ctx *Context, pkg tokens.Package, version *semver.Version,
options map[string]interface{}, disableProviderPreview bool) (Provider, error) {
// Load the plugin's path by using the standard workspace logic.
t := time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("getting plugin path, %v, %v", pkg, t)
_, path, err := workspace.GetPluginPath(
workspace.ResourcePlugin, strings.Replace(string(pkg), tokens.QNameDelimiter, "_", -1), version)
if err != nil {
@ -83,6 +86,8 @@ func NewProvider(host Host, ctx *Context, pkg tokens.Package, version *semver.Ve
Version: version,
})
}
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("done getting plugin path, %v, %v", pkg, t)
// Runtime options are passed as environment variables to the provider.
env := os.Environ()
@ -90,11 +95,15 @@ func NewProvider(host Host, ctx *Context, pkg tokens.Package, version *semver.Ve
env = append(env, fmt.Sprintf("PULUMI_RUNTIME_%s=%v", strings.ToUpper(k), v))
}
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("newing plugin, %v, %v", pkg, t)
plug, err := newPlugin(ctx, ctx.Pwd, path, fmt.Sprintf("%v (resource)", pkg),
[]string{host.ServerAddr()}, env)
if err != nil {
return nil, err
}
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("done newing plugin, %v, %v", pkg, t)
contract.Assertf(plug != nil, "unexpected nil resource plugin for %s", pkg)
return &provider{

47
sdk/go/common/workspace/plugins.go
View file

@ -190,7 +190,8 @@ func (info *PluginInfo) SetFileMetadata(path string) error {
}
// Next, get the size from the directory (or, if there is none, just the file).
size, err := getPluginSize(path)
// size, err := getPluginSize(path)
size, err := int64(0), nil
if err != nil {
return errors.Wrapf(err, "getting plugin dir %s size", path)
}
@ -536,14 +537,20 @@ func GetPluginDir() (string, error) {
// GetPlugins returns a list of installed plugins.
func GetPlugins() ([]PluginInfo, error) {
// To get the list of plugins, simply scan the directory in the usual place.
t := time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("getting plugin dir, %v", t)
dir, err := GetPluginDir()
if err != nil {
return nil, err
}
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("done getting plugin dir, %v", t)
return getPlugins(dir)
}
func getPlugins(dir string) ([]PluginInfo, error) {
t := time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("reading plugin dir, %v", t)
files, err := ioutil.ReadDir(dir)
if err != nil {
if os.IsNotExist(err) {
@ -551,12 +558,17 @@ func getPlugins(dir string) ([]PluginInfo, error) {
}
return nil, err
}
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("done reading plugin dir, %v", t)
// Now read the file infos and create the plugin infos.
var plugins []PluginInfo
for _, file := range files {
start := time.Now()
// Skip anything that doesn't look like a plugin.
if kind, name, version, ok := tryPlugin(file); ok {
logging.V(1).Infof("success try plugin: %v", time.Since(start))
start = time.Now()
plugin := PluginInfo{
Name: name,
Kind: kind,
@ -569,9 +581,13 @@ func getPlugins(dir string) ([]PluginInfo, error) {
} else if !os.IsNotExist(err) {
return nil, err
}
logging.V(1).Infof("checked plugin: %v", time.Since(start))
start = time.Now()
if err = plugin.SetFileMetadata(path); err != nil {
return nil, err
}
logging.V(1).Infof("set plugin metadata: %v", time.Since(start))
start = time.Now()
plugins = append(plugins, plugin)
}
}
@ -585,6 +601,9 @@ func getPlugins(dir string) ([]PluginInfo, error) {
func GetPluginPath(kind PluginKind, name string, version *semver.Version) (string, string, error) {
var filename string
t := time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("starting plugin path lookup, %v, %v", name, t)
// If we have a version of the plugin on its $PATH, use it, unless we have opted out of this behavior explicitly.
// This supports development scenarios.
if _, isFound := os.LookupEnv("PULUMI_IGNORE_AMBIENT_PLUGINS"); !isFound {
@ -622,12 +641,18 @@ func GetPluginPath(kind PluginKind, name string, version *semver.Version) (strin
}
}
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("getting all plugins in cache, %v, %v", name, t)
// Otherwise, check the plugin cache.
plugins, err := GetPlugins()
if err != nil {
return "", "", errors.Wrapf(err, "loading plugin list")
}
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("done getting all plugins in cache, %v, %v", name, t)
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("searching for plugin match, %v, %v", name, t)
var match *PluginInfo
if !enableLegacyPluginBehavior && version != nil {
logging.V(6).Infof("GetPluginPath(%s, %s, %s): enabling new plugin behavior", kind, name, version)
@ -667,6 +692,9 @@ func GetPluginPath(kind PluginKind, name string, version *semver.Version) (strin
}
}
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("found plugin match, %v, %v", name, t)
if match != nil {
matchDir, err := match.DirPath()
if err != nil {
@ -803,9 +831,13 @@ var installingPluginRegexp = regexp.MustCompile(`\.tmp[0-9]+$`)
// tryPlugin returns true if a file is a plugin, and extracts information about it.
func tryPlugin(file os.FileInfo) (PluginKind, string, semver.Version, bool) {
t := time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
start := time.Now()
logging.V(1).Infof("trying plugin, %v", t)
// Only directories contain plugins.
if !file.IsDir() {
logging.V(11).Infof("skipping file in plugin directory: %s", file.Name())
logging.V(1).Infof("skipping since dir in: %v", time.Since(start))
return "", "", semver.Version{}, false
}
@ -815,13 +847,20 @@ func tryPlugin(file os.FileInfo) (PluginKind, string, semver.Version, bool) {
return "", "", semver.Version{}, false
}
logging.V(1).Infof("ran install regexp: %v", time.Since(start))
start = time.Now()
// Filenames must match the plugin regexp.
match := pluginRegexp.FindStringSubmatch(file.Name())
logging.V(1).Infof("ran plugin regexp: %v", time.Since(start))
start = time.Now()
if len(match) != len(pluginRegexp.SubexpNames()) {
logging.V(11).Infof("skipping plugin %s with missing capture groups: expect=%d, actual=%d",
file.Name(), len(pluginRegexp.SubexpNames()), len(match))
return "", "", semver.Version{}, false
}
logging.V(1).Infof("check cap groups: %v", time.Since(start))
start = time.Now()
var kind PluginKind
var name string
var version *semver.Version
@ -848,6 +887,12 @@ func tryPlugin(file os.FileInfo) (PluginKind, string, semver.Version, bool) {
}
}
logging.V(1).Infof("iterate cap groups: %v", time.Since(start))
start = time.Now()
t = time.Now().UnixNano() / (int64(time.Millisecond) * 1000)
logging.V(1).Infof("done trying plugin, %v", t)
// If anything was missing or invalid, skip this plugin.
if kind == "" || name == "" || version == nil {
logging.V(11).Infof("skipping plugin with missing information: kind=%s, name=%s, version=%v",