W dniu 17.01.2012 10:10, Tomasz Sterna pisze: > Dnia 2012-01-16, pon o godzinie 18:19 +0100, Marcin Mirosław pisze: >> 1. First case, gmail is unreachable, in s2s debug log there is: >> [...] >> Mon Jan 16 15:31:58 2012 out.c:117 creating new out packet queue for >> 'mejor.pl/gmail.com' >> Mon Jan 16 15:31:58 2012 out.c:125 queueing packet for 'mejor.pl/gmail.com >> [...] >> Mon Jan 16 15:31:58 2012 out.c:1177 dns resolve for >> gmail.com@0x7f1fc3d5dc60 started >> [...] >> Mon Jan 16 15:31:58 2012 out.c:793 dns host added for >> gmail.com@0x7f1fc3d5dc60: alt2.xmpp-server.l.google.com/5269 (20/0/842) >> Mon Jan 16 15:31:58 2012 out.c:822 dns response for >> gmail.com@0x7f1fc3d5dc60: SRV _xmpp-server._tcp.gmail.com[4] >> alt3.xmpp-server.l.google.com/5269 (20/0) >> Mon Jan 16 15:31:58 2012 out.c:793 dns host added for >> gmail.com@0x7f1fc3d5dc60: alt3.xmpp-server.l.google.com/5269 (20/0/842) >> Mon Jan 16 15:31:58 2012 out.c:1077 dns ttl for gmail.com@0x7f1fc3d5dc60 >> limited to 842 >> Mon Jan 16 15:31:58 2012 out.c:1088 dns request for >> gmail.com@0x7f1fc3d5dc60: A alt1.xmpp-server.l.google.com >> Mon Jan 16 15:31:58 2012 out.c:1249 read action on fd 11 >> sx (io.c:191) 11 ready for reading > > This looks ok. What happens next?
Now I'm pasting from diffrent log (but symptoms was the same, gmail.com was resolved). Mon Jan 16 17:12:43 2012 out.c:815 dns response for gmail.com@0x7f6e77e5dc60: SRV _xmpp-server._tcp.gmail.com 5 (110) Mon Jan 16 17:12:43 2012 out.c:822 dns response for gmail.com@0x7f6e77e5dc60: SRV _xmpp-server._tcp.gmail.com[0] alt1.xmpp-server.l.google.com/5269 (20/0) Mon Jan 16 17:12:43 2012 out.c:793 dns host added for gmail.com@0x7f6e77e5dc60: alt1.xmpp-server.l.google.com/5269 (20/0/110) Mon Jan 16 17:12:43 2012 out.c:822 dns response for gmail.com@0x7f6e77e5dc60: SRV _xmpp-server._tcp.gmail.com[1] alt2.xmpp-server.l.google.com/5269 (20/0) Mon Jan 16 17:12:43 2012 out.c:793 dns host added for gmail.com@0x7f6e77e5dc60: alt2.xmpp-server.l.google.com/5269 (20/0/110) Mon Jan 16 17:12:43 2012 out.c:822 dns response for gmail.com@0x7f6e77e5dc60: SRV _xmpp-server._tcp.gmail.com[2] alt3.xmpp-server.l.google.com/5269 (20/0) Mon Jan 16 17:12:43 2012 out.c:793 dns host added for gmail.com@0x7f6e77e5dc60: alt3.xmpp-server.l.google.com/5269 (20/0/110) Mon Jan 16 17:12:43 2012 out.c:822 dns response for gmail.com@0x7f6e77e5dc60: SRV _xmpp-server._tcp.gmail.com[3] alt4.xmpp-server.l.google.com/5269 (20/0) Mon Jan 16 17:12:43 2012 out.c:793 dns host added for gmail.com@0x7f6e77e5dc60: alt4.xmpp-server.l.google.com/5269 (20/0/110) Mon Jan 16 17:12:43 2012 out.c:822 dns response for gmail.com@0x7f6e77e5dc60: SRV _xmpp-server._tcp.gmail.com[4] xmpp-server.l.google.com/5269 (5/0) Mon Jan 16 17:12:43 2012 out.c:793 dns host added for gmail.com@0x7f6e77e5dc60: xmpp-server.l.google.com/5269 (5/0/110) Mon Jan 16 17:12:43 2012 out.c:1077 dns ttl for gmail.com@0x7f6e77e5dc60 limited to 110 Mon Jan 16 17:12:43 2012 out.c:1088 dns request for gmail.com@0x7f6e77e5dc60: A alt1.xmpp-server.l.google.com Mon Jan 16 17:12:43 2012 router.c:296 read action on fd 6 sx (io.c:191) 6 ready for reading sx (io.c:197) tag 6 event 2 data 0x77e71dd0 Mon Jan 16 17:12:43 2012 router.c:44 reading from 6 Mon Jan 16 17:12:43 2012 router.c:69 read 1024 bytes sx (io.c:216) passed 1024 read bytes sx (chain.c:93) calling io read chain sx (io.c:240) decoded read data (1024 bytes): r:client' type='unavailable' id='1391' from='mar...@mejor.pl/Gajim_' to='xxx...@gmail.com'><x xmlns='vcard-temp:x:update'><photo/></x></presence></route><route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' to='jabster.pl' from='mejor.pl'><presence xmlns='jabber:client' type='unavailable' id='1391' from='mar...@mejor.pl/Gajim_' to='xxxxxx...@jabster.pl'><x xmlns='vcard-temp:x:update'><photo/></x></presence></route><route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' to='jabbim.pl' from='mejor.pl'><presence xmlns='jabber:client' type='unavailable' id='1391' from='mar...@mejor.pl/Gajim_' to='xxxxxx...@jabbim.pl'><x xmlns='vcard-temp:x:update'><photo/></x></presence></route><route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' to='gmail.com' from='mejor.pl'><presence xmlns='jabber:client' type='unavailable' id='1391' from='mar...@mejor.pl/Gajim_' to='yyyyy...@gmail.com'><x xmlns='vcard-temp:x:update'><photo/></x></presence></route><route xmlns='http://jabberd.jabberstudio.org/n sx (io.c:92) completed nad: <route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' from='mejor.pl' to='gmail.com'><presence xmlns='jabber:client' to='xxxx...@gmail.com' from='mar...@mejor.pl/Gajim_' id='1391' type='unavailable'><x xmlns='vcard-temp:x:update'><photo/></x></presence></route> sx (chain.c:119) calling nad read chain sx (io.c:156) tag 6 event 6 data 0x77e6a7d0 Mon Jan 16 17:12:43 2012 router.c:205 got a packet Mon Jan 16 17:12:43 2012 out.c:403 trying to find connection for 'gmail.com' Mon Jan 16 17:12:43 2012 out.c:406 connection for 'gmail.com' not found Mon Jan 16 17:12:43 2012 out.c:431 pending resolution Mon Jan 16 17:12:43 2012 out.c:125 queueing packet for 'mejor.pl/gmail.com' sx (io.c:92) completed nad: <route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' from='mejor.pl' to='jabster.pl'><presence xmlns='jabber:client' to='xxx...@jabster.pl' from='mar...@mejor.pl/Gajim_' id='1391' type='unavailable'><x xmlns='vcard-temp:x:update'><photo/></x></presence></route> sx (chain.c:119) calling nad read chain sx (io.c:156) tag 6 event 6 data 0x77e68f90 [...] Mon Jan 16 17:12:43 2012 out.c:125 queueing packet for 'mejor.pl/jabbim.pl' sx (io.c:92) completed nad: <route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' from='mejor.pl' to='gmail.com'><presence xmlns='jabber:client' to='yyyy...@gmail.com' from='mar...@mejor.pl/Gajim_' id='1391' type='unavailable'><x xmlns='vcard-temp:x:update'><photo/></x></presence></route> sx (chain.c:119) calling nad read chain sx (io.c:156) tag 6 event 6 data 0x77e72c50 Mon Jan 16 17:12:43 2012 router.c:205 got a packet Mon Jan 16 17:12:43 2012 out.c:403 trying to find connection for 'gmail.com' Mon Jan 16 17:12:43 2012 out.c:406 connection for 'gmail.com' not found Mon Jan 16 17:12:43 2012 out.c:431 pending resolution Mon Jan 16 17:12:43 2012 out.c:125 queueing packet for 'mejor.pl/gmail.com' Mon Jan 16 17:12:43 2012 main.c:583 read action on fd 5 [...] Mon Jan 16 17:12:43 2012 out.c:1029 dns response for gmail.com@0x7f6e77e5dc60: A alt1.xmpp-server.l.google.com 1 (300) Mon Jan 16 17:12:43 2012 out.c:1037 dns response for gmail.com@0x7f6e77e5dc60: A alt1.xmpp-server.l.google.com[0] 209.85.175.125/5269 Mon Jan 16 17:12:43 2012 out.c:739 dns result added for gmail.com@0x7f6e77e5dc60: 209.85.175.125/5269 (20/0/110) Mon Jan 16 17:12:43 2012 out.c:1077 dns ttl for gmail.com@0x7f6e77e5dc60 limited to 110 Mon Jan 16 17:12:43 2012 out.c:1088 dns request for gmail.com@0x7f6e77e5dc60: A alt4.xmpp-server.l.google.com Mon Jan 16 17:12:43 2012 router.c:296 read action on fd 6 sx (io.c:191) 6 ready for reading [...] Mon Jan 16 17:12:43 2012 out.c:1029 dns response for gmail.com@0x7f6e77e5dc60: A alt4.xmpp-server.l.google.com 1 (300) Mon Jan 16 17:12:43 2012 out.c:1037 dns response for gmail.com@0x7f6e77e5dc60: A alt4.xmpp-server.l.google.com[0] 74.125.127.125/5269 Mon Jan 16 17:12:43 2012 out.c:739 dns result added for gmail.com@0x7f6e77e5dc60: 74.125.127.125/5269 (20/0/110) Mon Jan 16 17:12:43 2012 out.c:1077 dns ttl for gmail.com@0x7f6e77e5dc60 limited to 110 Mon Jan 16 17:12:43 2012 out.c:1088 dns request for gmail.com@0x7f6e77e5dc60: A xmpp-server.l.google.com [...] Mon Jan 16 17:12:43 2012 out.c:1029 dns response for gmail.com@0x7f6e77e5dc60: A xmpp-server.l.google.com 1 (15) Mon Jan 16 17:12:43 2012 out.c:1037 dns response for gmail.com@0x7f6e77e5dc60: A xmpp-server.l.google.com[0] 173.194.70.125/5269 Mon Jan 16 17:12:43 2012 out.c:739 dns result added for gmail.com@0x7f6e77e5dc60: 173.194.70.125/5269 (5/0/15) Mon Jan 16 17:12:43 2012 out.c:1077 dns ttl for gmail.com@0x7f6e77e5dc60 limited to 110 Mon Jan 16 17:12:43 2012 out.c:1088 dns request for gmail.com@0x7f6e77e5dc60: A alt3.xmpp-server.l.google.com [...] sx (chain.c:93) calling io read chain sx (io.c:240) decoded read data (1024 bytes): <route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' to='marcel.pl' from='mejor.pl'><presence xmlns='jabber:client' id='1405' from='mar...@mejor.pl/Gajim_' to='xx...@marcel.pl'><priority>50</priority><x xmlns='vcard-temp:x:update'><photo/></x><c xmlns='http://jabber.org/protocol/caps' node='http://gajim.org' ver='47EPEmSc9oqPGwcrbNtpKcYyJcE=' hash='sha-1'/></presence></route><route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' to='gmail.com' from='mejor.pl'><presence xmlns='jabber:client' type='probe' to='zzz...@gmail.com' from='mar...@mejor.pl'/></route><route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' to='gmail.com' from='mejor.pl'><presence xmlns='jabber:client' id='1405' from='mar...@mejor.pl/Gajim_' to='zzzz...@gmail.com'><priority>50</priority><x xmlns='vcard-temp:x:update'><photo/></x><c xmlns='http://jabber.org/protocol/caps' node='http://gajim.org' ver='47EPEmSc9oqPGwcrbNtpKcYyJcE=' hash='sha-1'/></presence></route><route xmlns='http://jabberd.jabberstudio sx (io.c:92) completed nad: <route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' from='mejor.pl' to='marcel.pl'><presence xmlns='jabber:client' to='xxxxxxx...@marcel.pl' from='mar...@mejor.pl/Gajim_' id='1405'><priority>50</priority><x xmlns='vcard-temp:x:update'><photo/></x><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' ver='47EPEmSc9oqPGwcrbNtpKcYyJcE=' node='http://gajim.org'/></presence></route> sx (chain.c:119) calling nad read chain sx (io.c:156) tag 6 event 6 data 0x77e73550 Mon Jan 16 17:12:47 2012 router.c:205 got a packet [...] sx (io.c:92) completed nad: <route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' from='mejor.pl' to='gmail.com'><presence xmlns='jabber:client' from='mar...@mejor.pl' to='zzz...@gmail.com' type='probe'/></route> sx (chain.c:119) calling nad read chain sx (io.c:156) tag 6 event 6 data 0x77e73640 Mon Jan 16 17:12:47 2012 router.c:205 got a packet Mon Jan 16 17:12:47 2012 out.c:403 trying to find connection for 'gmail.com' Mon Jan 16 17:12:47 2012 out.c:406 connection for 'gmail.com' not found Mon Jan 16 17:12:47 2012 out.c:431 pending resolution Mon Jan 16 17:12:47 2012 out.c:125 queueing packet for 'mejor.pl/gmail.com' sx (io.c:92) completed nad: <route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' from='mejor.pl' to='gmail.com'><presence xmlns='jabber:client' to='zzzzz...@gmail.com' from='mar...@mejor.pl/Gajim_' id='1405'><priority>50</priority><x xmlns='vcard-temp:x:update'><photo/></x><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' ver='47EPEmSc9oqPGwcrbNtpKcYyJcE=' node='http://gajim.org'/></presence></route> sx (chain.c:119) calling nad read chain sx (io.c:156) tag 6 event 6 data 0x77e5b850 Mon Jan 16 17:12:47 2012 router.c:205 got a packet Mon Jan 16 17:12:47 2012 out.c:403 trying to find connection for 'gmail.com' Mon Jan 16 17:12:47 2012 out.c:406 connection for 'gmail.com' not found Mon Jan 16 17:12:47 2012 out.c:431 pending resolution Mon Jan 16 17:12:47 2012 out.c:125 queueing packet for 'mejor.pl/gmail.com' Mon Jan 16 17:12:47 2012 router.c:296 read action on fd 6 sx (io.c:191) 6 ready for reading [...] similar messages appears a couple of times, then: sx (io.c:240) decoded read data (241 bytes): <route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' to='gmail.com' from='mejor.pl'><iq xmlns='jabber:client' to='xxxx...@gmail.com' type='get' id='1419' from='mar...@mejor.pl/Gajim_'><query xmlns='jabber:iq:last'/></iq></route> sx (io.c:92) completed nad: <route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' from='mejor.pl' to='gmail.com'><iq xmlns='jabber:client' from='mar...@mejor.pl/Gajim_' id='1419' type='get' to='xxx...@gmail.com'><query xmlns='jabber:iq:last'/></iq></route> sx (chain.c:119) calling nad read chain sx (io.c:156) tag 6 event 6 data 0x77ecc3f0 Mon Jan 16 17:13:09 2012 router.c:205 got a packet Mon Jan 16 17:13:09 2012 out.c:403 trying to find connection for 'gmail.com' Mon Jan 16 17:13:09 2012 out.c:406 connection for 'gmail.com' not found Mon Jan 16 17:13:09 2012 out.c:431 pending resolution Mon Jan 16 17:13:09 2012 out.c:125 queueing packet for 'mejor.pl/gmail.com' Mon Jan 16 17:13:09 2012 router.c:296 read action on fd 6 [...] Mon Jan 16 17:13:09 2012 router.c:205 got a packet Mon Jan 16 17:13:09 2012 out.c:403 trying to find connection for 'gmail.com' Mon Jan 16 17:13:09 2012 out.c:406 connection for 'gmail.com' not found Mon Jan 16 17:13:09 2012 out.c:431 pending resolution Mon Jan 16 17:13:09 2012 out.c:125 queueing packet for 'mejor.pl/gmail.com' Mon Jan 16 17:13:39 2012 main.c:814 running time checks Mon Jan 16 17:13:39 2012 main.c:316 running time checks for mejor.pl/users.jabber.org Mon Jan 16 17:13:39 2012 main.c:324 dns lookup pending for users.jabber.org Mon Jan 16 17:13:39 2012 main.c:316 running time checks for mejor.pl/gmail.com Mon Jan 16 17:13:39 2012 main.c:324 dns lookup pending for gmail.com [...] Mon Jan 16 17:14:39 2012 out.c:1831 deleting out packet queue for mejor.pl/users.jabber.org Mon Jan 16 17:14:39 2012 main.c:316 running time checks for mejor.pl/gmail.com Mon Jan 16 17:14:39 2012 main.c:324 dns lookup pending for gmail.com Mon Jan 16 17:14:39 2012 [notice] dns lookup for gmail.com timed out sx (chain.c:106) calling nad write chain sx (io.c:406) queueing for write: <route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' from='s2s' to='mejor.pl'><presence xmlns='jabber:client' to='mar...@mejor.pl/Gajim_' from='zzzzz...@gmail.com' id='1391' type='error'><error type='cancel' code='404'><remote-server-not-found xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></error><x xmlns='vcard-temp:x:update'><photo/></x></presence></route> sx (io.c:429) tag 6 event 1 data 0x0 Mon Jan 16 17:14:39 2012 router.c:39 want write Mon Jan 16 17:14:39 2012 router.c:307 write action on fd 6 sx (io.c:328) 6 ready for writing sx (io.c:286) encoding 373 bytes for writing: <route xmlns='http://jabberd.jabberstudio.org/ns/component/1.0' from='s2s' to='mejor.pl'><presence xmlns='jabber:client' to='mar...@mejor.pl/Gajim_' from='zzz...@gmail.com' id='1391' type='error'><error type='cancel' code='404'><remote-server-not-found xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></error><x xmlns='vcard-temp:x:update'><photo/></x></presence></route> sx (chain.c:79) calling io write chain and all remain gmail's users are marked as "remote-server-not-found" >> 2. Second case, i restarted s2s daemon and i get similar behavior on >> client "remote-server-not-found". This time there is no messages like >> "out.c:822 dns response for gmail.com@0x7f1fc3d5dc60: SRV >> _xmpp-server._tcp.gmail.com[4] alt3.xmpp-server.l.google.com/5269 >> (20/0)" in s2s debug log. > > Looks like your resolver is failing. I suspect this but i can't confirm. As i wrote earlier i tried local resolver, i tried remote resolver. Nothing changed. Other local software (like spamassassin, exim) didn't log about problems with dns resolving. >> Mon Jan 16 16:53:56 2012 out.c:793 dns host added for >> marcel.pl@0x7fe5d27b01a0: maraton.marcel.pl/5269 (0/0/2901) >> Mon Jan 16 16:53:56 2012 out.c:1077 dns ttl for marcel.pl@0x7fe5d27b01a0 >> limited to 2901 >> Mon Jan 16 16:53:56 2012 out.c:1088 dns request for >> marcel.pl@0x7fe5d27b01a0: A maraton.marcel.pl >> Mon Jan 16 16:53:56 2012 router.c:296 read action on fd 6 >> sx (io.c:191) 6 ready for reading > > Also looks good. What happens next? I didn't save logs, i was sure i can reproduce all situations, today i can't do it. Now i have situation s2s can't resolve hostnames, i started tcpdump to check what is going on. Here it is: 15:30:43.394695 IP (tos 0x0, ttl 60, id 0, offset 0, flags [DF], proto UDP (17), length 96) 127.0.0.1.35090 > 127.0.0.1.53: 55598+ [1au] SRV? _xmpp-server._tcp.conference.jabber.org. (68) 15:30:43.474664 IP (tos 0x0, ttl 60, id 0, offset 0, flags [DF], proto UDP (17), length 91) 127.0.0.1.35090 > 127.0.0.1.53: 63253+ [1au] SRV? _xmpp-server._tcp.users.jabber.org. (63) 15:30:43.484660 IP (tos 0x0, ttl 60, id 0, offset 0, flags [DF], proto UDP (17), length 84) 127.0.0.1.35090 > 127.0.0.1.53: 19408+ [1au] SRV? _xmpp-server._tcp.marcel.pl. (56) 15:30:43.494656 IP (tos 0x0, ttl 60, id 42318, offset 0, flags [none], proto UDP (17), length 143) 127.0.0.1.53 > 127.0.0.1.35090: 63253 NXDomain 0/1/1 (115) 15:30:43.504653 IP (tos 0x0, ttl 60, id 42319, offset 0, flags [none], proto UDP (17), length 198) 127.0.0.1.53 > 127.0.0.1.35090: 19408 1/3/2 _xmpp-server._tcp.marcel.pl. SRV maraton.marcel.pl.:5269 0 0 (170) 15:30:43.554633 IP (tos 0x0, ttl 60, id 42320, offset 0, flags [none], proto UDP (17), length 250) 127.0.0.1.53 > 127.0.0.1.35090: 55598 1/5/2 _xmpp-server._tcp.conference.jabber.org. SRV hermes.jabber.org.:5269 30 30 (222) So resolver answered, but s2s didn't got it, didn't ask for A maraton.marcel.pl. S2s debug log says: x (chain.c:119) calling nad read chain sx (io.c:156) tag 6 event 6 data 0xd05b0070 Tue Jan 17 15:30:43 2012 router.c:205 got a packet Tue Jan 17 15:30:43 2012 out.c:403 trying to find connection for 'marcel.pl' Tue Jan 17 15:30:43 2012 out.c:406 connection for 'marcel.pl' not found Tue Jan 17 15:30:43 2012 out.c:412 no dns for marcel.pl, preparing for resolution Tue Jan 17 15:30:43 2012 out.c:440 requesting resolution for marcel.pl Tue Jan 17 15:30:43 2012 out.c:1177 dns resolve for marcel.pl@0x7f8ed05b03c0 started Tue Jan 17 15:30:43 2012 out.c:839 dns request for marcel.pl@0x7f8ed05b03c0: SRV xmpp-server Tue Jan 17 15:30:43 2012 out.c:117 creating new out packet queue for 'mejor.pl/marcel.pl' Tue Jan 17 15:30:43 2012 out.c:125 queueing packet for 'mejor.pl/marcel.pl' Tue Jan 17 15:30:43 2012 main.c:583 read action on fd 5 Tue Jan 17 15:30:43 2012 main.c:583 read action on fd 5 Tue Jan 17 15:30:43 2012 router.c:296 read action on fd 6 [...] Tue Jan 17 15:31:38 2012 main.c:814 running time checks Tue Jan 17 15:31:38 2012 main.c:316 running time checks for mejor.pl/users.jabber.org Tue Jan 17 15:31:38 2012 main.c:324 dns lookup pending for users.jabber.org Tue Jan 17 15:31:38 2012 main.c:316 running time checks for mejor.pl/conference.jabber.org Tue Jan 17 15:31:38 2012 main.c:324 dns lookup pending for conference.jabber.org Tue Jan 17 15:31:38 2012 main.c:316 running time checks for mejor.pl/marcel.pl Tue Jan 17 15:31:38 2012 main.c:324 dns lookup pending for marcel.pl Tue Jan 17 15:31:38 2012 main.c:819 next time check at 1326810758 There was no dns traffic in tame later than 15:30:43. This situation is mysterious for me. Is it possible to have more precise timestams in debug log? Regards, Marcin.
