SystemStackError on selecting records from MySQL

[tokichie]

I'm using rom as ORM with Hanami. Recently, I noticed that sometimes server hanged up raising SystemStackError. I dug into stack trace, and found that auto_curry method was called too many times.

Here is part of the trace:

SystemStackError: stack level too deep
  from rom/sql/relation.rb:64:in `by_pk'
  from rom/auto_curry.rb:48:in `block (2 levels) in auto_curry'
         : 509 times in total
  from rom/auto_curry.rb:48:in `block (2 levels) in auto_curry'
  from lib/lf_webapp/repositories/tenants_user_repository.rb:7:in `find'

And here is the caller:

5  def find(tenant_uuid, user_uuid)
6    tenants_users  # tenants_users is the intermediate table for many_to_many association
7      .by_pk(tenant_uuid, user_uuid)
8      .one
9  end

Things that I know at this point are:

• The error seems to happen at selecting records from table with composite primary keys
• The error occurs at certain timing after restarting server. Once occurred, it doesn't become normal unless restarting. (requesting count or memory usage may be related?)
• The error hasn't occurred in local environment.
• Invoking tenants_user_repository.find method calls auto_curry only once in local env.

Here is the environment:

• Server: AWS Elastic Container Service on two t2.micro instances with load balancing
• Deployment: create docker container in CircleCI and push container image to ECS registry
• Database: AWS RDS t2.micro instance running MySQL 5.7

Versions:

ruby 2.5.1
hanami 1.2.0
sequel 5.6.0
rom 4.1.3
rom-changeset 1.0.1
rom-core 4.1.2
rom-mapper 1.1.0
rom-repository 2.0.2
rom-sql 2.4.0

[tokichie]

I found that ancestor stack of relation class increased by every request. I got logs by adding logging code into auto_curry.rb.

46      response =
47        if arity < 0 || arity == args.size
48          p self.class.ancestors
49          super(*args, &mblock)
50        else
51          self.class.curried.new(self, view: name, curry_args: args, arity: arity)
52        end

immediately after restarting puma: Only 5 modules are created above LfWebapp::Relations::TenantsUsers.

[#<Module:0x00007f91249883e0>, #<Module:0x00007f91183a08f8>, #<Module:0x00007f91247553e8>, #<Module:0x00007f91180bc1f0>, #<Module:0x0000000005a6df88>, LfWebapp::Relations::TenantsUsers, #<Module:0x00007f91183b8b88>, #<ROM::Plugins::Relation::RegistryReader:0x00007f912495e298>, #<Module:0x00007f91249346f0>, #<ROM::Plugins::Relation::RegistryReader:0x00007f9124929b60>, #<Module:0x00007f91180be9f0>, #<ROM::Plugins::Relation::RegistryReader:0x0000000005dde7a8>, #<Module:0x00007f91246f5c40>, #<ROM::Plugins::Relation::RegistryReader:0x00007f91246ebd08>, #<Module:0x0000000005a71e30>, ROM::Plugins::Relation::Changeset::InstanceMethods, #<ROM::Plugins::Relation::RegistryReader:0x000000000596ebf0>, Dry::Initializer::Mixin::Local[LfWebapp::Relations::TenantsUsers], #<Module:0x00000000047df038>, #<Module:0x00000000047df308>, ROM::SQL::Relation, ROM::SQL::Relation::Reading, ROM::SQL::Relation::Writing, ROM::SQL, Dry::Initializer::Mixin::Local[ROM::SQL::Relation], #<Module:0x0000000002b77cd8>, #<Module:0x000000000343f4b0>, #<Module:0x00000000061c0e98>, #<Module:0x00000000024293f0>, #<ROM::Memoizable::Memoizer:0x0000000002540130>, ROM::Relation, ROM::Pipeline, ROM::Pipeline::Operator, ROM::Relation::Materializable, Dry::Equalizer::Methods, #<Dry::Equalizer:0x0000000002b5e508>, ROM::Memoizable, ROM::Relation::Commands, ROM::Initializer::InstanceMethods, Dry::Initializer::Mixin::Root, Dry::Initializer::Mixin::Local[ROM::Relation], Object, PP::ObjectMixin, JSON::Ext::Generator::GeneratorMethods::Object, Kernel, BasicObject]

after several requests from restarting puma: 26 modules are created above LfWebapp::Relations::TenantsUsers.

[#<Module:0x00000000043a6e80>, #<Module:0x0000000005686ac8>, #<Module:0x00007f73a08a0910>, #<Module:0x00007f73a09e44e8>, #<Module:0x0000000005d6eac0>, #<Module:0x00007f73a0b14d18>, #<Module:0x00007f73a0b37ca0>, #<Module:0x00007f73a0773c18>, #<Module:0x00007f73941290a8>, #<Module:0x00000000059eee90>, #<Module:0x0000000005a39a30>, #<Module:0x00007f73942e6fa8>, #<Module:0x00007f7394309990>, #<Module:0x0000000005c1d040>, #<Module:0x00007f73a05f9a68>, #<Module:0x00007f739428fb40>, #<Module:0x00007f73944c9a28>, #<Module:0x0000000005a5fa78>, #<Module:0x00007f73a067bc20>, #<Module:0x00007f73942aa710>, #<Module:0x00007f739454f6f0>, #<Module:0x0000000004bab478>, #<Module:0x00007f73944ef598>, #<Module:0x00007f73a08586d8>, #<Module:0x00007f73941d7180>, #<Module:0x00007f73a04de930>, LfWebapp::Relations::TenantsUsers, #<Module:0x00000000046d2f00>, #<ROM::Plugins::Relation::RegistryReader:0x00000000047d7a68>, #<Module:0x000000000575d820>, #<ROM::Plugins::Relation::RegistryReader:0x000000000579dd80>, #<Module:0x00007f73a0931500>, #<ROM::Plugins::Relation::RegistryReader:0x00007f7394354c88>, #<Module:0x00007f73944580d0>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73a0a16740>, #<Module:0x0000000005d9ff30>, #<ROM::Plugins::Relation::RegistryReader:0x0000000005e41df8>, #<Module:0x00007f7394653858>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73946715b0>, #<Module:0x00007f739467ec60>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73a0b3d330>, #<Module:0x00007f73a079f070>, #<ROM::Plugins::Relation::RegistryReader:0x00007f7394108bf0>, #<Module:0x00007f73a07d5f58>, #<ROM::Plugins::Relation::RegistryReader:0x00007f7394166b88>, #<Module:0x0000000005a44200>, #<ROM::Plugins::Relation::RegistryReader:0x0000000005a60f90>, #<Module:0x0000000005a77a10>, #<ROM::Plugins::Relation::RegistryReader:0x0000000005adaa70>, #<Module:0x00007f7394315128>, #<ROM::Plugins::Relation::RegistryReader:0x00007f739432ab90>, #<Module:0x00007f73a090c570>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73a0915440>, #<Module:0x0000000005c44fc8>, #<ROM::Plugins::Relation::RegistryReader:0x0000000005cc0d08>, #<Module:0x00007f73a063ff68>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73a06582c0>, #<Module:0x00007f739429ec80>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73942b3590>, #<Module:0x00007f73a0a31360>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73944e2208>, #<Module:0x0000000005a636a0>, #<ROM::Plugins::Relation::RegistryReader:0x0000000005aae3a8>, #<Module:0x00007f73a068b6e8>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73a06a82c0>, #<Module:0x00007f73942b0f20>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73942cc108>, #<Module:0x00007f73a010e3f0>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73a00f5f58>, #<Module:0x00007f739450fb90>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73a00d96f0>, #<Module:0x00007f73a0a307a8>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73944c95f0>, #<Module:0x00007f73941ef140>, #<ROM::Plugins::Relation::RegistryReader:0x00007f73941e3b60>, #<Module:0x00007f73a0812610>, #<ROM::Plugins::Relation::RegistryReader:0x0000000005a21548>, #<Module:0x0000000005f4b1b8>, ROM::Plugins::Relation::Changeset::InstanceMethods, #<ROM::Plugins::Relation::RegistryReader:0x00007f73a04ad498>, Dry::Initializer::Mixin::Local[LfWebapp::Relations::TenantsUsers], #<Module:0x000000000462bb60>, #<Module:0x000000000462be30>, ROM::SQL::Relation, ROM::SQL::Relation::Reading, ROM::SQL::Relation::Writing, ROM::SQL, Dry::Initializer::Mixin::Local[ROM::SQL::Relation], #<Module:0x0000000005fe64d8>, #<Module:0x000000000291cee8>, #<Module:0x0000000003ae5800>, #<Module:0x0000000002085258>, #<ROM::Memoizable::Memoizer:0x0000000002256c80>, ROM::Relation, ROM::Pipeline, ROM::Pipeline::Operator, ROM::Relation::Materializable, Dry::Equalizer::Methods, #<Dry::Equalizer:0x000000000298a420>, ROM::Memoizable, ROM::Relation::Commands, ROM::Initializer::InstanceMethods, Dry::Initializer::Mixin::Root, Dry::Initializer::Mixin::Local[ROM::Relation], Object, PP::ObjectMixin, JSON::Ext::Generator::GeneratorMethods::Object, Kernel, BasicObject]

FYI, the query log is here:

(0.015262s) SELECT `tenants_users`.`tenant_uuid`, `tenants_users`.`user_uuid`, `tenants_users`.`role` FROM `tenants_users` WHERE ((`tenants_users`.`tenant_uuid` = 'development') AND (`tenants_users`.`user_uuid` = 'e960083f-ffc3-43d0-a7ff-b34716fad1fe')) ORDER BY `tenants_users`.`tenant_uuid`, `tenants_users`.`user_uuid`

[solnic]

@tokichie how do you run this app locally? also via puma?

[tokichie]

@solnic Yes. Also using puma locally (via bundle exec hanami server) Here is puma.rb

#!/usr/bin/env puma

app_path = File.expand_path '../../', __FILE__
run_dir = ENV['HANAMI_ENV'] == 'development' ? '/tmp' : '/var/run'

environment ENV['HANAMI_ENV']
pidfile "#{run_dir}/puma.pid"
state_path "#{run_dir}/puma.state"
threads 0, 16
bind "unix://#{run_dir}/puma.sock"

[tokichie]

@solnic I found the root cause of this. That is calling auto_registration multiple times in app (more particulary, requiring relation classes more than once).

I adopt multi-tenancy model for my app, so database is created for each tenant. On the other hand, account database is shared. Here is database structure:

mysql> show databases;
+--------------------------------------+
| Database                             |
+--------------------------------------+
| account                              | (only one account database, storing list of tenants, users)
| 1d6fc7d3_650b_476b_8175_91fc1f8a4fde | (one of tenant database, named by uuid of tenant)
| 22d6e05f_6201_477a_bc17_d352f0b5688a |
| ab6cebe7_194c_406f_8cdb_c318ed3bed5e |
  :
  :

This means that I should re-create rom container with 2 gateways to account DB and tenant DB for each request according to credentials. So auto_registration is called in every request. This results in increasing call stack of auto_curry.

I prepare the reproduction code: https://gist.github.com/tokichie/defffdf68f54167954161cc01e493812

[solnic]

@tokichie you should not setup rom at run-time, esp that it's probably not thread-safe. What you can do instead, is setting up a basic configuration and then recreate it on each request, ie like this:

# when booting
rom_base = ROM::Configuration.new(your_base_opts)
rom_base.auto_registration(...)

# at run-time (this assumes you made `rom_base` available somehow)
rom_config = ROM::Configuration.new(your_base_opts)
rom_config.register_relation(*rom_base.relation_classes) # do it with other components if you have them too
rom = ROM.container(rom_config)

[tokichie]

@solnic Thank you for work around. I try to use it.

[tokichie]

I applied the workaround to reproduction code, but output didn't change. Something wrong? Updated gist: https://gist.github.com/tokichie/defffdf68f54167954161cc01e493812

[solnic]

@tokichie hmm damn, I'll have to debug this. Thanks for the gist. I'll get back to you.