The Build Was Green the Whole Time

· 11 min read
Contents
  • 12:06. irc-bot, freshly ported from Spring Boot to Micronaut 5.0.6, is committed with fourteen passing tests.
  • 13:35. A test I had just written fails on a class name.
  • 13:56. A sanitiser build of the group's C IRC daemon names the line where it writes to address zero.
  • 19:15. The bot is launched against a real IRC network for the first time. By 19:20 there are three more failures on the list.

Five failures in one afternoon. None of them broke compilation, and none of them tripped a test that existed before I went looking. They turned up because something finally ran: a proxy check, a socket, a live launch.

Earlier the same day, the same repositories' upgrade failures mostly announced themselves, with errors that pointed at the wrong layer. The address was usually wrong, but the phone rang. These five never rang. That post left irc-bot on Spring Boot 4; this one starts after the port to Micronaut, which is why Micronaut does most of the damage. Assumes you know what an annotation processor and an AOP proxy are.

@Connectable compiled and proxied nothing#

Micronaut Data wants an open connection scope around every repository call. Spring Data JPA made repository methods implicitly transactional; Micronaut Data does not, and an unscoped call throws:

io.micronaut.data.connection.exceptions.NoConnectionException: No current connection present. Consider declaring @Connectable or @Transactional on the surrounding method

Thirty-four repository calls across six classes had no scope. Every listener descends from pircbotx's ListenerAdapter, whose onEvent is the single dispatch point, so one annotated override in the shared superclass looked like it would cover every listener at once:

// in IrcListenerAdapter, the shared superclass
@Override
@Connectable
public void onEvent(Event event) throws Exception {
    super.onEvent(event);
}

It compiled. It proxied nothing.

Micronaut generates around advice as a compile-time subclass of the bean: each advised method is overridden to run the interceptor, then call super. The bean under test was SeenListener, and SeenListener already declared its own onEvent, an override with no annotation on it. Micronaut's annotation-inheritance rules are blunt about what happens next: annotations "not meta-annotated with Inherited will not be included in the metadata." javap on micronaut-data-connection 5.0.6 shows @Connectable carries no @Inherited. So the override never picked it up, the compiler generated no proxy, and nothing warned. (A listener with no onEvent of its own is the other case. I never tested it; every listener got its own annotated override instead.)

It didn't ship because the test asserted the mechanism instead of the outcome:

assertThat(seenListener.getClass().getName()).contains("Intercepted");

A proxied bean's class name carries an $Intercepted suffix. This one came back com.ztomic.ircbot.listener.SeenListener: no suffix, no proxy, no scope. Asserting "a repository call succeeds" would have passed anyway, because AOP doesn't apply to JUnit test methods either, so the tests open their scopes by hand through TransactionOperations.executeRead. Assert the outcome and the harness quietly supplies what production is missing.

The fix is @Connectable on each concrete listener's own onEvent, plus DataExporter, the one non-IRC bean making its own calls. The instructive case is QuizChannelHandler, holder of seventeen of the thirty-four calls. The listener builds it with new and then hands it to beanContext.inject, so the container fills its fields but never gets the chance to wrap it. Calls it makes on the listener's thread borrow the listener's scope, because that listener is proxied. Its own run() does not: QuizChannelHandler is a Runnable handed to a plain ThreadPoolExecutor — ExecutorFactory's comment notes that the old JPA-binding executor is gone — so the repository calls inside run() sit outside any connection scope. That path never ran before the session ended; read from the code, it is a sixth bug still waiting. Annotating entry points beats annotating leaves, but a thread hop is a new entry point.

100% coverage, zero bytes handled#

The plan had been to point the bots at the group's own IRC daemon instead of a public network. The daemon cannot serve a single client.

Connecting is fine. Sending one line is not. Binary-searching the handshake:

  connect-only             SERVER ALIVE
  NICK                     SERVER DEAD (exit/signal 139)
  NICK+USER                SERVER DEAD (exit/signal 139)
  NICK+USER+JOIN           SERVER DEAD (exit/signal 139)

139 is 128 + 11, and 11 is SIGSEGV. An ASan + UBSan build, fed NICK probe\r\n, named the spot:

src/irc_server_main.c:272:5: runtime error: null pointer passed as argument 1, which is declared to never be null
AddressSanitizer:DEADLYSIGNAL
=================================================================
==2485094==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000000 (pc 0x7f13beb6a33a bp 0x7fff3c430b30 sp 0x7fff3c430558 T0)
==2485094==The signal is caused by a WRITE memory access.
==2485094==Hint: address points to the zero page.
    #0 0x7f13beb6a33a in __memcpy_avx512_unaligned_erms (/lib64/libc.so.6+0x16333a) (BuildId: 17f2e1fd905f485786f6fd6e3bede4ad737137e7)
    #1 0x00000040393b in handle_client_data src/irc_server_main.c:272
[…]

The register dump agrees: rdi, the destination, is 0x0; rdx, the length, is 0xc, the twelve bytes of NICK probe\r\n. A write of the client's first line to address zero.

The cause is one declaration, include/network.h:34:

char* read_buffer;

A pointer. Nothing, anywhere, allocates it. So line 272 does exactly what it was told:

// src/irc_server_main.c:272
memcpy(clients[client_idx].read_buffer + atomic_load(&clients[client_idx].read_buffer_pos),
       buffer, bytes_read);

memcpy into NULL + 0. The overflow guard just above it is real code, and it runs. It checks BUFFER_SIZE - read_buffer_pos - 1, and with read_buffer_pos at zero the check passes cleanly. It guards the length of a buffer that was never allocated.

The repository's baseline commit is titled "IRC Server baseline with 100% test coverage". Whatever those tests exercise, none of them drives a byte through handle_client_data, the first function every real client reaches. A coverage number that misses the front door sells a confidence nobody earned.

I have diagnosed this segfault. I have not fixed it.

Logging was off, and logback filed it under housekeeping#

At 19:15 irc-bot ran for the first time, pointed at Libera.Chat with an empty channel list: connect, sit still, join nothing. The run produced thirty-eight lines of output. None of them came from the application.

I'd rewritten a Spring-coupled logback-spring.xml (Boot's bundled defaults.xml, <springProperty>, Boot's LOG_FILE) into a neutral logback.xml, and put the root logger inside the conditional branches:

<if condition='isDefined("LOG_FILE")'>
  <then>  ...FILE appender... <root><appender-ref ref="FILE"/></root>  </then>
  <else>                      <root><appender-ref ref="CONSOLE"/></root> </else>
</if>

LOG_FILE was unset, so the <else> should have won. It didn't. The root logger came out with no appender at all, and every application log line went nowhere. Logback's complaint, in full:

19:14:55,114 |-WARN in ch.qos.logback.core.model.processor.AppenderModelHandler - Appender named [CONSOLE] not referenced. Skipping further processing.

That is the tone you reserve for an unused import. It meant the application had no logging.

The fix is dull: attach CONSOLE unconditionally, add FILE on top, let logback merge the two <root> elements.

The config file that didn't bind#

Two minutes later the second run got as far as a crash:

java.lang.NullPointerException: Cannot invoke "java.net.InetAddress.toString()" because "localAddress" is null
	at org.pircbotx.IdentServer.<init>(IdentServer.java:124)
	at org.pircbotx.IdentServer.startServer(IdentServer.java:95)
	at org.pircbotx.IdentServer.startServer(IdentServer.java:88)
	at org.pircbotx.IdentServer.startServer(IdentServer.java:78)
	at com.ztomic.ircbot.service.BotRunner.start(BotRunner.java:37)
[…]

BotRunner had started the ident server. start-ident: false is in both config files. The field initialiser for that flag is true.

Read that again. The setting said false, the default said true, and the running code used true. Configuration wasn't binding at all; every field kept its initialiser.

That crash had been waiting since the port. The first run hid it, because the logging bug sat directly on top of it. Two silent failures stacked, the upper one hiding the lower, and the lower one only became visible once the upper one was fixed.

The test I wrote that couldn't fail#

I would like to say all five were inherited. This one I wrote myself, a minute later, to confirm the binding failure:

@Test
void secretMasterKeyBinds() {
    // Present in application.yml; proves scalar binding beyond the boolean above.
    assertThat(ircConfiguration.getSecretMasterKey()).isNotBlank();
}

The suite's verdict:

  tests=3 failures=2 errors=0
    PASS  secretMasterKeyBinds
    FAIL  startIdentBindsFromConfigurationRatherThanTheFieldDefault
[…]
    FAIL  serverListBinds
[…]

It passed. It was worthless. The field's initialiser is a hard-coded "QuizBot", and despite what the comment says, secret-master-key isn't in application.yml at all. The assertion holds whether binding works, half-works, or never runs. Two red and one green looked like partial progress for the twenty-six seconds it took me to notice the default. The green was the test agreeing with itself.

The replacement asserts on a server hostname that comes from application.yml and has no field default, a value that can only appear if config bound. That's the whole rule, and the $Intercepted assertion had been following it without my noticing: when you test that a mechanism ran, assert on something the code cannot produce on its own. Any value the code can conjure with the system switched off is a value your test can pass on with the system switched off.

The YAML that stopped being YAML#

Lombok's setters were in the class file and Micronaut had generated the bean definition, so the machinery existed. That left the input. Running the config through a YAML parser by hand:

src/main/resources/application.yml: YAML PARSE FAILED -> ScannerError: while scanning for the next token
found character '@' that cannot start any token
  in "src/main/resources/application.yml", line 44, column 16

Line 44:

real-name: @artifactId@ by ztomic, v@version@

@ is a reserved indicator in YAML. The 1.2.2 spec parks @ and ` as "reserved for future use", which in practice means a plain scalar may not start with one. The parser gave up on the whole document, and the application started on field defaults as though no configuration existed.

Nobody had edited that line. It had worked for years because spring-boot-starter-parent turns on Maven resource filtering with @..@ placeholders, so the tokens were real strings before any YAML scanner saw them. (Spring's own example even wraps its placeholders in quotes.) Micronaut's parent POM does no such filtering. The port didn't touch the file. It removed the build behaviour underneath it.

Honest note: fixing the YAML did not fix binding. With a clean parse, the irc.* block still doesn't bind, and I have not proven why. Adding a lombok.config didn't move it.

What ran: one bot, bound by a record#

Before starting barnslig-micronaut I predicted it would bind, because it holds its configuration in a record. Pointed at irc.libera.chat:6667, it connected, bound its configuration, its ConnectionListener received the ClientConnectionEstablishedEvent, and startup took 2244 ms. Outbound channel traffic: zero, as intended, since it had no channels to join.

The record is the most visible difference between the app that binds and the one that doesn't. It's not the only one. barnslig-micronaut binds a flat, six-field record through @ConfigurationInject. irc-bot binds a Lombok @Data class holding a list of nested @Data server configs, each with its own channel list. The two apps don't even share an IRC library: kitteh in one, pircbotx in the other. So a prediction survived; that's weaker than a proof. If you're moving @ConfigurationProperties onto Micronaut and binding goes quiet, the record is still the first thing to try.

Everything else is still on the floor:

runs?config binds?tests
barnslig-micronautyes, silentlyyes3
irc-botnono, unsolved, tests @Disabled23 (3 skipped)
irc-server-cno, SIGSEGV on byte onen/a"100%"; segfault diagnosed, not fixed

Half of those tests (13 of 26) are pure-function unit tests; the rest round-trip a repository or boot a context, and the quiz logic that is the bulk of irc-bot has none.

Stop at the green build and I'd have shipped an annotation that does nothing, a config file no parser accepts, an application with no logs, a server that dies on hello, and a test that cannot fail. The compiler had checked that names resolve. The tests that existed had checked values the code produces with the system switched off. The first live launch at 19:15 surfaced, in four and a half minutes, two failures the compiler and the suite had been sitting on since 12:06, and a third I wrote myself while chasing them.

Filed under: java, micronaut, migration, testing, lombok, c

Sources#