Tracking Messages in your GWAVA logs

There are many different logs in GWAVA.  For a summary description of all GWAVA logs see:  https://support.microfocus.com/kb/doc.php?id=7019614.  This article refers to the actual "GWAVA" logs, which shows each message that is scanned by GWAVA (whether blocked or no).  These logs correspond to the GWAVA Scanner Console, although the Console, by default, will only be in Normal mode not Diagnostic like the support logs.  Here is a snippet of a GWAVA Support log, as an example:

<ln><p>42</p><l>4</l><d>2008-JUL-28</d><t>16:58:50</t><i>Event outbound triggered service ASENGINE_HAM_LEARN by object 148fqnh.148kn4v.5v</i></ln>
<ln><p>42</p><l>3</l><d>2008-JUL-28</d><t>16:58:50</t><i>PROCESSING ASENGINE HAM LEARN SERVICE</i></ln>
<ln><p>42</p><l>4</l><d>2008-JUL-28</d><t>16:58:50</t><i>> 200 Postprocessing complete</i></ln>
<ln><p>42</p><l>4</l><d>2008-JUL-28</d><t>16:58:50</t><i>< PROCESS_XML <gwava><scan><query><event.block /></query></scan></gwava></i></ln>
<ln><p>42</p><l>3</l><d>2008-JUL-28</d><t>16:58:50</t><i>Work file: SYS:\OPT\BEGINFINITE\GWAVA4\services\gwava_scan_engine_148fqnh.148kn4v.5m\work\wrk_81.xml</i></ln>
<ln><p>42</p><l>4</l><d>2008-JUL-28</d><t>16:58:50</t><i>> 300 Query results ready to send</i></ln>

The first thing to note is the formatting.  Unlike the Normal logs, the Support logs have a lot of additional formatting which may be discouraging upon first glance.  Most of the formatting can be disregarded, however.  There are a few items of importance, though.  The date and time are obviously useful, but it is critical that you note the thread ID. 

The thread ID will be surrounded by <p> and </p> tags.  In the above example, the thread ID is 42.  The thread ID will indicate which message is being scanned.  Since GWAVA is multithreaded (32 threads by default), many messages can be processed at once.  This can make reading the logs difficult.  You may find a message all in one block (no other thread ID's in the middle) or the message can be scattered over hundreds of lines of log.  I will show you a trick later on to make this skipping around more manageable.

The first entries in the log for a message should look something like this (depending on your build of GWAVA):

<ln><p>38</p><l>4</l><d>2008-JUL-28</d><t>16:57:14</t><i>< PROCESS_XML <gwava><scan><query><email.modified /></query></scan></gwava></i></ln>
<ln><p>38</p><l>3</l><d>2008-JUL-28</d><t>16:57:14</t><i>Work file: SYS:\OPT\BEGINFINITE\GWAVA4\services\gwava_scan_engine_148fqnh.148kn4v.5m\work\wrk_2u.xml</i></ln>
<ln><p>38</p><l>4</l><d>2008-JUL-28</d><t>16:57:14</t><i>> 300 Query results ready to send</i></ln>
<ln><p>38</p><l>4</l><d>2008-JUL-28</d><t>16:57:14</t><i>< 200 Ready to receive</i></ln>

This obviously doesn't give you any information about the message being scanned, but will be important to know later.

The last entries in the log for a message looks something like this:

<ln><p>38</p><l>4</l><d>2008-JUL-28</d><t>16:57:13</t><i>> 200 Postprocessing complete</i></ln>
<ln><p>38</p><l>4</l><d>2008-JUL-28</d><t>16:57:13</t><i>< PROCESS_XML <gwava><scan><query><event.block /></query></scan></gwava></i></ln>
<ln><p>38</p><l>3</l><d>2008-JUL-28</d><t>16:57:13</t><i>Work file: SYS:\OPT\BEGINFINITE\GWAVA4\services\gwava_scan_engine_148fqnh.148kn4v.5m\work\wrk_2s.xml</i></ln>
<ln><p>38</p><l>4</l><d>2008-JUL-28</d><t>16:57:13</t><i>> 300 Query results ready to send</i></ln>
<ln><p>38</p><l>4</l><d>2008-JUL-28</d><t>16:57:14</t><i>< 200</i></ln>

Now that you know a few of the basics, let's track a message.  This is how I recommend proceeding:

1)  Find the GWAVA Support log for the date and time that the message of interest came into the system.  The name of the log includes a date and time.  This should be equivalent to the last time stamp in the log.  Logs are rolled over periodically when they get too large.  Old logs are zipped up at the end of the day.

2)  Open the log in a text editor.

3)  Search for the criteria that you're looking for.  For every message that GWAVA processes, the logs will include the sender, recipient(s) and the subject.  Any of these items are searchable.  If you search for an e-mail address, the logs will specify whether that address is the sender of the message or the recipient.  For instance:

<ln><p>3o</p><l>4</l><d>2008-JUL-28</d><t>13:01:38</t><i>Meta data 'email.recipient.address' = 'razor@dota.com'</i></ln>

Note:  Assuming that you are searching the correct log within the appropriate timeframe, if you do not find the message you are looking for in the GWAVA Support logs, then it was NOT scanned by GWAVA.

4)  Once you've located the message, note the thread ID.  You will need to follow this thread through to the end to ascertain what happened with this message.  As already stated, one thread may be scattered in between dozens of others.  To follow the message all the way to the end, I like to do a "find" on the thread ID, starting with the line you found in step 3.  If you start there and search down, you can do a "find next" (usually F3) to get to the next line.  Continue to use F3 to browse through this thread until you find the needed information.

5)  As you browse down the thread, you'll see a lot more additional formatting, which can again be ignored.  If you have no idea what the lines mean, they're probably not going to be important to what you're looking for.  All GWAVA events are labeled clearly (spam scanning, fingerprinting, RBL, etc.).  If an event is triggered, the log will indicate this.  Here is an example of an SURBL lookup:

<ln><p>3i</p><l>4</l><d>2008-JUL-28</d><t>16:57:45</t><i>SURBL lookup: 0ffshorepharm.com.multi.surbl.org</i></ln>
<ln><p>3i</p><l>4</l><d>2008-JUL-28</d><t>16:57:45</t><i>SURBL record found: 0ffshorepharm.com.multi.surbl.org</i></ln>

As opposed to (event not triggered):

<ln><p>38</p><l>4</l><d>2008-JUL-28</d><t>16:58:48</t><i>RBL lookup: 5.102.11.204.bl.spamcop.net</i></ln>
<ln><p>34</p><l>4</l><d>2008-JUL-28</d><t>16:58:48</t><i>Host 5.102.11.204.sbl-xbl.spamhaus.org not located in RBL lookup</i></ln>

6)  You can read down through the whole message and see each event that was fired, but the most important information is located at the end of the message.  Right before the closing lines described earlier, there may also be lines like these ones:

<ln><p>40</p><l>4</l><d>2008-JUL-28</d><t>16:58:01</t><i>Event surbl triggered service BLOCK by object 148fqnh.148kn4v.ge</i></ln>
<ln><p>40</p><l>4</l><d>2008-JUL-28</d><t>16:58:01</t><i>Event spam_threshold_5 triggered service BLOCK by object 148fqnh.148kn4v.ig</i></ln>
<ln><p>40</p><l>4</l><d>2008-JUL-28</d><t>16:58:01</t><i>Event spam_threshold_5 triggered service QUARANTINE by object 148fqnh.148kn4v.ig</i></ln>
<ln><p>40</p><l>4</l><d>2008-JUL-28</d><t>16:58:01</t><i>Event surbl triggered service ASENGINE_SPAM_LEARN by object 148fqnh.148kn4v.ge</i></ln>
<ln><p>40</p><l>3</l><d>2008-JUL-28</d><t>16:58:01</t><i>PROCESSING MESSAGE BLOCK SERVICE</i></ln>
<ln><p>40</p><l>3</l><d>2008-JUL-28</d><t>16:58:01</t><i>PROCESSING ASENGINE SPAM LEARN SERVICE</i></ln>
<ln><p>40</p><l>3</l><d>2008-JUL-28</d><t>16:58:01</t><i>PROCESSING QUARANTINE SERVICE</i></ln>

This is similar to what you'll see if the message was blocked.  These lines at the end of message scanning summarize which events were triggered and specify what actions were taken, based on your configuration.  In the above example, an SURBL event was triggered, which led to a BLOCK service and an ASENGINE_SPAM_LEARN service, meaning that the message was blocked for SURBL and added to the spam corpus, due to spam autolearning settings.  Also, spam_threshold_5 was triggered, which also tells GWAVA to BLOCK the message.  Spam Threshold 5 is set to quarantine the message, so you see a QUARANTINE service as well.

Note: Tthe BLOCK, QUARANTINE and NOTIFICATION services (among others) will always be capitalized, making them easier to find.

If you track a message to the end and don't see a BLOCK service triggered, then the message was sent through to the recipient.  There is NOT a line in the logs that indicates that the message was clean.  This is assumed if there is no BLOCK event.