DebugTrace-java チュートリアル

DebugTraceについて

デバッグには主に2つの方法があります。

  1. EclipseVisual StudioなどのIDEを使用してブレークポイントで停止させステップ実行する。
  2. プログラムの各所にデバッグ用のログ出力文を挿入する。

1の方法でバグが見つかる場合はそれで良いのですが、複数スレッドで動作するなど複雑なプログラムの場合は、(準備の手間はかかりますが)2の方法の方がバグを見つけやすい場合もあります。

DebugTraceは、2の方法でのデバッグを支援するライブラリです。言語毎にリリースされていて、以下があります。

リフレクションの機能の有無(C++にはない)、メモリ管理方法(ガベッジコレクションを行うかどうか)および命名規約によってそれぞれの言語用のDebugTraceのAPIは異なっていますが、できる事は主に以下の2つです。

  1. メソッド(あるいは関数)の開始時と終了時にログを出力する。またその間のログ出力のインデントを1増やす。
  2. 必要に応じてリフレクションを使用して変数内容をログに出力する。また見易くするため、必要に応じて改行、インデントを行う。

プロジェクト(Java)の作成

AdoptOpenJDKのOpenJDK 11 (LTS)およびEclipse IDE 2020-09 (4.17)を使用するのでインストールします。 JDKはAdoptOpenJDK以外でもかまいません。 Pleiadesを使用して日本語化している場合は、以下の内容を適宜日本語に置き換えてください。

  1. Eclipse起動後に[File]-[New]-[Project...]を実行します。
  2. Wizardの選択ダイアログが表示されるので、Gradle/Gradle Projectを選択して[Next>]をクリックします。
  3. Welcomeダイアログが表示されるので、[Next>]をクリックします。
  4. New Gradle Projectダイアログが表示されるので、Project name:DebugTraceJavaTutorialを入力します。
  5. 入力後[Finish]をクリックするとプロジェクトが作成されます。

生成されたbuild.gradleを以下の内容に置き換えます。

plugins {
    id 'java-library'
}

repositories {
    jcenter()
}

dependencies {
    testImplementation 'org.junit.jupiter:junit-jupiter:5.7.+'
    testImplementation 'org.junit.jupiter:junit-jupiter-params:5.7.+'

    compileOnly        'org.debugtrace:debugtrace:3.+'
    testImplementation 'org.debugtrace:debugtrace:3.+'
}

sourceCompatibility = '11'
targetCompatibility = '11'

生成されたソース(src/main/java内)をフォルダ毎削除して以下のJavaソースを追加します。
パス: src/main/java/org/debugtrace/tutorial/Tutorial1.java

package org.debugtrace.tutorial;

public class Tutorial1 {
    public static int maxLogByteArrayLength = 1024;

    /**
     * バイト配列の文字列表現をStringBuilderに追加する。
     * @param builder StringBuilder
     * @param bytes バイト配列
     * @return 引数のbuilder
     */
    public static StringBuilder appendBytes(StringBuilder builder, byte[] bytes) {
        builder.append('[');
        var delimiter = "";
        for (var index = 0; index < bytes.length; ++index) {
            builder.append(delimiter);
            if (index >= maxLogByteArrayLength) {
                builder.append("...");
                break;
            }
            var value = bytes[index];
            if (value < 0) value += 256;
            var ch = (char)(value / 16 + '0');
            if (ch > '9') ch += 'A' - '9' - 1;
            builder.append(ch);
            ch = (char)(value % 16 + '0');
            if (ch > '9') ch += 'A' - '9' - 1;
            builder.append(ch);
            delimiter = ", ";
        }
        builder.append(']');

        return builder;
    }
}

生成されたテストソース(src/test/java内)をフォルダ毎削除して以下のJavaソースを追加します。
パス: src/test/java/org/debugtrace/tutorial/Tutorial1Test.java

package org.debugtrace.tutorial;
import static org.junit.jupiter.api.Assertions.assertEquals;
import java.util.stream.Stream;
import org.junit.jupiter.params.ParameterizedTest;
import org.junit.jupiter.params.provider.Arguments;
import org.junit.jupiter.params.provider.MethodSource;

public class Tutorial1Test {
    /**
     * appendBytesのテスト。
     * @param bytes バイト配列
     * @param expected StringBuilderに追加されると期待する文字列
     */
    @ParameterizedTest
    @MethodSource("testAppendBytesParams")
    public void testAppendBytes(byte[] bytes, String expected) {
        // when
        var builder = Tutorial1.appendBytes(new StringBuilder(), bytes);

        // then
        assertEquals(expected, builder.toString());
    }

    static Stream<Arguments> testAppendBytesParams() {
        return Stream.of(
            Arguments.of(new byte[] {}, "[]"),
            Arguments.of(new byte[] {1}, "[01]"),
            Arguments.of(
                new byte[] {0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15},
                "[00, 01, 02, 03, 04, 05, 06, 07, 08, 09, 0A, 0B, 0C, 0D, 0E, 0F]"
            ),
            Arguments.of(
                new byte[] {-16, -15, -14, -13, -12, -11, -10, -9, -8, -7, -6, -5, -4, -3, -2, -1},
                "[F0, F1, F2, F3, F4, F5, F6, F7, F8, F9, FA, FB, FC, FD, FE, FF]"
            )
        );
    }
}

チュートリアル1

上記のtestAppendBytesはパラメータ付きのテストメソッドで、testAppendBytesParamsを呼び出して引数を受け取ります。 Arguments.of(...)が一度に渡す引数のセットになっています。

テストを実行すると最初の3つは成功しますが、最後の1つで失敗します。

org.opentest4j.AssertionFailedError: expected: <[F0, F1, F2, F3, F4, F5, F6, F7, F8, F9, FA, FB, FC, FD, FE, FF]> but was: <[/0, 0!, 0", 0#, 0$, 0%, 0&, 0', 0(, 0), 0*, 0+, 0,, 0-, 0., 0/]>

対象のメソッドとテストメソッドにDebugTrace-javaのメソッドを呼び出すコードを挿入してみます。

package org.debugtrace.tutorial;
import org.debugtrace.DebugTrace;

public class Tutorial1 {
    public static int maxLogByteArrayLength = 1024;

    /**
     * バイト配列の文字列表現をStringBuilderに追加する。
     * @param builder StringBuilder
     * @param bytes バイト配列
     * @return 引数のbuilder
     */
    public static StringBuilder appendBytes(StringBuilder builder, byte[] bytes) {
        DebugTrace.enter(); // TODO: Delete after debugging
        DebugTrace.print("bytes", bytes); // TODO: Delete after debugging
        builder.append('[');
        var delimiter = "";
        for (var index = 0; index < bytes.length; ++index) {
            DebugTrace.print("index", index); // TODO: Delete after debugging
            builder.append(delimiter);
            if (index >= maxLogByteArrayLength) {
                builder.append("...");
                break;
            }
            var value = bytes[index];
            DebugTrace.print("1 value", value); // TODO: Delete after debugging
            if (value < 0) value += 256;
            DebugTrace.print("2 value", value); // TODO: Delete after debugging
            var ch = (char)(value / 16 + '0');
            DebugTrace.print("1-1 ch", ch); // TODO: Delete after debugging
            if (ch > '9') ch += 'A' - '9' - 1;
            DebugTrace.print("1-2 ch", ch); // TODO: Delete after debugging
            builder.append(ch);
            ch = (char)(value % 16 + '0');
            DebugTrace.print("2-1 ch", ch); // TODO: Delete after debugging
            if (ch > '9') ch += 'A' - '9' - 1;
            DebugTrace.print("2-2 ch", ch); // TODO: Delete after debugging
            builder.append(ch);
            delimiter = ", ";
        }
        builder.append(']');

        DebugTrace.leave(); // TODO: Delete after debugging
        return builder;
    }
}
package org.debugtrace.tutorial;
import static org.junit.jupiter.api.Assertions.assertEquals;
import java.util.stream.Stream;
import org.debugtrace.DebugTrace;
import org.junit.jupiter.params.ParameterizedTest;
import org.junit.jupiter.params.provider.Arguments;
import org.junit.jupiter.params.provider.MethodSource;

public class Tutorial1Test {
    /**
     * appendBytesのテスト。
     * @param bytes バイト配列
     * @param expected StringBuilderに追加されると期待する文字列
     */
    @ParameterizedTest
    @MethodSource("testAppendBytesParams")
    public void testAppendBytes(byte[] bytes, String expected) {
        DebugTrace.enter(); // TODO: Delete after debugging
        // when
        var builder = Tutorial1.appendBytes(new StringBuilder(), bytes);

        // then
        assertEquals(expected, builder.toString());
        DebugTrace.leave(); // TODO: Delete after debugging
    }

    static Stream<Arguments> testAppendBytesParams() {
        return Stream.of(
            Arguments.of(new byte[] {}, "[]"),
            Arguments.of(new byte[] {1}, "[01]"),
            Arguments.of(
                new byte[] {0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15},
                "[00, 01, 02, 03, 04, 05, 06, 07, 08, 09, 0A, 0B, 0C, 0D, 0E, 0F]"
            ),
            Arguments.of(
                new byte[] {-16, -15, -14, -13, -12, -11, -10, -9, -8, -7, -6, -5, -4, -3, -2, -1},
                "[F0, F1, F2, F3, F4, F5, F6, F7, F8, F9, FA, FB, FC, FD, FE, FF]"
            )
        );
    }
}

もう一度テストを実行してみます。以下は上記を実行したログの一部です。ログはデフォルトで標準エラー(stderr)に出力されます。Eclipseで実行した場合は、Consoleに出力されます。

2020-11-02 14:59:58.346+09:00 Enter org.debugtrace.tutorial.Tutorial1Test.testAppendBytes (Tutorial1Test.java:20)
2020-11-02 14:59:58.347+09:00 | Enter org.debugtrace.tutorial.Tutorial1.appendBytes (Tutorial1.java:16)
2020-11-02 14:59:58.347+09:00 | | bytes = (byte[16])[F0 F1 F2 F3 F4 F5 F6 F7 F8 F9 FA FB FC FD FE FF] (Tutorial1.java:17)
2020-11-02 14:59:58.347+09:00 | | index = 0 (Tutorial1.java:21)
2020-11-02 14:59:58.348+09:00 | | 1 value = (byte)-16 (Tutorial1.java:28)
2020-11-02 14:59:58.348+09:00 | | 2 value = (byte)-16 (Tutorial1.java:30)
2020-11-02 14:59:58.348+09:00 | | 1-1 ch = '/' (Tutorial1.java:32)
2020-11-02 14:59:58.348+09:00 | | 1-2 ch = '/' (Tutorial1.java:34)
2020-11-02 14:59:58.349+09:00 | | 2-1 ch = '0' (Tutorial1.java:37)
2020-11-02 14:59:58.349+09:00 | | 2-2 ch = '0' (Tutorial1.java:39)

バイト配列の最初のF0の1桁目のF'/'に間違って変換されています。2 value =の箇所は正値を期待しているのですが、負値のままです。 これはvar value = bytes[index];で、value変数がbyteなのが原因なので、var value = (int)bytes[index];に修正します。

修正後もう一度テストを実行すると成功します。ログの一部は以下になります。

2020-11-02 15:03:51.930+09:00 Enter org.debugtrace.tutorial.Tutorial1Test.testAppendBytes (Tutorial1Test.java:20)
2020-11-02 15:03:51.931+09:00 | Enter org.debugtrace.tutorial.Tutorial1.appendBytes (Tutorial1.java:16)
2020-11-02 15:03:51.931+09:00 | | bytes = (byte[16])[F0 F1 F2 F3 F4 F5 F6 F7 F8 F9 FA FB FC FD FE FF] (Tutorial1.java:17)
2020-11-02 15:03:51.931+09:00 | | index = 0 (Tutorial1.java:21)
2020-11-02 15:03:51.932+09:00 | | 1 value = -16 (Tutorial1.java:29)
2020-11-02 15:03:51.932+09:00 | | 2 value = 240 (Tutorial1.java:31)
2020-11-02 15:03:51.932+09:00 | | 1-1 ch = '?' (Tutorial1.java:33)
2020-11-02 15:03:51.932+09:00 | | 1-2 ch = 'F' (Tutorial1.java:35)
2020-11-02 15:03:51.933+09:00 | | 2-1 ch = '0' (Tutorial1.java:38)
2020-11-02 15:03:51.933+09:00 | | 2-2 ch = '0' (Tutorial1.java:40)

デバッグの終了後にデバッグ用コードを削除するには、正規表現で検索して空文字列に置換します。改行コードも削除しているのでデバッグ用コードを挿入する前のソースに戻ります。

正規表現検索文字列: ^.+DebugTrace.*\r?\n

チュートリアル2

次のチュートリアルのソースとテストソースは以下です。
パス: src/main/java/org/debugtrace/tutorial/Tutorial2.java

package org.debugtrace.tutorial;
import java.util.Objects;

public class Tutorial2 {
    /**
     * クラス名を返します。ただしjava.xxxパッケージの場合はパッケージ名を取り除いて返します。
     * @param clazz クラス
     * @return クラス名
     * @throws NullPointerException clazzがnullの場合
     */
    public static String getName(Class<?> clazz) {
        if (Objects.requireNonNull(clazz, "clazz is null.").isArray())
            return getName(clazz.getComponentType()) + "[]";

        String className = clazz.getName();
        if (className.startsWith("java"))
            return className.substring(className.lastIndexOf('.') + 1);

        return className;
    }
}

パス: src/test/java/org/debugtrace/tutorial/Tutorial2Test.java

package org.debugtrace.tutorial;
import static org.junit.jupiter.api.Assertions.assertEquals;
import java.util.stream.Stream;
import javax.sql.RowSet;
import org.junit.jupiter.params.ParameterizedTest;
import org.junit.jupiter.params.provider.Arguments;
import org.junit.jupiter.params.provider.MethodSource;

public class Tutorial2Test {
    /**
     * getNameのテスト。
     * @param clazz クラス
     * @param expected 期待するクラス名
     */
    @ParameterizedTest
    @MethodSource("testGetNameParams")
    public void testGetName(Class<?> clazz, String expected) {
        // when
        var className = Tutorial2.getName(clazz);

        // then
        assertEquals(expected, className);
    }

    static Stream<Arguments> testGetNameParams() {
        return Stream.of(
            Arguments.of(String.class, "String"),
            Arguments.of(String[].class, "String[]"),
            Arguments.of(String[][].class, "String[][]"),
            Arguments.of(RowSet.class, "javax.sql.RowSet"),
            Arguments.of(RowSet[].class, "javax.sql.RowSet[]"),
            Arguments.of(RowSet[][].class, "javax.sql.RowSet[][]")
        );
    }
}

実行すると最初の3つで成功しますが、後の3つでは失敗します。

org.opentest4j.AssertionFailedError: expected: <javax.sql.RowSet> but was: <RowSet>

デバッグコードを挿入しますが、メソッドが終了する箇所が3箇所あるため、DebugTrace.leaveメソッドの呼び出しをgetNameメソッドの最後に挿入だけでは不十分です。 この場合は、以下のようにします。

package org.debugtrace.tutorial;
import java.util.Objects;
import org.debugtrace.DebugTrace;

public class Tutorial2 {
    /**
     * クラス名を返します。ただしjava.xxxパッケージの場合はパッケージ名を取り除いて返します。
     * @param clazz クラス
     * @return クラス名
     * @throws NullPointerException clazzがnullの場合
     */
    public static String getName(Class<?> clazz) {
        try {DebugTrace.enter(); // TODO: Delete after debugging
        DebugTrace.print("clazz", clazz); // TODO: Delete after debugging
        if (Objects.requireNonNull(clazz, "clazz is null.").isArray())
            return getName(clazz.getComponentType()) + "[]";

        String className = clazz.getName();
        DebugTrace.print("className", className); // TODO: Delete after debugging
        DebugTrace.print("className.startsWith(\"java\")", className.startsWith("java")); // TODO: Delete after debugging
        if (className.startsWith("java"))
            return className.substring(className.lastIndexOf('.') + 1);

        return className;
        } finally {DebugTrace.leave();} // TODO: Delete after debugging
    }
}

テスト対象のメソッド全体をtry {DebugTrace.enter();} finally {DebugTrace.leave();}で囲います。 テストメソッドの方はチュートリアル1と同様にします。
テストを実行すると以下のログ(失敗している部分)が出力されます。

2020-11-02 15:28:39.405+09:00 Enter org.debugtrace.tutorial.Tutorial2Test.testGetName (Tutorial2Test.java:22)
2020-11-02 15:28:39.408+09:00 | Enter org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:16)
2020-11-02 15:28:39.414+09:00 | | clazz = (Class)interface javax.sql.RowSet (Tutorial2.java:17)
2020-11-02 15:28:39.415+09:00 | | className = (length:16)"javax.sql.RowSet" (Tutorial2.java:22)
2020-11-02 15:28:39.418+09:00 | | className.startsWith("java") = true (Tutorial2.java:23)
2020-11-02 15:28:39.420+09:00 | Leave org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:28) duration: 00:00:00.005
2020-11-02 15:28:39.444+09:00 | 
2020-11-02 15:28:39.450+09:00 | Enter org.debugtrace.tutorial.Tutorial2Test.testGetName (Tutorial2Test.java:22)
2020-11-02 15:28:39.450+09:00 | | Enter org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:16)
2020-11-02 15:28:39.451+09:00 | | | clazz = (Class)class [Ljavax.sql.RowSet; (Tutorial2.java:17)
2020-11-02 15:28:39.451+09:00 | | | Enter org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:16)
2020-11-02 15:28:39.451+09:00 | | | | clazz = (Class)interface javax.sql.RowSet (Tutorial2.java:17)
2020-11-02 15:28:39.451+09:00 | | | | className = (length:16)"javax.sql.RowSet" (Tutorial2.java:22)
2020-11-02 15:28:39.458+09:00 | | | | className.startsWith("java") = true (Tutorial2.java:23)
2020-11-02 15:28:39.461+09:00 | | | Leave org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:28) duration: 00:00:00.006
2020-11-02 15:28:39.461+09:00 | | Leave org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:28) duration: 00:00:00.010
2020-11-02 15:28:39.474+09:00 | | 
2020-11-02 15:28:39.475+09:00 | | Enter org.debugtrace.tutorial.Tutorial2Test.testGetName (Tutorial2Test.java:22)
2020-11-02 15:28:39.476+09:00 | | | Enter org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:16)
2020-11-02 15:28:39.476+09:00 | | | | clazz = (Class)class [[Ljavax.sql.RowSet; (Tutorial2.java:17)
2020-11-02 15:28:39.476+09:00 | | | | Enter org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:16)
2020-11-02 15:28:39.477+09:00 | | | | | clazz = (Class)class [Ljavax.sql.RowSet; (Tutorial2.java:17)
2020-11-02 15:28:39.483+09:00 | | | | | Enter org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:16)
2020-11-02 15:28:39.484+09:00 | | | | | | clazz = (Class)interface javax.sql.RowSet (Tutorial2.java:17)
2020-11-02 15:28:39.485+09:00 | | | | | | className = (length:16)"javax.sql.RowSet" (Tutorial2.java:22)
2020-11-02 15:28:39.491+09:00 | | | | | | className.startsWith("java") = true (Tutorial2.java:23)
2020-11-02 15:28:39.491+09:00 | | | | | Leave org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:28) duration: 00:00:00.007
2020-11-02 15:28:39.492+09:00 | | | | Leave org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:28) duration: 00:00:00.014
2020-11-02 15:28:39.492+09:00 | | | Leave org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:28) duration: 00:00:00.016

テスト毎にネストが深くなっていきますが、テストが失敗した場合は、途中で例外がスローされてテストメソッドのDebugTrace.leave()が呼ばれないためです。そこでテストメソッドもtry {}finally{}を使用します。

package org.debugtrace.tutorial;
import static org.junit.jupiter.api.Assertions.assertEquals;
import java.util.stream.Stream;
import javax.sql.RowSet;
import org.debugtrace.DebugTrace;
import org.junit.jupiter.params.ParameterizedTest;
import org.junit.jupiter.params.provider.Arguments;
import org.junit.jupiter.params.provider.MethodSource;

public class Tutorial2Test {
    /**
     * getNameのテスト。
     * @param clazz クラス
     * @param expected 期待するクラス名
     */
    @ParameterizedTest
    @MethodSource("testGetNameParams")
    public void testGetName(Class<?> clazz, String expected) {
        try {DebugTrace.enter(); // TODO: Delete after debugging
        // when
        var className = Tutorial2.getName(clazz);

        // then
        assertEquals(expected, className);
        } finally {DebugTrace.leave();} // TODO: Delete after debugging
    }

    static Stream<Arguments> testGetNameParams() {
        return Stream.of(
            Arguments.of(String.class, "String"),
            Arguments.of(String[].class, "String[]"),
            Arguments.of(String[][].class, "String[][]"),
            Arguments.of(RowSet.class, "javax.sql.RowSet"),
            Arguments.of(RowSet[].class, "javax.sql.RowSet[]"),
            Arguments.of(RowSet[][].class, "javax.sql.RowSet[][]")
        );
    }
}

実行してみます。

2020-11-02 15:51:39.386+09:00 Enter org.debugtrace.tutorial.Tutorial2Test.testGetName (Tutorial2Test.java:21)
2020-11-02 15:51:39.387+09:00 | Enter org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:15)
2020-11-02 15:51:39.387+09:00 | | clazz = (Class)interface javax.sql.RowSet (Tutorial2.java:16)
2020-11-02 15:51:39.388+09:00 | | className = (length:16)"javax.sql.RowSet" (Tutorial2.java:21)
2020-11-02 15:51:39.388+09:00 | | className.startsWith("java") = true (Tutorial2.java:22)
2020-11-02 15:51:39.388+09:00 | Leave org.debugtrace.tutorial.Tutorial2.getName (Tutorial2.java:27) duration: 00:00:00.001
2020-11-02 15:51:39.390+09:00 Leave org.debugtrace.tutorial.Tutorial2Test.testGetName (Tutorial2Test.java:27) duration: 00:00:00.002

テストが失敗する原因は、javax.sql.RowSetの場合は、falseになって欲しいif (className.startsWith("java"))が原因なので、if (className.startsWith("java."))に修正します。

デバッグ終了後は、チュートリアル1と同様にデバッグ用コードを削除します。

まとめ

  • チュートリアル1: デバッグコードを挿入する対象のメソッドの終了箇所が1箇所でかつ例外をスローしない場合
    (または例外がスローされた場合にインデントが正しくなくても良い場合)
  • チュートリアル2: デバッグコードを挿入する対象のメソッドの終了箇所が複数か途中で例外をスローする可能性がある場合

以上でチュートリアルは終了です。