And Lo,
for the Earth was empty of Form,
and void.
And Darkness was all over the Face of the Deep.
And We said: 'Look at that fucker Dance.'
― David Foster Wallace, Infinite JestBack to Index
Early Bukowski is so weird and pretentious and sad.
Far from the image of Bukowski recognized in certain b-tier art consumer circles today: the tired but ultimately complacent and entertainingly vulgar, foul-mouthed, grotesuqe, post-sexual old fuck.
It is a frustrated and resentful young Buk, aggresively naive, lobbing trite and tired old observations about consumerism and superficiality at a society he sees himself as somehow, not belonging, if not so much as superior to. Criticizing, unsubtly justifying himself and his obvious misery instead of trying to merely 'convey' and 'express'
We see a man utterly, yet understandably, incapable of conceiving of a reader who is genuinely curious to read about who he is, what he sees and says and does, to get to know him as opposed to his thoughts and opinions and, strangely, words.
A sort of like, archetypal adolescent lamentation, representative of types that he would, himself, eventually come to describe as: 'writing about life as if they had a real angle on it.'
He, to put it rather mildly, bores. If his trick is being such a disastrous mess that you can not, for the life of you, look away, then clearly he isn't there yet, as he writes.
The aspiration to come out on top is still there, and it's so familiarly tedious and dull, another ambitious striver making ostensibly pointed remarks on the sourness of the proverbial grapes. He loathes and resents us for having and enjoying and taking for grant all these things which he will, eventually, come to confess a profound pain of deprivation and unmet need for. The deadthly-tired old toad now brooding, ruminating, reflecting on all those things he never had, will never have. The deep and festering wounds of rejection, isolation and pain ever wide open, never healed, nor closed or scarred. A Bukowski who, in due time, wearing his collosal gash on the proverbial sleeve, would gather small and rowdy crowds in small rooms translucent with smoke and loud with jeering and swear words, crowds that never missed a good laugh at a bodily-function type joke but would often seem to fail to perceive the endings of his rather more serious pieces and, like, forget to applaud, or respond, the way that failing to add the appropriate inflection at the end of a sentence can leave your interlocutor like, hanging, waiting for you to go on
Because, still, at that point, we see a man, who, like so many of us, still hopes and strives, kicks back and wants, grasps for it, frustrated and sad.
A while back I was looking into HTTP GETs timing out over the loopback interface. Big server, plenty of headroom, no network in the path — just curl talking to nginx on the same box. Should have taken under a second. Was hitting my 10s timeout instead. Not every request. Just some of them.
First thing you do is check the error log. Nothing. Access log? Everything looks normal. syslog? Nothing of interest. dmesg? Clean. No OOM, no kernel weirdness, the box wasn't even sweating.
So I did the most basic thing imaginable. Wrote a small bash loop that fired GETs at the server forever and printed how many requests it had done since the last timeout. Then I sat there and watched logs scroll by in another terminal, waiting to see if anything suspicious happened in syslog at the moment a timeout occurred.
If I have ever felt like more of monkey then I'm not sure when that was.
And then it occured to me that there was a way to match curl's timeouts to nginx's access log lines. The server was already logging the User-Agent. So instead of just printing the iteration number to my terminal, I started sending it as the User-Agent of each request:
i=0
while true; do
i=$((i+1))
curl -m 10 --user-agent "iter:$i" -s -o /dev/null \
-w "%{http_code} %{time_total} iter:$i\n" \
http://127.0.0.1/
done
Now when curl reported a timeout I had a unique iteration number I could grep for in the access log. I waited for one, took the iteration from curl's output, grepped the access log.
Status: 200.
Ok. Probably typo'd the grep. Try again. Wait for another timeout. Grep.
200.
Every single timed-out request was logged as 200 by nginx. Every. Single. One. The server believed it had served a request that the client never received.
So then I stopped and stared into the abyss of the terminal.
Once you stop staring, the explanation isn't even that exotic. nginx logs the request when it considers it complete, and "complete" for nginx means I finished writing the response into the kernel send buffer. It does not mean the client acknowledged anything. It does not mean the connection closed cleanly. There is no FIN-ACK in this picture. From nginx's point of view the transaction ended when the last writev / sendfile / SSL_write returned and there was nothing more to send. Status: 200. bytes_sent: whatever. Log line written. Move on.
Whatever happens on the wire after that is somebody else's problem. And on loopback, apparently, somebody else had a problem.
I think a lot of people read an access log the way they'd read the receipt at a restaurant — status 200, you got the food. But it's more like reading the kitchen ticket. The kitchen says the food went out. Whether it ever made it to your table is a separate question, and the access log is not going to answer it for you.
Once I understood this I stopped chasing nginx and went to look at the actual TCP state, which is where the answer was always going to be. Send buffer was full, nothing was being acked from the other end of loopback (yes, loopback can do this — that's a separate rabbit hole), eventually curl gave up. nginx never noticed because nginx had already moved on.
I'd love to tell you the next chapter and what was actually wrong on the kernel side, but that's a different post and honestly I'm still not 100% sure. The point of this one is simpler: stop trusting the access log.
If your access log shows 200 and your client says it timed out, your client is right. Always. The access log is telling you what the server intended; it is not telling you what happened to the bytes.
A few things I do differently now:
$bytes_sent and $request_length in my log format and sanity-check them when I have weird timeouts. If bytes_sent equals the full content length, the server believes it did its job. If it's short, that's a clue.The lesson here is not really about nginx. nginx is doing exactly what it's documented to do. The lesson is that every log line is triggered by some specific event in the code, and if you don't know which event, you don't know what the line means. Otherwise you end up where I was — staring at a terminal at 11pm wondering why a server that says it succeeded is also the one that's making your client time out.
Ask me how I know.
Back to Index