Tracking Messages Through The GroupWise Mobility Service

As you will be aware a GroupWise system comprises of a number of discrete components (agents). When the Groupwise client sends a new message it will first of all be transferred to the Post Office Agent (POA).  If the message is not local to it the POA forwards the message to it’s Message Transfer Agent (MTA) and if it’s an internal message it will eventually reach the destination POA. These components are more than likely to be on different servers and the receiving device connected through some secure channel.

The user may use either a desktop client, web client or a smart device to receive the message. If the latter then the message is delivered via the GroupWise Mobility Service (GMS). If the need arises to track a message’s journey through the system then you will need to access and interpret the log files of the relevant agents. This article highlights how to troubleshoot message delivery.

Set the Logging Level

Before you can follow an item through your GroupWise system you must set the right log levels otherwise the tracking information isn't recorded. So we need to make sure the following is set.

• POA in verbose log level
• POA settings in the HTTP interface must have "Show SOAP requests" and "Show SOAP events" checked in Configuration, Log settings
• GMS set to DEBUG log level

With these settings we can now track a regular email sent from the GroupWise client to an user that has a GMS account. For the rest of the article the sender of the message is user2 and the receiver, also the GMS user, is user1. I will only show the parts from the log file that are most important to follow the message. There is much more content in these log files. However to make it more clear the lines below show enough context to track the message.

Unique Record Id

You can start following messages based on the item’s Record Id that is unique to each item in GroupWise. You can see this when you check the properties of the email (figure 1).  I started by sending an email from user2 to user1 with the subject "OH article". You see in the screenshot below the properties of the item in the mailbox of user1. At the bottom it shows the Record Id as 5EDE3B5F.DOM18.PO18.100.1346F36.1.50.1

In the POA log file you will see the item being delivered and the same Record Id shows in a GMS SOAP event. The POA logfile by default has all the information in it, but if you use the POA startup switch –spawnsoap the POA will split the logfiles. One will contain the regular information and the other one will only have the SOAP related information. The names of these POA logfiles will be <date>poa.xxx for the regular POA logfile and <date>soa.xxx.

GMS Notification

The POA creates a notify event so that GMS is aware that there is a new item. This is done by the POA over port 4500 that’s listening on the GMS server for these notifications. If the firewall on the GMS doesn’t have this port open the notification can’t be received, and GMS will not be aware of new items.

The next step is to check the GMS server log files. The first is the groupwise-agent.log as this is the logfile created by the GroupWise Connector. This is the component of GMS that communicates with the GroupWise POA over SOAP. It shows the notification from the POA in the GroupWise connector and initiates the GroupWise connector to retrieve the data from the POA.

The GroupWise connector then requests the item from the POA by making a SOAP getItemsRequest.

The item is received and as you see both the Subject and the Record Id are showing in the information received from the POA.

Processing by GMS

The GMS server now creates an eventID thats related to this item. This eventID is used in all parts of GMS from now on for this event. So this new eventID can be used to find the item in any other log file in GMS.

For this event the assigned eventID is default.pipeline1.groupwise.376e0f2ca97a11ea9adc000c29d65903. As you can see the Record Id is mapped to the new eventID.

The GroupWise connector is finished handling this event when you see the following line with the Record Id. This means the next step will be carried out in the engine and the mobility connector.

Next we look in the mobility-agent.log and as we have seen before the EventID can be used to look for the item. So searching for:

default.pipeline1.groupwise.376e0f2ca97a11ea9adc000c29d65903 you will see the event arriving.

You see this eventID in the data from the received event as <id>default.pipeline1.groupwise.376e0f2ca97a11ea9adc000c29d65903</id>

As this is an event and we need to be able to track what happens to the item ( which could be more events ) we need to look for the mapping from event to object, which is done here. The object ID -4718320530235178852 is assigned by the line below. This object ID will be used for any other action done on this item so when the user reads the item, moves the item or deletes the item all events will be linked to this Object ID even if the actions are days apart.

When following the item we need to check what happens to the object Id -4718320530235178852 so the next thing you see is the ActiveSync conversion as this is the format we need to provide the data in to the device when the item is requested.

When we see the next line, by searching again for the eventID or object ID, we can see that GMS has performed all tasks and the data is waiting to be retrieved by the device. Only when the device(s) are connecting and requesting items is the data sent over. GMS does not push items to the device at any point in time. We will however, if possible, notify the device that there is something new to retrieve; but it will be the device that has to connect and request the new items.

ActiveSync

The final step is the device requesting the data so we need to work back from the point we know the data is synchronised. This happens in the following lines. The RESPONSE is based on a sync request which generates these lines in the log file, from a device with the ID A71B200B8989C8CB28F06986733455B6. The following data is the actual raw ActiveSync data that is provided to the device.

This means the message is synchronised to the device. We can also see more of the event and what is provided to the device within this data

This line indicates the event for the item we have provided and the number in front of the object ID indicates the folder it is placed in. There are some default folders defined within ActiveSync and the number 2 indicates the Inbox folder. On the device this should be located in the same folder.

The ActiveSync defined numbers are shown in the drop-down below. If the item is in a user created folder the number will be different.

So when you track items the log indicates what and where the item is. For example you might see that a synchronised calendar entry is <ServerId>8:1234</ServerId> or an item that’s deleted and is in the trash is <ServerId>4:1234</ServerId>.

When you would follow an item and both the sender and receiver are GMS users you need to find the specific item for or the sender or the receiver. This can be done based on the device ID but also when looking at the actual data synchronised. The sender has the item in the sent items folder so <ServerId>5:1234</ServerId> while the receiver has the item in the inbox which is showing as <ServerId>2:1234</ServerId>

Multiple Devices

As mentioned earlier we need to search back for the connection and device that made this request as more then one device can be used by a user. This also means the data can be provided in the above way multiple times so this also will result in multiple lines as seen above in the mobility-agent.log. The way to split this is by looking at the RESPONSE and device ID which will tell you the device that retrieved the message.

In the next line the device connections shows how connections from devices will show in the logfile. Most of the info will be the same but the main information to look for is

• User=
• Cmd=
• DeviceID=

These 3 are all in the same line as part of the QUERY_STRING. In this case as we are looking for the device requesting the data it looks like this:

You will see that the user making this request is user1 and based on the cmd parameter we see this is the synchronisation request. In other words the device with ID A71B200B8989C8CB28F06986733455B6 is asking the GMS server for items. Some additional information you will see is the parameter ‘DeviceType’ which indicates the type of device being used. For this test I’m using the Windows 10 Mail app (WindowsMail). You will usually see iOS devices or Android devices when mobile phones or tablets are used.

With the above information you are able to tell that the item sent from Groupwise at 13:21 is retreived by the device with ID A71B200B8989C8CB28F06986733455B6 ( a Windows mail app) at 13:23. What happens after this is out of the hands of GMS, we have no influence on what happens on the device with the data provided.

If there are delays in the delivery of the message to the device(s) then troubleshooting is helped with the above information. You will see that the first thing you need to verify is that the mobility-agent.log has the item and has converted the item into the ActiveSync format. When this is done you can actually see that in the line “Processed Event” you can be sure the GMS server has the data waiting for the device to retrieve it. You can look at the time between this line and the actual time the item was created to verify if there is/was a delay in GMS. Normally the processing time up to the “Processed Event” should not take more than a few minutes.

Device Notification

The GMS server has one more action to perform which is to notify the device that a new item is waiting and the device should retrieve it. The way this is done is based on a process that involves the device negotiating a time window between itself and the GMS server to keep the connection open. This is done the first time the device connects after GMS is started. In the logfile you will see the connection of the device and after this the line

This means the device and GMS agree on a 900 seconds open connection. If any item arrives in this timeframe the GMS will “ping” the device and you will see the device connecting again to the GMS server with the ‘cmd=sync’ request.

After this 900 seconds has passed the device is responsible to setup the next timeframe and will do this with the following connection. Notice the ‘Ping’ command.

This request is then followed by the line

The number of seconds negotiated between the device and GMS can be different every time but in general is between 540 and 1200 seconds.

As you can see all the GMS server does is to agree on the timeframe and ping the device when needed. The rest is all initiated by the device itself. When you setup devices to manual retrieve items or with certain intervals this process does not happen. However if you setup the device to retrieve messages as they are available it needs to start this negotiation process with the GMS server.

I hope that this article helps you to troubleshoot message delivery issues in your GroupWise system, particularly when they pass through the Mobility Service. The GroupWise log files provide a lot of diagnostic information that helps you pinpoint which process is causing the issue. However GroupWise is still a very reliable application, even now when the variety of devices is much more diverse.