Improve step logging (#88)

* Improve step logging

* Fix vendor

* *

* *

* *

* *

* *

README.md

@@ -59,6 +59,7 @@ You can also run this step directly with [Bitrise CLI](https://github.com/bitris
 | `default_certificate_url` | URL of the default certificate.  You can specify a local path as well, using the `file://` scheme. For example `file://./Cert.p12`  | sensitive | `$BITRISE_DEFAULT_CERTIFICATE_URL` |
 | `default_certificate_passphrase` | Passphrase of the default Certificate.  | sensitive | `$BITRISE_DEFAULT_CERTIFICATE_PASSPHRASE` |
 | `default_provisioning_profile_url` | URL of the default provisioning profile to download.  You can specify a local path as well, using the `file://` scheme. For example `file://./BuildAnything.mobileprovision`  | sensitive | `$BITRISE_DEFAULT_PROVISION_URL` |
+| `verbose` | Enable logging additional information for troubleshooting | required | `false` |
 </details>
 
 <details>

go.sum

@@ -17,6 +17,7 @@ github.com/bitrise-io/go-xcode/v2 v2.0.0-alpha.42/go.mod h1:BFDhHF1ftPWpnZt4sjpP
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/fatih/color v1.16.0 h1:zmkK9Ngbjj+K0yRhTVONQh1p/HknKYSlNT+vZCzyokM=
 github.com/fullsailor/pkcs7 v0.0.0-20190404230743-d7302db945fa h1:RDBNVkRviHZtvDvId8XSGPu3rmpmSe+wKRcEWNgsfWU=
 github.com/fullsailor/pkcs7 v0.0.0-20190404230743-d7302db945fa/go.mod h1:KnogPXtdwXqoenmZCw6S+25EAm2MkxbG0deNDu4cbSA=
 github.com/golang-jwt/jwt/v4 v4.5.0 h1:7cYmW1XlMY7h7ii7UhUyChSgS5wUJEnm9uZVTGqOWzg=
@@ -28,16 +29,16 @@ github.com/google/go-querystring v1.1.0/go.mod h1:Kcdr2DB4koayq7X8pmAG4sNG59So17
 github.com/hashicorp/go-cleanhttp v0.5.1/go.mod h1:JpRdi6/HCYpAwUzNwuwqhbovhLtngrth3wmdIIUrZ80=
 github.com/hashicorp/go-cleanhttp v0.5.2 h1:035FKYIWjmULyFRBKPs8TBQoi0x6d9G4xc9neXJWAZQ=
 github.com/hashicorp/go-cleanhttp v0.5.2/go.mod h1:kO/YDlP8L1346E6Sodw+PrpBSV4/SoxCXGY6BqNFT48=
-github.com/hashicorp/go-hclog v0.9.2 h1:CG6TE5H9/JXsFWJCfoIVpKFIkFe6ysEuHirp4DxCsHI=
 github.com/hashicorp/go-hclog v0.9.2/go.mod h1:5CU+agLiy3J7N7QjHK5d05KxGsuXiQLrjA0H7acj2lQ=
+github.com/hashicorp/go-hclog v1.6.3 h1:Qr2kF+eVWjTiYmU7Y31tYlP1h0q/X3Nl3tPGdaB11/k=
 github.com/hashicorp/go-retryablehttp v0.7.0/go.mod h1:vAew36LZh98gCBJNLH42IQ1ER/9wtLZZ8meHqQvEYWY=
-github.com/hashicorp/go-retryablehttp v0.7.4 h1:ZQgVdpTdAL7WpMIwLzCfbalOcSUdkDZnpUv3/+BxzFA=
-github.com/hashicorp/go-retryablehttp v0.7.4/go.mod h1:Jy/gPYAdjqffZ/yFGCFV2doI5wjtH1ewM9u8iYVjtX8=
 github.com/hashicorp/go-retryablehttp v0.7.7 h1:C8hUCYzor8PIfXHa4UrZkU4VvK8o9ISHxT2Q8+VepXU=
 github.com/hashicorp/go-retryablehttp v0.7.7/go.mod h1:pkQpWZeYWskR+D1tR2O5OcBFOxfA7DoAO6xtkuQnHTk=
 github.com/hashicorp/go-version v1.6.0 h1:feTTfFNnjP967rlCxM/I9g701jU+RN74YKx2mOkIeek=
 github.com/hashicorp/go-version v1.6.0/go.mod h1:fltr4n8CU8Ke44wwGCBoEymUuxUHl09ZGVZPK5anwXA=
 github.com/jessevdk/go-flags v1.4.0/go.mod h1:4FA24M0QyGHXBuZZK/XkWh8h0e1EYbRYJSGM75WSRxI=
+github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA=
+github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY=
 github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
 github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
@@ -64,6 +65,7 @@ golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20211205182925-97ca703d548d/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.20.0 h1:Od9JTbYCk261bKm4M/mw7AklTlFYIa0bIp9BgSm1S8Y=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
 golang.org/x/term v0.0.0-20210927222741-03fcf44c2211/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8=
 golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=

main.go

@@ -6,6 +6,7 @@ import (
 	"net/http"
 	"os"
 	"strings"
+	"time"
 	"unicode/utf8"
 
 	"github.com/bitrise-io/go-steputils/input"
@@ -14,6 +15,7 @@ import (
 	"github.com/bitrise-io/go-utils/retry"
 	"github.com/bitrise-io/go-utils/v2/command"
 	"github.com/bitrise-io/go-utils/v2/env"
+	"github.com/bitrise-io/go-utils/v2/log/colorstring"
 	"github.com/bitrise-io/go-xcode/certificateutil"
 	"github.com/bitrise-io/go-xcode/v2/autocodesign/certdownloader"
 	"github.com/bitrise-io/go-xcode/v2/autocodesign/codesignasset"
@@ -35,6 +37,8 @@ type Config struct {
 
 	KeychainPath     string
 	KeychainPassword string
+
+	Verbose bool
 }
 
 func createConfigFromEnvs() Config {
@@ -50,6 +54,8 @@ func createConfigFromEnvs() Config {
 
 		KeychainPath:     os.Getenv("keychain_path"),
 		KeychainPassword: os.Getenv("keychain_password"),
+
+		Verbose: os.Getenv("verbose") == "true",
 	}
 }
 
@@ -102,7 +108,7 @@ func secureInput(str string) string {
 
 func (c Config) print() {
 	fmt.Println()
-	log.Infof("Configs:")
+	log.Infof("Inputs:")
 	log.Printf(" - CertificateURL: %s", secureInput(c.CertificateURL))
 	log.Printf(" - CertificatePassphrase: %s", secureInput(c.CertificatePassphrase))
 	log.Printf(" - ProvisioningProfileURL: %s", secureInput(c.ProvisioningProfileURL))
@@ -179,10 +185,10 @@ func appendWithoutDuplicatesAndKeepOrder(items []string, item string) []string {
 }
 
 func printCertificateInfo(info certificateutil.CertificateInfoModel) {
-	log.Donef(info.CommonName)
-	log.Printf("serial: %s", info.Serial)
-	log.Printf("team: %s (%s)", info.TeamName, info.TeamID)
-	log.Printf("expiry: %s", info.EndDate)
+	log.Printf(colorstring.Magenta(info.CommonName))
+	log.Printf("Serial: %s", info.Serial)
+	log.Printf("Team: \t%s (%s)", info.TeamName, info.TeamID)
+	log.Printf("Expiry: %s", info.EndDate)
 
 	if err := info.CheckValidity(); err != nil {
 		log.Errorf("[X] %s", err)
@@ -203,8 +209,10 @@ func main() {
 	configs := createConfigFromEnvs()
 	configs.print()
 	if err := configs.validate(); err != nil {
-		failF("Issue with input: %s", err)
+		failF("Issue with inputs: %s", err)
 	}
+	log.SetEnableDebugLog(configs.Verbose)
+
 	fmt.Println()
 
 	// Collect Certificates
@@ -274,8 +282,9 @@ func main() {
 
 	retryHTTPClient := retry.NewHTTPClient()
 	retryHTTPClient.CheckRetry = func(ctx context.Context, resp *http.Response, err error) (bool, error) {
+		log.Debugf("HTTP retry: %s", err)
 		if resp != nil && resp.StatusCode == http.StatusNotFound {
-			log.Debugf("Received HTTP 404, retrying request...")
+			log.Debugf("Received HTTP 404, retrying request: %s %s", resp.Request.Method, resp.Request.URL)
 			return true, nil
 		}
 
@@ -287,20 +296,27 @@ func main() {
 	assetInstaller := codesignasset.NewWriter(*keychainWriter)
 
 	fmt.Println()
-	log.Infof("Downloading Certificate(s)...")
+	log.Infof("Downloading Certificates...")
 
+	certDownloadStart := time.Now()
 	certificates, err := certDownloader.GetCertificates()
 	if err != nil {
 		failE(fmt.Errorf("Download failed: %w", err))
 	}
 
-	log.Printf("%d Certificate(s) downloaded.", len(certificates))
+	log.Printf("Download took %s", time.Since(certDownloadStart).Round(time.Millisecond))
+	if len(certificates) == 1 {
+		log.Donef("1 certificate downloaded")
+	} else {
+		log.Donef("%d certificates downloaded", len(certificates))
+	}
 
 	fmt.Println()
-	log.Infof("Installing downloaded Certificates")
+	log.Infof("Installing downloaded certificates...")
 
+	certInstallStart := time.Now()
 	for i, cert := range certificates {
-		log.Printf("%d/%d Certificate:", i+1, len(certificates))
+		log.Printf("%d/%d:", i+1, len(certificates))
 		printCertificateInfo(cert)
 
 		if err := assetInstaller.InstallCertificate(cert); err != nil {
@@ -309,27 +325,49 @@ func main() {
 
 		fmt.Println()
 	}
+	log.Printf("Installation took %s", time.Since(certInstallStart).Round(time.Millisecond))
+	log.Donef("Certificates installed.")
 
 	fmt.Println()
-	log.Infof("Downloading Provisioning Profile(s)...")
+	log.Infof("Downloading Provisioning Profiles...")
 
+	profileDownloadStart := time.Now()
 	profiles, err := profileDownloader.GetProfiles()
 	if err != nil {
 		failE(fmt.Errorf("Download failed: %w", err))
 	}
+	log.Printf("Download took %s", time.Since(profileDownloadStart).Round(time.Millisecond))
 
-	log.Printf("%d Provisioning Profile(s) downloaded.", len(profiles))
+	if len(profiles) == 1 {
+		log.Donef("1 Provisioning Profile downloaded.")
+	} else {
+		log.Donef("%d Provisioning Profiles downloaded.", len(profiles))
+	}
 
 	fmt.Println()
-	log.Infof("Installing Provisioning Profile(s)")
+	log.Infof("Installing Provisioning Profiles...")
 
+	profileInstallStart := time.Now()
 	for i, profile := range profiles {
-		log.Printf("%d/%d Provisioning Profile:", i+1, len(profiles))
-		log.Printf("%s", profile.Info.String(certificates...))
+		log.Printf("%d/%d:", i+1, len(profiles))
+		if configs.Verbose {
+			log.Debugf("%s", profile.Info.String(certificates...))
+		} else {
+			log.Printf("%s", colorstring.Magenta(profile.Info.Name))
+			log.Printf("Type: \t\t%s", profile.Info.Type)
+			log.Printf("Expiry: \t%s", profile.Info.ExpirationDate)
+			log.Printf("Bundle ID: \t%s", profile.Info.BundleID)
+			log.Printf("Included certificates:")
+			for _, cert := range profile.Info.DeveloperCertificates {
+				log.Printf("- %s", cert.CommonName)
+			}
+		}
 		fmt.Println()
 
 		if err := assetInstaller.InstallProfile(profile.Profile); err != nil {
 			failE(fmt.Errorf("Failed to install Provisioning Profile: %w", err))
 		}
 	}
+	log.Printf("Installation took %s", time.Since(profileInstallStart).Round(time.Millisecond))
+	log.Donef("Provisioning Profiles installed.")
 }

step.yml

@@ -135,3 +135,11 @@ inputs:
       You can specify a local path as well, using the `file://` scheme.
       For example `file://./BuildAnything.mobileprovision`
     is_sensitive: true
+- verbose: "false"
+  opts:
+    title: Verbose logging
+    summary: Enable logging additional information for troubleshooting
+    is_required: true
+    value_options:
+    - "true"
+    - "false"