search

keybase / client

Keybase Go Library, Client, Service, OS X, iOS, Android, Electron
BSD 3-Clause "New" or "Revised" License
8.92k stars 1.23k forks source link

Keybase error when dragging files into private shared folder #4825

Open juicetoon opened 8 years ago

juicetoon commented 8 years ago

Keybase GUI Version: 1.0.17-20161024112838+4d

image cf351

strib commented 8 years ago

Hi @juicetoon -- could you please run keybase log send from the Keybase command prompt and post the resulting log ID here? Thanks!

juicetoon commented 8 years ago

Hi Jeremy - the log ID is a3af385e1dd632d4456671c

On 10 November 2016 at 17:07, Jeremy Stribling notifications@github.com wrote:

Hi @juicetoon https://github.com/juicetoon -- could you please run keybase log send from the Keybase command prompt and post the resulting log ID here? Thanks!

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/keybase/client/issues/4825#issuecomment-259609314, or mute the thread https://github.com/notifications/unsubscribe-auth/AIgMahXqaFxy48NZr3zBs7_x0oIujQ2Bks5q8rS-gaJpZM4KuTLi .

cjb commented 8 years ago

CC @zanderz @taruti

strib commented 8 years ago

The real log ID is a3af385e1dd632d445667f1c -- the one above is somehow missing a character.

strib commented 8 years ago

I see two different sources for errors in the log, and I'm not sure which one you're reporting here.

The first is that it seems KBFS is struggling to upload a 300MB file to our servers without a certain timeout, even on the lowest bandwidth setting. I think either your network connection or your CPU is the bottleneck. The good news is we are currently testing fixes for this to make KBFS less reliant on the network connection and CPU performance. In the meantime, maybe try again? Sorry for the inconvenience.

The second is a timeout while trying to verify a user's identity while you were looking at a public folder. It looks a little weird to me since the timeout occurs after only a second, whereas the KBFS timeout on Windows should be 29 seconds.

@patrickxb @maxtaco: this occurs in the service log of a3af385e1dd632d445667f1c:

31703 2016-11-10T19:37:33.704177 - [DEBU keybase notify_router.go:269] 5d00 FS activity: {true context deadline exceeded 2 3 4 map[tlf:XXX mode:read] 0}

(username redacted for privacy)

Is this "deadline exceeded" error coming from a deadline set by the service? I assume so, since I don't think the KBFS deadline is transferred via RPC. Is the deadline intentionally so short? I recall something about canceling identifies quickly and retrying them, but in that case the error shouldn't be transferred back to KBFS right? KBFS sees a "deadline exceeded" just after it appears in the service log:

2016-11-10T19:37:32.887014 - [DEBU kbfs(FBO 7f4f5b66) folder_branch_ops.go:837] 257d Running identifies on /keybase/public/XXX [tags:DID=7SW5GwLTF2C98F-mv5SYSw]
2016-11-10T19:37:33.704177 - [DEBU kbfs(FBO 7f4f5b66) folder_branch_ops.go:1322] 257e Done: context deadline exceeded [tags:DID=7SW5GwLTF2C98F-mv5SYSw]
2016-11-10T19:37:33.704177 - [DEBU kbfs kbfs_ops.go:402] 2580 Done: context.deadlineExceededError{} [tags:DID=7SW5GwLTF2C98F-mv5SYSw]
2016-11-10T19:37:33.704177 - [DEBU kbfs(FBO 7f4f5b66) folder_branch_ops.go:841] 257f Identify finished with error: context deadline exceeded [tags:DID=7SW5GwLTF2C98F-mv5SYSw]
2016-11-10T19:37:33.704177 - [DEBU kbfs dir.go:131] 2581 context deadline exceeded [tags:DID=7SW5GwLTF2C98F-mv5SYSw]
strib commented 8 years ago

@patrickxb @maxtaco: d'oh, I just realized that the service log I'm citing is a notification for FS activity -- i.e., it's coming in from KBFS. So the timeout must be happening there.

@songgao: there is a weird one-second deadline happening during an identify call, when it really should be 29 seconds. I wonder if this is related to the delayed cancellation stuff?

songgao commented 8 years ago

@strib If you search for "/keybase/public/XXX", the getMaybeCreateRootNode is called 29 seconds ago before the context is canceled. It looks like it's indeed the 29 timeout that kicked in?

strib commented 8 years ago

@songgao: d'oh you are right, thanks. Don't know how I missed that.

So, this does seem to be another instance of identifies of a certain well-known user taking a long time. @patrickxb @maxtaco, starting at 2016-11-10T19:37:04.702367 in the log mentioned above.

maxtaco commented 8 years ago

Network calls in this trace are going extremely slowly:

31362 2016-11-10T19:37:20.649230 - [DEBU keybase notify_router.go:269] 5bab FS activity: { XXX }
31363 2016-11-10T19:37:32.335932 - [DEBU keybase api.go:644] 5bac - API call sig/get success

And:

31923 2016-11-10T19:37:37.177651 - [DEBU keybase identify2_with_uid.go:306] 5ddc - CheckCompleted
31924 2016-11-10T19:37:44.037705 - [DEBU keybase api.go:196] 5ddd | doRequestShared(Done) for XXXXX some web site

Not much that can be done. Since presumably the user is being tracked, all components have to be checked. Is KBFS using a lot of bandwidth here BTW in another TLF?

strib commented 8 years ago

@maxtaco: QR was happening but that shouldn't be bandwidth-intensive. Ok, guess there's not much else to do here for now.

taruti commented 8 years ago

Looks like timeouts unfortunately.

We should degrade better when there is not enough network speed.