Arvados

I'm getting what seems to be a low-probability race condition in testing:

fatal error: concurrent map iteration and map write

goroutine 3143 [running]:
runtime.throw(0xe6d335, 0x26)
    /var/lib/arvados/go/src/runtime/panic.go:1117 +0x72 fp=0xc002eadd98 sp=0xc002eadd68 pc=0x43a5f2
runtime.mapiternext(0xc002eade58)
    /var/lib/arvados/go/src/runtime/map.go:858 +0x54c fp=0xc002eade18 sp=0xc002eadd98 pc=0x412d8c
runtime.mapiterinit(0xd655a0, 0xc004f2a030, 0xc002eade58)
    /var/lib/arvados/go/src/runtime/map.go:848 +0x1c5 fp=0xc002eade38 sp=0xc002eade18 pc=0x412745
git.arvados.org/arvados.git/sdk/go/arvados.(*treenode).MemorySize(0xc004f2c000, 0x0)
    /usr/src/arvados/sdk/go/arvados/fs_base.go:336 +0xd2 fp=0xc002eaded8 sp=0xc002eade38 pc=0x8cec72
git.arvados.org/arvados.git/sdk/go/arvados.(*fileSystem).MemorySize(0xc004f2e000, 0x0)
    /usr/src/arvados/sdk/go/arvados/fs_base.go:631 +0x33 fp=0xc002eadef8 sp=0xc002eaded8 pc=0x8d1193
git.arvados.org/arvados.git/services/keep-web.(*cache).pruneSessions(0xc0044af288)
    /usr/src/arvados/services/keep-web/cache.go:277 +0x415 fp=0xc002eadfd8 sp=0xc002eadef8 pc=0xc80cf5
runtime.goexit()
    /var/lib/arvados/go/src/runtime/asm_amd64.s:1371 +0x1 fp=0xc002eadfe0 sp=0xc002eadfd8 pc=0x474241
created by git.arvados.org/arvados.git/services/keep-web.(*cache).GetSession
    /usr/src/arvados/services/keep-web/cache.go:249 +0x1b0

The MemorySize routine is really simple:

func (n *treenode) MemorySize() (size int64) {
    n.RLock()
    defer n.RUnlock()
    for _, inode := range n.inodes {
        size += inode.MemorySize()
    }
    return
}

So there must be something else stealthily modifying the map.

I noticed the Child() method modifies the inodes map but doesn't have any locking.

func (n *treenode) Child(name string, replace func(inode) (inode, error)) (child inode, err error) {

There's a note about "caller must have lock".

The above-mentiond race condition aside, the branch is ready for review

17464-download-logging @ 0da30aa9a699faa5e735c3aca2f2d6cd96429944

• Adds "File download" and "File upload" log messages with the user uuid, user full name, and collection uuid
• Posts an file_download or file_upload event to the logs table. The object_uuid is the user, the properties are the collection uuid.
• Add seperate user / admin permission bits for file upload and download.
• Adds documentation page explaining how to use the permissions feature
• Adds tests for all the above functionality.

developer-run-tests: #2528

17464-keepproxy-logging-perms @ 699ddfc7ed0a8ea10def11df03e38d5a169f77d2

• Keepproxy logs "Block upload" and "Block download" with the user full name and user uuid.
• Restricts GET / PUT based on new permission configuration for keepproxy
• Adds tests

developer-run-tests: #2530

comments on 17464-download-logging:

doc page typo @keepprox@ and KeepWebPermisison (in all the example configs)

Elsewhere in config we use "WebDAV" rather than "KeepWeb", in keeping with the cluster-config theme that we're configuring the service, not the binary that implements it. Should we say WebDAVPermission instead? The comment that it also applies to S3 should still work?

("Keepproxy" is basically how we spell "keep service for external clients"... so I think it fits.)

This seems a bit wordy -- maybe just "Permissions for regular users and admins to upload/download files via WebDAV and S3"? And mentioning Workbench might be misleading -- doesn't wb1 still upload via keepproxy?

      # Selectively set permissions for regular users and admins to be
      # able to download or upload data files using the
      # upload/download features for Workbench, WebDAV and S3 API
      # support.

The KeepproxyPermission comment also seems extra-wordy to me ("permissions ... to be able to download" can be just "permissions ... to download").

The docs and config comments should mention the fact that non-upload writes (mkdir, rename) and non-download reads (list files) are always permitted / unaffected by these settings.

It seems like if you don't have Download permission you ca do "PROPFIND /" (get an xml document with a file listing) but you can't do "GET /" (get an html document with a file listing), which I don't think anyone would guess without reading the code -- this should probably be either documented or changed.

If the asynchronous "create log record" calls fail, we should probably log the error message, so it's not too big a mystery if something goes sour.

This should un-pyramid to "if err != nil { continue }" ... current version looks like it will start panicking when we make (*sdk/go/arvados.filehandle)Close() do anything more than "return nil":

               f, err := fs.OpenFile(strings.Join(dir, "/"), os.O_RDONLY, 0)
               if err == nil {
                       ...
               }
               f.Close()

That code should also probably treat a non-IsNotExist error as a real error instead of ignoring it.

What happens

The new handler funcs aren't intended for outsiders, so shouldn't be exported. They also don't seem to access their receiver at all, so maybe they should just be regular funcs instead of handler methods.

In DetermineCollection, would it work just as well to start at the root level and work down, instead of the other way around? I think that could avoid the possibility of reading a file named ".arvados#collection" stored in a subdir in a collection (accidentally or on purpose) with the wrong uuid/pdh.

It looks like TestUploadLoggingPermission doesn't really need to use FooCollection specifically. Rather than modifying FooCollection and then doing a full database-reset to revert it, could we just create a new collection to modify in the test, similar to TestCacheWriteCollectionSamePDH?

I think it would be worth testing the logging feature with some different paths (non-top-level files, /users/..., PDH) with the logging features, to make sure the UUID and PDH get filled in as expected.

I'm not sure but it looks like we might get a "download" log message for "GET /dir/" and "GET /dir", which would be confusing. Either way we should probably test this.

I wonder whether the logging feature should be configurable, at least for the anonymous user case. It seems like creating postgresql rows via RailsAPI (and related websocket events) could become the most resource-intensive part of using Arvados to host data on the web, which would be a shame on a site where nobody is interested in reading them.

The complete output for the race error is:

======= test services/keep-web
child.pid is 204016
child.pid is 204029
Sent SIGTERM to 204016 (/root/arvados/tmp/keep0.pid)
Sent SIGTERM to 204029 (/root/arvados/tmp/keep1.pid)
child.pid is 204048
child.pid is 204063
2021/06/16 17:44:04 authSettings: map[ARVADOS_API_HOST:127.0.0.1:40603 ARVADOS_API_HOST_INSECURE:true ARVADOS_API_TOKEN:4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h]
Sent SIGTERM to 204048 (/root/arvados/tmp/keep0.pid)
Sent SIGTERM to 204063 (/root/arvados/tmp/keep1.pid)
child.pid is 204083
child.pid is 204098
fatal error: concurrent map iteration and map write

goroutine 3068 [running]:
runtime.throw(0xe6d335, 0x26)
    /var/lib/arvados/go/src/runtime/panic.go:1117 +0x72 fp=0xc00301a5b8 sp=0xc00301a588 pc=0x43a5f2
runtime.mapiternext(0xc00301a658)
    /var/lib/arvados/go/src/runtime/map.go:858 +0x54c fp=0xc00301a638 sp=0xc00301a5b8 pc=0x412d8c
git.arvados.org/arvados.git/sdk/go/arvados.(*treenode).MemorySize(0xc004b6c990, 0x0)
    /root/arvados/sdk/go/arvados/fs_base.go:336 +0x10d fp=0xc00301a6d8 sp=0xc00301a638 pc=0x8cecad
git.arvados.org/arvados.git/sdk/go/arvados.(*fileSystem).MemorySize(0xc004e10000, 0x0)
    /root/arvados/sdk/go/arvados/fs_base.go:631 +0x33 fp=0xc00301a6f8 sp=0xc00301a6d8 pc=0x8d1193
git.arvados.org/arvados.git/services/keep-web.(*cache).pruneSessions(0xc003943108)
    /root/arvados/services/keep-web/cache.go:277 +0x415 fp=0xc00301a7d8 sp=0xc00301a6f8 pc=0xc80cf5
runtime.goexit()
    /var/lib/arvados/go/src/runtime/asm_amd64.s:1371 +0x1 fp=0xc00301a7e0 sp=0xc00301a7d8 pc=0x474241
created by git.arvados.org/arvados.git/services/keep-web.(*cache).GetSession
    /root/arvados/services/keep-web/cache.go:249 +0x1b0

goroutine 1 [chan receive]:
testing.(*T).Run(0xc000298900, 0xe47bda, 0x4, 0xe8c990, 0x499286)
    /var/lib/arvados/go/src/testing/testing.go:1239 +0x2da
testing.runTests.func1(0xc000298780)
    /var/lib/arvados/go/src/testing/testing.go:1511 +0x78
testing.tRunner(0xc000298780, 0xc00031fda8)
    /var/lib/arvados/go/src/testing/testing.go:1193 +0xef
testing.runTests(0xc000208360, 0x14863d0, 0x1, 0x1, 0xc02aac8e0ed53c53, 0x8bb3156edf, 0x149c200, 0xe5145e)
    /var/lib/arvados/go/src/testing/testing.go:1509 +0x2fe
testing.(*M).Run(0xc00022a800, 0x0)
    /var/lib/arvados/go/src/testing/testing.go:1417 +0x1eb
main.main()
    _testmain.go:103 +0x1c5

goroutine 34 [chan receive]:
gopkg.in/check%2ev1.(*suiteRunner).runTest(...)
    /root/.cache/arvados-build/GOPATH/pkg/mod/gopkg.in/check.v1@v1.0.0-20161208181325-20d25e280405/check.go:810
gopkg.in/check%2ev1.(*suiteRunner).run(0xc00022a100, 0xc000430750)
    /root/.cache/arvados-build/GOPATH/pkg/mod/gopkg.in/check.v1@v1.0.0-20161208181325-20d25e280405/check.go:615 +0x126
gopkg.in/check%2ev1.Run(0xe45080, 0xc000430750, 0xc00006af18, 0xc0004422d0)
    /root/.cache/arvados-build/GOPATH/pkg/mod/gopkg.in/check.v1@v1.0.0-20161208181325-20d25e280405/run.go:92 +0x4d
gopkg.in/check%2ev1.RunAll(0xc00006af18, 0x0)
    /root/.cache/arvados-build/GOPATH/pkg/mod/gopkg.in/check.v1@v1.0.0-20161208181325-20d25e280405/run.go:84 +0x96
gopkg.in/check%2ev1.TestingT(0xc000298900)
    /root/.cache/arvados-build/GOPATH/pkg/mod/gopkg.in/check.v1@v1.0.0-20161208181325-20d25e280405/run.go:72 +0x38b
git.arvados.org/arvados.git/services/keep-web.Test(0xc000298900)
    /root/arvados/services/keep-web/server_test.go:466 +0x2b
testing.tRunner(0xc000298900, 0xe8c990)
    /var/lib/arvados/go/src/testing/testing.go:1193 +0xef
created by testing.(*T).Run
    /var/lib/arvados/go/src/testing/testing.go:1238 +0x2b3

goroutine 144 [select]:
gopkg.in/check%2ev1.(*resultTracker)._loopRoutine(0xc00050a510)
    /root/.cache/arvados-build/GOPATH/pkg/mod/gopkg.in/check.v1@v1.0.0-20161208181325-20d25e280405/check.go:461 +0xa5
created by gopkg.in/check%2ev1.(*resultTracker).start
    /root/.cache/arvados-build/GOPATH/pkg/mod/gopkg.in/check.v1@v1.0.0-20161208181325-20d25e280405/check.go:441 +0x3f

goroutine 40 [syscall]:
os/signal.signal_recv(0x0)
    /var/lib/arvados/go/src/runtime/sigqueue.go:168 +0xa5
os/signal.loop()
    /var/lib/arvados/go/src/os/signal/signal_unix.go:23 +0x25
created by os/signal.Notify.func1.1
    /var/lib/arvados/go/src/os/signal/signal.go:151 +0x45

goroutine 41 [chan receive]:
git.arvados.org/arvados.git/sdk/go/keepclient.RefreshServiceDiscoveryOnSIGHUP.func1()
    /root/arvados/sdk/go/keepclient/discover.go:49 +0x5d
created by git.arvados.org/arvados.git/sdk/go/keepclient.RefreshServiceDiscoveryOnSIGHUP
    /root/arvados/sdk/go/keepclient/discover.go:48 +0x111

goroutine 54 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc0001920f0)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 70 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc0004642d0)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 99 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc0004644b0)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 58 [IO wait]:
internal/poll.runtime_pollWait(0x7f40d175b768, 0x72, 0xffffffffffffffff)
    /var/lib/arvados/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc000122118, 0x72, 0x700, 0x7d3, 0xffffffffffffffff)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000122100, 0xc000458800, 0x7d3, 0x7d3, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc000122100, 0xc000458800, 0x7d3, 0x7d3, 0x7c6, 0xc00051efa0, 0xd)
    /var/lib/arvados/go/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc00011a048, 0xc000458800, 0x7d3, 0x7d3, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/net/net.go:183 +0x91
crypto/tls.(*atLeastReader).Read(0xc00080aa68, 0xc000458800, 0x7d3, 0x7d3, 0xc0000719f8, 0xc000060c00, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:776 +0x63
bytes.(*Buffer).ReadFrom(0xc00051f078, 0x1024920, 0xc00080aa68, 0x40d8e5, 0xd78e80, 0xe1c260)
    /var/lib/arvados/go/src/bytes/buffer.go:204 +0xbe
crypto/tls.(*Conn).readFromUntil(0xc00051ee00, 0x10254e0, 0xc00011a048, 0x5, 0xc00011a048, 0x203000)
    /var/lib/arvados/go/src/crypto/tls/conn.go:798 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc00051ee00, 0x0, 0x0, 0x43d31c)
    /var/lib/arvados/go/src/crypto/tls/conn.go:605 +0x115
crypto/tls.(*Conn).readRecord(...)
    /var/lib/arvados/go/src/crypto/tls/conn.go:573
crypto/tls.(*Conn).Read(0xc00051ee00, 0xc0005ba000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:1276 +0x165
net/http.(*persistConn).Read(0xc0000ce360, 0xc0005ba000, 0x1000, 0x1000, 0xc0002a4960, 0xc000071d40, 0x407795)
    /var/lib/arvados/go/src/net/http/transport.go:1922 +0x77
bufio.(*Reader).fill(0xc0000895c0)
    /var/lib/arvados/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).Peek(0xc0000895c0, 0x1, 0x0, 0x1, 0x4, 0x1, 0x3)
    /var/lib/arvados/go/src/bufio/bufio.go:139 +0x4f
net/http.(*persistConn).readLoop(0xc0000ce360)
    /var/lib/arvados/go/src/net/http/transport.go:2083 +0x1a8
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1743 +0xc77

goroutine 59 [select]:
net/http.(*persistConn).writeLoop(0xc0000ce360)
    /var/lib/arvados/go/src/net/http/transport.go:2382 +0xf7
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1744 +0xc9c

goroutine 150 [select]:
net/http.(*persistConn).writeLoop(0xc0001e2240)
    /var/lib/arvados/go/src/net/http/transport.go:2382 +0xf7
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1744 +0xc9c

goroutine 103 [IO wait]:
internal/poll.runtime_pollWait(0x7f40d175b598, 0x72, 0xffffffffffffffff)
    /var/lib/arvados/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc00022a198, 0x72, 0x700, 0x7d3, 0xffffffffffffffff)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc00022a180, 0xc0001d0000, 0x7d3, 0x7d3, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc00022a180, 0xc0001d0000, 0x7d3, 0x7d3, 0x7c6, 0xc00038cc20, 0xd)
    /var/lib/arvados/go/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc00020a040, 0xc0001d0000, 0x7d3, 0x7d3, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/net/net.go:183 +0x91
crypto/tls.(*atLeastReader).Read(0xc00060c048, 0xc0001d0000, 0x7d3, 0x7d3, 0xc0001b79f8, 0xc000600000, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:776 +0x63
bytes.(*Buffer).ReadFrom(0xc00038ccf8, 0x1024920, 0xc00060c048, 0x40d8e5, 0xd78e80, 0xe1c260)
    /var/lib/arvados/go/src/bytes/buffer.go:204 +0xbe
crypto/tls.(*Conn).readFromUntil(0xc00038ca80, 0x10254e0, 0xc00020a040, 0x5, 0xc00020a040, 0x203000)
    /var/lib/arvados/go/src/crypto/tls/conn.go:798 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc00038ca80, 0x0, 0x0, 0x43d31c)
    /var/lib/arvados/go/src/crypto/tls/conn.go:605 +0x115
crypto/tls.(*Conn).readRecord(...)
    /var/lib/arvados/go/src/crypto/tls/conn.go:573
crypto/tls.(*Conn).Read(0xc00038ca80, 0xc0001de000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:1276 +0x165
net/http.(*persistConn).Read(0xc000168a20, 0xc0001de000, 0x1000, 0x1000, 0xc000094360, 0xc0001b7d40, 0x407795)
    /var/lib/arvados/go/src/net/http/transport.go:1922 +0x77
bufio.(*Reader).fill(0xc000089b00)
    /var/lib/arvados/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).Peek(0xc000089b00, 0x1, 0x0, 0x1, 0x4, 0x1, 0x3)
    /var/lib/arvados/go/src/bufio/bufio.go:139 +0x4f
net/http.(*persistConn).readLoop(0xc000168a20)
    /var/lib/arvados/go/src/net/http/transport.go:2083 +0x1a8
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1743 +0xc77

goroutine 75 [select]:
git.arvados.org/arvados.git/sdk/go/keepclient.(*cachedSvcList).poll(0xc000111d70)
    /root/arvados/sdk/go/keepclient/discover.go:94 +0x12f
created by git.arvados.org/arvados.git/sdk/go/keepclient.(*KeepClient).discoverServices
    /root/arvados/sdk/go/keepclient/discover.go:154 +0x545

goroutine 76 [select]:
git.arvados.org/arvados.git/sdk/go/keepclient.(*cachedSvcList).poll.func1(0xc0002a52c0, 0xc0002a5320, 0xc000111d70)
    /root/arvados/sdk/go/keepclient/discover.go:77 +0x17a
created by git.arvados.org/arvados.git/sdk/go/keepclient.(*cachedSvcList).poll
    /root/arvados/sdk/go/keepclient/discover.go:73 +0xac

goroutine 73 [IO wait]:
internal/poll.runtime_pollWait(0x7f40d175b680, 0x72, 0xffffffffffffffff)
    /var/lib/arvados/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc000122318, 0x72, 0x700, 0x7d3, 0xffffffffffffffff)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000122300, 0xc000459000, 0x7d3, 0x7d3, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc000122300, 0xc000459000, 0x7d3, 0x7d3, 0x7c6, 0xc0002b3a20, 0xd)
    /var/lib/arvados/go/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc00011a1a0, 0xc000459000, 0x7d3, 0x7d3, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/net/net.go:183 +0x91
crypto/tls.(*atLeastReader).Read(0xc00000e3a8, 0xc000459000, 0x7d3, 0x7d3, 0xc0001bd9f8, 0xc000100000, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:776 +0x63
bytes.(*Buffer).ReadFrom(0xc0002b3af8, 0x1024920, 0xc00000e3a8, 0x40d8e5, 0xd78e80, 0xe1c260)
    /var/lib/arvados/go/src/bytes/buffer.go:204 +0xbe
crypto/tls.(*Conn).readFromUntil(0xc0002b3880, 0x10254e0, 0xc00011a1a0, 0x5, 0xc00011a1a0, 0x203000)
    /var/lib/arvados/go/src/crypto/tls/conn.go:798 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc0002b3880, 0x0, 0x0, 0x43d31c)
    /var/lib/arvados/go/src/crypto/tls/conn.go:605 +0x115
crypto/tls.(*Conn).readRecord(...)
    /var/lib/arvados/go/src/crypto/tls/conn.go:573
crypto/tls.(*Conn).Read(0xc0002b3880, 0xc000246000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:1276 +0x165
net/http.(*persistConn).Read(0xc0001fac60, 0xc000246000, 0x1000, 0x1000, 0xc000094cc0, 0xc0001bdd40, 0x407795)
    /var/lib/arvados/go/src/net/http/transport.go:1922 +0x77
bufio.(*Reader).fill(0xc000130a20)
    /var/lib/arvados/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).Peek(0xc000130a20, 0x1, 0x0, 0x1, 0x4, 0x1, 0x3)
    /var/lib/arvados/go/src/bufio/bufio.go:139 +0x4f
net/http.(*persistConn).readLoop(0xc0001fac60)
    /var/lib/arvados/go/src/net/http/transport.go:2083 +0x1a8
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1743 +0xc77

goroutine 74 [select]:
net/http.(*persistConn).writeLoop(0xc0001fac60)
    /var/lib/arvados/go/src/net/http/transport.go:2382 +0xf7
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1744 +0xc9c

goroutine 104 [select]:
net/http.(*persistConn).writeLoop(0xc000168a20)
    /var/lib/arvados/go/src/net/http/transport.go:2382 +0xf7
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1744 +0xc9c

goroutine 138 [select]:
net/http.(*persistConn).writeLoop(0xc000666ea0)
    /var/lib/arvados/go/src/net/http/transport.go:2382 +0xf7
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1744 +0xc9c

goroutine 130 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc000001a08)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 134 [IO wait]:
internal/poll.runtime_pollWait(0x7f40d175b4b0, 0x72, 0xffffffffffffffff)
    /var/lib/arvados/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc000122198, 0x72, 0xcc00, 0xcc2a, 0xffffffffffffffff)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000122180, 0xc000194000, 0xcc2a, 0xcc2a, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc000122180, 0xc000194000, 0xcc2a, 0xcc2a, 0xcc1d, 0xc000408c20, 0xd)
    /var/lib/arvados/go/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc00011a038, 0xc000194000, 0xcc2a, 0xcc2a, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/net/net.go:183 +0x91
crypto/tls.(*atLeastReader).Read(0xc00000e960, 0xc000194000, 0xcc2a, 0xcc2a, 0xc0000199f8, 0xc000101c00, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:776 +0x63
bytes.(*Buffer).ReadFrom(0xc000408cf8, 0x1024920, 0xc00000e960, 0x40d8e5, 0xd78e80, 0xe1c260)
    /var/lib/arvados/go/src/bytes/buffer.go:204 +0xbe
crypto/tls.(*Conn).readFromUntil(0xc000408a80, 0x10254e0, 0xc00011a038, 0x5, 0xc00011a038, 0x203000)
    /var/lib/arvados/go/src/crypto/tls/conn.go:798 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc000408a80, 0x0, 0x0, 0x43d31c)
    /var/lib/arvados/go/src/crypto/tls/conn.go:605 +0x115
crypto/tls.(*Conn).readRecord(...)
    /var/lib/arvados/go/src/crypto/tls/conn.go:573
crypto/tls.(*Conn).Read(0xc000408a80, 0xc0004a2000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:1276 +0x165
net/http.(*persistConn).Read(0xc0001fa000, 0xc0004a2000, 0x1000, 0x1000, 0xc0002a4000, 0xc000019d40, 0x407795)
    /var/lib/arvados/go/src/net/http/transport.go:1922 +0x77
bufio.(*Reader).fill(0xc00052f320)
    /var/lib/arvados/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).Peek(0xc00052f320, 0x1, 0x0, 0x1, 0x4, 0x1, 0x3)
    /var/lib/arvados/go/src/bufio/bufio.go:139 +0x4f
net/http.(*persistConn).readLoop(0xc0001fa000)
    /var/lib/arvados/go/src/net/http/transport.go:2083 +0x1a8
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1743 +0xc77

goroutine 135 [select]:
net/http.(*persistConn).writeLoop(0xc0001fa000)
    /var/lib/arvados/go/src/net/http/transport.go:2382 +0xf7
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1744 +0xc9c

goroutine 172 [select]:
net/http.(*persistConn).writeLoop(0xc000ef2120)
    /var/lib/arvados/go/src/net/http/transport.go:2382 +0xf7
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1744 +0xc9c

goroutine 1036 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc000870f88)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 171 [IO wait]:
internal/poll.runtime_pollWait(0x7f40d175b2e0, 0x72, 0xffffffffffffffff)
    /var/lib/arvados/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc000766418, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000766400, 0xc000abf000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc000766400, 0xc000abf000, 0x1000, 0x1000, 0x43d31c, 0xc00006dc38, 0x46bce0)
    /var/lib/arvados/go/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc000011008, 0xc000abf000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/net/net.go:183 +0x91
net/http.(*persistConn).Read(0xc000ef2120, 0xc000abf000, 0x1000, 0x1000, 0xc00072f080, 0xc00006dd40, 0x407795)
    /var/lib/arvados/go/src/net/http/transport.go:1922 +0x77
bufio.(*Reader).fill(0xc000970720)
    /var/lib/arvados/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).Peek(0xc000970720, 0x1, 0x0, 0x1, 0x4, 0x1, 0x3)
    /var/lib/arvados/go/src/bufio/bufio.go:139 +0x4f
net/http.(*persistConn).readLoop(0xc000ef2120)
    /var/lib/arvados/go/src/net/http/transport.go:2083 +0x1a8
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1743 +0xc77

goroutine 149 [IO wait]:
internal/poll.runtime_pollWait(0x7f40d175b3c8, 0x72, 0xffffffffffffffff)
    /var/lib/arvados/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc000122418, 0x72, 0x700, 0x7d3, 0xffffffffffffffff)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000122400, 0xc0001d0800, 0x7d3, 0x7d3, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc000122400, 0xc0001d0800, 0x7d3, 0x7d3, 0x7c6, 0xc0004fe1a0, 0xd)
    /var/lib/arvados/go/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc000744000, 0xc0001d0800, 0x7d3, 0x7d3, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/net/net.go:183 +0x91
crypto/tls.(*atLeastReader).Read(0xc00080b8c0, 0xc0001d0800, 0x7d3, 0x7d3, 0xc0000189f8, 0xc000101c00, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:776 +0x63
bytes.(*Buffer).ReadFrom(0xc0004fe278, 0x1024920, 0xc00080b8c0, 0x40d8e5, 0xd78e80, 0xe1c260)
    /var/lib/arvados/go/src/bytes/buffer.go:204 +0xbe
crypto/tls.(*Conn).readFromUntil(0xc0004fe000, 0x10254e0, 0xc000744000, 0x5, 0xc000744000, 0x203000)
    /var/lib/arvados/go/src/crypto/tls/conn.go:798 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc0004fe000, 0x0, 0x0, 0x43d31c)
    /var/lib/arvados/go/src/crypto/tls/conn.go:605 +0x115
crypto/tls.(*Conn).readRecord(...)
    /var/lib/arvados/go/src/crypto/tls/conn.go:573
crypto/tls.(*Conn).Read(0xc0004fe000, 0xc00076a000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:1276 +0x165
net/http.(*persistConn).Read(0xc0001e2240, 0xc00076a000, 0x1000, 0x1000, 0xc000094660, 0xc000018d40, 0x407795)
    /var/lib/arvados/go/src/net/http/transport.go:1922 +0x77
bufio.(*Reader).fill(0xc00052ee40)
    /var/lib/arvados/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).Peek(0xc00052ee40, 0x1, 0x0, 0x1, 0x4, 0x1, 0x3)
    /var/lib/arvados/go/src/bufio/bufio.go:139 +0x4f
net/http.(*persistConn).readLoop(0xc0001e2240)
    /var/lib/arvados/go/src/net/http/transport.go:2083 +0x1a8
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1743 +0xc77

goroutine 278 [IO wait]:
internal/poll.runtime_pollWait(0x7f40d175b110, 0x72, 0xffffffffffffffff)
    /var/lib/arvados/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc000122298, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000122280, 0xc00090c000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc000122280, 0xc00090c000, 0x1000, 0x1000, 0x43d31c, 0xc00095ec38, 0x46bce0)
    /var/lib/arvados/go/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc00093e540, 0xc00090c000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/net/net.go:183 +0x91
net/http.(*persistConn).Read(0xc00097e900, 0xc00090c000, 0x1000, 0x1000, 0xc0004cec00, 0xc00095ed40, 0x407795)
    /var/lib/arvados/go/src/net/http/transport.go:1922 +0x77
bufio.(*Reader).fill(0xc000cda360)
    /var/lib/arvados/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).Peek(0xc000cda360, 0x1, 0x0, 0x1, 0x4, 0x1, 0x3)
    /var/lib/arvados/go/src/bufio/bufio.go:139 +0x4f
net/http.(*persistConn).readLoop(0xc00097e900)
    /var/lib/arvados/go/src/net/http/transport.go:2083 +0x1a8
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1743 +0xc77

goroutine 748 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc022184508)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 137 [IO wait]:
internal/poll.runtime_pollWait(0x7f40d175b1f8, 0x72, 0xffffffffffffffff)
    /var/lib/arvados/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc00022a318, 0x72, 0xcc00, 0xcc2a, 0xffffffffffffffff)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc00022a300, 0xc000304000, 0xcc2a, 0xcc2a, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc00022a300, 0xc000304000, 0xcc2a, 0xcc2a, 0x49e3, 0xc0004fe8a0, 0xd)
    /var/lib/arvados/go/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc00020a218, 0xc000304000, 0xcc2a, 0xcc2a, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/net/net.go:183 +0x91
crypto/tls.(*atLeastReader).Read(0xc0008fc4f8, 0xc000304000, 0xcc2a, 0xcc2a, 0x8, 0xc000680000, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:776 +0x63
bytes.(*Buffer).ReadFrom(0xc0004fe978, 0x1024920, 0xc0008fc4f8, 0x40d8e5, 0xd78e80, 0xe1c260)
    /var/lib/arvados/go/src/bytes/buffer.go:204 +0xbe
crypto/tls.(*Conn).readFromUntil(0xc0004fe700, 0x10254e0, 0xc00020a218, 0x5, 0xc00020a218, 0x41b0fb)
    /var/lib/arvados/go/src/crypto/tls/conn.go:798 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc0004fe700, 0x0, 0x0, 0x43d31c)
    /var/lib/arvados/go/src/crypto/tls/conn.go:605 +0x115
crypto/tls.(*Conn).readRecord(...)
    /var/lib/arvados/go/src/crypto/tls/conn.go:573
crypto/tls.(*Conn).Read(0xc0004fe700, 0xc0004d0000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:1276 +0x165
net/http.(*persistConn).Read(0xc000666ea0, 0xc0004d0000, 0x1000, 0x1000, 0xc0004ce4e0, 0xc000016d40, 0x407795)
    /var/lib/arvados/go/src/net/http/transport.go:1922 +0x77
bufio.(*Reader).fill(0xc00046e780)
    /var/lib/arvados/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).Peek(0xc00046e780, 0x1, 0x0, 0x1, 0x4, 0x1, 0x3)
    /var/lib/arvados/go/src/bufio/bufio.go:139 +0x4f
net/http.(*persistConn).readLoop(0xc000666ea0)
    /var/lib/arvados/go/src/net/http/transport.go:2083 +0x1a8
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1743 +0xc77

goroutine 223 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc000565e88)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 291 [select]:
git.arvados.org/arvados.git/sdk/go/keepclient.(*cachedSvcList).poll.func1(0xc000094ba0, 0xc000094d20, 0xc0007b8318)
    /root/arvados/sdk/go/keepclient/discover.go:77 +0x17a
created by git.arvados.org/arvados.git/sdk/go/keepclient.(*cachedSvcList).poll
    /root/arvados/sdk/go/keepclient/discover.go:73 +0xac

goroutine 227 [IO wait]:
internal/poll.runtime_pollWait(0x7f40d175b028, 0x72, 0xffffffffffffffff)
    /var/lib/arvados/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc000998698, 0x72, 0xcc00, 0xcc2a, 0xffffffffffffffff)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000998680, 0xc000ad2000, 0xcc2a, 0xcc2a, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc000998680, 0xc000ad2000, 0xcc2a, 0xcc2a, 0x100, 0x7f40d42c7fff, 0x400)
    /var/lib/arvados/go/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc00020a270, 0xc000ad2000, 0xcc2a, 0xcc2a, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/net/net.go:183 +0x91
crypto/tls.(*atLeastReader).Read(0xc000ac0150, 0xc000ad2000, 0xcc2a, 0xcc2a, 0x8, 0xc00026b800, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:776 +0x63
bytes.(*Buffer).ReadFrom(0xc0004ff078, 0x1024920, 0xc000ac0150, 0x40d8e5, 0xd78e80, 0xe1c260)
    /var/lib/arvados/go/src/bytes/buffer.go:204 +0xbe
crypto/tls.(*Conn).readFromUntil(0xc0004fee00, 0x10254e0, 0xc00020a270, 0x5, 0xc00020a270, 0x203000)
    /var/lib/arvados/go/src/crypto/tls/conn.go:798 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc0004fee00, 0x0, 0x0, 0x43d31c)
    /var/lib/arvados/go/src/crypto/tls/conn.go:605 +0x115
crypto/tls.(*Conn).readRecord(...)
    /var/lib/arvados/go/src/crypto/tls/conn.go:573
crypto/tls.(*Conn).Read(0xc0004fee00, 0xc000ab1000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:1276 +0x165
net/http.(*persistConn).Read(0xc000aa67e0, 0xc000ab1000, 0x1000, 0x1000, 0xc000094fc0, 0xc000960d40, 0x407795)
    /var/lib/arvados/go/src/net/http/transport.go:1922 +0x77
bufio.(*Reader).fill(0xc000130540)
    /var/lib/arvados/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).Peek(0xc000130540, 0x1, 0x0, 0x1, 0x4, 0x1, 0x3)
    /var/lib/arvados/go/src/bufio/bufio.go:139 +0x4f
net/http.(*persistConn).readLoop(0xc000aa67e0)
    /var/lib/arvados/go/src/net/http/transport.go:2083 +0x1a8
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1743 +0xc77

goroutine 228 [select]:
net/http.(*persistConn).writeLoop(0xc000aa67e0)
    /var/lib/arvados/go/src/net/http/transport.go:2382 +0xf7
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1744 +0xc9c

goroutine 321 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc000683288)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 290 [select]:
git.arvados.org/arvados.git/sdk/go/keepclient.(*cachedSvcList).poll(0xc0007b8318)
    /root/arvados/sdk/go/keepclient/discover.go:94 +0x12f
created by git.arvados.org/arvados.git/sdk/go/keepclient.(*KeepClient).discoverServices
    /root/arvados/sdk/go/keepclient/discover.go:154 +0x545

goroutine 279 [select]:
net/http.(*persistConn).writeLoop(0xc00097e900)
    /var/lib/arvados/go/src/net/http/transport.go:2382 +0xf7
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1744 +0xc9c

goroutine 1134 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc000871708)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 400 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc000683708)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 354 [select]:
net/http.(*persistConn).writeLoop(0xc0009c2240)
    /var/lib/arvados/go/src/net/http/transport.go:2382 +0xf7
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1744 +0xc9c

goroutine 241 [IO wait]:
internal/poll.runtime_pollWait(0x7f40d175ac88, 0x72, 0xffffffffffffffff)
    /var/lib/arvados/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc000122218, 0x72, 0x700, 0x7d3, 0xffffffffffffffff)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000122200, 0xc000459800, 0x7d3, 0x7d3, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc000122200, 0xc000459800, 0x7d3, 0x7d3, 0x7c6, 0xc0000aa520, 0xd)
    /var/lib/arvados/go/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc00093e530, 0xc000459800, 0x7d3, 0x7d3, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/net/net.go:183 +0x91
crypto/tls.(*atLeastReader).Read(0xc004dd2240, 0xc000459800, 0x7d3, 0x7d3, 0x8, 0xc00026b800, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:776 +0x63
bytes.(*Buffer).ReadFrom(0xc0000aa5f8, 0x1024920, 0xc004dd2240, 0x40d8e5, 0xd78e80, 0xe1c260)
    /var/lib/arvados/go/src/bytes/buffer.go:204 +0xbe
crypto/tls.(*Conn).readFromUntil(0xc0000aa380, 0x10254e0, 0xc00093e530, 0x5, 0xc00093e530, 0x203001)
    /var/lib/arvados/go/src/crypto/tls/conn.go:798 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc0000aa380, 0x0, 0x0, 0x43d31c)
    /var/lib/arvados/go/src/crypto/tls/conn.go:605 +0x115
crypto/tls.(*Conn).readRecord(...)
    /var/lib/arvados/go/src/crypto/tls/conn.go:573
crypto/tls.(*Conn).Read(0xc0000aa380, 0xc000cbe000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/crypto/tls/conn.go:1276 +0x165
net/http.(*persistConn).Read(0xc0009c2240, 0xc000cbe000, 0x1000, 0x1000, 0xc000abde60, 0xc00095dd40, 0x407795)
    /var/lib/arvados/go/src/net/http/transport.go:1922 +0x77
bufio.(*Reader).fill(0xc0004ed500)
    /var/lib/arvados/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).Peek(0xc0004ed500, 0x1, 0x0, 0x1, 0x4, 0x1, 0x3)
    /var/lib/arvados/go/src/bufio/bufio.go:139 +0x4f
net/http.(*persistConn).readLoop(0xc0009c2240)
    /var/lib/arvados/go/src/net/http/transport.go:2083 +0x1a8
created by net/http.(*Transport).dialConn
    /var/lib/arvados/go/src/net/http/transport.go:1743 +0xc77

goroutine 437 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc000783708)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 839 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc022185b88)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 919 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc022175d08)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 858 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc022174988)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 2165 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc002e8ac88)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 3055 [IO wait]:
internal/poll.runtime_pollWait(0x7f40d175af40, 0x72, 0x0)
    /var/lib/arvados/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc0045bfe98, 0x72, 0x0, 0x0, 0xe4b0ab)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc0045bfe80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/internal/poll/fd_unix.go:401 +0x212
net.(*netFD).accept(0xc0045bfe80, 0x0, 0xb4, 0x0)
    /var/lib/arvados/go/src/net/fd_unix.go:172 +0x45
net.(*TCPListener).accept(0xc004a75530, 0x0, 0x0, 0xc00095cde0)
    /var/lib/arvados/go/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).AcceptTCP(0xc004a75530, 0xc00095ce08, 0x499286, 0x60ca3873)
    /var/lib/arvados/go/src/net/tcpsock.go:248 +0x65
git.arvados.org/arvados.git/sdk/go/httpserver.tcpKeepAliveListener.Accept(0xc004a75530, 0xc00095ce58, 0x18, 0xc001602900, 0x749dfb)
    /root/arvados/sdk/go/httpserver/httpserver.go:89 +0x2f
net/http.(*Server).Serve(0xc004c02240, 0x1033820, 0xc004a75530, 0x0, 0x0)
    /var/lib/arvados/go/src/net/http/server.go:2981 +0x285
git.arvados.org/arvados.git/sdk/go/httpserver.(*Server).Start.func1(0xc004c02240, 0xc004b75c80, 0xc004d95a70)
    /root/arvados/sdk/go/httpserver/httpserver.go:50 +0x12a
created by git.arvados.org/arvados.git/sdk/go/httpserver.(*Server).Start
    /root/arvados/sdk/go/httpserver/httpserver.go:45 +0x1eb

goroutine 3050 [IO wait]:
internal/poll.runtime_pollWait(0x7f40d175ad70, 0x72, 0xffffffffffffffff)
    /var/lib/arvados/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc004db7ab8, 0x72, 0x501, 0x5d3, 0xffffffffffffffff)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /var/lib/arvados/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc004db7aa0, 0xc004ecc02d, 0x5d3, 0x5d3, 0x0, 0x0, 0x0)
    /var/lib/arvados/go/src/internal/poll/fd_unix.go:166 +0x1d5
os.(*File).read(...)
    /var/lib/arvados/go/src/os/file_posix.go:31
os.(*File).Read(0xc001a156b0, 0xc004ecc02d, 0x5d3, 0x5d3, 0x1d, 0x0, 0x0)
    /var/lib/arvados/go/src/os/file.go:117 +0x77
bytes.(*Buffer).ReadFrom(0xc004dd8990, 0x1025920, 0xc001a156b0, 0x7f40d0375a20, 0xc004dd8990, 0x1)
    /var/lib/arvados/go/src/bytes/buffer.go:204 +0xbe
io.copyBuffer(0x1024800, 0xc004dd8990, 0x1025920, 0xc001a156b0, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0)
    /var/lib/arvados/go/src/io/io.go:409 +0x357
io.Copy(...)
    /var/lib/arvados/go/src/io/io.go:382
git.arvados.org/arvados.git/services/keep-web.(*IntegrationSuite).runCadaver(0xc000430750, 0xc0024d91d0, 0xe79d40, 0x32, 0xe4aa30, 0x7, 0xe47173, 0x2, 0x0, 0x0)
    /root/arvados/services/keep-web/cadaver_test.go:369 +0x77e
git.arvados.org/arvados.git/services/keep-web.(*IntegrationSuite).TestCadaverUsersDir(0xc000430750, 0xc0024d91d0)
    /root/arvados/services/keep-web/cadaver_test.go:327 +0x325
reflect.Value.call(0xe45080, 0xc000430750, 0x3e13, 0xe479f6, 0x4, 0xc000015f08, 0x1, 0x1, 0x14cd3c0, 0xc003972640, ...)
    /var/lib/arvados/go/src/reflect/value.go:476 +0x8e7
reflect.Value.Call(0xe45080, 0xc000430750, 0x3e13, 0xc003972708, 0x1, 0x1, 0xc0024d92c0, 0x0, 0x0)
    /var/lib/arvados/go/src/reflect/value.go:337 +0xb9
gopkg.in/check%2ev1.(*suiteRunner).forkTest.func1(0xc0024d91d0)
    /root/.cache/arvados-build/GOPATH/pkg/mod/gopkg.in/check.v1@v1.0.0-20161208181325-20d25e280405/check.go:772 +0x6b5
gopkg.in/check%2ev1.(*suiteRunner).forkCall.func1(0xc00022a100, 0xc0024d91d0, 0xc004e92340)
    /root/.cache/arvados-build/GOPATH/pkg/mod/gopkg.in/check.v1@v1.0.0-20161208181325-20d25e280405/check.go:666 +0x98
created by gopkg.in/check%2ev1.(*suiteRunner).forkCall
    /root/.cache/arvados-build/GOPATH/pkg/mod/gopkg.in/check.v1@v1.0.0-20161208181325-20d25e280405/check.go:663 +0x1fe

goroutine 3039 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc003943108)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227

goroutine 3070 [runnable]:
net/http.(*connReader).backgroundRead(0xc004dd8a50)
    /var/lib/arvados/go/src/net/http/server.go:691
created by net/http.(*connReader).startBackgroundRead
    /var/lib/arvados/go/src/net/http/server.go:688 +0xd5

goroutine 3069 [runnable]:
git.arvados.org/arvados.git/services/keep-web.(*cache).pruneSessions(0xc003943108)
    /root/arvados/services/keep-web/cache.go:262
created by git.arvados.org/arvados.git/services/keep-web.(*cache).GetSession
    /root/arvados/services/keep-web/cache.go:249 +0x1b0

goroutine 3101 [runnable]:
unicode.Is(0x1488880, 0x78, 0x40)
    /var/lib/arvados/go/src/unicode/letter.go:155 +0xd6
golang.org/x/net/webdav/internal/xml.isName(0xc004a43940, 0x3, 0x40, 0x0)
    /root/.cache/arvados-build/GOPATH/pkg/mod/golang.org/x/net@v0.0.0-20201021035429-f5854403a974/webdav/internal/xml/xml.go:1214 +0x85
golang.org/x/net/webdav/internal/xml.(*Decoder).name(0xc004eb6800, 0x13f, 0x14302d0, 0xc004f326f0)
    /root/.cache/arvados-build/GOPATH/pkg/mod/golang.org/x/net@v0.0.0-20201021035429-f5854403a974/webdav/internal/xml/xml.go:1165 +0xa5
golang.org/x/net/webdav/internal/xml.(*Decoder).rawToken(0xc004eb6800, 0xc001275da0, 0xe29420, 0xc00308c000, 0x10000c004f32801)
    /root/.cache/arvados-build/GOPATH/pkg/mod/golang.org/x/net@v0.0.0-20201021035429-f5854403a974/webdav/internal/xml/xml.go:586 +0x9f6
golang.org/x/net/webdav/internal/xml.(*Decoder).Token(0xc004eb6800, 0xc004dbb560, 0xc004e10058, 0xc004dbb568, 0x0)
    /root/.cache/arvados-build/GOPATH/pkg/mod/golang.org/x/net@v0.0.0-20201021035429-f5854403a974/webdav/internal/xml/xml.go:280 +0xefb
golang.org/x/net/webdav/internal/xml.(*Decoder).unmarshal(0xc004eb6800, 0xde6240, 0xc004ec40c0, 0x199, 0x0, 0x199, 0x0)
    /root/.cache/arvados-build/GOPATH/pkg/mod/golang.org/x/net@v0.0.0-20201021035429-f5854403a974/webdav/internal/xml/read.go:276 +0x2bf9
golang.org/x/net/webdav/internal/xml.(*Decoder).DecodeElement(0xc004eb6800, 0xd19fa0, 0xc004ec40c0, 0x0, 0xc94f42, 0xc004f32d70)
    /root/.cache/arvados-build/GOPATH/pkg/mod/golang.org/x/net@v0.0.0-20201021035429-f5854403a974/webdav/internal/xml/read.go:133 +0x134
golang.org/x/net/webdav/internal/xml.(*Decoder).Decode(...)
    /root/.cache/arvados-build/GOPATH/pkg/mod/golang.org/x/net@v0.0.0-20201021035429-f5854403a974/webdav/internal/xml/read.go:121
golang.org/x/net/webdav.readPropfind(0x7f40d032e1b8, 0xc004eb0a00, 0xc004eb0a00, 0x7f40d032e1b8, 0xc004eb0a00, 0x103a9d0, 0xc004eb0b40, 0x0, 0x0, 0xd362a0, ...)
    /root/.cache/arvados-build/GOPATH/pkg/mod/golang.org/x/net@v0.0.0-20201021035429-f5854403a974/webdav/xml.go:180 +0xb6
golang.org/x/net/webdav.(*Handler).handlePropfind(0xc004eb0b00, 0x7f40d047d800, 0xc004eb4370, 0xc004eb6700, 0x0, 0xc004f33048, 0x4102b8)
    /root/.cache/arvados-build/GOPATH/pkg/mod/golang.org/x/net@v0.0.0-20201021035429-f5854403a974/webdav/webdav.go:529 +0x27e
golang.org/x/net/webdav.(*Handler).ServeHTTP(0xc004eb0b00, 0x7f40d047d800, 0xc004eb4370, 0xc004eb6700)
    /root/.cache/arvados-build/GOPATH/pkg/mod/golang.org/x/net@v0.0.0-20201021035429-f5854403a974/webdav/webdav.go:67 +0x57b
git.arvados.org/arvados.git/services/keep-web.(*handler).serveSiteFS(0xc004ae14a0, 0x7f40d047d800, 0xc004eb4370, 0xc004eb6700, 0xc004e9e3b0, 0x1, 0x1, 0x101)
    /root/arvados/services/keep-web/handler.go:646 +0x7ec
git.arvados.org/arvados.git/services/keep-web.(*handler).ServeHTTP(0xc004ae14a0, 0x1033e80, 0xc004ec04a0, 0xc004eb6700)
    /root/arvados/services/keep-web/handler.go:348 +0x3085
git.arvados.org/arvados.git/sdk/go/httpserver.LogRequests.func1(0x7f40d02b6f68, 0xc004eb42d0, 0xc004eb6600)
    /root/arvados/sdk/go/httpserver/logger.go:56 +0x8f9
net/http.HandlerFunc.ServeHTTP(0xc004a75380, 0x7f40d02b6f68, 0xc004eb42d0, 0xc004eb6600)
    /var/lib/arvados/go/src/net/http/server.go:2069 +0x44
git.arvados.org/arvados.git/sdk/go/httpserver.AddRequestIDs.func1(0x7f40d02b6f68, 0xc004eb42d0, 0xc004eb6600)
    /root/arvados/sdk/go/httpserver/id_generator.go:57 +0x1ae
net/http.HandlerFunc.ServeHTTP(0xc004e01080, 0x7f40d02b6f68, 0xc004eb42d0, 0xc004eb6600)
    /var/lib/arvados/go/src/net/http/server.go:2069 +0x44
git.arvados.org/arvados.git/sdk/go/httpserver.HandlerWithContext.func1(0x7f40d02b6f68, 0xc004eb42d0, 0xc004eb6500)
    /root/arvados/sdk/go/httpserver/logger.go:30 +0x107
net/http.HandlerFunc.ServeHTTP(0xc004c005a0, 0x7f40d02b6f68, 0xc004eb42d0, 0xc004eb6500)
    /var/lib/arvados/go/src/net/http/server.go:2069 +0x44
github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerDuration.func1(0x1033670, 0xc004eb21c0, 0xc004eb6500)
    /root/.cache/arvados-build/GOPATH/pkg/mod/github.com/prometheus/client_golang@v1.2.1/prometheus/promhttp/instrument_server.go:68 +0x122
net/http.HandlerFunc.ServeHTTP(0xc004c00870, 0x1033670, 0xc004eb21c0, 0xc004eb6500)
    /var/lib/arvados/go/src/net/http/server.go:2069 +0x44
git.arvados.org/arvados.git/sdk/go/httpserver.(*metrics).ServeHTTP(0xc004da9000, 0x1033670, 0xc004eb21c0, 0xc004eb6500)
    /root/arvados/sdk/go/httpserver/metrics.go:70 +0x51
net/http.serverHandler.ServeHTTP(0xc004c02240, 0x1033670, 0xc004eb21c0, 0xc004eb6500)
    /var/lib/arvados/go/src/net/http/server.go:2887 +0xa3
net/http.(*conn).serve(0xc004b54a00, 0x1036018, 0xc004e95cc0)
    /var/lib/arvados/go/src/net/http/server.go:1952 +0x8cd
created by net/http.(*Server).Serve
    /var/lib/arvados/go/src/net/http/server.go:3013 +0x39b

goroutine 2994 [chan receive]:
git.arvados.org/arvados.git/services/keep-web.(*cache).setup.func1(0xc003942e08)
    /root/arvados/services/keep-web/cache.go:167 +0x91
created by git.arvados.org/arvados.git/services/keep-web.(*cache).setup
    /root/arvados/services/keep-web/cache.go:166 +0x227
FAIL    git.arvados.org/arvados.git/services/keep-web    19.144s
FAIL

17464-fix-missing-locks @ 87033e4c4aae0fd4366d1d807e87fb4bb7e7af9d -- developer-run-tests: #2531

Tom Clegg wrote:

comments on 17464-download-logging:

doc page typo @keepprox@ and KeepWebPermisison (in all the example configs)

Fixed.

Elsewhere in config we use "WebDAV" rather than "KeepWeb", in keeping with the cluster-config theme that we're configuring the service, not the binary that implements it. Should we say WebDAVPermission instead? The comment that it also applies to S3 should still work?

I went and changed everything to say WebDAV. Arguably we should change everything to say KeepWeb but I'm fine with just making it consistent.

("Keepproxy" is basically how we spell "keep service for external clients"... so I think it fits.)

This seems a bit wordy -- maybe just "Permissions for regular users and admins to upload/download files via WebDAV and S3"? And mentioning Workbench might be misleading -- doesn't wb1 still upload via keepproxy?

[...]

The KeepproxyPermission comment also seems extra-wordy to me ("permissions ... to be able to download" can be just "permissions ... to download").

Fixed.

The docs and config comments should mention the fact that non-upload writes (mkdir, rename) and non-download reads (list files) are always permitted / unaffected by these settings.

Done

It seems like if you don't have Download permission you can do "PROPFIND /" (get an xml document with a file listing) but you can't do "GET /" (get an html document with a file listing), which I don't think anyone would guess without reading the code -- this should probably be either documented or changed.

Fixed so that it doesn't deny or log downloads of directories.

If the asynchronous "create log record" calls fail, we should probably log the error message, so it's not too big a mystery if something goes sour.

Logs errors now.

This should un-pyramid to "if err != nil { continue }" ... current version looks like it will start panicking when we make (*sdk/go/arvados.filehandle)Close() do anything more than "return nil":
[...]

That code should also probably treat a non-IsNotExist error as a real error instead of ignoring it.

Fixed.

What happens

???

The new handler funcs aren't intended for outsiders, so shouldn't be exported. They also don't seem to access their receiver at all, so maybe they should just be regular funcs instead of handler methods.

Fixed. I keep forgetting about the uppercase/lowercase rule for module visibility.

In DetermineCollection, would it work just as well to start at the root level and work down, instead of the other way around? I think that could avoid the possibility of reading a file named ".arvados#collection" stored in a subdir in a collection (accidentally or on purpose) with the wrong uuid/pdh.

Made it start from the beginning. I think I was thinking how you could have nested projects, so you would need to do this for projects, but that doesn't make sense for collections.

It looks like TestUploadLoggingPermission doesn't really need to use FooCollection specifically. Rather than modifying FooCollection and then doing a full database-reset to revert it, could we just create a new collection to modify in the test, similar to TestCacheWriteCollectionSamePDH?

Fixed.

I think it would be worth testing the logging feature with some different paths (non-top-level files, /users/..., PDH) with the logging features, to make sure the UUID and PDH get filled in as expected.

Added some more tests.

I'm not sure but it looks like we might get a "download" log message for "GET /dir/" and "GET /dir", which would be confusing. Either way we should probably test this.

GET on directories should no longer be logged.

I wonder whether the logging feature should be configurable, at least for the anonymous user case. It seems like creating postgresql rows via RailsAPI (and related websocket events) could become the most resource-intensive part of using Arvados to host data on the web, which would be a shame on a site where nobody is interested in reading them.

I added an option WebDAVLogEvents to turn them off.

17464-download-activity @ eb9fa033e0d19a2459041f296e3286639ad4d1ff

developer-run-tests: #2532

Peter Amstutz wrote:

What happens

???

Hey, why won't you tell me what happens?

Pretty sure whatever I was about to ask there didn't need to be asked after all.

git diff origin/17464-download-logging...origin/17464-keepproxy-logging-perms (0da30aa9a...699ddfc7e)

• it seems like it could get weird if the error is something else, like "connection reset by peer" -- perhaps we should error out if the users/current error isn't 403.
• a scoped admin token follows the "user can download" rules instead of the "admin can download" rules, which is fine in most cases but we do support configuring "admin download = false, user download = true" (which actually doesn't sound entirely useless) and it seems a bit surprising that certain scoped admin tokens would be permitted to download anyway with that config. I'm not sure there's a great solution to this -- maybe we just have to document it?

AFAICT old entries are never removed so the token cache grows forever. Is now (while we're adding a user record to each cache entry) the time to address this?

Tom Clegg wrote:

git diff origin/17464-download-logging...origin/17464-keepproxy-logging-perms (0da30aa9a...699ddfc7e)

If "GET users/current" fails for any reason, and op=="read", and "HEAD keep_services/accessible" succeeds, we treat that token as non-admin for 5 minutes. This is the desired outcome for the scoped non-admin token case, but

• it seems like it could get weird if the error is something else, like "connection reset by peer" -- perhaps we should error out if the users/current error isn't 403.

It turns out that an error because oy missing scope is 403, and an error because of an invalid token is 401. So it is only useful to do the second check if we got a 403.

• a scoped admin token follows the "user can download" rules instead of the "admin can download" rules, which is fine in most cases but we do support configuring "admin download = false, user download = true" (which actually doesn't sound entirely useless) and it seems a bit surprising that certain scoped admin tokens would be permitted to download anyway with that config. I'm not sure there's a great solution to this -- maybe we just have to document it?

admin=false, user=true really is completely useless, but a more likely scenario would be admin=true, user=false, and then creating a sharing link as an admin, the user would not be able to download the file.

I documented this. However functionally this is actually a little bit of a problem because we probably want to provide a reasonable way for an admin to release data (individual collections) to users. Perhaps the sharing token scopes should include permission to read users/current?

AFAICT old entries are never removed so the token cache grows forever. Is now (while we're adding a user record to each cache entry) the time to address this?

I switched it over to use the lru.2Q cache that keep-web uses.

17464-download-activity @ 891783a0a90b37336455c81748dd3fe002e95a9c

developer-run-tests: #2538

Fixed a bug with sharing token downloads from keep-web:

2ffe1a900d4cfcceac02b44768a13a47edf18184

developer-run-tests: #2539

If "GET users/current" fails for any reason, and op=="read", and "HEAD keep_services/accessible" succeeds, we treat that token as non-admin for 5 minutes. This is the desired outcome for the scoped non-admin token case, but

• it seems like it could get weird if the error is something else, like "connection reset by peer" -- perhaps we should error out if the users/current error isn't 403.

It turns out that an error because oy missing scope is 403, and an error because of an invalid token is 401. So it is only useful to do the second check if we got a 403.

Yes, exactly.

• a scoped admin token follows the "user can download" rules instead of the "admin can download" rules, which is fine in most cases but we do support configuring "admin download = false, user download = true" (which actually doesn't sound entirely useless) and it seems a bit surprising that certain scoped admin tokens would be permitted to download anyway with that config. I'm not sure there's a great solution to this -- maybe we just have to document it?

admin=false, user=true really is completely useless

Do you mean nobody could want it? Or the way it's implemented makes it useless?

but a more likely scenario would be admin=true, user=false, and then creating a sharing link as an admin, the user would not be able to download the file.

I documented this. However functionally this is actually a little bit of a problem because we probably want to provide a reasonable way for an admin to release data (individual collections) to users. Perhaps the sharing token scopes should include permission to read users/current?

• if admin shares a collection via embedded-token url, everyone (even anonymous users) can download
• if admin shares a collection via permission link, logged-in regular users cannot download

• non-admin users cannot download, only list files
• embedded-token urls cannot download, only list files

Which one is right depends on your intended usage, I suppose.

I switched it over to use the lru.2Q cache that keep-web uses.

Definitely an improvement, thanks.

Stack trace (without showing the error) seems rough here, even though the current implementation seems to guarantee no error. It looks like we only call MakeRESTRouter from 3 places including tests, so adding an error return value and handling it the usual way might not be too much trouble.

       if err != nil {
               panic("Could not create 2Q")
       }

Tom Clegg wrote:

• a scoped admin token follows the "user can download" rules instead of the "admin can download" rules, which is fine in most cases but we do support configuring "admin download = false, user download = true" (which actually doesn't sound entirely useless) and it seems a bit surprising that certain scoped admin tokens would be permitted to download anyway with that config. I'm not sure there's a great solution to this -- maybe we just have to document it?

admin=false, user=true really is completely useless

Do you mean nobody could want it? Or the way it's implemented makes it useless?

Well, the admin can always impersonate another user, so it doesn't effectively restrict anything.

but a more likely scenario would be admin=true, user=false, and then creating a sharing link as an admin, the user would not be able to download the file.

I documented this. However functionally this is actually a little bit of a problem because we probably want to provide a reasonable way for an admin to release data (individual collections) to users. Perhaps the sharing token scopes should include permission to read users/current?

This implementation of admin=true, user=false would seem a little surprising:

• if admin shares a collection via embedded-token url, everyone (even anonymous users) can download
• if admin shares a collection via permission link, logged-in regular users cannot download

That's how it would behave if the sharing token scope includes users/current (which currently it doesn't).

This would seem less surprising, but also less useful, depending on the use case:

• non-admin users cannot download, only list files
• embedded-token urls cannot download, only list files

This is how it currently behaves, because the sharing token scope does not include users/current, so it has no way of knowing who the token owner is and if they are admin, so it just applies the user policy.

Which one is right depends on your intended usage, I suppose.

I guess the question is, since we kind of already know that we are going to want it, should we also be adding a way to mark individual collections as "permitted for download". Maybe a follow-on ticket because that requires a little bit of additional design and planning.

Stack trace (without showing the error) seems rough here, even though the current implementation seems to guarantee no error. It looks like we only call MakeRESTRouter from 3 places including tests, so adding an error return value and handling it the usual way might not be too much trouble.

It returns an error now.

Peter Amstutz wrote:

admin=false, user=true really is completely useless

Do you mean nobody could want it? Or the way it's implemented makes it useless?

Well, the admin can always impersonate another user, so it doesn't effectively restrict anything.

I see. I agree it wouldn't prevent an admin user from deliberately bypassing the restriction and downloading/uploading data.

However, that doesn't really seem to be the goal of this feature, given that even non-admin users also have ways to bypass these restrictions (run a container that downloads/uploads data, by use scp with a shell node, etc.) Isn't it more about making it sufficiently inconvenient that it won't happen merely because a person clicked a button without realizing/remembering it wasn't allowed?

This would seem less surprising, but also less useful, depending on the use case:

• non-admin users cannot download, only list files
• embedded-token urls cannot download, only list files

This is how it currently behaves, because the sharing token scope does not include users/current, so it has no way of knowing who the token owner is and if they are admin, so it just applies the user policy.

I guess the question is, since we kind of already know that we are going to want it, should we also be adding a way to mark individual collections as "permitted for download". Maybe a follow-on ticket because that requires a little bit of additional design and planning.

That would certainly create more possibilities. I guess that would mean "overcome lack of download permission for admin/non-admin users alike"? Maybe that flag could only be set by admin users, and only if admin=true in the webdav download config? And it wouldn't apply to keepproxy since it doesn't know which collection is being operated on?

Meanwhile, above you were suggesting adding users/current to the sharing token scope. We seem to vehemently agree that would change the meaning of admin=true,user=false from "less useful" version B to "more surprising" version A. Does the follow-on ticket comment mean we are sticking with the "less useful" version? That sounds safer to me. I just wasn't sure what you meant by "functionally this is actually a little bit of a problem" -- little enough to accept for now?

If we're on the same page here, the code LGTM.

The doc reference to sharing links says "because the downloader is anonymous," but it's really because the sharing token is anonymous (can't read users/current), not the downloader. I'm not sure anyone but us would appreciate the difference though.

Also, it describes extracting the token from the sharing link and passing it to arv-get, but the same thing applies to WebDAV, i.e., using a sharing link the usual way, right? Do we need another version of this comment in the WebDAV permission section? (Or am I just not seeing it?)

Just noticed "...the case where restricted data sets are shared users" is missing the word "with"

• 17464-download-logging was an early version (mentioned in note-11 and note-13)
• 17464-fix-missing-locks is 17464-download-logging plus a fix for the sdk/go/arvados locking issue which has since been merged... so I deleted this branch
• 17464-keepproxy-logging-perms (699ddfc7e) is 17464-download-logging plus 2 more commits
• 17464-download-activity starts from a rebased version (a271aaf8e) of 17464-keepproxy-logging-perms (in order to pick up the missing-locks commit), and this is the only branch we're contemplating merging, currently at 47e278f42

Tom Clegg wrote:

That would certainly create more possibilities. I guess that would mean "overcome lack of download permission for admin/non-admin users alike"? Maybe that flag could only be set by admin users, and only if admin=true in the webdav download config? And it wouldn't apply to keepproxy since it doesn't know which collection is being operated on?

Meanwhile, above you were suggesting adding users/current to the sharing token scope. We seem to vehemently agree that would change the meaning of admin=true,user=false from "less useful" version B to "more surprising" version A. Does the follow-on ticket comment mean we are sticking with the "less useful" version? That sounds safer to me.

I just wasn't sure what you meant by "functionally this is actually a little bit of a problem" -- little enough to accept for now?

I just meant that if we maintain the current behavior, we can't use that as way to release results. But it would be better anyway to have a separate, explicit feature to grant download permission to an individual user.

If we're on the same page here, the code LGTM.

Yes, we are. Thanks.

The doc reference to sharing links says "because the downloader is anonymous," but it's really because the sharing token is anonymous (can't read users/current), not the downloader. I'm not sure anyone but us would appreciate the difference though.

Well, I meant anonymous in the sense that normally we can assume that the user of the token is the entity/account it was issued to, but for special-purpose sharing tokens we have no way of knowing who is using it.

Also, it describes extracting the token from the sharing link and passing it to arv-get, but the same thing applies to WebDAV, i.e., using a sharing link the usual way, right? Do we need another version of this comment in the WebDAV permission section? (Or am I just not seeing it?)

I'll check.

Just noticed "...the case where restricted data sets are shared users" is missing the word "with"

Will fix.