Error Handling bug in zc_policy_request_log.go : NewRequestLogPolicyFactory

[plombardi89]

Which version of the SDK was used?

v0.10.0

Which platform are you using? (ex: Windows, Linux, Debian)

Linux

What problem was encountered?

The library falls into a situation where forceLog is enabled for a situation where forceLog should not be set to true

			if err == nil { // We got a response from the service
				sc := response.Response().StatusCode
				if ((sc >= 400 && sc <= 499) && sc != http.StatusNotFound && sc != http.StatusConflict && sc != http.StatusPreconditionFailed && sc != http.StatusRequestedRangeNotSatisfiable) || (sc >= 500 && sc <= 599) {
					fmt.Printf("!!! Status = %d\n", sc)
					logLevel, forceLog = pipeline.LogError, true // Promote to Error any 4xx (except those listed is an error) or any 5xx
				} else {
					// For other status codes, we leave the level as is.
				}
			} else { // This error did not get an HTTP response from the service; upgrade the severity to Error
				fmt.Printf("!!! Unknown error: %v\n", err)
				logLevel, forceLog = pipeline.LogError, true
			}

I was noticing a lot of logging going on that wasn't expected due to a ContainerAlreadyExists error so I added some debug logging to the library to try and figure out where the problem is occuring. The above code maps to this particular error.

Oct 13 18:28:51 : !!! Unknown error: -> github.com/Azure/azure-storage-blob-go/azblob.newStorageError, github.com/Azure/azure-storage-blob-go@v0.10.0/azblob/zc_storage_er
Oct 13 18:28:51 : ===== RESPONSE ERROR (ServiceCode=ContainerAlreadyExists) =====
Oct 13 18:28:51 : Description=The specified container already exists.
Oct 13 18:28:51 : RequestId:dcdad6f3-401e-00a2-518e-a1711e000000
Oct 13 18:28:51 : Time:2020-10-13T18:28:51.8795374Z, Details:
Oct 13 18:28:51 :    Code: ContainerAlreadyExists
Oct 13 18:28:51 :    PUT https://REDACTED.blob.core.windows.net/REDACTED?restype=container&timeout=61
Oct 13 18:28:51 :    Authorization: REDACTED
Oct 13 18:28:51 :    User-Agent: [Azure-Storage/0.10 (go1.15.2; linux)]
Oct 13 18:28:51 :    X-Ms-Client-Request-Id: [ed4b5de8-412c-4fc6-4c55-00d91c1b5f2c]
Oct 13 18:28:51 :    X-Ms-Date: [Tue, 13 Oct 2020 18:28:51 GMT]
Oct 13 18:28:51 :    X-Ms-Version: [2019-02-02]
Oct 13 18:28:51 :    --------------------------------------------------------------------------------
Oct 13 18:28:51 :    RESPONSE Status: 409 The specified container already exists.
Oct 13 18:28:51 :    Content-Length: [230]
Oct 13 18:28:51 :    Content-Type: [application/xml]
Oct 13 18:28:51 :    Date: [Tue, 13 Oct 2020 18:28:51 GMT]
Oct 13 18:28:51 :    Server: [Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0]
Oct 13 18:28:51 :    X-Ms-Client-Request-Id: [ed4b5de8-412c-4fc6-4c55-00d91c1b5f2c]
Oct 13 18:28:51 :    X-Ms-Error-Code: [ContainerAlreadyExists]
Oct 13 18:28:51 :    X-Ms-Request-Id: [dcdad6f3-401e-00a2-518e-a1711e000000]
Oct 13 18:28:51 :    X-Ms-Version: [2019-02-02]

The code is checking that err == nil but somewhere deeper in the library the err being returned is not nil and therefore it falls into this else branch and circumvents the logic contained in the if branch to avoid logging for a http.StatusConflict.

How can we reproduce the problem in the simplest way?

Have you found a mitigation/solution?

Mitigation, not ideal:

func init() {
	pipeline.SetForceLogEnabled(false)
}

[pharaujo]

I have exactly the same problem (manifested here), and was actually looking right now at what was causing this. I believe the problem is that the condition that tests the HTTP status code never sees the 4xx and 5xx because they are encapsulated in a StorageError. I will send a PR with a suggestion fix shortly.

[serprex]

@mohsha-msft this issue can be closed