Error in the output of archive.php


#1

Hi all,

today (after upgrading to 1.7.1, which went fine) I decided to give archive.php a try (before I was using archive.sh). It went smooth through all the sites , but the following was outputted:

–8<–
[2012-02-27 11:00:34] [9b6526c2] Archived website id = 7, today = XXX visits, XXX API requests, Time elapsed: 39.670s [2/13 done]

PHP Notice: unserialize(): Error at offset 0 of 164 bytes in /html/piwik/misc/cron/archive.php on line 265

Notice: unserialize(): Error at offset 0 of 164 bytes in /html/piwik/misc/cron/archive.php on line 265
PHP Warning: end() expects parameter 1 to be array, boolean given in /html/piwik/misc/cron/archive.php on line 266

Warning: end() expects parameter 1 to be array, boolean given in /html/piwik/misc/cron/archive.php on line 266
PHP Warning: array_sum() expects parameter 1 to be array, boolean given in /html/piwik/misc/cron/archive.php on line 279

Warning: array_sum() expects parameter 1 to be array, boolean given in /html/piwik/misc/cron/archive.php on line 279

[2012-02-27 11:00:38] [9b6526c2] Archived website id = 15, period = day, Time elapsed: 4.862s

–8<–

Please let me know if I should open a bugreport instead of writing it in the forums.

Regards,
Daniele


(Matthieu Aubry) #2

Thanks for the report. I have made a change to improve output logging. please replace archive.php with http://dev.piwik.org/svn/trunk/misc/cron/archive.php and run the script again. it will now output the “invalid response” which should tell you what the problem is?


#3

Hi matt,

thanks for the updated script. Tonight the archiving went well (with the old script). I updated the archive.php and will report back if anything goes wrong again.

Thanks again,
Daniele


#4

Hi.

I have a similar problem with the archive.php script. I updated from 1.6 to 1.7.1 and installed the new cronjob. The first test via console with the user “www-data” did this:


su www-data -c "/usr/bin/php5 /var/www/piwik/html/misc/cron/archive.php --url=http://www.oururl.com/piwik/"

Here is the full output of the script:
---------------------------
INIT
Querying Piwik API at: http://www.oururl.de/piwik/index.php
Running as Super User: admin
Notes
- Reports for today will be processed at most every 3600 seconds. You can change this value in Piwik UI > Settings > General Settings.
- Reports for the current week/month/year will be refreshed at most every 3600 seconds.
- Archiving was last executed without error 1 Stunden 38 Minuten ago
Will process 1 websites with new visits since 1 Stunden 38 Minuten , IDs: 1
---------------------------
START
Starting Piwik reports archiving...
ERROR: Got invalid response from API request: http://www.oururl.de/piwik/blablalba. Response was 'curl_exec: Empty reply from server'
WARNING: Empty or invalid response for website id 1, Time elapsed: 3.992s, skipping
Done archiving!
---------------------------
SUMMARY
Total daily visits archived: 0
Archived today's reports for 0 websites
Archived week/month/year for 0 websites.
Skipped 4 websites: no new visit since the last script execution
Skipped 0 websites day archiving: existing daily reports are less than 3600 seconds old
Skipped 0 websites week/month/year archiving: existing periods reports are less than 3600 seconds old
Total API requests: 0
done: 0/1 0%, 0 v, 0 wtoday, 0 wperiods, 0 req, 3993 ms, 1 errors. eg. 'Got invalid response from API request: http://www.oururl.de/piwik/blablalba. Response was 'curl_exec: Empty reply from server''
Time elapsed: 3.993s
---------------------------
SCHEDULED TASKS
Starting Scheduled tasks...
 No task to run
done
---------------------------
SUMMARY OF ERRORS
Error: Got invalid response from API request: http://www.oururl.de/piwik/blablalba. Response was 'curl_exec: Empty reply from server'
1 total errors during this script execution, please investigate and try and fix these errors
ERROR: 1 total errors during this script execution, please investigate and try and fix these errors. First error was: Got invalid response from API request: http://www.oururl.de/piwik/blablalba. Response was 'curl_exec: Empty reply from server'
PHP Fatal error:  1 total errors during this script execution, please investigate and try and fix these errors. First error was: Got invalid response from API request: http://www.oururl.de/piwik/blablalba. Response was 'curl_exec: Empty reply from server' in /var/www/piwik/html/misc/cron/archive.php on line 519

Fatal error: 1 total errors during this script execution, please investigate and try and fix these errors. First error was: Got invalid response from API request: http://www.oururl.de/piwik/blablalba. Response was 'curl_exec: Empty reply from server' in /var/www/piwik/html/misc/cron/archive.php on line 519

Then I ran the same script with under the root user and it worked fine:


/usr/bin/php5 /var/www/piwik/html/misc/cron/archive.php --url=http://www.oururl.de/piwik/
[2012-03-01 10:44:29] [c5f70920] ---------------------------
[2012-03-01 10:44:29] [c5f70920] INIT
[2012-03-01 10:44:29] [c5f70920] Querying Piwik API at: http://www.oururl.de/piwik/index.php
[2012-03-01 10:44:29] [c5f70920] Running as Super User: admin
[2012-03-01 10:44:29] [c5f70920] Notes
[2012-03-01 10:44:29] [c5f70920] - Reports for today will be processed at most every 3600 seconds. You can change this value in Piwik UI > Settings > General Settings.
[2012-03-01 10:44:29] [c5f70920] - Reports for the current week/month/year will be refreshed at most every 3600 seconds.
[2012-03-01 10:44:29] [c5f70920] - Archiving was last executed without error 1 Stunden 39 Minuten ago
[2012-03-01 10:44:29] [c5f70920] Will process 1 websites with new visits since 1 Stunden 39 Minuten , IDs: 1
[2012-03-01 10:44:29] [c5f70920] ---------------------------
[2012-03-01 10:44:29] [c5f70920] START
[2012-03-01 10:44:29] [c5f70920] Starting Piwik reports archiving...
[2012-03-01 10:44:29] [c5f70920] Archived website id = 1, period = day, Time elapsed: 0.270s
[2012-03-01 10:44:33] [c5f70920] Archived website id = 1, period = week, 516721 visits, Time elapsed: 3.962s
[2012-03-01 10:44:34] [c5f70920] Archived website id = 1, period = month, 516721 visits, Time elapsed: 1.053s
[2012-03-01 10:44:37] [c5f70920] Archived website id = 1, period = year, 516721 visits, Time elapsed: 2.731s
[2012-03-01 10:44:37] [c5f70920] Archived website id = 1, today = 1133 visits, 4 API requests, Time elapsed: 8.017s [1/1 done]
[2012-03-01 10:44:37] [c5f70920] Done archiving!
[2012-03-01 10:44:37] [c5f70920] ---------------------------
[2012-03-01 10:44:37] [c5f70920] SUMMARY
[2012-03-01 10:44:37] [c5f70920] Total daily visits archived: 1133
[2012-03-01 10:44:37] [c5f70920] Archived today's reports for 1 websites
[2012-03-01 10:44:37] [c5f70920] Archived week/month/year for 1 websites.
[2012-03-01 10:44:37] [c5f70920] Skipped 3 websites: no new visit since the last script execution
[2012-03-01 10:44:37] [c5f70920] Skipped 0 websites day archiving: existing daily reports are less than 3600 seconds old
[2012-03-01 10:44:37] [c5f70920] Skipped 0 websites week/month/year archiving: existing periods reports are less than 3600 seconds old
[2012-03-01 10:44:37] [c5f70920] Total API requests: 4
[2012-03-01 10:44:37] [c5f70920] done: 1/1 100%, 1133 v, 1 wtoday, 1 wperiods, 4 req, 8017 ms, no error
[2012-03-01 10:44:37] [c5f70920] Time elapsed: 8.018s
[2012-03-01 10:44:37] [c5f70920] ---------------------------
[2012-03-01 10:44:37] [c5f70920] SCHEDULED TASKS
[2012-03-01 10:44:37] [c5f70920] Starting Scheduled tasks...
[2012-03-01 10:44:37] [c5f70920]  No task to run
[2012-03-01 10:44:37] [c5f70920] done

Any ideas??? My first idea was rights. But /tmp folder has 777. Or does the script use other folders/files??


(Nicolas Cynober) #5

Got the same error here:


PHP Notice:  unserialize(): Error at offset 0 of 170 bytes in /piwik/misc/cron/archive.php on line 265
PHP Warning:  end() expects parameter 1 to be array, boolean given in /piwik/misc/cron/archive.php on line 266
PHP Warning:  array_sum() expects parameter 1 to be array, boolean given in /piwik/misc/cron/archive.php on line 279

I tried to update archive.php from the trunk but I got the following error:


PHP Fatal error:  Call to undefined method Piwik_Config::getInstance() in /piwik/misc/cron/archive.php on line 718


(Matthieu Aubry) #6

Don’t use trunk, use this one: http://dev.piwik.org/trac/export/5927/trunk/misc/cron/archive.php


(Nicolas Cynober) #7

I’m working hard on this issue but I still can’t figuring out what is happening. Any help welcomed.

First I displayed the request error message by modifying archive.php like this:


$response = $this->request($url);
$test_unserialized_response = unserialize($response);

if(empty($response) || (!$test_unserialized_response))  {
       // cancel the succesful run flag
       Piwik_SetOption( $this->lastRunKey($idsite, "day"), 0 );

       $this->log("WARNING: Empty or invalid response for website id $idsite, ".$timerWebsite.", skipping");
       $this->log("URL: ".$url);
       var_dump($response);
       $skipped++;
       continue;
}

Then my archive script logged what I expected, a nasty nginx error:


<html>
<head><title>502 Bad Gateway</title></head>
<body bgcolor="white">
<center><h1>502 Bad Gateway</h1></center>
<hr><center>nginx/1.0.5</center>
</body>
</html>

As I am new at tunning nginx and php-fpm, I reviewed the basic parameters that could create such a problem: max_execution_time and memory limits are far above what I need.

Funny stuff: I don’t have any other errors on the rest of the script. If I ignore the error and I let the archive script continue, I don’t have any errors on week, month and year archiving:


...
[2012-03-11 18:54:51] [29d97439] ---------------------------
[2012-03-11 18:54:51] [29d97439] START
[2012-03-11 18:54:51] [29d97439] Starting Piwik reports archiving...
PHP Notice:  unserialize(): Error at offset 0 of 170 bytes in /piwik/misc/cron/archive.php on line 265
PHP Warning:  end() expects parameter 1 to be array, boolean given in /piwik/misc/cron/archive.php on line 266
PHP Warning:  array_sum() expects parameter 1 to be array, boolean given in /piwik/misc/cron/archive.php on line 279
[2012-03-11 18:58:00] [29d97439] Archived website id = 1, period = day, Time elapsed: 189.153s
[2012-03-11 18:58:43] [29d97439] Archived website id = 1, period = week, 410866 visits, Time elapsed: 43.665s
[2012-03-11 19:03:04] [29d97439] Archived website id = 1, period = month, 1587306 visits, Time elapsed: 260.771s
[2012-03-11 19:05:11] [29d97439] Archived website id = 1, period = year, 8815130 visits, Time elapsed: 126.841s
[2012-03-11 19:05:11] [29d97439] Archived website id = 1, today =  visits, 4 API requests, Time elapsed: 620.433s [1/1 done]
[2012-03-11 19:05:11] [29d97439] Done archiving!
...

In the php-fpm log:


WARNING: [pool www] child 29524 exited on signal 11 (SIGSEGV)

In nginx log:


[error] 26863#0: *1563613 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: [...], server: [...], request: "GET /index.php?module=API&method=VisitsSummary.getVisits&idSite=1&period=day&date=last2&format=php&token_auth=[...]&trigger=archivephp HTTP/1.1", upstream: "fastcgi://unix:/tmp/php5-fpm.sock:", host: [...]

In syslog:


kernel: [12893927.352532] php5-fpm[10685]: segfault at 7f60cff2b809 ip 00000000006b49c9 sp 00007fff9add9440 error 4 in php5-fpm[400000+756000]

Before the crash, the last request I see on mysql side is:


SELECT
log_link_visit_action.custom_var_k5 AS custom_var_k5, log_link_visit_action.custom_var_v5 AS custom_var_v5, ROUND(AVG(log_link_visit_action.custom_var_v2),2) as `27`,
count(distinct log_link_visit_action.idvisit) as `2`,
count(distinct log_link_visit_action.idvisitor) as `1`,
count(*) as `3`
FROM
piwik_log_link_visit_action AS log_link_visit_action
WHERE
log_link_visit_action.server_time >= '2012-03-10 23:00:00'
AND log_link_visit_action.server_time <= '2012-03-11 22:59:59'
AND log_link_visit_action.idsite = '1'
AND log_link_visit_action.custom_var_k5 != ''
GROUP BY
log_link_visit_action.custom_var_k5, log_link_visit_action.custom_var_v5

Any help is realy welcomed because I’m going crazy right now… :slight_smile:
Thanks


(Matthieu Aubry) #8

Are you using latest PHP / APC / Apache versions? there is a bug in some of these unfortunately :frowning:


(Nicolas Cynober) #9

This is related to a garbage collector crash (see the dump below).
The best way to solve this should be discussed in this thread.

FYI: here is the dump of my archive processing error with gdb:


Core was generated by `php-fpm: pool www                                         '.
Program terminated with signal 11, Segmentation fault.
#0  0x00000000006b49c9 in gc_init () at /build/buildd/php5-5.3.6/Zend/zend_gc.c:123
...

Thanks.