Auto-resume upon disconnect

[varenius]

I want to transfer data and I run e.g.
etc '/mnt/vbsmnt/vo1074_oe*' TARGETIP#PORT:/gpfs/cdata/incoming/oe-test/ --resume -v -m 3
This runs fine, until it suddenly doesn't:

2021-03-23 10:42:24.42: PUSH Resume /mnt/vbsmnt/vo1074_oe_074-1919a_6 -> /gpfs/cdata/incoming/oe/vo1074_oe_074-1919a_6
terminate called after throwing an instance of 'etdc::assertion_error'
  what():  assertion error: src/etdc_etdserver.cc:359 [transfer.data_fd] Failed to connect to any of the data servers: <udt/TARGETIP:2630>: system call failed: /usr/local/src/etransfer.git/src/etdc_fd.h:892 connecting to udt[TARGETIP:2630] - Connection setup failure: connection time out.,
Aborted (core dumped)

due to the "connection time out." error. @haavee theorised that this may happen because UDT being based on UDP, so if an important packets (e.g. connection setup or the reply to that) is lost, that it cannot recover from that. This may be the reason, and it may be a rare problem, but it is unfortunate because then no data is transferred. The fix is to simply restart the transfer, i.e. I press "up-arrow, enter" in my terminal. Now etc reconnects, resumes the transfer and all works fine. Until next time it breaks.

I would like to be able to start etc with an auto-reconnect option, e.g. "--autorecon" which would upon "connection time out" try to automatically re-connect. It could, for example, try to auto-reconnect 5 times with 1 minute delay between each try. In this way, transfers will not sit idle due to an unlucky interruption.

Because we in practice start the transfer and then go do something else, there is a high risk of transfer failing silently in this way. Therefore, this auto-reconnect feature would be good.

[varenius]

This happened again last night, so 7h of possible transfer time was not used:

2021-03-24 01:03:31.72: PUSH Resume /mnt/vbsmnt/vo1074_ow_075-0216_6 -> /gpfs/cdata/incoming/ow/vo1074_ow_075-0216_6
terminate called after throwing an instance of 'etdc::assertion_error'
  what():  assertion error: src/etdc_etdserver.cc:359 [transfer.data_fd] Failed to connect to any of the data servers: <udt/TARGETIP:2630>: system call failed: /usr/local/src/etransfer.git/src/etdc_fd.h:892 connecting to udt[TARGETIP:2630] - Connection setup failure: connection time out.,
Aborted

[varenius]

For reference, it happened again now (but I caught it fairly quickly this time)

2021-03-24 10:44:17.50: PUSH Resume /mnt/vbsmnt/vo1074_oe_075-0633_4 -> /gpfs/cdata/incoming/oe/vo1074_oe_075-0633_4
terminate called after throwing an instance of 'etdc::assertion_error'
  what():  assertion error: src/etdc_etdserver.cc:359 [transfer.data_fd] Failed to connect to any of the data servers: <udt/TARGETIP4:2630>: system call failed: /usr/local/src/etransfer.git/src/etdc_fd.h:892 connecting to udt[TARGETIP:2630] - Connection setup failure: connection time out.,
Aborted (core dumped)

I'm just posting these for reference, so we have an idea about how common this is.

[varenius]

Once more connection time out at 2021-03-24 14:21:17.50.

[haavee]

Do you have an estimate of how many transfers did succeed between failures? So as to have a feeling for "once in every N"?
(Might make the s/w look a bit less worse on this issue report ;-))

[varenius]

:) I see your point. I don't have logs (would be a nother nice feature of etc to give a logfile flag) but from the terminal output I have on screen I estimate that I transfer about 10 files in 4 minutes. From the log above, I had 3 timeouts in about 24h. This would imply a failure rate of 3/(102460/4)=0.08%. It is a tiny number indeed.

But, in some way the rate is not so important. The problem is that if it fails just after I leave the office, I cannot resume it until the next day. This means the possible down-time due to the failure is 16h (assuming 8h work day) which for a 24h possible transfer range would be a failure rate of 16/24 = 67%.

So the severity is highly depending on the calculation method. However, in practice, the problem is not that I have to restart it often (I could do that), it is the long periods when there's noone looking at the transfer (e.g. at night). So I'd prefer the second method of calculation, which unfortunately gives quite a high possible failure impact.

[haavee]

#!/bin/sh
while /bin/true; do
    /path/to/etc '/mnt/.../vo*' tcp://HOST:IP#PORT/path/to/dir/
done

?

[varenius]

Yeah, that could work. I did something similar for m5copy where I had other issues. But it would be so nice to just be able to run one command and not have to write wrapper scripts for each transfer :). I deal with a few transfers every week, and although trivial it would just be nice to have the transfer software handle all the issues for me :).

[haavee]

It is a very useful suggestion you make and it will arrive in the code at some point. But for your current ailment at hand this poor man's solution could get you up to 24h usage cycles. Add in a bit of "output redirecting" and massaging and you have your logging facility too; skipping the pesky "Oh I already did this file" messages

#/bin/sh
while /bin/true; do
    echo "(re)starting at `date`" >> log.txt
    /path/to/etc '....' 2>&1 | awk '/finished/ { print prv_line; print $0; next; } {prv_line = $0}' >> log.txt
done

[varenius]

Thank you for the "bashing", it'll make me happy for now :).

[haavee]

Can you try this branch: https://github.com/jive-vlbi/etransfer/tree/issue-5?
It has compiled in default of trying to connect three times w/ 10s delay between failures (i.e. nRetry = 2; thus total nr of connection attempts = 3). If this works at all I should be able to make this into command line options (nRetry and retryDelay)

[varenius]

Not sure exactly how to test this, but I tried to run the "etd" from the compile-issues branch on one machine, and the new issue-5 etc from another machine. Seems to fail, although not sure why.
etc log:

oper@gyller:/usr/local/src/etransfer.git/Linux-x86_64-native-opt$ git branch
  compile-issues
* issue-5
  master
oper@gyller:/usr/local/src/etransfer.git/Linux-x86_64-native-opt$ ./etc '/mnt/vbsmnt/vo1074_oe_075-133*' skirner_x#43992:/mnt/disk0/vm_0188ow_1/ --resume -v -m 5
2021-03-25 06:48:48.34: [etdc::ETDServer::ETDServer(etdc::etd_state&)] ETDServer starting, my uuid=fNZqyzlmBxeoJnJ
2021-03-25 06:48:48.73: [virtual etdc::dataaddrlist_type etdc::ETDProxy::dataChannelAddr() const] ETDProxy::dataChannelAddr/sending message 'data-channel-addr
'
2021-03-25 06:48:48.73: [virtual etdc::dataaddrlist_type etdc::ETDProxy::dataChannelAddr() const] dataChannelAddr/reply from server: 'OK <udt/0.0.0.0:43995>'
2021-03-25 06:48:48.74: [etdc::sockname_type etdc::decode_data_addr(const string&)] decode_data_addr: 1='udt' 2='0.0.0.0' 9='43995'
2021-03-25 06:48:48.74: [virtual etdc::dataaddrlist_type etdc::ETDProxy::dataChannelAddr() const] dataChannelAddr/reply from server: 'OK'
2021-03-25 06:48:48.74: [int main(int, const char* const*)] PUSH Resume /mnt/vbsmnt/vo1074_oe_075-1330_0 -> /mnt/disk0/vm_0188ow_1/vo1074_oe_075-1330_0
2021-03-25 06:48:48.74: [void signal_thread(const signallist_type&, etdc::etd_state&, pthread_t) [with int KillSignal = 10; signallist_type = std::vector<int>; pthread_t = long unsigned int]] sigwaiterthread: enter wait phase
2021-03-25 06:48:48.74: [virtual etdc::result_type etdc::ETDProxy::requestFileWrite(const string&, etdc::openmode_type)] ETDProxy::requestFileWrite/sending message 'write-file-Resume /mnt/disk0/vm_0188ow_1/vo1074_oe_075-1330_0
' sz=62
2021-03-25 06:48:48.74: [int etdc::detail::open_file(const string&, int, Args&& ...) [with Args = {}; std::__cxx11::string = std::__cxx11::basic_string<char>]] open_file/npath='/mnt/vbsmnt/vo1074_oe_075-1330_0'
2021-03-25 06:49:18.75: [virtual bool etdc::ETDProxy::removeUUID(const etdc::uuid_type&)] ETDProxy::removeUUID/sending message 'remove-uuid S2MIwzNNLqKjewWqfKN
'
terminate called after throwing an instance of 'etdc::assertion_error'
  what():  assertion error: src/etdc_etdserver.cc:359 [transfer.data_fd] Failed to connect to any of the data servers: <udt/skirner_x:43995>: assertion error: /usr/local/src/etransfer.git/src/etdc_fd.h:933 [didConnect] connecting to udt[10.100.0.11:43995] - Bad file descriptor, 
Aborted (core dumped)

etd log:

oper@skirner DiFX-trunk vm_0188ow_1> etd --command tcp://:43992 --data udt://:43995 -f -m 5
2021-03-25 06:46:23.29: [void signal_thread(const signallist_type&, std::promise<int>&)] sigwaiterthread: enter wait phase
2021-03-25 06:46:23.30: [etdc::etdc_fdptr string2socket_type_m::operator()(const string&) const] etd: server is-at <udt/0.0.0.0:43995>
2021-03-25 06:46:23.30: [<lambda(etdc::etdc_fdptr, const string&)>] server/UDT rcvbuf = 335543872 sndbuf = 335543872 linger=0:0
2021-03-25 06:46:23.30: [etdc::etdc_fdptr string2socket_type_m::operator()(const string&) const] etd: server is-at <tcp/0.0.0.0:43992>
2021-03-25 06:46:23.30: [<lambda(etdc::etdc_fdptr, const string&)>] server/TCP rcvbuf = 67108864 sndbuf = 67108864
2021-03-25 06:46:42.68: [void command_server_thread(etdc::etdc_fdptr, etdc::etd_state&) [with int <anonymous> = 10; etdc::etdc_fdptr = std::shared_ptr<etdc::etdc_fd>]] Incoming COMMAND from <tcp/10.100.0.15:47082> [local <tcp/10.100.0.11:43992>]
2021-03-25 06:46:42.68: [<lambda(etdc::etdc_fdptr, const string&)>] client/TCP rcvbuf = 67108864 sndbuf = 67108864
2021-03-25 06:46:42.68: [etdc::ETDServer::ETDServer(etdc::etd_state&)] ETDServer starting, my uuid=FXQEw0xEZmlYDQOYWE
2021-03-25 06:46:42.68: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / start loop, curPos=0
2021-03-25 06:46:43.11: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / read n=18 => nTotal=18
2021-03-25 06:46:43.11: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle()/got line: 'data-channel-addr'
2021-03-25 06:46:43.12: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: sending reply 'OK <udt/0.0.0.0:43995>'
2021-03-25 06:46:43.12: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: sending reply 'OK'
2021-03-25 06:46:43.12: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / start loop, curPos=0
2021-03-25 06:46:43.12: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / read n=62 => nTotal=62
2021-03-25 06:46:43.12: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle()/got line: 'write-file-Resume /mnt/disk0/vm_0188ow_1/vo1074_oe_075-1330_0'
2021-03-25 06:46:43.12: [int etdc::detail::open_file(const string&, int, Args&& ...) [with Args = {int}; std::__cxx11::string = std::__cxx11::basic_string<char>]] open_file/npath='/mnt/disk0/vm_0188ow_1/vo1074_oe_075-1330_0'
2021-03-25 06:46:43.12: [int etdc::detail::open_file(const string&, int, Args&& ...) [with Args = {int}; std::__cxx11::string = std::__cxx11::basic_string<char>]] open_file/O_CREAT is set, dir='/mnt/disk0/vm_0188ow_1/'
2021-03-25 06:46:43.12: [int etdc::detail::open_file(const string&, int, Args&& ...) [with Args = {int}; std::__cxx11::string = std::__cxx11::basic_string<char>]] open_file/path_so_far='/mnt'
2021-03-25 06:46:43.12: [int etdc::detail::open_file(const string&, int, Args&& ...) [with Args = {int}; std::__cxx11::string = std::__cxx11::basic_string<char>]] open_file/path_so_far='/mnt/disk0'
2021-03-25 06:46:43.12: [int etdc::detail::open_file(const string&, int, Args&& ...) [with Args = {int}; std::__cxx11::string = std::__cxx11::basic_string<char>]] open_file/path_so_far='/mnt/disk0/vm_0188ow_1'
2021-03-25 06:46:43.12: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: sending reply 'AlreadyHave:0'
2021-03-25 06:46:43.12: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: sending reply 'UUID:FXQEw0xEZmlYDQOYWE'
2021-03-25 06:46:43.12: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: sending reply 'OK'
2021-03-25 06:46:43.12: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / start loop, curPos=0
2021-03-25 06:47:13.13: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / read n=31 => nTotal=31
2021-03-25 06:47:13.13: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle()/got line: 'remove-uuid FXQEw0xEZmlYDQOYWE'
2021-03-25 06:47:13.13: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: removeUUID(FXQEw0xEZmlYDQOYWE yields 1
2021-03-25 06:47:13.13: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: sending reply 'OK'
2021-03-25 06:47:13.13: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / start loop, curPos=0
2021-03-25 06:47:13.25: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / read n=0 => nTotal=0
2021-03-25 06:47:13.25: [void command_server_thread(etdc::etdc_fdptr, etdc::etd_state&) [with int <anonymous> = 10; etdc::etdc_fdptr = std::shared_ptr<etdc::etdc_fd>]] command server thread got exception: assertion error: src/etdc_etdserver.cc:987 [n>0] Failed to read data from remote end
2021-03-25 06:47:13.25: [void command_server_thread(etdc::etdc_fdptr, etdc::etd_state&) [with int <anonymous> = 10; etdc::etdc_fdptr = std::shared_ptr<etdc::etdc_fd>]] command server thread terminated
^C2021-03-25 06:47:34.96: [void signal_thread(const signallist_type&, std::promise<int>&)] sigwaiterthread: got signal 2
2021-03-25 06:47:34.96: [int main(int, const char* const*)] main: terminating because of signal#2
2021-03-25 06:47:34.96: [data_server_thread(etdc::etdc_fdptr, etdc::etd_state&)::<lambda()> [with int KillSignal = 12]] Cancellation fn/signalling thread for data fd=365782979
2021-03-25 06:47:34.96: [command_server_thread(etdc::etdc_fdptr, etdc::etd_state&)::<lambda()> [with int KillSignal = 10]] Cancellation fn/signalling thread for command fd=4
2021-03-25 06:47:34.96: [int main(int, const char* const*)] main: terminating.
2021-03-25 06:47:34.96: [etdc::etd_state::~etd_state()] ~etd_state/need to wait for 2 threads
2021-03-25 06:47:34.96: [void data_server_thread(etdc::etdc_fdptr, etdc::etd_state&) [with int <anonymous> = 12; etdc::etdc_fdptr = std::shared_ptr<etdc::etdc_fd>]] data server thread got exception: system call failed: /usr/local/src/etransfer.git/src/etdc_fd.h:658 failed to accept on udt[0.0.0.0:43995] - Operation not supported: Socket is not in listening state.
2021-03-25 06:47:34.96: [void command_server_thread(etdc::etdc_fdptr, etdc::etd_state&) [with int <anonymous> = 10; etdc::etdc_fdptr = std::shared_ptr<etdc::etdc_fd>]] command server thread got exception: system call failed: /usr/local/src/etransfer.git/src/etdc_fd.h:551 failed to accept on tcp[0.0.0.0:43992] - Interrupted system call
2021-03-25 06:47:34.96: [void data_server_thread(etdc::etdc_fdptr, etdc::etd_state&) [with int <anonymous> = 12; etdc::etdc_fdptr = std::shared_ptr<etdc::etdc_fd>]] data server thread terminated
2021-03-25 06:47:34.96: [void command_server_thread(etdc::etdc_fdptr, etdc::etd_state&) [with int <anonymous> = 10; etdc::etdc_fdptr = std::shared_ptr<etdc::etdc_fd>]] command server thread terminated
oper@skirner DiFX-trunk vm_0188ow_1> etd --command tcp://:43992 --data udt://:43995 -f -m 5
2021-03-25 06:48:36.26: [void signal_thread(const signallist_type&, std::promise<int>&)] sigwaiterthread: enter wait phase
2021-03-25 06:48:36.26: [etdc::etdc_fdptr string2socket_type_m::operator()(const string&) const] etd: server is-at <udt/0.0.0.0:43995>
2021-03-25 06:48:36.26: [<lambda(etdc::etdc_fdptr, const string&)>] server/UDT rcvbuf = 335543872 sndbuf = 335543872 linger=0:0
2021-03-25 06:48:36.26: [etdc::etdc_fdptr string2socket_type_m::operator()(const string&) const] etd: server is-at <tcp/0.0.0.0:43992>
2021-03-25 06:48:36.26: [<lambda(etdc::etdc_fdptr, const string&)>] server/TCP rcvbuf = 67108864 sndbuf = 67108864
2021-03-25 06:48:48.34: [void command_server_thread(etdc::etdc_fdptr, etdc::etd_state&) [with int <anonymous> = 10; etdc::etdc_fdptr = std::shared_ptr<etdc::etdc_fd>]] Incoming COMMAND from <tcp/10.100.0.15:47084> [local <tcp/10.100.0.11:43992>]
2021-03-25 06:48:48.34: [<lambda(etdc::etdc_fdptr, const string&)>] client/TCP rcvbuf = 67108864 sndbuf = 67108864
2021-03-25 06:48:48.34: [etdc::ETDServer::ETDServer(etdc::etd_state&)] ETDServer starting, my uuid=S2MIwzNNLqKjewWqfKN
2021-03-25 06:48:48.34: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / start loop, curPos=0
2021-03-25 06:48:48.73: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / read n=18 => nTotal=18
2021-03-25 06:48:48.73: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle()/got line: 'data-channel-addr'
2021-03-25 06:48:48.73: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: sending reply 'OK <udt/0.0.0.0:43995>'
2021-03-25 06:48:48.73: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: sending reply 'OK'
2021-03-25 06:48:48.73: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / start loop, curPos=0
2021-03-25 06:48:48.74: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / read n=62 => nTotal=62
2021-03-25 06:48:48.74: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle()/got line: 'write-file-Resume /mnt/disk0/vm_0188ow_1/vo1074_oe_075-1330_0'
2021-03-25 06:48:48.74: [int etdc::detail::open_file(const string&, int, Args&& ...) [with Args = {int}; std::__cxx11::string = std::__cxx11::basic_string<char>]] open_file/npath='/mnt/disk0/vm_0188ow_1/vo1074_oe_075-1330_0'
2021-03-25 06:48:48.74: [int etdc::detail::open_file(const string&, int, Args&& ...) [with Args = {int}; std::__cxx11::string = std::__cxx11::basic_string<char>]] open_file/O_CREAT is set, dir='/mnt/disk0/vm_0188ow_1/'
2021-03-25 06:48:48.74: [int etdc::detail::open_file(const string&, int, Args&& ...) [with Args = {int}; std::__cxx11::string = std::__cxx11::basic_string<char>]] open_file/path_so_far='/mnt'
2021-03-25 06:48:48.74: [int etdc::detail::open_file(const string&, int, Args&& ...) [with Args = {int}; std::__cxx11::string = std::__cxx11::basic_string<char>]] open_file/path_so_far='/mnt/disk0'
2021-03-25 06:48:48.74: [int etdc::detail::open_file(const string&, int, Args&& ...) [with Args = {int}; std::__cxx11::string = std::__cxx11::basic_string<char>]] open_file/path_so_far='/mnt/disk0/vm_0188ow_1'
2021-03-25 06:48:48.74: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: sending reply 'AlreadyHave:0'
2021-03-25 06:48:48.74: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: sending reply 'UUID:S2MIwzNNLqKjewWqfKN'
2021-03-25 06:48:48.74: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: sending reply 'OK'
2021-03-25 06:48:48.74: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / start loop, curPos=0
2021-03-25 06:49:18.75: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / read n=32 => nTotal=32
2021-03-25 06:49:18.75: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle()/got line: 'remove-uuid S2MIwzNNLqKjewWqfKN'
2021-03-25 06:49:18.75: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: removeUUID(S2MIwzNNLqKjewWqfKN yields 1
2021-03-25 06:49:18.75: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper: sending reply 'OK'
2021-03-25 06:49:18.75: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / start loop, curPos=0
2021-03-25 06:49:18.86: [void etdc::ETDServerWrapper::handle()] ETDServerWrapper::handle() / read n=0 => nTotal=0
2021-03-25 06:49:18.86: [void command_server_thread(etdc::etdc_fdptr, etdc::etd_state&) [with int <anonymous> = 10; etdc::etdc_fdptr = std::shared_ptr<etdc::etdc_fd>]] command server thread got exception: assertion error: src/etdc_etdserver.cc:987 [n>0] Failed to read data from remote end
2021-03-25 06:49:18.86: [void command_server_thread(etdc::etdc_fdptr, etdc::etd_state&) [with int <anonymous> = 10; etdc::etdc_fdptr = std::shared_ptr<etdc::etdc_fd>]] command server thread terminated

[varenius]

And just to confirm; running etc from compile-issues, not from issue-5 branch, works just fine with the command above.

[varenius]

Note regarding propose bash-while workaround: As stated, the suggested bash code has two problems a) It did not run when I put my etc command where I thought it should be, but that may just be due to bash incompetence, and b) after spending some time getting it working (using eval instead to excecute the command string), it now does not handle ^C anymore since the loop eats it. I can of course work around this, but then I'm spending time coding work arounds which is exactly what I wanted to avoid :). For now, I settled on a bash script which just has the same "eval" call 10 times, no loops or anything, to just catch a few timeouts that will happen. Simple enough to just work (tm) for now.

[varenius]

Note: This is now very nearly solved, except for possible unusual cases like #12 .

[haavee]

Closing this one for now as this is continued in issue #12