2012-10-01 14:22:15.938310 D [31512:70362457736280] SimpleTCPServer -- Waiting for a client to connect 2012-10-01 14:22:15.939757 D [31512:70362457736280] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-01 14:22:15.940152 I [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- Connected to server (1.9ms) 2012-10-01 14:22:15.940374 T [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- #actionfailattempt 2012-10-01 14:22:15.940968 D [31512:70362457736280] SimpleTCPServer -- ****************** Received request 2012-10-01 14:22:15.940984 T [31512:70362457736280] SimpleTCPServer -- Request -- {"action"=>"fail", "attempt"=>1} 2012-10-01 14:22:15.940999 D [31512:70362457736280] SimpleTCPServer -- Closing client since no reply is being sent back 2012-10-01 14:22:15.941058 D [31512:70362457736280] SimpleTCPServer -- Server closed 2012-10-01 14:22:15.941070 D [31512:70362457736280] SimpleTCPServer -- thread killed 2012-10-01 14:22:15.941179 D [31512:70362457736280] SimpleTCPServer -- Server Restarted 2012-10-01 14:22:15.941716 D [31512:70362458740580] SimpleTCPServer -- Waiting for a client to connect 2012-10-01 14:22:15.942365 D [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 35 bytes (2.0ms) 2012-10-01 14:22:15.942635 W [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- #read Connection failure while reading data: EOFError: end of file reached 2012-10-01 14:22:15.942767 D [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 4 bytes -- ResilientSocket::ConnectionFailure: EOFError: end of file reached /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:324:in `rescue in block in read' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:318:in `block in read' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/semantic_logger-0.6.2/lib/semantic_logger/base.rb:173:in `benchmark_debug' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:302:in `read' /Users/rmorrison/Sandbox/resilient_socket/test/simple_tcp_server.rb:11:in `read_bson_document' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:92:in `block (5 levels) in ' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:264:in `retry_on_connection_failure' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:87:in `block (4 levels) in ' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/shoulda-context-1.0.0/lib/shoulda/context/context.rb:398:in `call' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/shoulda-context-1.0.0/lib/shoulda/context/context.rb:398:in `block in create_test_from_should_hash' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:949:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/testcase.rb:17:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:787:in `block in _run_suite' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `map' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `_run_suite' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:565:in `block in _run_suites' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `each' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `_run_suites' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:746:in `_run_anything' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:909:in `run_tests' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:896:in `block in _run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `each' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `_run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:884:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:21:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:326:in `block (2 levels) in autorun' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:27:in `run_once' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun' (0.3ms) 2012-10-01 14:22:15.942794 W [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- #retry_on_connection_failure Connection failure: EOFError: end of file reached. Retry: 1 2012-10-01 14:22:15.943738 D [31512:70362458740580] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-01 14:22:15.943940 I [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- Connected to server (1.1ms) 2012-10-01 14:22:15.944003 T [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- #actionfailattempt 2012-10-01 14:22:15.944252 D [31512:70362458740580] SimpleTCPServer -- ****************** Received request 2012-10-01 14:22:15.944268 T [31512:70362458740580] SimpleTCPServer -- Request -- {"action"=>"fail", "attempt"=>2} 2012-10-01 14:22:15.944281 D [31512:70362458740580] SimpleTCPServer -- Sending Reply 2012-10-01 14:22:15.944290 T [31512:70362458740580] SimpleTCPServer -- Reply -- {"result"=>"fail"} 2012-10-01 14:22:15.944687 D [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 35 bytes (0.7ms) 2012-10-01 14:22:15.944772 T [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x16\x00\x00\x00" 2012-10-01 14:22:15.944781 D [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 4 bytes (0.0ms) 2012-10-01 14:22:15.944825 T [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x02result\x00\x05\x00\x00\x00fail\x00\x00" 2012-10-01 14:22:15.945031 D [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 18 bytes (0.2ms) 2012-10-01 14:22:15.948602 D [31512:70362457698780] SimpleTCPServer -- Waiting for a client to connect 2012-10-01 14:22:15.949402 D [31512:70362457698780] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-01 14:22:15.949961 I [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- Connected to server (1.4ms) 2012-10-01 14:22:15.950067 T [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- actiontest1 2012-10-01 14:22:15.950334 D [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 23 bytes (0.2ms) 2012-10-01 14:22:15.950569 D [31512:70362457698780] SimpleTCPServer -- ****************** Received request 2012-10-01 14:22:15.950585 T [31512:70362457698780] SimpleTCPServer -- Request -- {"action"=>"test1"} 2012-10-01 14:22:15.950601 D [31512:70362457698780] SimpleTCPServer -- Sending Reply 2012-10-01 14:22:15.950610 T [31512:70362457698780] SimpleTCPServer -- Reply -- {"result"=>"test1"} 2012-10-01 14:22:15.950992 T [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x17\x00\x00\x00" 2012-10-01 14:22:15.951032 D [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 4 bytes (0.6ms) 2012-10-01 14:22:15.951266 T [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x02result\x00\x06\x00\x00\x00test1\x00\x00" 2012-10-01 14:22:15.951304 D [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 19 bytes (0.3ms) 2012-10-01 14:22:15.952247 D [31512:70362458119960] SimpleTCPServer -- Waiting for a client to connect 2012-10-01 14:22:15.953152 D [31512:70362458119960] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-01 14:22:15.953468 I [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- Connected to server (1.4ms) 2012-10-01 14:22:15.953575 T [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- )actionsleepduration @ 2012-10-01 14:22:15.953894 D [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 41 bytes (0.3ms) 2012-10-01 14:22:15.954141 D [31512:70362458119960] SimpleTCPServer -- ****************** Received request 2012-10-01 14:22:15.954158 T [31512:70362458119960] SimpleTCPServer -- Request -- {"action"=>"sleep", "duration"=>3.5} 2012-10-01 14:22:18.954543 W [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- #read Timeout waiting for server to reply 2012-10-01 14:22:18.954919 D [31512:70362457135840] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 4 bytes -- ResilientSocket::ReadTimeout: Timedout after 3.0 seconds trying to read from localhost:2000 /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:309:in `block in read' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/semantic_logger-0.6.2/lib/semantic_logger/base.rb:173:in `benchmark_debug' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:302:in `read' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:80:in `block (5 levels) in ' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:330:in `assert_raises' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/assertions.rb:69:in `assert_raise' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:78:in `block (4 levels) in ' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/shoulda-context-1.0.0/lib/shoulda/context/context.rb:398:in `call' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/shoulda-context-1.0.0/lib/shoulda/context/context.rb:398:in `block in create_test_from_should_hash' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:949:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/testcase.rb:17:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:787:in `block in _run_suite' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `map' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `_run_suite' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:565:in `block in _run_suites' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `each' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `_run_suites' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:746:in `_run_anything' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:909:in `run_tests' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:896:in `block in _run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `each' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `_run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:884:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:21:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:326:in `block (2 levels) in autorun' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:27:in `run_once' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun' (3001.0ms) 2012-10-01 14:22:18.956730 W [31512:70362457135840] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 1 2012-10-01 14:22:19.058806 W [31512:70362457135840] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 2 2012-10-01 14:22:19.160380 W [31512:70362457135840] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 3 2012-10-01 14:22:19.261561 W [31512:70362457135840] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 4 2012-10-01 14:22:19.363067 W [31512:70362457135840] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 5 2012-10-01 14:22:19.465008 E [31512:70362457135840] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Giving up after 5 retries 2012-10-01 14:22:19.465183 I [31512:70362457135840] ResilientSocket::TCPClient ["localhost:3300"] -- Connected to server -- ResilientSocket::ConnectionFailure: After 5 attempts: Errno::ECONNREFUSED: Connection refused - connect(2) /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:208:in `rescue in block in connect' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:174:in `block in connect' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/semantic_logger-0.6.2/lib/semantic_logger/base.rb:173:in `benchmark_info' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:173:in `connect' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:150:in `initialize' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:21:in `new' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:21:in `block (4 levels) in ' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:330:in `assert_raises' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/assertions.rb:69:in `assert_raise' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:20:in `block (3 levels) in ' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/shoulda-context-1.0.0/lib/shoulda/context/context.rb:398:in `call' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/shoulda-context-1.0.0/lib/shoulda/context/context.rb:398:in `block in create_test_from_should_hash' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:949:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/testcase.rb:17:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:787:in `block in _run_suite' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `map' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `_run_suite' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:565:in `block in _run_suites' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `each' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `_run_suites' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:746:in `_run_anything' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:909:in `run_tests' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:896:in `block in _run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `each' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `_run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:884:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:21:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:326:in `block (2 levels) in autorun' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:27:in `run_once' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun' (509.2ms) 2012-10-01 14:22:41.853331 D [31740:70129267023840] SimpleTCPServer -- Waiting for a client to connect 2012-10-01 14:22:41.854815 I [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- Connected to server (1.6ms) 2012-10-01 14:22:41.855040 T [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- #actionfailattempt 2012-10-01 14:22:41.855099 D [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 35 bytes (0.0ms) 2012-10-01 14:22:41.855299 D [31740:70129267023840] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-01 14:22:41.855625 D [31740:70129267023840] SimpleTCPServer -- ****************** Received request 2012-10-01 14:22:41.855642 T [31740:70129267023840] SimpleTCPServer -- Request -- {"action"=>"fail", "attempt"=>1} 2012-10-01 14:22:41.855657 D [31740:70129267023840] SimpleTCPServer -- Closing client since no reply is being sent back 2012-10-01 14:22:41.855691 D [31740:70129267023840] SimpleTCPServer -- Server closed 2012-10-01 14:22:41.855702 D [31740:70129267023840] SimpleTCPServer -- thread killed 2012-10-01 14:22:41.855837 W [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- #read Connection failure while reading data: EOFError: end of file reached 2012-10-01 14:22:41.855912 D [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 4 bytes -- ResilientSocket::ConnectionFailure: EOFError: end of file reached /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:324:in `rescue in block in read' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:318:in `block in read' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/semantic_logger-0.6.2/lib/semantic_logger/base.rb:173:in `benchmark_debug' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:302:in `read' /Users/rmorrison/Sandbox/resilient_socket/test/simple_tcp_server.rb:11:in `read_bson_document' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:92:in `block (5 levels) in ' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:264:in `retry_on_connection_failure' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:87:in `block (4 levels) in ' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/shoulda-context-1.0.0/lib/shoulda/context/context.rb:398:in `call' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/shoulda-context-1.0.0/lib/shoulda/context/context.rb:398:in `block in create_test_from_should_hash' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:949:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/testcase.rb:17:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:787:in `block in _run_suite' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `map' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `_run_suite' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:565:in `block in _run_suites' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `each' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `_run_suites' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:746:in `_run_anything' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:909:in `run_tests' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:896:in `block in _run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `each' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `_run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:884:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:21:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:326:in `block (2 levels) in autorun' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:27:in `run_once' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun' (0.8ms) 2012-10-01 14:22:41.855939 W [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- #retry_on_connection_failure Connection failure: EOFError: end of file reached. Retry: 1 2012-10-01 14:22:41.856663 D [31740:70129267023840] SimpleTCPServer -- Server Restarted 2012-10-01 14:22:41.856735 D [31740:70129271583740] SimpleTCPServer -- Waiting for a client to connect 2012-10-01 14:22:41.857229 I [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- Connected to server (1.3ms) 2012-10-01 14:22:41.857272 T [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- #actionfailattempt 2012-10-01 14:22:41.857320 D [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 35 bytes (0.0ms) 2012-10-01 14:22:41.857366 D [31740:70129271583740] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-01 14:22:41.857420 D [31740:70129271583740] SimpleTCPServer -- ****************** Received request 2012-10-01 14:22:41.857432 T [31740:70129271583740] SimpleTCPServer -- Request -- {"action"=>"fail", "attempt"=>2} 2012-10-01 14:22:41.857445 D [31740:70129271583740] SimpleTCPServer -- Sending Reply 2012-10-01 14:22:41.857454 T [31740:70129271583740] SimpleTCPServer -- Reply -- {"result"=>"fail"} 2012-10-01 14:22:41.858124 T [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x16\x00\x00\x00" 2012-10-01 14:22:41.858138 D [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 4 bytes (0.8ms) 2012-10-01 14:22:41.858359 T [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x02result\x00\x05\x00\x00\x00fail\x00\x00" 2012-10-01 14:22:41.858373 D [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 18 bytes (0.2ms) 2012-10-01 14:22:41.859312 D [31740:70129266973380] SimpleTCPServer -- Waiting for a client to connect 2012-10-01 14:22:41.859835 I [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- Connected to server (0.6ms) 2012-10-01 14:22:41.859903 T [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- actiontest1 2012-10-01 14:22:41.859950 D [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 23 bytes (0.0ms) 2012-10-01 14:22:41.860296 D [31740:70129266973380] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-01 14:22:41.860434 D [31740:70129266973380] SimpleTCPServer -- ****************** Received request 2012-10-01 14:22:41.860450 T [31740:70129266973380] SimpleTCPServer -- Request -- {"action"=>"test1"} 2012-10-01 14:22:41.860464 D [31740:70129266973380] SimpleTCPServer -- Sending Reply 2012-10-01 14:22:41.860473 T [31740:70129266973380] SimpleTCPServer -- Reply -- {"result"=>"test1"} 2012-10-01 14:22:41.860864 T [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x17\x00\x00\x00" 2012-10-01 14:22:41.860877 D [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 4 bytes (0.9ms) 2012-10-01 14:22:41.861111 T [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x02result\x00\x06\x00\x00\x00test1\x00\x00" 2012-10-01 14:22:41.861124 D [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 19 bytes (0.2ms) 2012-10-01 14:22:41.861748 D [31740:70129270904960] SimpleTCPServer -- Waiting for a client to connect 2012-10-01 14:22:41.862320 I [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- Connected to server (0.6ms) 2012-10-01 14:22:41.862451 T [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- )actionsleepduration @ 2012-10-01 14:22:41.862506 D [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 41 bytes (0.0ms) 2012-10-01 14:22:41.862840 D [31740:70129270904960] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-01 14:22:41.862991 D [31740:70129270904960] SimpleTCPServer -- ****************** Received request 2012-10-01 14:22:41.863003 T [31740:70129270904960] SimpleTCPServer -- Request -- {"action"=>"sleep", "duration"=>3.5} 2012-10-01 14:22:44.862855 W [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- #read Timeout waiting for server to reply 2012-10-01 14:22:44.863154 D [31740:70129266416340] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 4 bytes -- ResilientSocket::ReadTimeout: Timedout after 3.0 seconds trying to read from localhost:2000 /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:309:in `block in read' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/semantic_logger-0.6.2/lib/semantic_logger/base.rb:173:in `benchmark_debug' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:302:in `read' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:80:in `block (5 levels) in ' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:330:in `assert_raises' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/assertions.rb:69:in `assert_raise' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:78:in `block (4 levels) in ' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/shoulda-context-1.0.0/lib/shoulda/context/context.rb:398:in `call' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/shoulda-context-1.0.0/lib/shoulda/context/context.rb:398:in `block in create_test_from_should_hash' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:949:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/testcase.rb:17:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:787:in `block in _run_suite' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `map' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `_run_suite' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:565:in `block in _run_suites' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `each' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `_run_suites' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:746:in `_run_anything' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:909:in `run_tests' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:896:in `block in _run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `each' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `_run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:884:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:21:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:326:in `block (2 levels) in autorun' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:27:in `run_once' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun' (3000.6ms) 2012-10-01 14:22:44.864903 W [31740:70129266416340] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 1 2012-10-01 14:22:44.967275 W [31740:70129266416340] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 2 2012-10-01 14:22:45.070243 W [31740:70129266416340] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 3 2012-10-01 14:22:45.171742 W [31740:70129266416340] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 4 2012-10-01 14:22:45.273644 W [31740:70129266416340] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 5 2012-10-01 14:22:45.375647 E [31740:70129266416340] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Giving up after 5 retries 2012-10-01 14:22:45.375744 I [31740:70129266416340] ResilientSocket::TCPClient ["localhost:3300"] -- Connected to server -- ResilientSocket::ConnectionFailure: After 5 attempts: Errno::ECONNREFUSED: Connection refused - connect(2) /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:208:in `rescue in block in connect' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:174:in `block in connect' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/semantic_logger-0.6.2/lib/semantic_logger/base.rb:173:in `benchmark_info' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:173:in `connect' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:150:in `initialize' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:21:in `new' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:21:in `block (4 levels) in ' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:330:in `assert_raises' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/assertions.rb:69:in `assert_raise' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:20:in `block (3 levels) in ' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/shoulda-context-1.0.0/lib/shoulda/context/context.rb:398:in `call' /Users/rmorrison/.rvm/gems/ruby-1.9.3-p194/gems/shoulda-context-1.0.0/lib/shoulda/context/context.rb:398:in `block in create_test_from_should_hash' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:949:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/testcase.rb:17:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:787:in `block in _run_suite' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `map' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `_run_suite' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:565:in `block in _run_suites' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `each' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `_run_suites' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:746:in `_run_anything' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:909:in `run_tests' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:896:in `block in _run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `each' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `_run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:884:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:21:in `run' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:326:in `block (2 levels) in autorun' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:27:in `run_once' /Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun' (511.6ms)