Too many successive queries result in DB::ConnectionLost about crystal-pg HOT 4 CLOSED

I tried to reproduce the issue using docker-compose and couldn't reproduce it. So I tried many other things, added another parts of the original program until it finally resurfaced.

I'm sorry, but the underlying issue was in my misuse of destructor, which, in release mode, is called immediately and it closes the connection.

I'm using a connection handling class, which calls @connection = DB.open in constructor and @connection.close in its destructor.

I'm using this approach for 2 years now, so I don and it only started crashing in recent days, so I thought it was caused by adding more and more queries. Now, when I know the real cause, I also remembered that I moved the scope of the connection holding variable from class to method, which crystal can now optimize away completely. When it was initialized as part of the instance, it was properly destroyed after the parent class was destroyed.

See https://github.com/daliborfilus/crystal-pg-issue-230/blob/master/src/main.cr#L13 if you are interested.
(You can try running docker-compose up --build if you have docker installed. Let postgres start first though.)

On line https://github.com/daliborfilus/crystal-pg-issue-230/blob/master/src/main.cr#L54 handle is initialized, but immediately destroyed. What I still don't understand is how adding debug output helps with it. That's kind of a mystery. But oh well.

Sorry for the trouble and for taking your time.

from crystal-pg.

Tried to make the queries smaller - that did not help. It looks like it's really caused by just too many queries in rapid succession , without any break like logging, etc.

Just now I've tried adding small log message above each query and that doesn't help for some reason. It looks like the "puts" operation in between must take longer.

        queries_num = 0
        queries.each do |query_str|
          queries_num += 1
          Log.info { "Running query no. #{queries_num}" }
          affected += tx.connection.exec(query_str).rows_affected
        end
        Log.info { "Affected rows total: #{affected}" }

result in --release mode with this:

2021-06-20T20:40:55.804905Z   INFO - seed: Running seed queries
2021-06-20T20:40:55.806832Z   INFO - seed: Running query no. 1
Unhandled exception:  (DB::ConnectionLost)
  from lib/pg/src/pg/statement.cr:11:5 in 'perform_query'
  from lib/pg/src/pg/statement.cr:35:14 in 'exec'
  from src/gen/actions/seed.cr:46:23 in 'run'
  from src/main.cr:7:1 in '__crystal_main'
  from /snap/crystal/652/share/crystal/src/crystal/main.cr:110:5 in 'main'
  from __libc_start_main
  from _start
  from ???

So it crashes on the query (!). It always crashes, it doesn't allow for even one query to run, ever.

But with debug logging enabled OR in non-release mode it succeds.

from crystal-pg.

from crystal-pg.

It's great you figured out the cause and put it here. Hopefully if anyone else does the same thing, they’ll be able to find it. So thanks for reporting it, even if it wasn't anything in the library itself :)

from crystal-pg.