`middleware_mutex` is racey. #1065

ioquatix · 2019-10-23T09:36:59Z

#!/usr/bin/env ruby

# Taken from faraday internals
def middleware_mutex(&block)
	@middleware_mutex ||= begin
		require 'monitor'
		puts "I'm making a monitor!"
		Monitor.new
	end
	puts @middleware_mutex.inspect
	@middleware_mutex.synchronize(&block)
end


threads = 10.times.collect do
	Thread.new do
		middleware_mutex do
			puts "I got the power!"
		end
	end
end

threads.each(&:join)

Here is example output on 2.6:

koyoko% rvm use 2.6          
Using /home/samuel/.rvm/gems/ruby-2.6.3
^[[A%                                                                                                                                                         koyoko% ./middleware_mutex.rb
I'm making a monitor!
#<Monitor:0x000055fb2217ec60 @mon_mutex=#<Thread::Mutex:0x000055fb2217ec10>, @mon_mutex_owner_object_id=47268548572720, @mon_owner=nil, @mon_count=0>
I got the power!
#<Monitor:0x000055fb2217ec60 @mon_mutex=#<Thread::Mutex:0x000055fb2217ec10>, @mon_mutex_owner_object_id=47268548572720, @mon_owner=nil, @mon_count=0>
I got the power!
#<Monitor:0x000055fb2217ec60 @mon_mutex=#<Thread::Mutex:0x000055fb2217ec10>, @mon_mutex_owner_object_id=47268548572720, @mon_owner=nil, @mon_count=0>
I got the power!
#<Monitor:0x000055fb2217ec60 @mon_mutex=#<Thread::Mutex:0x000055fb2217ec10>, @mon_mutex_owner_object_id=47268548572720, @mon_owner=nil, @mon_count=0>
I got the power!
#<Monitor:0x000055fb2217ec60 @mon_mutex=#<Thread::Mutex:0x000055fb2217ec10>, @mon_mutex_owner_object_id=47268548572720, @mon_owner=nil, @mon_count=0>
I got the power!
#<Monitor:0x000055fb2217ec60 @mon_mutex=#<Thread::Mutex:0x000055fb2217ec10>, @mon_mutex_owner_object_id=47268548572720, @mon_owner=nil, @mon_count=0>
I got the power!
#<Monitor:0x000055fb2217ec60 @mon_mutex=#<Thread::Mutex:0x000055fb2217ec10>, @mon_mutex_owner_object_id=47268548572720, @mon_owner=nil, @mon_count=0>
I got the power!
#<Monitor:0x000055fb2217ec60 @mon_mutex=#<Thread::Mutex:0x000055fb2217ec10>, @mon_mutex_owner_object_id=47268548572720, @mon_owner=nil, @mon_count=0>
I got the power!
#<Monitor:0x000055fb2217ec60 @mon_mutex=#<Thread::Mutex:0x000055fb2217ec10>, @mon_mutex_owner_object_id=47268548572720, @mon_owner=nil, @mon_count=0>
I got the power!
#<Monitor:0x000055fb2217ec60 @mon_mutex=#<Thread::Mutex:0x000055fb2217ec10>, @mon_mutex_owner_object_id=47268548572720, @mon_owner=nil, @mon_count=0>
I got the power!
koyoko% ./middleware_mutex.rb
I'm making a monitor!
I'm making a monitor!
#<Monitor:0x000055f197e82388 @mon_mutex=#<Thread::Mutex:0x000055f197e82338>, @mon_mutex_owner_object_id=47248062026180, @mon_owner=nil, @mon_count=0>
I got the power!
I'm making a monitor!
#<Monitor:0x000055f197e81eb0 @mon_mutex=#<Thread::Mutex:0x000055f197e81e60>, @mon_mutex_owner_object_id=47248062025560, @mon_owner=nil, @mon_count=0>
I got the power!
I'm making a monitor!
#<Monitor:0x000055f197e81b90 @mon_mutex=#<Thread::Mutex:0x000055f197e81b40>, @mon_mutex_owner_object_id=47248062025160, @mon_owner=nil, @mon_count=0>
I got the power!
I'm making a monitor!
#<Monitor:0x000055f197e81938 @mon_mutex=#<Thread::Mutex:0x000055f197e818e8>, @mon_mutex_owner_object_id=47248062024860, @mon_owner=nil, @mon_count=0>
I got the power!
I'm making a monitor!
#<Monitor:0x000055f197e816e0 @mon_mutex=#<Thread::Mutex:0x000055f197e81690>, @mon_mutex_owner_object_id=47248062024560, @mon_owner=nil, @mon_count=0>
I got the power!
#<Monitor:0x000055f197e827c0 @mon_mutex=#<Thread::Mutex:0x000055f197e82590>, @mon_mutex_owner_object_id=47248062026720, @mon_owner=nil, @mon_count=0>
I got the power!
I'm making a monitor!
#<Monitor:0x000055f197e81438 @mon_mutex=#<Thread::Mutex:0x000055f197e813e8>, @mon_mutex_owner_object_id=47248062024220, @mon_owner=nil, @mon_count=0>
I got the power!
I'm making a monitor!
#<Monitor:0x000055f197e811e0 @mon_mutex=#<Thread::Mutex:0x000055f197e81190>, @mon_mutex_owner_object_id=47248062023920, @mon_owner=nil, @mon_count=0>
I got the power!
I'm making a monitor!
#<Monitor:0x000055f197e80f88 @mon_mutex=#<Thread::Mutex:0x000055f197e80f38>, @mon_mutex_owner_object_id=47248062023620, @mon_owner=nil, @mon_count=0>
I got the power!
I'm making a monitor!
#<Monitor:0x000055f197e80d30 @mon_mutex=#<Thread::Mutex:0x000055f197e80ce0>, @mon_mutex_owner_object_id=47248062023320, @mon_owner=nil, @mon_count=0>
I got the power!

Here is example output on jruby:

koyoko% rvm use jruby        
Using /home/samuel/.rvm/gems/jruby-9.2.6.0
koyoko% ./middleware_mutex.rb
I'm making a monitor!
I'm making a monitor!
I'm making a monitor!
#<Monitor:0x7ea668b0 @mon_mutex=#<Thread::Mutex:0x3027cbd3>, @mon_owner=nil, @mon_count=0>
I got the power!
I'm making a monitor!I'm making a monitor!#<Monitor:0x53ca91a5 @mon_mutex=#<Thread::Mutex:0x57f50f04>, @mon_owner=nil, @mon_count=0>I'm making a monitor!
#<Monitor:0x1b5e79ce @mon_mutex=#<Thread::Mutex:0x159994d5>, @mon_owner=nil, @mon_count=0>
I got the power!
#<Monitor:0x67589eb3 @mon_mutex=#<Thread::Mutex:0x63671680>, @mon_owner=nil, @mon_count=1>#<Monitor:0x1b5e79ce @mon_mutex=#<Thread::Mutex:0x159994d5>, @mon_owner=nil, @mon_count=0>
I got the power!
#<Monitor:0x67589eb3 @mon_mutex=#<Thread::Mutex:0x63671680>, @mon_owner=nil, @mon_count=0>
I got the power!

#<Monitor:0x49c2c95a @mon_mutex=#<Thread::Mutex:0xcc04e06>, @mon_owner=nil, @mon_count=0>
I got the power!

I'm making a monitor!#<Monitor:0x1b5e79ce @mon_mutex=#<Thread::Mutex:0x159994d5>, @mon_owner=nil, @mon_count=0>
#<Monitor:0x6fa38df1 @mon_mutex=#<Thread::Mutex:0x756e0d98>, @mon_owner=nil, @mon_count=0>
I got the power!
I got the power!

#<Monitor:0x4a9f0f52 @mon_mutex=#<Thread::Mutex:0x600dfde7>, @mon_owner=nil, @mon_count=0>

I got the power!

I got the power!
I got the power!

The text was updated successfully, but these errors were encountered:

ioquatix · 2019-10-23T09:38:12Z

If you run this on JRuby, @middleware_mutex ||= begin is not atomic and you not only end up executing the block multiple times, @middleware_mutex actually gets set several times to different monitors. Looks like this can also happen on 2.6 since puts can introduce blocking/thread context switch.

olleolleolle · 2019-10-23T11:02:02Z

Thanks for analysis!

eregon · 2019-10-26T10:49:34Z

It's quite interesting to see ||= doesn't guarantee single assignment, even on MRI.

ioquatix · 2019-10-26T10:50:27Z

@eregon Yeah, I was surprised by that too. Can we dump the instructions to see what is actually going on?

eregon · 2019-10-26T11:14:40Z

@ioquatix

$ xsel -b | ruby --dump=insns
...
== disasm: #<ISeq:middleware_mutex@-:1 (1,0)-(9,3)> (catch: FALSE)
local table (size: 1, argc: 0 [opts: 0, rest: -1, post: 0, block: 0, kw: -1@-1, kwrest: -1])
[ 1] block@0<Block>
0000 putnil                                                           (   2)[LiCa]
0001 defined                      instance-variable, :@middleware_mutex, false
0005 branchunless                 14
0007 getinstancevariable          :@middleware_mutex, <is:0>
0010 dup
0011 branchif                     42
0013 pop
0014 putself                                                          (   3)[Li]
0015 putstring                    "monitor"
0017 opt_send_without_block       <callinfo!mid:require, argc:1, FCALL|ARGS_SIMPLE>, <callcache>
0020 pop
0021 putself                                                          (   4)[Li]
0022 putstring                    "I'm making a monitor!"
0024 opt_send_without_block       <callinfo!mid:puts, argc:1, FCALL|ARGS_SIMPLE>, <callcache>
0027 pop
0028 opt_getinlinecache           35, <is:1>                          (   5)[Li]
0031 getconstant                  :Monitor
0033 opt_setinlinecache           <is:1>
0035 opt_send_without_block       <callinfo!mid:new, argc:0, ARGS_SIMPLE>, <callcache>
0038 dup                                                              (   2)
0039 setinstancevariable          :@middleware_mutex, <is:0>
0042 pop
0043 putself                                                          (   7)[Li]
0044 getinstancevariable          :@middleware_mutex, <is:0>
0047 opt_send_without_block       <callinfo!mid:inspect, argc:0, ARGS_SIMPLE>, <callcache>
0050 opt_send_without_block       <callinfo!mid:puts, argc:1, FCALL|ARGS_SIMPLE>, <callcache>
0053 pop
0054 getinstancevariable          :@middleware_mutex, <is:0>          (   8)[Li]
0057 getblockparamproxy           block@0, 0
0060 send                         <callinfo!mid:synchronize, argc:0, ARGS_BLOCKARG>, <callcache>, nil
0064 leave                                                            (   9)[Re]

So ||= is like:

if defined?(@middleware_mutex)
  @middleware_mutex
else
  @middleware_mutex = expression
end

To make it not override in MRI we'd need:

if defined?(@middleware_mutex)
  @middleware_mutex
else
  result = expression
  # special bytecode to do `@middleware_mutex = result unless defined?(@middleware_mutex)` atomically
end

Of course that has a cost as it's an extra check before assigning.

And the block would still execute multiple times, trying to fix that automatically would likely lead to deadlock and high overhead, so that part is best left to user code.

ioquatix · 2019-10-26T11:16:03Z

Oh, I totally agree this isn't something we can fix automatically, the code is horribly broken from the POV of thread safety and making ||= atomic won't fix that.

iMacTia · 2019-10-30T17:40:33Z

Wow thanks for the analysis @ioquatix and once again your expertise around this topic can clearly be seen.
That is, as far as I know, quite an old piece of code which I guess was introduced specifically to support JRuby and other concurrent ruby implementations.

Today, we don't officially support JRuby and other non-MRI rubies anymore, mostly because I think we lack the necessary knowledge to do so, but we just left that untouched in the hope it would at least help.

I'm not really sure how to tackle this, if you or @eregon could point us in the right direction I'd be happy to gain some knowledge and have a look 🤓

ioquatix · 2019-10-30T19:08:46Z

This is also a bug on CRuby. I can submit a PR.

technoweenie · 2019-11-13T18:50:56Z

I tried one solution in #1074. I have another idea that involves converting the MiddlewareRegistry module into a class. So instead of this:

faraday/lib/faraday/response.rb

Lines 26 to 28 in d51a6c6

    
           register_middleware File.expand_path('response', __dir__), 
        
                               raise_error: [:RaiseError, 'raise_error'], 
        
                               logger: [:Logger, 'logger']

It could be something like:

module Faraday
  class Response
    self.middleware_registry = MiddlewareRegistry.new(File.expand_path('response', __dir__),
      raise_error: [:RaiseError, 'raise_error'],
      logger: [:Logger, 'logger'],
    )

This doesn't rely on class lifecycle hooks. It's pretty clear that MiddlewareRegistry is being instantiated here when the ruby is being interpreted.

class MiddlewareRegistry
  def initialize
    @mutex = Monitor.new
  end
end

technoweenie linked a pull request Nov 13, 2019 that will close this issue

Set middleware_mutex when middleware/adapter classes are defined #1074

Draft

mollerhoj mentioned this issue Oct 8, 2021

Register json middleware #1331

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

`middleware_mutex` is racey. #1065

`middleware_mutex` is racey. #1065

ioquatix commented Oct 23, 2019 •

edited

Loading

ioquatix commented Oct 23, 2019 •

edited

Loading

olleolleolle commented Oct 23, 2019

eregon commented Oct 26, 2019

ioquatix commented Oct 26, 2019

eregon commented Oct 26, 2019 •

edited

Loading

ioquatix commented Oct 26, 2019

iMacTia commented Oct 30, 2019

ioquatix commented Oct 30, 2019

technoweenie commented Nov 13, 2019

middleware_mutex is racey. #1065

middleware_mutex is racey. #1065

Comments

ioquatix commented Oct 23, 2019 • edited Loading

ioquatix commented Oct 23, 2019 • edited Loading

olleolleolle commented Oct 23, 2019

eregon commented Oct 26, 2019

ioquatix commented Oct 26, 2019

eregon commented Oct 26, 2019 • edited Loading

ioquatix commented Oct 26, 2019

iMacTia commented Oct 30, 2019

ioquatix commented Oct 30, 2019

technoweenie commented Nov 13, 2019

`middleware_mutex` is racey. #1065

`middleware_mutex` is racey. #1065

ioquatix commented Oct 23, 2019 •

edited

Loading

ioquatix commented Oct 23, 2019 •

edited

Loading

eregon commented Oct 26, 2019 •

edited

Loading