double print in log file

[xwings]

test case will be with netgear in example

with multithread = Faslse and contain fork

@ucgJhe will you be able to help ?

close(6) = 0
close(6) = 0
fcntl(4, 6) = 0
fcntl(4, 6) = 0
close(4) = 0
close(4) = 0

write(1,7fd71458,2173) = 0

write(1,7fd71458,2173) = 0
write(1,7fd71458,2173) = -1
write(1,7fd71458,2173) = -1
[!] SYSCALL ERROR: ql_syscall_write
[!] SYSCALL ERROR: ql_syscall_write
[!] SYSCALL ERROR: ql_syscall_execve
[!] SYSCALL ERROR: ql_syscall_execve

[ucgJhe]

can you provide the firmware you are using? I tried two different version and none of this happened

[xwings]

https://www.netgear.com/support/product/R6220.aspx

there you go

[ucgJhe]

Hi , did you use the latest firmware ?

just tried 1.1.0.92 hotfix and 1.1.0.86 both failed bcuz syscall_clone error, could not reproduced what u got

[xwings]

will you be able to drop me an email and i let you access to the private repo

[ucgJhe]

sure.

[ucgJhe]

@xwings pls check #90 should resolve both double logging in file and console issue

[xwings]

merged, thanks and i will try later.

[xwings]

new issue

(311)$ Traceback (most recent call last):
  File "netgear_6220_mips32el_linux.py", line 42, in <module>
    "rootfs/netgear_r6220")
  File "netgear_6220_mips32el_linux.py", line 33, in my_netgear
    ql.run()
  File "../qiling/core.py", line 210, in run
    runner(self)
  File "../qiling/os/linux/mips32el.py", line 289, in runner
    raise ql.internal_exception
  File "../qiling/core.py", line 23, in wrapper
    return func(*args, **kw)
  File "../qiling/core.py", line 278, in _callback
    callback(self, intno)
  File "../qiling/os/linux/mips32el.py", line 54, in hook_syscall
    LINUX_SYSCALL_FUNC(ql, param0, param1, param2, param3, param4, param5)
  File "../qiling/os/posix/syscall.py", line 866, in ql_syscall_write
    ql.file_des[write_fd].write(buf)
  File "../qiling/os/posix/filestruct.py", line 80, in write
    return os.write(self.__fd, write_buf)
BrokenPipeError: [Errno 32] Broken pipe
Traceback (most recent call last):
  File "netgear_6220_mips32el_linux.py", line 42, in <module>
    "rootfs/netgear_r6220")
  File "netgear_6220_mips32el_linux.py", line 33, in my_netgear
    ql.run()
  File "../qiling/core.py", line 210, in run
    runner(self)
  File "../qiling/os/linux/mips32el.py", line 289, in runner
    raise ql.internal_exception
  File "../qiling/core.py", line 23, in wrapper
    return func(*args, **kw)
  File "../qiling/core.py", line 278, in _callback
    callback(self, intno)
  File "../qiling/os/linux/mips32el.py", line 54, in hook_syscall
    LINUX_SYSCALL_FUNC(ql, param0, param1, param2, param3, param4, param5)
  File "../qiling/os/posix/syscall.py", line 1239, in ql_syscall_execve
    ql.run()
  File "../qiling/core.py", line 210, in run
    runner(self)
  File "../qiling/os/linux/mips32el.py", line 289, in runner
    raise ql.internal_exception
  File "../qiling/core.py", line 23, in wrapper
    return func(*args, **kw)
  File "../qiling/core.py", line 278, in _callback
    callback(self, intno)
  File "../qiling/os/linux/mips32el.py", line 54, in hook_syscall
    LINUX_SYSCALL_FUNC(ql, param0, param1, param2, param3, param4, param5)
  File "../qiling/os/posix/syscall.py", line 866, in ql_syscall_write
    ql.file_des[write_fd].write(buf)
  File "../qiling/os/posix/filestruct.py", line 148, in write
    return os.write(self.__fd, write_buf)
BrokenPipeError: [Errno 32] Broken pipe

[ucgJhe]

@xwings this doesn't look like a logging issue to me, any details ?

[xwings]

after merge your code run netgear, it shows this. i did not check yet.,

[xwings]

It was ok before fork()

fcntl64(4, 2, 1) = 0
setsockopt
bind(4,127.0.0.1:8080,16) = 0
[+] syscall bind host: 127.0.0.1 and port: 8080 sin_family: 2
listen(4, 1024) = 0
vfork() = 29791
[+] vfork(): is this a child process: True
exit(0) = 0
[+] is this a child process: False
 Traceback (most recent call last):
  File "netgear_6220_mips32el_linux.py", line 42, in <module>
    "rootfs/netgear_r6220")
  File "netgear_6220_mips32el_linux.py", line 33, in my_netgear
    ql.run()
  File "../qiling/core.py", line 210, in run
    runner(self)
  File "../qiling/os/linux/mips32el.py", line 289, in runner
    raise ql.internal_exception
  File "../qiling/core.py", line 23, in wrapper
    return func(*args, **kw)
  File "../qiling/core.py", line 278, in _callback
    callback(self, intno)
  File "../qiling/os/linux/mips32el.py", line 54, in hook_syscall
    LINUX_SYSCALL_FUNC(ql, param0, param1, param2, param3, param4, param5)
  File "../qiling/os/posix/syscall.py", line 866, in ql_syscall_write
    ql.file_des[write_fd].write(buf)
  File "../qiling/os/posix/filestruct.py", line 80, in write
    return os.write(self.__fd, write_buf)
BrokenPipeError: [Errno 32] Broken pipe
Traceback (most recent call last):
  File "netgear_6220_mips32el_linux.py", line 42, in <module>
    "rootfs/netgear_r6220")
  File "netgear_6220_mips32el_linux.py", line 33, in my_netgear
    ql.run()
  File "../qiling/core.py", line 210, in run
    runner(self)

[ucgJhe]

the log before last commit didn't log properly(only logging after vfork), but now its working correctly so I assume the error is not trigger by logging related function

and if you use curl 127.0.0.1:8080 wont trigger the error, but browser did thats odd

[xwings]

we still have this issue and lets see how can we fix this

[ucgJhe]

@xwings did you mean double print in log file ?

[xwings]

yes. after your fix it seems like we got another issue. we figure it out slowly without breaking things

[ucgJhe]

the code I submitted shouldn't trigger the broken pipe error, its doing nothing about ql_syscall_write.

[xwings]

after i revert back . only the part in syscall. the error went missing.

we need to figure out

[ucgJhe]

Cuz we create logger for each thread and loggers share one logger name, thats why double log in file. and I just split the name for different thread, that shouldn't change the syscall behavior I think.

[ucgJhe]

@xwings I think I got something about Broken pipe error, the firmware try to write to writer pipe for unknown reason even the paired reader pipe is closed.

[xwings]

i think is the fork issue, not too sure yet. need to dig more

[ucgJhe]

i found that if I prevent the writing to fd 2 when it refers to ql_pipe , everything will be just fine

[xwings]

cool, maybe we can do it for mips only ?

[ucgJhe]

I am not sure the root cause is the netgear firmware bug or the syscall behavior problem, so its more a workaround than a proper fix. thus do it in the netgear_6220_mips32el_linux.py may be more suitable ?

[xwings]

that works too. thanks !

[ucgJhe]

just pushed the code(#116) and if you want the debug logging working with log_split you may need to uncomment the code below https://github.com/qilingframework/qiling/blob/master/qiling/os/posix/syscall.py#L1177-L1182

[xwings]

i think we solved this