[리눅스커널] 디버깅: 커널 로그 레벨(/proc/sys/kernel/printk)을 누가 설정하나?

Background

 

부팅 도중에는 '/proc/sys/kernel/printk' 파일이 다음과 같았다가,

 

austin:/ $ cat /proc/sys/kernel/printk

6       6       1       7

 

 

부팅이 끝난 후 '/proc/sys/kernel/printk' 파일이 다음과 같이 바뀝니다.

 

austin:/ $ cat /proc/sys/kernel/printk

7       6       1       7

 

 

부팅 과정에서 어딘가 rc 파일에서 다음 명령어로  '/proc/sys/kernel/printk'을 바꾸는 것 같다는 생각이 듭니다.

 

echo "7 6 1 7" > /proc/sys/kernel/printk

 

분석

 

리눅스 시스템을 구동하기 위해 설정되는 정보는 '/proc/sys/kernel' 폴더에서 확인할 수 있습니다.

이번에는 커널 로그 레벨을 저장하는 '/proc/sys/kernel/printk' 파일을 커널의 어느 함수가 변경하는지 확인해보겠습니다.

 

먼저, '/proc/sys/kernel/printk' 파일에 어떤 값을 쓸 때 호출되는 __do_proc_dointvec() 함수에 패치 코드를 추가하겠습니다.

 

diff --git a/kernel/sysctl.c b/kernel/sysctl.c

index 865152d..423bcc9 100644

--- a/kernel/sysctl.c

+++ b/kernel/sysctl.c

@@ -2440,6 +2440,7 @@ static int do_proc_douintvec_conv(unsigned long *lvalp,

 

 static const char proc_wspace_sep[] = { ' ', '\t', '\n' };

 

+static printk_debug_state = 1;

 static int __do_proc_dointvec(void *tbl_data, struct ctl_table *table,

                  int write, void __user *buffer,

                  size_t *lenp, loff_t *ppos,

@@ -2456,6 +2457,19 @@ static int __do_proc_dointvec(void *tbl_data, struct ctl_table *table,

                return 0;

        }

 

+       if (printk_debug_state) {

+               int debug_state;

+

+               if(table->procname) {

+                       pr_emerg("======= sys_name: %s ======\n", table->procname);

+

+                       debug_state = !strcmp(table->procname, "printk");

+                       if ( debug_state ) {

+                               BUG();

+                       }

+               }

+       }

+

        i = (int *) tbl_data;

        vleft = table->maxlen / sizeof(*i);

        left = *lenp;

 

패치 코드의 목적은 간단합니다. printk란 속성 정보를 저장할 때 커널 크래시를 유발하는 코드입니다.

 

콜 스택은 다음과 같은데 프로세스의 이름은 'rpi_printk.sh' 입니다.

 

-000|el1_dbg(asm)

 -->|exception

-001|proc_first_pos_non_zero_ignore(inline)

-001|__do_proc_dointvec(tbl_data = 0xFFFFFFAAEC104790, table = 0xFFFFFFE1701BB000, write = 1, buffer = 0x00000074CC40B0A8, lenp = 0xFFF

-002|proc_dointvec(table = 0xFFFFFFE1701BB000, ?, ?, ?, ?)

-003|proc_sys_call_handler(?, buf = 0x00000074CC40B0A8, count = 8, ppos = 0xFFFFFF80168C3E00, write = 1)

-004|proc_sys_write(?, ?, ?, ?)

-005|__vfs_write(file = 0xFFFFFFE1C12D7A00, p = 0x00000074CC40B0A8, count = 8, pos = 0xFFFFFF80168C3E00)

-006|vfs_write(file = 0xFFFFFFE1C12D7A00, buf = 0x00000074CC40B0A8, count = 8, pos = 0xFFFFFF80168C3E00)

-007|ksys_write(?, buf = 0x00000074CC40B0A8, count = 8)

-008|__se_sys_write(inline)

-008|__arm64_sys_write(regs = 0xFFFFFF80168C3EC0)

-009|el0_svc_common(regs = 0xFFFFFF80168C3EC0, scno = 64, sc_nr = 294, syscall_table = 0xFFFFFFAAEB400798)

-010|el0_svc_handler(regs = 0xFFFFFF80168C3EC0)

-011|el0_svc(asm)

 -->|exception

-012|NUX:0x74CCB74AF8(asm)

-013|c_print(?)

-014|call_builtin(inline)

-014|comexec()

-015|execute(t = 0x00000074CC44F5C8, flags = 0, xerrok = 0x0000007FDF1CC384)

-016|execute(t = 0x00000074CC44F588, flags = 0, xerrok = 0x0000007FDF1CC384)

-017|shell(s = 0x00000074CC438008, level = 0)

-018|main(?, ?)

-019|NUX:0x74CCB2089C(asm)

 ---|end of frame

 

 

__vfs_write() 함수 인자 'p = 0x00000074CC40B0A8'을 확인해봅시다. 0x00000074CC40B0A8 주소에 '6 6 1 7'이 있습니다.

 

________________address|________0________4________8________C_0123456789ABCDEF

   NSD:00000074CC40B0A0| CC40B1E0 00000074>20362036 0A372031 ..@.t...6 6 1 7.

   NSD:00000074CC40B0B0| 746E6169 6573753D 62656472 00006775 iant=userdebug..

 

부팅 과정에서 호출되는 'rpi_printk.sh' 코드를 확인하니 다음과 같은 코드가 확인됩니다.

 

       echo "6 6 1 7" > /proc/sys/kernel/printk

 

이제 커널 로그로 '/proc/sys/kernel/printk' 파일로 로그 레벨을 설정하는 정보를 출력하는 패치를 작성해보겠습니다. 

 

diff --git a/kernel/sysctl.c b/kernel/sysctl.c

index f857650..09a946b 100644

--- a/kernel/sysctl.c

+++ b/kernel/sysctl.c

@@ -2219,6 +2219,7 @@ static int do_proc_douintvec_conv(unsigned long *lvalp,

 

 static const char proc_wspace_sep[] = { ' ', '\t', '\n' };

 

+static int printk_debug_state = 1;

 static int __do_proc_dointvec(void *tbl_data, struct ctl_table *table,

                  int write, void __user *buffer,

                  size_t *lenp, loff_t *ppos,

@@ -2235,6 +2236,26 @@ static int __do_proc_dointvec(void *tbl_data, struct ctl_table *table,

                return 0;

        }

 

+       if (printk_debug_state) {

+               int debug_state;

+

+               if(table->procname) {

+                       pr_emerg("[%s]sys_name: %s \n", current->comm, table->procname);

+

+                       debug_state = !strcmp(table->procname, "printk");

+                       if ( debug_state ) {

+                               char strbuffer[56] = {0,};

+

+                               strncpy_from_user(&strbuffer[0], buffer, sizeof(strbuffer) - 1);

+                               strbuffer[sizeof(strbuffer) - 1] = '\0';

+

+                               pr_emerg("======= sys_name: %s changed by %s ======\n", table->procname, current->comm);

+                               pr_emerg("config printk as [%s]\n", strbuffer);

+

+                       }

+               }

+       }

+

        i = (int *) tbl_data;

        vleft = table->maxlen / sizeof(*i);

        left = *lenp;

 

위 패치를 적용하고 라즈베리 파이에 적용하면 다음과 같은 커널 로그를 볼 수 있습니다.

 

[  408.741741 / 01-01 00:07:08.569][6] [rpi_printk.sh]sys_name: printk

[  408.748485 / 01-01 00:07:08.569][6] ======= sys_name: printk changed by rpi_printk.sh ======

[  408.757155 / 01-01 00:07:08.569][6] config printk as [6 6 1 7

[  408.757155 / 01-01 00:07:08.569][6] iant=userdebug]

...

[  450.014540 / 07-23 05:53:46.129][7] [rpi_printk.sh]sys_name: printk

[  450.021274 / 07-23 05:53:46.139][7] ======= sys_name: printk changed by rpi_printk.sh ======

 

 

Peace!