Opened 3 years ago

Closed 3 years ago

#2508 closed Bug (fixed)

2 goal conversions in the same second, or a page view and goal in same second results in one request being ignored

Reported by: OS1 Owned by:
Priority: normal Milestone: 1.5.1 Piwik 1.5.1
Component: Core Keywords:
Cc: Sensitive: no

Description

We have a number of sites feeding into two shop sites. The WorldPay callback scripts are on just one of these shop sites. We want to be track visitors from specific landing pages with the goal set as a WorldPay callback with SUCCESS is a conversion.

Here is the code we use in the WorldPay callback script:
-- Piwik Tracking API init --
require_once "../piwik/PiwikTracker.php";
PiwikTracker::$URL = 'http://oursite.com/piwik';

$piwikTracker = new PiwikTracker(1);
You can manually set the visitor details (resolution, time, plugins, etc.)
See all other ->set* functions available in the PiwikTracker.php file
$piwikTracker->setResolution(1600, 1400);
Mandatory: set the URL being tracked
$piwikTracker->setUrl('http://oursite.com/post/wp.php' );
Sends Tracker request via http
$piwikTracker->doTrackPageView('Oursite.com Post Worldpay');
You can also track Goal conversions
$piwikTracker->doTrackGoal(3, $totalAmount);

The call to doTrackPageView(...) appears to be working. The call to doTrackGoal(...) does not. Goal ID 3 is defined as a "manually" goal. We have other "when visitors" goals and these appear to update correctly.

I have loaded the code into NetBeans and with the PHP debugger I can see it going to PiwikTracker::sendRequest(...) but it never seems to get to core/Tracker/GoalManager.php nor plugins/Goals/ except when in the admin pages.

I have configured Piwik to output debug information to a file and I can see lines like:
INSERT IGNORE INTO piwik_log_conversion (idvisit, idsite, idvisitor, server_time, location_country, location_continent, visitor_returning, visitor_days_since_first, visitor_days_since_order, visitor_count_visits, referer_type, referer_name, referer_keyword, referer_visit_server_date, idgoal, url, revenue, idaction_url, idlink_va, buster) VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?).

In 14 attempts goal 3 was only recorded twice in piwik_log_conversion, all the "when visitors" goals have 14 entries.

All goals are currently "Allow Goal to be converted more than once per visit"

How does it manage to INSERT INTO piwik_log_conversion when apparently it doesn't execute any code that actually does this. I've found the message dispatcher but not the message handler!

Attachments (2)

logger_message.htm (468.2 KB) - added by OS1 3 years ago.
Piwik debug message file
logger_api_call (28.4 KB) - added by OS1 3 years ago.
Piwik API calls debug file

Download all attachments as: .zip

Change History (20)

Changed 3 years ago by OS1

Piwik debug message file

Changed 3 years ago by OS1

Piwik API calls debug file

comment:1 Changed 3 years ago by OS1

Issue appears to be intermittent. Have now got 23 completed "when visitor" type goals but the manual goal has only been recorded 10 times

comment:2 follow-up: Changed 3 years ago by OS1

Is this the result of the CURL call? i.e. PiwiTracker.php accesses the core by issuing an HTTP GET to piwik.php?

0000 00 00 00 00 00 00 00 00 00 00 00 00 08 00 45 00 ..............E.
0010 01 7e e1 55 40 00 40 06 5a 22 7f 00 00 01 7f 00 .~.U@.@.Z"......
0020 00 01 d3 30 00 50 84 8b 54 55 85 0e c7 3b 80 18 ...0.P..TU...;..
0030 02 01 ff 72 00 00 01 01 08 0a 00 cc b5 07 00 cc ...r............
0040 b5 07 47 45 54 20 2f 70 69 77 69 6b 2f 70 69 77 ..GET /piwik/piw
0050 69 6b 2e 70 68 70 3f 69 64 73 69 74 65 3d 31 26 ik.php?idsite=1&
0060 72 65 63 3d 31 26 61 70 69 76 3d 31 26 72 61 6e rec=1&apiv=1&ran
0070 64 3d 31 37 36 34 31 32 33 39 36 32 26 63 69 70 d=1764123962&cip
0080 3d 31 32 37 2e 30 2e 30 2e 31 26 5f 69 64 3d 31 =127.0.0.1&_id=1
0090 65 65 62 30 63 63 65 61 35 61 30 62 34 30 36 26 eeb0ccea5a0b406&
00a0 75 72 6c 3d 68 74 74 70 25 33 41 25 32 46 25 32 url=http%3A%2F%2
00b0 46 76 65 67 65 70 61 2d 64 65 76 25 32 46 70 6f Fvegepa-dev%2Fpo
00c0 73 74 25 32 46 6d 75 6e 67 65 72 47 42 2e 70 68 st%2FmungerGB.ph
00d0 70 26 75 72 6c 72 65 66 3d 26 69 64 67 6f 61 6c p&urlref=&idgoal
00e0 3d 33 26 72 65 76 65 6e 75 65 3d 32 30 20 48 54 =3&revenue=20 HT
00f0 54 50 2f 31 2e 31 0d 0a 55 73 65 72 2d 41 67 65 TP/1.1..User-Age
0100 6e 74 3a 20 4d 6f 7a 69 6c 6c 61 2f 35 2e 30 20 nt: Mozilla/5.0
0110 28 58 31 31 3b 20 4c 69 6e 75 78 20 69 36 38 36 (X11; Linux i686
0120 3b 20 72 76 3a 32 2e 30 2e 31 29 20 47 65 63 6b ; rv:2.0.1) Geck
0130 6f 2f 32 30 31 30 30 31 30 31 20 46 69 72 65 66 o/20100101 Firef
0140 6f 78 2f 34 2e 30 2e 31 0d 0a 48 6f 73 74 3a 20 ox/4.0.1..Host:
0150 76 65 67 65 70 61 2d 64 65 76 0d 0a 41 63 63 65 vegepa-dev..Acce
0160 70 74 3a 20 2a 2f 2a 0d 0a 41 63 63 65 70 74 2d pt: */*..Accept-
0170 4c 61 6e 67 75 61 67 65 3a 20 65 6e 2d 75 73 2c Language: en-us,
0180 65 6e 3b 71 3d 30 2e 35 0d 0a 0d 0a en;q=0.5....

comment:3 Changed 3 years ago by OS1

0000 00 00 00 00 00 00 00 00 00 00 00 00 08 00 45 00 ..............E.
0010 01 7e e1 55 40 00 40 06 5a 22 7f 00 00 01 7f 00 .~.U@.@.Z"......
0020 00 01 d3 30 00 50 84 8b 54 55 85 0e c7 3b 80 18 ...0.P..TU...;..
0030 02 01 ff 72 00 00 01 01 08 0a 00 cc b5 07 00 cc ...r............
0040 b5 07 47 45 54 20 2f 70 69 77 69 6b 2f 70 69 77 ..GET /piwik/piw
0050 69 6b 2e 70 68 70 3f 69 64 73 69 74 65 3d 31 26 ik.php?idsite=1&
0060 72 65 63 3d 31 26 61 70 69 76 3d 31 26 72 61 6e rec=1&apiv=1&ran
0070 64 3d 31 37 36 34 31 32 33 39 36 32 26 63 69 70 d=1764123962&cip
0080 3d 31 32 37 2e 30 2e 30 2e 31 26 5f 69 64 3d 31 =127.0.0.1&_id=1
0090 65 65 62 30 63 63 65 61 35 61 30 62 34 30 36 26 eeb0ccea5a0b406&
00a0 75 72 6c 3d 68 74 74 70 25 33 41 25 32 46 25 32 url=http%3A%2F%2
00b0 46 76 65 67 65 70 61 2d 64 65 76 25 32 46 70 6f Fvegepa-dev%2Fpo
00c0 73 74 25 32 46 6d 75 6e 67 65 72 47 42 2e 70 68 st%2FmungerGB.ph
00d0 70 26 75 72 6c 72 65 66 3d 26 69 64 67 6f 61 6c p&urlref=&idgoal
00e0 3d 33 26 72 65 76 65 6e 75 65 3d 32 30 20 48 54 =3&revenue=20 HT
00f0 54 50 2f 31 2e 31 0d 0a 55 73 65 72 2d 41 67 65 TP/1.1..User-Age
0100 6e 74 3a 20 4d 6f 7a 69 6c 6c 61 2f 35 2e 30 20 nt: Mozilla/5.0
0110 28 58 31 31 3b 20 4c 69 6e 75 78 20 69 36 38 36 (X11; Linux i686
0120 3b 20 72 76 3a 32 2e 30 2e 31 29 20 47 65 63 6b ; rv:2.0.1) Geck
0130 6f 2f 32 30 31 30 30 31 30 31 20 46 69 72 65 66 o/20100101 Firef
0140 6f 78 2f 34 2e 30 2e 31 0d 0a 48 6f 73 74 3a 20 ox/4.0.1..Host:
0150 76 65 67 65 70 61 2d 64 65 76 0d 0a 41 63 63 65 vegepa-dev..Acce
0160 70 74 3a 20 2a 2f 2a 0d 0a 41 63 63 65 70 74 2d pt: */*..Accept-
0170 4c 61 6e 67 75 61 67 65 3a 20 65 6e 2d 75 73 2c Language: en-us,
0180 65 6e 3b 71 3d 30 2e 35 0d 0a 0d 0a en;q=0.5....

comment:4 in reply to: ↑ 2 Changed 3 years ago by peterb (peterbo)

Correct - are all the pageviews correctly logged in the log_visit table (and only some triggered goals are missing)?

comment:5 Changed 3 years ago by OS1

Yes, it looks like it, visitor_count_visits is 1 and visit_total_action is 28 on the new local DB. I'm only visiting one page on this local site The only missing / incomplete goal is the one set to manual. I can do an SQL dump of the live site table if that would help.

comment:6 Changed 3 years ago by OS1

How does it work?! The HTTP request results in /piwik/piwik.php getting called but piwik.php doesn't in itself seem to handle GET parameters and the debugger fails to stop at breakpoints in the file. Please could you tell me the mechanism whereby the GET parameters are processed? Thanks.

comment:7 Changed 3 years ago by peterb (peterbo)

Take a look at the files which are included by piwik.php. Tracker related actions are in core/tracker. The request and all request params are handled there.

comment:8 Changed 3 years ago by OS1

Hmmm, well currently I can find no evidence that this HTTP GET is actually being processed at all. None of the breakpoints is triggered and no diagnostics are being output. I have all the diagnostic config parameters I can find turned on and / or set to "file" I have scattered liberally extra diagnostics. The only API calls that ever get logged is when the Piwik admin pages are being viewed.

I think it should be calling core::Tracker::GoalManager::recordGoals(...) but it never seems to get there.

Would you expect the API calls to be logged when goals are being completed from PiwikTracker?

comment:9 Changed 3 years ago by OS1

My mistake, I'm using direct file writes now and not relying on Piwik debug output. piwik.php is being called so the debugging can start...

comment:10 Changed 3 years ago by OS1

First diagnostic run shows now reference to Goal 3 matching so nothing gets updated, will keep getting more output. debugLog file attached

comment:11 Changed 3 years ago by OS1

Hmmm, can't attach file, it's rejected as spam. Doubt I could paste the 7K in here!

comment:12 Changed 3 years ago by OS1

There appears to be an issue with calling doTrackPageView(...) before doTrackGoal(...) as shown in the API documentation as an example. If the call to doTrackPageView(...) is removed or placed after doTrackGoal(...) it kind of works. In fact it looks like making multiple API calls is problematic. I've have put multiple doTrackGoal(...) calls and every other one fails. For a good call I see this in the diagnostics file:

'Visit is known. '
'getDatabase'
'Updating existing visit: array (

\'visit_goal_converted\' => 1,
\'visit_last_action_time\' => \'2011-06-24 15:28:22\',
\'visit_total_time\' => 4753,
\'idvisitor\' => \'24a34600cd46727d\',
\'visit_goal_buyer\' => \'0\',

)'
'getDatabase'
'enter recordGoals'


whereas the next call to doTrackGoal(...) fails and the diag output is:

'Visit is known. '
'getDatabase'
'Updating existing visit: array (

\'visit_goal_converted\' => 1,
\'visit_last_action_time\' => \'2011-06-24 15:28:22\',
\'visit_total_time\' => 4753,
\'idvisitor\' => \'24a34600cd46727d\',
\'visit_goal_buyer\' => \'0\',

)'
'getDatabase'
'Visitor with this idvisit wasn\'t found in the DB.'
'UPDATE piwik_log_visit

SET visit_goal_converted = ?, visit_last_action_time = ?, visit_total_time = ?, idvisitor = ?, visit_goal_buyer = ?
WHERE idsite = ?

AND idvisit = ? --- '

the next call to doTrackGoal(...) then works again.

I now have four log files if you would like them but I cannot attach them as I appear to appear as a spammer!

comment:13 Changed 3 years ago by OS1

Br it!

There is an edge case when:
- two manual goal conversions happen in the same second
- which result in handleKnownVisit throwing the exception
because the UPDATE didn't affect any rows (one row was found, but not updated since no field changed)
- the exception is caught here and will result in a new visit incorrectly
In this case, we cancel the current conversion to be recorded:

Known issue!!

comment:14 Changed 3 years ago by vipsoft (robocoder)

  • Milestone set to 1.6 Piwik 1.6

comment:15 Changed 3 years ago by matt (mattab)

  • Resolution set to wontfix
  • Status changed from new to closed

OS1, thanks for your investigation. The solution here is to manually change the datetime of the request using
$t->setTokenAuth( $token_auth );
$t->setForceVisitDateTime( '2011-04-05 23:55:02' );

putting a datetime different for each pageview/goal conversion.

comment:16 Changed 3 years ago by OS1

Many thanks Matt, I'll give it a try.

comment:17 Changed 3 years ago by matt (mattab)

  • Resolution wontfix deleted
  • Status changed from closed to reopened
  • Summary changed from Manual goals don't get updated to 2 goal conversions in the same second, or a page view and goal in same second results in one request being ignored

This is a bug which we can easily enough fix actually

comment:18 Changed 3 years ago by matt (mattab)

  • Resolution set to fixed
  • Status changed from reopened to closed

(In [5167]) Fixes #2508

Note: See TracTickets for help on using tickets.