Re: http 408 messages in httpd logs

2017-02-14 Thread Walter Alejandro Iglesias 
On Tue, Feb 14, 2017 at 11:34:02AM -0800, Reyk Floeter wrote:
> Yes, this is possible. Could you send me some more
> details including config?

I just sent another message with the whole logs that didn't reach misc@,
too heavy :-).  Here you go a simplified version:


OpenBSD 6.0-current (GENERIC.MP) #169: Mon Feb 13 17:44:12 MST 2017
dera...@amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP


# /etc/pf.conf
table  {
0.0.0.0/8
10.0.0.0/8
127.0.0.1/8
169.254.0.0/16
172.16.0.0/12
192.0.2.0/24
192.88.99.0/24
192.168.0.0/16
198.18.0.0/15
198.51.100.0/24
203.0.113.0/24
224.0.0.0/4
240.0.0.0/4
}
table  persist file "/etc/port22"
table  persist file "/etc/port25"
set block-policy drop
set skip on lo0
match in all scrub (no-df random-id max-mss 1440)
antispoof log quick for egress
pass out quick all
pass in quick from { 192.168.1.1 192.168.1.102 192.168.1.103 } allow-opts
block quick inet proto udp from any to port \
{ bootps bootpc netbios-ns netbios-dgm }
block in log quick inet proto tcp from  to port ssh
block in log quick inet proto tcp from  to port smtp
block in log quick from { urpf-failed no-route  }
pass in quick proto tcp to port { http https smtp smtps pop3s ssh }
pass in quick inet proto icmp all icmp-type 8 code 0
block in log all


# /etc/httpd.conf
ext_addr="em0"
r_timeout="300"

types {
include "/usr/share/misc/mime.types"
}

server "roquesor.com" {
listen on $ext_addr port 80
connection request timeout $r_timeout
alias "www.roquesor.com"
alias "es.roquesor.com"
block return 301 "https://$SERVER_NAME$REQUEST_URI;
location "/.well-known/acme-challenge/*" {
root "/acme"
root strip 2
}
log {
access "roquesor.com-access.log"
error "roquesor.com-error.log"
}
root "/htdocs/roquesor.com"
}
server "en.roquesor.com" {
listen on $ext_addr port 80
connection request timeout $r_timeout
block return 301 "https://$SERVER_NAME$REQUEST_URI;
location "/.well-known/acme-challenge/*" {
root "/acme"
root strip 2
}
log {
access "roquesor.com-access.log"
error "roquesor.com-error.log"

}
root "/htdocs/roquesor.com/en"
}
server "roquesor.com" {
listen on $ext_addr tls port 443
connection request timeout $r_timeout
alias "www.roquesor.com"
alias "es.roquesor.com"
tls certificate "/etc/ssl/server.crt"
tls key "/etc/ssl/private/server.key"
location "/.well-known/acme-challenge/*" {
root "/acme"
root strip 2
}
log {
access "roquesor.com-SSL-access.log"
error "roquesor.com-SSL-error.log"
}
root "/htdocs/roquesor.com"
}
server "en.roquesor.com" {
listen on $ext_addr tls port 443
connection request timeout $r_timeout
tls certificate "/etc/ssl/server.crt"
tls key "/etc/ssl/private/server.key"
location "/.well-known/acme-challenge/*" {
root "/acme"
root strip 2
}
log {
access "roquesor.com-SSL-access.log"
error "roquesor.com-SSL-error.log"
}
root "/htdocs/roquesor.com/en"
}


$ cat /var/www/logs/roquesor.com-access.log | sed -E 's/([^ ] 
)([0-9]{1,3})\.(.*)/\1xxx.\3/'
Feb 12 00:00:01 server newsyslog[54883]: logfile turned over
roquesor.com xxx.249.75.40 - - [12/Feb/2017:00:03:02 +0100] " " 408 0
roquesor.com xxx.249.75.136 - - [12/Feb/2017:00:06:51 +0100] " " 408 0
roquesor.com xxx.249.75.58 - - [12/Feb/2017:00:10:18 +0100] " " 408 0
roquesor.com xxx.249.69.221 - - [12/Feb/2017:00:12:57 +0100] " " 408 0
roquesor.com xxx.249.75.47 - - [12/Feb/2017:00:13:01 +0100] " " 408 0
roquesor.com xxx.249.75.40 - - [12/Feb/2017:00:13:14 +0100] " " 408 0
roquesor.com xxx.249.69.233 - - [12/Feb/2017:00:15:23 +0100] " " 408 0
roquesor.com xxx.249.75.47 - - [12/Feb/2017:00:16:41 +0100] " " 408 0
www.roquesor.com xxx.180.228.163 - - [12/Feb/2017:00:18:04 +0100] "GET 
/robots.txt HTTP/1.1" 200 36
www.roquesor.com xxx.180.228.163 - - [12/Feb/2017:00:18:05 +0100] "GET 
/novelas.html HTTP/1.1" 200 1542
roquesor.com xxx.180.228.163 - - [12/Feb/2017:00:19:06 +0100] " " 408 0
roquesor.com xxx.249.75.47 - - [12/Feb/2017:00:19:53 +0100] " " 408 0
roquesor.com xxx.249.75.56 - - [12/Feb/2017:00:22:44 +0100] " " 408 0
roquesor.com xxx.249.69.183 - - [12/Feb/2017:00:23:08 +0100] " " 408 0
roquesor.com xxx.125.88.204 - - [12/Feb/2017:00:25:27 +0100] " " 408 0
roquesor.com xxx.249.75.43 - - [12/Feb/2017:00:25:56 +0100] " " 408 0
roquesor.com xxx.249.75.148 - - [12/Feb/2017:00:28:18 +0100] " " 408 0
roquesor.com xxx.249.69.183 - - [12/Feb/2017:00:28:21 +0100] " " 408 0

Re: http 408 messages in httpd logs

2017-02-14 Thread Walter Alejandro Iglesias 
On Tue, Feb 14, 2017 at 02:34:24PM -0500, trondd wrote:
> On Tue, February 14, 2017 2:27 pm, trondd wrote:
> > http://cvsweb.openbsd.org/cgi-bin/cvsweb/src/usr.sbin/httpd/server.c.diff?r1=1.106=1.107=h
> >
> > Unfortunately the commit message is not helpful here.
> >
> 
> Ah hah.  I knew it'd be somewhere:
> http://marc.info/?l=openbsd-cvs=148647072802851=2
> 
> I'd guess that the web browser was previously closing these connection
> long before the server was timing out.
> 


Trondd, big champ! :-)

Re: http 408 messages in httpd logs

2017-02-14 Thread Reyk Floeter 
> Am 14.02.2017 um 11:27 schrieb trondd :
>
>> On Tue, February 14, 2017 1:48 pm, Walter Alejandro Iglesias wrote:
>> Starting from Feb 11 my httpd logs are filled with 408 messages:
>>
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET /
>> HTTP/1.1" 200 2535
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
>> /en/styles.css HTTP/1.1" 200 282
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
>> /en/img/home-novelas.png HTTP/1.1" 200 1812
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
>> /en/img/home-comic.png HTTP/1.1" 200 2779
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
>> /en/img/at.png HTTP/1.1" 200 324
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
>> /en/img/home-devel.png HTTP/1.1" 200 4111
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
>> /en/img/home-articles.png HTTP/1.1" 200 5835
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
>> /en/img/home-about.jpg HTTP/1.1" 200 22211
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
>> /en/img/home-social.png HTTP/1.1" 200 2782
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
>> 408 0
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
>> 408 0
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
>> 408 0
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
>> 408 0
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
>> 408 0
>> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
>> 408 0
>>
>> This affects my main site only (I have other several virtual sites
>> hosted in that machine), the only one using ssl on 443 port.  As the
>> example shows, some of them come right before a same source IP
>> successful connection.  In fact, the hidden ip above is me browsing my
>> web site from another location.  Besides, I didn't notice any delay, the
>> pages are loaded as fast as before the messages started to appear.
>>
>> Increasing the request time out (in /etc/httpd.conf):
>>
>>  connection request timeout 120
>>
>> seems (not sure) to reduce a bit the number of messages.
>>
>> What intrigues me (and the reason I'm mentioning this here) is before
>> Feb 11th, the date the first appeared, there is none, passed that date
>> *all* requests generate that message.  I follow -current and upgrade
>> snapshots regularly.  Could be some change in the system the cause?
>>
>
> Yes:
>
http://cvsweb.openbsd.org/cgi-bin/cvsweb/src/usr.sbin/httpd/server.c.diff?r1=
1.106=1.107=h
>
> I am assuming these are client pre-negotiated connections to speed up the
> user experience.  I guess they were not properly being closed before.
> Unfortunately the commit message is not helpful here.
>

Good catch. Maybe changing it to a 408 was not the right thing here.

Reyk

Re: http 408 messages in httpd logs

2017-02-14 Thread Reyk Floeter 
> Am 14.02.2017 um 10:48 schrieb Walter Alejandro Iglesias
:
>
> Starting from Feb 11 my httpd logs are filled with 408 messages:
>
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET /
HTTP/1.1" 200 2535
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
/en/styles.css HTTP/1.1" 200 282
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
/en/img/home-novelas.png HTTP/1.1" 200 1812
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
/en/img/home-comic.png HTTP/1.1" 200 2779
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
/en/img/at.png HTTP/1.1" 200 324
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
/en/img/home-devel.png HTTP/1.1" 200 4111
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
/en/img/home-articles.png HTTP/1.1" 200 5835
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
/en/img/home-about.jpg HTTP/1.1" 200 22211
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
/en/img/home-social.png HTTP/1.1" 200 2782
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
408 0
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
408 0
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
408 0
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
408 0
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
408 0
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
408 0
>
> This affects my main site only (I have other several virtual sites
> hosted in that machine), the only one using ssl on 443 port.  As the
> example shows, some of them come right before a same source IP
> successful connection.  In fact, the hidden ip above is me browsing my
> web site from another location.  Besides, I didn't notice any delay, the
> pages are loaded as fast as before the messages started to appear.
>
> Increasing the request time out (in /etc/httpd.conf):
>
>  connection request timeout 120
>
> seems (not sure) to reduce a bit the number of messages.
>
> What intrigues me (and the reason I'm mentioning this here) is before
> Feb 11th, the date the first appeared, there is none, passed that date
> *all* requests generate that message.  I follow -current and upgrade
> snapshots regularly.  Could be some change in the system the cause?
>

Yes, this is possible. Could you send me some more
details including config?

Reyk

Re: http 408 messages in httpd logs

2017-02-14 Thread trondd 
On Tue, February 14, 2017 2:27 pm, trondd wrote:
> http://cvsweb.openbsd.org/cgi-bin/cvsweb/src/usr.sbin/httpd/server.c.diff?r1=1.106=1.107=h
>
> Unfortunately the commit message is not helpful here.
>

Ah hah.  I knew it'd be somewhere:
http://marc.info/?l=openbsd-cvs=148647072802851=2

I'd guess that the web browser was previously closing these connection
long before the server was timing out.

Re: http 408 messages in httpd logs

2017-02-14 Thread trondd 
On Tue, February 14, 2017 1:48 pm, Walter Alejandro Iglesias wrote:
> Starting from Feb 11 my httpd logs are filled with 408 messages:
>
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET /
> HTTP/1.1" 200 2535
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
> /en/styles.css HTTP/1.1" 200 282
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
> /en/img/home-novelas.png HTTP/1.1" 200 1812
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
> /en/img/home-comic.png HTTP/1.1" 200 2779
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
> /en/img/at.png HTTP/1.1" 200 324
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
> /en/img/home-devel.png HTTP/1.1" 200 4111
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
> /en/img/home-articles.png HTTP/1.1" 200 5835
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
> /en/img/home-about.jpg HTTP/1.1" 200 22211
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET
> /en/img/home-social.png HTTP/1.1" 200 2782
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
> 408 0
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
> 408 0
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
> 408 0
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
> 408 0
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
> 408 0
> roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " "
> 408 0
>
> This affects my main site only (I have other several virtual sites
> hosted in that machine), the only one using ssl on 443 port.  As the
> example shows, some of them come right before a same source IP
> successful connection.  In fact, the hidden ip above is me browsing my
> web site from another location.  Besides, I didn't notice any delay, the
> pages are loaded as fast as before the messages started to appear.
>
> Increasing the request time out (in /etc/httpd.conf):
>
>   connection request timeout 120
>
> seems (not sure) to reduce a bit the number of messages.
>
> What intrigues me (and the reason I'm mentioning this here) is before
> Feb 11th, the date the first appeared, there is none, passed that date
> *all* requests generate that message.  I follow -current and upgrade
> snapshots regularly.  Could be some change in the system the cause?
>

Yes:
http://cvsweb.openbsd.org/cgi-bin/cvsweb/src/usr.sbin/httpd/server.c.diff?r1=1.106=1.107=h

I am assuming these are client pre-negotiated connections to speed up the
user experience.  I guess they were not properly being closed before. 
Unfortunately the commit message is not helpful here.

http 408 messages in httpd logs

2017-02-14 Thread Walter Alejandro Iglesias 
Starting from Feb 11 my httpd logs are filled with 408 messages:

roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET / HTTP/1.1" 
200 2535
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET 
/en/styles.css HTTP/1.1" 200 282
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET 
/en/img/home-novelas.png HTTP/1.1" 200 1812
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET 
/en/img/home-comic.png HTTP/1.1" 200 2779
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET 
/en/img/at.png HTTP/1.1" 200 324
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET 
/en/img/home-devel.png HTTP/1.1" 200 4111
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET 
/en/img/home-articles.png HTTP/1.1" 200 5835
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET 
/en/img/home-about.jpg HTTP/1.1" 200 22211
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:48:32 +0100] "GET 
/en/img/home-social.png HTTP/1.1" 200 2782
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " " 408 0
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " " 408 0
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " " 408 0
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " " 408 0
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " " 408 0
roquesor.com 79.xxx.150.xx4 - - [14/Feb/2017:15:49:32 +0100] " " 408 0

This affects my main site only (I have other several virtual sites
hosted in that machine), the only one using ssl on 443 port.  As the
example shows, some of them come right before a same source IP
successful connection.  In fact, the hidden ip above is me browsing my
web site from another location.  Besides, I didn't notice any delay, the
pages are loaded as fast as before the messages started to appear.

Increasing the request time out (in /etc/httpd.conf):

  connection request timeout 120

seems (not sure) to reduce a bit the number of messages.

What intrigues me (and the reason I'm mentioning this here) is before
Feb 11th, the date the first appeared, there is none, passed that date
*all* requests generate that message.  I follow -current and upgrade
snapshots regularly.  Could be some change in the system the cause?