Combating client timeout error -1001

[Michal Moravec]

Hi. Our Munki setup looks like this:

Webserver hosting Munki repo:

• VM with Ubuntu 14.04.3 LTS
  
• Apache 2.4.7 (munki is a virtual host, reposado is another virtual host)
  
• FQDN -> Accessible over internet
• HTTPS only (TLS 1.0+) with HTTP Basic auth. TLS 1.0 is there for 10.8 clients. 
  
• Munki repo is located on small system SSD but pkgs dir is symlinked to slower 1TB mounted volume.

Clients at Site 1

• Different location than server. They talk to Munki repo over internet
  
• MacBook Airs are connected to wi-fi

Most of the time everything is working correctly but sometimes clients fails to download some bigger file (typically bigger .dmg, .pkg or reposado .sucatalog).

Downloading InstallOSX_10.11.1_15B42-10.11.1.dmg...
0. Download error -1001: The request timed out.
Headers: {u'Content-Length': u'6171214406', u'Accept-Ranges': u'bytes', u'Keep-Alive': u'timeout=5, max=94', u'Server': u'Apache/2.4.7 (Ubuntu)', u'Last-Modified': u'Fri, 30 Oct 2015 12:56:39 GMT', u'Connection': u'Keep-Alive', u'Etag': u'"16fd54246-52351f5570fc0"', u'Date': u'Wed, 25 Nov 2015 15:27:10 GMT', u'Content-Type': u'application/x-apple-diskimage'}
WARNING: Download of InstallOSXElcap failed: Error -1001: The request timed out.

On next Munki run download of "timeouted" file resumes exactly where it ended. 

-> This problem is not big issue for managed installs since client downloads (resumes download of) file on next Munki run so it gets download and installed eventually.

With optional installs it is different story. For example user can initiate download of OS X installer dmg. If download of this ~7GB file fails Manages Software Center shows it as unavailable. This creates confustion.

Similiar problem can happen when computer goes to sleep during download (I believe I read Greg's post about power assertions not beeing present during downloads).

In this case -1001 The request Timed out is followed by -1009 The Internet connection appers to be offline. 

However I've seen multiple times -1001 alone without computer going to sleep (set to never) and wi-fi connection looked solid.

When I tried to replicate this problem from another location in OS X VMware VM I sometimes get -1005 “The network connection was lost.” when dowloading bigger files

-1005 happnes exclusively in VM.

Debugging so far:

• It appears to be happening at random -> I am unable to reproduce it with with set of steps.
  
• We set Apache logging to debug. There is nothing in error log higher than info. Info and debug messages doen't tell us anything is out of order. Access log shows only GET 200 OK for start of download.
• So far I haven't encounter this problem when dowloading file in Safari

Do you have any ideas how could I pinpoint the problem?

Edit: btw is munki-discuss proper place to ask this question or should this be moved to munki-dev instead?

Edit2: This looks similiar to https://groups.google.com/forum/#!msg/munki-dev/2snLJz6jnC0/KssxR34y75UJ , https://groups.google.com/forum/#!topic/munki-dev/2snLJz6jnC0 or https://groups.google.com/forum/#!topic/munki-dev/I6-58VOJHoU 

[Clayton Burlison]

Hi Michal,

Firstly, munki-discuss is fine forum for this type of question as Munki itself is fine. You web server is the issue.

You will want to look in your apache logs on your server, by default located at:

/var/log/apache2/

Your two error codes (-1001, and -1005) are directly related to your server configuration. How you fix this will require testing in your environment as server RAM, server upload bandwidth, and client download bandwidth will all play variables in this issue. 

My recommendation would be try using the "mod_reqtimeout" module from apache to increase the timeout or throttle the connection. This article goes over the details: http://httpd.apache.org/docs/2.2/mod/mod_reqtimeout.html

Start in your logs, then start playing with changing your settings one at a time.

-Clayton

[Karamoja]

We also experience these errors with large files such as the full Adobe CC suite.  Our main repo is also on a virtual
 server so I did some testing with the same large pkg files using a Mac Pro as a server, and never got the same errors with large files.  I therefore concluded that the problems were caused by the virtual server.  Never got to the bottom of the cause though.

[Michal Moravec]

Thank you for answers.

On Tuesday, December 8, 2015 at 4:43:45 PM UTC+1, Clayton Burlison wrote:

You will want to look in your apache logs on your server, by default located at:

/var/log/apache2/

Start in your logs, then start playing with changing your settings one at a time.

I have done that. There is nothing problematic in Apache logs even when set to debug level.

Is there a way to log infomation about specific Apache TCP connection? 

Your two error codes (-1001, and -1005) are directly related to your server configuration. How you fix this will require testing in your environment as server RAM, server upload bandwidth, and client download bandwidth will all play variables in this issue. 

Hmm. What about storage? All affected files (/pkgs dir and reposado) are on secondary volume which is not very fast.

I haven't seen any timout errors for catalog or manifest files located on SSD.

 

My recommendation would be try using the "mod_reqtimeout" module from apache to increase the timeout or throttle the connection. This article goes over the details: http://httpd.apache.org/docs/2.2/mod/mod_reqtimeout.html

This applies only to start of transfer where client is sending HTTP request, right? Does this help in the middle of TCP download?

Our main repo is also on a virtual

Could you post more specs (RAM, type/speed of storage) 

[Michal Moravec]

I did more testing. I have problem replication 1001 error from different location than site A.

Look at log down bellow.

I was pinging same sever from other computer connected to different AP at the same time. There was no "window" with droped ICMP packats. 

It looks more like wi-fi issue.

There is a suggestion to disable IPv6 on clients. Doubtful. I have yet to try it.

Munki log
Dec 14 2015 11:43:10 +0100 Downloading InstallOSX_10.11.1_15B42-10.11.1.dmg from apple/osx/InstallOSX_10.11.1_15B42-10.11.1.dmg
Dec 14 2015 11:43:10 +0100 Downloading InstallOSX_10.11.1_15B42-10.11.1.dmg from apple/osx/InstallOSX_10.11.1_15B42-10.11.1.dmg
Dec 14 2015 11:43:10 +0100 Downloading InstallOSX_10.11.1_15B42-10.11.1.dmg...
Dec 14 2015 12:09:16 +0100 Download error -1001: The request timed out.


ping
Mon Dec 14 12:08:57 CET 2015: 64 bytes from IPv4:IPv4:IPv4:IPv4: icmp_seq=4098 ttl=56 time=3.562 ms
Mon Dec 14 12:08:58 CET 2015: 64 bytes from IPv4:IPv4:IPv4:IPv4: icmp_seq=4099 ttl=56 time=27.030 ms
Mon Dec 14 12:08:59 CET 2015: 64 bytes from IPv4:IPv4:IPv4:IPv4: icmp_seq=4100 ttl=56 time=27.219 ms
Mon Dec 14 12:09:01 CET 2015: Request timeout for icmp_seq 4101
Mon Dec 14 12:09:02 CET 2015: Request timeout for icmp_seq 4102
Mon Dec 14 12:09:03 CET 2015: Request timeout for icmp_seq 4103
Mon Dec 14 12:09:04 CET 2015: Request timeout for icmp_seq 4104
Mon Dec 14 12:09:05 CET 2015: Request timeout for icmp_seq 4105
Mon Dec 14 12:09:06 CET 2015: Request timeout for icmp_seq 4106
Mon Dec 14 12:09:06 CET 2015: 64 bytes from IPv4:IPv4:IPv4:IPv4: icmp_seq=4101 ttl=56 time=6029.512 ms
Mon Dec 14 12:09:06 CET 2015: 64 bytes from IPv4:IPv4:IPv4:IPv4: icmp_seq=4102 ttl=56 time=5025.090 ms
Mon Dec 14 12:09:06 CET 2015: 64 bytes from IPv4:IPv4:IPv4:IPv4: icmp_seq=4103 ttl=56 time=4020.128 ms
Mon Dec 14 12:09:06 CET 2015: 64 bytes from IPv4:IPv4:IPv4:IPv4: icmp_seq=4104 ttl=56 time=3015.901 ms
Mon Dec 14 12:09:06 CET 2015: 64 bytes from IPv4:IPv4:IPv4:IPv4: icmp_seq=4105 ttl=56 time=2015.036 ms
Mon Dec 14 12:09:06 CET 2015: 64 bytes from IPv4:IPv4:IPv4:IPv4: icmp_seq=4106 ttl=56 time=1009.890 ms
Mon Dec 14 12:09:06 CET 2015: 64 bytes from IPv4:IPv4:IPv4:IPv4: icmp_seq=4107 ttl=56 time=6.099 ms
Mon Dec 14 12:09:07 CET 2015: 64 bytes from IPv4:IPv4:IPv4:IPv4: icmp_seq=4108 ttl=56 time=5.238 ms
Mon Dec 14 12:09:08 CET 2015: 64 bytes from IPv4:IPv4:IPv4:IPv4: icmp_seq=4109 ttl=56 time=5.035 ms

[Michal Moravec]

Hmm. Munki source ->

There is connection_timeout with default of 10 in code/client/munkilib/gurl.py

This value is passed to NSMutableURLRequest. It looks like seconds.

As far as I can see there is currently no way to set connection_timeout apart from modifing magic constant in source.

Could be handy to be able to set connection_timeout in Munki preferences.

Is this worth creating issue and possible pull request?

Correct procedure is probably to debug & fix wi-fi. However that may be tricky and increasing timeout could help us mitigating this issue.

[Gregory Neagle]

On Dec 14, 2015, at 4:19 PM, Michal Moravec <micha...@gmail.com> wrote:

Hmm. Munki source ->

There is connection_timeout with default of 10 in code/client/munkilib/gurl.py

This value is passed to NSMutableURLRequest. It looks like seconds.

As far as I can see there is currently no way to set connection_timeout apart from modifing magic constant in source.

Connection timeout is just that — a time limit for establishing the initial connection. I don’t think it is connected to how NSURLConnection decides a download isn’t going to complete and abandons it.

Could be handy to be able to set connection_timeout in Munki preferences.

Is this worth creating issue and possible pull request?

Not without evidence that altering this has any useful effect.

Correct procedure is probably to debug & fix wi-fi. However that may be tricky and increasing timeout could help us mitigating this issue.

I don’t think it will, but feel free to try internally.

--
You received this message because you are subscribed to the Google Groups "munki-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to munki-discus...@googlegroups.com.
To post to this group, send email to munki-...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/munki-discuss/5ab9bb55-48ee-41af-8784-5a0a305d7aa4%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Michal Moravec]

 time limit for establishing the initial connection.

Are you sure?

Apple documentation on timeoutInterval in NSURLRequest  class says this ->

 

If during a connection attempt the request remains idle for longer than the timeout interval, the request is considered to have timed out.

and timeoutInterval  in NSMutableURLRequest

If during a connection attempt the request remains idle for longer than the timeout interval, the request is considered to have timed out. The default timeout interval is 60 seconds.
As a general rule, you should not use short timeout intervals. Instead, you should provide an easy way for the user to cancel a long-running operation. For more information, read Designing for Real-World Networks.

[Gregory Neagle]

“connection attempt”: sounds like the initial _connection_ to me…

On Dec 14, 2015, at 4:34 PM, Michal Moravec <micha...@gmail.com> wrote:

Apple documentation on NSURLRequest  says this ->

 

If during a connection attempt the request remains idle for longer than the timeout interval, the request is considered to have timed out.

and NSMutableURLRequest

If during a connection attempt the request remains idle for longer than the timeout interval, the request is considered to have timed out. The default timeout interval is 60 seconds.
As a general rule, you should not use short timeout intervals. Instead, you should provide an easy way for the user to cancel a long-running operation. For more information, read Designing for Real-World Networks.

--
You received this message because you are subscribed to the Google Groups "munki-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to munki-discus...@googlegroups.com.
To post to this group, send email to munki-...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/munki-discuss/0e5bf111-7adc-466f-a10a-1c42c9014022%40googlegroups.com.

[Gregory Neagle]

But again: please feel free to test this. You don’t need my agreement to test your thoughts here.

-Greg

[Michal Moravec]

On Tuesday, December 15, 2015 at 1:37:12 AM UTC+1, Gregory Neagle wrote:

“connection attempt”: sounds like the initial _connection_ to me…

It was 2:00 AM and I was like how could I missed that.

I did the testing and it turns out timeoutInterval plays a role in connection problem during download.

Setup

MacBook (10.11.2) <- eth cable A -> switch <- eth cable B -> LAN <- Internet -> Munki Server

I simulate network error by disconnecing eth cable B.

OS thinks it is connected to network but there is acuatly severed connestion to LAN.

Both tests were conducted twice.

Test 1-  stock Munki 2.4.0

1. Start dowload of big .dmg in Manage Software Center.
   
2. Start pinging something in the LAN or Internet.
   
3. tail -f ManagedSoftwareUpdate.log
   
4. After while disconnect eth cable B.
   
5. See what happens.

Ping
Tue Dec 15 11:13:11 CET 2015: 64 bytes from ipv4.ipv4.ipv4.ipv4: icmp_seq=6117 ttl=56 time=40.306 ms
Tue Dec 15 11:13:13 CET 2015: Request timeout for icmp_seq 6118  <- cable disconnect
Tue Dec 15 11:13:14 CET 2015: Request timeout for icmp_seq 6119
...
Tue Dec 15 11:13:31 CET 2015: Request timeout for icmp_seq 6136
Tue Dec 15 11:13:31 CET 2015: 64 bytes from ipv4.ipv4.ipv4.ipv4: icmp_seq=6137 ttl=56 time=24.714 ms <- cable reconnect


ManagedSoftwareUpdate.log
Dec 15 2015 11:12:56 +0100     Downloading InstallOSX_10.11.1_15B42-10.11.1.dmg from apple/osx/InstallOSX_10.11.1_15B42-10.11.1.dmg
Dec 15 2015 11:12:57 +0100     Downloading InstallOSX_10.11.1_15B42-10.11.1.dmg...
Dec 15 2015 11:13:22 +0100     Download error -1001: The request timed out.

Cable disconnect at ~11:13:11. Download error -1001 at 11:13:22.

Error 1001 occured 10 seconds after cable disconnect.

Test 2 Munki with modified gurl.py

1. In gurl.py change connection_timeout from 10 to 60. connection_timeout = options.get('connection_timeout', 10) -> connection_timeout = options.get('connection_timeout', 60) .
   
2. Delete bytecode file gurl.pyc.
   
3. Repeat same scenario as in Test 1.

Ping
Tue Dec 15 11:35:55 CET 2015: 64 bytes from ipv4.ipv4.ipv4.ipv4: icmp_seq=154 ttl=56 time=35.478 ms
Tue Dec 15 11:35:57 CET 2015: Request timeout for icmp_seq 155 <- cable disconnect
Tue Dec 15 11:35:58 CET 2015: Request timeout for icmp_seq 156
....
Tue Dec 15 11:36:57 CET 2015: Request timeout for icmp_seq 215
ping: sendto: No route to host
....
Tue Dec 15 11:37:07 CET 2015: 64 bytes from ipv4.ipv4.ipv4.ipv4: icmp_seq=226 ttl=56 time=24.165 ms <- cable reconnect


ManagedSoftwareUpdate.log

Dec 15 2015 11:35:22 +0100     Downloading InstallOSX_10.11.1_15B42-10.11.1.dmg from apple/osx/InstallOSX_10.11.1_15B42-10.11.1.dmg
Dec 15 2015 11:35:22 +0100     Downloading InstallOSX_10.11.1_15B42-10.11.1.dmg...
Dec 15 2015 11:36:56 +0100     Download error -1001: The request timed out.

Cable disconnect at ~11:35:57. Download error -1001 at 11:36:56.

Error 1001 occured 60 seconds after cable disconnect.

From this test I conclude timeoutInterval of NSMutableURLRequest plays a role during when connecting problem occurs during download.

I've seen download to continue after 20 secs of cable disconnect. During some longer disconnecs download sometimes failed anyway

.

So is this worth creating issue and possible pull request? 

[Erik Gomez]

I think you're on to something here and this may help people who don't have the best wifi signal. 

Sent from my iPhone

--
You received this message because you are subscribed to the Google Groups "munki-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to munki-discus...@googlegroups.com.
To post to this group, send email to munki-...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/munki-discuss/63c15793-a634-41dd-bb27-a487f73785df%40googlegroups.com.

[Michal Moravec]

I did few more tests. When I set timeout to f.e. 120 seconds and pull cable out for more then 60 seconds download usually fails with 1001 after 120 seconds from connectiong problem.

When connection problem lasted less than 50% of timeout interval (30s, 40s,...) download continued successfully. 

Setting timeout to something big does not look very smart but values like 30 or 60 may help me increase download survivability for wi-fi connection problems lasting 5-15 seconds.

I created pull request.

[Gregory Neagle]

Is there any real reason to complicate things with a new preference and more code, or should we just set the timeout to 60 seconds?

-Greg

--
You received this message because you are subscribed to the Google Groups "munki-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to munki-discus...@googlegroups.com.
To post to this group, send email to munki-...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/munki-discuss/002d2be6-7403-4ca7-84da-94abb93e046f%40googlegroups.com.

[Josh Malone]

I can't see a 60 sec timeout causing any real headache, personally.

To view this discussion on the web visit https://groups.google.com/d/msgid/munki-discuss/C24ECE51-8401-4DF6-A9B3-02AA472A1C2F%40mac.com.

[Erik Gomez]

Same here. It's probably a welcome change. 

To view this discussion on the web visit https://groups.google.com/d/msgid/munki-discuss/CAB%3D%3DwoOXWSRx_KNBOvqgTxG8p83YiteyVNfv73COX_h6qsd_yw%40mail.gmail.com.

[Michal Moravec]

60 seconds souds like value I would end up using.

First of all the current default. I don't know why it is exactly 10 seconds (different from Apple's 60 secs). I am thinking there was some reason for 10 secs? Can this change affect someone in negative way or have other unexpected consequences? 

Code isn't IMHO any more complicated. If I am not missing anything it should require only 3 small changes. Actually it may be more clean this way since we get rid of connection_timeout magic constant buried in gurl.py and move default timeout value to dictionary with other defaults.