While investigating the delay in ssh connection establishment I observed that the wallclock timestamps added to the log file don't match the deltas in the kernel-supplied uptime timestamps: 2021-02-10 09:55:35 PST I (305470) wolfssh: Entering wolfSSH_accept() 2021-02-10 09:55:35 PST I (305480) wolfssh: Entering DoKexInit() 2021-02-10 09:55:35 PST I (305480) wolfssh: Leaving DoKexInit(), ret = 0 2021-02-10 09:55:35 PST I (305490) wolfssh: Entering wolfSSH_accept() 2021-02-10 09:55:35 PST I (305490) wolfssh: Entering SendKexDhReply() 2021-02-10 09:55:35 PST I (310800) wolfssh: Signing hash with RSA. 2021-02-10 09:55:35 PST I (312640) wolfssh: Entering SendNewKeys() 2021-02-10 09:55:35 PST I (312640) wolfssh: Entering wolfSSH_SendPacket() 2021-02-10 09:55:35 PST I (312640) wolfssh: Leaving SendNewKeys(), ret = 0 2021-02-10 09:55:35 PST I (312640) wolfssh: Leaving SendKexDhReply(), ret = 0 That's because the wallclock timestamps are obtained when the log is written, not when the message occurred and may have been queued. I have improved this by basing the timestamps on the kernel-supplied uptime timestamp added to a calculated system boot time. I also extended the wallclock timestamp with milliseconds: 2021-02-10 23:59:16.410 PST I (99560) wolfssh: Entering wolfSSH_accept() 2021-02-10 23:59:16.410 PST I (99560) wolfssh: Entering DoKexInit() 2021-02-10 23:59:16.410 PST I (99560) wolfssh: Leaving DoKexInit(), ret = 0 2021-02-10 23:59:16.420 PST I (99570) wolfssh: Entering wolfSSH_accept() 2021-02-10 23:59:16.420 PST I (99570) wolfssh: Entering SendKexDhReply() 2021-02-10 23:59:16.430 PST I (99580) wolfssl: wolfSSL Entering wc_ecc_make_key_ex2 2021-02-10 23:59:18.730 PST I (101880) wolfssl: wolfSSL Leaving wc_ecc_make_key_ex2, return 0 2021-02-10 23:59:18.730 PST I (101880) wolfssl: wolfSSL Entering wc_ecc_shared_secret 2021-02-10 23:59:21.070 PST I (104220) wolfssl: wolfSSL Leaving wc_ecc_shared_secret, return 0 2021-02-10 23:59:21.070 PST I (104220) wolfssh: Signing hash with RSA. 2021-02-10 23:59:21.070 PST I (104220) wolfssl: wolfSSL Entering RsaPublicEncryptEx 2021-02-10 23:59:22.980 PST I (106130) wolfssl: wolfSSL Leaving RsaPublicEncryptEx, return 256 2021-02-10 23:59:22.980 PST I (106130) wolfssh: Entering SendNewKeys() 2021-02-10 23:59:22.980 PST I (106130) wolfssh: Entering wolfSSH_SendPacket() 2021-02-10 23:59:22.980 PST I (106130) wolfssh: Leaving SendNewKeys(), ret = 0 2021-02-10 23:59:22.990 PST I (106140) wolfssh: Leaving SendKexDhReply(), ret = 0 If the extra milliseconds field is going to cause breakage in some scripts or something I can remove it. -- Steve