Statistics File Lack of CRLF at End of Entry Line

[Jack Winch (RR)]

Hi folks,

I'm currently running ptpd2 version 2.3.1 on Raspbian GNU/Linux 9 (stretch) and have only made the following changes to the standard ptd2.conf file (the rest of the config remains un-changed and in its default state post-install) in order to enable the logging of stats.

global:statistics_file = /var/log/ptpd2-stats.log
global:statistics_log_interval = 1
global:statistics_file_max_size = 100

I can produce more of the config. file (and any other details) upon request.

The statistics file is being produced, however there appears to be an issue with a lack of end-of-line CR LF after the first few log entries. This can be seen below (some lines omitted for readability and are denoted using '[...]').

# Timestamp, State, Clock ID, One Way Delay, Offset From Master, Slave to Master, Master to Slave, Observed Drift, Last packet Received, One Way Delay Mean, One Way Delay Std Dev, Offset From Master Mean, Offset From Master Std Dev, Observed Drift Mean, Observed Drift Std Dev, raw delayMS, raw delaySM
2018-10-02 16:51:30.697098, init,
2018-10-02 16:51:30.802144, lstn_init,  1
2018-10-02 16:51:31.420286, slv, 80e01dfffe735841(unknown)/34000cecfffe0a0eeb,  0.000000000,  0.000000000,  0.000000000,  0.000000000, -21205.612182617, I, 0.000000000, 0, 0.000000000, 0, 0, 0,  0.000000000,  0.000000000
2018-10-02 16:51:33.414165, slv, 80e01dfffe735841(unknown)/34000cecfffe0a0eeb,  0.000000000,  0.023918438,  0.000000000,  0.047836876, -21205.612182617, S, 0.000000000, 0, 0.000000000, 0, 0, 0,  0.048000909,  0.000000000
2018-10-02 16:51:34.410095, slv, 80e01dfffe735841(unknown)/34000cecfffe0a0eeb,  0.000083041,  0.023918438, -0.047273083,  0.047836876, -21205.612182617, D, 0.000000000, 0, 0.000000000, 0, 0, 0,  0.048000909, -0.047273083
2018-10-02 16:51:35.410712, slv, 80e01dfffe735841(unknown)/34000cecfffe0a0eeb,  0.000083041,  0.047813370, -0.047273083,  0.047872905, -21205.612182617, S, 0.000000000, 0, 0.000000000, 0, 0, 0,  0.048102553, -0.047273083

[...]

2018-10-02 16:52:01.363988, slv, 80e01dfffe735841(unknown)/34000cecfffe0a0eeb,  0.000388607,  0.035305063, -0.034647740,  0.035194389, 500000.000000000, S, 0.000000000, 0, 0.000000000, 0, 0, 0,  0.035380358, -0.034647740
2018-10-02 16:52:02.519895, slv, 80e01dfffe735841(unknown)/34000cecfffe0a0eeb,  0.000393353,  0.035305063, -0.034113364,  0.035194389, 500000.000000000, D, 0.000308621, 79478, 0.040520844, 6068468, 385035, 178607,  0.035380358,2018-10-02 16:52:02.519895, slv, 80e01dfffe735841(unknown)/34000cecfffe0a0eeb,  0.000393353,  0.035305063, -0.034113364,  0.035194389, 500000.000000000, D, 0.000308621, 79478, 0.040520844, 6068468, 385035, 178607,  0.035380358

[...]

Having removed the statistics log file completely and repeated the test (between stopping and starting the service) I can confirm that the first line effected by a lack of CRLF always appears to be the first line where columns 'One Way Delay Mean' thru 'Observed Drift Std Dev' is listed as a non-zero value. Is this a known problem?

Your suggestions on how I can rectify the issue would be much appreciated (although, I suspect this will require a bug fix). As always, if this is not a known issue, I am always happy to assist in a bug hunting exercise. :)

Many Thanks,
Jack W.

[Eric Bonjour]

Have the same issues with CRLF. Running on CentOS 7.3.
Were you able to find any configuration values that help mitigate the bug Jack?

[Eric Bonjour]

Shortly after my last post I found:
; Timestamp format used when logging timing statistics
; (when global:log_statistics is enabled):
; datetime - formatttted date and time: YYYY-MM-DD hh:mm:ss.uuuuuu
; unix - Unix timestamp with nanoseconds: s.ns
; both - Formatted date and time, followed by unix timestamp
; (adds one extra field to the log)
;
; Options: datetime unix both

Changing to
global:statistics_timestamp_format = unix
results in no CRLF issues, try it on your side.

Changing to
global:statistics_timestamp_format = both
results in no CRLFs at all! So something is up with the timestamp that causes this bug.