[gridftp-user] client debugging

[Jaime Frey]

On Jul 1, 2008, at 11:37 AM, John Bresnahan wrote:

>>> I'm using the gridftp client libraries to submit jobs to the  
>>> NorduGrid ARC service. On a certain client machine, if I start a  
>>> couple dozen gridftp operations in parallel (with different  
>>> gridftp handles), a random set of the operations will fail after  
>>> 10 minutes with the following error:
>>>
>>> an end-of-file was reached globus_xio: An end of file occurred
>>>
>>> This sounds like one side is timing out and closing the connection.
>
> That is a possibilty, or one side is crashing.
>
>>> The operations are gets, puts, and deletions of small files. If I  
>>> run the same test on another machine at a different site, no  
>>> failures occur.
>>>
>>> I'm not sure how to debug this problem further. Is there a way to  
>>> enable extra debugging in the gridftp client libraries to log what  
>>> messages are being sent over the wire and when?
>
> export GLOBUS_FTP_CLIENT_DEBUG_LEVEL=255


Thanks. The debugging output tells more of what's going on, but I  
still don't have a complete picture.

Attached below is the output caused by a globus_ftp_client_rmdir(),  
with timestamps prepended. I had 50 client processes issuing commands  
in parallel, but each client was issuing only one command at a time.

The resulting error string was "an end-of-file was reached globus_xio:  
An end of file occurred". Out of the 50 clients, 11 failed with this  
error. All of them showed similar output to that below, including a  
gap of exactly 10 minutes.

It's unclear to me why it's stalling in authentication. I'm going to  
strace the processes next to pin down what's happening on the wire. In  
the meantime, does the output below suggest what's wrong to you?

7/2 18:25:18 globus_i_ftp_client_target_find() entering
7/2 18:25:18 globus_l_ftp_client_target_new() entering
7/2 18:25:18 globus_l_ftp_client_target_new() exiting
7/2 18:25:18 globus_i_ftp_client_target_find() exiting
7/2 18:25:18 globus_i_ftp_client_target_activate() entering
7/2 18:25:18 globus_i_ftp_client_target_activate() exiting
7/2 18:25:22 globus_i_ftp_client_response_callback() entering
7/2 18:25:22    handle state = SOURCE_CONNECT
7/2 18:25:22    source state = CONNECT
7/2 18:25:22    dest   state = NULL
7/2 18:25:22 globus_i_ftp_client_response_callback() exiting
7/2 18:25:22    handle state = SOURCE_CONNECT
7/2 18:25:22    source state = AUTHENTICATE
7/2 18:25:22    dest   state = NULL
7/2 18:35:22 globus_i_ftp_client_response_callback() entering
7/2 18:35:22    handle state = SOURCE_CONNECT
7/2 18:35:22    source state = AUTHENTICATE
7/2 18:35:22    dest   state = NULL
7/2 18:35:22 globus_l_ftp_client_connection_error() entering
7/2 18:35:22    handle state = SOURCE_CONNECT
7/2 18:35:22    source state = SETUP_CONNECTION
7/2 18:35:22    dest   state = NULL
7/2 18:35:22 globus_i_ftp_client_transfer_complete() entering
7/2 18:35:22 globus_i_ftp_client_target_release() entering
7/2 18:35:22 globus_l_ftp_client_target_delete() entering
7/2 18:35:22 globus_l_ftp_client_target_delete() exiting
7/2 18:35:22 globus_i_ftp_client_target_release() exiting
7/2 18:35:22 globus_i_ftp_client_transfer_complete() exiting
7/2 18:35:22 globus_l_ftp_client_connection_error() exiting
7/2 18:35:22 globus_i_ftp_client_response_callback() exiting with error
7/2 18:35:22    handle state = START
7/2 18:35:22    source state = NULL
7/2 18:35:22    dest   state = NULL
7/2 18:35:22 globus_l_ftp_client_quit_callback() entering
7/2 18:35:22 globus_l_ftp_client_quit_callback() exiting

+--------------------------------+-----------------------------------+
|           Jaime Frey           | I used to be a heavy gambler.     |
|       jfrey at cs.wisc.edu        | But now I just make mental bets.  |
| http://www.cs.wisc.edu/~jfrey/ | That's how I lost my mind.        |
+--------------------------------+-----------------------------------+