Comment 1 for bug 1580200

Revision history for this message
Ilya Shakhat (shakhat) wrote :

rsyslogd is ON (note that one of calls lasts for 1.5 seconds!):

13:55:30.540264 setsockopt(8, SOL_TCP, TCP_QUICKACK, [1], 4) = 0 <0.000031>
13:55:30.540419 recvfrom(8, "GET / HTTP/1.1\r\nUser-Agent: curl"..., 8192, 0, NULL, NULL) = 77 <0.000010>
13:55:30.540550 getsockname(8, {sa_family=AF_INET, sin_port=htons(9292), sin_addr=inet_addr("192.168.0.88")}, [16]) = 0 <0.000009>
13:55:30.540985 stat("/var/log/glance/api.log", {st_mode=S_IFREG|0644, st_size=2606291, ...}) = 0 <0.000016>
13:55:30.542807 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000017>
13:55:30.542885 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000014>
13:55:30.542987 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000015>
13:55:30.543091 write(3, "2016-05-10 13:55:30.540 7654 DEB"..., 228) = 228 <0.000020>
13:55:30.543186 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000011>
13:55:30.543228 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000009>
13:55:30.543274 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000013>
13:55:30.543344 sendto(7, "<151>May 10 13:55:30 glance-api:"..., 260, MSG_NOSIGNAL, NULL, 0) = 260 <1.587517>
13:55:32.131202 stat("/var/log/glance/api.log", {st_mode=S_IFREG|0644, st_size=2606519, ...}) = 0 <0.000015>
13:55:32.131641 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000018>
13:55:32.131721 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000013>
13:55:32.131791 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000012>
13:55:32.131885 write(3, "2016-05-10 13:55:32.131 7654 DEB"..., 199) = 199 <0.000019>
13:55:32.131979 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000017>
13:55:32.132066 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000017>
13:55:32.132139 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000013>
13:55:32.132218 sendto(7, "<151>May 10 13:55:32 glance-api:"..., 231, MSG_NOSIGNAL, NULL, 0) = 231 <0.000012>
13:55:32.132385 stat("/var/log/glance/api.log", {st_mode=S_IFREG|0644, st_size=2606718, ...}) = 0 <0.000010>
13:55:32.132463 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000012>
13:55:32.132515 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000012>
13:55:32.132564 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000010>
13:55:32.132628 write(3, "2016-05-10 13:55:32.132 7654 DEB"..., 222) = 222 <0.000017>
13:55:32.132728 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000012>
13:55:32.132772 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000009>
13:55:32.132812 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000009>
13:55:32.132863 sendto(7, "<151>May 10 13:55:32 glance-api:"..., 254, MSG_NOSIGNAL, NULL, 0) = 254 <0.000011>
13:55:32.133379 sendto(8, "HTTP/1.1 300 Multiple Choices\r\nC"..., 768, 0, NULL, 0) = 768 <0.000038>
13:55:32.133468 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000014>
13:55:32.133617 stat("/var/log/glance/api.log", {st_mode=S_IFREG|0644, st_size=2606940, ...}) = 0 <0.000011>
13:55:32.133683 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000016>
13:55:32.133734 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000011>
13:55:32.133785 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000010>
13:55:32.133883 write(3, "2016-05-10 13:55:32.133 7654 INF"..., 133) = 133 <0.000026>
13:55:32.134006 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.002144>
13:55:32.136208 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000010>
13:55:32.136263 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000010>
13:55:32.136320 sendto(7, "<150>May 10 13:55:32 glance-api:"..., 165, MSG_NOSIGNAL, NULL, 0) = 165 <0.000011>
13:55:32.136396 recvfrom(8, "", 8192, 0, NULL, NULL) = 0 <0.000008>
13:55:32.136457 shutdown(8, SHUT_RDWR) = 0 <0.000044>

glance-ap 7654 glance 0u CHR 1,3 0t0 1029 /dev/null
glance-ap 7654 glance 1u CHR 136,5 0t0 8 /dev/pts/5
glance-ap 7654 glance 2u CHR 136,5 0t0 8 /dev/pts/5
glance-ap 7654 glance 3w REG 252,2 2603096 3145732 /var/log/glance/api.log
glance-ap 7654 glance 4u IPv4 173449409 0t0 TCP messaging-node-159.domain.tld:9292 (LISTEN)
glance-ap 7654 glance 6r CHR 1,9 0t0 1034 /dev/urandom
glance-ap 7654 glance 7u unix 0xffff881fc4d603c0 0t0 173586615 socket

--------------

rsyslogd is OFF:

13:50:34.233469 setsockopt(7, SOL_TCP, TCP_QUICKACK, [1], 4) = 0 <0.000010>
13:50:34.233559 recvfrom(7, "GET / HTTP/1.1\r\nUser-Agent: curl"..., 8192, 0, NULL, NULL) = 77 <0.000009>
13:50:34.233686 getsockname(7, {sa_family=AF_INET, sin_port=htons(9292), sin_addr=inet_addr("192.168.0.131")}, [16]) = 0 <0.000007>
13:50:34.233979 stat("/var/log/glance/api.log", {st_mode=S_IFREG|0644, st_size=2796601, ...}) = 0 <0.000010>
13:50:34.234048 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.234081 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.234122 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000006>
13:50:34.234169 write(3, "2016-05-10 13:50:34.233 13713 DE"..., 229) = 229 <0.000011>
13:50:34.234227 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000008>
13:50:34.234256 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000006>
13:50:34.234291 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000006>
13:50:34.234328 sendto(4, "<151>May 10 13:50:34 glance-api:"..., 261, MSG_NOSIGNAL, NULL, 0) = 261 <0.000012>
13:50:34.234460 stat("/var/log/glance/api.log", {st_mode=S_IFREG|0644, st_size=2796830, ...}) = 0 <0.000010>
13:50:34.234519 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.234549 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000006>
13:50:34.234579 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000006>
13:50:34.234621 write(3, "2016-05-10 13:50:34.234 13713 DE"..., 200) = 200 <0.000011>
13:50:34.234677 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.234705 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000006>
13:50:34.234733 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.234770 sendto(4, "<151>May 10 13:50:34 glance-api:"..., 232, MSG_NOSIGNAL, NULL, 0) = 232 <0.000011>
13:50:34.234883 stat("/var/log/glance/api.log", {st_mode=S_IFREG|0644, st_size=2797030, ...}) = 0 <0.000009>
13:50:34.234935 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.234965 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.234995 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.235038 write(3, "2016-05-10 13:50:34.234 13713 DE"..., 223) = 223 <0.000011>
13:50:34.235092 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.235121 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000006>
13:50:34.235149 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.235185 sendto(4, "<151>May 10 13:50:34 glance-api:"..., 255, MSG_NOSIGNAL, NULL, 0) = 255 <0.000010>
13:50:34.235567 sendto(7, "HTTP/1.1 300 Multiple Choices\r\nC"..., 768, 0, NULL, 0) = 768 <0.000035>
13:50:34.235639 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000008>
13:50:34.235742 stat("/var/log/glance/api.log", {st_mode=S_IFREG|0644, st_size=2797253, ...}) = 0 <0.000010>
13:50:34.235800 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.235832 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.235863 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.235906 write(3, "2016-05-10 13:50:34.235 13713 IN"..., 135) = 135 <0.000011>
13:50:34.235961 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000008>
13:50:34.235991 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000007>
13:50:34.236020 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0 <0.000006>
13:50:34.236055 sendto(4, "<150>May 10 13:50:34 glance-api:"..., 167, MSG_NOSIGNAL, NULL, 0) = 167 <0.000011>
13:50:34.236103 recvfrom(7, "", 8192, 0, NULL, NULL) = 0 <0.000010>
13:50:34.236153 shutdown(7, SHUT_RDWR) = 0 <0.000039>
13:50:34.236208 close(7) = 0 <0.000010>

glance-ap 13713 glance 0u CHR 1,3 0t0 1029 /dev/null
glance-ap 13713 glance 1u CHR 136,5 0t0 8 /dev/pts/5
glance-ap 13713 glance 2u CHR 136,5 0t0 8 /dev/pts/5
glance-ap 13713 glance 3w REG 252,2 2804472 6553604 /var/log/glance/api.log
glance-ap 13713 glance 4u unix 0xffff881fca5b9a40 0t0 245673379 socket
glance-ap 13713 glance 5u IPv4 245638031 0t0 TCP node-134.domain.tld:9292 (LISTEN)
glance-ap 13713 glance 6r CHR 1,9 0t0 1034 /dev/urandom