ruby-core

Bug #2339: DRb leaves connections half-open
http://redmine.ruby-lang.org/issues/show/2339

Author: Pierre-Alexandre Meyer
Status: Open, Priority: Normal
Category: lib
ruby -v: ruby 1.9.1p243 (2009-07-16 revision 24175) [x86_64-linux]

Hello,

  While examining some tcp frames, I encountered the following behaviour in the DRb protocol.

In a nutshell, when the client closes the connection with a server, a stack trace is sent back to the client (indicating a DRbConnError) leaving the connection
half-open. I was wondering if there is a rational behind it?

With the simple server/client example from the DRb documentation (attached), 1707 bytes are being transmitted as part of the tcp conversation,
730 of which is the data for this stack trace.

The behaviour seems to come from drb/drb.rb, in DRbServer#main_loop:

          client.send_reply(succ, result) rescue nil

the server sends data back, even when the client tries to close the connection (after initiating a FIN).

The current TCP conversation looks like:

No.     Time        Source                Destination           Protocol Info
      1 0.000000    ::1                   ::1                   TCP      49630 > msgsrvr [SYN] Seq=0 Win=32752 Len=0 MSS=16376 TSV=111955923 TSER=0 WS=7
      2 0.000014    ::1                   ::1                   TCP      msgsrvr > 49630 [SYN, ACK] Seq=0 Ack=1 Win=32728 Len=0 MSS=16376 TSV=111955923 TSER=111955923 WS=7
      3 0.000025    ::1                   ::1                   TCP      49630 > msgsrvr [ACK] Seq=1 Ack=1 Win=32768 Len=0 TSV=111955923 TSER=111955923
      4 0.005520    ::1                   ::1                   TCP      49630 > msgsrvr [PSH, ACK] Seq=1 Ack=1 Win=32768 Len=68 TSV=111955923 TSER=111955923
      5 0.005533    ::1                   ::1                   TCP      msgsrvr > 49630 [ACK] Seq=1 Ack=69 Win=32768 Len=0 TSV=111955923 TSER=111955923
      6 0.005947    ::1                   ::1                   TCP      msgsrvr > 49630 [PSH, ACK] Seq=1 Ack=69 Win=32768 Len=45 TSV=111955923 TSER=111955923
      7 0.005956    ::1                   ::1                   TCP      49630 > msgsrvr [ACK] Seq=69 Ack=46 Win=32768 Len=0 TSV=111955923 TSER=111955923
      8 0.008436    ::1                   ::1                   TCP      49630 > msgsrvr [FIN, ACK] Seq=69 Ack=46 Win=32768 Len=0 TSV=111955924 TSER=111955923
      9 0.009124    ::1                   ::1                   TCP      msgsrvr > 49630 [PSH, ACK] Seq=46 Ack=70 Win=32768 Len=730 TSV=111955924 TSER=111955924
     10 0.009142    ::1                   ::1                   TCP      49630 > msgsrvr [RST] Seq=70 Win=0 Len=0

The extra PUSH is

0000  00 00 00 00 00 00 00 00 00 00 00 00 86 dd 60 00   ..............`.
0010  00 00 02 fa 06 40 00 00 00 00 00 00 00 00 00 00   .....@..........
0020  00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00   ................
0030  00 00 00 00 00 01 22 53 c1 de ae c9 dc 23 ae b0   ......"S.....#..
0040  48 3c 80 18 01 00 03 02 00 00 01 01 08 0a 06 ac   H<..............
0050  4f d4 06 ac 4f d4 00 00 00 03 04 08 46 00 00 02   O...O.......F...
0060  cf 04 08 6f 3a 16 44 52 62 3a 3a 44 52 62 43 6f   ...o:.DRb::DRbCo
0070  6e 6e 45 72 72 6f 72 07 3a 09 6d 65 73 67 49 22   nnError.:.mesgI"
0080  16 63 6f 6e 6e 65 63 74 69 6f 6e 20 63 6c 6f 73   .connection clos
0090  65 64 06 3a 0d 65 6e 63 6f 64 69 6e 67 22 0d 55   ed.:.encoding".U
00a0  53 2d 41 53 43 49 49 3a 07 62 74 5b 0e 22 41 2f   S-ASCII:.bt[."A/
00b0  6f 70 74 2f 72 75 62 79 2d 31 2e 39 2e 31 2d 70   opt/ruby-1.9.1-p
00c0  32 34 33 2f 6c 69 62 2f 72 75 62 79 2f 31 2e 39   243/lib/ruby/1.9
00d0  2e 31 2f 64 72 62 2f 64 72 62 2e 72 62 3a 35 37   .1/drb/drb.rb:57
00e0  30 3a 69 6e 20 60 6c 6f 61 64 27 22 49 2f 6f 70   0:in `load'"I/op
00f0  74 2f 72 75 62 79 2d 31 2e 39 2e 31 2d 70 32 34   t/ruby-1.9.1-p24
0100  33 2f 6c 69 62 2f 72 75 62 79 2f 31 2e 39 2e 31   3/lib/ruby/1.9.1
0110  2f 64 72 62 2f 64 72 62 2e 72 62 3a 36 31 32 3a   /drb/drb.rb:612:
0120  69 6e 20 60 72 65 63 76 5f 72 65 71 75 65 73 74   in `recv_request
0130  27 22 49 2f 6f 70 74 2f 72 75 62 79 2d 31 2e 39   '"I/opt/ruby-1.9
0140  2e 31 2d 70 32 34 33 2f 6c 69 62 2f 72 75 62 79   .1-p243/lib/ruby
0150  2f 31 2e 39 2e 31 2f 64 72 62 2f 64 72 62 2e 72   /1.9.1/drb/drb.r
0160  62 3a 39 30 38 3a 69 6e 20 60 72 65 63 76 5f 72   b:908:in `recv_r
0170  65 71 75 65 73 74 27 22 4e 2f 6f 70 74 2f 72 75   equest'"N/opt/ru
0180  62 79 2d 31 2e 39 2e 31 2d 70 32 34 33 2f 6c 69   by-1.9.1-p243/li
0190  62 2f 72 75 62 79 2f 31 2e 39 2e 31 2f 64 72 62   b/ruby/1.9.1/drb
01a0  2f 64 72 62 2e 72 62 3a 31 35 33 33 3a 69 6e 20   /drb.rb:1533:in 
01b0  60 69 6e 69 74 5f 77 69 74 68 5f 63 6c 69 65 6e   `init_with_clien
01c0  74 27 22 4b 2f 6f 70 74 2f 72 75 62 79 2d 31 2e   t'"K/opt/ruby-1.
01d0  39 2e 31 2d 70 32 34 33 2f 6c 69 62 2f 72 75 62   9.1-p243/lib/rub
01e0  79 2f 31 2e 39 2e 31 2f 64 72 62 2f 64 72 62 2e   y/1.9.1/drb/drb.
01f0  72 62 3a 31 35 34 35 3a 69 6e 20 60 73 65 74 75   rb:1545:in `setu
0200  70 5f 6d 65 73 73 61 67 65 27 22 45 2f 6f 70 74   p_message'"E/opt
0210  2f 72 75 62 79 2d 31 2e 39 2e 31 2d 70 32 34 33   /ruby-1.9.1-p243
0220  2f 6c 69 62 2f 72 75 62 79 2f 31 2e 39 2e 31 2f   /lib/ruby/1.9.1/
0230  64 72 62 2f 64 72 62 2e 72 62 3a 31 34 39 37 3a   drb/drb.rb:1497:
0240  69 6e 20 60 70 65 72 66 6f 72 6d 27 22 5b 2f 6f   in `perform'"[/o
0250  70 74 2f 72 75 62 79 2d 31 2e 39 2e 31 2d 70 32   pt/ruby-1.9.1-p2
0260  34 33 2f 6c 69 62 2f 72 75 62 79 2f 31 2e 39 2e   43/lib/ruby/1.9.
0270  31 2f 64 72 62 2f 64 72 62 2e 72 62 3a 31 35 39   1/drb/drb.rb:159
0280  32 3a 69 6e 20 60 62 6c 6f 63 6b 20 28 32 20 6c   2:in `block (2 l
0290  65 76 65 6c 73 29 20 69 6e 20 6d 61 69 6e 5f 6c   evels) in main_l
02a0  6f 6f 70 27 22 42 2f 6f 70 74 2f 72 75 62 79 2d   oop'"B/opt/ruby-
02b0  31 2e 39 2e 31 2d 70 32 34 33 2f 6c 69 62 2f 72   1.9.1-p243/lib/r
02c0  75 62 79 2f 31 2e 39 2e 31 2f 64 72 62 2f 64 72   uby/1.9.1/drb/dr
02d0  62 2e 72 62 3a 31 35 38 38 3a 69 6e 20 60 6c 6f   b.rb:1588:in `lo
02e0  6f 70 27 22 50 2f 6f 70 74 2f 72 75 62 79 2d 31   op'"P/opt/ruby-1
02f0  2e 39 2e 31 2d 70 32 34 33 2f 6c 69 62 2f 72 75   .9.1-p243/lib/ru
0300  62 79 2f 31 2e 39 2e 31 2f 64 72 62 2f 64 72 62   by/1.9.1/drb/drb
0310  2e 72 62 3a 31 35 38 38 3a 69 6e 20 60 62 6c 6f   .rb:1588:in `blo
0320  63 6b 20 69 6e 20 6d 61 69 6e 5f 6c 6f 6f 70 27   ck in main_loop'

With the attached patch, which makes the server not send any data when the client tries to close the connection:

No.     Time        Source                Destination           Protocol Info
      1 0.000000    ::1                   ::1                   TCP      55904 > msgsrvr [SYN] Seq=0 Win=32752 Len=0 MSS=16376 TSV=112384805 TSER=0 WS=7
      2 0.000014    ::1                   ::1                   TCP      msgsrvr > 55904 [SYN, ACK] Seq=0 Ack=1 Win=32728 Len=0 MSS=16376 TSV=112384805 TSER=112384805 WS=7
      3 0.000025    ::1                   ::1                   TCP      55904 > msgsrvr [ACK] Seq=1 Ack=1 Win=32768 Len=0 TSV=112384805 TSER=112384805
      4 0.000212    ::1                   ::1                   TCP      55904 > msgsrvr [PSH, ACK] Seq=1 Ack=1 Win=32768 Len=68 TSV=112384805 TSER=112384805
      5 0.000220    ::1                   ::1                   TCP      msgsrvr > 55904 [ACK] Seq=1 Ack=69 Win=32768 Len=0 TSV=112384805 TSER=112384805
      6 0.000655    ::1                   ::1                   TCP      msgsrvr > 55904 [PSH, ACK] Seq=1 Ack=69 Win=32768 Len=45 TSV=112384805 TSER=112384805
      7 0.000663    ::1                   ::1                   TCP      55904 > msgsrvr [ACK] Seq=69 Ack=46 Win=32768 Len=0 TSV=112384805 TSER=112384805
      8 0.001523    ::1                   ::1                   TCP      55904 > msgsrvr [FIN, ACK] Seq=69 Ack=46 Win=32768 Len=0 TSV=112384805 TSER=112384805
      9 0.001685    ::1                   ::1                   TCP      msgsrvr > 55904 [FIN, ACK] Seq=46 Ack=70 Win=32768 Len=0 TSV=112384805 TSER=112384805
     10 0.001700    ::1                   ::1                   TCP      55904 > msgsrvr [ACK] Seq=70 Ack=47 Win=32768 Len=0 TSV=112384805 TSER=112384805


----------------------------------------
http://redmine.ruby-lang.org

Thread

Prev Next

In This Thread

Prev Next

[#26463] New Features for the Array Module — Daniel Cohen <danielc2017@...>

[#26467] ARGF.binmode limitation — Vladimir Sizikov <vsizikov@...>

[#26470] [Feature #2321] [PATCH] Array Module sum and mean features — Daniel Cohen <redmine@...>

[#26473] [Feature #2322] [PATCH] Add standard deviation function to Math Module — Daniel Cohen <redmine@...>

[#26474] Building with gcov — Aaron Patterson <aaron@...>

[#26488] Add Standard Deviation Function to Math Module — Daniel Cohen <danielc2017@...>

[#26492] HashWithIndifferentAccess to core — Urabe Shyouhei <shyouhei@...>

[#26497] [Bug #2326] 1.8.7 Segmentation fault — Johan Holmberg <redmine@...>

[#26509] pathname--is this a bug? — Roger Pack <rogerdpack@...>

[#26512] why RUBY_INIT_STACK in main? — Suraj Kurapati <sunaku@...>

[#26523] [Bug #2330] Non systematic segmentation fault with autoload rubyspec — Marc-Andre Lafortune <redmine@...>

[#26525] [Bug #2332] Ruby doesn't run properly from unicode folder on windows — Vit Ondruch <redmine@...>

[#26526] [Bug #2333] __FILE__ macro should have unicode encoding — Vit Ondruch <redmine@...>

[#26540] [Bug #2336] pathname compare fails in windows — Roger Pack <redmine@...>

[#26544] [Bug #2337] "for object in collection" syntax not thread-safe — John-Michael fischer <redmine@...>

[#26554] [Bug #2339] DRb leaves connections half-open — Pierre-Alexandre Meyer <redmine@...>

[#26560] [Feature #2340] Removing YAML/Syck — Yui NARUSE <redmine@...>

[#26563] [Bug #2343] Timeout.timeout doesn't raise Timeout::Error by default — Hongli Lai <redmine@...>

[#26608] code review please — Aaron Patterson <aaron@...>

[#26616] getters and setters for vmode — Roger Pack <rogerdpack@...>

[#26618] [Bug #2345] RDoc improvement for Test::Unit — Andrew Grimm <redmine@...>

[#26623] Re: [ruby-cvs:32896] Ruby:r25678 (trunk): * ext/dl/cptr.c (rb_dlptr_s_malloc, rb_dlptr_initialize): adding — Tanaka Akira <akr@...>

[#26628] [Bug #2346] Array(nil) fails after redefining NilClass.method_missing to throw NoMethodError — Romulo Ceccon <redmine@...>

[#26632] [Feature #2347] Math::INFINITY — Marc-Andre Lafortune <redmine@...>

[#26635] [Feature #2348] RBTree Should be Added to the Standard Library — James Gray <redmine@...>

[#26646] [Bug #2349] lib/bigdecimal: errors in comparisons [patch] — Marc-Andre Lafortune <redmine@...>

[#26650] [Feature #2350] Unicode specific functionality on String in 1.9 — Manfred Stienstra <redmine@...>

[#26652] [Bug #2351] system() hardlinked to /bin/sh — Marcus Franke <redmine@...>

[#26660] [ANN] RubyInstaller Release Candidate 1 - 1.8 and 1.9 releases signed! — Luis Lavena <luislavena@...>

[#26663] [Bug #2352] C:/Ruby/lib/ruby/site_ruby/1.9.1/rubygems.rb:578: [BUG] Segmentation fault ruby 1.9.1p129 (2009-05-12 revision 23412) [i386-mswin32] — Vladimir Sibirskiy <redmine@...>

[#26668] [Bug #2353] hash.c:setenv causes crashes in Solaris — Christian Höltje <redmine@...>

[#26670] [Bug #2354] Undefined BLOCKING_REGION definitions when compiling under MinGW — Luis Lavena <redmine@...>

[#26678] [Bug #2066](Assigned) Merge Latest RDoc/Ri — Yui NARUSE <redmine@...>

[#26679] [Bug #2355] Please update rubygems! — Yusuke Endoh <redmine@...>

[#26680] keys aus der combobox — hamid i. <al_caponeiran@...>

[#26681] [Bug #2357] make install fails due recent Tempfile modifications — Luis Lavena <redmine@...>

[#26693] [Bug #2358] Segmentation fault using dl/import — Luis Adolfo Hernandez Lara <redmine@...>

[#26694] [Bug #2359] test_threads.rb:test_list — Christian Höltje <redmine@...>

[#26695] [Bug #2359] test_threads.rb:test_list — Christian Höltje <redmine@...>

[#26704] Maintainer confirmation process done. — "Yugui (Yuki Sonoda)" <yugui@...>

[#26712] [Bug #2361] "undefined method in 'targetnamespace='" in wsdl/import after upgrading to Snow Leopard/1.8.7 — Bill Gathen <redmine@...>

[#26722] [Bug #2362] undefined variable has value? — Vit Ondruch <redmine@...>

[#26732] [Bug #2363] Syck needs more tests — Aaron Patterson <redmine@...>

[#26733] [Bug #2364] Float conversion of NaN in 1.8.x — Marc-Andre Lafortune <redmine@...>

[#26735] warnings on build — Roger Pack <rogerdpack@...>

[#26736] [Bug #2365] Matrix: poor handling of coercion errors [patch] — Marc-Andre Lafortune <redmine@...>

[#26744] [Bug #2370] Forked process generates spurious signal errors — Chris Schlaeger <redmine@...>

[#26745] [Bug #2371] [BUG] thread_free: locking _mutex must be NULL — Chris Schlaeger <redmine@...>

[#26752] --enabled-shared configure flags/vars — Ryan Davis <ryand-ruby@...>

[#26753] (send #2) cgi.rb cleanup — Ryan Davis <ryand-ruby@...>

[#26761] [Bug #2375] protected singleton methods can be called from other instances — Shugo Maeda <redmine@...>

[#26767] [Bug #2376] Kernel.__method__ rubyspec failures for 1.8.* — Vladimir Sizikov <redmine@...>

[#26771] [Bug #2377] update documentation for IO#eof? — Roger Pack <redmine@...>

[#26772] [Bug #2378] Regression in ParseDate.parsedate('nn-nn') — Vladimir Sizikov <redmine@...>

[#26774] Ruby constant lookup — Yehuda Katz <wycats@...>

[#26787] [Bug #2379] String#[] returns invalid values for short multibyte strings — Alexey Froloff <redmine@...>

[#26788] [Bug #2380] IO#eof? behavior different with 1.9.1p243-mingw32 than other platforms — Ian Dees <redmine@...>

[#26807] [Bug #2382] test_process.rb runs very slowly — Hongli Lai <redmine@...>

[#26808] [Bug #2382] test_process.rb runs very slowly — Hongli Lai <redmine@...>

[#26813] [Bug #2383] windows - calling FreeEnvironmentStrings on envarea invalidates memory in use — Mos Bessus <redmine@...>

[#26814] Weird rubygems behaviour on ruby 1.9.1 — Saimon Moore <saimonmoore@...>

[#26821] [Bug #2384] mkmf find_executable doesn't find batch files in doze — Roger Pack <redmine@...>

[#26837] [Bug #2389] REXML rails to format parsed SVGs created with inkscape — Alexey Froloff <redmine@...>

[#26842] latest test results in mingw — Roger Pack <rogerdpack@...>

[#26852] Internals: #to_s .vs. #to_str? — Kurt Stephens <ks@...>

[#26858] [Bug #2391] in CentOS after some times Ruby 1.9.1 get "segmentation fault" — Salvo Micciché <redmine@...>

[#26867] cref in nil.instance_eval — Shugo Maeda <shugo@...>

[#26868] [Bug #2392] "Date.valid_civil?" issue in p383 — Ozgun Koyun <redmine@...>

[#26869] Caching #to_s for immutables (and a possible future for constant-folding) — Kurt Stephens <ks@...>

[#26877] [Bug #2394] [BUG] pthread_mutex_lock: 22 revisited — Roger Pack <redmine@...>

[#26889] email from redmine — danielcavanagh@...

[#26893] Reproducible crashes on 1.9.2.preview1 and 1.9.2.preview2 — Mikel Lindsaar <raasdnil@...>

[#26894] [Bug #2396] Time.strftime returns a wrong time zone as hour offset (%z) — Chulki Lee <redmine@...>

[#26898] [Bug #2399] pthread_mutex_lock: 22 — Tim Pease <redmine@...>

[#26899] [Bug #2400] string formating in, e. g. rb_raise, is truncated differently depending on OS/build environment — Florian Frank <redmine@...>

[#26909] [Bug #2403] Segment fault when converting method to block — Jan Berdajs <redmine@...>

[#26910] [Bug #2404] [PATCH] force_encoding on frozen string in gem_prelude — Sam Ruby <redmine@...>

[#26923] [Bug #2406] Regression in RSS 2.0 creation — Petteri Räty <redmine@...>

[#26925] [Feature #2408] better error reporting in windows when you try to run a directory — Roger Pack <redmine@...>

[#26931] Re: something broke ruby floats — Ryan Davis <ryand-ruby@...>

[#26526] [Bug #2333] FILE macro should have unicode encoding — Vit Ondruch <redmine@...>

[#26767] [Bug #2376] Kernel.method rubyspec failures for 1.8.* — Vladimir Sizikov <redmine@...>