[OpenAFS-port-darwin] callbacks hanging on Intel Macs?
Nicholas Riley
njriley@uiuc.edu
Thu, 12 Oct 2006 21:52:56 -0500
On Oct 12, 2006, at 7:45 AM, Derrick J Brashear wrote:
> On Wed, 11 Oct 2006, Nicholas Riley wrote:
>> ppc% touch bar
>> touch: bar: No such file or directory
>> # should this happen?
>> ppc% touch bar
>> intel% ls bar
>> ls: bar: No such file or directory
>
> Intel is 32 or 64 bit? Can you get fstrace data?
It's 64-bit (Core 2 Duo iMac).
Here's a fstrace from the iMac doing the above:
raw op 701087790, time 953.687890, pid 944
p0:0x50223a64 p1:0x50447344 p2:568092 p3:568092
raw op 701087791, time 953.687892, pid 944
p0:10240 p1:1 p2:0.0 p3:0.0
raw op 701087823, time 953.687898, pid 944
p0:0x50223a64 p1:bar p2:89.536871243.92525600.623721040 p3:2
raw op 701087810, time 953.687899, pid 944
p0:2 p1:19
raw op 701087790, time 953.687913, pid 944
p0:0x50223a64 p1:0x50447344 p2:568092 p3:568092
raw op 701087791, time 953.687914, pid 944
p0:10240 p1:1 p2:0.0 p3:0.0
raw op 701087823, time 953.687915, pid 944
p0:0x50223a64 p1:bar p2:89.536871243.92525600.623721040 p3:2
raw op 701087810, time 953.687916, pid 944
p0:2 p1:19
raw op 701087815, time 953.687926, pid 944
p0:0x5021c0e4 p1:1
raw op 701087815, time 953.687929, pid 944
p0:0x50223a64 p1:999999
raw op 701087816, time 953.688485, pid 944
p0:0x5021c0e4 p1:1
> So then the questions there: rxdebug the client and whatever server
> it's talking to, perhaps tcpdump the traffic between the two?
OK, this is the tcpdump when I try the hanging 'touch bar':
maggie:~ root# tcpdump -vv -O '(udp and udp[0:2] >= 7000 and udp[0:2]
<= 7010)'
21:42:42.355566 IP (tos 0x0, ttl 64, id 54390, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2298 seq 1 ser 13429 secindex 2 serviceid 1 <client-
init>,<last-pckt> fs call create-file fid 536871243/1/1 "bar" [|fs] (76)
21:42:42.355886 IP (tos 0x0, ttl 255, id 48732, offset 0, flags [DF],
proto: UDP (17), length: 94) alnitak.acm.uiuc.edu.afs3-fileserver >
maggie.acm.uiuc.edu.afs3-callback: rx ack cid e373a0e0 call# 2298
seq 0 ser 9605 secindex 2 serviceid 1 <req-ack>,<slow-start> bufspace
0 maxskew 0 first 1 serial 0 reason ping acked 16777216 ifmtu 1444 (66)
21:42:42.355965 IP (tos 0x0, ttl 64, id 54391, offset 0, flags
[none], proto: UDP (17), length: 93) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx ack cid e373a0e0
call# 2298 seq 0 ser 13430 secindex 2 serviceid 1 <client-init>,<slow-
start> bufspace 0 maxskew 0 first 1 serial 9605 reason ping response
ifmtu 5692 (65)
21:42:42.411352 IP (tos 0x0, ttl 255, id 48733, offset 0, flags [DF],
proto: UDP (17), length: 60) alnitak.acm.uiuc.edu.afs3-fileserver >
maggie.acm.uiuc.edu.afs3-callback: [udp sum ok] rx abort cid
e373a0e0 call# 2298 seq 0 ser 9606 secindex 2 serviceid 1 fs reply
create-file error #49733392 (32)
21:42:42.411496 IP (tos 0x0, ttl 64, id 54392, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2299 seq 1 ser 13431 secindex 2 serviceid 1 <client-
init>,<last-pckt> fs call create-file fid 536871243/1/1 "bar" [|fs] (76)
21:42:42.482574 IP (tos 0x0, ttl 255, id 48734, offset 0, flags [DF],
proto: UDP (17), length: 60) alnitak.acm.uiuc.edu.afs3-fileserver >
maggie.acm.uiuc.edu.afs3-callback: [udp sum ok] rx abort cid
e373a0e0 call# 2299 seq 0 ser 9607 secindex 2 serviceid 1 fs reply
create-file error #49733392 (32)
21:42:42.482710 IP (tos 0x0, ttl 64, id 54393, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2300 seq 1 ser 13432 secindex 2 serviceid 1 <client-
init>,<last-pckt> fs call create-file fid 536871243/1/1 "bar" [|fs] (76)
21:42:42.536476 IP (tos 0x0, ttl 255, id 48735, offset 0, flags [DF],
proto: UDP (17), length: 60) alnitak.acm.uiuc.edu.afs3-fileserver >
maggie.acm.uiuc.edu.afs3-callback: [udp sum ok] rx abort cid
e373a0e0 call# 2300 seq 0 ser 9608 secindex 2 serviceid 1 fs reply
create-file error #49733392 (32)
21:42:42.536591 IP (tos 0x0, ttl 64, id 54394, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2301 seq 1 ser 13433 secindex 2 serviceid 1 <client-
init>,<last-pckt> fs call create-file fid 536871243/1/1 "bar" [|fs] (76)
21:42:42.616133 IP (tos 0x0, ttl 255, id 48736, offset 0, flags [DF],
proto: UDP (17), length: 60) alnitak.acm.uiuc.edu.afs3-fileserver >
maggie.acm.uiuc.edu.afs3-callback: [udp sum ok] rx abort cid
e373a0e0 call# 2301 seq 0 ser 9609 secindex 2 serviceid 1 fs reply
create-file error #49733392 (32)
21:42:42.616273 IP (tos 0x0, ttl 64, id 54395, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2302 seq 1 ser 13434 secindex 2 serviceid 1 <client-
init>,<last-pckt> fs call create-file fid 536871243/1/1 "bar" [|fs] (76)
21:42:42.661898 IP (tos 0x0, ttl 255, id 48737, offset 0, flags [DF],
proto: UDP (17), length: 60) alnitak.acm.uiuc.edu.afs3-fileserver >
maggie.acm.uiuc.edu.afs3-callback: [udp sum ok] rx abort cid
e373a0e0 call# 2302 seq 0 ser 9610 secindex 2 serviceid 1 fs reply
create-file error #49733392 (32)
21:42:42.662040 IP (tos 0x0, ttl 64, id 54396, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2303 seq 1 ser 13435 secindex 2 serviceid 1 <client-
init>,<last-pckt> fs call create-file fid 536871243/1/1 "bar" [|fs] (76)
21:42:42.715359 IP (tos 0x0, ttl 255, id 48738, offset 0, flags [DF],
proto: UDP (17), length: 60) alnitak.acm.uiuc.edu.afs3-fileserver >
maggie.acm.uiuc.edu.afs3-callback: [udp sum ok] rx abort cid
e373a0e0 call# 2303 seq 0 ser 9611 secindex 2 serviceid 1 fs reply
create-file error #49733392 (32)
21:42:42.715497 IP (tos 0x0, ttl 64, id 54397, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2304 seq 1 ser 13436 secindex 2 serviceid 1 <client-
init>,<last-pckt> fs call create-file fid 536871243/1/1 "bar" [|fs] (76)
21:42:42.763366 IP (tos 0x0, ttl 255, id 48739, offset 0, flags [DF],
proto: UDP (17), length: 60) alnitak.acm.uiuc.edu.afs3-fileserver >
maggie.acm.uiuc.edu.afs3-callback: [udp sum ok] rx abort cid
e373a0e0 call# 2304 seq 0 ser 9612 secindex 2 serviceid 1 fs reply
create-file error #49733392 (32)
21:42:42.763505 IP (tos 0x0, ttl 64, id 54398, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2305 seq 1 ser 13437 secindex 2 serviceid 1 <client-
init>,<last-pckt> fs call create-file fid 536871243/1/1 "bar" [|fs] (76)
21:42:42.810642 IP (tos 0x0, ttl 255, id 48740, offset 0, flags [DF],
proto: UDP (17), length: 60) alnitak.acm.uiuc.edu.afs3-fileserver >
maggie.acm.uiuc.edu.afs3-callback: [udp sum ok] rx abort cid
e373a0e0 call# 2305 seq 0 ser 9613 secindex 2 serviceid 1 fs reply
create-file error #49733392 (32)
21:42:42.810781 IP (tos 0x0, ttl 64, id 54399, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2306 seq 1 ser 13438 secindex 2 serviceid 1 <client-
init>,<last-pckt> fs call create-file fid 536871243/1/1 "bar" [|fs] (76)
21:42:42.864621 IP (tos 0x0, ttl 255, id 48741, offset 0, flags [DF],
proto: UDP (17), length: 60) alnitak.acm.uiuc.edu.afs3-fileserver >
maggie.acm.uiuc.edu.afs3-callback: [udp sum ok] rx abort cid
e373a0e0 call# 2306 seq 0 ser 9614 secindex 2 serviceid 1 fs reply
create-file error #49733392 (32)
21:42:42.864760 IP (tos 0x0, ttl 64, id 54400, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2307 seq 1 ser 13439 secindex 2 serviceid 1 <client-
init>,<last-pckt> fs call create-file fid 536871243/1/1 "bar" [|fs] (76)
21:42:42.894883 IP (tos 0x0, ttl 255, id 48742, offset 0, flags [DF],
proto: UDP (17), length: 60) alnitak.acm.uiuc.edu.afs3-fileserver >
maggie.acm.uiuc.edu.afs3-callback: [udp sum ok] rx abort cid
e373a0e0 call# 2307 seq 0 ser 9615 secindex 2 serviceid 1 fs reply
create-file error #49733392 (32)
21:42:42.895023 IP (tos 0x0, ttl 64, id 54401, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2308 seq 1 ser 13440 secindex 2 serviceid 1 <client-
init>,<last-pckt> fs call create-file fid 536871243/1/1 "bar" [|fs] (76)
21:42:43.413758 IP (tos 0x0, ttl 64, id 54402, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2308 seq 1 ser 13441 secindex 2 serviceid 1 <client-
init>,<req-ack>,<last-pckt> fs call create-file fid 536871243/1/1
"bar" [|fs] (76)
21:42:44.413865 IP (tos 0x0, ttl 64, id 54403, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2308 seq 1 ser 13442 secindex 2 serviceid 1 <client-
init>,<req-ack>,<last-pckt> fs call create-file fid 536871243/1/1
"bar" [|fs] (76)
21:42:45.914025 IP (tos 0x0, ttl 64, id 54404, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2308 seq 1 ser 13443 secindex 2 serviceid 1 <client-
init>,<req-ack>,<last-pckt> fs call create-file fid 536871243/1/1
"bar" [|fs] (76)
21:42:45.946620 IP (tos 0x0, ttl 255, id 48743, offset 0, flags [DF],
proto: UDP (17), length: 60) alnitak.acm.uiuc.edu.afs3-fileserver >
maggie.acm.uiuc.edu.afs3-callback: [udp sum ok] rx abort cid
e373a0e0 call# 2308 seq 0 ser 9616 secindex 2 serviceid 1 fs reply
create-file error #49733392 (32)
21:42:45.946797 IP (tos 0x0, ttl 64, id 54405, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2309 seq 1 ser 13444 secindex 2 serviceid 1 <client-
init>,<last-pckt> fs call create-file fid 536871243/1/1 "bar" [|fs] (76)
21:42:46.414089 IP (tos 0x0, ttl 64, id 54406, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2309 seq 1 ser 13445 secindex 2 serviceid 1 <client-
init>,<req-ack>,<last-pckt> fs call create-file fid 536871243/1/1
"bar" [|fs] (76)
21:42:47.414214 IP (tos 0x0, ttl 64, id 54415, offset 0, flags
[none], proto: UDP (17), length: 104) maggie.acm.uiuc.edu.afs3-
callback > alnitak.acm.uiuc.edu.afs3-fileserver: rx data cid
e373a0e0 call# 2309 seq 1 ser 13446 secindex 2 serviceid 1 <client-
init>,<req-ack>,<last-pckt> fs call create-file fid 536871243/1/1
"bar" [|fs] (76)
21:42:47.796509 IP (tos 0x0, ttl 255, id 48744, offset 0, flags [DF],
proto: UDP (17), length: 112) alnitak.acm.uiuc.edu.afs3-callback >
maggie.acm.uiuc.edu.49446: rx debug cid 00000000 call# 101 seq 0 ser
0 secindex 0 serviceid 0 <last-pckt> (84)
21:42:47.797018 IP (tos 0x0, ttl 255, id 48745, offset 0, flags [DF],
proto: UDP (17), length: 232) alnitak.acm.uiuc.edu.afs3-callback >
maggie.acm.uiuc.edu.49446: rx debug cid 00000000 call# 102 seq 0 ser
0 secindex 0 serviceid 0 <last-pckt> (204)
and rxdebug on the server:
maggie:~ njriley$ rxdebug alnitak 7001
Trying 128.174.251.8 (port 7001):
Free packets: 130, packet reclaims: 0, calls: 2216, used FDs: 64
not waiting for packets.
0 calls waiting for a thread
1 threads are idle
Done.
and the client:
maggie:~ njriley$ rxdebug maggie 7001
Trying 128.174.251.20 (port 7001):
Free packets: 129, packet reclaims: 0, calls: 56, used FDs: 64
not waiting for packets.
0 calls waiting for a thread
1 threads are idle
Connection from host 128.174.251.8, port 7000, Cuid b00aae76/1494f914
serial 298, natMTU 1444, security index 0, client conn
call 0: # 142, state dally, mode: receiving, flags: receive_done
call 1: # 0, state not initialized
call 2: # 0, state not initialized
call 3: # 0, state not initialized
Connection from host 128.174.251.8, port 7000, Cuid b00aae76/e373a0e0
serial 13445, natMTU 1444, flags pktCksum, security index 2,
client conn
rxkad: level clear, flags pktCksum
Received 7933009 bytes in 7627 packets
Sent 9000870 bytes in 8593 packets
call 0: # 2309, state active, mode: receiving, flags:
reader_wait, has_output_packets
call 1: # 93, state not initialized
call 2: # 0, state not initialized
call 3: # 0, state not initialized
Done.
Another thing I notice is, if I do 'touch bar' on another machine,
and 'ls bar' on the iMac, tcpdump shows no AFS network traffic.
This seems a bit fragile to reproduce, still; I've been able to
provoke the client into behaving correctly for a while but I'm not
sure what does it.
Thanks for the help.