couchdb: Unexpected Unauthorized if PUT intervals closely match couchdb cookie timeout

[iivvoo]

We have been getting unexpected Unauthorized responses when inserting documents at a really slow pace. The interval of those insertions seem to closely match the cookie timeout on couchdb.

To reproduce this, we've set the couch_httpd_auth.timeout to 60 (seconds) on a couch 3.1.1 instance (not in docker) and ran the following code:

package main

import (
	"context"
	"fmt"
	"net/url"
	"time"

	_ "github.com/go-kivik/couchdb/v4"
	"github.com/go-kivik/kivik/v4"
	"github.com/google/uuid"
)

type Sample struct {
	UUID string `json:"uuid"`
	Name string `json:"name"`
	Age  int    `json:"age"`
}

type DB struct {
	client *kivik.Client
	db     *kivik.DB
}

func Setup(dsn string, qShards, nCopies int) (*DB, error) {
	u, err := url.Parse(dsn)
	if err != nil {
		return nil, err
	}
	dbName := u.Path
	u.Path = ""
	dsn = u.String()
	client, err := kivik.New("couch", dsn)
	if err != nil {
		return nil, err
	}

	ctx := context.TODO()

	if exists, err := client.DBExists(ctx, dbName); err == nil && exists {
		client.DestroyDB(ctx, dbName)
	} else if err != nil {
		return nil, err
	}
	client.CreateDB(ctx, dbName, kivik.Options{
		"q": qShards,
		"n": nCopies,
	})
	db := client.DB(dbName)
	return &DB{
		client: client,
		db:     db,
	}, nil
}

func (f *DB) RepeatPut(t time.Duration) {
	for {
		fmt.Println("PUT doc")
		id := uuid.New().String()
		_, err := f.db.Put(context.TODO(), id, &Sample{id, "John Doe", 42})
		if err != nil {
			panic(err)
		}
		fmt.Println("Sleep", t)
		time.Sleep(t)
	}
}

func main() {
	f, err := Setup("http://admin:a-secret@localhost:5984/auth-test", 1, 1)
	if err != nil {
		panic(err)
	}
	f.RepeatPut(time.Second*60 - time.Millisecond*100)
}

running this

» go run main.go                                                                  1 ↵
PUT doc
Sleep 59.9s
PUT doc
Sleep 59.9s
PUT doc
Sleep 59.9s
PUT doc
panic: Unauthorized: You are not authorized to access this db.

goroutine 1 [running]:
main.(*DB).RepeatPut(0xc00018a320, 0xdf2517700)
	.../RnD/couch-auth/main.go:62 +0x2e0
main.main()
	.../RnD/couch-auth/main.go:74 +0x78
exit status 2

The Coouchd debug logs show

[debug] 2021-06-05T13:31:23.316469Z couchdb@127.0.0.1 <0.7274.224> d8f6067caa Attempt Login: admin
[debug] 2021-06-05T13:31:23.317540Z couchdb@127.0.0.1 <0.7274.224> d8f6067caa no record of user admin
[notice] 2021-06-05T13:31:23.318362Z couchdb@127.0.0.1 <0.7274.224> d8f6067caa localhost:5984 127.0.0.1 undefined POST /_session 200 ok 2
[debug] 2021-06-05T13:31:23.361040Z couchdb@127.0.0.1 <0.7759.224> 24c1844e6f no record of user admin
[debug] 2021-06-05T13:31:23.361187Z couchdb@127.0.0.1 <0.7759.224> 24c1844e6f timeout 60
[debug] 2021-06-05T13:31:23.361269Z couchdb@127.0.0.1 <0.7759.224> 24c1844e6f Successful cookie auth as: "admin"
[notice] 2021-06-05T13:31:23.369124Z couchdb@127.0.0.1 <0.7759.224> 24c1844e6f localhost:5984 127.0.0.1 admin PUT /auth-test/2c85a130-a5c4-4b79-b7be-796729e11b69 201 ok 9
[debug] 2021-06-05T13:32:23.291989Z couchdb@127.0.0.1 <0.7759.224> e75e50fda1 no record of user admin
[debug] 2021-06-05T13:32:23.292117Z couchdb@127.0.0.1 <0.7759.224> e75e50fda1 timeout 60
[error] 2021-06-05T13:32:23.292864Z couchdb@127.0.0.1 <0.8275.224> e75e50fda1 rexi_server: from: couchdb@127.0.0.1(<0.7759.224>) mfa: fabric_rpc:open_shard/2 throw:{unauthorized,<<"You are not authorized to access this db.">>} [{couch_db,open,2,[{file,"src/couch_db.erl"},{line,168}]},{fabric_rpc,open_shard,2,[{file,"src/fabric_rpc.erl"},{line,307}]},{rexi_server,init_p,3,[{file,"src/rexi_server.erl"},{line,138}]}]
[notice] 2021-06-05T13:32:23.293600Z couchdb@127.0.0.1 <0.7759.224> e75e50fda1 localhost:5984 127.0.0.1 undefined PUT /auth-test/d675aae3-2e24-435f-b5c4-794228a5dda5 401 ok 3

I am aware that there is an auth/cookie related fix in go-kivik/couchdb#280 that has been merged, but even with this change the problem occurs

» grep kivik go.sum
github.com/go-kivik/couchdb/v4 v4.0.0-20210603203912-7a5e3ef402b2 h1:9pc2vYfo000Vj4Yj+irBfcPMQQ3mgS+ujo0ERoL0Bak=
github.com/go-kivik/couchdb/v4 v4.0.0-20210603203912-7a5e3ef402b2/go.mod h1:O/j3V4Lx/XY2Dunvs8Kj2Gpg0a9ZSyFa51Fr9JpMGNM=
github.com/go-kivik/kivik/v4 v4.0.0-20201011094523-ab1764d67e62/go.mod h1:O2fxy5xMXO7vaVr2gQG38sYTj/mHwg5Md/8kP7qUZQk=
github.com/go-kivik/kivik/v4 v4.0.0-20201015190251-5d5c2f1c89fa/go.mod h1:O2fxy5xMXO7vaVr2gQG38sYTj/mHwg5Md/8kP7qUZQk=
github.com/go-kivik/kivik/v4 v4.0.0-20201202093909-da42f0daa1b2 h1:lxXbqi5ayfzXUGafeQjUGgeiXO2HjCzdZdcbmhklRLg=
github.com/go-kivik/kivik/v4 v4.0.0-20201202093909-da42f0daa1b2/go.mod h1:O2fxy5xMXO7vaVr2gQG38sYTj/mHwg5Md/8kP7qUZQk=
github.com/go-kivik/kiviktest/v4 v4.0.0-20210410161422-2df5be2daeb6 h1:FXnNxH7j79NFxnDKxSqL8vjPN9hsamOhs4Eu/OZ6KVU=
github.com/go-kivik/kiviktest/v4 v4.0.0-20210410161422-2df5be2daeb6/go.mod h1:d5boDDPySqnpjX41iT7H7FTyUcqjAKrw9gQPkdAo5Ko=

github.com/go-kivik/couchdb/v4 v4.0.0-20210603203912-7a5e3ef402b2 should contain that fix, right?

[iivvoo]

LiberaChat #couchdb people suggest to run using basic http auth to see if the problem disappears - I will try this (not sure how to make kivik do that, though)

[flimzy]

LiberaChat #couchdb people suggest to run using basic http auth to see if the problem disappears - I will try this (not sure how to make kivik do that, though)

This should help: https://github.com/go-kivik/kivik/wiki/Authentication#http-basic-auth

[flimzy]

We have been getting unexpected Unauthorized responses when inserting documents at a really slow pace. The interval of those insertions seem to closely match the cookie timeout on couchdb.

This is an inherent problem with many HTTP-based services that uses cookies for authentication. We can refresh the cookie on every request, but if there are no requests, there's no way to refresh the cookie.

There are basically two possible approaches:

1. Detect when a failure occurs (as you've observed), and retry. This is difficult to do at the network level, because not every HTTP request is safe to retry. In the case of Kivik, I think we're already telling the net/http lib when we know it's safe to retry, but maybe we could be a bit more aggressive there. However, that would only reduce the size of the problem, not eliminate it.
2. Continually make active connections, to keep the cookie fresh.

If it's reasonable in your app, you could have some background task do a CouchDB ping every N seconds (where N is reasonably less than your cookie expiration time).

Maybe I could add this as an option to Kivik, as well. 🤔

I could have kivik fire off a goroutine that sends a simple ping request to CouchDB when the cookie is nearing expiration. I think it would have to be an opt-in feature--probably an option to the CookieAuth type.

What do you think?

[iivvoo]

I don't fully understand the problem - if I wait longer, everything works fine, e.g. increasing the timout to 90 seconds and it will always re-authenticate:

[debug] 2021-06-05T15:17:40.668205Z couchdb@127.0.0.1 <0.27183.225> cb1823b988 Attempt Login: admin
[debug] 2021-06-05T15:17:40.668559Z couchdb@127.0.0.1 <0.27183.225> cb1823b988 no record of user admin
[notice] 2021-06-05T15:17:40.668835Z couchdb@127.0.0.1 <0.27183.225> cb1823b988 localhost:5984 127.0.0.1 undefined POST /_session 200 ok 1
[debug] 2021-06-05T15:17:40.737687Z couchdb@127.0.0.1 <0.26906.225> f98f1e7e6e no record of user admin
[debug] 2021-06-05T15:17:40.737766Z couchdb@127.0.0.1 <0.26906.225> f98f1e7e6e timeout 60
[debug] 2021-06-05T15:17:40.737795Z couchdb@127.0.0.1 <0.26906.225> f98f1e7e6e Successful cookie auth as: "admin"
[notice] 2021-06-05T15:17:40.743197Z couchdb@127.0.0.1 <0.26906.225> f98f1e7e6e localhost:5984 127.0.0.1 admin PUT /auth-test/6454b3d4-564c-4ac2-bc52-26dc4de299eb 201 ok 34
[debug] 2021-06-05T15:19:10.663836Z couchdb@127.0.0.1 <0.26906.225> 2a8ce2ed97 Attempt Login: admin
[debug] 2021-06-05T15:19:10.664149Z couchdb@127.0.0.1 <0.26906.225> 2a8ce2ed97 no record of user admin
[notice] 2021-06-05T15:19:10.664390Z couchdb@127.0.0.1 <0.26906.225> 2a8ce2ed97 localhost:5984 127.0.0.1 undefined POST /_session 200 ok 1
[debug] 2021-06-05T15:19:10.705265Z couchdb@127.0.0.1 <0.28530.225> 5507cb2863 no record of user admin
[debug] 2021-06-05T15:19:10.705302Z couchdb@127.0.0.1 <0.28530.225> 5507cb2863 timeout 60
[debug] 2021-06-05T15:19:10.705318Z couchdb@127.0.0.1 <0.28530.225> 5507cb2863 Successful cookie auth as: "admin"
[notice] 2021-06-05T15:19:10.711484Z couchdb@127.0.0.1 <0.28530.225> 5507cb2863 localhost:5984 127.0.0.1 admin PUT /auth-test/b85aae04-d88a-4b68-b3dd-fdfee092fcb2 201 ok 7

Possibly because kivik "knows" the cookie has expired?

It appears asif it only fails during this sweet spot where the interval ~ timeout. What if kivik would just re-authenticate if the cookie expires not just now, but also in the next few seconds?

[flimzy]

I just pushed a change to v3.2.10 to re-auth if kivik knows the cookie will expire within the next 60 seconds. This should eliminate any problems caused by clocks being slightly out of sync.

I don't know if that's enough to address this, but if you're able to try that and let me know if it changes things for you, that could be nice.

It still won't solve any problem of long delays between requests, but it sounds like that's not your problem anyway.

[iivvoo]

FWIW, this is not about clock sync - the error occurs when the sample code and couchdb run on the same machine. It's probably that slight interval between checking pre-request and the request actually ending up in couchdb.

Long delays actually work fine - the problem does not occur when pausing for ~50 sec or ~90 sec, only specificaly ~60 sec

I would expect your fix to work but it doesn't

» go run main.go                                                               
PUT doc
Sleep 59.9s
PUT doc
Sleep 59.9s
PUT doc
Sleep 59.9s
PUT doc
panic: Unauthorized: You are not authorized to access this db.

goroutine 1 [running]:
main.(*DB).RepeatPut(0xc0000121e0, 0xdf2517700)
	.../RnD/couch-auth/main.go:62 +0x2e0
main.main()
	.../RnD/couch-auth/main.go:74 +0x78
exit status 2

» grep kivik go.*                                                                 1 ↵
go.mod:	github.com/go-kivik/couchdb/v4 v4.0.0-20210606123901-7c3aefbfa34c
go.mod:	github.com/go-kivik/kivik/v4 v4.0.0-20210424210959-2885c4d889d9
go.sum:github.com/go-kivik/couchdb/v4 v4.0.0-20210606123901-7c3aefbfa34c h1:twz3AfaHTofgudtJGgjaiEvy2uyDC089lHClyBGaHkg=
go.sum:github.com/go-kivik/couchdb/v4 v4.0.0-20210606123901-7c3aefbfa34c/go.mod h1:O/j3V4Lx/XY2Dunvs8Kj2Gpg0a9ZSyFa51Fr9JpMGNM=
go.sum:github.com/go-kivik/kivik/v4 v4.0.0-20201011094523-ab1764d67e62/go.mod h1:O2fxy5xMXO7vaVr2gQG38sYTj/mHwg5Md/8kP7qUZQk=
go.sum:github.com/go-kivik/kivik/v4 v4.0.0-20201015190251-5d5c2f1c89fa/go.mod h1:O2fxy5xMXO7vaVr2gQG38sYTj/mHwg5Md/8kP7qUZQk=
go.sum:github.com/go-kivik/kivik/v4 v4.0.0-20210424210959-2885c4d889d9 h1:3PBV8evSm0nvJx1CotKVeF02PwwM99X2otMSlCoReA8=
go.sum:github.com/go-kivik/kivik/v4 v4.0.0-20210424210959-2885c4d889d9/go.mod h1:O2fxy5xMXO7vaVr2gQG38sYTj/mHwg5Md/8kP7qUZQk=
go.sum:github.com/go-kivik/kiviktest/v4 v4.0.0-20210410161422-2df5be2daeb6/go.mod h1:d5boDDPySqnpjX41iT7H7FTyUcqjAKrw9gQPkdAo5Ko=

[flimzy]

Very curious. I'll spend some additional time investigating with your repro case when I have a moment.

[iivvoo]

FWIW, this is not about clock sync - the error occurs when the sample code and couchdb run on the same machine. It's probably that slight interval between checking pre-request and the request actually ending up in couchdb.

Long delays actually work fine - the problem does not occur when pausing for ~50 sec or ~90 sec, only specificaly ~60 sec

I would expect your fix to work but it doesn't

» go run main.go                                                               
PUT doc
Sleep 59.9s
PUT doc
Sleep 59.9s
PUT doc
Sleep 59.9s
PUT doc
panic: Unauthorized: You are not authorized to access this db.

goroutine 1 [running]:
main.(*DB).RepeatPut(0xc0000121e0, 0xdf2517700)
	.../RnD/couch-auth/main.go:62 +0x2e0
main.main()
	.../RnD/couch-auth/main.go:74 +0x78
exit status 2

» grep kivik go.*                                                                 1 ↵
go.mod:	github.com/go-kivik/couchdb/v4 v4.0.0-20210606123901-7c3aefbfa34c
go.mod:	github.com/go-kivik/kivik/v4 v4.0.0-20210424210959-2885c4d889d9
go.sum:github.com/go-kivik/couchdb/v4 v4.0.0-20210606123901-7c3aefbfa34c h1:twz3AfaHTofgudtJGgjaiEvy2uyDC089lHClyBGaHkg=
go.sum:github.com/go-kivik/couchdb/v4 v4.0.0-20210606123901-7c3aefbfa34c/go.mod h1:O/j3V4Lx/XY2Dunvs8Kj2Gpg0a9ZSyFa51Fr9JpMGNM=
go.sum:github.com/go-kivik/kivik/v4 v4.0.0-20201011094523-ab1764d67e62/go.mod h1:O2fxy5xMXO7vaVr2gQG38sYTj/mHwg5Md/8kP7qUZQk=
go.sum:github.com/go-kivik/kivik/v4 v4.0.0-20201015190251-5d5c2f1c89fa/go.mod h1:O2fxy5xMXO7vaVr2gQG38sYTj/mHwg5Md/8kP7qUZQk=
go.sum:github.com/go-kivik/kivik/v4 v4.0.0-20210424210959-2885c4d889d9 h1:3PBV8evSm0nvJx1CotKVeF02PwwM99X2otMSlCoReA8=
go.sum:github.com/go-kivik/kivik/v4 v4.0.0-20210424210959-2885c4d889d9/go.mod h1:O2fxy5xMXO7vaVr2gQG38sYTj/mHwg5Md/8kP7qUZQk=
go.sum:github.com/go-kivik/kiviktest/v4 v4.0.0-20210410161422-2df5be2daeb6/go.mod h1:d5boDDPySqnpjX41iT7H7FTyUcqjAKrw9gQPkdAo5Ko=

[iivvoo]

(most likely this is a dead end - don't put too much time in this comment)

I'm doing some local testing/debugging but I can't make much sense. My cookies always have Expires.IsZero() true, making shouldAuth() false. The .Raw is empty suggesting it's probably not updated from the response?

But if I inspect the calls with strace I do see a cookie being set with a valid expiration.

(may update this comment with additional findings)

I'm trying to make sense of this al but can't really. I don't understand why the Expires isn't set properly from the response. I've added a wrapping CookieJar that intercepts and dumps the cookies as follows (chttpd.go)

type MyCJ struct {
	cj *cookiejar.Jar
}

func (m *MyCJ) SetCookies(u *url.URL, cookies []*http.Cookie) {
	fmt.Println("** Intercepted SetCookies", m, u, cookies)
	for _, c := range cookies {
		fmt.Println("** ....", c.Expires)
	}
	m.cj.SetCookies(u, cookies)
	fmt.Println("-- result after SetCookies")
	m.Cookies(u)
	fmt.Println("--")
}

func (m *MyCJ) Cookies(u *url.URL) []*http.Cookie {
	cs := m.cj.Cookies(u)
	fmt.Println("** Intercepted Cookies()", m, u, cs)
	for _, c := range cs {
		fmt.Println("** ....", c.Expires)
	}
	return cs
}

// Authenticator is an interface that provides authentication to a server.
type Authenticator interface {
	Authenticate(*Client) error
}

func (a *CookieAuth) setCookieJar() {
	// If a jar is already set, just use it
	if a.client.Jar != nil {
		return
	}
	// cookiejar.New never returns an error
	jar, _ := cookiejar.New(&cookiejar.Options{PublicSuffixList: publicsuffix.List})
	a.client.Jar = &MyCJ{jar}
}

This produces the following output when running the sample code:

** Intercepted Cookies() &{0xc00009cd80} http://localhost:5984/auth-test []
** Intercepted Cookies() &{0xc00009cd80} http://localhost:5984/ []
** Intercepted Cookies() &{0xc00009cd80} http://localhost:5984/ []
** Intercepted Cookies() &{0xc00009cd80} http://localhost:5984/_session []
** Intercepted SetCookies &{0xc00009cd80} http://localhost:5984/_session [AuthSession=YWRtaW46NjBCREVGODE64dIpRUK8V_HwmopiKykZD2Y24ho; Path=/; Expires=Mon, 07 Jun 2021 10:06:53 GMT; Max-Age=60; HttpOnly]
** .... 2021-06-07 10:06:53 +0000 UTC
-- result after SetCookies
** Intercepted Cookies() &{0xc00009cd80} http://localhost:5984/_session [AuthSession=YWRtaW46NjBCREVGODE64dIpRUK8V_HwmopiKykZD2Y24ho]
** .... 0001-01-01 00:00:00 +0000 UTC
--
** Intercepted Cookies() &{0xc00009cd80} http://localhost:5984/ [AuthSession=YWRtaW46NjBCREVGODE64dIpRUK8V_HwmopiKykZD2Y24ho]
** .... 0001-01-01 00:00:00 +0000 UTC
** Intercepted Cookies() &{0xc00009cd80} http://localhost:5984/auth-test [AuthSession=YWRtaW46NjBCREVGODE64dIpRUK8V_HwmopiKykZD2Y24ho]
** .... 0001-01-01 00:00:00 +0000 UTC
** Intercepted Cookies() &{0xc00009cd80} http://localhost:5984/auth-test?n=1&q=1 [AuthSession=YWRtaW46NjBCREVGODE64dIpRUK8V_HwmopiKykZD2Y24ho]
** .... 0001-01-01 00:00:00 +0000 UTC
PUT doc
** Intercepted Cookies() &{0xc00009cd80} http://localhost:5984/auth-test/3bd14141-bb16-47c7-be52-e68451ee8a28 [AuthSession=YWRtaW46NjBCREVGODE64dIpRUK8V_HwmopiKykZD2Y24ho]
** .... 0001-01-01 00:00:00 +0000 UTC
Sleep 59.9s

It retrieves and dumps the cookies immediately after set, and the expires is gone

** Intercepted SetCookies &{0xc00009cd80} http://localhost:5984/_session [AuthSession=YWRtaW46NjBCREVGODE64dIpRUK8V_HwmopiKykZD2Y24ho; Path=/; Expires=Mon, 07 Jun 2021 10:06:53 GMT; Max-Age=60; HttpOnly]
** .... 2021-06-07 10:06:53 +0000 UTC
-- result after SetCookies
** Intercepted Cookies() &{0xc00009cd80} http://localhost:5984/_session [AuthSession=YWRtaW46NjBCREVGODE64dIpRUK8V_HwmopiKykZD2Y24ho]
** .... 0001-01-01 00:00:00 +0000 UTC
--

--

(the cookie hasn't expired at this point)

I'm probably missing something obvious here, and I'm probably approaching it incorrectly, but for me it's time to let this rest for now :)

update

Okay, so I couldn't let it rest. CookieJar.Cookies() creates fresh new cookies and doesn't include Expires, see https://github.com/golang/go/blob/master/src/net/http/cookiejar/jar.go#L221

		cookies = append(cookies, &http.Cookie{Name: e.Name, Value: e.Value})

But even when I add Expires there, the problem remains. Giving up for now, for real.

[flimzy]

I'm able to reproduce this locally.

That behavior of the cookie jar is strange. I'll ponder a proper solution. I hope it won't mean reimplementing the cookie jar myself, but that could be an option if all else fails.

[flimzy]

I think I have a fix with go-kivik/couchdb#285

[iivvoo]

Unfortunately that doesn't fix it for my reproduction code - it still (eventually) results in the Unauthorized error. It might be that it runs slightly longer, but after a few minutes it will crash

I added an extra interval to the expiration check in shouldAuth(), that doesn't seem to make a difference.

(I double checked using Println() that I am truely using the expiredSessions branch)