search

Kong / kong

🦍 The Cloud-Native API Gateway and AI Gateway.
https://konghq.com/install/#kong-community
Apache License 2.0
39.28k stars 4.82k forks source link

Requests from browsers are not logged #6186

Closed Eyal-Shalev closed 3 years ago

Eyal-Shalev commented 4 years ago

Summary

I've added the udp-log plugin to a kong instance, that points to a local logstash server. But browser request logs are not being sent to my logstash server, only curl requests from my terminal.

Steps To Reproduce

  1. Setup kong (db-less)
  2. Setup logstash (used a variation of github.com/deviantony/docker-elk)
  3. Add the udp-log plugin pointing to the logstash port.
  4. Add a POC service that returns OK 200 on every request.

Additional Details & Logs

Eyal-Shalev commented 4 years ago

The following is the request I'm making:

curl 'http://localhost:8000/greet' \
  -H 'Connection: keep-alive' \
  -H 'Pragma: no-cache' \
  -H 'Cache-Control: no-cache' \
  -H 'Upgrade-Insecure-Requests: 1' \
  -H 'User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.105 Safari/537.36' \
  -H 'Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9' \
  -H 'Sec-Fetch-Site: none' \
  -H 'Sec-Fetch-Mode: navigate' \
  -H 'Sec-Fetch-User: ?1' \
  -H 'Sec-Fetch-Dest: document' \
  -H 'Accept-Language: en-US,en;q=0.9' \
  --compressed

Though the following request is logged:

curl 'http://localhost:8000/greet' \
  -H 'User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.105 Safari/537.36' \
  -H 'Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9' \
  -H 'Accept-Language: en-US,en;q=0.9' \
  --compressed

It seems that the Sec-Fetch, Upgrade-Insecure-Requests, Pragma, Connection & Cache-Control headers prevent the request from being logged.

kikito commented 4 years ago

Hello Eyal,

My first impression is that this is a browser-caching issue. The browser caches the value of the first request it sends and then it does not send it the second time.

Eyal-Shalev commented 4 years ago

Hi @kikito, curl with the above headers doesn't register as well. That is how I figured which headers are problematic. Though, sometimes requests with the problematic headers were logged (but not consistently, and I couldn't figure out why).

Eyal-Shalev commented 4 years ago

Another curious thing, is that if the route doesn't exist in kong, the request is being logged.

Eyal-Shalev commented 4 years ago

Hi @kikito any news?

Eyal-Shalev commented 4 years ago

Do you guys have any news regarding this issue? @kikito , @hutchic ?

dndx commented 4 years ago

Hi @Eyal-Shalev,

I investigated the report, however I was not able to reproduce the bug with the exact curl command you gave. Could you make sure that you test this using the latest version of Kong and make sure nothing sits between the curl client and Kong is caching the HTTP request in the middle?

If there is a reliably way to reproduce this with the latest version of Kong, please share them in the issue (something like a Dockerfile or automated reproduction script will be helpful).

Eyal-Shalev commented 4 years ago

@dndx below is a small POC:

kong.yml

_format_version: "1.1"
services:
  - name: hello-world
    url: http://host.docker.internal:1234
    routes:
      - name: hello-world
        paths:
          - /greet
plugins:
  - name: udp-log
    config:
      host: host.docker.internal
      port: 5000

hello-world service is defined with the following go program.
hello-world.go

package main

import (
    "net/http"
)

func main() {
    _ = http.ListenAndServe("0.0.0.0:1234", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        w.Header().Set("Content-Type", "text/html")
        _, _ = w.Write([]byte(`"Hello world"`))
    }))
}

run-local.sh

docker run --rm -it --name hello-kong \
  -p 8000:8000 -p 8001:8001 \
  -e "KONG_ADMIN_LISTEN=0.0.0.0:8001" \
  -e "KONG_MEM_CACHE_SIZE=1024m" \
  -e "KONG_DECLARATIVE_CONFIG=/usr/local/kong/etc/kong.yml" \
  -e "KONG_DATABASE=off" \
  -v "$PWD/kong.yml:/usr/local/kong/etc/kong.yml" \
  kong:2.1-alpine kong start --vv

My Logstash server is based on: deviantony/docker-elk.
with the following patch:

diff --git a/logstash/pipeline/logstash.conf b/logstash/pipeline/logstash.conf
index 14c76f8..3f8f313 100644
--- a/logstash/pipeline/logstash.conf
+++ b/logstash/pipeline/logstash.conf
@@ -1,6 +1,12 @@
 input {
        tcp {
                port => 5000
+               codec => json_lines
+               host => "0.0.0.0"
+       }
+       udp {
+               port => 5000
+               codec => json_lines
        }
 }
Eyal-Shalev commented 4 years ago

Below is a screen recording of the issue ezgif-4-0e930a5b0eef

bungle commented 4 years ago

Is it possible that the UDP packet is too big?

Eyal-Shalev commented 4 years ago

Is it possible that the UDP packet is too big?

How can I test it?

Eyal-Shalev commented 4 years ago

I switched to TCP and weirdly after testing again, I saw a single /greet request in the log. But future requests did not include it (via curl as well). image

Is it possible that Kong is by default caching requests (and doesn't send them to the log)?

curl 'http://localhost:8000/greet' is always logged successfully.

Eyal-Shalev commented 4 years ago

This is the successful logged /greet request I had above (see image).

{
  "_index": "logstash-2020.09.07-000001",
  "_type": "_doc",
  "_id": "1ljumnQBIhYXwHJVS_aV",
  "_score": 1,
  "_source": {
    "host": "gateway",
    "request": {
      "headers": {
        "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.102 Safari/537.36",
        "sec-fetch-dest": "document",
        "sec-fetch-user": "?1",
        "dnt": "1",
        "host": "localhost:8000",
        "cookie": "sid=Fe26.2**2319dfbf22d73a731f89bec4ba6549deb577c4e128ecaaceb46c6f1f3f9ef516*Beq2xj8--LPqCymbG9kf6w*VJqJYyTyGHXB6FDbw3mslgA-43ILUEGwkOqbSjnVF7t3xWe1hVT0lY6tPi6mgrFnlSmaSdx0M37athpv0tIP28Kzb7O5eNiMpu7jkw_LZx_0hVkR2n_GyCMrRUGO7xRnq2oxtpsN8UUzjvp9SU24mO4qDMnD1A52L0co6ZpRl69tMdlnpETFF32HfHgFs7rcKxA6jtaGmg37gqRQmKdzMQ**f9baebbe1899f022a5be48035b84140245cb51a7e63353859237877d0ea0b2c7*G16J4koy1HK-nyjb_24o1JfeHtl5firJm7phIqSZ5eQ",
        "sec-fetch-mode": "navigate",
        "accept-encoding": "gzip, deflate, br",
        "upgrade-insecure-requests": "1",
        "accept-language": "en-US,en;q=0.9,he;q=0.8",
        "sec-fetch-site": "none",
        "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9",
        "connection": "keep-alive"
      },
      "method": "GET",
      "uri": "/greet",
      "size": "993",
      "querystring": {},
      "url": "http://localhost:8000/greet"
    },
    "port": 55504,
    "upstream_uri": "/",
    "service": {
      "write_timeout": 60000,
      "ws_id": "0dc6f45b-8f8d-40d2-a504-473544ee190b",
      "retries": 5,
      "host": "host.docker.internal",
      "read_timeout": 60000,
      "port": 1234,
      "connect_timeout": 60000,
      "id": "d7ca8386-6a7e-5bf7-bd63-347609249458",
      "name": "hello-world",
      "updated_at": 1600327132,
      "protocol": "http",
      "created_at": 1600327132
    },
    "tries": [
      {
        "balancer_latency": 0,
        "balancer_start": 1600327141848,
        "code": 502,
        "port": 1234,
        "ip": "192.168.65.2",
        "state": "failed"
      },
      {
        "balancer_latency": 0,
        "balancer_start": 1600327141850,
        "code": 502,
        "port": 1234,
        "ip": "192.168.65.2",
        "state": "failed"
      },
      {
        "balancer_latency": 0,
        "balancer_start": 1600327141853,
        "code": 502,
        "port": 1234,
        "ip": "192.168.65.2",
        "state": "failed"
      },
      {
        "balancer_latency": 0,
        "balancer_start": 1600327141854,
        "code": 502,
        "port": 1234,
        "ip": "192.168.65.2",
        "state": "failed"
      },
      {
        "balancer_latency": 0,
        "balancer_start": 1600327141855,
        "code": 502,
        "port": 1234,
        "ip": "192.168.65.2",
        "state": "failed"
      },
      {
        "balancer_latency": 0,
        "balancer_start": 1600327141857,
        "port": 1234,
        "ip": "192.168.65.2"
      }
    ],
    "route": {
      "ws_id": "0dc6f45b-8f8d-40d2-a504-473544ee190b",
      "regex_priority": 0,
      "path_handling": "v0",
      "strip_path": true,
      "paths": [
        "/greet"
      ],
      "id": "b2a5e842-2e58-5d07-878d-6c2f050c44ad",
      "service": {
        "id": "d7ca8386-6a7e-5bf7-bd63-347609249458"
      },
      "protocols": [
        "http",
        "https"
      ],
      "name": "greet",
      "https_redirect_status_code": 426,
      "updated_at": 1600327132,
      "created_at": 1600327132,
      "preserve_host": false
    },
    "latencies": {
      "request": 14,
      "kong": 13,
      "proxy": 1
    },
    "started_at": 1600327141844,
    "@timestamp": "2020-09-17T07:19:02.153Z",
    "response": {
      "headers": {
        "server": "kong/2.1.3",
        "x-kong-proxy-latency": "13",
        "x-kong-upstream-latency": "1",
        "via": "kong/2.1.3",
        "content-length": "75",
        "connection": "close",
        "content-type": "application/json; charset=utf-8"
      },
      "status": 502,
      "size": "322"
    },
    "@version": "1",
    "client_ip": "172.17.0.1"
  },
  "fields": {
    "@timestamp": [
      "2020-09-17T07:19:02.153Z"
    ]
  }
}

This is a logged curl 'http://localhost:8000/greet' request:

{
  "_index": "logstash-2020.09.07-000001",
  "_type": "_doc",
  "_id": "F1j5mnQBIhYXwHJVVf9A",
  "_score": 1,
  "_source": {
    "host": "172.19.0.1",
    "request": {
      "headers": {
        "accept": "*/*",
        "user-agent": "curl/7.64.1",
        "host": "localhost:8000"
      },
      "method": "GET",
      "uri": "/greet",
      "size": "83",
      "querystring": {},
      "url": "http://localhost:8000/greet"
    },
    "upstream_uri": "/",
    "service": {
      "write_timeout": 60000,
      "ws_id": "0dc6f45b-8f8d-40d2-a504-473544ee190b",
      "retries": 5,
      "host": "host.docker.internal",
      "read_timeout": 60000,
      "port": 1234,
      "connect_timeout": 60000,
      "id": "d7ca8386-6a7e-5bf7-bd63-347609249458",
      "name": "hello-world",
      "updated_at": 1600327807,
      "protocol": "http",
      "created_at": 1600327807
    },
    "tries": [
      {
        "balancer_latency": 0,
        "balancer_start": 1600327865542,
        "port": 1234,
        "ip": "192.168.65.2"
      }
    ],
    "route": {
      "ws_id": "0dc6f45b-8f8d-40d2-a504-473544ee190b",
      "regex_priority": 0,
      "path_handling": "v0",
      "strip_path": true,
      "paths": [
        "/greet"
      ],
      "id": "fca9ee99-edf2-51ca-bdc8-0714ecf9bb52",
      "service": {
        "id": "d7ca8386-6a7e-5bf7-bd63-347609249458"
      },
      "protocols": [
        "http",
        "https"
      ],
      "name": "hello-world",
      "https_redirect_status_code": 426,
      "updated_at": 1600327807,
      "created_at": 1600327807,
      "preserve_host": false
    },
    "latencies": {
      "request": 3,
      "kong": 0,
      "proxy": 2
    },
    "started_at": 1600327865541,
    "@timestamp": "2020-09-17T07:31:05.549Z",
    "response": {
      "headers": {
        "date": "Thu, 17 Sep 2020 07:31:05 GMT",
        "x-kong-proxy-latency": "1",
        "x-kong-upstream-latency": "2",
        "via": "kong/2.1.3",
        "content-length": "13",
        "connection": "close",
        "content-type": "text/plain; charset=UTF-8"
      },
      "status": 200,
      "size": "224"
    },
    "@version": "1",
    "client_ip": "172.17.0.1"
  },
  "fields": {
    "@timestamp": [
      "2020-09-17T07:31:05.549Z"
    ]
  }
}
Eyal-Shalev commented 4 years ago

@kikito are there any updates on this issue?

Eyal-Shalev commented 3 years ago

Are there any updates on this issue? @kikito @dndx @hutchic

dndx commented 3 years ago

Hello @Eyal-Shalev,

I took another look at your example and the udp-log source, and could not spot any reason why this would happen.

Could you provide some tcpdump pcap files for the Kong proxy port and the UDP log port? That way we can confirm if the browser request or the UDP log packet was actually sent.

Eyal-Shalev commented 3 years ago

@dndx Here is a dump created with Wireshark (filtered to only UDP entries) localhost-udp.pcapng

gszr commented 3 years ago

@Eyal-Shalev Could you use netcat and see if the UDP packages are received? You can open a UDP socket with netcat -vv 127.0.0.1 -p 5000 -u -l -- this is on a Mac; if you use Linux the command might be a bit different (check this out if needed https://www.binarytides.com/programming-udp-sockets-c-linux/). Thanks in advance!

Eyal-Shalev commented 3 years ago

@gszr I added a -z to the command (-z, --zero zero-I/O mode (used for scanning)). Without it only a single request is logged.

With the browser (2 requests):

~ % netcat -vv 127.0.0.1 -p 5000 -u -l -z
Listening on any address 5000 (commplex-main) (using 1 sockets)
Received packet from 127.0.0.1:50931 -> 127.0.0.1:5000 (local)
{"latencies":{"request":1,"kong":1,"proxy":-1},"request":{"querystring":{},"size":"513","uri":"\/favicon.ico","url":"http:\/\/localhost:8000\/favicon.ico","headers":{"host":"localhost:8000","connection":"keep-alive","accept-language":"en-US,en;q=0.9,he;q=0.8","sec-fetch-site":"same-origin","sec-fetch-dest":"image","cache-control":"no-cache","sec-fetch-mode":"no-cors","pragma":"no-cache","user-agent":"Mozilla\/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit\/537.36 (KHTML, like Gecko) Chrome\/87.0.4280.67 Safari\/537.36","accept-encoding":"gzip, deflate, br","referer":"http:\/\/localhost:8000\/greet","dnt":"1","accept":"image\/avif,image\/webp,image\/apng,image\/*,*\/*;q=0.8"},"method":"GET"},"client_ip":"172.17.0.1","upstream_uri":"","response":{"headers":{"content-type":"application\/json; charset=utf-8","x-kong-response-latency":"1","server":"kong\/2.1.3","connection":"close","content-length":"48"},"status":404,"size":"250"},"started_at":1606656272267}

Received packet from 127.0.0.1:57159 -> 127.0.0.1:5000 (local)
{"latencies":{"request":1,"kong":1,"proxy":-1},"request":{"querystring":{},"size":"513","uri":"\/favicon.ico","url":"http:\/\/localhost:8000\/favicon.ico","headers":{"host":"localhost:8000","connection":"keep-alive","accept-language":"en-US,en;q=0.9,he;q=0.8","sec-fetch-site":"same-origin","sec-fetch-dest":"image","cache-control":"no-cache","sec-fetch-mode":"no-cors","pragma":"no-cache","user-agent":"Mozilla\/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit\/537.36 (KHTML, like Gecko) Chrome\/87.0.4280.67 Safari\/537.36","accept-encoding":"gzip, deflate, br","referer":"http:\/\/localhost:8000\/greet","dnt":"1","accept":"image\/avif,image\/webp,image\/apng,image\/*,*\/*;q=0.8"},"method":"GET"},"client_ip":"172.17.0.1","upstream_uri":"","response":{"headers":{"content-type":"application\/json; charset=utf-8","x-kong-response-latency":"1","server":"kong\/2.1.3","connection":"close","content-length":"48"},"status":404,"size":"250"},"started_at":1606656278844}

With curl (2 requests):

~ % netcat -vv 127.0.0.1 -p 5000 -u -l -z
Listening on any address 5000 (commplex-main) (using 1 sockets)
Received packet from 127.0.0.1:62291 -> 127.0.0.1:5000 (local)
{"latencies":{"request":2,"kong":1,"proxy":1},"service":{"host":"host.docker.internal","created_at":1606656019,"connect_timeout":60000,"id":"d7ca8386-6a7e-5bf7-bd63-347609249458","protocol":"http","name":"hello-world","read_timeout":60000,"port":1234,"updated_at":1606656019,"write_timeout":60000,"retries":5,"ws_id":"0dc6f45b-8f8d-40d2-a504-473544ee190b"},"request":{"querystring":{},"size":"83","uri":"\/greet","url":"http:\/\/localhost:8000\/greet","headers":{"host":"localhost:8000","accept":"*\/*","user-agent":"curl\/7.64.1"},"method":"GET"},"client_ip":"172.17.0.1","tries":[{"balancer_latency":0,"port":1234,"balancer_start":1606656412521,"ip":"192.168.65.2"}],"upstream_uri":"\/","response":{"headers":{"content-type":"text\/plain; charset=UTF-8","date":"Sun, 29 Nov 2020 13:26:52 GMT","via":"kong\/2.1.3","connection":"close","x-kong-proxy-latency":"1","x-kong-upstream-latency":"1","content-length":"13"},"status":200,"size":"224"},"route":{"id":"fca9ee99-edf2-51ca-bdc8-0714ecf9bb52","path_handling":"v0","paths"

Received packet from 127.0.0.1:55896 -> 127.0.0.1:5000 (local)
{"latencies":{"request":3,"kong":1,"proxy":0},"service":{"host":"host.docker.internal","created_at":1606656019,"connect_timeout":60000,"id":"d7ca8386-6a7e-5bf7-bd63-347609249458","protocol":"http","name":"hello-world","read_timeout":60000,"port":1234,"updated_at":1606656019,"write_timeout":60000,"retries":5,"ws_id":"0dc6f45b-8f8d-40d2-a504-473544ee190b"},"request":{"querystring":{},"size":"83","uri":"\/greet","url":"http:\/\/localhost:8000\/greet","headers":{"host":"localhost:8000","accept":"*\/*","user-agent":"curl\/7.64.1"},"method":"GET"},"client_ip":"172.17.0.1","tries":[{"balancer_latency":0,"port":1234,"balancer_start":1606656422438,"ip":"192.168.65.2"}],"upstream_uri":"\/","response":{"headers":{"content-type":"text\/plain; charset=UTF-8","date":"Sun, 29 Nov 2020 13:27:02 GMT","via":"kong\/2.1.3","connection":"close","x-kong-proxy-latency":"2","x-kong-upstream-latency":"0","content-length":"13"},"status":200,"size":"224"},"route":{"id":"fca9ee99-edf2-51ca-bdc8-0714ecf9bb52","path_handling":"v0","paths"

Note: For some reason the JSON sent when requesting with CURL is invalid (maybe it is missing an assumed header).

gszr commented 3 years ago

@Eyal-Shalev So both requests were successfully logged if you use netcat instead of Logstash?

Eyal-Shalev commented 3 years ago

@gszr no. The request that is logged, is for the /favicon.ico path not for the /greet path - as seen by the logstash reports above. Sorry I did not point that out in the previous comment.

Eyal-Shalev commented 3 years ago

After building a custom UDP logger plugin (that encountered the same issue), I discovered that this is caused by a limit on the UDP packet size (MTU).

This did not come up when I used WireShark, because the limit was set inside the docker container I used to run Kong.

I'm closing this issue, but you guys should probably update the description on the udp-logger that requests won't be logged, if the information passed passes your MTU limit (of any part in the chain from the kong machine to the logger machine).