SNOW-724764: Silent failure for PUT operation

[mihaitodor]

Issue description

This driver fails to upload files silently when compiled with CGO_ENABLED=0 and the USER environment variable isn't set. This can happen, for example, when running the app in a simple Go container with --user 1000:1000 (try docker run --rm -it --user 1000:1000 golang:1.18-alpine sh). I tried adding gosnowflake.GetLogger().SetLogLevel("trace"), but there's no hint in the output that a failure has occurred.

One cause for the issue is here, where the error is swallowed for some reason... I modified the code and logged the error returned by it and it contains "user: Current requires cgo or $USER set in environment", which helped me find the root cause. Even so, returning non-nil errors there doesn't seem to be enough to trigger a failure log, so more changes might be needed.

Not sure if you considered adding extra linting to this repo, but I believe golangci-lint should be able to detect missing error checks, among other potential issues and it can be run with ease using GitHub Actions: https://github.com/marketplace/actions/run-golangci-lint

Example code

The sample code from the docs here should suffice.

Error log

N/A

Configuration

Driver version (or git SHA):
v1.6.16

Go version: run go version in your console
go version go1.19.4 darwin/amd64

Server version: E.g. 1.90.1
You may get the server version by running a query:

SELECT CURRENT_VERSION();

7.0.0

Client OS: E.g. Debian 8.1 (Jessie), Windows 10

golang:1.18-alpine Docker container.

[sfc-gh-dszmolka]

hi and thank you for submitting this issue with us! special thanks for providing a detailed error description 👍
tried to reproduce the same issue but obviously doing something wrong, because could not get to it.

1. using golang:1.19-alpine or golang:1.18-alpine base image, did not matter
2. using the sample1.go example script to connect to Snowflake + execute the query; which has been modified to be

query := "PUT file:///go/gosnowflake/cmd/select1/select1.go @~ OVERWRITE=true"

should suffice from the reproduction perspective.

Also modified the Config to have some deeper logging, something like this:

	cfg := &sf.Config{
		Account:  account,
		User:     user,
..
		Tracing: "debug",
	}

(few more words about this connection parameter)

3. however when i'm running the container (which has the CMD of running the binary compiled from the example program) I don't get the issue you're getting, but something else instead (user: unknown userid 1000):

$ docker run --rm --user 1000:1000 --env-file=gh700.env gh701:1 #env file with account, user, password, etc. envvars
..
INFO[0002]connection.go:309 gosnowflake.(*snowflakeConn).queryContextInternal Query: "PUT file:///go/gosnowflake/cmd/select1/select1.go @~ OVERWRITE=true", [] 
INFO[0002]connection.go:92 gosnowflake.(*snowflakeConn).exec parameters: map[]                            
INFO[0002]connection.go:101 gosnowflake.(*snowflakeConn).exec bindings: map[]                              
INFO[0002]log.go:106 gosnowflake.(*defaultLogger).Infof params: &map[]                               
INFO[0002]retry.go:211 gosnowflake.(*retryHTTP).execute retryHTTP.totalTimeout: 0s                   
DEBU[0002]log.go:102 gosnowflake.(*defaultLogger).Debugf retry count: 0                               
INFO[0002]restful.go:216 gosnowflake.postRestfulQueryHelper postQuery: resp: &{200 OK 200 HTTP/1.1 1 1 map[Cache-Control:[no-cache, no-store] Connection:[keep-alive] Content-Type:[application/json] Date:[Wed, 29 Mar 2023 17:02:41 GMT] Expect-Ct:[enforce, max-age=3600] Strict-Transport-Security:[max-age=31536000] Vary:[Accept-Encoding, User-Agent] X-Content-Type-Options:[nosniff] X-Country:[<x-country>] X-Frame-Options:[deny] X-Xss-Protection:[: 1; mode=block]] 0xc00037ff40 -1 [] false true map[] 0xc000112300 0xc0000da4d0} 
INFO[0002]connection.go:131 gosnowflake.(*snowflakeConn).exec Success: true, Code: -1                      
ERRO[0002]connection.go:320 gosnowflake.(*snowflakeConn).queryContextInternal error: user: unknown userid 1000             
2023/03/29 17:02:41 failed to run a query. PUT file:///go/gosnowflake/cmd/select1/select1.go @~ OVERWRITE=true, err: user: unknown userid 1000

so if you could please provide further details on how to get to this issue, that would be very helpful to troubleshoot this issue further.

Finally, thank you for the suggestion on the extra linting, will draw the team's attention.

[mihaitodor]

Hey @sfc-gh-dszmolka, here's how I was able to reproduce it just now:

> mkdir gosnowflake_test && cd gosnowflake_test
> go mod init gosnowflake-test
> touch main.go

I added this code in main.go:

package main

import (
	"bytes"
	"context"
	"crypto/rsa"
	"database/sql"
	"encoding/pem"
	"errors"
	"fmt"
	"log"
	"os"

	"github.com/snowflakedb/gosnowflake"
	"github.com/youmark/pkcs8"
	"golang.org/x/crypto/ssh"
)

func getPrivateKey(path, passphrase string) (*rsa.PrivateKey, error) {
	privateKeyBytes, err := os.ReadFile(path)
	if err != nil {
		return nil, fmt.Errorf("failed to read private key %s: %s", path, err)
	}
	if len(privateKeyBytes) == 0 {
		return nil, errors.New("private key is empty")
	}

	privateKeyBlock, _ := pem.Decode(privateKeyBytes)
	if privateKeyBlock == nil {
		return nil, fmt.Errorf("could not parse private key, key is not in PEM format")
	}

	if privateKeyBlock.Type == "ENCRYPTED PRIVATE KEY" {
		if passphrase == "" {
			return nil, fmt.Errorf("private key requires a passphrase, but private_key_passphrase was not supplied")
		}

		// Only keys encrypted with pbes2 http://oid-info.com/get/1.2.840.113549.1.5.13 are supported.
		// pbeWithMD5AndDES-CBC http://oid-info.com/get/1.2.840.113549.1.5.3 is not supported.
		privateKey, err := pkcs8.ParsePKCS8PrivateKeyRSA(privateKeyBlock.Bytes, []byte(passphrase))
		if err != nil {
			return nil, fmt.Errorf("failed to decrypt encrypted private key (only ciphers aes-128-cbc, aes-128-gcm, aes-192-cbc, aes-192-gcm, aes-256-cbc, aes-256-gcm, and des-ede3-cbc are supported): %s", err)
		}

		return privateKey, nil
	}

	privateKey, err := ssh.ParseRawPrivateKey(privateKeyBytes)
	if err != nil {
		return nil, fmt.Errorf("could not parse private key: %s", err)
	}

	rsaPrivateKey, ok := privateKey.(*rsa.PrivateKey)
	if !ok {
		return nil, fmt.Errorf("private key must be of type RSA but got %T instead: ", privateKey)
	}
	return rsaPrivateKey, nil
}

func main() {
	privateKey, err := getPrivateKey("/home/.ssh/snowflake_rsa_key.pem", "test")
	if err != nil {
		log.Fatalf("failed to read private key: %s", err)
	}

	if err := gosnowflake.GetLogger().SetLogLevel("trace"); err != nil {
		log.Fatalf("failed to set log level: %s", err)
	}

	dsn, err := gosnowflake.DSN(&gosnowflake.Config{
		Account:       "TODO",
		Authenticator: gosnowflake.AuthTypeJwt,
		User:          "TODO",
		Role:          "TODO",
		Database:      "TODO",
		Warehouse:     "TODO",
		Schema:        "TODO",
		PrivateKey:    privateKey,
		Tracing:       "debug",
	})
	if err != nil {
		log.Fatalf("failed to create DSN: %s", err)
	}

	db, err := sql.Open("snowflake", dsn)
	if err != nil {
		log.Fatalf("failed to connect to snowflake: %s", err)
	}

	_, err = db.ExecContext(gosnowflake.WithFileStream(context.Background(), bytes.NewReader([]byte("foobar"))), "PUT file:///./foo.txt @~ OVERWRITE=true")
	if err != nil {
		log.Fatalf("failed to write to snowflake: %s", err)
	}
}

NOTES:

• You'll have to substitute the TODO strings in gosnowflake.Config with your own account data.
• You'll have to placesnowflake_rsa_key.pem in your ${HOME}/.ssh directory encrypted with password "test". It needs to be encrypted using PKCS#5 v2.0 (openssl genrsa 2048 | openssl pkcs8 -topk8 -v2 des3 -inform PEM -out snowflake_rsa_key.p8) and it has to be assigned to your user.

> docker run --rm -it -v $(pwd):/workspace -v ${HOME}/.ssh:/home/.ssh --name=golang golang:1.20-alpine sh
/go # cd /workspace/
/workspace # go mod tidy
/workspace # CGO_ENABLED=0 go build .

Leave this terminal window open and launch a new one:

> docker exec -it --user=1000 golang sh
/go $ cd /workspace/
/workspace $ ./gosnowflake-test

Note that you won't get foo.txt.gz when you'll run ls @~; in the web console.

Now go to the terminal in which you ran go build and execute ./gosnowflake-test. You should get foo.txt.gz in your stage.

Here is the log from when it fails:
failed.txt

And here is the log from when it succeeds:
success.txt

[sfc-gh-dszmolka]

hi @mihaitodor this is awesome 🤩 thank you for these details; could easily reproduce the issue. i could not yet figure out where user.Current() is called exactly in the driver, but we'll take a look.

in addition as other folks hinted on the internet for similar issues with different libraries:

• Error: Failed to get user environment user: Current requires cgo or $USER set in environment splunk-terraform/terraform-provider-signalfx#266
• Error: user: Current requires cgo or $HOME set in environment digitalocean/doctl#734

the issue can be worked around by adding the envvar and setting USER to literally any user, even a nonexistant one. Either directly to the container runtime (-e USER=iamnothere) or directly to the Go program invocation (USER=iamnothere ./gosnowflake_test).
Anyways, we'll take a look what can be done. Thank you again for all the efforts, really appreciated !

[mihaitodor]

Awesome, thanks for the quick test and glad you were able to reproduce it! It's probably fine to require the USER env var to be set (which is what I ended up doing as a workaround), but the problem is not getting any indication of the failure when it's not set. I expect the driver to return an error back to the user app in such cases, which is why I pointed out that code where the returned error is not checked

[sfc-gh-dszmolka]

absolutely agree, and that's why one of the asks to the driver team is to provide a better/more intuitive error message if possible ;) will keep this Issue updated with the progress.

[sfc-gh-dszmolka]

as it turns out, the offending user.Current() is being called when s3_storage_client.extractBucketNameAndPath() calls file_util.expandUser(). If the file is small, it goes through the flow for uploading in parallel. If we look here, a map is created to store results and errors for each file. Whether or not the error is thrown depends on the option 'RaisePutGetError': https://github.com/snowflakedb/gosnowflake/blob/master/file_transfer_agent.go#L1049

The behaviour is not changed, but the error handling is better and more intuitive, and is coming with #770 which is already merged and awaiting the next release which is expected towards end of April.

[mihaitodor]

@sfc-gh-dszmolka Thank you very much! This also revealed that, in my use case inside Benthos, I should probably add ctx := gosnowflake.WithFileTransferOptions(context.Background(), &gosnowflake.SnowflakeFileTransferOptions{RaisePutGetError: true}).

Somehow, I didn't notice this before. Might be worth mentioning it in the docs here.

Otherwise, happy to close this issue.

[sfc-gh-dszmolka]

fix released with 1.6.20