matomo-org / plugin-QueuedTracking

Scale your large traffic Matomo service by queuing tracking requests (in Redis or MySQL) for better performance.
https://matomo.org
GNU General Public License v3.0
82 stars 35 forks source link

Second queue is growing forever #153

Open marcinzp opened 3 years ago

marcinzp commented 3 years ago

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+0~20210701.86+debian10~1.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 commented 3 years ago

@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 commented 3 years ago

@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:

Screenshot 2021-08-05 at 11 11 57

tsteur commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

@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 commented 3 years ago

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 commented 3 years ago

Great, thanks for the update. Keep us informed đź‘Ť

marcinzp commented 3 years ago

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

tsteur commented 3 years ago

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.

marcinzp commented 3 years ago

@tsteur The problem is back :-(

/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 16 workers will be used Processor will start once there are at least 10 request sets in the queue 915616 (915550+8+1+9+3+3+8+7+2+9+2+0+7+4+0+3) request sets left in queue. 1.39G used memory (5.90G peak). 1 workers active.

sudo -u www-data /usr/share/piwik/console queuedtracking:print-queued-requests --queue-id=0 | grep "'uid'" | sort | uniq -c 2 'uid' => '02136e85b1e38a8a65d910491da6a67c', 2 'uid' => 'c188b6b6edce7e15387177a16a90d250', 2 'uid' => 'o73v5ss4in6689g79s12hv68i68r6gllppv625orm7', 280 'uid' => 'qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7',

marcinzp commented 3 years ago

@tsteur could you possible reopen this issue?

Thank you, Marcin

tsteur commented 3 years ago

@marcinzp can you also check if there are maybe a lot of requests with the same visitorId (this is the _id parameter) or the same IP address (not sure the IP can be filtered out easily)?

Have you checked if there is any kind of information in any error log?

marcinzp commented 3 years ago

@tsteur

  1. I didn't see any error messages on "/console queuedtracking:print-queued-requests --queue-id=0"
  2. Now I've checked historical logs of nginx and stderr from "console queuedtracking:process" but there's nothing interesting.
  3. For now, the problem already disappeared (but it will come back for sure :-) )
  4. As for _id, I've been focused on uid (as above) and next time I'll check for _id
marcinzp commented 2 years ago

So @tsteur ... I'm trying to catch the problem again:

/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 16 workers will be used Processor will start once there are at least 20 request sets in the queue 643332 (599912+42854+33+48+30+27+51+42+47+34+39+56+41+42+37+39) request sets left in queue. 1.02G used memory (5.90G peak). 2 workers active.

/usr/share/piwik/console queuedtracking:print-queued-requests --queue-id=0 | grep "'uid'" | sort | uniq -c 2 'uid' => '14e927b86329e6acc09212e882b2ce67', 2 'uid' => '4eb30a904900dfec5201fc22f480324f', 2 'uid' => '6d89500cbbca2a16e51c56d0c162d98c', 6 'uid' => '7a0ab288759fbde45a121775ba17c68a', 2 'uid' => '86ab4a8705e4adb218947f62f54882e1', 2 'uid' => 'bfde41bfe7c35aaf8b49112dc7daec5d', 14 'uid' => 'nnrf2j06gvuee9s4gsuq6vu6lmf9mn1lfpvc4qtpg7', 440 'uid' => 'qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7',

/usr/share/piwik/console queuedtracking:print-queued-requests --queue-id=0 | grep "'_id'" | sort | uniq -c 440 '_id' => '2691ea3d93de4912', 2 '_id' => '5a49e17a2b3e6e2f', 2 '_id' => '65e7bd0e2402bd00', 14 '_id' => '7e177923d5424324', 2 '_id' => '818da8095bf1d354', 2 '_id' => '9a5a95eff13ad9c3', 2 '_id' => 'dcf4c9766071ca8a', 6 '_id' => 'e1a3d99ec09a84bd',

I still have most request from the same user. Those requests come from our application (using Matomo SDK). There are in fact, some occurrences of this user id in access.log, but...:

grep -c "qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7" /var/log/nginx/access.log 29

zgrep -c "qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7" /var/log/nginx/access.log-20211001.gz 35

As you can see, it's not that often as in the queue. And:

grep "qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7" /var/log/nginx/access.log | cut -f5 -d\ | tail -n5 [01/Oct/2021:15:10:32 [01/Oct/2021:15:10:33 [01/Oct/2021:15:10:33 [01/Oct/2021:15:10:34 [01/Oct/2021:15:10:34

Last occurrences today were 4 hours ago...

So I took a look at the contents of those records and I see them to be almost the same:

/usr/share/piwik/console queuedtracking:print-queued-requests | grep -C4 qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7 | csplit --suppress-matched - "/^--$/" '{*}'

md5sum xx* | cut -f1 -d\ | sort | uniq -c | sort -nr 504 71b0cbd43d9a8dc8099f4021ccf5157c 334 39ebb0e1023d7383edd7f27a136f5430 200 863c4987d4d4399f541fdb3c4867e5da 92 068c4ac2443b18638a1673ea94196c80 26 6ddff64a6f5ef622b7f475ace9cf745e 4 795f399bb013928aedf1fa9c92d6299f

tsteur commented 2 years ago

@marcinzp thanks for the update. You could exclude specific user ID from being tracked like this see https://matomo.org/faq/how-to/how-do-i-exclude-specific-tracking-requests-in-matomo/

Edit your config/config.ini.php

[Tracker] # only add this line if it doesn't exist yet
exclude_requests = "uid==ENTER THE USER ID THAT SHOULD BE BLOCKED"
marcinzp commented 2 years ago

@tsteur Thank you, I've added recommended entry:

[Tracker] ignore_visits_cookie_name = "piwik_ignore" exclude_requests = "uid==qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7"

but the queue still seems to be growing: /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 16 workers will be used Processor will start once there are at least 20 request sets in the queue 844619 (843880+45+53+37+79+56+57+49+56+35+42+30+54+42+43+61) request sets left in queue. 1.28G used memory (5.90G peak). 1 workers active.
845134 (844619+28+25+24+37+23+36+40+44+42+36+30+42+39+35+34) request sets left in queue. 1.28G used memory (5.90G peak). 1 workers active.
853774 (853346+43+43+30+10+32+17+22+31+36+19+26+23+32+34+30) request sets left in queue. 1.29G used memory (5.90G peak). 1 workers active.

/usr/share/piwik/console queuedtracking:print-queued-requests --queue-id=0 | grep -c qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7 480 /usr/share/piwik/console queuedtracking:print-queued-requests --queue-id=0 | grep -c qn5flmc4uvua9bs4mso81ku46ejd1htr3pt6iakog7 520

marcinzp commented 2 years ago

... but after a longer while, the queue is melting indeed :-)

/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 16 workers will be used Processor will start once there are at least 20 request sets in the queue 560961 (560331+48+43+41+51+24+26+49+25+44+53+44+47+37+55+43) request sets left in queue. 921.88M used memory (5.90G peak). 1 workers active.

rishabhkailey commented 2 years ago

@tsteur we are facing a similar issue after updating Matomo from 3.14 to 4.6.2. we are using matomo:4.6.2-fpm-alpine docker image for Matomo, redis:6.0-alpine for Redis and mysql:8.0.21 for the MySQL DB.

for tracking, we are using

before the update, the requests were getting processed correctly.

Output of ./console queuedtracking:monitor

Queue is enabled
Request sets in the queue will be processed automatically after a tracking request
Up to 4 workers will be used
Processor will start once there are at least 25 request sets in the queue
374199 (3122+7067+404+363606) request sets left in queue. 699.36M used memory (699.53M peak). 4 workers active.

Output of ./console queuedtracking:print-queued-requests --queue-id=3 | grep "'uid'" | sort | uniq -c

    404           'uid' => 'Java_application_user',
     24           'uid' => 'random_user_1',
     22           'uid' => 'random_user_2',
      4           'uid' => 'random_user_3',
      6           'uid' => 'random_user_4',
      2           'uid' => 'random_user_5'

I also checked ./console queuedtracking:print-queued-requests --queue-id=3 command, even after 1 hour the output was the same.

tsteur commented 2 years ago

@rishabhkailey the requests from the java tracker, are they maybe mostly sent from the same IP address or maybe you are using the Matomo User ID feature and there could be a bug that many users have the same user ID?

rishabhkailey commented 2 years ago

The requests from the java tracker are from the same IP and have the same user id (piwikRequest.setUserId(<CONSTANT_USER_ID>)).

tsteur commented 2 years ago

The requests from the java tracker are from the same IP and have the same user id (piwikRequest.setUserId()).

This would be expected behaviour in that case. Queued tracking would put these requests all in the same queue to make sure the data for these are processed correctly. Otherwise there could be issues that data would be processed out of order and then the data could become inaccurate.

rishabhkailey commented 2 years ago

I will check with the team. I think we are only using user id for creating segments in Matomo. we can try to use custom variables instead.

Queued tracking would put these requests all in the same queue to make sure the data for these are processed correctly

We didn't face this issue in Matomo 3.14, is the above behavior have been added after Matomo 3.14?

rishabhkailey commented 2 years ago

and If we do not set the user id then will it work? does the same IP for all the requests will cause problems without user id? is there anything else we can do here?

tsteur commented 2 years ago

We didn't face this issue in Matomo 3.14, is the above behavior have been added after Matomo 3.14?

That should have been always there. So it's not clear why this changed now. Maybe it didn't happen exactly since the update to a newer Matomo version and was caused by something else?

and If we do not set the user id then will it work? does the same IP for all the requests will cause problems without user id? is there anything else we can do here?

The same IP for all the requests will cause the same issue. This is the case because requests of the same IP might belong to the same visitor which means we have to put these requests into the same queue. A workaround would be, if possible, to set a custom IP in the tracker (cip tracking parameter, the Java tracker might have a method for it). You could attach some kind of randomised IPs to each request. For Matomo to recognise this custom IP in the tracker the tracking request would need to be authenticated though using a token_auth parameter. see https://developer.matomo.org/api-reference/tracking-api#other-parameters-require-authentication-via-token_auth

rishabhkailey commented 2 years ago

@tsteur Thanks for the help, setting the Custom IP for the Matomo requests, seems to solve the problem.

loris-av commented 9 months ago

Hi, we have the same issue.

php console queuedtracking:monitor
Queue is enabled
Request sets in the queue will be processed automatically after a tracking request
Up to 6 workers will be used
Processor will start once there are at least 50 request sets in the queue
5327211 (22+5327135+5+29+6+14) request sets left in queue. disabled used memory (disabled peak). 1 workers active.

Since days, I have tested a lot of tricks I've found.

Like :

By deactivating ProcessDuringTrackingRequest there is no way to treat all off the 5M process.

I re-create empty table matomo_queuedtracking_list_trackingQueueV1_1 -> its growing too:

Processor will start once there are at least 50 request sets in the queue
2542 (47+2333+32+44+42+44) request sets left in queue. disabled used memory (disabled peak). 1 workers active.        
php -d memory_limit=-1 console queuedtracking:process 
Starting to process request sets, this can take a while

This worker finished queue processing with 0req/s (0 requests in 0.01 seconds)
php console queuedtracking:test
Settings that will be used:
Backend: mysql
NumQueueWorkers: 6
NumRequestsToProcess: 50
ProcessDuringTrackingRequest: 1
QueueEnabled: 1

Redis backend only settings (does not apply when using MySQL backend):
Host: 127.0.0.1
Port: 6379
Timeout: 0
Password: 
Database: 0
UseSentinelBackend: 0
SentinelMasterName: xxxx

Version / stats:
PHP version: 8.1.17RC1
Uname: Linux 3.10.0-1160.102.1.el7.x86_64 #1 SMP Tue Oct 17 15:42:21 UTC 2023 x86_64
Backend version: 5.7.34-log
Memory: array (
  'used_memory_human' => 'disabled',
  'used_memory_peak_human' => 'disabled',
)

Performing some tests:
Connection works in general
Initial expire seems to be set correctly
setIfNotExists works fine
expireIfKeyHasValue seems to work fine
Extending expire seems to be set correctly
expireIfKeyHasValue correctly expires only when the value is correct
Expire is still set which is correct
deleteIfKeyHasValue seems to work fine
List feature seems to work fine

Done
loris-av commented 9 months ago

I moved all to Redis database that is the same :

https://github.com/matomo-org/plugin-QueuedTracking/assets/58932787/ef9254db-a116-4075-b7f1-2e91606c8e0c

Nothing seems to be treated

AltamashShaikh commented 9 months ago

@loris-av Does running this command works ?

./console queuedtracking:process --queue-id=1,2,3,4,5,6 --force-num-requests-process-at-once=5
loris-av commented 9 months ago

Hi @AltamashShaikh I've playe by changing number of NumRequestsToProcess to have the possibility to run manually the process for this specific problematic queue-id=1.

With very low number of element (50-100) I've running

php console queuedtracking:process --queue-id="1" --force-num-requests-process-at-once=25 -vvv > process-queue-1.log

And it was running without finish..

Your command dont work

@loris-av Does running this command works ?

./console queuedtracking:process --queue-id=1,2,3,4,5,6 --force-num-requests-process-at-once=5

image

loris-av commented 9 months ago

It's look like the problem is like described before the uid, our Android App introduced an user_id, uid -1 when user is not connected.

It seems le process method dont like like this value. Maybe this boke the while or anything else, if someone can help me for investigating by adding some debug in the code ?

$php console queuedtracking:print-queued-requests --queue-id=0 | grep "'uid'" | sort | uniq -c
      6           'uid' => '3858254',
      4           'uid' => '3939042',
      8           'uid' => '4246446',
      2           'uid' => '4589110',
      4           'uid' => '5323922',
     10           'uid' => '5486155',
      4           'uid' => '5519028',
      4           'uid' => '5519346',
      2           'uid' => '5522626',
      6           'uid' => '5539295',

php console queuedtracking:print-queued-requests --queue-id=1 | grep "'uid'" | sort | uniq -c
     24           'uid' => '-1',
      6           'uid' => '264703',
      2           'uid' => '3648177',
      4           'uid' => '3712985',
      2           'uid' => '3741630',
      4           'uid' => '4250976',
      4           'uid' => '4305619',
      4           'uid' => '4404256',
      4           'uid' => '4951727',
      2           'uid' => '5163783',
      2           'uid' => '5230366',
     12           'uid' => '5299536',
      2           'uid' => '5500209',

php console queuedtracking:print-queued-requests --queue-id=2 | grep "'uid'" | sort | uniq -c
      4           'uid' => '1145003',
      4           'uid' => '1237099',
      4           'uid' => '3067949',
      4           'uid' => '3179250',
      2           'uid' => '3678958',
      4           'uid' => '5339337',
     10           'uid' => '5466222',
      2           'uid' => '5534975',
      2           'uid' => '5539280',
      6           'uid' => '5539302',

php console queuedtracking:print-queued-requests --queue-id=3 | grep "'uid'" | sort | uniq -c
      2           'uid' => '3811113',
      4           'uid' => '5245582',

php console queuedtracking:print-queued-requests --queue-id=4 | grep "'uid'" | sort | uniq -c
      2           'uid' => '5148425',

php console queuedtracking:print-queued-requests --queue-id=5 | grep "'uid'" | sort | uniq -c
      2           'uid' => '1669078',
      2           'uid' => '4999425',
      2           'uid' => '5539301',

I've read the trick by dealing with auth_token and cip, but for now we cannot fix this for all users because deploy new App version on the Play Store should not solve this immediately (because all users have to do the update etc..).

loris-av commented 9 months ago

I temporary fixed the problem by ignoring request directly into piwik.php..

image

AltamashShaikh commented 9 months ago

It's look like the problem is like described before the uid, our Android App introduced an user_id, uid -1 when user is not connected.

It seems le process method dont like like this value. Maybe this boke the while or anything else, if someone can help me for investigating by adding some debug in the code ?

$php console queuedtracking:print-queued-requests --queue-id=0 | grep "'uid'" | sort | uniq -c
      6           'uid' => '3858254',
      4           'uid' => '3939042',
      8           'uid' => '4246446',
      2           'uid' => '4589110',
      4           'uid' => '5323922',
     10           'uid' => '5486155',
      4           'uid' => '5519028',
      4           'uid' => '5519346',
      2           'uid' => '5522626',
      6           'uid' => '5539295',

php console queuedtracking:print-queued-requests --queue-id=1 | grep "'uid'" | sort | uniq -c
     24           'uid' => '-1',
      6           'uid' => '264703',
      2           'uid' => '3648177',
      4           'uid' => '3712985',
      2           'uid' => '3741630',
      4           'uid' => '4250976',
      4           'uid' => '4305619',
      4           'uid' => '4404256',
      4           'uid' => '4951727',
      2           'uid' => '5163783',
      2           'uid' => '5230366',
     12           'uid' => '5299536',
      2           'uid' => '5500209',

php console queuedtracking:print-queued-requests --queue-id=2 | grep "'uid'" | sort | uniq -c
      4           'uid' => '1145003',
      4           'uid' => '1237099',
      4           'uid' => '3067949',
      4           'uid' => '3179250',
      2           'uid' => '3678958',
      4           'uid' => '5339337',
     10           'uid' => '5466222',
      2           'uid' => '5534975',
      2           'uid' => '5539280',
      6           'uid' => '5539302',

php console queuedtracking:print-queued-requests --queue-id=3 | grep "'uid'" | sort | uniq -c
      2           'uid' => '3811113',
      4           'uid' => '5245582',

php console queuedtracking:print-queued-requests --queue-id=4 | grep "'uid'" | sort | uniq -c
      2           'uid' => '5148425',

php console queuedtracking:print-queued-requests --queue-id=5 | grep "'uid'" | sort | uniq -c
      2           'uid' => '1669078',
      2           'uid' => '4999425',
      2           'uid' => '5539301',

I've read the trick by dealing with auth_token and cip, but for now we cannot fix this for all users because deploy new App version on the Play Store should not solve this immediately (because all users have to do the update etc..).

@loris-av Which version of plugin are you using and can you give more details about your setup ?

AltamashShaikh commented 9 months ago

We added something in this PR to help debugging such cases. If your plugin is upto date, you might need to add log_failed_tracking_request_body=1 under QueuedTracking in config.ini.php

loris-av commented 9 months ago

Yes log_failed_tracking_request_body=1 is set since few days.

Today I have some errors due to dead locks, and others not due to this uid -1.

WARNING QueuedTracking[2023-12-15 09:55:58 UTC] [8656c] There was an error while trying to process a queued tracking request.
WARNING QueuedTracking[2023-12-15 09:55:58 UTC] [8656c] Error:
WARNING QueuedTracking[2023-12-15 09:55:58 UTC] [8656c] Custom timestamp is 93238 seconds old, requires &token_auth...
WARNING QueuedTracking[2023-12-15 09:55:58 UTC] [8656c] Stack trace:

I've solved "blocked" queue by adding this temporary trick into piwik.php

if (isset($_GET['uid']) && $_GET['uid'] === '-1') {
    @file_put_contents('../logs-blocked-1-' . date('Y-m-d') . '.txt', json_encode(['GET' => $_GET, 'POST' => $_POST, 'REQUEST' => $_REQUEST]) . PHP_EOL, FILE_APPEND | LOCK_EX);

    header('HTTP/1.1 200 OK');
    return;
}

$requests = json_decode(file_get_contents('php://input'))->requests ?? [];
foreach ($requests as $request) {
    if (str_contains($request, 'uid=-1')) {
        @file_put_contents('../logs-blocked-1-multi-' . date('Y-m-d') . '.txt', json_encode(['GET' => $_GET, 'POST' => $_POST, 'STREAM' => $requests, 'REQUEST' => $_REQUEST]) . PHP_EOL, FILE_APPEND | LOCK_EX);
        header('HTTP/1.1 200 OK');
        return;
    }
}

@file_put_contents('../logs-passed-' . date('Y-m-d') . '.txt', json_encode(['GET' => $_GET, 'POST' => $_POST, 'REQUEST' => $_REQUEST]) . PHP_EOL, FILE_APPEND | LOCK_EX);
loris-av commented 9 months ago

I've backuped the MySQL table with 5M records containing these events with this uid: -1. Can you think if if easy to remove this problematic lines with a job using matomo Core with custom command or something like this ?

I know these line are saved as longblog and ar gzipped with gzuncompress

loris-av commented 9 months ago

@loris-av Which version of plugin are you using and can you give more details about your setup ?

QueuedTracking (v4.0.7)

Details :

Click to view System Check ### Mandatory checks #### Version PHP >= 7.2.5: ✔ 8.1.17RC1 #### PDO extension: ✔ #### PDO\MYSQL extension: ✔ #### MYSQLI extension: ✔ #### Connexion au lecteur de la base de données: ✔ #### Autres extensions requises: ✔ zlib ✔ json ✔ filter ✔ hash ✔ session #### Fonctions requises: ✔ debug_backtrace ✔ eval ✔ hash ✔ gzcompress ✔ gzuncompress ✔ pack #### Configuration PHP requise (php.ini): ✔ session.auto_start = 0 ✔ max_execution_time = 0 OR = -1 OR >= 30 #### Répertoires avec les droits d'accès en écriture: ✔ $DOC_ROOT/tmp ✔ $DOC_ROOT/tmp/assets ✔ $DOC_ROOT/tmp/cache ✔ $DOC_ROOT/tmp/climulti ✔ $DOC_ROOT/tmp/latest ✔ $DOC_ROOT/tmp/logs ✔ $DOC_ROOT/tmp/sessions ✔ $DOC_ROOT/tmp/tcpdf ✔ $DOC_ROOT/tmp/templates_c #### Répertoires avec accès en écriture pour Gestionnaire de balises: ✔ $DOC_ROOT/js ### Optional checks #### Répertoires privés requis: ✔ Tous les répertoires privés sont inaccessibles depuis Internet. #### Répertoires privés recommandés: ✔ Tous les répertoires privés sont inaccessibles depuis Internet. #### Intégrité des fichiers: ⚠ Warning: Le contrôle d'intégrité a échoué et a rapporté des erreurs. Vous devriez corriger ces problèmes puis rafraîchir cette page jusqu'à ce qu'il n'y ait plus d'erreur.

Les erreurs ci-dessous peuvent être dues à des téléversements de fichiers Matomo partiels ou échoués. --> Essayez de renvoyer tous les fichiers Matomo en utilisant le mode BINAIRE. #### Binaire PHP 64 bits: ✔ #### État du traqueur: ✔ #### Limite mémoire: ✔ 8192M #### Fuseau horaire: ✔ #### Ouvrir l'URL: ✔ curl #### PageSpeed est désactivé: ✔ #### GD > 2.x + FreeType (graphics): ✔ #### Autres extensions: ✔ json ✔ libxml ✔ dom ✔ SimpleXML ✔ openssl #### Autres fonctions: ✔ shell_exec ✔ set_time_limit ✔ mail ✔ parse_ini_file ✔ glob ✔ gzopen ✔ md5_file #### Système de fichiers: ⚠ Warning: Votre serveur utilise un système de fichier NFS.
Cela signifie que Matomo va être très lent lors de l'utilisation des sessions basées sur des fichiers. #### Paramétrer une tâche Cron - Gestion des processus via la ligne de commande: ✔ Ok #### Dernière exécution d'archivage réussie: ✔ Le processus d'archivage s'est terminé avec succès il y a 01:15:46. #### Capacités de la base de données: ✔ UTF8mb4 charset ⚠ Warning: LOAD DATA INFILE
Astuce : l'utilisation de LOAD DATA INFILE en mettant à jour PHP et MySQL et s'assurant que votre utilisateur MySQL a les privilèges de FILE va grandement accélérer la vitesse du processus d'archivage de Matomo.
Si votre serveur Matomo suit des sites à fort trafic (ex. > 100000 pages par mois). ✔ CREATE TEMPORARY TABLES ✔ Changing transaction isolation level #### Taille maximale des paquets: ✔ #### Connexion SSL forcée: ✔ #### Géolocalisation: ✔ geoip2php (continent_code, continent_name, country_code, country_name, region_code, region_name, city_name, postal_code, lat, long) #### Mettre à jour via HTTPS: ✔ #### Traceur JavaScript inscriptible ("/matomo.js" & "/piwik.js"): ✔ ### Informational results #### Matomo Version: 4.16.0 #### Matomo Update History: 4.14.2,4.3.1,4.3.0-b3,4.2.1,3.14.1, #### Matomo Install Version: Unknown - pre 3.8. #### Latest Available Version: 4.16.0 #### Is Git Deployment: 0 #### PHP_OS: Linux #### PHP_BINARY: /opt/remi/php81/root/usr/sbin/php-fpm #### PHP SAPI: fpm-fcgi #### Timezone Version: 2022.1 #### PHP Timezone: UTC #### PHP Time: 1702636201 #### PHP Datetime: 2023-12-15 10:30:01 #### PHP INI max_execution_time: 0 #### PHP INI post_max_size: 8M #### PHP INI max_input_vars: 1000 #### PHP INI zlib.output_compression: #### Curl Version: 7.29.0, NSS/3.53.1 #### Suhosin Installed: 0 #### DB Prefix: matomo_ #### DB Charset: utf8mb4 #### DB Adapter: MYSQLI #### MySQL Version: 5.7.34-log #### Num Tables: 425 #### Browser Segment Archiving Enabled: 0 #### Development Mode Enabled: 0 #### Internet Enabled: 1 #### Multi Server Environment: 0 #### Auto Update Enabled: 1 #### Custom User Path: 0 #### Custom Include Path: 0 #### Release Channel: latest_stable #### Plugins Activated: API, Actions, Annotations, BulkTracking, Contents, CoreAdminHome, CoreConsole, CoreHome, CorePluginsAdmin, CoreUpdater, CoreVisualizations, CoreVue, CustomDimensions, CustomJsTracker, CustomReports 4.1.8, CustomVariables 4.1.3, Dashboard, DevicePlugins, DevicesDetection, Diagnostics, Ecommerce, Events, Feedback, Funnels 4.1.7, GeoIp2, Goals, Heartbeat, ImageGraph, Insights, Installation, Intl, IntranetMeasurable, LanguagesManager, Live, Login, MarketingCampaignsReporting 4.1.3, Marketplace, MobileMessaging, Monolog, Morpheus, MultiSites, Overlay, PagePerformance, PrivacyManager, ProfessionalServices, Proxy, QueuedTracking 4.0.7, Referrers, Resolution, RssWidget, SEO, ScheduledReports, SegmentEditor, SitesManager, TagManager, Tour, Transitions, TwoFactorAuth, UserCountry, UserCountryMap, UserId, UserLanguage, UsersManager, VisitFrequency, VisitTime, VisitorInterest, VisitsSummary, WebsiteMeasurable, Widgetize #### Plugins Deactivated: DBStats, MobileAppMeasurable, Provider 4.0.5 #### Plugins Invalid: #### Server Info: nginx/1.22.0 #### Had visits in last 1 day: 1 #### Had visits in last 3 days: 1 #### Had visits in last 5 days: 1 #### Archive Time Last Started: 2023-12-15 10:05:02 #### Archive Time Last Finished: 2023-12-15 09:14:14 #### User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0 #### Browser Language: fr-fr,fr #### Total Invalidation Count: 382 #### In Progress Invalidation Count: 41 #### Scheduled Invalidation Count: 341 #### Earliest invalidation ts_started: 2023-12-14 12:34:17 #### Latest invalidation ts_started: 2023-12-15 11:26:17 #### Earliest invalidation ts_invalidated: 2022-12-22 16:05:03 #### Latest invalidation ts_invalidated: 2023-12-15 10:05:19 #### Number of segment invalidations: 373 #### Number of plugin invalidations: 0 #### List of plugins being invalidated: #### Anonymize Referrer: #### Do Not Track enabled: 1
AltamashShaikh commented 9 months ago

@loris-av Do you have the stack trace for uid=-1 ?? You can run the ./console queuedtracking:process -vvv to enable verbose logging to get more info and with the stack track we can se

log_failed_tracking_request_body

@loris-av You meant removing the uid=-1 requests from queue ? You can may be add a temporary code here

public function getForcedUserId()
    {
        $userId = $this->getParam('uid');
        if (strlen($userId) > 0 && $userId != -1) {
            return $userId;
        }

        return false;
    }
AltamashShaikh commented 9 months ago

@loris-av I think this should work ./console queuedtracking:process --queue-id=2 --force-num-requests-process-at-once=5

loris-av commented 9 months ago

@loris-av I think this should work ./console queuedtracking:process --queue-id=2 --force-num-requests-process-at-once=5

I've tested this params --force-num-requests-process-at-once without success.

Do you thing reduce it to 5 work (i've tested it setted to 10)

AltamashShaikh commented 9 months ago

@loris-av it should have worked, @snake14 anything you could think of why its not working??

snake14 commented 9 months ago

@AltamashShaikh I found the error mentioned in the previous comment and it looks like it's because the core code says that the request is too old and requires an auth token. Does the QueuedTracking plugin supply a token when processing requests? I wonder if it should.

AltamashShaikh commented 9 months ago

@loris-av You can solve the authentication bug by following this FAQ, increase the timeout to 10 days from 1 day and try.

loris-av commented 9 months ago

Thanks for all these returns, Maybe we have multiple "issues", for now I've fixed it manually by ignoring the requests https://github.com/matomo-org/plugin-QueuedTracking/issues/153#issuecomment-1857600095 we will see