OS-4525: lxbrand implement getsockopt(TCP_INFO)

Details

Issue Type:Bug
Priority:5 - Low
Status:Open
Created at:2015-07-20T19:28:04.000Z
Updated at:2019-09-03T20:22:18.024Z

People

Created by:Former user
Reported by:Former user

Labels

lxbrand

Description

I think I figured out the root cause. There is no log output for tutum/hello-world. In Linux, this just shows a blank line.

This is illustrated with this simple command:

➜  haproxy-bug  docker run -it tutum/hello-world
[20-Jul-2015 19:40:44] ERROR: failed to retrieve TCP_INFO for socket: Protocol not available (92)

Original steps, left for historical purposes:

1. Used docker-compose to spin up two containers that are linked to each other.
2. Attempted to view the logs on one container (dekobon/bouncy-haproxy). There were no problems.
3. Attempted to view the logs on the other container (tutum/hello-world). There were problems as listed below.

  haproxy-bug  docker-compose -p hatest up -d
Creating hatest_site_1...
Creating hatest_lb_1...
➜  haproxy-bug  # ok. This is a huge divergence.
➜  haproxy-bug  # Docker logs should show all of the logs since container start...
➜  haproxy-bug  # let's see if we can get them without using docker-compose
➜  haproxy-bug  docker logs hatest_lb_1
*** Running /etc/my_init.d/00_regen_ssh_host_keys.sh...
*** Running /etc/rc.local...
*** Booting runit daemon...
*** Runit started as PID 5863
ok: run: syslog-ng: (pid 5874) 0s
Jul 20 18:50:02 215639fdfa0c syslog-ng[5874]: syslog-ng starting up; version='3.5.3'
Jul 20 18:50:04 127.0.0.1 haproxy[6335]: Proxy stats started.
Jul 20 18:50:04 127.0.0.1 haproxy[6335]: Proxy stats started.
Jul 20 18:50:04 127.0.0.1 haproxy[6335]: Proxy http-in started.
Jul 20 18:50:04 127.0.0.1 haproxy[6335]: Proxy http-in started.
Jul 20 18:50:04 127.0.0.1 haproxy[6335]: Proxy servers started.
Jul 20 18:50:04 127.0.0.1 haproxy[6335]: Proxy servers started.
➜  haproxy-bug  docker logs hatest_site_1
[20-Jul-2015 18:48:38] ERROR: failed to retrieve TCP_INFO for socket: Protocol not available (92)
➜  haproxy-bug  docker logs hatest_site_1
[20-Jul-2015 18:48:38] ERROR: failed to retrieve TCP_INFO for socket: Protocol not available (92)
➜  haproxy-bug  # That's weird...
quote>
➜  haproxy-bug  docker-compose -p hatest ps
    Name                   Command               State                    Ports
-------------------------------------------------------------------------------------------------
hatest_lb_1     /sbin/my_init                    Up      0.0.0.0:443->443/tcp, 0.0.0.0:80->80/tcp
hatest_site_1   /bin/sh -c php-fpm -d vari ...   Up      80/tcp
➜  haproxy-bug  docker logs hatest_site_1
[20-Jul-2015 18:48:38] ERROR: failed to retrieve TCP_INFO for socket: Protocol not available (92)
➜  haproxy-bug  docker ps
CONTAINER ID        IMAGE                    COMMAND                CREATED             STATUS              PORTS                                      NAMES
215639fdfa0c        dekobon/bouncy-haproxy   "/sbin/my_init"        2 minutes ago       Up 2 minutes        0.0.0.0:80->80/tcp, 0.0.0.0:443->443/tcp   hatest_lb_1
f3e0956d21cb        tutum/hello-world        "/bin/sh -c 'php-fpm   4 minutes ago       Up 3 minutes        80/tcp                                     hatest_site_1
➜  haproxy-bug  docker logs f3e0956d21cb
[20-Jul-2015 18:48:38] ERROR: failed to retrieve TCP_INFO for socket: Protocol not available (92)

Comments

Comment by Josh Wilsdon
Created at 2015-07-20T20:25:56.000Z
Updated at 2018-05-07T17:50:26.888Z

The error message here:

[20-Jul-2015 18:48:38] ERROR: failed to retrieve TCP_INFO for socket: Protocol not available (92)

is the actual content of the log, so sdc-docker is working correctly here. I've reproduced this myself with:

[joshw@sledgehammer ~]$ docker run -it tutum/hello-world
Unable to find image 'tutum/hello-world:latest' locally
latest: Pulling from tutum/hello-world (5f509591-d423-41ac-a4c3-6fd589a4aee2)
c833a1892a15: Already exists.
5e314245be14: Already exists.
da052ae129c2: Already exists.
a1dd7097a8e8: Already exists.
2e26b130ff1d: Already exists.
01fb4017dfb8: Already exists.
b93eb18c953b: Already exists.
8989fc3642f5: Already exists.
Status: Downloaded newer image for docker.io/tutum/hello-world:latest
[20-Jul-2015 20:02:52] ERROR: failed to retrieve TCP_INFO for socket: Protocol not available (92)

and this VM is happily running. The data in the log on the CN is indeed:

[root@5DVP842 (us-east-3b) ~]# cat /zones/0a6e729d-9036-47a9-a9db-7d289df052ab/logs/stdio.log
{"log":"[20-Jul-2015 20:02:52] ERROR: failed to retrieve TCP_INFO for socket: Protocol not available (92)\r\n","stream":"stdout","time":"2015-07-20T20:02:52.31660000Z"}
[root@5DVP842 (us-east-3b) ~]#

so we're correctly returning the data here. The remaining question is what this image is doing that it's trying to TCP_INFO here and that'll either be a bug with the image or the OS/LX here so I'm moving this to the OS project for now.


Comment by Former user
Created at 2015-07-21T19:38:35.000Z
patrick.mooney:
	ElijahZ: What app is running inside that tutum container?
	The fact that it demands TCP_INFO is unfortunate
jwilsdon:
	pmooney this is what it runs:
	        "Cmd": [
            "/bin/sh",
            "-c",
            "php-fpm -d variables_order=\"EGPCS\" && exec nginx -g \"daemon off;\""
        ],
elijah.zupancic:
	I'm not sure, give me a second
patrick.mooney:
	ah
	probably nginx, then
	I assume the '-d' param on php-fpm will silence its output

Comment by Former user
Created at 2015-07-22T01:33:53.000Z

You can find the Dockerfile definition here: https://registry.hub.docker.com/u/tutum/hello-world/dockerfile/

Hopping on the instance. I have invoked only php-fpm in daemon mode:

  entrypoint-divergence  docker run -it tutum/hello-world sh
/ # php-fpm -d variables_order="EGPCS"
[22-Jul-2015 01:30:00] ERROR: failed to retrieve TCP_INFO for socket: Protocol not available (92)

So, it looks like php-fpm is the culprit.

Using my remedial understanding of dtrace:

/ # /native/usr/sbin/dtrace -n 'syscall:::entry/pid == $target/{@[probefunc] = count();}' -c "php-fpm"
dtrace: description 'syscall:::entry' matched 236 probes
[22-Jul-2015 01:32:43] ERROR: failed to retrieve TCP_INFO for socket: Protocol not available (92)
dtrace: pid 23986 has exited

  access                                                            1
  forksys                                                           1
  getcwd                                                            1
  getpid                                                            1
  getrlimit                                                         1
  memcntl                                                           1
  mmapobj                                                           1
  open                                                              1
  pollsys                                                           1
  rexit                                                             1
  schedctl                                                          1
  sigpending                                                        1
  getuid                                                            2
  lseek                                                             2
  sysconfig                                                         2
  zone                                                              2
  munmap                                                            4
  lwp_cond_broadcast                                                5
  setcontext                                                        5
  fstat                                                             6
  lstat                                                             6
  mprotect                                                          6
  modctl                                                            7
  fcntl                                                             8
  stat                                                              8
  close                                                            16
  mmap                                                             18
  lwp_sigmask                                                      22
  uucopy                                                           28
  brandsys                                                         71
  sigaction                                                        81

Comment by Former user
Created at 2015-07-22T01:47:41.000Z
Updated at 2015-07-22T01:48:07.000Z

See attachment for strace output of php-fpm.


Comment by Former user
Created at 2015-07-22T16:07:49.000Z

@accountid:6245dc81699649006ae71bff Can you confirm if the container running php-fpm is (or is not) functioning properly. From the above notes, the container appears to stay up. I want to differentiate between an error indicating broken service and a printed (but harmless) warning.


Comment by Former user
Created at 2015-07-22T17:15:59.000Z

Just confirmed this doesn't impact hello world functionality. I do wonder, what effects it is having on php-fpm, but it is not a priority.


Comment by Former user
Created at 2015-07-22T17:26:59.000Z

It appears that php uses TCP_INFO to query the queue length on the listening socket. From my cursory glance, it seems to handle failure gracefully.


Comment by Former user
Created at 2019-09-03T20:21:44.418Z
Updated at 2019-09-03T20:22:18.021Z

I took a look at what it would take to implement this a while back. The Linux header file frustratingly leaves the struct undocumented, so I put together a commented version:

typedef struct lx_tcp_info {
	/* Current state in TCP state machine */
	uint8_t		tcpi_state;
	/* Congestion avoidance state */
	uint8_t		tcpi_ca_state;
	/* Number of unrecovered RTO timeouts */
	uint8_t		tcpi_retransmits;
	/* Unanswered 0 window probes */
	uint8_t		tcpi_probes;
	/* Current exponential backoff for RTO */
	uint8_t		tcpi_backoff;
	/* Enabled TCP options */
	uint8_t		tcpi_options;
#define	LX_TCPI_OPT_TIMESTAMPS	0x01	/* Negotiated TCP Timestamps */
#define	LX_TCPI_OPT_SACK	0x02	/* Negotiated SACK */
#define	LX_TCPI_OPT_WSCALE	0x04	/* Negotiated Window Scaling */
#define	LX_TCPI_OPT_ECN		0x08	/* Negotiated ECN */
#define	LX_TCPI_OPT_ECN_SEEN	0x10	/* Received at least 1 packet w/ ECT */
#define	LX_TCPI_OPT_SYN_DATA	0x20	/* Sent or received SYN-ACK for SYN */

	uint8_t
		tcpi_snd_wscale : 4,	/* Send window scale shift */
		tcpi_rcv_wscale : 4;	/* Receive window scale shift */

	/* Whether the application is sending less than the send window */
	uint8_t		tcpi_delivery_rate_app_limited : 1;

	/* Retransmission timeout (usecs) */
	uint32_t	tcpi_rto;
	/* Predicted soft clock tick for delivering delayed ACK */
	uint32_t	tcpi_ato;
	/* Maximum Segment Size, sent (RFC 4898 tcpEStatsStackMSSSent) */
	uint32_t	tcpi_snd_mss;
	/* Maximum Segment Size, received (RFC 4898 tcpEStatsStackMSSRcvd) */
	uint32_t	tcpi_rcv_mss;

	/* Sent but unacknowledged bytes */
	uint32_t	tcpi_unacked;
	/* # of SACKed packets; without SACK, # of recvd dup packets */
	uint32_t	tcpi_sacked;
	/* Estimated # of packets lost */
	uint32_t	tcpi_lost;
	/* Total # of rexmitted segments */
	uint32_t	tcpi_retrans;
	/* # of packets to highest SACKed sequence (deprecated on Linux) */
	uint32_t	tcpi_fackets;

	/* Time (msecs) since last sent data */
	uint32_t	tcpi_last_data_sent;
	/* Time (msecs) since last sent ACK (not filled in on Linux) */
	uint32_t	tcpi_last_ack_sent;
	/* Time (msecs) since last recv data */
	uint32_t	tcpi_last_data_recv;
	/* Time (msecs) since last recv ACK */
	uint32_t	tcpi_last_ack_recv;

	/* Last PMTU seen by socket */
	uint32_t	tcpi_pmtu;
	/* Slow start threshold (recv) */
	uint32_t	tcpi_rcv_ssthresh;
	/* Smoothed RTT (usecs) */
	uint32_t	tcpi_rtt;
	/* RTT variance (usecs) */
	uint32_t	tcpi_rttvar;
	/* Slow start threshold (send) */
	uint32_t	tcpi_snd_ssthresh;
	/* Send congestion window */
	uint32_t	tcpi_snd_cwnd;
	/* Advertised MSS */
	uint32_t	tcpi_advmss;
	/* ? */
	uint32_t	tcpi_reordering;

	/* ? */
	uint32_t	tcpi_rcv_rtt;
	/* Advertised recv window */
	uint32_t	tcpi_rcv_space;

	/* Total # of rexmitted segments for connection */
	uint32_t	tcpi_total_retrans;

	/* ? */
	uint64_t	tcpi_pacing_rate;
	/* ? */
	uint64_t	tcpi_max_pacing_rate;
	/* RFC 4898 tcpEStatsAppHCThruOctetsAcked */
	uint64_t	tcpi_bytes_acked;
	/* RFC 4898 tcpEStatsAppHCThruOctetsReceived */
	uint64_t	tcpi_bytes_received;
	/* RFC 4898 tcpEStatsPerfSegsOut */
	uint32_t	tcpi_segs_out;
	/* RFC 4898 tcpEStatsPerfSegsIn */
	uint32_t	tcpi_segs_in;
	/* Current # of unsent bytes */
	uint32_t	tcpi_notsent_bytes;
	/* Minimum observed RTT */
	uint32_t	tcpi_min_rtt;
	/* RFC 4898 tcpEStatsDataSegsIn */
	uint32_t	tcpi_data_segs_in;
	/* RFC 4898 tcpEStatsDataSegsOut */
	uint32_t	tcpi_data_segs_out;
	/* ? */
	uint64_t	tcpi_delivery_rate;
	/* Time (usecs) busy sending data */
	uint64_t	tcpi_busy_time;
	/* Time (usecs) limited by received window */
	uint64_t	tcpi_rwnd_limited;
	/* Time (usecs) limited by send buffer */
	uint64_t	tcpi_sndbuf_limited;

	/* Total # of data packets delivered to peer, including rexmits */
	uint32_t	tcpi_delivered;
	/* Same as the above field, but only counts ECE-marked packets */
	uint32_t	tcpi_delivered_ce;

	/* RFC 4898 tcpEStatsPerfHCDataOctetsOut */
	uint64_t	tcpi_bytes_sent;
	/* Total # of bytes rexmitted (RFC 4898 tcpEStatsPerfOctetsRetrans) */
	uint64_t	tcpi_bytes_retrans;
	/* RFC 4898 tcpEStatsStackDSACKDups */
	uint32_t	tcpi_dsack_dups;
	/* # of reordering events seen */
	uint32_t	tcpi_reord_seen;
} lx_tcp_info_t;

Note that when TCP_INFO is used on a listening socket, tcpi_unacked is the current backlog length, and tcpi_sacked is the maximum allowed backlog length.

I also took a look at what fields different software looks at: