sqitch deploy hangs with no output

[Kinrany]

I ran into a problem with sqitch deploy hanging forever with no output, even with -VVV. This is likely due to an unknown third party error, but it'd be nice to be able to know what exactly it is sqitch is waiting for.

v1.1.0, running in a container equivalent to:

FROM debian:11.9-slim
RUN apt-get update && apt-get install -y sqitch libdbd-mysql-perl mariadb-client

[theory]

It's almost certainly waiting on your database CLI. Can you set an environment variable or mysql config file variable to enable shell logging and debugging.

[Kinrany]

I'll try that, thanks.

Might make sense to pass the --verbose flag to the CLI at one of the three sqitch verbosity levels? Assuming database clients are consistent enough at this.

[theory]

Yeah, you'd either have to hack it into the source:

sqitch/lib/App/Sqitch/Engine/mysql.pm

Lines 172 to 177 in 8ee14fb

	push @ret => (
	(App::Sqitch::ISWIN ? () : '--skip-pager' ),
	'--silent',
	'--skip-column-names',
	'--skip-line-numbers',
	);

Or create a shell wrapper around mysql that always passes it and set engine.mysql.client to point to it.

[Kinrany]

I tried running with -vvv, this is the end of the output:

--------------
COMMIT
--------------

Query OK, 0 rows affected (0.000 sec)

Bye

I'm guessing this happens after sqitch is done applying the change and tries to close the connection.

[theory]

In that case maybe it's the DBI connection. Set DBI_TRACE=3 and see what happens (will be quite verbose).

[Kinrany]

For posterity, the error I'm trying to track down appears to be in https://github.com/denodrivers/mysql, based on the fact that a rewrite in Rust doesn't have the same problem.

[theory]

Uhhhhh…where is the error coming from? Sqitch uses the mysql CLI and the DBD::mysql Perl module, not anything in Deno or Rust. Are you using some third-party mysql CLI? Super confused.

[Kinrany]

Oh no, this is just for context, sorry.

I'm using my own CLI written for Deno, and then try to run sqitch deploy. Sqitch works by itself but hangs when it runs after my CLI.

I'm still looking at the logs produced by DBI_TRACE, they are indeed very verbose 😄

[Kinrany]

file3.txt

All right, here's the log. I stopped after the first twelve currow= 12, whatever that is.

The repeating fragment

>parse_params statement
         SELECT UNIX_TIMESTAMP(committed_at) >= UNIX_TIMESTAMP()
           FROM events
          WHERE project = ?
          ORDER BY committed_at DESC
          LIMIT 1
Binding parameters: SELECT UNIX_TIMESTAMP(committed_at) >= UNIX_TIMESTAMP()

FROM events

WHERE project = 'pilot'

ORDER BY committed_at DESC

LIMIT 1
<- dbd_st_execute returning imp_sth->row_num 1

<- execute= ( 1 ) [1 items] at DBI.pm line 1696 via  at mysql.pm line 352

1   <- _async_check= ( 1 ) [1 items] at mysql.pm line 876 via  at DBIEngine.pm line 588

<- bind_col= ( 1 ) [1 items] at DBI.pm line 1701 via  at mysql.pm line 352

-> dbd_st_fetch

dbd_st_fetch for aaaad8f80a68, chopblanks 0

dbd_st_fetch result set details

imp_sth->result=aaaad8f829d0

mysql_num_fields=1

mysql_num_rows=1

mysql_affected_rows=1

dbd_st_fetch for aaaad8f80a68, currow= 11

<- dbd_st_fetch, 1 cols

<- fetch= ( [ 1 ] ) [1 items] row1 at DBI.pm line 1708 via  at mysql.pm line 352

-> dbd_st_fetch

dbd_st_fetch for aaaad8f80a68, chopblanks 0

dbd_st_fetch result set details

imp_sth->result=aaaad8f829d0

mysql_num_fields=1

mysql_num_rows=1

mysql_affected_rows=1

dbd_st_fetch for aaaad8f80a68, currow= 12

dbd_st_fetch, no more rows to fetch

--> dbd_st_finish

>- dbd_st_free_result_sets

<- dbd_st_free_result_sets RC -1

<- dbd_st_free_result_sets
<-- dbd_st_finish

<- fetch= ( undef ) [1 items] row1 at DBI.pm line 1708 via  at mysql.pm line 352

<- selectcol_arrayref= ( [ 1 ] ) [1 items] at mysql.pm line 352 via  at DBIEngine.pm line 588

-> selectcol_arrayref in DBD::_::db for DBD::mysql::db (DBI::db=HASH(0xaaaad8922098)~0xaaaad8922350 DBI::st=HASH(0xaaaad8f809d8) undef "pilot") thr#aaaad61292a0

Called: dbd_bind_ph

-> dbd_st_execute for aaaad8f80a68

>- dbd_st_free_result_sets

<- dbd_st_free_result_sets RC -1

<- dbd_st_free_result_sets

mysql_st_internal_execute MYSQL_VERSION_ID 100506

I'm afraid this tells me nothing at all 😅

[theory]

Sqitch works by itself but hangs when it runs after my CLI.

I'm sorry, I'm confused. Are you saying it works as expected unless it runs after your CLI? What is your CLI? What does it do? How does it relate to Sqitch?

[Kinrany]

Yes, you got it right.

My CLI connects to the database and tries to revert a single migration, the same way sqitch would do it.

[Kinrany]

My CLI doesn't use sqitch directly though, only the database of changes.

[theory]

Is your client taking a lock on the database? That would explain why Sqitch hangs.

[Kinrany]

Not explicitly and I don't think it locks the whole database, but it does lock rows/tables. It is weird that the locks aren't dropped when the connection drops, but I guess it's up to the driver to terminate them.

Should sqitch do something in these cases? My awful attempt at reimplementing the revert command is probably not the only way the database could get locked by some random process 🤔

[theory]

Try not taking locks and see if that fixes it.

I agree Sqitch shouldn't hang, but until I understand what your CLI might be doing, I can't fix it :-)

[Kinrany]

Haha, fair. Thank you for your interest in investigating this edge case in the first place.

Here's a full list of all the database operations the CLI does:

• creates tables changes and events
• select schema_name from information_schema.schemata where schema_name = ?
• select 1
• select * from changes
• insert into events (...) values (?, ...)
• delete from changes where change_id = ?

The code if you care to look for yourself, apologies for the weekend-project quality: https://github.com/Kinrany/quitch/
(ignore the Rust rewrite in src, sqitch works fine after using that one)

[theory]

I suggest you start commenting out some of those commands and see what happens. Selecting the schema name looks like a likely suspect.