Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Unexpected freeswitch startup failures #2743

Open
hdep opened this issue Jan 20, 2025 · 2 comments
Open

Unexpected freeswitch startup failures #2743

hdep opened this issue Jan 20, 2025 · 2 comments
Labels
bug Something isn't working

Comments

@hdep
Copy link

hdep commented Jan 20, 2025 •
edited
Loading

Describe the bug

randomly freeswitch won't start

To Reproduce
Steps to reproduce the behavior:

  1. reboot the server
  2. freeswitch try to start but failed in loop

This is random issue, mostof the time process start without any issues.
I might not be the only one according to the forum : https://forum.signalwire.community/t/unexpected-freeswitch-startup-failures/1082/10

Starting freeswitch in CLI when issue occured, looks like the process is stuck because last log is Successfully Loaded [mod_g729]

Expected behavior
Freeswitch start

Package version or git hash

  • Version 1.10.11release25f24064fbullseye-1~bullseye+1

Trace logs

When issue occurs I tried to execute freeswitch manually to get more logs:

root@server~  /usr/bin/freeswitch -u freeswitch -g freeswitch  -nonat
2025-01-17 11:02:35.916219 0.00% [INFO] switch_event.c:714 Activate Eventing Engine.
2025-01-17 11:02:35.926411 0.00% [WARNING] switch_event.c:685 Create additional event dispatch thread 0
2025-01-17 11:02:35.934228 0.00% [ERR] switch_xml.c:1395 Error including /etc/freeswitch/lang/en/demo/*.xml
2025-01-17 11:02:35.956793 0.00% [CONSOLE] switch_core.c:1593 Created ip list lan default (allow)
2025-01-17 11:02:35.956831 0.00% [CONSOLE] switch_core.c:1593 Created ip list domains default (deny)
2025-01-17 11:02:35.957411 0.00% [CONSOLE] switch_core.c:2468 Bringing up environment.
2025-01-17 11:02:35.957429 0.00% [CONSOLE] switch_core.c:2469 Loading Modules.
2025-01-17 11:02:35.957801 0.00% [CONSOLE] switch_time.c:1576 Clock calibration disabled.
2025-01-17 11:02:35.957815 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [CORE_SOFTTIMER_MODULE]
2025-01-17 11:02:35.957862 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [CORE_PCM_MODULE]
2025-01-17 11:02:35.957932 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [CORE_SPEEX_MODULE]
2025-01-17 11:02:35.957954 0.00% [CONSOLE] switch_loadable_module.c:2196 open of pre_load_modules.conf failed
2025-01-17 11:02:35.963395 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [CORE_VPX_MODULE]
2025-01-17 11:02:35.963670 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_console]
2025-01-17 11:02:35.964328 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_enum]
2025-01-17 11:02:35.964530 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_cdr_csv]
2025-01-17 11:02:35.964700 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_event_socket]
2025-01-17 11:02:35.969178 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_snmp]
2025-01-17 11:02:37.470507 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_sofia]
2025-01-17 11:02:37.470924 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_loopback]
2025-01-17 11:02:37.471650 0.00% [CONSOLE] mod_signalwire.c:1020 Welcome to
     _____ _                   ___       ___
    / ___/(_)___ _____  ____ _/ / |     / (_)_______
    \__ \/ / __ `/ __ \/ __ `/ /| | /| / / / ___/ _ \
   ___/ / / /_/ / / / / /_/ / / | |/ |/ / / /  /  __/
  /____/_/\__, /_/ /_/\__,_/_/  |__/|__/_/_/   \___/
         /____/
2025-01-17 11:02:37.471682 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_signalwire]
2025-01-17 11:02:37.472298 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_commands]
2025-01-17 11:02:37.473881 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_curl]
2025-01-17 11:02:37.474328 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_db]
2025-01-17 11:02:37.474720 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_dptools]
2025-01-17 11:02:37.476240 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_expr]
2025-01-17 11:02:37.478509 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_fifo]
2025-01-17 11:02:37.478790 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_hash]
2025-01-17 11:02:37.479030 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_httapi]
2025-01-17 11:02:37.479212 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_dialplan_xml]
2025-01-17 11:02:37.479364 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_dialplan_asterisk]
2025-01-17 11:02:37.500315 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_spandsp]
2025-01-17 11:02:37.500870 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_g723_1]
2025-01-17 11:02:37.501034 0.00% [CONSOLE] switch_loadable_module.c:1772 Successfully Loaded [mod_g729]

I did run strace against the process to identify issues :

# strace -f -s 200 -p 1194
[pid  1214] fcntl(35, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=1073741824, l_len=1}) = 0
[pid  1215] fcntl(36, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0} <unfinished ...>
[pid  1214] stat("/var/lib/freeswitch/db/sofia_reg_internal.db-journal",  <unfinished ...>
[pid  1215] <... fcntl resumed>)        = 0
[pid  1214] <... stat resumed>0x7f5c202ad650) = -1 ENOENT (No such file or directory)
[pid  1214] pread64(35, "\0\0\0U\0\0\0S\0\0\0\0\0\0\0\0", 16, 24) = 16
[pid  1214] stat("/var/lib/freeswitch/db/sofia_reg_internal.db-wal", 0x7f5c202ad650) = -1 ENOENT (No such file or directory)
[pid  1215] fcntl(36, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=1073741824, l_len=1} <unfinished ...>
[pid  1214] fstat(35,  <unfinished ...>
[pid  1215] <... fcntl resumed>)        = 0
[pid  1214] <... fstat resumed>{st_mode=S_IFREG|0640, st_size=339968, ...}) = 0
[pid  1215] fcntl(36, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=1073741826, l_len=510} <unfinished ...>
[pid  1214] fcntl(35, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0} <unfinished ...>
[pid  1215] <... fcntl resumed>)        = 0
[pid  1214] <... fcntl resumed>)        = 0
[pid  1215] fcntl(36, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=1073741824, l_len=1} <unfinished ...>
[pid  1214] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=131177000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1215] <... fcntl resumed>)        = 0
[pid  1215] stat("/var/lib/freeswitch/db/sofia_reg_external.db-journal", 0x7f5c20270650) = -1 ENOENT (No such file or directory)
[pid  1215] pread64(36, "\0\0\0U\0\0\0S\0\0\0\0\0\0\0\0", 16, 24) = 16
[pid  1215] stat("/var/lib/freeswitch/db/sofia_reg_external.db-wal", 0x7f5c20270650) = -1 ENOENT (No such file or directory)
[pid  1215] fstat(36, {st_mode=S_IFREG|0640, st_size=339968, ...}) = 0
[pid  1215] fcntl(36, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
[pid  1215] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=131471000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1209] <... epoll_wait resumed>[], 4, 395) = 0
[pid  1209] epoll_wait(27, [], 4, 0)    = 0
[pid  1209] epoll_wait(27,  <unfinished ...>
[pid  1210] <... epoll_wait resumed>[], 4, 457) = 0
[pid  1210] epoll_wait(30, [], 4, 0)    = 0
[pid  1210] epoll_wait(30,  <unfinished ...>
[pid  1214] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1214] futex(0x7f5c218bdb20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  1214] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=231401000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1215] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1215] futex(0x7f5c218bdb20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  1215] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=231597000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1214] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1214] futex(0x7f5c218bdb20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  1214] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=331600000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1215] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1215] futex(0x7f5c218bdb20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  1215] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=331741000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1214] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1214] futex(0x7f5c218bdb20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  1214] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=431729000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1215] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1215] futex(0x7f5c218bdb20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  1215] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=431872000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1199] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1199] futex(0x558b77e19520, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  1199] futex(0x558b77e1959c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=846464000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1214] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1214] futex(0x7f5c218bdb20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  1214] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=531918000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1215] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1215] futex(0x7f5c218bdb20, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  1215] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=531997000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1214] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1215] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1214] futex(0x7f5c218bdb20, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  1215] futex(0x7f5c218bdb20, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  1214] <... futex resumed>)        = 0
[pid  1215] <... futex resumed>)        = 0
[pid  1214] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=632102000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1215] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=632108000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1221] <... select resumed>)       = 0 (Timeout)
[pid  1221] select(0, NULL, NULL, NULL, {tv_sec=1, tv_usec=0} <unfinished ...>
[pid  1215] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1214] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid  1215] futex(0x7f5c218bdb20, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  1214] futex(0x7f5c218bdb20, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  1215] <... futex resumed>)        = 0
[pid  1214] <... futex resumed>)        = 0
[pid  1215] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=732227000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid  1214] futex(0x7f5c218bdb98, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1737110213, tv_nsec=732232000}, FUTEX_BITSET_MAT
  • systemd logs
Jan 09 06:46:09 server systemd[1]: freeswitch.service: start operation timed out. Terminating.
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Waiting for background process pid:7933 to be ready.....
Jan 09 06:46:09 server freeswitch[7932]: FreeSWITCH[7932] Error starting system! pid:7933
Jan 09 06:46:09 server systemd[1]: freeswitch.service: Control process exited, code=exited, status=1/FAILURE
Jan 09 06:46:09 server systemd[1]: freeswitch.service: Killing process 7958 (freeswitch) with signal SIGKILL.
Jan 09 06:46:09 server systemd[1]: freeswitch.service: Failed with result 'timeout'.
Jan 09 06:46:09 server systemd[1]: Failed to start freeswitch.
Jan 09 06:46:09 server systemd[1]: freeswitch.service: Scheduled restart job, restart counter is at 221.
Jan 09 06:46:09 server systemd[1]: Stopped freeswitch.
@hdep hdep added the bug Something isn't working label Jan 20, 2025
@greenbea
Copy link
Contributor

take a core dump when it happens.

@hdep
Copy link
Author

hdep commented Jan 24, 2025

I generated two coredump because I got two running processes :

root       12324  0.0  0.1  37000 10900 ?        Ss   09:25   0:00 /usr/bin/freeswitch -u freeswitch -g freeswitch -ncwait -nonat
freeswi+   12325  1.8  0.6 1449900 37548 ?       S<sl 09:25   0:00 /usr/bin/freeswitch -u freeswitch -g freeswitch -ncwait -nonat

How can I securely share those coredumps ?

thanks

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@hdep @greenbea