Move find_co_root into DBICTest::Util
[dbsrgits/DBIx-Class-Historic.git] / t / storage / debug.t
1 use strict;
2 use warnings;
3 no warnings 'once';
4
5 BEGIN {
6   delete @ENV{qw(
7     DBIC_TRACE
8     DBIC_TRACE_PROFILE
9     DBICTEST_SQLITE_USE_FILE
10     DBICTEST_VIA_REPLICATED
11   )};
12 }
13
14 use Test::More;
15 use Test::Exception;
16 use Try::Tiny;
17 use File::Spec;
18 use lib qw(t/lib);
19 use DBICTest;
20 use Path::Class qw/file/;
21
22 my $schema = DBICTest->init_schema();
23
24 my $lfn = file("t/var/sql-$$.log");
25 unlink $lfn or die $!
26   if -e $lfn;
27
28 # make sure we are testing the vanilla debugger and not ::PrettyPrint
29 require DBIx::Class::Storage::Statistics;
30 $schema->storage->debugobj(DBIx::Class::Storage::Statistics->new);
31
32 ok ( $schema->storage->debug(1), 'debug' );
33 $schema->storage->debugfh($lfn->openw);
34 $schema->storage->debugfh->autoflush(1);
35 $schema->resultset('CD')->count;
36
37 my @loglines = $lfn->slurp;
38 is (@loglines, 1, 'one line of log');
39 like($loglines[0], qr/^SELECT COUNT/, 'File log via debugfh success');
40
41 $schema->storage->debugfh(undef);
42
43 {
44   local $ENV{DBIC_TRACE} = "=$lfn";
45   unlink $lfn;
46
47   $schema->resultset('CD')->count;
48
49   my $schema2 = DBICTest->init_schema(no_deploy => 1);
50   $schema2->storage->_do_query('SELECT 1'); # _do_query() logs via standard mechanisms
51
52   my @loglines = $lfn->slurp;
53   is(@loglines, 2, '2 lines of log');
54   like($loglines[0], qr/^SELECT COUNT/, 'Env log from schema1 success');
55   like($loglines[1], qr/^SELECT 1:/, 'Env log from schema2 success');
56
57   $schema->storage->debugobj->debugfh(undef)
58 }
59
60 END {
61   unlink $lfn;
62 }
63
64 open(STDERRCOPY, '>&STDERR');
65
66 my $exception_line_number;
67 # STDERR will be closed, no T::B diag in blocks
68 my $exception = try {
69   close(STDERR);
70   $exception_line_number = __LINE__ + 1;  # important for test, do not reformat
71   $schema->resultset('CD')->search({})->count;
72 } catch {
73   $_
74 } finally {
75   # restore STDERR
76   open(STDERR, '>&STDERRCOPY');
77 };
78
79 ok $exception =~ /
80   \QDuplication of STDERR for debug output failed (perhaps your STDERR is closed?)\E
81     .+
82   \Qat @{[__FILE__]} line $exception_line_number\E$
83 /xms
84   or diag "Unexpected exception text:\n\n$exception\n";
85
86 my @warnings;
87 $exception = try {
88   local $SIG{__WARN__} = sub { push @warnings, @_ if $_[0] =~ /character/i };
89   close STDERR;
90   open(STDERR, '>', File::Spec->devnull) or die $!;
91   $schema->resultset('CD')->search({ title => "\x{1f4a9}" })->count;
92   '';
93 } catch {
94   $_;
95 } finally {
96   # restore STDERR
97   close STDERR;
98   open(STDERR, '>&STDERRCOPY');
99 };
100
101 die "How did that fail... $exception"
102   if $exception;
103
104 is_deeply(\@warnings, [], 'No warnings with unicode on STDERR');
105
106 # test debugcb and debugobj protocol
107 {
108   my $rs = $schema->resultset('CD')->search( {
109     artist => 1,
110     cdid => { -between => [ 1, 3 ] },
111     title => { '!=' => \[ '?', undef ] }
112   });
113
114   my $sql_trace = 'SELECT me.cdid, me.artist, me.title, me.year, me.genreid, me.single_track FROM cd me WHERE ( ( artist = ? AND ( cdid BETWEEN ? AND ? ) AND title != ? ) )';
115   my @bind_trace = qw( '1' '1' '3' NULL );  # quotes are in fact part of the trace </facepalm>
116
117
118   my @args;
119   $schema->storage->debugcb(sub { push @args, @_ } );
120
121   $rs->all;
122
123   is_deeply( \@args, [
124     "SELECT",
125     sprintf( "%s: %s\n", $sql_trace, join ', ', @bind_trace ),
126   ]);
127
128   {
129     package DBICTest::DebugObj;
130     our @ISA = 'DBIx::Class::Storage::Statistics';
131
132     sub query_start {
133       my $self = shift;
134       ( $self->{_traced_sql}, @{$self->{_traced_bind}} ) = @_;
135     }
136   }
137
138   my $do = $schema->storage->debugobj(DBICTest::DebugObj->new);
139
140   $rs->all;
141
142   is( $do->{_traced_sql}, $sql_trace );
143
144   is_deeply ( $do->{_traced_bind}, \@bind_trace );
145 }
146
147 # recreate test as seen in DBIx::Class::QueryLog
148 # the rationale is that if someone uses a non-IO::Handle object
149 # on CPAN, many are *bound* to use one on darkpan. Thus this
150 # test to ensure there is no future silent breakage
151 {
152   my $output = "";
153
154   {
155     package DBICTest::_Printable;
156
157     sub print {
158       my ($self, @args) = @_;
159       $output .= join('', @args);
160     }
161   }
162
163   $schema->storage->debugobj(undef);
164   $schema->storage->debug(1);
165   $schema->storage->debugfh( bless {}, "DBICTest::_Printable" );
166   $schema->storage->txn_do( sub { $schema->resultset('Artist')->count } );
167
168   like (
169     $output,
170     qr/
171       \A
172       ^ \QBEGIN WORK\E \s*?
173       ^ \QSELECT COUNT( * ) FROM artist me:\E \s*?
174       ^ \QCOMMIT\E \s*?
175       \z
176     /xm
177   );
178
179   $schema->storage->debug(0);
180   $schema->storage->debugfh(undef);
181 }
182
183 done_testing;