ftp upload problem; Errno 0 Error; ftplib problem?

[Kip Kennedy]

Hi,

I'm having trouble getting ftp uploads to work.  I'm using Weewx 3.7.1 on a Raspberry Pi and uploading to a GoDaddy host.  I can connect and upload fine interactively (MacOS ftp, Windows WinSCP). I've also double checked my settings in weewx.conf. Here is syslog during the ftp:


Oct 26 13:08:57 PiWeather wee_reports[15450]: reportengine: Running report FTP
Oct 26 13:08:57 PiWeather wee_reports[15450]: reportengine: Found configuration file /etc/weewx/skins/Ftp/skin.conf for report FTP
Oct 26 13:08:57 PiWeather wee_reports[15450]: ftpupload: Attempting secure connection to ftp.xxx.com
Oct 26 13:08:57 PiWeather wee_reports[15450]: ftpupload: Secure connection to ftp.xxx.com
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Attempt #1. Failed uploading /daywind.png to ftp.xxx.com. Reason: [Errno 0] Error
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Attempt #2. Failed uploading /daywind.png to ftp.xxx.com. Reason:
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Attempt #3. Failed uploading /daywind.png to ftp.xxx.com. Reason:
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Failed to upload file /daywind.png
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Attempt #1. Failed uploading /daytemp.png to ftp.xxx.com. Reason:
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Attempt #2. Failed uploading /daytemp.png to ftp.xxx.com. Reason:
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Attempt #3. Failed uploading /daytemp.png to ftp.xxx.com. Reason:
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Failed to upload file /daytemp.png
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Attempt #1. Failed uploading /index.html to ftp.xxx.com. Reason:
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Attempt #2. Failed uploading /index.html to ftp.xxx.com. Reason:
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Attempt #3. Failed uploading /index.html to ftp.xxx.com. Reason:
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Failed to upload file /index.html
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Attempt #1. Failed uploading /dayrain.png to ftp.xxx.com. Reason:
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Attempt #2. Failed uploading /dayrain.png to ftp.xxx.com. Reason: [Errno 32] Broken pipe
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Attempt #3. Failed uploading /dayrain.png to ftp.xxx.com. Reason: [Errno 32] Broken pipe
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpupload: Failed to upload file /dayrain.png
Oct 26 13:08:58 PiWeather wee_reports[15450]: ftpgenerator: ftp'd 0 files in 1.75 seconds


I also turned on extra logging for ftp (debug = 2 in [[Ftp]] in weewx.conf) and got the following on stdout when I ran wee_reports. It looks like the STOR is started before the TYPE I? Maybe a race condition? In ftplib.py, the storbinary routine should handle the TYPE I before the transfer but the log shows the TYPE I issue after the STOR. Maybe just a logging race?


Generating for all time
*cmd* 'AUTH TLS'
*put* 'AUTH TLS\r\n'
*get* '234 AUTH TLS OK.\r\n'
*resp* '234 AUTH TLS OK.'
*cmd* 'USER x...@xxx.com'
*put* 'USER x...@xxx.com\r\n'
*get* '331 User x...@xxx.com OK. Password required\r\n'
*resp* '331 User x...@xxx.com OK. Password required'
*cmd* 'PASS ***************'
*put* 'PASS ***************\r\n'
*get* '230-Your bandwidth usage is restricted\r\n'
*get* '230-OK. Current restricted directory is /\r\n'
*get* '230 0 Kbytes used (0%) - authorized: 204800 Kb\r\n'
*resp* '230-Your bandwidth usage is restricted\n230-OK. Current restricted directory is /\n230 0 Kbytes used (0%) - authorized: 204800 Kb'
*cmd* 'PBSZ 0'
*put* 'PBSZ 0\r\n'
*get* '200 PBSZ=0\r\n'
*resp* '200 PBSZ=0'
*cmd* 'PROT P'
*put* 'PROT P\r\n'
*get* '200 Data protection level set to "private"\r\n'
*resp* '200 Data protection level set to "private"'
*cmd* 'MKD /'
*put* 'MKD /\r\n'
*get* "550-Can't create directory: File exists\r\n"
*get* '550 0 Kbytes used (0%) - authorized: 204800 Kb\r\n'
*resp* "550-Can't create directory: File exists\n550 0 Kbytes used (0%) - authorized: 204800 Kb"
*cmd* 'TYPE I'
*put* 'TYPE I\r\n'
*get* '200 TYPE is now 8-bit binary\r\n'
*resp* '200 TYPE is now 8-bit binary'
*cmd* 'PASV'
*put* 'PASV\r\n'
*get* '227 Entering Passive Mode (107,180,40,150,197,84)\r\n'
*resp* '227 Entering Passive Mode (107,180,40,150,197,84)'
*cmd* 'STOR /daywind.png'
*put* 'STOR /daywind.png\r\n'
*get* '150 Accepted data connection\r\n'
*resp* '150 Accepted data connection'
*cmd* 'TYPE I'
*put* 'TYPE I\r\n'
*get* ''
*cmd* 'TYPE I'
*put* 'TYPE I\r\n'
*get* ''
*cmd* 'TYPE I'
*put* 'TYPE I\r\n'
*get* ''
*cmd* 'TYPE I'
*put* 'TYPE I\r\n'
*get* ''
*cmd* 'TYPE I'
*put* 'TYPE I\r\n'
*get* ''
*cmd* 'TYPE I'
*put* 'TYPE I\r\n'
*get* ''
*cmd* 'TYPE I'
*put* 'TYPE I\r\n'
*get* ''
*cmd* 'TYPE I'
*put* 'TYPE I\r\n'
*get* ''
*cmd* 'TYPE I'
*put* 'TYPE I\r\n'
*get* ''
*cmd* 'TYPE I'
*put* 'TYPE I\r\n'
*cmd* 'TYPE I'
*put* 'TYPE I\r\n'
*cmd* 'QUIT'
*put* 'QUIT\r\n'

[Thomas Keffer]

Hi, Kip

I also use GoDaddy. What it normally does is before every file it sets TYPE I and PASV, then does the file transfer, all synchronously. So, I don't think it's a race condition within either FTP, or the log. 

Did this work before and now it's not? Or, has it never worked?

The PROT_P command suggests that you're trying to use FTPS (option secure_FTP=True). Have you tried just regular FTP?

Take a look in the HTML directory (probably /var/www/html/weewx) and see if all looks normal. Are the file sizes zero? 

It's a Hail Mary, but you can try deleting the file #FTP.last in that subdirectory. This file holds the last time a file was uploaded, so deleting it will force all files to be uploaded. 

-tk

--
You received this message because you are subscribed to the Google Groups "weewx-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Kip Kennedy]

Thanks for the quick response Tom. I just tried regular FTP and it works fine. So something amiss with FTPS? Maybe just a problem with PROT_P (encrypted data)? I only really care about AUTH_TLS (encrypted login).  Maybe I will delve into the ftplib.py source and give it a try, I don't want plain text logins with write access flying around.

To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+...@googlegroups.com.

[Thomas Keffer]

Couple of questions:

Do you know what kind of server you're using on the other end? One of my FTP accounts has a Microsoft server and it doesn't handle FTPS very well.

You mentioned you can get FTP to work with the Mac FTP and with WinSCP. Do these use FTPS?

-tk

To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+unsubscribe@googlegroups.com.

[Kip Kennedy]

The FTP server at GoDaddy is Pure-FTPd.

WinSCP can use FTPS. I chose explicit TLS and was able to connect and upload a file.  In the resulting log I see AUTH TLS and PROT P being enabled before the transfer. So, I'm not sure Pure-FTPd is at fault (at least when used with WinSCP).

[Thomas Keffer]

OK, you've got me stumped.

If you're comfortable around source code, perhaps you could instrument the ftplib code and see what's going on.

-tk

To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+unsubscribe@googlegroups.com.

[Kip Kennedy]

It looks like others are seeing this Errno 0 problem in ftplib with TLS:

https://bugs.python.org/issue31727
https://bugs.python.org/issue25278

It could be caused by the server enforcing session reuse which isn't supported yet:

https://bugs.python.org/issue19500

In any case, I found that if I skip enabling data encryption the ftp works with just control encryption.  That is, just AUTH TLS but no PROT P.  I commented out line 103 in ftpupload.py:

if self.secure:
     #ftp_server.prot_p()

At least the login won't be sent in the clear with this change.  Maybe we could have a new option in weewx.conf that enables data security separately?

[Thomas Keffer]

I suspect you're right. Good sleuthing!

This is difficult to debug, because I need a broken server/client connection, and mine is working fine!

Created issue #284 to track this problem.

-tk

To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+unsubscribe@googlegroups.com.

[Thomas Keffer]

Fixed (I think) in commit ae7c2fb.

Download the patched file ftpupload.py and give it a try. You can now set whether to use a secure FTP data connection separately from the authentication. By default, it is True, but you can set it to False:

[[FTP]]

...

secure_ftp = True

secure_data = False

Should appear in V3.8.0, due RSN.

-tk

[Kip Kennedy]

This works great!  I get the expected Error 0 with secure_data=True but everything works fine with secure_data=False.  Thanks Tom!