Bug 45601

Summary: hangs on access to /etc/pve (freeze in pmxcfs)
Product: Sisyphus Reporter: Vitaly Lipatov <lav>
Component: pve-clusterAssignee: Alexey Shabalin <shaba>
Status: CLOSED WORKSFORME QA Contact: qa-sisyphus
Severity: normal    
Priority: P5 CC: shaba, shrek
Version: unstable   
Hardware: x86_64   
OS: Linux   

Description Vitaly Lipatov 2023-03-21 03:40:13 MSK
Steps to reproduce on a machine with PVE installed:

0. Preparing
# killall -9 pmxcfs
# umount /etc/pve -l

1. Run pmxcfs manually:
# pmxcfs -l -f -d

2. Access to /etc/pve:
# ls /etc/pve

last message on this access:
[main] debug: enter cfs_plug_link_getattr  (cfs-plug-link.c:58:cfs_plug_link_getattr)


The code:
static int cfs_plug_link_getattr(cfs_plug_t *plug, const char *path, struct stat *stbuf)
{
        g_return_val_if_fail(plug != NULL, PARAM_CHECK_ERRNO);
        g_return_val_if_fail(plug->ops == &cfs_ops, PARAM_CHECK_ERRNO);
        g_return_val_if_fail(path != NULL, PARAM_CHECK_ERRNO);
        g_return_val_if_fail(stbuf != NULL, PARAM_CHECK_ERRNO);

        cfs_debug("enter cfs_plug_link_getattr %s", path);

        memset(stbuf, 0, sizeof(struct stat));

        if (cfs_is_quorate()) {
                stbuf->st_mode = S_IFLNK | 0777;
        } else {
                stbuf->st_mode = S_IFLNK | 0555;
        }

        stbuf->st_nlink = 1;

        return 0;
}


gdb shows after install pve-cluster-debuginfo
pmxcfs hungs on
cfs_is_quorate() call


1948	gboolean
1949	cfs_is_quorate(void)
1950	{
1951		g_mutex_lock (&mutex);
1952		gboolean res =  cfs_status.quorate;
1953		g_mutex_unlock (&mutex);
1954	
1955		return res;


1951		g_mutex_lock (&mutex);
(gdb) s
g_mutex_lock (mutex=0x555555584a60 <mutex>) at ../glib/gthread-posix.c:1515
1515	  if G_UNLIKELY (g_atomic_int_add (&mutex->i[0], 1) != 0)
1516	    g_mutex_lock_slowpath (mutex);
g_mutex_lock_slowpath (mutex=0x555555584a60 <mutex>) at ../glib/gthread-posix.c:1491
1491	  while (exchange_acquire (&mutex->i[0], 2) != 0)
1492	    syscall (__NR_futex, &mutex->i[0], (gsize) FUTEX_WAIT_PRIVATE, (gsize) 2, NULL);
(hung)
Comment 1 Vitaly Lipatov 2023-03-21 18:35:19 MSK
It hangs on rrdcached access via rrd_client_update


(gdb) info threads
  Id   Target Id                                   Frame 
* 1    Thread 0x7f665918ba00 (LWP 3193) "pmxcfs"   futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x7ffe6657f8e0) at ../sysdeps/nptl/futex-internal.h:320
  2    Thread 0x7f6659156640 (LWP 3194) "cfs_loop" 0x00007f665a089856 in epoll_wait (epfd=8, events=events@entry=0x7f6659155990, maxevents=maxevents@entry=12, timeout=timeout@entry=999)
    at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
  3    Thread 0x7f6658934640 (LWP 3318) "server"   __libc_recv (flags=<optimized out>, len=4096, buf=0x7f665a1de290 <default_client+16>, fd=21) at ../sysdeps/unix/sysv/linux/recv.c:28
  4    Thread 0x7f6653fff640 (LWP 3319) "pmxcfs"   __libc_read (nbytes=135168, buf=0x7f6658112010, fd=7) at ../sysdeps/unix/sysv/linux/read.c:26
  5    Thread 0x7f66537fe640 (LWP 3320) "pmxcfs"   syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38

(gdb) thread 3
[Switching to thread 3 (Thread 0x7f6658934640 (LWP 3318))]
#0  __libc_recv (flags=<optimized out>, len=4096, buf=0x7f665a1de290 <default_client+16>, fd=21) at ../sysdeps/unix/sysv/linux/recv.c:28
28	  return SYSCALL_CANCEL (recvfrom, fd, buf, len, flags, NULL, NULL);

(gdb) bt
#0  __libc_recv (flags=<optimized out>, len=4096, buf=0x7f665a1de290 <default_client+16>, fd=21) at ../sysdeps/unix/sysv/linux/recv.c:28
#1  __libc_recv (fd=21, buf=buf@entry=0x7f665a1de290 <default_client+16>, len=len@entry=4096, flags=flags@entry=0) at ../sysdeps/unix/sysv/linux/recv.c:23
#2  0x00007f665a1b88bc in recv (__flags=0, __n=4096, __buf=0x7f665a1de290 <default_client+16>, __fd=<optimized out>) at /usr/include/bits/socket2.h:44
#3  recvline (client=client@entry=0x7f665a1de280 <default_client>, buf=buf@entry=0x7f66589306b0 "", n=4095) at rrd_client.c:526
#4  0x00007f665a1b8bd4 in recvline (n=4096, buf=0x7f66589306b0 "", client=0x7f665a1de280 <default_client>) at rrd_client.c:514
#5  response_read (client=client@entry=0x7f665a1de280 <default_client>, ret_response=ret_response@entry=0x7f6658931700) at rrd_client.c:588
#6  0x00007f665a1b9373 in request (buffer=0x7f6658931790 "update /var/lib/rrdcached/db/pve2-node/aspetos 1679411717:1.24:32:0:0:134163562496:1661198336:134179975168:0:1882764304384:12975132672:693041:297340\n", buffer_size=0, 
    ret_response=0x7f6658931788, client=0x7f665a1de280 <default_client>) at rrd_client.c:692
#7  request (client=client@entry=0x7f665a1de280 <default_client>, 
    buffer=buffer@entry=0x7f6658931790 "update /var/lib/rrdcached/db/pve2-node/aspetos 1679411717:1.24:32:0:0:134163562496:1661198336:134179975168:0:1882764304384:12975132672:693041:297340\n", buffer_size=<optimized out>, 
    ret_response=ret_response@entry=0x7f6658931788) at rrd_client.c:671
#8  0x00007f665a1b9c07 in rrd_client_update (client=client@entry=0x7f665a1de280 <default_client>, filename=filename@entry=0x7f664c005950 "/var/lib/rrdcached/db/pve2-node/aspetos", values_num=1486038928, values_num@entry=1, 
    values=values@entry=0x7f6658933800) at rrd_client.c:1090
#9  0x00007f665a1b9cb0 in rrdc_update (filename=0x7f664c005950 "/var/lib/rrdcached/db/pve2-node/aspetos", values_num=1, values=0x7f6658933800) at rrd_client.c:1109
#10 0x00005571d2457853 in update_rrd_data (len=<optimized out>, data=<optimized out>, key=<optimized out>) at status.c:1374
#11 rrdentry_hash_set (rrdhash=0x2, key=0x7f664c005950 "/var/lib/rrdcached/db/pve2-node/aspetos", data=0x7f66500cfe0c "1679411717:1.24:32:0:0:134163562496:1661198336:134179975168:0:1882764304384:12975132672:693041:297340", 
    len=140077549434880) at status.c:1523
#12 0x00005571d245ad16 in cfs_status_set (key=<optimized out>, data=0x7f66500cfe08, len=len@entry=106) at status.c:1697
#13 0x00005571d2455ef2 in s1_msg_process_fn (c=0x7f664c006900, data=<optimized out>, size=<optimized out>) at server.c:234
#14 0x00007f665a4af409 in _process_request_ (ms_timeout=10, c=0x7f664c006900) at ipcs.c:699
#15 qb_ipcs_dispatch_connection_request (fd=<optimized out>, revents=<optimized out>, data=0x7f664c006900) at ipcs.c:801
#16 0x00007f665a4ab5df in _poll_dispatch_and_take_back_ (item=0x7f664c0012e8, p=<optimized out>) at loop_poll.c:109
#17 0x00007f665a4ab3fc in qb_loop_run_level (level=<optimized out>) at loop.c:43
#18 qb_loop_run (lp=<optimized out>) at loop.c:211
#19 0x00005571d2455833 in worker_thread (data=<optimized out>) at server.c:592
#20 0x00007f665a3ea1cd in g_thread_proxy (data=0x5571d400d060) at ../glib/gthread.c:826
#21 0x00007f665a169eb0 in start_thread (arg=0x7f6658934640) at pthread_create.c:463
#22 0x00007f665a08952f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
Comment 2 Vitaly Lipatov 2023-03-21 18:36:52 MSK
Вроде как помогло выключение инициализации сервиса rrrdcached через сокет:
 # systemctl disable rrdcached.socket
Removed /etc/systemd/system/sockets.target.wants/rrdcached.socket.

И включение через rdcached.service (хотя и без него работает вроде как).
Comment 3 Alexey Shabalin 2023-03-21 20:50:33 MSK
rdcached нужен для pve, он в нем кэштрует графики загрузки процессора и т.п.
при этом сами rrd лежат в /etc/pve.
Вполне возможно, что есть гонка, кто-то рано стучится в сокет и запускается сервис раньше положенного. Если в этом и есть проблема, то можно вообще убрать socket файл из пакета.
Comment 4 Vitaly Lipatov 2023-04-22 01:26:52 MSK
(Ответ для Alexey Shabalin на комментарий #3)
> rdcached нужен для pve, он в нем кэштрует графики загрузки процессора и т.п.
> при этом сами rrd лежат в /etc/pve.
> Вполне возможно, что есть гонка, кто-то рано стучится в сокет и запускается
> сервис раньше положенного. Если в этом и есть проблема, то можно вообще
> убрать socket файл из пакета.
Мы не могли воспроизвести проблему на тестовом стенде.
Если проблема встречается, то проще убрать socket-файл и прописать обязательство запускать rrdcached явно.
Comment 5 Vitaly Lipatov 2023-11-08 01:17:42 MSK
(Ответ для Vitaly Lipatov на комментарий #2)
> Вроде как помогло выключение инициализации сервиса rrrdcached через сокет:
>  # systemctl disable rrdcached.socket
> Removed /etc/systemd/system/sockets.target.wants/rrdcached.socket.
Напоролся ещё раз на новой машине после очередной перезагрузки. Выключение инициализации через сокет помогло.