Ticket #156: jabberlog

File jabberlog, 16.4 KB (added by giftculture, 16 months ago)
Line 
1JBRD: debug on
2JBRD: version(2.1.15)
3JBRD: config_dir(/usr/local/etc)
4JBRD: LaunchJob: router -> /usr/local/bin/router -c /usr/local/etc/router.xml -D
5JBRD: LaunchJob: resolver -> /usr/local/bin/resolver -c /usr/local/etc/resolver.xml -D
6JBRD: LaunchJob: sm -> /usr/local/bin/sm -c /usr/local/etc/sm.xml -D
7JBRD: LaunchJob: s2s -> /usr/local/bin/s2s -c /usr/local/etc/s2s.xml -D
8JBRD: LaunchJob: c2s -> /usr/local/bin/c2s -c /usr/local/etc/c2s.xml -D
9ROUT: Fri Sep 28 14:59:57 2007 [notice] starting up
10RSLV: Fri Sep 28 14:59:57 2007 [notice] starting up
11ROUT: Fri Sep 28 14:59:57 2007 user.c:34 loading user table
12SM  : Fri Sep 28 14:59:57 2007 [notice] starting up
13RSLV: sx (sasl_gsasl.c:677) initialising sasl plugin
14S2S : Fri Sep 28 14:59:57 2007 [notice] starting up (interval=60, queue=60, keepalive=0, idle=86400)
15SM  : Fri Sep 28 14:59:57 2007 storage.c:96 adding arbitrary types to driver 'mysql'
16C2S : Fri Sep 28 14:59:57 2007 [notice] starting up
17S2S : sx (sasl_gsasl.c:677) initialising sasl plugin
18C2S : Fri Sep 28 14:59:57 2007 authreg.c:73 preloaded module 'mysql' (not initialized yet)
19ROUT: Fri Sep 28 14:59:57 2007 [info] process id is 27941, written to /usr/local/var/jabberd/pid/router.pid
20ROUT: Fri Sep 28 14:59:57 2007 user.c:89 remembering user 'jabberd'
21C2S : Fri Sep 28 14:59:57 2007 [info] process id is 27945, written to /usr/local/var/jabberd/pid/c2s.pid
22C2S : sx (sasl_gsasl.c:677) initialising sasl plugin
23ROUT: Fri Sep 28 14:59:57 2007 [notice] loaded user table (1 users)
24ROUT: Fri Sep 28 14:59:57 2007 aci.c:37 loading aci
25C2S : Fri Sep 28 14:59:57 2007 [notice] modules search path: /usr/local/lib/jabberd
26ROUT: Fri Sep 28 14:59:57 2007 [notice] loaded filters (0 rules)
27ROUT: Fri Sep 28 14:59:57 2007 aci.c:56 building list for 'all'
28C2S : Fri Sep 28 14:59:57 2007 [info] loading 'mysql' authreg module
29ROUT: Fri Sep 28 14:59:57 2007 [notice] [0.0.0.0, port=5347] listening for incoming connections
30ROUT: Fri Sep 28 14:59:57 2007 aci.c:78 added 'jabberd'
31C2S : Fri Sep 28 14:59:58 2007 [notice] initialized auth module 'mysql'
32ROUT: Fri Sep 28 14:59:57 2007 [notice] [127.0.0.1, port=57623] connect
33ROUT: Fri Sep 28 14:59:57 2007 filter.c:51 loading filter
34ROUT: Fri Sep 28 14:59:57 2007 [notice] [127.0.0.1, port=57624] connect
35ROUT: Fri Sep 28 14:59:57 2007 filter.c:96 building filter list
36ROUT: Fri Sep 28 14:59:58 2007 [notice] [127.0.0.1, port=57625] connect
37ROUT: sx (sasl_gsasl.c:677) initialising sasl plugin
38ROUT: sx (sasl_gsasl.c:705) sasl context initialised
39ROUT: sx (env.c:77) plugin initialised (index 0)
40ROUT: Fri Sep 28 14:59:57 2007 router.c:907 accept action on fd 7
41ROUT: sx (sx.c:55) allocated new sx for 7
42ROUT: sx (server.c:236) doing server init for sx 7
43ROUT: sx (server.c:251) waiting for stream header
44ROUT: sx (server.c:254) tag 7 event 0 data 0x0
45ROUT: Fri Sep 28 14:59:57 2007 router.c:516 want read
46ROUT: Fri Sep 28 14:59:57 2007 main.c:445 running time checks
47ROUT: Fri Sep 28 14:59:57 2007 main.c:450 next time check at 1191009657
48ROUT: Fri Sep 28 14:59:57 2007 router.c:907 accept action on fd 8
49ROUT: sx (sx.c:55) allocated new sx for 8
50ROUT: sx (server.c:236) doing server init for sx 8
51ROUT: sx (server.c:251) waiting for stream header
52ROUT: sx (server.c:254) tag 8 event 0 data 0x0
53ROUT: Fri Sep 28 14:59:57 2007 router.c:516 want read
54ROUT: Fri Sep 28 14:59:58 2007 router.c:907 accept action on fd 9
55SM  : Fri Sep 28 14:59:57 2007 [notice] id: localhost
56SM  : Fri Sep 28 14:59:57 2007 storage.c:119 driver not loaded, trying to init
57SM  : Fri Sep 28 14:59:57 2007 [info] process id is 27943, written to /usr/local/var/jabberd/pid/sm.pid
58SM  : Fri Sep 28 14:59:57 2007 storage.c:141 preloaded module 'mysql' (not initialized yet)
59SM  : Fri Sep 28 14:59:57 2007 [info] loading 'mysql' storage module
60SM  : Fri Sep 28 14:59:57 2007 storage.c:161 calling driver initializer
61SM  : Fri Sep 28 14:59:58 2007 [notice] initialised storage driver 'mysql'
62SM  : Fri Sep 28 14:59:58 2007 aci.c:37 loading aci
63SM  : Fri Sep 28 14:59:58 2007 [notice] modules search path: /usr/local/lib/jabberd
64SM  : Fri Sep 28 14:59:58 2007 aci.c:57 building list for 'all'
65SM  : Fri Sep 28 14:59:58 2007 [notice] module 'status' added to chain 'sess-start' (order 0 index 0 seq 0)
66SM  : Fri Sep 28 14:59:58 2007 aci.c:67 added 'admin@localhost'
67SM  : Fri Sep 28 14:59:58 2007 [notice] module 'status' added to chain 'sess-end' (order 0 index 0 seq 1)
68SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature iq
69ROUT: Fri Sep 28 14:59:58 2007 [notice] [127.0.0.1, port=57626] connect
70ROUT: sx (sx.c:55) allocated new sx for 9
71SM  : Fri Sep 28 14:59:58 2007 [notice] module 'iq-last' added to chain 'sess-end' (order 1 index 1 seq 0)
72SM  : Fri Sep 28 14:59:58 2007 mm.c:80 processing config for chain 'sess-start'
73ROUT: sx (server.c:236) doing server init for sx 9
74SM  : Fri Sep 28 14:59:58 2007 [notice] module 'validate' added to chain 'in-sess' (order 0 index 2 seq 0)
75SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'status' to chain 'sess-start' (not added yet)
76ROUT: sx (server.c:251) waiting for stream header
77SM  : Fri Sep 28 14:59:58 2007 [notice] module 'status' added to chain 'in-sess' (order 1 index 0 seq 2)
78SM  : Fri Sep 28 14:59:58 2007 mm.c:80 processing config for chain 'sess-end'
79ROUT: sx (server.c:254) tag 9 event 0 data 0x0
80SM  : Fri Sep 28 14:59:58 2007 [notice] module 'privacy' added to chain 'in-sess' (order 2 index 3 seq 0)
81SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'iq-last' to chain 'sess-end' (not added yet)
82ROUT: Fri Sep 28 14:59:58 2007 router.c:516 want read
83SM  : Fri Sep 28 14:59:58 2007 [notice] module 'roster' added to chain 'in-sess' (order 3 index 4 seq 0)
84SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature jabber:iq:last
85ROUT: Fri Sep 28 14:59:58 2007 router.c:907 accept action on fd 10
86SM  : Fri Sep 28 14:59:58 2007 [notice] module 'vacation' added to chain 'in-sess' (order 4 index 5 seq 0)
87SM  : Fri Sep 28 14:59:58 2007 mm.c:80 processing config for chain 'in-sess'
88SM  : Fri Sep 28 14:59:58 2007 [notice] module 'iq-vcard' added to chain 'in-sess' (order 5 index 6 seq 0)
89SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'validate' to chain 'in-sess' (not added yet)
90SM  : Fri Sep 28 14:59:58 2007 [notice] module 'iq-ping' added to chain 'in-sess' (order 6 index 7 seq 0)
91SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'privacy' to chain 'in-sess' (not added yet)
92SM  : Fri Sep 28 14:59:58 2007 [notice] module 'iq-private' added to chain 'in-sess' (order 7 index 8 seq 0)
93SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature jabber:iq:privacy
94SM  : Fri Sep 28 14:59:58 2007 [notice] module 'disco' added to chain 'in-sess' (order 8 index 9 seq 0)
95SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'roster' to chain 'in-sess' (not added yet)
96SM  : Fri Sep 28 14:59:58 2007 [notice] module 'amp' added to chain 'in-sess' (order 9 index 10 seq 0)
97SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature jabber:iq:roster
98SM  : Fri Sep 28 14:59:58 2007 [notice] module 'offline' added to chain 'in-sess' (order 10 index 11 seq 0)
99SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'vacation' to chain 'in-sess' (not added yet)
100SM  : Fri Sep 28 14:59:58 2007 [notice] module 'announce' added to chain 'in-sess' (order 11 index 12 seq 0)
101SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature http://jabber.org/protocol/vacation
102SM  : Fri Sep 28 14:59:58 2007 [notice] module 'presence' added to chain 'in-sess' (order 12 index 13 seq 0)
103SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'iq-vcard' to chain 'in-sess' (not added yet)
104SM  : Fri Sep 28 14:59:58 2007 [notice] module 'deliver' added to chain 'in-sess' (order 13 index 14 seq 0)
105SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature vcard-temp
106SM  : Fri Sep 28 14:59:58 2007 [notice] module 'session' added to chain 'in-router' (order 0 index 15 seq 0)
107SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'iq-ping' to chain 'in-sess' (not added yet)
108SM  : Fri Sep 28 14:59:58 2007 [notice] module 'validate' added to chain 'in-router' (order 1 index 2 seq 1)
109SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature urn:xmpp:ping
110SM  : Fri Sep 28 14:59:58 2007 [notice] module 'presence' added to chain 'in-router' (order 2 index 13 seq 1)
111SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'iq-private' to chain 'in-sess' (not added yet)
112SM  : Fri Sep 28 14:59:58 2007 [notice] module 'privacy' added to chain 'in-router' (order 3 index 3 seq 1)
113SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature jabber:iq:private
114SM  : Fri Sep 28 14:59:58 2007 [notice] module 'privacy' added to chain 'out-router' (order 0 index 3 seq 2)
115SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'disco' to chain 'in-sess' (not added yet)
116SM  : Fri Sep 28 14:59:58 2007 [notice] module 'iq-last' added to chain 'pkt-sm' (order 0 index 1 seq 1)
117SM  : Fri Sep 28 14:59:58 2007 mod_disco.c:632 disco module init
118SM  : Fri Sep 28 14:59:58 2007 [notice] module 'iq-ping' added to chain 'pkt-sm' (order 1 index 7 seq 1)
119SM  : Fri Sep 28 14:59:58 2007 mod_disco.c:657 agents compat enabled
120SM  : Fri Sep 28 14:59:58 2007 [notice] module 'iq-time' added to chain 'pkt-sm' (order 2 index 16 seq 0)
121SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature http://jabber.org/protocol/disco
122SM  : Fri Sep 28 14:59:58 2007 [notice] module 'iq-version' added to chain 'pkt-sm' (order 3 index 17 seq 0)
123SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature jabber:iq:agents
124SM  : Fri Sep 28 14:59:58 2007 mod_disco.c:94 unifying lists
125SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'amp' to chain 'in-sess' (not added yet)
126SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature http://jabber.org/protocol/amp
127SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'offline' to chain 'in-sess' (not added yet)
128SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature msgoffline
129SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'announce' to chain 'in-sess' (not added yet)
130SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'presence' to chain 'in-sess' (not added yet)
131SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature presence
132SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'deliver' to chain 'in-sess' (not added yet)
133SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature message
134SM  : Fri Sep 28 14:59:58 2007 mm.c:80 processing config for chain 'out-sess'
135SM  : Fri Sep 28 14:59:58 2007 mm.c:80 processing config for chain 'in-router'
136SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'session' to chain 'in-router' (not added yet)
137SM  : Fri Sep 28 14:59:58 2007 mm.c:80 processing config for chain 'out-router'
138SM  : Fri Sep 28 14:59:58 2007 mm.c:80 processing config for chain 'pkt-sm'
139SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'iq-time' to chain 'pkt-sm' (not added yet)
140SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature jabber:iq:time
141SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'iq-version' to chain 'pkt-sm' (not added yet)
142SM  : Fri Sep 28 14:59:58 2007 feature.c:39 registering feature jabber:iq:version
143SM  : Fri Sep 28 14:59:58 2007 mm.c:194 preloaded module 'help' to chain 'pkt-sm' (not added yet)
144S2S : sx (sasl_gsasl.c:705) sasl context initialised
145S2S : sx (env.c:77) plugin initialised (index 0)
146S2S : Fri Sep 28 14:59:57 2007 sx.c:47 initialising dialback sx plugin
147S2S : sx (env.c:77) plugin initialised (index 1)
148S2S : sx (sx.c:55) allocated new sx for 6
149S2S : sx (client.c:122) doing client init for sx 6
150S2S : sx (client.c:138) stream request: ns (null) to (null) from (null) version 1.0
151S2S : sx (client.c:168) prepared stream header: <?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>
152S2S : sx (client.c:175) tag 6 event 1 data 0x0
153S2S : Fri Sep 28 14:59:57 2007 router.c:39 want write
154S2S : Fri Sep 28 14:59:57 2007 main.c:572 running time checks
155S2S : Fri Sep 28 14:59:57 2007 main.c:577 next time check at 1191009657
156S2S : Fri Sep 28 15:00:57 2007 main.c:572 running time checks
157ROUT: sx (sx.c:55) allocated new sx for 10
158ROUT: sx (server.c:236) doing server init for sx 10
159ROUT: sx (server.c:251) waiting for stream header
160ROUT: sx (server.c:254) tag 10 event 0 data 0x0
161ROUT: Fri Sep 28 14:59:58 2007 router.c:516 want read
162ROUT: Fri Sep 28 15:00:58 2007 main.c:445 running time checks
163S2S : Fri Sep 28 15:00:57 2007 main.c:577 next time check at 1191009717
164S2S : Fri Sep 28 15:01:57 2007 main.c:572 running time checks
165ROUT: Fri Sep 28 15:00:58 2007 main.c:450 next time check at 1191009718
166ROUT: Fri Sep 28 15:01:58 2007 main.c:445 running time checks
167S2S : Fri Sep 28 15:01:57 2007 main.c:577 next time check at 1191009777
168S2S : Fri Sep 28 15:02:57 2007 main.c:572 running time checks
169ROUT: Fri Sep 28 15:01:58 2007 main.c:450 next time check at 1191009778
170ROUT: Fri Sep 28 15:02:58 2007 main.c:445 running time checks
171S2S : Fri Sep 28 15:02:57 2007 main.c:577 next time check at 1191009837
172S2S : Fri Sep 28 15:03:57 2007 main.c:572 running time checks
173ROUT: Fri Sep 28 15:02:58 2007 main.c:450 next time check at 1191009838
174ROUT: Fri Sep 28 15:03:58 2007 main.c:445 running time checks
175S2S : Fri Sep 28 15:03:57 2007 main.c:577 next time check at 1191009897
176S2S : Fri Sep 28 15:04:57 2007 main.c:572 running time checks
177ROUT: Fri Sep 28 15:03:58 2007 main.c:450 next time check at 1191009898
178ROUT: Fri Sep 28 15:04:58 2007 main.c:445 running time checks
179S2S : Fri Sep 28 15:04:57 2007 main.c:577 next time check at 1191009957
180S2S : Fri Sep 28 15:05:57 2007 main.c:572 running time checks
181ROUT: Fri Sep 28 15:04:58 2007 main.c:450 next time check at 1191009958
182ROUT: Fri Sep 28 15:05:58 2007 main.c:445 running time checks
183S2S : Fri Sep 28 15:05:57 2007 main.c:577 next time check at 1191010017
184S2S : Fri Sep 28 15:06:57 2007 main.c:572 running time checks
185ROUT: Fri Sep 28 15:05:58 2007 main.c:450 next time check at 1191010018
186ROUT: Fri Sep 28 15:06:58 2007 main.c:445 running time checks
187S2S : Fri Sep 28 15:06:57 2007 main.c:577 next time check at 1191010077
188S2S : Fri Sep 28 15:07:57 2007 main.c:572 running time checks
189ROUT: Fri Sep 28 15:06:58 2007 main.c:450 next time check at 1191010078
190ROUT: Fri Sep 28 15:07:58 2007 main.c:445 running time checks
191S2S : Fri Sep 28 15:07:57 2007 main.c:577 next time check at 1191010137
192S2S : Fri Sep 28 15:08:57 2007 main.c:572 running time checks
193ROUT: Fri Sep 28 15:07:58 2007 main.c:450 next time check at 1191010138
194ROUT: Fri Sep 28 15:08:58 2007 main.c:445 running time checks
195S2S : Fri Sep 28 15:08:57 2007 main.c:577 next time check at 1191010197
196S2S : Fri Sep 28 15:09:57 2007 main.c:572 running time checks
197ROUT: Fri Sep 28 15:08:58 2007 main.c:450 next time check at 1191010198
198ROUT: Fri Sep 28 15:09:58 2007 main.c:445 running time checks
199S2S : Fri Sep 28 15:09:57 2007 main.c:577 next time check at 1191010257
200S2S : Fri Sep 28 15:10:57 2007 main.c:572 running time checks
201ROUT: Fri Sep 28 15:09:58 2007 main.c:450 next time check at 1191010258
202ROUT: Fri Sep 28 15:10:58 2007 main.c:445 running time checks
203ROUT: Fri Sep 28 15:11:55 2007 [notice] [127.0.0.1, port=57665] connect
204ROUT: Fri Sep 28 15:10:58 2007 main.c:450 next time check at 1191010318
205ROUT: Fri Sep 28 15:11:55 2007 router.c:907 accept action on fd 11
206ROUT: Fri Sep 28 15:11:56 2007 [notice] [127.0.0.1, port=57665] disconnect
207ROUT: sx (sx.c:55) allocated new sx for 11
208ROUT: Fri Sep 28 15:11:56 2007 [notice] [127.0.0.1, port=57666] connect
209ROUT: sx (server.c:236) doing server init for sx 11
210ROUT: sx (server.c:251) waiting for stream header
211ROUT: sx (server.c:254) tag 11 event 0 data 0x0
212ROUT: Fri Sep 28 15:11:55 2007 router.c:516 want read
213ROUT: Fri Sep 28 15:11:56 2007 router.c:858 read action on fd 11
214S2S : Fri Sep 28 15:10:57 2007 main.c:577 next time check at 1191010317
215S2S : Fri Sep 28 15:11:57 2007 main.c:572 running time checks
216ROUT: Fri Sep 28 15:11:56 2007 [notice] [127.0.0.1, port=57666] disconnect
217ROUT: sx (io.c:473) 11 state change from 0 to 6
218ROUT: Fri Sep 28 15:11:57 2007 [notice] [127.0.0.1, port=57667] connect
219ROUT: sx (io.c:474) tag 11 event 7 data 0x0
220ROUT: Fri Sep 28 15:11:56 2007 router.c:880 close action on fd 11
221ROUT: sx (sx.c:72) freeing sx for 11
222ROUT: Fri Sep 28 15:11:56 2007 router.c:907 accept action on fd 11
223ROUT: sx (sx.c:55) allocated new sx for 11
224ROUT: sx (server.c:236) doing server init for sx 11
225ROUT: Fri Sep 28 15:11:57 2007 [notice] [127.0.0.1, port=57667] disconnect
226ROUT: sx (server.c:251) waiting for stream header
227ROUT: Fri Sep 28 15:11:57 2007 [notice] [127.0.0.1, port=57668] connect
228ROUT: sx (server.c:254) tag 11 event 0 data 0x0
229ROUT: Fri Sep 28 15:11:56 2007 router.c:516 want read
230ROUT: Fri Sep 28 15:11:56 2007 router.c:858 read action on fd 1