智能信息费服务，上游是SOA调用，上线一段时间后，偶尔有短暂上游调用接口出错告警，之后立刻恢复。排查日志发现有7-8s间单台pod的所有请求被hang住，之后立刻恢复，在hang住期间出问题的pod可以正常接收上游请求，消费MQ的goroutine也可以启动执行，不过从日志记录上看，就是所有的逻辑【很短暂】的执行后，就不往下执行，表现的很奇怪。

首先，由于Java和Go的技术栈问题，日志trace无法关联，不能很好的定位问题，从Http header中提前sw8字段解析成全链路traceID。同时，注意到hang住的时候，处理每个请求都是打印出最多的日志后没有后续，猜测是不是单条日志打印过多？（打印的是gin的请求日志，也就是c.Request的内容）。该条日志打印后的代码逻辑是从gin的Http请求中读取请求数据。猜测是不是这里分配内存过多等问题导致的？从goruntime监控看，发生hang的时间点附近，有问题的那台pod突然申请了几百M的内存，（之后却又都释放。下面会解释这种现象的原因）。修改代码去掉手动分配内存解析Http body的部分，现象依旧。

联系运维查看hang住的问题，运维无法定位原因，但给了一个思路，之前订单的几个核心Java服务也发生过短暂hang住的情况，是由于日志同步刷盘的问题导致，Java服务改成日志异步刷盘后，得到解决。于是找到日志框架的技术，得到的答复是 “采用容器化部署的服务 日志直接输出到标准输出，docker会处理，不用关系同步/异步刷盘的问题”（之后再看这句话，是非常业余的）。

放弃日志方向的问题，容器化的开发同学和运维给出了服务hang住的常见几个原因，以及Go服务容器部署的最佳实践等，感觉都不是很适用此问题。（修改MAXGOPROCS=容器limit 貌似真的可以降低服务占用CPU）。综合之前调整过容器的负载均衡（四层-》七层-》四层）和开启了CPU burst，虽然看起来与此无关，但确实是各种调整后出现的hang住问题，去掉CPU burst，同时修改代码，去掉自定义gin中间件中打印长日志的那条，因为感觉就像是打印长日志后，不再调用其他函数，不进其他函数执行，还猜测是不是调度发生了问题，每个goroutine分配到的调度时间过短？之后很长一段时间没有任务排查思路，容器化开发leader也没有头绪。

服务断断续续使用，上游报错确实也会收到压力。尝试自己修改代码，在原来hang住的位置连续打印两条日志，日志内容是当前系统时间戳，无任何多余信息，两条日志之间无任何代码逻辑。同时启动一个单独的goroutine，使用ticker每隔500ms输出一条时间戳日志，测试hang住期间这个独立的线程是否正常工作（运维和容器化都觉得是业务服务本身代码问题，因为其他Go服务都没有遇到。）。测试代码上线后，发现hang住期间，独立的goroutine也hang住，不能每隔500ms输出日志。同时发现hang后，有一条输出的时间戳不是规律的间隔500ms。

问题的突破点在查看gin处理Http请求的日志中，发现之前连续打印两条时间戳日志的地方，每次都是打印出第一条，之后没有后续，理论上来讲，不应该有这种问题，因为两条打印日志的代码中间没有任何的逻辑。

在多次查看hang住的请求trace日志时，偶然间发现有一条trace日志是这样的：第一条日志正常，日志中显示的时间戳也正常，后续的日志是hang了7、8s后打印出来的，但是发现所有的这几条日志被日志系统收集到的时间collect_time是同一时间，也就是说第一条日志没有及时的被收集，（找日志系统的人，想看看他们在pod中有没有日志收集agent的监控，说明这段时间日志收集也hang住了。原来容器部署的服务日志收集是docker收集各个pod的stdout，在pod中无日志相关服务）。

Google搜索容器pod hang住的相关问题，找到一篇文章容器排查实战: 请求无响应 - 掘金，感觉现象很类似，猜测是不是stdout的pipe有问题，导致每次服务处理请求，生成第一条日志（包含正常时间戳）向stdout输出的时候有问题，导致这个地方被卡住，goroutine无法继续向下执行，可以解释问题的现象。因为不懂容器化相关知识，就把文章给容器化开发的leader，大佬说文章里的容器技术和公司使用的技术不一样，并分享了一篇他自己写的文章，里面介绍了Java服务hang住问题的情况：Java服务使用的是logback日志框架，为了保证日志的顺序性，一般日志框架都是同步写日志，或者是像logback这种同步写到一个队列中，然后业务线程返回继续后续的逻辑执行，单独的线程从队列中读取日志内容，输出到日志文件或者stdout。Java服务被hang住是因为服务流量过大，缓存队列被写满，消费队列内容的线程处理不过来，导致写队列的线程也就是业务线程被阻塞。（之所以消费日志队列的线程没有及时处理，我认为不是文章里说的docker 的日志daemon没有及时从stdout读取日志，因为就算没有及时从stdout读取日志，特意看了man7中Linux glibc对stdout的详细解释，stdout是一个普通文件，是对普通内核文件描述符的加缓冲封装，可以一直写下去，不至于卡住。）

收到文章的启发和对stdout的详细了解，查看了服务使用的logrus的代码，以及golang关于写文件操作的源代码（golang对内核文件描述符的封装不像C语言等，没有做任何系统用户层的buffer，对于文件的读写直接使用write（）系统调用，其实write()是glibc对系统调用的封装，真正的系统内核调用是一个宏实现的。所以Go对stdout的输出也没有no-buffer，line-buffer，block-buffer可言，性能相对于C之类性能肯定是较差的。）猜测是Go服务中写日志同步阻塞式调用write()卡住导致的系统hang住。那么fix问题就很简单了，直接把写日志的调用改成起一个新goroutine异步的写日志，业务goroutine立刻返回，不阻塞业务处理流程。（因为之前重写了logrus日志库的iowirter和formatter，所以这里的修改成本很低），想效仿logback日志库增加缓存队列，这样可以保证日志的顺序性，因为纯异步的写日志，可能会遇到日志收集无序的问题，但是每条日志中有时间戳，查看日志是从ES中搜索，所以日志的顺序性可以暂时忽略，另外就是加了队列，还是广义上的同步写日志，虽然可以把队列设置成很大，极端情况可能还是有问题，另外，增加队列增大了逻辑复杂度，线上业务使用期间暂时还是不要改动过多。

修改后的代码上线，满心期待，经历了一个周末，周一查看日志，发现周六发生了一次pod hang住的情况，系统write()超时，但是业务本身处理请求正常，问题完美解决。