Add comprehensive concurrent-test-locking logging to aid future debugging
[dbsrgits/DBIx-Class.git] / t / lib / DBICTest / BaseSchema.pm
1 package #hide from pause
2   DBICTest::BaseSchema;
3
4 use strict;
5 use warnings;
6 use base qw(DBICTest::Base DBIx::Class::Schema);
7
8 use Fcntl qw(:DEFAULT :seek :flock);
9 use Time::HiRes 'sleep';
10 use DBICTest::Util::LeakTracer qw(populate_weakregistry assert_empty_weakregistry);
11 use DBICTest::Util qw( local_umask dbg DEBUG_TEST_CONCURRENCY_LOCKS );
12 use namespace::clean;
13
14 sub capture_executed_sql_bind {
15   my ($self, $cref) = @_;
16
17   $self->throw_exception("Expecting a coderef to run") unless ref $cref eq 'CODE';
18
19   require DBICTest::SQLTracerObj;
20
21   # hack around stupid, stupid API
22   no warnings 'redefine';
23   local *DBIx::Class::Storage::DBI::_format_for_trace = sub { $_[1] };
24   Class::C3->reinitialize if DBIx::Class::_ENV_::OLD_MRO;
25
26
27   local $self->storage->{debugcb};
28   local $self->storage->{debugobj} = my $tracer_obj = DBICTest::SQLTracerObj->new;
29   local $self->storage->{debug} = 1;
30
31   local $Test::Builder::Level = $Test::Builder::Level + 2;
32   $cref->();
33
34   return $tracer_obj->{sqlbinds} || [];
35 }
36
37 sub is_executed_querycount {
38   my ($self, $cref, $exp_counts, $msg) = @_;
39
40   local $Test::Builder::Level = $Test::Builder::Level + 1;
41
42   $self->throw_exception("Expecting an hashref of counts or an integer representing total query count")
43     unless ref $exp_counts eq 'HASH' or (defined $exp_counts and ! ref $exp_counts);
44
45   my @got = map { $_->[0] } @{ $self->capture_executed_sql_bind($cref) };
46
47   return Test::More::is( @got, $exp_counts, $msg )
48     unless ref $exp_counts;
49
50   my $got_counts = { map { $_ => 0 } keys %$exp_counts };
51   $got_counts->{$_}++ for @got;
52
53   return Test::More::is_deeply(
54     $got_counts,
55     $exp_counts,
56     $msg,
57   );
58 }
59
60 sub is_executed_sql_bind {
61   my ($self, $cref, $sqlbinds, $msg) = @_;
62
63   local $Test::Builder::Level = $Test::Builder::Level + 1;
64
65   $self->throw_exception("Expecting an arrayref of SQL/Bind pairs") unless ref $sqlbinds eq 'ARRAY';
66
67   my @expected = @$sqlbinds;
68
69   my @got = map { $_->[1] } @{ $self->capture_executed_sql_bind($cref) };
70
71
72   return Test::Builder->new->ok(1, $msg || "No queries executed while running $cref")
73     if !@got and !@expected;
74
75   require SQL::Abstract::Test;
76   my $ret = 1;
77   while (@expected or @got) {
78     my $left = shift @got;
79     my $right = shift @expected;
80
81     # allow the right side to "simplify" the entire shebang
82     if ($left and $right) {
83       $left = [ @$left ];
84       for my $i (1..$#$right) {
85         if (
86           ! ref $right->[$i]
87             and
88           ref $left->[$i] eq 'ARRAY'
89             and
90           @{$left->[$i]} == 2
91         ) {
92           $left->[$i] = $left->[$i][1]
93         }
94       }
95     }
96
97     $ret &= SQL::Abstract::Test::is_same_sql_bind(
98       \( $left || [] ),
99       \( $right || [] ),
100       $msg,
101     );
102   }
103
104   return $ret;
105 }
106
107 our $locker;
108 END {
109   # we need the $locker to be referenced here for delayed destruction
110   if ($locker->{lock_name} and ($ENV{DBICTEST_LOCK_HOLDER}||0) == $$) {
111     DEBUG_TEST_CONCURRENCY_LOCKS
112       and dbg "$locker->{type} LOCK RELEASED (END): $locker->{lock_name}";
113   }
114 }
115
116 my $weak_registry = {};
117
118 sub connection {
119   my $self = shift->next::method(@_);
120
121 # MASSIVE FIXME
122 # we can't really lock based on DSN, as we do not yet have a way to tell that e.g.
123 # DBICTEST_MSSQL_DSN=dbi:Sybase:server=192.168.0.11:1433;database=dbtst
124 #  and
125 # DBICTEST_MSSQL_ODBC_DSN=dbi:ODBC:server=192.168.0.11;port=1433;database=dbtst;driver=FreeTDS;tds_version=8.0
126 # are the same server
127 # hence we lock everything based on sqlt_type or just globally if not available
128 # just pretend we are python you know? :)
129
130
131   # when we get a proper DSN resolution sanitize to produce a portable lockfile name
132   # this may look weird and unnecessary, but consider running tests from
133   # windows over a samba share >.>
134   #utf8::encode($dsn);
135   #$dsn =~ s/([^A-Za-z0-9_\-\.\=])/ sprintf '~%02X', ord($1) /ge;
136   #$dsn =~ s/^dbi/dbi/i;
137
138   # provide locking for physical (non-memory) DSNs, so that tests can
139   # safely run in parallel. While the harness (make -jN test) does set
140   # an envvar, we can not detect when a user invokes prove -jN. Hence
141   # perform the locking at all times, it shouldn't hurt.
142   # the lock fh *should* inherit across forks/subprocesses
143   #
144   # File locking is hard. Really hard. By far the best lock implementation
145   # I've seen is part of the guts of File::Temp. However it is sadly not
146   # reusable. Since I am not aware of folks doing NFS parallel testing,
147   # nor are we known to work on VMS, I am just going to punt this and
148   # use the portable-ish flock() provided by perl itself. If this does
149   # not work for you - patches more than welcome.
150   if (
151     ! $DBICTest::global_exclusive_lock
152       and
153     ( ! $ENV{DBICTEST_LOCK_HOLDER} or $ENV{DBICTEST_LOCK_HOLDER} == $$ )
154       and
155     ref($_[0]) ne 'CODE'
156       and
157     ($_[0]||'') !~ /^ (?i:dbi) \: SQLite \: (?: dbname\= )? (?: \:memory\: | t [\/\\] var [\/\\] DBIxClass\-) /x
158   ) {
159
160     my $locktype;
161
162     {
163       # guard against infinite recursion
164       local $ENV{DBICTEST_LOCK_HOLDER} = -1;
165
166       # we need to work with a forced fresh clone so that we do not upset any state
167       # of the main $schema (some tests examine it quite closely)
168       local $SIG{__WARN__} = sub {};
169       local $@;
170
171       # this will either give us an undef $locktype or will determine things
172       # properly with a default ( possibly connecting in the process )
173       eval {
174         my $s = ref($self)->connect(@{$self->storage->connect_info})->storage;
175
176         $locktype = $s->sqlt_type || 'generic';
177
178         # in case sqlt_type did connect, doesn't matter if it fails or something
179         $s->disconnect;
180       };
181     }
182
183     # Never hold more than one lock. This solves the "lock in order" issues
184     # unrelated tests may have
185     # Also if there is no connection - there is no lock to be had
186     if ($locktype and (!$locker or $locker->{type} ne $locktype)) {
187
188       # this will release whatever lock we may currently be holding
189       # which is fine since the type does not match as checked above
190       DEBUG_TEST_CONCURRENCY_LOCKS
191         and $locker
192         and dbg "$locker->{type} LOCK RELEASED (UNDEF): $locker->{lock_name}";
193
194       undef $locker;
195
196       my $lockpath = DBICTest::RunMode->tmpdir->file("_dbictest_$locktype.lock");
197
198       DEBUG_TEST_CONCURRENCY_LOCKS
199         and dbg "Waiting for $locktype LOCK: $lockpath...";
200
201       my $lock_fh;
202       {
203         my $u = local_umask(0); # so that the file opens as 666, and any user can lock
204         sysopen ($lock_fh, $lockpath, O_RDWR|O_CREAT) or die "Unable to open $lockpath: $!";
205       }
206
207       flock ($lock_fh, LOCK_EX) or die "Unable to lock $lockpath: $!";
208
209       DEBUG_TEST_CONCURRENCY_LOCKS
210         and dbg "Got $locktype LOCK: $lockpath";
211
212       # see if anyone was holding a lock before us, and wait up to 5 seconds for them to terminate
213       # if we do not do this we may end up trampling over some long-running END or somesuch
214       seek ($lock_fh, 0, SEEK_SET) or die "seek failed $!";
215       my $old_pid;
216       if (
217         read ($lock_fh, $old_pid, 100)
218           and
219         ($old_pid) = $old_pid =~ /^(\d+)$/
220       ) {
221         DEBUG_TEST_CONCURRENCY_LOCKS
222           and dbg "Post-grab WAIT for $old_pid START: $lockpath";
223
224         for (1..50) {
225           kill (0, $old_pid) or last;
226           sleep 0.1;
227         }
228
229         DEBUG_TEST_CONCURRENCY_LOCKS
230           and dbg "Post-grab WAIT for $old_pid FINISHED: $lockpath";
231       }
232
233       truncate $lock_fh, 0;
234       seek ($lock_fh, 0, SEEK_SET) or die "seek failed $!";
235       $lock_fh->autoflush(1);
236       print $lock_fh $$;
237
238       $ENV{DBICTEST_LOCK_HOLDER} ||= $$;
239
240       $locker = {
241         type => $locktype,
242         fh => $lock_fh,
243         lock_name => "$lockpath",
244       };
245     }
246   }
247
248   if ($INC{'Test/Builder.pm'}) {
249     populate_weakregistry ( $weak_registry, $self->storage );
250
251     my $cur_connect_call = $self->storage->on_connect_call;
252
253     $self->storage->on_connect_call([
254       (ref $cur_connect_call eq 'ARRAY'
255         ? @$cur_connect_call
256         : ($cur_connect_call || ())
257       ),
258       [sub {
259         populate_weakregistry( $weak_registry, shift->_dbh )
260       }],
261     ]);
262   }
263
264   return $self;
265 }
266
267 sub clone {
268   my $self = shift->next::method(@_);
269   populate_weakregistry ( $weak_registry, $self )
270     if $INC{'Test/Builder.pm'};
271   $self;
272 }
273
274 END {
275   assert_empty_weakregistry($weak_registry, 'quiet');
276 }
277
278 1;