fix webui log hanging bug #1914

whyrusleeping · 2015-10-30T07:25:41Z

the webui can currently cause the entire daemon to deadlock because the writer set up when it queries the log endpoints is never closed (and will hang on writes). This causes all the calls to any log function to hang and subsequently deadlocks the daemon.

I beleive this is the root cause of 1896, and after this PR, I am unable to repro by messing around via the webui.

Interestingly, i was never able to get a repro via curl... only in-browser.

whyrusleeping · 2015-10-30T07:57:04Z

In debugging this issue i ended up cleaning up a bunch more logging things, everything is just a little bit nicer now (flatfs was importing its own separate instance of go-log, that was making weirdness)

daviddias · 2015-10-30T08:01:06Z

When doing go install ./cmd/ipfs, I'm getting this:

│vendor/QmZUcdoz4Afhc5vr3LEoPHxr1wwZfjBxxjWx2oMmfChG9W/go-log/metadata.go:8:2: cannot find package "github.com/satori/go.uuid" in any of:
                                                                                                                                                               │        /usr/local/go/src/github.com/satori/go.uuid (from $GOROOT)
                                                                                                                                                               │        /Users/david/Documents/Code/go-projects/src/github.com/satori/go.uuid (from $GOPATH)
                                                                                                                                                               │vendor/QmZUcdoz4Afhc5vr3LEoPHxr1wwZfjBxxjWx2oMmfChG9W/go-log/oldlog.go:8:2: cannot find package "github.com/whyrusleeping/go-logging" in any of:
                                                                                                                                                               │        /usr/local/go/src/github.com/whyrusleeping/go-logging (from $GOROOT)
                                                                                                                                                               │        /Users/david/Documents/Code/go-projects/src/github.com/whyrusleeping/go-logging (from $GOPATH)

go get doesn't solve it, thoughts?

whyrusleeping · 2015-10-30T08:05:43Z

@diasdavid my bad, tired brain forgot to vendor correctly.

daviddias · 2015-10-30T08:11:00Z

thank you @whyrusleeping :)

so, 1st thing I noticed were these logs when I opened the webui:

08:08:02.161 ERROR     flatfs: too many open files, retrying in %dms0 flatfs.go:119
08:08:02.161 ERROR     flatfs: too many open files, retrying in %dms100 flatfs.go:119
08:08:02.263 ERROR     flatfs: too many open files, retrying in %dms200 flatfs.go:119
08:08:03.562 ERROR core/serve: Path Resolve error: no link named "fontawesome-webfont.woff2" under QmWjympWW8hpP5Jgfu66ZrqTMykUBjGbFQF2XgfChau5NZ gateway_handler.go:479
08:08:03.782 ERROR     flatfs: too many open files, retrying in %dms0 flatfs.go:119
08:08:03.782 ERROR     flatfs: too many open files, retrying in %dms100 flatfs.go:119

daviddias · 2015-10-30T08:33:47Z

Been testing with js-ipfs-api latest and very happy with the results, because it works again :) (0.3.8 made the response parser go nuts)

whyrusleeping · 2015-10-30T16:43:23Z

@diasdavid yeah, i notice that when on osx as well. its that darn 256 fd limit. Nothing bad should actually be happening though, you'll see an uglier error if it does.

jbenet · 2015-10-31T00:58:15Z

@whyrusleeping the new webui with logging disabled is:

/ipfs/QmR9MzChjp1MdFWik7NjEjqKQMzVmBkdK3dz14A6B5Cupm

cryptix · 2015-11-03T18:07:32Z

commands/http/handler.go

+			case <-cn.CloseNotify():
+			case <-ctx.Done():
+			}
+			cancel()


is it okay to cancel a context twice?

perfectly fine :)

whyrusleeping · 2015-11-05T06:26:43Z

looks like circleCI was trying to run fuse tests? thats weird

License: MIT Signed-off-by: Jeromy <jeromyj@gmail.com>

jbenet · 2015-11-08T15:17:00Z

@whyrusleeping this LGTM.

that one test failed many times. hangs, or this:

not ok 19 - 'ipfs daemon' should be able to run with a pipe attached to stdin (issue #861)
#   
#     yes | ipfs daemon --init >stdin_daemon_out 2>stdin_daemon_err &
#     pollEndpoint -ep=/version -v -tout=1s -tries=10 >stdin_poll_apiout 2>stdin_poll_apierr &&
#     test_kill_repeat_10_sec $! ||
#     test_fsh cat stdin_daemon_out || test_fsh cat stdin_daemon_err || test_fsh cat stdin_poll_apiout || test_fsh cat stdin_poll_apierr
#

https://travis-ci.org/ipfs/go-ipfs/jobs/89554589

jbenet · 2015-11-08T15:22:47Z

@whyrusleeping worried these tests failures (hangs!) are related to this PR. cant get things to pass, and even on the off chance it does now, i dont have confidence on it.

i'll give it a few hours for travis to shake up, then rerun everything a few times

whyrusleeping · 2015-11-08T19:34:22Z

i'm seeing similar tests failing (the stdin pipe one) on other PRs. While thats not a good thing, i'm slightly more confident that its not this PRs fault

whyrusleeping · 2015-11-08T20:01:52Z

@jbenet clean tests (minus the attached stdin one that i'm seeing elsewhere as well)

whyrusleeping · 2015-11-08T20:54:00Z

the stdin faiure appears to just be caused by the daemon taking a little longer to startup now (not sure why that is), locally, it takes four or five seconds to startup the daemon. The test is set to fail it after ten seconds, a particularly slow and stressed travis CI machine will likely hit this with some frequency

whyrusleeping · 2015-11-08T20:56:20Z

Actually, thinking about it a bit more. That test bootstraps to our bootstrap nodes, they have been really slow lately (@lgierth mentioned they havent been rebooted in a while). These failures are very likely a result of bootstrapping taking way longer than usual.

jbenet · 2015-11-08T22:17:59Z

until we are satisfied with ipfs's reliability at long periods we should continue periodically rebooting the nodes. it's a service people depend on.

jbenet · 2015-11-08T22:19:17Z

we should get to the bottom of these tests failing before merging anything else. either it's a problem that snuck in, or its a service problem that needs to be fixed.

jbenet · 2015-11-08T23:50:26Z

ok looks good now

fix webui log hanging bug

whyrusleeping · 2015-11-08T23:55:33Z

@jbenet in the future, could you just say "RFM" or something and let me rebase and merge it in so we can get a straight line of history?

jbenet · 2015-11-09T00:00:37Z

Sure. Feel free to fix it and force push to master

—
Sent from Mailbox

On Sun, Nov 8, 2015 at 11:55 PM, Jeromy Johnson notifications@github.com
wrote:

@jbenet in the future, could you just say "RFM" or something and let me rebase and merge it in so we can get a straight line of history?

Reply to this email directly or view it on GitHub:
#1914 (comment)

jbenet · 2015-11-09T00:01:01Z

Just drop the heads here for reference

—
Sent from Mailbox

On Mon, Nov 9, 2015 at 12:00 AM, Juan Batiz-Benet juan@benet.ai wrote:

Sure. Feel free to fix it and force push to master
—
Sent from Mailbox
On Sun, Nov 8, 2015 at 11:55 PM, Jeromy Johnson notifications@github.com
wrote:

@jbenet in the future, could you just say "RFM" or something and let me rebase and merge it in so we can get a straight line of history?

Reply to this email directly or view it on GitHub:
#1914 (comment)

whyrusleeping · 2015-11-09T00:34:55Z

Can just do it for future PR's. force pushing to master is very scary for many reasons other than just "i might screw something up"

jbenet added the status/in-progress In progress label Oct 30, 2015

whyrusleeping added kind/bug A bug in existing code (including security flaws) RFCR and removed status/in-progress In progress labels Oct 30, 2015

whyrusleeping force-pushed the fix/log-hang branch from 54dce63 to f21fe5c Compare October 30, 2015 08:05

whyrusleeping force-pushed the fix/log-hang branch from f21fe5c to 3727f48 Compare October 30, 2015 18:36

whyrusleeping force-pushed the fix/log-hang branch from 3727f48 to ce81fb4 Compare November 3, 2015 18:00

cryptix reviewed Nov 3, 2015
View reviewed changes

whyrusleeping force-pushed the fix/log-hang branch 4 times, most recently from 823df45 to c5b133a Compare November 5, 2015 03:44

whyrusleeping force-pushed the fix/log-hang branch from c5b133a to f87f3d6 Compare November 5, 2015 22:39

whyrusleeping added 2 commits November 5, 2015 15:57

vendor logging lib update

94bdce6

License: MIT Signed-off-by: Jeromy <jeromyj@gmail.com>

fix log hanging issue, and implement close-notify for commands

2f5563b

License: MIT Signed-off-by: Jeromy <jeromyj@gmail.com>

whyrusleeping force-pushed the fix/log-hang branch from f87f3d6 to 2f5563b Compare November 5, 2015 23:59

jbenet added a commit that referenced this pull request Nov 8, 2015

Merge pull request #1914 from ipfs/fix/log-hang

0b3e037

fix webui log hanging bug

jbenet merged commit 0b3e037 into master Nov 8, 2015

jbenet deleted the fix/log-hang branch November 8, 2015 23:50

rht mentioned this pull request Dec 17, 2015

Make master green again! #2002

Closed

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix webui log hanging bug #1914

fix webui log hanging bug #1914

whyrusleeping commented Oct 30, 2015

whyrusleeping commented Oct 30, 2015

daviddias commented Oct 30, 2015

whyrusleeping commented Oct 30, 2015

daviddias commented Oct 30, 2015

daviddias commented Oct 30, 2015

whyrusleeping commented Oct 30, 2015

jbenet commented Oct 31, 2015

cryptix Nov 3, 2015

whyrusleeping Nov 3, 2015

whyrusleeping commented Nov 5, 2015

jbenet commented Nov 8, 2015

jbenet commented Nov 8, 2015

whyrusleeping commented Nov 8, 2015

whyrusleeping commented Nov 8, 2015

whyrusleeping commented Nov 8, 2015

whyrusleeping commented Nov 8, 2015

jbenet commented Nov 8, 2015

jbenet commented Nov 8, 2015

jbenet commented Nov 8, 2015

whyrusleeping commented Nov 8, 2015

jbenet commented Nov 9, 2015

@jbenet in the future, could you just say "RFM" or something and let me rebase and merge it in so we can get a straight line of history?

jbenet commented Nov 9, 2015

@jbenet in the future, could you just say "RFM" or something and let me rebase and merge it in so we can get a straight line of history?

whyrusleeping commented Nov 9, 2015

fix webui log hanging bug #1914

fix webui log hanging bug #1914

Conversation

whyrusleeping commented Oct 30, 2015

whyrusleeping commented Oct 30, 2015

daviddias commented Oct 30, 2015

whyrusleeping commented Oct 30, 2015

daviddias commented Oct 30, 2015

daviddias commented Oct 30, 2015

whyrusleeping commented Oct 30, 2015

jbenet commented Oct 31, 2015

cryptix Nov 3, 2015

Choose a reason for hiding this comment

whyrusleeping Nov 3, 2015

Choose a reason for hiding this comment

whyrusleeping commented Nov 5, 2015

jbenet commented Nov 8, 2015

jbenet commented Nov 8, 2015

whyrusleeping commented Nov 8, 2015

whyrusleeping commented Nov 8, 2015

whyrusleeping commented Nov 8, 2015

whyrusleeping commented Nov 8, 2015

jbenet commented Nov 8, 2015

jbenet commented Nov 8, 2015

jbenet commented Nov 8, 2015

whyrusleeping commented Nov 8, 2015

jbenet commented Nov 9, 2015

@jbenet in the future, could you just say "RFM" or something and let me rebase and merge it in so we can get a straight line of history?

jbenet commented Nov 9, 2015

@jbenet in the future, could you just say "RFM" or something and let me rebase and merge it in so we can get a straight line of history?

whyrusleeping commented Nov 9, 2015