On Thu, Feb 20, 2014 at 05:00:59PM +0100, Lukas Slebodnik wrote:

ehlo,

It was not easy to reproduce this crash in the find-uid-test (log attached)

Here is a backtrace: #0 0x00007fbeaf7850cf in _IO_vfprintf_internal (s=<optimized out>, format=<optimized out>, ap=<optimized out>) at vfprintf.c:1635 #1 0x00007fbeaf788b01 in buffered_vfprintf (s=s@entry=0x7fbeafaf51c0 <_IO_2_1_stderr_>, format=format@entry=0x7fbeb119c1a8 "Proc file [%s] is not available anymore, continuing.\n", args=args@entry=0x7fff2d20b668) at vfprintf.c:2328 #2 0x00007fbeaf783ffe in _IO_vfprintf_internal (s=s@entry=0x7fbeafaf51c0 <_IO_2_1_stderr_>, format=0x7fbeb119c1a8 "Proc file [%s] is not available anymore, continuing.\n", ap=0x7fff2d20b668) at vfprintf.c:1289 #3 0x00007fbeaf840a06 in ___vfprintf_chk (fp=0x7fbeafaf51c0 <_IO_2_1_stderr_>, flag=1, format=<optimized out>, ap=<optimized out>) at vfprintf_chk.c:33 #4 0x00007fbeb0d7461a in debug_fn (file=file@entry=0x7fbeb119bfcf "src/util/find_uid.c", line=line@entry=90, function=function@entry=0x7fbeb119c270 <__FUNCTION__.8600> "get_uid_from_pid", level=level@entry=4096, format=format@entry=0x7fbeb119c1a8 "Proc file [%s] is not available anymore, continuing.\n") at src/util/debug.c:257 #5 0x00007fbeb119ae74 in get_uid_from_pid (pid=<optimized out>, uid=uid@entry=0x7fff2d20c9a4) at src/util/find_uid.c:88 #6 0x00007fbeb119b381 in get_active_uid_linux (table=table@entry=0x0, search_uid=search_uid@entry=4294967292) at src/util/find_uid.c:236 #7 0x00007fbeb119b69f in check_if_uid_is_active (uid=uid@entry=4294967292, result=result@entry=0x7fff2d20ca67) at src/util/find_uid.c:333 #8 0x00007fbeb119a9ab in test_check_if_uid_is_active_fail (_i=<optimized out>) at src/tests/find_uid-tests.c:58 #9 0x00007fbeb054887e in tcase_run_tfun_fork (i=0, tfun=0x7fbeb14a0300, tc=0x7fbeb14a00a0, sr=0x7fbeb14a0390) at check_run.c:396 #10 srunner_iterate_tcase_tfuns (tc=0x7fbeb14a00a0, sr=0x7fbeb14a0390) at check_run.c:181 #11 srunner_run_tcase (tc=0x7fbeb14a00a0, sr=0x7fbeb14a0390) at check_run.c:313 #12 srunner_iterate_suites (print_mode=CK_SILENT, tcname=0x0, sname=0x0, sr=0x7fbeb14a0390) at check_run.c:156 #13 srunner_run (sr=sr@entry=0x7fbeb14a0390, sname=sname@entry=0x0, tcname=tcname@entry=0x0, print_mode=print_mode@entry=CK_ENV) at check_run.c:618 #14 0x00007fbeb054892b in srunner_run_all (sr=sr@entry=0x7fbeb14a0390, print_mode=print_mode@entry=CK_ENV) at check_run.c:587 #15 0x00007fbeb119a685 in main () at src/tests/find_uid-tests.c:125

(gdb) l src/util/find_uid.c:88 83 84 fd = open(path, O_RDONLY); 85 if (fd == -1) { 86 error = errno; 87 if (error == ENOENT) { 88 DEBUG(SSSDBG_TRACE_LIBS, 89 "Proc file [%s] is not available anymore, continuing.\n", 90 path); 91 return EOK; 92 }

As you can see in frame 5, it was caused by DEBUG macro. It was strange because variable path was declared on stack "char path[PATHLEN];"

But it looks like va_list should not be used twice. http://en.cppreference.com/w/cpp/utility/variadic/va_copy

yes, this can also be seen from the vsprintf man page: "Because they invoke the va_arg macro, the value of ap is undefined after the call."

very good catch, ACK to the patch.

bye, Sumit

It is really difficult to reproduce it. I was not able to reproduce problem on fedora 19 or rawhide http://koji.fedoraproject.org/koji/taskinfo?taskID=6551367 http://koji.fedoraproject.org/koji/taskinfo?taskID=6551377

and only sometimes on fedora 20 x86_64 http://koji.fedoraproject.org/koji/taskinfo?taskID=6551997 --works http://koji.fedoraproject.org/koji/taskinfo?taskID=6551349 --doesn't work

Patch is attached.

LS

Running suite(s): find_uid Proc file [ 1268 kB VmData: 448 kB VmStk: 136 kB VmExe: 16 kB VmLib: 5168 kB VmPTE: 108 kB VmSwap: 0 kB Threads: 1 SigQ: 2/61566 SigPnd: 0000000000000000 ShdPnd: 0000000000000000 SigBlk: 0000000000000000 SigIgn: 0000000001000000 SigCgt: 0000000180002000 CapInh: 0000000000000000 CapPrm: 0000000000000000 CapEff: 0000000000000000 CapBnd: 0000001fffffffff Seccomp: 0 Cpus_allowed: ff Cpus_allowed_list: 0-7 Mems_allowed: 00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000001 Mems_allowed_list: 0 voluntary_ctxt_switches: 21 nonvoluntary_ctxt_switches: 2 70 s: 2

] is not available anymore, continuing. 66%: Checks: 3, Failures: 0, Errors: 1 src/tests/find_uid-tests.c:50:E:find_uid:test_check_if_uid_is_active_fail:0: (after this point) Received signal 11 (Segmentation fault)

From a05c53c12ae81c59eca39bc66b2808cb86d0641b Mon Sep 17 00:00:00 2001 From: Lukas Slebodnik lslebodn@redhat.com Date: Thu, 20 Feb 2014 13:11:27 +0100 Subject: [PATCH] DEBUG: Fix crash after fallback from journal log

if journal_send fail we should not use the same va_list in the fallback functions. va_list can be modiefied and it may cause crashes im some cases e.g. printing string.

This patch use copy of initialised va_list for debug_vprintf function.

src/util/debug.c | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/src/util/debug.c b/src/util/debug.c index 9cd0f41fffcda50bec52147b4bc9afe836392a17..1db3693a11bef9d6dced6b085e320d99c4fe3384 100644 --- a/src/util/debug.c +++ b/src/util/debug.c @@ -203,6 +203,7 @@ void debug_fn(const char *file, const char *format, ...) { va_list ap;

• va_list ap_fallback; struct timeval tv; struct tm *tm; char datetime[20];

@@ -220,13 +221,15 @@ void debug_fn(const char *file, * searchable. */ va_start(ap, format);

•    va_copy(ap_fallback, ap);
     ret = journal_send(file, line, function, level, format, ap);
  

•    va_end(ap);
     if (ret != EOK) {
         /* Emergency fallback, send to STDERR */
  

•        debug_vprintf(format, ap);
  

•        debug_vprintf(format, ap_fallback);
         debug_fflush();
     }
  

•    va_end(ap);
  

•    va_end(ap_fallback);
     return;
  

  }

#endif

1.8.5.3

---

sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel