Return-Path: X-Original-To: apmail-httpd-users-archive@www.apache.org Delivered-To: apmail-httpd-users-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 4CF41C2F9 for ; Thu, 13 Nov 2014 13:07:05 +0000 (UTC) Received: (qmail 66618 invoked by uid 500); 13 Nov 2014 13:07:01 -0000 Delivered-To: apmail-httpd-users-archive@httpd.apache.org Received: (qmail 66584 invoked by uid 500); 13 Nov 2014 13:07:01 -0000 Mailing-List: contact users-help@httpd.apache.org; run by ezmlm Precedence: bulk Reply-To: users@httpd.apache.org list-help: list-unsubscribe: List-Post: List-Id: Delivered-To: mailing list users@httpd.apache.org Received: (qmail 66574 invoked by uid 99); 13 Nov 2014 13:07:01 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 13 Nov 2014 13:07:01 +0000 X-ASF-Spam-Status: No, hits=1.5 required=5.0 tests=HTML_MESSAGE,RCVD_IN_DNSWL_LOW,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of stefan.landro@gmail.com designates 209.85.220.50 as permitted sender) Received: from [209.85.220.50] (HELO mail-pa0-f50.google.com) (209.85.220.50) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 13 Nov 2014 13:06:34 +0000 Received: by mail-pa0-f50.google.com with SMTP id eu11so15094760pac.23 for ; Thu, 13 Nov 2014 05:06:32 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:date:message-id:subject:from:to:content-type; bh=UpixbzMqs8cHEmZsBMz9Hq9bwwbyFXQMaQPr91QBXes=; b=mMZubX0qQl6SEyi/6e6XPDNtCfWjZjK9ImfU8E2wVRO7jwBEe5xETqwFy/15Ob0Cx7 tzwQRolCy9Fd8pJMyNChTpJRvFMYxrp0elQbKp7Zb/6t5XThqUBzZBBG8mqM3IHQPw9S QAqHBm6QhaEYk6hr0bgy/djSlOIG/9+l2H0hGr9PozylFGGZSE+i4ut6+ok1ADaGVTRM hw86K8PKlLWSK0viv8UAnJvCQVdGfrzbgbpVUUEdB1FvVnwXX8LS6wm8RX09odO7TLSF vFaB+XRqMdsidOodwtPovsrQS/kuo7CyXaV3R1vNAW0qaEoEsOi25X788ec4k2OwCEmx tHPw== MIME-Version: 1.0 X-Received: by 10.68.220.39 with SMTP id pt7mr2433191pbc.37.1415883992739; Thu, 13 Nov 2014 05:06:32 -0800 (PST) Received: by 10.70.59.73 with HTTP; Thu, 13 Nov 2014 05:06:32 -0800 (PST) Date: Thu, 13 Nov 2014 14:06:32 +0100 Message-ID: From: =?UTF-8?Q?Stefan_Magnus_Landr=C3=B8?= To: users@httpd.apache.org Content-Type: multipart/alternative; boundary=e89a8ff249d56e362b0507bd2eda X-Virus-Checked: Checked by ClamAV on apache.org Subject: [users@httpd] Weird access logs --e89a8ff249d56e362b0507bd2eda Content-Type: text/plain; charset=UTF-8 Hi there, We're seeing some weird behaviour in our access logs. For around 13 minutes we see entries from requests received several minutes before it actually gets logged (the two timestamps on the same line are up to 13 minutes apart! ). The number to the far right is %D - the response time (microseconds) Also, we're using big ip as a load balancer in front of this server, and the big ip health check considers this apache as down during this timeframe. BTW, in total there are exactly 200 weird entries like this. Are we hitting some crazy default? What could be going on? Cheers Stefan Nov 13 02:02:22 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:02:22 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 505 Nov 13 02:02:22 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:02:22 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 563 Nov 13 02:02:23 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:02:23 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 466 Nov 13 02:02:23 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:02:23 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 469 Nov 13 02:02:23 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:02:23 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 612 Nov 13 02:02:24 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:02:24 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 413 *Nov 13 02:02:25 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:02:25 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 408* *Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:03:15 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 509* Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:03:16 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 2138 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:03:16 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 735 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:03:16 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 2262 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:03:17 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 549 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:03:17 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 2356 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:03:18 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 698 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:03:18 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 673 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:03:18 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 523 ... Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:04:39 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 568 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:04:40 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 2354 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:04:40 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 840 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:04:40 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 1941 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:04:41 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 778 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:04:41 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 3106 Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:04:42 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 440 *Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:04:42 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 599* *Nov 13 02:15:50 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:15:50 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 646* Nov 13 02:15:51 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:15:51 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 586 Nov 13 02:15:51 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:15:51 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 2248 Nov 13 02:15:51 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:15:51 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 624 Nov 13 02:15:52 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:15:52 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 2562 Nov 13 02:15:52 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:15:52 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 519 Nov 13 02:15:52 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:15:52 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 2411 Nov 13 02:15:53 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:15:53 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 403 Nov 13 02:15:53 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:15:53 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 2517 --e89a8ff249d56e362b0507bd2eda Content-Type: text/html; charset=UTF-8 Content-Transfer-Encoding: quoted-printable
Hi there,

We're seeing s= ome weird behaviour in our access logs.=C2=A0

For = around 13 minutes we see entries from requests received several minutes bef= ore it actually gets logged (the two timestamps on the same line are up to = 13 minutes apart! ).=C2=A0
The number to the far right is %D - th= e response time (microseconds)

Also, we'r= e using big ip as a load balancer in front of this server, and the big ip h= ealth check considers this apache as down during this timeframe.=C2=A0

BTW, in total there are exactly 200 weird entrie= s like this. Are we hitting some crazy default?

What could be going on?

Cheers
=
Stefan

Nov 13 02:02:22 alq-kronos h= ttpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:02:22 +0100] "GET /big= ip.txt HTTP/1.0" 200 10 "-" "-" statisk 505
<= div>Nov 13 02:02:22 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/201= 4:02:02:22 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" = "-" statisk 563
Nov 13 02:02:23 alq-kronos httpd[32388]= : 139.116.14.253 - - [13/Nov/2014:02:02:23 +0100] "GET /bigip.txt HTTP= /1.0" 200 10 "-" "-" statisk 466
Nov 13 = 02:02:23 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:02:23 = +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-&quo= t; statisk 469
Nov 13 02:02:23 alq-kronos httpd[32388]: 139.116.1= 4.254 - - [13/Nov/2014:02:02:23 +0100] "GET /bigip.txt HTTP/1.0" = 200 10 "-" "-" statisk 612
Nov 13 02:02:24 al= q-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:02:24 +0100] &quo= t;GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk = 413
Nov 13 02:02:25 alq-kronos httpd[32388]: 139.116.14.253 - = - [13/Nov/2014:02:02:25 +0100] "GET /bigip.txt HTTP/1.0" 200 10 &= quot;-" "-" statisk 408
Nov 13 02:15:44 alq= -kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:03:15 +0100] "= ;GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 5= 09
Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.253 - = - [13/Nov/2014:02:03:16 +0100] "GET /bigip.txt HTTP/1.0" 200 10 &= quot;-" "-" statisk 2138
Nov 13 02:15:44 alq-krono= s httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:03:16 +0100] "GET /= bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 735
Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/= 2014:02:03:16 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-&quo= t; "-" statisk 2262
Nov 13 02:15:44 alq-kronos httpd[32= 388]: 139.116.14.253 - - [13/Nov/2014:02:03:17 +0100] "GET /bigip.txt = HTTP/1.0" 200 10 "-" "-" statisk 549
Nov= 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:03= :17 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-= " statisk 2356
Nov 13 02:15:44 alq-kronos httpd[32388]: 139.= 116.14.253 - - [13/Nov/2014:02:03:18 +0100] "GET /bigip.txt HTTP/1.0&q= uot; 200 10 "-" "-" statisk 698
Nov 13 02:15:= 44 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:03:18 +0100]= "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" sta= tisk 673
Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 = - - [13/Nov/2014:02:03:18 +0100] "GET /bigip.txt HTTP/1.0" 200 10= "-" "-" statisk 523
...
Nov 1= 3 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:04:3= 9 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-&q= uot; statisk 568
Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116= .14.253 - - [13/Nov/2014:02:04:40 +0100] "GET /bigip.txt HTTP/1.0"= ; 200 10 "-" "-" statisk 2354
Nov 13 02:15:44= alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:04:40 +0100] &= quot;GET /bigip.txt HTTP/1.0" 200 10 "-" "-" stati= sk 840
Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - = - [13/Nov/2014:02:04:40 +0100] "GET /bigip.txt HTTP/1.0" 200 10 &= quot;-" "-" statisk 1941
Nov 13 02:15:44 alq-krono= s httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02:04:41 +0100] "GET /= bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 778
Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/= 2014:02:04:41 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-&quo= t; "-" statisk 3106
Nov 13 02:15:44 alq-kronos httpd[32= 388]: 139.116.14.253 - - [13/Nov/2014:02:04:42 +0100] "GET /bigip.txt = HTTP/1.0" 200 10 "-" "-" statisk 440
= Nov 13 02:15:44 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02= :04:42 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" &quo= t;-" statisk 599
Nov 13 02:15:50 alq-kronos httpd[323= 88]: 139.116.14.253 - - [13/Nov/2014:02:15:50 +0100] "GET /bigip.txt H= TTP/1.0" 200 10 "-" "-" statisk 646
= Nov 13 02:15:51 alq-kronos httpd[32388]: 139.116.14.253 - - [13/Nov/2014:02= :15:51 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" &quo= t;-" statisk 586
Nov 13 02:15:51 alq-kronos httpd[32388]: 13= 9.116.14.253 - - [13/Nov/2014:02:15:51 +0100] "GET /bigip.txt HTTP/1.0= " 200 10 "-" "-" statisk 2248
Nov 13 02:= 15:51 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:15:51 +01= 00] "GET /bigip.txt HTTP/1.0" 200 10 "-" "-" = statisk 624
Nov 13 02:15:52 alq-kronos httpd[32388]: 139.116.14.2= 53 - - [13/Nov/2014:02:15:52 +0100] "GET /bigip.txt HTTP/1.0" 200= 10 "-" "-" statisk 2562
Nov 13 02:15:52 alq-= kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:02:15:52 +0100] "= GET /bigip.txt HTTP/1.0" 200 10 "-" "-" statisk 51= 9
Nov 13 02:15:52 alq-kronos httpd[32388]: 139.116.14.254 - - [13= /Nov/2014:02:15:52 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "= -" "-" statisk 2411
Nov 13 02:15:53 alq-kronos htt= pd[32388]: 139.116.14.253 - - [13/Nov/2014:02:15:53 +0100] "GET /bigip= .txt HTTP/1.0" 200 10 "-" "-" statisk 403
Nov 13 02:15:53 alq-kronos httpd[32388]: 139.116.14.254 - - [13/Nov/2014:= 02:15:53 +0100] "GET /bigip.txt HTTP/1.0" 200 10 "-" &q= uot;-" statisk 2517
--e89a8ff249d56e362b0507bd2eda--