Notice
Recent Posts
관리 메뉴

Hacking Arts

xinetd실행시 printf가 늦게 출력되는 경우 본문

Trouble Shooting/Linux

xinetd실행시 printf가 늦게 출력되는 경우

Rakehell 2015. 12. 28. 20:56

출처 : http://www.hackerschool.org/HS_Boards/view.php?id=QNA_linux&no=4218

질문:


fedora13에서 서버 9999 포트로 접근을 하면 New Start라는 문자열을 돌려주고 문자열을 입력하면 그대로 다시 돌려주는 프로그램을 짜려고 합니다.

프로그램 소스 
int main(){
char a[100];
printf("New Start");
scanf("%s", a);
printf("%s", a);
}

서비스 설정

service back
{
  socket_type = stream
  wait = no
  user = root
  server = /home/guest/back
  disable = no
}

그런데 telnet localhost 9999로 접근해보니
먼저 입력을 받고 (scanf) 다음에 printf 2개가 같이 출력이 되더군요 (printf("New Start%s", a))
왜 printf가 나중에 출력되나요?


정확한 printf의 출력 시점을 파악하기 위해 로컬 디버깅에 나섰습니다.
0x080484b1 <+29>: call 0x80483ac <printf@plt>
여기서 nexti해봐도 출력을 안하고
0x80484c6 <main+50>: call 0x80483cc <__isoc99_scanf@plt>
여기서 nexti해야 출력하길래

(gdb) si 를 통해내부로 들어가보았습니다.
0x17cc04 <__isoc99_scanf+132>: call 0x1753d0 <_IO_vfscanf>
안에서 요런 함수를 호출하고
0x179b85 <_IO_vfscanf+18357>: call 0x197c60 <__uflow>
그 안에선 또 요런함수를 호출하고
(gdb) si
0x00197cc5 in __uflow () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x197cc5 <__uflow+101>: call *0x14(%eax)
여기서 또 어디를 호출하는데..
(gdb) 
New Start
내부에 출력루틴이 포함되어있네요. 다시 이곳에 bp걸고 실행하면
Breakpoint 5, 0x00197cc5 in __uflow () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x197cc5 <__uflow+101>: call *0x14(%eax)
(gdb) si
0x00196880 in _IO_default_uflow () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x196880 <_IO_default_uflow>: push %ebp

_IO_default_uflow 함수에서 _IO_file_underflow함수로 들어가고
0x00196898 in _IO_default_uflow () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x196898 <_IO_default_uflow+24>: call *0x10(%eax)
(gdb) si
0x00194ed0 in _IO_file_underflow () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x194ed0 <_IO_file_underflow>: push %ebp
저기서 콜하면 다시 출력되는거 확인성공
0x00194f86 in _IO_file_underflow () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x194f86 <_IO_file_underflow+182>: call *0xc(%eax)
(gdb) 
New Start

다시 재실행후 들어가봤더니 오버플로우 함수도 계십니다
Breakpoint 9, 0x00194f86 in _IO_file_underflow () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x194f86 <_IO_file_underflow+182>: call *0xc(%eax)
(gdb) si
0x00195730 in _IO_file_overflow () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x195730 <_IO_file_overflow>: push %ebp
다시 여기서 출력하는것같네요
0x00195818 in _IO_file_overflow () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x195818 <_IO_file_overflow+232>: call 0x194d10 <_IO_do_write>
(gdb) 
New Start


이제 잘생긴 _IO_do_write 함수를 찬찬히 살펴봅시다
Breakpoint 10, 0x00194d10 in _IO_do_write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x194d10 <_IO_do_write>: push %ebp
(gdb) ni

하다가 출력도 안하고 _IO_file_overflow로 나가길래
nexti하다가 _IO_file_xsputn+107에서 컨티뉴 했더니 다시 들어오네요
=> 0x194b6b <_IO_file_xsputn+107>: je 0x194cc8 <_IO_file_xsputn+456>
(gdb) c
Continuing.

Breakpoint 10, 0x00194d10 in _IO_do_write () from /lib/tls/i686/cmov/libc.so.6

0x00194d31 in _IO_do_write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x194d31 <_IO_do_write+33>: call 0x1949d0
(gdb) 
New Start
되게 깁니다 일단 여기서 출력하는거 다시확인했고여

다시 bp 걸고 재실행하고 들어가보니 심볼명이 없는 함수(?)가 나타났습니다.
Breakpoint 11, 0x00194d31 in _IO_do_write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x194d31 <_IO_do_write+33>: call 0x1949d0
(gdb) si
0x001949d0 in ?? () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x1949d0: push %ebp

여기서 또출력확인했습니다.
0x00194a1c in ?? () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x194a1c: call *0x3c(%eax)
(gdb) 
New Start

이름없는 함수를 지나 재실행후 만난 함수는 놀랍게도 라이브러리 함수 _IO_file_write
Breakpoint 12, 0x00194a1c in ?? () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x194a1c: call *0x3c(%eax)
(gdb) si
0x00194d50 in _IO_file_write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x194d50 <_IO_file_write>: push %ebp
따라가다보니 전설의write함수를 만났습니다.
0x00194d8f in _IO_file_write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x194d8f <_IO_file_write+63>: call 0x1ebda0 <write>
(gdb) 
New Start

이제 요함수는 전부 보여드리겠습니다.
Breakpoint 14, 0x001ebda0 in write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x1ebda0 <write>: cmpl $0x0,%gs:0xc
(gdb) si
0x001ebda8 in write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x1ebda8 <write+8>: jne 0x1ebdcc <write+44>
(gdb) 
0x001ebdaa in write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x1ebdaa <write+10>: push %ebx
(gdb) 
0x001ebdab in write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x1ebdab <write+11>: mov 0x10(%esp),%edx
(gdb) 
0x001ebdaf in write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x1ebdaf <write+15>: mov 0xc(%esp),%ecx
(gdb) 
0x001ebdb3 in write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x1ebdb3 <write+19>: mov 0x8(%esp),%ebx
(gdb) 
0x001ebdb7 in write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x1ebdb7 <write+23>: mov $0x4,%eax
(gdb) 
0x001ebdbc in write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x1ebdbc <write+28>: call *%gs:0x10
(gdb) 
0x0012d420 in __kernel_vsyscall ()
1: x/i $pc
=> 0x12d420 <__kernel_vsyscall>: int $0x80
(gdb) 
New Start0x0012d422 in __kernel_vsyscall ()
1: x/i $pc
=> 0x12d422 <__kernel_vsyscall+2>: ret 

커널 vsyscall 결과 New Start가 출력됩니다. 따라서 출력결과보기 직전부터 디버깅하려면
이곳(0x1ebdbc <write+28>: call *%gs:0x10)에 break를 거는게 타당한것같습니다.

다시 그럼 저곳에 브레이크를 걸고 원격에서 실행한것을 디버깅해보겠습니다.
root@hex-ubuntu:/# gdb -p 17877
GNU gdb (GDB) 7.1-ubuntu
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "i486-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 17877
Reading symbols from /usr/sbin/xinetd...(no debugging symbols found)...done.
Reading symbols from /lib/ld-linux.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/ld-linux.so.2
0x00d70422 in __kernel_vsyscall ()
(gdb) b *main
Breakpoint 1 at 0x237180
(gdb) set follow-g
Display all 199 possibilities? (y or n)
(gdb) set follow-
follow-exec-mode follow-fork-mode 
기본세팅이 자식을 끊는거라 자식놈을 잡아주게 바꿔주고
(gdb) set follow-fork-mode child
(gdb) c
Continuing.
다른창에서 # telnet localhost 6666 해주고
[New process 18466]
process 18466 is executing new program: /a
[Switching to process 18466]
아까 그주소로 bp를 걸었는데요
Breakpoint 1, 0x08048494 in main ()
(gdb) b *0x1ebdbc
Breakpoint 2 at 0x1ebdbc
(gdb) disp/i $pc
1: x/i $pc
=> 0x8048494 <main>: push %ebp
(gdb) c
Continuing.
Warning:
Cannot insert breakpoint 2.
Error accessing memory address 0x1ebdbc: Input/output error.
알수없는 주소랍니다. 이유를 보아하니
0x08048495 in main ()
1: x/i $pc
=> 0x8048495 <main+1>: mov %esp,%ebp
(gdb) x/i 0x1ebdbc
0x1ebdbc: Cannot access memory at address 0x1ebdbc
(gdb) delete breakpoints 2
접근할수없는 주소라카네요.
라이브러리영역도 ASLR style이 걸린환경에서 하다보니 그런가봅니다.
상대주소로 줘봅시다.
(gdb) b *write+28
Breakpoint 3 at 0xc1adbc
(gdb) c
Continuing.
아래와 같이 컨티뉴후 클라이언트측에서 입력을해주니까 그제서야 브레이크포인터에 걸립니다.
요현상은 일단 로컬과 다른 순서로 함수가 호출된것같다는 것이 유력합니다.
확신하는건 telnet을 쓰던 nc를 쓰던 같은현상이 일어나니 클라이언트쪽의 문제는 아닙니다.
일단 scanf가 수행된것이 확실한지 데몬이 자체적으로 차일드 프로세스 실행시 라이브러리함수 호출순서를 수정한지 확인해봅시다.
Breakpoint 3, 0x00c1adbc in write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0xc1adbc <write+28>: call *%gs:0x10
(gdb) ni
0x00171420 in ?? ()
1: x/i $pc
=> 0x171420: int $0x80
write에서 ni를 해주면 나오는 함수가 있는데요 리모트 환경에선 __kernel_vsyscall이 아닌 ??로 나오는 차이가보입니다.
우선 유력한점을 증명하기 위해 위 인터럽트 루틴에 브레이크를 걸경우를 로컬과 비교해보겟습니다.

먼저 로컬에서 저곳 인터럽트 루틴에 브레이크를 걸경우입니다.
우선 printf나 scanf 함수 실행전에 브레이크걸고 실행을 해야 __kernel_vsyscall이 존재하기때문에
(run 이전에는 저 주소에 접근할수없습니다.)
실행후
Breakpoint 1, 0x08048494 in main ()
(gdb) x/i *write+28
0x1ebdbc <write+28>: call *%gs:0x10
(gdb) b *write+28
Breakpoint 2 at 0x1ebdbc
(gdb) c
Continuing.
주소확인후 브레이크 그리고 실행하였습니다.
Breakpoint 2, 0x001ebdbc in write () from /lib/tls/i686/cmov/libc.so.6
(gdb) si
0x0012d420 in __kernel_vsyscall ()
(gdb) disp/i $pc
1: x/i $pc
=> 0x12d420 <__kernel_vsyscall>: int $0x80
single instruction(한명령어)을 수행하면 __kernel_vsyscal루틴의 주소를 알수있습니다.
(리모트에선 자식프로세스로 fork되서인지 단순히 xinetd데몬이 저렇게 만든건지 몰라도 저 함수 정보가 없기때문에 주소를 미리 알수없기때문에 같은 가정을 두고 하는겁니다.)
그곳에 브레이크 걸고 계속 컨티뉴해보겠습니다.
(gdb) b *0x12d420
Breakpoint 3 at 0x12d420
(gdb) c
Continuing.
역시 로컬에선 첫번째로 printf문의 출력이 끝났습니다.
New Start
Breakpoint 3, 0x0012d420 in __kernel_vsyscall ()
1: x/i $pc
=> 0x12d420 <__kernel_vsyscall>: int $0x80
(gdb) c
Continuing.
ee (ee를 입력해준 겁니다.)
두번째는 scanf 입력받는데 쓰였네요. 소스코드대로 올바른 순서입니다.
Breakpoint 2, 0x001ebdbc in write () from /lib/tls/i686/cmov/libc.so.6
1: x/i $pc
=> 0x1ebdbc <write+28>: call *%gs:0x10
(gdb) c
Continuing.
write break 건게 남아있습니다. 계속 넘기면
Breakpoint 3, 0x0012d420 in __kernel_vsyscall ()
1: x/i $pc
=> 0x12d420 <__kernel_vsyscall>: int $0x80
(gdb) c
Continuing.
ee (입력해준 ee가 출력되었습니다. 3번째 printf의 출력이 끝났습니다.)
Breakpoint 3, 0x0012d420 in __kernel_vsyscall ()
1: x/i $pc
=> 0x12d420 <__kernel_vsyscall>: int $0x80
(gdb) ni
다음시스템콜은 뭔가했더니
Program exited with code 02.
exit함수에서 끝내는 인터럽트 보내는건가봅니다.
이것으로 printf(내부함수 : write), scanf(내부함수 : ??), printf(내부함수 write), exit(추정)
총 4번 __kernel_vsyscall이 호출되었습니다.
이제 리모트를 볼차례인데요
scanf 없이 printf만 있는얘 데몬 하나 더 만들어서 돌릴려고 xinetd를 리스타트 해서 아까와 pid가 좀 다릅니다.
#ps 로 pid를 재확인 해준뒤 attach합시다.
root@hex-ubuntu:/# gdb -q -p 18991 
Attaching to process 18991
Reading symbols from /usr/sbin/xinetd...(no debugging symbols found)...done.
Reading symbols from /lib/ld-linux.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/ld-linux.so.2
0x004a2422 in __kernel_vsyscall ()
(gdb) b *main
Breakpoint 1 at 0x54f180
(gdb) set follow-fork-mode child
(gdb) c
Continuing.
[New process 19152]
process 19152 is executing new program: /a
[Switching to process 19152]
군말없이 아까 한과정에다가 write에 브레이크 걸고 주소를 확인합시다.
__kernel_vsyscal찾으면 심볼 낫 파운드로 찾을수 없다 뜨니까 여기에 걸어야합니다.
Breakpoint 1, 0x08048494 in main ()
(gdb) b *write+28
Breakpoint 2 at 0x53fdbc
(gdb) c
Continuing.
컨티뉴한결과 이대로 멈춰있길래 클라이언트 측에서(이제 nc를 사용합니다.) 아무값을 입력해줬습니다.
root@hex-ubuntu:/etc/xinetd.d# nc localhost 6666
dkanrjsk
(커서위치)
다시 디버깅하는곳으로 넘어가서 보면 브레이크가 걸려있습니다.
scanf 는 지났고 write함수인것으로 보아 printf가 틀림없습니다.
Breakpoint 2, 0x0053fdbc in write () from /lib/tls/i686/cmov/libc.so.6
(gdb) disp/i $pc
1: x/i $pc
=> 0x53fdbc <write+28>: call *%gs:0x10
(gdb) si
0x007e3420 in ?? ()
1: x/i $pc
=> 0x7e3420: int $0x80
인터럽트직전에 bp걸고 이제 계속 해보겠습니다.
(gdb) b *0x7e3420
Breakpoint 3 at 0x7e3420
(gdb) si
0x007e3422 in ?? ()
1: x/i $pc
=> 0x7e3422: ret
클라이언트측에서 놀랍게도 아까 커서 위치에서 New Startdkanrjsk이 한꺼번에 출력되었습니다.
(gdb) c
Continuing.
다시 컨티뉴하면 scanf, printfx2(write) 이순서로 처리해왔으니 마지막으로 남은건 exit뿐인것같습니다.
Breakpoint 3, 0x007e3420 in ?? ()
1: x/i $pc
=> 0x7e3420: int $0x80
(gdb) c
Continuing.
예상대로 한번더 브레이크 걸립니다.
Breakpoint 3, 0x007e3420 in ?? ()
1: x/i $pc
=> 0x7e3420: int $0x80
(gdb) si
exit code가 10번인게 좀 이상하지만 잘종료되었습니다.
Program exited with code 010.

이번엔 printf 한줄만있는 프로그램을 실행해보겠습니다.
# nc localhost 7777
Breakpoint 1, 0x080483e4 in main ()
(gdb) b *write+28
Breakpoint 2 at 0x403dbc
(gdb) c
Continuing.

Breakpoint 2, 0x00403dbc in write () from /lib/tls/i686/cmov/libc.so.6
(gdb) disp/i $pc
1: x/i $pc
=> 0x403dbc <write+28>: call *%gs:0x10
(gdb) si
0x00db2420 in ?? ()
1: x/i $pc
=> 0xdb2420: int $0x80
(gdb) b *0xdb2420
Breakpoint 3 at 0xdb2420
(gdb) si
여기서 출력결과는 다음과 같습니다.
# nc localhost 7777
b
브레이크 걸린상태에서도 제가 아무거나 입력해주면
# nc localhost 7777
b
dd
e
e
ee

ee

ee

r
계속해서 입력을 받습니다. 그냥 클라이언트측에서 제한없이 메세지를 보낼수있는거네요.

서버측에서 그걸 받던말던 상관없는것같습니다. sleep(5) 한줄만 있는 프로그램에 접속하면 계속해서 5초간 아무거나 입력하고 엔터칠수있는걸 본다면요. 그냥 순서대로 넘겨준 인자를 프로그램에서 알

아서 가져오는 구조인것같습니다. 다가져오면 printf 함수를 호출하고여.
0x00db2422 in ?? ()
1: x/i $pc
=> 0xdb2422: ret 
(gdb) c
Continuing.

Breakpoint 3, 0x00db2420 in ?? ()
1: x/i $pc
=> 0xdb2420: int $0x80
(gdb) si
exit 호출후 종료코드는 이번엔 2번입니다.
Program exited with code 02.

(gdb) q

결론 : scanf가 먼저 실행됩니당, 심지어 printf가 생성자에 있고 소멸자에서 scanf받아줘도 마찬가지로 생성자의 printf가 나중에 호출됩니다.
호출되는 printf는 묶어서 한번에 인터럽트됩니당. scanf함수가 없는경우 입력을 받진않고 출력만 합니당. 하지만 sleep 함수가 돌때도 입력을 잘 받는걸로 보아
클라이언트쪽에서 서버프로그램이 종료되기전까지 제한없이 계속 데이터를 써서 보낼수는 있는것같습니다. scanf 함수가 보낸 인자를 받아오는 순서는 보낸 순서와 동일합니다.
따라서 xinetd 데몬대신 독립적으로 실행되는 Standalone 환경의 서비스 데몬을 쓰시면됩니다.
send 함수쓰세요. 두번쓰세요.
2012/10/14 
attainer감사합니다2012/10/14 
attainersetvbuf를 이용하여 해결했습니다. 같은 문제 있는 분들 참고하세요