I am facing a really confusing problem with our SQL Server, and I hope
somebody can give me hint how to debug this issue.
Grab a cup of coffee or something, this is going to get slightly
convoluted. And you may think along the way, "Well, you have been
asking for this! You've got no one to blame but yourself!". And you
may even be right. But I promise that every step along the way, I did
the best I could think of, and I do believe I had valid reasons for my
decisions.
Soooo, we use a little-known ERP software and a Product/Projekt Data
Management System (PDM). Actually, we are currently in the last steps
(we hope) of setting up the PDM system so we can eventually introduce
it to our users.
In order to be useful, the PDM system needs to have kind-of-realtime
information on what goes on in the ERP system, e.g. when a project is
created or various kinds of documents are created in the ERP system
(orders, invoices, quotations, etc.).
The problem I face has to do with telling the PDM system about new
projects from the ERP system. Both the ERP and the PDM system use MS
SQL Server databases as their backends (each uses its own database,
obviously). To make things more interesting, we also created a
transfer database that serves as an intermediate step the data takes
on its way from the ERP to the PDM database (but it only has a single
table).
My first thought was to just create a trigger on the table in the ERP
database where projects are stored to insert a corresponding record in
the transfer database. But my research led me to think that this is
generally considered a bad idea, because then any hickup in the
process of transferring data would cause the initial transation that
created the project to fail. Needless to say, our users would not like
that very much.
I came across a suggestion, though, to use the Service Broker that
comes with SQL Server and use a message queue to decouple these
steps. I liked this idea, because I wanted to avoid having to write,
set up and maintain yet another program to transfer the data. If I
could keep everything in the database instance, I thought, things will
be easier to understand. I might have been wrong about that, but I am
not entirely sure what I could have done better.
So with the current setup, the data flow looks like this:
- User creates a new project
- A trigger on the project table in the ERP database extracts some
metadata about the project, creates an XML message and writes that
to the message queue. - This triggers an activation procedure to read the message from the
queue, extract the metadata and insert a record into the transfer
database. - A trigger on the transfer database/table reads the new record, does
a little data mangling and inserts a new record into the PDM
database table that stores projects on the PDM side (which in turn
causes triggers to run, that cause triggers to run). This trigger
was originally written by a consultant from the company that sold us
the PDM software, but since that consultant is far more expensive
than me, maintenance of that thing has landed in my lap.
(And just to be clear, I do kind of like it. generally. It is
interesting work, and I get to help to bridge the gap people
sometimes see between the IT side and the business side.)
We have recreated the complete setup of ERP database, Transfer
database, and PDM database on a testing system.
And this is where things get really strange.
If we create a new project in the ERP testing instance, it does not
arrive.
I see the XML message arrive in the message queue, and it looks pretty
much the way I expect it to. But from there, things go sideways.
In the ERROR log file of the SQL Server instance, many message
appear that tell me: "The activated proc [dbo].[PDM_Transfer] running
on queue 'MyCompany.dbo.project_transfer_queue' output the following:
Conversion failed when converting the varchar value 'FEHLER ' to data
type int." In case it matters: FEHLER is German for ERROR. We are
located in Germany, so that is not surprising as such – the rest of
the error message is in English, though.
I find this message confusing, because the only place where my sproc
attempts to convert text to an integer is when extracting fields from
the XML message that have been filled with an integer value from the
ERP database. So as far as I understand, it should be pretty much
impossible for anything but a valid integer literal to appear there.
And when I inspect the XML messages, like I said, they look the way I
expect them to.
If at some point in the whole chain of triggers and sprocs, some piece
of code actually tried to convert the string "FEHLER " to an int, it
is no surprise that fails. But I am at a loss where this could happen
and why.
To make things more confusing, I deactivated the sproc on the message
queue (in the sense that it was no longer called automatically. Then
I called the sproc manually from the SSMS debugger.
And it worked exactly the way it should.
At that point I began to suspect it might be a permission
problem. Normally the activation procedure on the message queue runs
under a dedicated user, when I call the sproc manually, it runs under
my user account (obviously), which has (almost) unrestricted
permissions on the test database.
So I checked the account under which the activation procedure is
executed on the message queue, compared its permissions with those in
the production system. I discovered a few discrepancies, but after I
fixed those, the problem remained the same.
Just to be extra sure, I removed all the service broker objects and
recreated them.
By now, I am at the end of my rope. Can anyone give me a hint where I
can look for the root cause of my problem?
Thank you very much,
Benjamin
EDIT: As suggested by Aaron Bertrand, here is the source code to the sproc and table/s that are affected by it.
I tried to make the source code as readable as I could, and add a few comments to explain things I thought were non-obvious. But the source code is kind of long (by my standards at least), so I probably missed quite a few places. If you see something that is unclear, I will happily explain it if you ask.
It seems that the source code is not formatted properly. Not sure if it is just too long or too ugly. I am not sure how to fix it. 🙁
So without further ado, here we go:
CREATE PROCEDURE dbo.ProFile_Transfer
AS
BEGIN
DECLARE @conversation_handle UNIQUEIDENTIFIER;
DECLARE @messagetypename VARCHAR(256);
DECLARE @messagebody XML;
DECLARE @message_type VARCHAR(MAX);
DECLARE @transaction_name VARCHAR(MAX);
DECLARE @tmp VARCHAR(MAX);
DECLARE @projektnummer VARCHAR(MAX);
DECLARE @kurztext VARCHAR(MAX);
DECLARE @vertreter VARCHAR(MAX);
DECLARE @anlagedatum DATETIME;
DECLARE @kundennummer INT;
DECLARE @status INT;
DECLARE @vorgang VARCHAR(MAX);
DECLARE @kunde VARCHAR(MAX);
DECLARE @kunde2 VARCHAR(MAX);
DECLARE @anschrift VARCHAR(MAX);
DECLARE @ort VARCHAR(MAX);
DECLARE @telefon VARCHAR(MAX);
DECLARE @fax VARCHAR(MAX);
DECLARE @kostenstelle INT;
DECLARE @LOGMSG VARCHAR(MAX);
DECLARE @MSGLEN INT;
SET NOCOUNT ON;
-- Originally, the ERP database and the PDM database resided on
-- different SQL servers, therefore we use a distributed transaction.
-- Both databases now reside in the same SQL Server instance, so
-- the distributed transaction is not required any more.
-- I have decided to keep it nevertheless, because I am not sure
-- of the implications.
BEGIN DISTRIBUTED TRANSACTION;
BEGIN TRY
WAITFOR(
RECEIVE TOP (1) @conversation_handle = conversation_handle,
@messagetypename = message_type_name,
@messagebody = CAST(message_body AS XML)
FROM projekt_transfer_rcv_queue),
TIMEOUT 60000;
IF @@ROWCOUNT = 0
BEGIN
ROLLBACK TRANSACTION;
RETURN 0;
END; -- IF (@@ROWCOUNT = 0)
SET @MSGLEN = DATALENGTH(@messagebody);
IF @messagetypename = 'projekt_transfer_message'
BEGIN
SET @projektnummer = @messagebody.value(
'(Message/Projektnummer/text())[1]', 'VARCHAR(40)'
);
SET @vorgang = @messagebody.value(
'(Message/Vorgang/text())[1]', 'VARCHAR(40)'
);
SET @kurztext = @messagebody.value(
'(Message/Kurztext/text())[1]', 'VARCHAR(40)'
);
SET @vertreter = @messagebody.value(
'(Message/Vertreter/text())[1]', 'VARCHAR(40)'
);
SET @anlagedatum = @messagebody.value(
'(Message/Anlagedatum/text())[1]', 'DATETIME'
);
SET @kundennummer = @messagebody.value(
'(Message/Kundennummer/text())[1]', 'INT'
);
SET @status = @messagebody.value(
'(Message/Projektstatus/text())[1]', 'VARCHAR(40)'
);
SET @kunde = @messagebody.value(
'(Message/Kunde/text())[1]', 'VARCHAR(40)'
);
SET @kunde2 = @messagebody.value(
'(Message/Kunde2/text())[1]', 'VARCHAR(40)'
);
SET @anschrift = @messagebody.value(
'(Message/Anschrift/text())[1]', 'VARCHAR(40)'
);
SET @ort = @messagebody.value(
'(Message/Ort /text())[1]', 'VARCHAR(40)'
);
SET @telefon = @messagebody.value(
'(Message/Telefon/text())[1]', 'VARCHAR(40)'
);
SET @fax = @messagebody.value(
'(Message/Fax/text())[1]', 'VARCHAR(40)'
);
SET @kostenstelle = @messagebody.value(
'(Message/Kostenstelle/text())[1]', 'VARCHAR(40)'
);
-- dbg_log is an sproc that writes a log message to a dedicated table in the
-- PDM transfer database. This was meant to help me in debugging, but it turned out
-- less helpful than I had hoped.
SET @tmp = 'ProjektXFR - '+@projektnummer+' ('+ @vorgang+')';
EXEC dbg_log @tmp;
-- The maximum length of various VARCHAR fields in the ERP database
-- is longer than the corresponding fields in the PDM database.
-- In order to prevent errors, we explicitly check the fields, and
-- if any of them are too long, we truncate them manually and emit
-- a log message.
IF DATALENGTH(@projektnummer) > 40
BEGIN
SET @LOGMSG = 'Projektnummer "'+
@projektnummer+'" ist zu lang: '+CAST(
DATALENGTH(@projektnummer) AS VARCHAR(100));
EXEC dbg_log
@LOGMSG;
END;
IF DATALENGTH(@vorgang) > 40
BEGIN
SET @LOGMSG = 'Vorgangsart "'+@vorgang+
'" ist zu lang: '+CAST(DATALENGTH(@vorgang)
AS VARCHAR(100));
EXEC dbg_log
@LOGMSG;
END;
IF DATALENGTH(@kurztext) > 40
BEGIN
SET @LOGMSG = 'Kurztext "'+@kurztext+
'" ist zu lang: '+CAST(DATALENGTH(@kurztext)
AS VARCHAR(100));
EXEC dbg_log
@LOGMSG;
END;
IF DATALENGTH(@vertreter) > 40
BEGIN
SET @LOGMSG = 'Vertreter "'+@vertreter+
'" ist zu lang: '+CAST(DATALENGTH(
@vertreter) AS VARCHAR(100));
EXEC dbg_log
@LOGMSG;
END;
IF DATALENGTH(@status) > 40
BEGIN
SET @LOGMSG = 'Status "'+@status+
'" ist zu lang: '+CAST(DATALENGTH(@status) AS
VARCHAR(100));
EXEC dbg_log
@LOGMSG;
END;
IF DATALENGTH(@kunde) > 40
BEGIN
SET @LOGMSG = 'Kunde "'+@kunde+
'" ist zu lang: '+CAST(DATALENGTH(@kunde) AS
VARCHAR(100));
EXEC dbg_log
@LOGMSG;
END;
IF DATALENGTH(@kunde2) > 40
BEGIN
SET @LOGMSG = 'Kunde2 "'+@kunde2+
'" ist zu lang: '+CAST(DATALENGTH(@kunde2) AS
VARCHAR(100));
EXEC dbg_log
@LOGMSG;
END;
IF DATALENGTH(@anschrift) > 40
BEGIN
SET @LOGMSG = 'Anschrift "'+@anschrift+
'" ist zu lang: '+CAST(DATALENGTH(
@anschrift) AS VARCHAR(100));
EXEC dbg_log
@LOGMSG;
END;
IF DATALENGTH(@ort) > 40
BEGIN
SET @LOGMSG = 'Ort "'+@ort+'" ist zu lang: '+
CAST(DATALENGTH(@ort) AS VARCHAR(100));
EXEC dbg_log
@LOGMSG;
END;
IF DATALENGTH(@telefon) > 40
BEGIN
SET @LOGMSG = 'Telefonnummer "'+@telefon+
'" ist zu lang: '+CAST(DATALENGTH(@telefon)
AS VARCHAR(100));
EXEC dbg_log
@LOGMSG;
END;
IF DATALENGTH(@fax) > 40
BEGIN
SET @LOGMSG = 'Faxnummer "'+@fax+
'" ist zu lang: '+CAST(DATALENGTH(@fax) AS
VARCHAR(100));
EXEC dbg_log
@LOGMSG;
END;
INSERT INTO TransferERPPRofile.dbo.TransferToPROFILEProject
(MessageType,
IDENT,
DESC1,
RESP_USER,
CREATE_DATE,
CUSTOMER_NO,
PROJECT_STATUS,
CUSTOMER_NAME,
CUSTOMER_SHORTNAME,
CUSTOMER_STREET,
CUSTOMER_TOWN,
CUSTOMER_TEL,
CUSTOMER_FAX,
COST_CENTER
)
VALUES
(@vorgang,
@projektnummer,
@kurztext,
@vertreter,
@anlagedatum,
@kundennummer,
@status,
@kunde,
@kunde2,
@anschrift,
@ort,
@telefon,
@fax,
@kostenstelle
);
END;
ELSE
BEGIN
SET @tmp = 'Unbekannter bzw. unerwarteter Nachrichtentyp: '+ @messagetypename;
PRINT @tmp;
EXEC dbg_log @tmp;
END;
END CONVERSATION @conversation_handle;
COMMIT TRANSACTION;
END TRY
BEGIN CATCH
DECLARE
@ERRORNO INT,
@Severity TINYINT,
@state SMALLINT,
@LineNo INT,
@message NVARCHAR(4000),
@errmsg VARCHAR(MAX);
SELECT @ERRORNO = ERROR_NUMBER(),
@Severity = ERROR_SEVERITY(),
@state = ERROR_STATE(),
@LineNo = ERROR_LINE(),
@Message = ERROR_MESSAGE();
DECLARE @x VARCHAR(MAX);
SET @x = 'FEHLER '+@ERRORNO+
' beim Lesen aus Message Queue, Zeile '+CAST(@LineNo AS
VARCHAR(MAX))+': '+@message;
ROLLBACK TRANSACTION;
EXEC dbg_log @x;
SET @x = 'XML-Nachrichtenlänge war '+CAST(@MSGLEN AS VARCHAR(MAX))+' bytes.';
EXEC dbg_log @x;
END CATCH;
END;
CREATE PROCEDURE [dbo].[dbg_log]
@msg varchar(max)
--WITH EXECUTE AS 'anw'
AS
BEGIN TRY
INSERT INTO TransferERPProfile.dbo.DebugLog( [Timestamp], [Message] )
VALUES( GETDATE(), @msg );
END TRY
BEGIN CATCH
END CATCH;
GO
USE [TransferERPProfile];
GO
/****** Object: Table [dbo].[TransferToPROFILEProject] Script Date: 27.11.2017 08:27:05 ******/
SET ANSI_NULLS ON;
GO
SET QUOTED_IDENTIFIER ON;
GO
SET ANSI_PADDING ON;
GO
CREATE TABLE dbo.TransferToPROFILEProject
(MessageID INT IDENTITY(1, 1) NOT NULL,
MessageType VARCHAR(50) NOT NULL,
MessageRetVal INT NULL,
MessageRetDate DATETIME NULL,
IDENT VARCHAR(50) NOT NULL,
DESC1 VARCHAR(50) NULL,
RESP_USER VARCHAR(50) NULL,
CREATE_DATE DATETIME NOT NULL,
CUSTOMER_NO INT NOT NULL,
PROJECT_STATUS INT NULL,
CUSTOMER_NAME VARCHAR(50) NULL,
CUSTOMER_SHORTNAME VARCHAR(50) NULL,
CUSTOMER_STREET VARCHAR(50) NULL,
CUSTOMER_TOWN VARCHAR(50) NULL,
CUSTOMER_TEL VARCHAR(50) NULL,
CUSTOMER_FAX VARCHAR(50) NULL,
COST_CENTER INT NULL,
CONSTRAINT PK_TransferToPROFILEProject
PRIMARY KEY CLUSTERED(MessageID ASC)
WITH(PAD_INDEX = OFF,
STATISTICS_NORECOMPUTE = OFF,
IGNORE_DUP_KEY = OFF,
ALLOW_ROW_LOCKS = ON,
ALLOW_PAGE_LOCKS = ON,
FILLFACTOR = 60)
ON [PRIMARY])
ON [PRIMARY];
GO
SET ANSI_PADDING OFF;
GO
EXEC sys.sp_addextendedproperty
@name = N'MS_Description',
@value = N'Transfertabelle für Daten aus Mosaik ins Pro.File',
@level0type = N'SCHEMA',
@level0name = N'dbo',
@level1type = N'TABLE',
@level1name = N'TransferToPROFILEProject';
GO
CREATE TABLE [dbo].[DebugLog](
[ID] [int] IDENTITY(1,1) NOT NULL,
[Timestamp] [datetime] NOT NULL,
[Message] [varchar](max) NOT NULL,
CONSTRAINT [PK_DebugLog] PRIMARY KEY CLUSTERED
(
[ID] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON, FILLFACTOR = 60) ON [PRIMARY]
) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY]
GO
SET ANSI_PADDING OFF
GO
Best Answer
Just in case anyone ever runs into this kind of problem, I think I have figured out the problem and found a solution. The root cause apparently was an embarrassing misunderstanding of T-SQL's type system on my part.
While not the most elegant approach to problem solving, using grep to search for instances of the string "FEHLER " throughout my SQL code has led me to the following piece of code near the end of the SProc:
@xis a variable of type VARCHAR(MAX). In most programming languages where VARCHAR/STRING + INT is defined and legal, the integer value gets converted to a string/varchar automatically.Apparently, T-SQL tries to convert the first part (
'FEHLER ') to an INT instead.Replacing
@ERRORNOwithCONVERT(VARCHAR(MAX), @ERRORNO)has made this problem disappear.I feel kind of sheepish that the mistake had been sitting right in front of me the whole time, but at least I am relieved that it is working now.
Cheers, Benjamin