search

burke / zeus

Boot any rails app in under a second.
MIT License
3.33k stars 231 forks source link

slavenode.go:215: [test_helper] read unix ->: EOF #617

Closed typeoneerror closed 7 years ago

typeoneerror commented 7 years ago

zeus start produces this error after upgrading to 0.15.12.

slavenode.go:215: [test_helper] read unix ->: EOF
typeoneerror commented 7 years ago

Went ahead and blasted my gemset and reinstalled all gems and seems to work now. Must've been a temporary fail.

sideshowcoder commented 7 years ago

Might be a dependency interaction, I had the same some time ago with an earlier version.

mmcnl commented 7 years ago

I'm still experiencing this issue, on both ruby-2.3.3 and 2.4.0.

sideshowcoder commented 7 years ago

Ugh thats not good have you tried removing and reinstalling the zeus gem?

mmcnl commented 7 years ago

Hmm, I could have sworn I tried that but indeed gem uninstall zeus followed by a reinstall has allowed it to work. The previous issue had occurred in multiple ruby envs as well as with the previous version of zeus (I tried installing this in case the current issue was due to a recent regression). I'll let you know if it shows up again. Thanks for the help!

sideshowcoder commented 7 years ago

Sorry for that I would really like to know what is going on but can't think of a way to debug... Thanks for your quick feedback.

kenn commented 7 years ago

I'm also seeing this, some time after upgraded to 0.15.13.pre:

slavenode.go:215: [test_environment] read unix ->: EOF
slavenode.go:215: [development_environment] read unix ->: EOF

and remove / reinstall gem does not help, so I'm kinda stuck here. Oddly enough, zeus still works for another project, so there seems to be project-specific persistent state somewhere.

kenn commented 7 years ago

Oops sorry, it occurred when there's an error in an initializer where ERB evaluation fails due to a stupid syntax error in a yml file.

# config.yml
key: <%= key: value %> # <= syntax error

# syntax error, unexpected tLABEL (SyntaxError)
ERB.new(config.read).result

Sorry for confusion.

sideshowcoder commented 7 years ago

Yeah I think it's one of the cases for #555 to be honest, it should be clearer in what is actually going wrong...

blimmer commented 7 years ago

@kenn how did you identify what file was the problem? I'm getting this same error message but don't know what's wrong

sideshowcoder commented 7 years ago

@blimmer have you tried to run the command without zeus?

kenn commented 7 years ago

@blimmer run without zeus, and confirm the issue is not related to zeus. Problems vary, but that's a start 😉

blimmer commented 7 years ago

I can run bundle exec rspec and just rspec and my test suite runs with no problems. This issue only occurs when I try to run it with zeus.

zeus test (alias: rspec) [run to see backtrace]
slavenode.go:215: [test_helper] read unix ->: EOF

When I run zeus test in another tab it still just gives me the read unix ->: EOF message.

blimmer commented 7 years ago

Does anyone know how to get more information about this error? cc @sideshowcoder

I've finally figured out how to clone this, build the app, but it seems like Go only exposes the err.Error() string, so I can't figure out how to get more information (like a stacktrace) from the error.

I was hoping that a panic could help, but no dice:

panic: read unix ->: EOF

goroutine 22 [running]:
panic(0x412f380, 0xc4204b2050)
        /usr/local/Cellar/go/1.7.5/libexec/src/runtime/panic.go:500 +0x1a1
github.com/burke/zeus/go/processtree.(*SlaveNode).doBootingState(0xc420010380, 0x0, 0x0)
        /usr/local/golang/src/github.com/burke/zeus/go/processtree/slavenode.go:215 +0x413
github.com/burke/zeus/go/processtree.(*SlaveNode).Run(0xc420010380, 0xc420114000)
        /usr/local/golang/src/github.com/burke/zeus/go/processtree/slavenode.go:146 +0x26e
created by github.com/burke/zeus/go/processtree.StartSlaveMonitor.func1
        /usr/local/golang/src/github.com/burke/zeus/go/processtree/slavemonitor.go:53 +0x1cc

It really seems like there has to be a way to get even just a little more information about this issue, but I don't really know any golang 😞

also, this is the log I get if I ask zeus to give me more info:

2017/02/24 15:34:41.478296 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:142] test_helper/(no PID) entering state SUnbooted
2017/02/24 15:34:41.478566 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:142] default_bundle/(no PID) entering state SUnbooted
2017/02/24 15:34:41.478620 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:142] boot/(no PID) entering state SUnbooted
2017/02/24 15:34:41.478635 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:142] development_environment/(no PID) entering state SUnbooted
2017/02/24 15:34:41.478664 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:142] prerake/(no PID) entering state SUnbooted
2017/02/24 15:34:41.478717 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:142] test_environment/(no PID) entering state SUnbooted
2017/02/24 15:34:41.479335 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:380] boot/(no PID) running the root command now
2017/02/24 15:34:41.623468 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:128] boot/(77840) initialized slave boot with pid 77840 from parent 0
2017/02/24 15:34:41.623496 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:145] boot/(77840) entering state SBooting
2017/02/24 15:34:44.422590 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:220] boot/(77840) received action message
2017/02/24 15:34:44.422616 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:148] boot/(77840) entering state SReady
2017/02/24 15:34:44.422631 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:328] boot/(77840) now sending slave boot request for default_bundle
2017/02/24 15:34:44.425115 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:128] default_bundle/(77842) initialized slave default_bundle with pid 77842 from parent 77840
2017/02/24 15:34:44.425162 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:145] default_bundle/(77842) entering state SBooting
2017/02/24 15:34:51.099618 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:220] default_bundle/(77842) received action message
2017/02/24 15:34:51.099713 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:148] default_bundle/(77842) entering state SReady
2017/02/24 15:34:51.099730 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:328] default_bundle/(77842) now sending slave boot request for development_environment
2017/02/24 15:34:51.099748 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:328] default_bundle/(77842) now sending slave boot request for test_environment
2017/02/24 15:34:51.103224 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:128] test_environment/(77850) initialized slave test_environment with pid 77850 from parent 77842
2017/02/24 15:34:51.103226 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:128] development_environment/(77849) initialized slave development_environment with pid 77849 from parent 77842
2017/02/24 15:34:51.103271 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:145] development_environment/(77849) entering state SBooting
2017/02/24 15:34:51.103318 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:145] test_environment/(77850) entering state SBooting
2017/02/24 15:35:05.378814 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:220] test_environment/(77850) received action message
2017/02/24 15:35:05.378847 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:148] test_environment/(77850) entering state SReady
2017/02/24 15:35:05.378857 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:328] test_environment/(77850) now sending slave boot request for test_helper
2017/02/24 15:35:05.383167 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:128] test_helper/(77856) initialized slave test_helper with pid 77856 from parent 77850
2017/02/24 15:35:05.383190 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:145] test_helper/(77856) entering state SBooting
2017/02/24 15:35:06.103102 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:220] development_environment/(77849) received action message
2017/02/24 15:35:06.103127 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:148] development_environment/(77849) entering state SReady
2017/02/24 15:35:06.103138 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:328] development_environment/(77849) now sending slave boot request for prerake
2017/02/24 15:35:06.108546 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:128] prerake/(77857) initialized slave prerake with pid 77857 from parent 77849
2017/02/24 15:35:06.108579 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:145] prerake/(77857) entering state SBooting
2017/02/24 15:35:06.298363 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:220] prerake/(77857) received action message
2017/02/24 15:35:06.298390 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:148] prerake/(77857) entering state SReady
2017/02/24 15:35:06.367293 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:151] test_helper/(77856) entering state SCrashed
sideshowcoder commented 7 years ago

@blimmer yeah I've been looking into this as well, one option would maybe be to try using a debugger, maybe https://github.com/derekparker/delve/ would do the trick. Sadly / luckily I don't have a project which experiences this, but I would really hope to be able to improve the error messages as well.

blimmer commented 7 years ago

My current process for testing this out to is clone the repo, run make && make install and then test in my repo - would something like delve work with this workflow?

The other crazy part about all of this is that the issue only exhibits itself (on the exact same codebase / macOS latest / etc) for some people on my team, not everyone.

sideshowcoder commented 7 years ago

Oh that sounds like its gonna be fun to debug... But yes delve should be able to help there see https://github.com/derekparker/delve/blob/master/Documentation/usage/dlv_attach.md for attaching to a running process

seyonv commented 7 years ago

@blimmer I was having problems with this too but got it working . Gem uninstalls and reinstalls ended up making it work. It does not work when running $bundle exec zeus start, but it does work when running $zeus start.

Something to note is that when I run

$zeus --log/dev/stderr start it still gives the following messages

2017/03/07 11:18:04.055498 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:142] test_helper/(no PID) entering state SUnbooted
2017/03/07 11:18:04.055511 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:142] default_bundle/(no PID) entering state SUnbooted
2017/03/07 11:18:04.055513 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:142] boot/(no PID) entering state SUnbooted
2017/03/07 11:18:04.055514 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:142] test_environment/(no PID) entering state SUnbooted
2017/03/07 11:18:04.055517 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:142] development_environment/(no PID) entering state SUnbooted
2017/03/07 11:18:04.056168 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:380] boot/(no PID) running the root command now
2017/03/07 11:18:04.055521 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:142] prerake/(no PID) entering state SUnbooted
sideshowcoder commented 7 years ago

@seyonv those messages look fine to me actually they are the trace log right?

seyonv commented 7 years ago

Yeah they're fine, shouldn't have mentioned them. Broader point is bundler causing failure and uninstalling, reinstalling different gems helped. As mentioned elsewhere, I believe the wrong versions of method_source and json were causing problems.

sideshowcoder commented 7 years ago

Cool sorry for the confusion :+1: yes this seems to help and I've seen it before as well, I got no idea why so :panda_face:

blimmer commented 7 years ago

I "fixed" this on my machine by running gem pristine --all. It's definitely weird and I don't know exactly what upstream gem caused the problem.

tanmayforgit commented 7 years ago

In my case it was caused by these two lines in spec_helper

require 'database_cleaner' require 'capybara/poltergeist'

I am using ruby 2.4 with Rails 5.0.1

sideshowcoder commented 7 years ago

@tanmayforgit how did you resolve it?

kriskhaira commented 7 years ago

Had a similar error today while running zeus start.

slavenode.go:215: [boot] read unix ->: EOF

Updating zeus from 0.15.10 to 0.15.13 fixes it. Not sure if it was the upgrade or simply a reinstall that fixed it. Could've been a conflict with a gem or Go library added to my system recently.

Environment

screen shot 2017-04-19 at 12 09 30 pm
AlanRuijia commented 7 years ago

In my case, updating bundler from 1.13.7 to 1.14.6 helps.

em77 commented 7 years ago

Running gem pristine --all worked for me.

dmcinnes commented 7 years ago

I ran into this issue as well though my error message is on a different line number, and the "boot" step was green:

slavenode.go:226: [bundler] read unix ->: EOF

Uninstalling/reinstalling didn't work, neither did gem pristine --all.

What did work was installing the previous version 0.15.13, so seems like the issue was experiencing was introduced with 0.15.14 (at least what I'm experiencing).

I'm running Ruby 2.4.1p111, if that helps.

sideshowcoder commented 7 years ago

Interesting @dmcinnes have you uninstalled all versions before installing 0.15.14?

dmcinnes commented 7 years ago

I believe it was the only version I had since I was on a new Ruby install through rbenv. It's the only one I have now in any case:

$ gem list zeus --all

*** LOCAL GEMS ***

zeus (0.15.13)
leods92 commented 7 years ago

Had the same experience @dmcinnes had:

Uninstalling/reinstalling didn't work, neither did gem pristine --all.

What did work was installing the previous version 0.15.13, so seems like the issue was experiencing was introduced with 0.15.14 (at least what I'm experiencing).

mvalipour commented 7 years ago

I had this issue in several occasions and it when I tried to run a standard bundle exec I noticed I need to do a bundle install. After doing so zeus start is back to normal.

@sideshowcoder should zeus have a friendly error asking for bundle install to avoid confusion?

sideshowcoder commented 7 years ago

That would be great @mvalipour

gitconfig commented 7 years ago

bundle update zeus (to 0.15.14) had introduced the problem.

So,

gem uninstall zeus

Select gem to uninstall:
 1. zeus-0.15.13
 2. zeus-0.15.14
 3. All versions
> 2
Successfully uninstalled zeus-0.15.14

And it works now.

hraynaud commented 7 years ago

This worked for me as well. Going back to 0.15.3 resolved the problem.

kigster commented 7 years ago

Confirming the same issue/solution worked for me on Ruby 2.2.3.

jmgarnier commented 7 years ago

I had the same problem with ruby 2.4.1 on a Rails 4.2.9 app with zeus 0.15.14.

slavenode.go:226: [boot] read unix ->: EOF
exit status 1

Running zeus --log ./zeus.log start and then cat zeus.log, I found out the cause:

You have already activated byebug `9.1.0`, but your Gemfile requires byebug `9.0.6`

Full Stacktrace:

``` 2017/09/11 14:56:13.643652 [/Users/phil/Source/go/src/github.com/burke/zeus/go/processtree/slavenode.go:402] boot/(63200) root process exited with an error before it could boot: exit status 1; output was: .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/runtime.rb:317:in `check_for_activated_spec!': You have already activated byebug 9.1.0, but your Gemfile requires byebug 9.0.6. Prepending `bundle exec` to your command may solve this. (Gem::LoadError) from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/runtime.rb:32:in `block in setup' from .rbenv/versions/2.4.1/lib/ruby/2.4.0/forwardable.rb:229:in `each' from .rbenv/versions/2.4.1/lib/ruby/2.4.0/forwardable.rb:229:in `each' from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/runtime.rb:27:in `map' from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/runtime.rb:27:in `setup' from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler.rb:101:in `setup' from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/setup.rb:9:in `' from .rbenv/versions/2.4.1/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:133:in `require' from .rbenv/versions/2.4.1/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:133:in `rescue in require' from .rbenv/versions/2.4.1/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:40:in `require' from src/nedap/dossier/config/boot.rb:8:in `' from .rbenv/versions/2.4.1/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require' from .rbenv/versions/2.4.1/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require' from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/zeus-0.15.14/lib/zeus/rails.rb:82:in `boot' from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/zeus-0.15.14/lib/zeus.rb:204:in `block in run_action' from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/zeus-0.15.14/lib/zeus/load_tracking.rb:18:in `track_features_loaded_by' from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/zeus-0.15.14/lib/zeus.rb:202:in `run_action' from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/zeus-0.15.14/lib/zeus.rb:75:in `block in boot_steps' from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/zeus-0.15.14/lib/zeus.rb:57:in `catch' from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/zeus-0.15.14/lib/zeus.rb:57:in `boot_steps' from .rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/zeus-0.15.14/lib/zeus.rb:49:in `go' from -e:1:in `
' ```

Upgrading byebug to 9.1.0 solved the problem. I am thinking to coming back to rvm gemsets to prevent that kind of problem in the future.

Pristine all your gems sounds like a temporary fix.

joelvh commented 7 years ago

Zeus has been great, and I saw a note somewhere that we shouldn't prefix the commands with bundle exec. This issue seems to stem from not isolating the gems the command can load. Any reason this can't be updated to utilize bundle exec?

sfahlberg commented 7 years ago

yeah, this is really annoying. Would be nice if zeus could have this fixed internally so everybody doesn't have to pristine the gems. Didn't work for me though. Still having trouble

kigster commented 7 years ago

Hey, guys — I have spent a few days setting up Zeus in our dev environment, and I ended up learning a lot about what to expect when various weird things happen. The good news is that I think I've been able to resolve majority of our initial issues with Zeus, so let me walk through some use cases and what I've found, perhaps it will be helpful to somebody.

NOTE that Zeus 0.15.14 started to work on High Sierra, but was broken on Sierra.

My setup:

Since Zeus is not supposed to be in your Gemfile, you are expected to install it separately. In the environments that Zeus boots, Bundler is initialized and used to load all bundled dependencies. A problem arises when Zeus code (or custom commands) use require and load some gems before bundler setup. In particular, if you have a version mismatch between what's installed as "gem install" and what's in your Gemfile.lock.

Crashes

We also experienced a bunch of SEGV crashes, that I was able to trace to the following gems. Each was exploding in a different place.

With these cleaned up, Zeus appears very stable.

Hope this helps!

typeoneerror commented 7 years ago

@kigster awesome detective work! of all your SEGV xp's, I have faker, so I'll see if your fix works. It appears faker was aware of the issue; looks like a ruby bug... https://github.com/stympy/faker/issues/982#issuecomment-328192861

jmgarnier commented 7 years ago

@kigster What was your workflow to trace SEGV crashes? With zeus --log ?

AnwarShah commented 7 years ago

I experienced the same problem on Fedora 26 today. Though it was working on my Ubuntu. I just removed the Gemfile.lock file and used bundle install. It fixed the problem

dmcinnes commented 7 years ago

I'm now getting failures on 0.15.13 as well 😞 and I'm not sure what changed. slavenode.go:215: [bundler] read unix ->: EOF on 0.15.13 and slavenode.go:226: [bundler] read unix ->: EOF on v0.15.14.

We're now on Ruby 2.4.2 for over a month (still on rbenv) and Bundler version 1.15.4.

dmcinnes commented 7 years ago

Possibly related change: I'm on OS X Sierra and yesterday I had updated Xcode and command line tools to Version 9.0.1 and 9.0 respectively...

kigster commented 7 years ago

My workflow with SEGV is rather simple:

Look at the 5-7K lines of a stacktrace (make sure to set iterm2 screen history to unlimited), and find the first 100 or so lines. It the top of this stack will invariably be one of the gems I listed. If I see a new stack with no listed gems, I’d try to see the last few stacks: typically it’s a gem doing something via a native extension C callback.

However, segv is a good problem to have: you know when you have one. But I’ve also seen Zeus not start and almost nothing in any logs.

In that case I would try to run by hand a non-Zeus command, for example “rails console” instead of “Zeus console”: most of the time it explodes somewhere until fixed. When ruby VM that Zeus boots up throws parsing errors, there will be very little info why Zeus fails to start. So just manually start a new vm and hopefully you will see some errors.

HTH

kliffy commented 7 years ago

Also getting the same exact problem as @dmcinnes. Had to reformat the other day. None of these solutions seem to apply to me in getting zeus to work.

On High Sierra with ruby 2.1.1

strickinato commented 6 years ago

I was getting slavenode.go:226: [bundler] read unix ->: EOF

AnwarShahs solution worked for me.

I just removed the Gemfile.lock file and used bundle install. It fixed the problem

alsutton commented 6 years ago

You can set OBJC_DISABLE_INITIALIZE_FORK_SAFETY=YES as an environment variable as a workaround.

kigster commented 6 years ago

I found one additional issue that was happening to me. In my environment I use rbenv some of the time, but do not use it when I switch to chefdk ruby. So I changed the line in zeus.json that loads custom plan to the following:

{
  "command": "rbenv exec ruby -rubygems -r./lib/zeus/custom_plan.rb -eZeus.go",
}

Notice the rbenv exec ruby instead of just ruby. Maybe this will help someone else too.