2012-10-02 14:20:18.542776 D [91092:70099667172120] SimpleTCPServer -- Waiting for a client to connect 2012-10-02 14:20:18.544384 W [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 1 2012-10-02 14:20:19.046497 W [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 2 2012-10-02 14:20:19.548428 W [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 3 2012-10-02 14:20:20.050344 W [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 4 2012-10-02 14:20:20.552856 W [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 5 2012-10-02 14:20:21.054129 W [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 6 2012-10-02 14:20:21.556165 W [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 7 2012-10-02 14:20:22.058152 W [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 8 2012-10-02 14:20:22.560487 W [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 9 2012-10-02 14:20:23.062359 W [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 10 2012-10-02 14:20:23.564197 E [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Giving up after 10 retries 2012-10-02 14:20:23.564292 I [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connecting to server localhost:1999 -- ResilientSocket::ConnectionFailure: After 10 attempts: Errno::ECONNREFUSED: Connection refused - connect(2) /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:418:in `rescue in block in connect_to_server' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:388:in `block in connect_to_server' /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:387:in `connect_to_server' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:193:in `block in connect' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:191:in `each' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:191:in `each_with_index' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:191:in `connect' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:163:in `initialize' test/tcp_client_test.rb:101:in `new' test/tcp_client_test.rb:101: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' (5021.6ms) 2012-10-02 14:20:23.565124 T [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- ==> Sending -- actiontest1 2012-10-02 14:20:23.565184 D [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- ==> #send Sent 23 bytes (0.0ms) 2012-10-02 14:20:23.565246 D [91092:70099667172120] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-02 14:20:23.565333 D [91092:70099667172120] SimpleTCPServer -- ****************** Received request 2012-10-02 14:20:23.565344 T [91092:70099667172120] SimpleTCPServer -- Request -- {"action"=>"test1"} 2012-10-02 14:20:23.565372 D [91092:70099667172120] SimpleTCPServer -- Sending Reply 2012-10-02 14:20:23.565382 T [91092:70099667172120] SimpleTCPServer -- Reply -- {"result"=>"test1"} 2012-10-02 14:20:23.568285 T [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- <== #read Received -- "\x17\x00\x00\x00" 2012-10-02 14:20:23.568302 D [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- <== #read Received upto 4 bytes (3.1ms) 2012-10-02 14:20:23.568557 T [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- <== #read Received -- "\x02result\x00\x06\x00\x00\x00test1\x00\x00" 2012-10-02 14:20:23.568572 D [91092:70099667213020] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- <== #read Received upto 19 bytes (0.2ms) 2012-10-04 11:39:55.369536 D [52237:70269712936140] SimpleTCPServer -- Waiting for a client to connect 2012-10-04 11:39:55.372309 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- #actionfailattempt 2012-10-04 11:39:55.372368 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 35 bytes (0.0ms) 2012-10-04 11:39:55.372478 D [52237:70269712936140] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-04 11:39:55.372559 D [52237:70269712936140] SimpleTCPServer -- ****************** Received request 2012-10-04 11:39:55.372570 T [52237:70269712936140] SimpleTCPServer -- Request -- {"action"=>"fail", "attempt"=>1} 2012-10-04 11:39:55.372594 D [52237:70269712936140] SimpleTCPServer -- Closing client since no reply is being sent back 2012-10-04 11:39:55.372692 D [52237:70269712936140] SimpleTCPServer -- Server closed 2012-10-04 11:39:55.372738 D [52237:70269712936140] SimpleTCPServer -- thread killed 2012-10-04 11:39:55.372878 D [52237:70269712936140] SimpleTCPServer -- Server Restarted 2012-10-04 11:39:55.373742 D [52237:70269712645880] SimpleTCPServer -- Waiting for a client to connect 2012-10-04 11:39:55.375235 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- #read Connection failure while reading data: EOFError: end of file reached 2012-10-04 11:39:55.375358 D [52237:70269708491480] 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:269:in `rescue in block in read' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:263: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:247: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:338: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' (3.0ms) 2012-10-04 11:39:55.375389 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- #retry_on_connection_failure Connection failure: EOFError: end of file reached. Retry: 1 2012-10-04 11:39:55.380217 D [52237:70269712645880] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-04 11:39:55.380495 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- #actionfailattempt 2012-10-04 11:39:55.380739 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 35 bytes (0.2ms) 2012-10-04 11:39:55.380881 D [52237:70269712645880] SimpleTCPServer -- ****************** Received request 2012-10-04 11:39:55.380892 T [52237:70269712645880] SimpleTCPServer -- Request -- {"action"=>"fail", "attempt"=>2} 2012-10-04 11:39:55.380908 D [52237:70269712645880] SimpleTCPServer -- Sending Reply 2012-10-04 11:39:55.380917 T [52237:70269712645880] SimpleTCPServer -- Reply -- {"result"=>"fail"} 2012-10-04 11:39:55.381919 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x16\x00\x00\x00" 2012-10-04 11:39:55.381936 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 4 bytes (1.1ms) 2012-10-04 11:39:55.382278 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x02result\x00\x05\x00\x00\x00fail\x00\x00" 2012-10-04 11:39:55.382309 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 18 bytes (0.3ms) 2012-10-04 11:39:55.383449 D [52237:70269709421020] SimpleTCPServer -- Waiting for a client to connect 2012-10-04 11:39:55.384050 D [52237:70269709421020] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-04 11:39:55.384306 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- actiontest1 2012-10-04 11:39:55.384514 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 23 bytes (0.2ms) 2012-10-04 11:39:55.384734 D [52237:70269709421020] SimpleTCPServer -- ****************** Received request 2012-10-04 11:39:55.384750 T [52237:70269709421020] SimpleTCPServer -- Request -- {"action"=>"test1"} 2012-10-04 11:39:55.384764 D [52237:70269709421020] SimpleTCPServer -- Sending Reply 2012-10-04 11:39:55.384772 T [52237:70269709421020] SimpleTCPServer -- Reply -- {"result"=>"test1"} 2012-10-04 11:39:55.385147 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x17\x00\x00\x00" 2012-10-04 11:39:55.385179 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 4 bytes (0.6ms) 2012-10-04 11:39:55.385421 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x02result\x00\x06\x00\x00\x00test1\x00\x00" 2012-10-04 11:39:55.385453 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 19 bytes (0.2ms) 2012-10-04 11:39:55.386552 D [52237:70269712947300] SimpleTCPServer -- Waiting for a client to connect 2012-10-04 11:39:55.387050 D [52237:70269712947300] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-04 11:39:55.387317 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- )actionsleepduration @ 2012-10-04 11:39:55.387510 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 41 bytes (0.1ms) 2012-10-04 11:39:55.387731 D [52237:70269712947300] SimpleTCPServer -- ****************** Received request 2012-10-04 11:39:55.387748 T [52237:70269712947300] SimpleTCPServer -- Request -- {"action"=>"sleep", "duration"=>3.5} 2012-10-04 11:39:58.388842 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- #read Timeout waiting for server to reply 2012-10-04 11:39:58.389130 D [52237:70269708491480] 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:254: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:247: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.6ms) 2012-10-04 11:39:58.391844 D [52237:70269712911300] SimpleTCPServer -- Waiting for a client to connect 2012-10-04 11:39:58.392375 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- ==> Sending -- actiontest1 2012-10-04 11:39:58.392546 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- ==> #send Sent 23 bytes (0.1ms) 2012-10-04 11:39:58.392622 D [52237:70269712911300] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-04 11:39:58.392691 D [52237:70269712911300] SimpleTCPServer -- ****************** Received request 2012-10-04 11:39:58.392702 T [52237:70269712911300] SimpleTCPServer -- Request -- {"action"=>"test1"} 2012-10-04 11:39:58.392716 D [52237:70269712911300] SimpleTCPServer -- Sending Reply 2012-10-04 11:39:58.392725 T [52237:70269712911300] SimpleTCPServer -- Reply -- {"result"=>"test1"} 2012-10-04 11:39:58.393289 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x17\x00\x00\x00" 2012-10-04 11:39:58.393304 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 4 bytes (0.7ms) 2012-10-04 11:39:58.393506 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received -- "\x02result\x00\x06\x00\x00\x00test1\x00\x00" 2012-10-04 11:39:58.393520 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:2000"] -- <== #read Received upto 19 bytes (0.2ms) 2012-10-04 11:39:58.394046 D [52237:70269709993020] SimpleTCPServer -- Waiting for a client to connect 2012-10-04 11:39:58.394938 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 1 2012-10-04 11:39:58.896865 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 2 2012-10-04 11:39:59.399038 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 3 2012-10-04 11:39:59.900982 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 4 2012-10-04 11:40:00.402385 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 5 2012-10-04 11:40:00.904285 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 6 2012-10-04 11:40:01.406225 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 7 2012-10-04 11:40:01.907989 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 8 2012-10-04 11:40:02.409589 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 9 2012-10-04 11:40:02.911452 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 10 2012-10-04 11:40:03.413555 E [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Giving up after 10 retries 2012-10-04 11:40:03.413684 I [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- Connecting to server localhost:1999 -- ResilientSocket::ConnectionFailure: After 10 attempts: Errno::ECONNREFUSED: Connection refused - connect(2) /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:418:in `rescue in block in connect_to_server' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:388:in `block in connect_to_server' /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:387:in `connect_to_server' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:193:in `block in connect' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:191:in `each' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:191:in `each_with_index' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:191:in `connect' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:163:in `initialize' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:101:in `new' /Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:101: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' (5019.7ms) 2012-10-04 11:40:03.414525 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- ==> Sending -- actiontest1 2012-10-04 11:40:03.414627 D [52237:70269709993020] SimpleTCPServer -- Client connected, waiting for data from client 2012-10-04 11:40:03.414694 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- ==> #send Sent 23 bytes (0.1ms) 2012-10-04 11:40:03.414821 D [52237:70269709993020] SimpleTCPServer -- ****************** Received request 2012-10-04 11:40:03.414836 T [52237:70269709993020] SimpleTCPServer -- Request -- {"action"=>"test1"} 2012-10-04 11:40:03.414854 D [52237:70269709993020] SimpleTCPServer -- Sending Reply 2012-10-04 11:40:03.414866 T [52237:70269709993020] SimpleTCPServer -- Reply -- {"result"=>"test1"} 2012-10-04 11:40:03.415128 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- <== #read Received -- "\x17\x00\x00\x00" 2012-10-04 11:40:03.415142 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- <== #read Received upto 4 bytes (0.4ms) 2012-10-04 11:40:03.415288 T [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- <== #read Received -- "\x02result\x00\x06\x00\x00\x00test1\x00\x00" 2012-10-04 11:40:03.415301 D [52237:70269708491480] ResilientSocket::TCPClient ["localhost:1999", "localhost:2000"] -- <== #read Received upto 19 bytes (0.1ms) 2012-10-04 11:40:03.417543 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 1 2012-10-04 11:40:03.519473 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 2 2012-10-04 11:40:03.621412 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 3 2012-10-04 11:40:03.723351 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 4 2012-10-04 11:40:03.825712 W [52237:70269708491480] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Retry: 5 2012-10-04 11:40:03.927556 E [52237:70269708491480] ResilientSocket::TCPClient ["localhost:3300"] -- Connection failure: Errno::ECONNREFUSED: Connection refused - connect(2). Giving up after 5 retries 2012-10-04 11:40:03.927657 I [52237:70269708491480] ResilientSocket::TCPClient ["localhost:3300"] -- Connecting to server localhost:3300 -- ResilientSocket::ConnectionFailure: After 5 attempts: Errno::ECONNREFUSED: Connection refused - connect(2) /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:418:in `rescue in block in connect_to_server' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:388:in `block in connect_to_server' /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:387:in `connect_to_server' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:193:in `block in connect' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:191:in `each' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:191:in `each_with_index' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:191:in `connect' /Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:163: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' (510.9ms)