Join 34,000+ subscribers and receive articles from our blog about software quality, testing, QA and security.
 

Strange cron error


#1

We use testrail v2.4.1.1156. The machine on which testrail is running had get an upgrade last week to Debian Squeeze. Since the upgrade in our logs every day strange warnings/errors appear:

Jan 31 09:14:01 hostname /USR/SBIN/CRON[21674]: (www-data) CMD (/usr/bin/php /var/www/testrail/task.php)
Jan 31 09:14:01 hostname suhosin[21674]: 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 'unknown')
Jan 31 09:14:01 hostname /USR/SBIN/CRON[21673]: (CRON) error (grandchild #21674 failed with exit status 1)

After I changed the php.ini and restarted the apache the failure seems to be fixed, but now in the logfiles appears:

Jan 31 09:51:01 hostname /USR/SBIN/CRON[22861]: (www-data) CMD (/usr/bin/php /var/www/testrail/task.php)
Jan 31 09:51:01 hostname /USR/SBIN/CRON[22860]: (CRON) error (grandchild #22861 failed with exit status 1)

What is the problem? Can someone help me with this?
Thanks!
S.


#2

Hello,

Thanks for your posting. TestRail’s background task deactivates the default memory limit as it’s not executed through a web server and might need to more memory to process all tasks. With specific PHP configurations this is blocked for security reasons, as this usually runs in the context of the web server, which is not the case with TestRail’s background task. Could you please let me know what kind of changes you’ve made to the PHP.ini file?

As the background task couldn’t cleanly terminate it’s still locked in TestRail’s database, which would explain why the task didn’t run even after you’ve resolved the first problem. The lock is automatically released after an hour. Do you still see the same problem or is the task working correctly now? If not I’m happy to send you the details on how to enable debug logging for the task. I also recommend trying to execute the background task directly from the command line once to see if the task outputs any system messages/errors.

Thanks,
Dennis


#3

Hi Dennis,
Thanks for your answer! When I execute the task.php on command line:

/usr/bin/php /var/www/testrail/task.php The ionCube PHP Loader is not installed
in /etc/php5/apache2/php.ini

[PHP]

zend_extension = /usr/local/ioncube/ioncube_loader_lin_5.3.so

;;;;;;;;;;;;;;;;;;;
; About php.ini   ;
;;;;;;;;;;;;;;;;;;;

is already added and we’re able to login and use testrail without any problems. In /etc/php5/cli/php.ini we commented the memory_limit out, because it always was overwritten somehow, but we added in /etc/php5/conf.d a file which contains the following:

memory_limit = 128M

after that, the first error was fixed. But as shown in my first post, now in syslog we get the error:

Feb  1 15:06:01 hostnam /USR/SBIN/CRON[8057]: (www-data) CMD (/usr/bin/php /var/www/testrail/task.php)
Feb  1 15:06:01 hostname /USR/SBIN/CRON[8056]: (CRON) error (grandchild #8057 failed with exit status 1)

Thanks!
S.


#4

Hello,

Thanks for the feedback. You also need to add all required extensions to your /etc/php5/cli/php.ini file (specifically the ioncube extension). The reason for this is that PHP uses a different configuration file for the command line version and it won’t pick up the ioncube extension from your Apache PHP configuration file (when you install a PHP extension via apt-get or similar it’s usually added as a file in /etc/php5/conf.d which is picked up by all configuration files; for custom extensions you would usually just add them to all PHP.ini files).

So I suggest adding the ioncube extension to the /etc/php5/cli/php.ini file as well, and then testing the background task from the command line again (you can see that it’s working if it doesn’t print any messages and the status in TestRail under Administration should show that it’s installed).

I hope this helps.

Regards,
Dennis


#5

Hi Dennis,

I tried what you suggested. But…
php.ini’s

hostname:/etc# find . -name php.ini
./php5/apache2/php.ini
./php5/cli/php.ini
hostname:/etc# head php5/apache2/php.ini
[PHP]

zend_extension = /usr/local/ioncube/ioncube_loader_lin_5.3.so

;;;;;;;;;;;;;;;;;;;
; About php.ini   ;
;;;;;;;;;;;;;;;;;;;
; PHP's initialization file, generally called php.ini, is responsible for
; configuring many of the aspects of PHP's behavior.

hostname:/etc# head php5/cli/php.ini
[PHP]

zend_extension = /usr/local/ioncube/ioncube_loader_lin_5.3.so

;;;;;;;;;;;;;;;;;;;
; About php.ini   ;
;;;;;;;;;;;;;;;;;;;
; PHP's initialization file, generally called php.ini, is responsible for
; configuring many of the aspects of PHP's behavior.

Apache was restarted. Now when i try to execute task.php on command line this happens:

hostname:/etc# /usr/bin/php /var/www/testrail/task.php
Another task instance is still running.
hostname:/etc# 

and in syslog:

hostname:/etc# tail -f /var/log/syslog
…
Feb  1 17:44:01 hostname /USR/SBIN/CRON[9975]: (www-data) CMD (/usr/bin/php /var/www/testrail/task.php)
Feb  1 17:44:01 hostname /USR/SBIN/CRON[9974]: (CRON) error (grandchild #9975 failed with exit status 1)
...
Feb  1 17:45:01 hostname /USR/SBIN/CRON[9988]: (www-data) CMD (/usr/bin/php /var/www/testrail/task.php)
Feb  1 17:45:01 hostname /USR/SBIN/CRON[9987]: (CRON) error (grandchild #9988 failed with exit status 1)
...
Feb  1 17:46:01 hostname /USR/SBIN/CRON[10014]: (www-data) CMD (/usr/bin/php /var/www/testrail/task.php)
Feb  1 17:46:01 hostname /USR/SBIN/CRON[10013]: (CRON) error (grandchild #10014 failed with exit status 1)

And now in testrail under the admin tab every minute:

[ERROR] 2012-02-01 17:52:01 [38ms]: [ModelException] Another task instance is still running.
at ex::raise (ex.php:23)
at ex::raise (model.php:67)
at Model->_raiset (task.php:55)
at Task_model->_trx_acquire_lock (callback.php:58)
at callback::runv (database.php:1002)
at Database_library->_transaction_run (database.php:1093)
at Database_library->transaction_run (task.php:27)
at Task_model->acquire_lock (tasks.php:81)
at Tasks_controller->_acquire_lock (tasks.php:110)
at Tasks_controller->index (controller.php:76)
at Controller->_invoke_cli (controller.php:64)
at Controller->_invoke (gizmo.php:108)
at require_once (index.php:106)
at require_once (task.php:44)
[ERROR] 2012-02-01 17:51:01 [38ms]: [ModelException] Another task instance is still running.
at ex::raise (ex.php:23)
at ex::raise (model.php:67)
at Model->_raiset (task.php:55)
at Task_model->_trx_acquire_lock (callback.php:58)
at callback::runv (database.php:1002)
at Database_library->_transaction_run (database.php:1093)
at Database_library->transaction_run (task.php:27)
at Task_model->acquire_lock (tasks.php:81)
at Tasks_controller->_acquire_lock (tasks.php:110)
at Tasks_controller->index (controller.php:76)
at Controller->_invoke_cli (controller.php:64)
at Controller->_invoke (gizmo.php:108)
at require_once (index.php:106)
at require_once (task.php:44)


Do you have additional suggestions?
Thanks,
S.
Update: The problem is solved now: we changed is_locked column in the MySQL DB to 0.
Thanks for your help!


#6

Hello,

Thanks for your feedback and glad to hear that it’s working now. The background task would have unlocked itself automatically after a certain time (about an hour) but manually clearing this flag is also fine.

Thanks,
Dennis