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
{ }button in the editor.