Frequent but intermittent failure in specjour listen on Linux

[josephlord]

/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

[sandro]

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!

[josephlord]

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.