Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Exceptions only showing up as "unknown error" on fly.io #36

Open
marvinosswald opened this issue Apr 23, 2024 · 6 comments
Open

Exceptions only showing up as "unknown error" on fly.io #36

marvinosswald opened this issue Apr 23, 2024 · 6 comments

Comments

@marvinosswald
Copy link

please let me know if this should rather be posted in the community forum.

If i trigger an exception all i see in the fly logs is: ERROR unknown error

more precisely:
Screenshot 2024-04-23 at 11 57 45

no details about it.
i tested this locally with frankenphp and stderr and did see the exception in frankenphp's log

logging.php

'stderr' => [
    'driver' => 'monolog',
    'level' => env('LOG_LEVEL', 'debug'),
    'handler' => StreamHandler::class,
    'formatter' => env('LOG_STDERR_FORMATTER'),
    'formatter_with' => [
        'includeStacktraces' => true,
    ],
    'with' => [
        'stream' => 'php://stderr',
    ],
    'processors' => [PsrLogMessageProcessor::class],
],

fly.toml

[build]
  [build.args]
    NODE_VERSION = '18'
    PHP_VERSION = '8.3'

[env]
    APP_ENV = 'production'
    LOG_CHANNEL = 'stderr'
    LOG_LEVEL = 'info'
    LOG_STDERR_FORMATTER = 'Monolog\Formatter\JsonFormatter'
    SESSION_DRIVER = 'cookie'
    SESSION_SECURE_COOKIE = 'true'


[http_service]
  internal_port = 8000
  force_https = true
  auto_stop_machines = true
  auto_start_machines = true
  min_machines_running = 0
  processes = ['app']

[processes]
  app = ""
#  cron = "cron -f"
#  worker = "php artisan queue:listen"

[[vm]]
  size = 'shared-cpu-1x'
  memory = "512MB"
@marvinosswald marvinosswald changed the title Logs not showing up on fly.io Exceptions only showing up as "unknown error" on fly.io Apr 23, 2024
@KTanAug21
Copy link
Contributor

Hi @marvinosswald!

I'm trying to replicate the behavior you are experiencing re: fly logs is: ERROR unknown error.

So in a Laravel 11 project, I added the same stderr config you have, and same fly.toml [env] keys you've shared. Added a route that's bound to throw an error:

Route::get('/test', function () {
    dd($kathryn);
});

And did a fly deploy. Visited the test route that throwed a 500 error. And checked out my logs at https://fly.io/apps/<app-name>/monitoring:
image
And the stack trace is there!

Are there other configurations you think will help me replicate the issue you're experiencing? Like:

  1. How did you configure your app with frankenphp?
  2. Where did you find the first image in your post( that showed the unknown error log )? I usually check my app's monitoring dashboard to see logs:
    https://fly.io/apps/<app-name>/monitoring

@marvinosswald
Copy link
Author

Hi @KTanAug21,
thank you for looking into this. I'll attach a couple of hopefully relevant files.
The first image is just the grafana view of the monitoring link you mentioned. It shows the same thing in fly live logs as well.

Dockerfile

# syntax = docker/dockerfile:experimental

ARG PHP_VERSION=8.3
ARG NODE_VERSION=18
FROM fideloper/fly-laravel:${PHP_VERSION} as base

# PHP_VERSION needs to be repeated here
# See https://docs.docker.com/engine/reference/builder/#understand-how-arg-and-from-interact
ARG PHP_VERSION

LABEL fly_launch_runtime="laravel"

# copy application code, skipping files based on .dockerignore
COPY . /var/www/html

RUN composer install --optimize-autoloader --no-dev \
    && mkdir -p storage/logs \
    && php artisan optimize:clear \
    && chown -R www-data:www-data /var/www/html \
    && echo "MAILTO=\"\"\n* * * * * www-data /usr/bin/php /var/www/html/artisan schedule:run" > /etc/cron.d/laravel \
    && sed -i='' '/->withMiddleware(function (Middleware \$middleware) {/a\
        \$middleware->trustProxies(at: "*");\
    ' bootstrap/app.php; \
    if [ -d .fly ]; then cp .fly/entrypoint.sh /entrypoint; chmod +x /entrypoint; fi;


RUN rm -rf /etc/supervisor/conf.d/fpm.conf; \
    mv /etc/supervisor/octane-franken.conf /etc/supervisor/conf.d/octane-franken.conf; \
    rm -f frankenphp; \
    php artisan octane:install --no-interaction --server=frankenphp; \
    rm /etc/nginx/sites-enabled/default; \
    ln -sf /etc/nginx/sites-available/default-octane /etc/nginx/sites-enabled/default;

# Multi-stage build: Build static assets
# This allows us to not include Node within the final container
FROM node:${NODE_VERSION} as node_modules_go_brrr

RUN mkdir /app

RUN mkdir -p  /app
WORKDIR /app
COPY . .
COPY --from=base /var/www/html/vendor /app/vendor

# Use yarn or npm depending on what type of
# lock file we might find. Defaults to
# NPM if no lock file is found.
# Note: We run "production" for Mix and "build" for Vite
RUN if [ -f "vite.config.js" ]; then \
        ASSET_CMD="build"; \
    else \
        ASSET_CMD="production"; \
    fi; \
    if [ -f "yarn.lock" ]; then \
        yarn install --frozen-lockfile; \
        yarn $ASSET_CMD; \
    elif [ -f "pnpm-lock.yaml" ]; then \
        corepack enable && corepack prepare pnpm@latest-8 --activate; \
        pnpm install --frozen-lockfile; \
        pnpm run $ASSET_CMD; \
    elif [ -f "package-lock.json" ]; then \
        npm ci --no-audit; \
        npm run $ASSET_CMD; \
    else \
        npm install; \
        npm run $ASSET_CMD; \
    fi;

# From our base container created above, we
# create our final image, adding in static
# assets that we generated above
FROM base

# Packages like Laravel Nova may have added assets to the public directory
# or maybe some custom assets were added manually! Either way, we merge
# in the assets we generated above rather than overwrite them
COPY --from=node_modules_go_brrr /app/public /var/www/html/public-npm
RUN rsync -ar /var/www/html/public-npm/ /var/www/html/public/ \
    && rm -rf /var/www/html/public-npm \
    && chown -R www-data:www-data /var/www/html/public

EXPOSE 8080

Composer.json

```json "require": { "php": "^8.3", "laravel/cashier-paddle": "^2.4", "laravel/framework": "11.3.0", "laravel/octane": "^2.3", "laravel/pulse": "^1.0@beta", "laravel/reverb": "@beta", "laravel/tinker": "^2.9", "livewire/livewire": "3.4.10", "lorisleiva/laravel-actions": "^2.8", "nick-potts/laravel-libsql-driver": "^0.1.2", "spatie/dns": "2.6.0", "staudenmeir/belongs-to-through": "^2.5", "torann/geoip": "^3.0" }, "require-dev": { "fakerphp/faker": "^1.23", "fly-apps/dockerfile-laravel": "^1.0", "larastan/larastan": "^2.0", "laravel/pint": "^1.13", "laravel/sail": "^1.26", "mockery/mockery": "^1.6", "nunomaduro/collision": "^8.0", "pestphp/pest": "^2.34", "pestphp/pest-plugin-laravel": "^2.3", "spatie/laravel-ignition": "^2.4" }, ```

@marvinosswald
Copy link
Author

marvinosswald commented Apr 25, 2024

I also just confirmed it has nothing to do with Livewire, happens on this route as well:

Route::get('/ex', function () {
   throw new Exception("ex");
});

as well as a logs screenshot:
Screenshot 2024-04-25 at 10 23 55

@KTanAug21
Copy link
Contributor

Hi again @marvinosswald!

First of, thank you for adding an issue here( you're def free to add any issues in our fly community forumas well! )--I should have added that thanks in my earlier comment( but better late than never right )! Reporting issues like this really help the Laravel team at Fly.io work on our goal of making Fly.io the best place to deploy Laravel apps in.

Next, let's get back into the issue at hand. Thanks to sharing your Dockerfile configuration, I've finally replicated the same behavior you're experiencing. I now also get the same "unknown error" log. I've located where this message is orginating from, to be exact, in octane/frankenphp, exactly in this line here.. It goes like this: $message = $debug['msg'] ?? 'unknown error';

Upon further inspection, it turns out that the $debug variable really does not contain the msg key. Because, as an alternative, it contains $debug['message']. One weird fix to get our logs out, is to use message instead of msg. But, of course this isn't good at all, we'll have to manually copy the StartFrankenPhpCommand.php in the base directory, revise that to ALSO use the message key if msg is not available, then in our Dockerfile use that revised file in our vendor folder. Like so:

RUN mv StartFrankenPhpCommand.php vendor/laravel/octane/src/Commands/StartFrankenPhpCommand.php

Not so neat. Of course this isn't the only solution! See a few lines above the line I mentioned above, is this line . Which is :

if ($this->option('log-level') !== null) {
            return $errorOutput->each(fn ($output) => $this->raw($output));
}

Now, if we pass a log-level option when starting octane, this will proceed with sending the output to the raw method, which results in neatly logging our errors as we want! So, create a file revising our supervisor config for octane-frankenphp here .fly/supervisor/octane-franken.conf and add that log-level option in:

[program:octane]
priority=5
command=php -d variables_order=EGPCS /var/www/html/artisan octane:start --server=frankenphp --log-level="INFO" --admin-port=2019 --port=8000
user=www-data
autostart=true
autorestart=true
stdout_events_enabled=true
stderr_events_enabled=true
stdout_logfile=/dev/stdout
stdout_logfile_maxbytes=0
stderr_logfile=/dev/stderr
stderr_logfile_maxbytes=0

Then revise our Dockerfile to use the new config at .fly/supervisor/octane-franken.conf instead of the default one:

RUN rm -rf /etc/supervisor/conf.d/fpm.conf; \
    mv .fly/supervisor/octane-franken.conf /etc/supervisor/conf.d/octane-franken.conf; \
    rm -f frankenphp; \
    php artisan octane:install --no-interaction --server=frankenphp; \
    rm /etc/nginx/sites-enabled/default; \
    ln -sf /etc/nginx/sites-available/default-octane /etc/nginx/sites-enabled/default;

I'm thinking of adding the second solution as a PR here, but I'm not sure if it's the best solution yet. Can you test it out and let me know if you get your log? Hope it helps!

@marvinosswald
Copy link
Author

Hi @KTanAug21,

thank you so much for figuring this out. Your provided solution absolutely works for me.
Seems like a weird behaviour to me why it uses message or msg and am not sure from your message where this originates from but your supervisor fix looks good for a downstream fix to me 👍

@KTanAug21
Copy link
Contributor

Hi @KTanAug21,

thank you so much for figuring this out. Your provided solution absolutely works for me. Seems like a weird behaviour to me why it uses message or msg and am not sure from your message where this originates from but your supervisor fix looks good for a downstream fix to me 👍

Awesome! That's great to read.

footnote: For the "message" attribute, I've logged the value of the $debug variable in this line like: Log::info(json_encode($debug)). And found it instead of the msg attribute

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants