Introduction

Novell Identity Manager has a number of drivers for a variety of systems. The SAP HR driver is designed to allow the SAP Human Resources module to provision users as they are hired, changed, and terminated.

The SAP HR driver uses two different technologies to communicate on the two channels. On the Subscriber channel (From the eDirectory tree to SAP dataflow) the driver uses BAPI via the JConnect libraries. See a related article at:
http://www.novell.com/communities/node/2792/idm-sap-hr-driver-where-get-jconnect-libraries

On the Publisher channel (the channel where data flows from SAP HR to eDirectory) the driver uses iDOCS (Intermediate documents) to transfer data. See related documents at:
http://www.novell.com/communities/node/4144/decoding-idocs-idm-sap-driver

In the article above Decoding iDOCS, I discuss how to look at an iDOC read it, and understand it. But sometimes even though you think you have every thing set correctly, it is still not working. Where do you go from there? The purpose of this article is to run through an example to help you understand what is going on, and what to look for when things go wrong.

Troubleshooting

Usually the first place to start troubleshooting in an Identity Manager environment is looking at trace files. There are two places in each driver to look at trace files: the engine view and the remote loader/shim view. See a related article about reading trace files at:
http://www.novell.com/communities/node/4428/guide-reading-dstrace-output-identity-manager

Let's work through a specific example I ran through. The SAP HR people were using the Infotype 105, USRID field for a variety of things. In fact, the default configuration uses several subtypes already for the pager and fax numbers. The schema definition looks something like this: P0105:USRID:78:30 in the HRMD_A06.meta file. This means for the P object (P) infotype 105 (0105), the field is USRID, which is 78 characters into the line and runs for 30 characters long. (The 78th character comes after it starts counting; since the zeroth (0th) placeholder is not the beginning of the line, it is usually about 63 characters in - we will see more about this later.)

This is a typical meta file definition.

In the Schema mapping rules of the driver, we get an extra field, between the USRID and the 78. For most fields we leave it as "none" (P0002:PERNR:none:0:8), which is the Person number (WorkforceID, employeeNumber, etc) in the P object's Infotype 0002. This is at the 0th point in the line and is 8 characters long. The "none" value means that there are no specific subtypes.

When you have a subtype, you will see the same Infotype line in the iDOC one for each subtype. This looks something like the following:

E2P0105002                    4000000000011548069000016000015040000871701050001   999912312004010100020071220HR-SUPER                   0001BC1234                                                                                                                                                                                                                                                                          

Here we have an Infotype 105, subtype 001. We are using this for the username, which is used as the CN in the Identity Vault in eDirectory. The 78th position is ABC1234, immediately before it is the 001 value of the subtype.

The Infotype 105 full meta file definition is shown below, so you can parse this line. The meta file contains all the infotype definitions and can be quite long, as there are many infotypes with many many components to define.

SEGMENT:P0105:E1P0105:
P0105:PERNR:0:8
P0105:INFTY:8:4
P0105:SUBTY:12:4
P0105:OBJPS:16:2
P0105:SPRPS:18:1
P0105:ENDDA:19:8
P0105:BEGDA:27:8
P0105:SEQNR:35:3
P0105:AEDTM:38:8
P0105:UNAME:46:12
P0105:HISTO:58:1
P0105:ITXEX:59:1
P0105:REFEX:60:1
P0105:ORDEX:61:1
P0105:ITBLD:62:2
P0105:PREAS:64:2
P0105:FLAG1:66:1
P0105:FLAG2:67:1
P0105:FLAG3:68:1
P0105:FLAG4:69:1
P0105:RESE1:70:2
P0105:RESE2:72:2
P0105:USRTY:74:4
P0105:USRID:78:30
P0105:USRID_LONG:108:241

So the Person number is the beginning, (0th character, running for 8 characters, whose value is 00008717 in our example iDOC). Then we have the Infotype for 4 characters, which is 0105, then the Subtype for 4 characters, which is 0001. Then we skip the rest, since we don't really care at this point, down to the third last entry of USRTY at position 74. This seems to duplicate the Subtype value of 0001.

The value we really care about is USRID. This is set to ABC1234 with 23 blank spaces after it at the 78th place holder, running for 30 characters.

For the same user, we might also have a line in the iDOC that looks like this:

E2P0105002                    4000000000011548069000016000015040000871701050010   999912312004010100020071220HR-SUPER                   0010ABCUSER@ACME.COM

In this case, the Subtype is 0010 and the value of USRID is ABCUSER@ACME.COM, since we want to use Subtype 0010 to represent the email address.

In my case, I wanted to use subtype 0030 to represent a flag as to whether to provision an email account or not. So we were getting this:

E2P0105002                    4000000000011548069000016000015040000871701050030   999912312004010100020071220HR-SUPER                   0030                       YES                                                                                                                                                                                                                                                          

where the value of the field was 23 spaces, then the string "YES". For some reason, the driver would not pick that up, and we never resolved it. We instead moved to use infotype 0040, which is left justified, and would look like this:

E2P0105002                    4000000000011548069000016000015040000871701050040   999912312004010100020071220HR-SUPER                   0040YES                                                                                                                                                                                                                                                                              

But for some reason it was still not picking up the event.

So finally I went to trace to look at it. The problem was that the engine trace was showing an empty modify document coming in. That is, there was a modify for an associated user, but there was nothing being modified. This is not very helpful at all!

It was time to look in the remote loader trace. In my case, we were running the dirxml_jremote lightweight remote loader on an AIX server. We had set the configuration file to a trace level of 3, and were seeing that the iDOC was recognized, coming in with no changes. It looked something like this:

DirXML: [04/07/08 15:55:23.643]: TRACE:  ParseIDoc: No Character Set Encoding specified. Using default encoding: ISO8859_1
DirXML: [04/07/08 15:55:23.644]: TRACE:  ParseIDoc: IDoc file opened successfully.
DirXML: [04/07/08 15:55:23.669]: TRACE:  ParseIDoc: File '/idm/idocs/O_400_0000000011563061' renamed to '/idm/idocs/O_400_0000000011563061.proc' successfully.
DirXML: [04/07/08 15:55:23.670]: TRACE:  SAPPublicationShim: Sending event doc for P 00000700
DirXML: [04/07/08 15:55:23.670]: TRACE:  Remote Loader: Received document from publicationShim
DirXML: [04/07/08 15:55:23.671]: TRACE:  <nds dtdversion="1.0" ndsversion="8.5">
	<source>
		<product build="20070918_0739 " instance="SAP-HR351" version="3.5.1">DirXML Driver for SAP/HR</product>
		<contact>Novell, Inc.</contact>
	</source>
	<input xmlns:sapshim="http://www.novell.com/dirxml/drivers/SAPShim">
		<modify class-name="P" event-id="SAP-HR351:O_400_0000000011563061:P 00000700" src-dn="00000700" timestamp="20080407">
			<association>00000700</association>
		</modify>
	</input>
</nds>

It found the iDOC, as we can see, and parsed it. It recognized there was a modify event, but nothing was being changed in the modify event. It was time for trace level 5 - when in doubt, up the trace level!

Trace level is controlled in the remote loader configuration file. The location of the file depends on how you configured it, so I couldn't specify an exact path. It looked something like this:

-commandport 8001
-connection "port=8090"
-trace 3
-tracefile /idm/trace8000.log
-tracefilemax 200M
-description sap-hr
-class com.novell.nds.dirxml.driver.SAPShim.SAPDriverShim

The line "-trace 3" is the one to edit. I set it to 5 and restarted the remote loader.

Now looking at the trace we see:

DirXML: [04/07/08 16:33:32.672]: TRACE:  ParseIDoc: No Character Set Encoding specified. Using default encoding: ISO8859_1
DirXML: [04/07/08 16:33:32.674]: TRACE:  ParseIDoc: IDoc file opened successfully.
DirXML: [04/07/08 16:33:32.679]: TRACE:  ParseIDoc: IDoc to parse: /idm/idocs/O_400_0000000011563061
DirXML: [04/07/08 16:33:32.705]: TRACE:  ParseIDoc: Segment EDI_DC40
DirXML: [04/07/08 16:33:32.706]: TRACE:  ParseIDoc: Segment E2PLOGI
DirXML: [04/07/08 16:33:32.719]: TRACE:  ParseIDoc: Object type P found in filter.
DirXML: [04/07/08 16:33:32.719]: TRACE:  ParseIDoc: Parsing object type P segment
DirXML: [04/07/08 16:33:32.720]: TRACE:  ParseIDoc: Object identifier: 00000700
DirXML: [04/07/08 16:33:32.720]: TRACE:  ParseIDoc: Operation: U
DirXML: [04/07/08 16:33:32.721]: TRACE:  ParseIDoc: Parsing infotype: 0105, subtype: 0040
DirXML: [04/07/08 16:33:32.875]: TRACE:  ParseIDoc: GSA segment 'E2P0105002'
DirXML: [04/07/08 16:33:32.893]: TRACE:  ParseIDoc: Infotype 'P0105' is in filter or valid
DirXML: [04/07/08 16:33:32.893]: TRACE:  ParseIDoc: Found a communication in segment, type: 0040
DirXML: [04/07/08 16:33:32.897]: TRACE:  ParseIDoc: Found a communication in key, type: 0001
DirXML: [04/07/08 16:33:32.897]: TRACE:  ParseIDoc: Infotype 'P0105' is in filter or valid
DirXML: [04/07/08 16:33:32.898]: TRACE:  ParseIDoc: Found a communication in segment, type: 0040
DirXML: [04/07/08 16:33:32.898]: TRACE:  ParseIDoc: Found a communication in key, type: 0030
DirXML: [04/07/08 16:33:32.899]: TRACE:  ParseIDoc: Infotype 'P0105' is in filter or valid
DirXML: [04/07/08 16:33:32.900]: TRACE:  ParseIDoc: Found a communication in segment, type: 0040
DirXML: [04/07/08 16:33:32.900]: TRACE:  ParseIDoc: Found a communication in key, type: MPHN
DirXML: [04/07/08 16:33:32.901]: TRACE:  ParseIDoc: Infotype 'P0105' is in filter or valid
DirXML: [04/07/08 16:33:32.901]: TRACE:  ParseIDoc: Found a communication in segment, type: 0040
DirXML: [04/07/08 16:33:32.902]: TRACE:  ParseIDoc: Found a communication in key, type: 9200
DirXML: [04/07/08 16:33:32.903]: TRACE:  ParseIDoc: Infotype 'P0105' is in filter or valid
DirXML: [04/07/08 16:33:32.903]: TRACE:  ParseIDoc: Found a communication in segment, type: 0040
DirXML: [04/07/08 16:33:32.904]: TRACE:  ParseIDoc: Found a communication in key, type: 0010
DirXML: [04/07/08 16:33:32.909]: TRACE:  ParseIDoc: File '/idm/idocs/O_400_0000000011563061' renamed to '/idm/idocs/O_400_0000000011563061.proc' successfully.
DirXML: [04/07/08 16:33:32.931]: TRACE:  ParseIDoc: Number of elements in idocData: 1
DirXML: [04/07/08 16:33:32.935]: TRACE:  SAPPublicationShim: Received '1' docs from ParseIDoc.
DirXML: [04/07/08 16:33:32.962]: TRACE:  <nds dtdversion="1.0" ndsversion="8.5">
	<source>
		<product build="20070918_0739 " instance="SAP-HR351" version="3.5.1">DirXML Driver for SAP/HR</product>
		<contact>Novell, Inc.</contact>
	</source>
	<input xmlns:sapshim="http://www.novell.com/dirxml/drivers/SAPShim">
		<modify class-name="P" event-id="SAP-HR351:O_400_0000000011563061:P 00000700" src-dn="00000700" timestamp="20080407">
			<association>00000700</association>
		</modify>
	</input>
</nds>
DirXML: [04/07/08 16:33:33.029]: TRACE:  SAPPublicationShim: Sending event doc for P 00000700

Now we have some interesting information revealed. The parsing of the iDOC is broken out, and we can see that it does recognize the 105 infotype for the P object. This is good to know. It recognizes that there is a subtype 0040 in the document, and it walks through the schema mapping for the 105 subtypes that it knows about. It knows about 0001 (which is the User name), 0030 (a flag to signal email account or not), MHPN (Cell phone number), 9200 (pager number), and 0010 (email address) - but apparently not 0040.

I decided to see what happens in trace when it does parse and find something in the iDOC, so I could better understand what was going on. Here is the trace of it finding a Username in subtype 0001:

DirXML: [04/07/08 16:36:09.661]: TRACE:  ParseIDoc: No Character Set Encoding specified. Using default encoding: ISO8859_1
DirXML: [04/07/08 16:36:09.662]: TRACE:  ParseIDoc: IDoc file opened successfully.
DirXML: [04/07/08 16:36:09.671]: TRACE:  ParseIDoc: IDoc to parse: /idm/idocs/O_400_0000000011563061GMC
DirXML: [04/07/08 16:36:09.674]: TRACE:  ParseIDoc: Segment EDI_DC40
DirXML: [04/07/08 16:36:09.675]: TRACE:  ParseIDoc: Segment E2PLOGI
DirXML: [04/07/08 16:36:09.676]: TRACE:  ParseIDoc: Object type P found in filter.
DirXML: [04/07/08 16:36:09.677]: TRACE:  ParseIDoc: Parsing object type P segment
DirXML: [04/07/08 16:36:09.677]: TRACE:  ParseIDoc: Object identifier: 00000700
DirXML: [04/07/08 16:36:09.678]: TRACE:  ParseIDoc: Operation: U
DirXML: [04/07/08 16:36:09.679]: TRACE:  ParseIDoc: Parsing infotype: 0105, subtype: 0040
DirXML: [04/07/08 16:36:09.682]: TRACE:  ParseIDoc: GSA segment 'E2P0105002'
DirXML: [04/07/08 16:36:09.684]: TRACE:  ParseIDoc: Infotype 'P0105' is in filter or valid
DirXML: [04/07/08 16:36:09.685]: TRACE:  ParseIDoc: Found a communication in segment, type: 0001
DirXML: [04/07/08 16:36:09.686]: TRACE:  ParseIDoc: Found a communication in key, type: 0001
DirXML: [04/07/08 16:36:09.687]: TRACE:  ParseIDoc: Field name: 'P:P0105:USRID:0001'
DirXML: [04/07/08 16:36:09.694]: TRACE:  ParseIDoc: keyVal is 78:30
DirXML: [04/07/08 16:36:09.697]: TRACE:  ParseIDoc:   Field data is at location 78, length 30
DirXML: [04/07/08 16:36:09.721]: TRACE:  ParseIDoc:   IDOCOFFSET: '141', len: '30'
DirXML: [04/07/08 16:36:09.722]: TRACE:  ParseIDoc:   Field data is: 'BC1234'
DirXML: [04/07/08 16:36:09.724]: TRACE:  ParseIDoc: Putting field 'P0105:USRID:0001:78:30', value 'BC1234' in inputHash vector
DirXML: [04/07/08 16:36:09.728]: TRACE:  ParseIDoc: Infotype 'P0105' is in filter or valid
DirXML: [04/07/08 16:36:09.729]: TRACE:  ParseIDoc: Found a communication in segment, type: 0001
DirXML: [04/07/08 16:36:09.730]: TRACE:  ParseIDoc: Found a communication in key, type: 0030
DirXML: [04/07/08 16:36:09.730]: TRACE:  ParseIDoc: Infotype 'P0105' is in filter or valid
DirXML: [04/07/08 16:36:09.731]: TRACE:  ParseIDoc: Found a communication in segment, type: 0001
DirXML: [04/07/08 16:36:09.732]: TRACE:  ParseIDoc: Found a communication in key, type: MPHN
DirXML: [04/07/08 16:36:09.733]: TRACE:  ParseIDoc: Infotype 'P0105' is in filter or valid
DirXML: [04/07/08 16:36:09.734]: TRACE:  ParseIDoc: Found a communication in segment, type: 0001
DirXML: [04/07/08 16:36:09.734]: TRACE:  ParseIDoc: Found a communication in key, type: 9200
DirXML: [04/07/08 16:36:09.735]: TRACE:  ParseIDoc: Infotype 'P0105' is in filter or valid
DirXML: [04/07/08 16:36:09.736]: TRACE:  ParseIDoc: Found a communication in segment, type: 0001
DirXML: [04/07/08 16:36:09.737]: TRACE:  ParseIDoc: Found a communication in key, type: 0010
DirXML: [04/07/08 16:36:09.745]: TRACE:  ParseIDoc: File '/idm/idocs/O_400_0000000011563061GMC' renamed to '/idm/idocs/O_400_0000000011563061GMC.proc' successfully.
DirXML: [04/07/08 16:36:09.746]: TRACE:  ParseIDoc: Number of elements in idocData: 1
DirXML: [04/07/08 16:36:09.747]: TRACE:  SAPPublicationShim: Received '1' docs from ParseIDoc.
DirXML: [04/07/08 16:36:09.749]: TRACE:  SAPPublicationShim: Comm add value check: 'P0105:USRID:0001:78:30'
DirXML: [04/07/08 16:36:09.750]: TRACE:  SAPPublicationShim:    field value: 'BC1234'
DirXML: [04/07/08 16:36:09.750]: TRACE:  SAPPublicationShim:        begdate: '20080401'
DirXML: [04/07/08 16:36:09.751]: TRACE:  SAPPublicationShim:        enddate: '99991231'
DirXML: [04/07/08 16:36:09.752]: TRACE:  SAPPublicationShim:          SEQNR: '000'
DirXML: [04/07/08 16:36:09.755]: TRACE:  <nds dtdversion="1.0" ndsversion="8.5">
	<source>
		<product build="20070918_0739 " instance="SAP-HR351" version="3.5.1">DirXML Driver for SAP/HR</product>
		<contact>Novell, Inc.</contact>
	</source>
	<input xmlns:sapshim="http://www.novell.com/dirxml/drivers/SAPShim">
		<modify class-name="P" event-id="SAP-HR351:O_400_0000000011563061GMC:P 00000700" src-dn="00000700" timestamp="20080407">
			<association>00000700</association>
			<modify-attr attr-name="P0105:USRID:0001:78:30">
				<remove-all-values/>
				<add-value>
					<value seqnr="000" timestamp="20080401-99991231">BC1234</value>
				</add-value>
			</modify-attr>
		</modify>
	</input>
</nds>

The snippet below is instructive:

DirXML: [04/07/08 16:36:09.679]: TRACE:  ParseIDoc: Parsing infotype: 0105, subtype: 0040
DirXML: [04/07/08 16:36:09.682]: TRACE:  ParseIDoc: GSA segment 'E2P0105002'
DirXML: [04/07/08 16:36:09.684]: TRACE:  ParseIDoc: Infotype 'P0105' is in filter or valid
DirXML: [04/07/08 16:36:09.685]: TRACE:  ParseIDoc: Found a communication in segment, type: 0001
DirXML: [04/07/08 16:36:09.686]: TRACE:  ParseIDoc: Found a communication in key, type: 0001
DirXML: [04/07/08 16:36:09.687]: TRACE:  ParseIDoc: Field name: 'P:P0105:USRID:0001'
DirXML: [04/07/08 16:36:09.694]: TRACE:  ParseIDoc: keyVal is 78:30
DirXML: [04/07/08 16:36:09.697]: TRACE:  ParseIDoc:   Field data is at location 78, length 30
DirXML: [04/07/08 16:36:09.721]: TRACE:  ParseIDoc:   IDOCOFFSET: '141', len: '30'
DirXML: [04/07/08 16:36:09.722]: TRACE:  ParseIDoc:   Field data is: 'BC1234'
DirXML: [04/07/08 16:36:09.724]: TRACE:  ParseIDoc: Putting field 'P0105:USRID:0001:78:30', value 'BC1234' in inputHash vector

We see that there was an infotype 105 event in the document: it was a 0001 segment and key. We see that the location in Field data is 78 for a length of 30, but the IDOCOFFSET is actually 141. So, there are 63 characters that don't count showing up. It gets the correct value, BC1234, that I had set in the test iDOC for this example.

We then see that it keeps trying for each of the other 105 subtypes in the schema filter until finally it is ready to convert the iDOC info into an XDS document to send to the engine.

Resolution

So why was it not pulling out my subtype in the iDOC I was sending it?

It turns out that the subtype 0030 that I originally was using, but was not working, does not seem to like the right- justified value of YES. The syntax of the subtype 0040 in SAP sets it as left-justified, and the driver WILL pick it up, once you correct an important step.

You need to actually add the attribute to the Schema Map and into the Filter of the driver and restart the driver. I was using Designer for Identity Manager, and there were two replicas of this development tree. One was remote and the other was local. For some foolish reason, I was updating against one replica (the remote one), but running iManager to restart the driver on the other replica.

A common example of this might be if you are testing against the remote replica. In my case, there was a production eDirectory instance running on the local server, so I was trying to add all my testing load to the remote replica. However, some of your testing may be done in ConsoleOne (say, flipping a flag attribute from true to false, etc.).

Console One, when run on Windows with the Novell client is smart enough to try and find the closest (usually defined as the fastest responding replica) replica. Which would of course be the local replica in this case. Normally this would be a good thing! I find this a bit annoying in testing, as a change I make via Console One does not cause an immediate event in Identity Manager! The fastest solution I could think of was to use ndstrace on the local replica (when you run it, you will be prompted which eDirectory instance you want to monitor, if like me, you are running more than one instance on a single box), and issuing the command "set dstrace=*h" to kick off a heart beat event. Usually I have the log for the driver I am testing running via tail -f in an SSH session, and as soon as I hit enter on the set dstrace=*h command, I will see the log start to process events.

Console One on Linux does not appear to exhibit this issue, as Jclient which provides the NCP access to eDirectory does not seem to look for the fastest local replica, the same way that Client 32 for Windows does. On Linux, when you tell Console One to login to a server address, it logs in and stays in that specific server.

In this particular case, changes I had just uploaded via Designer's Compare function, had not yet synchronized between the two replicas, so when I restarted the driver, I was still running with the old configuration, which was missing the filter modification. However, I learned a lot of interesting things about the SAP HR driver and trace level 5 in the process, so it was probably worth the frustration.

My hope is that this example will give you a feel for some of the troubleshooting you can perform via the remote loader trace, and see how the driver is supposed to act, and what it might look like when it is not acting the way you want. I think examples that walk through a trace can be very helpful. Please let me know what you think in comments to this article!