Badly coded search filters can hang the sympa_msg.pl process...

[skunktoy]

Badly coded search filters can hang the sympa_msg.pl process, it sends a note the listmaster(s) about the database being unreachable, and then hangs.

Version

sympa-6.2.56 running on redhat ES 7

Installation method

from source

Expected behavior

Would expect it to error out, or restart sympa_msg.pl ?

Actual behavior

sympa_msg.pl just hangs after hitting this issue, so that you either have to find and fix the issue or dump that particular email from the msg spool.

Additional information

/home/sympa/etc/search_filters/listname_senders.sql code example, if it has the wrong info (ie passwd boom)
sql_named_filter_query
db_type mysql
db_name sympa
db_host localhost
db_user sympa
db_passwd notapassword
statement SELECT count(*) as c FROM mail_aliases_temp INNER JOIN subscriber_table ON subscriber_table.user_subscriber=mail_aliases_temp.zimbraMailCanonicalAddress WHERE subscriber_table.list_subscriber=[listname] AND mail_aliases_temp.alias=[sender]

[skunktoy]

Jun 17 08:44:46 sega sympa_msg[743]: err main::#243 > Sympa::Spindle::spin#95 > Sympa::Spindle::DoCommand::_twist#120 > Sympa::Spindle::spin#95 > Sympa::Request::Handler::confirm::_twist#57 > Sympa::Spindle::spin#95 > Sympa::Spindle::AuthorizeMessage::_twist#106 > Sympa::Scenario::authz#407 > (eval)#407 > Sympa::Scenario::ANON#22 > Sympa::Scenario::do_search#1293 > Sympa::DatabaseDriver::MySQL::connect#58 > Sympa::Database::connect#157 Can't connect to Database Sympa::DatabaseDriver::MySQL <db_host=localhost;db_name=sympa;db_user=sympa>: Access denied for user 'sympa'@'localhost' (using password: YES)
Jun 17 08:44:46 sega sympa_msg[743]: notice Sympa::Scenario::do_search() Unable to connect to the SQL server Sympa::DatabaseDriver::MySQL <db_host=localhost;db_name=sympa;db_user=sympa>
Jun 17 08:44:46 sega sympa_msg[743]: info Sympa::Scenario::authz() Error in scenario Sympa::Scenario <send.privatewithconfirmation;/home/sympa/etc/scenari/send.privatewithconfirmation>, context Sympa::List 52656.202050@sega.emich.edu: (error-performing-condition)

after this no processing...

[ikedas]

Hi @skunktoy ,
What do you mean "hunging"? How the Sympa behavves during "no processing"? (For example, sympa_msg.pl isn't terminated while it no longer ouput log messages).

[skunktoy]

By hanging I mean as soon as it throws this error, it stops all processing : no mail in sympa/spool/msg is processed and no new log information is generated.

[ikedas]

• Whether sympa_msg.pl is still running or not?
• Is there anything in the file $SPOOLDIR/tmp/<PID>.stderr ? (<PID> is process ID of sympa_msg.pl process)

[racke]

If sympa_msg.pl is still running, run strace -p to see what the process is doing.

[ikedas]

@skunktoy ,

Additionally please check these things:

• After when sympa_msg.pl looks hanging, if you post a new message, what does happen?
• How about after additional ten minutes?
• Is there anything in the log during 10 and some minutes above? Is there anything in <PID>.stderr file?

[skunktoy]

So I created a situation on my test box where this can happen, and here is end of the strace -fp for sympa_msg.pl after it hits this issue and stops ...

connect(7, {sa_family=AF_UNIX, sun_path="/tmp/mysql.sock"}, 110) = 0
fcntl(7, F_SETFL, O_RDONLY) = 0
setsockopt(7, SOL_IP, IP_TOS, [8], 4) = -1 EOPNOTSUPP (Operation not supported)
setsockopt(7, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
recvfrom(7, "Y\0\0\0\n5.5.5-10.3.23-MariaDB\0H\0\0\0~"..., 16384, MSG_DONTWAIT, NULL, NULL) = 93
sendto(7, "\355\0\0\1\216\242\236\0\0\0\0@\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 241, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 241
recvfrom(7, 0x7942750, 16384, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=7, events=POLLIN}], 1, -1) = 1 ([{fd=7, revents=POLLIN|POLLHUP}])
recvfrom(7, "I\0\0\2\377\25\4#28000Access denied for u"..., 16384, MSG_DONTWAIT, NULL, NULL) = 77
close(7) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {sa_handler=0x4a8980, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f213e8ad630}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({tv_sec=70, tv_nsec=0}, ^Cstrace: Process 11976 detached
<detached ...>

then it keeps looping with this

0x7ffcc6a56910) = 0
socket(AF_UNIX, SOCK_STREAM, 0) = 7
fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
connect(7, {sa_family=AF_UNIX, sun_path="/tmp/mysql.sock"}, 110) = 0
fcntl(7, F_SETFL, O_RDONLY) = 0
setsockopt(7, SOL_IP, IP_TOS, [8], 4) = -1 EOPNOTSUPP (Operation not supported)
setsockopt(7, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
recvfrom(7, "Y\0\0\0\n5.5.5-10.3.23-MariaDB\0J\0\0\0$"..., 16384, MSG_DONTWAIT, NULL, NULL) = 93
sendto(7, "\355\0\0\1\216\242\236\0\0\0\0@\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 241, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 241
recvfrom(7, "I\0\0\2\377\25\4#28000Access denied for u"..., 16384, MSG_DONTWAIT, NULL, NULL) = 77
close(7) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {sa_handler=0x4a8980, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f213e8ad630}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0

Matt

[skunktoy]

output of pid file in spool/tmp

Use of uninitialized value in pattern match (m//) at /home/sympa/bin/Conf.pm line 1675, line 8.
Use of uninitialized value in string eq at /home/sympa/bin/Conf.pm line 1601, line 8.

[skunktoy]

When it is hanging, and I wait a while and try to send another message, it ends up sitting in spool/msg and not being processed...

Matt

[ikedas]

When it is hanging, and I wait a while and try to send another message, it ends up sitting in spool/msg and not being processed...

Are there additional logs, new contents in <PID>.strderr, and/or output of strace?

[skunktoy]

So the following is generated with a second message, which it never seems to get to since it keeps bombing out on the original one...

rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {sa_handler=0x4a8980, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f375b899630}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({tv_sec=70, tv_nsec=0},
0x7ffc024f4ee0) = 0
socket(AF_UNIX, SOCK_STREAM, 0) = 7
fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
connect(7, {sa_family=AF_UNIX, sun_path="/tmp/mysql.sock"}, 110) = 0
fcntl(7, F_SETFL, O_RDONLY) = 0
setsockopt(7, SOL_IP, IP_TOS, [8], 4) = -1 EOPNOTSUPP (Operation not supported)
setsockopt(7, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
recvfrom(7, "Y\0\0\0\n5.5.5-10.3.23-MariaDB\0\211\f\0\0l"..., 16384, MSG_DONTWAIT, NULL, NULL) = 93
sendto(7, "\354\0\0\1\216\242\236\0\0\0\0@\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 240, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 240
recvfrom(7, "I\0\0\2\377\25\4#28000Access denied for u"..., 16384, MSG_DONTWAIT, NULL, NULL) = 77
close(7) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {sa_handler=0x4a8980, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f375b899630}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({tv_sec=80, tv_nsec=0},

0x7ffc024f4ee0) = 0
socket(AF_UNIX, SOCK_STREAM, 0) = 7
fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
connect(7, {sa_family=AF_UNIX, sun_path="/tmp/mysql.sock"}, 110) = 0
fcntl(7, F_SETFL, O_RDONLY) = 0
setsockopt(7, SOL_IP, IP_TOS, [8], 4) = -1 EOPNOTSUPP (Operation not supported)
setsockopt(7, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
recvfrom(7, "Y\0\0\0\n5.5.5-10.3.23-MariaDB\0\213\f\0\0n"..., 16384, MSG_DONTWAIT, NULL, NULL) = 93
sendto(7, "\354\0\0\1\216\242\236\0\0\0\0@\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 240, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 240
recvfrom(7, "I\0\0\2\377\25\4#28000Access denied for u"..., 16384, MSG_DONTWAIT, NULL, NULL) = 77
close(7) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {sa_handler=0x4a8980, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f375b899630}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({tv_sec=90, tv_nsec=0},

Use of uninitialized value in pattern match (m//) at /home/sympa/bin/Conf.pm line 1675, line 8.
Use of uninitialized value in string eq at /home/sympa/bin/Conf.pm line 1601, line 8.

[root@testvax.emich.edu:/home/sympa/spool/msg]# ls -alF
total 36
drwxr-xr-x 4 sympa sympa 4096 Jul 7 14:49 ./
drwxr-x--- 17 sympa sympa 4096 Sep 21 2015 ../
drwxr-x--- 2 sympa sympa 4096 Jul 6 14:54 bad/
-rw------- 1 sympa sympa 5054 Jul 7 14:48 matt-test@testvax.emich.edu.1594147716.7013
-rw------- 1 sympa sympa 37 Jul 7 14:48 matt-test@testvax.emich.edu.1594147716.7013,lock
-rw------- 1 sympa sympa 5053 Jul 7 14:49 matt-test@testvax.emich.edu.1594147777.7033
drwxr-x--- 2 sympa sympa 4096 Sep 21 2015 moved/
[root@testvax.emich.edu:/home/sympa/spool/msg]# ls -alF
total 36
drwxr-xr-x 4 sympa sympa 4096 Jul 7 14:49 ./
drwxr-x--- 17 sympa sympa 4096 Sep 21 2015 ../
drwxr-x--- 2 sympa sympa 4096 Jul 6 14:54 bad/
-rw------- 1 sympa sympa 5054 Jul 7 14:48 matt-test@testvax.emich.edu.1594147716.7013
-rw------- 1 sympa sympa 37 Jul 7 14:48 matt-test@testvax.emich.edu.1594147716.7013,lock
-rw------- 1 sympa sympa 5053 Jul 7 14:49 matt-test@testvax.emich.edu.1594147777.7033
drwxr-x--- 2 sympa sympa 4096 Sep 21 2015 moved/

[ikedas]

Are there additional logs?

[ikedas]

From the strace results, it appears that sympa_msg.pl simply sleeps.

According to the code below, if Sympa's process failed to connect to the database, it repeatedly retries, with an increasing interval of 60 seconds, 70 seconds and so on.

sympa/src/lib/Sympa/Database.pm

Lines 170 to 177 in 0fa5376

	# Loop until connect works
	my $sleep_delay = 60;
	while (1) {
	sleep $sleep_delay;
	$connection_of{$self->{_id}} = eval { $self->_connect };
	last if $self->ping;
	$sleep_delay += 10;
	}

This is considered normal behavior of Sympa.