When someone on my Mailchimp site signs up, a webhook sends that data to my backend Rails API. Today something strange happened, and I’m not sure if it’s a Puma setting or something in Render worth investigating. All times are CDT.
Explaining what happened
At 8:32 AM, this line shows up in the logs indicating Puma Worker 1 booted. I guess it goes to sleep if it doesn’t see traffic very often? I’m not sure what caused this. But a similar line reappears later…
At 5:40 PM, a person signed up on my Mailchimp site, and three lines in the logs show that my backend received it the webhook. But my controller logic never executed and didn’t return any status code. The fourth line at the same time indicates that Puma Worker 1 booted. I suspect this action is to blame for the request not executing my code and not sending a response.
When Mailchimp doesn’t get a 200 OK response, they’ll try again later.
At 6:05 PM, the request came in again (retry from Mailchimp), and this time my controller logic ran and returned 200 OK.
Log output (edited for brevity)
Aug 30 08:32:19 AM [69] - Worker 1 (PID: 162) booted in 0.01s, phase: 0
Aug 30 05:40:10 PM INFO -- : [c258] Started POST "/mailchimp" for 172.11.22.123 at 2022-08-30 22:40:10 +0000
Aug 30 05:40:10 PM INFO -- : [c258] Processing by MailchimpController#webhook as HTML
Aug 30 05:40:10 PM INFO -- : [c258] Parameters: {"type"=>"subscribe", "fired_at"=>"2022-08-30 22:40:09", "data"=>{"id"=>"a778e", "email"=>"hey@example.com", "email_type"=>"html", "ip_opt"=>"200.99.222.33", "web_id"=>"29873"}}
Aug 30 05:40:10 PM [69] - Worker 1 (PID: 176) booted in 0.01s, phase: 0
Aug 30 06:05:11 PM INFO -- : [3e28] Started POST "/mailchimp" for 172.11.22.123 at 2022-08-30 22:40:10 +0000
Aug 30 06:05:11 PM INFO -- : [3e28] Processing by MailchimpController#webhook as HTML
Aug 30 06:05:11 PM INFO -- : [3e28] Parameters: {"type"=>"subscribe", "fired_at"=>"2022-08-30 23:05:10", "data"=>{"id"=>"a778e", "email"=>"hey@example.com", "email_type"=>"html", "ip_opt"=>"200.99.222.33", "web_id"=>"29873"}}
Aug 30 06:05:11 PM INFO -- : [3e28] Completed 200 OK in 440ms (ActiveRecord: 68.0ms | Allocations: 11288)
Question
It appears that somehow Puma is interfering with my app as indicated by this log line: Worker 1 (PID: XYZ) booted in 0.01s, phase: 0. Would you know if this kind of behavior is something I could fix in my Puma settings, or could it be something Render is doing?
Sometimes my server doesn’t see any activity for over 24 hours. So I think it’s Puma doing something, or Render trying to conserve resources and Puma is just responding.
