Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Incorrect actions during event tracking #9246

Closed
andrzejewsky opened this issue Nov 20, 2015 · 6 comments
Closed

Incorrect actions during event tracking #9246

andrzejewsky opened this issue Nov 20, 2015 · 6 comments
Assignees
@tsteur
Labels
answered For when a question was asked and we referred to forum or answered it.
Milestone
2.16.0

Comments

@andrzejewsky
Copy link

When I was tracking events, I saw some discrepancies in log_link_visit_actions and sometimes in log_visit table. After tracking events, all of them should be saved into the database but I think only one time, however sometimes I saw this event saved many times! I attached below more information about this case with steps to reproduce:

1) Clear all of log_* tables:
delete from piwik_log_action;
delete from piwik_log_link_visit_action;
delete from piwik_log_visit;
delete from piwik_log_profiling;
2) Add this code at the end of piwik.js
var tracker = Piwik.getTracker();
for (var j = 0; j < 10; j++) {
        tracker.trackEvent(
            'testcat',
            'eventname' + j,
            'eventitle',
            Math.random()
        );
}
3) Go to the browser and open a website which include your tracking code. Your request should looks like:

zrzut ekranu 2015-11-20 o 13 22 41

4) Check the results in the database:
log_visit:
mysql> select idvisit, idsite, hex(idvisitor), visit_last_action_time, hex(config_id) from piwik_log_visit;
+---------+--------+------------------+------------------------+------------------+
| idvisit | idsite | hex(idvisitor)   | visit_last_action_time | hex(config_id)   |
+---------+--------+------------------+------------------------+------------------+
|      23 |      1 | 9E2833D1EF5CD467 | 2015-11-20 12:22:27    | CA20F195884A354F |
|      24 |      1 | 9E2833D1EF5CD467 | 2015-11-20 12:22:29    | CA20F195884A354F |
+---------+--------+------------------+------------------------+------------------+
2 rows in set (0,00 sec)

Why I have two visits?

log_visit_action:
mysql> select idlink_va, idsite, hex(idvisitor), idvisit, server_time, idaction_event_action, name from piwik_log_link_visit_action left join piwik_log_action on piwik_log_action.idaction = idaction_event_action;
+-----------+--------+------------------+---------+---------------------+-----------------------+------------+
| idlink_va | idsite | hex(idvisitor)   | idvisit | server_time         | idaction_event_action | name       |
+-----------+--------+------------------+---------+---------------------+-----------------------+------------+
|       219 |      1 | 9E2833D1EF5CD467 |      23 | 2015-11-20 12:22:27 |                   115 | eventname0 |
|       220 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:27 |                  NULL | NULL       |
|       221 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:27 |                   118 | eventname1 |
|       222 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:27 |                   119 | eventname2 |
|       223 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:28 |                   120 | eventname3 |
|       224 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:28 |                   121 | eventname5 |
|       225 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:28 |                   122 | eventname4 |
|       226 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:28 |                   123 | eventname6 |
|       227 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:28 |                   124 | eventname7 |
|       228 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:28 |                   125 | eventname8 |
|       229 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:28 |                   126 | eventname9 |
|       230 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:29 |                   121 | eventname5 |
|       231 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:29 |                   122 | eventname4 |
|       232 |      1 | 9E2833D1EF5CD467 |      24 | 2015-11-20 12:22:29 |                   124 | eventname7 |
+-----------+--------+------------------+---------+---------------------+-----------------------+------------+

For better view:

mysql> select piwik_log_action.name, count(*) from piwik_log_link_visit_action left join piwik_log_action on piwik_log_action.idaction = idaction_event_action group by piwik_log_action.name;
+------------+----------+
| name       | count(*) |
+------------+----------+
| NULL       |        1 |
| eventname0 |        1 |
| eventname1 |        1 |
| eventname2 |        1 |
| eventname3 |        1 |
| eventname4 |        2 |
| eventname5 |        2 |
| eventname6 |        1 |
| eventname7 |        2 |
| eventname8 |        1 |
| eventname9 |        1 |
+------------+----------+
11 rows in set (0,00 sec)

As you see some actions was duplicated: eventname4, eventname5, eventname7

tested on piwik 2.15.0
@tsteur
Copy link
Member

tsteur commented Nov 22, 2015

Two visits are kinda a known issue as there can be race conditions when sending two requests for the same user at the same time. Pretty much the only workaround to this is currently the QueuedTracking plugin which uses Redis in the background.

Re the duplicated actions I could not reproduce that. Are you sure the join is correct etc? Can you maybe just get the entries in log_link_visit_action and see if you get 10 results?

select idlink_va, idsite, idvisit, server_time, idaction_event_action from piwik_log_link_visit_action where idaction_event_action is not null;

@andrzejewsky
Copy link
Author

Are you sure the join is correct etc?

Yes, it's correct. After sent mentioned request in my first comment, I had more than 10 actions in log_link_visit_action. I suppose should be 11: 1 - pageviews and 10 - my defined events.

I used joins/group here for better view.

@tsteur
Copy link
Member

tsteur commented Nov 23, 2015

Just to be sure: Can you reproduce this every time? The tracking of actions is pretty much straight forward and looking at the code I can't see how it could write multiple actions during one request.

Which Piwik version are you using? When testing, can you maybe also check the webserver logs to see if there is something weird happening?

@mattab mattab mentioned this issue Nov 26, 2015
Closed
@andrzejewsky
Copy link
Author

@tsteur

Can you reproduce this every time?

Yes, but it looks like random behavior, sometimes everything is tracked correct, sometimes not

Which Piwik version are you using?

2.15.0

For reproducing this I used only those steps what I described in my first comment:

  1. Clear database
  2. Append mentioned script at the end of piwik.js
  3. Refresh the tracked page

If nothing happened, repeat from step 1 (except step 2). I think, you will see duplicated actions.
Please write a message here when you find out something more. Also, I'll check this again

@tsteur
Copy link
Member

tsteur commented Nov 26, 2015

Copied it directly at the end of piwik.js and still could not reproduce it. If you could provide as a URL where we can debug the client side that could be helpful. Feel free to send an email with the URL to hello at piwik.org if you can make it somehow available.

Also is this a blank / basic HTML page where you are testing it or are there other JS libraries etc used as well?

@tsteur
Copy link
Member

tsteur commented Dec 4, 2015

We were able to reproduce this behaviour and it was actually a bug in Google Chrome / Chromium.

The requests were not shown in the network panel / developer toolbar but in apache logs. After updating Chrome to latest version (from 46 to 47) the bug was gone. It was not possible to reproduce this behaviour in other browsers.

This means for a certain period there were (or will be if some users are still using the buggy Chrome version) more actions tracked via Google Chrome than normal.

@tsteur tsteur closed this as completed Dec 4, 2015
@tsteur tsteur added the answered For when a question was asked and we referred to forum or answered it. label Dec 4, 2015
@tsteur tsteur added this to the 2.15.1 milestone Dec 4, 2015
@tsteur tsteur self-assigned this Dec 4, 2015
@tsteur tsteur mentioned this issue Dec 6, 2015
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@tsteur tsteur

Labels
answered For when a question was asked and we referred to forum or answered it.
Projects
None yet
Milestone
2.16.0
Development

No branches or pull requests
2 participants
@tsteur @andrzejewsky