Rails - Feb 2008 - random exception driving me crazy: SecurityError (Insecure: can't modify array)

Hi all, I''m running into a very strange but incredibly annoying
problem that I just can''t seem to solve.

The exception is occurring from a seemingly innocuous line in my code,
a simple ''logger.warn("some debug information")''. 
The backtrace
follows:

SecurityError (Insecure: can''t modify array)
       
[RAILS_ROOT]/vendor/rails/activesupport/lib/active_support/buffered_logger.rb:68:in
`<<''
       
[RAILS_ROOT]/vendor/rails/activesupport/lib/active_support/buffered_logger.rb:68:in
`add''
       
[RAILS_ROOT]/vendor/rails/activesupport/lib/active_support/buffered_logger.rb:75:in
`warn''
        [RAILS_ROOT]/app/models/order.rb:244:in
`process_with_active_merchant''
       
[RAILS_ROOT]/vendor/plugins/acts_as_state_machine/lib/acts_as_state_machine.rb:162:in
`call''

The line in my model class, order.rb, that causes the exception is the
following:

logger.warn("Processing order with payment gateway")

Now, I could probably just remove the offending log line to fix the
problem, but this bothers me, since it may point to a larger problem
that I''m not aware of, which I ''d rather not ignore.  What
makes this
problem even more difficult to solve is that it doesn''t happen
consistently and is very difficult to reproduce.  It seems to only
happen after my mongrel instances have been running for a few hours
and are each using over 100 megs of memory (maybe there''s some memory
leak or thrashing or something that''s causing this to happen). 
I''ve
googled for the error and can''t seem to find much information, nor why
it would be thrown from a Rails standard library file.  I''ve tested
this both on edge Rails 8117 and also a more recent edge Rails 8927
with no difference.

When I restart my mongrel cluster, everything works fine, orders are
processed, no exceptions are thrown.  But after a few hours,  maybe a
day of running on the production site, I start getting the
''SecurityError (Insecure: can''t modify array)''
message as described
above (it happens at the same place each time)

My next guess is that it could possibly have something to do with
using acts_as_state_machine, which I''m going to remove and see if it
changes anything.

If anyone has any suggestions or advice, please let me know.  I''ve
been trying to fix this for over a week and haven''t made any progress.

For those interested, the following is the code that leads up to the
error.  It''s pretty simple stuff, we attempt to save the order, and in
an after_create method in the Order model, we charge the user''s credit
card (using a transition from acts_as_state_machine).  If we can
charge it successfully, we save the order, otherwise, we raise an
exception and display an error message to the user.

orders_controller.rb

def create
  # populate order details (ommitted for brevity)

  begin
    if @order.save
      # display successful message, redirect somewhere
    else
      # user probably forgot to enter some info, display error message
    end
  rescue
    # if we get here, then an exception must have been raised while
    # processing the credit card with active merchant
    logger.warn("Error occurred while attempting to save order")
    # render some page with warning message
  end
end


order.rb

# we use acts_as_state_machine to provide order state
acts_as_state_machine :initial => :pending, :column => :status

# order has been created, but no payment has been received
state :pending

# process the payment with active_merchant
state :processing_payment, :after => :process_with_active_merchant

# charge the user''s credit card
event :process_payment do
  transitions :from => :pending, :to => :processing_payment
end


def after_create
  # the following method raises an exception if we fail to charge the users
  # credit card, prevents the order from being saved.
  self.process_payment!

  # some other post-processing tasks
  self.send_order_to_distributor!

  self.complete!
end

def process_with_active_merchant
  # the following line causes a SecurityError (Insecure: can''t modify
array) exception
  logger.warn("Processing order with payment gateway")

  gateway = ActiveMerchant::Billing::AuthorizedNetGateway.new({:login
=> API_LOGIN_ID, :password => TRANSACTION_KEY})

  response = gateway.purchase(self.total_price, @credit_card, options)

  if response.success?
    logger.warn("Successfully charged credit card with
#{self.total_price}: #{response.message}")
    self.transaction_id = response.authorization
    self.save
  else
    logger.warn("Failed to charge credit card")
    raise
OrderFailedException.new(response.params[''response_reason_code'']),
response.message
  end

end


Thanks,

Mike

--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en
-~----------~----~----~----~------~----~------~--~---

Hey Mike,

Any update on this? I''m seeing something similar as well with
acts_as_state_machine


?


Mike Garey wrote:
> Hi all, I''m running into a very strange but incredibly annoying
> problem that I just can''t seem to solve.
> 
> The exception is occurring from a seemingly innocuous line in my code,
> a simple ''logger.warn("some debug
information")''.  The backtrace
> follows:
-- 
Posted via http://www.ruby-forum.com/.

--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en
-~----------~----~----~----~------~----~------~--~---

On Wed, Feb 27, 2008 at 9:53 PM, Mike Garey
<random52k-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org>
wrote:
> Hi all, I''m running into a very strange but incredibly annoying
> problem that I just can''t seem to solve.
>
> The exception is occurring from a seemingly innocuous line in my code,
> a simple ''logger.warn("some debug
information")''.  The backtrace
> follows:
>
> SecurityError (Insecure: can''t modify array)
>       
[RAILS_ROOT]/vendor/rails/activesupport/lib/active_support/buffered_logger.rb:68:in
> `<<''
>       
[RAILS_ROOT]/vendor/rails/activesupport/lib/active_support/buffered_logger.rb:68:in
> `add''
>       
[RAILS_ROOT]/vendor/rails/activesupport/lib/active_support/buffered_logger.rb:75:in
> `warn''
>        [RAILS_ROOT]/app/models/order.rb:244:in
`process_with_active_merchant''
>       
[RAILS_ROOT]/vendor/plugins/acts_as_state_machine/lib/acts_as_state_machine.rb:162:in
> `call''
>
> The line in my model class, order.rb, that causes the exception is the
> following:
>
> logger.warn("Processing order with payment gateway")
>
> Now, I could probably just remove the offending log line to fix the
> problem, but this bothers me, since it may point to a larger problem
> that I''m not aware of, which I ''d rather not ignore. 
What makes this
> problem even more difficult to solve is that it doesn''t happen
> consistently and is very difficult to reproduce.

Rehashing an old message. I found a solution to this a while ago but
never responded to my original message.  Well, better late than never!
 Hopefully this will help someone in the future from wasting the
amount of time that I did.

The problem turned out to be a bug with using self.method(action).call
in acts_as_state_machine.  To fix it, I removed
self.method(action).call from run_transition_action(action) method in
acts_as_state_machine.rb, and replaced it with self.send(action),
since self.method(action) was causing the SecurityError (Insecure:
can''t modify array).

Here''s two other links from people who have run into the same problem
in the past:

http://cmms.norfello.com/cmms/ticket/445
http://code.google.com/p/dry-scaffold/source/browse/dry_scaffold/CHANGELOG

This issue existed in revision 66 of the acts_as_state_machine from here:

http://elitists.textdriven.com/svn/plugins/acts_as_state_machine/trunk/lib/acts_as_state_machine.rb

I''m not sure if it still exists in the github version.


Mike

--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk+unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en
-~----------~----~----~----~------~----~------~--~---