Project

General

Profile

Forums » Support »

[Solved] global/HTTPhost==myhost.lan not available yet

Added by bwechner almost 6 years ago

I have a fully functional web server (in fact 2) running lighttpd. So thought I was pretty much on top of it ;-)

Alas a new issue arises as I try to migrate one of them. To clarify I just installed a fresh Ubuntu 18.04 server and am stuck on a surprising new issue.

I use a conditional like this:

$HTTP["host"] == "myhost.lan" {
}

This works fine on my existing server. On the new server not.

I can load the default index why going straight to the IP:

$ wget 192.168.0.15

But if I use my servers name:

$ wget myhost.lan
--2018-04-29 13:24:59--  http://myhost.lan/
Resolving myhost.lan (myhost.lan)... 192.168.0.15
Connecting to myhost.lan (myhost.lan)|192.168.0.15|:80... connected.
HTTP request sent, awaiting response... 400 Bad Request
2018-04-29 13:25:04 ERROR 400: Bad Request.

So I enable some logging with:

debug.log-request-handling = "enable" 
debug.log-request-header  = "enable" 
debug.log-condition-handling = "enable"

in order to drill down. When I do I see a big contrast between fetching by IP and by name:

By IP:

2018-04-29 13:43:25: (request.c.436) fd: 8 request-len: 139 \nGET / HTTP/1.1\r\nUser-Agent: Wget/1.17.1 (linux-gnu)\r\nAccept: */*\r\nAccept-Encoding: identity\r\nHost: 192.168.0.15\r\nConnection: Keep-Alive\r\n\r\n 
2018-04-29 13:43:25: (response.c.261) run condition 
2018-04-29 13:43:25: (configfile-glue.c.694) === start of condition block === 
2018-04-29 13:43:25: (configfile-glue.c.557) HTTP["host"] ( 192.168.0.15 ) compare to  myhost.lan 
2018-04-29 13:43:25: (configfile-glue.c.615) 1 (uncached) result: false 
2018-04-29 13:43:25: (configfile-glue.c.615) 2 (uncached) result: skipped 
2018-04-29 13:43:25: (response.c.350) -- splitting Request-URI 
2018-04-29 13:43:25: (response.c.351) Request-URI     :  / 
2018-04-29 13:43:25: (response.c.352) URI-scheme      :  http 
2018-04-29 13:43:25: (response.c.353) URI-authority   :  192.168.0.15 
2018-04-29 13:43:25: (response.c.354) URI-path (raw)  :  / 
2018-04-29 13:43:25: (response.c.355) URI-path (clean):  / 
...

by comparison with name:

2018-04-29 13:38:13: (request.c.436) fd: 8 request-len: 143 \nGET / HTTP/1.1\r\nUser-Agent: Wget/1.17.1 (linux-gnu)\r\nAccept: */*\r\nAccept-Encoding: identity\r\nHost: myhost.lan\r\nConnection: Keep-Alive\r\n\r\n 
2018-04-29 13:38:13: (configfile-glue.c.694) === start of condition block === 
2018-04-29 13:38:13: (configfile-glue.c.393) 3 global/HTTPhost==myhost.lan not available yet 
2018-04-29 13:38:13: (configfile-glue.c.615) 1 (uncached) result: unset 
2018-04-29 13:38:13: (configfile-glue.c.615) 2 (uncached) result: unset 
2018-04-29 13:39:13: (server.c.1615) connection closed - read timeout: 10

Two distinct symptoms that bug me:

  1. The condition block just fails with "not available yet"
  2. It fails with a timeout (a browser returns 400 - Bad Request)

But try as I might I can't find any documentation or web reference to this kind of "not available yet" error. Not does the existing webserver do this, it works fine (it however is running on Raspbian and not Ubuntu, but both are Debian deriviatives and I'm not seeing an OS issue obvious here.

What I'm suspecting is a lighttpd config issue and a cryptic message. For now I will focus on asking if anyone can explain why such a message is presented, what it means.

For the record these both produce fine results:

$ lighttpd -tt -f /etc/lighttpd/lighttpd.conf
$ lighttpd -p -f /etc/lighttpd/lighttpd.conf

And yes, if it helps I can attach output of the last one, but to be honest I'd rather check first if there's any traction on this message. Certainly no errors or issues on the output.

The head of "lighttpd -p -f /etc/lighttpd/lighttpd.conf" look like:

config {
    var.PID                        = 3311
    var.CWD                        = "/var/log/lighttpd" 
    server.modules                 = (
        "mod_access",
        "mod_accesslog",
        "mod_alias",
        "mod_compress",
        "mod_redirect",
        "mod_rewrite",
        "mod_scgi",
        "mod_fastcgi",
        # 8
    )
    server.errorlog                = "/var/log/lighttpd/error.log" 
    accesslog.filename             = "/var/log/lighttpd/access.log" 
    accesslog.format               = "%t %h %V %u \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" 
    debug.log-request-handling     = "enable" 
    debug.log-request-header       = "enable" 
    debug.log-condition-handling   = "enable" 
    server.document-root           = "/data/www" 
    server.upload-dirs             = ("/var/cache/lighttpd/uploads")
    server.pid-file                = "/var/run/lighttpd.pid" 
    server.username                = "www-data" 
    server.groupname               = "www-data" 
    server.port                    = 80
    index-file.names               = ("index.php", "index.html", "index.lighttpd.html")
    url.access-deny                = ("~", ".inc")
    static-file.exclude-extensions = (".php", ".pl", ".fcgi")
    compress.cache-dir             = "/var/cache/lighttpd/compress/" 
    compress.filetype              = ("application/javascript", "text/css", "text/html", "text/plain")
    mimetype.assign                = (

But the mimetype list blows out some and is tricky to post. After mime types though its like:

    alias.url                      = (
        "/javascript" => "/usr/share/javascript",
    )

    $HTTP["host"] == "myhost.lan" {
         ... stuff that isn't even seen ...
    }

A puzzling problem that might be easier to work with if the debug output suggested a reason for "not available yet" I guess. Clearly the name resolves to the IP and the only difference in the request header is the Host: header. If I extract the headers from the logs and format them nicely they look like:

GET / HTTP/1.1
User-Agent: Wget/1.17.1 (linux-gnu)
Accept: */*
Accept-Encoding: identity
Host: 192.168.0.15
Connection: Keep-Alive

GET / HTTP/1.1
User-Agent: Wget/1.17.1 (linux-gnu)
Accept: */*
Accept-Encoding: identity
Host: myhost.lan
Connection: Keep-Alive

And in one case the conditionals evaluate and in the other they don't!


Replies (13)

RE: global/HTTPhost==myhost.lan not available yet - Added by gstrauss almost 6 years ago

This works fine on my existing server. On the new server not.

What is the lighttpd version of the existing server? What is the lighttpd version of the new server?

That part of the condition processing should not be hanging. Did Ubuntu patch lighttpd to do something else?

Have you tried 'strace' on the lighttpd daemon to see what is happening during those 10 seconds before the read timeout? That information might be useful.

RE: global/HTTPhost==myhost.lan not available yet - Added by gstrauss almost 6 years ago

Try commenting out all the modules in server.modules = ( ... ). You'll get some warnings about unrecognized directives when you start lighttpd up, but please see what happens with a simpler configuration.

RE: global/HTTPhost==myhost.lan not available yet - Added by bwechner almost 6 years ago

Both machines use lighttpd 1.4.45.

On the Raspbian system (works):

$ lighttpd -v
lighttpd/1.4.45 (ssl) - a light and fast webserver
Build-Date: Jan 14 2017 21:07:19

On the Ubuntu system (exhibiting this odd problem)

$ lighttpd -v
lighttpd/1.4.45 (ssl) - a light and fast webserver
Build-Date: Feb  6 2018 12:41:51

Yes stripping down the config and trying again is on my agenda.

strace is new on me and I'll try!

Thanks for the quick reply. Have to play a game with my 4 year old now but will look at this again later today/tonight.

RE: global/HTTPhost==myhost.lan not available yet - Added by bwechner almost 6 years ago

OK quick update. Stripped lighttpd.conf down to bare minimum with maximal debug logging:

server.modules = ()

# Configure the logs
server.errorlog             = "/var/log/lighttpd/error.log" 

# Debugging options
debug.log-request-handling = "enable" 
debug.log-request-header  = "enable" 
debug.log-condition-handling = "enable" 
debug.log-response-header = "enable" 
debug.log-file-not-found = "enable" 
debug.log-timeouts = "enable" 

# Basic configurations
server.document-root        = "/data/www" 
server.upload-dirs          = ( "/var/cache/lighttpd/uploads" )
server.pid-file             = "/var/run/lighttpd.pid" 
server.username             = "www-data" 
server.groupname            = "www-data" 
server.port                 = 80

index-file.names            = ( "index.php", "index.html", "index.lighttpd.html" )
static-file.exclude-extensions = ( ".php", ".pl", ".fcgi" )

Then ran:

$ wget arachne_nova.lan
--2018-04-29 17:45:20--  http://arachne_nova.lan/
Resolving arachne_nova.lan (arachne_nova.lan)... 192.168.0.15
Connecting to arachne_nova.lan (arachne_nova.lan)|192.168.0.15|:80... connected.
HTTP request sent, awaiting response... 400 Bad Request
2018-04-29 17:45:25 ERROR 400: Bad Request.

$ wget 192.168.0.15
--2018-04-29 17:45:44--  http://192.168.0.15/
Connecting to 192.168.0.15:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 3361 (3.3K) [application/octet-stream]
Saving to: 'index.html.4’

index.html.4                100%[==========================================>]   3.28K  --.-KB/s    in 0s      

2018-04-29 17:45:44 (25.2 MB/s) - 'index.html.4’ saved [3361/3361]

And this is what's in the error log:

2018-04-29 17:45:09: (log.c.217) server started 
2018-04-29 17:45:24: (request.c.436) fd: 7 request-len: 143 \nGET / HTTP/1.1\r\nUser-Agent: Wget/1.17.1 (linux-gnu)\r\nAccept: */*\r\nAccept-Encoding: identity\r\nHost: arachne_nova.lan\r\nConnection: Keep-Alive\r\n\r\n 
2018-04-29 17:45:24: (response.c.122) Response-Header: \nHTTP/1.1 400 Bad Request\r\nContent-Type: text/html\r\nContent-Length: 349\r\nConnection: close\r\nDate: Sun, 29 Apr 2018 07:45:24 GMT\r\nServer: lighttpd/1.4.45\r\n\r\n 
2018-04-29 17:45:44: (request.c.436) fd: 7 request-len: 139 \nGET / HTTP/1.1\r\nUser-Agent: Wget/1.17.1 (linux-gnu)\r\nAccept: */*\r\nAccept-Encoding: identity\r\nHost: 192.168.0.15\r\nConnection: Keep-Alive\r\n\r\n 
2018-04-29 17:45:44: (response.c.261) run condition 
2018-04-29 17:45:44: (response.c.350) -- splitting Request-URI 
2018-04-29 17:45:44: (response.c.351) Request-URI     :  / 
2018-04-29 17:45:44: (response.c.352) URI-scheme      :  http 
2018-04-29 17:45:44: (response.c.353) URI-authority   :  192.168.0.15 
2018-04-29 17:45:44: (response.c.354) URI-path (raw)  :  / 
2018-04-29 17:45:44: (response.c.355) URI-path (clean):  / 
2018-04-29 17:45:44: (response.c.356) URI-query       :   
2018-04-29 17:45:44: (response.c.490) -- before doc_root 
2018-04-29 17:45:44: (response.c.491) Doc-Root     : /data/www 
2018-04-29 17:45:44: (response.c.492) Rel-Path     : / 
2018-04-29 17:45:44: (response.c.493) Path         :  
2018-04-29 17:45:44: (response.c.542) -- after doc_root 
2018-04-29 17:45:44: (response.c.543) Doc-Root     : /data/www 
2018-04-29 17:45:44: (response.c.544) Rel-Path     : / 
2018-04-29 17:45:44: (response.c.545) Path         : /data/www/ 
2018-04-29 17:45:44: (response.c.562) -- logical -> physical 
2018-04-29 17:45:44: (response.c.563) Doc-Root     : /data/www 
2018-04-29 17:45:44: (response.c.564) Basedir      : /data/www 
2018-04-29 17:45:44: (response.c.565) Rel-Path     : / 
2018-04-29 17:45:44: (response.c.566) Path         : /data/www/ 
2018-04-29 17:45:44: (response.c.583) -- handling physical path 
2018-04-29 17:45:44: (response.c.584) Path         : /data/www/ 
2018-04-29 17:45:44: (response.c.591) -- file found 
2018-04-29 17:45:44: (response.c.592) Path         : /data/www/ 
2018-04-29 17:45:44: (response.c.753) -- handling subrequest 
2018-04-29 17:45:44: (response.c.754) Path         : /data/www/ 
2018-04-29 17:45:44: (mod_indexfile.c.153) -- handling the request as Indexfile 
2018-04-29 17:45:44: (mod_indexfile.c.154) URI          : / 
2018-04-29 17:45:44: (mod_staticfile.c.202) -- handling file as static file 
2018-04-29 17:45:44: (response.c.765) -- subrequest finished 
2018-04-29 17:45:44: (response.c.122) Response-Header: \nHTTP/1.1 200 OK\r\nContent-Type: application/octet-stream\r\nAccept-Ranges: bytes\r\nContent-Length: 3361\r\nDate: Sun, 29 Apr 2018 07:45:44 GMT\r\nServer: lighttpd/1.4.45\r\n\r\n

And so, while the name resolves to the IP wget sends the self same request with a different Host: header and lighttpd is doing its job when the IP is in the header but not when the name is in the header. Getting down to the minimalist version. An strace effort next.

RE: global/HTTPhost==myhost.lan not available yet - Added by bwechner almost 6 years ago

And one strace later nothing revealed. I did this:

$ sudo strace -olighttpd.trace -tt -s 4000 -p `pgrep lighttpd` &

and then repeated:

$ wget arachne_nova.lan

and got this trace (the relevant bits anyhow, snipped lead tail off as it's just a pile epoll_waits, i.e., last line repeated, until I kill strace):

17:53:55.707956 epoll_wait(6, [], 1025, 1000) = 0
17:53:56.709118 epoll_wait(6, [], 1025, 1000) = 0
17:53:57.710200 openat(AT_FDCWD, "/proc/loadavg", O_RDONLY) = 7
17:53:57.710299 read(7, "0.00 0.00 0.00 1/169 4563\n", 64) = 26
17:53:57.710370 close(7)                = 0
17:53:57.710434 epoll_wait(6, [], 1025, 1000) = 0
17:53:58.711520 epoll_wait(6, [], 1025, 1000) = 0
17:53:59.712602 epoll_wait(6, [], 1025, 1000) = 0
17:54:00.713687 epoll_wait(6, [], 1025, 1000) = 0
17:54:01.714781 epoll_wait(6, [], 1025, 1000) = 0
17:54:02.715864 epoll_wait(6, [], 1025, 1000) = 0
17:54:03.716947 epoll_wait(6, [], 1025, 1000) = 0
17:54:04.718029 epoll_wait(6, [], 1025, 1000) = 0
17:54:05.719113 epoll_wait(6, [], 1025, 1000) = 0
17:54:06.720394 epoll_wait(6, [], 1025, 1000) = 0
17:54:07.721492 epoll_wait(6, [{EPOLLIN, {u32=4, u64=4}}], 1025, 1000) = 1
17:54:07.887237 accept4(4, {sa_family=AF_INET, sin_port=htons(35058), sin_addr=inet_addr("192.168.0.11")}, [112->16], SOCK_CLOEXEC|SOCK_NONBLOCK) = 7
17:54:07.887336 ioctl(7, FIONREAD, [0]) = 0
17:54:07.887405 read(7, "GET / HTTP/1.1\r\nUser-Agent: Wget/1.17.1 (linux-gnu)\r\nAccept: */*\r\nAccept-Encoding: identity\r\nHost: arachne_nova.lan\r\nConnection: Keep-Alive\r\n\r\n", 4159) = 143
17:54:07.887474 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
17:54:07.887560 write(5, "2018-04-29 17:54:07: (request.c.436) fd: 7 request-len: 143 \\nGET / HTTP/1.1\\r\\nUser-Agent: Wget/1.17.1 (linux-gnu)\\r\\nAccept: */*\\r\\nAccept-Encoding: identity\\r\\nHost: arachne_nova.lan\\r\\nConnection: Keep-Alive\\r\\n\\r\\n \n", 221) = 221
17:54:07.887664 write(5, "2018-04-29 17:54:07: (response.c.122) Response-Header: \\nHTTP/1.1 400 Bad Request\\r\\nContent-Type: text/html\\r\\nContent-Length: 349\\r\\nConnection: close\\r\\nDate: Sun, 29 Apr 2018 07:54:07 GMT\\r\\nServer: lighttpd/1.4.45\\r\\n\\r\\n \n", 228) = 228
17:54:07.887736 setsockopt(7, SOL_TCP, TCP_CORK, [1], 4) = 0
17:54:07.887797 writev(7, [{iov_base="HTTP/1.1 400 Bad Request\r\nContent-Type: text/html\r\nContent-Length: 349\r\nConnection: close\r\nDate: Sun, 29 Apr 2018 07:54:07 GMT\r\nServer: lighttpd/1.4.45\r\n\r\n", iov_len=155}, {iov_base="<?xml version=\"1.0\" encoding=\"iso-8859-1\"?>\n<!DOCTYPE html PUBLIC \"-//W3C//DTD XHTML 1.0 Transitional//EN\"\n         \"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd\">\n<html xmlns=\"http://www.w3.org/1999/xhtml\" xml:lang=\"en\" lang=\"en\">\n <head>\n  <title>400 - Bad Request</title>\n </head>\n <body>\n  <h1>400 - Bad Request</h1>\n </body>\n</html>\n", iov_len=349}], 2) = 504
17:54:07.887874 setsockopt(7, SOL_TCP, TCP_CORK, [0], 4) = 0
17:54:07.887941 shutdown(7, SHUT_WR)    = 0
17:54:07.888000 read(7, 0x7ffd384e5150, 4096) = -1 EAGAIN (Resource temporarily unavailable)
17:54:07.888067 epoll_ctl(6, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=7, u64=7}}) = 0
17:54:07.888128 accept4(4, 0x7ffd384e6150, [112], SOCK_CLOEXEC|SOCK_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)
17:54:07.888196 epoll_wait(6, [{EPOLLIN|EPOLLERR|EPOLLHUP, {u32=7, u64=7}}], 1025, 1000) = 1
17:54:07.888388 read(7, 0x7ffd384e51b0, 4096) = -1 ECONNRESET (Connection reset by peer)
17:54:07.888443 read(7, "", 4096)       = 0
17:54:07.888496 epoll_ctl(6, EPOLL_CTL_DEL, 7, 0x7ffd384e614c) = 0
17:54:07.888550 close(7)                = 0
17:54:07.888620 epoll_wait(6, [], 1025, 1000) = 0

Which provides no clues at all alas. I shall repeat now using the IP.

RE: global/HTTPhost==myhost.lan not available yet - Added by bwechner almost 6 years ago

OK, attached strace and:

$ wget 192.168.0.15

and get this trace:

17:59:24.546068 epoll_wait(6, [], 1025, 1000) = 0
17:59:25.547243 epoll_wait(6, [], 1025, 1000) = 0
17:59:26.548336 epoll_wait(6, [], 1025, 1000) = 0
17:59:27.549417 epoll_wait(6, [], 1025, 1000) = 0
17:59:28.550498 epoll_wait(6, [], 1025, 1000) = 0
17:59:29.551586 epoll_wait(6, [], 1025, 1000) = 0
17:59:30.553010 epoll_wait(6, [], 1025, 1000) = 0
17:59:31.554096 epoll_wait(6, [], 1025, 1000) = 0
17:59:32.555181 epoll_wait(6, [{EPOLLIN, {u32=4, u64=4}}], 1025, 1000) = 1
17:59:33.151482 accept4(4, {sa_family=AF_INET, sin_port=htons(35214), sin_addr=inet_addr("192.168.0.11")}, [112->16], SOCK_CLOEXEC|SOCK_NONBLOCK) = 7
17:59:33.151582 ioctl(7, FIONREAD, [0]) = 0
17:59:33.151672 read(7, "GET / HTTP/1.1\r\nUser-Agent: Wget/1.17.1 (linux-gnu)\r\nAccept: */*\r\nAccept-Encoding: identity\r\nHost: 192.168.0.15\r\nConnection: Keep-Alive\r\n\r\n", 4159) = 139
17:59:33.151757 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
17:59:33.151849 write(5, "2018-04-29 17:59:32: (request.c.436) fd: 7 request-len: 139 \\nGET / HTTP/1.1\\r\\nUser-Agent: Wget/1.17.1 (linux-gnu)\\r\\nAccept: */*\\r\\nAccept-Encoding: identity\\r\\nHost: 192.168.0.15\\r\\nConnection: Keep-Alive\\r\\n\\r\\n \n", 217) = 217
17:59:33.151951 write(5, "2018-04-29 17:59:32: (response.c.261) run condition \n", 53) = 53
17:59:33.152026 write(5, "2018-04-29 17:59:32: (response.c.350) -- splitting Request-URI \n", 64) = 64
17:59:33.152098 write(5, "2018-04-29 17:59:32: (response.c.351) Request-URI     :  / \n", 60) = 60
17:59:33.152169 write(5, "2018-04-29 17:59:32: (response.c.352) URI-scheme      :  http \n", 63) = 63
17:59:33.152241 write(5, "2018-04-29 17:59:32: (response.c.353) URI-authority   :  192.168.0.15 \n", 71) = 71
17:59:33.152313 write(5, "2018-04-29 17:59:32: (response.c.354) URI-path (raw)  :  / \n", 60) = 60
17:59:33.152384 write(5, "2018-04-29 17:59:32: (response.c.355) URI-path (clean):  / \n", 60) = 60
17:59:33.152456 write(5, "2018-04-29 17:59:32: (response.c.356) URI-query       :   \n", 59) = 59
17:59:33.152528 write(5, "2018-04-29 17:59:32: (response.c.490) -- before doc_root \n", 58) = 58
17:59:33.152599 write(5, "2018-04-29 17:59:32: (response.c.491) Doc-Root     : /data/www \n", 64) = 64
17:59:33.152672 write(5, "2018-04-29 17:59:32: (response.c.492) Rel-Path     : / \n", 56) = 56
17:59:33.152744 write(5, "2018-04-29 17:59:32: (response.c.493) Path         :  \n", 55) = 55
17:59:33.152816 write(5, "2018-04-29 17:59:32: (response.c.542) -- after doc_root \n", 57) = 57
17:59:33.152888 write(5, "2018-04-29 17:59:32: (response.c.543) Doc-Root     : /data/www \n", 64) = 64
17:59:33.152959 write(5, "2018-04-29 17:59:32: (response.c.544) Rel-Path     : / \n", 56) = 56
17:59:33.153030 write(5, "2018-04-29 17:59:32: (response.c.545) Path         : /data/www/ \n", 65) = 65
17:59:33.153102 write(5, "2018-04-29 17:59:32: (response.c.562) -- logical -> physical \n", 62) = 62
17:59:33.153173 write(5, "2018-04-29 17:59:32: (response.c.563) Doc-Root     : /data/www \n", 64) = 64
17:59:33.153245 write(5, "2018-04-29 17:59:32: (response.c.564) Basedir      : /data/www \n", 64) = 64
17:59:33.153316 write(5, "2018-04-29 17:59:32: (response.c.565) Rel-Path     : / \n", 56) = 56
17:59:33.153387 write(5, "2018-04-29 17:59:32: (response.c.566) Path         : /data/www/ \n", 65) = 65
17:59:33.153459 write(5, "2018-04-29 17:59:32: (response.c.583) -- handling physical path \n", 65) = 65
17:59:33.153530 write(5, "2018-04-29 17:59:32: (response.c.584) Path         : /data/www/ \n", 65) = 65
17:59:33.153602 stat("/data/www/", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
17:59:33.153680 write(5, "2018-04-29 17:59:32: (response.c.591) -- file found \n", 53) = 53
17:59:33.153753 write(5, "2018-04-29 17:59:32: (response.c.592) Path         : /data/www/ \n", 65) = 65
17:59:33.153825 write(5, "2018-04-29 17:59:32: (response.c.753) -- handling subrequest \n", 62) = 62
17:59:33.153897 write(5, "2018-04-29 17:59:32: (response.c.754) Path         : /data/www/ \n", 65) = 65
17:59:33.153970 write(5, "2018-04-29 17:59:32: (mod_indexfile.c.153) -- handling the request as Indexfile \n", 81) = 81
17:59:33.154054 write(5, "2018-04-29 17:59:32: (mod_indexfile.c.154) URI          : / \n", 61) = 61
17:59:33.154124 stat("/data/www/index.php", 0x7ffd384e5f30) = -1 ENOENT (No such file or directory)
17:59:33.154202 stat("/data/www/index.html", 0x7ffd384e5f30) = -1 ENOENT (No such file or directory)
17:59:33.154268 stat("/data/www/index.lighttpd.html", {st_mode=S_IFREG|0644, st_size=3361, ...}) = 0
17:59:33.154339 openat(AT_FDCWD, "/data/www/index.lighttpd.html", O_RDONLY) = 8
17:59:33.154410 close(8)                = 0
17:59:33.154473 write(5, "2018-04-29 17:59:32: (mod_staticfile.c.202) -- handling file as static file \n", 77) = 77
17:59:33.154544 openat(AT_FDCWD, "/data/www/index.lighttpd.html", O_RDONLY|O_NOCTTY|O_NONBLOCK) = 8
17:59:33.154610 fstat(8, {st_mode=S_IFREG|0644, st_size=3361, ...}) = 0
17:59:33.154674 write(5, "2018-04-29 17:59:32: (response.c.765) -- subrequest finished \n", 62) = 62
17:59:33.154753 write(5, "2018-04-29 17:59:32: (response.c.122) Response-Header: \\nHTTP/1.1 200 OK\\r\\nContent-Type: application/octet-stream\\r\\nAccept-Ranges: bytes\\r\\nContent-Length: 3361\\r\\nDate: Sun, 29 Apr 2018 07:59:32 GMT\\r\\nServer: lighttpd/1.4.45\\r\\n\\r\\n \n", 238) = 238
17:59:33.154839 setsockopt(7, SOL_TCP, TCP_CORK, [1], 4) = 0
17:59:33.154903 writev(7, [{iov_base="HTTP/1.1 200 OK\r\nContent-Type: application/octet-stream\r\nAccept-Ranges: bytes\r\nContent-Length: 3361\r\nDate: Sun, 29 Apr 2018 07:59:32 GMT\r\nServer: lighttpd/1.4.45\r\n\r\n", iov_len=165}], 1) = 165
17:59:33.154975 fstat(8, {st_mode=S_IFREG|0644, st_size=3361, ...}) = 0
17:59:33.155052 sendfile(7, 8, [0] => [3361], 3361) = 3361
17:59:33.155139 close(8)                = 0
17:59:33.155197 setsockopt(7, SOL_TCP, TCP_CORK, [0], 4) = 0
17:59:33.155264 ioctl(7, FIONREAD, [0]) = 0
17:59:33.155328 read(7, 0x557c83352c50, 4159) = -1 EAGAIN (Resource temporarily unavailable)
17:59:33.155388 epoll_ctl(6, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=7, u64=7}}) = 0
17:59:33.155453 accept4(4, 0x7ffd384e6150, [112], SOCK_CLOEXEC|SOCK_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)
17:59:33.155527 epoll_wait(6, [{EPOLLIN, {u32=7, u64=7}}], 1025, 1000) = 1
17:59:33.156255 ioctl(7, FIONREAD, [0]) = 0
17:59:33.156318 read(7, "", 4159)       = 0
17:59:33.156379 shutdown(7, SHUT_WR)    = 0
17:59:33.156442 read(7, "", 4096)       = 0
17:59:33.156501 epoll_ctl(6, EPOLL_CTL_DEL, 7, 0x7ffd384e614c) = 0
17:59:33.156559 close(7)                = 0
17:59:33.156619 epoll_wait(6, [], 1025, 1000) = 0
17:59:34.157700 epoll_wait(6, [], 1025, 1000) = 0
17:59:35.158787 epoll_wait(6, [], 1025, 1000) = 0
17:59:36.160198 epoll_wait(6, [], 1025, 1000) = 0
17:59:37.161300 epoll_wait(6, [], 1025, 1000) = 0
17:59:38.162390 openat(AT_FDCWD, "/proc/loadavg", O_RDONLY) = 7
17:59:38.162482 read(7, "0.00 0.00 0.00 1/169 4593\n", 64) = 26
17:59:38.162553 close(7)                = 0
17:59:38.162619 epoll_wait(6, [], 1025, 1000) = 0
17:59:39.163046 epoll_wait(6, [], 1025, 1000) = 0
17:59:40.164133 epoll_wait(6,  <detached ...>

Which is identical up until it diverges at:

17:59:33.151951 write(5, "2018-04-29 17:59:32: (response.c.261) run condition \n", 53) = 53

where the IP GET returns the index file and the name GET immediately bombs with a Bad Request (well 104 ms later with no clues between).

Pulling my hair out ;-). Murphy in the background whispering "this'll be easy once you work it out" ;-).

[solved] RE: global/HTTPhost==myhost.lan not available yet - Added by stbuehler almost 6 years ago

Yet another example why you should not try to hide internal names.

arachne_nova.lan is not a valid hostname, underscores are not allowed. (It is a valid DNS name though).

I'd recommend using "-" instead, i.e. arachne-nova.lan.

You can also disable the check:

server.http-parseopt-host-strict = "disable"

RE: global/HTTPhost==myhost.lan not available yet - Added by bwechner almost 6 years ago

Bingo! As Murphy whispered it'd be easy once diagnosed. But Grrrr.

I haven't had ime to change the name (more involved) but I did try the option:

server.http-parseopt-host-strict = "disable"

and I get the most bizarre behaviour! That is, it actually works, and loads (yipee!) BUT go figure, in a browser it downloads the index.html file, doesn't render it! Amazing.

Hoping that disappears when I find time to doctor the name to arachne-nova. Funny thing is, the server will be arachne, the current web server is arachne, and I'm building its replacement beside it while it's still running so I just called it arachne_nova for now ;-).

But you live and learn. My take though would be that lighttpd needs to seriously output this in the error log. This whole thread and all my time and your time invested into it would not be if only the error log had said something lucid about the domain name and why it wasn't returning anything. It may be wortha feature request/bug report on ligthty when I get around to it (citing this thread as the kind of work lucid feedback in the error log avoids).

RE: global/HTTPhost==myhost.lan not available yet - Added by stbuehler almost 6 years ago

bwechner wrote:

[...]
My take though would be that lighttpd needs to seriously output this in the error log. This whole thread and all my time and your time invested into it would not be if only the error log had said something lucid about the domain name and why it wasn't returning anything. It may be wortha feature request/bug report on ligthty when I get around to it (citing this thread as the kind of work lucid feedback in the error log avoids).

Agreed, that would be nice to have (probably tied to some debug option).

I'm sure gstrauss is open to merging patches: in src/request.c the strict check is done by request_check_hostname; it will probably need a server *srv argument to check the debug flag and to write the log message (it could also return an error code through some new enum type that could be logged elsewhere).

RE: global/HTTPhost==myhost.lan not available yet - Added by bwechner almost 6 years ago

Have now renamed the server and restarted and everything works fine! Am blown away how such tiny little mistake can cause so much trouble and not be reported in the error log!

Here's an issue already!

https://redmine.lighttpd.net/issues/551

but methinks it's worth a new one so I filed:

https://redmine.lighttpd.net/issues/2885

which points here.

RE: global/HTTPhost==myhost.lan not available yet - Added by gstrauss almost 6 years ago

Debug trace would have been emitted with debug.log-request-header-on-error = "enable"

I'll update the docs on Docs_ConfigurationOptions to note that extra diagnostic info is also emitted along with logging the request header.

RE: [Solved] global/HTTPhost==myhost.lan not available yet - Added by bwechner almost 6 years ago

Oh dear, I intentionally left that out as from doco I assumed it was just a subset of debug.log-request-header, outputting the header if there is an error.

Methinks to be honest this is the sort of error that is worth logging unconditionally though. As it's an error! The optional stuff should be reserved fro diagnostics. At the very least an error to the effect that the hostname requested (Host: HTTP header) is illegal or contains illegal characters.

RE: [Solved] global/HTTPhost==myhost.lan not available yet - Added by gstrauss almost 6 years ago

I tested with an invalid Host: "arachne_nova.lan" and lighttpd immediately returns 400 Bad Request, as expected. I see that lighttpd also quickly returned 400 Bad Request in your strace, so your additional problem looks like bad browser behavior.

Methinks to be honest this is the sort of error that is worth logging unconditionally though.

Bad requests happen all the time on publicly facing servers. Do you run a high-capacity site that would lend some weight to that opinion of yours? tldr: You must enable the extra diagnostics if you want all that noise in your error log.

    (1-13/13)