Decoding BlackBerry Server NSD Logs

Even though I've tried to optimize my environment to the best of my ability, I will still occasionally see the dreaded Fault report that one of my BES servers has crashed. If this happens to you, here is how you can decode the NSD log that Domino creates and track it back to what BES was doing at the time. In some situations - not all - this can help you figure out what is going on and resolve it yourself instead of waiting for a log file analysis from RIM.

For example, I just happen to have an NSD log from a crash that happened this morning. These crash files can be found in the "Lotus\Domino\Data\IBM_TECHNICAL_SUPPORT" directory of your data partition. The NSD log file is name something like this:

nsd_W32I_[YOUR SERVER NAME]_2007_03_18@21_15_02.log

In my experience, most of the relevant information can be gleaned from the first page full of information. The first thing we want to look for is the following line right near the top:

Arguments : "c:\lotus\domino\nsd.exe" -dumpandkill -termstatus 5 -crashpid 4592 -crashtid 3252

The most important information is the "-crashtid 3252" portion, which indicates that the thread ID that caused the crash is 3252 decimal. Well if you remember, the BlackBerry log files record the thread ID for every operation, however they are encoded in Hex. So using calc we convert 3252 decimal = CB4 Hex.

With the thread ID known, lets parse the BES MAGT log for the thread ID CB4. I use the line "grep 'xCB4' [logfile name]" The final line of this thread process is this:

[40000] (03/18 20:42:38):{0xCB4} CN=XXXX/OU=XXXX/O=XXXX!!mail\XXXX.nsf, fetching modified documents since 03/18/2007 08:42:37 PM for user XXXX

Of course identifying information has been removed to protect the innocent, however this appears to be the last thing this thread did before the server crashed. I think we have our culprit mailfile.

So now I open the mailfile and look in the All Documents view, and discover there is a Sent Item from guess what time? That's right: 03/18/2007 08:42:37 PM. Could this be our culprit document? It appears to be a reply, initiated from the device, to an email that contains a large bitmap in the body.

To verify, I check the NoteID; it is "1C542". If I now do a search on "1C542" in the NSD file I find the following lines:

@[22] 0x6001f146 nnotes._NSFNoteOpenExtended@24+678 (71,1c542,4080000,0,35b4eb34,17)
@[23] 0x6003d3b7 nnotes._NSFNoteOpen@16+55 (71,1c542,0,35b4f7d0)
[24] 0x0058ab01 nBES (6a033c,5f,71,1c542) - SYM FILE OUTDATED!
[25] 0x0058f2d4 nBES (1c542,0,0,d4683b3) - SYM FILE OUTDATED!
# 35b4f310 35b4f7d0 00000000 0001c542 0bd1a0e4 |...5....B.......|
@[22] 0x6001f146 nnotes._NSFNoteOpenExtended@24+678 (71,1c542,4080000,0,35b4eb34,17)
# 35b4f354 35b4f380 6003d3b7 00000071 0001c542 |...5...`q...B...|
# 35b4f374 0001c542 35b4f7d0 00000010 35b4f5ac |B......5.......5|
@[23] 0x6003d3b7 nnotes._NSFNoteOpen@16+55 (71,1c542,0,35b4f7d0)
# 35b4f380 35b4f5ac 0058ab01 00000071 0001c542 |...5..X.q...B...|
# 35b4f560 35b4f5c4 0058f993 0001c542 35b4f7c8 |...5..X.B......5|
[24] 0x0058ab01 nBES (6a033c,5f,71,1c542) - SYM FILE OUTDATED!
# 35b4f5bc 00000071 0001c542 00000000 35b4f7d0 |q...B..........5|
# 35b4f61c 00000002 0d44e858 00475182 0001c542 |....X.D..QG.B...|
[25] 0x0058f2d4 nBES (1c542,0,0,d4683b3) - SYM FILE OUTDATED!
# 35b4f620 0d44e858 00475182 0001c542 00000000 |X.D..QG.B.......|
# 35b4f700 0001c542 0d2e7b15 1f7957bc 00096573 |B....{...Wy.se..|
# 35b4f7d0 00003306 0001c542 00000001 00000000 |.3..B...........|
@[22] 0x6001f146 nnotes._NSFNoteOpenExtended@24+678 (71,1c542,4080000,0,35b4eb34,17)
@[23] 0x6003d3b7 nnotes._NSFNoteOpen@16+55 (71,1c542,0,35b4f7d0)
# 35b4f7d0 00003306 0001c542 00000001 00000000 |.3..B...........|
[24] 0x0058ab01 nBES (6a033c,5f,71,1c542) - SYM FILE OUTDATED!
[25] 0x0058f2d4 nBES (1c542,0,0,d4683b3) - SYM FILE OUTDATED!


It looks like NBES was trying to open this Note using the NSFNoteOpen and NSFNoteOpenExtended API calls when it crashed the server. So now I am sure this note caused the crash. What now? Delete the note from the user's mailfile so that it now resides in the trash, then restart the BES server. Of course you want to let the user know why their message is in the trash, and of course follow up on RIM on why this happened in the first place. But at least you have the server back up!

Moves between Servers - Not 100% foolproof

I moved over 500 accounts from an old BES server to a new BES server today. I set the expectation with our regional managers and BB admins that there would be no impact to end users during this migration. How could I be so naive?

First, a minor amount of users were not able to send or send & receive after the move, and required either pushing the service books, reactivation, or complete account removal and re-add / re-activate to get working again. This is not so bad, it is a small number (<20 probably) of 500 people.

The bigger problem was this: The source (old) BES server's "Blackberry Synchronization Service" would sometimes freak out during bulk moves. I would move maybe 50 people at a time max, but apparently that was too much for the sync service to handle. So it would just quit, and I would have to restart it. I also noticed that the initial moves went really fast, a few per minute, but then they started to bog down and it would take 5 minutes to move one account.

That is no big deal, until I realized by looking through the logs what was happening: the sync service contains the device backup service, and it was going through and deleting the backup data not only for the accounts being moved, but FOR EVERY USER ON THE SERVER: (names removed to protect the innocent)

[46036] (03/14 10:15:41):{0xC50} [SYNC-Gate] Start removing user. [W
[46036] (03/14 10:15:41):{0xC50} [SYNC-Gate] Start removing user. [R
[46036] (03/14 10:15:42):{0xC50} [SYNC-Gate] Start removing user. [Z
[46036] (03/14 10:15:42):{0xC50} [SYNC-Gate] Start removing user. [O
[46036] (03/14 10:15:43):{0xC50} [SYNC-Gate] Start removing user. [S
[46036] (03/14 10:15:43):{0xC50} [SYNC-Gate] Start removing user. [H
[46036] (03/14 10:15:44):{0xC50} [SYNC-Gate] Start removing user. [K
[46036] (03/14 10:15:44):{0xC50} [SYNC-Gate] Start removing user. [D
[46036] (03/14 10:15:45):{0xC50} [SYNC-Gate] Start removing user. [G
[46036] (03/14 10:15:45):{0xC50} [SYNC-Gate] Start removing user. [B
[46036] (03/14 10:15:46):{0xC50} [SYNC-Gate] Start removing user. [D
[46036] (03/14 10:15:46):{0xC50} [SYNC-Gate] Start removing user. [O
[46036] (03/14 10:15:47):{0xC50} [SYNC-Gate] Start removing user. [S
[46036] (03/14 10:15:48):{0xC50} [SYNC-Gate] Start removing user. [R
[46036] (03/14 10:15:48):{0xC50} [SYNC-Gate] Start removing user. [A
[46036] (03/14 10:15:48):{0xC50} [SYNC-Gate] Start removing user. [C
[46036] (03/14 10:15:49):{0xC50} [SYNC-Gate] Start removing user. [F
[46036] (03/14 10:15:49):{0xC50} [SYNC-Gate] Start removing user. [N
[46036] (03/14 10:15:50):{0xC50} [SYNC-Gate] Start removing user. [R
[46036] (03/14 10:15:50):{0xC50} [SYNC-Gate] Start removing user. [W
[46036] (03/14 10:15:51):{0xC50} [SYNC-Gate] Start removing user. [B
[46036] (03/14 10:15:51):{0xC50} [SYNC-Gate] Start removing user. [G
[46036] (03/14 10:15:52):{0xC50} [SYNC-Gate] Start removing user. [A
[46036] (03/14 10:15:53):{0xC50} [SYNC-Gate] Start removing user. [P
[46036] (03/14 10:15:53):{0xC50} [SYNC-Gate] Start removing user. [Z
[46036] (03/14 10:15:54):{0xC50} [SYNC-Gate] Start removing user. [B
[46036] (03/14 10:15:55):{0xC50} [SYNC-Gate] Start removing user. [L
[46036] (03/14 10:15:58):{0xC50} [SYNC-Gate] Start removing user. [M

Once this happened, it kicked off an OTA device backup, which once again sync'ed everything back from each device, which slowed down EVERYTHING.

Now here is the worst part: many of the devices (with accounts that were not even scheduled to be moved that day) received either:

1) An activation complete - OK prompt
2) A continuing activation process
3) A leftover activation icon on their ribbon (home screen).

I started to get calls from admins in other cities, who weren't even scheduled to be moved that day. Bad.

Lesson: Don't move more than 10-20 accounts at a time, and watch the SYNC service.

Oh, and by the way - the brand new server hardware I migrated to? It crashed this morning. :(

Gathering Wireless Vendor Info from the SQL DB

My manager asked for a report of the BlackBerry users and their associated wireless provider. Given this is all stored in the BES SQL DB, it shouldn't be a problem to get the info - but there are some things to figure out before it works right:

1. There are two fields in the BES SQL DB that refer to a wireless provider. The first is the VendorID field, which specifies the actual maker of the BlackBerry device itself, regardless of what network it is currently connected to or roaming on.

2. The second is the Home Network field, which actually doesn't make sense because it shows you which wireless network provider the device is connected to right now, so it may not actually be the home network, but a roaming partner.

For example I have a user whose device is a T-Mobile device and their home network would obviously be T-Mobile, however they currently appear as Cingular under Home Network.

To get these values out of the SQL DB we need a query, here is the one I use to pull the data into Excel:

SELECT UserConfig.DisplayName, vHandheldSummaryInfo.VendorID, vHandheldSummaryInfo.HomeNetwork
FROM BesConfig.dbo.UserConfig UserConfig, BesConfig.dbo.vHandheldSummaryInfo vHandheldSummaryInfo
WHERE vHandheldSummaryInfo.PIN = UserConfig.PIN

Note that you need to join these two tables in Microsoft Query using the PIN field, not the default "id" field that it starts with, otherwise your data won't match. Haven't discovered why, perhaps their are two different id fields in the two tables. Anyway, just use PIN because that is a common key that I know is unique.

So once you run this query you get the user's Display Name, Vendor ID, and Home Network. Now to get the device's carrier I need just the Vendor ID field but I like to see what Home Network people are on, it is interesting to see where your people are in the world and what unique names other wireless carriers have, such as "CCT Boatphone" (!). (Apparently from the British Virgin Islands, but is it really for boats? a cruise ship? hmmm...)

One final issue is that the Vendor ID is in decimal format, so I wasn't quite sure which was which. The Home Network let me see which vendor ID matched up with which vendor name, but after doing a bunch of work for that I figured out that the vendor id's are stored in where else... the Vendors.xml file!

While the Vendors.xml file did in fact contain all the matchings between vendor ID and vendor name, the id's in this file were in Hex format! :( After a little hacking in Excel with the HEX2DEC formula, I came up with the following master table below of all vendors RIM supports:

Hex (vendor.xml)	Decimal (BES DB)	Provider Name
64	100	T-Mobile US
65	101	AWS
66	102	Cingular Wireless
67	103	Nextel
68	104	Sprint PCS
69	105	Verizon
6B	107	Rogers
6D	109	BWA (Aliant/Sasktel)
6F	111	MM02 DE
71	113	Telfort
72	114	T-Mobile DE/AU
73	115	TIM
74	116	Hutchison
75	117	Bouygues
76	118	SFR
77	119	Orange_France
78	120	VODAFONE (UK)
79	121	Telcel
7A	122	Telstra
7B	123	T-Mobile (UK)
7C	124	Vodafone Germany
7D	125	MM02 UK/IRL/NL
7E	126	Telus
7F	127	SMART
80	128	Starhub
81	129	Telefonica
82	130	Swisscom
83	131	Cable and Wireless
84	132	Vodafone (IT)
85	133	Vodafone (ES)
86	134	T-Mobile (NL)
87	135	Cincinnati Bell
89	137	Vodafone Austria
8A	138	Vodafone Australia
8B	139	Vodafone Ireland
8C	140	Vodafone Sweden
8D	141	CSL
8E	142	Orange UK
8F	143	Vodafone New Zealand
90	144	SingTel
91	145	Globe
92	146	Optus
93	147	Orange Mobistar
95	149	Bharti
96	150	KPN
98	152	Proximus
99	153	Vodafone_Portugal
9B	155	BT_Mobile
9C	156	Earthlink
9E	158	E-Plus
9F	159	BASE
A0	160	Dobson
A1	161	Vodafone_Egypt
A2	162	Orange_Switzerland
A4	164	Triton
A5	165	Maxis
A6	166	Vodafone_Denmark_(TDC)
A7	167	MobileOne_(Voda_Singapore)
A8	168	Vodacom

So now I can run my SQL query and easily match up the vendor ID's in decimal with the vendor names from this table. Cool.

Components of a NoteID

This is a diagram of the components of a NoteID that I put together after trying to figure out just how the State Database correlates it's entries with that of the messages in the mailfile. Of course there is no information actually in the State DB entry - it tracks it by having exactly the same Universal ID as the mailfile note itself.

Umm, ok...

Two separate Notes having the same Universal ID? Wasn't the idea that this ID was Universal, as in no other identical ID in the known Universe? Oh well...

Knife-Edge Cutover for Domino BES

Here is a compilation of the steps required to do a knife-edge cutover (also called a forklift upgrade) to move a BES server over to new hardware. Disclaimer: I have not done this yet, I am compiling these steps for a future migration. So there may be steps missing or just wrong. But it may be useful as an initial starting point.

1. Build new server with new windows server name and ip address.
2. Stop Domino service on original server
3. Copy the following files to the new server:
- d:\lotus\domino\data\server.id
- d:\lotus\domino\data\mdsservi.id
- d:\lotus\domino\data\names.nsf
- d:\lotus\domino\data\certlog.nsf
- d:\lotus\domino\data\BES\*.*
4. Install Domino with same release and fixpack as original server (click Yes to any registry prompt)
5. Copy the following file from the original server c:\lotus\domino\notes.ini
6. Remove the BES task from startup in Notes.ini
7. Set Lotus Domino service startup to Manual if not already
6. Shut down original server completely and unplug from network
7. Delete original server from Windows AD
9. Change IP address on new server to old IP address
8. Change name on new server to old server name
9. Reboot server to have name change take effect
10. Disconnect network cable
11. From console, start Domino to ensure it operates properly
12. Shut down Domino
13. Re-connect to network
14. Set service to automatic and add BES to startup tasks
15. Start server and check for errors


Note: If using a new IP address, check the server doc Net Address field

BES Stability - A History

Well the stability of our BES servers have been up and down over the last few years. Let me detail what has happened and where we are now.

2004 Implement BES in production. Ramp up to over 1,000 users within 1 year.

2005 BES 2.2 begins having stability issues with different types of faults, about once or twice a week. Requires a restart each time, which takes awhile to initialize given >1,000 users on the box.

10/2005 After submitting enless tickets and logfiles and dumpfiles to RIM, decided - even though monitoring said it was not an issue - to upgrade the RAM on our BES box from 2GB to 4GB. Immediately notice vast improvement - crashes virtually end overnight. Huzzah!

2006 Now have a new 4.0 server (w/ 4GB) that approaches and surpasses 1,000 users without issue.

Fall 2006 At about 1,300 users, 4.0 starts getting crashes now in either NBES or NSERVER process. Back down below 1,100 users and the server stops crashing (regularly)!

Lessons learned: 1,000 is just about the technical limit for a BES Domino box, even with 4GB of memory.

There are reasons why you would want to go below this limit for recoverability as well:

1) Restart times are less with lower users
2) Log file size (and associated searching, zipping up for RIM, etc) is smaller
3) Less time to do sourceless moves to another available server in DR situation
4) Less users out of service when server goes down
5) Maintain spare capacity to move users from other servers in case they go down

For all these reasons, I like to use 500 as an upper limit for number of BB accounts per BES 4.0 server. Yes this is much less than the theoretical 2,000 per server, but then I notice I end up sleeping better these days vs. when I didn't know how the server would act the next day...

Beware Sourceless Moves!

A few months back we had one of our servers go down, fortunately it "only" had about 350 users on it. Well I thought what a great opportunity to test out the sourceless move option to our hot standby server in our Colocation site.

I moved a few users at a time to be sure it worked, and it only seemed to take a minute or so per user. So I got some confidence and started moving 10-20 people at a time. (I didn't get confident enough to bulk move more than that) All this time I was watching the logs to see when the accounts completed the move process to gauge how fast it was going. Pretty nice, actually, the move automatically updates the service books on the device with the new SRP ID, so no user intervention required, in fact it truly is seamless. Nice.

Well after a couple of hours all the accounts were moved over and I focused on rebuilding the original server. Then after awhile I noticed something odd - there were some error messages in the log I was not familiar with:

[NoteID] was not found in any of the 1 redirected folders

Well actually I have seen these before but not so many of them. After a LOT of investigation, I discovered that Sent Items were not being redirected to *any* of the devices that had been moved to the new server.

Although I had replicas of all the user's State DB's on the Colo BES server, I had assumed that I did not a backup of the BlackBerryProfiles.nsf database. Upon each move, the new BES would pull info out of SQL and create a new Profile entry in this empty database. "Great", I thought, "that creates a fresh clean profile entry, and besides, we are SQL all the way now, so these profile entries aren't really used."

Ummm.... not quite.

Creating a fresh profile DB entry for each user misses some critical information that, apparently - even in this age of the SQL DB as the master and core of our BES environment - exists only in the profile DB entries.

I will name names here. In particular, the following fields:

1) DeviceCapabilities
2) RedirectSelectedFolders

First of all, DeviceCapabilities is set to null upon a sourceless move, and RedirectSelectedFolders doesn't even exist!

What are the ramifications of this? Well for DeviceCapabilities, the BES server will note that it is set to nothing and assume that it is a pre-4.0 device, and thus will not reconcile the Sent Items from Notes onto the device, and will throw the error I noted above.

For RedirectSelectedFolders, this would be created and set to "1" if someone went into their subfolders and marked selected ones for redirection to the device. If this field doesn't exist, then the BES assumes naturally that they don't have any subfolders to redirect.

So the "seamless" sourceless moves result in all devices not getting Sent Items or any custom redirected subfolders. Not good.

Of course, reactivating the device fixes this stuff. But was I about to call 350 users and reactivate them all? Nope.

In order to fix this from the server side (which is where I prefer to be), I had to get a backup copy of the BlackBerryProfiles.nsf DB from the downed server, and script an agent to populate the fields in the new Profiles BD. Although partially scripted, this was not automated, so I ran the script for each account, copying and pasting in the long string in the DeviceCapabilities field which the script then set in the new Profiles db entry.

When these fields matched what was in the previous Profiles db, then magically people began getting their Sent Items and subfolders redirected as normal. Not a fun day for me though.

Of course I called RIM to ask about this "bug" and was told that they knew about this behavior but it really wasn't planned on being fixed.

The upshot is.... never allow the BlackBerryProfiles.nsf database to be recreated, either by deleting it yourself or doing a sourceless move to a new server. You will lose valuable info in each document. Instead, in addition to the backup replicas you have of the state DB's, have a backup replica of this DB as well, so that in an emergency you can copy and paste the profiles into the database on the backup server, so they don't get autocreated and inherit all the fields with valuable goodies in them.

One final note, this only applies to sourceless moves - if you have the original BES server up and available during an account move, the destination server will pull all the information from the original profile document into it's database cleanly.