[OPEN-ILS-DEV] problems running opensrf-c

Tue May 23 09:44:02 EDT 2006

I am having trouble with opensrf-c segfaulting after about a minute.  
First I started the system with the opensrf_all start command which 
gives this output.

 >>>>>
debiantest1:/openils/bin$ ./opensrf_all start
Starting Chop Chop, Jabber (jserver-c)...
Attempting to launch ChopChop with:
domain: 127.0.0.1
port: 5222
listen address: 127.0.0.1
log level: 3
log file: syslog
Chop Chop started OK
Starting router...
Router started OK
Starting OpenSRF...
Use of uninitialized value in string eq at 
/openils/lib/perl5/OpenSRF/System.pm line 155.

 --- PS ---
24473 pts/1    S      0:01 OpenSRF System
24469 ?        Ss     0:00 OpenSRF Router
 --- PS ---

OpenSRF System is running

Starting OpenSRF-C...
Loading OpenSRF host debiantest.larl.org with bootstrap config 
/openils/conf//opensrf_core.xml and config context opensrf
./opensrf_all: line 89: 24490 Segmentation fault      
"$BINDIR/opensrf-c" $(hostname -f) "$ETCDIR//opensrf_core.xml" "opensrf"
OpenSRF-C started OK
OpenSRF started OK
 >>>>>

Then I tried running just opensrf-c
 >>>>>
debiantest1:/openils/bin$ ./opensrf-c 127.0.0.1 ../conf/opensrf_core.xml 
"opensrf"
Loading OpenSRF host 127.0.0.1 with bootstrap config 
../conf/opensrf_core.xml and config context opensrf
Segmentation fault
 >>>>>

These are the log files from running just opensrf-c.

 >>>>> From osrfsys.log
opensrf 2006-05-23 08:32:05 [INFO:24506:osrf_system.c:190] Bootstrapping 
system with domain 127.0.0.1, port 5222, and unixpath (null)
opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:46] Adding 
socket node with fd 3
opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:472] 1 active 
sockets after select()
opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:641] 24506 : 
Received data at 1148391125.265216

opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:644] Socket 3 
Read 183 bytes and data: <?xml version='1.0'?><stream:stream 
xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' 
from='127.0.0.1' version='1.0' 
id='ae5ffe593536e646726d368da92e82b891ddfe32'>
opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:472] 1 active 
sockets after select()
opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:641] 24506 : 
Received data at 1148391125.272869

opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:644] Socket 3 
Read 57 bytes and data: <iq xmlns='jabber:client' id='0123456789' 
type='result'/>
opensrf 2006-05-23 08:32:05 [DEBG:24506:osrf_app_session.c:230] 
opensrf.settings session is stateless
opensrf 2006-05-23 08:32:05 [DEBG:24506:osrf_app_session.c:242] Building 
a new client session with id [opensrf.settings] 
[1148391125.275433.114839112524506]
opensrf 2006-05-23 08:32:05 [DEBG:24506:osrf_app_session.c:554] 
AppSession in queue_wait with timeout 0
opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:472] 0 active 
sockets after select()
opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:641] 24506 : 
Received data at 1148391125.278778

opensrf 2006-05-23 08:32:05 [DEBG:24506:osrf_app_session.c:377] App 
Session [opensrf.settings] [1148391125.275433.114839112524506] resetting 
remote id to router at 127.0.0.1/opensrf.settings
opensrf 2006-05-23 08:32:05 [DEBG:24506:osrf_app_session.c:521] Session 
[opensrf.settings] [1148391125.275433.114839112524506]  sending to 
router at 127.0.0.1/opensrf.settings
Data: [/*--S 
osrfMessage--*/{"threadTrace":"1","type":"REQUEST","payload":/*--S 
osrfMethod--*/{"method":"opensrf.settings.host_config.get","params":["127.0.0.1"]}/*--E 
osrfMethod--*/}/*--E osrfMessage--*/]
opensrf 2006-05-23 08:32:05 [DEBG:24506:osrf_app_session.c:347] Pushing 
[1] onto requeust queue for session [opensrf.settings] 
[1148391125.275433.114839112524506]
opensrf 2006-05-23 08:32:05 [DEBG:24506:osrf_app_session.c:119] In 
app_request receive with remaining time [60]
opensrf 2006-05-23 08:32:05 [DEBG:24506:osrf_app_session.c:554] 
AppSession in queue_wait with timeout 0
opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:472] 0 active 
sockets after select()
opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:641] 24506 : 
Received data at 1148391125.292866

opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:644] Socket 3 
Read 270 bytes and data: <message xmlns='jabber:client' type='error' 
from='router at 127.0.0.1/opensrf.settings' 
to='client at 127.0.0.1/settings_grabber__24506'><error type='cancel' 
code='404'><item-not-found 
xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></error><body>NOT ADDING 
BODY</body></message>
opensrf 2006-05-23 08:32:05 [INFO:24506:transport_session.c:401] 
Received <error> message with type cancel and code 404
opensrf 2006-05-23 08:32:05 [DEBG:24506:osrf_stack.c:15] Received 
message from transport code from router at 127.0.0.1/opensrf.settings
opensrf 2006-05-23 08:32:05 [DEBG:24506:osrf_stack.c:32] Transport 
handler received new message
from router at 127.0.0.1/opensrf.settings to 
client at 127.0.0.1/settings_grabber__24506 with body

NOT ADDING BODY

opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:472] 0 active 
sockets after select()
opensrf 2006-05-23 08:32:05 [INT :24506:socket_bundle.c:641] 24506 : 
Received data at 1148391125.296864

opensrf 2006-05-23 08:32:05 [DEBG:24506:osrf_app_session.c:554] 
AppSession in queue_wait with timeout 60
 >>>>>

 >>>>> From syslog
May 23 08:32:05 localhost chochop: [INFO:24466:osrf_chat.c:719] 
client at 127.0.0.1/settings_grabber__24506 successfully logged in
May 23 08:32:05 localhost chochop: [INFO:24466:osrf_chat.c:278] Sending 
message on local connection from: 
client at 127.0.0.1/settings_grabber__24506 to: 
router at 127.0.0.1/opensrf.settings
May 23 08:32:05 localhost chochop: [INFO:24466:osrf_chat.c:304] We have 
no connection for router at 127.0.0.1/opensrf.settings
 >>>>>>

 >>>>> When I do a strace on opensrf-c, this is what it looks like when 
it is pausing, before it crashes.  It looks like it is waiting for a 
message.
open("/openils/var/log/osrfsys.log", O_WRONLY|O_APPEND|O_CREAT, 0666) = 4
fstat64(4, {st_mode=S_IFREG|0644, st_size=60039, ...}) = 0
mmap2(NULL, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 
0) = 0x4030f000
fstat64(4, {st_mode=S_IFREG|0644, st_size=60039, ...}) = 0
_llseek(4, 60039, [60039], SEEK_SET)    = 0
write(4, "opensrf 2006-05-23 08:38:20 [DEB"..., 105) = 105
close(4)                                = 0
munmap(0x4030f000, 131072)              = 0
time(NULL)                              = 1148391500
select(4, [3], NULL, NULL, {60, 0}     <<<<<<< Waiting for select to 
return, for 60 seconds.
 >>>>>>>

 >>>>>> opensrf section from opensrf_core.xml
        <opensrf> <!-- bootstrap config for the C apps -->
      <router_name>router</router_name>
      <routers>
         <router>127.0.0.1</router>
      </routers>
      <domains>
         <domain>127.0.0.1</domain>
      </domains>
      <username>client</username>
      <passwd>mypass</passwd>
      <port>5222</port>
      <logfile>/openils/var/log/osrfsys.log</logfile>
      <loglevel>5</loglevel>
   </opensrf>
 >>>>>>

Let me know what other info might be usefull.