@narfk opened this Issue on December 2nd 2020

with the default Tracking Code (Backend) i got this error with the new 4.0.0 Version.
In 3.14.1 this works fine.

<script type="text/javascript">
  var _paq = window._paq = window._paq || [];
  _paq.push(['trackPageView']);
  _paq.push(['enableLinkTracking']);
  (function() {
    var u="https://statistics.domain.dd/piwik/";
    _paq.push(['setTrackerUrl', u+'matomo.php']);
    _paq.push(['setSiteId', '2']);
    var d=document, g=d.createElement('script'), s=d.getElementsByTagName('script')[0];
    g.type='text/javascript'; g.async=true; g.src=u+'matomo.js'; s.parentNode.insertBefore(g,s);
  })();
</script>

Header
Status400
Bad Request
VersionHTTP/1.1
Transferred1.13 KB (410 B size)
Referrer Policystrict-origin-when-cross-origin

While is was inspecting matomo.js i found setRequestMethod.
So i tried this.

<script type="text/javascript">
  var _paq = window._paq = window._paq || [];
  _paq.push(['setRequestMethod', 'GET']);
  _paq.push(['trackPageView']);
  _paq.push(['enableLinkTracking']);
  (function() {
    var u="https://statistics.domain.dd/piwik/";
    _paq.push(['setTrackerUrl', u+'matomo.php']);
    _paq.push(['setSiteId', '2']);
    var d=document, g=d.createElement('script'), s=d.getElementsByTagName('script')[0];
    g.type='text/javascript'; g.async=true; g.src=u+'matomo.js'; s.parentNode.insertBefore(g,s);
  })();
</script>

without any results.
Its still a POST and i got a bad request.

The URL in the networkinspector looks weird for a POST
https://statistics.domain.dd/piwik/matomo.phhp?action_name=title&idsite=2&rec=1&r=944278&h=14&m=29&s=34&url=...

example

Any advices?

@sgiehl commented on December 2nd 2020 Member

I don't think that has something to do with the POST request method. Matomo tries to use sendBeacon if that is available, which uses POST by default.

Maybe try enabling the debugging for tracking by setting

[Tracker]
debug = 1

in your config.ini.php

After that a tracking request should have debugging details as response. Maybe that helps to identify the problem.

@tsteur commented on December 2nd 2020 Member

@narfk you may want to try _paq.push(['disableAlwaysUseSendBeacon']) if send beacon is causing any issues.

Meanwhile I have created a PR to automatically disable send beacon when forcing GET request method.

The POST URL by default includes all URL parameters so if there's a redirect then the parameters don't get lost. This is to avoid basically a regression as usually all webservers support POST.

By forcing POST request method those URL parameters would be gone and then they would be sent as a proper POST request.

@narfk commented on December 3rd 2020

_paq.push(['disableAlwaysUseSendBeacon']) forces a GET request. but with the same result => 400 bad request.

[Tracker]
debug = 1

I got this error with in Debugmode (_Error query: SQLSTATE[42S22]: Column not found: 1054 Unknown column 'last_idlink_va' in 'field list'). It doesn't matter if this is a GET or POST request

`[2020-12-03 06:10:15] piwik.DEBUG: Debug enabled - Input parameters: array () {"params":"array (...)"} {"class":"Piwik\\Tracker","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Current datetime: 2020-12-03 06:10:16 {"date":"2020-12-03 06:10:16"} {"class":"Piwik\\Tracker","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Website * tracker cache was re-created. [] {"class":"Piwik\\Tracker\\Cache","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Executing Piwik\Plugins\CoreHome\Tracker\VisitRequestProcessor::manipulateRequest()... [] {"class":"Piwik\\Common","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Executing Piwik\Plugins\Actions\Tracker\ActionsRequestProcessor::manipulateRequest()... [] {"class":"Piwik\\Common","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Executing Piwik\Plugins\Goals\Tracker\GoalsRequestProcessor::manipulateRequest()... [] {"class":"Piwik\\Common","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Executing Piwik\Plugins\Ecommerce\Tracker\EcommerceRequestProcessor::manipulateRequest()... [] {"class":"Piwik\\Common","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Executing Piwik\Plugins\SitesManager\Tracker\SitesManagerRequestProcessor::manipulateRequest()... [] {"class":"Piwik\\Common","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Executing Piwik\Plugins\PrivacyManager\Tracker\RequestProcessor::manipulateRequest()... [] {"class":"Piwik\\Common","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: General tracker cache was re-created. [] {"class":"PrivacyManager","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Executing Piwik\Plugins\Heartbeat\Tracker\PingRequestProcessor::manipulateRequest()... [] {"class":"Piwik\\Common","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Executing Piwik\Plugins\PagePerformance\Tracker\PerformanceDataProcessor::manipulateRequest()... [] {"class":"Piwik\\Common","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Executing Piwik\Plugins\CustomDimensions\Tracker\CustomDimensionsRequestProcessor::manipulateRequest()... [] {"class":"Piwik\\Common","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Executing Piwik\Plugins\CustomVariables\Tracker\CustomVariablesRequestProcessor::manipulateRequest()... [] {"class":"Piwik\\Common","request_id":"9d5f2"}

[2020-12-03 06:10:16] piwik.DEBUG: Executing Piwik\Plugins\CoreHome\Tracker\VisitRequestProcessor::processRequestParams()... [] {"class":"Piwik\\Common","request_id":"9d5f2"}

[2020-12-03 06:10:17] piwik.DEBUG: DoNotTrack support is not enabled, skip check [] {"class":"PrivacyManager","request_id":"9d5f2"}

[2020-12-03 06:10:17] piwik.DEBUG: Matching visitors with: visitorId=xxx OR configId=8d8eb1f8c39499b2 [] {"class":"CoreHome","request_id":"9d5f2"}

[2020-12-03 06:10:17] piwik.DEBUG: Tracker encountered an exception: {ex} null {"class":"Piwik\\Tracker","request_id":"9d5f2"}

[2020-12-03 06:10:17] piwik.ERROR: Exception: /srv/www/DocRoot/piwik/core/Tracker/Db/Pdo/Mysql.php(238): Error query: SQLSTATE[42S22]: Column not found: 1054 Unknown column 'last_idlink_va' in 'field list' In query: SELECT visit_last_action_time, visit_first_action_time, idvisitor, idvisit, user_id, visit_exit_idaction_url, visit_exit_idaction_name, visitor_returning, visitor_seconds_since_first, visitor_seconds_since_order, visitor_count_visits, visit_goal_buyer, location_country, location_region, location_city, location_latitude, location_longitude, referer_name, referer_keyword, referer_type, idsite, profilable, visit_entry_idaction_url, visit_total_actions, visit_total_interactions, visit_total_searches, referer_url, config_browser_name, config_client_type, config_device_brand, config_device_model, config_device_type, visit_total_events, visit_total_time, location_ip, location_browser_lang, last_idlink_va, custom_var_k1, custom_var_v1, custom_var_k2, custom_var_v2, custom_var_k3, custom_var_v3, custom_var_k4, custom_var_v4, custom_var_k5, custom_var_v5  FROM piwik_log_visit FORCE INDEX (index_idsite_idvisitor)  WHERE idsite = ? AND visit_last_action_time <= ? AND idvisitor = ?                 ORDER BY visit_last_action_time DESC                 LIMIT 1 Parameters: array (   0 => *,   1 => '2020-12-03 06:40:16',   2 => '9ù.xP£', ) Error query: SQLSTATE[42S22]: Column not found: 1054 Unknown column 'last_idlink_va' in 'field list' In query: SELECT visit_last_action_time, visit_first_action_time, idvisitor, idvisit, user_id, visit_exit_idaction_url, visit_exit_idaction_name, visitor_returning, visitor_seconds_since_first, visitor_seconds_since_order, visitor_count_visits, visit_goal_buyer, location_country, location_region, location_city, location_latitude, location_longitude, referer_name, referer_keyword, referer_type, idsite, profilable, visit_entry_idaction_url, visit_total_actions, visit_total_interactions, visit_total_searches, referer_url, config_browser_name, config_client_type, config_device_brand, config_device_model, config_device_type, visit_total_events, visit_total_time, location_ip, location_browser_lang, last_idlink_va, custom_var_k1, custom_var_v1, custom_var_k2, custom_var_v2, custom_var_k3, custom_var_v3, custom_var_k4, custom_var_v4, custom_var_k5, custom_var_v5  FROM piwik_log_visit FORCE INDEX (index_idsite_idvisitor)  WHERE idsite = ? AND visit_last_action_time <= ? AND idvisitor = ?                 ORDER BY visit_last_action_time DESC                 LIMIT 1 Parameters: array (   0 => *,   1 => '2020-12-03 06:40:16',   2 => '9ù.xP£', ) <a href='/0'>#0</a> /srv/www/DocRoot/piwik/core/Tracker/Db/Pdo/Mysql.php(197): Piwik\Tracker\Db\Pdo\Mysql->query('SELECT visit_la...', Array) <a href='/1'>#1</a> /srv/www/DocRoot/piwik/core/Tracker/Model.php(458): Piwik\Tracker\Db\Pdo\Mysql->fetch('SELECT visit_la...', Array) <a href='/2'>#2</a> /srv/www/DocRoot/piwik/core/Tracker/Model.php(440): Piwik\Tracker\Model->fetchVisitor('SELECT visit_la...', 'FROM piwik_log_...', 'idsite = ? AND ...', Array) <a href='/3'>#3</a> /srv/www/DocRoot/piwik/core/Tracker/Model.php(401): Piwik\Tracker\Model->findVisitorByVisitorId('9\x17\xF9.xP\xA3\x15', 'SELECT visit_la...', 'FROM piwik_log_...', 'idsite = ? AND ...', Array) <a href='/4'>#4</a> /srv/www/DocRoot/piwik/core/Tracker/VisitorRecognizer.php(107): Piwik\Tracker\Model->findVisitor(*, '\x8D\x8E\xB1\xF8\xC3\x94\x99\xB2', '9\x17\xF9.xP\xA3\x15', false, Array, false, true, '2020-12-03 05:4...', '2020-12-03 06:4...') <a href='/5'>#5</a> /srv/www/DocRoot/piwik/plugins/CoreHome/Tracker/VisitRequestProcessor.php(118): Piwik\Tracker\VisitorRecognizer->findKnownVisitor('\x8D\x8E\xB1\xF8\xC3\x94\x99\xB2', Object(Piwik\Tracker\Visit\VisitProperties), Object(Piwik\Tracker\Request)) <a href='/6'>#6</a> /srv/www/DocRoot/piwik/core/Tracker/Visit.php(163): Piwik\Plugins\CoreHome\Tracker\VisitRequestProcessor->processRequestParams(Object(Piwik\Tracker\Visit\VisitProperties), Object(Piwik\Tracker\Request)) <a href='/7'>#7</a> /srv/www/DocRoot/piwik/core/Tracker.php(160): Piwik\Tracker\Visit->handle() <a href='/8'>#8</a> /srv/www/DocRoot/piwik/core/Tracker/Handler.php(55): Piwik\Tracker->trackRequest(Object(Piwik\Tracker\Request)) <a href='/9'>#9</a> /srv/www/DocRoot/piwik/core/Tracker.php(140): Piwik\Tracker\Handler->process(Object(Piwik\Tracker), Object(Piwik\Tracker\RequestSet)) <a href='/10'>#10</a> /srv/www/DocRoot/piwik/core/Tracker.php(115): Piwik\Tracker->track(Object(Piwik\Tracker\Handler), Object(Piwik\Tracker\RequestSet)) <a href='/11'>#11</a> /srv/www/DocRoot/piwik/piwik.php(73): Piwik\Tracker->main(Object(Piwik\Tracker\Handler), Object(Piwik\Tracker\RequestSet)) <a href='/12'>#12</a> /srv/www/DocRoot/piwik/matomo.php(13): include('/srv/www/DocRoo...') <a href='/13'>#13</a> {main} null {"class":"Piwik\\Tracker\\Handler","request_id":"9d5f2"}

while I was viewing at the code, i found some references in the CustomDimension plugin.
CustomDimenstion is the troublemaker. with deactivatet plugin the request works fine.

In my case this CustomDimenstion table looks like:

piwik_custom_dimensions (
idcustomdimension bigint(20) unsigned NOT NULL,
idsite bigint(20) unsigned NOT NULL,
name varchar(100) NOT NULL,
index smallint(5) unsigned NOT NULL,
scope varchar(10) NOT NULL,
active tinyint(3) unsigned NOT NULL DEFAULT '0',
extractions mediumtext NOT NULL,
case_sensitive tinyint(3) unsigned NOT NULL DEFAULT '1',
PRIMARY KEY (idcustomdimension,idsite),
UNIQUE KEY uniq_hash (idsite,scope,index)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;

In my opinion the update script for 4.0.0 is wrong, not all tables/columns are created

@sgiehl commented on December 3rd 2020 Member

@narfk Try removing the CustomDimensions plugin from config.ini.php. There should be an entry in the PluginsInstalled and Plugins section.
That should trigger the install of the plugin again, which should create the missing columns

@narfk commented on December 3rd 2020

@sgiehl This works in my Testenvironment. But There should be a dbUpdate-Script. I have a multiserver environment and this is not how it work. I cannot do this steps on every host.

@sgiehl commented on December 3rd 2020 Member

Did you have the CustomDimensions plugin installed & activated before you did the update?

@narfk commented on December 3rd 2020

Nope. But i can remember that this plugin cames with the 4.0.0 db update script.
After Installing 4.0.0, CustomDimension was active by default.

@sgiehl commented on December 3rd 2020 Member

Ok. That might be the reason. Seems the update might not trigger the plugin install if the plugin was not there before maybe.
Will investigate that.

@narfk commented on December 3rd 2020

Thanx!

@sgiehl commented on December 3rd 2020 Member

Just installed a 3.14.1 and did an update to 4.0.3 using the UI updater. Custom Dimensions did not exist before, but was created with the update. The plugin was installed correctly and everything looks fine afterwards.

Did you do the update in the UI or using console command?

@narfk commented on December 3rd 2020

I was using the console command.

@sgiehl commented on December 3rd 2020 Member

Ok. did you replace the files manually?

@narfk commented on December 3rd 2020

i was download the zip file with wget. but i created a new /piwik folder (and moved my configs).
the update command tooks arround 5-6 hours (the dbdump i made before was arround 50 gb).

@sgiehl commented on December 3rd 2020 Member

Ok. Will try to reproduce it that way.
Was the CustomDimensions plugin marked as installed in your old config maybe?

@narfk commented on December 3rd 2020

No, it wasn't installed (in PluginDirectory).
Even nothing about it in the config files.

@Findus23 commented on December 3rd 2020 Member
@sgiehl commented on December 3rd 2020 Member

@narfk I'm not able to reproduce that behavior. Did a clean install of 3.14. Reused only the config file with a clean extract of 4.0.3 and ran update on console. All columns are created correctly and everything seems to work.
The only thing I could image is that Matomo somehow considered the plugin as already installed when the update tries to activate it. But not sure how that can happen (unless it's already in config, but not installed)

@tsteur Do you maybe have an idea? Would it maybe make sense to directly trigger installing the plugin maybe?

@narfk commented on December 3rd 2020

@sgiehl i was checking the config files before 4.0.0. nothing about the custom dimension plugin. maybe something happend during the update. at least the workaround (remove plugin, reactive plugin) seems to work. hopefully this won't happen in the live environment.

maybe something for the the system check?

@tsteur commented on December 3rd 2020 Member

Thanks for all the troubleshooting work @narfk we'll probably not add something to the system check there for now as we'd need to put some new code into every plugin exposing what columns they expect to exist etc. I'll keep this open though for now as we might do it in the future.

@ysard commented on December 21st 2020

Hi, same error here from 3.13.x (3.13.3 if I remember correctly) to 4.0.5.

First, just after the installation process (from the website, not from the console), I had errors on the dashboard, related to #16868.
As mentioned in the issue, this was resolved by:
ALTER TABLE log_conversion ADD COLUMN config_browser_name VARCHAR(40) NULL;

But after that PHP started to output a large amount of this error:

2020/12/20 11:19:07 [error] 2623<a href='/2623'>#2623</a>: *196 FastCGI sent in stderr: "PHP message: Error in Matomo (tracker): Error query: preparing query failed: Unknown column 'last_idlink_va' in 'field list' : SELECT visit_last_action_time, visit_first_action_time, idvisitor, idvisit, user_id, visit_exit_idaction_url, visit_exit_idaction_name, visitor_returning, visitor_seconds_since_first, visitor_seconds_since_order, visitor_count_visits, visit_goal_buyer, location_country, location_region, location_city, location_latitude, location_longitude, referer_name, referer_keyword, referer_type, idsite, profilable, visit_entry_idaction_url, visit_total_actions, visit_total_interactions, visit_total_searches, referer_url, config_browser_name, config_client_type, config_device_brand, config_device_model, config_device_type, visit_total_events, visit_total_time, location_ip, location_browser_lang, last_idlink_va FROM piwik_log_visit FORCE INDEX (index_idsite_idvisitor) WHERE idsite = ? AND visit_last_action_time <= ? AND idvisitor = ? ORDER BY visit_last_action_time DES" while reading response header from upstream, client: <client>, server: <domain_name>, request: "POST <url data>"

These errors are gone now by deactivating/reactivating the CustomDimensions plugin, thanks to this issue.

After that, the following missing columns were added in piwik_log_visit :

last_idlink_va  bigint(20) unsigned NULL
custom_dimension_1  varchar(255) NULL
custom_dimension_2  varchar(255) NULL
custom_dimension_3  varchar(255) NULL
custom_dimension_4  varchar(255) NULL
custom_dimension_5  varchar(255) NULL

Honestly I could not say if this plugin was activated before.
One thing is certain, I had added the support for more than 5 custom variables per query on this installation (FAQ related page: https://matomo.org/faq/how-to/faq_17931/). And by doing the manipulation for CustomDimensions I found that the CustomVariables plugin was disabled, which obviously was not the case before the update.

Before reactivation of CustomVariables:

./console customvariables:info
ERROR [2020-12-21 03:12:26] 20780  Uncaught exception: /var/www/html/piwik/vendor/symfony/console/Symfony/Component/Console/Application.php(501): There are no commands defined in the "customvariables" namespace.
There are no commands defined in the "customvariables" namespace.

  [InvalidArgumentException]                                         
  There are no commands defined in the "customvariables" namespace.

After:

./console customvariables:info

Your Piwik is configured for 6 custom variables.

Hope this helps you...

Powered by GitHub Issue Mirror