1130395 - final verify timestamps are confusing

Status: NEW

(Release Engineering :: Release Automation: Updates, defect, P5)

Description

[[e-mail] (:bhearsum)]

Rail noticed that the timestamps on output like the following is the _print_ time, not the time of the actual operation. Eg, all of the curl output happened much earlier in the script:

Fri Feb  6 02:28:28 PST 2015:  FAILURE 10: Update xml file not available
Fri Feb  6 02:28:28 PST 2015:  
Fri Feb  6 02:28:28 PST 2015:      Download url: https://aus4.mozilla.org/update/3/Firefox/33.0/20140911191954/Linux_x86-gcc3/es-CL/beta-cdntest/default/default/default/update.xml?force=1
Fri Feb  6 02:28:28 PST 2015:      Curl returned exit code: 56
Fri Feb  6 02:28:28 PST 2015:  
Fri Feb  6 02:28:28 PST 2015:      The HTTP headers were:
Fri Feb  6 02:28:28 PST 2015:  
Fri Feb  6 02:28:28 PST 2015:      The full curl debug output was:
Fri Feb  6 02:28:28 PST 2015:          * About to connect() to aus4.mozilla.org port 443 (#0)
Fri Feb  6 02:28:28 PST 2015:          *   Trying 63.245.217.219... connected
Fri Feb  6 02:28:28 PST 2015:          * Connected to aus4.mozilla.org (63.245.217.219) port 443 (#0)
Fri Feb  6 02:28:28 PST 2015:          * Initializing NSS with certpath: sql:/etc/pki/nssdb
Fri Feb  6 02:28:28 PST 2015:          * warning: ignoring value of ssl.verifyhost
Fri Feb  6 02:28:28 PST 2015:          * skipping SSL peer certificate verification
Fri Feb  6 02:28:28 PST 2015:          * SSL connection using TLS_DHE_RSA_WITH_AES_128_CBC_SHA
Fri Feb  6 02:28:28 PST 2015:          * Server certificate:
Fri Feb  6 02:28:28 PST 2015:          * 	subject: CN=aus4.mozilla.org,O=Mozilla Foundation,L=Mountain View,ST=CA,C=US
Fri Feb  6 02:28:28 PST 2015:          * 	start date: Sep 23 00:00:00 2013 GMT
Fri Feb  6 02:28:28 PST 2015:          * 	expire date: Sep 27 12:00:00 2016 GMT
Fri Feb  6 02:28:28 PST 2015:          * 	common name: aus4.mozilla.org
Fri Feb  6 02:28:28 PST 2015:          * 	issuer: CN=DigiCert Secure Server CA,O=DigiCert Inc,C=US
Fri Feb  6 02:28:28 PST 2015:          > GET /update/3/Firefox/33.0/20140911191954/Linux_x86-gcc3/es-CL/beta-cdntest/default/default/default/update.xml?force=1 HTTP/1.1
Fri Feb  6 02:28:28 PST 2015:          > User-Agent: curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.14.0.0 zlib/1.2.3 libidn/1.18 libssh2/1.4.2
Fri Feb  6 02:28:28 PST 2015:          > Host: aus4.mozilla.org
Fri Feb  6 02:28:28 PST 2015:          > Accept: */*
Fri Feb  6 02:28:28 PST 2015:          > 
Fri Feb  6 02:28:28 PST 2015:          * SSL connection receive timeout
Fri Feb  6 02:28:28 PST 2015:          * Closing connection #0


And this one:

Fri Feb  6 02:28:27 PST 2015:  ====================================
Fri Feb  6 02:28:27 PST 2015:  
Fri Feb  6 02:28:27 PST 2015:  FAILURE 6: Update xml file not available
Fri Feb  6 02:28:27 PST 2015:  
Fri Feb  6 02:28:27 PST 2015:      Download url: https://aus4.mozilla.org/update/3/Firefox/32.0/20140814150857/Linux_x86_64-gcc3/rm/beta-cdntest/default/default/default/update.xml?force=1
Fri Feb  6 02:28:27 PST 2015:      Curl returned exit code: 35
Fri Feb  6 02:28:27 PST 2015:  
Fri Feb  6 02:28:27 PST 2015:      The HTTP headers were:
Fri Feb  6 02:28:27 PST 2015:  
Fri Feb  6 02:28:27 PST 2015:      The full curl debug output was:
Fri Feb  6 02:28:27 PST 2015:          * About to connect() to aus4.mozilla.org port 443 (#0)
Fri Feb  6 02:28:27 PST 2015:          *   Trying 63.245.217.219... connected
Fri Feb  6 02:28:27 PST 2015:          * Connected to aus4.mozilla.org (63.245.217.219) port 443 (#0)
Fri Feb  6 02:28:27 PST 2015:          * Initializing NSS with certpath: sql:/etc/pki/nssdb
Fri Feb  6 02:28:27 PST 2015:          * warning: ignoring value of ssl.verifyhost
Fri Feb  6 02:28:27 PST 2015:          * NSS error -5990
Fri Feb  6 02:28:27 PST 2015:          * Closing connection #0
Fri Feb  6 02:28:27 PST 2015:          * SSL connect error



If it's not possible to print the real timestamps for those operations we should print no timestamp at all to avoid confusion IMO.