[
https://issues.apache.org/jira/browse/IGNITE-22057?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Alexander Lapin updated IGNITE-22057:
-------------------------------------
Description:
Seems that `destruction_does_not_update_data` may hang forever on tx rollback
which causes
{code:java}
The build [Test]::> Run :: C++ Linux Tests #24053 {buildId=8040877} has been
running for more than 15 minutes. Terminating...{code}
{code:java}
[08:15:21] : [Step 8/12] [ RUN ]
transactions_test.rollback_does_not_update_data
[08:15:21] : [Step 8/12] [ ] [ INFO ] Established connection
with remote host 127.0.0.1:10942
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Connection ID: 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Handshake sent
successfully
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 149
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Got handshake response
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Server-side protocol
version: 3.0.0
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
op=50, req_id=0
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 26
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Closed Connection ID 1,
error=Client stopped
[08:15:21] : [Step 8/12] [ ] [ INFO ] Established connection
with remote host 127.0.0.1:10942
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Connection ID: 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Handshake sent
successfully
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 149
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Got handshake response
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Server-side protocol
version: 3.0.0
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request: op=4,
req_id=0
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 21
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
op=43, req_id=1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 12
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request: op=5,
req_id=2
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 36
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
op=10, req_id=3
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 12
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
op=45, req_id=4
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 11
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
op=12, req_id=5
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 13
[08:15:21] : [Step 8/12] [ ] [ INFO ] Established connection
with remote host 127.0.0.1:10942
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Connection ID: 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Handshake sent
successfully
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 149
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Got handshake response
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Server-side protocol
version: 3.0.0
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
op=50, req_id=0
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 26
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Closed Connection ID 1,
error=Client stopped
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Closed Connection ID 1,
error=Client stopped
[08:15:21] : [Step 8/12] [ OK ]
transactions_test.rollback_does_not_update_data (49 ms)
[08:15:21] : [Step 8/12] [ RUN ]
transactions_test.destruction_does_not_update_data
[08:15:21] : [Step 8/12] [ ] [ INFO ] Established connection
with remote host 127.0.0.1:10942
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Connection ID: 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Handshake sent
successfully
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 149
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Got handshake response
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Server-side protocol
version: 3.0.0
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
op=50, req_id=0
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 26
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Closed Connection ID 1,
error=Client stopped
[08:15:21] : [Step 8/12] [ ] [ INFO ] Established connection
with remote host 127.0.0.1:10942
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Connection ID: 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Handshake sent
successfully
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 149
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Got handshake response
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Server-side protocol
version: 3.0.0
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request: op=4,
req_id=0
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 21
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
op=43, req_id=1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 12
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request: op=5,
req_id=2
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 36
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
op=10, req_id=3
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent successfully
on Connection ID 1
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection ID
1, size: 12
[08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
op=45, req_id=4
[08:15:21]E: [Step 8/12] [2024-04-17T05:15:21,767][WARN
][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner%partition-operations-13][TrackableNetworkMessageHandler]
Message handling has been too long [duration=6ms, message=[class
org.apache.ignite.internal.tx.message.TxCleanupMessageImpl]]
[08:15:21] : [Step 8/12] [2024-04-17T05:15:21,739][INFO
][org.apache.ignite.internal.runner.app.PlatformTestNodeRunner-srv-worker-4][ClientInboundMessageHandler]
Partition primary replica changed, notifying client [connectionId=262,
remoteAddress=/127.0.0.1:42022]
[08:15:21] : [Step 8/12] [2024-04-17T05:15:21,755][INFO
][org.apache.ignite.internal.runner.app.PlatformTestNodeRunner-srv-worker-5][ClientInboundMessageHandler]
Partition primary replica changed, notifying client [connectionId=263,
remoteAddress=/127.0.0.1:42024]
[08:15:21] : [Step 8/12] [2024-04-17T05:15:21,771][INFO
][org.apache.ignite.internal.runner.app.PlatformTestNodeRunner-srv-worker-6][ClientInboundMessageHandler]
Partition primary replica changed, notifying client [connectionId=264,
remoteAddress=/127.0.0.1:42036]
[08:15:21] : [Step 8/12] [2024-04-17T05:15:21,788][INFO
][org.apache.ignite.internal.runner.app.PlatformTestNodeRunner-srv-worker-7][ClientInboundMessageHandler]
Partition primary replica changed, notifying client [connectionId=265,
remoteAddress=/127.0.0.1:42046]
[08:15:21] : [Step 8/12] [2024-04-17T05:15:21,801][INFO
][org.apache.ignite.internal.runner.app.PlatformTestNodeRunner-srv-worker-1][ClientInboundMessageHandler]
Partition primary replica changed, notifying client [connectionId=266,
remoteAddress=/127.0.0.1:42052]
[08:15:26] : [Step 8/12] [2024-04-17T05:15:26,451][INFO
][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner_2%lease-updater][LeaseUpdater]
Leases updated (printed once per 10 iteration(s)):
[inCurrentIteration=LeaseStats [leasesCreated=0, leasesPublished=0,
leasesProlonged=80, leasesWithoutCandidates=0], active=435,
currentAssignmentsSize=435].
[08:15:27]E: [Step 8/12] [2024-04-17T05:15:27,809][WARN
][org.apache.ignite.internal.runner.app.PlatformTestNodeRunner-srv-worker-1][IdleChannelHandler]
Closing idle channel [idleTimeout=6000, remoteAddress=/127.0.0.1:42052]
[08:15:32] : [Step 8/12] [2024-04-17T05:15:31,992][INFO
][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner_2%lease-updater][LeaseUpdater]
Leases updated (printed once per 10 iteration(s)):
[inCurrentIteration=LeaseStats [leasesCreated=0, leasesPublished=0,
leasesProlonged=65, leasesWithoutCandidates=0], active=435,
currentAssignmentsSize=435].
[08:15:37] : [Step 8/12] [2024-04-17T05:15:37,530][INFO
][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner_2%lease-updater][LeaseUpdater]
Leases updated (printed once per 10 iteration(s)):
[inCurrentIteration=LeaseStats [leasesCreated=0, leasesPublished=0,
leasesProlonged=115, leasesWithoutCandidates=0], active=435,
currentAssignmentsSize=435].
[08:15:43] : [Step 8/12] [2024-04-17T05:15:43,061][INFO
][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner_2%lease-updater][LeaseUpdater]
Leases updated (printed once per 10 iteration(s)):
[inCurrentIteration=LeaseStats [leasesCreated=0, leasesPublished=0,
leasesProlonged=90, leasesWithoutCandidates=0], active=435,
currentAssignmentsSize=435].
[08:15:48] : [Step 8/12] [2024-04-17T05:15:48,589][INFO
][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner_2%lease-updater][LeaseUpdater]
Leases updated (printed once per 10 iteration(s)):
[inCurrentIteration=LeaseStats [leasesCreated=0, leasesPublished=0,
leasesProlonged=85, leasesWithoutCandidates=0], active=435,
currentAssignmentsSize=435].
[08:15:49] : [Step 8/12] [2024-04-17T05:15:49,146][INFO
][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner%resource-vacuum-executor-0][VolatileTxStateMetaStorage]
Vacuum started [vacuumObservationTimestamp=1713330949146,
txnResourceTtl=30000].
[08:15:49] : [Step 8/12] [2024-04-17T05:15:49,146][INFO
][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner_2%resource-vacuum-executor-0][VolatileTxStateMetaStorage]
Vacuum started [vacuumObservationTimestamp=1713330949146,
txnResourceTtl=30000].
{code}
was:Seems that
> destruction_does_not_update_data is flaky
> -----------------------------------------
>
> Key: IGNITE-22057
> URL: https://issues.apache.org/jira/browse/IGNITE-22057
> Project: Ignite
> Issue Type: Bug
> Reporter: Alexander Lapin
> Priority: Major
> Labels: ignite-3
>
> Seems that `destruction_does_not_update_data` may hang forever on tx rollback
> which causes
> {code:java}
> The build [Test]::> Run :: C++ Linux Tests #24053 {buildId=8040877} has been
> running for more than 15 minutes. Terminating...{code}
> {code:java}
> [08:15:21] : [Step 8/12] [ RUN ]
> transactions_test.rollback_does_not_update_data
> [08:15:21] : [Step 8/12] [ ] [ INFO ] Established connection
> with remote host 127.0.0.1:10942
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Connection ID: 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Handshake sent
> successfully
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 149
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Got handshake response
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Server-side protocol
> version: 3.0.0
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=50, req_id=0
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 26
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Closed Connection ID 1,
> error=Client stopped
> [08:15:21] : [Step 8/12] [ ] [ INFO ] Established connection
> with remote host 127.0.0.1:10942
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Connection ID: 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Handshake sent
> successfully
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 149
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Got handshake response
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Server-side protocol
> version: 3.0.0
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=4, req_id=0
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 21
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=43, req_id=1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 12
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=5, req_id=2
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 36
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=10, req_id=3
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 12
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=45, req_id=4
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 11
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=12, req_id=5
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 13
> [08:15:21] : [Step 8/12] [ ] [ INFO ] Established connection
> with remote host 127.0.0.1:10942
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Connection ID: 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Handshake sent
> successfully
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 149
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Got handshake response
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Server-side protocol
> version: 3.0.0
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=50, req_id=0
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 26
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Closed Connection ID 1,
> error=Client stopped
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Closed Connection ID 1,
> error=Client stopped
> [08:15:21] : [Step 8/12] [ OK ]
> transactions_test.rollback_does_not_update_data (49 ms)
> [08:15:21] : [Step 8/12] [ RUN ]
> transactions_test.destruction_does_not_update_data
> [08:15:21] : [Step 8/12] [ ] [ INFO ] Established connection
> with remote host 127.0.0.1:10942
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Connection ID: 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Handshake sent
> successfully
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 149
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Got handshake response
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Server-side protocol
> version: 3.0.0
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=50, req_id=0
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 26
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Closed Connection ID 1,
> error=Client stopped
> [08:15:21] : [Step 8/12] [ ] [ INFO ] Established connection
> with remote host 127.0.0.1:10942
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Connection ID: 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Handshake sent
> successfully
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 149
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Got handshake response
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Server-side protocol
> version: 3.0.0
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=4, req_id=0
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 21
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=43, req_id=1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 12
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=5, req_id=2
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 36
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=10, req_id=3
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message sent
> successfully on Connection ID 1
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Message on Connection
> ID 1, size: 12
> [08:15:21] : [Step 8/12] [ ] [ DEBUG ] Performing request:
> op=45, req_id=4
> [08:15:21]E: [Step 8/12] [2024-04-17T05:15:21,767][WARN
> ][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner%partition-operations-13][TrackableNetworkMessageHandler]
> Message handling has been too long [duration=6ms, message=[class
> org.apache.ignite.internal.tx.message.TxCleanupMessageImpl]]
> [08:15:21] : [Step 8/12] [2024-04-17T05:15:21,739][INFO
> ][org.apache.ignite.internal.runner.app.PlatformTestNodeRunner-srv-worker-4][ClientInboundMessageHandler]
> Partition primary replica changed, notifying client [connectionId=262,
> remoteAddress=/127.0.0.1:42022]
> [08:15:21] : [Step 8/12] [2024-04-17T05:15:21,755][INFO
> ][org.apache.ignite.internal.runner.app.PlatformTestNodeRunner-srv-worker-5][ClientInboundMessageHandler]
> Partition primary replica changed, notifying client [connectionId=263,
> remoteAddress=/127.0.0.1:42024]
> [08:15:21] : [Step 8/12] [2024-04-17T05:15:21,771][INFO
> ][org.apache.ignite.internal.runner.app.PlatformTestNodeRunner-srv-worker-6][ClientInboundMessageHandler]
> Partition primary replica changed, notifying client [connectionId=264,
> remoteAddress=/127.0.0.1:42036]
> [08:15:21] : [Step 8/12] [2024-04-17T05:15:21,788][INFO
> ][org.apache.ignite.internal.runner.app.PlatformTestNodeRunner-srv-worker-7][ClientInboundMessageHandler]
> Partition primary replica changed, notifying client [connectionId=265,
> remoteAddress=/127.0.0.1:42046]
> [08:15:21] : [Step 8/12] [2024-04-17T05:15:21,801][INFO
> ][org.apache.ignite.internal.runner.app.PlatformTestNodeRunner-srv-worker-1][ClientInboundMessageHandler]
> Partition primary replica changed, notifying client [connectionId=266,
> remoteAddress=/127.0.0.1:42052]
> [08:15:26] : [Step 8/12] [2024-04-17T05:15:26,451][INFO
> ][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner_2%lease-updater][LeaseUpdater]
> Leases updated (printed once per 10 iteration(s)):
> [inCurrentIteration=LeaseStats [leasesCreated=0, leasesPublished=0,
> leasesProlonged=80, leasesWithoutCandidates=0], active=435,
> currentAssignmentsSize=435].
> [08:15:27]E: [Step 8/12] [2024-04-17T05:15:27,809][WARN
> ][org.apache.ignite.internal.runner.app.PlatformTestNodeRunner-srv-worker-1][IdleChannelHandler]
> Closing idle channel [idleTimeout=6000, remoteAddress=/127.0.0.1:42052]
> [08:15:32] : [Step 8/12] [2024-04-17T05:15:31,992][INFO
> ][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner_2%lease-updater][LeaseUpdater]
> Leases updated (printed once per 10 iteration(s)):
> [inCurrentIteration=LeaseStats [leasesCreated=0, leasesPublished=0,
> leasesProlonged=65, leasesWithoutCandidates=0], active=435,
> currentAssignmentsSize=435].
> [08:15:37] : [Step 8/12] [2024-04-17T05:15:37,530][INFO
> ][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner_2%lease-updater][LeaseUpdater]
> Leases updated (printed once per 10 iteration(s)):
> [inCurrentIteration=LeaseStats [leasesCreated=0, leasesPublished=0,
> leasesProlonged=115, leasesWithoutCandidates=0], active=435,
> currentAssignmentsSize=435].
> [08:15:43] : [Step 8/12] [2024-04-17T05:15:43,061][INFO
> ][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner_2%lease-updater][LeaseUpdater]
> Leases updated (printed once per 10 iteration(s)):
> [inCurrentIteration=LeaseStats [leasesCreated=0, leasesPublished=0,
> leasesProlonged=90, leasesWithoutCandidates=0], active=435,
> currentAssignmentsSize=435].
> [08:15:48] : [Step 8/12] [2024-04-17T05:15:48,589][INFO
> ][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner_2%lease-updater][LeaseUpdater]
> Leases updated (printed once per 10 iteration(s)):
> [inCurrentIteration=LeaseStats [leasesCreated=0, leasesPublished=0,
> leasesProlonged=85, leasesWithoutCandidates=0], active=435,
> currentAssignmentsSize=435].
> [08:15:49] : [Step 8/12] [2024-04-17T05:15:49,146][INFO
> ][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner%resource-vacuum-executor-0][VolatileTxStateMetaStorage]
> Vacuum started [vacuumObservationTimestamp=1713330949146,
> txnResourceTtl=30000].
> [08:15:49] : [Step 8/12] [2024-04-17T05:15:49,146][INFO
> ][%org.apache.ignite.internal.runner.app.PlatformTestNodeRunner_2%resource-vacuum-executor-0][VolatileTxStateMetaStorage]
> Vacuum started [vacuumObservationTimestamp=1713330949146,
> txnResourceTtl=30000].
> {code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
