k3s下查看容器日志，换行格式混乱

huapox commented 3 years ago

2021-03-08_171857

[root@(⎈ |default:kube-web) /]$ kc logs -f --tail=20 goldpinger-vssjq
{"level":"info","ts":1615175439.9033206,"caller":"goldpinger/pinger.go:159","msg":"Starting pinger","op":"pinger","name":"goldpinger-vssjq","hostIP":"3.4.5.2","podIP":"","period":30,"initialWait":15,"jitterFactor":0.05}
{"level":"warn","ts":1615175439.9035208,"caller":"goldpinger/pinger.go:151","msg":"Ping returned error","op":"pinger","name":"goldpinger-mrx67","hostIP":"3.4.5.2","podIP":"10.42.0.9","responseTime":0.000411561,"error":"Get \"http://10.42.0.9:80/ping\": dial tcp 10.42.0.9:80: connect: no route to host"}
{"level":"warn","ts":1615175447.7036345,"caller":"goldpinger/pinger.go:151","msg":"Ping returned error","op":"pinger","name":"goldpinger-4wr78","hostIP":"3.4.5.3","podIP":"10.42.1.6","responseTime":0.300109295,"error":"Get \"http://10.42.1.6:80/ping\": context deadline exceeded"}
{"level":"warn","ts":1615175454.9034328,"caller":"goldpinger/pinger.go:84","msg":"Could not get client","op":"pinger","name":"goldpinger-vssjq","hostIP":"3.4.5.2","podIP":"","error":"Host or pod IP empty, can't make a call"}
{"level":"warn","ts":1615175462.40329,"caller":"goldpinger/pinger.go:84","msg":"Could not get client","op":"pinger","name":"goldpinger-tqwqg","hostIP":"3.4.5.3","podIP":"","error":"Host or pod IP empty, can't make a call"}
{"level":"info","ts":1615175469.9066997,"caller":"goldpinger/updater.go:128","msg":"Deleting pod from pingers","name":"goldpinger-vssjq","podIP":"","hostIP":"3.4.5.2"}
{"level":"info","ts":1615175469.9067352,"caller":"goldpinger/updater.go:128","msg":"Deleting pod from pingers","name":"goldpinger-tqwqg","podIP":"","hostIP":"3.4.5.3"}
{"level":"info","ts":1615175469.9067416,"caller":"goldpinger/updater.go:107","msg":"Starting pingers for new pods","numNewPods":2,"refreshPeriod":30,"waitPeriod":15,"JitterFactor":0.05}
{"level":"info","ts":1615175469.906774,"caller":"goldpinger/pinger.go:159","msg":"Starting pinger","op":"pinger","name":"goldpinger-tqwqg","hostIP":"3.4.5.3","podIP":"10.42.3.3","period":30,"initialWait":15,"jitterFactor":0.05}
{"level":"info","ts":1615175469.9067938,"caller":"goldpinger/pinger.go:159","msg":"Starting pinger","op":"pinger","name":"goldpinger-vssjq","hostIP":"3.4.5.2","podIP":"10.42.2.3","period":30,"initialWait":0,"jitterFactor":0.05}
{"level":"warn","ts":1615175470.8107235,"caller":"goldpinger/pinger.go:151","msg":"Ping returned error","op":"pinger","name":"goldpinger-mrx67","hostIP":"3.4.5.2","podIP":"10.42.0.9","responseTime":0.000450583,"error":"Get \"http://10.42.0.9:80/ping\": dial tcp 10.42.0.9:80: connect: no route to host"}
{"level":"warn","ts":1615175479.114571,"caller":"goldpinger/pinger.go:151","msg":"Ping returned error","op":"pinger","name":"goldpinger-4wr78","hostIP":"3.4.5.3","podIP":"10.42.1.6","responseTime":0.300135316,"error":"Get \"http://10.42.1.6:80/ping\": dial tcp 10.42.1.6:80: i/o timeout"}
{"level":"warn","ts":1615175501.840936,"caller":"goldpinger/pinger.go:151","msg":"Ping returned error","op":"pinger","name":"goldpinger-mrx67","hostIP":"3.4.5.2","podIP":"10.42.0.9","responseTime":0.000343806,"error":"Get \"http://10.42.0.9:80/ping\": dial tcp 10.42.0.9:80: connect: no route to host"}
{"level":"warn","ts":1615175509.2131298,"caller":"goldpinger/pinger.go:151","msg":"Ping returned error","op":"pinger","name":"goldpinger-4wr78","hostIP":"3.4.5.3","podIP":"10.42.1.6","responseTime":0.300135966,"error":"Get \"http://10.42.1.6:80/ping\": dial tcp 10.42.1.6:80: i/o timeout"}
{"level":"warn","ts":1615175532.292389,"caller":"goldpinger/pinger.go:151","msg":"Ping returned error","op":"pinger","name":"goldpinger-mrx67","hostIP":"3.4.5.2","podIP":"10.42.0.9","responseTime":0.000330327,"error":"Get \"http://10.42.0.9:80/ping\": dial tcp 10.42.0.9:80: connect: no route to host"}
{"level":"warn","ts":1615175539.9861126,"caller":"goldpinger/pinger.go:151","msg":"Ping returned error","op":"pinger","name":"goldpinger-4wr78","hostIP":"3.4.5.3","podIP":"10.42.1.6","responseTime":0.300149933,"error":"Get \"http://10.42.1.6:80/ping\": context deadline exceeded"}
{"level":"warn","ts":1615175563.1632693,"caller":"goldpinger/pinger.go:151","msg":"Ping returned error","op":"pinger","name":"goldpinger-mrx67","hostIP":"3.4.5.2","podIP":"10.42.0.9","responseTime":0.300122017,"error":"Get \"http://10.42.0.9:80/ping\": context deadline exceeded"}
{"level":"warn","ts":1615175570.4632773,"caller":"goldpinger/pinger.go:151","msg":"Ping returned error","op":"pinger","name":"goldpinger-4wr78","hostIP":"3.4.5.3","podIP":"10.42.1.6","responseTime":0.300147665,"error":"Get \"http://10.42.1.6:80/ping\": context deadline exceeded"}
{"level":"info","ts":1615175589.932876,"caller":"goldpinger/updater.go:128","msg":"Deleting pod from pingers","name":"goldpinger-mrx67","podIP":"10.42.0.9","hostIP":"3.4.5.2"}
{"level":"info","ts":1615175589.9329145,"caller":"goldpinger/updater.go:128","msg":"Deleting pod from pingers","name":"goldpinger-4wr78","podIP":"10.42.1.6","hostIP":"3.4.5.3"}

wrfly commented 3 years ago

啊，这个的确很头疼，应该是少输出了一个换行，我抽空瞅瞅，看怎么加回来。

wrfly commented 3 years ago

BTW, 换个别的image也会出现同样的问题吗，比如nginx？

huapox commented 3 years ago

BTW, 换个别的image也会出现同样的问题吗，比如nginx？

polaris(一行)

time="2021-03-08T03:53:09Z" level=info msg="Starting Polaris dashboard server on port 8080"

coredns

.:53
    [INFO] plugin/reload: Running configuration MD5 = 4665410bf21c8b272fcfd562c482cb82
                                                                                         ______                ____  _   _______
                                                                                                                                  / ____/___  ________  / __ \/ | / / ___/ ~ CoreDNS-1.6.3
               / /   / __ \/ ___/ _ \/ / / /  |/ /\__ \         ~ linux/amd64, go1.12.9, 37b9550
                                                                                                / /___/ /_/ / /  /  __/ /_/ / /|  /___/ / 
                                                                                                                                          \____/\____/_/   \___/_____/_/ |_//____/

dnsmasq

[webproc] 2021/03/08 03:53:13 loaded config files changes from disk
                                                                   [webproc] 2021/03/08 03:53:13 agent listening on http://0.0.0.0:8080...
                                                                                                                                          dnsmasq: started, version 2.80 cachesize 150
          dnsmasq: compile time options: IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP DHCPv6 no-Lua TFTP no-conntrack ipset auth no-DNSSEC loop-detect inotify dumpfile
                                                                                                                                                                      dnsmasq: using nameserver 10.0.0.1#53 for domain company 
                                                   dnsmasq: using nameserver 8.8.8.8#53
                                                                                       dnsmasq: using nameserver 114.114.114.114#53
                                                                                                                                   dnsmasq: read /etc/hosts - 7 addresses

huapox commented 3 years ago

大多只是每行多了空格，还好做匹配处理

coredns

coredns那显示效果过分了啊..~

[root@(⎈ |default:kube-system) /]$ kc logs -f --tail=20 coredns-6c6bb68b64-bjlgd 
.:53
[INFO] plugin/reload: Running configuration MD5 = 4665410bf21c8b272fcfd562c482cb82
   ______                ____  _   _______
  / ____/___  ________  / __ \/ | / / ___/  ~ CoreDNS-1.6.3
 / /   / __ \/ ___/ _ \/ / / /  |/ /\__ \   ~ linux/amd64, go1.12.9, 37b9550
/ /___/ /_/ / /  /  __/ /_/ / /|  /___/ / 
\____/\____/_/   \___/_____/_/ |_//____/

#coredns 手工清理行首空格(不能完全匹配)
.:53
[INFO] plugin/reload: Running configuration MD5 = 4665410bf21c8b272fcfd562c482cb82
______                ____  _   _______
/ ____/___  ________  / __ \/ | / / ___/ ~ CoreDNS-1.6.3
/ /   / __ \/ ___/ _ \/ / / /  |/ /\__ \         ~ linux/amd64, go1.12.9, 37b9550
/ /___/ /_/ / /  /  __/ /_/ / /|  /___/ / 
\____/\____/_/   \___/_____/_/ |_//____/

dnsmasq 手工清理行首空格

[webproc] 2021/03/08 03:53:13 loaded config files changes from disk
[webproc] 2021/03/08 03:53:13 agent listening on http://0.0.0.0:8080...
dnsmasq: started, version 2.80 cachesize 150
dnsmasq: compile time options: IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP DHCPv6 no-Lua TFTP no-conntrack ipset auth no-DNSSEC loop-detect inotify dumpfile
dnsmasq: using nameserver 10.0.0.1#53 for domain company 
dnsmasq: using nameserver 8.8.8.8#53
dnsmasq: using nameserver 114.114.114.114#53
dnsmasq: read /etc/hosts - 7 addresses

wrfly commented 3 years ago

我debug了一下，是因为这些容器的输出少了 \r\n，换一个简单的容器，比如 wrfly/echo 试试，日志就应该正常了。

感觉这个问题除了从容器角度修改，没有办法解决，logs是一次性输出了很多日志，无法判断哪个是新的一行。如果只从fix当前问题考虑的话，可以在 \r 后面追加一个 \n, 但是这样就修改原始日志了，我不确定这是一个好的方法。

wrfly commented 3 years ago

tail /var/lib/docker/containers/470eeb1c4b3e64caf67aedc67b2b24304012a22ee559aa3ffdbf51f0a62a6dca/470eeb1c4b3e64caf67aedc67b2b24304012a22ee559aa3ffdbf51f0a62a6dca-json.log
{"log":"          `-._        _.-'                                           \r\n","stream":"stdout","time":"2021-03-13T16:36:14.253970513Z"}
{"log":"              `-.__.-'                                               \r\n","stream":"stdout","time":"2021-03-13T16:36:14.253974316Z"}
{"log":"\r\n","stream":"stdout","time":"2021-03-13T16:36:14.253978398Z"}
{"log":"1:M 13 Mar 2021 16:36:14.253 # Server initialized\r\n","stream":"stdout","time":"2021-03-13T16:36:14.253982264Z"}
{"log":"1:M 13 Mar 2021 16:36:14.253 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.\r\n","stream":"stdout","time":"2021-03-13T16:36:14.253987746Z"}
{"log":"1:M 13 Mar 2021 16:36:14.253 * Loading RDB produced by version 6.0.10\r\n","stream":"stdout","time":"2021-03-13T16:36:14.253995756Z"}
{"log":"1:M 13 Mar 2021 16:36:14.253 * RDB age 8360 seconds\r\n","stream":"stdout","time":"2021-03-13T16:36:14.254064352Z"}
{"log":"1:M 13 Mar 2021 16:36:14.253 * RDB memory usage when created 0.77 Mb\r\n","stream":"stdout","time":"2021-03-13T16:36:14.254076763Z"}
{"log":"1:M 13 Mar 2021 16:36:14.253 * DB loaded from disk: 0.000 seconds\r\n","stream":"stdout","time":"2021-03-13T16:36:14.254090025Z"}
{"log":"1:M 13 Mar 2021 16:36:14.253 * Ready to accept connections\r\n","stream":"stdout","time":"2021-03-13T16:36:14.254094666Z"}

docker 原始日志文件里面都有一个 \r\n，所以在浏览器上也可以正常显示。

huapox commented 3 years ago

我debug了一下，是因为这些容器的输出少了 \r\n，换一个简单的容器，比如 wrfly/echo 试试，日志就应该正常了。

感觉这个问题除了从容器角度修改，没有办法解决，logs是一次性输出了很多日志，无法判断哪个是新的一行。如果只从fix当前问题考虑的话，可以在 \r 后面追加一个 \n, 但是这样就修改原始日志了，我不确定这是一个好的方法。

ar 17 10:13:35 UTC 2021
                       Wed Mar 17 10:13:36 UTC 2021
                                                   Wed Mar 17 10:13:37 UTC 2021
                                                                               Wed Mar 17 10:13:38 UTC 2021
                                                                                                           Wed Mar 17 10:13:39 UTC 2021
                                                                                                                                       Wed Mar 17 10:13:40 UTC 2021
                                                                                                                                                                   Wed Mar 17 10:13:41 UTC 2021
                   Wed Mar 17 10:13:42 UTC 2021
                                               Wed Mar 17 10:13:43 UTC 2021
                                                                           Wed Mar 17 10:13:44 UTC 2021
                                                                                                       Wed Mar 17 10:13:45 UTC 2021
                                                                                                                                   Wed Mar 17 10:13:46 UTC 2021
                                                                                                                                                               Wed Mar 17 10:13:47 UTC 2021
               Wed Mar 17 10:13:48 UTC 2021
                                           Wed Mar 17 10:13:49 UTC 2021
                                                                       Wed Mar 17 10:13:50 UTC 2021

也不行

wrfly commented 3 years ago

Hi @huapox 我升级了一下所有的依赖库 (docker/k8s) 你pull一下最新的image看有没有fix这个issue

huapox commented 3 years ago

Hi @huapox 我升级了一下所有的依赖库 (docker/k8s) 你pull一下最新的image看有没有fix这个issue

感谢，晚些时间验证后回复

wrfly / container-web-tty

k3s下查看容器日志，换行格式混乱 #60