Error in the output of archive.php

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

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?

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

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??

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

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

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

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

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.