[tc490225]

Next post..

So I have a log file parser that ive writte in .vbs.. it aint much but its mine. hehe

I had a demo of Conceivium Business Solutions, Inc. .. its a great product but really strikes me as a glorified log file parser, yes its advanced but I feel I could perform much of the same stuff.. the only thing I dont have is what needs to be parsed out of the log.. any suggestions here? can you guys give me what you look for in the log files, id be glad to submit my parser once we all contribute.

I have also seen Zenprise and am slated to see Boxtone, any others I should give a gander?

[ashworth]

I would LOVE to see you put in a refid or a transcation ID and it will pull every tag, and log line from the Router, Disp, and MAGT files for that single refid or transcation ID, and then place them in the proper order.

I WOULD LOVE IT!!!!

[tc490225]

currently I have a couple parsers, one is used for parsing a single MAGT file and the other is used to parse the entire log folder for whatever you search line is.. is there more to know ? what line in the log is the best place to grabe the refid ? please provide as much excat info as you can.. from you bes blog i see your email is
want me to email you there the .vbs parser?

[ashworth]

I would love to get anything you could provide me. I love playing in the BES logs.

I'm not at work around now but when I get to work I can give you a full run down of what I would like by inputting a refid.

I though about doing it, but my coding skills are way to weak. (even tho i went to school for computer programming)

[Spawneh]

it would be good if you could specify specific users to parse for to remove any unwanted user transactions, also being able to remove some of the standard junk errors which are expected to be there..

[tc490225]

I dont understand what your saying Spaweh.. you want me to remove stuff from the bes logs? I dont think that would be a a good idea. At least in my environment if I caught a admin deleting stuff outta my logs I would be wondering what they were trying to hide.. did i miss somthing?

also, I was really more interested in understanding what people search for when looking in the logs, such as 'user not started' thats usually a good thing to search for or the various MAPI codes that start with (80401..)

[tc490225]

ok, i think i understand. Yes, the parser currently does just what you suggest. it pulls all lines in the log that meet your criteria and places them into a new .txt file..

[Spawneh]

Sorry mate was referring to enabling you to remove (remove visability) all the things your not trying to see.

So for instance if I have issues with a user account called Spawneh.

I'd like to see all entries pertaining to me only.

also being able to remove the usual 40465 type coded errors.

[ashworth]

OK BES Log review 201

Please make sure you have taken the pre-requisite of GREP'ing 101

I look up an email I got on my handheld and the refid is: -537543770 (ALT-VIEW in the message to get the RefID)

I then take this RefID and I grep the MAGT log for this message and I find the following log lines:

[40287] (08/13 08:43:21.242):{0x17B0} {user@email.address.net} Queuing message, RefId=-537543770, EntryId=378539, Posted=08/13 08:42:18, Delivered=08/13 08:42:27
[30081] (08/13 08:43:21.304):{0x17B0} {user@email.address.net} Sending message to device, size=945, EntryId=378539, RefId=-537543770, TransactionId=-931458912, Tag=998
[40572] (08/13 08:43:37.808):{0x17B0} {user@email.address.net} Receiving MESSAGE_STATUS_UPDATE request from device, Tag=322, TransactionId=-1399330782, RefId=-537543770, MsgStatus=1
[40262] (08/13 08:43:37.808):{0x17B0} {user@email.address.net} StateDb - Found RefId=-537543770

So now I take the first line I found and it has an EntryID of 378539 so I grep for that in the MAGT log and remove and duplicates (dups) from the log lines above:

[40423] (08/13 08:43:20.618):{0x618} {user@email.address.net} Queuing new mail through notification (external). EntryId=378539
[40724] (08/13 08:43:20.618):{0x17B0} {user@email.address.net} Get record key for this MAPI object, EntryId=378539
[40435] (08/13 08:43:20.618):{0x17B0} {user@email.address.net} Queuing new mail through notification. EntryId=378539. Msgs Pending 0
[30085] (08/13 08:43:20.618):{0x17B0} {user@email.address.net} New mail has arrived, EntryId=378539
[30097] (08/13 08:43:22.365):{0x17B0} {user@email.address.net} Message has been delivered to device, Tag=998, EntryId=378539

So now I take the second line from the first Grep within the MAGT and I grep for the Tag of 998 and remove dups

[40279] (08/13 08:43:21.304):{0x17B0} {user@email.address.net} SubmitToRelaySendQ, Tag=998
[40000] (08/13 08:43:21.304):{0x16F4} [BIPP] Send data, Tag=998
[40000] (08/13 08:43:22.365):{0x163C} [BIPP] Received status DELIVERED, Tag=998

Then I take the TranscationID of -931458912 and search the Dispatcher logs for it and I find the following:

[30222] (08/13 08:43:21.320):{0xDB8} {User} MTH: contentType=CMIME, sizeOTA=548, sizeOTW=911, TransactionId=-931458912, Tag=1270
[30310] (08/13 08:43:21.320):{0xDB8} {User} Forwarding internal data to device, contentType=CMIME, routing=S0000000, device=20000PIN, size=584, cmd=0x3, ack=0, TransactionId=-931458912, intTag=998, Tag=1270, Submit=1

I then take the Tag of 998 and grep the DISP log for that tag as the intTag and I get the following (after removing the dups):

[30388] (08/13 08:43:22.365):{0xDBC} [BIPPa] {User} Forwarding status to BES Agent (S0000000_001), intTag=998, extTag=1270

I now take the Dispatcher Tag of 1270 and grep within DISP for that (and remove dups and get)

[30368] (08/13 08:43:22.365):{0xDBC} {User} Packet has been delivered to device, Tag=1270

I now take the Dispatcher tag of 1270 and grep for that Within the Router logs and I get:

[40000] (08/13 08:43:21.320):{0xB4C} [SERVICE_RELAY_SESSION:S0000000:00b51528] Service V2 GME packet received. DESTINATION=20000PIN, CONTENT=CMIME, TAG=1270, RELAYROUTABLE=true, LENGTH=584
[40000] (08/13 08:43:22.349):{0xB4C} [SERVICE_RELAY_SESSION:S0000000:00b51528] Handle Transaction Status. TAG=1270 STATUS=1

Now to put it all in the proper order:

MAGT: (This is where Exchange sends BES UPD packet and the BES goes and picks up the message and sends it.)
[40423] (08/13 08:43:20.618):{0x618} {user@email.address.net} Queuing new mail through notification (external). EntryId=378539
[40724] (08/13 08:43:20.618):{0x17B0} {user@email.address.net} Get record key for this MAPI object, EntryId=378539
[40435] (08/13 08:43:20.618):{0x17B0} {user@email.address.net} Queuing new mail through notification. EntryId=378539. Msgs Pending 0
[30085] (08/13 08:43:20.618):{0x17B0} {user@email.address.net} New mail has arrived, EntryId=378539
[40287] (08/13 08:43:21.242):{0x17B0} {user@email.address.net} Queuing message, RefId=-537543770, EntryId=378539, Posted=08/13 08:42:18, Delivered=08/13 08:42:27
[30081] (08/13 08:43:21.304):{0x17B0} {user@email.address.net} Sending message to device, size=945, EntryId=378539, RefId=-537543770, TransactionId=-931458912, Tag=998
[40279] (08/13 08:43:21.304):{0x17B0} {user@email.address.net} SubmitToRelaySendQ, Tag=998
[40000] (08/13 08:43:21.304):{0x16F4} [BIPP] Send data, Tag=998

DISP: (The Agent send the information to the DISP and the DSIP then sends it to the Router to get sent to the HH. And then gets the ACK back from the HH that it has been delivered)
[30222] (08/13 08:43:21.320):{0xDB8} {User} MTH: contentType=CMIME, sizeOTA=548, sizeOTW=911, TransactionId=-931458912, Tag=1270
[30310] (08/13 08:43:21.320):{0xDB8} {User} Forwarding internal data to device, contentType=CMIME, routing=S0000000, device=20000PIN, size=584, cmd=0x3, ack=0, TransactionId=-931458912, intTag=998, Tag=1270, Submit=1

Router: (Send the email and gets the ACK Back)
[40000] (08/13 08:43:21.320):{0xB4C} [SERVICE_RELAY_SESSION:S0000000:00b51528] Service V2 GME packet received. DESTINATION=20000PIN, CONTENT=CMIME, TAG=1270, RELAYROUTABLE=true, LENGTH=584
[40000] (08/13 08:43:22.349):{0xB4C} [SERVICE_RELAY_SESSION:S0000000:00b51528] Handle Transaction Status. TAG=1270 STATUS=1

DISP: (Gets the Ack Back)
[30388] (08/13 08:43:22.365):{0xDBC} [BIPPa] {User} Forwarding status to BES Agent (S0000000_001), intTag=998, extTag=1270
[40000] (08/13 08:43:22.365):{0x163C} [BIPP] Received status DELIVERED, Tag=998

MAGT: (Gets the ACK Back that the message has been delivred to the BlackBerry)
[40000] (08/13 08:43:22.365):{0x163C} [BIPP] Received status DELIVERED, Tag=998
[30097] (08/13 08:43:22.365):{0x17B0} {user@email.address.net} Message has been delivered to device, Tag=998, EntryId=378539

MAGT: (Message getting marked as read and you would need to start all over again with the new Tag of 322 and the new TranscationID of -1399330782
[40572] (08/13 08:43:37.808):{0x17B0} {user@email.address.net} Receiving MESSAGE_STATUS_UPDATE request from device, Tag=322, TransactionId=-1399330782, RefId=-537543770, MsgStatus=1
[40262] (08/13 08:43:37.808):{0x17B0} {user@email.address.net} StateDb - Found RefId=-537543770

So this took me about 20 minutes to do but i bet you could create a script to do this and it would only take about 1 minute to scan the logs (depending on the size and number of agents)

I would like to see it output the data from the section above without my comments in ()'s

I also have a few other ideas I'm currently thinking of but still in the thinking process.

Thanks!

[ashworth]

I would also like another one that can find changes within the User setting logs lines:

[40442] (08/13 00:20:58.046):{0x17B0} User settings: email=user@domain.com, routing=S000020, service=X-415, device=30000042, calendar=1, MDS=1, userOTAFM=63, incradle=0, SMIME=0, sentItems=1, dir=user, server=EX2K3
[40442] (08/13 05:21:38.678):{0x17B0} User settings: email=user@domain.com, routing=S000020, service=X-415, device=30000042, calendar=0, MDS=1, userOTAFM=63, incradle=0, SMIME=0, sentItems=1, dir=user, server=EX2K3

From the above to log lines you can see that the Calendar changed from enabled (1) to disabled (0).


It could search all of the agents and check for changes between all users, or you could put in a users email address and it can change for changes just for that user.

[cancundan]

Originally Posted by tc490225

Next post..

So I have a log file parser that ive writte in .vbs.. it aint much but its mine. hehe

I had a demo of Conceivium Business Solutions, Inc. .. its a great product but really strikes me as a glorified log file parser, yes its advanced but I feel I could perform much of the same stuff.. the only thing I dont have is what needs to be parsed out of the log.. any suggestions here? can you guys give me what you look for in the log files, id be glad to submit my parser once we all contribute.

I have also seen Zenprise and am slated to see Boxtone, any others I should give a gander?

what is the purpose of you parsing the logs? Proactive Alerting? Easier troubleshooting? I ask because there are things that you should track for troubleshooting purposes, but not necessarily get alerts on.

[tc490225]

ash.. wow ! let me work on that and get back to you. Thanks for the hard work, seems doable.

cancundan.. Both, Id like to be able to troubleshoot an activation issue or a send/recieve issue 'easier' I realize parsing the log isnt the end all be all but it can certainly help, espically in the case where the user shoot thier foot off.. like changing the name of thier notes folder, parsing the log will tell you this.

as well as troubleshooting.. id like to be able to snapshot the performance of the BES server and provide mgmt with a point in time report of anything important..

[tc490225]

ashworth..

when I 'grep' the DISP for the transactionid.. I get lots of 'noise'.. there are lots and lots of entries with the same transactionid.. any suggestions? and.. to make things worse it seems the DISP logs dont use the SMTP address of the user like the rest of the logs, they use the displayname of the user.

[ashworth]

Here is a tip. When I grep for stuff I sometimes leave in the equal sign '=' that way when you are searching for a small tag like 998 you are going to get tones of hits but if you search for =998 or if you know you are searching for more log lines that are a Tag then just search for Tag=998. That should help for all of the duplicate items (EntriesID, Tags and TranscationID's).

As for the DISP. I would take the TransactionId from log line 30081 within the MAGT log:
[30081] (08/13 08:43:21.304):{0x17B0} {user@email.address.net} Sending message to device, size=945, EntryId=378539, RefId=-537543770, TransactionId=-931458912, Tag=998

Have a variable called UserSMTPAddr and save the users smtp address here.

And then find that same TransactionId within the DISP log:
[30222] (08/13 08:43:21.320):{0xDB8} {UserfirstName UserLastName} MTH: contentType=CMIME, sizeOTA=548, sizeOTW=911, TransactionId=-931458912, Tag=1270

And another variable called UserDisplayName and save the xxx8220;UserfirstName UserLastNamexxx8221; to it.

The only way to make sure is to match the above log lines to verify it is the same user.

[ashworth]

Since I put so much work into this I have also added this to my blog with some more info about each of the bes log lines themselves: besadmin - How to track the RefID in the BES Logs

[hookedOnBB]

Hi ashworth,

It is an excellent post. Can you explain the issue that you troubleshoot with this information? I assume that this information would be useful if a user calls in to complain that email delivery is very slow.

[ashworth]

Originally Posted by hookedOnBB

It is an excellent post. Can you explain the issue that you troubleshoot with this information? I assume that this information would be useful if a user calls in to complain that email delivery is very slow.

At the time on one of our production servers we where having slow emails delivery for a few users. That is when I had to take the time to learn about message flow. After a lot of calls within RIM support I found that we were having some disk issues with our Exchange server. But that is besides the point. It was help from RIM's Tech support that showed me the BES was nice and fast and that it was the delay coming from Exchange.

This can also be useful if you are not able to reply to an email and getting a red X on the device. (Other then the Send As issue) I have had to do this a few times now and the more and more I do it the faster I get at it, but if I could just get me a script to do this that would be Sweet!

[tc490225]

sorry, I havet been able to work this.. I was up all night Friday into Sat morning.. The BlackBerry User Administration service was causing us issues.. it seems the last place you would want to load it is on a bes server

Anyway, ill study the posts and get back to you.

[tc490225]

Still confused.. I was using 'transactionid=-928604561' as my search criteria. I am pulling tons of people out of my dispatcher log. Looks like I could map the tag to the inttag and vise versa to get the entries i need and not use the transactionid=-928604561.. thoughts?

[30222] (08/18 19:20:54.775):{0xb94} {Doe, John} mth: contenttype=cmime, sizeota=244, sizeotw=228, transactionid=-928604561, tag=4220592
[30310] (08/18 19:20:54.775):{0xb94} {Doe, John} forwarding internal data to device, contenttype=cmime, routing=sXXXXXXXX, device=23XXXXXX, size=282, cmd=0x3, ack=0, transactionid=-928604561, inttag=720370, tag=4220592, submit=1
[30222] (08/18 19:21:59.401):{0xbc0} {Cricket, Jimney} mth: contenttype=cmime, sizeota=244, sizeotw=277, transactionid=-928604561, tag=4220758
[30310] (08/18 19:21:59.401):{0xbc0} {Cricket, Jimney} forwarding internal data to device, contenttype=cmime, routing=sXXXXXXXX, device=24XXXXXX, size=282, cmd=0x3, ack=0, transactionid=-928604561, inttag=703572, tag=4220758, submit=1

[ashworth]

Hmmm I will try to take a look when I'm at work tomorrow. When I did my example it was on my test lab logs and I only had 2 users within the database. I will pull down my production logs and take a peek.