Empty error when invoking function with incorrect type hinting #135

esetnik · 2018-09-04T21:49:10Z

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)) [] []

The text was updated successfully, but these errors were encountered:

PabloKowalczyk · 2018-09-05T18:37:01Z

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 · 2018-09-05T18:39:52Z

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 · 2018-09-05T19:07:52Z

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

esetnik · 2018-09-05T19:13:57Z

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 · 2018-09-05T19:22:08Z

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 · 2018-09-06T17:00:24Z

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

esetnik · 2018-09-17T15:29:35Z

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 · 2018-09-21T10:47:05Z

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 · 2018-09-22T07:31:36Z

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

esetnik · 2018-10-11T21:32:10Z

@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 · 2018-10-13T08:45:06Z

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

esetnik · 2018-10-13T20:05:16Z

Yes that is correct

PabloKowalczyk · 2018-10-14T06:44:07Z

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 · 2018-10-20T07:07:24Z

@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 · 2018-11-10T10:55:44Z

@esetnik you should see #161, seems related. If you still have issues feel free to open new issue.

esetnik · 2018-11-11T19:42:59Z

@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 · 2019-01-24T21:08:38Z

@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 · 2019-01-24T21:33:46Z

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 · 2019-01-25T15:28:34Z

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 · 2019-01-25T16:04:30Z

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 · 2019-01-25T16:09:35Z

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 · 2019-01-25T16:10:49Z

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 · 2019-01-25T16:13:00Z

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

esetnik · 2019-01-25T16:17:07Z

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 · 2019-01-25T16:28:39Z

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 · 2019-01-26T06:37:00Z

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 😃

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 · 2019-01-26T18:17:32Z

@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 · 2019-01-26T18:27:40Z

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 · 2019-01-27T08:01:39Z

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 · 2019-01-27T14:31:31Z

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 · 2019-01-27T14:35:29Z

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 · 2019-01-27T14:47:32Z

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 · 2019-01-27T17:12:40Z

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

PabloKowalczyk added the Status: Waiting feedback label Sep 6, 2018

esetnik mentioned this issue Sep 6, 2018

Empty error when invoking global function #134

Closed

PabloKowalczyk removed the Status: Waiting feedback label Sep 6, 2018

PabloKowalczyk added the Status: Waiting feedback label Sep 9, 2018

PabloKowalczyk mentioned this issue Sep 22, 2018

Treat whole output of failed command as "error output". #137

Merged

PabloKowalczyk closed this as completed Sep 22, 2018

PabloKowalczyk added the bug label Oct 13, 2018

PabloKowalczyk reopened this Jan 24, 2019

PabloKowalczyk removed the Status: Waiting feedback label Jan 24, 2019

PabloKowalczyk removed the bug label Jan 26, 2019

PabloKowalczyk mentioned this issue Jan 27, 2019

Fix Crunz bin path when running closures #190

Merged

PabloKowalczyk added the bug label Jan 27, 2019

PabloKowalczyk closed this as completed Jan 27, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Empty error when invoking function with incorrect type hinting #135

Empty error when invoking function with incorrect type hinting #135

esetnik commented Sep 4, 2018

PabloKowalczyk commented Sep 5, 2018

esetnik commented Sep 5, 2018

PabloKowalczyk commented Sep 5, 2018

esetnik commented Sep 5, 2018

PabloKowalczyk commented Sep 5, 2018

PabloKowalczyk commented Sep 6, 2018

esetnik commented Sep 17, 2018

PabloKowalczyk commented Sep 21, 2018

PabloKowalczyk commented Sep 22, 2018

esetnik commented Oct 11, 2018

PabloKowalczyk commented Oct 13, 2018

esetnik commented Oct 13, 2018

PabloKowalczyk commented Oct 14, 2018

PabloKowalczyk commented Oct 20, 2018 •

edited

Loading

PabloKowalczyk commented Nov 10, 2018

esetnik commented Nov 11, 2018 •

edited

Loading

esetnik commented Jan 24, 2019 •

edited

Loading

esetnik commented Jan 24, 2019 •

edited

Loading

PabloKowalczyk commented Jan 25, 2019

esetnik commented Jan 25, 2019

PabloKowalczyk commented Jan 25, 2019

esetnik commented Jan 25, 2019

PabloKowalczyk commented Jan 25, 2019

esetnik commented Jan 25, 2019 •

edited

Loading

esetnik commented Jan 25, 2019

PabloKowalczyk commented Jan 26, 2019

esetnik commented Jan 26, 2019

esetnik commented Jan 26, 2019

PabloKowalczyk commented Jan 27, 2019

esetnik commented Jan 27, 2019 •

edited

Loading

PabloKowalczyk commented Jan 27, 2019

esetnik commented Jan 27, 2019

PabloKowalczyk commented Jan 27, 2019

Empty error when invoking function with incorrect type hinting #135

Empty error when invoking function with incorrect type hinting #135

Comments

esetnik commented Sep 4, 2018

PabloKowalczyk commented Sep 5, 2018

esetnik commented Sep 5, 2018

PabloKowalczyk commented Sep 5, 2018

esetnik commented Sep 5, 2018

PabloKowalczyk commented Sep 5, 2018

PabloKowalczyk commented Sep 6, 2018

esetnik commented Sep 17, 2018

PabloKowalczyk commented Sep 21, 2018

PabloKowalczyk commented Sep 22, 2018

esetnik commented Oct 11, 2018

PabloKowalczyk commented Oct 13, 2018

esetnik commented Oct 13, 2018

PabloKowalczyk commented Oct 14, 2018

PabloKowalczyk commented Oct 20, 2018 • edited Loading

PabloKowalczyk commented Nov 10, 2018

esetnik commented Nov 11, 2018 • edited Loading

esetnik commented Jan 24, 2019 • edited Loading

esetnik commented Jan 24, 2019 • edited Loading

PabloKowalczyk commented Jan 25, 2019

esetnik commented Jan 25, 2019

PabloKowalczyk commented Jan 25, 2019

esetnik commented Jan 25, 2019

PabloKowalczyk commented Jan 25, 2019

esetnik commented Jan 25, 2019 • edited Loading

esetnik commented Jan 25, 2019

PabloKowalczyk commented Jan 26, 2019

esetnik commented Jan 26, 2019

esetnik commented Jan 26, 2019

PabloKowalczyk commented Jan 27, 2019

esetnik commented Jan 27, 2019 • edited Loading

PabloKowalczyk commented Jan 27, 2019

esetnik commented Jan 27, 2019

PabloKowalczyk commented Jan 27, 2019

PabloKowalczyk commented Oct 20, 2018 •

edited

Loading

esetnik commented Nov 11, 2018 •

edited

Loading

esetnik commented Jan 24, 2019 •

edited

Loading

esetnik commented Jan 24, 2019 •

edited

Loading

esetnik commented Jan 25, 2019 •

edited

Loading

esetnik commented Jan 27, 2019 •

edited

Loading