テストケース内でログ出力ができない

Question

Laravelを使っていて、テストを書いています。
テストケース内でログ出力しようとしても、順番に実行される先頭のケースでしか出力されません。

たとえば以下のようにケースを持たせて実行します。

class ValidationTraitTest extends TestCase
{
  public function testA() {\Log::info('A');}
  public function testB() {\Log::info('B');}
  public function testC() {\Log::info('C');}
}

ログファイルが"A B C"となることを期待しますが、"A"としか出力されません。
testA()をコメントアウトして実行すると今度は"B"とだけ出力されます。
testB()もコメントアウトすると今度は"C"になります。

3ケース実行後のターミナルには

OK, but incomplete, skipped, or risky tests!
Tests: 3, Assertions: 0, Risky: 3.

と表示されていますから、すべてのテストケースは実行されているようですが、一番最初に実行されるケースの出力しかされません。

この理由は何でしょうか？
それぞれで出力したいのですが、方法はあるでしょうか。

試したこと

public function testA() {\Log::info('A1');\Log::info('A2');$this->assertTrue(true);}
public function testB() {\Log::info('B');$this->assertTrue(true);}
public function testC() {\Log::info('C');$this->assertTrue(true);}

とすると"A1 A2"とは出力されるので、
Logのほうで1つ目の出力しかしないのではなくて、テストランナーのほうで1つ目のケースしか出力していないように見えました。

それと、各ケース内でログ出力だけではなく簡単なアサーションを1つ実行してもいます。つまりテストランナーが実行事前にケース内を解釈して実行不要（アサーションなし）だから実行しておらずログ出力されない、ということもないと考えています。

なんとなく、各ケース内でテストコンテキスト？を毎回初期化すると良いような感覚を持ちました。標題と少しズレますが、複数のケースがあって連続して実行されるとき、ケース内での状態はコンテキストとして次のケースに持ち越されて実行されているのでしょうか。初期化方法などあるでしょうか。

補足

Risky: 3 は、「テストケース内にアサーションが1つもない（のでパスしているとは言えず危険な）」ケースが3つあるという指摘です。
ログ出力は入れても入れなくても同じで、$this->assertTrue(true);のようなアサーションを入れると指摘が収まります。
また、アサーションを入れてRiskyを抑えても、最初に実行されるケースでしかログ出力されない状況は変わりません。

例として単純化するためにアサーションを入れませんでした。
Tests: 3, Assertions: 0, Risky: 3.
の Risky は問題でなく、Tests: 3で期待どおり3ケースすべて実行されている（のにログ出力は最初だけな）ことをお伝えするため示しております。

コード

以下は当件テストコード全文です。
Laravel インストール時につくられる ExampleTest.php のメソッドだけを編集したコードになります。

<?php

namespace Tests\Unit;

use Tests\TestCase;
use Illuminate\Foundation\Testing\RefreshDatabase;

class ExampleTest extends TestCase
{
    public function testA() {\Log::info('A');$this->assertTrue(true);}
    public function testB() {\Log::info('B');$this->assertTrue(true);}
    public function testC() {\Log::info('C');$this->assertTrue(true);}
}

ご興味持って頂けたかたは、上記全文をそのまま プロジェクトディレクトリ/tests/SampleTest.php のようなファイル名で保存して実行してみてください。
storage/logs/内のログファイルには"A"としか出力されないはずです。

$ ./vendor/bin/phpunit tests/SampleTest

Comments

[fagai]

テスト結果にRisky: 3とでており、危険なテストと認識されていますね。試しにログを出力しない場合はどうでしょうか？

[utatane]

ありがとうございます。ここには1行しかリプライできないようでしたので、質問に「補足」「コード」を追記しました！

[fagai]

追記ありがとうございます。ちょっとこちらでも試してみようと思います。

Answer 1

一度やってみたのですが、正常に動作しました。(PHP7.1.2を利用)

$ vendor/bin/phpunit tests/Unit/ExampleTest
PHPUnit 6.3.0 by Sebastian Bergmann and contributors.

...                                                                 3 / 3 (100%)

Time: 249 ms, Memory: 10.00MB

OK (3 tests, 3 assertions)

時間がUTC時間になっているのは変え忘れただけです

[2017-09-26 04:31:29] testing.INFO: A  
[2017-09-26 04:31:29] testing.INFO: B  
[2017-09-26 04:31:29] testing.INFO: C 

試しにcomposer updateをやってみてはどうでしょうか？
5.5.0が出てからすでに幾つもの修正がされているようなので、影響しているかもしれません。
なお私が確認したのはv5.5.9でした。

Comments

[utatane]

`composer update`は頻繁にしているのですが、状況変わりません。

再現なさらないということで、環境によるかもしれないことがわかりました。ありがとうございます。

当方も素のインストール状態ですので意外でしたが、、再インストールや別環境でも試したいと思います。

[fagai]

それは謎ですね。。。
私は今回確認にmac(homebrewでphpを入れたもの)を利用しました。
win環境でも確認してみますね

[fagai]

win環境(php7.0.10)でも動作いたしましたので一応報告しておきますね。

Answer 2

解決という表現ではないのですが、
その後、別マシンが2台あるのですがどちらでも再現しないことがわかりました。
そして、質問時のマシンで今ひさしぶりに再現させてみたら、しませんでした。

推測ですが、インストールパッケージや拡張、ミドルウェア、phpunitの細かいバージョンの相性？や一過性の不具合等の環境でたまたま発生した状況で、日々アップデートしているなかで再現しなくなった感覚です（あくまで感覚です）。
PHPまわりはすべてHomebrewとComposerでまとめています。

明快に原因理解できませんでしたが、
おそらく環境のせいであってアップデートしていれば勝手に直る、自分が書いたコードのせいではなさそう、というのは同現象でこの質問を見る人にとってはひとつの情報ですので記しておきます。

またご回答や再現等にお付き合いくださった方にもお礼申し上げます。

Answer 3

回答とはずれてしまうのですが、私の環境(Laravel5.4)では下記の様に動作しましたのでご報告します。

テストコード

<?php

namespace Tests\Unit;

use Tests\TestCase;
use Illuminate\Foundation\Testing\DatabaseMigrations;
use Illuminate\Foundation\Testing\DatabaseTransactions;

class ExampleTest extends TestCase
{
    public function testA() {\Log::info('A');$this->assertTrue(true);}
    public function testB() {\Log::info('B');$this->assertTrue(true);}
    public function testC() {\Log::info('C');$this->assertTrue(true);}
}

実行結果

PHPUnit 5.7.17 by Sebastian Bergmann and contributors.

....                                                                4 / 4 (100%)

Time: 714 ms, Memory: 12.00MB

OK (4 tests, 4 assertions)
完了。

出力ログ

[2017-09-26 04:35:13] local.INFO: A  
[2017-09-26 04:35:13] local.INFO: B  
[2017-09-26 04:35:13] local.INFO: C  

私はvendor/bin/phpunitを使っていますが、それを使われていない可能性はありませんか？

Comments

[utatane]

ありがとうございます。
`vendor/bin/phpunit`にて実行しております。
他のご回答者と同じく期待どおりに動作なさるということで、当件は環境によりそうです。

ただ、当方も素のインストール状態ですので、何が原因かいま思い当たりませんが、、環境を変えて試してみます。ありがとうございます！