t/storage/debug.t

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