Impossible to correlate logs from NIO worker threads

[baiglin]

Version

2.18.0

Bug description

Hi,

We have sometimes the need to enable DEBUG logs to see what is happening in more details, the window adjustment messages etc... to investigate issues. Lately we have a problem with a server where some connections are fast, we create different channels in the same sessions, and they are all slow but if we create a new connections, it is fast. As a workaround we have implemented a way to renew the connections if it is opened for more than x minutes.
And when we open new session, then the transfer is fast again. It is really hard to understand what could cause this slowness, for that we enabled debug logs on mina, but we do not know how to correlate the logs from nio threads as we loose the mdc context and we have a lot of different logs!

Is there a way to correlate the logs ?

I know there are listeners that we could implement but obviously it does not cover all cases.

Actual behavior

Lot of logs from different threads without common client session identifier

Expected behavior

Be able to propagate MDC context to correlate logs

Relevant log output

[sshd-SshClient[f237ae7]-nio2-thread-1][common-transfer] DEBUG o.a.s.c.s.ClientSessionImpl doHandleMessage(ClientSessionImpl[adds.user@localhost/127.0.0.1:62253]) process #5 SSH_MSG_CHANNEL_OPEN_CONFIRMATION
2026-06-24 12:37:30,656 [sshd-SshClient[f237ae7]-nio2-thread-1][common-transfer] DEBUG o.a.s.c.s.ClientConnectionService channelOpenConfirmation(SftpChannelSubsystem[id=0, recipient=-1]-ClientSessionImpl[adds.user@localhost/127.0.0.1:62253][sftp]) SSH_MSG_CHANNEL_OPEN_CONFIRMATION sender=0, window-size=2097152, packet-size=32768
2026-06-24 12:37:30,656 [sshd-SshClient[f237ae7]-nio2-thread-1][common-transfer] DEBUG o.a.s.s.c.i.DefaultSftpClient$SftpChannelSubsystem setRecipient(SftpChannelSubsystem[id=0, recipient=-1]-ClientSessionImpl[adds.user@localhost/127.0.0.1:62253][sftp]) recipient=0
2026-06-24 12:37:30,656 [sshd-SshClient[f237ae7]-nio2-thread-1][common-transfer] DEBUG o.a.s.c.c.RemoteWindow init(RemoteWindow[client](SftpChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[adds.user@localhost/127.0.0.1:62253][sftp])) size=2097152, max=2097152, packet=32768

Other information

No response

[tomaswolf]

We have not implemented anything for MDC. Interestingly the few logs do show the client session identifier -- I think almost all logging in Apache MINA SSHD does include that. Channel-specific logging usually also outputs the channel.

MDC relies on thread-locals, and asynchronous hand-off may lose the MDC. So it would need extra code and extra care to avoid memory leaks or having the wrong MDC in a thread.

I don't quite see what advantages an MDC would bring over the current implementation.

[baiglin]

Hi Thomas,

I know how hard in such case implement MDC would be. It is more the only simple way we would have to identify a session would be by logging both the remote connect address and the local address to have the exact socket as we have simultaneously several connections to the same destination. Still inside the same session we could have different channel, here I hav a prod example

2026/06/22 14:46:57.953000 universal-distributor-dispatcher-genericloop-7569f87f67-fjl9k DDS_UDD#0-0 APP DEBUG <o.a.s.s.c.i.DefaultSftpClient$SftpChannelSubsystem#0 TID#00000> genericLoop [sshd-SshClient[1abf38d1]-nio2-thread-5] {} handleWindowAdjust(SftpChannelSubsystem[id=1, recipient=1]-ClientSessionImpl[user@xxxx.com/50.50.50.50:22][sftp]) SSH_MSG_CHANNEL_WINDOW_ADJUST window=131052
2026/06/22 14:46:57.952000 universal-distributor-dispatcher-genericloop-7569f87f67-fjl9k DDS_UDD#0-0 APP DEBUG <o.a.s.s.c.i.DefaultSftpClient$SftpChannelSubsystem#0 TID#00000> genericLoop [sshd-SshClient[1abf38d1]-nio2-thread-2] {} handleWindowAdjust(SftpChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[user@xxxx.com/50.50.50.50:22][sftp]) SSH_MSG_CHANNEL_WINDOW_ADJUST window=131052
2026/06/22 14:46:57.870000 universal-distributor-dispatcher-genericloop-7569f87f67-fjl9k DDS_UDD#0-0 APP DEBUG <o.a.s.s.c.i.DefaultSftpClient$SftpChannelSubsystem#0 TID#00000> genericLoop [sshd-SshClient[1abf38d1]-nio2-thread-8] {} handleWindowAdjust(SftpChannelSubsystem[id=1, recipient=1]-ClientSessionImpl[user@xxxx.com/50.50.50.50:22][sftp]) SSH_MSG_CHANNEL_WINDOW_ADJUST window=131052
2026/06/22 14:46:57.869000 universal-distributor-dispatcher-genericloop-7569f87f67-fjl9k DDS_UDD#0-0 APP WARN <c.a.d.d.t.s.s.l.SetupSessionListener#0 TID#00000> genericLoop [sshd-SshClient[1abf38d1]-nio2-thread-11] {DOMAIN=RMS, MEDIA_TYPE=SFTP, DROPBOX=*, PROFILE=RMS_BFF_dest, CORR_ID=d2d0f215-c388-4307-9900-a8f9a2768c2b, RUN_ID=a4cb8ec9-d1d1-4046-ac5e-fe124fc87690, OL_ID=3693281135, FILE_NAME=PRD.RMS.NFS.D260622.T120000.AMA.SWA.A.00039.csv.gz, SUBSCRIBER=WN, SSH_HOST=xxxx.com, SSH_PORT=22} Channel 1 has limited window size (0 bytes, expected 2097152): server may be rate-limiting this connection, throughput may be throttled
2026/06/22 14:46:57.869000 universal-distributor-dispatcher-genericloop-7569f87f67-fjl9k DDS_UDD#0-0 APP DEBUG <o.a.s.c.s.ClientConnectionService#0 TID#00000> genericLoop [sshd-SshClient[1abf38d1]-nio2-thread-11] {} channelOpenConfirmation(SftpChannelSubsystem[id=1, recipient=-1]-ClientSessionImpl[user@xxxx.com/50.50.50.50:22][sftp]) SSH_MSG_CHANNEL_OPEN_CONFIRMATION sender=1, window-size=0, packet-size=32768

the id and recipient are not unique if those are the channel identifier, so it is hard to correlate exactly all logs.

Maybe I am wrong but I do not see obvious correlator here.

Thnks for the feedback

[tomaswolf]

the id and recipient are not unique

Hmmm. True for client sessions. Printing the peer address doesn't help for client sessions if you have multiple sessions with the same user to the same server.

For client sessions, it might help to include the locally bound port.

Instead of adding code to deal with MDC through thread locals (which I'd prefer not to have because of the concern mentioned above) we could maybe think about ways to customize SessionHelper.toString() and possibly the channels' toString() method. Of course you could do so already by subclassing ClientSessionImpl (and the factory), but that's tedious. And more tedious to do for channels. But if the library had a simple way to configure this, it might be good enough for this purpose and less risky and simpler to implement.

[bferrenq]

Thank you @tomaswolf .
Also given :

1. the use case , which is the ability to troubleshoot why a given file transfer using sftp is slow,
2. and the huge number of log that would be logged

would it be possible to expose/log few stats.
I have in mind, for instance 1 one line stat vs 1M row parsing:
Total WINDOW_ADJUST messages : 1,011,049
Rate : 768.0 msg/s
Min window : 4,096 bytes (4.0 KB)
Max window : 2,097,152 bytes (2048.0 KB)
Mean window : 22,703 bytes (22.2 KB)
Zero-window occurrences : 0
Small-window (≤4 KB) : 801,650 (79.3%)
Mean gap between adjusts : 1.3 ms
Longest gap between adjusts : 1402.0 ms

Thx!

[baiglin]

Hi @tomaswolf , sorry to bother you with this one again, on our side we have implemented a ChannelListener, that compute statistics around the Window adjust, one remark:

• In the method for state changes we only get in the hint the sftp command (SSH_MSG_CHANNEL_WINDOW_ADJUST) without the value of the window adjust... And sometimes when I access the remoteWindow Size (channel.getRemoteWindow().getSize()) right after it is already down to 0... And we agree it is impossible we receive WINDOW ADJUST with a value of 0....

  @Override
  public void channelStateChanged(Channel channel, String hint) {

Long story short I cannot precisely confirm that the server sends huge amount tiny Window Adjust but it looks like this.... And DEBUG logs does not help for previous reasons, while here I am free to propagate context to correlate my logs...

Second question is if I wanted to show that WE on client side are waiting on the server to allocate more space on the window to send data (Meaning remote size is 0 and we wait for server to send Window Adjust), do you have hint on how we could do, I dug and could not find easy way...

Here we have the feeling that the few really slow transfer are due to the server struggling to read data and for some reason send an insane amount of small window adjust....

[baiglin]

Hi @tomaswolf here is what we have done to try to demonstrate server is the culprit:

public class SftpClient extends DefaultSftpClient {

  /**
   * @param clientSession
   *          The {@link ClientSession}
   * @param initialVersionSelector
   *          The initial {@link SftpVersionSelector} - if {@code null} then version 6 is assumed.
   * @param errorDataHandler
   *          The {@link SftpErrorDataHandler} to handle incoming data through the error stream - if {@code null} the
   *          data is silently ignored
   * @throws IOException
   *           If failed to initialize
   */
  public SftpClient(ClientSession clientSession,
      SftpVersionSelector initialVersionSelector,
      SftpErrorDataHandler errorDataHandler) throws IOException {
    super(clientSession, initialVersionSelector, errorDataHandler);
  }

  /**
   * {@inheritDoc
   */
  @Override
  public SftpMessage write(int cmd, Buffer buffer) throws IOException {
    return new InternalSftpMessage(super.write(cmd, buffer));
  }

  class InternalSftpMessage extends SftpMessage {

    public InternalSftpMessage(SftpMessage sftpMessage) {
      super(sftpMessage.getId(), sftpMessage.getFuture(), sftpMessage.getTimeout());
    }

    @Override
    public void waitUntilSent() throws IOException {
      long time = System.currentTimeMillis();
      super.waitUntilSent();
      // Compute the wait time and update statistics
      long waitTime = System.currentTimeMillis() - time;
     // UPdatae the stat objects created in the channel listener
      SftpClient.this.getChannel()
          .getAttribute(ChannelMonitorListener.CHANNEL_STATS_ATTRIBUTE_KEY)
          .getMessageWaitTime()
          .add(waitTime);
    }

@Slf4j
public class ChannelMonitorListener implements ChannelListener {

  // Default SSH channel window size (2,097,152 bytes) CoreModuleProperties.DEFAULT_WINDOW_SIZE

  // Threshold: warn if server assigns less than 1MB (indicating rate-limiting)
  private static final long WINDOW_SIZE_WARNING_THRESHOLD = 1_048_576L;

  /**
   * SSH_MSG_CHANNEL_WINDOW_ADJUST is a constant representing the SSH message type for channel window adjustment events.
   */
  public static final String SSH_MSG_CHANNEL_WINDOW_ADJUST = "SSH_MSG_CHANNEL_WINDOW_ADJUST";

  /**
   * Attribute to store channel stats
   */
  public static final AttributeRepository.AttributeKey<ChannelStats> CHANNEL_STATS_ATTRIBUTE_KEY =
      new AttributeRepository.AttributeKey<>();

  @Override
  public void channelInitialized(Channel channel) {
    SessionMdcPropagator.extractMdcContextToChannel(channel);
    LOG.info("Channel 'id={}' initialized from session localAddress={}, remoteAddress={}", channel.getChannelId(),
        channel.getSession().getLocalAddress(), channel.getSession().getRemoteAddress());

    // Create channel stats object
    channel.setAttribute(CHANNEL_STATS_ATTRIBUTE_KEY, new ChannelStats());
  }

  @Override
  public void channelOpenSuccess(Channel channel) {
    try {
      SessionMdcPropagator.propagateMdcContextFromAttributes(channel);

      channel.getAttribute(CHANNEL_STATS_ATTRIBUTE_KEY).updateStats(channel);
    } finally {
      SessionMdcPropagator.clear(channel);
    }
  }

In the end to compute stats as channel closed:

Channel 'id=0' closed from session localAddress=/xx.xx.xx.xx.xx:58352, remoteAddress=/xx.xx.xx.xx:22 after 6043518 ms (6043.518 s.). Reason: Normal closure.
Round Trip Time (RTT): 642 ms
Packet Size: local size=32768 bytes, remote size=32768 bytes
Number of transfers on this channel: 1
Sftp Message Wait time statistics:  average size=1343.6645089285723 ms, max size=16281.0 ms, min size=0.0 ms, deviation=2760.3744373805444 ms, count=4480
Local Window statistics: average size=2055742.5244444483 bytes, max size=2097152.0 bytes, min size=1998884.0 bytes, deviation=29255.405394112648 bytes, count=1125
Remote Window statistics: average size=1672537.548444444 bytes, max size=2097152.0 bytes, min size=98289.0 bytes, deviation=409827.6400159729 bytes, count=1125
Elapsed time between window adjust statistics: average time=5371.843555555543 ms, max time=15737.0 ms, min time=0.0 ms, deviation=2910.765478314483 ms, count=1125
Number of time remote window size was 0: 0

In normal time we see Sftp Message Wait time statistics: average size=0.25 ms, max size=1.0 ms, min size=0.0 ms, deviation=0.4330127018922193 ms, count=4

I wanted to confirm that the only possibility to wait during the upload in the waitUntilSent method is when we are waiting for window expansion ... Because normally the IOFuture should return as soon as write operation is done.

When I check the code SftpOutputStreamAsinc#internalFlush -> client.write() -> ChannelAsyncOutputStream#writeBuffer -> ChannelAsyncOutputStream#doWriteIfPossible -> ChannelAsyncOutputStream#writePacket that return the future without doing anything, while if possible to write it should perform the write, return null and resume the future once write operation is done.

So this should completely confirm the culprit is server is lon to read and sends WINDOW ADJUST