Re: Proposal about new default SSL log format

[William Lallemand]

On Thu, Jul 08, 2021 at 02:48:32PM +0200, Willy Tarreau wrote:
> On Thu, Jul 08, 2021 at 02:18:32PM +0200, William Lallemand wrote:
> > I saw that you hesitated between "conn_status" and "conn_err_code", the
> > "conn_" prefix could be confusing at some point once you try to have
> > errors on the frontend and the backend side in the same log-format, I
> > think something starting by "fc_conn_" would be more understandable.
> 
> Indeed, and more consistent with what we already have. fc_* is for the
> front connection, bc_* is for the back connection. By the way if we're
> focusing on SSL it should even be ssl_fc_* (we already have a ton of
> them, nobody will find the new one if it doesn't use the same prefix).
>

That's what Rémi implemented for the SSL fetches, but the connection
error one is more generic and does not focus on SSL at all.

> > That seems good to me, we only need frontend info IMHO. People who need
> > the SSL backend connection are not the most common case so they could
> > make their own log-format with it.
> 
> I tend to think that if we're focusing on https vs http, it makes sense
> to consider the frontend only as well for the standard logs.
>

I agree.

> Also some background on the log format, originally we used to place the
> URI at the end of the line because most loggers used to truncate logs
> at 1024 bytes and the tail of the URI was far less important than other
> fields. This explains why we've started to insert certain fields at
> certain places before this. 20 years later I think it is perfectly
> reasonable to consider appending fields *after* the URI, which is also
> a great way of applying minimal changes to existing log parsers, and
> to allow http/https log lines to be easily compared when aligned.
> 

I agree, this way it's easily readable without having to realign
mentally the fields in common between an http line and an https one.


-- 
William Lallemand

Re: Proposal about new default SSL log format

[Willy Tarreau]

On Thu, Jul 08, 2021 at 02:18:32PM +0200, William Lallemand wrote:
> I saw that you hesitated between "conn_status" and "conn_err_code", the
> "conn_" prefix could be confusing at some point once you try to have
> errors on the frontend and the backend side in the same log-format, I
> think something starting by "fc_conn_" would be more understandable.

Indeed, and more consistent with what we already have. fc_* is for the
front connection, bc_* is for the back connection. By the way if we're
focusing on SSL it should even be ssl_fc_* (we already have a ton of
them, nobody will find the new one if it doesn't use the same prefix).

> That seems good to me, we only need frontend info IMHO. People who need
> the SSL backend connection are not the most common case so they could
> make their own log-format with it.

I tend to think that if we're focusing on https vs http, it makes sense
to consider the frontend only as well for the standard logs.

Also some background on the log format, originally we used to place the
URI at the end of the line because most loggers used to truncate logs
at 1024 bytes and the tail of the URI was far less important than other
fields. This explains why we've started to insert certain fields at
certain places before this. 20 years later I think it is perfectly
reasonable to consider appending fields *after* the URI, which is also
a great way of applying minimal changes to existing log parsers, and
to allow http/https log lines to be easily compared when aligned.

Willy

Re: Proposal about new default SSL log format

[William Lallemand]

Hello,

On Wed, Jul 07, 2021 at 04:43:53PM +0200, Remi Tricot-Le Breton wrote:
> I was indeed more focused on logging SSL related information only, with 
> the idea that an SSL log line could be displayed after a completed 
> handshake, hence the lack of upper layer information in the log line. 
> But it would indeed bring a new level of complexity in the log because 
> correlating the SSL and HTTP log lines of a specific session might be a 
> pain. After talking with Willy, an https log was deemed more useful. It 
> would only be an extension of the existing HTTP log with SSL specific 
> information added. This log format would concern every log line raised 
> by the frontends using this log format (one line per HTTP response of 
> the SSL session).

Yes, what would be great is a "option httpslog" which would provide a
default log line for HTTP over SSL.

> A quick recap of the topics raised by the multiple conversations had in 
> this thread :
> - we won't used tabs as separators in order to remain consistent with 
> the existing log format (especially since this new format will only be 
> an extension of the HTTP one)

I agree, using tab doesn't not seems to be something we would want, it's
the same problem with people that would want json in their log, they
need a new format, not the default one.

> - the date format won't change right now, it is a whole new subject
> - the logged lines will all have the same "date+process_name+pid" prefix 
> as the already existing logs
> - the HTTP log format won't be touched yet, changing it would be a whole 
> new subject as well

Agreed.

> 
> 
> The log would then be as follows :
> 
> 
>      >>> Jul  1 18:11:31 haproxy[143338]: 127.0.0.1:37740 
> [01/Jul/2021:18:11:31.517] \
>    ssl_frontend~ ssl_frontend/s2 0/0/0/7/+7 200 2750 - -  \
>    1/1/1/1/0 0/0 {1wt.eu} {} "GET /index.html HTTP/1.1 \
>    0/0/0/0 TLSv1.3/TLS_AES_256_GCM_SHA384
> 
>    Field   Format    Extract from the 
> example above
>    1   process_name '[' pid ']:' haproxy[143338]:
>    2   client_ip ':' client_port 127.0.0.1:37740
>    3   '[' request_date ']' [01/Jul/2021:18:11:31.517]
>    4   frontend_name ssl_frontend~
>    5   backend_name '/' server_name ssl_frontend/s2
>    6   TR '/' Tw '/' Tc '/' Tr '/' Ta*   
> 0/0/0/7/+7
>    7 status_code 200
>    8 bytes_read* 2750
>    9 captured_request_cookie -
>   10 captured_response_cookie -
>   11 termination_state 
>   12   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*    
> 1/1/1/1/0
>   13   srv_queue '/' 
> backend_queue  0/0
>   14   '{' captured_request_headers* '}' {haproxy.1wt.eu}
>   15   '{' captured_response_headers* 
> '}'    {}
>   16   '"' http_request '"'  "GET /index.html 
> HTTP/1.1"
>   17 *conn_status '/' SSL fe hsk error '/' SSL vfy '/' SSL CA vfy*  
> 0/0/0/0
>   18 *ssl_version '/' ssl_ciphers* TLSv1.3/TLS_AES_256_GCM_SHA384
> 
> and the corresponding log-format :
> 
>      %ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC \
>      %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r \
> *%[conn_err_code]/%[ssl_fc_hsk_err]/%[ssl_c_err]/%[ssl_c_ca_err]* \
> *%sslv/%sslc*
> 

I saw that you hesitated between "conn_status" and "conn_err_code", the
"conn_" prefix could be confusing at some point once you try to have
errors on the frontend and the backend side in the same log-format, I
think something starting by "fc_conn_" would be more understandable.

That seems good to me, we only need frontend info IMHO. People who need
the SSL backend connection are not the most common case so they could
make their own log-format with it.


-- 
William Lallemand

Re: Proposal about new default SSL log format

[Tim Düsterhus]

Remi,

On 7/7/21 4:43 PM, Remi Tricot-Le Breton wrote:
A quick recap of the topics raised by the multiple conversations had in 
this thread :
- we won't used tabs as separators in order to remain consistent with 
the existing log format (especially since this new format will only be 
an extension of the HTTP one)

- the date format won't change right now, it is a whole new subject
- the logged lines will all have the same "date+process_name+pid" prefix 
as the already existing logs
- the HTTP log format won't be touched yet, changing it would be a whole 
new subject as well



The log would then be as follows :


     >>> Jul  1 18:11:31 haproxy[143338]: 127.0.0.1:37740 
[01/Jul/2021:18:11:31.517] \

   ssl_frontend~ ssl_frontend/s2 0/0/0/7/+7 200 2750 - -  \
   1/1/1/1/0 0/0 {1wt.eu} {} "GET /index.html HTTP/1.1 \
   0/0/0/0 TLSv1.3/TLS_AES_256_GCM_SHA384

*snip*

and the corresponding log-format :

     %ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC \
     %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r \
*%[conn_err_code]/%[ssl_fc_hsk_err]/%[ssl_c_err]/%[ssl_c_ca_err]* \
*%sslv/%sslc*



Looks good to me, this is a natural extension of the existing format.

Best regards
Tim Düsterhus

Re: Proposal about new default SSL log format

[Remi Tricot-Le Breton]

Hello,

On 06/07/2021 14:55, Willy Tarreau wrote:

On Tue, Jul 06, 2021 at 12:19:56PM +0200, Tim Düsterhus wrote:

Willy,

On 7/6/21 12:12 PM, Willy Tarreau wrote:

A few points first, that are needed to address various concerns. The
goal here is to defined an HTTPS log format because that's what the
vast majority of users are dealing with day-to-day. For specific usages,
everyone already redefines log formats. But for a very basic setup, right
now it's true that httplog is a bit limited, and all it shows to help guess
there was SSL involved is to append this '~' after the frontend's name.

It was not clear to me that this log format is meant to apply to HTTPS
requests, because the example given by Remi does not include the HTTP verb
and neither the request URI (unless I need glasses). I thought it was a
format for TLS errors or something like this.

At least it was my understanding that it was mostly aimed at HTTPS given
that the discussion we had on the subject started around this :-)

Is this a mistake in the examples? Or is HAProxy going to emit multiple log
lines: One for the TLS connection and one for each HTTP request passing
through this TLS connection?

There was a discussion around logging at various layers, I don't remember
if it was on the list or in a github issue, but I remember having been
involved in this some time ago. I think that it makes sense to ultimately
be able to emit error logs at various levels (i.e. when being certain that
no other event will happen) but it's particularly confusing to log successes
at various levels. Thus typically seeing TLS handshake failures is important
but their success should not be logged as all the info will instead be
available with the traffic logs. There are already enough users complaining
about noise caused by client-aborted connections :-)

Willy


I was indeed more focused on logging SSL related information only, with 
the idea that an SSL log line could be displayed after a completed 
handshake, hence the lack of upper layer information in the log line. 
But it would indeed bring a new level of complexity in the log because 
correlating the SSL and HTTP log lines of a specific session might be a 
pain. After talking with Willy, an https log was deemed more useful. It 
would only be an extension of the existing HTTP log with SSL specific 
information added. This log format would concern every log line raised 
by the frontends using this log format (one line per HTTP response of 
the SSL session).


A quick recap of the topics raised by the multiple conversations had in 
this thread :
- we won't used tabs as separators in order to remain consistent with 
the existing log format (especially since this new format will only be 
an extension of the HTTP one)

- the date format won't change right now, it is a whole new subject
- the logged lines will all have the same "date+process_name+pid" prefix 
as the already existing logs
- the HTTP log format won't be touched yet, changing it would be a whole 
new subject as well



The log would then be as follows :


    >>> Jul  1 18:11:31 haproxy[143338]: 127.0.0.1:37740 
[01/Jul/2021:18:11:31.517] \

  ssl_frontend~ ssl_frontend/s2 0/0/0/7/+7 200 2750 - -  \
  1/1/1/1/0 0/0 {1wt.eu} {} "GET /index.html HTTP/1.1 \
  0/0/0/0 TLSv1.3/TLS_AES_256_GCM_SHA384

  Field   Format    Extract from the 
example above

  1   process_name '[' pid ']:' haproxy[143338]:
  2   client_ip ':' client_port 127.0.0.1:37740
  3   '[' request_date ']' [01/Jul/2021:18:11:31.517]
  4   frontend_name ssl_frontend~
  5   backend_name '/' server_name ssl_frontend/s2
  6   TR '/' Tw '/' Tc '/' Tr '/' Ta*   
0/0/0/7/+7

  7 status_code 200
  8 bytes_read* 2750
  9 captured_request_cookie -
 10 captured_response_cookie -
 11 termination_state 
 12   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*    
1/1/1/1/0
 13   srv_queue '/' 
backend_queue  0/0

 14   '{' captured_request_headers* '}' {haproxy.1wt.eu}
 15   '{' captured_response_headers* 
'}'    {}
 16   '"' http_request '"'  "GET /index.html 
HTTP/1.1"
 17 *conn_status '/' SSL fe hsk error '/' SSL vfy '/' SSL CA vfy*  
0/0/0/0

 18 *ssl_version '/' ssl_ciphers* TLSv1.3/TLS_AES_256_GCM_SHA384

and the corresponding log-format :

    %ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC \
    %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r \
*%[conn_err_code]/%[ssl_fc_hsk_err]/%[ssl_c_err]/%[ssl_c_ca_err]* \
*%sslv/%sslc*

Thanks

Rémi

Re: Proposal about new default SSL log format

[Willy Tarreau]

On Tue, Jul 06, 2021 at 12:19:56PM +0200, Tim Düsterhus wrote:
> Willy,
> 
> On 7/6/21 12:12 PM, Willy Tarreau wrote:
> > A few points first, that are needed to address various concerns. The
> > goal here is to defined an HTTPS log format because that's what the
> > vast majority of users are dealing with day-to-day. For specific usages,
> > everyone already redefines log formats. But for a very basic setup, right
> > now it's true that httplog is a bit limited, and all it shows to help guess
> > there was SSL involved is to append this '~' after the frontend's name.
> 
> It was not clear to me that this log format is meant to apply to HTTPS
> requests, because the example given by Remi does not include the HTTP verb
> and neither the request URI (unless I need glasses). I thought it was a
> format for TLS errors or something like this.

At least it was my understanding that it was mostly aimed at HTTPS given
that the discussion we had on the subject started around this :-)

> Is this a mistake in the examples? Or is HAProxy going to emit multiple log
> lines: One for the TLS connection and one for each HTTP request passing
> through this TLS connection?

There was a discussion around logging at various layers, I don't remember
if it was on the list or in a github issue, but I remember having been
involved in this some time ago. I think that it makes sense to ultimately
be able to emit error logs at various levels (i.e. when being certain that
no other event will happen) but it's particularly confusing to log successes
at various levels. Thus typically seeing TLS handshake failures is important
but their success should not be logged as all the info will instead be
available with the traffic logs. There are already enough users complaining
about noise caused by client-aborted connections :-)

Willy

Re: Proposal about new default SSL log format

[Tim Düsterhus]

Willy,

On 7/6/21 12:12 PM, Willy Tarreau wrote:

A few points first, that are needed to address various concerns. The
goal here is to defined an HTTPS log format because that's what the
vast majority of users are dealing with day-to-day. For specific usages,
everyone already redefines log formats. But for a very basic setup, right
now it's true that httplog is a bit limited, and all it shows to help guess
there was SSL involved is to append this '~' after the frontend's name.


It was not clear to me that this log format is meant to apply to HTTPS 
requests, because the example given by Remi does not include the HTTP 
verb and neither the request URI (unless I need glasses). I thought it 
was a format for TLS errors or something like this.


Is this a mistake in the examples? Or is HAProxy going to emit multiple 
log lines: One for the TLS connection and one for each HTTP request 
passing through this TLS connection?



However, it's also clear that most users will not violently migrate from
httplog to httpslog, and it's important to keep a smooth enough transition.
This also means not to change stuff that would be relevant to httplog as
well (e.g. delimitors, time format etc).

We can (and should) have discussions about what to change in future log
formats, but let's not use the https one as a bootstrap for passing
everyone's missing field. Instead, let's focus on the SSL-specific stuff
that users are always missing from HTTP logs, and try to establish a
reasonable list that will always be there and suit most users without
adding too much for others, and that will require limited adaptations
to parsers.


Agree.

Best regards
Tim Düsterhus

Re: Proposal about new default SSL log format

[Willy Tarreau]

Hi Rémi,

[ I warned you that this was going to open a pandora box :-) ]

On Fri, Jul 02, 2021 at 04:26:48PM +0200, Remi Tricot-Le Breton wrote:
> Some work in ongoing to ease connection error and SSL handshake error
> logging.
> This will rely on some new sample fetches that could be added to a custom
> log-format string.
> In order to ease SSL logging and debugging, we will also add a new default
> log
> format for SSL connections. Now is then the good time to find the best
> format
> for everyone.
> The proposed format looks like the HTTP one to which the SSL specific
> information is added. But if anybody sees a missing information that could
> be
> beneficial for everybody, feel free to tell it, nothing is set in stone yet.

A few points first, that are needed to address various concerns. The
goal here is to defined an HTTPS log format because that's what the
vast majority of users are dealing with day-to-day. For specific usages,
everyone already redefines log formats. But for a very basic setup, right
now it's true that httplog is a bit limited, and all it shows to help guess
there was SSL involved is to append this '~' after the frontend's name.

However, it's also clear that most users will not violently migrate from
httplog to httpslog, and it's important to keep a smooth enough transition.
This also means not to change stuff that would be relevant to httplog as
well (e.g. delimitors, time format etc).

We can (and should) have discussions about what to change in future log
formats, but let's not use the https one as a bootstrap for passing
everyone's missing field. Instead, let's focus on the SSL-specific stuff
that users are always missing from HTTP logs, and try to establish a
reasonable list that will always be there and suit most users without
adding too much for others, and that will require limited adaptations
to parsers.

> The format would look like this :
>     >>> Jul  1 18:11:31 haproxy[143338]: 127.0.0.1:37740
> [01/Jul/2021:18:11:31.517] \
>   ssl_frontend~ ssl_frontend/s2 0/0/0/7/+7 \
>   0/0/0/0 2750  1/1/1/1/0 0/0 TLSv1.3 TLS_AES_256_GCM_SHA384

Like Aleks, I think that we could have a single version+cipher field,
as not all combinations are permitted anyway.

>   Field   Format    Extract from the example
> above
>   1   process_name '[' pid ']:' haproxy[143338]:
>   2   client_ip ':' client_port 127.0.0.1:37740
>   3   '[' request_date ']' [01/Jul/2021:18:11:31.517]
>   4   frontend_name ssl_frontend~
>   5   backend_name '/' server_name ssl_frontend/s2
>   6   TR '/' Tw '/' Tc '/' Tr '/' Ta*  
> 0/0/0/7/+7
>   7 *conn_status '/' SSL hsk error '/' SSL vfy '/' SSL CA vfy*0/0/0/0

Be careful above not to reproduce the errors from the past, namely
using a designation that could apply to both sides. "SSL hsk error"
etc could be valid for either frontend connection, backend connection
or both. We must absolutely be clear and explicit here about what
this is. The same will be true for the versions and ciphers.

I suspect that all of these will mostly be of interest for the front
side but I could be wrong (particularly for errors). But it's probable
that discussing the backend side already enters a new sub-topic in fact.

Willy

Re: Proposal about new default SSL log format

[Remi Tricot-Le Breton]

Hello Aleksandar,

On 03/07/2021 13:19, Aleksandar Lazic wrote:

Hi Remi.

How about to combine ssl_version/ssl_ciphers in one line.


Yes why not.



It would be helpful to see also the backend status.
Maybe add a 14th and 15th line with following fields

*backend_name '/' conn_status '/' SSL hsk error '/' SSL vfy '/' SSL CA 
vfy*

*backend_name '/' ssl_version '/' ssl_ciphers*


The backend name is already included in the log line, I'll avoid 
duplicating information.




I had in the past several issues with the backend where the backend CA 
wasn't in the CA File which was quite

difficult to debug.


Backend related errors won't be raised in the log line since it is 
emitted on the fronted side of the connection but this backend error 
problem will also be treated after this.




+1 to the suggestion from Илья Шипицин to use iso8601 which is already 
in haproxy since 2019/10/01:2.1-dev2.


I haven't found sub second format parameter in strftime call therefore 
I assume the strftime call have this

".00" as fix value.

```
strftime(iso_time_str, sizeof(iso_time_str), 
"%Y-%m-%dT%H:%M:%S.00+00:00", &tm)

```


In the timeofday_as_iso_us function where the strftime call happens, the 
time zone and microsecond precision are set in the time string just 
after the strftime call (see the 'offset' variable and the utoa_pad call).




Maybe another option is to use TAI for timestamps.

https://en.wikipedia.org/wiki/International_Atomic_Time
https://cr.yp.to/proto/utctai.html
http://www.madore.org/~david/computers/unix-leap-seconds.html


Thanks

Rémi


Jm2c

Alex



Thanks

Rémi

Re: Proposal about new default SSL log format

[Tim Düsterhus]

Remi,

On 7/5/21 5:15 PM, Remi Tricot-Le Breton wrote:

1) tab separated is better for any log import tool (mixing spaces and
"/" is terrible for import)


I don't have any problems with that apart from inconsistency with the
other default formats. If switching to tabs for this format only does
not bother anyone I'll do it.


This inconsistency bothers me. Tabs also bother me in general, because 
they make it hard for a human to parse the log format, whereas one can 
simply teach a program to understand the HAProxy format. With 'halog' 
there already is a dedicated log parser that works with HAProxy's format.


Regarding my suggestion of %ID: I also don't think it is useful to put 
%ID into the SSL log when it is not in the HTTP log. Please don't do 
this, unless you also introduce an updated 'option httplog2' or 
something like this.


Best regards
Tim Düsterhus

Re: Proposal about new default SSL log format

[Remi Tricot-Le Breton]

Hello,

On 02/07/2021 16:52, Илья Шипицин wrote:

I worked with log formats a lot, couple of thoughts

1) tab separated is better for any log import tool (mixing spaces and 
"/" is terrible for import)


I don't have any problems with that apart from inconsistency with the 
other default formats. If switching to tabs for this format only does 
not bother anyone I'll do it.



2) time should be iso8601


For now the "format" field of the "log" option only applies to the log 
line header (containing the timestamp and process_name/pid). It could be 
nice that it applies also to all time related fields of the log format. 
I'll try to see if it is easily feasible.


Thanks

Rémi

Re: Proposal about new default SSL log format

[Remi Tricot-Le Breton]

Hello,

On 02/07/2021 16:56, Илья Шипицин wrote:
also, "process name" is something that is prior knowledge. no need to 
log it every time (for millions of requests)


This process name part does not seem to come from the log format line, 
it is never mentioned in the HTTP log-format string. If it is a prefix 
appended to all the haproxy logs it will also be added to SSL ones, 
regardless of the new log format.


Rémi

Re: Proposal about new default SSL log format

[Remi Tricot-Le Breton]

Hello Tim,

On 02/07/2021 16:34, Tim Düsterhus wrote:

Remi,

On 7/2/21 4:26 PM, Remi Tricot-Le Breton wrote:

But if anybody sees a missing information that could be
beneficial for everybody, feel free to tell it, nothing is set in 
stone yet.

[…]
Feel free to suggest any missing data, which could come from log-format
specific fields or already existing sample fetches.



Not sure whether the HTTP format will also be updated then, but: Put 
%ID somewhere by default, please.


I won't touch the HTTP format yet because it would bring too much 
trouble for now since some people might already have dedicated parsers 
they can't change whenever they want but I can easily add this ID field 
to the SSL format.


Thanks

Rémi

Re: Proposal about new default SSL log format

[Aleksandar Lazic]

On 03.07.21 13:27, Илья Шипицин wrote:



сб, 3 июл. 2021 г. в 16:22, Aleksandar Lazic mailto:al-hapr...@none.at>>:

Hi Remi.

On 02.07.21 16:26, Remi Tricot-Le Breton wrote:
 > Hello list,
 >
 > Some work in ongoing to ease connection error and SSL handshake error 
logging.
 > This will rely on some new sample fetches that could be added to a custom
 > log-format string.
 > In order to ease SSL logging and debugging, we will also add a new 
default log
 > format for SSL connections. Now is then the good time to find the best 
format
 > for everyone.
 > The proposed format looks like the HTTP one to which the SSL specific
 > information is added. But if anybody sees a missing information that 
could be
 > beneficial for everybody, feel free to tell it, nothing is set in stone 
yet.
 >
 > The format would look like this :
 >      >>> Jul  1 18:11:31 haproxy[143338]: 127.0.0.1:37740 
 [01/Jul/2021:18:11:31.517] \
 >    ssl_frontend~ ssl_frontend/s2 0/0/0/7/+7 \
 >    0/0/0/0 2750  1/1/1/1/0 0/0 TLSv1.3 TLS_AES_256_GCM_SHA384
 >
 >    Field   Format    Extract from the 
example above
 >    1   process_name '[' pid ']:'                           
haproxy[143338]:
 >    2   client_ip ':' client_port 127.0.0.1:37740 

 >    3   '[' request_date ']'                      
[01/Jul/2021:18:11:31.517]
 >    4   frontend_name                                          
ssl_frontend~
 >    5   backend_name '/' server_name                         
ssl_frontend/s2
 >    6   TR '/' Tw '/' Tc '/' Tr '/' Ta*   
0/0/0/7/+7
 >    7 *conn_status '/' SSL hsk error '/' SSL vfy '/' SSL CA vfy* 
0/0/0/0
 >    8 bytes_read*                                                     
  2750
 >    9 termination_state                                               
  
 >   10   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*    
1/1/1/1/0
 >   11   srv_queue '/' backend_queue   
   0/0
 >   12 *ssl_version*                                                  
TLSv1.3
 >   13 *ssl_ciphers*                                   
TLS_AES_256_GCM_SHA384
 >
 >
 > The equivalent log-format string would be the following :
 >      "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta \
 > %[conn_err_code]/%[ssl_fc_hsk_err]/%[ssl_c_err]/%[ssl_c_ca_err] \
 >          %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq %sslv %sslc
 >
 > The fields in bold are the SSL specific ones and the statuses ones will 
come
 > from a not yet submitted code so the names and format might slightly 
change.
 >
 > Feel free to suggest any missing data, which could come from log-format
 > specific fields or already existing sample fetches.

How about to combine ssl_version/ssl_ciphers in one line.

It would be helpful to see also the backend status.
Maybe add a 14th and 15th line with following fields

*backend_name '/' conn_status '/' SSL hsk error '/' SSL vfy '/' SSL CA vfy*
*backend_name '/' ssl_version '/' ssl_ciphers*

I had in the past several issues with the backend where the backend CA 
wasn't in the CA File which
was quite difficult to debug.

+1 to the suggestion from Илья Шипицин to use iso8601 which is already in 
haproxy since
2019/10/01:2.1-dev2.

I haven't found sub second format parameter in strftime call therefore I 
assume the strftime call
have this
".00" as fix value.

```
strftime(iso_time_str, sizeof(iso_time_str), "%Y-%m-%dT%H:%M:%S.00+00:00", 
&tm)
```

Maybe another option is to use TAI for timestamps.


many analysis tools, for example Microsoft LogParser, ClickHouse, can perform 
queries right on top
of TSV files with iso8601 time.


Agree.
The output could be a TSV just to get sub seconds information could TAI be used.

https://en.wikipedia.org/wiki/International_Atomic_Time 
https://cr.yp.to/proto/utctai.html 
http://www.madore.org/~david/computers/unix-leap-seconds.html 


 > Thanks
 >
 > Rémi

Jm2c

Alex

Re: Proposal about new default SSL log format

[Илья Шипицин]

сб, 3 июл. 2021 г. в 16:22, Aleksandar Lazic :

> Hi Remi.
>
> On 02.07.21 16:26, Remi Tricot-Le Breton wrote:
> > Hello list,
> >
> > Some work in ongoing to ease connection error and SSL handshake error
> logging.
> > This will rely on some new sample fetches that could be added to a custom
> > log-format string.
> > In order to ease SSL logging and debugging, we will also add a new
> default log
> > format for SSL connections. Now is then the good time to find the best
> format
> > for everyone.
> > The proposed format looks like the HTTP one to which the SSL specific
> > information is added. But if anybody sees a missing information that
> could be
> > beneficial for everybody, feel free to tell it, nothing is set in stone
> yet.
> >
> > The format would look like this :
> >  >>> Jul  1 18:11:31 haproxy[143338]: 127.0.0.1:37740
> [01/Jul/2021:18:11:31.517] \
> >ssl_frontend~ ssl_frontend/s2 0/0/0/7/+7 \
> >0/0/0/0 2750  1/1/1/1/0 0/0 TLSv1.3 TLS_AES_256_GCM_SHA384
> >
> >Field   FormatExtract from the
> example above
> >1   process_name '[' pid ']:'
>  haproxy[143338]:
> >2   client_ip ':' client_port
> 127.0.0.1:37740
> >3   '[' request_date ']'
> [01/Jul/2021:18:11:31.517]
> >4   frontend_name
> ssl_frontend~
> >5   backend_name '/' server_name
>  ssl_frontend/s2
> >6   TR '/' Tw '/' Tc '/' Tr '/' Ta*
> 0/0/0/7/+7
> >7 *conn_status '/' SSL hsk error '/' SSL vfy '/' SSL CA vfy*
> 0/0/0/0
> >8 bytes_read*
>2750
> >9 termination_state
>
> >   10   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*
> 1/1/1/1/0
> >   11   srv_queue '/'
> backend_queue  0/0
> >   12 *ssl_version*
> TLSv1.3
> >   13 *ssl_ciphers*
>  TLS_AES_256_GCM_SHA384
> >
> >
> > The equivalent log-format string would be the following :
> >  "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta \
> > %[conn_err_code]/%[ssl_fc_hsk_err]/%[ssl_c_err]/%[ssl_c_ca_err] \
> >  %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq %sslv %sslc
> >
> > The fields in bold are the SSL specific ones and the statuses ones will
> come
> > from a not yet submitted code so the names and format might slightly
> change.
> >
> > Feel free to suggest any missing data, which could come from log-format
> > specific fields or already existing sample fetches.
>
> How about to combine ssl_version/ssl_ciphers in one line.
>
> It would be helpful to see also the backend status.
> Maybe add a 14th and 15th line with following fields
>
> *backend_name '/' conn_status '/' SSL hsk error '/' SSL vfy '/' SSL CA vfy*
> *backend_name '/' ssl_version '/' ssl_ciphers*
>
> I had in the past several issues with the backend where the backend CA
> wasn't in the CA File which was quite
> difficult to debug.
>
> +1 to the suggestion from Илья Шипицин to use iso8601 which is already in
> haproxy since 2019/10/01:2.1-dev2.
>
> I haven't found sub second format parameter in strftime call therefore I
> assume the strftime call have this
> ".00" as fix value.
>
> ```
> strftime(iso_time_str, sizeof(iso_time_str),
> "%Y-%m-%dT%H:%M:%S.00+00:00", &tm)
> ```
>
> Maybe another option is to use TAI for timestamps.
>


many analysis tools, for example Microsoft LogParser, ClickHouse, can
perform queries right on top of TSV files with iso8601 time.





>
> https://en.wikipedia.org/wiki/International_Atomic_Time
> https://cr.yp.to/proto/utctai.html
> http://www.madore.org/~david/computers/unix-leap-seconds.html
>
> > Thanks
> >
> > Rémi
>
> Jm2c
>
> Alex
>
>

Re: Proposal about new default SSL log format

[Aleksandar Lazic]

Hi Remi.

On 02.07.21 16:26, Remi Tricot-Le Breton wrote:

Hello list,

Some work in ongoing to ease connection error and SSL handshake error logging.
This will rely on some new sample fetches that could be added to a custom
log-format string.
In order to ease SSL logging and debugging, we will also add a new default log
format for SSL connections. Now is then the good time to find the best format
for everyone.
The proposed format looks like the HTTP one to which the SSL specific
information is added. But if anybody sees a missing information that could be
beneficial for everybody, feel free to tell it, nothing is set in stone yet.

The format would look like this :
     >>> Jul  1 18:11:31 haproxy[143338]: 127.0.0.1:37740 
[01/Jul/2021:18:11:31.517] \
   ssl_frontend~ ssl_frontend/s2 0/0/0/7/+7 \
   0/0/0/0 2750  1/1/1/1/0 0/0 TLSv1.3 TLS_AES_256_GCM_SHA384

   Field   Format    Extract from the example above
   1   process_name '[' pid ']:'   haproxy[143338]:
   2   client_ip ':' client_port127.0.0.1:37740
   3   '[' request_date ']'  [01/Jul/2021:18:11:31.517]
   4   frontend_name  ssl_frontend~
   5   backend_name '/' server_name ssl_frontend/s2
   6   TR '/' Tw '/' Tc '/' Tr '/' Ta*   0/0/0/7/+7
   7 *conn_status '/' SSL hsk error '/' SSL vfy '/' SSL CA vfy* 0/0/0/0
   8 bytes_read*   2750
   9 termination_state 
  10   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*    1/1/1/1/0
  11   srv_queue '/' backend_queue  0/0
  12 *ssl_version*  TLSv1.3
  13 *ssl_ciphers*   TLS_AES_256_GCM_SHA384


The equivalent log-format string would be the following :
     "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta \
%[conn_err_code]/%[ssl_fc_hsk_err]/%[ssl_c_err]/%[ssl_c_ca_err] \
         %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq %sslv %sslc

The fields in bold are the SSL specific ones and the statuses ones will come
from a not yet submitted code so the names and format might slightly change.

Feel free to suggest any missing data, which could come from log-format
specific fields or already existing sample fetches.


How about to combine ssl_version/ssl_ciphers in one line.

It would be helpful to see also the backend status.
Maybe add a 14th and 15th line with following fields

*backend_name '/' conn_status '/' SSL hsk error '/' SSL vfy '/' SSL CA vfy*
*backend_name '/' ssl_version '/' ssl_ciphers*

I had in the past several issues with the backend where the backend CA wasn't 
in the CA File which was quite
difficult to debug.

+1 to the suggestion from Илья Шипицин to use iso8601 which is already in 
haproxy since 2019/10/01:2.1-dev2.

I haven't found sub second format parameter in strftime call therefore I assume 
the strftime call have this
".00" as fix value.

```
strftime(iso_time_str, sizeof(iso_time_str), "%Y-%m-%dT%H:%M:%S.00+00:00", 
&tm)
```

Maybe another option is to use TAI for timestamps.

https://en.wikipedia.org/wiki/International_Atomic_Time
https://cr.yp.to/proto/utctai.html
http://www.madore.org/~david/computers/unix-leap-seconds.html


Thanks

Rémi


Jm2c

Alex

Re: Proposal about new default SSL log format

[Илья Шипицин]

also, "process name" is something that is prior knowledge. no need to log
it every time (for millions of requests)

пт, 2 июл. 2021 г. в 19:52, Илья Шипицин :

> I worked with log formats a lot, couple of thoughts
>
> 1) tab separated is better for any log import tool (mixing spaces and "/"
> is terrible for import)
> 2) time should be iso8601
>
> пт, 2 июл. 2021 г. в 19:29, Remi Tricot-Le Breton :
>
>> Hello list,
>>
>> Some work in ongoing to ease connection error and SSL handshake error
>> logging.
>> This will rely on some new sample fetches that could be added to a custom
>> log-format string.
>> In order to ease SSL logging and debugging, we will also add a new
>> default log
>> format for SSL connections. Now is then the good time to find the best
>> format
>> for everyone.
>> The proposed format looks like the HTTP one to which the SSL specific
>> information is added. But if anybody sees a missing information that
>> could be
>> beneficial for everybody, feel free to tell it, nothing is set in stone
>> yet.
>>
>> The format would look like this :
>> >>> Jul  1 18:11:31 haproxy[143338]: 127.0.0.1:37740
>> [01/Jul/2021:18:11:31.517] \
>>   ssl_frontend~ ssl_frontend/s2 0/0/0/7/+7 \
>>   0/0/0/0 2750  1/1/1/1/0 0/0 TLSv1.3 TLS_AES_256_GCM_SHA384
>>
>>   Field   FormatExtract from the example
>> above
>>   1   process_name '[' pid ']:'
>> haproxy[143338]:
>>   2   client_ip ':' client_port
>> 127.0.0.1:37740
>>   3   '[' request_date ']'
>> [01/Jul/2021:18:11:31.517]
>>   4   frontend_name
>> ssl_frontend~
>>   5   backend_name '/' server_name
>> ssl_frontend/s2
>>   6   TR '/' Tw '/' Tc '/' Tr '/' Ta*
>> 0/0/0/7/+7
>>   7   *conn_status '/' SSL hsk error '/' SSL vfy '/' SSL CA vfy*
>> 0/0/0/0
>>   8   bytes_read*
>> 2750
>>   9   termination_state
>> 
>>  10   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*
>> 1/1/1/1/0
>>  11   srv_queue '/'
>> backend_queue  0/0
>>  12   *ssl_version*
>> TLSv1.3
>>  13   *ssl_ciphers*
>> TLS_AES_256_GCM_SHA384
>>
>>
>> The equivalent log-format string would be the following :
>> "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta \
>> %[conn_err_code]/%[ssl_fc_hsk_err]/%[ssl_c_err]/%[ssl_c_ca_err] \
>> %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq %sslv %sslc
>>
>> The fields in bold are the SSL specific ones and the statuses ones will
>> come
>> from a not yet submitted code so the names and format might slightly
>> change.
>>
>> Feel free to suggest any missing data, which could come from log-format
>> specific fields or already existing sample fetches.
>>
>> Thanks
>>
>> Rémi
>>
>

Re: Proposal about new default SSL log format

[Илья Шипицин]

I understand that everybody can redefine its own format.

but I saw several times that default (not very comfortable) format was
later adopted as industry wide.

пт, 2 июл. 2021 г. в 19:52, Илья Шипицин :

> I worked with log formats a lot, couple of thoughts
>
> 1) tab separated is better for any log import tool (mixing spaces and "/"
> is terrible for import)
> 2) time should be iso8601
>
> пт, 2 июл. 2021 г. в 19:29, Remi Tricot-Le Breton :
>
>> Hello list,
>>
>> Some work in ongoing to ease connection error and SSL handshake error
>> logging.
>> This will rely on some new sample fetches that could be added to a custom
>> log-format string.
>> In order to ease SSL logging and debugging, we will also add a new
>> default log
>> format for SSL connections. Now is then the good time to find the best
>> format
>> for everyone.
>> The proposed format looks like the HTTP one to which the SSL specific
>> information is added. But if anybody sees a missing information that
>> could be
>> beneficial for everybody, feel free to tell it, nothing is set in stone
>> yet.
>>
>> The format would look like this :
>> >>> Jul  1 18:11:31 haproxy[143338]: 127.0.0.1:37740
>> [01/Jul/2021:18:11:31.517] \
>>   ssl_frontend~ ssl_frontend/s2 0/0/0/7/+7 \
>>   0/0/0/0 2750  1/1/1/1/0 0/0 TLSv1.3 TLS_AES_256_GCM_SHA384
>>
>>   Field   FormatExtract from the example
>> above
>>   1   process_name '[' pid ']:'
>> haproxy[143338]:
>>   2   client_ip ':' client_port
>> 127.0.0.1:37740
>>   3   '[' request_date ']'
>> [01/Jul/2021:18:11:31.517]
>>   4   frontend_name
>> ssl_frontend~
>>   5   backend_name '/' server_name
>> ssl_frontend/s2
>>   6   TR '/' Tw '/' Tc '/' Tr '/' Ta*
>> 0/0/0/7/+7
>>   7   *conn_status '/' SSL hsk error '/' SSL vfy '/' SSL CA vfy*
>> 0/0/0/0
>>   8   bytes_read*
>> 2750
>>   9   termination_state
>> 
>>  10   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*
>> 1/1/1/1/0
>>  11   srv_queue '/'
>> backend_queue  0/0
>>  12   *ssl_version*
>> TLSv1.3
>>  13   *ssl_ciphers*
>> TLS_AES_256_GCM_SHA384
>>
>>
>> The equivalent log-format string would be the following :
>> "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta \
>> %[conn_err_code]/%[ssl_fc_hsk_err]/%[ssl_c_err]/%[ssl_c_ca_err] \
>> %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq %sslv %sslc
>>
>> The fields in bold are the SSL specific ones and the statuses ones will
>> come
>> from a not yet submitted code so the names and format might slightly
>> change.
>>
>> Feel free to suggest any missing data, which could come from log-format
>> specific fields or already existing sample fetches.
>>
>> Thanks
>>
>> Rémi
>>
>

Re: Proposal about new default SSL log format

[Илья Шипицин]

I worked with log formats a lot, couple of thoughts

1) tab separated is better for any log import tool (mixing spaces and "/"
is terrible for import)
2) time should be iso8601

пт, 2 июл. 2021 г. в 19:29, Remi Tricot-Le Breton :

> Hello list,
>
> Some work in ongoing to ease connection error and SSL handshake error
> logging.
> This will rely on some new sample fetches that could be added to a custom
> log-format string.
> In order to ease SSL logging and debugging, we will also add a new default
> log
> format for SSL connections. Now is then the good time to find the best
> format
> for everyone.
> The proposed format looks like the HTTP one to which the SSL specific
> information is added. But if anybody sees a missing information that could
> be
> beneficial for everybody, feel free to tell it, nothing is set in stone
> yet.
>
> The format would look like this :
> >>> Jul  1 18:11:31 haproxy[143338]: 127.0.0.1:37740
> [01/Jul/2021:18:11:31.517] \
>   ssl_frontend~ ssl_frontend/s2 0/0/0/7/+7 \
>   0/0/0/0 2750  1/1/1/1/0 0/0 TLSv1.3 TLS_AES_256_GCM_SHA384
>
>   Field   FormatExtract from the example
> above
>   1   process_name '[' pid ']:'
> haproxy[143338]:
>   2   client_ip ':' client_port
> 127.0.0.1:37740
>   3   '[' request_date ']'
> [01/Jul/2021:18:11:31.517]
>   4   frontend_name
> ssl_frontend~
>   5   backend_name '/' server_name
> ssl_frontend/s2
>   6   TR '/' Tw '/' Tc '/' Tr '/' Ta*
> 0/0/0/7/+7
>   7   *conn_status '/' SSL hsk error '/' SSL vfy '/' SSL CA vfy*
> 0/0/0/0
>   8   bytes_read*
> 2750
>   9   termination_state
> 
>  10   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*
> 1/1/1/1/0
>  11   srv_queue '/' backend_queue
> 0/0
>  12   *ssl_version*
> TLSv1.3
>  13   *ssl_ciphers*
> TLS_AES_256_GCM_SHA384
>
>
> The equivalent log-format string would be the following :
> "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta \
> %[conn_err_code]/%[ssl_fc_hsk_err]/%[ssl_c_err]/%[ssl_c_ca_err] \
> %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq %sslv %sslc
>
> The fields in bold are the SSL specific ones and the statuses ones will
> come
> from a not yet submitted code so the names and format might slightly
> change.
>
> Feel free to suggest any missing data, which could come from log-format
> specific fields or already existing sample fetches.
>
> Thanks
>
> Rémi
>

Re: Proposal about new default SSL log format

[Tim Düsterhus]

Remi,

On 7/2/21 4:26 PM, Remi Tricot-Le Breton wrote:

But if anybody sees a missing information that could be
beneficial for everybody, feel free to tell it, nothing is set in stone yet.
[…]
Feel free to suggest any missing data, which could come from log-format
specific fields or already existing sample fetches.



Not sure whether the HTTP format will also be updated then, but: Put %ID 
somewhere by default, please.


Best regards
Tim Düsterhus

Proposal about new default SSL log format

[Remi Tricot-Le Breton]

Hello list,

Some work in ongoing to ease connection error and SSL handshake error 
logging.

This will rely on some new sample fetches that could be added to a custom
log-format string.
In order to ease SSL logging and debugging, we will also add a new 
default log
format for SSL connections. Now is then the good time to find the best 
format

for everyone.
The proposed format looks like the HTTP one to which the SSL specific
information is added. But if anybody sees a missing information that 
could be

beneficial for everybody, feel free to tell it, nothing is set in stone yet.

The format would look like this :
    >>> Jul  1 18:11:31 haproxy[143338]: 127.0.0.1:37740 
[01/Jul/2021:18:11:31.517] \

  ssl_frontend~ ssl_frontend/s2 0/0/0/7/+7 \
  0/0/0/0 2750  1/1/1/1/0 0/0 TLSv1.3 TLS_AES_256_GCM_SHA384

  Field   Format    Extract from the 
example above

  1   process_name '[' pid ']:' haproxy[143338]:
  2   client_ip ':' client_port 127.0.0.1:37740
  3   '[' request_date ']' [01/Jul/2021:18:11:31.517]
  4   frontend_name ssl_frontend~
  5   backend_name '/' server_name ssl_frontend/s2
  6   TR '/' Tw '/' Tc '/' Tr '/' Ta*   
0/0/0/7/+7
  7 *conn_status '/' SSL hsk error '/' SSL vfy '/' SSL CA vfy* 
0/0/0/0

  8 bytes_read* 2750
  9 termination_state 
 10   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*    
1/1/1/1/0
 11   srv_queue '/' 
backend_queue  0/0

 12 *ssl_version* TLSv1.3
 13 *ssl_ciphers* TLS_AES_256_GCM_SHA384


The equivalent log-format string would be the following :
    "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta \
%[conn_err_code]/%[ssl_fc_hsk_err]/%[ssl_c_err]/%[ssl_c_ca_err] \
        %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq %sslv %sslc

The fields in bold are the SSL specific ones and the statuses ones will come
from a not yet submitted code so the names and format might slightly change.

Feel free to suggest any missing data, which could come from log-format
specific fields or already existing sample fetches.

Thanks

Rémi