Inconsistent response-proxy behavior
Encrypted UDP based FTP with multicast
Brought to you by:
dennisbush
Menu
▾
▴
Hello Dennis,
I am currently having an issue with my response proxies having consistent behavior. I am testing a file send to 3 clients and using 3 different response proxies. One client consistently is able to send responses to its specified proxy. The other 2 clients are incosistent. If I restart the uftpproxyd daemon on the proxies, the only client that will send responses is the one associated with the most recent restarted proxy. So the server only gets FILEINFO_ACK from 2 out of 3 proxies and therefore only sends the file to 2 clients. The problem client/proxy in this case, 0x00001904/ rxa-multicast05 never communicate with each other. However, if I restart uftpproxyd on rxa-multicast05 then they start communicating again and client 0x00016743 drops. Client 0x00003968 is always consistent. I have thousands of clients and 5 response proxies configured, I am worried this problem will be magnified if I decide to send to more clients.
Server command:
/usr/bin/uftp -M 239.172.1.1 -P 239.172.1.129 /home/uftp-test3and5-500MB.txt -t 16 -j /home/proxy.txt -H @/home//hostlist.txt -L /home/log/uftp.log
uftp proxy cmmands:
/usr/bin/uftpproxyd -x 3 -L /var/log/uftpproxyd.log -r -M 239.172.1.1 239.172.1.16 -U rxa-multicast02 -t 100 -g 400
/usr/bin/uftpproxyd -x 3 -L /var/log/uftpproxyd.log -r -M 239.172.1.1 239.172.1.16 -U rxa-multicast04 -t 100 -g 400
/usr/bin/uftpproxyd -x 3 -L /var/log/uftpproxyd.log -r -M 239.172.1.1 239.172.1.16 -U rxa-multicast05 -t 100 -g 400
Client commands:
/usr/bin/uftpd -D /app/common/download/multicast -T /app/common/download/multicast/incoming -P /var/run/uftpd.pid -M 239.172.1.1 -U 0x00001904 -R rxa-multicast05.xyz.com -L /var/log/uftpd.log
/usr/bin/uftpd -D /app/common/download/multicast -T /app/common/download/multicast/incoming -P /var/run/uftpd.pid -M 239.172.1.1 -U 0x00016743 -R rxa-multicast02.xyz.com -L /var/log/uftpd.log
/usr/bin/uftpd -D /app/common/download/multicast -T /app/common/download/multicast/incoming -P /var/run/uftpd.pid -M 239.172.1.1 -U 0x00003968 -R rxa-multicast04.xyz.com -L /var/log/uftpd.log
Log output from 0x00001904 client:
/var/log/uftpd.log.1:2018/05/01 07:58:24.983006: [3E3FAB5C/00:0]: Received request from 0AE6220F at rxa-multicast01.stores.cvs.com (10.230.34.15)
/var/log/uftpd.log.1:2018/05/01 07:58:24.983018: [3E3FAB5C/00:0]: Using private multicast address 239.172.1.129
.......
.......
/var/log/uftpd.log.1:2018/05/01 07:58:24.983029: [3E3FAB5C/00:0]: grtt = 0.532216
/var/log/uftpd.log.1:2018/05/01 07:58:24.983045: [3E3FAB5C/00:0]: send time: 1525197504.896959
/var/log/uftpd.log.1:2018/05/01 07:58:24.983056: [3E3FAB5C/00:0]: receive time: 1525197504.982984
/var/log/uftpd.log.1:2018/05/01 07:59:25.249176: [71715228/00:0]: REGISTER sent
/var/log/uftpd.log.1:2018/05/01 07:59:25.249213: [71715228/00:0]: send time: 1525197565.173064
/var/log/uftpd.log.1:2018/05/01 07:59:25.251625: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.262167: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.272799: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.283339: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.293827: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.304378: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.315024: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.326236: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.335937: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.346506: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.357163: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.367723: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.378396: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.388819: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.399463: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.410032: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.420558: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.431167: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.441696: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.452189: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.462859: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.474048: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.484069: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.494518: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.505114: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.515638: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.526357: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.536773: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.547372: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.557976: [71715228/00:0]: Expected REG_CONF, got FILESEG
/var/log/uftpd.log.1:2018/05/01 07:59:25.560515: [71715228/00:0]: Registration unconfirmed by server
/var/log/uftpd.log.1:2018/05/01 07:59:25.560797: [71715228/00:0]: Writing restart file
Logfile from server:
2018/05/01 13:58:48.726511: [71715228/00:0]: ----- uftp-test3and5-500MB.txt -----
2018/05/01 13:58:48.726553: [71715228/00:0001]: File ID: 0001 Name: uftp-test3and5-500MB.txt
2018/05/01 13:58:48.726564: [71715228/00:0001]: sending as: uftp-test3and5-500MB.txt
2018/05/01 13:58:48.726571: [71715228/00:0001]: Bytes: 503316480 Blocks: 387167 Sections: 38
2018/05/01 13:58:48.726583: [71715228/00:0001]: Sending FILEINFO 1.1
2018/05/01 13:58:48.819586: [71715228/00:0001]: Received FILEINFO_ACK from proxy rxa-multicast02
2018/05/01 13:58:48.819608: [71715228/00:0001]: For client 0x00016743
2018/05/01 13:58:48.893128: [71715228/00:0001]: Received FILEINFO_ACK from proxy rxa-multicast04
2018/05/01 13:58:48.893151: [71715228/00:0001]: For client 0x00003968
2018/05/01 13:58:48.894449: [71715228/00:0001]: Sending file
2018/05/01 13:58:48.894522: [71715228/00:0001]: Starting pass 1
2018/05/01 13:58:48.905221: [71715228/00:0001]: Sending section 0
2018/05/01 14:00:36.521356: [71715228/00:0001]: Sending section 1
2018/05/01 14:02:24.137571: [71715228/00:0001]: Sending section 2
2018/05/01 14:04:11.753801: [71715228/00:0001]: Sending section 3
2018/05/01 14:05:59.369997: [71715228/00:0001]: Sending section 4
2018/05/01 14:07:46.986214: [71715228/00:0001]: Sending section 5
2018/05/01 14:09:34.602443: [71715228/00:0001]: Sending section 6
2018/05/01 14:11:22.218647: [71715228/00:0001]: Sending section 7
2018/05/01 14:13:09.834869: [71715228/00:0001]: Sending section 8
2018/05/01 14:14:57.451093: [71715228/00:0001]: Sending section 9
2018/05/01 14:16:45.067315: [71715228/00:0001]: Sending section 10
2018/05/01 14:18:32.683531: [71715228/00:0001]: Sending section 11
2018/05/01 14:20:20.299738: [71715228/00:0001]: Sending section 12
2018/05/01 14:22:07.915972: [71715228/00:0001]: Sending section 13
2018/05/01 14:23:55.532175: [71715228/00:0001]: Sending section 14
2018/05/01 14:25:43.148405: [71715228/00:0001]: Sending section 15
2018/05/01 14:27:30.764621: [71715228/00:0001]: Sending section 16
2018/05/01 14:29:18.380844: [71715228/00:0001]: Sending section 17
2018/05/01 14:31:05.997056: [71715228/00:0001]: Sending section 18
2018/05/01 14:31:07.105195: [71715228/00:0001]: Got 562 NAKs for section 17 from proxy rxa-multicast04
2018/05/01 14:32:53.613275: [71715228/00:0001]: Sending section 19
2018/05/01 14:34:41.229500: [71715228/00:0001]: Sending section 20
2018/05/01 14:36:28.845712: [71715228/00:0001]: Sending section 21
2018/05/01 14:38:16.461929: [71715228/00:0001]: Sending section 22
2018/05/01 14:40:04.078108: [71715228/00:0001]: Sending section 23
2018/05/01 14:41:51.683793: [71715228/00:0001]: Sending section 24
2018/05/01 14:43:39.289470: [71715228/00:0001]: Sending section 25
2018/05/01 14:45:26.895115: [71715228/00:0001]: Sending section 26
2018/05/01 14:47:14.500777: [71715228/00:0001]: Sending section 27
2018/05/01 14:49:02.106435: [71715228/00:0001]: Sending section 28
2018/05/01 14:50:49.712086: [71715228/00:0001]: Sending section 29
2018/05/01 14:52:37.317740: [71715228/00:0001]: Sending section 30
2018/05/01 14:54:24.923401: [71715228/00:0001]: Sending section 31
2018/05/01 14:56:12.528981: [71715228/00:0001]: Sending section 32
2018/05/01 14:58:00.134710: [71715228/00:0001]: Sending section 33
2018/05/01 14:59:47.740364: [71715228/00:0001]: Sending section 34
2018/05/01 15:01:35.345983: [71715228/00:0001]: Sending section 35
2018/05/01 15:03:22.951660: [71715228/00:0001]: Sending section 36
2018/05/01 15:05:10.557331: [71715228/00:0001]: Sending section 37
2018/05/01 15:06:58.153262: [71715228/00:0001]: Sending DONE 1.1
2018/05/01 15:06:58.395995: [71715228/00:0001]: Got 562 NAKs for section 17 from proxy rxa-multicast04
2018/05/01 15:06:58.398534: [71715228/00:0001]: Sending DONE 2.1
2018/05/01 15:06:58.473228: [71715228/00:0001]: Starting pass 2
2018/05/01 15:06:58.489046: [71715228/00:0001]: Sending section 17
2018/05/01 15:07:04.350940: [71715228/00:0001]: Sending DONE 1.1
2018/05/01 15:07:04.519005: [71715228/00:0001]: Got COMPLETE from proxy rxa-multicast04
2018/05/01 15:07:04.519058: [71715228/00:0001]: For client 0x00003968
2018/05/01 15:07:04.596285: [71715228/00:0001]: Sending DONE 2.1
2018/05/01 15:07:04.841647: [71715228/00:0001]: Sending DONE 3.1
2018/05/01 15:07:05.087024: [71715228/00:0001]: Sending DONE 4.1
2018/05/01 15:07:05.332334: [71715228/00:0001]: Sending DONE 5.1
2018/05/01 15:07:05.577751: [71715228/00:0001]: Sending DONE 6.1
2018/05/01 15:07:05.823143: [71715228/00:0001]: Sending DONE 7.1
2018/05/01 15:07:06.068497: [71715228/00:0001]: Sending DONE 8.1
2018/05/01 15:07:06.313783: [71715228/00:0001]: Sending DONE 9.1
2018/05/01 15:07:06.559135: [71715228/00:0001]: Sending DONE 10.1
2018/05/01 15:07:06.804523: [71715228/00:0001]: Sending DONE 11.1
2018/05/01 15:07:07.049852: [71715228/00:0001]: Sending DONE 12.1
2018/05/01 15:07:07.295167: [71715228/00:0001]: Sending DONE 13.1
2018/05/01 15:07:07.540478: [71715228/00:0001]: Sending DONE 14.1
2018/05/01 15:07:07.785791: [71715228/00:0001]: Sending DONE 15.1
2018/05/01 15:07:08.031111: [71715228/00:0001]: Sending DONE 16.1
2018/05/01 15:07:08.276511: [71715228/00:0001]: Sending DONE 17.1
2018/05/01 15:07:08.521853: [71715228/00:0001]: Sending DONE 18.1
2018/05/01 15:07:08.767143: [71715228/00:0001]: Sending DONE 19.1
2018/05/01 15:07:09.012560: [71715228/00:0001]: Sending DONE 20.1
2018/05/01 15:07:09.033941: [71715228/00:0001]: Sending thread timed out
2018/05/01 15:07:09.040065: [71715228/00:0001]: No response from rxa-multicast02
2018/05/01 15:07:09.040123: [71715228/00:0001]: No response from rxa-multicast04
2018/05/01 15:07:09.040132: [71715228/00:0001]: No response from 0x00016743
2018/05/01 15:07:09.040154: [71715228/00:0001]: Transfer status:
2018/05/01 15:07:09.040164: [71715228/00:0001]: Host: 0x00001904 Status: Mute
2018/05/01 15:07:09.040174: [71715228/00:0001]: Host: 0x00016743 Status: Lost connection
2018/05/01 15:07:09.040184: [71715228/00:0001]: Host: 0x00003968 Status: Completed time: 4095.626 seconds
2018/05/01 15:07:09.040202: [71715228/00:0001]: Total elapsed time: 4095.626 seconds
2018/05/01 15:07:09.040211: [71715228/00:0001]: Overall throughput: 120.01 KB/s
2018/05/01 15:07:09.040276: [71715228/00:0]: -----------------------------
2018/05/01 15:07:09.040300: [71715228/00:0]: Finishing group
2018/05/01 15:07:09.040318: [71715228/00:0]: Sending DONE 1.1
2018/05/01 15:07:09.193548: [71715228/00:0]: Got COMPLETE from proxy rxa-multicast04
2018/05/01 15:07:09.193573: [71715228/00:0]: For client 0x00003968
2018/05/01 15:07:09.193583: [71715228/00:0]: Late completions:
2018/05/01 15:07:09.193593: [71715228/00:0]: Sending DONE_CONF 2.1
2018/05/01 15:07:09.270200: [71715228/00:0]: Group complete
Let me know if you need any clarification.
Thanks.
-Gene
Last edit: Gene A. 2018-05-01
Gene,
I attempted to recreate this issue with two clients and two reponse proxies but could not replicate the behavior you're seeing.
Can you post the logs of the proxies and clients at the time the proxies restart, as well during the announce phase of the server session?
Regards,
Dennis
Dennis,
Sorry for the delay, I have attached the logs you requested. I have trimmed them down a bit to reflect the time of the file send. Also, 2 of the clients are in different timzones incase you are wondering why there is a time disrepancy betweem client/server.
Thanks.
-Gene
Gene,
It looks like some of the proxies are having trouble receiving multicast traffic from the server.
The logs of proxy02 show no indication that it received the announcement from the server, so it never joined the session. Then when client 16743, which did get the announcement, sent its responses back to proxy02 the packets were ignored because the session was not known to the proxy.
The proxy05 logs show that it joined the group and that it forwarded the REGISTER and FILEINFO_ACK messages from client 1904, but it then showed a session timeout after about 5 minutes. This indicates that the proxy stopped receiving data from the server and dropped out of the session as a result.
You'll need to do some packet traces on the proxies to see whether or not packets from the server are arriving.
Regards,
Dennis