Transition Technology: Ticket #207: Logwatch Issues

estimatedhours changed

chris — Fri, 17 Dec 2010 14:40:06 GMT

estimatedhours changed from 0.0 to 0.25

80 of these (different times but the same) in the logwatch email:

Dec 17 13:02:48 quince apache2: PHP Fatal error:  Call to undefined function date_is_all_day() in /web/transitionnetwork.org/www/sites/all/modules/calendar/calendar.module on line 889

Line 889 of /web/transitionnetwork.org/www/sites/all/modules/calendar/calendar.module

          $node->calendar_all_day = date_is_all_day($node->calendar_end, $node->calendar_end, $granularity, $increment);

I couldn't find any corresponding errors in the dblog module system events here: https://www.transitionnetwork.org/admin/reports/dblog

The corresponding apache log appear to be this:

/var/log/apache2/transitionnetwork.org_access.log:74.111.12.244 - - [17/Dec/2010:13:02:48 +0000] "GET /events/calendar/2010-W25 HTTP/1.1" 200 152 "-" "Mozilla/5.0 (compatible; MJ12bot/v1.3.3; http://www.majestic12.co.uk/bot.php?+)"

So it's a bot causing the problem... The error can be duplicated at this address:

http://www.transitionnetwork.org/events/calendar/2010-W25

I don't know what page links to this as the bot doesn't supply a HTTP Referer in it's header.

jim — Fri, 17 Dec 2010 14:53:50 GMT

Looks like the DEV version of Calendar we're using also needs a post 20 Nov DEV version of Date: http://drupal.org/node/986776

Updated in SVN, when I push the next batch of updates to the server it'll be fixed.

milestone set

chris — Fri, 17 Dec 2010 16:50:32 GMT

milestone set to Phase 3

Opps forgot to add this to Phase 3.

hours, totalhours changed

chris — Fri, 07 Jan 2011 13:27:30 GMT

hours changed from 0.0 to 0.2
totalhours changed from 0.0 to 0.2

A couple of errors in the last logwatch email:

Jan  7 12:30:14 quince apache2: PHP Fatal error:  Call to undefined function curl_init() in
+/web/transitionnetwork.org/www/sites/all/modules/feeds/libraries/PuSHSubscriber.inc on line 73
Jan  7 13:00:21 quince apache2: PHP Fatal error:  Call to undefined function curl_init() in
+/web/transitionnetwork.org/www/sites/all/modules/feeds/libraries/PuSHSubscriber.inc on line 73

This line 73:

$request = curl_init($url);

So I have installed the php-curl package:

aptitude install php5-curl
  The following NEW packages will be installed:
  libcurl3{a} libssh2-1{a} php5-curl

And restarted apache -- hopefull this error won't pop up again, this package was already installed on the dev server.

hours, totalhours changed

chris — Fri, 07 Jan 2011 13:29:51 GMT

hours changed from 0.0 to 0.25
totalhours changed from 0.2 to 0.45

Adding 15mins to this ticket -- the first comment has it's time entered in the esitmate box not the time spent box: https://tech.transitionnetwork.org/trac/ticket/207#comment:1

hours, totalhours changed

chris — Mon, 10 Jan 2011 14:27:02 GMT

hours changed from 0.0 to 0.1
totalhours changed from 0.45 to 0.55

There are a few "Maximum execution time of 60 seconds exceeded" errors popping up, perhaps the pages that these requests are for could be cached as suggested by Jim?

Jan 10 12:27:33 quince apache2: PHP Fatal error:  Maximum execution time of 60 seconds exceeded in
+/web/transitionnetwork.org/www/modules/node/node.module on line 679
Jan 10 10:58:38 quince apache2: PHP Fatal error:  Maximum execution time of 60 seconds exceeded in
+/web/transitionnetwork.org/www/sites/all/modules/cacherouter/engines/file.php on line 48
Jan  9 21:12:01 quince apache2: PHP Fatal error:  Maximum execution time of 60 seconds exceeded in
+/web/transitionnetwork.org/www/sites/all/modules/xmlsitemap/xmlsitemap.module on line 357

Also there is a bunch of these from *different* IP addresses but all around the same time, this might not be a false positive...

Jan 10 05:03:21 quince suhosin[7705]: ALERT - configured GET variable value length limit exceeded - dropped variable 'dest' (attacker 'XX.XX.XX.XX',
+file '/web/transitionnetwork.org/www/index.php')
Jan 10 05:04:16 quince suhosin[9635]: ALERT - configured GET variable value length limit exceeded - dropped variable 'dest' (attacker 'XX.XX.XX.XX',
+file '/web/transitionnetwork.org/www/index.php')
Jan 10 05:04:24 quince suhosin[8169]: ALERT - configured GET variable value length limit exceeded - dropped variable 'dest' (attacker 'XX.XX.XX.XX',
+file '/web/transitionnetwork.org/www/index.php')
Jan 10 05:05:25 quince suhosin[9631]: ALERT - configured GET variable value length limit exceeded - dropped variable 'dest' (attacker 'XX.XX.XX.XX',
+file '/web/transitionnetwork.org/www/index.php')
Jan 10 05:05:42 quince suhosin[8172]: ALERT - configured GET variable value length limit exceeded - dropped variable 'dest' (attacker 'XX.XX.XX.XX',
+file '/web/transitionnetwork.org/www/index.php')
Jan 10 05:05:54 quince suhosin[9630]: ALERT - configured GET variable value length limit exceeded - dropped variable 'dest' (attacker 'XX.XX.XX.XX',
+file '/web/transitionnetwork.org/www/index.php')
Jan 10 05:07:34 quince suhosin[9635]: ALERT - configured GET variable value length limit exceeded - dropped variable 'dest' (attacker 'XX.XX.XX.XX',
+file '/web/transitionnetwork.org/www/index.php')

jim — Mon, 10 Jan 2011 18:46:13 GMT

Is it possible to increase the verbosity here? It'd be nice to know what the variables or more of the call stack to try to narrow down what's cracking.

chris — Fri, 28 Jan 2011 14:08:38 GMT

One I've not looked into yet:

Jan 28 13:30:32 quince apache2: PHP Fatal error:  Maximum execution time of 60 seconds exceeded in
+/web/transitionnetwork.org/www/sites/all/modules/nodehierarchy/nodehierarchy.module on line 261

ed — Fri, 17 Jun 2011 11:00:04 GMT

Does this need to be changed from phase 3 to phase 4?

hours, totalhours, milestone changed

chris — Sun, 03 Jul 2011 21:56:09 GMT

hours changed from 0.0 to 0.1
totalhours changed from 0.55 to 0.65
milestone changed from Phase 3 to Phase 4

Jim, lots of these in the last logwatch email:

Jul  3 20:39:22 quince apache2: PHP Parse error:  syntax error, unexpected ';' in /web/transitionnetwork.org/www/sites/all/modules/views_customfield/includes/views_customfield_handler_field_phpcode.inc(118) : eval()'d code on line 2

I couldn't find anything with google to help with these errors.

And one of these:

Jul  3 20:31:46 quince apache2: PHP Fatal error:  Unsupported operand types in /web/transitionnetwork.org/www/includes/common.inc on line 1429

There is a suggestion here for this: http://drupal.org/node/362799

And looking at the apache logs I think it was a POST done by Jim that caused it:

[03/Jul/2011:20:39:33 +0100] "POST /admin/build/views/ajax/config-item/blogs/panel_pane_3/field/phpcode HTTP/1.1" 200 14840 "https://www.transitionnetwork.org/admin/build/views/edit/blogs"

chris — Sun, 03 Jul 2011 21:59:58 GMT

Oops I got it the wrong way around above, the snip from the apache log, the POST cause the first error not the second.

ed — Tue, 13 Sep 2011 15:24:49 GMT

is this a phase 4 ticket? keep open? move to phase 5?

milestone changed

chris — Tue, 13 Sep 2011 20:49:35 GMT

milestone changed from Phase 4 to Phase 5

This is onging...

status, type changed

chris — Tue, 13 Sep 2011 21:24:41 GMT

status changed from new to accepted
type changed from defect to maintenance

hours, totalhours changed

chris — Thu, 06 Oct 2011 10:54:13 GMT

hours changed from 0.0 to 0.5
totalhours changed from 0.65 to 1.15

I was getting a lot of these logwatch emails:

Oct  6 10:06:19 quince /USR/SBIN/CRON[25012]: (CRON) error (grandchild #25020 failed with exit status 255)

I tracked it down to the www-data user who has this cron job:

5 * * * * /web/stats.transitionnetwork.org/piwik/misc/cron/archive.sh > /dev/null

It was failing with this in the syslog:

/var/log/syslog:Oct  5 11:05:01 quince /USR/SBIN/CRON[17136]: (www-data) CMD (/web/stats.transitionnetwork.org/piwik/misc/cron/archive.sh > /dev/null)
/var/log/syslog:Oct  5 11:05:57 quince /USR/SBIN/CRON[17132]: (CRON) error (grandchild #17136 failed with exit status 255)

When the script was run on the command line it failed here:

Fatal error: Allowed memory size of 268435456 bytes exhausted (tried to allocate 8388608 bytes) in /web/stats.transitionnetwork.org/piwik/core/DataTable.php on line 969

After increasing the memory_limit in /etc/php5/apache2/php.ini from 256m to 512m it still failed:

Fatal error: Allowed memory size of 268435456 bytes exhausted (tried to allocate 8388608 bytes) in /web/stats.transitionnetwork.org/piwik/core/DataTable.php on line 969

With the same "Allowed memory size" limit, 256 not 512... this was because the limit needed increasing in /etc/php5/cli/php.ini -- after increasing it to 512 it runs OK.

cc, hours, totalhours changed

chris — Mon, 12 Mar 2012 15:24:52 GMT

cc laura added
hours changed from 0.0 to 0.1
totalhours changed from 1.15 to 1.25

Email from logwatch:

Mar 12 12:43:57 quince suhosin[22133]: ALERT - script tried to disable memory_limit by setting it to a negative value -1 bytes which is not allowed (attacker 'REMOTE_ADDR not set', file '/web/wiki.transitionnetwork.org/www/maintenance/Maintenance.php', line 544)
Mar 12 12:43:57 quince suhosin[22133]: ALERT - script tried to disable memory_limit by setting it to a negative value -1 bytes which is not allowed (attacker 'REMOTE_ADDR not set', file '/web/wiki.transitionnetwork.org/www/maintenance/Maintenance.php', line 544)

I assumed the cron task triggered this but it was logged a few seconds after (or are the logs out by a few seconds?), from the apache access.log:

127.0.0.1 - - [12/Mar/2012:12:44:01 +0000] "GET /cron.php HTTP/1.0" 302 - "-" "Wget/1.12 (linux-gnu)"

-1 is unlimited.

So the questions I have are:

What triggered this, was it cron?
Depending on the answer to the first question do we need to either increase the cli or apache php memory limit?

Current values, /etc/php5/cli/php.ini:

memory_limit = 512M

And /etc/php/apache2/php.ini:

memory_limit = 256M

chris — Mon, 12 Mar 2012 17:11:14 GMT

This will have been cause by the mediawiki upgrade and it's OK to ignore it.

hours, totalhours changed

chris — Tue, 02 Oct 2012 10:23:03 GMT

hours changed from 0.0 to 0.1
totalhours changed from 1.25 to 1.35

This was flagged up in a logwatch email:

Oct  2 10:38:52 quince suhosin[11930]: ALERT - configured GET variable name length limit exceeded - dropped variable
+'Entrepreneurship_(Preparing_vegetable_boxes_at_Growing_Communities,_a_local_food_social_enterprise_in_Hackney)_x_jpg' (attacker '127.0.0.1',
+file '/web/transitionnetwork.org/www/index.php')

So I have doubled this value in /etc/php5/conf.d/suhosin.ini:

;suhosin.get.max_value_length = 2048
suhosin.get.max_value_length = 4096

description, milestone changed

ed — Thu, 09 May 2013 09:41:41 GMT

description modified (diff)
milestone changed from Phase 5 to Maintenance

cc, status changed; resolution set

chris — Fri, 15 Nov 2013 14:23:17 GMT

cc laura removed
status changed from accepted to closed
resolution set to fixed

This ticket was last used when wiki:NewLiveServer was running, so closing it.