[FTPServer] Plans for Logging

[Dave Roberts <da...@saaconsultants.com>]

With the "standard" IOListener, it was easy to trace each connection
within the log output, because each connection was handled by a
different thread.  Filtering by thread ID, gave the full picture.

With the MinaListener, multiple connections are handled by a single
thread, and it's not possible to differentiate between the sessions
within the log output.

I see MINA provides a SessionLogger, and the latest FTP Server code
also refers to the (now defunct) IoSessionLogger, as well as a
reference to MDC.  However I don't see MDC as the magic wand
solution here, as it simply provides a per-thread area for static data.

I'm guessing the MINA group have hit these problems already, hence
the provision of the SessionLogger in the first place.  Obviously,
using it throughout FTP Server will require passing it around, or at
least a way to get at it.

Just wondering: where do we go from here?

Re: [FTPServer] Plans for Logging

[Maarten Bosteels <mb...@gmail.com>]

ok, I will adapt the javadocs, I thought they were clear...

Can you have a look at the test-case for the MdcInjectingFilter, and see if
anything is missing ?

Thanks,
Maarten

On Fri, Feb 29, 2008 at 10:58 PM, Niklas Gustavsson <ni...@protocol7.com>
wrote:

> On Fri, Feb 29, 2008 at 10:52 PM, Mike Heath <mh...@apache.org> wrote:
> >  The MDC properties are stored in a ThreadLocal so if you have the
> >  logging filter before an executor filter, the MDC properties will get
> >  lost.  If you put the MDC logging filter after the executor filter then
> >  it should work just fine.
>
> Seconds after sending my email I realized that it was the same
> MdcInjectionFilter instance needed in both places, previously we
> created separate instances. This fixes the issue Dave discovered. Fix
> commited in rev 632454.
>
> The JavaDoc doesn't make this very clear and I'm not sure if it is the
> intended behavior?
>
> /niklas
>

Re: [FTPServer] Plans for Logging

[Niklas Gustavsson <ni...@protocol7.com>]

On Fri, Feb 29, 2008 at 10:52 PM, Mike Heath <mh...@apache.org> wrote:
>  The MDC properties are stored in a ThreadLocal so if you have the
>  logging filter before an executor filter, the MDC properties will get
>  lost.  If you put the MDC logging filter after the executor filter then
>  it should work just fine.

Seconds after sending my email I realized that it was the same
MdcInjectionFilter instance needed in both places, previously we
created separate instances. This fixes the issue Dave discovered. Fix
commited in rev 632454.

The JavaDoc doesn't make this very clear and I'm not sure if it is the
intended behavior?

/niklas

Re: [FTPServer] Plans for Logging

[Mike Heath <mh...@apache.org>]

Niklas Gustavsson wrote:
> On Tue, Feb 26, 2008 at 4:37 PM, Dave Roberts
> <da...@saaconsultants.com> wrote:
>>  OK, I see what you're saying, but that doesn't seem to be how it
>>  works.  For example...
>>
>>  (NioProcessor-2) [anonymous] [127.0.0.1] SENT: 331 Guest login okay,
>>  send your complete e-mail address as password.
>>  (NioProcessor-2) [anonymous] [127.0.0.1] RECEIVED: PASS dave@
>>  (pool-1-thread-2) [] [] Anonymous login success - dave@
>>  (NioProcessor-2) [anonymous] [127.0.0.1] SENT: 230 User logged in,
>>  proceed.
>>
>>  The log of the successful login comes from the PASS class, with a
>>  simple LOG.info() call.  None of the MDC information is filled in there.
> 
> Does anyone have any input on this issue? I just debugged it some, and
> MdcInjectionFilter.getProperty() will return the properties correctly,
> but the will not be included in the log output. This is only happens
> for MdcInjectionFilters added after an ExecutorFilter, the one before
> logs the MDC as expected (as shown by the output from the
> LoggingFilter in Daves log above). Removing the ExecutorFilter
> resolves the issue, but that does really help of course :-)
> 
> /niklas
> 

The MDC properties are stored in a ThreadLocal so if you have the
logging filter before an executor filter, the MDC properties will get
lost.  If you put the MDC logging filter after the executor filter then
it should work just fine.

-Mike

Re: [FTPServer] Plans for Logging

[Niklas Gustavsson <ni...@protocol7.com>]

On Tue, Feb 26, 2008 at 4:37 PM, Dave Roberts
<da...@saaconsultants.com> wrote:
>  OK, I see what you're saying, but that doesn't seem to be how it
>  works.  For example...
>
>  (NioProcessor-2) [anonymous] [127.0.0.1] SENT: 331 Guest login okay,
>  send your complete e-mail address as password.
>  (NioProcessor-2) [anonymous] [127.0.0.1] RECEIVED: PASS dave@
>  (pool-1-thread-2) [] [] Anonymous login success - dave@
>  (NioProcessor-2) [anonymous] [127.0.0.1] SENT: 230 User logged in,
>  proceed.
>
>  The log of the successful login comes from the PASS class, with a
>  simple LOG.info() call.  None of the MDC information is filled in there.

Does anyone have any input on this issue? I just debugged it some, and
MdcInjectionFilter.getProperty() will return the properties correctly,
but the will not be included in the log output. This is only happens
for MdcInjectionFilters added after an ExecutorFilter, the one before
logs the MDC as expected (as shown by the output from the
LoggingFilter in Daves log above). Removing the ExecutorFilter
resolves the issue, but that does really help of course :-)

/niklas

Re: [FTPServer] Plans for Logging

[Dave Roberts <da...@saaconsultants.com>]

Niklas Gustavsson wrote:
> On Tue, Feb 26, 2008 at 3:50 PM, Dave Roberts
> <da...@saaconsultants.com> wrote:
>>  So, will all LOG writes (e.g. PASS.java:215) be replaced with this
>>  new logging functionality?
> 
> There should be no need for that. The MINA MdcInjectionFilter sets
> some things for us (handlerClass, remoteAddress, localAddress,
> remoteIp, remotePort, localIp, localPort) and we provide some

That answers another question. Thanks :)

>>  If so, can we also expose the FtpIoSession to things like the
>>  FileSystemManager, FileSystemView and FileSystemObject, as well as
>>  the Ftplet implementations, such that other implementations can make
>>  use of the logging as well.
> 
> That would be completely transparent, no changes required. Just add
> the normal log statements where needed and the MDC context will be
> handled for them.

OK, I see what you're saying, but that doesn't seem to be how it
works.  For example...

(NioProcessor-2) [anonymous] [127.0.0.1] SENT: 331 Guest login okay,
send your complete e-mail address as password.
(NioProcessor-2) [anonymous] [127.0.0.1] RECEIVED: PASS dave@
(pool-1-thread-2) [] [] Anonymous login success - dave@
(NioProcessor-2) [anonymous] [127.0.0.1] SENT: 230 User logged in,
proceed.

The log of the successful login comes from the PASS class, with a
simple LOG.info() call.  None of the MDC information is filled in there.

>>  In terms of the information stored in the MDC attributes, I think
>>  we'd benefit from something unique, like the client host _and_
>>  client port, or a hex version of the connection timestamp.
> 
> You mean a session identifier?

I do, but if the remote port is already stored in the MDC
attributes, then that can be used by anyone that needs such
granularity, in conjunction with the remote IP.

Re: [FTPServer] Plans for Logging

[Niklas Gustavsson <ni...@protocol7.com>]

On Tue, Feb 26, 2008 at 3:50 PM, Dave Roberts
<da...@saaconsultants.com> wrote:
>  So, will all LOG writes (e.g. PASS.java:215) be replaced with this
>  new logging functionality?

There should be no need for that. The MINA MdcInjectionFilter sets
some things for us (handlerClass, remoteAddress, localAddress,
remoteIp, remotePort, localIp, localPort) and we provide some
additional FTP specific items, current the user name (USER line 74).
We could set additional values if we would like to, maybe indicating
the session status like what file is currently being downloaded.

>  If so, can we also expose the FtpIoSession to things like the
>  FileSystemManager, FileSystemView and FileSystemObject, as well as
>  the Ftplet implementations, such that other implementations can make
>  use of the logging as well.

That would be completely transparent, no changes required. Just add
the normal log statements where needed and the MDC context will be
handled for them.

>  In terms of the information stored in the MDC attributes, I think
>  we'd benefit from something unique, like the client host _and_
>  client port, or a hex version of the connection timestamp.

You mean a session identifier?

/niklas

Re: [FTPServer] Plans for Logging

[Dave Roberts <da...@saaconsultants.com>]

Niklas Gustavsson wrote:
> Dave Roberts wrote:
>> Just wondering: where do we go from here?
> 
> My plan is to enable MDC by default (using the MDC filter that MINA 
> provides). This will give you the possibility of logging for example to 
> client IP or user name. I've played around some with this and it's real 
> sweet. Have a look at the core unit test as they use MDC for logging, 
> does that cover your needs?

It certainly appears to exceed my expectations. :-)  It looks like
each session logger has it's own thread (e.g. NioProcessor-2), even
though the sessions themselves have a shared thread (e.g.
pool-1-thread-2).  So in this case, the MDC attributes are unique
for each session, which helps.

So, will all LOG writes (e.g. PASS.java:215) be replaced with this
new logging functionality?

If so, can we also expose the FtpIoSession to things like the
FileSystemManager, FileSystemView and FileSystemObject, as well as
the Ftplet implementations, such that other implementations can make
use of the logging as well.

In terms of the information stored in the MDC attributes, I think
we'd benefit from something unique, like the client host _and_
client port, or a hex version of the connection timestamp.

Re: [FTPServer] Plans for Logging

[Niklas Gustavsson <ni...@protocol7.com>]

Dave Roberts wrote:
> I see MINA provides a SessionLogger, and the latest FTP Server code
> also refers to the (now defunct) IoSessionLogger, as well as a
> reference to MDC.  However I don't see MDC as the magic wand
> solution here, as it simply provides a per-thread area for static data.
> 
...

> Just wondering: where do we go from here?

My plan is to enable MDC by default (using the MDC filter that MINA 
provides). This will give you the possibility of logging for example to 
client IP or user name. I've played around some with this and it's real 
sweet. Have a look at the core unit test as they use MDC for logging, 
does that cover your needs?

/niklas