Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
iivvoo opened this issue Jun 5, 2021 · 12 comments

Comments

@iivvoo
Copy link

iivvoo commented Jun 5, 2021

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("https://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 [email protected] <0.7274.224> d8f6067caa Attempt Login: admin
[debug] 2021-06-05T13:31:23.317540Z [email protected] <0.7274.224> d8f6067caa no record of user admin
[notice] 2021-06-05T13:31:23.318362Z [email protected] <0.7274.224> d8f6067caa localhost:5984 127.0.0.1 undefined POST /_session 200 ok 2
[debug] 2021-06-05T13:31:23.361040Z [email protected] <0.7759.224> 24c1844e6f no record of user admin
[debug] 2021-06-05T13:31:23.361187Z [email protected] <0.7759.224> 24c1844e6f timeout 60
[debug] 2021-06-05T13:31:23.361269Z [email protected] <0.7759.224> 24c1844e6f Successful cookie auth as: "admin"
[notice] 2021-06-05T13:31:23.369124Z [email protected] <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 [email protected] <0.7759.224> e75e50fda1 no record of user admin
[debug] 2021-06-05T13:32:23.292117Z [email protected] <0.7759.224> e75e50fda1 timeout 60
[error] 2021-06-05T13:32:23.292864Z [email protected] <0.8275.224> e75e50fda1 rexi_server: from: [email protected](<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 [email protected] <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
Copy link
Author

iivvoo commented Jun 5, 2021

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
Copy link
Member

flimzy commented Jun 5, 2021

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
Copy link
Member

flimzy commented Jun 5, 2021

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
Copy link
Author

iivvoo commented Jun 5, 2021

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 [email protected] <0.27183.225> cb1823b988 Attempt Login: admin
[debug] 2021-06-05T15:17:40.668559Z [email protected] <0.27183.225> cb1823b988 no record of user admin
[notice] 2021-06-05T15:17:40.668835Z [email protected] <0.27183.225> cb1823b988 localhost:5984 127.0.0.1 undefined POST /_session 200 ok 1
[debug] 2021-06-05T15:17:40.737687Z [email protected] <0.26906.225> f98f1e7e6e no record of user admin
[debug] 2021-06-05T15:17:40.737766Z [email protected] <0.26906.225> f98f1e7e6e timeout 60
[debug] 2021-06-05T15:17:40.737795Z [email protected] <0.26906.225> f98f1e7e6e Successful cookie auth as: "admin"
[notice] 2021-06-05T15:17:40.743197Z [email protected] <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 [email protected] <0.26906.225> 2a8ce2ed97 Attempt Login: admin
[debug] 2021-06-05T15:19:10.664149Z [email protected] <0.26906.225> 2a8ce2ed97 no record of user admin
[notice] 2021-06-05T15:19:10.664390Z [email protected] <0.26906.225> 2a8ce2ed97 localhost:5984 127.0.0.1 undefined POST /_session 200 ok 1
[debug] 2021-06-05T15:19:10.705265Z [email protected] <0.28530.225> 5507cb2863 no record of user admin
[debug] 2021-06-05T15:19:10.705302Z [email protected] <0.28530.225> 5507cb2863 timeout 60
[debug] 2021-06-05T15:19:10.705318Z [email protected] <0.28530.225> 5507cb2863 Successful cookie auth as: "admin"
[notice] 2021-06-05T15:19:10.711484Z [email protected] <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
Copy link
Member

flimzy commented Jun 6, 2021

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
Copy link
Author

iivvoo commented Jun 6, 2021

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
Copy link
Member

flimzy commented Jun 6, 2021

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

@iivvoo
Copy link
Author

iivvoo commented Jun 7, 2021

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 iivvoo closed this as completed Jun 7, 2021
@iivvoo iivvoo reopened this Jun 7, 2021
@iivvoo
Copy link
Author

iivvoo commented Jun 7, 2021

(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} https://localhost:5984/auth-test []
** Intercepted Cookies() &{0xc00009cd80} https://localhost:5984/ []
** Intercepted Cookies() &{0xc00009cd80} https://localhost:5984/ []
** Intercepted Cookies() &{0xc00009cd80} https://localhost:5984/_session []
** Intercepted SetCookies &{0xc00009cd80} https://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} https://localhost:5984/_session [AuthSession=YWRtaW46NjBCREVGODE64dIpRUK8V_HwmopiKykZD2Y24ho]
** .... 0001-01-01 00:00:00 +0000 UTC
--
** Intercepted Cookies() &{0xc00009cd80} https://localhost:5984/ [AuthSession=YWRtaW46NjBCREVGODE64dIpRUK8V_HwmopiKykZD2Y24ho]
** .... 0001-01-01 00:00:00 +0000 UTC
** Intercepted Cookies() &{0xc00009cd80} https://localhost:5984/auth-test [AuthSession=YWRtaW46NjBCREVGODE64dIpRUK8V_HwmopiKykZD2Y24ho]
** .... 0001-01-01 00:00:00 +0000 UTC
** Intercepted Cookies() &{0xc00009cd80} https://localhost:5984/auth-test?n=1&q=1 [AuthSession=YWRtaW46NjBCREVGODE64dIpRUK8V_HwmopiKykZD2Y24ho]
** .... 0001-01-01 00:00:00 +0000 UTC
PUT doc
** Intercepted Cookies() &{0xc00009cd80} https://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} https://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} https://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, &amp;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
Copy link
Member

flimzy commented Jun 7, 2021

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
Copy link
Member

flimzy commented Jun 8, 2021

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

@iivvoo
Copy link
Author

iivvoo commented Jun 9, 2021

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)

@flimzy flimzy transferred this issue from go-kivik/couchdb Aug 28, 2023
@flimzy flimzy changed the title Unexpected Unauthorized if PUT intervals closely match couchdb cookie timeout couchdb: Unexpected Unauthorized if PUT intervals closely match couchdb cookie timeout Aug 28, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants