Skip to content

Lack of graceful shutdown on SIGTERM #451

Description

@gavinvangent

aws-kcl version: 3.1.1 (Latest at time of writing)

KCL v3 introduced graceful shutdown logic to aid the redistribution/rebalancing of leases between consumer processes, which this library appears to be handling successfully. However, there is also support in the java daemon for SIGTERM and SIGINT to also attempt a graceful shutdown, however, using the kcl-bootstrap doesn't handle this correctly.

What should happen:

  • Stopping the process sends SIGTERM/SIGINT into pid 1 (kcl-bootstrap), which then passes the SIGTERM/SIGINT to the java daemon.
  • The daemon should then prevent the SIGTERM/SIGINT from getting to the nodejs child process
  • The daemon should then begin the graceful shutdown process. This would involve sending the shutdownRequested and then leaseLost events to the nodejs child process.
  • The callbacks for shutdownRequested and leaseLost would be invoked signalling to the daemon that the child process has successfully shut down, and its at this point that the daemon can send the SIGTERM/SIGINT to the nodejs child process
  • The daemon can then exit
  • The kcl-boostrap can then exit

This would be a successful graceful shutdown.

It appears to me that the kcl-bootstrap process is somehow pushing the SIGTERM/SIGINT to the daemon and child process, so the nodejs process exits before the java daemon has a chance to perform the graceful shutdown:

2025-11-25 21:30:19,027 [multi-lang-daemon-0000] INFO  s.a.k.l.DynamoDBLockBasedLeaderDecider [NONE] - Worker : 954edcdd-342f-4da8-9c13-6841c493ac99 is the current leader. 

\npm error path /app

\npm error command failed

\npm error signal SIGTERM

\npm error command sh -c kcl-bootstrap --java /usr/bin/java --jar-path ./java --properties ./kinesis.template.properties -e

\npm error A complete log of this run can be found in: /root/.npm/_logs/2025-11-25T21_28_56_743Z-debug-0.log

\2025-11-25 21:30:19,745 [Thread-1] INFO  s.a.k.multilang.MultiLangDaemon [NONE] - Process terminated, will initiate shutdown. 

2025-11-25 21:30:19,745 [multi-lang-daemon-0001] INFO  s.a.kinesis.multilang.LineReaderTask [NONE] - Stopping: Reading STDERR for shardId-000000000000

Notice the nodejs child process logs the SIGTERM before the daemon has a chance to initiate the shutdown, and then realizes the child has already exited so it exits too.

This was started using (in a docker container):

exec npx kcl-bootstrap --java /usr/bin/java --jar-path ./java --properties ./kinesis.template.properties -e

When i change this entry point to not use the kcl-boostrap:

# Build classpath (what kcl-bootstrap does)
CLASSPATH=""
for jar in ./java/*.jar; do
    if [ -z "$CLASSPATH" ]; then
        CLASSPATH="$jar"
    else
        CLASSPATH="$CLASSPATH:$jar"
    fi
done

# Run Java daemon directly (bypassing kcl-bootstrap)
exec java -cp "$CLASSPATH" software.amazon.kinesis.multilang.MultiLangDaemon --properties-file kinesis.template.properties

I get the following:

2025-11-25 21:35:31,889 [multi-lang-daemon-0000] INFO  s.a.k.l.DynamoDBLockBasedLeaderDecider [NONE] - Worker : b9004ba2-4e7f-409a-9d18-6cf54e862d1c is the current leader.
2025-11-25 21:35:32,009 [Thread-1] INFO  s.a.k.multilang.MultiLangDaemon [NONE] - Process terminated, will initiate shutdown.
...
2025-11-25 21:35:32,892 [ShardRecordProcessor-0001] INFO  s.a.k.m.MultiLangShardRecordProcessor [NONE] - Shutdown is requested.
2025-11-25 21:35:32,892 [ShardRecordProcessor-0001] INFO  s.a.k.m.MultiLangShardRecordProcessor [NONE] - Requesting a checkpoint on shutdown notification.
2025-11-25 21:35:32,893 [ShardRecordProcessor-0001] INFO  s.a.kinesis.multilang.MessageWriter [NONE] - Writing ShutdownRequestedMessage to child process for shard shardId-000000000000
2025-11-25 21:35:32,893 [multi-lang-daemon-0003] INFO  s.a.kinesis.multilang.LineReaderTask [NONE] - Starting: Reading next message from STDIN for shardId-000000000000
2025-11-25 21:35:32,893 [multi-lang-daemon-0002] INFO  s.a.kinesis.multilang.MessageWriter [NONE] - Message size == 30 bytes for shard shardId-000000000000
2025-11-25 21:35:32,894 [multi-lang-daemon-0003] INFO  s.a.k.multilang.GetNextMessageTask [NONE] - Skipping unexpected line on STDOUT for shard shardId-000000000000: [base] 2025-11-25T21:35:32.894Z - shardId-000000000000 - shutdownRequested called
2025-11-25 21:35:32,894 [ShardRecordProcessor-0001] INFO  s.a.kinesis.multilang.MessageWriter [NONE] - Writing CheckpointMessage to child process for shard shardId-000000000000
2025-11-25 21:35:32,895 [multi-lang-daemon-0003] INFO  s.a.kinesis.multilang.MessageWriter [NONE] - Message size == 83 bytes for shard shardId-000000000000
2025-11-25 21:35:32,895 [multi-lang-daemon-0003] INFO  s.a.kinesis.multilang.LineReaderTask [NONE] - Starting: Reading next message from STDIN for shardId-000000000000
2025-11-25 21:35:32,895 [ShardRecordProcessor-0001] INFO  s.a.k.multilang.MultiLangProtocol [NONE] - Received response {"action":"status","responseFor":"shutdownRequested"} from subprocess while waiting for shutdownRequested while processing shard shardId-000000000000
2025-11-25 21:35:32,896 [ForkJoinPool.commonPool-worker-1] INFO  s.a.kinesis.coordinator.Scheduler [NONE] - Worker shutdown requested.
2025-11-25 21:35:32,896 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.c.m.MigrationStateMachineImpl [NONE] - Shutdown successfully
2025-11-25 21:35:32,896 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.c.DynamicMigrationComponentsInitializer [NONE] - Shutting down components
2025-11-25 21:35:32,896 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.c.DynamicMigrationComponentsInitializer [NONE] - Stopping LAM, LeaderDecider, workerMetrics reporting and collection
2025-11-25 21:35:32,896 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.c.a.LeaseAssignmentManager [NONE] - Completed shutdown of LeaseAssignmentManager
2025-11-25 21:35:32,897 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.c.DynamicMigrationComponentsInitializer [NONE] - Stopping worker metrics reporter
2025-11-25 21:35:32,897 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.c.DynamicMigrationComponentsInitializer [NONE] - Shutting down lamThreadPool and workerMetrics reporter thread pool
2025-11-25 21:35:32,898 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.l.d.DynamoDBLeaseCoordinator [NONE] - Worker b9004ba2-4e7f-409a-9d18-6cf54e862d1c has successfully stopped lease-tracking threads
2025-11-25 21:35:32,898 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.l.LeaseGracefulShutdownHandler [NONE] - Stopping graceful lease handoff thread.
2025-11-25 21:35:32,898 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.leases.LeaseCleanupManager [NONE] - Stopping the lease cleanup thread.
2025-11-25 21:35:32,899 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.c.PeriodicShardSyncManager [NONE] - Shutting down leader decider on worker b9004ba2-4e7f-409a-9d18-6cf54e862d1c
2025-11-25 21:35:32,899 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.l.DynamoDBLockBasedLeaderDecider [NONE] - Current worker : b9004ba2-4e7f-409a-9d18-6cf54e862d1c holds the lock, releasing it.

2025-11-25 21:35:33,018 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.c.PeriodicShardSyncManager [NONE] - Shutting down periodic shard sync task scheduler on worker b9004ba2-4e7f-409a-9d18-6cf54e862d1c
2025-11-25 21:35:33,898 [multi-lang-daemon-0000] INFO  s.a.kinesis.coordinator.Scheduler [NONE] - Lease failover time is reached, so forcing shutdown.
2025-11-25 21:35:33,898 [multi-lang-daemon-0000] INFO  s.a.kinesis.coordinator.Scheduler [NONE] - Starting worker's final shutdown.
2025-11-25 21:35:33,898 [multi-lang-daemon-0000] INFO  s.a.k.m.CloudWatchPublisherRunnable [NONE] - Shutting down CWPublication thread.
2025-11-25 21:35:33,998 [cw-metrics-publisher] INFO  s.a.k.m.CloudWatchPublisherRunnable [NONE] - CWPublication thread finished.
2025-11-25 21:35:33,998 [multi-lang-daemon-0000] INFO  s.a.kinesis.coordinator.Scheduler [NONE] - Worker loop is complete. Exiting from worker.
2025-11-25 21:35:34,019 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.c.GracefulShutdownCoordinator$GracefulShutdownCallable [NONE] - Waiting for 1 record processors to complete final shutdown
2025-11-25 21:35:34,019 [ForkJoinPool.commonPool-worker-1] INFO  s.a.k.c.GracefulShutdownCoordinator$GracefulShutdownCallable [NONE] - Shutdown completed, but shutdownCompleteLatch still had outstanding 1 with a current value of 1. shutdownComplete: true -- Consumer Map: 1
2025-11-25 21:35:34,019 [Thread-1] INFO  s.a.k.multilang.MultiLangDaemon [NONE] - Process shutdown is complete.

This issue affects my consumer any time it scales in and on every container replacement (especially bad at deploy time).

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Fields

    No fields configured for issues without a type.

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions