These are chat archives for fanout/pushpin

28th
Jun 2017
Francis Eytan Dortort
@dortort
Jun 28 2017 05:35 UTC
@jkarneges just ran into the DNS issue again. Having trouble figuring out where it's coming from.
zurl.log says, as before:
[DEBUG] 2017-06-28 05:27:21.206 curl: Added api.---.com:443:52.7.157.102 to DNS cache
[DEBUG] 2017-06-28 05:27:21.206 curl: Found bundle for host api.---.com: 0xe75690 [serially]
[DEBUG] 2017-06-28 05:27:21.206 curl: Hostname api.---.com was found in DNS cache
[DEBUG] 2017-06-28 05:27:21.206 curl:   Trying 52.7.157.102...
[DEBUG] 2017-06-28 05:27:21.206 socketFunction: CURL_POLL_OUT 28
[DEBUG] 2017-06-28 05:27:21.206 timerFunction: wake up in 1ms
[DEBUG] 2017-06-28 05:27:21.207 curl: Connected to api.---.com (52.7.157.102) port 443 (#6999)
[DEBUG] 2017-06-28 05:27:21.207 curl: ALPN, offering http/1.1
[DEBUG] 2017-06-28 05:27:21.207 curl: Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
[DEBUG] 2017-06-28 05:27:21.214 curl: successfully set certificate verify locations:
[DEBUG] 2017-06-28 05:27:21.214 curl:   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
[DEBUG] 2017-06-28 05:27:21.214 curl: TLSv1.2 (OUT), TLS header, Certificate Status (22):
[DEBUG] 2017-06-28 05:27:21.214 curl: TLSv1.2 (OUT), TLS handshake, Client hello (1):
[DEBUG] 2017-06-28 05:27:21.214 socketFunction: CURL_POLL_IN 28
[DEBUG] 2017-06-28 05:27:21.214 timerFunction: wake up in 192ms
[DEBUG] 2017-06-28 05:27:21.214 curl: TLSv1.2 (IN), TLS handshake, Server hello (2):
[DEBUG] 2017-06-28 05:27:21.216 curl: TLSv1.2 (IN), TLS handshake, Certificate (11):
[DEBUG] 2017-06-28 05:27:21.216  subjectAltName does not match api.---.com

[WARN] 2017-06-28 05:27:21.216 SSL: no alternative certificate subject name matches target host name 'api.---.com'
[DEBUG] 2017-06-28 05:27:21.216 curl: TLSv1.2 (OUT), TLS alert, Server hello (2):
[DEBUG] 2017-06-28 05:27:21.216 curl: SSL certificate problem: subject issuer mismatch
[DEBUG] 2017-06-28 05:27:21.216 curl: Closing connection 6999
[DEBUG] 2017-06-28 05:27:21.216 curl: TLSv1.2 (OUT), TLS alert, Client hello (1):
[DEBUG] 2017-06-28 05:27:21.217 socketFunction: CURL_POLL_REMOVE 28
[DEBUG] 2017-06-28 05:27:21.217 message: CURLMSG_DONE
[DEBUG] 2017-06-28 05:27:21.217 curl result: 60
Francis Eytan Dortort
@dortort
Jun 28 2017 05:42 UTC
So I restart the pushpin service from within the container, but still the same DNS resolution and error:
root@0185e3ea2416:/# /etc/init.d/pushpin restart
 * Restarting pushpin pushpin
   ...done.
[DEBUG] 2017-06-28 05:40:50.983 recv-init: { "uri": "https://api.---.com/", "id": "194db56f-a3d8-4a74-ab6d-399062ade990", "ignore-policies": true, "stream": true, "connect-host": "api.---.com", "method": "GET", "seq": 0, "from": "pushpin-proxy_11", "connect-port": 443, "credits": 200000, "ext": { "multi": true }, "headers": [ [ "User-Agent", "ELB-HealthChecker/2.0" ], [ "Grip-Sig", "eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjE0OTg2MzIwNTAsImlzcyI6InB1c2hwaW4ifQ.tjmxZkRjKNV6lrjyDJoHzheaumYnjpUkaeGMLx8I2PQ" ], [ "Grip-Feature", "status" ], [ "Host", "api.---.com" ] ] }
[INFO] 2017-06-28 05:40:50.983 IN id=194db56f-a3d8-4a74-ab6d-399062ade990, GET https://api.---.com/
[DEBUG] 2017-06-28 05:40:50.983 resolving: [api.---.com]
[DEBUG] 2017-06-28 05:40:50.983 send: { "id": "194db56f-a3d8-4a74-ab6d-399062ade990", "type": "keep-alive", "seq": 0, "from": "{0f3d8a7d-b362-449c-9c7b-f504639a0631}" }
[DEBUG] 2017-06-28 05:40:50.983 trying 52.87.28.76
[DEBUG] 2017-06-28 05:40:50.984 timerFunction: wake up in 1ms
[DEBUG] 2017-06-28 05:40:50.984 timerFunction: wake up in 1ms
[DEBUG] 2017-06-28 05:40:50.985 curl: Added api.---.com:443:52.87.28.76 to DNS cache
[DEBUG] 2017-06-28 05:40:50.985 curl: Hostname api.---.com was found in DNS cache
[DEBUG] 2017-06-28 05:40:50.985 curl:   Trying 52.87.28.76...
[DEBUG] 2017-06-28 05:40:50.985 socketFunction: CURL_POLL_OUT 27
[DEBUG] 2017-06-28 05:40:50.985 timerFunction: wake up in 1ms
[DEBUG] 2017-06-28 05:40:50.986 timerFunction: wake up in 198ms
[DEBUG] 2017-06-28 05:40:51.176 timerFunction: wake up in 9ms
[DEBUG] 2017-06-28 05:40:51.185 timerFunction: wake up in 1ms
[DEBUG] 2017-06-28 05:40:51.719 recv-init: { "uri": "https://api.---.com/", "id": "da375da5-078f-4019-af78-f3eb606e1963", "ignore-policies": true, "stream": true, "connect-host": "api.---.com", "method": "GET", "seq": 0, "from": "pushpin-proxy_11", "connect-port": 443, "credits": 200000, "ext": { "multi": true }, "headers": [ [ "User-Agent", "ELB-HealthChecker/2.0" ], [ "Grip-Sig", "eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjE0OTg2MzIwNTEsImlzcyI6InB1c2hwaW4ifQ.uGxPOAhRwq25_6LGHoUYyobMNb6SnL2d0wEUselYkhk" ], [ "Grip-Feature", "status" ], [ "Host", "api.---.com" ] ] }
[INFO] 2017-06-28 05:40:51.720 IN id=da375da5-078f-4019-af78-f3eb606e1963, GET https://api.---.com/
[DEBUG] 2017-06-28 05:40:51.720 resolving: [api.---.com]
[DEBUG] 2017-06-28 05:40:51.720 send: { "id": "da375da5-078f-4019-af78-f3eb606e1963", "type": "keep-alive", "seq": 0, "from": "{0f3d8a7d-b362-449c-9c7b-f504639a0631}" }
[DEBUG] 2017-06-28 05:40:51.720 trying 52.7.157.102
[DEBUG] 2017-06-28 05:40:51.720 timerFunction: wake up in 1ms
[DEBUG] 2017-06-28 05:40:51.720 timerFunction: wake up in 1ms
[DEBUG] 2017-06-28 05:40:51.721 curl: Added api.---.com:443:52.7.157.102 to DNS cache
[DEBUG] 2017-06-28 05:40:51.721 curl: Found bundle for host api.---.com: 0xea4970 [serially]
[DEBUG] 2017-06-28 05:40:51.722 curl: Hostname api.---.com was found in DNS cache
[DEBUG] 2017-06-28 05:40:51.722 curl:   Trying 52.7.157.102...
[DEBUG] 2017-06-28 05:40:51.722 socketFunction: CURL_POLL_OUT 28
[DEBUG] 2017-06-28 05:40:51.722 timerFunction: wake up in 1ms
[DEBUG] 2017-06-28 05:40:51.722 curl: Connected to api.---.com (52.7.157.102) port 443 (#7162)
[DEBUG] 2017-06-28 05:40:51.722 curl: ALPN, offering http/1.1
[DEBUG] 2017-06-28 05:40:51.722 curl: Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
[DEBUG] 2017-06-28 05:40:51.729 curl: successfully set certificate verify locations:
[DEBUG] 2017-06-28 05:40:51.729 curl:   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
[DEBUG] 2017-06-28 05:40:51.729 curl: TLSv1.2 (OUT), TLS header, Certificate Status (22):
[DEBUG] 2017-06-28 05:40:51.729 curl: TLSv1.2 (OUT), TLS handshake, Client hello (1):
[DEBUG] 2017-06-28 05:40:51.729 socketFunction: CURL_POLL_IN 28
[DEBUG] 2017-06-28 05:40:51.729 timerFunction: wake up in 192ms
[DEBUG] 2017-06-28 05:40:51.730 curl: TLSv1.2 (IN), TLS handshake, Server hello (2):
[DEBUG] 2017-06-28 05:40:51.731 curl: TLSv1.2 (IN), TLS handshake, Certificate (11):
[DEBUG] 2017-06-28 05:40:51.732  subjectAltName does not match api.---.com

[WARN] 2017-06-28 05:40:51.732 SSL: no alternative certificate subject name matches target host name 'api.---.com'
[DEBUG] 2017-06-28 05:40:51.732 curl: TLSv1.2 (OUT), TLS alert, Server hello (2):
[DEBUG] 2017-06-28 05:40:51.732 curl: SSL certificate problem: subject issuer mismatch
[DEBUG] 2017-06-28 05:40:51.732 curl: Closing connection 7162
[DEBUG] 2017-06-28 05:40:51.732 curl: TLSv1.2 (OUT), TLS alert, Client hello (1):
[DEBUG] 2017-06-28 05:40:51.733 socketFunction: CURL_POLL_REMOVE 28
[DEBUG] 2017-06-28 05:40:51.733 message: CURLMSG_DONE
[DEBUG] 2017-06-28 05:40:51.733 curl result: 60
[DEBUG] 2017-06-28 05:40:51.733 timerFunction: cancel timer
[DEBUG] 2017-06-28 05:40:51.733 trying 52.87.28.76
[DEBUG] 2017-06-28 05:40:51.733 timerFunction: wake up in 1ms
[DEBUG] 2017-06-28 05:40:51.733 timerFunction: wake up in 1ms
[DEBUG] 2017-06-28 05:40:51.735 curl: Added api.---.com:443:52.87.28.76 to DNS cache
[DEBUG] 2017-06-28 05:40:51.735 curl: Found bundle for host api.---.com: 0xea4970 [serially]
[DEBUG] 2017-06-28 05:40:51.735 curl: Hostname api.---.com was found in DNS cache
[DEBUG] 2017-06-28 05:40:51.735 curl:   Trying 52.87.28.76...
[DEBUG] 2017-06-28 05:40:51.735 socketFunction: CURL_POLL_OUT 28
[DEBUG] 2017-06-28 05:40:51.735 timerFunction: wake up in 1ms
[DEBUG] 2017-06-28 05:40:51.736 timerFunction: wake up in 198ms
[DEBUG] 2017-06-28 05:40:51.926 timerFunction: wake up in 9ms
[DEBUG] 2017-06-28 05:40:51.935 timerFunction: wake up in 1ms
[DEBUG] 2017-06-28 05:40:55.986 recv-stream: { "id": "194db56f-a3d8-4a74-ab6d-399062ade990", "type": "cancel", "seq": 1, "from": "pushpin-proxy_11" }
[DEBUG] 2017-06-28 05:40:55.986 curl: Closing connection 7161
[DEBUG] 2017-06-28 05:40:55.986 socketFunction: CURL_POLL_REMOVE 27
[DEBUG] 2017-06-28 05:40:56.723 recv-stream: { "id": "da375da5-078f-4019-af78-f3eb606e1963", "type": "cancel", "seq": 1, "from": "pushpin-proxy_11" }
[DEBUG] 2017-06-28 05:40:56.723 curl: Closing connection 7163
[DEBUG] 2017-06-28 05:40:56.723 socketFunction: CURL_POLL_REMOVE 28
Francis Eytan Dortort
@dortort
Jun 28 2017 06:02 UTC
A simple CURL from within the container works though:
[root@hostname pushpin]# docker exec -it 0185e3ea2416 bash
root@0185e3ea2416:/# curl -v https://api.---.com/
*   Trying 34.199.213.109...
* Connected to api.---.com (34.199.213.109) port 443 (#0)
* found 173 certificates in /etc/ssl/certs/ca-certificates.crt
* found 692 certificates in /etc/ssl/certs
* ALPN, offering http/1.1
* SSL connection using TLS1.2 / ECDHE_RSA_AES_128_GCM_SHA256
*      server certificate verification OK
*      server certificate status verification SKIPPED
*      common name: ---.com (matched)
*      server certificate expiration date OK
*      server certificate activation date OK
*      certificate public key: RSA
*      certificate version: #3
*      subject: CN=---.com
*      start date: Tue, 31 Jan 2017 00:00:00 GMT
*      expire date: Wed, 28 Feb 2018 12:00:00 GMT
*      issuer: C=US,O=Amazon,OU=Server CA 1B,CN=Amazon
*      compression: NULL
* ALPN, server did not agree to a protocol
> GET / HTTP/1.1
> Host: api.---.com
> User-Agent: curl/7.47.0
> Accept: */*
> 
< HTTP/1.1 200 OK
< Access-Control-Allow-Methods: GET,POST,PUT,PATCH,DELETE,OPTIONS
< Access-Control-Allow-Origin: *
< Cache-Control: no-cache
< Content-Type: text/plain; charset=UTF-8
< Date: Wed, 28 Jun 2017 05:29:11 GMT
< Server: Apache
< Vary: Accept,Accept-Encoding,X-Token
< transfer-encoding: chunked
< Connection: keep-alive
< 
* Connection #0 to host api.---.com left intact
OK
It resolves to the correct IP.
Any ideas?
Justin Karneges
@jkarneges
Jun 28 2017 07:06 UTC
when you restart pushpin, is zurl also being restarted?
(you'll know if it says "started" in the logs)
if you dig the domain, what's the ttl?
what's /etc/resolv.conf look like, and also /etc/nsswitch.conf
Justin Karneges
@jkarneges
Jun 28 2017 07:22 UTC
if zurl is restarting, then I'm certain this isn't a zurl-level caching issue, but it could be an external cache that for some reason zurl uses but other programs don't, due to the way zurl's resolver (jdns) works
basically, jdns always uses udp to contact a dns server listed in /etc/resolv.conf
if docker hijacks native OS methods like gethostbyname and does something else with those calls then I could see how different programs could get different results
(hence the suggestion about nsswitch which is where those overrides usually are I believe)
Francis Eytan Dortort
@dortort
Jun 28 2017 12:14 UTC
/etc/resolv.conf
options timeout:2 attempts:5
; generated by /sbin/dhclient-script
search ec2.internal
nameserver 172.31.0.2
/etc/nsswitch.conf
# /etc/nsswitch.conf
#
# Example configuration of GNU Name Service Switch functionality.
# If you have the `glibc-doc-reference' and `info' packages installed, try:
# `info libc "Name Service Switch"' for information about this file.

passwd:         compat
group:          compat
shadow:         compat
gshadow:        files

hosts:          files dns
networks:       files

protocols:      db files
services:       db files
ethers:         db files
rpc:            db files

netgroup:       nis
the TTL is 60
In which log file should it say "started"? I can't find it
Francis Eytan Dortort
@dortort
Jun 28 2017 12:19 UTC
root@0185e3ea2416:/# /etc/init.d/pushpin restart; /etc/init.d/zurl restart; tail -f /var/log/pushpin/*.log | grep -i start  
 * Restarting pushpin pushpin
   ...done.
 * Restarting zurl zurl
   ...done.
Mon, 19 Jun 2017 18:57:35 GMT [INFO] (src/mongrel2.c:229) -- Starting Mongrel2/1.11.0. Copyright (C) Zed A. Shaw. Licensed BSD.
Mon, 19 Jun 2017 18:57:35 GMT [INFO] (src/mongrel2.c:230) -- Look in /var/log/pushpin/error_7999.log for startup messages and errors.
Justin Karneges
@jkarneges
Jun 28 2017 14:31 UTC
in your case it would be in zurl's log
which I think must be /var/log/zurl.log. zurl can be either managed by pushpin or managed by the OS. if there isn't a zurl.log in /var/log/pushpin, then zurl must be running as a separate service managed by the OS, so probably it only gets restarted when you run "service zurl restart"
Francis Eytan Dortort
@dortort
Jun 28 2017 15:36 UTC
there seems to be an issue restarting zurl:
root@0185e3ea2416:/# service zurl status                     
 * zurl is running
root@0185e3ea2416:/# service zurl stop  
root@0185e3ea2416:/# service zurl status
 * zurl is running
root@0185e3ea2416:/# service zurl restart
 * Restarting zurl zurl
   ...done.
root@0185e3ea2416:/# grep -i start /var/log/pushpin/zurl.log 
[DEBUG] 2017-06-28 15:12:35.470 curl:      start date: Apr 15 22:08:00 2017 GMT
[DEBUG] 2017-06-28 15:27:35.480 curl:      start date: Apr 15 22:08:00 2017 GMT
Justin Karneges
@jkarneges
Jun 28 2017 17:11 UTC
oh, so you have /var/log/pushpin/zurl.log. pushpin must be managing zurl itself then
probably "service zurl start" manages an independent zurl instance not being used by pushpin
very strange that restarting pushpin doesn't appear to log a starting message in /var/log/pushpin/zurl.log though
does pushpin-proxy.log show a start message?
you might also check the process list for pushpin-proxy and zurl and see if the pids change after running "service pushpin restart"