Showing posts with label ruby-on-rails. Show all posts
Showing posts with label ruby-on-rails. Show all posts

Tuesday, May 27, 2025

Fix: Large file upload tests in a Rails app start failing after bumping rack to 3.0.16

Problem: After bumping the Rack gem in a Rails app from 3.0.14 to 3.0.16, a couple of tests which tested an HTTP POST of a large-ish (~30 MB) PDF file to a controller started failing. Other similar tests, which did not upload a large file, continued passing.

The failure symptom was the POST returning an HTTP 400 Bad Request error. The error was returned before the request made it to any of our application code (as evidenced by none of our breakpoints being hit, or debug statements appearing in the output log).  

For our particular test, the specific error message was: Minitest::Assertion: Expected response to be a <413: payload_too_large>, but was a <400: Bad Request>

Fortunately, there were no other gem dependencies that came with the bump of Rack to 3.0.16. So we knew the problem must be caused by some change in Rack 3.0.15 or 3.0.16. 

Solution: The single item in the rack 3.0.16 release notes did turn out to be the pertinent change:

Security: CVE-2025-46727 Unbounded parameter parsing in Rack::QueryParser can lead to memory exhaustion.

As that linked advisory mentions, a new check is added in rack 3.0.16 that turns away "extremely large" application/x-www-form-urlencoded bodies. From this nist.gov page on CVE-2025-46727, links were available to the fix's specific code changes. From the first linked change, we can see that a "BYTESIZE_LIMIT" of 4194304 (a little over 4 MB) is now imposed on application/x-www-form-urlencoded request bodies. 

Per the mozilla.org page on HTTP POSTapplication/x-www-form-urlencoded is only one possible form Content-Type HTTP header value -- and not the one that is supposed to be used with binary data, such as PDF file uploads! Instead, multipart/form-data should be used.

Our original unit test code was actually not specifying any Content-Type HTTP header value in our test POST request. Changing the test's POST request to additionally send the HTTP header Content-Type: multipart/form-data fixed the problem, and got our test passing once again.

Aside: When I spent a minute during the investigation to ask ChatGPT about this problem -- a POST request failure introduced as of Rack 3.0.16, possibly due to a large request payload -- ChatGPT obligingly hallucinated up a plausible-sounding (but 100% fictional) response about Rack introducing a default limit in POST request payload size, and a corresponding plausible-sounding (but 100% fictional) response about a configuration line to be added to config/applicaiton.rb to override the supposed new behavior. 😂🙄

Friday, December 20, 2024

Getting deep recursion to work in a simple Ruby program on Mac

As part of one of my Advent of Code 2024 solutions, I wrote a small program that included a fairly deep level of recursion. 

When run on my Mac, using Ruby 2.7.2, the program failed to run to completion, generating a stack trace like this (shown in part for brevity):

Traceback (most recent call last):
    3304: from day-16/day-16-part-1-dfs.rb:125:in `<main>'
    3303: from day-16/day-16-part-1-dfs.rb:86:in `explore_map'
    3302: from day-16/day-16-part-1-dfs.rb:86:in `each'
    3301: from day-16/day-16-part-1-dfs.rb:96:in `block in explore_map'
    3300: from day-16/day-16-part-1-dfs.rb:86:in `explore_map'
     ... 3292 levels...
day-16/day-16-part-1-dfs.rb:87:in `key?': stack level too deep (SystemStackError)

I could have fixed this by rewriting my recursive function to use a queue instead, but I wanted to see if I could change my runtime configuration to get my program to run as-is; and I was able to do so! I ended up needing to change TWO things to get the program to run successfully.

First, I needed to increase the system stack size limit for my Mac, for the current terminal session. For my particular program, I needed to set it near my machine's max:

ulimit -s 65520

(The default stack size limit had been 8176.)

Making just that change allowed my program (when run from that terminal session -- not from my IDE) to reach a deeper count of recursions; but it still failed with a similar error:

Traceback (most recent call last):
    10920: from day-16/day-16-part-1-dfs.rb:125:in `<main>'
    10919: from day-16/day-16-part-1-dfs.rb:86:in `explore_map'
    10918: from day-16/day-16-part-1-dfs.rb:86:in `each'
    10917: from day-16/day-16-part-1-dfs.rb:96:in `block in explore_map'
    10916: from day-16/day-16-part-1-dfs.rb:86:in `explore_map'
     ... 10908 levels...

day-16/day-16-part-1-dfs.rb:32:in `hash': stack level too deep (SystemStackError)

Second, I needed to set an environment variable to increase the Ruby VM's maximum allowed stack size. For this "toy" program, I just picked an arbitrary very large value:

export RUBY_THREAD_VM_STACK_SIZE=50000000

With that change also in place, my program was able to successfully run to completion!

I did end up refactoring my solution from using a depth-first search to a breadth-first search, which, in addition to not needing to deal with Ruby's limit on recursion stack depth, was a lot more efficient for solving that particular problem.

I wanted to make a note on what I did, though, so that if I ever face a situation again where I'm bumping up against a Ruby stack depth limit (and a solution other than increasing the limit isn't called for), then I'll be able to remember what I did this last time!

Thursday, April 06, 2023

The Mystery of the NULL Values in a NOT NULL DATETIME MySQL Database Column

My development team at work yesterday picked up a task to investigate a error that was periodically showing up in our production logs:

NoMethodError: undefined method `>' for nil:NilClass

This is a common Ruby error that occurs when you try to call a method on a variable with a value of nil. In this case, the "method" in question was the greater-than operator, ">". 

The line of code associated with the error in question was actually a conditional evaluation that involved 3 separate ">" evaluations, which obscured the exact variable that was the source of the error a bit. 

Two of the three variables in question were attributes of an ActiveRecord model object whose associated database column was defined as NOT NULL. Those attributes were not being re-assigned after being read from the database, so we initially ruled them out as being the possible cause of the error.

However, further investigation revealed that none of the three variables on the problematic line of code could -- in theory -- possibly ever be null. Faced with this, I decided to take a closer look at the actual data in the database.

Our production environment is split into multiple MySQL databases. For purposes of conveniently being able to query customer data across databases all at once, we have an ETL process which extracts (non-sensitive) customer data from the source databases, and populates it all into a single central Snowflake SQL database. 

The database structure of the relevant table (Users) was similar to this (simplified for brevity):

  • id: INT, primary key
  • first_name: VARCHAR(255)
  • last_name: VARCHAR(255)
  • updated_at: DATETIME, NOT NULL

Temporarily putting common sense aside, I queried the snowflake database to see if any of the NOT NULL updated_at values were nevertheless null:

SELECT * FROM Users WHERE updated_at IS null

This returned 0 results, as expected. 

Acting on a hunch, I tried searching for unexpectedly old records; this database has been in service since about 2009:

SELECT * FROM Users WHERE updated_at < '2005-01-01'

This query did produce some results! Out of the tens of thousands of records in the Users table, a few hundred records were returned whose updated_at date was '1970-01-01 00:00' -- a value equal to the start of the epoch in Unix time

At this point I questioned: Does Ruby on Rails and/or ActiveRecord somehow treat start-of-epoch date values of '1970-01-01 00:00' at nil? This seemed unlikely, but I tested it anyway, setting the updated_at value for an existing record in my local machine's copy of the database to that start-of-epoch value; and then reading the record into the corresponding ActiveRecord model object. Not unexpectedly, the updated_at attribute on the model did not end up with a nil value; it had the expected value of midnight on January 1, 1970.

I still felt like I might be onto something here, though. At this point, I wanted to inspect the data in the actual MySQL customer database. I don't have access to the live database, but I was able to access a read-only replica of the database.

Having connected to that MySQL database, I verified that the updated_at column was still defined at NOT NULL; it was. I then ran the same query to look for old values:

SELECT * FROM Users WHERE updated_at < '2005-01-01'

As before, this returned a few records -- about 300. However, I noticed that the actual updated_at values were different. This time, they were returned as '0000-00-00 00:00'. 

Year "0", month "0", day "0" -- all nonexistent values. Feeling a bit of a chill, I re-ran my earlier query to look for records with null values:

SELECT * FROM Users WHERE updated_at IS null

MySQL returned the same 300 records

Cool, cool, coolcoolcool. The evidence indicated that (1) MySQL was allowing values of '0000-00-00 00:00' to be set on a DATETIME, NOT NULL column; and (2) despite the aforementioned NOT NULL restriction on the column, was evaluating such values as being null.

To close the loop, back on my local development machine's database, I set an existing record to the '0000-00-00 00:00' value -- which MySQL happily allowed -- and then, in the Rails console, populated a model object from the record. Sure enough: The updated_at attribute on the record had been assigned a value of nil.

Summary of findings

(1) In a Rails application (and possibly in other languages / frameworks as well), it may not be safe to assume that a value read from a DATETIME, NOT NULL column on a MySQL database is actually guaranteed not to be null. MySQL allows a value of '0000-00-00 00:00' to be set in such columns (despite the NOT NULL restriction); such values are treated as null both my MySQL itself, and by Rails / ActiveRecord.

(2) Although I'm not familiar with its inner workings, that the ETL process from the multiple production MySQL databases to consolidate data into a single Snowflake database couldn't 100.0% be trusted not to change data values. In this case, it silently converted MySQL DATETIME values of '0000-00-00 00:00' to values of '1970-01-01 00:00' 

Mitigations

Doing a bit of additional reading after the fact, I found a StackOverflow post that references a MySQL configuration mode of "NO_ZERO_DATE," which when set, prevents such "zero date values" from being set. 

According to the MySQL documentation, not setting that option may be "more convenient" and/or consume less space. Based on my team's experience here, though, I'd certainly be inclined to take advantage of that NO_ZERO_DATE setting whenever feasible!


Friday, June 28, 2019

Workaround: HTTP 502 "Incomplete response received from application" in Rails app on Phusion Passenger server

I've recently been fighting an intermittent issue in a specific Ruby on Rails app running on a Phusion Passenger web server on my local macOS development machine: HTTP requests to the app would intermittently return the error "Incomplete response received from application" wrapped in a simple h2 element, instead of the desired resource.

When this occurred, I'd also see a message like the following appear in the Phusion Passenger web server log:

App 6510 output: [ 2019-06-27 12:07:49.0318 6510/0x00007f83639eb6f8(HTTP helper worker) utils.rb ]: *** Exception Errno::EBADF (Bad file descriptor) (process 6510, thread 0x00007f83639eb6f8(HTTP helper worker))

Oddly, no one else working on this application saw these errors while running the app on their machines, even though as far as we could tell, we were all running pretty much the exact same environment.

The workaround

 I found that I could get this issue to stop manifesting on my machine by appending the following parameter to my passenger server start-up command:

--spawn-method direct

This resulted in the complete Passenger start command for the application looking like:

bundle exec passenger start --port 3000 --max-pool-size 4 --min-instances 4 --spawn-method direct

Explanation

The key to coming up with this workaround was an article on the Phusion Passenger website: Spawn methods explained (for Ruby developers).

That article talks about how, in order to save memory and improve start-up time, Passenger uses a "spawn method" setting of "smart" for Ruby applications by default. That setting accomplishes that by having multiple server processes share certain objects in memory.

A caveat of the "smart" spawn mode noted by the article is unintentional file descriptor sharing. This caught my attention: Research I'd done on the "EBADF (Bad file descriptor)" error noted that it could be caused when a file descriptor -- that is, a handle pointing to a resource like a local file or a network socket -- is closed, but then accessed again after being closed. If such a handle was being unintentionally shared between web server processes, it does seem entirely plausible that one process could close a handle, then the other process could try to use it for something.

It seemed logical that configuring Passenger to not share objects between processes, via using the "direct" spawn mode setting instead of the "smart" setting, would avoid this. Sure enough, using the "direct" setting did immediately stop the "Incomplete response from application" errors I was seeing in my local environment.  Additionally, running the app on my local machine (with myself as the only user), I didn't observe any meaningful degradation in app performance.

What I'm still unsure about at this point is exactly what specific handle was being incorrectly shared between processes, and why no one else working on this application was having the same error that I was manifest in their environments. Thus, I'm considering this a "workaround" rather than a "solution" for the time being.  (And I'm not committing a change to have the app use the "direct" spawn mode in any environment other than my own.)


Other solutions attempted

Prior to finding the workaround, as all signs pointed to this being some kind of environmental issue with my local machine, I tried to "fix" my environment in quite a few different ways:
  • Use a different client browser
  • Restart the Passenger web server
  • Reboot 
  • Reinstall Ruby 2.6.3
  • Revert to an older Ruby version (2.5.3) using rvm (and uninstall 2.6.3)
  • Reinstall gems via bundle install --force
  • Clone a fresh copy of the Rails application code itself from the remote repository
  • Run the application on a different port (other than 3000)
  • Update the database (mySQL) to the latest patch version
  • Increase the limit of open files per process via ulimit -n 8192
  • Increase the database pool size in database.yml
None of those attempted fixes made a difference; the "Incomplete response received from application" response to HTTP requests, and the "Errno::EBADF (Bad file descriptor)" in the server log continued to manifest.

I had initially suspected the Ruby 2.6.3 upgrade to have something to do with the problem, as I had first started noticing the issue around the time I made that upgrade locally. However, as downgrading to 2.5.3 didn't fix the issue -- and others working on this app were running 2.6.3 with no issues -- I ended up concluding that the 2.6.3 upgrade did not seem to be the direct cause of the issue.

I'd very much like to understand what is actually causing this error in my environment. In the meantime, though, I'm very happy to finally have a viable workaround, so I can get work done again!