Using Java 8 to Prevent Excessively Wide Logs

Some logs are there to be consumed by machines and kept forever.

Other logs are there just to debug and to be consumed by humans. In the latter case, you often want to make sure that you don’t produce too much logs, especially not too wide logs, as many editors and other tools have problems once line lenghts exceed a certain size (e.g. this Eclipse bug).

String manipulation used to be a major pain in Java, with lots of tedious-to-write loops and branches, etc. No longer with Java 8!

The following truncate method will truncate all lines within a string to a certain length:

public String truncate(String string) {
    return truncate(string, 80);
}

public String truncate(String string, int length) {
    return Seq.of(string.split("\n"))
              .map(s -> StringUtils.abbreviate(s, 400))
              .join("\n");
}

The above example uses jOOλ 0.9.4 and Apache Commons Lang, but you can achieve the same using vanilla Java 8, of course:

public String truncate(String string) {
    return truncate(string, 80);
}

public String truncate(String string, int length) {
    return Stream.of(string.split("\n"))
                 .map(s -> s.substring(0, Math.min(s.length(), length)))
                 .collect(Collectors.joining("\n"));
}

The above when truncating logs to length 10, the above program will produce:

Input

Lorem ipsum dolor sit amet, consectetur adipiscing elit, sed do eiusmod tempor
incididunt ut labore et dolore magna aliqua. Ut enim ad minim veniam, quis
nostrud exercitation ullamco laboris nisi ut aliquip ex ea commodo consequat.
Duis aute irure dolor in reprehenderit in voluptate velit esse cillum dolore eu
fugiat nulla pariatur. Excepteur sint occaecat cupidatat non proident, sunt in
culpa qui officia deserunt mollit anim id est laborum.

Output

Lorem ipsum dolor...
incididunt ut lab...
nostrud exercitat...
Duis aute irure d...
fugiat nulla pari...
culpa qui officia...

Happy logging!

PL/SQL backtraces for debugging

For many PL/SQL developers, this might be common sense, but for one of our customers, this was an unknown PL/SQL feature: Backtraces.

When your application raises an error somewhere deep down in the call stack, you don’t get immediate information about the exact source of the error. For large PL/SQL applications, this can be a pain. One workaround is to keep track of statement numbers that were last executed before any error occurred:

DECLARE
  v_statement_no := 0;
BEGIN
  v_statement_no := 1;
  SELECT ...

  v_statement_no := 2;
  INSERT ...

  v_statement_no := 3;
  ...
EXCEPTION
  WHEN OTHERS THEN
    -- Log error message somewhere
    logger.error(module, v_statement_no, sqlerrm);
END;

The above looks an awful lot like println-debugging, a thing that isn’t really known to Java developers ;-)

But println-debugging isn’t necessary in PL/SQL either. Use the DBMS_UTILITY.FORMAT_ERROR_BACKTRACE function, instead! An example:

DECLARE
  PROCEDURE p4 IS BEGIN
    raise_application_error(-20000, 'Some Error');
  END p4;
  PROCEDURE p3 IS BEGIN
    p4;
  END p3;
  PROCEDURE p2 IS BEGIN
    p3;
  END p2;
  PROCEDURE p1 IS BEGIN
    p2;
  END p1;

BEGIN
  p1;
EXCEPTION
  WHEN OTHERS THEN
    dbms_output.put_line(sqlerrm);
    dbms_output.put_line(
      dbms_utility.format_error_backtrace
    );
END;
/

The above PL/SQL block generates the following output:

ORA-20000: Some Error
ORA-06512: at line 3
ORA-06512: at line 6
ORA-06512: at line 9
ORA-06512: at line 12
ORA-06512: at line 16

You can see exactly what line number generated the error. If you’re not using local procedures in anonymous blocks (which you quite likely aren’t), this gets even more useful:

CREATE PROCEDURE p4 IS BEGIN
  raise_application_error(-20000, 'Some Error');
END p4;
/
CREATE PROCEDURE p3 IS BEGIN
  p4;
END p3;
/
CREATE PROCEDURE p2 IS BEGIN
  p3;
END p2;
/
CREATE PROCEDURE p1 IS BEGIN
  p2;
END p1;
/

BEGIN
  p1;
EXCEPTION
  WHEN OTHERS THEN
    dbms_output.put_line(sqlerrm);
    dbms_output.put_line(
      dbms_utility.format_error_backtrace
    );
END;
/

The above now outputs:

ORA-20000: Some Error
ORA-06512: at "PLAYGROUND.P4", line 2
ORA-06512: at "PLAYGROUND.P3", line 2
ORA-06512: at "PLAYGROUND.P2", line 2
ORA-06512: at "PLAYGROUND.P1", line 2
ORA-06512: at line 2

To learn more about the DBMS_UTILITY package, please consider the manual. True to the nature of all things called “UTILITY”, it really contains pretty much random things that you wouldn’t expect there :-)

Debug logging SQL with jOOQ

This nice little feature is not much advertised in the jOOQ manual, but probably it’s something that most of us developers want and love when we have it. When you put log4j or slf4j on the classpath along with jOOQ, then jOOQ will use those frameworks for logging according to your configuration. While jOOQ is pretty quiet on ERROR/WARN/INFO level logging, it becomes quite a chatty tool on DEBUG/TRACE level.

DEBUG level logging example

Check out some sample DEBUG level output when executing this query:

Result<Record> result = create
  .select(TAuthor.LAST_NAME, create.count().as("c"))
  .from(T_BOOK)
  .join(T_AUTHOR)
  .on(TBook.AUTHOR_ID.equal(TAuthor.ID))
  .where(TBook.TITLE.notEqual("1984"))
  .groupBy(TAuthor.LAST_NAME)
  .having(create.count().equal(2))
  .fetch();

And the output is:


Executing query          : select "t_author"."last_name", 
  count(*) as "c" from "t_book" join "t_author" on 
  "t_book"."author_id" = "t_author"."id" where 
  "t_book"."title" <> '1984' group by "t_author"."last_name"
  having count(*) = 2

Fetched result           : +---------+----+
                         : |last_name|   c|
                         : +---------+----+
                         : |Coelho   |   2|
                         : +---------+----+
Statement executed       : Total: 3.911ms


The query text is printed to the log output with inlined parameters (i.e. bind variables are replaced for logging). Then a text table representation of the result’s first 5 rows is printed before the query execution time.

TRACE level logging example

On trace level, you can see even more of jOOQ’s internals, although usually this is only needed when debugging jOOQ:


Executing query          : select "t_author"."last_name", 
  count(*) as "c" from "t_book" join "t_author" on 
  "t_book"."author_id" = "t_author"."id" where 
  "t_book"."title" <> '1984' group by "t_author"."last_name"
  having count(*) = 2

Preparing statement      : select "t_author"."last_name", 
  count(*) as "c" from "t_book" join "t_author" on 
  "t_book"."author_id" = "t_author"."id" where 
  "t_book"."title" <> cast(? as varchar) 
  group by "t_author"."last_name" 
  having count(*) = cast(? as int)

Statement prepared       : Total: 1.451ms, +0.435ms
Binding variable 1       : 1984 (class java.lang.String)
Binding variable 2       : 2 (class java.lang.Integer)
Variables bound          : Total: 1.808ms, +0.356ms
Attaching                : RecordImpl [ RecordImpl [values=[null, null]] ]
Fetching record          : RecordImpl [values=[Coelho, 2]]
Fetched result           : +---------+----+
                         : |last_name|   c|
                         : +---------+----+
                         : |Coelho   |   2|
                         : +---------+----+
Statement executed       : Total: 6.29ms, +4.481ms


In addition to the previously shown DEBUG-level output, you’ll also find the true SQL statement that is executed, including bind variables and some additional type-casts introduced by jOOQ. Time measuring is divided into 3 steps: statement preparing, variable binding, and statement execution. Also, all bind variables are documented, and every fetched record is documented. That’s a lot of logging. Be sure to turn it off when not needed!

Logging configuration

In future versions of jOOQ, logging will become more configurable