Bug 4440 - urpmi-proxy fail caching at some timeout - but file actually got through
Summary: urpmi-proxy fail caching at some timeout - but file actually got through
Status: ASSIGNED
Alias: None
Product: Mageia
Classification: Unclassified
Component: RPM Packages (show other bugs)
Version: Cauldron
Hardware: All Linux
Priority: Low normal
Target Milestone: ---
Assignee: AL13N
QA Contact:
URL:
Whiteboard: OK
Keywords: NEEDINFO
Depends on:
Blocks:
 
Reported: 2012-02-08 16:56 CET by Morgan Leijström
Modified: 2017-12-02 11:53 CET (History)
3 users (show)

See Also:
Source RPM: urpmi-proxy-0.2.4-3.mga2.src.rpm
CVE:
Status comment:


Attachments

Description Morgan Leijström 2012-02-08 16:56:05 CET
Description of problem:

Using network install it is very convenient to direct the installer to go through urpmi-proxy.

It would be great if it cached the installer that is initially fetched: <architecture>/install/stage2/*.sqfs

Steps to Reproduce:
Install mageia using boot.iso, and set it to use your urpmi-proxy, start.
Do it again or on another machine; file was not cached.

( I also tried to set installing client to use a caching proxy: squid, but it does not cache that file either, and i have not looked up on if that is possible, just set max size enough but that did not work.  Logically though i think it is better if urpmi-proxy caches this too )
Manuel Hiebel 2012-02-08 17:56:46 CET

Assignee: bugsquad => alien

Comment 1 AL13N 2012-02-08 20:12:42 CET
weird, urpmi-proxy does not discriminate for any files... if it's on mageia mirror, it should cache it, both distrib and iso directories...

what did you configure as source, and can you also post both log entries about that file? (i'm interested in their return status).

is it possible it just changed in the main time?

this is likely cauldron? if so, anyone know if there is something that rebuilds the installer files automagically?
AL13N 2012-02-08 20:13:55 CET

Keywords: (none) => NEEDINFO
Assignee: alien => bugsquad
Severity: enhancement => normal

Comment 2 Morgan Leijström 2012-02-08 22:39:21 CET
Thank you for the quick handling and reply!

It is good it shall cache all files already :)

I am trying an install on an old Thinkpad T40.
The partitionning part have a couple problems i also reported tonight, with the effect i had to reboot it *several* times, and i only get average 40 kBytes/s from my ISP. The rpms get cached, but downloading this sqfs always took a painfully long time.

__from urpmi-proxy.cfg:
$sources = [
        'ftp://ftp.acc.umu.se/mirror/mageia'
 ];

I see it caches the cauldron i586 rpms right now, and i also use it without any hassle at all for one x86_64 cauldron, and three mga1 x86_64 :)

Now, in the installer where it asked for mirrors i entered my urpmi-proxy IP, and  mageia/distrib/cauldron/i586

Also it seem to work the same if i go through squid or not - currently, this time i entered that as proxy to the installer. squid runs on same machine as urpmi-proxy.  I see both squid and urpmi-proxy is logging the requests right now.


___Below is a part of urpmi-proxy.log, first three install attempts: some files get cached, some not.

[Wed Feb  8 13:46:58 CET 2012] /distrib/cauldron/i586/install/stage2/mdkinst.sqfs - 200 - MISS_FAIL_SENT
[Wed Feb  8 13:47:07 CET 2012] /distrib/cauldron/i586/install/stage2/VERSION - 200 - MISS
[Wed Feb  8 13:47:08 CET 2012] /distrib/cauldron/i586/install/stage2/VERSION - 200 - CACHED_NO_CHECK
[Wed Feb  8 13:47:13 CET 2012] /distrib/cauldron/i586/install/patch-oem.pl - 404 - MISS_FAIL
[Wed Feb  8 13:47:17 CET 2012] /distrib/cauldron/i586/product.id - 200 - MISS
[Wed Feb  8 13:47:45 CET 2012] /distrib/cauldron/i586/release-notes.html - 200 - MISS
[Wed Feb  8 13:47:46 CET 2012] /distrib/cauldron/i586/release-notes.i686.html - 404 - MISS_FAIL
[Wed Feb  8 14:17:37 CET 2012] /distrib/cauldron/i586/install/stage2/mdkinst.sqfs - 200 - MISS_FAIL_SENT
[Wed Feb  8 14:17:41 CET 2012] /distrib/cauldron/i586/install/stage2/VERSION - 200 - CACHED_NO_CHECK
[Wed Feb  8 14:17:42 CET 2012] /distrib/cauldron/i586/install/stage2/VERSION - 200 - CACHED_NO_CHECK
[Wed Feb  8 14:17:49 CET 2012] /distrib/cauldron/i586/install/patch-oem.pl - 404 - MISS_FAIL
[Wed Feb  8 14:17:51 CET 2012] /distrib/cauldron/i586/product.id - 200 - CACHED_NO_CHECK
[Wed Feb  8 14:18:35 CET 2012] /distrib/cauldron/i586/release-notes.html - 200 - CACHED_NO_CHECK
[Wed Feb  8 14:18:37 CET 2012] /distrib/cauldron/i586/release-notes.i686.html - 404 - MISS_FAIL
[Wed Feb  8 14:51:08 CET 2012] /distrib/cauldron/i586/install/stage2/mdkinst.sqfs - 200 - MISS_FAIL_SENT
[Wed Feb  8 14:51:11 CET 2012] /distrib/cauldron/i586/install/stage2/VERSION - 200 - CACHED_NO_CHECK
[Wed Feb  8 14:51:12 CET 2012] /distrib/cauldron/i586/install/stage2/VERSION - 200 - CACHED_NO_CHECK
[Wed Feb  8 14:51:17 CET 2012] /distrib/cauldron/i586/install/patch-oem.pl - 404 - MISS_FAIL
[Wed Feb  8 14:51:18 CET 2012] /distrib/cauldron/i586/product.id - 200 - CACHED_NO_CHECK
[Wed Feb  8 14:54:20 CET 2012] /distrib/cauldron/i586/release-notes.html - 200 - CACHED_NO_CHECK
[Wed Feb  8 14:54:24 CET 2012] /distrib/cauldron/i586/release-notes.i686.html - 404 - MISS_FAIL
Comment 3 Manuel Hiebel 2012-02-09 15:16:25 CET
(added again alien)

Keywords: NEEDINFO => (none)
Assignee: bugsquad => alien

Comment 4 AL13N 2012-02-09 21:13:35 CET
the log looks odd...

CACHED obviously means that it's cached (no_check, because it didn't check for update)
MISS obviously means that it's not cached.

the MISS_FAIL are all normal, due to their return code 404 <-- doesn't exist.

the biggest puzzle is the sqfs file: MISS_FAIL_SENT

the _SENT means that even though it failed, something was sent... but then there was a 200 return code...

did it fail to cache it? or did the original returned only a partial result?

Dit the installer actually work?

can you try one more thing?

try setting the $debug = 1;

then give me the apache log ( /var/log/httpd/error_log , iinm) relevant part about mdkinst.sqfs .

also, i'm sure you checked the write permissions of the apache user on the paths specified in the config file? and if your disk is becoming full?

Keywords: (none) => NEEDINFO
CC: (none) => alien
Assignee: alien => bugsquad

Comment 5 Morgan Leijström 2012-02-10 01:34:46 CET
So it thinks it failed, then sent anyway?
maybe did not cache because it thinks it did not get it?

Yes the installer worked, with exception for a bug or two i reported.
I also had many missing packages, timeouts, but i blame that on my lousy internet connection, and possibly changes in repo.  Same urpmi-proxy serve our three mga1 production machines perfectly, and a second boot cauldroon x86_64. This is however first time i use only internet and try to pull everything through urpmi-proxy.

The installer always took ages to load the sqfs (not to mention several hours for the bulk install first time)

Do you think there may be some issue with apache default setup, so it hinders certain files...? Do you want some config file maybe?

I will try installing the same on two other semi-old computers next week or so, and check, set, and report as you wish.


Please bug me if i do not report back in 2 weeks!
Comment 6 AL13N 2012-02-10 12:50:54 CET
the MISS_FAIL_SENT is a state that happens due to how urpmi-proxy works:

it proxies a file, but it tries to store the file locally at the same time it passes through.

this state happens when the file is being passed through (so something has been sent), but some kind of error happens wrt storing the file locally, or if the remote connection was interrupted suddenly.

since it doesn't wait for it to store, but already sends some info to the client even while it still is getting it from upstream.

so, normally, i would report that this failed, but since there's already data passed to the client, i can't just change and say that it has failed after all.

in this case i don't store the file, so that next time it can retry.

if you get the debug info, we can see more what happened. i don't think you have to completely retry installing though.

you can just try to fetch the file from your urpmi-proxy manually... this should give the same results.
Comment 7 Morgan Leijström 2012-02-12 00:08:30 CET
This is weird.
Without touching anything at all @ server, at this my mga1 workstation:

$ wget http://192.168.0.12/mageia/distrib/cauldron/i586/install/stage2/mdkinst.sqfs

And bang server retrieved it from cache @ 40MB/s; urpmi-proxy log say for the .sqfs: 200 - CACHED_NO_CHECK

So it was already cached OK now!
Searching the log i see it cached the file Thursday 01:37 : result 200 - MISS on that file.  Apparently i did a new try then, but forgot to check log that time.

So I booted the same laptop i was installing on before, on same boot.iso image as before, and it works perfectly there too, both when setting it to go through my squid proxy, and not.

Strange it missed but delivered three times, and a half day later suceeded.

What varies much however is the quality of my connection, it can go down both because mu lousy router reboot, ISP change IP, or it simply rain a lot.  Tha tree times it failed was during a period with unusually lousy connection.
Maybe there is some timeout that triggers?

I got an idea and searched the log for MISS_FAIL_SENT, and sure enough there are some packages that was retrieved during that period that also show that status!  And they are all also big packages; java openjdk, kde workspace, digikam, extremetuxracer, and a few more.

So:
I believe we have a timeout problem.

And that *.sqfs is not special.

I turn on debug and check later if i see MISS_FAIL_SENT again in the log.
Comment 8 AL13N 2012-02-12 09:03:44 CET
There are several configurable timeouts related to this.

however, since all packages have md5sum 's, if it is MISS_FAIL_SENT, the application requesting it, will likely give an error on the md5sum and possibly retry?

thinking on it, i have no idea if the sqfs file has a md5sum wrt network install...

so, what i think that happened. is that due to lousy connection, maybe even with timeouts, the original is being fetched, but has errors along the way. sadly I have no idea how the sqfs errors are being handled...

with packages, it _is_ being handled though
Comment 9 Morgan Leijström 2012-02-12 11:00:28 CET
I put a checksum question in my bug https://bugs.mageia.org/show_bug.cgi?id=4449 that is about problems with the install when i *.sqfs retrieval was strange.

In urpmi-proxy.conf i have set
$debug = 1;

But i see no more output than usual on the log.
Is debug output somewhere else?
Comment 10 AL13N 2012-02-12 21:47:44 CET
yes, the debug stuff is in the apache error logs
Comment 11 Morgan Leijström 2012-02-14 01:07:05 CET
Timeout.

And yes that MISS_FAIL_SENT was only one time in the log, and file got installed OK

Tieout seem ony to have made it not getting cached, but a complete file was sent to client...


____Line in urpmi-proxy.log:

[Sun Feb 12 12:52:29 CET 2012] /distrib/cauldron/x86_64/media/core/release/libreoffice-core-3.5.0.3-3.mga2.x86_64.rpm - 200 - MISS_FAIL_SENT

____Corresponding part of /var/log/httpd/error_log:

[Sun Feb 12 12:35:35 2012] [error] [client 192.168.0.155]  - ftp://ftp.acc.umu.se/mirror/mageia
[Sun Feb 12 12:35:35 2012] [error] [client 192.168.0.155] file: /distrib/cauldron/x86_64/media/core/release/libreoffice-core-3.5.0.3-3.mga2.x86_64.rpm
[Sun Feb 12 12:35:35 2012] [error] [client 192.168.0.155] dest_path: /distrib/cauldron/x86_64/media/core/release
[Sun Feb 12 12:35:35 2012] [error] [client 192.168.0.155] filename: libreoffice-core-3.5.0.3-3.mga2.x86_64.rpm
[Sun Feb 12 12:35:35 2012] [error] [client 192.168.0.155] check_file: 0
[Sun Feb 12 12:35:35 2012] [error] [client 192.168.0.155] merge: 0
[Sun Feb 12 12:35:35 2012] [error] [client 192.168.0.155] sources: 1
[Sun Feb 12 12:35:35 2012] [error] [client 192.168.0.155]  - ftp://ftp.acc.umu.se/mirror/mageia
[Sun Feb 12 12:35:35 2012] [error] [client 192.168.0.155] interpolated sources: 1
[Sun Feb 12 12:35:35 2012] [error] [client 192.168.0.155]  - ftp://ftp.acc.umu.se/mirror/mageia
[Sun Feb 12 12:35:35 2012] [error] [client 192.168.0.155] source of type ftp: 'ftp://ftp.acc.umu.se/mirror/mageia'
[Sun Feb 12 12:35:35 2012] [error] [client 192.168.0.155] curl fetch url 'ftp://ftp.acc.umu.se/mirror/mageia/distrib/cauldron/x86_64/media/core/release/libreoffice-core-3.5.0.3-3.mga2.x86_64.rpm'
[Sun Feb 12 12:35:38 2012] [error] [client 192.168.0.155] Content-Type: 
[Sun Feb 12 12:35:38 2012] [error] [client 192.168.0.155] Content-Length: 65604532
[Sun Feb 12 12:52:29 2012] [error] [client 192.168.0.155] curl return value: 200
[Sun Feb 12 12:52:29 2012] [error] [client 192.168.0.155] transfer error: Timeout was reached (28)
[Sun Feb 12 12:52:29 2012] [error] [client 192.168.0.155] logfile: /var/log/urpmi-proxy.log
[Sun Feb 12 12:52:29 2012] [error] [client 192.168.0.155] orig sources: 1
Comment 12 Morgan Leijström 2012-02-14 01:25:08 CET
I meant to say that *the file* that got result MISS_FAIL_SENT was only one time in the log.
Morgan Leijström 2012-02-14 01:29:19 CET

Summary: urpmi-proxy better cache <architecture>/install/stage2/*.sqfs too => urpmi-proxy fail caching at some timeout - but file actually got through

Comment 13 AL13N 2012-02-14 13:41:47 CET
hmm, maybe it's the way FTP's connections are different rather than http timeouts...

I would advise you to use HTTP mirrors, since those can be done more efficiently.

still strange that the original file was complete, even though there was a timeout reached...
Comment 14 Morgan Leijström 2012-02-14 22:48:21 CET
OK, I switch to HTTP mirror now and report back later.

Excerpt from my last post:
12:52:29 curl return value: 200
12:52:29 transfer error: Timeout was reached (28)

Same time;  so it thinks it timed out efter it got the file OK?
Comment 15 Morgan Leijström 2012-02-15 00:01:16 CET
Right: it works correctly when using http on that same mirror.

I first tried a big file and got 200 - MISS_FAIL_SENT, and in apache error_log "Timeout was reached (28)"  And yes that rpm installed OK.

Then changed mirror in urpmi-poxy.conf to http:// and restarted httpd
Same file now got 200 - MISS, and on next attempt it was read from cache.

(I know i should test more large files, and maybe time them, but must sleep now and i will report if i see it again of course )
Comment 16 AL13N 2012-02-15 12:00:47 CET
it's possible timeouts aren't correctly done in ftp transfers, i'll need to investigate in that area.

i'm assigning it to myself

Keywords: NEEDINFO => (none)
Priority: Normal => Low
Status: NEW => ASSIGNED
Assignee: bugsquad => alien

Comment 17 Morgan Leijström 2012-02-18 15:21:24 CET
FTP still seem to work perfectly,no more MISS_FAIL_SENT in log,except for
the strange result code: 404 - MISS_FAIL_SENT

[Sat Feb 18 15:08:17 CET 2012] /distrib/1/x86_64/media/nonfree/updates/media_info/descriptions - 404 - MISS_FAIL_SENT

(and exactly happens for the same URI for i586)

[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40] orig sources: 1
[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40]  - http://ftp.acc.umu.se/mirror/mageia
[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40] file: /distrib/1/x86_64/media/nonfree/updates/media_info/descriptions
[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40] dest_path: /distrib/1/x86_64/media/nonfree/updates/media_info
[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40] filename: descriptions
[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40] check_file: 0
[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40] merge: 0
[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40] sources: 1
[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40]  - http://ftp.acc.umu.se/mirror/mageia
[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40] interpolated sources: 1
[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40]  - http://ftp.acc.umu.se/mirror/mageia
[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40] source of type http: 'http://ftp.acc.umu.se/mirror/mageia'
[Sat Feb 18 15:08:16 2012] [error] [client 192.168.0.40] curl fetch url 'http://ftp.acc.umu.se/mirror/mageia/distrib/1/x86_64/media/nonfree/updates/media_info/descriptions'
[Sat Feb 18 15:08:17 2012] [error] [client 192.168.0.40] HTTP header: 404 Not Found
[Sat Feb 18 15:08:17 2012] [error] [client 192.168.0.40] Content-Type: text/html; charset=iso-8859-1
[Sat Feb 18 15:08:17 2012] [error] [client 192.168.0.40] Content-Length: 392
[Sat Feb 18 15:08:17 2012] [error] [client 192.168.0.40] curl return value: 200
[Sat Feb 18 15:08:17 2012] [error] [client 192.168.0.40] transfer error: http code 404
[Sat Feb 18 15:08:17 2012] [error] [client 192.168.0.40] logfile: /var/log/urpmi-proxy.log
Comment 18 AL13N 2012-02-18 18:17:46 CET
that's completely normal.

you request something, you get a 404 back, with headers and a "custom error page".

so, you have a 404 (fail), but you did get something (and error page) so it's _SENT

the file simply does not exist still...

it'd be nice for this file to exist really, cause that's what should give the advisories and stuff...
Comment 19 Marja Van Waes 2012-05-26 13:09:33 CEST
Hi,

This bug was filed against cauldron, but we do not have cauldron at the moment.

Please report whether this bug is still valid for Mageia 2.

Thanks :)

Cheers,
marja

Keywords: (none) => NEEDINFO

Comment 20 AL13N 2012-10-01 22:51:45 CEST
just replying to myself: to see what this is about:

-----
it's possible timeouts aren't correctly done in ftp transfers, i'll need to
investigate in that area.
AL13N 2012-10-01 22:52:01 CEST

Keywords: NEEDINFO => (none)
Whiteboard: (none) => OK

Comment 21 Morgan Leijström 2014-11-18 15:18:26 CET
Just keeping bug alive: I have not experienced any problems from this I think since last post but I have set it up as adviced above so that works.
Now on urpmi-proxy-0.4.0-4.mga5 through updates.
Comment 22 Marja Van Waes 2017-08-02 23:29:00 CEST
(In reply to Morgan Leijström from comment #21)
> Just keeping bug alive: I have not experienced any problems from this I
> think since last post but I have set it up as adviced above so that works.
> Now on urpmi-proxy-0.4.0-4.mga5 through updates.

Almost 3 years later..... is this bug still valid?

CC: (none) => marja11
Keywords: (none) => NEEDINFO

Comment 23 Morgan Leijström 2017-08-03 06:45:40 CEST
I do not know...
I have not seen any issue since last time, but i also have not touched configuration and server was still mga5, updated when i took the machine down for rebuild a month ago.

I currently do not use urpmi-proxy but plan to have it again

In short, when configured with http mirror this bug is not seen, but I also have not tested with ftp mirror for years.
Comment 24 Marja Van Waes 2017-12-02 11:53:30 CET
(In reply to Morgan Leijström from comment #23)
> I do not know...
> I have not seen any issue since last time, but i also have not touched
> configuration and server was still mga5, updated when i took the machine
> down for rebuild a month ago.
> 
> I currently do not use urpmi-proxy but plan to have it again
> 
> In short, when configured with http mirror this bug is not seen, but I also
> have not tested with ftp mirror for years.

Closing as OLD, then.

Please reopen if you hit the issue again.

CC: (none) => mageiatools


Note You need to log in before you can comment on or make changes to this bug.