Hope this make sense.
Below is part of a debug log, what I wondering is what is the "[aa.bbb]". It appears to be "time" and it seems to be seconds.milliseconds. However, in some logs the "seconds" seems to match the "clock" seconds. Meaning if the session started at 10:30:25, I will see [25.bbb], other times it will it will be the current seconds puls a multiple of 10.
Examples of the multiple of 10 thing, I had "-e -l debug" on and logged on multple times. Output from 'grep "client version" *'.
sftp-server.xxx0ft1.285.101352.303.log:[32.882] received client version 3 - current seconds +40
sftp-server.xxx0ft1.285.101605.50332425.log:[65.440] received client version 3 - current seconds +60
sftp-server.xxx0ft1.285.105219.33555310.log:[39.540] received client version 3 - current seconds +20
sftp-server.xxx0ft1.285.105753.16778089.log:[73.497] received client version 3 - current seconds +20
sftp-server.xxx0ft1.285.112738.50331839.log:[58.163] received client version 3 - current seconds +20
sftp-server.xxx0ft1.285.114608.67109337.log:[68.775] received client version 3 - current seconds +60
sftp-server.xxx0ft1.285.114703.281.log:[23.407] received client version 3 - current seconds +20
sftp-server.xxx0ft1.285.115058.441.log:[58.811] received client version 3 - current seconds
sftp-server.xxx0ft1.285.115938.16777657.log:[78.527] received client version 3 - current seconds 40
Example
Co:Z SFTP Server version: 5.1.1 (6.4p1) 2018-06-01
Copyright (C) Dovetailed Technologies, LLC. 2008-2018. All rights reserved.
ZosSettings[T]: -> readConfiguration()
ZosSettings[T]: -> processConfigurationFile(/etc/ssh/cozsftp_server_config)
ZosSettings[T]: processConfigurationFile: Processing fixed: configuration file section
ZosSettings[T]: processConfigurationFile: Processing configuration file option: 'conddisp=delete'
ZosSettings[T]: processConfigurationFile: Processing default: configuration file section
ZosSettings[T]: processConfigurationFile: Processing configuration file option: 'release'
ZosSettings[T]: processConfigurationFile: Processing configuration file option: 'lrecl=0'
ZosSettings[T]: processConfigurationFile: Processing configuration file option: 'blksize=27990'
ZosSettings[T]: processConfigurationFile: Processing configuration file option: 'recfm=u'
ZosSettings[T]: processConfigurationFile: Processing configuration file option: 'space=cyl.200.200'
ZosSettings[T]: processConfigurationFile: Processing configuration file option: 'unit=sysda'
ZosSettings[T]: processConfigurationFile: Processing configuration file option: 'ucount=3'
< Some data cut out>
[14.149] session opened for local user XXX0FT1 from [172.16.111.57]
Connection established, local_addr=172.16.206.1 local_port=22 remote_addr=172.16.111.57 remote_port=51035
ZosExitInterface[T]: -> checkIP()
ZosExitInterface[T]: checkIP: unable to load CZCHKIP - EDC5239S FETCHED MODULE NOT FOUND. (errno2=0xC4070044)
ZosExitInterface[T]: <- checkIP(true (module not found))
ZosExitInterface[T]: -> checkPwd()
ZosExitInterface[T]: <- checkPwd(true, rc=0)
[14.172] debug3: Type: SSH2_FXP_INIT
[14.172] received client version 3
[14.196] debug3: Type: SSH2_FXP_REALPATH
[14.196] debug3: request 1: realpath
[14.196] realpath "."
[14.196] debug3: initial zos directory requested: /xmtftp/xxx
[14.196] debug1: request 1: sent names count 1
[17.383] debug3: Type: SSH2_FXP_OPENDIR
[17.383] debug3: request 2: opendir
[17.383] opendir "/xmtftp/xxx"
ZosExitInterface[T]: -> checkCommandWithFileArg(LIST /xmtftp/xxx)
ZosExitInterface[D]: -> checkSetFiletype(SEQ)
ZosExitInterface[D]: <- checkSetFiletype(true (no change))
ZosExitInterface[T]: <- checkCommandWithFileArg(true, outfile="/xmtftp/xxx")
[17.390] debug1: request 2: sent handle handle 0
[17.398] debug3: Type: SSH2_FXP_READDIR
[17.398] debug1: request 3: readdir "/xmtftp/xxx" (handle 0)
[17.403] debug1: request 3: count= 0 name= "." long_name= "drwxr-x--- 3 BPXROOT FTP 8192 Oct 12 17:26 ."
[17.414] debug1: request 3: count= 1 name= ".." long_name= "drwxr-xr-x 3 ATPAJSG STS 288 Sep 23 2010 .."
[17.414] debug1: request 3: count= 2 name= ".sh_history" long_name= "-rwxr-x--- 1 XXX0FT1 FTP 605 Sep 24 2010 .sh_history"
[17.414] debug1: request 3: count= 3 name= ".ssh" long_name= "drwxr-x--- 2 BPXROOT FTP 8192 Oct 12 14:22 .ssh"