search

micronaut-projects / micronaut-discovery-client

Micronaut's Discovery Client
Apache License 2.0
22 stars 20 forks source link

Fast registration/deregistration leads to inconsistent Consul state #216

Open katoquro opened 3 years ago

katoquro commented 3 years ago

Some time ago we faced with unstable tests. They become very often on CI and rare at dev machine. I found out that there is an issue with registration and deregistration in consul (I'll prove logs and traces bellow)

Task List

Steps to Reproduce

  1. Create context with endpoints and client bean with annotation @Client(id = 'service-id', path = '/api/endpoint-path')
  2. Create fast test with annotation @MicronautTest (in my case it's validation configuration test)
  3. Create test with endpoint also annotated with @MicronautTest
  4. Make sure the fast test runs before test with endpoint

Expected Behaviour

in the first test app register and then deregister correctly and the second test goes OK

Actual Behaviour

first test call deregister earlier than register and make consul inconsistent the second fails with stacktrace

?[36m18:57:37.257?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.context.env.DefaultEnvironment?[0;39m - Established active environments: [test]
?[36m18:57:37.263?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.context.DefaultBeanContext?[0;39m - Reading Startup environment from bootstrap.yml
?[36m18:57:37.319?[0;39m ?[1;30m[default-nioEventLoopGroup-3-3]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Sending HTTP PUT to http://localhost:8500/v1/agent/service/register
?[36m18:57:37.355?[0;39m ?[1;30m[default-nioEventLoopGroup-4-2]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Sending HTTP GET to http://localhost:8500/v1/kv/config/myproject?recurse=true
?[36m18:57:37.356?[0;39m ?[1;30m[default-nioEventLoopGroup-4-1]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Sending HTTP GET to http://localhost:8500/v1/kv/config/application?recurse=true
?[36m18:57:37.359?[0;39m ?[1;30m[default-nioEventLoopGroup-4-2]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Received response 404 from http://localhost:8500/v1/kv/config/myproject?recurse=true
?[36m18:57:37.367?[0;39m ?[1;30m[default-nioEventLoopGroup-4-1]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Received response 404 from http://localhost:8500/v1/kv/config/application?recurse=true
?[36m18:57:37.371?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.discovery.client.config.DistributedPropertySourceLocator?[0;39m - Resolved 0 configuration sources from client: compositeConfigurationClient(consul)
?[36m18:57:37.400?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mcom.zaxxer.hikari.HikariDataSource?[0;39m - HikariPool-2 - Starting...
?[36m18:57:37.408?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mcom.zaxxer.hikari.HikariDataSource?[0;39m - HikariPool-2 - Start completed.
?[36m18:57:37.421?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.flyway.AbstractFlywayMigration?[0;39m - Cleaning schema for database with qualifier [default]
?[36m18:57:37.423?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.license.VersionPrinter?[0;39m - Flyway Community Edition 7.0.4 by Redgate
?[36m18:57:37.426?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.database.base.DatabaseType?[0;39m - Database: jdbc:postgresql://localhost:5432/jdkmn_main_test (PostgreSQL 12.4)
?[36m18:57:37.435?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbClean?[0;39m - Successfully dropped pre-schema database level objects (execution time 00:00.000s)
?[36m18:57:37.462?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbClean?[0;39m - Successfully cleaned schema "public" (execution time 00:00.026s)
?[36m18:57:37.463?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbClean?[0;39m - Successfully dropped post-schema database level objects (execution time 00:00.000s)
?[36m18:57:37.528?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.flyway.AbstractFlywayMigration?[0;39m - Running migrations for database with qualifier [default]
?[36m18:57:37.529?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.license.VersionPrinter?[0;39m - Flyway Community Edition 7.0.4 by Redgate
?[36m18:57:37.556?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbValidate?[0;39m - Successfully validated 2 migrations (execution time 00:00.013s)
?[36m18:57:37.569?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.schemahistory.JdbcTableSchemaHistory?[0;39m - Creating Schema History table "public"."flyway_schema_history" ...
?[36m18:57:37.588?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbMigrate?[0;39m - Current version of schema "public": << Empty Schema >>
?[36m18:57:37.593?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbMigrate?[0;39m - Migrating schema "public" to version "0.0 - create-testing-schema"
?[36m18:57:37.608?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbMigrate?[0;39m - Migrating schema "public" to version "1.0 - initial-ddl"
?[36m18:57:37.627?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbMigrate?[0;39m - Successfully applied 2 migrations to schema "public" (execution time 00:00.044s)
?[36m18:57:37.704?[0;39m ?[1;30m[default-nioEventLoopGroup-5-3]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Sending HTTP PUT to http://localhost:8500/v1/agent/service/register
?[36m18:57:37.714?[0;39m ?[1;30m[default-nioEventLoopGroup-5-3]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Received response 200 from http://localhost:8500/v1/agent/service/register
?[36m18:57:37.715?[0;39m ?[1;30m[default-nioEventLoopGroup-5-3]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.discovery.registration.AutoRegistration?[0;39m - Registered service [myproject] with Consul
?[36m18:57:38.019?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.mongodb.driver.cluster?[0;39m - Cluster created with settings {hosts=[localhost:27017], mode=SINGLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms'}
?[36m18:57:38.064?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.mongodb.driver.cluster?[0;39m - Cluster description not yet available. Waiting for 30000 ms before timing out
?[36m18:57:38.102?[0;39m ?[1;30m[cluster-ClusterId{value='606e00a25e8b1707517304df', description='null'}-localhost:27017]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.mongodb.driver.connection?[0;39m - Opened connection [connectionId{localValue:1, serverValue:22}] to localhost:27017
?[36m18:57:38.102?[0;39m ?[1;30m[cluster-rtt-ClusterId{value='606e00a25e8b1707517304df', description='null'}-localhost:27017]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.mongodb.driver.connection?[0;39m - Opened connection [connectionId{localValue:2, serverValue:23}] to localhost:27017
?[36m18:57:38.116?[0;39m ?[1;30m[cluster-ClusterId{value='606e00a25e8b1707517304df', description='null'}-localhost:27017]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.mongodb.driver.cluster?[0;39m - Monitor thread successfully connected to server with description ServerDescription{address=localhost:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=8, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=31479707, setName='rs0', canonicalAddress=mongo:27017, hosts=[mongo:27017], passives=[mongo-repl1:27018, mongo-repl2:27019], arbiters=[], primary='mongo:27017', tagSet=TagSet{[]}, electionId=7fffffff0000000000000001, setVersion=1, topologyVersion=null, lastWriteDate=Wed Apr 07 18:57:31 UTC 2021, lastUpdateTimeNanos=894121323822}
?[36m18:57:38.264?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.mongodb.driver.connection?[0;39m - Opened connection [connectionId{localValue:3, serverValue:24}] to localhost:27017
?[36m18:57:38.530?[0;39m ?[1;30m[default-nioEventLoopGroup-5-4]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Sending HTTP GET to http://localhost:8500/v1/health/service/myproject?passing=false
?[36m18:57:38.538?[0;39m ?[1;30m[default-nioEventLoopGroup-5-4]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Received response 200 from http://localhost:8500/v1/health/service/myproject?passing=false
?[36m18:57:38.654?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[1;31mERROR?[0;39m ?[35mio.micronaut.retry.intercept.RecoveryInterceptor?[0;39m - Type [myproject.NavigationFsControllerSpec$NavigationFsControllerClient$Intercepted] executed with error: Connect Error: Connection refused: localhost/127.0.0.1:28394
io.micronaut.http.client.exceptions.HttpClientException: Connect Error: Connection refused: localhost/127.0.0.1:28394
    at io.micronaut.http.client.netty.DefaultHttpClient.lambda$null$34(DefaultHttpClient.java:1119)
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571)
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491)
    at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616)
    at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609)
    at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:117)
    at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.fulfillConnectPromise(AbstractNioChannel.java:321)
    at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:337)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:707)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: localhost/127.0.0.1:28394
Caused by: java.net.ConnectException: Connection refused
    at java.base/sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
    at java.base/sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:779)
    at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:330)
    at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:707)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:834)

What happens in consul 

==> Found address '172.18.0.3' for interface 'eth0', setting bind option...
==> Starting Consul agent...
           Version: '1.8.9'
           Node ID: '34af0a18-a36b-e150-61c6-1b9fbb6abf99'
         Node name: '0e17b5bd8380'
        Datacenter: 'dc1' (Segment: '<all>')
            Server: true (Bootstrap: false)
       Client Addr: [0.0.0.0] (HTTP: 8500, HTTPS: -1, gRPC: 8502, DNS: 8600)
      Cluster Addr: 172.18.0.3 (LAN: 8301, WAN: 8302)
           Encrypt: Gossip: false, TLS-Outgoing: false, TLS-Incoming: false, Auto-Encrypt-TLS: false

==> Log data will now stream in as it occurs:

    2021-04-07T18:55:24.940Z [INFO]  agent.server.raft: initial configuration: index=1 servers="[{Suffrage:Voter ID:34af0a18-a36b-e150-61c6-1b9fbb6abf99 Address:172.18.0.3:8300}]"
    2021-04-07T18:55:24.940Z [INFO]  agent.server.serf.wan: serf: EventMemberJoin: 0e17b5bd8380.dc1 172.18.0.3
    2021-04-07T18:55:24.940Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 0e17b5bd8380 172.18.0.3
    2021-04-07T18:55:24.941Z [INFO]  agent.router: Initializing LAN area manager
    2021-04-07T18:55:24.941Z [INFO]  agent.server: Adding LAN server: server="0e17b5bd8380 (Addr: tcp/172.18.0.3:8300) (DC: dc1)"
    2021-04-07T18:55:24.941Z [INFO]  agent.server: Handled event for server in area: event=member-join server=0e17b5bd8380.dc1 area=wan
    2021-04-07T18:55:24.941Z [INFO]  agent: Started DNS server: address=0.0.0.0:8600 network=udp
    2021-04-07T18:55:24.941Z [INFO]  agent.server.raft: entering follower state: follower="Node at 172.18.0.3:8300 [Follower]" leader=
    2021-04-07T18:55:24.941Z [INFO]  agent: Started DNS server: address=0.0.0.0:8600 network=tcp
    2021-04-07T18:55:24.942Z [INFO]  agent: Started HTTP server: address=[::]:8500 network=tcp
    2021-04-07T18:55:24.942Z [INFO]  agent: Started gRPC server: address=[::]:8502 network=tcp
    2021-04-07T18:55:24.942Z [INFO]  agent: started state syncer
==> Consul agent running!
    2021-04-07T18:55:24.981Z [WARN]  agent.server.raft: heartbeat timeout reached, starting election: last-leader=
    2021-04-07T18:55:24.982Z [INFO]  agent.server.raft: entering candidate state: node="Node at 172.18.0.3:8300 [Candidate]" term=2
    2021-04-07T18:55:24.982Z [DEBUG] agent.server.raft: votes: needed=1
    2021-04-07T18:55:24.982Z [DEBUG] agent.server.raft: vote granted: from=34af0a18-a36b-e150-61c6-1b9fbb6abf99 term=2 tally=1
    2021-04-07T18:55:24.982Z [INFO]  agent.server.raft: election won: tally=1
    2021-04-07T18:55:24.982Z [INFO]  agent.server.raft: entering leader state: leader="Node at 172.18.0.3:8300 [Leader]"
    2021-04-07T18:55:24.982Z [INFO]  agent.server: cluster leadership acquired
    2021-04-07T18:55:24.982Z [DEBUG] agent.server: Cannot upgrade to new ACLs: leaderMode=0 mode=0 found=true leader=172.18.0.3:8300
    2021-04-07T18:55:24.982Z [INFO]  agent.server: New leader elected: payload=0e17b5bd8380
    2021-04-07T18:55:24.982Z [INFO]  agent.leader: started routine: routine="federation state anti-entropy"
    2021-04-07T18:55:24.983Z [INFO]  agent.leader: started routine: routine="federation state pruning"
    2021-04-07T18:55:24.983Z [DEBUG] connect.ca.consul: consul CA provider configured: id=07:80:c8:de:f6:41:86:29:8f:9c:b8:17:d6:48:c2:d5:c5:5c:7f:0c:03:f7:cf:97:5a:a7:c1:68:aa:23:ae:81 is_primary=true
    2021-04-07T18:55:24.989Z [INFO]  agent.server.connect: initialized primary datacenter CA with provider: provider=consul
    2021-04-07T18:55:24.990Z [INFO]  agent.leader: started routine: routine="intermediate cert renew watch"
    2021-04-07T18:55:24.990Z [INFO]  agent.leader: started routine: routine="CA root pruning"
    2021-04-07T18:55:24.990Z [DEBUG] agent.server: Skipping self join check for node since the cluster is too small: node=0e17b5bd8380
    2021-04-07T18:55:24.990Z [INFO]  agent.server: member joined, marking health alive: member=0e17b5bd8380
    2021-04-07T18:55:25.013Z [INFO]  agent.server: federation state anti-entropy synced
    2021-04-07T18:55:25.073Z [DEBUG] agent: Skipping remote check since it is managed automatically: check=serfHealth
    2021-04-07T18:55:25.073Z [INFO]  agent: Synced node info
    2021-04-07T18:55:26.407Z [DEBUG] agent: Skipping remote check since it is managed automatically: check=serfHealth
    2021-04-07T18:55:26.407Z [DEBUG] agent: Node info in sync
    2021-04-07T18:55:26.407Z [DEBUG] agent: Node info in sync
    2021-04-07T18:56:24.982Z [DEBUG] agent.server: Skipping self join check for node since the cluster is too small: node=0e17b5bd8380
    2021-04-07T18:56:33.857Z [DEBUG] agent: Skipping remote check since it is managed automatically: check=serfHealth
    2021-04-07T18:56:33.857Z [DEBUG] agent: Node info in sync
    2021-04-07T18:57:24.941Z [DEBUG] agent.router.manager: Rebalanced servers, new active server: number_of_servers=1 active_server="0e17b5bd8380.dc1 (Addr: tcp/172.18.0.3:8300) (DC: dc1)"
    2021-04-07T18:57:24.941Z [DEBUG] agent.router.manager: Rebalanced servers, new active server: number_of_servers=1 active_server="0e17b5bd8380 (Addr: tcp/172.18.0.3:8300) (DC: dc1)"
    2021-04-07T18:57:24.982Z [DEBUG] agent.server: Skipping self join check for node since the cluster is too small: node=0e17b5bd8380
    2021-04-07T18:57:34.982Z [DEBUG] agent.http: Request finished: method=GET url=/v1/kv/config/application?recurse=true from=172.18.0.1:35540 latency=88.79µs
    2021-04-07T18:57:34.985Z [DEBUG] agent.http: Request finished: method=GET url=/v1/kv/config/myproject?recurse=true from=172.18.0.1:35536 latency=64.455µs
        2021-04-07T18:57:37.177Z [WARN]  agent: Failed to deregister service: service=myproject:28394 error="Service {"myproject:28394" {}} does not exist"
    2021-04-07T18:57:37.177Z [DEBUG] agent: Node info in sync
    2021-04-07T18:57:37.177Z [DEBUG] agent.http: Request finished: method=PUT url=/v1/agent/service/deregister/myproject%3A28394 from=172.18.0.1:35590 latency=647.099µs
    2021-04-07T18:57:37.350Z [DEBUG] agent: Node info in sync
    2021-04-07T18:57:37.350Z [INFO]  agent: Synced service: service=myproject:28394
    2021-04-07T18:57:37.350Z [DEBUG] agent: Check in sync: check=service:myproject:28394
    2021-04-07T18:57:37.350Z [DEBUG] agent.http: Request finished: method=PUT url=/v1/agent/service/register from=172.18.0.1:35586 latency=3.44803ms
    2021-04-07T18:57:37.350Z [DEBUG] agent: Node info in sync
    2021-04-07T18:57:37.350Z [DEBUG] agent: Service in sync: service=myproject:28394
    2021-04-07T18:57:37.350Z [DEBUG] agent: Check in sync: check=service:myproject:28394
    2021-04-07T18:57:37.357Z [DEBUG] agent.http: Request finished: method=GET url=/v1/kv/config/myproject?recurse=true from=172.18.0.1:35598 latency=48.017µs
    2021-04-07T18:57:37.360Z [DEBUG] agent.http: Request finished: method=GET url=/v1/kv/config/application?recurse=true from=172.18.0.1:35594 latency=60.014µs

You can see log 

2021-04-07T18:57:37.177Z [WARN]  agent: Failed to deregister service: service=myproject:28394 error="Service {"myproject:28394" {}} does not exist"

appears earlier than registration bellow. We use random port configuration so every test uses it's own port

my fast test looks like 

@MicronautTest(application = TestingApplication)
class MicronautValidationSpec extends Specification {
    @Inject Validator validator

    void "dto is validated with validator"() {
       //some code 
    }

    def "hack for very fast register and deregister in consul" (){
        when: "on CI it can leads to inconsistency in consult when all integration test takes several ms"
        sleep(500)

        then: 'deregister done correctly'
        noExceptionThrown()
    }
}

and this is it's log 

?[36m18:57:33.077?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.context.env.DefaultEnvironment?[0;39m - Established active environments: [test]
?[36m18:57:33.102?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.context.env.DefaultEnvironment?[0;39m - Established active environments: [test]
?[36m18:57:33.134?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.context.DefaultBeanContext?[0;39m - Reading Startup environment from bootstrap.yml
?[36m18:57:34.925?[0;39m ?[1;30m[default-nioEventLoopGroup-1-2]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Sending HTTP GET to http://localhost:8500/v1/kv/config/jdkmn-main?recurse=true
?[36m18:57:34.927?[0;39m ?[1;30m[default-nioEventLoopGroup-1-1]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Sending HTTP GET to http://localhost:8500/v1/kv/config/application?recurse=true
?[36m18:57:34.991?[0;39m ?[1;30m[default-nioEventLoopGroup-1-2]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Received response 404 from http://localhost:8500/v1/kv/config/jdkmn-main?recurse=true
?[36m18:57:34.993?[0;39m ?[1;30m[default-nioEventLoopGroup-1-1]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Received response 404 from http://localhost:8500/v1/kv/config/application?recurse=true
?[36m18:57:35.004?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.discovery.client.config.DistributedPropertySourceLocator?[0;39m - Resolved 0 configuration sources from client: compositeConfigurationClient(consul)
?[36m18:57:35.519?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mcom.zaxxer.hikari.HikariDataSource?[0;39m - HikariPool-1 - Starting...
?[36m18:57:35.603?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mcom.zaxxer.hikari.HikariDataSource?[0;39m - HikariPool-1 - Start completed.
?[36m18:57:35.610?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.flyway.AbstractFlywayMigration?[0;39m - Cleaning schema for database with qualifier [default]
?[36m18:57:35.622?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.license.VersionPrinter?[0;39m - Flyway Community Edition 7.0.4 by Redgate
?[36m18:57:35.669?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.database.base.DatabaseType?[0;39m - Database: jdbc:postgresql://localhost:5432/myproject_test (PostgreSQL 12.4)
?[36m18:57:35.705?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbClean?[0;39m - Successfully dropped pre-schema database level objects (execution time 00:00.000s)
?[36m18:57:35.730?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbClean?[0;39m - Successfully cleaned schema "public" (execution time 00:00.022s)
?[36m18:57:35.731?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbClean?[0;39m - Successfully dropped post-schema database level objects (execution time 00:00.000s)
?[36m18:57:36.130?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.flyway.AbstractFlywayMigration?[0;39m - Running migrations for database with qualifier [default]
?[36m18:57:36.131?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.license.VersionPrinter?[0;39m - Flyway Community Edition 7.0.4 by Redgate
?[36m18:57:36.184?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbValidate?[0;39m - Successfully validated 2 migrations (execution time 00:00.029s)
?[36m18:57:36.196?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.schemahistory.JdbcTableSchemaHistory?[0;39m - Creating Schema History table "public"."flyway_schema_history" ...
?[36m18:57:36.232?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbMigrate?[0;39m - Current version of schema "public": << Empty Schema >>
?[36m18:57:36.238?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbMigrate?[0;39m - Migrating schema "public" to version "0.0 - create-testing-schema"
?[36m18:57:36.267?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbMigrate?[0;39m - Migrating schema "public" to version "1.0 - initial-ddl"
?[36m18:57:36.291?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35morg.flywaydb.core.internal.command.DbMigrate?[0;39m - Successfully applied 2 migrations to schema "public" (execution time 00:00.068s)
?[36m18:57:37.146?[0;39m ?[1;30m[default-nioEventLoopGroup-3-6]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Sending HTTP PUT to http://localhost:8500/v1/agent/service/deregister/jdkmn-main%3A28394
?[36m18:57:37.178?[0;39m ?[1;30m[default-nioEventLoopGroup-3-6]?[0;39m [/] ?[39mDEBUG?[0;39m ?[35mio.micronaut.http.client.netty.DefaultHttpClient?[0;39m - Received response 200 from http://localhost:8500/v1/agent/service/deregister/jdkmn-main%3A28394
?[36m18:57:37.180?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mio.micronaut.discovery.registration.AutoRegistration?[0;39m - De-registered service [jdkmn-main] with Consul
?[36m18:57:37.213?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mcom.zaxxer.hikari.HikariDataSource?[0;39m - HikariPool-1 - Shutdown initiated...
?[36m18:57:37.244?[0;39m ?[1;30m[Test worker]?[0;39m [/] ?[34mINFO ?[0;39m ?[35mcom.zaxxer.hikari.HikariDataSource?[0;39m - HikariPool-1 - Shutdown completed.

You can see that timing is odd in consul, looks like registering takes more time and deregistering ignores fails and during heartbeat (I think) all next tests can see wrong registration

How I create my clients inside test

@MicronautTest(application = TestingApplication, rollback = false, transactional = false)
class NavigationFsControllerSpec extends Specification {
    @Inject NavigationFsControllerClient client

    //tests

    @Client(id = 'jmyproject', path = '/api/web/navigation')
    static interface NavigationFsControllerClient extends NavigationFsEndpoints {} 
}

Environment Information

Example Application

katoquro commented 3 years ago

Still here in 2.5.5 I can suggest using a workaround: different registration id for every test.... It looks like 

@MicronautTest(application = TestingApplication)
@Property(name="micronaut.application.name", value = "ProjectControllerSpec")
class ProjectControllerSpec extends Specification {
    @Client(id = 'ProjectControllerSpec', path = '/api/web/projects')
    static interface ProjectControllerClient extends ProjectEndpoints {}

    @Inject ProjectControllerClient client
    //...
}