logging stored procedure fails when inserting via linked server

[l***@gmail.com]

Hi There,

I've created a stored procedure that inserts into a table in my current database using a loopback linked server, this was done because i need the logging transaction to be independent of the current active transaction.

the idea was taken from:
https://blogs.msdn.microsoft.com/sqlprogrammability/2008/08/22/how-to-create-an-autonomous-transaction-in-sql-server-2008/

this is the statement used to create the linked server:
EXEC sp_addlinkedserver @server = N'BIloopback',@srvproduct = N' ',@provider = N'SQLNCLI', @datasrc = @@SERVERNAME
EXEC sp_serveroption BIloopback,N'remote proc transaction promotion','FALSE' -- we want to ensure transactions do not propogate for logging
EXEC sp_serveroption BIloopback,N'RPC OUT','TRUE' -- Enable RPC to the given server.


i call my logging proc directly from the code and the logging proc then executes the following dynamic sql:

DECLARE @DMLVars nvarchar(1024)
, @qry nvarchar(1024)
SET @DMLVars = '@LogDate datetime, @RowCount int, @Severity int, @ExtractSession uniqueidentifier, @LogLevel int, @MessageID int, @ProcName nvarchar(128), @Message nvarchar(max)'
SET @qry = 'INSERT INTO '+isnull(quotename(@LoopbackServer)+'.','')+DB_NAME()+'.[Log].[BIInfoLog] '
+' ([LogDate] , [RowCount] , [Severity], [LogLevel] ,[MessageID], [SPName] , [Message], [ExtractSession] ) '
+' values (@LogDate,@RowCount,@Severity,@LogLevel,@MessageID,@ProcName,@Message, @ExtractSession )'

--SET ANSI_WARNINGS OFF -- don't warn about truncation
--set ANSI_NULLS OFF
EXEC sp_executesql @qry
, @DMLVars
, -- declare
-- input vars
@LogDate = @now
, @RowCount = @RowCount
, @Severity = @Severity
, @LogLevel = @LogLevel
, @MessageID = @MessageID
, @ProcName = @ProcName
, @Message = @Message
, @ExtractSession= @ExtractSession

however when i then use it, the first attempt to the logging proc returns this error:
2017-05-24 15:48:50.607| |1:0|Staging.BIGetFormatterColumnList|Starting...
Logging to db!
Transaction context in use by another session.
Error: 50000, Severity: -1, State: 1. (Params:). The error is printed in terse mode because there was error during formatting. Tracing, ETW, notifications etc are skipped.
Msg 50000, Level 5, State 1

the second call returns this error:
2017-05-24 15:48:50.610| |4:0|Staging.BIGetFormatterColumnList|column discovery query size: 329
Logging to db!
The current transaction cannot be committed and cannot support operations that write to the log file. Roll back the transaction.
Error: 50000, Severity: -1, State: 1. (Params:). The error is printed in terse mode because there was error during formatting. Tracing, ETW, notifications etc are skipped.
Msg 50000, Level 5, State 1


At this time i haven't even created a transaction in the caller as i am in the testing phase and wanted to make sure everything worked.

I'm not sure what i'm doing wrong.

[l***@gmail.com]

Digging further, it appears that it can be boiled down to the fact that the inner procedure (BIGetFormatterColumnList) is being called to insert into a table variable. the error can be reproduced with this snippet. I need to be able to insert the output of the stored procedure into table variable to gather the results for further work but i also want to be able to log the start/end of the called procedure when i have a high enough debugging level.

create table dbo.logging (logdate datetime, msg nvarchar(max))
GO
CREATE proc dbo.logger (@Message nvarchar(max)) as
BEGIN
declare @now datetime; set @now=GETUTCDATE()
insert into loopback.mydb.dbo.logging(logdate,msg) values (@now,@Message)

END
GO
CREATE proc dbo.pInner as
BEGIN
--uncomment either line to cause it to fail
--EXEC dbo.logger 'inner start'
select 1
--EXEC dbo.logger 'inner end'
END
GO
--exec pInner -- uncomment to see the "inner" stored proc is okay
GO
CREATE proc dbo.pOuter as
BEGIN
exec dbo.logger 'outer start'
begin try
DECLARE @MatchingColList AS TABLE ( ColumnName NVARCHAR(128) );
insert into @MatchingColList (ColumnName)
EXEC dbo.pInner
end try
begin catch
print ERROR_MESSAGE()
end catch
END
GO
exec pOuter

-- this fails, commenting out the "insert into" line will also allow it to be successful so its the combination of the "insert into" and the inserting into the linked server.

[Erland Sommarskog]

Post by l***@gmail.com
Digging further, it appears that it can be boiled down to the fact that
the inner procedure (BIGetFormatterColumnList) is being called to insert
into a table variable. the error can be reproduced with this snippet. I
need to be able to insert the output of the stored procedure into table
variable to gather the results for further work but i also want to be
able to log the start/end of the called procedure when i have a high
enough debugging level.

When you run a procedure from INSERT EXEC, the procedure will run in the
context of the transaction started by the INSERT statement, even if you
did run BEGIN TRANSACTION yourself.

[l***@gmail.com]

Thanks for the quick reply! I continued testing and stumbled on the same solution you described above, if i called the logger stored proc via the linked server rather than calling the logger locally but doing the insert remotely it works.

Because i have parameterized both the linked server name and the database it is in is not guaranteed to be static from install to install i decided to create a synonym which links to the loopback server. this way my procedures can directly reference the synonym and avoids the need for dynamic sql when calling the procedure.

here is the final version that worked:


create table dbo.logging (logdate datetime, msg nvarchar(max))
GO
CREATE proc dbo.logger (@Message nvarchar(max)) as
BEGIN
declare @now datetime; set @now=GETUTCDATE()
insert into dbo.logging(logdate,msg) values (@now,@Message)

END
GO
-- this avoids the need to know the name of the db or the loopback once initialized, this creation can be wrapped into a stored proc for parameterization
CREATE SYNONYM MyLogger for Loopback.MyDB.dbo.Logger
GO
CREATE proc dbo.pInner as
BEGIN
EXEC MyLogger 'inner start'
select 'mycolumn'
EXEC MyLogger 'inner end'
END
GO
--exec pInner
GO
CREATE proc dbo.pOuter as
BEGIN
exec MyLogger 'outer start'
begin try
DECLARE @MatchingColList AS TABLE ( ColumnName NVARCHAR(128) );
insert into @MatchingColList (ColumnName)
EXEC dbo.pInner
end try
begin catch
print ERROR_MESSAGE()
end catch
exec MyLogger 'outer end'
END
GO
exec pOuter

[Erland Sommarskog]

Post by l***@gmail.com
Because i have parameterized both the linked server name and the
database it is in is not guaranteed to be static from install to install
i decided to create a synonym which links to the loopback server. this
way my procedures can directly reference the synonym and avoids the need
for dynamic sql when calling the procedure.

Good move!

[l***@gmail.com]

Thanks, i figured that out quickly, just hadn't gotten around to removing them from the procedure fully.

[Erland Sommarskog]

Post by l***@gmail.com
I've created a stored procedure that inserts into a table in my current
database using a loopback linked server, this was done because i need
the logging transaction to be independent of the current active
transaction.
i call my logging proc directly from the code and the logging proc then

I would recommend that you write a stored proceedure that writes to the
log table, and then you call it this way:

SELECT @spname = quotename(@loopbackserver) + '.' +
quotename(db_name()) + '.dbo.your_sp'
EXEC  @spname @LogDate = @now
, @RowCount = @RowCount
, @Severity = @Severity
, @LogLevel = @LogLevel
, @MessageID = @MessageID
, @ProcName = @ProcName
, @Message = @Message
, @ExtractSession= @ExtractSession


EXEC accepts a variable for the procedure name, so that works fine.

I don't really know why you get the error you do, but I would execpt
the above to work. If you don't want a separate SP, you can still do:

DECLARE @DMLVars nvarchar(1024)
@sp_executesql nvarchar(1023)
SET @DMLVars = '@LogDate datetime, @RowCount int,
@Severity int, @ExtractSession uniqueidentifier,
@LogLevel int, @MessageID int, @ProcName nvarchar(128),
@Message nvarchar(max)'

SET @sp_executesql = quotename(@loopbackserver) + '.' +
quotename(db_name()) + '.sys.sp_executesql'

EXEC @sp_executesql N'INSERT INTO [Log].[BIInfoLog]
([LogDate] , [RowCount] , [Severity],
[LogLevel] ,[MessageID], [SPName] ,
[Message], [ExtractSession] )
values (@LogDate, @RowCount, @Severity, @LogLevel, @MessageID, @ProcName,
@Message, @ExtractSession )

Post by l***@gmail.com
--SET ANSI_WARNINGS OFF -- don't warn about truncation
--set ANSI_NULLS OFF

Never touch these SET options! Never! They are pure legacy, and will only
cause you pain. Specifically, they must be on when you are dealing with
linked servers.

A completely different take on this is to write a CLR procedure to
do the loopback. It will need to be installed with EXTERNAL_ACCESS
permission, but I think this is the better option. You can read
this chapter in my series on Error and Transaction Handling in SQL
Server where I discuss an error-logging facility not unlike what you
are trying to achieve.