Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

middleware_mutex is racey. #1065

Open
ioquatix opened this issue Oct 23, 2019 · 9 comments · May be fixed by #1074
Open

middleware_mutex is racey. #1065

ioquatix opened this issue Oct 23, 2019 · 9 comments · May be fixed by #1074

Comments

@ioquatix
Copy link
Contributor

ioquatix commented Oct 23, 2019 •
edited 

#!/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!
@ioquatix
Copy link
Contributor Author

ioquatix commented Oct 23, 2019 •
edited

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
Copy link
Member

Thanks for analysis!

@eregon
Copy link

eregon commented Oct 26, 2019

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

@ioquatix
Copy link
Contributor Author

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

@eregon
Copy link

eregon commented Oct 26, 2019 •
edited

@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
Copy link
Contributor Author

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
Copy link
Member

iMacTia commented Oct 30, 2019

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
Copy link
Contributor Author

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

@technoweenie technoweenie linked a pull request Nov 13, 2019 that will close this issue
Draft
@technoweenie
Copy link
Member

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

@mollerhoj mollerhoj mentioned this issue Oct 8, 2021
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Set middleware_mutex when middleware/adapter classes are defined lostisland/faraday
5 participants
@technoweenie @olleolleolle @ioquatix @eregon @iMacTia