Fluentd: sometimes out_forward heartbeat(tcp) failed with fluentd>0.14.9
sometimes out_forward heartbeat(tcp) failed
when sender fluentd: 0.14.11 and 0.14.13
aggregator fluentd: 0.14.11 and 0.14.13
This problem does not have occurred in sender v0.14.8.
fluentd.log
2017-03-01 06:49:37 +0000 [warn]: recovered forwarding server '' host="log-aggregator.local" port=10224
2017-03-01 06:49:37 +0000 [warn]: recovered forwarding server '' host="log-aggregator.local" port=10224
2017-03-01 06:49:45 +0000 [warn]: retry succeeded. chunk_id="549a573de08a4928f31d10f236155293"
2017-03-01 06:49:51 +0000 [warn]: retry succeeded. chunk_id="549a579f25b7d32e5db46d5b6ab57ce5"
2017-03-01 06:54:18 +0000 [warn]: detached forwarding server '' host="log-aggregator.local" port=10224 hard_timeout=true
2017-03-01 06:54:18 +0000 [warn]: buffer flush took longer time than slow_flush_log_threshold: elapsed_time=60.00606061401777 slow_flush_log_threshold=20.0 plugin_id="object:2b093717af00"
2017-03-01 06:55:18 +0000 [warn]: failed to flush the buffer. retry_time=0 next_retry_seconds=2017-03-01 06:55:19 +0000 chunk="549a5c80fadbc463279c0c9408e0c210" error_class=Fluent::Plugin::ForwardOutput::NoNodesAvailable error="no nodes are available"
2017-03-01 06:56:18 +0000 [warn]: suppressed same stacktrace
2017-03-01 06:56:18 +0000 [warn]: failed to flush the buffer. retry_time=0 next_retry_seconds=2017-03-01 06:55:19 +0000 chunk="549a5c80fadbc463279c0c9408e0c210" error_class=Fluent::Plugin::ForwardOutput::NoNodesAvailable error="no nodes are available"
2017-03-01 06:56:18 +0000 [warn]: suppressed same stacktrace
2017-03-01 06:57:18 +0000 [warn]: detached forwarding server '' host="log-aggregator.local" port=10224 hard_timeout=true
2017-03-01 07:00:18 +0000 [warn]: failed to flush the buffer. retry_time=1 next_retry_seconds=2017-03-01 06:56:19 +0000 chunk="549a5c80fadbc463279c0c9408e0c210" error_class=Fluent::Plugin::ForwardOutput::NoNodesAvailable error="no nodes are available"
2017-03-01 07:01:18 +0000 [warn]: suppressed same stacktrace
2017-03-01 07:07:18 +0000 [warn]: failed to flush the buffer. retry_time=2 next_retry_seconds=2017-03-01 07:03:20 +0000 chunk="549a5c80fadbc463279c0c9408e0c210" error_class=Fluent::Plugin::ForwardOutput::NoNodesAvailable error="no nodes are available"
2017-03-01 07:07:18 +0000 [warn]: suppressed same stacktrace
2017-03-01 07:08:18 +0000 [warn]: buffer flush took longer time than slow_flush_log_threshold: elapsed_time=780.0749890550505 slow_flush_log_threshold=20.0 plugin_id="object:2b093717af00"
2017-03-01 07:08:18 +0000 [warn]: failed to flush the buffer. retry_time=3 next_retry_seconds=2017-03-01 07:07:22 +0000 chunk="549a5c80fadbc463279c0c9408e0c210" error_class=Fluent::Plugin::ForwardOutput::NoNodesAvailable error="no nodes are available"
2017-03-01 07:08:18 +0000 [warn]: suppressed same stacktrace
tcpdump in sender-server
sender-server$ tcpdump -s 0 -nn port 10224
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
07:05:31.338389 IP 172.17.0.3.36562 > 10.80.1.45.10224: Flags [F.], seq 2513917648, ack 2404494309, win 229, options [nop,nop,TS val 136819588 ecr 32246235], length 0
07:05:44.186393 IP 172.17.0.3.36562 > 10.80.1.45.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136822800 ecr 32246235], length 0
07:06:09.850392 IP 172.17.0.3.36562 > 10.80.1.45.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136829216 ecr 32246235], length 0
07:06:18.528050 IP 172.17.0.3.48160 > 10.80.31.242.10224: Flags [F.], seq 230348335, ack 1336453961, win 229, options [nop,nop,TS val 136831385 ecr 32070779], length 0
07:06:18.730397 IP 172.17.0.3.48160 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136831436 ecr 32070779], length 0
07:06:18.934388 IP 172.17.0.3.48160 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136831487 ecr 32070779], length 0
07:06:19.342383 IP 172.17.0.3.48160 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136831589 ecr 32070779], length 0
07:06:20.158387 IP 172.17.0.3.48160 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136831793 ecr 32070779], length 0
07:06:21.794381 IP 172.17.0.3.48160 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136832202 ecr 32070779], length 0
07:06:25.066536 IP 172.17.0.3.48160 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136833020 ecr 32070779], length 0
07:06:31.610412 IP 172.17.0.3.48160 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136834656 ecr 32070779], length 0
07:06:44.698389 IP 172.17.0.3.48160 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136837928 ecr 32070779], length 0
07:07:10.906398 IP 172.17.0.3.48160 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136844480 ecr 32070779], length 0
07:07:18.527420 IP 10.80.19.80.54804 > 10.80.31.242.10224: Flags [S], seq 1102294848, win 29200, options [mss 1460,sackOK,TS val 136846385 ecr 0,nop,wscale 7], length 0
07:07:18.527641 IP 10.80.31.242.10224 > 10.80.19.80.54804: Flags [S.], seq 2300741022, ack 1102294849, win 26847, options [mss 8961,sackOK,TS val 32290337 ecr 136846385,nop,wscale 8], length 0
07:07:18.527676 IP 10.80.19.80.54804 > 10.80.31.242.10224: Flags [.], ack 1, win 229, options [nop,nop,TS val 136846385 ecr 32290337], length 0
07:07:18.534713 IP 172.17.0.3.48310 > 10.80.31.242.10224: Flags [F.], seq 1614423095, ack 1935553673, win 229, options [nop,nop,TS val 136846387 ecr 32071528], length 0
07:07:18.738405 IP 172.17.0.3.48310 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136846438 ecr 32071528], length 0
07:07:18.942403 IP 172.17.0.3.48310 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136846489 ecr 32071528], length 0
07:07:19.350413 IP 172.17.0.3.48310 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136846591 ecr 32071528], length 0
07:07:20.166387 IP 172.17.0.3.48310 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136846795 ecr 32071528], length 0
07:07:21.802406 IP 172.17.0.3.48310 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136847204 ecr 32071528], length 0
07:07:25.074384 IP 172.17.0.3.48310 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136848022 ecr 32071528], length 0
07:07:31.610408 IP 172.17.0.3.48310 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136849656 ecr 32071528], length 0
07:07:44.698388 IP 172.17.0.3.48310 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136852928 ecr 32071528], length 0
07:08:10.874391 IP 172.17.0.3.48310 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136859472 ecr 32071528], length 0
07:08:18.293572 IP 10.80.31.242.10224 > 10.80.19.80.54804: Flags [F.], seq 1, ack 1, win 105, options [nop,nop,TS val 32305278 ecr 136846385], length 0
07:08:18.294385 IP 10.80.19.80.54804 > 10.80.31.242.10224: Flags [.], ack 2, win 229, options [nop,nop,TS val 136861327 ecr 32305278], length 0
07:08:18.535001 IP 10.80.19.80.54804 > 10.80.31.242.10224: Flags [F.], seq 1, ack 2, win 229, options [nop,nop,TS val 136861387 ecr 32305278], length 0
07:08:18.535208 IP 10.80.31.242.10224 > 10.80.19.80.54804: Flags [.], ack 2, win 105, options [nop,nop,TS val 32305339 ecr 136861387], length 0
07:08:18.539957 IP 10.80.19.80.50448 > 10.80.1.45.10224: Flags [S], seq 2820230188, win 29200, options [mss 1460,sackOK,TS val 136861388 ecr 0,nop,wscale 7], length 0
07:08:18.542520 IP 10.80.1.45.10224 > 10.80.19.80.50448: Flags [S.], seq 2297201150, ack 2820230189, win 26847, options [mss 8961,sackOK,TS val 32306338 ecr 136861388,nop,wscale 8], length 0
07:08:18.542546 IP 10.80.19.80.50448 > 10.80.1.45.10224: Flags [.], ack 1, win 229, options [nop,nop,TS val 136861389 ecr 32306338], length 0
07:08:18.542739 IP 172.17.0.3.48410 > 10.80.31.242.10224: Flags [F.], seq 2020798759, ack 1505973842, win 229, options [nop,nop,TS val 136861389 ecr 32072279], length 0
07:08:18.746408 IP 172.17.0.3.48410 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136861440 ecr 32072279], length 0
07:08:18.950400 IP 172.17.0.3.48410 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136861491 ecr 32072279], length 0
07:08:19.362390 IP 172.17.0.3.48410 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136861594 ecr 32072279], length 0
07:08:20.178382 IP 172.17.0.3.48410 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136861798 ecr 32072279], length 0
07:08:21.814400 IP 172.17.0.3.48410 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136862207 ecr 32072279], length 0
07:08:25.082385 IP 172.17.0.3.48410 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136863024 ecr 32072279], length 0
07:08:31.630389 IP 172.17.0.3.48410 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136864661 ecr 32072279], length 0
07:08:44.730388 IP 172.17.0.3.48410 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136867936 ecr 32072279], length 0
07:09:10.906437 IP 172.17.0.3.48410 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136874480 ecr 32072279], length 0
07:09:18.130913 IP 10.80.1.45.10224 > 10.80.19.80.50448: Flags [F.], seq 1, ack 1, win 105, options [nop,nop,TS val 32321235 ecr 136861389], length 0
07:09:18.134411 IP 10.80.19.80.50448 > 10.80.1.45.10224: Flags [.], ack 2, win 229, options [nop,nop,TS val 136876287 ecr 32321235], length 0
07:09:18.567265 IP 172.17.0.3.48670 > 10.80.31.242.10224: Flags [F.], seq 1740187083, ack 3998838662, win 229, options [nop,nop,TS val 136876395 ecr 32074529], length 0
07:09:18.770410 IP 172.17.0.3.48670 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136876446 ecr 32074529], length 0
07:09:18.974390 IP 172.17.0.3.48670 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136876497 ecr 32074529], length 0
07:09:19.382381 IP 172.17.0.3.48670 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136876599 ecr 32074529], length 0
07:09:20.198396 IP 172.17.0.3.48670 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136876803 ecr 32074529], length 0
07:09:21.834405 IP 172.17.0.3.48670 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136877212 ecr 32074529], length 0
07:09:25.106399 IP 172.17.0.3.48670 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136878030 ecr 32074529], length 0
07:09:31.642416 IP 172.17.0.3.48670 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136879664 ecr 32074529], length 0
07:09:44.730373 IP 172.17.0.3.48670 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136882936 ecr 32074529], length 0
07:10:10.874392 IP 172.17.0.3.48670 > 10.80.31.242.10224: Flags [F.], seq 0, ack 1, win 229, options [nop,nop,TS val 136889472 ecr 32074529], length 0
bungoume
All 16 comments
Thanks for the report!
This problem does not have occurred in sender v0.14.8.
How about v0.14.9 or v0.14.10?
Diff between v0.14.8 and v0.14.9 is changing plugin API to v0.14.
Diff between v0.14.9 and v0.14.10 is introducing socket helper and more.
I want to know which change causes this problem.
BTW, this failure happens immediately or need some time?
repeatedly
on 2 Mar 2017
How about v0.14.9 or v0.14.10?
OK, I'll try v0.14.9.
this failure happens immediately or need some time?
This figure shows the presence or absence of log for each sender server (4 servers) in aggregator.
Sender stops several times in a few hours.
Sender config is here.
https://github.com/bungoume/log-sender/blob/master/fluent.tmpl#L122
bungoume
on 2 Mar 2017
v0.14.9: did not work using same config because of https://github.com/fluent/fluentd/issues/1345
delete expire_dns_cache and testing for 1 hour, but the bug has not yet occurred.
v0.14.10: This problem occurred.
2017-03-02 02:39:43 +0000 [info]: delayed_commit_timeout is overwritten by ack_response_timeout
2017-03-02 02:39:43 +0000 [info]: delayed_commit_timeout is overwritten by ack_response_timeout
2017-03-02 02:39:43 +0000 [info]: following tail of /data/log/uwsgi_access.log
2017-03-02 02:39:43 +0000 [info]: listening udp socket bind="0.0.0.0" port=12514
2017-03-02 02:39:43 +0000 [info]: listening udp socket bind="0.0.0.0" port=11514
2017-03-02 02:39:43 +0000 [info]: listening udp socket bind="0.0.0.0" port=10514
2017-03-02 02:43:24 +0000 [warn]: failed to flush the buffer chunk, timeout to commit. chunk_id="549b658c83805b4b4cbed3d3ef75a859" flushed_at=2017-03-02 02:40:06 +0000
2017-03-02 02:43:24 +0000 [warn]: detached forwarding server '' host="log-aggregator.local" port=10224 hard_timeout=true
2017-03-02 02:43:24 +0000 [warn]: detached forwarding server '' host="log-aggregator.local" port=10224 hard_timeout=true
2017-03-02 02:43:24 +0000 [warn]: failed to flush the buffer. retry_time=0 next_retry_seconds=2017-03-02 02:43:25 +0000 chunk="549b66105129b447b48254d6c24cd337" error_class=Fluent::Plugin::ForwardOutput::NoNodesAvailable error="no nodes are available"
2017-03-02 02:43:24 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.10/lib/fluent/plugin/out_forward.rb:257:in `select_a_healthy_node'
2017-03-02 02:43:24 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.10/lib/fluent/plugin/out_forward.rb:214:in `write'
2017-03-02 02:43:24 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.10/lib/fluent/plugin/output.rb:1002:in `try_flush'
2017-03-02 02:43:24 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.10/lib/fluent/plugin/output.rb:1217:in `flush_thread_run'
2017-03-02 02:43:24 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.10/lib/fluent/plugin/output.rb:396:in `block (2 levels) in start'
2017-03-02 02:43:24 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.10/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
2017-03-02 02:44:24 +0000 [warn]: failed to flush the buffer. retry_time=0 next_retry_seconds=2017-03-02 02:43:25 +0000 chunk="549b66105129b447b48254d6c24cd337" error_class=Fluent::Plugin::ForwardOutput::NoNodesAvailable error="no nodes are available"
2017-03-02 02:44:24 +0000 [warn]: failed to flush the buffer. retry_time=0 next_retry_seconds=2017-03-02 02:43:25 +0000 chunk="549b658c83805b4b4cbed3d3ef75a859" error_class=Fluent::Plugin::ForwardOutput::NoNodesAvailable error="no nodes are available"
2017-03-02 02:44:24 +0000 [warn]: suppressed same stacktrace
2017-03-02 02:44:24 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.10/lib/fluent/plugin/out_forward.rb:257:in `select_a_healthy_node'
2017-03-02 02:44:24 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.10/lib/fluent/plugin/out_forward.rb:229:in `try_write'
2017-03-02 02:44:24 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.10/lib/fluent/plugin/output.rb:995:in `try_flush'
2017-03-02 02:44:24 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.10/lib/fluent/plugin/output.rb:1217:in `flush_thread_run'
2017-03-02 02:44:24 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.10/lib/fluent/plugin/output.rb:396:in `block (2 levels) in start'
2017-03-02 02:44:24 +0000 [warn]: /usr/lib/ruby/gems/2.3.0/gems/fluentd-0.14.10/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
2017-03-02 02:44:24 +0000 [warn]: failed to flush the buffer chunk, timeout to commit. chunk_id="549b65c220c657d607d188b9b67eca4e" flushed_at=2017-03-02 02:41:03 +0000
2017-03-02 02:44:26 +0000 [warn]: failed to flush the buffer. retry_time=1 next_retry_seconds=2017-03-02 02:44:26 +0000 chunk="549b66105129b447b48254d6c24cd337" error_class=Fluent::Plugin::ForwardOutput::NoNodesAvailable error="no nodes are available"
Thanks for the report.
So v0.14.10 changes cause this problem.
I will check socket helper and related code.
repeatedly
on 2 Mar 2017
👍2
I tried to reproduce this problem but it can't on my local environment.
So I want more information about this problem.
Could you launch fluentd with trace logging level?
And your log says flush is sometimes timed out.
It means the v0.14.10's out_forward takes longer time to send chunk to in_forward or other parts takes longer time?
Could you add time logging code in FowardOutput#write like below?
def write(chunk)
# ...
select_a_healthy_node{|node|
start = Time.now
node.send_data(tag, chunk)
diff = Time.now - start
log.info "[forward] elapsed time of send_data = #{diff}"
}
end
Similar code can be used in v0.14.8's write.
Of course, please add it to tcp heartbeat handling part.
repeatedly
on 13 Mar 2017
Sorry for the late reply.
Add elasped time log to try_write function. used in v0.14.10
2017-03-31 04:37:18 +0000 [info]: [forward] elapsed time of send_data = 0.001240573
2017-03-31 04:37:19 +0000 [info]: [forward] elapsed time of send_data = 0.000705089
2017-03-31 04:37:19 +0000 [info]: [forward] elapsed time of send_data = 0.000873565
2017-03-31 04:37:20 +0000 [info]: [forward] elapsed time of send_data = 0.000678126
2017-03-31 04:37:20 +0000 [info]: [forward] elapsed time of send_data = 0.000636901
2017-03-31 04:37:21 +0000 [info]: [forward] elapsed time of send_data = 0.000705793
2017-03-31 04:37:21 +0000 [info]: [forward] elapsed time of send_data = 0.000535107
2017-03-31 04:37:22 +0000 [info]: [forward] elapsed time of send_data = 0.000553111
2017-03-31 04:37:22 +0000 [info]: [forward] elapsed time of send_data = 0.000596062
2017-03-31 04:37:23 +0000 [info]: [forward] elapsed time of send_data = 0.000613834
2017-03-31 04:37:23 +0000 [info]: [forward] elapsed time of send_data = 0.000956875
2017-03-31 04:37:24 +0000 [info]: [forward] elapsed time of send_data = 0.000514704
2017-03-31 04:37:24 +0000 [info]: [forward] elapsed time of send_data = 0.001189617
2017-03-31 04:37:25 +0000 [info]: [forward] elapsed time of send_data = 0.000646942
2017-03-31 04:37:25 +0000 [info]: [forward] elapsed time of send_data = 0.000653387
2017-03-31 04:37:26 +0000 [info]: [forward] elapsed time of send_data = 0.000746027
2017-03-31 04:37:26 +0000 [info]: [forward] elapsed time of send_data = 0.000830015
2017-03-31 04:37:27 +0000 [info]: [forward] elapsed time of send_data = 0.000668958
2017-03-31 04:38:27 +0000 [warn]: detached forwarding server '' host="log-aggregator.local" port=10224 hard_timeout=true
tcpdump file is here.
packetdump.txt
(+09:00 JST)
bungoume
on 31 Mar 2017
Thanks!
Elapsed time seems no problem, so the basic functionality works fine.
Will check network operation code after back to japan.
repeatedly
on 31 Mar 2017
2017-05-22 13:08:24 +0000 [info]: starting fluentd-0.14.16 pid=25662
2017-05-22 13:08:24 +0000 [info]: spawn command to main: cmdline=["/usr/bin/ruby", "-Eascii-8bit:ascii-8bit", "/usr/bin/fluentd", "--under-supervisor"]
2017-05-22 13:08:25 +0000 [info]: gem 'fluentd' version '0.14.16'
2017-05-22 13:08:25 +0000 [info]: adding match pattern="*.**" type="forward"
2017-05-22 13:08:25 +0000 [info]: #0 [forward_any] adding forwarding server '127.0.0.1:24224' host="127.0.0.1" port=24224 weight=60 plugin_id="forward_any"
2017-05-22 13:08:25 +0000 [info]: adding source type="forward"
2017-05-22 13:08:25 +0000 [info]: using configuration file: <ROOT>
<system>
root_dir "/data/buffer"
</system>
<source>
@type forward
port 24224
</source>
<match *.**>
@id forward_any
@type forward
heartbeat_type transport
heartbeat_interval 100
require_ack_response true
phi_failure_detector false
<buffer>
@type "file"
flush_interval 1
chunk_limit_size 8m
total_limit_size 4g
</buffer>
<server>
host "127.0.0.1"
port 24224
</server>
</match>
</ROOT>
2017-05-22 13:08:25 +0000 [info]: #0 starting fluentd worker pid=25668 ppid=25662 worker=0
2017-05-22 13:08:25 +0000 [info]: #0 [forward_any] delayed_commit_timeout is overwritten by ack_response_timeout
2017-05-22 13:08:25 +0000 [info]: #0 listening port port=24224 bind="0.0.0.0"
2017-05-22 13:08:25 +0000 [info]: #0 fluentd worker is now running worker=0
$ while true; do echo '{"name":"test"}' | fluent-cat some.tag; sleep 1 ; done
2017-05-22 13:10:05 +0000 [warn]: #0 [forward_any] detached forwarding server '' host="127.0.0.1" port=24224 hard_timeout=true
2017-05-22 13:10:05 +0000 [warn]: #0 [forward_any] recovered forwarding server '' host="127.0.0.1" port=24224
md5-9dce2cd10ffa56964c2b423bc4e9cdcb
# netstat -nap
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
tcp 0 0 0.0.0.0:24224 0.0.0.0:* LISTEN 25668/ruby
tcp 0 0 127.0.0.1:51252 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51363 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51456 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51349 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51345 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51484 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51508 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51399 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51425 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51348 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51364 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51456 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51352 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51392 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51249 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51370 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51393 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51461 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51368 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51384 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51368 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51356 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51357 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51385 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51443 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51344 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51360 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51482 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51510 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51360 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51250 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51378 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51352 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51484 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51419 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51376 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51373 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51392 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51356 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51455 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51429 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51342 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51399 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51394 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51420 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51406 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51552 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51443 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51426 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51364 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51428 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51524 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51420 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51441 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51372 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51372 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51363 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51353 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51405 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51375 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51353 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51253 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51391 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51345 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51525 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51359 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51393 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51400 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51252 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51425 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51461 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51373 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51460 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51405 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51349 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51369 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51249 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51419 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51367 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51370 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51367 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51384 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51348 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51394 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51375 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51428 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51250 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51429 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51550 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51342 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51253 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51441 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51344 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51379 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51460 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51385 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51426 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51455 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51482 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51552 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51357 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51524 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51400 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51359 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51406 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51525 127.0.0.1:24224 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51391 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51508 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51378 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51510 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51376 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51379 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:24224 127.0.0.1:51369 ESTABLISHED 25668/ruby
tcp 0 0 127.0.0.1:51550 127.0.0.1:24224 ESTABLISHED 25668/ruby
udp 0 0 0.0.0.0:24224 0.0.0.0:* 25668/ruby
tcp connection is not closed?
bungoume
on 22 May 2017
Ah, you are right.
I confirmed this problem on my side.
I'm now writing a patch...
repeatedly
on 23 May 2017
@bungoume Sorry for the late.
https://github.com/fluent/fluentd/pull/1581
I wrote a patch. Could you test this?
repeatedly
on 24 May 2017
👍1
@repeatedly thanks! I'll check it out.
bungoume
on 24 May 2017
Looks good to me!
data packets
18:35:23.214578 IP 10.3.24.149.34312 > 10.3.2.248.10224: Flags [S], seq 3532253381, win 17922, options [mss 8961,sackOK,TS val 3316041388 ecr 0,nop,wscale 7], length 0
18:35:23.217326 IP 10.3.2.248.10224 > 10.3.24.149.34312: Flags [S.], seq 3770136860, ack 3532253382, win 28960, options [mss 1460,sackOK,TS val 33722668 ecr 3316041388,nop,wscale 7], length 0
18:35:23.217396 IP 10.3.24.149.34312 > 10.3.2.248.10224: Flags [.], ack 1, win 141, options [nop,nop,TS val 3316041391 ecr 33722668], length 0
18:35:23.217477 IP 10.3.24.149.34312 > 10.3.2.248.10224: Flags [P.], seq 1:2, ack 1, win 141, options [nop,nop,TS val 3316041391 ecr 33722668], length 1
18:35:23.220026 IP 10.3.2.248.10224 > 10.3.24.149.34312: Flags [.], ack 2, win 227, options [nop,nop,TS val 33722669 ecr 3316041391], length 0
18:35:23.220055 IP 10.3.24.149.34312 > 10.3.2.248.10224: Flags [P.], seq 2:175, ack 1, win 141, options [nop,nop,TS val 3316041394 ecr 33722669], length 173
18:35:23.222564 IP 10.3.2.248.10224 > 10.3.24.149.34312: Flags [.], ack 175, win 235, options [nop,nop,TS val 33722669 ecr 3316041394], length 0
18:35:23.222819 IP 10.3.2.248.10224 > 10.3.24.149.34312: Flags [P.], seq 1:32, ack 175, win 235, options [nop,nop,TS val 33722669 ecr 3316041394], length 31
18:35:23.222842 IP 10.3.24.149.34312 > 10.3.2.248.10224: Flags [.], ack 32, win 141, options [nop,nop,TS val 3316041397 ecr 33722669], length 0
18:35:23.408799 IP 10.3.24.149.34312 > 10.3.2.248.10224: Flags [F.], seq 175, ack 32, win 141, options [nop,nop,TS val 3316041583 ecr 33722669], length 0
18:35:23.411705 IP 10.3.2.248.10224 > 10.3.24.149.34312: Flags [R.], seq 32, ack 176, win 235, options [nop,nop,TS val 33722716 ecr 3316041583], length 0
heatbeat packets
18:38:48.201263 IP 10.3.24.149.35099 > 10.3.2.248.10224: Flags [S], seq 3585909603, win 17922, options [mss 8961,sackOK,TS val 3316246375 ecr 0,nop,wscale 7], length 0
18:38:48.203938 IP 10.3.2.248.10224 > 10.3.24.149.35099: Flags [S.], seq 1462521086, ack 3585909604, win 28960, options [mss 1460,sackOK,TS val 33773915 ecr 3316246375,nop,wscale 7], length 0
18:38:48.204001 IP 10.3.24.149.35099 > 10.3.2.248.10224: Flags [.], ack 1, win 141, options [nop,nop,TS val 3316246378 ecr 33773915], length 0
18:38:48.204060 IP 10.3.24.149.35099 > 10.3.2.248.10224: Flags [F.], seq 1, ack 1, win 141, options [nop,nop,TS val 3316246378 ecr 33773915], length 0
18:38:48.206825 IP 10.3.2.248.10224 > 10.3.24.149.35099: Flags [R.], seq 1, ack 2, win 227, options [nop,nop,TS val 33773915 ecr 3316246378], length 0
ESTABLISHED and TIME_WAIT are not found in netstat.
(when connecting without Load Barancer)
bungoume
on 24 May 2017
but many TIME_WAIT appears when using Amazon CLB(ELB).
log-sender -> ELB -> log-aggregator(s)
maybe ELB replace RST to FIN response.
bungoume
on 24 May 2017
Problem1
AWS CLB seems to convert RST to FIN with 2 patterns.
log-sender -> ELB -> log-aggregator(s)
- client send FIN.
- log-aggregator return RST.
- ELB Replace RST to (FIN's ACK + FIN)
sometimes only return FIN. - when only returned FIN, client TCP status become TIME_WAIT(CLOSING)
This is may be CLB plobrem. I'll contact AWS.
packet sample (heatbeat)
- FIN's ACK + FIN
19:02:27.125288 IP 10.3.24.149.47138 > 10.3.22.203.10224: Flags [S], seq 553153379, win 17922, options [mss 8961,sackOK,TS val 3317665299 ecr 0,nop,wscale 7], length 0
19:02:27.125800 IP 10.3.22.203.10224 > 10.3.24.149.47138: Flags [S.], seq 1880515537, ack 553153380, win 26847, options [mss 8961,sackOK,TS val 1810336752 ecr 3317665299,nop,wscale 8], length 0
19:02:27.125840 IP 10.3.24.149.47138 > 10.3.22.203.10224: Flags [.], ack 1, win 141, options [nop,nop,TS val 3317665300 ecr 1810336752], length 0
19:02:27.125932 IP 10.3.24.149.47138 > 10.3.22.203.10224: Flags [F.], seq 1, ack 1, win 141, options [nop,nop,TS val 3317665300 ecr 1810336752], length 0
19:02:27.126611 IP 10.3.22.203.10224 > 10.3.24.149.47138: Flags [.], ack 2, win 105, options [nop,nop,TS val 1810336753 ecr 3317665300], length 0
19:02:27.127529 IP 10.3.22.203.10224 > 10.3.24.149.47138: Flags [F.], seq 1, ack 2, win 105, options [nop,nop,TS val 1810336753 ecr 3317665300], length 0
19:02:27.127571 IP 10.3.24.149.47138 > 10.3.22.203.10224: Flags [.], ack 2, win 141, options [nop,nop,TS val 3317665301 ecr 1810336753], length 0
- FIN Only
18:58:47.129643 IP 10.3.24.149.48922 > 10.3.11.68.10224: Flags [S], seq 1216453890, win 17922, options [mss 8961,sackOK,TS val 3317445304 ecr 0,nop,wscale 7], length 0
18:58:47.132288 IP 10.3.11.68.10224 > 10.3.24.149.48922: Flags [S.], seq 2782128884, ack 1216453891, win 26847, options [mss 8961,sackOK,TS val 1810281730 ecr 3317445304,nop,wscale 8], length 0
18:58:47.132326 IP 10.3.24.149.48922 > 10.3.11.68.10224: Flags [.], ack 1, win 141, options [nop,nop,TS val 3317445306 ecr 1810281730], length 0
18:58:47.132383 IP 10.3.24.149.48922 > 10.3.11.68.10224: Flags [F.], seq 1, ack 1, win 141, options [nop,nop,TS val 3317445306 ecr 1810281730], length 0
18:58:47.136033 IP 10.3.11.68.10224 > 10.3.24.149.48922: Flags [F.], seq 1, ack 2, win 105, options [nop,nop,TS val 1810281731 ecr 3317445306], length 0
18:58:47.136066 IP 10.3.24.149.48922 > 10.3.11.68.10224: Flags [.], ack 2, win 141, options [nop,nop,TS val 3317445310 ecr 1810281731], length 0
Problem2
when setting linger_timeout 1 to log-aggregator's source_forward, log-aggregator not return FIN's ACK.
log-sender -> log-aggregator(s)
(without ELB pattern)
10:48:05.172797 IP 10.3.11.68.10888 > 10.3.2.248.24224: Flags [S], seq 1220495692, win 26883, options [mss 8961,sackOK,TS val 1811021240 ecr 0,nop,wscale 8], length 0
10:48:05.172957 IP 10.3.2.248.24224 > 10.3.11.68.10888: Flags [S.], seq 728748913, ack 1220495693, win 28960, options [mss 1460,sackOK,TS val 34813157 ecr 1811021240,nop,wscale 7], length 0
10:48:05.173243 IP 10.3.11.68.10888 > 10.3.2.248.24224: Flags [.], ack 1, win 106, options [nop,nop,TS val 1811021240 ecr 34813157], length 0
10:48:05.173285 IP 10.3.11.68.10888 > 10.3.2.248.24224: Flags [F.], seq 1, ack 1, win 106, options [nop,nop,TS val 1811021240 ecr 34813157], length 0
10:48:05.173707 IP 10.3.2.248.24224 > 10.3.11.68.10888: Flags [F.], seq 1, ack 2, win 227, options [nop,nop,TS val 34813157 ecr 1811021240], length 0
10:48:05.174065 IP 10.3.11.68.10888 > 10.3.2.248.24224: Flags [.], ack 2, win 106, options [nop,nop,TS val 1811021240 ecr 34813157], length 0
I was planning to respond with linger_timeout while investigating ELB,
but there seems to be a problem here too.
Could you fix this problem?
bungoume
on 24 May 2017
I'm not sure the expected sequence on this situation, client side close, but Problem2 sequence also happens on other situation.
For example, python HTTP server and ruby TCP client also has same sequence.
$ python -m SimpleHTTPServer
Serving HTTP on 0.0.0.0 port 8000 ...
$ ruby -rsocket -e 'sock = TCPSocket.open("127.0.0.1", 8000); sock.close'
$ sudo tcpdump -i lo port 8000
09:09:03.904187 IP localhost.57868 > localhost.8000: Flags [S], seq 4262166317, win 43690, options [mss 65495,sackOK,TS val 6988912 ecr 0,nop,wscale 7], length 0
09:09:03.904202 IP localhost.8000 > localhost.57868: Flags [S.], seq 2989685197, ack 4262166318, win 43690, options [mss 65495,sackOK,TS val 6988912 ecr 6988912,nop,wscale 7], length 0
09:09:03.904214 IP localhost.57868 > localhost.8000: Flags [.], ack 1, win 342, options [nop,nop,TS val 6988912 ecr 6988912], length 0
09:09:03.904238 IP localhost.57868 > localhost.8000: Flags [F.], seq 1, ack 1, win 342, options [nop,nop,TS val 6988912 ecr 6988912], length 0
09:09:03.904445 IP localhost.8000 > localhost.57868: Flags [F.], seq 1, ack 2, win 342, options [nop,nop,TS val 6988912 ecr 6988912], length 0
09:09:03.904455 IP localhost.57868 > localhost.8000: Flags [.], ack 2, win 342, options [nop,nop,TS val 6988912 ecr 6988912], length 0
So with this situation, first FIN's ACK is skipped on Linux?
Mac has different sequence
01:13:24.858278 IP localhost.59517 > localhost.irdmi: Flags [S], seq 3075251422, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 518559330 ecr 0,sackOK,eol], length 0
01:13:24.858392 IP localhost.irdmi > localhost.59517: Flags [S.], seq 1135067205, ack 3075251423, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 518559330 ecr 518559330,sackOK,eol], length 0
01:13:24.858406 IP localhost.59517 > localhost.irdmi: Flags [.], ack 1, win 12759, options [nop,nop,TS val 518559330 ecr 518559330], length 0
01:13:24.858416 IP localhost.irdmi > localhost.59517: Flags [.], ack 1, win 12759, options [nop,nop,TS val 518559330 ecr 518559330], length 0
01:13:24.858439 IP localhost.59517 > localhost.irdmi: Flags [F.], seq 1, ack 1, win 12759, options [nop,nop,TS val 518559330 ecr 518559330], length 0
01:13:24.858453 IP localhost.irdmi > localhost.59517: Flags [.], ack 2, win 12759, options [nop,nop,TS val 518559330 ecr 518559330], length 0
01:13:24.858457 IP localhost.59517 > localhost.irdmi: Flags [.], ack 1, win 12759, options [nop,nop,TS val 518559330 ecr 518559330], length 0
01:13:24.858666 IP localhost.irdmi > localhost.59517: Flags [F.], seq 1, ack 2, win 12759, options [nop,nop,TS val 518559330 ecr 518559330], length 0
01:13:24.859027 IP localhost.59517 > localhost.irdmi: Flags [.], ack 2, win 12759, options [nop,nop,TS val 518559330 ecr 518559330], length 0
👍1
Hmm, sorry it is my misunderstanding. It does not seem to be a problem.
bungoume
on 25 May 2017
Was this page helpful?
0 / 5 - 0 ratings
Related issues
khteh
路
4Comments
jdoss
路
4Comments
amread
路
5Comments
pdecat
路
7Comments
rolindroy
路
7Comments
Most helpful comment
Thanks for the report.
So v0.14.10 changes cause this problem.
I will check socket helper and related code.