t/storage/debug.t

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