Empty error when invoking function with incorrect type hinting

esetnik commented 6 years ago

Example:

TestTasks.php

<?php

use Crunz\Schedule;

$schedule = new Schedule();

$schedule->run(function () {
    echo 'test';

    function test(boolean $parameter)
    {
        echo 'test2';
    }

    test(true);
})
->everyMinute()
->description('Test schedule');

return $schedule;

Output: [2018-09-04 17:47:02] crunz.ERROR: Test schedule(object(Closure)) [] []

PabloKowalczyk commented 6 years ago

Actually your closure do not work at all - https://3v4l.org/bjv0n Fatal error: Uncaught TypeError: Argument 1 passed to test() must be an instance of boolean, bool given There is no problem with Crunz itself :)

esetnik commented 6 years ago

The issue is not that the closure is incorrect (I purposely made it this way). The issue is that crunz does not report the error. Look at my output from crunz. It does not contain any information about the error.

PabloKowalczyk commented 6 years ago

You are right, output could be more "verbose". Would you like to provide a PR for this issue?

esetnik commented 6 years ago

I did some debugging and I found that I actually get the correct output when I have:

// php.ini

log_errors = On

So it seems that crunz logs an empty error if there is a PHP Fatal Error and log_errors = On is not set. Maybe crunz can install a custom error handler and log to monolog regardless of the log_errors setting. In my opinion, crunz should never log an empty error message.

PabloKowalczyk commented 6 years ago

Crunz actually do not omit errors, there is issue with writing error to stderr instead of stdout:

// \Crunz\EventRunner

protected function handleError(Event $event)
    {
        // ...
            $this->display($event->getProcess()->getErrorOutput());
        // ...
    }

As you can see Crunz show error output (stderr) $event->getProcess()->getErrorOutput(), but error is in stdout. Possible solution is, as you said, redirect errors to error output. Maybe a better idea is to log whole output to give some context to error?

PabloKowalczyk commented 6 years ago

@esetnik i improved error logging/displaying, could you test changes on https://github.com/PabloKowalczyk/crunz/tree/improve-error-logging ?

esetnik commented 6 years ago

Hi @PabloKowalczyk thank you for your work. I have not had an opportunity to test the changes yet, but I reviewed the commit and it makes sense to me. The only thing that's questionable is the formatting of the error output with <error> tags. I will leave it up to you how you want it to present, but in my opinion it's a bit strange to have tags in logs.

PabloKowalczyk commented 6 years ago

Mentioned <error> is used only for display and it is not a problem because Symfony's formatter will turn it into white text with red background, only on supported terminals. Logs always have "raw" content, without any tags.

PabloKowalczyk commented 6 years ago

Merged and released in https://github.com/lavary/crunz/releases/tag/v1.10.0. Thanks @esetnik.

esetnik commented 6 years ago

@PabloKowalczyk I actually found that after v1.10.0 with log_errors = On there is an empty output on an exception thrown. I had to revert to v1.9.0

PabloKowalczyk commented 6 years ago

@esetnik did you mean log_errors = On in php.ini?

esetnik commented 6 years ago

Yes that is correct

PabloKowalczyk commented 6 years ago

I have this option enabled and everything working as expected. In your previous post, "empty output" mean empty cli console or empty file where Crunz stores error logs?

PabloKowalczyk commented 6 years ago

@esetnik seems errors displaying depends on display_error. i have created PR which enables displaying errors ,could you test that version https://github.com/PabloKowalczyk/crunz/tree/show-all-errors?

BTW could could you paste output of command php -i | grep error?

PabloKowalczyk commented 5 years ago

@esetnik you should see https://github.com/lavary/crunz/issues/161, seems related. If you still have issues feel free to open new issue.

esetnik commented 5 years ago

@PabloKowalczyk thanks for the update and continued hard work. When the update becomes stable I will test the changes and let you know if it resolves things.

esetnik commented 5 years ago

@PabloKowalczyk just tested with 1.11 and it's still not working. It logs the crunz.INFO but the task output is missing. Here's a sample to reproduce:

root@a636be9c78e8:/usr/src/app/src# vendor/bin/crunz -V
Crunz Command Line Interface v1.11.0

command i'm running inside the container

root@a57cf902413f:/usr/src/app/src# vendor/bin/crunz schedule:run -vvv
Using config file /usr/src/app/src/crunz.yml.
Task source path '/usr/src/app/src/jobs'
Realpath for '/usr/src/app/src/jobs' is '/usr/src/app/src/jobs'
Task finder pattern '/usr/src/app/src/jobs/*Tasks.php'
Found 1 task(s) at path '/usr/src/app/src/jobs'
Timezone from config: 'UTC'.
Timezone for comparisons: 'UTC'.
Invoke Schedule's ping before
There is no ping before url.
Invoke Event's ping before.
There is no ping before url.
Invoke Event's ping after.
There is no ping after url.
[2019-01-24 16:05:00] crunz.INFO: Copying the project directory(object(Closure))

 [] []
Task Copying the project directory status: success.
Invoke Schedule's ping after.
There is no ping after url.

src/jobs/TestTasks.php

<?php

use Crunz\Schedule;

$schedule = new Schedule();

$x = 12;
$schedule->run(function () use ($x) {
    echo "hi";
    echo $x;
})
->everyMinute()
->description('Copying the project directory');
return $schedule;

src/jobs/set_env.sh

#!/bin/bash
set -e

export SQL_DATABASE=$SQL_DATABASE;
export SQL_HOST=$SQL_HOST;
export SQL_USER=$SQL_USER;
export SQL_PASSWORD=$SQL_PASSWORD;
export SQL_PORT=$SQL_PORT;
export ENV=$ENV;
export SENDGRID_API_KEY=$SENDGRID_API_KEY;

src/jobs/start.sh

#!/bin/bash
set -e

envsubst < src/jobs/set_env.sh > /set_env.sh
chmod +x /set_env.sh

echo 'starting cron job daemon...'

cron -f

src/jobs/crontab

* * * * * . /set_env.sh; cd /usr/src/app/src && vendor/bin/crunz schedule:run -vvv > /proc/1/fd/1 2>/proc/1/fd/2

Dockerfile

FROM php:7.3-stretch

# Set timezone to America/New_York
ENV TZ=America/New_York
ENV php_vars /usr/local/etc/php/conf.d/docker-vars.ini

RUN ln -snf /usr/share/zoneinfo/$TZ /etc/localtime \
  && echo $TZ > /etc/timezone \
  && echo "date.timezone=\"$TZ\"" >> /usr/local/etc/php/conf.d/docker-vars.ini

RUN apt-get update && \
  apt-get install -y --no-install-recommends gnupg \
  apt-transport-https \
  cron \
  gettext

RUN ln -s /usr/local/bin/php /usr/bin/php
RUN mv $PHP_INI_DIR/php.ini-production $PHP_INI_DIR/php.ini && \ 
  echo "log_errors = On"  >> ${php_vars} && \
  echo "display_errors = On"  >> ${php_vars} && \
  echo "error_log = /dev/stderr" >> ${php_vars} && \
  echo "display_startup_errors = On" >> ${php_vars}

RUN mkdir /usr/src/app
WORKDIR /usr/src/app

COPY . .
COPY src/jobs/crontab /etc/cron.d/jobs-cron
# COPY src/jobs/php.ini /usr/local/etc/php
RUN chmod 755 /etc/cron.d/jobs-cron
RUN crontab /etc/cron.d/jobs-cron
RUN chmod +x src/jobs/start.sh

RUN touch /usr/src/app/src/crunz

CMD ["src/jobs/start.sh"]

php -i (from inside container)

crunz.yml

# Crunz Configuration Settings

# This option defines where the task files and
# directories reside.
# The path is relative to the project's root directory,
# where the Crunz is installed (Trailing slashes will be ignored).
source: jobs

# The suffix is meant to target the task files inside the ":source" directory.
# Please note if you change this value, you need
# to make sure all the existing tasks files are renamed accordingly.
suffix: Tasks.php

# Timezone is used to calculate task run time
# This option is very important and not setting it is deprecated
# and will result in exception in 2.0 version.
timezone: UTC

# By default the errors are not logged by Crunz
# You may set the value to true for logging the errors
log_errors: true

# This is the absolute path to the errors' log file
# You need to make sure you have the required permission to write to this file though.
errors_log_file: php://stderr

# By default the output is not logged as they are redirected to the
# null output.
# Set this to true if you want to keep the outputs
log_output: true

# This is the absolute path to the global output log file
# The events which have dedicated log files (defined with them), won't be
# logged to this file though.
output_log_file: php://stdout

# By default line breaks in logs aren't allowed.
# Set the value to true to allow them.
log_allow_line_breaks: true

# This option determines whether the output should be emailed or not.
email_output: false

# This option determines whether the error messages should be emailed or not.
email_errors: false

# Global Swift Mailer settings
mailer:
  # Possible values: smtp, mail, and sendmail
  transport: smtp
  recipients:
  sender_name:
  sender_email:

# SMTP settings
smtp:
  host: ~
  port: ~
  username: ~
  password: ~
  encryption: ~

esetnik commented 5 years ago

For a quick test I also just mocked the scheduler and am getting the correct output:

<?php
class Schedule
{
    public function run($func)
    {
        $func();
        return $this;
    }
    public function everyMinute()
    {
        return $this;
    }
    public function description()
    {
        return $this;
    }
}

$schedule = new Schedule();

$x = 12;
$schedule->run(function () use ($x) {
    echo "hi";
    echo $x;
})
->everyMinute()
->description('Copying the project directory');

return $schedule;

root@84c44308ddca:/usr/src/app/src# vendor/bin/crunz schedule:run -vvv
Using config file /usr/src/app/src/crunz.yml.
Task source path '/usr/src/app/src/jobs'
Realpath for '/usr/src/app/src/jobs' is '/usr/src/app/src/jobs'
Task finder pattern '/usr/src/app/src/jobs/*Tasks.php'
Found 1 task(s) at path '/usr/src/app/src/jobs'
Timezone from config: 'UTC'.
Timezone for comparisons: 'UTC'.
hi12No event is due!

note the hi12 in the output.

PabloKowalczyk commented 5 years ago

On version v1.11.0, task:

<?php

use Crunz\Schedule;

$x = 13;

$scheduler = new Schedule();

$scheduler
    ->run(function () use ($x) {
        echo 'From lambda' . PHP_EOL;
        echo 'Out: ' . $x . PHP_EOL;
    })
    ->description('Lambda echo')
    ->everyMinute();

return $scheduler;

produces following log entry: [2019-01-25 15:25:51] crunz.INFO: Lambda echo(object(Closure)) From lambda Out: 13 [] []. For me, everything works as expected.

esetnik commented 5 years ago

Using the configuration I provided above and running your example I get the following output:

starting cron job daemon...
Using config file /usr/src/app/src/crunz.yml.
Task source path '/usr/src/app/src/jobs'
Realpath for '/usr/src/app/src/jobs' is '/usr/src/app/src/jobs'
Task finder pattern '/usr/src/app/src/jobs/*Tasks.php'
Found 1 task(s) at path '/usr/src/app/src/jobs'
Timezone from config: 'UTC'.
Timezone for comparisons: 'UTC'.
Invoke Schedule's ping before
There is no ping before url.
Invoke Event's ping before.
There is no ping before url.
Invoke Event's ping after.
There is no ping after url.
[2019-01-25 11:04:02] crunz.INFO: Lambda echo(object(Closure))

 [] []
Task Lambda echo status: success.
Invoke Schedule's ping after.
There is no ping after url.

PabloKowalczyk commented 5 years ago

Interesting, for some reason you enabled loggin to file log_output: true, but still redirect whole output to stdout output_log_file: php://stdout, why?

Below configuration works for me:

log_output: true
output_log_file: crunz.log

esetnik commented 5 years ago

Because it is a docker container so I want the logs to go to the container logging and not to a file on the container filesystem.

PabloKowalczyk commented 5 years ago

This is default behavior, there shouldn't be need to do tricks. Does it work with log_output: false?

esetnik commented 5 years ago

So what I know is that there is definitely a change in the project which introduces this issue. The exact same example (identical container and configuration) I provided above works fine if I revert to v1.10.0 (or earlier) but doesn't work after upgrading to v1.11.0. Is there any relevant change to how log output is captured by the crunz scheduler between 1.10 and 1.11? Or possibly it's related to a change in a dependency resolution between 1.10 and 1.11?

esetnik commented 5 years ago

log_output: false produces no output at all...

Using config file /usr/src/app/src/crunz.yml.
Task source path '/usr/src/app/src/jobs'
Realpath for '/usr/src/app/src/jobs' is '/usr/src/app/src/jobs'
Task finder pattern '/usr/src/app/src/jobs/*Tasks.php'
Found 1 task(s) at path '/usr/src/app/src/jobs'
Timezone from config: 'UTC'.
Timezone for comparisons: 'UTC'.
Invoke Schedule's ping before
There is no ping before url.
Invoke Event's ping before.
There is no ping before url.
Invoke Event's ping after.
There is no ping after url.
Task Lambda echo status: success.
Invoke Schedule's ping after.
There is no ping after url.

PabloKowalczyk commented 5 years ago

On version v1.11.0, in docker container and with config

log_output: true
output_log_file: php://stdout

everything works for me as expected. Here is my output:

[2019-01-26 06:25:32] crunz.INFO: Lambda echo(object(Closure))   From lambda Out: 13   [] []
[2019-01-26 06:25:32] crunz.INFO: PHP version(php -v)   PHP 5.6.39 (cli) (built: Dec 21 2018 03:40:29)  Copyright (c) 1997-2016 The PHP Group Zend Engine v2.6.0, Copyright (c) 1998-2016 Zend Technologies     with Zend OPcache v7.0.6-dev, Copyright (c) 1999-2016, by Zend Technologies   [] []

Could you create repository with code (including docker, Cron config, task, php config and all other configurations) to reproduce?

And to answer your questions:

Is there any relevant change to how log output is captured by the crunz scheduler between 1.10 and 1.11?

Yes and no. Now whole output (stdout and stderr) of command is captured. Theoretically you should see more output than previously :smiley:

Or possibly it's related to a change in a dependency resolution between 1.10 and 1.11?

Definitely no, monolog was not touched.

esetnik commented 5 years ago

@PabloKowalczyk https://github.com/esetnik/crunz-output is a minimum reproducible example. Hopefully it can help us get to the bottom of what's going on. One thing I noticed is that my container is using php:7.3-stretch whereas yours is using php version 5.6.39.

esetnik commented 5 years ago

In fact I tried using php:5.6-stretch but the project doesn't even run...

❯ docker run -it crunz-output
starting cron job daemon...

Fatal error: Default value for parameters with a class type hint can only be NULL in /usr/src/app/src/vendor/symfony/console/Application.php on line 85

In fact it appears that symphony 4 requires php 7.1 https://symfony.com/doc/current/reference/requirements.html so i'm not sure how you managed to get crunz working on php 5.6 unless you're using an older symphony version.

PabloKowalczyk commented 5 years ago

Finally found out what is going on, you are right, v1.11.0 broke running closures - path to Crunz bin was wrong. Fixed and added E2E test, could you try this version https://github.com/PabloKowalczyk/crunz/tree/fix-closure-run?

esetnik commented 5 years ago

Confirmed fixed in fix-closure-run although the project does not run on 5.6 only 7.1+. Do you want me to open a separate issue for this? It should be made note of in the documentation at least.

PabloKowalczyk commented 5 years ago

Crunz is 100% compatible with PHP 5.6 - https://travis-ci.org/lavary/crunz/jobs/484720655. When you downgrade Symfony version you need to clear Crunz cache at /tmp/.crunz.

esetnik commented 5 years ago

Actually you are right about that. I was accidentally installing the project dependencies using 7.3 and then trying to use them in the 5.6 docker context. So this can be closed once your branch is merged.

PabloKowalczyk commented 5 years ago

Patch merged and released as v1.11.1. Thanks @esetnik.

lavary / crunz

Empty error when invoking function with incorrect type hinting #135