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;