Trying to get access logging to work

[nepa...@gmail.com]

Hi,

First time posting here.

I'm trying to track down an issue with using SSL and Envoy but I'm not having any luck with getting the access logging to work correctly.

I'm running Envoy using Docker and I've managed to get things working correctly in the non SSL case but now I want to add SSL and I can't seem to make that work so I'm trying to use access logging to debug my SSL problem but I'm having no luck making the access logging work.

I've read thru all the docs, but they aren't a lot of useful examples or samples to follow for logging. The admin access logging is working, but not the normal access logging.

I've included my envoy.yaml file. Can someone point me in the right direction.

Thanks in advance.

Nick

my envoy.yaml file:

admin:

  access_log_path: /tmp/admin_access.log

  address:

    socket_address: { address: 0.0.0.0, port_value: 9901 }

static_resources:

  listeners:

    - name: listener_0

      address:

        socket_address: { address: 0.0.0.0, port_value: 8090 }

      filter_chains:

        - filters:

            - name: envoy.http_connection_manager

              config:            

                codec_type: auto

                stat_prefix: ingress_http

                route_config:

                  name: local_route

                  virtual_hosts:

                    - name: local_service

                      domains: 

                      - "coxos.testdomain.com"

                      routes:

                        - match: { prefix: "/" }

                          route:

                            cluster: controlweb_backendservice

                            max_grpc_timeout: 0s

                      cors:

                        allow_origin_string_match:

                          - prefix: "*"

                        allow_methods: GET, PUT, DELETE, POST, OPTIONS

                        allow_headers: keep-alive,user-agent,cache-control,content-type,content-transfer-encoding,access-token,x-accept-content-transfer-encoding,x-accept-response-streaming,x-user-agent,x-grpc-web,grpc-timeout

                        max_age: "1728000"

                        expose_headers: access-token,grpc-status,grpc-message

                http_filters:

                  - name: envoy.grpc_web

                  - name: envoy.cors

                  - name: envoy.router

                access_log:

                - name: envoy.file_access_log

                  config:

                    path: "/tmp/access_error.log"                  

          tls_context:

            common_tls_context:

              tls_certificates:

                - certificate_chain:

                    filename: "/etc/coxos.crt"

                  private_key:

                    filename: "/etc/coxos.key"

  clusters:

    - name: controlweb_backendservice

      connect_timeout: 0.25s

      type: logical_dns

      http2_protocol_options: {}

      lb_policy: round_robin

      hosts: [{ socket_address: { address: 172.55.22.109, port_value: 50251 } }]

[Stephan Zuercher]

If SSL is not working (e.g. if the connections are being terminated by either the server or the client before an http request is sent) then the HTTP connection manager will not come into play and the access log will not be of use. Envoy logs diagnostic information to the console by default and you can set the log level (e.g. with "-l debug" or "-l trace" or via the admin listener) to get more verbose log output. That might help diagnose the problem.

You might also try "openssl s_client -connect <host:port>" and see if that sheds light on the problem.

--
You received this message because you are subscribed to the Google Groups "envoy-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to envoy-users...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/envoy-users/d1df8128-8843-429c-a72c-26a8e39cf1e9%40googlegroups.com.

[nepa...@gmail.com]

Hi, 

Thanks for the response.  

That makes perfect sense. I'm not sure if I'm even getting to the Envoy proxy so that's why I'm trying to figure it out.

Sorry to sound dumb but how would I set/turn on the "-l debug" or "-l trace" logging settings?  If I go to the admin listener I can see the logging levels are all set to info:

active loggers: admin: info aws: info assert: info backtrace: info client: info config: info

When I execute the openssl command I get this:

openssl s_client -connect coxos:8090

CONNECTED(00000003)

Can't use SSL_get_servername

depth=0 C = US, ST = CA, L = Hometown, O = Company, OU = Org, CN = coxos.Orgcorp.com, emailAddress = webm...@Orgcorp.com

verify error:num=18:self signed certificate

verify return:1

depth=0 C = US, ST = CA, L = Hometown, O = Company, OU = Org, CN = coxos.Orgcorp.com, emailAddress = webm...@Orgcorp.com

verify return:1

---

Certificate chain

 0 s:C = US, ST = CA, L = Hometown, O = Company, OU = Org, CN = coxos.Orgcorp.com, emailAddress = webm...@Orgcorp.com

   i:C = US, ST = CA, L = Hometown, O = Company, OU = Org, CN = coxos.Orgcorp.com, emailAddress = webm...@Orgcorp.com

---

Server certificate

-----BEGIN CERTIFICATE-----

MII60= - cert info

-----END CERTIFICATE-----

subject=C = US, ST = CA, L = Hometown, O = Company, OU = Org, CN = coxos.Orgcorp.com, emailAddress = webm...@Orgcorp.com

issuer=C = US, ST = CA, L = Hometown, O = Company, OU = Org, CN = coxos.Orgcorp.com, emailAddress = webm...@Orgcorp.com

---

No client certificate CA names sent

Peer signing digest: SHA256

Peer signature type: RSA-PSS

Server Temp Key: X25519, 253 bits

---

SSL handshake has read 2299 bytes and written 363 bytes

Verification error: self signed certificate

---

New, TLSv1.3, Cipher is TLS_AES_256_GCM_SHA384

Server public key is 4096 bit

Secure Renegotiation IS NOT supported

Compression: NONE

Expansion: NONE

No ALPN negotiated

Early data was not sent

Verify return code: 18 (self signed certificate)

---

To unsubscribe from this group and stop receiving emails from it, send an email to envoy...@googlegroups.com.

[Stephan Zuercher]

Those are command line flags. Or you can post to /logging?level=debug (or trace). See https://www.envoyproxy.io/docs/envoy/latest/operations/admin.html#post--logging

The s_client response looks fine assuming you actually used a self-signed cert. Will your client accept a self-signed cert? What error do you see there?

Stephan

On Jun 1, 2020, at 2:30 PM, nepa...@gmail.com wrote:



To unsubscribe from this group and stop receiving emails from it, send an email to envoy-users...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/envoy-users/806245ea-776d-4828-bca5-41d18802c65b%40googlegroups.com.

[nepa...@gmail.com]

Hi Stephan,

Thanks for the info.  i've read the link you provided, but I'm kinda dense with some of this stuff.  How would I use post to send the command?  Would I use curl to send the command to the envoy admin address?  Also, where would I see the output?  Envoy is running in a docker so I'm assuming the output would be somewhere on the docker right?

And I am using a self-signed cert which our app will accept.  I'm currently running with the runtime software so I can't see the exact error. I'm trying to get a debugging environment setup so I can try and see the actual error.

Thanks

To view this discussion on the web visit https://groups.google.com/d/msgid/envoy-users/806245ea-776d-4828-bca5-41d18802c65b%40googlegroups.com.

[nepa...@gmail.com]

I tried the following command with no luck

 curl -d "/logging?level=trace" -X POST http://coxos:9901

Also, is there any issue with using self-signed certs?  The example I followed for how to configure SSL created a self signed cert but I'm not sure where the error is happening so not sure if the self signed cert is the issue.

I'm not getting any error in my application code so that makes me think this is an envoy config issue but can't seem to figure out where.

Thanks

To view this discussion on the web visit https://groups.google.com/d/msgid/envoy-users/806245ea-776d-4828-bca5-41d18802c65b%40googlegroups.com.

[Stephan Zuercher]

"curl -X POST http://coxos:9901/logging?level=debug" is what you want. The output will be written to Envoy's stdout (I think it's stdout, not stderr, but I might be mistaken). How to see that will depend on how you're running Envoy.

To unsubscribe from this group and stop receiving emails from it, send an email to envoy-users...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/envoy-users/89db73d4-0ac3-4f94-8b34-4a83fd8bfedf%40googlegroups.com.

[nepa...@gmail.com]

Ok that worked!  I can now see the log info when I try and connect.  Here is what I'm getting when I try and connect using SSL

Debug

[2020-06-03 15:37:52.620][18][debug][conn_handler] [source/server/connection_handler_impl.cc:335] [C6] new connection

[2020-06-03 15:37:52.649][18][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C6] handshake expecting read

[2020-06-03 15:37:52.649][18][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C6] handshake expecting read

[2020-06-03 15:37:52.669][18][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:198] [C6] handshake error: 5

[2020-06-03 15:37:52.669][18][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:226] [C6]

[2020-06-03 15:37:52.669][18][debug][connection] [source/common/network/connection_impl.cc:193] [C6] closing socket: 0

[2020-06-03 15:37:52.669][18][debug][conn_handler] [source/server/connection_handler_impl.cc:88] [C6] adding to cleanup list

[2020-06-03 15:37:53.771][7][debug][upstream] [source/common/upstream/logical_dns_cluster.cc:72] starting async DNS resolution for 172.16.0.109

[2020-06-03 15:37:53.771][7][debug][upstream] [source/common/upstream/logical_dns_cluster.cc:79] async DNS resolution complete for 172.16.0.109

[2020-06-03 15:37:54.144][7][debug][main] [source/server/server.cc:175] flushing stats

Trace

[2020-06-03 15:47:31.470][18][debug][conn_handler] [source/server/connection_handler_impl.cc:335] [C9] new connection

[2020-06-03 15:47:31.470][18][trace][connection] [source/common/network/connection_impl.cc:462] [C9] socket event: 3

[2020-06-03 15:47:31.470][18][trace][connection] [source/common/network/connection_impl.cc:550] [C9] write ready

[2020-06-03 15:47:31.498][18][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C9] handshake expecting read

[2020-06-03 15:47:31.498][18][trace][connection] [source/common/network/connection_impl.cc:500] [C9] read ready

[2020-06-03 15:47:31.498][18][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C9] handshake expecting read

[2020-06-03 15:47:31.503][18][trace][connection] [source/common/network/connection_impl.cc:462] [C9] socket event: 3

[2020-06-03 15:47:31.503][18][trace][connection] [source/common/network/connection_impl.cc:550] [C9] write ready

[2020-06-03 15:47:31.503][18][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:198] [C9] handshake error: 5

[2020-06-03 15:47:31.503][18][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:226] [C9]

[2020-06-03 15:47:31.503][18][debug][connection] [source/common/network/connection_impl.cc:193] [C9] closing socket: 0

[2020-06-03 15:47:31.503][18][debug][conn_handler] [source/server/connection_handler_impl.cc:88] [C9] adding to cleanup list

[2020-06-03 15:47:31.503][18][trace][main] [source/common/event/dispatcher_impl.cc:160] item added to deferred deletion list (size=1)

[2020-06-03 15:47:31.503][18][trace][main] [source/common/event/dispatcher_impl.cc:79] clearing deferred deletion list (size=1)

[2020-06-03 15:47:33.821][7][debug][upstream] [source/common/upstream/logical_dns_cluster.cc:72] starting async DNS resolution for 172.16.0.109

[2020-06-03 15:47:33.821][7][debug][upstream] [source/common/upstream/logical_dns_cluster.cc:79] async DNS resolution complete for 172.16.0.109

[2020-06-03 15:47:34.203][7][debug][main] [source/server/server.cc:175] flushing stats

[2020-06-03 15:47:38.821][7][debug][upstream] [source/common/upstream/logical_dns_cluster.cc:72] starting async DNS resolution for 172.16.0.109

[2020-06-03 15:47:38.821][7][debug][upstream] [source/common/upstream/logical_dns_cluster.cc:79] async DNS resolution complete for 172.16.0.109

[2020-06-03 15:47:39.202][7][debug][main] [source/server/server.cc:175] flushing stats

So the question is, what is handshake error: 5?

I looked at the envoy source and based on the line number this appears to be the default error case 

To view this discussion on the web visit https://groups.google.com/d/msgid/envoy-users/89db73d4-0ac3-4f94-8b34-4a83fd8bfedf%40googlegroups.com.

[Stephan Zuercher]

That "5" means an error occurred inside the boringSSL library while reading from the socket and the fact that it reports expecting to be able to read twice makes me think the client is closing the connection when Envoy is expecting SSL handshake data.

To unsubscribe from this group and stop receiving emails from it, send an email to envoy-users...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/envoy-users/5b533c64-15fe-4fb1-ab94-517d1fc7b1a5%40googlegroups.com.

[nepa...@gmail.com]

Ok thanks for the explanation.  Maybe I should take a step back and explain what we are trying to do.

Here is a rough picture of how we are using envoy

+------------------------------------+

|                                             |

| User (Browser, gRPC-web)|

|                                             |

+------------------------------------+

               |

               | SSL

               |

+------------------------------------+

|                                             |

| Envoy proxy                        |

|                                             |

+------------------------------------+               

               |

               | Is SSL required here as well?

               |

+------------------------------------+

|                                             |

| Downstream gRPC server  |

|                                             |

+------------------------------------+

So right now we have SSL configured using envoy between the client and envoy.  Do we also need to configure SSL between envoy and the downstream gRPC server as well?  Or another way to say that, do downstream servers from Envoy require SSL connections also?  Is this why we are seeing the handshake error: 5?

Do you know if there is an example of getting Grpc-Web on the browser to connect successfully to Envoy using SSL  (using the tls_context in the .yaml file)?

Thanks

To view this discussion on the web visit https://groups.google.com/d/msgid/envoy-users/5b533c64-15fe-4fb1-ab94-517d1fc7b1a5%40googlegroups.com.

[Stephan Zuercher]

Envoy does not require you to use SSL for its connection to the upstream host. It can be configured, similar to how you've configured the downstream TLS context. The upstream grpc server might require SSL, however. In any event, I don't think you're getting that far.

The downstream client may require SSL and may, by default, attempt to validate the certificate using a CA certificates installed on the client host. For instance, go-grpc has a WithInsecure DialOption to disable SSL on the client. I believe you need to create a tls.Config{InsecureSkipVerify: true} and use it with the WithTransportCredentials DialOption to disable certificate validation for a self-signed certificate. Not sure what the defaults for other implementations are or how to configure them. I would expect to see connect errors on the client side, though.

To unsubscribe from this group and stop receiving emails from it, send an email to envoy-users...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/envoy-users/cb75474a-f4e7-4067-a568-63d9baad1cb7%40googlegroups.com.