Unable to start SEMS on dedicated server


#1

After succesfully testing the yeti softswitch on a single machine I decided to setup a dedicated management machine and separated SEMS nodes for failover.

Unfortunately I am unable to start the SEMS node on a dedicated machine.
It successfully starts, connects with the management server and fetches the config, connects with the database on the management server and then crashes.

Does anybody see why this is crashing?

The node is setup with it’s external IP as opposed to 127.0.0.1. The management server can reach the node and vice versa.

 [1267/1267] [yeti:Sensors.cpp:149] INFO: sensors are loaded successfully. apply changes
 [1267/1267] [yeti:SqlRouter.cpp:91] WARNING: Master SQLThread started
 [1267/1267] [yeti:cdr/CdrWriter.cpp:115] DEBUG: CdrWriter::start: Starting 4 async DB threads
 [1267/1309] [core/AmThread.cpp:85] INFO: Thread 139835792099072 is starting.
 [1267/1309] [yeti:db/PgConnectionPool.cpp:224] DEBUG: PgCP  thread starting
 [1267/1309] [yeti:db/PgConnectionPool.cpp:250] DEBUG: PgCP: : start connection
 [1267/1311] [core/AmThread.cpp:85] INFO: Thread 139835789993728 is starting.
 [1267/1311] [yeti:cdr/CdrWriter.cpp:302] INFO: Starting CdrWriter thread
 [1267/1310] [core/AmThread.cpp:85] INFO: Thread 139835791046400 is starting.
 [1267/1310] [yeti:cdr/CdrWriter.cpp:302] INFO: Starting CdrWriter thread
 [1267/1313] [core/AmThread.cpp:85] INFO: Thread 139835787888384 is starting.
 [1267/1313] [yeti:cdr/CdrWriter.cpp:302] INFO: Starting CdrWriter thread
 [1267/1312] [core/AmThread.cpp:85] INFO: Thread 139835788941056 is starting.
 [1267/1312] [yeti:cdr/CdrWriter.cpp:302] INFO: Starting CdrWriter thread
 [1267/1310] [yeti:cdr/CdrWriter.cpp:574] INFO: CdrWriter: SQL connected. Backend pid: 13553.
 [1267/1312] [yeti:cdr/CdrWriter.cpp:574] INFO: CdrWriter: SQL connected. Backend pid: 13554.
 [1267/1267] [yeti:SBC.cpp:177] DEBUG: OPTIONS messages handled by the core: yes
 [1267/1267] [core/AmPlugIn.cpp:788] DEBUG: Application 'yeti' registered.
 [1267/1267] [core/AmPlugIn.cpp:855] DEBUG: DI Interface 'yeti' registered.
 [1267/1267] [core/AmEventQueueProcessor.cpp:83] DEBUG: starting 1 session processor threads
 [1267/1267] [core/AmEventQueueProcessor.cpp:90] DEBUG: now 1 session processor threads running
 [1267/1314] [core/AmThread.cpp:85] INFO: Thread 139835786835712 is starting.
 [1267/1309] [yeti:db/PgConnectionPool.cpp:264] DEBUG: PgCP: : SQL connected. Backend pid: 13550.
 [1267/1311] [yeti:cdr/CdrWriter.cpp:574] INFO: CdrWriter: SQL connected. Backend pid: 13551.
 [1267/1313] [yeti:cdr/CdrWriter.cpp:574] INFO: CdrWriter: SQL connected. Backend pid: 13555.
 [1267/1315] [core/AmThread.cpp:85] INFO: Thread 139835785783040 is starting.
 [1267/1267] [core/AmConfigReader.cpp:82] WARNING: could not open configuration file '/etc/sems/etc/uac_auth.conf': No such file or directory
 [1267/1267] [core/plug-in/uac_auth/UACAuth.cpp:120] WARNING: Could not open '/etc/sems/etc/uac_auth.conf', assuming that default values are fine
 [1267/1267] [core/plug-in/uac_auth/UACAuth.cpp:666] DEBUG: Server Nonce secret set
 [1267/1267] [core/AmConfigReader.cpp:82] WARNING: could not open configuration file '/etc/sems/etc/uac_auth.conf': No such file or directory
 [1267/1267] [core/plug-in/uac_auth/UACAuth.cpp:120] WARNING: Could not open '/etc/sems/etc/uac_auth.conf', assuming that default values are fine
 [1267/1267] [core/plug-in/uac_auth/UACAuth.cpp:666] DEBUG: Server Nonce secret set
 [1267/1267] [apps/di_log/DILog.cpp:38] DEBUG: DILog logging ring-buffer loaded.
 [1267/1267] [apps/di_log/DILog.cpp:38] DEBUG: DILog logging ring-buffer loaded.
 [1267/1267] [core/AmConfigReader.cpp:82] WARNING: could not open configuration file '/etc/sems/etc/registrar_client.conf': No such file or directory
 [1267/1267] [apps/registrar_client/SIPRegistrarClient.cpp:267] DEBUG: missed or wrong configuration file. shaper will be disabled by default
 [1267/1316] [core/AmThread.cpp:85] INFO: Thread 139835784730368 is starting.
 [1267/1316] [apps/registrar_client/SIPRegistrarClient.cpp:137] DEBUG: SIPRegistrarClient starting...
 [1267/1267] [apps/jsonrpc/JsonRPC.cpp:74] DEBUG: using server listen address 10.216.0.4
 [1267/1267] [apps/jsonrpc/JsonRPC.cpp:75] DEBUG: using server port 7080
 [1267/1267] [apps/jsonrpc/JsonRPC.cpp:76] DEBUG: using 1 server threads
 [1267/1267] [apps/jsonrpc/JsonRPC.cpp:78] DEBUG: starting server loop thread
 [1267/1267] [core/AmSessionContainer.cpp:124] INFO: monitoring module not loaded, monitoring disabled
 [1267/1267] [core/SipCtrlInterface.cpp:400] DEBUG: Starting SIP control interface
 [1267/1317] [core/AmThread.cpp:85] INFO: Thread 139835783677696 is starting.
 [1267/1317] [apps/jsonrpc/RpcServerLoop.cpp:356] DEBUG: adding 0 more server threads
 [1267/1317] [apps/jsonrpc/RpcServerThread.cpp:197] DEBUG: adding 0 RPC server threads
 [1267/1317] [apps/jsonrpc/RpcServerLoop.cpp:361] INFO: running server loop; listening on 10.216.0.4:7080
 [1267/1317] [apps/jsonrpc/RpcServerLoop.cpp:406] INFO: running event loop
 [1267/1321] [core/AmThread.cpp:85] INFO: Thread 139835779467008 is starting.
 [1267/1321] [core/sip/udp_trsp.cpp:338] INFO: Started SIP server UDP transport on 10.216.0.4:5060
 [1267/1319] [core/AmThread.cpp:85] INFO: Thread 139835781572352 is starting.
 [1267/1319] [core/sip/udp_trsp.cpp:338] INFO: Started SIP server UDP transport on 10.216.0.4:5060
 [1267/1318] [core/AmThread.cpp:85] INFO: Thread 139835782625024 is starting.
 [1267/1320] [core/AmThread.cpp:85] INFO: Thread 139835780519680 is starting.
 [1267/1320] [core/sip/udp_trsp.cpp:338] INFO: Started SIP server UDP transport on 10.216.0.4:5060
 [1267/1322] [core/AmThread.cpp:85] INFO: Thread 139835778414336 is starting.
 [1267/1267] [core/SipCtrlInterface.cpp:419] DEBUG: SIP control interface ending
 [1267/1267] [core/sems.cpp:677] INFO: Disposing session container
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread session-cleaner 139836405630720 (139836405630720)calling on_stop, give it a chance to clean up.
 [1267/1267] [core/AmSessionContainer.cpp:163] INFO: unclean shutdown requested - not broadcasting shutdown
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread session-cleaner 139836405630720 (139836405630720) finished detach.
 [1267/1323] [core/AmThread.cpp:85] INFO: Thread 139835777361664 is starting.
 [1267/1324] [core/AmThread.cpp:85] INFO: Thread 139835776308992 is starting.
 [1267/1323] [core/sip/tcp_trsp.cpp:947] INFO: Started SIP server TCP transport on 10.216.0.4:5060
 [1267/1269] [core/AmSessionContainer.cpp:148] DEBUG: Session cleaner terminating
 [1267/1269] [core/AmThread.cpp:92] INFO: Thread session-cleaner 139836405630720 is ending.
 [1267/1327] [core/AmThread.cpp:85] INFO: Thread 139835773150976 is starting.
 [1267/1325] [core/AmThread.cpp:85] INFO: Thread 139835775256320 is starting.
 [1267/1322] [core/sip/udp_trsp.cpp:338] INFO: Started SIP server UDP transport on 10.216.0.4:5060
 [1267/1326] [core/AmThread.cpp:85] INFO: Thread 139835774203648 is starting.
 [1267/1267] [core/sems.cpp:680] DEBUG: ** Transaction table dump: **
 [1267/1267] [core/sems.cpp:682] DEBUG: *****************************
 [1267/1267] [core/sems.cpp:689] INFO: Disposing RTP receiver
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread rtp-rx 139836380366592 (139836380366592)calling on_stop, give it a chance to clean up.
 [1267/1267] [core/AmRtpReceiver.cpp:109] INFO: requesting RTP receiver to stop.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread rtp-rx 139836380366592 (139836380366592) finished detach.
 [1267/1293] [core/AmThread.cpp:92] INFO: Thread rtp-rx 139836380366592 is ending.
 [1267/1309] [yeti:db/PgConnectionPool.cpp:264] DEBUG: PgCP: : SQL connected. Backend pid: 13557.
 [1267/1267] [core/AmRtpReceiver.cpp:104] INFO: RTP receiver has been recycled.
 [1267/1267] [core/sems.cpp:692] INFO: Disposing media processor
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread media-proc 139836382471936 (139836382471936)calling on_stop, give it a chance to clean up.
 [1267/1267] [core/AmMediaProcessor.cpp:261] INFO: requesting media processor to stop.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread media-proc 139836382471936 (139836382471936) finished detach.
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread media-proc 139836381419264 (139836381419264)calling on_stop, give it a chance to clean up.
 [1267/1267] [core/AmMediaProcessor.cpp:261] INFO: requesting media processor to stop.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread media-proc 139836381419264 (139836381419264) finished detach.
 [1267/1292] [core/AmThread.cpp:92] INFO: Thread media-proc 139836381419264 is ending.
 [1267/1291] [core/AmThread.cpp:92] INFO: Thread media-proc 139836382471936 is ending.
 [1267/1267] [core/AmMediaProcessor.cpp:60] INFO: Media processor has been recycled.
 [1267/1267] [core/sems.cpp:695] INFO: Disposing event dispatcher
 [1267/1267] [core/AmEventDispatcher.cpp:238] DEBUG: *** dumping Event dispatcher buckets ***
 [1267/1267] [core/AmEventDispatcher.cpp:242] DEBUG: queues[38].size() = 1
 [1267/1267] [core/AmEventDispatcher.cpp:245] DEBUG:    sctp_bus -> 0x557c1d6e3128
 [1267/1267] [core/AmEventDispatcher.cpp:242] DEBUG: queues[281].size() = 1
 [1267/1267] [core/AmEventDispatcher.cpp:245] DEBUG:    AmAudioFileRecorder -> 0x557c1d6c9a28
 [1267/1267] [core/AmEventDispatcher.cpp:242] DEBUG: queues[533].size() = 1
 [1267/1267] [core/AmEventDispatcher.cpp:245] DEBUG:    yeti -> 0x557c1d718f20
 [1267/1267] [core/AmEventDispatcher.cpp:242] DEBUG: queues[630].size() = 1
 [1267/1267] [core/AmEventDispatcher.cpp:245] DEBUG:    reg_client -> 0x557c1d716ac0
 [1267/1267] [core/AmEventDispatcher.cpp:242] DEBUG: queues[987].size() = 1
 [1267/1267] [core/AmEventDispatcher.cpp:245] DEBUG:    jsonrpc -> 0x557c1d7b8910
 [1267/1267] [core/AmEventDispatcher.cpp:256] DEBUG: *** End of Event dispatcher bucket dump ***
 [1267/1267] [core/sems.cpp:699] INFO: Disposing plug-ins
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: session_timer
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: uac_auth
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: sctp_bus
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: yeti
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: core
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: di_log
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: jsonrpc
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: registrar_client
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: sctp_bus
 [1267/1267] [apps/sctp_bus/SctpConnection.cpp:23] DEBUG: ~SctpConnection()
 [1267/1267] [apps/sctp_bus/SctpConnection.cpp:81] DEBUG: close connection with id 0, socket: 43
 [1267/1267] [apps/sctp_bus/SctpConnection.cpp:23] DEBUG: ~SctpConnection()
 [1267/1267] [apps/sctp_bus/SctpConnection.cpp:81] DEBUG: close connection with id 0, socket: 42
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: uac_auth
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: yeti
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread sip-reg-cache 139835785783040 (139835785783040)calling on_stop, give it a chance to clean up.
 [1267/1315] [core/AmThread.cpp:92] INFO: Thread sip-reg-cache 139835785783040 is ending.
 [1267/1267] [core/AmThread.cpp:151] DEBUG: pthread_detach failed with code ESRCH: thread could not be found.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread sip-reg-cache 139835785783040 (139835785783040) finished detach.
 [1267/1267] [yeti:RegisterCache.cpp:202] DEBUG: ##### REG CACHE DUMP #####
 [1267/1267] [yeti:RegisterCache.cpp:204] DEBUG: ##### ID IDX DUMP #####
 [1267/1267] [yeti:RegisterCache.cpp:206] DEBUG: ##### CONTACT IDX DUMP #####
 [1267/1267] [yeti:RegisterCache.cpp:208] DEBUG: ##### DUMP END #####
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread event-queue 139835786835712 (139835786835712)calling on_stop, give it a chance to clean up.
 [1267/1267] [core/AmEventQueueProcessor.cpp:145] INFO: requesting worker to stop.
 [1267/1314] [core/AmEventQueueProcessor.cpp:120] DEBUG: running processing loop
 [1267/1314] [core/AmThread.cpp:92] INFO: Thread event-queue 139835786835712 is ending.
 [1267/1267] [core/AmThread.cpp:151] DEBUG: pthread_detach failed with code ESRCH: thread could not be found.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread event-queue 139835786835712 (139835786835712) finished detach.
 [1267/1267] [yeti:db/PgConnectionPool.cpp:38] DEBUG: PgCP thread stopping
 [1267/1267] [yeti:SqlRouter.cpp:75] INFO: SqlRouter instance[0x557c1d714080] destroyed
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: di_log
 [1267/1267] [core/AmPlugIn.cpp:117] DEBUG: decreasing reference to plug-in factory: syslog
 [1267/1267] [core/SipCtrlInterface.cpp:430] DEBUG: Stopping SIP control interface threads
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread sip-udp-rx 139835781572352 (139835781572352)calling on_stop, give it a chance to clean up.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread sip-udp-rx 139835781572352 (139835781572352) finished detach.
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread sip-udp-rx 139835780519680 (139835780519680)calling on_stop, give it a chance to clean up.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread sip-udp-rx 139835780519680 (139835780519680) finished detach.
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread sip-udp-rx 139835779467008 (139835779467008)calling on_stop, give it a chance to clean up.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread sip-udp-rx 139835779467008 (139835779467008) finished detach.
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread sip-udp-rx 139835778414336 (139835778414336)calling on_stop, give it a chance to clean up.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread sip-udp-rx 139835778414336 (139835778414336) finished detach.
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread sip-tcp-trsp 139835777361664 (139835777361664)calling on_stop, give it a chance to clean up.
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread sip-tcp-worker 139835776308992 (139835776308992)calling on_stop, give it a chance to clean up.
 [1267/1323] [core/sip/tcp_trsp.cpp:955] INFO: TCP SIP server on 10.216.0.4:5060 finished (0)
 [1267/1323] [core/AmThread.cpp:92] INFO: Thread sip-tcp-trsp 139835777361664 is ending.
 [1267/1324] [core/AmThread.cpp:92] INFO: Thread sip-tcp-worker 139835776308992 is ending.
 [1267/1267] [core/AmThread.cpp:151] DEBUG: pthread_detach failed with code ESRCH: thread could not be found.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread sip-tcp-worker 139835776308992 (139835776308992) finished detach.
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread sip-tcp-worker 139835775256320 (139835775256320)calling on_stop, give it a chance to clean up.
 [1267/1325] [core/AmThread.cpp:92] INFO: Thread sip-tcp-worker 139835775256320 is ending.
 [1267/1267] [core/AmThread.cpp:151] DEBUG: pthread_detach failed with code ESRCH: thread could not be found.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread sip-tcp-worker 139835775256320 (139835775256320) finished detach.
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread sip-tcp-worker 139835774203648 (139835774203648)calling on_stop, give it a chance to clean up.
 [1267/1326] [core/AmThread.cpp:92] INFO: Thread sip-tcp-worker 139835774203648 is ending.
 [1267/1267] [core/AmThread.cpp:151] DEBUG: pthread_detach failed with code ESRCH: thread could not be found.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread sip-tcp-worker 139835774203648 (139835774203648) finished detach.
 [1267/1267] [core/AmThread.cpp:142] DEBUG: Thread sip-tcp-worker 139835773150976 (139835773150976)calling on_stop, give it a chance to clean up.
 [1267/1327] [core/AmThread.cpp:92] INFO: Thread sip-tcp-worker 139835773150976 is ending.
 [1267/1267] [core/AmThread.cpp:151] DEBUG: pthread_detach failed with code ESRCH: thread could not be found.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread sip-tcp-worker 139835773150976 (139835773150976) finished detach.
 [1267/1267] [core/AmThread.cpp:159] DEBUG: Thread sip-tcp-trsp 139835777361664 (139835777361664) finished detach.
 [1267/1267] [core/SipCtrlInterface.cpp:461] DEBUG: dec_ref(0x557c1d6ceda0)
 [1267/1267] [core/SipCtrlInterface.cpp:472] DEBUG: dec_ref(0x557c1d6cf1d0)
 [1267/1267] [core/sems.cpp:719] INFO: Exiting (success)
 [1267/1267] [apps/jsonrpc/RpcPeer.cpp:83] DEBUG: destroying connection ''

#2

could you run it as sems -D3 -E and post output?


#3

Hi dmitry,

This was part of the debug output indeed.

In the mean time I found the issue. While I had changed the listening addresses from localhost to the internal IP of Postgres, management server and such, the only thing not listening on the local IP was redis.

I’ve updated this in the redis config, after that it is working. :slight_smile:
Though it does not start the service automatically after a reboot, but that was a work in progress, right?


#4

you can try modify /lib/systemd/system/sems.service as https://github.com/yeti-switch/sems/commit/4c5451957ce1a30d8e2c273320140e0d9050abb9 to fix autostart issue.