t/storage/debug.t

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