Description of problem: A customer constantly gets the following messages, sometimes multiple times, when executing the following command: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- # oscap xccdf eval --rule xccdf_org.ssgproject.content_rule_xwindows_runlevel_target --profile xccdf_org.ssgproject.content_profile_stig /usr/share/xml/scap/ssg/content/ssg-rhel8-ds.xml error : Unknown IO error [...] --- Starting Evaluation --- Title Disable X Windows Startup By Setting Default Target Rule xccdf_org.ssgproject.content_rule_xwindows_runlevel_target Ident CCE-83380-6 Result pass -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- We are trying to understand where this comes from (apparently it's from libxml2 library, xmlIO.c line 406) and if this is benign or not. Version-Release number of selected component (if applicable): openscap-scanner-1.3.7-1.el8.x86_64 How reproducible: Always on customer system, couldn't reproduce internally
The strace shows a high number of `brk()` calls and `mremap()` just before (hence memory allocation), but nothing else: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- 9140 12:20:06.995983 brk(NULL) = 0x562a83433000 <0.000027> 9140 12:20:06.996096 brk(0x562a83454000) = 0x562a83454000 <0.000022> 9140 12:20:07.070091 brk(NULL) = 0x562a83454000 <0.000026> 9140 12:20:07.070190 brk(0x562a83479000) = 0x562a83479000 <0.000021> 9140 12:20:07.070437 mremap(0x7f65561d0000, 331776, 659456, MREMAP_MAYMOVE) = 0x7f65561d0000 <0.000018> 9140 12:20:07.082584 brk(NULL) = 0x562a83479000 <0.000020> 9140 12:20:07.082659 brk(0x562a8349d000) = 0x562a8349d000 <0.000020> 9140 12:20:07.107506 brk(NULL) = 0x562a8349d000 <0.000021> 9140 12:20:07.107594 brk(0x562a834be000) = 0x562a834be000 <0.000019> 9140 12:20:07.113993 brk(NULL) = 0x562a834be000 <0.000020> 9140 12:20:07.114050 brk(0x562a834df000) = 0x562a834df000 <0.000020> 9140 12:20:07.123826 brk(NULL) = 0x562a834df000 <0.000039> 9140 12:20:07.123917 brk(0x562a83506000) = 0x562a83506000 <0.000018> 9140 12:20:07.750464 brk(NULL) = 0x562a83506000 <0.000054> 9140 12:20:07.750607 brk(0x562a83527000) = 0x562a83527000 <0.000021> 9140 12:20:07.783420 brk(NULL) = 0x562a83527000 <0.000023> 9140 12:20:07.783525 brk(0x562a83548000) = 0x562a83548000 <0.000026> 9140 12:20:07.838506 brk(NULL) = 0x562a83548000 <0.000048> 9140 12:20:07.838659 brk(0x562a8356d000) = 0x562a8356d000 <0.000023> 9140 12:20:07.891447 brk(NULL) = 0x562a8356d000 <0.000033> 9140 12:20:07.891552 brk(0x562a83590000) = 0x562a83590000 <0.000026> 9140 12:20:07.941167 brk(NULL) = 0x562a83590000 <0.000027> 9140 12:20:07.941280 brk(0x562a835b1000) = 0x562a835b1000 <0.000025> 9140 12:20:07.956697 brk(NULL) = 0x562a835b1000 <0.000016> 9140 12:20:07.956770 brk(0x562a835d2000) = 0x562a835d2000 <0.000020> 9140 12:20:07.971919 brk(NULL) = 0x562a835d2000 <0.000025> 9140 12:20:07.972001 brk(0x562a835f3000) = 0x562a835f3000 <0.000020> 9140 12:20:08.191901 munmap(0x7f655617f000, 331776) = 0 <0.000141> 9140 12:20:08.198655 munmap(0x7f65561d0000, 659456) = 0 <0.000111> 9140 12:20:08.228927 munmap(0x7f6556273000, 151552) = 0 <0.000067> 9140 12:20:08.229188 write(2</dev/pts/2<char 136:2>>, "error : ", 8) = 8 <0.000384> 9140 12:20:08.229745 write(2</dev/pts/2<char 136:2>>, "Unknown IO error\n", 17) = 17 <0.000050> -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
The customer delivered me a coredump which was taken when the "Unknown IO error" message was getting printed. The backtrace shows this: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- (gdb) bt #0 0x00007f71479a9a28 in __GI___libc_write (fd=2, buf=0x7fff94db34a0, nbytes=17) at ../sysdeps/unix/sysv/linux/write.c:26 #1 0x00007f714791b9ed in _IO_new_file_write (f=0x7f7147c4a600 <_IO_2_1_stderr_>, data=0x7fff94db34a0, n=17) at fileops.c:1180 #2 0x00007f714791ad5f in new_do_write (fp=fp@entry=0x7f7147c4a600 <_IO_2_1_stderr_>, data=data@entry=0x7fff94db34a0 "Unknown IO error\n", to_do=to_do@entry=17) at libioP.h:838 #3 0x00007f714791c11e in _IO_new_file_xsputn (n=17, data=<optimized out>, f=0x7f7147c4a600 <_IO_2_1_stderr_>) at fileops.c:1259 #4 _IO_new_file_xsputn (f=0x7f7147c4a600 <_IO_2_1_stderr_>, data=<optimized out>, n=17) at fileops.c:1201 #5 0x00007f71478f30ca in buffered_vfprintf (s=s@entry=0x7f7147c4a600 <_IO_2_1_stderr_>, format=format@entry=0x7f714b3a337d "%s\n", args=args@entry=0x7fff94db5a50) at ../libio/libioP.h:838 #6 0x00007f71478f20b7 in _IO_vfprintf_internal (s=s@entry=0x7f7147c4a600 <_IO_2_1_stderr_>, format=format@entry=0x7f714b3a337d "%s\n", ap=0x7fff94db5a50) at vfprintf.c:1329 #7 0x00007f71479c656c in ___vfprintf_chk (fp=0x7f7147c4a600 <_IO_2_1_stderr_>, flag=flag@entry=1, format=format@entry=0x7f714b3a337d "%s\n", ap=ap@entry=0x7fff94db5a50) at vfprintf_chk.c:33 #8 0x00007f714b2b3677 in vfprintf (__ap=0x7fff94db5a50, __fmt=0x7f714b3a337d "%s\n", __stream=<optimized out>) at /usr/include/bits/stdio2.h:132 #9 xmlGenericErrorDefaultFunc (ctx=<optimized out>, msg=0x7f714b3a337d "%s\n") at ../error.c:78 #10 0x00007f714b2b3892 in xmlReportError (err=err@entry=0x7f714b5e6140 <xmlLastError>, ctxt=ctxt@entry=0x0, str=str@entry=0x55d1d4c7b970 "Unknown IO error", channel=channel@entry=0x7f714b2b35c0 <xmlGenericErrorDefaultFunc>, data=data@entry=0x7f7147c4a600 <_IO_2_1_stderr_>) at ../error.c:398 #11 0x00007f714b2b5466 in __xmlRaiseError (schannel=0x0, channel=0x7f714b2b35c0 <xmlGenericErrorDefaultFunc>, data=0x7f7147c4a600 <_IO_2_1_stderr_>, ctx=0x0, nod=<optimized out>, domain=9, code=2003, level=XML_ERR_ERROR, file=<optimized out>, line=0, str1=<optimized out>, str2=<optimized out>, str3=<optimized out>, int1=0, col=0, msg=<optimized out>) at ../error.c:636 #12 0x00007f714b2b54f7 in __xmlSimpleError (domain=<optimized out>, code=<optimized out>, node=node@entry=0x0, msg=<optimized out>, extra=extra@entry=0x7f714b3a0b1e "Syntax Error\n") at ../error.c:657 #13 0x00007f714b2e1419 in __xmlIOErr (domain=domain@entry=9, code=code@entry=2003, extra=extra@entry=0x7f714b3a0b1e "Syntax Error\n") at ../xmlIO.c:413 #14 0x00007f714b3204e6 in xmlNanoFTPScanProxy__internal_alias (URL=<optimized out>) at ../nanoftp.c:441 #15 xmlNanoFTPScanProxy__internal_alias (URL=<optimized out>) at ../nanoftp.c:419 #16 0x00007f714b32055d in xmlNanoFTPInit__internal_alias () at ../nanoftp.c:204 [...] -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- The message happens because there is a FTP_PROXY env variable starting with `http://`, and this string is not understood by embedded nanoftp.c handler. For some reason the code wants the string to start with `ftp://`: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- 418 void 419 xmlNanoFTPScanProxy(const char *URL) { : 438 uri = xmlParseURIRaw(URL, 1); 439 if ((uri == NULL) || (uri->scheme == NULL) || 440 (strcmp(uri->scheme, "ftp")) || (uri->server == NULL)) { <----- HERE check against "ftp" 441 __xmlIOErr(XML_FROM_FTP, XML_FTP_URL_SYNTAX, "Syntax Error\n"); 442 if (uri != NULL) 443 xmlFreeURI(uri); 444 return; 445 } : -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- This ends up reporting an error, but there is some oddity: on frame 13, we have "code == 2003" (XML_FTP_URL_SYNTAX error): -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- (gdb) up #13 0x00007f714b2e1419 in __xmlIOErr (domain=domain@entry=9, code=code@entry=2003, extra=extra@entry=0x7f714b3a0b1e "Syntax Error\n") at ../xmlIO.c:413 413 __xmlSimpleError(domain, code, NULL, IOerr[idx], extra); (gdb) p code $27 = 2003 -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- But then in inner frame 12m the "code" automagically changed into 2 (XML_ERR_NO_MEMORY error): -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- (gdb) down #12 0x00007f714b2b54f7 in __xmlSimpleError (domain=<optimized out>, code=<optimized out>, node=node@entry=0x0, msg=<optimized out>, extra=extra@entry=0x7f714b3a0b1e "Syntax Error\n") at ../error.c:657 657 __xmlRaiseError(NULL, NULL, NULL, NULL, node, domain, (gdb) list 652 const char *msg, const char *extra) 653 { 654 655 if (code == XML_ERR_NO_MEMORY) { 656 if (extra) 657 __xmlRaiseError(NULL, NULL, NULL, NULL, node, domain, 658 XML_ERR_NO_MEMORY, XML_ERR_FATAL, NULL, 0, extra, 659 NULL, NULL, 0, 0, 660 "Memory allocation failed : %s\n", extra); 661 else -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- Assembly code shows "code" is supposed to be in $esi (2nd argument) and is compared against 2 (no memory error): -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- (gdb) disassemble /m Dump of assembler code for function __xmlSimpleError: 653 { 0x00007f714b2b54b0 <+0>: endbr64 654 655 if (code == XML_ERR_NO_MEMORY) { 0x00007f714b2b54b4 <+4>: sub $0x8,%rsp 0x00007f714b2b54b8 <+8>: mov %edi,%r9d 0x00007f714b2b54bb <+11>: cmp $0x2,%esi : -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- In upper frame, we can see at some point in time "code" is indeed stored in $esi: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- (gdb) up #13 0x00007f714b2e1419 in __xmlIOErr (domain=domain@entry=9, code=code@entry=2003, extra=extra@entry=0x7f714b3a0b1e "Syntax Error\n") at ../xmlIO.c:413 413 __xmlSimpleError(domain, code, NULL, IOerr[idx], extra); (gdb) disassemble /m Dump of assembler code for function __xmlIOErr: 247 { : 410 if (code >= XML_IO_UNKNOWN) idx = code - XML_IO_UNKNOWN; 0x00007f714b2e1420 <+64>: lea 0xb57e1(%rip),%rcx # 0x7f714b396c08 0x00007f714b2e1427 <+71>: cmp $0x5db,%esi <------------ HERE 0x00007f714b2e142d <+77>: jle 0x7f714b2e140a <__xmlIOErr+42> 0x00007f714b2e142f <+79>: lea -0x5dc(%rsi),%eax -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- But then the compiler optimized the next instruction (the "if") and in this optimized code, $esi gets changed: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- 411 if (idx >= (sizeof(IOerr) / sizeof(IOerr[0]))) idx = 0; 0x00007f714b2e1435 <+85>: cmp $0x38,%eax 0x00007f714b2e1438 <+88>: jg 0x7f714b2e140a <__xmlIOErr+42> 0x00007f714b2e143a <+90>: lea 0x2fa6df(%rip),%rdx # 0x7f714b5dbb20 <IOerr> 0x00007f714b2e1441 <+97>: mov (%rdx,%rax,8),%rcx 0x00007f714b2e1445 <+101>: jmp 0x7f714b2e140a <__xmlIOErr+42> 0x00007f714b2e1447 <+103>: nopw 0x0(%rax,%rax,1) : lots of changes of $esi through "mov" statements 0x00007f714b2e196e <+1422>: jmpq 0x7f714b2e140a <__xmlIOErr+42> 0x00007f714b2e1973 <+1427>: lea 0xb53df(%rip),%rcx # 0x7f714b396d59 0x00007f714b2e197a <+1434>: mov $0x5ef,%esi 0x00007f714b2e197f <+1439>: jmpq 0x7f714b2e140a <__xmlIOErr+42> 0x00007f714b2e1984 <+0>: data16 nopw %cs:0x0(%rax,%rax,1) 0x00007f714b2e198f <+11>: nop 412 413 __xmlSimpleError(domain, code, NULL, IOerr[idx], extra); 0x00007f714b2e140a <+42>: add $0x10,%rsp 0x00007f714b2e140e <+46>: mov %rbx,%r8 0x00007f714b2e1411 <+49>: xor %edx,%edx 0x00007f714b2e1413 <+51>: pop %rbx 0x00007f714b2e1414 <+52>: jmpq 0x7f714b2ad800 <__xmlSimpleError@plt> => 0x00007f714b2e1419 <+57>: nopl 0x0(%rax) -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- So clearly something is weird with that code. The good news is it's super easy to reproduce: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- [root@vm-rhel8 ~]# export FTP_PROXY=http://8.8.8.8:3128 [root@vm-rhel8 ~]# oscap xccdf eval --rule xccdf_org.ssgproject.content_rule_xwindows_runlevel_target --profile xccdf_org.ssgproject.content_profile_stig /usr/share/xml/scap/ssg/content/ssg-rhel8-ds.xml error : Unknown IO error [...] --- Starting Evaluation --- Title Disable X Windows Startup By Setting Default Target Rule xccdf_org.ssgproject.content_rule_xwindows_runlevel_target Ident CCE-83380-6 Result pass -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------