test.log in resilient_socket-0.0.2 vs test.log in resilient_socket-0.1.0

- old
+ new

@@ -1,28 +1,29 @@ -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 <class:TCPClientTest>' -/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 <class:TCPClientTest>' +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 <class:TCPClientTest>' /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' @@ -38,56 +39,45 @@ /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 -- +/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-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 -- +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-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' +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:302:in `read' -/Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:80:in `block (5 levels) in <class:TCPClientTest>' -/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 <class:TCPClientTest>' +/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 <class:TCPClientTest>' +/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 <class:TCPClientTest>' /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' @@ -103,28 +93,53 @@ /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 <class:TCPClientTest>' +/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 <class:TCPClientTest>' /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 <class:TCPClientTest>' +/Users/rmorrison/Sandbox/resilient_socket/test/tcp_client_test.rb:78:in `block (4 levels) in <class:TCPClientTest>' /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' @@ -140,32 +155,48 @@ /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 -- +/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-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 <class:TCPClientTest>' -/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 <class:TCPClientTest>' +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 <class:TCPClientTest>' /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' @@ -181,90 +212,39 @@ /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 -- +/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-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 <class:TCPClientTest>' -/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 <class:TCPClientTest>' -/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' +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:173:in `connect' -/Users/rmorrison/Sandbox/resilient_socket/lib/resilient_socket/tcp_client.rb:150:in `initialize' +/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 <class:TCPClientTest>' /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 <class:TCPClientTest>' @@ -285,6 +265,6 @@ /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) +/Users/rmorrison/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun' (510.9ms)