Re: Error during SQL Server restore fails to propagate back to DBI client on Windows

--- On Mon, 2/22/10, Martin J. Evans <[email protected]> wrote:

> From: Martin J. Evans <[email protected]>
> Subject: Re: Error during SQL Server restore fails to propagate back to DBI client on Windows
> To: "pr" <[email protected]>
> Cc: [email protected]
> Date: Monday, February 22, 2010, 5:28 PM
> pr wrote:
> > 
> > --- On Fri, 2/19/10, pr <[email protected]>
> wrote:
> > 
> >> From: pr <[email protected]>
> >> Subject: Re: Error during SQL Server restore fails
> to propagate back to DBI client on Windows
> >> To: "Martin Evans" <[email protected]>
> >> Cc: [email protected]
> >> Date: Friday, February 19, 2010, 11:22 PM
> >>
> >>
> >> --- On Fri, 2/19/10, Martin Evans <[email protected]>
> >> wrote:
> >>
> >>> From: Martin Evans <[email protected]>
> >>> Subject: Re: Error during SQL Server restore
> fails to
> >> propagate back to DBI client on Windows
> >>> To: "pr" <[email protected]>
> >>> Cc: [email protected]
> >>> Date: Friday, February 19, 2010, 8:41 AM
> >>> pr wrote:
> >>>> --- On Thu, 2/18/10, Martin Evans <[email protected]>
> >>> wrote:
> >>>>> From: Martin Evans <[email protected]>
> >>>>> Subject: Re: Error during SQL Server
> restore
> >> fails
> >>> to propagate back to DBI client on Windows
> >>>>> To: "pr" <[email protected]>
> >>>>> Cc: [email protected]
> >>>>> Date: Thursday, February 18, 2010,
> 8:51 AM
> >>>>> pr wrote:
> >>>>>> Overview:
> >>>>>>
> >>>>>> Using perl+DBI+DBD::ODBC on
> Windows, I
> >> am
> >>> connecting
> >>>>> to a SQL Server 2005 instance and
> issuing a
> >>> "restore
> >>>>> database [foo] from
> >> disk='c:\foo-backup.bak'".
> >>>>>> The restore attempt appears to
> succeed,
> >> and
> >>> nothing
> >>>>> calls my installed error handler.
> >>>>>> However, if I run a trace on the
> SQL
> >> Server, I
> >>> can see
> >>>>> the restore is throwing an error:
> >>>>>> Error 3224, Severity 16, State 1:
> Cannot
> >>> create worker
> >>>>> thread.
> >>>>>> RESTORE DATABASE is terminating
> >> abnormally.
> >>>>>> If I write the same SQL to a file,
> then
> >>> execute the
> >>>>> file via sqlcmd, the restore works as
> >>> expected.  Hence
> >>>>> I am confident in the SQL command as
> well as
> >> the
> >>> backup
> >>>>> file.
> >>>>>> Other DML-type commands work as
> >> advertised, as
> >>> does
> >>>>> the error handler.  It seems to
> be
> >> something
> >>>>> specifically about a restore.
> >>>>>> Specifics:
> >>>>>>
> >>>>>> The version of perl is
> ActiveState's
> >> v5.10.0
> >>> running
> >>>>> on a 32 bit Windows 2003 server.
> >>>>>> My DSN and connect code looks
> like:
> >>>>>>
> >>>>>> my $dsn = 'Driver={SQL Native
> >>
> Client};Server=myServer;Database=master;Trusted_Connection=yes;Encrypt=yes;';
> >>>>>> my $dbh =
> >>> DBI->connect("dbi:ODBC:$dsn",'','', {
> >>>>> RaiseError => 1, AutoCommit => 1
> } );
> >>>>>> $dbh->{HandleError} =
> >> \&error_handler;
> >>>>>> My error handler looks like:
> >>>>>>
> >>>>>> sub error_handler {
> >>>>>>       my
> @err = @_;
> >>>>>>
> >>>>>>   
>    print "Error handler
> >>>>> triggered!\n";
> >>>>>>   
>    return 0;
> >>>>>> }
> >>>>>>
> >>>>>> I have tried:
> >>>>>> - $dbh->do ( $restore_command
> )
> >>>>>> - $sth = $dbh->prepare(
> >> $restore_command
> >>> );
> >>>>> $sth->execute(); ...
> >>>>>> I've tried with and without
> >>>>> $dbh->{odbc_exec_direct} = 1 and
> also not
> >>> specifying it.
> >>>>>> The MDAC version on the machine
> is
> >> recent:
> >>> version
> >>>>> 2.82.3959.0.
> >>>>>> The version of DBI is 1.604.
> >>>>>>
> >>>>>> I have tried running a DBI trace
> at up
> >> to
> >>> level 15,
> >>>>> and there doesn't seem to be anything
> of
> >>> interest.  
> >>>>>>
> >>>>>> Has this been brought up
> before?  Has
> >>> someone
> >>>>> encountered it?  
> >>>>>> If there are other things I should
> try,
> >> I
> >>> would very
> >>>>> much appreciate the suggestions!
> >>>>>> I'm completely at a loss where
> the
> >> problem is.
> >>>>> Code?  DBD?  DBI?  SQL
> >>> Server?  mdac?
> >>>>>> Thanks
> >>>>>> -rt
> >>>>>>
> >>>>>>
> >>>>>>
> >>>>>>
> >>>>>>
> >>>>> Can I see the rest of the code after
> the
> >> prepare
> >>> please?
> >>>>> Preferably a small self contained and
> >> complete
> >>> example
> >>>>> would be best.
> >>>>>
> >>>>> Are you calling odbc_more_results
> after
> >> execute
> >>> until it
> >>>>> returns false?
> >>>>>
> >>>>> Martin
> >>>>> -- 
> >>>>> Martin J. Evans
> >>>>> Easysoft Limited
> >>>>> http://www.easysoft.com
> >>>>>
> >>>> Hi Martin,
> >>>>
> >>>> Thank you for your reply.
> >>>>
> >>>> I'm depending on DBI's do() method:
> >>>>
> >>>> my
> $dbh=DBI->connect("dbi:ODBC:$dsn",'','');
> >>>> $dbh->{HandleError} = sub { print
> "error
> >>> occurred\n"; };
> >>>> $sql = 'restore database [foo] from
> >>> disk=\'c:\\mybackup.bak\' with replace';
> >>>> $dbh->do( $sql );
> >>>>
> >>>>
> >>>>
> >>>> I've also tried:
> >>>>
> >>>> my
> $dbh=DBI->connect("dbi:ODBC:$dsn",'','');
> >>>> $dbh->{HandleError} = sub { print
> "error
> >>> occurred\n"; };
> >>>> $sql = 'restore database [foo] from
> >>> disk=\'c:\\mybackup.bak\' with my $sth =
> >> $dbh->prepare(
> >>> $sql );
> >>>> my $dbh->execute();
> >>>> while ( my @junk =
> $sth->fetchrow_array() ) {
> >>>>     # do nothing
> >>>> }
> >>>>
> >>>>
> >>>> In both cases, the error handler is not
> >> triggered, and
> >>> all appears well on the client in. 
> However, a trace
> >>> using SQLProfiler shows Msg 3224 and that the
> backup
> >>> terminates abnormally.
> >>>> I've been able to confirm this on two
> systems
> >> running
> >>> the same versions of the software.
> >>>>
> >>>> I would expect either approach to work?
> >>>>
> >>>> Regards,
> >>>> -rt
> >>>>
> >>>>
> >>>>
> >>>>        
> >>>>
> >>>>
> >>> When you call procedures in MS SQL Server you
> often
> >> need to
> >>> use
> >>> prepare/execute/odbc_more_results because SQL
> Server
> >>> batches up results
> >>> and anything printed in the procedure can
> count as a
> >>> result. I would try
> >>> this:
> >>>
> >>> $sth = prepare(restore....)
> >>> $sth->execute
> >>> do {
> >>>         
>    my @row;
> >>>         
>    while (@row =
> >>> $sth->fetchrow_array()) {
> >>>            
> >>>    # do stuff here
> >>>         
>    }
> >>>          } while
> >>> ($sth->{odbc_more_results});
> >>>
> >>>
> >>> There is an example in t/20SqlServer.t that
> comes
> >> with
> >>> DBD::ODBC - you
> >>> can find it by browsing the source on CPAN.
> >>>
> >>> Martin
> >>> -- 
> >>> Martin J. Evans
> >>> Easysoft Limited
> >>> http://www.easysoft.com
> >>>
> >>
> >>
> >> Hi Martin,
> >>
> >> Once again, thank you for your time and patience.
> >>
> >> The suggestion to use $sth->{odbc_more_results}
> improved
> >> the situation, but there still seems to be a major
> issue.
> >>
> >>
> >> What works:
> >>
> >> my $dbh = DBI->connect("dbi:ODBC:$dsn", '',
> '');
> >> $dbh->{HandleError} = \&error_handler;
> >> $dbh->{HandleSetErr} =
> \&set_error_handler;
> >> $dbh->{odbc_exec_direct} = 1;
> >> my $sql = qq| restore database [foo] from
> >> disk='l:\\mssql.1\\mssql\\backup\\full\\foo.bak'
> WITH
> >> REPLACE |;
> >> $sth = $dbh->prepare($sql);
> >> $sth->execute();
> >> do {
> >>     print "RESULT SET:\n";
> >>     while ( my @row =
> >> $sth->fetchrow_array() ) {
> >>         print
> >> "\tfetchrow_array() should be empty\n";
> >>     }
> >> } while ( $sth->{odbc_more_results} );
> >>
> >>
> >> What does not work:
> >>
> >> Remove the call to set dbc_exec_direct to 1.
> >>
> >> In this case, I see in a SQLProfiler trace that
> the backup
> >> is prepared via a call to sp_prepexec (as would
> be
> >> expected).  However, the trace shows the
> server
> >> throwing Msg 3224 Severity 16 State 1 - cannot
> spawn worker
> >> thread again.  
> >>
> >> The main worry I have is this error does not
> propagate back
> >> to the client at all.  
> >>
> >> Here is the code for the error handler and set
> err
> >> handler:
> >>
> >> sub error_handler {
> >>     my @err = @_;
> >>     
> >>     for ( my $i = 0; $i <
> scalar( @err );
> >> $i++ ) {
> >>         if ( !
> defined
> >> $err[$i] ) {
> >>            
> >> $err[$i] = '(null)';
> >>         }
> >>         print "ERROR
> HANDLER:
> >> $i: $err[$i]\n";
> >>     }
> >> }
> >>
> >> sub set_error_handler {
> >>     my @err = @_;
> >>     
> >>     for ( my $i = 0; $i <
> scalar( @err );
> >> $i++ ) {
> >>         if ( !
> defined
> >> $err[$i] ) {
> >>            
> >> $err[$i] = '(null)';
> >>         }
> >>         print "SET
> ERROR
> >> HANDLER: $i: $err[$i]\n";
> >>     }
> >> }
> >>
> >>
> >> When I run the script in the failure case (i.e.
> not setting
> >> odbc_exec_direct), I see exactly this:
> >>
> >> SET ERROR HANDLER: 0: DBI::st=HASH(0x1a4d614)
> >> SET ERROR HANDLER: 1:
> >> SET ERROR HANDLER: 2: [Microsoft][SQL Native
> Client][SQL
> >> Server]Processed 160 pages for database 'foo',
> file 'foo' on
> >> file 1. (SQL-01000)
> >> SET ERROR HANDLER: 3: 01000
> >> SET ERROR HANDLER: 4: (null)
> >> RESULT SET:
> >>
> >> Hence there's every reason to believe from the
> client point
> >> of view this would be a success.
> >>
> >>
> >> The exact versions of the DBI and DBD::ODBC module
> (updated
> >> from ActiveState) are:
> >>
> >> 1.609 DBI
> >> 1.23 DBD::ODBC
> >>
> >>
> >> Any other suggestions?  Would it be helpful
> to bundle
> >> up an exact set of scripts to create, backup and
> run a
> >> restore to see if anyone else can reproduce
> this?  I've
> >> been able to reproduce this on other servers with
> a
> >> dummy/test setup.
> >>
> >> Regards,
> >> -rt
> >>
> >>
> > 
> > 
> > One other thing I should add:
> > 
> > It seems peculiar that I can only get the first
> 'Processed x pages for database ....' message, but none
> others.
> > 
> > This is true even when using odbc_more_results to
> ensure all result sets get processed, and true whether or
> not odbc_exec_direct is 1 or 0.
> > 
> > It seems these messages can only be caught via the
> HandleSetErr handler, and not the HandleError handler.
> > 
> > I am wondering if this is related.  
> > 
> > It would seem if in SQL Server I do:
> > 
> > create database foo;
> > backup database foo to disk='e:\foo.bak'
> > 
> > I should then be able to issue via a DBI connection
> using DBD::ODBC the command:
> > 
> > restore database foo from disk='e:\foo.bak' with
> replace
> > 
> > And see all 3 status messages that I would see if I
> issued this command at a sqlcmd prompt:
> > 
> > 1> restore database bar from disk='e:\bar.bak' with
> replace
> > 2> go
> > Processed 152 pages for database 'bar', file 'bar' on
> file 1.
> > Processed 1 pages for database 'bar', file 'bar_log'
> on file 1.
> > RESTORE DATABASE successfully processed 153 pages in
> 0.056 seconds (22.381 MB/sec).
> > 
> > 
> > I don't, though.  I see only that first
> 'Processed 152 pages...' message, in spite of using
> odbc_more results as follows:
> > 
> > 
> > $dbh=DBI->connect("dbi:ODBC:$dsn",'','');
> > 
> > $dbh->{odbc_exec_direct} = 1;
> > $dbh->{HandleSetErr} = sub { print "$_[2]\n"; };
> > 
> > $sql = qq| restore database [foo] from
> disk='l:\\mssql.1\\mssql\\backup\\full\\foo.bak' WITH
> REPLACE |;
> > $sth = $dbh->prepare($sql);
> > 
> > $sth->execute();
> > do {
> >     print "RESULT SET:\n";
> >     while ( my @row =
> $sth->fetchrow_array() ) {
> >         print
> "   fetchrow_array() should be empty, but
> still, here we are\n";
> >     }
> > } while ( $sth->{odbc_more_results} );
> > 
> > 
> > I see:
> > 
> > [Microsoft][SQL Native Client][SQL Server]Processed
> 160 pages for database 'foo', file 'foo' on file 1.
> (SQL-01000)
> > RESULT SET:
> > 
> > 
> > 
> > Thank you again for any suggestions or specific RTFM
> pointers.
> > 
> > -rt
> 
> Can I just wind back a bit as each time you email the
> number of things
> you seem unhappy with seems to grow.
> 
> Starting with some facts (as I believe they to be):
> 
> HandleError is only called for errors not warnings or
> informational
> messages. See the text "The HandleError attribute can be
> used to provide
> your own alternative behaviour in case of errors" in the
> DBI docs.
> 
> HandleSetError is called whenever the err, errstr or state
> variables are
> being set - this includes warnings and informational
> messages. See the text
> 
> "The HandleSetErr attribute can be used to intercept the
> setting of
> handle err, errstr, and state values." and
> 
> "The HandleSetErr and HandleError subroutines differ in
> subtle but
> significant ways. HandleError is only invoked at the point
> where the DBI
> is about to return to the application with err set true.
> It's not
> invoked by the failure of a method that's been called by
> another DBI
> method. HandleSetErr, on the other hand, is called whenever
> set_err() is
> called with a defined err value, even if false. So it's not
> just for
> errors, despite the name, but also warn and info states."
> 
> in the DBI docs.
> 
> DBD::ODBC like many other DBDs supports (to the degree DBI
> allows) the
> reporting of errors, warnings and informational messages.
> If you call
> err you can find errors, warnings or informationals as
> described in the
> docs - "A driver may return 0 from err() to indicate a
> warning condition
> after a method call. Similarly, a driver may return an
> empty string to
> indicate a 'success with information' condition. In both
> these cases the
> value is false but not undef." As an example:
> 
> use DBI;
> use strict;
> use warnings;
> 
> my $h = DBI->connect;
> print "last informational message was: ", $h->errstr,
> "\n\n"
>     if $h->err eq "";
> 
> produces:
> 
> last informational message was: [unixODBC][Easysoft][SQL
> Server
> Driver][SQL Server]Changed language setting to us_english.
> (SQL-01000)
> [unixODBC][Easysoft][SQL Server Driver][SQL Server]Changed
> database
> context to 'master'. (SQL-01000)
> 
> in my setup.
> 
> To my knowledge DBI does not allow multiple informational
> messages to be
> stacked i.e., there is only one err, errstr, state and so
> even if
> DBD::ODBC calls set_err multiple times you will only see
> the last
> informational in err, errstr and state (this is one aspect
> of this I'm
> not totally certain about and the above example might
> illustrate why I
> could be wrong here). You can catch these informationals
> with
> HandleSetError but in the case of DBD::ODBC calling
> SQLMoreResults
> automatically, it does not report each informational - I
> can change that
> specifically if you like and if you report it on rt.
> 
> Now some history and operational notes on DBD::ODBC:
> 
> SQL Server is rather strange when it comes to the calling
> of procedures.
> Firstly it does not batch result-sets up and hence
> odbc_more_results
> i.e., if you call select 1; select 2; etc in your procedure
> you have to
> call odbc_more_results (SQLMoreResults in the ODBC API) to
> move to the
> next result-set. Similarly if you call insert; insert; you
> need to call
> SQLMoreResults. However, because people using DBD::ODBC
> said it was a
> PITA the call odbc_more_results for each insert (as all
> they'd find out
> is the RowCount and nothing else unless an error occurs)
> DBD::ODBC skips
> non-result-set generating statements automatically i.e., if
> you do:
> 
> insert
> insert
> select
> select
> 
> the first 2 are skipped and the result from the first
> select is
> available then you call odbc_more_results to get the next
> result-set.
> 
> Also, the SQL Server ODBC driver works differently when
> calling
> prepare/execute from calling SQLExcDirect e.g., you can
> only use
> temporary tables when using SQLExecDirect. Initially, this
> was the
> reason for adding odbc_exec_direct. As it turns out there
> are other
> scenarios where odbc_exec_direct is worth using and you
> have hit one of
> them. As far as I am aware you need to set odbc_exec_direct
> to call your
> procedures reliably - it is something to do with the
> done_in_proc states
> returned by TDS.
> 
> Also, you should note that because SQL Server does not
> batch statements
> up in a procedure the output bound parameters are not
> available until
> AFTER the procedure is completed and it has not completed
> until
> SQLMoreResults returns SQL_NO_DATA - this is the second
> reason for
> odbc_more_results.
> 
> DBD::ODBC does not call SQLMoreResults if you use the do
> method since do
> should not be used for result-set generating statements.
> 
> Now back to what I believe are the issues you have brought
> up:
> 
> o you need to use prepare/execute and set odbc_exec_direct
> on the
> prepare call.
> 
> o you do not need to use odbc_more_results in this case if
> you use
> prepare/execute since DBD::ODBC will call SQLMoreResults
> for you
> internally. N.B. odbc_more_results does not cause
> SQLMoreResults to be
> called it simply tells you if when it was called it said
> there were more
> results.
> 
> I am now unsure if you are still saying your restore does
> not work but
> the following code works for me:
> 
> use DBI;
> use strict;
> use warnings;
> use Data::Dumper;
> 
> sub _error_handler {
>     print "ERROR HANDLER ", Dumper(\@_);
>     0;
> }
> 
> sub _seterr_handler {
>       print "SETERR HANDLER ",
> Dumper(\@_);
>       0;
> }
> 
> my $h = DBI->connect;
> print "Connection SUCCESS_WITH_INFO data", $h->errstr,
> "\n\n"
>     if $h->err eq "";
> 
> $h->{RaiseError} = 1;
> $h->{PrintError} = 1;
> $h->{PrintWarn} = 1;
> $h->{HandleError} = \&_error_handler;
> $h->{HandleSetErr} = \&_seterr_handler;
> 
> #eval {$h->do('create database foo');};
> 
> my $s = $h->prepare(q{backup database foo to
> disk='c:\foo.one'}
> ,{odbc_exec_direct => 1}
> );
> $s->execute;
> print "errstr: ", $s->errstr, "\n" if $s->err eq "";
> 
> print "backed up\n";
> #$h->do(q{backup database foo to disk='c:\foo.bak'});
> 
> $h->disconnect;
> 
> print "Restoring\n";
> $h = DBI->connect;
> print "Connection SUCCESS_WITH_INFO data", $h->errstr,
> "\n\n"
>     if $h->err eq "";
> 
> $h->{RaiseError} = 1;
> $h->{PrintError} = 1;
> $h->{PrintWarn} = 1;
> $h->{HandleError} = \&_error_handler;
> 
> $s = $h->prepare(q{restore database foo from
> disk='c:\foo.one'}
> ,{odbc_exec_direct => 1});
> $s->execute;
> print "errstr: ", $s->errstr, "\n" if $s->err eq "";
> 
> and produces:
> 
> C:\perlbuild_xxx>perl backup_restore.pl
> Connection SUCCESS_WITH_INFO data[Microsoft][ODBC SQL
> Server Driver][SQL
> Server]
> Changed database context to 'master'. (SQL-01000)
> [Microsoft][ODBC SQL Server Driver][SQL Server]Changed
> language setting
> to us_english. (SQL-01000)
> 
> SETERR HANDLER $VAR1 = [
>           bless( {}, 'DBI::st' ),
>           '',
>           '[Microsoft][ODBC SQL
> Server Driver][SQL Server]Processed 176
> pages for database \'foo\', file \'foo\' on file 1.
> (SQL-01000)',
>           '01000',
>           undef
>         ];
> errstr: [Microsoft][ODBC SQL Server Driver][SQL
> Server]Processed 176
> pages for database 'foo', file 'foo' on file 1.
> (SQL-01000)
> backed up
> Restoring
> Connection SUCCESS_WITH_INFO data[Microsoft][ODBC SQL
> Server Driver][SQL
> Server]
> Changed database context to 'master'. (SQL-01000)
> [Microsoft][ODBC SQL Server Driver][SQL Server]Changed
> language setting
> to us_english. (SQL-01000)
> 
> errstr: [Microsoft][ODBC SQL Server Driver][SQL
> Server]Processed 176
> pages for database 'foo', file 'foo' on file 1.
> (SQL-01000)
> 
> If I look at the ODBC trace I see it actually gets the
> following
> informationals:
> 
> 01000 Processed 176 pages for database 'foo' file foo
> 01000 Processed 1 pages for database foo, file foo_log
> 01000 BACKUP DATABASE successfully processed 177 pages in
> 0.735 seconds
> (1972 MS/sec)
> 
> Now if all you want is to capture all those informationals
> in
> HandleSetError then report it on rt and I'll try and change
> it for you.
> 
> Martin
> -- 
> Martin J. Evans
> Easysoft Limited
> http://www.easysoft.com



I apologize if it seems my point is wandering or if I am genuinely unhappy.  That's not my intention, to be sure.  

Yes, it does work for me when {odbc_exec_direct} is set to true.  I also understand your explanation of why this is the correct way to do things.

The real concern here is why error 3224 seems untrappable if this restore is done with {odbc_exec_direct} is set to false.  I cannot see how to trap this error at all.  

Is it possible to (incorrectly) set odbc_exec_direct to false, issue the database restore, and trap error 3224 in perl?

Plausible use cases for why this is a concern: 1) A person wants to use prepared statements as much as possible; it's not clear without extensive server side tracing which may be subject to this problem.   2) Add to case #1 a large shop where a number of people may be writing code.  It would be best to have a sure way to trap any possible server-side error, even if they did something incorrect such as setting odbc_exec_direct to false for a database restore.

Last, thanks for the suggestion about filing an rt ticket re: capturing all informational messages.  I think I will take you up on this, and I'll try and make a case for the value of this in the rt ticket.

Thank you once again for your time on this.  I do really appreciate it.

Regards,
-rt