{"comment":{"url":"https://api.github.com/repos/mirage/mirage-net-xen/comments/9639114","html_url":"https://github.com/mirage/mirage-net-xen/commit/7d2777d789530e2104b6d9252cdca0d6f8078acb#commitcomment-9639114","id":9639114,"user":{"login":"samoht","id":103693,"avatar_url":"https://avatars.githubusercontent.com/u/103693?v=3","gravatar_id":"","url":"https://api.github.com/users/samoht","html_url":"https://github.com/samoht","followers_url":"https://api.github.com/users/samoht/followers","following_url":"https://api.github.com/users/samoht/following{/other_user}","gists_url":"https://api.github.com/users/samoht/gists{/gist_id}","starred_url":"https://api.github.com/users/samoht/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/samoht/subscriptions","organizations_url":"https://api.github.com/users/samoht/orgs","repos_url":"https://api.github.com/users/samoht/repos","events_url":"https://api.github.com/users/samoht/events{/privacy}","received_events_url":"https://api.github.com/users/samoht/received_events","type":"User","site_admin":false},"position":null,"line":null,"path":"","commit_id":"7d2777d789530e2104b6d9252cdca0d6f8078acb","created_at":"2015-02-08T01:49:18Z","updated_at":"2015-02-08T01:49:18Z","body":"I think this code contains a deadlock/race. Not sure exactly where yet, but with @MagnusS we managed to bisect the 30% SYNACK losses in synjitsu to that commit (or the one later which tries to fix the deadlock, not totally sure).\r\n\r\nA working trace:\r\n```\r\nNetif: add resume hook\r\nNetif.connect 0\r\nNetfront.create: id=0 domid=0\r\nMAC: c0:ff:ee:c0:ff:ee\r\n sg:true gso_tcpv4:true rx_copy:true rx_flip:false smart_poll:false\r\nNetfif.poll_thread:loop\r\nNetif.rx_poll\r\nNOTIFY\r\nNetif.tx_poll\r\nManager: connect\r\nAttempt to open(/dev/urandom)!\r\nManager: configuring\r\nNetif.listen\r\nManager: Interface to 192.168.2.140 nm 255.255.255.0 gw [192.168.2.1]\r\n\r\nARP: sending gratuitous from 192.168.2.140\r\nNetif.writev\r\nwritev-no-retry \"<FF><FF><FF><FF><FF><FF><C0><FF><EE><C0><FF><EE>\\b\\006\\000\\001\\b\\000\\006\\004\\000\\002\r\n<C0><FF><EE><C0><FF><EE><C0><A8>\\002\\140<FF><FF><FF><FF><FF><FF>\\000\\000\\000\\000\"\r\nXXXX 1\r\n[1] available devices = [ 0 ]\r\nShare_page_pool.use\r\nShared_page_pool.alloc\r\n[1] write-request len=42 size=42\r\nNetif.notify\r\nFront.push done\r\nManager: configuration done\r\nFAST-START mode. Watching xenstore for incoming SYN!\r\nPorts: 80\r\nDest-ip: 192.168.2.1\r\nDest-ports: 56581\r\nFound 1 started connections.\r\ntx=65535 sequence=173859064 options=(SACK_ok(Timestamp 2098518192 0)Noop Noop(Window_size_shift 5)Noo\r\np(MSS 1460)) tx_isn=452892043 rx_wnd=65535 rx_wnd_sca=2\r\nFound SYN cookies.\r\nSegment.output time=0.13 xmit=true rexmit=true\r\nWire.xmit checksum 83fc 192.168.2.140.80->192.168.2.1.56581 rst false syn true fin false psh false seq\r\n         452892043 ack 173859065 [ MSS=1460; Window>>2 ] datalen 0 datafrag 0 dataoff 7 olen 8\r\nNetif.writev\r\nwritev-no-retry \"^<F9>8<F8><F1>d<C0><FF><EE><C0><FF><EE>\\b\\000E\\000\\0000<B4>\\011\\000\\000&\\006Z<DF>\r\n<C0><A8>\\002\\140<C0><A8>\\002\\001\\000P<DD>\\005\\026<FE>\\149\\139\\n\\\\<E0><F9>p\\018<FF><FF>\\131<FC>\\000\\000\\002\\004\\005<B4>\\003\\003\\002\\000\"\r\nNetfif.poll_thread:loop\r\nNetif.rx_poll\r\nNetif.tx_poll\r\n[1] reply done\r\n[2] available devices = [ 0 ]\r\nShare_page_pool.use\r\n[2] write-request len=62 size=62\r\nNOTIFY\r\nFront.push done\r\nwritev 6\r\nNetfif.poll_thread:loop\r\nNetif.rx_poll\r\nNetif.tx_poll\r\n[2] reply done\r\nNetfif.poll_thread:loop\r\nNetif.rx_poll\r\nSegment.input\r\nSegment.input\r\nNetif.tx_poll\r\nSegment.output time=0.15 xmit=true rexmit=true HTTP/1.1 200 OK^M\r\n```\r\n\r\nA failing trace:\r\n```\r\nNetif: add resume hook\r\nNetif.connect 0\r\nNetfront.create: id=0 domid=0\r\nMAC: c0:ff:ee:c0:ff:ee\r\n sg:true gso_tcpv4:true rx_copy:true rx_flip:false smart_poll:false\r\nNetfif.poll_thread:loop\r\nNetif.rx_poll\r\nNetif.notify\r\nNetif.tx_poll\r\nManager: connect\r\nAttempt to open(/dev/urandom)!\r\nManager: configuring\r\nNetif.listen\r\nManager: Interface to 192.168.2.140 nm 255.255.255.0 gw [192.168.2.1]\r\n\r\nARP: sending gratuitous from 192.168.2.140\r\nNetif.writev\r\nwritev-no-retry \"<FF><FF><FF><FF><FF><FF><C0><FF><EE><C0><FF><EE>\\b\\006\\000\\001\\b\\000\\006\\004\\000\\00\r\n2<C0><FF><EE><C0><FF><EE><C0><A8>\\002\\140<FF><FF><FF><FF><FF><FF>\\000\\000\\000\\000\"\r\nXXXX 1\r\n[1] available devices = [ 0 ]\r\nShare_page_pool.use\r\nShared_page_pool.alloc\r\n[1] write-request len=42 size=42\r\nNOTIFY\r\nFront.push done\r\nManager: configuration done\r\nFAST-START mode. Watching xenstore for incoming SYN!\r\nPorts: 80\r\nDest-ip: 192.168.2.1\r\nDest-ports: 56602\r\nFound 1 started connections.\r\ntx=65535 sequence=-1072429600 options=(SACK_ok(Timestamp 2098543247 0)Noop Noop(Window_size_shift 5)\r\nNoop(MSS 1460)) tx_isn=452869351 rx_wnd=65535 rx_wnd_sca=2\r\nFound SYN cookies.\r\nSegment.output time=0.11 xmit=true rexmit=true\r\nWire.xmit checksum 01ec 192.168.2.140.80->192.168.2.1.56602 rst false syn true fin false psh false seq\r\n         452869351 ack 3222537697 [ MSS=1460; Window>>2 ] datalen 0 datafrag 0 dataoff 7 olen 8\r\nNetif.writev\r\nwritev-no-retry \"^<F9>8<F8><F1>d<C0><FF><EE><C0><FF><EE>\\b\\000E\\000\\0000<CB><E9>\\000\\000&\\006C\\001\r\n<C0><A8>\\002\\140<C0><A8>\\002\\001\\000P<DD>\\026\\026<FE><<E7><C0>\\020\\005<E1>p\\018<FF><FF>\\001<EC>\\000\\000\\002\\004\\005<B4>\\003\\003\\002\\000\"\r\n[2] available devices = [ 0 ]\r\nShare_page_pool.use\r\n[2] write-request len=62 size=62\r\nFront.push done\r\nwritev 6\r\nNetfif.poll_thread:loop\r\nNetif.rx_poll\r\nNetif.tx_poll\r\n[2] reply done\r\n[1] reply done\r\nNetfif.poll_thread:loop\r\nNetif.rx_poll\r\nNetif.tx_poll\r\nNetfif.poll_thread:loop\r\nNetif.rx_poll\r\nNetif.tx_poll\r\nNetfif.poll_thread:loop\r\n...\r\nNetif.tx_poll\r\nNetfif.poll_thread:loop\r\nNetif.rx_poll\r\nNetif.tx_poll\r\nNetfif.poll_thread:loop\r\nNetif.rx_poll\r\nNetif.tx_poll\r\nNetfif.poll_thread:loop\r\nNetif.rx_poll\r\nSegment.output time=1.02 xmit=true rexmit=true\r\n```\r\n\r\nThe interesting bits being the `[1] write-request len=42 size=42` and `[1] reply done` (and same for [2]). So it seems that in the failing case, the ARP packet write is signalled *after* the SYNACK packet write, which actually never appears on the bridge."}}