#1063 Race condition in ftp::Get -variable

[Schelte Bron]

While using the METAR package by Jos Decoster (http://wiki.tcl.tk/19635) I frequently get an error from the ftp package:

can't read "ftp(GetData)": no such element in array
while executing
"set returnData $ftp(GetData)"
(procedure "::ftp::StateHandler" line 778)
invoked from within
"::ftp::StateHandler 0 sock19"
Error in plug-in weather:
can't read "ftp(GetData)": no such element in array
while executing
"set returnData $ftp(GetData)"
(procedure "::ftp::StateHandler" line 778)
invoked from within
"::ftp::StateHandler 0 sock19"

Investigation shows that this appears to be caused by a race condition between the data and control socket. The error shows up when the control event handler sees the "226 File send OK" report before the event handler on the data socket fires and processes the incoming file contents.

Here's the log with VERBOSE and DEBUG on:

debug | Starting new connection with:
debug | no option
debug control | C: Connection from 140.90.128.71:21
debug | -> rc="220"
-> msgtext="220 Authorized users only. All activity may be monitored and reported."
-> state="user"
debug | ---> USER anonymous
debug control | C: 220 Authorized users only. All activity may be monitored and reported.
debug | -> rc="331"
-> msgtext="331 Please specify the password."
-> state="passwd"
debug | ---> PASS anonymous
debug control | C: 331 Please specify the password.
debug | -> rc="230"
-> msgtext="230 Login successful."
-> state="connect"
debug control | C: 230 Login successful.
debug | -> rc=" "
-> msgtext=""
-> state="type"
debug | ---> TYPE I
debug | -> rc="200"
-> msgtext="200 Switching to Binary mode."
-> state="type_sent"
debug control | C: 200 Switching to Binary mode.
debug | -> rc=" "
-> msgtext=""
-> state="cd"
debug | ---> CWD data/observations/metar/stations
debug | -> rc="250"
-> msgtext="250 Directory successfully changed."
-> state="cd_sent"
debug control | C: 250 Directory successfully changed.
debug | -> rc=" "
-> msgtext=""
-> state="get_active"
debug data | D: Port is 33870
debug | ---> PORT 192,168,1,2,132,78
debug | -> rc="200"
-> msgtext="200 PORT command successful. Consider using PASV."
-> state="get_open"
debug | ---> RETR EHAM.TXT
debug control | C: 200 PORT command successful. Consider using PASV.
debug | -> rc="150"
-> msgtext="150 Opening BINARY mode data connection for EHAM.TXT (62 bytes)."
-> state="get_sent"
debug control | C: 150 Opening BINARY mode data connection for EHAM.TXT (62 bytes).
debug | -> rc="226"
-> msgtext="226 File send OK."
-> state="get_close"
debug data | D: Connection from 140.90.128.71:20
debug data | D: Port closed

I guess the error will only show up for small files. On larger files I can imagine that the last part of the file may be missing, but I haven't actually seen that happen.

I haven't yet come up with a solution for this problem. I fear it's not going to be straight forward. Temporarily removing the fileevent from the control socket may be a possibility.

[Schelte Bron]

Logged In: YES
user_id=37987
Originator: YES

Another race condition happened after switching to passive mode in an attempt to avoid the problem mentioned here. In that case the ftp package frequently throws an uncatchable error if the file does not exist:

can't read "ftp(Start_Time)": no such variable
while executing
"if {$ftp(Start_Time) == -1} {
set ftp(Start_Time) [clock seconds]
}"
(procedure "::ftp::HandleVar" line 5)
invoked from within
"::ftp::HandleVar 0 sock24"

This happens when the control connection is closed, which cleans up the ftp array, before the data connection is closed. Then when the event handler for the data connection fires due to an eof situation it tries to access ftp(Start_Time), which no longer exists.

It looks like some kind of mechanism is needed that can wait for certain events on the data connection before proceeding.