Incorrect displaying of stored_messages in statistics

[materkov]

Hi, @wandenberg It looks like that push stream module statistics can display wrong values for "stored_messages". For example, it now looks like this:

{"hostname": "my-hostname", "time": "2017-11-24T09:00:25", "channels": 2977, "wildcard_channels": 0, "published_messages": 18271, "stored_messages": 4, "messages_in_trash": 77, "channels_in_delete": 0, "channels_in_trash": 8, "subscribers": 2762, "uptime": 2878, "by_worker": [
{"pid": "12682", "subscribers": 589, "uptime": 2878},
{"pid": "12683", "subscribers": 819, "uptime": 2878},
{"pid": "12684", "subscribers": 660, "uptime": 2878},
{"pid": "12685", "subscribers": 694, "uptime": 2878}
]}

stored_messages always shows very low value (less than 20). If i look for stats for some specific channel (?id=CHANNEL_NAME):

{"channel": "conn_track_channel", "published_messages": 10041, "stored_messages": 1039, "subscribers": 0}

So, here is 1039, but in general stats the value is too low.

Could you please check this?

[wandenberg]

Hi @materkov can you confirm some info? 1) Which nginx version are you using? 2) Which module version are you using? 3) Which OS are you using? 4) Is the "conn_track_channel" channel the "event_channel"? If so, this can explain the difference.

The counters goes together, except for event_channel, since the messages stored there are not send by the user. For example, If a user connects to the push stream, send a message to channel "A" and disconnect, the channel "A" will have 1 stored message, the global counter for stored message will also be 1, but the events channel may have 3 messages, 1 saying that someone subscribe the channel, 1 saying that a message was sent, and another one saying that someone unsubscribe the channel. Take a look to see if this is your case, please. If not I will be happy to help debug your problem.

[materkov]

1) nginx version: nginx/1.12.0 2) Module was build today from latest commit in master 4d6d399721b6482c00af10da32651278504581e7 3) Ubuntu 14.04.5 LTS 4) Yes, this is events channel.

Ok, I don't know about the case that events channel messages were not counted.

I've tried another expirement. I've downloaded detailed info about all channels (?id=ALL), and then summarize all channels. Even without events channel, there should be about ~3k of stored messages. But total stats shows really weird number (it even shows 0 sometimes).

[materkov]

Here is another expirement. I've pulled /stats info every second, here is some result (with some detail cutted):

"time": "2017-11-24T13:05:43", "channels": 4223, "published_messages": 105065, "stored_messages": 5, "subscribers": 3638, "uptime": 17596
"time": "2017-11-24T13:05:44", "channels": 4224, "published_messages": 105067, "stored_messages": 7, "subscribers": 3639, "uptime": 17597
"time": "2017-11-24T13:05:45", "channels": 4224, "published_messages": 105070, "stored_messages": 10, "subscribers": 3638, "uptime": 17598
"time": "2017-11-24T13:05:46", "channels": 4219, "published_messages": 105072, "stored_messages": 0, "subscribers": 3638, "uptime": 17599
"time": "2017-11-24T13:05:47", "channels": 4219, "published_messages": 105074, "stored_messages": 0, "subscribers": 3636, "uptime": 17600
"time": "2017-11-24T13:05:48", "channels": 4220, "published_messages": 105080, "stored_messages": 6, "subscribers": 3635, "uptime": 17601
"time": "2017-11-24T13:05:49", "channels": 4221, "published_messages": 105090, "stored_messages": 16, "subscribers": 3635, "uptime": 17602
"time": "2017-11-24T13:05:50", "channels": 4223, "published_messages": 105096, "stored_messages": 22, "subscribers": 3637, "uptime": 17603
"time": "2017-11-24T13:05:51", "channels": 4222, "published_messages": 105104, "stored_messages": 8, "subscribers": 3639, "uptime": 17604
"time": "2017-11-24T13:05:51", "channels": 4222, "published_messages": 105116, "stored_messages": 7, "subscribers": 3637, "uptime": 17604
"time": "2017-11-24T13:05:52", "channels": 4225, "published_messages": 105121, "stored_messages": 4, "subscribers": 3639, "uptime": 17605
"time": "2017-11-24T13:05:53", "channels": 4226, "published_messages": 105123, "stored_messages": 6, "subscribers": 3640, "uptime": 17606
"time": "2017-11-24T13:05:54", "channels": 4217, "published_messages": 105125, "stored_messages": 0, "subscribers": 3639, "uptime": 17607
"time": "2017-11-24T13:05:55", "channels": 4221, "published_messages": 105129, "stored_messages": 4, "subscribers": 3642, "uptime": 17608
"time": "2017-11-24T13:05:56", "channels": 4223, "published_messages": 105145, "stored_messages": 1, "subscribers": 3642, "uptime": 17609
"time": "2017-11-24T13:05:57", "channels": 4223, "published_messages": 105151, "stored_messages": 2, "subscribers": 3641, "uptime": 17610

As you can see, published_messages grows, but stored_messages show weird number. TTL is 10 mintutes in config:

push_stream_message_ttl 10m;

[wandenberg]

What is the limit you set for the message queue length? (if any) Are you able to reproduce the problem in a controlled/reproducible environment like a vagrant machine? Or give me access to a test environment? Will be easier to try to investigate your issue, since the tests that I have for these counters are working :/