ftplet not being called

[Allen Firstenberg <pr...@addventure.com>]

We're trying to track down a problem with an ftplet (our logging ftplet,
which we're testing in production) that is totally baffling us.  We have a
user that reports that they downloaded a file.  As far as we can tell,
neither the beforeCommand() nor afterCommand() methods were called -
although the transfer appears to have succeeded.  There are numerous errors
sent to stdout about pipes being closed on either the command or data
channel, so we can't trace them to a specific instance.

Can anyone think of a way that the file could be transfered without our
ftplet being called?  Are there default ftplets that might have told it to
skip further processing before it got to ours?

Any thoughts about this, or how to track down the problem on a production
server, would be greatly appreciated.

Thanks!
Allen

Re: [proftpd] Re: ftplet not being called

[Allen Firstenberg <pr...@addventure.com>]

We know it is being initialized - it works for nearly all of the commands.
 It even appears to work for other commands in the session, and even most
downloads.  Just not for "some".  We're not even sure where the problem is -
just that either it means that we aren't running through this ftplet... or
somehow the user isn't actually downloading the file when they think they
are (or is downloading something else).

We are hesitant to turn on debugging.  The server gets over 30k connections,
over 13k logins, and over 10k downloads a day, and of these, fewer than 100
are having problems.  Thats kinda our next step - but we're hesitant about
it.  (Tho we do wonder why an ftplet throwing an exception disconnects with
only a logging to debug, but thats another issue.)  As it is, we had to turn
off logging for warnings and errors in some classes because of the volume of
logs they produced for "routine" connections, and we're considering turning
off even more.  We find there are a LOT of misbehaved clients out there who
will close the control or data connections unexpectedly, causing an
exception.

Thanks for the suggestions - any more welcome. :)  We're still floundering
around trying to figure out whats going on.

Allen

On Tue, Jun 7, 2011 at 9:36 PM, Toli Kuznets <tk...@marinsoftware.com>wrote:

> Allen,
>
> Not aware of any default ftplets... but if the user is willing to help
> out to repro the problem, you can try turning on all logging to
> "debug" and seeing what the chain of command is when the user logs in
> and uploads the file...
>
> Also, can you print out some logging messages in your Ftplet
> constructor? perhaps it's not being loaded into the system the way you
> expect, so it never gets executed?
>
> that'd be my first attempt
>
> On Tue, Jun 7, 2011 at 6:32 PM, Allen Firstenberg
> <pr...@addventure.com> wrote:
> > We're trying to track down a problem with an ftplet (our logging ftplet,
> > which we're testing in production) that is totally baffling us.  We have
> a
> > user that reports that they downloaded a file.  As far as we can tell,
> > neither the beforeCommand() nor afterCommand() methods were called -
> > although the transfer appears to have succeeded.  There are numerous
> errors
> > sent to stdout about pipes being closed on either the command or data
> > channel, so we can't trace them to a specific instance.
> >
> > Can anyone think of a way that the file could be transfered without our
> > ftplet being called?  Are there default ftplets that might have told it
> to
> > skip further processing before it got to ours?
> >
> > Any thoughts about this, or how to track down the problem on a production
> > server, would be greatly appreciated.
> >
> > Thanks!
> > Allen
> >
>

Re: ftplet not being called

[Toli Kuznets <tk...@marinsoftware.com>]

Allen,

Not aware of any default ftplets... but if the user is willing to help
out to repro the problem, you can try turning on all logging to
"debug" and seeing what the chain of command is when the user logs in
and uploads the file...

Also, can you print out some logging messages in your Ftplet
constructor? perhaps it's not being loaded into the system the way you
expect, so it never gets executed?

that'd be my first attempt

On Tue, Jun 7, 2011 at 6:32 PM, Allen Firstenberg
<pr...@addventure.com> wrote:
> We're trying to track down a problem with an ftplet (our logging ftplet,
> which we're testing in production) that is totally baffling us.  We have a
> user that reports that they downloaded a file.  As far as we can tell,
> neither the beforeCommand() nor afterCommand() methods were called -
> although the transfer appears to have succeeded.  There are numerous errors
> sent to stdout about pipes being closed on either the command or data
> channel, so we can't trace them to a specific instance.
>
> Can anyone think of a way that the file could be transfered without our
> ftplet being called?  Are there default ftplets that might have told it to
> skip further processing before it got to ours?
>
> Any thoughts about this, or how to track down the problem on a production
> server, would be greatly appreciated.
>
> Thanks!
> Allen
>

Re: [proftpd] Re: Re: Re: ftplet not being called

[Allen Firstenberg <pr...@addventure.com>]

On Wed, Jun 8, 2011 at 7:21 AM, David Latorre <dv...@gmail.com> wrote:

> Hello Allen,
>
>  I would need some more info for this, e.g.,
>
>  1) Are the clients using FTP or FTPS?
>

The clients are using FTP.  We have tried setting up packet sniffing for
some of this, but the volume of traffic is too high to sift through it.


>  2) Are they using a 'publicly available' FTP client? which one?
>

This is a little unclear.  They are either using a library from Microsoft
(although they haven't been able to tell us which one), or a library from
"DART PowerTCP FTP".  We have had problems with both in the past against
this server, when we didn't when using ProFTPD, but we thought we had traced
them to an issue with some redundancy network hardware that was resolved.


>  3) Is it possible that you're capturing some exceptions silently?
>

I never say its impossible.  But any exceptions in my code that I catch are
logged (using jdk logging) at a warning level, and none seem to have been
reported. The ftplets might, in theory, rethrow exceptions - and if they
are, they are caught and logged at a debugging level, so it is possible this
is being swallowed.  But it is difficult to see how this is happening given
the rest of the circumstances.


>  If I understand you correctly, FTPServer itself has logging
> disabled; is it so?  First option here is that you ask your client if
> they have any logs of the file transfer...
>

Yeah... we're working on that front.  So far all they can tell us is "Error
1"... which means nothing to them or us.  They can't even report what
command exactly is causing the error.  We're still trying to get more out of
them.

It is compounded that we're not convinced that the server is being hit at
all for some of the problems, or if it is the network redundancy
configuration or some other configuration outside the FTP server itself that
is messing things up again.  So even if we add more logging to ours, at best
we might be able to prove it has nothing to do with the FTP server...


> Otherwise, I don't find it easy to find your problem...


Us either. :)  But thank you for insights.


> Maybe you can
> try to obtain finer grained logging in FTPServer by using an
> implementation  that allows Filters to be specified so you don't have
> to turn on all the logging output if you're worried about  system
> performance (I don't actually know if there's reason to worry).


We're not too worried about performance of the server... we're more
concerned that somehow we would have to sift through lots of information
that doesn't indicate anything in search of one line that might. And then,
somehow, tie it to the actual session and command that caused the problem.
 We'll go this route if we need to, and narrow it as much as we can... but
we're trying to figure out what might be the cause before we go to that
point.

Re: [proftpd] Re: Re: ftplet not being called

[David Latorre <dv...@gmail.com>]

Hello Allen,

 I would need some more info for this, e.g.,

 1) Are the clients using FTP or FTPS?

 2) Are they using a 'publicly available' FTP client? which one?

 3) Is it possible that you're capturing some exceptions silently?

 If I understand you correctly, FTPServer itself has logging
disabled; is it so?  First option here is that you ask your client if
they have any logs of the file transfer...
Otherwise, I don't find it easy to find your problem... Maybe you can
try to obtain finer grained logging in FTPServer by using an
implementation  that allows Filters to be specified so you don't have
to turn on all the logging output if you're worried about  system
performance (I don't actually know if there's reason to worry).






2011/6/8 Allen Firstenberg <pr...@addventure.com>:
> On Wed, Jun 8, 2011 at 5:44 AM, Niklas Gustavsson <ni...@protocol7.com>wrote:
>
>>
>> Which exact log statement is it that you were expecting? From
>> FtpLoggingFilter?
>>
>> What logging provider are you using? Assuming this is a race
>> condition, it could be both in FtpServer, slf4j and the logging
>> provider.
>
>
> The "logging" in this case isn't code level logging, it is command/transfer
> logging.  It is an ftplet that can be configured to log various attributes
> from an FtpSession, FtpRequest, and/or FtpReply.  It is intended for xferlog
> and similar logging capabilities.  We've mentioned this in the past as
> something we're working on and that we intend to release to the project when
> we feel its ready for prime time.
>
> In this case, log messages are saved to a file during both beforeCommand()
> and afterCommand() in several different ftplets.  In order for it to be a
> race condition, these would have had to fail multiple times - and just for
> this particular instance.  I can't rule it out, of course, but it seems
> unlikely.
>
> Allen
>

Re: [proftpd] Re: Re: Re: ftplet not being called

[Allen Firstenberg <pr...@addventure.com>]

On Wed, Jun 8, 2011 at 7:10 AM, Niklas Gustavsson <ni...@protocol7.com>wrote:
>
>
> Sorry, I forgot the basic problem you described. I've reviewed our
> code, and fail to find a way that Ftplet.beforeCommand() would not be
> called. Ftplet.afterCommand() could of course we skipped if
> beforeCommand returns SKIP or the command itself throws an exception.
> But, I guess you already checked this.
>

Yeah, none of our code returns SKIP, and if there are no default ftplets,
then we're the only ones that could.

That narrows our thinking about this - thanks for looking over the code.


> If I understood correctly this happens very infrequently and with no
> possibility of reproducing?
>
> We haven't been able to consistently reproduce it, at least not this part
of the problem.  All we have right now is one documented case where they say
they have a file - but we have no record of it actually being downloaded.
 We have a couple of cases where they experience errors that don't match
anything we see in the system, and we aren't sure if these are because of
logging problems or something else.

Thanks!
Allen

Re: [proftpd] Re: Re: ftplet not being called

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

On Wed, Jun 8, 2011 at 12:55 PM, Allen Firstenberg
<pr...@addventure.com> wrote:
> The "logging" in this case isn't code level logging, it is command/transfer
> logging.  It is an ftplet that can be configured to log various attributes
> from an FtpSession, FtpRequest, and/or FtpReply.  It is intended for xferlog
> and similar logging capabilities.  We've mentioned this in the past as
> something we're working on and that we intend to release to the project when
> we feel its ready for prime time.

Sorry, I forgot the basic problem you described. I've reviewed our
code, and fail to find a way that Ftplet.beforeCommand() would not be
called. Ftplet.afterCommand() could of course we skipped if
beforeCommand returns SKIP or the command itself throws an exception.
But, I guess you already checked this.

If I understood correctly this happens very infrequently and with no
possibility of reproducing?

/niklas

Re: [proftpd] Re: Re: ftplet not being called

[Allen Firstenberg <pr...@addventure.com>]

On Wed, Jun 8, 2011 at 5:44 AM, Niklas Gustavsson <ni...@protocol7.com>wrote:

>
> Which exact log statement is it that you were expecting? From
> FtpLoggingFilter?
>
> What logging provider are you using? Assuming this is a race
> condition, it could be both in FtpServer, slf4j and the logging
> provider.


The "logging" in this case isn't code level logging, it is command/transfer
logging.  It is an ftplet that can be configured to log various attributes
from an FtpSession, FtpRequest, and/or FtpReply.  It is intended for xferlog
and similar logging capabilities.  We've mentioned this in the past as
something we're working on and that we intend to release to the project when
we feel its ready for prime time.

In this case, log messages are saved to a file during both beforeCommand()
and afterCommand() in several different ftplets.  In order for it to be a
race condition, these would have had to fail multiple times - and just for
this particular instance.  I can't rule it out, of course, but it seems
unlikely.

Allen

Re: [proftpd] Re: ftplet not being called

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

On Wed, Jun 8, 2011 at 10:58 AM, Allen Firstenberg
<pr...@addventure.com> wrote:
> Just on some sessions, as far as we can tell.  We can't figure out exactly
> the circumstances that it happens.  At the moment we have one known
> documented case where a file appears to have been downloaded and no record
> of it happening was recorded.

Which exact log statement is it that you were expecting? From FtpLoggingFilter?

What logging provider are you using? Assuming this is a race
condition, it could be both in FtpServer, slf4j and the logging
provider.

/niklas

Re: [proftpd] Re: ftplet not being called

[Allen Firstenberg <pr...@addventure.com>]

On Wed, Jun 8, 2011 at 2:03 AM, Niklas Gustavsson <ni...@protocol7.com>wrote:

> On Wed, Jun 8, 2011 at 3:32 AM, Allen Firstenberg
> <pr...@addventure.com> wrote:
> > We're trying to track down a problem with an ftplet (our logging ftplet,
> > which we're testing in production) that is totally baffling us.  We have
> a
> > user that reports that they downloaded a file.  As far as we can tell,
> > neither the beforeCommand() nor afterCommand() methods were called -
> > although the transfer appears to have succeeded.  There are numerous
> errors
> > sent to stdout about pipes being closed on either the command or data
> > channel, so we can't trace them to a specific instance.
>
> Is it consistent in that some commands are never logged, or just on
> some sessions?
>

Just on some sessions, as far as we can tell.  We can't figure out exactly
the circumstances that it happens.  At the moment we have one known
documented case where a file appears to have been downloaded and no record
of it happening was recorded.

We also seem to have a (related?) situation where "something" is happening
on the server that is forcing hte client to close the connection.  The
client program isn't very yielding on what or why, but its become
frustrating that it happens rarely and there is nothing logged that
indicates what might be going on.


> > Can anyone think of a way that the file could be transfered without our
> > ftplet being called?  Are there default ftplets that might have told it
> to
> > skip further processing before it got to ours?
>
> No, there are no default Ftplets.
>

Thanks.  That helps rule out some possibilities.

Allen

Re: ftplet not being called

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

On Wed, Jun 8, 2011 at 3:32 AM, Allen Firstenberg
<pr...@addventure.com> wrote:
> We're trying to track down a problem with an ftplet (our logging ftplet,
> which we're testing in production) that is totally baffling us.  We have a
> user that reports that they downloaded a file.  As far as we can tell,
> neither the beforeCommand() nor afterCommand() methods were called -
> although the transfer appears to have succeeded.  There are numerous errors
> sent to stdout about pipes being closed on either the command or data
> channel, so we can't trace them to a specific instance.

Is it consistent in that some commands are never logged, or just on
some sessions?

> Can anyone think of a way that the file could be transfered without our
> ftplet being called?  Are there default ftplets that might have told it to
> skip further processing before it got to ours?

No, there are no default Ftplets.

/niklas