SubscriptionEvent - Expiration

Jun 20, 2013 at 9:47 AM
Edited Jun 20, 2013 at 9:58 AM
Hi, keithh,

First, sorry for asking the questions without stopping, really need your comments to address our issue.

Let me introduce our case again, we have two server routers, one is origin(ServerA), while the other one is primary(ServerB), which connects to ServerA as its parent, and we have lots of clients connect to them via VIP, and every client subscribes the client-specific event type. I noticed sometimes the clients were wrongly marked as expired by the router on server side, and during that time, if new message was published, the client was not able to receive it.

On client side, we always keep the client running, subscribes 6 different topics, that means every 3 minutes, 6 subscription events will be forwarded to servers via balancer. On the server, we had configured the expiration time to 30 mins, to ensure the origin router can 99% get the next subscription event if the subscription events are not evenly distributed.

From logs on serverB, as highlighted, serverB had received the subscription event from serverA originated from client0335, and the expiration indicator was 6/20/2013 12:41:27 AM, that log tells us, the original subscript event was forwarded to serverA by VIP, and then forwarded by serverA to serverB, if it was right, inside the logs on sevrerA, I should be able to find the log that serverA had updated the exipiration indicator for the client0335 as well, but in fact I failed to find that.

ServerA should have received the subscription event from client0335, I think the subscription event was successfully queued into forwarder queue, and before that the event was successfully queued into subscriptionMgr queue, and ceitainly below codes should have been invoked to update the expiration indicator for client0335: but learning from the log below, it never happened, serverA haven’t updated the expiration indicator, in turn wrongly marked the client as expired.
lock (subscriptionDetail.SubscriptionDetailLock)
       {
              var @now = DateTime.UtcNow.AddMinutes(subscriptionExpirationIncrement);
              subscriptionDetail.Routes[element.InRouterName] = @now;
              LoggingService.Log("SubscriptionMgr, Start, update subscription expiration indicator for router {0},        subscriptionEventType: {1}, {2} ", element.InRouterName, subscriptionEvent.SubscriptionEventType.ToString(), @now);
       }
Had you met the similar issue before? Can you help point what was wrong behind this? By the way, our VIP is in round-robin mode.



Thanks a lot, appreciate all the helps.


Message template: {class}, {method}, update expiration indicator for router {InRouterName}, {Client-Specific EventType}, {UTC Expiration Indicator}

Logs on ServerA:
[Message] SubscriptionMgr, Start, update expiration indicator for router Client0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:32:27 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router Client0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:44:27 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router Client0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:26:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router Client0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:35:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router Client0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:38:27 AM
Message] SubscriptionMgr, Start, update expiration indicator for router Client0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:59:27 AM


Logs on ServerB:

[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:35:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:38:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:41:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:47:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:59:28 AM
Jun 20, 2013 at 11:20 AM
Edited Jun 20, 2013 at 11:21 AM
Attach all the logs, please please help

Logs from ServerA:
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:05:27 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:11:27 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:14:27 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net,
49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:26:27 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router CLIENT0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:32:27 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:35:27 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router CLIENT0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:44:27 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:47:27 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:56:27 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:02:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:11:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:14:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:17:28 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:20:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router CLIENT0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:26:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:32:28 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router CLIENT0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:35:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router CLIENT0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:38:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:44:28 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:50:28 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:53:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:56:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router CLIENT0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:59:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 1:08:28 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 1:11:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 1:14:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 1:20:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerB.domain.net, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 1:26:27 AM




Logs from ServerB:
Message] SubscriptionMgr, Start, update expiration indicator for router CLIENT0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:26:28 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:29:28 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:32:28 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:38:28 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:41:28 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-
dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:50:28 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:53:28 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:59:28 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:05:28 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:08:28 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router CLIENT0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:11:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router CLIENT0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:17:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router CLIENT0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:20:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:23:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:26:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router CLIENT0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:29:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router CLIENT0335, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/19/2013 11:23:28 PM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:35:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:38:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:41:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:47:27 AM
[Message] SubscriptionMgr, Start, update expiration indicator for router ServerA, 49dfc81a-dd0a-4c18-9f0e-ac0e00f4beca, 6/20/2013 12:59:28 AM
Coordinator
Jun 20, 2013 at 7:19 PM
Why are you manipulating the subscription events in your code? The SubscriptionMgr publishes the subscription events based upon the event types you subscribe to. So you should never see or have to deal with the subscription events.

It's not clear to me from what you write, is your client app not receiving events that it should? If not, is the server queuing up events for the client? You can look at the perf counters on the server for WspEventRouterCommunication to see all the queues. If you see events being queued for a client and on the client if you see a tcp connection to the server as established then it probably means the client thinks it's connected to the server when it's really only connected to the load balancer and the connection from the load balancer to the server is gone.

If you used Wsp v3 then you don't need the load balancer at all and the clients will automatically distribute across the two servers.
Jun 21, 2013 at 2:17 AM
Edited Jun 21, 2013 at 2:18 AM
Keithh,

What I manipulated was just adding the logging there.
The problem is if the client had been marked as expired, the client should not be able to receive the message, i think there was nothing wrong with the TCP connection.
what i just ask is, see from the logs from ServerB, there was subscription event for client0335 forwarded by serverA to serverB (6/20/2013 12:47:27 AM), but why i cannot see the corresponding log in serverA, to tell me the exipration indicator for client0335 was updated correspondingly.

Currently, We don't have the chance to move to WSP3.0
Coordinator
Jun 21, 2013 at 5:57 AM
I don't recall seeing any issues with subscriptions working. What's odd about your logs is that the 12:41:27 AM entry on ServerB came from ServerA but it wasn't logged on ServerA. Your logging app which would be running on each server have no interaction with the WspEventRouter on each box. The WspEventRouter on ServerA though had no problem getting the subscription event and forwarding it to ServerB. So you might take another look at your app to see if it had an issue.
Jun 21, 2013 at 7:03 AM
Edited Jun 21, 2013 at 7:15 AM
Keithh,

I think the logging function doesn't have any issue.

We noticed the client was wrongly marked as expired, and just started to check the log.

Maybe the 12:41:27 AM entry was just came from client0335, not forwarded by serverA to serverB. is that possible the InRouterName was wrongly set to ServerA after the QueueElement was dequeued from the queue, which originally should be Client0335?

From the logs I attached, you can see the InRouterName for ServerA on serverB is ServerA, InRouterName for ServerB on serverA is ServerB.domain.net, does it cause any problem?


Thanks.
Jun 21, 2013 at 7:09 AM
Another question:
If we disable the expiration client deleteion, besides the resource pressures on server side, what other thing should we pay the attention?

Thanks
Coordinator
Jun 21, 2013 at 7:10 AM
If the InRouterName is ServerA then the event had to come from ServerA. This means your logging function should have seen the event. As a double check to validate your logging function, you can always enable Wsp logging of the subscription events on both servers. You do this in the WspEventRouter.exe.config file (at the bottom of the file). This should write all the subscription events out to a file in JSON format.
Coordinator
Jun 21, 2013 at 7:12 AM
I wouldn't disable the expiration, this has worked fine for years so it would be good to know what's happening rather than ignoring.
Jun 21, 2013 at 7:36 AM
keithh wrote:
If the InRouterName is ServerA then the event had to come from ServerA. This means your logging function should have seen the event. As a double check to validate your logging function, you can always enable Wsp logging of the subscription events on both servers. You do this in the WspEventRouter.exe.config file (at the bottom of the file). This should write all the subscription events out to a file in JSON format.
Keithh,

Thanks for the quick answers.
Let me enable WSP logging as you said and have some checkings.