@mattab opened this Issue on November 23rd 2018 Member

Reported in https://forum.matomo.org/t/no-longer-logging-vists-piwik-php-called/29700/3

We can see in the tracker debug output that the Visit insertion seems to have occured, but actually failed:


DEBUG: array (
DEBUG:   'idvisitor' => '1db1ff046f15737f',
DEBUG:   'config_id' => '5c6948980cd42fd4',
DEBUG:   'location_ip' => 'xxx.xxx.xx.0',
DEBUG:   'idsite' => 1,
DEBUG:   'visit_first_action_time' => '2018-09-05 19:48:42',
[....]
DEBUG: )
DEBUG: Executing Piwik\Plugins\CoreHome\Tracker\VisitRequestProcessor::recordLogs()...
DEBUG: Executing Piwik\Plugins\Actions\Tracker\ActionsRequestProcessor::recordLogs()...
DEBUG: Inserted new action:
DEBUG: array (
DEBUG:   'idvisit' => 0,
DEBUG:   'idsite' => 1,
DEBUG:   'idvisitor' => '1db1ff046f15737f',

Here we see that 'idvisit' => 0, so it seems the log_visit insert went wrong? it is reproducible for this user and hasn't worked since months ago. Maybe the problem is a corrupted log_visit table but it could be anything really..

Suggested steps:

  • In the tracker debug log, let's add at the end the output of SHOW WARNINGS query so we can maybe learn about some hidden problems
  • maybe we need to double check in the code that we catch all possible errors/warnings from MySQL inserts during tracker
  • in the tracker code could we add a check if idvisit == 0 then we can exit with an error and not record the data? this way it's more likely these problems will be detected.
  • what do you think?
@tyler71 commented on November 24th 2018

Posted as requested from forum.

core/Profiler.php was patched and debug set to 1

Which DB Driver do you use (PDO or MYSQLI?)?

adapter = "MYSQLI"

Yes it is still occurring in 3.7.0.

With your patch I did not see any errors after specifically "Show warnings (SQL)" but here is the result

DEBUG: Debug enabled - Input parameters:
DEBUG: array (
DEBUG:   'action_name' => '',
DEBUG:   'idsite' => '1',
DEBUG:   'rec' => '1',
DEBUG:   'r' => '158468',
DEBUG:   'h' => '19',
DEBUG:   'm' => '9',
DEBUG:   's' => '18',
DEBUG:   'url' => 'https://www.mydomain.org/',
DEBUG:   '_id' => '60b9440dabe74582',
DEBUG:   '_idts' => '1543028958',
DEBUG:   '_idvc' => '1',
DEBUG:   '_idn' => '0',
DEBUG:   '_refts' => '0',
DEBUG:   '_viewts' => '1543028958',
DEBUG:   'cs' => 'windows-1252',
DEBUG:   'send_image' => '1',
DEBUG:   'pdf' => '0',
DEBUG:   'qt' => '0',
DEBUG:   'realp' => '0',
DEBUG:   'wma' => '0',
DEBUG:   'dir' => '0',
DEBUG:   'fla' => '1',
DEBUG:   'java' => '0',
DEBUG:   'gears' => '0',
DEBUG:   'ag' => '0',
DEBUG:   'cookie' => '1',
DEBUG:   'res' => '1920x1080',
DEBUG:   'gt_ms' => '48',
DEBUG:   'pv_id' => 'Xs27md',
DEBUG: )
DEBUG: Current datetime: 2018-11-24 03:10:05
DEBUG: Executing Piwik\Plugins\CoreHome\Tracker\VisitRequestProcessor::manipulateRequest()...
DEBUG: Executing Piwik\Plugins\IntranetMeasurable\Tracker\RequestProcessor::manipulateRequest()...
DEBUG: Executing Piwik\Plugins\Actions\Tracker\ActionsRequestProcessor::manipulateRequest()...
DEBUG: Executing Piwik\Plugins\Goals\Tracker\GoalsRequestProcessor::manipulateRequest()...
DEBUG: Executing Piwik\Plugins\SitesManager\Tracker\SitesManagerRequestProcessor::manipulateRequest()...
DEBUG: Executing Piwik\Plugins\PrivacyManager\Tracker\RequestProcessor::manipulateRequest()...
DEBUG: Executing Piwik\Plugins\Heartbeat\Tracker\PingRequestProcessor::manipulateRequest()...
DEBUG: Executing Piwik\Plugins\CoreHome\Tracker\VisitRequestProcessor::processRequestParams()...
DEBUG: DoNotTrack header not found
DEBUG: Matching visitors with: visitorId=60b9440dabe74582 OR configId=e8649634bc0fc22b
DEBUG: The visitor was not matched with an existing visitor...
DEBUG: Executing Piwik\Plugins\IntranetMeasurable\Tracker\RequestProcessor::processRequestParams()...
DEBUG: Executing Piwik\Plugins\Actions\Tracker\ActionsRequestProcessor::processRequestParams()...
DEBUG: (this is not a Site Search request)
DEBUG: Excluding parameters "fepaction,gclid,fb_xd_fragment,fb_comment_id,phpsessid,jsessionid,sessionid,aspsessionid,doing_wp_cron,sid,pk_vid,pk_cpn,pk_campaign,piwik_campaign,utm_campaign,utm_source,utm_medium,pk_kwd,pk_keyword,piwik_kwd,utm_term" from URL
DEBUG: Action is a PAGE_URL,
DEBUG:                 Action name =  ,
DEBUG:                 Action URL = https://www.mydomain.org/
DEBUG: Executing Piwik\Plugins\Goals\Tracker\GoalsRequestProcessor::processRequestParams()...
DEBUG: Executing Piwik\Plugins\SitesManager\Tracker\SitesManagerRequestProcessor::processRequestParams()...
DEBUG: Executing Piwik\Plugins\PrivacyManager\Tracker\RequestProcessor::processRequestParams()...
DEBUG: Executing Piwik\Plugins\Heartbeat\Tracker\PingRequestProcessor::processRequestParams()...
DEBUG: Executing Piwik\Plugins\CoreHome\Tracker\VisitRequestProcessor::afterRequestProcessed()...
DEBUG: Visitor IP (was: 168.xxx.xx.33) has been anonymized: 168.xxx.xx.0
DEBUG: Executing Piwik\Plugins\IntranetMeasurable\Tracker\RequestProcessor::afterRequestProcessed()...
DEBUG: Executing Piwik\Plugins\Actions\Tracker\ActionsRequestProcessor::afterRequestProcessed()...
DEBUG: Executing Piwik\Plugins\Goals\Tracker\GoalsRequestProcessor::afterRequestProcessed()...
DEBUG: Executing Piwik\Plugins\SitesManager\Tracker\SitesManagerRequestProcessor::afterRequestProcessed()...
DEBUG: Executing Piwik\Plugins\PrivacyManager\Tracker\RequestProcessor::afterRequestProcessed()...
DEBUG: Executing Piwik\Plugins\Heartbeat\Tracker\PingRequestProcessor::afterRequestProcessed()...
DEBUG: New Visit (IP = xxx.xxx.xx.0)
DEBUG: Following dimensions have been collected from plugins: idsite, user_id, visit_first_action_time, visit_first_action_time, visit_goal_buyer, visit_goal_converted, idvisit, location_ip, visit_last_action_time, visit_last_action_time, visit_last_action_time, visit_last_action_time, visit_last_action_time, visit_last_action_time, visit_last_action_time, visit_last_action_time, visit_last_action_time, visit_last_action_time, visit_last_action_time, visitor_days_since_first, visitor_days_since_order, idvisitor, visitor_returning, visitor_count_visits, visit_entry_idaction_name, visit_entry_idaction_url, visit_exit_idaction_name, visit_exit_idaction_url, visit_total_actions, visit_total_interactions, visit_total_searches, , referer_keyword, referer_name, referer_type, referer_url, , location_browser_lang, config_browser_engine, config_browser_name, config_browser_version, config_device_brand, config_device_model, config_device_type, config_os, config_os_version, visitor_localtime, visitor_localtime, visitor_days_since_last, config_resolution, config_cookie, config_director, config_flash, config_gears, config_java, config_pdf, config_quicktime, config_realplayer, config_silverlight, config_windowsmedia, , visit_total_time, location_city, location_country, location_latitude, location_longitude, location_provider, location_region, location_provider
DEBUG: GEO: Found IP xxx.xxx.xx.33 location (provider 'geoip_php'): array (
DEBUG:   'country_code' => 'US',
DEBUG:   'region_code' => 'CA',
DEBUG:   'city_name' => 'Los Angeles',
DEBUG:   'area_code' => 213,
DEBUG:   'lat' => xx.058,
DEBUG:   'long' => -xx.27800000000001,
DEBUG:   'postal_code' => '90017',
DEBUG:   'continent_code' => 'amn',
DEBUG:   'continent_name' => 'Intl_Continent_amn',
DEBUG:   'country_name' => 'Unknown',
DEBUG:   'region_name' => 'California',
DEBUG: )
DEBUG: array (
DEBUG:   'idvisitor' => '60b9440dabe74582',
DEBUG:   'config_id' => 'e8649634bc0fc22b',
DEBUG:   'location_ip' => 'xxx.xxx.xx.0',
DEBUG:   'idsite' => 1,
DEBUG:   'visit_first_action_time' => '2018-11-24 03:10:05',
DEBUG:   'visit_goal_buyer' => 0,
DEBUG:   'visit_goal_converted' => 0,
DEBUG:   'visit_last_action_time' => '2018-11-24 03:10:05',
DEBUG:   'visitor_days_since_first' => '0',
DEBUG:   'visitor_days_since_order' => 0,
DEBUG:   'visitor_returning' => 0,
DEBUG:   'visitor_count_visits' => 1,
DEBUG:   'visit_entry_idaction_name' => 0,
DEBUG:   'visit_entry_idaction_url' => 440,
DEBUG:   'visit_exit_idaction_name' => 0,
DEBUG:   'visit_exit_idaction_url' => 440,
DEBUG:   'visit_total_actions' => 1,
DEBUG:   'visit_total_interactions' => 1,
DEBUG:   'visit_total_searches' => 0,
DEBUG:   'referer_keyword' => NULL,
DEBUG:   'referer_name' => NULL,
DEBUG:   'referer_type' => 1,
DEBUG:   'referer_url' => '',
DEBUG:   'location_browser_lang' => 'en-us',
DEBUG:   'config_browser_engine' => 'Gecko',
DEBUG:   'config_browser_name' => 'FF',
DEBUG:   'config_browser_version' => '63.0',
DEBUG:   'config_device_brand' => '',
DEBUG:   'config_device_model' => 'generic desktop',
DEBUG:   'config_device_type' => 0,
DEBUG:   'config_os' => 'UBT',
DEBUG:   'config_os_version' => '',
DEBUG:   'visitor_localtime' => '19:09:18',
DEBUG:   'visitor_days_since_last' => '0',
DEBUG:   'config_resolution' => '1920x1080',
DEBUG:   'config_cookie' => 1,
DEBUG:   'config_director' => 0,
DEBUG:   'config_flash' => 1,
DEBUG:   'config_gears' => 0,
DEBUG:   'config_java' => 0,
DEBUG:   'config_pdf' => 0,
DEBUG:   'config_quicktime' => 0,
DEBUG:   'config_realplayer' => 0,
DEBUG:   'config_silverlight' => 0,
DEBUG:   'config_windowsmedia' => 0,
DEBUG:   'visit_total_time' => 0,
DEBUG:   'location_city' => 'Los Angeles',
DEBUG:   'location_country' => 'us',
DEBUG:   'location_latitude' => '34.058',
DEBUG:   'location_longitude' => '-118.278',
DEBUG:   'location_region' => 'CA',
DEBUG:   'location_provider' => 'Ip',
DEBUG: )
DEBUG: Executing Piwik\Plugins\CoreHome\Tracker\VisitRequestProcessor::recordLogs()...
DEBUG: Executing Piwik\Plugins\IntranetMeasurable\Tracker\RequestProcessor::recordLogs()...
DEBUG: Executing Piwik\Plugins\Actions\Tracker\ActionsRequestProcessor::recordLogs()...
DEBUG: Inserted new action:
DEBUG: array (
DEBUG:   'idvisit' => 0,
DEBUG:   'idsite' => 1,
DEBUG:   'idvisitor' => '60b9440dabe74582',
DEBUG:   'idaction_url' => '440',
DEBUG:   'idaction_url_ref' => 0,
DEBUG:   'idaction_name_ref' => 0,
DEBUG:   'server_time' => '2018-11-24 03:10:05',
DEBUG:   'idpageview' => 'Xs27md',
DEBUG:   'interaction_position' => 1,
DEBUG:   'time_spent_ref_action' => 0,
DEBUG:   'idaction_name' => 0,
DEBUG:   'custom_float' => '48',
DEBUG:   'idlink_va' => 316964,
DEBUG: )
DEBUG: Executing Piwik\Plugins\Goals\Tracker\GoalsRequestProcessor::recordLogs()...
DEBUG: Executing Piwik\Plugins\SitesManager\Tracker\SitesManagerRequestProcessor::recordLogs()...
DEBUG: Executing Piwik\Plugins\PrivacyManager\Tracker\RequestProcessor::recordLogs()...
DEBUG: Executing Piwik\Plugins\Heartbeat\Tracker\PingRequestProcessor::recordLogs()...
DEBUG: -> Scheduled tasks not running in Tracker: Browser archiving is disabled.
DEBUG: Nothing to notice => default behaviour
DEBUG: End of the page.
DEBUG: Show warnings (SQL):
DEBUG: array (
)
DEBUG: <hr /><strong>Breakdown by query</strong><br/>Executed <b>9</b> times in <b>3.1ms</b>  (average = <b>0.3ms</b>) <pre>  connect</pre>Executed <b>4</b> times in <b>2.4ms</b>  (average = <b>0.6ms</b>) <pre>  SELECT option_value, option_name FROM `piwik_option` WHERE autoload = 1</pre>Executed <b>1</b> time in <b>0.8ms</b>  <pre>  SELECT MIN(idaction) as idaction, type, name FROM piwik_log_action WHERE ( hash = CRC32('mydomain.org/') AND name = 'mydomain.org/' AND type = '1' ) GROUP BY type, hash, name</pre>Executed <b>1</b> time in <b>0.8ms</b>  <pre> SELECT MIN(idaction) as idaction, type, name FROM piwik_log_action WHERE ( hash = CRC32('2015 Kindle Paperwhite - LED Strain') AND name = '2015 Kindle Paperwhite - LED Strain' AND type = '4' ) OR ( hash = CRC32('ledstrain.org/d/56-2015-kindle-paperwhite') AND name = 'ledstrain.org/d/56-2015-kindle-paperwhite' AND type = '1' ) GROUP BY type, hash, name</pre>Executed <b>1</b> time in <b>0.8ms</b>  <pre>  SELECT option_value FROM `piwik_option` WHERE option_name = 'SearchEngineDefinitions'</pre>Executed <b>1</b> time in <b>0.8ms</b>  <pre>  SHOW COLUMNS FROM `piwik_log_visit`</pre>Executed <b>1</b> time in <b>0.7ms</b>  <pre>  SELECT MIN(idaction) as idaction, type, name FROM piwik_log_action WHERE ( hash = CRC32('Agency Complaints – Global Adoption News') AND name = 'Agency Complaints – Global Adoption News' AND type = '4' ) OR ( hash = CRC32('adoptionland.org/category/agency_complaints/') AND name = 'adoptionland.org/category/agency_complaints/' AND type = '1' ) GROUP BY type, hash, name</pre>Executed <b>1</b> time in <b>0.7ms</b>  <pre>  SHOW COLUMNS FROM `piwik_log_link_visit_action`</pre>Executed <b>2</b> times in <b>0.6ms</b>  (average = <b>0.3ms</b>) <pre>  SELECT option_name, option_value FROM `piwik_option` WHERE option_name LIKE 'report_to_invalidate_1_2018-11-23%'</pre>Executed <b>1</b> time in <b>0.6ms</b>  <pre> SHOW COLUMNS FROM `piwik_log_conversion`</pre>Executed <b>2</b> times in <b>0.6ms</b>  (average = <b>0.3ms</b>) <pre> SELECT url FROM piwik_site_url WHERE idsite = '4'</pre>Executed <b>1</b> time in <b>0.6ms</b>  <pre>  INSERT INTO `piwik_option` (option_name, option_value, autoload) VALUES ('report_to_invalidate_4_2018-11-23_2593', '1', '0') </pre>Executed <b>1</b> time in <b>0.5ms</b>  <pre>  INSERT INTO `piwik_option` (option_name, option_value, autoload) VALUES ('report_to_invalidate_1_2018-11-23_4830', '1', '0') </pre>Executed <b>4</b> times in <b>0.5ms</b>  (average = <b>0.1ms</b>) <pre>  SELECT option_value FROM `piwik_option` WHERE option_name = 'SitesManager_SearchCategoryParameters'</pre>Executed <b>4</b> times in <b>0.5ms</b>  (average = <b>0.1ms</b>) <pre>  SELECT option_value FROM `piwik_option` WHERE option_name = 'SitesManager_ExcludedUserAgentsGlobal'</pre>Executed <b>4</b> times in <b>0.5ms</b>  (average = <b>0.1ms</b>) <pre>  SELECT option_value FROM `piwik_option` WHERE option_name = 'SitesManager_SearchKeywordParameters'</pre>Executed <b>4</b> times in <b>0.5ms</b>  (average = <b>0.1ms</b>) <pre> SELECT option_value FROM `piwik_option` WHERE option_name = 'SitesManager_ExcludedIpsGlobal'</pre>Executed <b>4</b> times in <b>0.5ms</b>  (average = <b>0.1ms</b>) <pre> SELECT option_value FROM `piwik_option` WHERE option_name = 'SitesManager_KeepURLFragmentsGlobal'</pre>Executed <b>4</b> times in <b>0.4ms</b>  (average = <b>0.1ms</b>) <pre>  SELECT option_value FROM `piwik_option` WHERE option_name = 'SitesManager_ExcludedQueryParameters'</pre>Executed <b>4</b> times in <b>0.4ms</b>  (average = <b>0.1ms</b>) <pre> SELECT option_value FROM `piwik_option` WHERE option_name = 'SitesManager_EnableSiteSpecificUserAgentExclude'</pre>Executed <b>4</b> times in <b>0.4ms</b>  (average = <b>0.1ms</b>) <pre>  SELECT MIN(idaction) as idaction, type, name FROM piwik_log_action WHERE ( hash = CRC32('Global Adoption News – Adoptionland') AND name = 'Global Adoption News – Adoptionland' AND type = '4' ) OR ( hash = CRC32('adoptionland.org/') AND name = 'adoptionland.org/' AND type = '1' ) GROUP BY type, hash, name</pre>Executed <b>2</b> times in <b>0.4ms</b>  (average = <b>0.2ms</b>) <pre>  SELECT * FROM piwik_goal WHERE idsite IN (1) AND deleted = 0</pre>Executed <b>4</b> times in <b>0.3ms</b>  (average = <b>0.1ms</b>) <pre> SELECT * FROM piwik_site WHERE idsite = '1'</pre>Executed <b>2</b> times in <b>0.3ms</b>  (average = <b>0.2ms</b>) <pre>  UPDATE `piwik_option` SET option_value = '1', autoload = '0' WHERE option_name = 'report_to_invalidate_4_2018-11-23_2593'</pre>Executed <b>1</b> time in <b>0.3ms</b>  <pre>  SELECT option_value FROM `piwik_option` WHERE option_name = 'lastTrackerCronRun'</pre>Executed <b>1</b> time in <b>0.3ms</b>  <pre> SELECT option_name, option_value FROM `piwik_option` WHERE option_name LIKE 'report_to_invalidate_4_2018-11-23%'</pre>Executed <b>2</b> times in <b>0.3ms</b>  (average = <b>0.2ms</b>) <pre> SELECT * FROM piwik_goal WHERE idsite IN (4) AND deleted = 0</pre>Executed <b>1</b> time in <b>0.3ms</b>  <pre> SELECT option_value FROM `piwik_option` WHERE option_name = 'usercountry.location_provider'</pre>Executed <b>4</b> times in <b>0.2ms</b>  (average = <b>0.1ms</b>) <pre>  SELECT * FROM piwik_site WHERE idsite = '4'</pre>Executed <b>1</b> time in <b>0.2ms</b>  <pre>SELECT option_value FROM `piwik_option` WHERE option_name = 'PrivacyManager.useAnonymizedIpForVisitEnrichment'</pre>Executed <b>2</b> times in <b>0.2ms</b>  (average = <b>0.1ms</b>) <pre> SELECT login FROM piwik_access WHERE idsite = '1' AND access = 'admin'</pre>Executed <b>1</b> time in <b>0.2ms</b>  <pre> SELECT option_value FROM `piwik_option` WHERE option_name = 'PrivacyManager.ipAnonymizerEnabled'</pre>Executed <b>1</b> time in <b>0.2ms</b>  <pre> SELECT option_value FROM `piwik_option` WHERE option_name = 'PrivacyManager.ipAddressMaskLength'</pre>Executed <b>1</b> time in <b>0.1ms</b>  <pre> SELECT option_value FROM `piwik_option` WHERE option_name = 'PrivacyManager.anonymizeUserId'</pre>Executed <b>2</b> times in <b>0.1ms</b>  (average = <b>0.1ms</b>) <pre> SELECT url FROM piwik_site_url WHERE idsite = '1'</pre>Executed <b>1</b> time in <b>0.1ms</b>  <pre>  SELECT option_value FROM `piwik_option` WHERE option_name = 'PrivacyManager.doNotTrackEnabled'</pre>Executed <b>1</b> time in <b>0.1ms</b>  <pre> SELECT option_value FROM `piwik_option` WHERE option_name = 'PrivacyManager.anonymizeOrderId'</pre>Executed <b>2</b> times in <b>0.1ms</b>  (average = <b>0.1ms</b>) <pre>  SELECT login FROM piwik_access WHERE idsite = '1' AND access = 'write'</pre>Executed <b>2</b> times in <b>0.1ms</b>  (average = <b>0.1ms</b>) <pre> SELECT login FROM piwik_access WHERE idsite = '4' AND access = 'admin'</pre>Executed <b>2</b> times in <b>0.1ms</b>  (average = <b>0.1ms</b>) <pre> SELECT * FROM piwik_user WHERE login IN ('applefire') ORDER BY login ASC</pre>Executed <b>2</b> times in <b>0.1ms</b>  (average = <b>0.1ms</b>) <pre> SELECT login FROM piwik_access WHERE idsite = '4' AND access = 'write'</pre>
DEBUG: array (
DEBUG:   'PIWIK_SESSID' => 'c8pmgd1b3p6qoq2j6jhsak6f43',
DEBUG: )
DEBUG: Time elapsed: 0.076s
@tsteur commented on November 25th 2018 Member

Show warnings would need to be executed after each query or not? Not just at the end...

Powered by GitHub Issue Mirror