[Ovmsdev] Changed log file timestamps

[Stephen Casner]

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