pyHesiodFS sometimes returns mysterious EIO

[andersk]

anders@balanced-tree:~$ stat /mit/z
stat: cannot stat `/mit/z': No such file or directory
anders@balanced-tree:~$ stat /mit/e
stat: cannot stat `/mit/e': Input/output error

And this time I have an strace!

1212       0.000000 read(3,  <unfinished ...>
1211       0.000115 read(3,  <unfinished ...>
1184       0.000042 futex(0x7fff16975d80, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
1212      11.118132 <... read resumed> "*\0\0\0\1\0\0\0\22\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\350\3\0\0\350\3\0\0"..., 135168) = 42
1212       0.000311 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=185, ...}) = 0
1212       0.003602 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=185, ...}) = 0
1212       0.000156 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 5
1212       0.000113 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.1.1")}, 16) = 0
1212       0.000177 poll([{fd=5, events=POLLOUT}], 1, 0) = 1 ([{fd=5, revents=POLLOUT}])
1212       0.000106 sendto(5, "\364\1\1\0\0\1\0\0\0\0\0\0\1z\6filsys\2ns\6athena\3"..., 44, MSG_NOSIGNAL, NULL, 0) = 44
1212       0.000172 poll([{fd=5, events=POLLIN}], 1, 5000) = 1 ([{fd=5, revents=POLLIN}])
1212       0.136430 recvfrom(5, "\364\1\201\203\0\1\0\0\0\1\0\0\1z\6filsys\2ns\6athena\3"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.1.1")}, [16]) = 93
1212       0.000233 close(5)            = 0
1212       0.000271 writev(3, [{"\20\0\0\0\376\377\377\377\22\0\0\0\0\0\0\0", 16}], 1) = 16
1212       0.000154 read(3,  <unfinished ...>
1211       2.688271 <... read resumed> "*\0\0\0\1\0\0\0\23\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\350\3\0\0\350\3\0\0"..., 135168) = 42
1211       0.000357 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=185, ...}) = 0
1211       0.000246 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=185, ...}) = 0
1211       0.000222 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 5
1211       0.000178 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
1211       0.000191 poll([{fd=5, events=POLLOUT}], 1, 0) = 1 ([{fd=5, revents=POLLOUT}])
1211       0.000181 sendto(5, "\3007\1\0\0\1\0\0\0\0\0\0\1e\6filsys\2ns\6athena\3"..., 44, MSG_NOSIGNAL, NULL, 0) = 44
1211       0.000291 poll([{fd=5, events=POLLIN}], 1, 5000) = 1 ([{fd=5, revents=POLLERR}])
1211       0.000178 close(5)            = 0
1211       0.000138 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 5
1211       0.000139 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
1211       0.000149 poll([{fd=5, events=POLLOUT}], 1, 0) = 1 ([{fd=5, revents=POLLOUT}])
1211       0.000139 sendto(5, "\3007\1\0\0\1\0\0\0\0\0\0\1e\6filsys\2ns\6athena\3"..., 44, MSG_NOSIGNAL, NULL, 0) = 44
1211       0.000171 poll([{fd=5, events=POLLIN}], 1, 5000) = 1 ([{fd=5, revents=POLLERR}])
1211       0.000137 close(5)            = 0
1211       0.000127 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 5
1211       0.000129 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
1211       0.000149 poll([{fd=5, events=POLLOUT}], 1, 0) = 1 ([{fd=5, revents=POLLOUT}])
1211       0.000140 sendto(5, "\3007\1\0\0\1\0\0\0\0\0\0\1e\6filsys\2ns\6athena\3"..., 44, MSG_NOSIGNAL, NULL, 0) = 44
1211       0.000170 poll([{fd=5, events=POLLIN}], 1, 5000) = 1 ([{fd=5, revents=POLLERR}])
1211       0.000135 close(5)            = 0
1211       0.000128 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 5
1211       0.000139 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
1211       0.000148 poll([{fd=5, events=POLLOUT}], 1, 0) = 1 ([{fd=5, revents=POLLOUT}])
1211       0.000130 sendto(5, "\3007\1\0\0\1\0\0\0\0\0\0\1e\6filsys\2ns\6athena\3"..., 44, MSG_NOSIGNAL, NULL, 0) = 44
1211       0.000393 poll([{fd=5, events=POLLIN}], 1, 5000) = 1 ([{fd=5, revents=POLLERR}])
1211       0.000139 close(5)            = 0
1211       0.000759 writev(3, [{"\20\0\0\0\373\377\377\377\23\0\0\0\0\0\0\0", 16}], 1) = 16
1211       0.000164 read(3, 

[jdreed]

I can't reproduce this on Precise. Is there any reason to believe this was something actually fixable in PyHesiodFS as opposed to a bug in python-fuse?

[achernya]

I've seen similar behavior from a pyHesiodFS started by launchd on OS X. I mentioned this to Quentin, who believed the issue has to do with pyHesiodFS caching DNS servers that are no longer reachable/valid.

[quentin]

Yeah, my theory is that libhesiod is reading resolv.conf and not rereading it later when it changes.

[jdreed]

So, uh, this sounds like a libhesiod bug. And I hear we have a maintainer for libhesiod these days.