v1.3: RFE: SolidFire: Log error if failure to create "TenantName" (instead of silently ignored)

[dutchiechris]

According to the SolidFire config documentation if the TenantName (Account on SolidFire) does not exist it will be dynamically created. Testing shows this to not be the case.

The code snippet in solidfire_san.go that does not appear to function properly is:

// lookup the specified account; if not found, dynamically create it
    account, err := client.GetAccountByName(&req)
    if err != nil {
        req := sfapi.AddAccountRequest{
            Username: c.TenantName,
        }
        tenantID, err = client.AddAccount(&req)
        if err != nil {
            log.Fatal("Failed to initialize solidfire driver while creating tenant: ", err)
        }
    } else {
        tenantID = account.AccountID
    }

debug: true logging snippet is:

time="2017-01-26T20:43:35Z" level=info msg="Using storage driver: solidfire-san"
time="2017-01-26T20:43:35Z" level=info msg="Using config: {1 solidfire-san true false [] []}"
time="2017-01-26T20:43:35Z" level=info msg="Starting docker volume plugin with the following options:" port=27609 volume-driver=netapp volumeDir="/var/lib/docker-volumes/netapp"
time="2017-01-26T20:43:48Z" level=debug msg="Get({hellpo map[]})"
time="2017-01-26T20:43:48Z" level=debug msg="Getting path for volume 'netappdvp-hello' as '/var/lib/docker-volumes/netapp/netappdvp-hellpo'"
time="2017-01-26T20:43:48Z" level=debug msg="Create({hellpo map[]})"
time="2017-01-26T20:43:48Z" level=debug msg="SolidfireSANStorageDriver#Create(netappdvp-hellpo)"
time="2017-01-26T20:43:48Z" level=debug msg="GetVolumeByName: netappdvp-hello, 0"
time="2017-01-26T20:43:48Z" level=debug msg="Options passed in to create: map[]"
time="2017-01-26T20:43:48Z" level=debug msg="Issueing request to SolidFire Endpoint..."
time="2017-01-26T20:43:48Z" level=debug msg="POST request to: https://user:pass@10.64.35.240/json-rpc/7.0"
time="2017-01-26T20:43:48Z" level=debug msg="request:816 method:ListVolumesForAccount params:&{0}" ="{\n  \"error\": {\n    \"code\": 500,\n    \"message\": \"Illegal AccountID 0\",\n    \"name\": \"xAccountIDDoesNotExist\"\n  },\n  \"id\": 816\n}"
time="2017-01-26T20:43:48Z" level=error msg="Received error response from API request"
time="2017-01-26T20:43:48Z" level=error msg="Error retrieving volumes: Received error response from API request"
time="2017-01-26T20:43:48Z" level=debug msg="Options after conversion: map[]"
time="2017-01-26T20:43:48Z" level=info msg="Creating with default size of: 1073741824"
time="2017-01-26T20:43:48Z" level=debug msg="Issueing request to SolidFire Endpoint..."
time="2017-01-26T20:43:48Z" level=debug msg="POST request to: https://user:pass@10.64.35.240/json-rpc/7.0"
time="2017-01-26T20:43:48Z" level=debug msg="request:918 method:CreateVolume params:&{netappdvp-hellpo 0 1073741824 false {0 0 0 0} map[platform:Docker-NDVP]}" ="{\n  \"error\": {\n    \"code\": 500,\n    \"message\": \"Could not find an account with the given accountID.\",\n    \"name\": \"xAccountIDDoesNotExist\"\n  },\n  \"id\": 918\n}"

[j-griffith]

Yup, you're correct. The logic from the original SFDP is there, but something's not getting hit right. I'll take a look and get it fixed up.

[j-griffith]

So it turns out that it does work, but there's something going on intermittently that we're not catching or reporting clearly. I did see this in some testing earlier, but in trying to force the issue this afternoon I'm not having any luck reproducing it again. If you can make this happen consistently I'd love to instrument your setup with some additional debugging. Even just some debug statements around the GetAccountByName response and Create.

Unfortunately the current code masks out any debug logging during init, but thats easy enough to adjust: https://gist.github.com/j-griffith/8d6222adfaa07f7eb8146b8c93a23851

[dutchiechris]

I found it: RBAC. I had a user that had only volume access rights. When I enabled the user for accounts as well it worked. Duh.

I guess the "fix" for nDVP would be to improve logging in case it encountered a problem during dynamic account creation, including RBAC permission denied. Especially because the SF event log is silent in case of blocked API calls (maybe open an RFE there?) the root cause isn't obvious by checking logs...

Thanks!

[j-griffith]

I've added debug logging during init, I think this will address the issue you're seeing. Check out the latest release and let me know if there's still a problem you're seeing. I believe this can be closed at this point.

[adkerr]

@j-griffith Do you know which commit resolved this issue?

[dutchiechris]

Hi @j-griffith,

Here is the result if you start the netappdvp using a config.json where the tenant does not exist and the user does not have enough RBAC priv to create it:

[root@centos72 netappdvp]# ./netappdvp -debug
ERRO[2017-02-08T11:05:59Z] error detected in API response: {ID:859 Error:{Code:500 Message:xUnknownAccount Name:xUnknownAccount}}
ERRO[2017-02-08T11:05:59Z] error detected in API response: {ID:175 Error:{Code:500 Message:xPermissionDenied Name:xPermissionDenied}}
INFO[2017-02-08T11:05:59Z] successfully initialized SolidFire Docker driver version 1.3.3 [native]
Logfile Location (Level: debug): /var/log/netappdvp/netapp.log

If the tenant does not exist and you do have enough priv to create:

[root@centos72 netappdvp]# ./netappdvp -debug
ERRO[2017-02-08T11:10:38Z] error detected in API response: {ID:90 Error:{Code:500 Message:xUnknownAccount Name:xUnknownAccount}}
INFO[2017-02-08T11:10:38Z] successfully initialized SolidFire Docker driver version 1.3.3 [native]
Logfile Location (Level: debug): /var/log/netappdvp/netapp.log

The errors were logged to the interactive session and are not found in the netapp.log logfile.

I would suggest:

1. Make sure logging occurs to the netapp.log file
2. Remove the ERROR thrown if the account doesn't exist and instead log a more descriptive INFO message explaning that the account was not found and will be created.
3. In case the account can't be created log an ERROR that the Account doesn't exist and could not be created and then exit. Leave the existing 500 errror with permission denied as-is.

My 2 cents. Thanks for your work on this!

[innergy]

Tried this myself with the latest code and I still see the root issue when using a user that's unable to create a tenant and that tenant does not yet exist. Recent logging changes do assure that the error shows up in the log file now, but we're not any more clear about the reason for the failure. We also allow the plugin to continue to initialize and start in this scenario even though all subsequent operations will fail.

[j-griffith]

I've added some detection for unauthorized in the response from API requests, log it and return an error which should result in a fatal during init. The sequence looks like this, I hope that this will be sufficient:

ubuntu@ndvp:~/go/src/github.com/netapp/netappdvp$ sudo ./netappdvp -debug -config /etc/netappdvp/solidfire.json -log-level debug time="2017-05-24T19:43:15Z" level=info msg="Initialized logging." buildTime=unknown driverBuild="17.07.0-custom+unknown" driverVersion=17.07.0-custom logFileLocation="/var/log/netappdvp/netapp.log" logLevel=debug time="2017-05-24T19:43:15Z" level=debug msg="Setting default volume size." size=1G time="2017-05-24T19:43:15Z" level=debug msg="Parsed commonConfig: {Version:1 StorageDriverName:solidfire-san Debug:false DebugTraceFlags:map[] DisableDelete:false StoragePrefixRaw:[] SnapshotPrefixRaw:[] CommonStorageDriverConfigDefaults:{Size:1G}}" time="2017-05-24T19:43:15Z" level=debug msg="SolidfireSANStorageDriver#Initialize(...)" time="2017-05-24T19:43:15Z" level=debug msg="Reparsed into solidfireConfig" DisableDelete=false SnapshotPrefixRaw= StorageDriverName=solidfire-san StoragePrefixRaw= Version=1 time="2017-05-24T19:43:15Z" level=debug msg="Decoded to &{CommonStorageDriverConfig:{Version:1 StorageDriverName:solidfire-san Debug:false DebugTraceFlags:map[] DisableDelete:false StoragePrefixRaw:[] SnapshotPrefixRaw:[] CommonStorageDriverConfigDefaults:{Size:}} TenantName:ndvp EndPoint:https://foo:foopassword@10.117.36.101/json-rpc/7.0 DefaultVolSz:1 SVIP:10.117.37.101:3260 InitiatorIFace:default Types:0xc4200d0fc0 LegacyNamePrefix:netappdvp-}" time="2017-05-24T19:43:15Z" level=debug msg="About to call NewFromParameters" cfg={ndvp https://foo:foopassword@10.117.36.101/json-rpc/7.0 10.117.37.101:3260 default 0xc4200d0fc0 netappdvp-} defaultTenantName=ndvp endpoint="https://foo:foopassword@10.117.36.101/json-rpc/7.0" svip="10.117.37.101:3260" time="2017-05-24T19:43:15Z" level=debug msg="issuing request to SolidFire endpoint: {"id":521,"method":"GetAccountByName","params":{"username":"ndvp"}}" time="2017-05-24T19:43:15Z" level=debug msg="response to api call GetAccountByName: &{Status:200 OK StatusCode:200 Proto:HTTP/1.1 ProtoMajor:1 ProtoMinor:1 Header:map[Content-Type:[application/json] Access-Control-Allow-Methods:[GET, POST, OPTIONS] Access-Control-Allow-Headers:[DNT,X-CustomHeader,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization] Access-Control-Allow-Credentials:[true] Server:[nginx/1.9.14] Date:[Wed, 24 May 2017 19:43:15 GMT] Connection:[keep-alive] Vary:[Accept-Encoding]] Body:0xc420010240 ContentLength:-1 TransferEncoding:[chunked] Close:false Uncompressed:true Trailer:map[] Request:0xc4200d6870 TLS:0xc4200a86e0}" time="2017-05-24T19:43:15Z" level=warning msg="error detected in API response: {ID:521 Error:{Code:500 Message:xUnknownAccount Name:xUnknownAccount}}" time="2017-05-24T19:43:15Z" level=debug msg="issuing request to SolidFire endpoint: {"id":615,"method":"AddAccount","params":{"username":"ndvp"}}" time="2017-05-24T19:43:15Z" level=debug msg="response to api call AddAccount: &{Status:200 OK StatusCode:200 Proto:HTTP/1.1 ProtoMajor:1 ProtoMinor:1 Header:map[Connection:[keep-alive] Vary:[Accept-Encoding] Access-Control-Allow-Headers:[DNT,X-CustomHeader,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization] Access-Control-Allow-Credentials:[true] Date:[Wed, 24 May 2017 19:43:15 GMT] Content-Type:[application/json] Access-Control-Allow-Methods:[GET, POST, OPTIONS] Server:[nginx/1.9.14]] Body:0xc420010ba0 ContentLength:-1 TransferEncoding:[chunked] Close:false Uncompressed:true Trailer:map[] Request:0xc4201624b0 TLS:0xc4200a8790}" time="2017-05-24T19:43:15Z" level=warning msg="error detected in API response: {ID:615 Error:{Code:500 Message:xPermissionDenied Name:xPermissionDenied}}" time="2017-05-24T19:43:15Z" level=error msg="error detected in AddAccount API response: device API error: xPermissionDenied" time="2017-05-24T19:43:15Z" level=fatal msg="failed to initialize solidfire driver while creating tenant: device API error"