search

laravel / octane

Supercharge your Laravel application's performance.
https://laravel.com/docs/octane
MIT License
3.75k stars 291 forks source link

Parsing error of upstream time from roadrunner #169

Closed devoltt closed 3 years ago

devoltt commented 3 years ago

Description:

When roadrunner outputs upstream time with microseconds (µs) octane server can't parse value and server is falling down

Steps To Reproduce:

1) Add octane route like this to routes/web.php: \Laravel\Octane\Facades\Octane::route('GET', '/test', fn() => new Response('0'));

2) Run octane with 2 workers php artisan octane:start --workers=2 --server=roadrunner

3) Call this endpoint multiple time (~10-15) and when command parse output with microseconds, server is falling with error

[2021-04-10 20:02:58] local.ERROR: A non-numeric value encountered {"exception":"[object] (ErrorException(code: 0): A non-numeric value encountered at /Users/user/projects/example-app/vendor/laravel/octane/src/Commands/StartRoadRunnerCommand.php:154)
[stacktrace]
#0 /Users/user/projects/example-app/vendor/laravel/octane/src/Commands/StartRoadRunnerCommand.php(154): Illuminate\\Foundation\\Bootstrap\\HandleExceptions->handleError(2, 'A non-numeric v...', '/Users/batyrhan...', 154)
#1 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Collections/Traits/EnumeratesValues.php(234): Laravel\\Octane\\Commands\\StartRoadRunnerCommand->Laravel\\Octane\\Commands\\{closure}('{\"level\":\"debug...', 1)
#2 /Users/user/projects/example-app/vendor/laravel/octane/src/Commands/StartRoadRunnerCommand.php(163): Illuminate\\Support\\Collection->each(Object(Closure))
#3 /Users/user/projects/example-app/vendor/laravel/octane/src/Commands/Concerns/InteractsWithServers.php(48): Laravel\\Octane\\Commands\\StartRoadRunnerCommand->writeServerOutput(Object(Symfony\\Component\\Process\\Process))
#4 /Users/user/projects/example-app/vendor/laravel/octane/src/Commands/StartRoadRunnerCommand.php(85): Laravel\\Octane\\Commands\\StartRoadRunnerCommand->runServer(Object(Symfony\\Component\\Process\\Process), Object(Laravel\\Octane\\RoadRunner\\ServerProcessInspector), 'roadrunner')
#5 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): Laravel\\Octane\\Commands\\StartRoadRunnerCommand->handle(Object(Laravel\\Octane\\RoadRunner\\ServerProcessInspector), Object(Laravel\\Octane\\RoadRunner\\ServerStateFile))
#6 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Container/Util.php(40): Illuminate\\Container\\BoundMethod::Illuminate\\Container\\{closure}()
#7 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\\Container\\Util::unwrapIfClosure(Object(Closure))
#8 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\\Container\\BoundMethod::callBoundMethod(Object(Illuminate\\Foundation\\Application), Array, Object(Closure))
#9 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Container/Container.php(611): Illuminate\\Container\\BoundMethod::call(Object(Illuminate\\Foundation\\Application), Array, Array, NULL)
#10 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Console/Command.php(136): Illuminate\\Container\\Container->call(Array)
#11 /Users/user/projects/example-app/vendor/symfony/console/Command/Command.php(256): Illuminate\\Console\\Command->execute(Object(Symfony\\Component\\Console\\Input\\ArrayInput), Object(Illuminate\\Console\\OutputStyle))
#12 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Console/Command.php(121): Symfony\\Component\\Console\\Command\\Command->run(Object(Symfony\\Component\\Console\\Input\\ArrayInput), Object(Illuminate\\Console\\OutputStyle))
#13 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Console/Concerns/CallsCommands.php(68): Illuminate\\Console\\Command->run(Object(Symfony\\Component\\Console\\Input\\ArrayInput), Object(Illuminate\\Console\\OutputStyle))
#14 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Console/Concerns/CallsCommands.php(28): Illuminate\\Console\\Command->runCommand('octane:roadrunn...', Array, Object(Illuminate\\Console\\OutputStyle))
#15 /Users/user/projects/example-app/vendor/laravel/octane/src/Commands/StartCommand.php(84): Illuminate\\Console\\Command->call('octane:roadrunn...', Array)
#16 /Users/user/projects/example-app/vendor/laravel/octane/src/Commands/StartCommand.php(50): Laravel\\Octane\\Commands\\StartCommand->startRoadRunnerServer()
#17 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): Laravel\\Octane\\Commands\\StartCommand->handle()
#18 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Container/Util.php(40): Illuminate\\Container\\BoundMethod::Illuminate\\Container\\{closure}()
#19 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\\Container\\Util::unwrapIfClosure(Object(Closure))
#20 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\\Container\\BoundMethod::callBoundMethod(Object(Illuminate\\Foundation\\Application), Array, Object(Closure))
#21 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Container/Container.php(611): Illuminate\\Container\\BoundMethod::call(Object(Illuminate\\Foundation\\Application), Array, Array, NULL)
#22 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Console/Command.php(136): Illuminate\\Container\\Container->call(Array)
#23 /Users/user/projects/example-app/vendor/symfony/console/Command/Command.php(256): Illuminate\\Console\\Command->execute(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Illuminate\\Console\\OutputStyle))
#24 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Console/Command.php(121): Symfony\\Component\\Console\\Command\\Command->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Illuminate\\Console\\OutputStyle))
#25 /Users/user/projects/example-app/vendor/symfony/console/Application.php(971): Illuminate\\Console\\Command->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#26 /Users/user/projects/example-app/vendor/symfony/console/Application.php(290): Symfony\\Component\\Console\\Application->doRunCommand(Object(Laravel\\Octane\\Commands\\StartCommand), Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#27 /Users/user/projects/example-app/vendor/symfony/console/Application.php(166): Symfony\\Component\\Console\\Application->doRun(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#28 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Console/Application.php(92): Symfony\\Component\\Console\\Application->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#29 /Users/user/projects/example-app/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(129): Illuminate\\Console\\Application->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#30 /Users/user/projects/example-app/artisan(37): Illuminate\\Foundation\\Console\\Kernel->handle(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#31 {main}
"}

I suggest replace

https://github.com/laravel/octane/blob/master/src/Commands/StartRoadRunnerCommand.php#L153

$elapsed = Str::endsWith($debug['elapsed'], 'ms')
    ? substr($debug['elapsed'], 0, -2)
    : substr($debug['elapsed'], 0, -1) * 1000;

with something like this:

$elapsed = preg_replace('/[^0-9.]/', '', $debug['elapsed']);

switch (true) {
    case Str::endsWith($debug['elapsed'], 'µs'):
        $elapsed = $elapsed * 0.001;
        break;

    case Str::endsWith($debug['elapsed'], 'ns'):
        $elapsed = $elapsed * 0.00001;
        break;
}

P.S. sorry for my English

themsaid commented 3 years ago

It only outputs in seconds or milliseconds. Where in their docs do you see values could be in µs or ns?

devoltt commented 3 years ago

@themsaid I just debug this error and dump $debug['elapsed'], before the error - its value was outputting microseconds. Maybe a nanosecond check is superfluous, but when a request is processed in less than one millisecond , it outputs a value in microseconds.

themsaid commented 3 years ago

Handled in https://github.com/laravel/octane/pull/206