RE: Uploading a file with SFTP from an EPICS driver - Issue fixed!

[Mark Rivers via Tech-talk <tech-talk@aps.anl.gov>]

I removed my private key to eliminate failed private/public key negotiation failure from possibly slowing things down. 

 

This is the comparison of curl and curl_gen, which is the code that curl generated with the –libcurl option.

 

corvette:motorNewport/newportApp/src>time curl -k -s -u Administrator:Administrator -T TrajectoryScan.trj --verbose scp://164.54.160.71/Admin/Public/Trajectories/

*   Trying 164.54.160.71...

* TCP_NODELAY set

* Connected to 164.54.160.71 (164.54.160.71) port 22 (#0)

* SSH MD5 fingerprint: 8de67ccf8c2f9b3b584c703b9fb749f6

* SSH authentication methods available: publickey,password,keyboard-interactive

* Using SSH private key file ''

* SSH public key authentication failed: Unable to extract public key from private key file: Unable to open private key file

* Initialized password authentication

* Authentication complete

* SSH CONNECT phase done

} [5149 bytes data]

* We are completely uploaded and fine

* Connection #0 to host 164.54.160.71 left intact

0.009u 0.005s 0:00.12 0.0%      0+0k 0+0io 0pf+0w

 

 

corvette:motorNewport/newportApp/src>time ../../../../bin/linux-x86_64/curl_gen < TrajectoryScan.trj

* About to connect() to 164.54.160.71 port 22 (#0)

*   Trying 164.54.160.71...

* Connected to 164.54.160.71 (164.54.160.71) port 22 (#0)

* SSH MD5 fingerprint: 8de67ccf8c2f9b3b584c703b9fb749f6

* SSH authentication methods available: publickey,password,keyboard-interactive

* Using SSH private key file ''

* SSH public key authentication failed: Unable to extract public key from private key file: Unable to open private key file

* Initialized password authentication

* Authentication complete

* SSH CONNECT phase done

* We are completely uploaded and fine

* Connection #0 to host 164.54.160.71 left intact

0.007u 0.005s 0:00.31 0.0%      0+0k 0+0io 0pf+0w

 

Note that there is still a large difference in time, curl takes 120 ms, curl_gen takes 310 ms.

 

The messages from libcurl are identical for both commands except that curl has the message “TCP_NODELAY set”. 

 

I then modified curl_gen.c to add this line:

 

  curl_easy_setopt(hnd, CURLOPT_TCP_NODELAY, 1L);

 

That fixed the issue!

 

corvette:motorNewport/newportApp/src>time ../../../../bin/linux-x86_64/curl_gen < TrajectoryScan.trj

* About to connect() to 164.54.160.71 port 22 (#0)

*   Trying 164.54.160.71...

* TCP_NODELAY set

* Connected to 164.54.160.71 (164.54.160.71) port 22 (#0)

* SSH MD5 fingerprint: 8de67ccf8c2f9b3b584c703b9fb749f6

* SSH authentication methods available: publickey,password,keyboard-interactive

* Using SSH private key file ''

* SSH public key authentication failed: Unable to extract public key from private key file: Unable to open private key file

* Initialized password authentication

* Authentication complete

* SSH CONNECT phase done

* We are completely uploaded and fine

* Connection #0 to host 164.54.160.71 left intact

0.011u 0.003s 0:00.12 8.3%      0+0k 0+0io 0pf+0w

 

Now curl_gen also takes only 120 ms.

 

I don’t know why curl –libcurl curl_gen.c was not putting that line in curl_gen.c, since it is clearly required to reproduce the behavior of the curl command I used.

 

This is the documentation for CURLOP_TCP_NODELAY https://curl.haxx.se/libcurl/c/CURLOPT_TCP_NODELAY.html

 

Pass a long specifying whether the TCP_NODELAY option is to be set or cleared (1L = set, 0 = clear). The option is set by default. This will have no effect after the connection has been established.

Setting this option to 1L will disable TCP's Nagle algorithm on this connection. The purpose of this algorithm is to try to minimize the number of small packets on the network (where "small packets" means TCP segments less than the Maximum Segment Size (MSS) for the network).

Maximizing the amount of data sent per TCP segment is good because it amortizes the overhead of the send. However, in some cases small segments may need to be sent without delay. This is less efficient than sending larger amounts of data at a time, and can contribute to congestion on the network if overdone.

Note that the documentation appears to be wrong.  It says that the option is set by default.  This appears to be true for the curl command, but not for libcurl.  I had to explicitly set the option.

 

Thanks,

Mark

 

 

 

 

 

From: Johnson, Andrew N. <anj@anl.gov>
Sent: Monday, November 18, 2019 6:56 PM
To: Mark Rivers <rivers@cars.uchicago.edu>
Subject: Re: Uploading a file with SFTP from an EPICS driver

 

So if you aren’t using the public/private key-pair for the SFTP transfer that might be a cause of the slow-up. Try removing it, or adjusting the .ssh/config file so it won’t be used for that host to see if that changes the timing.

- Andrew

 

-- 

Sent from my iPad

On Nov 18, 2019, at 6:40 PM, Mark Rivers <rivers@cars.uchicago.edu> wrote:



I changed the key.  It was only being used for Github I think, and Github stopped working until I uploaded the new public key.

 

Thanks,

Mark

 

 

From: Johnson, Andrew N. <anj@anl.gov>
Sent: Monday, November 18, 2019 5:51 PM
To: Mark Rivers <rivers@cars.uchicago.edu>
Subject: Re: Uploading a file with SFTP from an EPICS driver
Importance: High

 

Mark,

You should probably immediately disable and regenerate the .ssh key that was being used when you ran that command. You just sent the initial contents of your /home/epics/.ssh/id_rsa private key file out to over 900 people:

17:30:57.014060 read(5, "-----BEGIN RSA PRIVATE KEY-----\nMIIEogIBAAKCAQEAw2XnqGqU7M6nYLFgVH5GsBWbNEVsp0cIY2Z5lZwWR+6u8LEw\nG6cLN7AxCq3Ww93fUKk1RSbU9t4yPwfjzVU+CbEN0Q9XLkDYdjapzMFeNThHak/P\nTFBgJOlSbuw/CIToQqZyD/fVngPgRixuQKyubCw5zli9LpzEtWZIBwE11HYAIOM5\ngUau8MEbkXAoPxcGoN0rbdQPk8+qa"..., 4096) = 1675 <0.000014>

I think the value has been truncated for display, but I don't know how easy it might be to crack the complete key given just that part. I wouldn't want to take that chance myself.

- Andrew

On 11/18/19 5:34 PM, Mark Rivers via Tech-talk wrote:

   3. Check the ldd output for curl, libcurl.so, and curl_gen for anything

      that looks suspicious.  Make sure curl_gen is not linked against

      libgnutls.

 Can you also list the same for curl?

ldd on curl and curl_gen are identical except that curl_gen has these 3 libraries that curl does not have:

  libstdc++.so.6 => /lib64/libstdc++.so.6 (0x00007fdd3c745000)

  libm.so.6 => /lib64/libm.so.6 (0x00007fdd3c443000)

  libgcc_s.so.1 => /lib64/libgcc_s.so.1 (0x00007fdd3c22d000)

Yeah, that's because my suggested strace command is no good.  Sorry about that.  Try "strace -CfttTw -s 256 <command>" instead.

I have attached the complete output from strace for both curl and curl_gen.  The main difference is that curl spent 0.105 seconds in "poll" while curl_gen spent 0.494 seconds "poll".  All other functions are trivial.

Note that curl spend a total of 0.12 seconds, which is the same as I see without using strace.  However, curl_gen spent a total of 0.502 seconds, which is significantly longer than the 0.33 seconds without strace.

Mark

-----Original Message-----

From: J. Lewis Muir <jlmuir@imca-cat.org> 

Sent: Monday, November 18, 2019 2:56 PM

To: Mark Rivers <rivers@cars.uchicago.edu>

Cc: tech-talk@aps.anl.gov

Subject: Re: Uploading a file with SFTP from an EPICS driver

On 11/18, Mark Rivers wrote:

Ø  Strange.  Other things you could try:

   1. Run curl and curl_gen under strace (e.g., "strace -CftT -s 256

      <command>") and see if you can tell where curl_gen is taking longer

      than curl.

This is the final output of strace when running curl_gen:

[snip]

This is the output of strace when running the curl command:

[snip]

I don't know how to interpret these because the total elapsed time for 

curl_gen was 0.33 seconds while for the curl command it was 0.12 

seconds.  The tables above seem to show only 2-3 ms?

Yeah, that's because my suggested strace command is no good.  Sorry about that.  Try "strace -CfttTw -s 256 <command>" instead.

I added an extra "-t" option to make it print the microseconds.  Without that, you can't see what's going on.

And I added a "-w" option so that the trace timestamp differences are wall clock time, not system time.  This affects the total seconds in the summary table too.  Without it, you were just seeing system time, I think.  With the "-w" option, the summary total in seconds should equal the wall clock running time you have observed.  Note, however, that if the program does any forking where the parent waits for the child to finish, I think that will mess up the summary total since, e.g., the parent could be waiting in a system call for the child to die, and the child could be waiting in a system call for something else, and both of those would be included in the summary total.  So, you could end up with a summary total that is greater than the actual wall clock running time of the program.

Also note that in the trace output, the number at the end of each line in angle brackets (e.g., "<0.000085>") is the elapsed wall clock time spent in the system call which might be easier to look at than taking the difference of the two timestamps.

BTW, I'd be more interested in comparing the trace and less interested in the summary at the end, but if the summary at the end shows anything interesting, then great, at least it didn't get missed.

[snip]

   3. Check the ldd output for curl, libcurl.so, and curl_gen for anything

      that looks suspicious.  Make sure curl_gen is not linked against

      libgnutls.

corvette:motorNewport/newportApp/src>ldd 

../../../../bin/linux-x86_64/curl_gen

[snip]

Can you also list the same for curl?

Lewis

-- 

Complexity comes for free, Simplicity you have to work for.