Skip to content

Commit bb77894

Browse files
antonmedvantonmedv
committed
Add human_duration helper and integrate duration output in Logger 
1 parent ac547b3 commit bb77894

9 files changed

Lines changed: 209 additions & 9 deletions

File tree

‎src/Logger/Logger.php‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919
use Throwable;
2020

2121
use function Deployer\Support\ci_name;
22+
use function Deployer\Support\human_duration;
2223

2324
class Logger
2425
{
@@ -82,18 +83,17 @@ public function endTask(Task $task): void
8283
}
8384

8485
$endTime = round(microtime(true) * 1000);
85-
$millis = $endTime - $this->startTime;
86-
$seconds = floor($millis / 1000);
87-
$millis = $millis - $seconds * 1000;
88-
$taskTime = ($seconds > 0 ? "{$seconds}s " : "") . "{$millis}ms";
86+
$taskTime = human_duration((int) ($endTime - $this->startTime));
8987

9088
$ci = ci_name();
9189
if ($ci === 'github') {
90+
$this->output->writeln("<fg=yellow;options=bold>done</> {$task->getName()} $taskTime");
9291
$this->output->writeln("::endgroup::");
9392
} elseif ($ci === 'gitlab') {
93+
$this->output->writeln("<fg=yellow;options=bold>done</> {$task->getName()} $taskTime");
9494
$sectionId = md5($task->getName());
95-
$endTime = round($endTime / 1000);
96-
$this->output->writeln("\e[0Ksection_end:{$endTime}:{$sectionId}\r\e[0K");
95+
$endSec = (int) round($endTime / 1000);
96+
$this->output->writeln("\e[0Ksection_end:{$endSec}:{$sectionId}\r\e[0K");
9797
} elseif ($this->output->isVeryVerbose()) {
9898
$this->output->writeln("<fg=yellow;options=bold>done</> {$task->getName()} $taskTime");
9999
}

‎src/Support/helpers.php‎

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -210,6 +210,29 @@ function colorize_host(string $alias): string
210210
return "<$tag>$alias</>";
211211
}
212212

213+
function human_duration(int $millis): string
214+
{
215+
if ($millis < 0) {
216+
$millis = 0;
217+
}
218+
if ($millis < 1000) {
219+
return "{$millis}ms";
220+
}
221+
$seconds = intdiv($millis, 1000);
222+
$ms = $millis - $seconds * 1000;
223+
if ($seconds < 60) {
224+
return "{$seconds}s {$ms}ms";
225+
}
226+
$minutes = intdiv($seconds, 60);
227+
$seconds = $seconds - $minutes * 60;
228+
if ($minutes < 60) {
229+
return "{$minutes}m {$seconds}s";
230+
}
231+
$hours = intdiv($minutes, 60);
232+
$minutes = $minutes - $hours * 60;
233+
return "{$hours}h {$minutes}m";
234+
}
235+
213236
function ci_name(): ?string
214237
{
215238
if (getenv('GITHUB_WORKFLOW')) {

‎tests/spec/CurrentPathTest.php‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,7 @@
1212

1313
class CurrentPathTest extends SpecTest
1414
{
15-
public const RECIPE = __DIR__ . '/recipe/deploy.php';
15+
public const RECIPE = __DIR__ . '/recipe/deploy_test.php';
1616

1717
public function testDeployWithDifferentCurrentPath()
1818
{

‎tests/spec/DeployTest.php‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,7 @@
1313

1414
class DeployTest extends SpecTest
1515
{
16-
public const RECIPE = __DIR__ . '/recipe/deploy.php';
16+
public const RECIPE = __DIR__ . '/recipe/deploy_test.php';
1717

1818
public function testDeploy()
1919
{

‎tests/spec/SpecTest.php‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@
1212
use Symfony\Component\Console\Application;
1313
use Symfony\Component\Console\Output\OutputInterface;
1414
use Symfony\Component\Console\Tester\ApplicationTester;
15+
1516
use const __TEMP_DIR__;
1617

1718
abstract class SpecTest extends TestCase

‎tests/spec/recipe/deploy_test.php‎

Lines changed: 47 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,47 @@
1+
<?php
2+
3+
namespace Deployer;
4+
5+
require 'recipe/common.php';
6+
7+
set('application', 'deployer');
8+
set('repository', __REPOSITORY__);
9+
set('shared_dirs', [
10+
'uploads',
11+
'storage/logs/',
12+
'storage/db',
13+
]);
14+
set('shared_files', [
15+
'.env',
16+
'config/test.yaml',
17+
]);
18+
set('keep_releases', 3);
19+
set('http_user', false);
20+
21+
localhost('prod');
22+
23+
task('deploy', [
24+
'deploy:prepare',
25+
'deploy:vendors',
26+
'deploy:publish',
27+
]);
28+
29+
// Mock vendors installation to speed up tests.
30+
task('deploy:vendors', function () {
31+
if (!commandExist('unzip')) {
32+
warning('To speed up composer installation setup "unzip" command with PHP zip extension.');
33+
}
34+
run('cd {{release_path}} && echo {{bin/composer}} {{composer_options}} 2>&1');
35+
});
36+
37+
task('deploy:fail', [
38+
'deploy:prepare',
39+
'fail',
40+
'deploy:publish',
41+
]);
42+
43+
task('fail', function () {
44+
run('false');
45+
});
46+
47+
fail('deploy:fail', 'deploy:unlock');

‎tests/spec/recipe/update_code.php‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,7 @@
22

33
namespace Deployer;
44

5-
require __DIR__ . '/deploy.php';
5+
require __DIR__ . '/deploy_test.php';
66

77
task('deploy:update_code', function () {
88
upload(__FIXTURES__ . '/project/', '{{release_path}}');

‎tests/src/Logger/LoggerTest.php‎

Lines changed: 96 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -144,6 +144,102 @@ public function testStartTaskGitlabCI(): void
144144
$logger->startTask(new Task('deploy', function () {}));
145145
}
146146

147+
public function testEndTaskVeryVerbosePrintsDuration(): void
148+
{
149+
$output = $this->createMock(OutputInterface::class);
150+
$output->method('isVeryVerbose')->willReturn(true);
151+
$output->expects($this->once())
152+
->method('writeln')
153+
->with($this->logicalAnd(
154+
$this->stringContains('done'),
155+
$this->stringContains('deploy'),
156+
$this->stringContains('ms'),
157+
));
158+
159+
$fileLog = $this->createStub(HandlerInterface::class);
160+
161+
$logger = new Logger($output, $fileLog);
162+
$logger->endTask(new Task('deploy', function () {}));
163+
}
164+
165+
public function testEndTaskNonVerboseSkipsOutput(): void
166+
{
167+
$output = $this->createMock(OutputInterface::class);
168+
$output->method('isVeryVerbose')->willReturn(false);
169+
$output->expects($this->never())->method('writeln');
170+
171+
$fileLog = $this->createStub(HandlerInterface::class);
172+
173+
$logger = new Logger($output, $fileLog);
174+
$logger->endTask(new Task('deploy', function () {}));
175+
}
176+
177+
public function testEndTaskGithubCIAlwaysPrintsDuration(): void
178+
{
179+
putenv('GITHUB_WORKFLOW=test');
180+
181+
$output = $this->createMock(OutputInterface::class);
182+
$output->method('isVeryVerbose')->willReturn(false);
183+
$writelnArgs = [];
184+
$output->expects($this->exactly(2))
185+
->method('writeln')
186+
->willReturnCallback(function ($msg) use (&$writelnArgs) {
187+
$writelnArgs[] = $msg;
188+
});
189+
190+
$fileLog = $this->createStub(HandlerInterface::class);
191+
192+
$logger = new Logger($output, $fileLog);
193+
$logger->endTask(new Task('deploy', function () {}));
194+
195+
$this->assertStringContainsString('done', $writelnArgs[0]);
196+
$this->assertStringContainsString('deploy', $writelnArgs[0]);
197+
$this->assertStringContainsString('ms', $writelnArgs[0]);
198+
$this->assertEquals('::endgroup::', $writelnArgs[1]);
199+
}
200+
201+
public function testEndTaskGitlabCIAlwaysPrintsDuration(): void
202+
{
203+
putenv('GITLAB_CI=true');
204+
205+
$output = $this->createMock(OutputInterface::class);
206+
$output->method('isVeryVerbose')->willReturn(false);
207+
$writelnArgs = [];
208+
$output->expects($this->exactly(2))
209+
->method('writeln')
210+
->willReturnCallback(function ($msg) use (&$writelnArgs) {
211+
$writelnArgs[] = $msg;
212+
});
213+
214+
$fileLog = $this->createStub(HandlerInterface::class);
215+
216+
$logger = new Logger($output, $fileLog);
217+
$logger->endTask(new Task('deploy', function () {}));
218+
219+
$this->assertStringContainsString('done', $writelnArgs[0]);
220+
$this->assertStringContainsString('deploy', $writelnArgs[0]);
221+
$this->assertStringContainsString('ms', $writelnArgs[0]);
222+
$this->assertStringContainsString('section_end:', $writelnArgs[1]);
223+
}
224+
225+
public function testEndTaskWritesDurationToFileLog(): void
226+
{
227+
$output = $this->createStub(OutputInterface::class);
228+
$output->method('isVeryVerbose')->willReturn(false);
229+
230+
$fileLog = $this->createMock(HandlerInterface::class);
231+
$fileLog->expects($this->once())
232+
->method('writeln')
233+
->with($this->logicalAnd(
234+
$this->stringContains('done'),
235+
$this->stringContains('deploy'),
236+
$this->stringContains('ms'),
237+
));
238+
239+
$logger = new Logger($output, $fileLog);
240+
$logger->endTask(new Task('deploy', function () {}));
241+
}
242+
147243
public function testEndOnHostWritesToFileLog(): void
148244
{
149245
$output = $this->createStub(OutputInterface::class);

‎tests/src/Support/HelpersTest.php‎

Lines changed: 33 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -66,4 +66,37 @@ public function testRsyncRsh()
6666
$this->assertEquals("ssh 'argument with spaces'", rsync_rsh(['argument with spaces']));
6767
$this->assertEquals("ssh 'argument with '' quote'", rsync_rsh(['argument with \' quote']));
6868
}
69+
70+
public function testHumanDurationMillis()
71+
{
72+
$this->assertEquals('0ms', human_duration(0));
73+
$this->assertEquals('1ms', human_duration(1));
74+
$this->assertEquals('999ms', human_duration(999));
75+
}
76+
77+
public function testHumanDurationSeconds()
78+
{
79+
$this->assertEquals('1s 0ms', human_duration(1000));
80+
$this->assertEquals('1s 234ms', human_duration(1234));
81+
$this->assertEquals('59s 999ms', human_duration(59999));
82+
}
83+
84+
public function testHumanDurationMinutes()
85+
{
86+
$this->assertEquals('1m 0s', human_duration(60000));
87+
$this->assertEquals('1m 30s', human_duration(90000));
88+
$this->assertEquals('59m 59s', human_duration(3599999));
89+
}
90+
91+
public function testHumanDurationHours()
92+
{
93+
$this->assertEquals('1h 0m', human_duration(3600000));
94+
$this->assertEquals('2h 30m', human_duration(2 * 3600000 + 30 * 60000));
95+
$this->assertEquals('25h 0m', human_duration(25 * 3600000));
96+
}
97+
98+
public function testHumanDurationNegative()
99+
{
100+
$this->assertEquals('0ms', human_duration(-100));
101+
}
69102
}

0 commit comments

Comments
 (0)