Frequent but intermittent failure in specjour listen on Linux
josephlord opened this issue · 2 comments
/tmp/specjour/lib/specjour/connection.rb:46:in block in print': private methodprint' called for nil:NilClass (NoMethodError)
from /tmp/specjour/lib/specjour/connection.rb:82:in call' from /tmp/specjour/lib/specjour/connection.rb:82:inwill_reconnect'
from /tmp/specjour/lib/specjour/connection.rb:45:in print' from /tmp/specjour/lib/specjour/connection.rb:58:inblock in send_message'
from /tmp/specjour/lib/specjour/connection.rb:82:in call' from /tmp/specjour/lib/specjour/connection.rb:82:inwill_reconnect'
from /tmp/specjour/lib/specjour/connection.rb:57:in send_message' from /home/josephl/hf/specjour/specjour/lib/specjour/loader.rb:91:inregister_tests_with_printer'
from /home/josephl/hf/specjour/specjour/lib/specjour/loader.rb:86:in load_app' from /home/josephl/hf/specjour/specjour/lib/specjour/loader.rb:22:instart'
from /home/josephl/hf/specjour/specjour/lib/specjour/cli.rb:57:in load' from /home/josephl/.rvm/gems/ruby-1.9.3-p125@specjour/gems/thor-0.14.6/lib/thor/task.rb:22:inrun'
from /home/josephl/.rvm/gems/ruby-1.9.3-p125@specjour/gems/thor-0.14.6/lib/thor/invocation.rb:118:in invoke_task' from /home/josephl/.rvm/gems/ruby-1.9.3-p125@specjour/gems/thor-0.14.6/lib/thor.rb:263:indispatch'
from /home/josephl/.rvm/gems/ruby-1.9.3-p125@specjour/gems/thor-0.14.6/lib/thor/base.rb:389:in start' from /home/josephl/hf/specjour/specjour/lib/specjour/cli.rb:24:instart'
from /home/josephl/hf/specjour/specjour/bin/specjour:5:in `
I don't understand what is happening here but I am usually but not always getting failures on my Linux based test server. I tried the current Gem and have built from the git source too but it doesn't seem to make a difference. I have also tried with Firewalls disabled.
This is output below from the 'specjour listen' command on the Linux server when I sent two 'specjour spec' commands from my OS X dev laptop. 90% of the time I get the failure you see that was the result of the second 'specjour spec' command. Sometimes the failure is received 4 times (it is a 4 core machine).
With my own application I have seen cases where I get the error message but it still manages a significant number
rsync -aL --delete --ignore-errors --port=23456 192.168.1.71::specjour /tmp/specjour
rsync complete
Loading RSpec Environment
Loading Cucumber Environment
[1] Running /tmp/specjour/features/undefined.feature
[1] Finished /tmp/specjour/features/undefined.feature in 0.0235
Workers ready: 4
Listening for specjour
rsync -aL --delete --ignore-errors --port=23456 192.168.1.71::specjour /tmp/specjour
rsync complete
Loading RSpec Environment
[1] Running /tmp/specjour/spec/specjour/cli_spec.rb:37
[2] Running /tmp/specjour/spec/specjour/cli_spec.rb:61
[4] Running /tmp/specjour/spec/specjour/cli_spec.rb:76[3] Running /tmp/specjour/spec/specjour/cli_spec.rb:71
[1] Finished /tmp/specjour/spec/specjour/cli_spec.rb:37 in 0.0398
[2] Finished /tmp/specjour/spec/specjour/cli_spec.rb:61 in 0.0449
[1] Running /tmp/specjour/spec/specjour/cli_spec.rb:83
[3] Finished /tmp/specjour/spec/specjour/cli_spec.rb:71 in 0.0480
[2] Running /tmp/specjour/spec/specjour/cli_spec.rb:88
[4] Finished /tmp/specjour/spec/specjour/cli_spec.rb:76 in 0.0442
[3] Running /tmp/specjour/spec/specjour/cli_spec.rb:93
[2] Finished /tmp/specjour/spec/specjour/cli_spec.rb:88 in 0.0167
[1] Finished /tmp/specjour/spec/specjour/cli_spec.rb:83 in 0.0197
[3] Finished /tmp/specjour/spec/specjour/cli_spec.rb:93 in 0.0165
[4] Running /tmp/specjour/spec/specjour/cli_spec.rb:98
[1] Running /tmp/specjour/spec/specjour/cli_spec.rb:103
[2] Running /tmp/specjour/spec/specjour/cli_spec.rb:117[3] Running /tmp/specjour/spec/specjour/cli_spec.rb:123
[3] Finished /tmp/specjour/spec/specjour/cli_spec.rb:123 in 0.0154
[4] Finished /tmp/specjour/spec/specjour/cli_spec.rb:98 in 0.0168
[1] Finished /tmp/specjour/spec/specjour/cli_spec.rb:103 in 0.0184
[2] Finished /tmp/specjour/spec/specjour/cli_spec.rb:117 in 0.0214
[3] Running /tmp/specjour/spec/specjour/cli_spec.rb:137
[4] Running /tmp/specjour/spec/specjour/cli_spec.rb:142
[1] Running /tmp/specjour/spec/specjour/cli_spec.rb:148
[2] Running /tmp/specjour/spec/specjour/configuration_spec.rb:45
[3] Finished /tmp/specjour/spec/specjour/cli_spec.rb:137 in 0.0151
[4] Finished /tmp/specjour/spec/specjour/cli_spec.rb:142 in 0.0160
[3] Running /tmp/specjour/spec/specjour/configuration_spec.rb:56
[1] Finished /tmp/specjour/spec/specjour/cli_spec.rb:148 in 0.0148
[2] Finished /tmp/specjour/spec/specjour/configuration_spec.rb:45 in 0.0153
[4] Running /tmp/specjour/spec/specjour/configuration_spec.rb:65
[1] Running /tmp/specjour/spec/specjour/configuration_spec.rb:73
[2] Running /tmp/specjour/spec/specjour/configuration_spec.rb:84
[3] Finished /tmp/specjour/spec/specjour/configuration_spec.rb:56 in 0.0156
[3] Running /tmp/specjour/spec/specjour/configuration_spec.rb:95
[4] Finished /tmp/specjour/spec/specjour/configuration_spec.rb:65 in 0.0133
[4] Running /tmp/specjour/spec/specjour/configuration_spec.rb:103
[4] Finished /tmp/specjour/spec/specjour/configuration_spec.rb:103 in 0.0134
[1] Finished /tmp/specjour/spec/specjour/configuration_spec.rb:73 in 0.0322
[4] Running /tmp/specjour/spec/specjour/configuration_spec.rb:111
[1] Running /tmp/specjour/spec/specjour/configuration_spec.rb:115
[3] Finished /tmp/specjour/spec/specjour/configuration_spec.rb:95 in 0.0348
[3] Running /tmp/specjour/spec/specjour/configuration_spec.rb:122
[1] Finished /tmp/specjour/spec/specjour/configuration_spec.rb:115 in 0.0141
[4] Finished /tmp/specjour/spec/specjour/configuration_spec.rb:111 in 0.0322
[1] Running /tmp/specjour/spec/specjour/cpu_spec.rb:25
[4] Running /tmp/specjour/spec/specjour/loader_spec.rb:10
[1] Finished /tmp/specjour/spec/specjour/cpu_spec.rb:25 in 0.0098
[4] Finished /tmp/specjour/spec/specjour/loader_spec.rb:10 in 0.0121
[1] Running /tmp/specjour/spec/specjour/loader_spec.rb:35
[2] Finished /tmp/specjour/spec/specjour/configuration_spec.rb:84 in 0.0923
[4] Running /tmp/specjour/spec/specjour/loader_spec.rb:53
[2] Running /tmp/specjour/spec/specjour/manager_spec.rb:6
[1] Finished /tmp/specjour/spec/specjour/loader_spec.rb:35 in 0.0129
[4] Finished /tmp/specjour/spec/specjour/loader_spec.rb:53 in 0.0129
[2] Finished /tmp/specjour/spec/specjour/manager_spec.rb:6 in 0.0114
[1] Running /tmp/specjour/spec/specjour/manager_spec.rb:10
[4] Running /tmp/specjour/spec/specjour/manager_spec.rb:15
[2] Running /tmp/specjour/spec/specjour/printer_spec.rb:9
[1] Finished /tmp/specjour/spec/specjour/manager_spec.rb:10 in 0.0079
[4] Finished /tmp/specjour/spec/specjour/manager_spec.rb:15 in 0.0080
[1] Running /tmp/specjour/spec/specjour/printer_spec.rb:14
[2] Finished /tmp/specjour/spec/specjour/printer_spec.rb:9 in 0.0139
[4] Running /tmp/specjour/spec/specjour/printer_spec.rb:19
[2] Running /tmp/specjour/spec/specjour/printer_spec.rb:24
[3] Finished /tmp/specjour/spec/specjour/configuration_spec.rb:122 in 0.0861
[1] Finished /tmp/specjour/spec/specjour/printer_spec.rb:14 in 0.0135
[4] Finished /tmp/specjour/spec/specjour/printer_spec.rb:19 in 0.0134
[3] Running /tmp/specjour/spec/specjour/printer_spec.rb:48
[2] Finished /tmp/specjour/spec/specjour/printer_spec.rb:24 in 0.0138
[1] Running /tmp/specjour/spec/specjour/printer_spec.rb:59
[4] Running /tmp/specjour/spec/specjour/printer_spec.rb:72
[2] Running /tmp/specjour/spec/specjour/printer_spec.rb:83
[1] Finished /tmp/specjour/spec/specjour/printer_spec.rb:59 in 0.0156
[4] Finished /tmp/specjour/spec/specjour/printer_spec.rb:72 in 0.0156
[3] Finished /tmp/specjour/spec/specjour/printer_spec.rb:48 in 0.0190
[2] Finished /tmp/specjour/spec/specjour/printer_spec.rb:83 in 0.0159
[1] Running /tmp/specjour/spec/specjour/printer_spec.rb:98
[3] Running /tmp/specjour/spec/specjour/printer_spec.rb:111
[4] Running /tmp/specjour/spec/specjour/printer_spec.rb:124
[2] Running /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:18
[3] Finished /tmp/specjour/spec/specjour/printer_spec.rb:111 in 0.0191
[3] Running /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:19
[1] Finished /tmp/specjour/spec/specjour/printer_spec.rb:98 in 0.0292
[2] Finished /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:18 in 0.0282
[4] Finished /tmp/specjour/spec/specjour/printer_spec.rb:124 in 0.0289
[1] Running /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:22
[2] Running /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:27
[4] Running /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:33
[3] Finished /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:19 in 0.0288
[1] Finished /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:22 in 0.0196
[4] Finished /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:33 in 0.0205
[3] Running /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:59
[1] Running /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:66
[4] Running /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:74
[3] Finished /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:59 in 0.0206
[4] Finished /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:74 in 0.0193
[1] Finished /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:66 in 0.0352
[3] Running /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:80
[4] Running /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:89
[1] Running /tmp/specjour/spec/specjour_spec.rb:11
[1] Finished /tmp/specjour/spec/specjour_spec.rb:11 in 0.0081
[1] Running /tmp/specjour/spec/specjour_spec.rb:15
[1] Finished /tmp/specjour/spec/specjour_spec.rb:15 in 0.0080
[3] Finished /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:80 in 0.0377
[4] Finished /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:89 in 0.0373
[2] Finished /tmp/specjour/spec/specjour/rsync_daemon_spec.rb:27 in 0.1200
Workers ready: 4
Listening for specjour
rsync -aL --delete --ignore-errors --port=23456 192.168.1.71::specjour /tmp/specjour
rsync complete
Loading RSpec Environment
/tmp/specjour/lib/specjour/connection.rb:46:in block in print': private methodprint' called for nil:NilClass (NoMethodError)
from /tmp/specjour/lib/specjour/connection.rb:82:in call' from /tmp/specjour/lib/specjour/connection.rb:82:inwill_reconnect'
from /tmp/specjour/lib/specjour/connection.rb:45:in print' from /tmp/specjour/lib/specjour/connection.rb:58:inblock in send_message'
from /tmp/specjour/lib/specjour/connection.rb:82:in call' from /tmp/specjour/lib/specjour/connection.rb:82:inwill_reconnect'
from /tmp/specjour/lib/specjour/connection.rb:57:in send_message' from /home/josephl/hf/specjour/specjour/lib/specjour/loader.rb:91:inregister_tests_with_printer'
from /home/josephl/hf/specjour/specjour/lib/specjour/loader.rb:86:in load_app' from /home/josephl/hf/specjour/specjour/lib/specjour/loader.rb:22:instart'
from /home/josephl/hf/specjour/specjour/lib/specjour/cli.rb:57:in load' from /home/josephl/.rvm/gems/ruby-1.9.3-p125@specjour/gems/thor-0.14.6/lib/thor/task.rb:22:inrun'
from /home/josephl/.rvm/gems/ruby-1.9.3-p125@specjour/gems/thor-0.14.6/lib/thor/invocation.rb:118:in invoke_task' from /home/josephl/.rvm/gems/ruby-1.9.3-p125@specjour/gems/thor-0.14.6/lib/thor.rb:263:indispatch'
from /home/josephl/.rvm/gems/ruby-1.9.3-p125@specjour/gems/thor-0.14.6/lib/thor/base.rb:389:in start' from /home/josephl/hf/specjour/specjour/lib/specjour/cli.rb:24:instart'
from /home/josephl/hf/specjour/specjour/bin/specjour:5:in `
Workers ready: 4
Listening for specjour
Does specjour work on the linux box when just running the specjour command? Does this issue only occur when using your linux machine as a listener?
If you don't mind hacking around, change the timeout interval in this file to 1.0 instead of 0.1: https://github.com/sandro/specjour/blob/master/lib/specjour/connection.rb#L77
You should only need to make that change on the linux box.
Hopefully, that'll fix it!
This seems to have fixed the issue for me. I'll let you know if I have further similar issues.
I had some problems before making the change (it wouldn't get past "Looking for listeners..") when trying to run the command locally but I later realized that there were old Specjour processes running in some form on the system. When I killed these it then worked but I only did this after making the timeout change and I didn't then go back to the old timeout and retest.