[OPEN-ILS-DEV] trouble starting OpenSRF
Chris Giordano
giordano at more.net
Thu Sep 8 11:50:01 EDT 2011
Hello everyone,
I'm attempting to install Evergreen for the first time and I'm having
trouble connecting the router to Jabber when I start OpenSRF. This is
an installation for testing so everything is getting installed on a
single server running on Ubuntu 11. Everything has been checked and
double checked against your installation and troubleshooting documents;
I've verified the user accounts I'm using are registered with Jabber and
I've checked file permissions and deleted PID files. Everything has
been restarted.
The issue seems to be related to Jabber itself. When I run strace
against Jabber while trying to connect, the return error message is
(Resource temporarily unavailable). I've included some output from my
commands and log output below.
Any advise would be appreciated.
Thanks
Chris Giordano
- When I try to start OpenSRF here's the output that I get. The router
actually doesn't start and I've included it's log file below. I've
also include the tail portion of the ejabberd.log file below.
####################
/opt/openils/bin$ ./osrf_ctl.sh -c /opt/openils/conf/opensrf_core.xml -l
-a start_all
Starting OpenSRF Router
Starting OpenSRF Perl
Use of uninitialized value $@ in concatenation (.) or string at
/usr/local/share/perl/5.10.1/OpenSRF/Transport/SlimJabber/Client.pm line
147.
Exception: OpenSRF::EX::Jabber 2011-09-02T11:01:18
OpenSRF::Transport::SlimJabber::Client
/usr/local/share/perl/5.10.1/OpenSRF/Transport/SlimJabber/Client.pm:147
Jabber Exception: Could not authenticate with Jabber server:
I've verified Jabber's running (netstat -anp) and I've successfully used
telnet to connect to Jabber on port 5222.
# netstat -anp |grep 5222
tcp 0 0 0.0.0.0:5222 0.0.0.0:*
LISTEN 6333/beam
# cat var/log/router.log
router 2011-09-02 11:05:49 [INFO:11644:osrf_router_main.c:205:] Router
connecting as: server: private.localhost port: 5222 user: router
resource: router
router 2011-09-02 11:05:49 [INFO:11644:osrf_router_main.c:228:] Router
adding trusted server: private.localhost
router 2011-09-02 11:05:49 [INFO:11644:osrf_router_main.c:240:] Router
adding trusted client: private.localhost
router 2011-09-02 11:05:49 [INFO:11643:osrf_router_main.c:205:] Router
connecting as: server: public.localhost port: 5222 user: router
resource: router
router 2011-09-02 11:05:49 [INFO:11643:osrf_router_main.c:228:] Router
adding trusted server: private.localhost
router 2011-09-02 11:05:49 [INFO:11643:osrf_router_main.c:235:] Router
adding trusted client: private.localhost
router 2011-09-02 11:05:49 [INFO:11643:osrf_router_main.c:235:] Router
adding trusted client: public.localhost
router 2011-09-02 11:05:49 [INT :11644:socket_bundle.c:96:] Adding
socket node with fd 3
router 2011-09-02 11:05:49 [INT :11644:socket_bundle.c:709:] 1 active
sockets after select()
router 2011-09-02 11:05:49 [INT :11644:socket_bundle.c:886:] 11644 :
Received data at 1314979549.031739
router 2011-09-02 11:05:49 [INT :11644:socket_bundle.c:891:] Socket 3
Read 161 bytes and data: <?xml version='1.0'?><stream:stream
xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams'
id='4019828137' from='private.localhost' xml:lang='en'>
router 2011-09-02 11:05:49 [DEBG:11644:socket_bundle.c:482:] removing
socket 3
router 2011-09-02 11:05:49 [WARN:11644:socket_bundle.c:560:]
_socket_send(): Error sending data with return -1
router 2011-09-02 11:05:49 [WARN:11644:socket_bundle.c:561:] Last Sys
Error: Bad file descriptor
router 2011-09-02 11:05:49 [WARN:11644:transport_session.c:506:] error
sending
router 2011-09-02 11:05:49 [INT :11644:socket_bundle.c:623:] Closing
socket 3
router 2011-09-02 11:05:49 [DEBG:11644:socket_bundle.c:482:] removing
socket 3
router 2011-09-02 11:05:49 [ERR :11644:osrf_router_main.c:261:] Unable
to connect router to jabber server private.localhost... exiting
router 2011-09-02 11:05:49 [INT :11643:socket_bundle.c:96:] Adding
socket node with fd 3
router 2011-09-02 11:05:49 [INT :11643:socket_bundle.c:709:] 1 active
sockets after select()
router 2011-09-02 11:05:49 [INT :11643:socket_bundle.c:886:] 11643 :
Received data at 1314979549.035704
router 2011-09-02 11:05:49 [INT :11643:socket_bundle.c:891:] Socket 3
Read 159 bytes and data: <?xml version='1.0'?><stream:stream
xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams'
id='920764740' from='public.localhost' xml:lang='en'>
router 2011-09-02 11:05:49 [DEBG:11643:socket_bundle.c:482:] removing
socket 3
router 2011-09-02 11:05:49 [WARN:11643:socket_bundle.c:560:]
_socket_send(): Error sending data with return -1
router 2011-09-02 11:05:49 [WARN:11643:socket_bundle.c:561:] Last Sys
Error: Bad file descriptor
router 2011-09-02 11:05:49 [WARN:11643:transport_session.c:506:] error
sending
router 2011-09-02 11:05:49 [INT :11643:socket_bundle.c:623:] Closing
socket 3
router 2011-09-02 11:05:49 [DEBG:11643:socket_bundle.c:482:] removing
socket 3
router 2011-09-02 11:05:49 [ERR :11643:osrf_router_main.c:261:] Unable
to connect router to jabber server public.localhost... exiting
# tail /var/log/ejabberd/ejabberd.log
=INFO REPORT==== 2011-09-02 11:05:51 ===
I(<0.533.0>:ejabberd_listener:232) : (#Port<0.1994>) Accepted connection
{{127,0,0,1},58108} -> {{127,0,1,3},5222}
=ERROR REPORT==== 2011-09-02 11:05:51 ===
** Generic server <0.1093.0> terminating
** Last message in was {'$gen_cast',{change_shaper,normal}}
** When Server state == {state,#Port<0.1994>,gen_tcp,none,<0.1094.0>,
infinity,
{xml_stream_state,<0.1094.0>,#Port<0.1995>,
[{xmlelement,"stream:stream",
[{"to","private.localhost"},
{"xmlns","jabber:client"},
{"xmlns:stream",
"http://etherx.jabber.org/streams"}],
[]}],
0,infinity},
infinity}
** Reason for termination ==
** {function_clause,[{shaper,new1,[{500000,1000}]},
{ejabberd_receiver,handle_cast,2},
{gen_server,handle_msg,5},
{proc_lib,init_p_do_apply,3}]}
strace snippit against Jabber while trying to the router:
################
write(15, "\n=INFO REPORT==== 2011-09-07 16:"..., 157) = 157
writev(1, [{"", 0}, {"\n=INFO REPORT==== 7-Sep-2011::16"..., 158}], 2) = 158
poll([{fd=3, events=POLLIN|POLLRDNORM}, {fd=5,
events=POLLIN|POLLRDNORM}, {fd=8, events=POLLIN|POLLRDNORM}, {fd=7,
events=POLLIN|POLLRDNORM}, {fd=14, events=POLLIN|POLLRDNORM}, {fd=19,
events=POLLIN|POLLRDNORM}, {fd=17, events=POLLIN|POLLRDNORM}, {fd=20,
events=POLLIN|POLLRDNORM}], 8, 0) = 0 (Timeout)
getpeername(21, {sa_family=AF_INET, sin_port=htons(47994),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
getpeername(21, {sa_family=AF_INET, sin_port=htons(47994),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
accept(16, 0x7fff48197cf0, [28]) = -1 EAGAIN (Resource
temporarily unavailable)
poll([{fd=3, events=POLLIN|POLLRDNORM}, {fd=5,
events=POLLIN|POLLRDNORM}, {fd=8, events=POLLIN|POLLRDNORM}, {fd=7,
events=POLLIN|POLLRDNORM}, {fd=14, events=POLLIN|POLLRDNORM}, {fd=19,
events=POLLIN|POLLRDNORM}, {fd=17, events=POLLIN|POLLRDNORM}, {fd=20,
events=POLLIN|POLLRDNORM}, {fd=21, events=POLLIN|POLLRDNORM}, {fd=16,
events=POLLIN|POLLRDNORM}], 10, 6489) = 1 ([{fd=20,
revents=POLLIN|POLLRDNORM}])
recvfrom(20, "<stream:stream to='private.local"..., 1460, 0, NULL, NULL)
= 108
getpeername(20, {sa_family=AF_INET, sin_port=htons(56426),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
writev(20, [{NULL, 0}, {"<?xml version='1.0'?><stream:str"..., 160}], 2)
= 160
close(20) = 0
write(15, "\n=ERROR REPORT==== 2011-09-07 16"..., 1014) = 1014
More information about the Open-ils-dev
mailing list