Menu

uftp client: sometimes strange behavior

banuchka
2015-04-30
2016-01-15
  • banuchka

    banuchka - 2015-04-30

    Hi again Dennis =)

    client's version that im using:

    "UFTP version 4.6.1  Copyright (C) 2001-2015  Dennis A. Bush"
    

    sometimes i've seen in log something like that:

    2015/04/30 08:52:24.858031: [C8E31F32:0]: Name not in host list
    2015/04/30 08:52:28.263434: [C8E31F32:0]: Received request from 0A143402 at main1.ulan (10.20.52.2)
    2015/04/30 08:52:28.263466: [C8E31F32:0]: Using private multicast address 230.5.5.84
    2015/04/30 08:52:28.265456: [C8E31F32:0]: REGISTER sent
    2015/04/30 08:52:28.306542: [C8E31F32:0]: Expected REG_CONF, got FILESEG
    2015/04/30 08:52:28.306613: [C8E31F32:0]: Expected REG_CONF, got FILESEG
    2015/04/30 08:52:28.306702: [C8E31F32:0]: Expected REG_CONF, got FILESEG
    2015/04/30 08:52:28.306798: [C8E31F32:0]: Expected REG_CONF, got FILESEG
    ....
    2015/04/30 08:52:29.537819: [C8E31F32:0]: Expected REG_CONF, got FILESEG
    2015/04/30 08:52:29.537919: [C8E31F32:0]: Expected REG_CONF, got FILESEG
    2015/04/30 08:52:29.538010: [C8E31F32:0]: Expected REG_CONF, got FILESEG
    2015/04/30 08:52:29.538021: [C8E31F32:0]: Registration unconfirmed by server
    

    Im still using UFTP server -> Client and Client -> Proxy -> UFTP server (Proxy is for aggregation client's responses).

    In the proxy's log:

    2015/04/30 08:52:28.265402: [C8E31F32:0]: Received REGISTER from 0x0A141919
    2015/04/30 08:52:28.371516: [C8E31F32:0]: Received REGISTER+ from 0x0A141919
    2015/04/30 08:52:28.477640: [C8E31F32:0]: Received REGISTER+ from 0x0A141919
    2015/04/30 08:52:28.583636: [C8E31F32:0]: Received REGISTER+ from 0x0A141919
    2015/04/30 08:52:28.689683: [C8E31F32:0]: Received REGISTER+ from 0x0A141919
    2015/04/30 08:52:28.795718: [C8E31F32:0]: Received REGISTER+ from 0x0A141919
    2015/04/30 08:52:28.901788: [C8E31F32:0]: Received REGISTER+ from 0x0A141919
    2015/04/30 08:52:29.007803: [C8E31F32:0]: Received REGISTER+ from 0x0A141919
    2015/04/30 08:52:29.113853: [C8E31F32:0]: Received REGISTER+ from 0x0A141919
    2015/04/30 08:52:29.219906: [C8E31F32:0]: Received REGISTER+ from 0x0A141919
    2015/04/30 08:52:29.326017: [C8E31F32:0]: Received REGISTER+ from 0x0A141919
    2015/04/30 08:52:29.431988: [C8E31F32:0]: Received REGISTER+ from 0x0A141919
    2015/04/30 08:52:29.538043: [C8E31F32:0]: Transfer aborted by 0x0A141919: Registration unconfirmed
    

    Server's log:

    # cat /local/logs/uftp/aida-20150430-085224.log | grep cloud24
    2015/04/30 08:52:29.538760: [C8E31F32:0001]: Transfer aborted by cloud24.ulan: Registration unconfirmed
    2015/04/30 08:52:41.741996: [C8E31F32:0001]: Host: cloud24.ulan     Status: Aborted
    

    But sometimes all went ok and nothing bad happen.

    Maybe you may say something about? Appreciate your help.

     
  • Dennis Bush

    Dennis Bush - 2015-04-30

    It looks like the client never got the REG_CONF it was expecting from the server. It also appears that it never got a FILEINFO from the server with its ID in the client list. This seems to indicate that the server never got the REGISTER. What's in the server log for this session?

     
  • Dennis Bush

    Dennis Bush - 2015-04-30

    I see that the client first received an ANNOUNCE with its name included at 08:52:28.263434. The server had finished the Announce phase at 08:52:27.680782 and the File Info phase finished at 08:52:27.936069, so it was too late for the client to start the session by the time it got the ANNOUNCE. It's possible that it got hung up doing a DNS lookup on the server's ID. You can disable this by passing -q to the client.

    Something else that seems out of place, while not a huge problem, is that the clients are sending multiple REGISTERS even after the server sends a REG_CONF.

    Can you run a test with just 2 or 3 receivers not using a proxy, and with logging set to 5 on both server and clients and post the logs? I'm curious to see how the timing is working out.

     
  • Dennis Bush

    Dennis Bush - 2015-05-05

    This seems to be a different issue, perhaps related to the clients not receiving anything on the private multicast address. Check your multicast settings to make sure traffic is moving properly.

    Try it again, this time adding a bogus client to the list so that the server sends the maximum number of ANNOUNCEs to try and prompt the clients to respond. Also, you can use a small file for this test, since it's not the data transfer part I'm concerned about.

     
  • banuchka

    banuchka - 2015-05-07

    Hi,

    sorry for my mistake

    Here is a new logs: https://dl.dropboxusercontent.com/u/21671126/uftp_sf.tar.xz

    $ tree
    .
    ├── banuchka_uftp_2015-05-07.log
    ├── cloud24.ulan
    │   └── uftpd_sf.log
    ├── images1.ulan
    │   └── uftpd_sf.log
    ├── images2.ulan
    │   └── uftpd_sf.log
    ├── images3.ulan
    │   └── uftpd_sf.log
    └── scripts25.ulan
        └── uftpd_sf.log
    

    where "banuchka_uftp_2015-05-07.log" is a log from the server and client's logs is in their subdirs.

    Run with

    /local/uftp/bin/uftp -R 100000 -W 10000 -s 10 -r 0.6:0.01:90 -t 2 -B $((2*1024*1024)) -b 1200 -I eth0 -x 5 -L /local/logs/banuchka_uftp_2015-05-07.log -M 230.4.3.100 -H images1.ulan,images2.ulan,images3.ulan,cloud24.ulan,scripts25.ulan -D /local/tmp/test_f_uftp_banuchka /home/banuchka/test_f_uftp_banuchka
    
     
  • Dennis Bush

    Dennis Bush - 2015-05-07

    While this doesn't exhibit the issue of repeated REGISTERs in the original log or the delay in responding to the ANNOUNCEs, it does show that none of the clients received a REG_CONF and that it took them a while before they got a FILEINFO. I don't know what your network setup looks like, but if you're passing through one or more routers I suspect that there's a delay in setting up the private multicast address to pass through the routers.

    If possible, place static routes in your routers for the public multicast address and the range of private multicast addresses you'll be using. That should help with that delay.

    Regarding the delays in responding to the ANNOUNCEs, we probably need to run with the full set of receivers to recreated it, so go ahead and do that, with loogging turned up on just the few receivers from the last test. Then send me the server log and the logs of those clients.

     
  • banuchka

    banuchka - 2015-05-08

    do i need to set "-x 5" on the server side?

     
  • Dennis Bush

    Dennis Bush - 2015-05-08

    No, just the clients we're focusing on should be fine.

     
  • banuchka

    banuchka - 2015-05-08

    Here is a new portion of log files from morning's deployment process

    https://dl.dropboxusercontent.com/u/21671126/uftp_sf_20150508.tar.xz

    $ tree uftp_sf
    uftp_sf
    ├── aida-20150508-092310.log
    ├── cloud24.ulan
    │   └── uftp_27C18288.log
    ├── images1.ulan
    │   └── uftp_27C18288.log
    ├── images2.ulan
    │   └── uftp_27C18288.log
    ├── images3.ulan
    │   └── uftp_27C18288.log
    └── scripts25.ulan
        └── uftp_27C18288.log
    

    and there is a simple scheme of out network(from network dpt): https://dl.dropboxusercontent.com/u/21671126/network_map.png

     

    Last edit: banuchka 2015-05-08
  • Dennis Bush

    Dennis Bush - 2015-05-08

    Alright, it seems that both this set of logs and the previous actually exhibit the same problem. In particular, I see that images1.ulan doesn't receive a REG_CONF until more than 500 ms after it gets the ANNOUNCE. This goes back to what I mentioned before, namely that it's taking a while for IGMP message to propagate while setting up the private multicast group. Also, I noticed that this client only received one of the three ANNOUNCE messages from the first set. I find it surprising that loss occurred at the very beginning of the session. I'm not sure if this is related as well.

    I'm not too familiar with PIM, but it's possible it may be responsible for these delays. You'll probably need to tweak some settings on your routers to reduce the delays. Set up a packet trace on images1.ulan so you can see exactly what went in and out. You can do this with a small number of receivers and a small datafile (less than 1 MB) so that the trace file isn't too big. With that data in hand, you can figure out what adjustments you need to make.

     
  • banuchka

    banuchka - 2015-05-12

    Hi,

    with tshark it looks like that:

     49  83.106873   10.20.52.2 -> 230.4.3.100  UFTP 1282 ANNOUNCE     ID=80C9B34C
     50  84.495178 Force10N_80:ec:56 -> Spanning-tree-(for-bridges)_00 STP 135 MST. Root = 4096/0/78:19:f7:05:fa:01  Cost = 0  Port = 0x8422
     51  84.528364 Force10N_80:ec:56 -> LLDP_Multicast LLDP 340 TTL = 120 System Name = sw-c300-3-tmk System Description = Dell Force10 Real Time Operating System Software. Dell Force10 Operating System Version: 1.0. Dell Force10 Application Software Version: 8.4.2.7. Copyright (c) 1999-2012 Dell Inc. All Rights Reserved.Build Time: Thu Sep 27 14:19:20 PDT 2012
     52  84.870730   10.20.52.2 -> 230.4.3.100  UFTP 1282 ANNOUNCE     ID=80C9B34C
     53  84.870916   10.20.52.2 -> 230.4.3.100  UFTP 242 ANNOUNCE     ID=80C9B34C
     54  84.875286   10.20.58.2 -> 230.5.5.124  IGMPv2 46 Membership Report group 230.5.5.124
     55  84.980260   10.20.52.2 -> 230.5.5.124  UFTP 1262 REG_CONF     ID=80C9B34C
     56  85.087280   10.20.58.2 -> 230.5.5.124  IGMPv2 46 Membership Report group 230.5.5.124
     57  85.240710   10.20.52.2 -> 230.5.5.124  UFTP 1342 FILEINFO     ID=80C9B34C
     58  85.240991   10.20.52.2 -> 230.5.5.124  UFTP 1342 FILEINFO     ID=80C9B34C
     59  85.241254   10.20.52.2 -> 230.5.5.124  UFTP 298 FILEINFO     ID=80C9B34C
     60  85.389384   10.20.52.2 -> 230.5.5.124  UFTP 478 FILEINFO     ID=80C9B34C
     61  85.523226   10.20.52.2 -> 230.5.5.124  UFTP 478 FILEINFO     ID=80C9B34C
     62  85.643686   10.20.52.2 -> 230.5.5.124  UFTP 146 FILEINFO     ID=80C9B34C
     63  85.752038   10.20.52.2 -> 230.5.5.124  UFTP 146 FILEINFO     ID=80C9B34C
     64  85.849683   10.20.52.2 -> 230.5.5.124  UFTP 146 FILEINFO     ID=80C9B34C
     65  85.937490   10.20.52.2 -> 230.5.5.124  UFTP 146 FILEINFO     ID=80C9B34C
     66  86.016557   10.20.52.2 -> 230.5.5.124  UFTP 146 FILEINFO     ID=80C9B34C
     67  86.055055   10.20.58.1 -> 224.0.0.13   PIMv2 68 Hello
     68  86.087734   10.20.52.2 -> 230.5.5.124  UFTP 146 FILEINFO     ID=80C9B34C
     69  86.152369   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    ...
    9266  87.288914   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9267  87.289011   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9268  87.289024   10.20.52.2 -> 230.5.5.124  UFTP 302 DONE         ID=80C9B34C
    9269  87.341099   10.20.52.2 -> 230.5.5.124  UFTP 214 DONE         ID=80C9B34C
    9270  87.364226   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9271  87.364286   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9272  87.364291   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9273  87.364293   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9274  87.364765   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9275  87.364853   10.20.52.2 -> 230.5.5.124  UFTP 274 DONE         ID=80C9B34C
    9276  87.417088   10.20.52.2 -> 230.5.5.124  UFTP 150 DONE         ID=80C9B34C
    9277  87.421160   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9278  87.421168   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9279  87.421235   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9280  87.421688   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9281  87.421732   10.20.52.2 -> 230.5.5.124  UFTP 154 DONE         ID=80C9B34C
    9282  87.473929   10.20.52.2 -> 230.5.5.124  UFTP 106 DONE         ID=80C9B34C
    9283  87.478543   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9284  87.478601   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9285  87.479084   10.20.52.2 -> 230.5.5.124  UFTP 110 DONE         ID=80C9B34C
    9286  87.531235   10.20.52.2 -> 230.5.5.124  UFTP 98 DONE         ID=80C9B34C
    9287  87.538350   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9288  87.538359   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9289  87.538837   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9290  87.538909   10.20.52.2 -> 230.5.5.124  UFTP 110 DONE         ID=80C9B34C
    9291  87.591122   10.20.52.2 -> 230.5.5.124  UFTP 90 DONE         ID=80C9B34C
    9292  87.606765   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9293  87.606861   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9294  87.606868   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9295  87.606871   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9296  87.606876   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9297  87.606878   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9298  87.606879   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9299  87.606881   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9300  87.607287   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9301  87.607296   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9302  87.607328   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9303  87.607335   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9304  87.607429   10.20.52.2 -> 230.5.5.124  UFTP 94 DONE         ID=80C9B34C
    9305  87.659614   10.20.52.2 -> 230.5.5.124  UFTP 82 DONE         ID=80C9B34C
    9306  87.679645   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9307  87.679701   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9308  87.679706   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9309  87.679708   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9310  87.679711   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9311  87.679734   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9312  87.679780   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9313  87.679788   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9314  87.680134   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9315  87.680148   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9316  87.680185   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9317  87.680188   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9318  87.680284   10.20.52.2 -> 230.5.5.124  UFTP 86 DONE         ID=80C9B34C
    9319  87.732382   10.20.52.2 -> 230.5.5.124  UFTP 74 DONE         ID=80C9B34C
    9320  87.771238   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9321  87.771281   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9322  87.771285   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9323  87.771287   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9324  87.771305   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9325  87.771714   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9326  87.771722   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9327  87.771757   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9328  87.771761   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9329  87.771879   10.20.52.2 -> 230.5.5.124  UFTP 74 DONE         ID=80C9B34C
    9330  87.824150   10.20.52.2 -> 230.5.5.124  UFTP 74 DONE         ID=80C9B34C
    9331  87.876368   10.20.52.2 -> 230.5.5.124  UFTP 74 DONE         ID=80C9B34C
    9332  87.928434   10.20.52.2 -> 230.5.5.124  UFTP 74 DONE         ID=80C9B34C
    9333  87.980634   10.20.52.2 -> 230.5.5.124  UFTP 74 DONE         ID=80C9B34C
    9334  88.032856   10.20.52.2 -> 230.5.5.124  UFTP 70 DONE         ID=80C9B34C
    9335  88.047745   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9336  88.047847   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9337  88.047854   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9338  88.047856   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9339  88.047859   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9340  88.047861   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9341  88.047866   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9342  88.047867   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9343  88.100689   10.20.52.2 -> 230.5.5.124  UFTP 74 DONE         ID=80C9B34C
    9344  88.152947   10.20.52.2 -> 230.5.5.124  UFTP 70 DONE         ID=80C9B34C
    9345  88.160556   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9346  88.160565   10.20.52.2 -> 230.5.5.124  UFTP 1266 FILESEG      ID=80C9B34C
    9347  88.160711   10.20.52.2 -> 230.5.5.124  UFTP 74 DONE         ID=80C9B34C
    9348  88.176642   10.20.52.2 -> 230.5.5.124  UFTP 1266 DONE         ID=80C9B34C
    9349  88.177050   10.20.52.2 -> 230.5.5.124  UFTP 1266 DONE         ID=80C9B34C
    9350  88.177146   10.20.52.2 -> 230.5.5.124  UFTP 230 DONE         ID=80C9B34C
    9351  88.201793   10.20.52.2 -> 230.5.5.124  UFTP 1262 DONE_CONF    ID=80C9B34C
    9352  88.202020   10.20.52.2 -> 230.5.5.124  UFTP 1262 DONE_CONF    ID=80C9B34C
    9353  88.202138   10.20.58.2 -> 224.0.0.2    IGMPv2 46 Leave Group 230.5.5.124
    9354  88.202159   10.20.52.2 -> 230.5.5.124  UFTP 222 DONE_CONF    ID=80C9B34C
    9355  88.385313   10.20.58.1 -> 230.5.5.124  IGMPv2 60 Membership Query, specific for group 230.5.5.124
    9356  88.618452 Force10N_80:ec:56 -> Spanning-tree-(for-bridges)_00 STP 135 MST. Root = 4096/0/78:19:f7:05:fa:01  Cost = 0  Port = 0x8422
    
     
  • Sagar Kumar

    Sagar Kumar - 2016-01-15

    Hi Dennis,

    Greetings !!

    We are trying to use UFTP for transferring large files across multiple location using satellite multicast . We are doing a test with 3 locations ,we are facing a strange problem for small files the transfer gets completed in most of the time but when we try for larger files >6GB we find at some or other location a disconnection & transfer aborts even when we have good connectivity.
    We are using the following setting for transfer on Ubuntu 12.0 across all location.

    1. Speed - 6mbps
    2. TTL value - 10
    3. Packet size and cache to be made to default settings -

    Can you suggest anything which we are missing which is aborting the transfer . Is it due to license ? I will be obliged if you can give us some tips to resolve the same.

    Thanks in advance.

    Rgds
    Sagar

     

Log in to post a comment.

Want the latest updates on software, tech news, and AI?
Get latest updates about software, tech news, and AI from SourceForge directly in your inbox once a month.