gogoogle-cloud-storagego-context

File is not commited to google cloud storage when using http.Request.Context() instead of context.Background()

I'm new to go and I write a simple pet project to upload encrypted files to google cloud storage. The problem: In my http handler on the line where I call AddEntry function, when I pass r.Context() instead of context.Background(), file is not uploaded to google storage. In google's console I can see bytes received, also I don't get any errors at all, but file itself is not there.

Handler code:



//imports, structs skipped

func ProcessAddEntryRequest(w http.ResponseWriter, r *http.Request) {
    //validation, getting params from jwt skipped

    reader, err := r.MultipartReader()
    if err != nil {
        http.Error(w, "multipart/form-data expected, not found", http.StatusBadRequest)
        log.Println("could not init MultipartReader from request: %w", err)
        return
    }

    gsService, err := googleStorageService.New()
    if err != nil {
        http.Error(w, "internal server error", http.StatusInternalServerError)
        log.Println(err)
        return
    }

    bservice, err := backupService.New(
        backupService.WithCipher(aes.New()),
        backupService.WithStorageService(gsService))

    if err != nil {
        http.Error(w, "internal server error", http.StatusInternalServerError)
        log.Println(err)
        return
    }
    var entry *entryRepo.BackupEntry
    for {
        part, err := reader.NextPart()
        if err == io.EOF {
            break
        }
        if err != nil {
            err = fmt.Errorf("error reading: %w", err)
            log.Println(err)
            http.Error(w, "internal server error", http.StatusInternalServerError)
            return
        }

        formName := part.FormName()
        if formName == "file" {
            entry, err = bservice.AddEntry(r.Context(), backupId, part.FileName(), part.Header.Get("Content-Type"), part)
            if err != nil {
                errClose := part.Close()
                err = fmt.Errorf("failed to add entry for backup %s: %w; error while closing multipart.Part: %w", backupId, err, errClose)
                log.Println(err)
                http.Error(w, "internal server error", http.StatusInternalServerError)
                return

            }
        }
        err = part.Close()
        if err != nil {
            err = fmt.Errorf("failed to close part for backup %s: %w", backupId, err)
            log.Println(err)
            http.Error(w, "internal server error", http.StatusInternalServerError)
            return
        }

    }
    response.Entry = *entry
    jsonData, err := json.Marshal(response)
    if err != nil {
        http.Error(w, "internal server error", http.StatusInternalServerError)
        log.Println("failed to marshal JSON: %w\n", err)
        return
    }
    w.WriteHeader(http.StatusOK)
    w.Header().Set("Content-Type", "application/json")
    w.Write(jsonData)
}

AddEntry function code:

func (backupService *BackupService) AddEntry(ctx context.Context, backupId string, entryFullName string,
    entryMimeType string, in io.Reader) (*ber.BackupEntry, error) {
    // validation skipped for readability
    entryId := uuid.New()
    outPath := backupId + "/" + entryId.String()

    entryChan := make(chan *ber.BackupEntry)
    errChan := make(chan error)
    go func() {
        gstorageClient, err := backupService.storageService.GetClient(ctx)
        if err != nil {
            errChan <- fmt.Errorf("could not add entry: %w", err)
        }
        defer gstorageClient.Close()

        out := gstorageClient.Bucket(config.GCBucketName()).Object(outPath).NewWriter(ctx)
        defer out.Close()

        mac, size, err := backupService.cipher.Encrypt(ctx, in, out,
            []byte(config.EncryptionKey()), []byte(config.HmacKey()))
        if err != nil {
            errChan <- fmt.Errorf("could not upload encrypted backupEntry with id=%s: %w", entryId.String(), err)
        }

        //db operation skipped
        entryChan <- entry
    }()
    select {
    case <-ctx.Done():
        dbCleanupErr, storageCleanupErr := backupService.cleanupEntry(entryId.String(), outPath)
        return nil,
            fmt.Errorf("could not add entry %s to backup %s: context was cancelled; db cleanup err: %w; gstorage cleanup err: %w",
                entryId.String(), backupId, dbCleanupErr, storageCleanupErr)
    case err := <-errChan:
        dbCleanupErr, storageCleanupErr := backupService.cleanupEntry(entryId.String(), outPath)
        return nil,
            fmt.Errorf("could not add entry %s to backup %s: %w; db cleanup err: %w; gstorage cleanup err: %w",
                entryId.String(), backupId, err, dbCleanupErr, storageCleanupErr)
    case entry := <-entryChan:
        return entry, nil
    }
}

What I tried:

  1. Enabling GODEBUG: http2debug=1 to check debug http logs. Logs are different, I will leave them below.
  2. Checking if the context is closed on all levels: in http handler itself, in AddEntry function add in Encrypt function. Context is not being closed, everything seems to be working fine.
  3. Creating a derived context from r.Context(), result is the same as r.Context()
  4. Obviously, passing context.Background() instead of r.Context() to AddEntry function, it fixes the problem

Debug logs when r.Context() is passed as a parameter:

ft-api  | 2023/08/02 19:23:46 stdout: 2023/08/02 19:23:46 [2606f10843ab/yuHa6i98Ak-000004] "POST http://0.0.0.0:8080/backup HTTP/1.1" from 172.18.0.1:36052 - 200 570B in 193.850041ms
ft-api  | 2023/08/02 19:23:47 stdout: 2023/08/02 19:23:47 [2606f10843ab/yuHa6i98Ak-000005] "POST http://0.0.0.0:8080/entry HTTP/1.1" from 172.18.0.1:36052 - 200 127B in 171.975584ms
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 h2_bundle.go:9019: http2: Transport encoding header ":authority" = "oauth2.googleapis.com"
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 h2_bundle.go:9019: http2: Transport encoding header ":method" = "POST"
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 h2_bundle.go:9019: http2: Transport encoding header ":path" = "/token"
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 h2_bundle.go:9019: http2: Transport encoding header ":scheme" = "https"
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 h2_bundle.go:9019: http2: Transport encoding header "content-type" = "application/x-www-form-urlencoded"
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 h2_bundle.go:9019: http2: Transport encoding header "content-length" = "861"
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 h2_bundle.go:9019: http2: Transport encoding header "accept-encoding" = "gzip"
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 h2_bundle.go:9019: http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 h2_bundle.go:9968: http2: Transport received HEADERS flags=END_HEADERS stream=3 len=42
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 h2_bundle.go:9968: http2: Transport received DATA flags=PADDED stream=3 len=974 data="\x1f\x8b\b\x00\x00\x00\x00\x00\x02\xff\x1d\xd4Ɏ\xa3H\x00\x04\xd0\x7f\xf1\xb9iA&\xeb܌]\xb4\xc9*L\x01\x05\x06.\x88%\xd9\xf7d\xcd\xd6\xfc\xfbXs\f).q\x88\xf7\xf7\x12\xa7)&$Z\x86\x06\xf7\x97\x7f.g\f\x94\xdf\xe9\uf13dƸ\xe98=\x9a\r\xe33\xe6FѶ\xa3\xcf\xd7ϪN-\x04\x9b]\x7f\xaf\xfc|\x95\xec!Ha\x97^[\xa4\xad\x0f\xe8\xeb\x03:\x051U\xb1\x12~2\x1e\xf5\xbe\xbfTν9\x8f\xe7\xedз\xaa\xac\x87\a\xa3\xfd!\x82ȡӝyb\xe3N\xb8\x91\xf8\x91*\xa1\xc5\xe7\x80\xc1|ڗ}P\x99\xd0D\xf7\xf8\xc7\xc7\"\xda\x1d\xabl\x96\xa4\x98\xf1'\xb2g\xef\xb1=\x10o\x7f\x8dC\x96\x8d\xc6\xfe\xfc\xae\xdc?\xb7f\x0f\xc0\xa2K\xb9^\xd5!\xc38\xe2\a\x84\xca1\x83\xfeG6\xbaNjPzW\xcf\xfb\xd3jͯn\x8d\xac\xf2[\xbe۰\xfcX\xbfBp\xbd\xdd\x14\xa1--\xbe" (613 bytes omitted)
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 h2_bundle.go:9968: http2: Transport received DATA flags=END_STREAM|PADDED stream=3 len=136 data=""
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 h2_bundle.go:9968: http2: Transport received PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x02"
ft-api  | 2023/08/02 19:23:47 stderr: 2023/08/02 19:23:47 transport.go:3015: http2: Transport failed to get client conn for storage.googleapis.com:443: http2: no cached connection was available

Debug logs when context.Background() is passed as a parameter (I removed jwt token value from the logs, but it is there)

ft-api  | 2023/08/02 19:24:51 stdout: 2023/08/02 19:24:51 [2606f10843ab/ukd5p0sXox-000001] "POST http://0.0.0.0:8080/backup HTTP/1.1" from 172.18.0.1:38934 - 200 570B in 465.2635ms
ft-api  | 2023/08/02 19:24:52 stdout: 2023/08/02 19:24:52 [2606f10843ab/ukd5p0sXox-000002] "POST http://0.0.0.0:8080/entry HTTP/1.1" from 172.18.0.1:38934 - 200 127B in 172.084834ms
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9968: http2: Transport failed to get client conn for oauth2.googleapis.com:443: http2: no cached connection was available
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9968: http2: Transport creating client conn 0x40003cc780 to 142.250.186.74:443
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9019: http2: Transport encoding header ":authority" = "oauth2.googleapis.com"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9019: http2: Transport encoding header ":method" = "POST"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9019: http2: Transport encoding header ":path" = "/token"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9019: http2: Transport encoding header ":scheme" = "https"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9019: http2: Transport encoding header "content-type" = "application/x-www-form-urlencoded"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9019: http2: Transport encoding header "content-length" = "861"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9019: http2: Transport encoding header "accept-encoding" = "gzip"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9019: http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9968: http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=65536
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9968: http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9968: http2: Transport received SETTINGS flags=ACK len=0
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9968: http2: Transport received HEADERS flags=END_HEADERS stream=1 len=220
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9968: http2: Transport received DATA flags=PADDED stream=1 len=1030 data="\x1f\x8b\b\x00\x00\x00\x00\x00\x02\xff\x1d\xd4Ir\xa3:\x00\x00лx\xddt1\x83z\x179&\x86\x84`#3n(!F3\v̠\xae\x7f\xf7\x9f\xea;\xbcz\x7fO\x98\x90|\x9e\x93eh\xf2\xfe\xf4\xe7t`\x11\xfc&\xbfS\xfe\r\xe7M'|\x9d\x83\x1b'\x06\xdf\x1f\xa2\xfa\xcd]78\xf5\xc4,\xedf\x8f\x18r\xb9+\xf8\x1aņl\xaf\x0f<\\#\x14\xa3\xeb\xce8O\xfb\xec\xa8p\xef#|}&\xeeM\x1e\xc5E\x94\x91-<Е\xbd\xea\x88X\xc8y\xbf<\x94\xfeHL5\xb8\x19&\x1e{?\xe3\x1a\xa3\xb2y\xf3\xd2T:ȿ\x1dX9K[4ԟ\x98a\x0e9\xfe \xea\xe1h\x910\xac\x9a\xf7h\xaf\xba\xa2\xd1\xeak\x1b\xc2\xcb\xea\xe4\x03\x9c\xaf\xfa\xed\xbd\x05\x89\x1f\xbf)\x1d5\xfc\xfevT\xf8\x9d\x9c\x81*4\xe9\xad|P̍(\xdb\xe8l=d\xe3\xc3c\xf5\xf2q\xdd\x05\xf4\xf6\x95\xc7\x10Ŗ\xbe\xa6\xf6\xf9Q|w" (611 bytes omitted)
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9968: http2: Transport received DATA flags=END_STREAM|PADDED stream=1 len=208 data=""
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 h2_bundle.go:9968: http2: Transport received PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:3015: http2: Transport failed to get client conn for storage.googleapis.com:443: http2: no cached connection was available
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:3015: http2: Transport creating client conn 0x400029e000 to 216.58.212.144:443
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:2076: http2: Transport encoding header ":authority" = "storage.googleapis.com"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:2076: http2: Transport encoding header ":method" = "POST"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:2076: http2: Transport encoding header ":path" = "/upload/storage/v1/b/bucketname/o?alt=json&name=a934c415-07bd-4686-8ad0-90ff5ef68c7e%2F6e6b9563-c9d9-484e-a24f-cd2f8bd1fcd8&prettyPrint=false&projection=full&uploadType=multipart"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:2076: http2: Transport encoding header ":scheme" = "https"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:2076: http2: Transport encoding header "content-type" = "multipart/related; boundary=976d8006696028fea8c40fc53fe0a817a80f334ae41925d1e08c3bb3c917"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:2076: http2: Transport encoding header "x-cloud-trace-context" = "cb5a9d07f5007be3d8dfe277e1fb6beb/9294889295348469653;o=0"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:2076: http2: Transport encoding header "authorization" = "Bearer <<token value removed>>"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:2076: http2: Transport encoding header "x-goog-api-client" = "gl-go/1.20.6 gccl/1.30.1"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:2076: http2: Transport encoding header "user-agent" = "gcloud-golang-storage/1.30.1"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:2076: http2: Transport encoding header "accept-encoding" = "gzip"
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:3015: http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=65536
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:3015: http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:3015: http2: Transport received SETTINGS flags=ACK len=0
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:3015: http2: Transport received HEADERS flags=END_HEADERS stream=1 len=314
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:3015: http2: Transport received DATA stream=1 len=944 data="{\"kind\":\"storage#object\",\"id\":\"bucketname/a934c415-07bd-4686-8ad0-90ff5ef68c7e/6e6b9563-c9d9-484e-a24f-cd2f8bd1fcd8/1691004292747760\",\"selfLink\":\"https://www.googleapis.com/storage/v1/b/bucketname/o/a934c415-07bd-4686-8ad0-90ff5ef68c7e%2F6e6b9563" (688 bytes omitted)
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:3015: http2: Transport received DATA flags=END_STREAM stream=1 len=0 data=""
ft-api  | 2023/08/02 19:24:52 stderr: 2023/08/02 19:24:52 transport.go:3015: http2: Transport received PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
Solution

  • The problem was fixed by explicitly calling Close() method on gstorage object writer instead of deferring it. I am still not entirely sure about the cause of this behaviour (I am aware that file is not commited to gstorage unless writer was closed, but there were no context cancellations involved, so it should've been closed).

    Edit: It seems to me that the problem might be in the order that go executes deferred functions declared inside of goroutine. If anyone has an explanation to this, it would be very welcome.