Second queue is growing forever

[marcinzp]

Hello, since few Matomo versions we have returning problem with the second queue which is growing forever (until I remove this plugin and reinstall it back, as I haven't found better method yet).

Matomo version: 4.4.1
MySQL version: 5.7.34-37-log
PHP version: 7.3.29-1+020210701.86+debian101.gbp7ad6eb
Backend: Redis

sudo -u www-data /usr/share/piwik/console queuedtracking:monitor
Queue is enabled
The command ./console queuedtracking:process has to be executed to process request sets within queue
Up to 8 workers will be used
Processor will start once there are at least 5 request sets in the queue
218717 (53+218338+68+60+54+60+40+44) request sets left in queue. 464.62M used memory (588.55M peak). 1 workers act...

How can I debug this?
Thanks :-)

[tsteur]

@marcinzp thanks for reaching out. You could use the command ./console queuedtracking:print-queued-requests --queue-id=2 to look into this queue to see what kind of requests are put in there. Generally, Matomo will put all requests for the same User, Visitor and IP address into the same queue. So if for example many requests are for the same "user" (if userId feature is used), then it will put them all into the same queue.

To give you some hint we would need to understand a bit better how you track data. Are you using the JavaScript tracker? If you are using log importer then please note that we usually don't recommend using log importer in combination with queued tracking (since they are both doing some kind of queued tracking but in a different way). And if there's no other way around this would maybe need to try applying some settings.

[marcinzp]

@tsteur thank you for your answer and explanations. In the night, the growing queue was "magically" processed, but I think I still need to prepare for the return of the problem, it returns every few days.

If I understand properly, queues as numbered from 0, so the second one has id == 1, right?

We're tracking data for multiple sites using JS tracker and two of our sites are our mobile application, which use SDK for tracking (we have two sites, separately for Android and iOS app).

What I also noticed, CPU was more busy, but it didn't process the queue even when heaving more "headroom" in processing power:

[tsteur]

If I understand properly, queues as numbered from 0, so the second one has id == 1, right?

That's the case as far as I know.

If it happens every few days you might want to look at the content of these requests using the command I mention to see what is different there. In the past we've seen eg people using the userId feature I mentioned and there was a bug where the same userId was tracked for every visitor (eg null or undefined or nil). Such things could cause many requests to be put into the same queue.

[marcinzp]

Thank you @tsteur
In advance - is there a way to remove permanently first request from the specific queue, just to see if this one was blocking the processing?

By userId feature you mean this one?
https://matomo.org/docs/user-id/

[tsteur]

By userId feature you mean this one?

Yes 👍

In advance - is there a way to remove permanently first request from the specific queue, just to see if this one was blocking the processing?

Not that I know but I don't think that's the issue (at least whenever I've seen this it's never been that problem)

[marcinzp]

Thank you. I've checked, that we are using userId both in JS and SDK clients.

So if my problem returns, I need to check what is different in requests in this not/slowly processed queue, and especially look at userId if it's not the same for all requests? (what would be an incarnation of some old error)

[marcinzp]

I didn't need to wait long @tsteur :-) I got WARNING of "Invalid argument"

/usr/share/piwik/console queuedtracking:monitor
Queue is enabled
The command ./console queuedtracking:process has to be executed to process request sets within queue
Up to 8 workers will be used
Processor will start once there are at least 5 request sets in the queue
22949 (44+22696+22+31+66+23+31+36) request sets left in queue. 206.05M used memory (588.55M peak). 1 workers active.

/usr/share/piwik/console queuedtracking:print-queued-requests --queue-id=1 | head
Showing requests of queue 1. Use --queue-id=1 to print only information for this queue.
WARNING [2021-08-11 14:03:51] 19792 /usr/share/piwik/core/Tracker/RequestSet.php(36): Warning - Invalid argument supplied for foreach() - Matomo 4.4.1 - Please report this message in the Matomo forums: https://forum.matomo.org (please do a search first as it might have been reported already)
array (
0 =>
Piwik\Tracker\RequestSet::__set_state(array(
'requests' =>
array (
),
'tokenAuth' => NULL,
'env' => NULL,

and request contain particularly many times one user id:

/usr/share/piwik/console queuedtracking:print-queued-requests --queue-id=1 | grep "'uid'" | sort | uniq -c
4 'uid' => '3bcf33a76d83aa3525de759972a8653c',
120 'uid' => 'qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7',

/usr/share/piwik/console queuedtracking:print-queued-requests --queue-id=1 | grep "'uid'" | sort | uniq -c
2 'uid' => '22b75868af85a18bac2b2ebab3c2edcf',
2 'uid' => '72fff74ca87546153a2357acaee53a19',
2 'uid' => '8sod5dt55468obo6jksmgim78ecbmltm4108i9snh7',
80 'uid' => 'qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7',

[marcinzp]

After two hours:

/usr/share/piwik/console queuedtracking:monitor
Queue is enabled
The command ./console queuedtracking:process has to be executed to process request sets within queue
Up to 8 workers will be used
Processor will start once there are at least 5 request sets in the queue
53144 (20+52985+28+20+37+13+17+24) request sets left in queue. 245.78M used memory (588.55M peak). 1 workers active.

/usr/share/piwik/console queuedtracking:print-queued-requests --queue-id=1 | grep "'uid'" | sort | uniq -c
4 'uid' => 'e51e2c12faa22bda35e06c4af65e215e',
120 'uid' => 'qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7',

[tsteur]

@marcinzp could you try to apply this patch if any possible to see if the error goes away? https://github.com/matomo-org/matomo/pull/17877/files

[marcinzp]

Thank you @tsteur -

EDITED

~2 hours after patching, I see that queue is indeed decreasing its size AND I don't see requests from that
user id:

179829 (50+179622+13+53+26+13+47+5) request sets left in queue. 413.77M used memory (588.55M peak). 1 workers active.

So either the problem is solved or it disappeared again.
Please, stay tuned :-)

MY PREVIOUS COMMENT:

unfortunately it didn't help:

/usr/share/piwik/console queuedtracking:monitor
Queue is enabled
The command ./console queuedtracking:process has to be executed to process request sets within queue
Up to 8 workers will be used
Processor will start once there are at least 5 request sets in the queue
204467 (96+203854+120+106+70+30+81+110) request sets left in queue. 445.32M used memory (588.55M peak). 1 workers active.

I didn't catch previous time, but the problem reappeared now and what I see, still requests of the same user keep dominating:

/usr/share/piwik/console queuedtracking:print-queued-requests --queue-id=1 | grep "'uid'" | sort | uniq -c
2 'uid' => '614821357dc16c4c009667b7942d98b8',
160 'uid' => 'qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7',

I don't see it so often in access.log:

grep -c qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7 /var/log/nginx/access.log
15

[tsteur]

Great, thanks for the update. Keep us informed 👍

[marcinzp]

So far so good :-)
Thank you for helping me, I'll keep you informed.

[tsteur]

Great, thanks for letting us know and fingers crossed. We'll merge the PR very likely soon and then it would be included in the next release.