You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@trafficserver.apache.org by Acácio Centeno <ac...@azion.com> on 2014/10/08 20:43:25 UTC

How to properly log a string on access.log

Hello,

I've written the following function to log our internal UUID to access.log:

int
LogAccessHttp::marshal_proxy_uuid(char *buf)
{
  const char *str = NULL;
  int len = INK_MIN_ALIGN;

  if (buf) {
    if ( m_http_sm->magic == HTTP_SM_MAGIC_ALIVE ) {
      str = m_http_sm->get_uuid();
    } else {
      str = "-";
    }
    len = LogAccess::strlen(str);
    Debug("Azion", "Logando UUID [%d:%s]", len, str);
    marshal_str(buf, str, len);
  }
  return len;
}

The debug message always logs 40 for the length and the correct UUID,
however, on production, sometimes it logs the correct information,
sometimes it logs garbage like:

7022d7ceH�5T
1534af18I�5T
3bbb55ccK�5T
f3a9bcf5R�5T

(Notice that the last 3 bytes are always the same)

Is there any gotcha I should be aware of when printing the log? Am I doing
something wrong on the serializer?

Best regards,
Acácio Centeno
Software Engineering
Azion Technologies
Porto Alegre, Brasil +55 51 3012 3005 | +55 51 8118 9947
Miami, USA +1 305 704 8816

Quaisquer informações contidas neste e-mail e anexos podem ser
confidenciais e privilegiadas, protegidas por sigilo legal. Qualquer forma
de utilização deste documento depende de autorização do emissor, sujeito as
penalidades cabíveis.

Any information in this e-mail and attachments may be confidential and
privileged, protected by legal confidentiality. The use of this document
require authorization by the issuer, subject to penalties.

Re: How to properly log a string on access.log

Posted by Acácio Centeno <ac...@azion.com>.
For the record, I found out what the problem was. ATS calls the method that
generates the field twice, the first time, it wants to know the field's
size, so buf is NULL. The second time it actually wants the field's value.
(I wasn't aware of it.)

So the first time the function was called (by LogField::marshal_len), I
would return INK_MIN_ALIGN (== 8), and the second time it was called (by
LogField::marshal) I would actually copy the real UUID to the buffer and
return 40, but ATS would think that only 8 bytes had been writen to the
buffer and would lead to the problem.

By refactoring the method to this:

LogAccessHttp::marshal_proxy_uuid(char *buf)
{
  const char *str = NULL;
  const int len = 40;

  if (buf) {
    str = m_http_sm->get_uuid();
    marshal_str(buf, str, len);
  }

  return len;
}

Solves the problem.


Acácio Centeno
Software Engineering
Azion Technologies
Porto Alegre, Brasil +55 51 3012 3005 | +55 51 8118 9947
Miami, USA +1 305 704 8816

Quaisquer informações contidas neste e-mail e anexos podem ser
confidenciais e privilegiadas, protegidas por sigilo legal. Qualquer forma
de utilização deste documento depende de autorização do emissor, sujeito as
penalidades cabíveis.

Any information in this e-mail and attachments may be confidential and
privileged, protected by legal confidentiality. The use of this document
require authorization by the issuer, subject to penalties.


2014-10-08 17:25 GMT-03:00 Acácio Centeno <ac...@azion.com>:

> 37. This length is fixed.
>
> I've looked marshal_str's code and my understanding is that it will pad
> the string with '$' to fill the necessary 40, right? so what gets copied to
> buf is actually something like "cdc19cac-527e-4e4b-b8f9-ef453db9e0d3$$$".
>
> Also, I'm not sure why the fields should use LogAccess::strlen instead of
> ::strlen, but as all other string fields do so, I thought it was the right
> thing to do.
>
>
> Acácio Centeno
> Software Engineering
> Azion Technologies
> Porto Alegre, Brasil +55 51 3012 3005 | +55 51 8118 9947
> Miami, USA +1 305 704 8816
>
> Quaisquer informações contidas neste e-mail e anexos podem ser
> confidenciais e privilegiadas, protegidas por sigilo legal. Qualquer forma
> de utilização deste documento depende de autorização do emissor, sujeito as
> penalidades cabíveis.
>
> Any information in this e-mail and attachments may be confidential and
> privileged, protected by legal confidentiality. The use of this document
> require authorization by the issuer, subject to penalties.
>
>
> 2014-10-08 16:59 GMT-03:00 James Peach <jp...@apache.org>:
>
> On Oct 8, 2014, at 11:43 AM, Acácio Centeno <ac...@azion.com>
>> wrote:
>>
>> > Hello,
>> >
>> > I've written the following function to log our internal UUID to
>> access.log:
>> >
>> > int
>> > LogAccessHttp::marshal_proxy_uuid(char *buf)
>> > {
>> >  const char *str = NULL;
>> >  int len = INK_MIN_ALIGN;
>> >
>> >  if (buf) {
>> >    if ( m_http_sm->magic == HTTP_SM_MAGIC_ALIVE ) {
>> >      str = m_http_sm->get_uuid();
>> >    } else {
>> >      str = "-";
>> >    }
>> >    len = LogAccess::strlen(str);
>> >    Debug("Azion", "Logando UUID [%d:%s]", len, str);
>> >    marshal_str(buf, str, len);
>> >  }
>> >  return len;
>> > }
>> >
>> > The debug message always logs 40 for the length and the correct UUID,
>>
>> How many bytes is does get_uuid() return?
>>
>> > however, on production, sometimes it logs the correct information,
>> > sometimes it logs garbage like:
>> >
>> > 7022d7ceH�5T
>> > 1534af18I�5T
>> > 3bbb55ccK�5T
>> > f3a9bcf5R�5T
>> >
>> > (Notice that the last 3 bytes are always the same)
>> >
>> > Is there any gotcha I should be aware of when printing the log? Am I
>> doing
>> > something wrong on the serializer?
>> >
>> > Best regards,
>> > Acácio Centeno
>> > Software Engineering
>> > Azion Technologies
>> > Porto Alegre, Brasil +55 51 3012 3005 | +55 51 8118 9947
>> > Miami, USA +1 305 704 8816
>> >
>> > Quaisquer informações contidas neste e-mail e anexos podem ser
>> > confidenciais e privilegiadas, protegidas por sigilo legal. Qualquer
>> forma
>> > de utilização deste documento depende de autorização do emissor,
>> sujeito as
>> > penalidades cabíveis.
>> >
>> > Any information in this e-mail and attachments may be confidential and
>> > privileged, protected by legal confidentiality. The use of this document
>> > require authorization by the issuer, subject to penalties.
>>
>>
>

Re: How to properly log a string on access.log

Posted by Acácio Centeno <ac...@azion.com>.
37. This length is fixed.

I've looked marshal_str's code and my understanding is that it will pad the
string with '$' to fill the necessary 40, right? so what gets copied to buf
is actually something like "cdc19cac-527e-4e4b-b8f9-ef453db9e0d3$$$".

Also, I'm not sure why the fields should use LogAccess::strlen instead of
::strlen, but as all other string fields do so, I thought it was the right
thing to do.


Acácio Centeno
Software Engineering
Azion Technologies
Porto Alegre, Brasil +55 51 3012 3005 | +55 51 8118 9947
Miami, USA +1 305 704 8816

Quaisquer informações contidas neste e-mail e anexos podem ser
confidenciais e privilegiadas, protegidas por sigilo legal. Qualquer forma
de utilização deste documento depende de autorização do emissor, sujeito as
penalidades cabíveis.

Any information in this e-mail and attachments may be confidential and
privileged, protected by legal confidentiality. The use of this document
require authorization by the issuer, subject to penalties.


2014-10-08 16:59 GMT-03:00 James Peach <jp...@apache.org>:

> On Oct 8, 2014, at 11:43 AM, Acácio Centeno <ac...@azion.com>
> wrote:
>
> > Hello,
> >
> > I've written the following function to log our internal UUID to
> access.log:
> >
> > int
> > LogAccessHttp::marshal_proxy_uuid(char *buf)
> > {
> >  const char *str = NULL;
> >  int len = INK_MIN_ALIGN;
> >
> >  if (buf) {
> >    if ( m_http_sm->magic == HTTP_SM_MAGIC_ALIVE ) {
> >      str = m_http_sm->get_uuid();
> >    } else {
> >      str = "-";
> >    }
> >    len = LogAccess::strlen(str);
> >    Debug("Azion", "Logando UUID [%d:%s]", len, str);
> >    marshal_str(buf, str, len);
> >  }
> >  return len;
> > }
> >
> > The debug message always logs 40 for the length and the correct UUID,
>
> How many bytes is does get_uuid() return?
>
> > however, on production, sometimes it logs the correct information,
> > sometimes it logs garbage like:
> >
> > 7022d7ceH�5T
> > 1534af18I�5T
> > 3bbb55ccK�5T
> > f3a9bcf5R�5T
> >
> > (Notice that the last 3 bytes are always the same)
> >
> > Is there any gotcha I should be aware of when printing the log? Am I
> doing
> > something wrong on the serializer?
> >
> > Best regards,
> > Acácio Centeno
> > Software Engineering
> > Azion Technologies
> > Porto Alegre, Brasil +55 51 3012 3005 | +55 51 8118 9947
> > Miami, USA +1 305 704 8816
> >
> > Quaisquer informações contidas neste e-mail e anexos podem ser
> > confidenciais e privilegiadas, protegidas por sigilo legal. Qualquer
> forma
> > de utilização deste documento depende de autorização do emissor, sujeito
> as
> > penalidades cabíveis.
> >
> > Any information in this e-mail and attachments may be confidential and
> > privileged, protected by legal confidentiality. The use of this document
> > require authorization by the issuer, subject to penalties.
>
>

Re: How to properly log a string on access.log

Posted by James Peach <jp...@apache.org>.
On Oct 8, 2014, at 11:43 AM, Acácio Centeno <ac...@azion.com> wrote:

> Hello,
> 
> I've written the following function to log our internal UUID to access.log:
> 
> int
> LogAccessHttp::marshal_proxy_uuid(char *buf)
> {
>  const char *str = NULL;
>  int len = INK_MIN_ALIGN;
> 
>  if (buf) {
>    if ( m_http_sm->magic == HTTP_SM_MAGIC_ALIVE ) {
>      str = m_http_sm->get_uuid();
>    } else {
>      str = "-";
>    }
>    len = LogAccess::strlen(str);
>    Debug("Azion", "Logando UUID [%d:%s]", len, str);
>    marshal_str(buf, str, len);
>  }
>  return len;
> }
> 
> The debug message always logs 40 for the length and the correct UUID,

How many bytes is does get_uuid() return?

> however, on production, sometimes it logs the correct information,
> sometimes it logs garbage like:
> 
> 7022d7ceH�5T
> 1534af18I�5T
> 3bbb55ccK�5T
> f3a9bcf5R�5T
> 
> (Notice that the last 3 bytes are always the same)
> 
> Is there any gotcha I should be aware of when printing the log? Am I doing
> something wrong on the serializer?
> 
> Best regards,
> Acácio Centeno
> Software Engineering
> Azion Technologies
> Porto Alegre, Brasil +55 51 3012 3005 | +55 51 8118 9947
> Miami, USA +1 305 704 8816
> 
> Quaisquer informações contidas neste e-mail e anexos podem ser
> confidenciais e privilegiadas, protegidas por sigilo legal. Qualquer forma
> de utilização deste documento depende de autorização do emissor, sujeito as
> penalidades cabíveis.
> 
> Any information in this e-mail and attachments may be confidential and
> privileged, protected by legal confidentiality. The use of this document
> require authorization by the issuer, subject to penalties.


Re: How to properly log a string on access.log

Posted by Acácio Centeno <ac...@azion.com>.
Yes, it's guaranteed. And it's logging correctly on debug.log.


Acácio Centeno
Software Engineering
Azion Technologies
Porto Alegre, Brasil +55 51 3012 3005 | +55 51 8118 9947
Miami, USA +1 305 704 8816

Quaisquer informações contidas neste e-mail e anexos podem ser
confidenciais e privilegiadas, protegidas por sigilo legal. Qualquer forma
de utilização deste documento depende de autorização do emissor, sujeito as
penalidades cabíveis.

Any information in this e-mail and attachments may be confidential and
privileged, protected by legal confidentiality. The use of this document
require authorization by the issuer, subject to penalties.


2014-10-08 15:46 GMT-03:00 Sudheer Vinukonda <sudheerv@yahoo-inc.com.invalid
>:

> Hi Acacio,
>
> Is m_http_sm->get_uuid() guaranteed to be null terminated?
>
> Thanks,
>
> Sudheer
>
> On 10/8/14, 11:43 AM, "Acácio Centeno" <ac...@azion.com> wrote:
>
> >Hello,
> >
> >I've written the following function to log our internal UUID to
> >access.log:
> >
> >int
> >LogAccessHttp::marshal_proxy_uuid(char *buf)
> >{
> >  const char *str = NULL;
> >  int len = INK_MIN_ALIGN;
> >
> >  if (buf) {
> >    if ( m_http_sm->magic == HTTP_SM_MAGIC_ALIVE ) {
> >      str = m_http_sm->get_uuid();
> >    } else {
> >      str = "-";
> >    }
> >    len = LogAccess::strlen(str);
> >    Debug("Azion", "Logando UUID [%d:%s]", len, str);
> >    marshal_str(buf, str, len);
> >  }
> >  return len;
> >}
> >
> >The debug message always logs 40 for the length and the correct UUID,
> >however, on production, sometimes it logs the correct information,
> >sometimes it logs garbage like:
> >
> >7022d7ceH�5T
> >1534af18I�5T
> >3bbb55ccK�5T
> >f3a9bcf5R�5T
> >
> >(Notice that the last 3 bytes are always the same)
> >
> >Is there any gotcha I should be aware of when printing the log? Am I doing
> >something wrong on the serializer?
> >
> >Best regards,
> >Acácio Centeno
> >Software Engineering
> >Azion Technologies
> >Porto Alegre, Brasil +55 51 3012 3005 | +55 51 8118 9947
> >Miami, USA +1 305 704 8816
> >
> >Quaisquer informações contidas neste e-mail e anexos podem ser
> >confidenciais e privilegiadas, protegidas por sigilo legal. Qualquer forma
> >de utilização deste documento depende de autorização do emissor, sujeito
> >as
> >penalidades cabíveis.
> >
> >Any information in this e-mail and attachments may be confidential and
> >privileged, protected by legal confidentiality. The use of this document
> >require authorization by the issuer, subject to penalties.
>
>

Re: How to properly log a string on access.log

Posted by Sudheer Vinukonda <su...@yahoo-inc.com.INVALID>.
Hi Acacio,

Is m_http_sm->get_uuid() guaranteed to be null terminated?

Thanks,

Sudheer

On 10/8/14, 11:43 AM, "Acácio Centeno" <ac...@azion.com> wrote:

>Hello,
>
>I've written the following function to log our internal UUID to
>access.log:
>
>int
>LogAccessHttp::marshal_proxy_uuid(char *buf)
>{
>  const char *str = NULL;
>  int len = INK_MIN_ALIGN;
>
>  if (buf) {
>    if ( m_http_sm->magic == HTTP_SM_MAGIC_ALIVE ) {
>      str = m_http_sm->get_uuid();
>    } else {
>      str = "-";
>    }
>    len = LogAccess::strlen(str);
>    Debug("Azion", "Logando UUID [%d:%s]", len, str);
>    marshal_str(buf, str, len);
>  }
>  return len;
>}
>
>The debug message always logs 40 for the length and the correct UUID,
>however, on production, sometimes it logs the correct information,
>sometimes it logs garbage like:
>
>7022d7ceH�5T
>1534af18I�5T
>3bbb55ccK�5T
>f3a9bcf5R�5T
>
>(Notice that the last 3 bytes are always the same)
>
>Is there any gotcha I should be aware of when printing the log? Am I doing
>something wrong on the serializer?
>
>Best regards,
>Acácio Centeno
>Software Engineering
>Azion Technologies
>Porto Alegre, Brasil +55 51 3012 3005 | +55 51 8118 9947
>Miami, USA +1 305 704 8816
>
>Quaisquer informações contidas neste e-mail e anexos podem ser
>confidenciais e privilegiadas, protegidas por sigilo legal. Qualquer forma
>de utilização deste documento depende de autorização do emissor, sujeito
>as
>penalidades cabíveis.
>
>Any information in this e-mail and attachments may be confidential and
>privileged, protected by legal confidentiality. The use of this document
>require authorization by the issuer, subject to penalties.