mirror of
https://github.com/SerenityOS/serenity
synced 2024-10-15 12:23:15 +00:00
Kernel: Tidy up debug logging a little bit
When using dbg() in the kernel, the output is automatically prefixed with [Process(PID:TID)]. This makes it a lot easier to understand which thread is generating the output. This patch also cleans up some common logging messages and removes the now-unnecessary "dbg() << *current << ..." pattern.
This commit is contained in:
parent
5dd5d5ca4e
commit
f38cfb3562
|
@ -24,10 +24,15 @@
|
||||||
* OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
|
* OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
|
||||||
*/
|
*/
|
||||||
|
|
||||||
#include <AK/String.h>
|
|
||||||
#include <AK/LogStream.h>
|
#include <AK/LogStream.h>
|
||||||
|
#include <AK/String.h>
|
||||||
#include <AK/StringView.h>
|
#include <AK/StringView.h>
|
||||||
|
|
||||||
|
#ifdef KERNEL
|
||||||
|
# include <Kernel/Process.h>
|
||||||
|
# include <Kernel/Thread.h>
|
||||||
|
#endif
|
||||||
|
|
||||||
namespace AK {
|
namespace AK {
|
||||||
|
|
||||||
const LogStream& operator<<(const LogStream& stream, const String& value)
|
const LogStream& operator<<(const LogStream& stream, const String& value)
|
||||||
|
@ -62,7 +67,7 @@ const LogStream& operator<<(const LogStream& stream, const void* value)
|
||||||
return stream << String::format("%p", value);
|
return stream << String::format("%p", value);
|
||||||
}
|
}
|
||||||
|
|
||||||
#if defined (__serenity__) && !defined(KERNEL)
|
#if defined(__serenity__) && !defined(KERNEL)
|
||||||
static TriState got_process_name = TriState::Unknown;
|
static TriState got_process_name = TriState::Unknown;
|
||||||
static char process_name_buffer[256];
|
static char process_name_buffer[256];
|
||||||
#endif
|
#endif
|
||||||
|
@ -70,7 +75,7 @@ static char process_name_buffer[256];
|
||||||
DebugLogStream dbg()
|
DebugLogStream dbg()
|
||||||
{
|
{
|
||||||
DebugLogStream stream;
|
DebugLogStream stream;
|
||||||
#if defined (__serenity__) && !defined(KERNEL)
|
#if defined(__serenity__) && !defined(KERNEL)
|
||||||
if (got_process_name == TriState::Unknown) {
|
if (got_process_name == TriState::Unknown) {
|
||||||
if (get_process_name(process_name_buffer, sizeof(process_name_buffer)) == 0)
|
if (get_process_name(process_name_buffer, sizeof(process_name_buffer)) == 0)
|
||||||
got_process_name = TriState::True;
|
got_process_name = TriState::True;
|
||||||
|
@ -79,6 +84,12 @@ DebugLogStream dbg()
|
||||||
}
|
}
|
||||||
if (got_process_name == TriState::True)
|
if (got_process_name == TriState::True)
|
||||||
stream << "\033[33;1m" << process_name_buffer << '(' << getpid() << ")\033[0m: ";
|
stream << "\033[33;1m" << process_name_buffer << '(' << getpid() << ")\033[0m: ";
|
||||||
|
#endif
|
||||||
|
#if defined(__serenity__) && defined(KERNEL)
|
||||||
|
if (current)
|
||||||
|
stream << "\033[34;1m[" << *current << "]\033[0m: ";
|
||||||
|
else
|
||||||
|
stream << "\033[36;1m[Kernel]\033[0m: ";
|
||||||
#endif
|
#endif
|
||||||
return stream;
|
return stream;
|
||||||
}
|
}
|
||||||
|
|
|
@ -123,9 +123,7 @@ KResultOr<Region*> BXVGADevice::mmap(Process& process, FileDescription&, Virtual
|
||||||
0,
|
0,
|
||||||
"BXVGA Framebuffer",
|
"BXVGA Framebuffer",
|
||||||
prot);
|
prot);
|
||||||
dbgprintf("BXVGA: %s(%u) created Region{%p} with size %u for framebuffer P%x with vaddr V%p\n",
|
dbg() << "BXVGADevice: mmap with size " << region->size() << " at " << region->vaddr();
|
||||||
process.name().characters(), process.pid(),
|
|
||||||
region, region->size(), m_framebuffer_address.as_ptr(), region->vaddr().get());
|
|
||||||
ASSERT(region);
|
ASSERT(region);
|
||||||
return region;
|
return region;
|
||||||
}
|
}
|
||||||
|
|
|
@ -62,9 +62,7 @@ KResultOr<Region*> MBVGADevice::mmap(Process& process, FileDescription&, Virtual
|
||||||
0,
|
0,
|
||||||
"MBVGA Framebuffer",
|
"MBVGA Framebuffer",
|
||||||
prot);
|
prot);
|
||||||
dbgprintf("MBVGA: %s(%u) created Region{%p} with size %u for framebuffer P%x with vaddr V%p\n",
|
dbg() << "MBVGADevice: mmap with size " << region->size() << " at " << region->vaddr();
|
||||||
process.name().characters(), process.pid(),
|
|
||||||
region, region->size(), m_framebuffer_address.as_ptr(), region->vaddr().get());
|
|
||||||
ASSERT(region);
|
ASSERT(region);
|
||||||
return region;
|
return region;
|
||||||
}
|
}
|
||||||
|
|
|
@ -728,38 +728,38 @@ KResult VFS::validate_path_against_process_veil(StringView path, int options)
|
||||||
|
|
||||||
auto* unveiled_path = find_matching_unveiled_path(path);
|
auto* unveiled_path = find_matching_unveiled_path(path);
|
||||||
if (!unveiled_path) {
|
if (!unveiled_path) {
|
||||||
dbg() << *current << " rejecting path '" << path << "' since it hasn't been unveiled.";
|
dbg() << "Rejecting path '" << path << "' since it hasn't been unveiled.";
|
||||||
return KResult(-ENOENT);
|
return KResult(-ENOENT);
|
||||||
}
|
}
|
||||||
|
|
||||||
if (options & O_CREAT) {
|
if (options & O_CREAT) {
|
||||||
if (!(unveiled_path->permissions & UnveiledPath::Access::CreateOrRemove)) {
|
if (!(unveiled_path->permissions & UnveiledPath::Access::CreateOrRemove)) {
|
||||||
dbg() << *current << " rejecting path '" << path << "' since it hasn't been unveiled with 'c' permission.";
|
dbg() << "Rejecting path '" << path << "' since it hasn't been unveiled with 'c' permission.";
|
||||||
return KResult(-EACCES);
|
return KResult(-EACCES);
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
if (options & O_UNLINK_INTERNAL) {
|
if (options & O_UNLINK_INTERNAL) {
|
||||||
if (!(unveiled_path->permissions & UnveiledPath::Access::CreateOrRemove)) {
|
if (!(unveiled_path->permissions & UnveiledPath::Access::CreateOrRemove)) {
|
||||||
dbg() << *current << " rejecting path '" << path << "' for unlink since it hasn't been unveiled with 'c' permission.";
|
dbg() << "Rejecting path '" << path << "' for unlink since it hasn't been unveiled with 'c' permission.";
|
||||||
return KResult(-EACCES);
|
return KResult(-EACCES);
|
||||||
}
|
}
|
||||||
return KSuccess;
|
return KSuccess;
|
||||||
}
|
}
|
||||||
if (options & O_RDONLY) {
|
if (options & O_RDONLY) {
|
||||||
if (!(unveiled_path->permissions & UnveiledPath::Access::Read)) {
|
if (!(unveiled_path->permissions & UnveiledPath::Access::Read)) {
|
||||||
dbg() << *current << " rejecting path '" << path << "' since it hasn't been unveiled with 'r' permission.";
|
dbg() << "Rejecting path '" << path << "' since it hasn't been unveiled with 'r' permission.";
|
||||||
return KResult(-EACCES);
|
return KResult(-EACCES);
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
if (options & O_WRONLY) {
|
if (options & O_WRONLY) {
|
||||||
if (!(unveiled_path->permissions & UnveiledPath::Access::Write)) {
|
if (!(unveiled_path->permissions & UnveiledPath::Access::Write)) {
|
||||||
dbg() << *current << " rejecting path '" << path << "' since it hasn't been unveiled with 'w' permission.";
|
dbg() << "Rejecting path '" << path << "' since it hasn't been unveiled with 'w' permission.";
|
||||||
return KResult(-EACCES);
|
return KResult(-EACCES);
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
if (options & O_EXEC) {
|
if (options & O_EXEC) {
|
||||||
if (!(unveiled_path->permissions & UnveiledPath::Access::Execute)) {
|
if (!(unveiled_path->permissions & UnveiledPath::Access::Execute)) {
|
||||||
dbg() << *current << " rejecting path '" << path << "' since it hasn't been unveiled with 'x' permission.";
|
dbg() << "Rejecting path '" << path << "' since it hasn't been unveiled with 'x' permission.";
|
||||||
return KResult(-EACCES);
|
return KResult(-EACCES);
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
|
@ -697,7 +697,7 @@ int Process::do_exec(NonnullRefPtr<FileDescription> main_program_description, Ve
|
||||||
{
|
{
|
||||||
ASSERT(is_ring3());
|
ASSERT(is_ring3());
|
||||||
auto path = main_program_description->absolute_path();
|
auto path = main_program_description->absolute_path();
|
||||||
dbgprintf("%s(%d) do_exec(%s): thread_count() = %d\n", m_name.characters(), m_pid, path.characters(), thread_count());
|
dbg() << "do_exec(" << path << ")";
|
||||||
// FIXME(Thread): Kill any threads the moment we commit to the exec().
|
// FIXME(Thread): Kill any threads the moment we commit to the exec().
|
||||||
if (thread_count() != 1) {
|
if (thread_count() != 1) {
|
||||||
dbgprintf("Gonna die because I have many threads! These are the threads:\n");
|
dbgprintf("Gonna die because I have many threads! These are the threads:\n");
|
||||||
|
@ -1251,7 +1251,7 @@ Process::Process(Thread*& first_thread, const String& name, uid_t uid, gid_t gid
|
||||||
, m_tty(tty)
|
, m_tty(tty)
|
||||||
, m_ppid(ppid)
|
, m_ppid(ppid)
|
||||||
{
|
{
|
||||||
dbgprintf("Process: New process PID=%u with name=%s\n", m_pid, m_name.characters());
|
dbg() << "Created new process " << m_name << "(" << m_pid << ")";
|
||||||
|
|
||||||
m_page_directory = PageDirectory::create_for_userspace(*this, fork_parent ? &fork_parent->page_directory().range_allocator() : nullptr);
|
m_page_directory = PageDirectory::create_for_userspace(*this, fork_parent ? &fork_parent->page_directory().range_allocator() : nullptr);
|
||||||
#ifdef MM_DEBUG
|
#ifdef MM_DEBUG
|
||||||
|
@ -1305,7 +1305,6 @@ Process::Process(Thread*& first_thread, const String& name, uid_t uid, gid_t gid
|
||||||
|
|
||||||
Process::~Process()
|
Process::~Process()
|
||||||
{
|
{
|
||||||
dbgprintf("~Process{%p} name=%s pid=%d, m_fds=%d, m_thread_count=%u\n", this, m_name.characters(), pid(), m_fds.size(), m_thread_count);
|
|
||||||
ASSERT(thread_count() == 0);
|
ASSERT(thread_count() == 0);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
@ -2269,7 +2268,7 @@ int Process::reap(Process& process)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
dbgprintf("reap: %s(%u)\n", process.name().characters(), process.pid());
|
dbg() << "Reaping process " << process;
|
||||||
ASSERT(process.is_dead());
|
ASSERT(process.is_dead());
|
||||||
g_processes->remove(&process);
|
g_processes->remove(&process);
|
||||||
}
|
}
|
||||||
|
@ -2280,7 +2279,7 @@ int Process::reap(Process& process)
|
||||||
pid_t Process::sys$waitpid(pid_t waitee, int* wstatus, int options)
|
pid_t Process::sys$waitpid(pid_t waitee, int* wstatus, int options)
|
||||||
{
|
{
|
||||||
REQUIRE_PROMISE(stdio);
|
REQUIRE_PROMISE(stdio);
|
||||||
dbgprintf("sys$waitpid(%d, %p, %d)\n", waitee, wstatus, options);
|
dbg() << "sys$waitpid(" << waitee << ", " << wstatus << ", " << options << ")";
|
||||||
|
|
||||||
if (!options) {
|
if (!options) {
|
||||||
// FIXME: This can't be right.. can it? Figure out how this should actually work.
|
// FIXME: This can't be right.. can it? Figure out how this should actually work.
|
||||||
|
@ -2712,7 +2711,7 @@ int Process::sys$select(const Syscall::SC_select_params* params)
|
||||||
for (int fd = 0; fd < nfds; ++fd) {
|
for (int fd = 0; fd < nfds; ++fd) {
|
||||||
if (FD_ISSET(fd, fds)) {
|
if (FD_ISSET(fd, fds)) {
|
||||||
if (!file_description(fd)) {
|
if (!file_description(fd)) {
|
||||||
dbg() << *current << " sys$select: Bad fd number " << fd;
|
dbg() << "sys$select: Bad fd number " << fd;
|
||||||
return -EBADF;
|
return -EBADF;
|
||||||
}
|
}
|
||||||
vector.append(fd);
|
vector.append(fd);
|
||||||
|
@ -2931,7 +2930,7 @@ int Process::sys$chown(const Syscall::SC_chown_params* user_params)
|
||||||
void Process::finalize()
|
void Process::finalize()
|
||||||
{
|
{
|
||||||
ASSERT(current == g_finalizer);
|
ASSERT(current == g_finalizer);
|
||||||
dbgprintf("Finalizing Process %s(%u)\n", m_name.characters(), m_pid);
|
dbg() << "Finalizing process " << *this;
|
||||||
|
|
||||||
m_fds.clear();
|
m_fds.clear();
|
||||||
m_tty = nullptr;
|
m_tty = nullptr;
|
||||||
|
|
|
@ -636,21 +636,21 @@ inline u32 Thread::effective_priority() const
|
||||||
return m_priority + m_process.priority_boost() + m_priority_boost + m_extra_priority;
|
return m_priority + m_process.priority_boost() + m_priority_boost + m_extra_priority;
|
||||||
}
|
}
|
||||||
|
|
||||||
#define REQUIRE_NO_PROMISES \
|
#define REQUIRE_NO_PROMISES \
|
||||||
do { \
|
do { \
|
||||||
if (current->process().has_promises()) { \
|
if (current->process().has_promises()) { \
|
||||||
dbg() << *current << " has made a promise"; \
|
dbg() << "Has made a promise"; \
|
||||||
cli(); \
|
cli(); \
|
||||||
current->process().crash(SIGABRT, 0); \
|
current->process().crash(SIGABRT, 0); \
|
||||||
ASSERT_NOT_REACHED(); \
|
ASSERT_NOT_REACHED(); \
|
||||||
} \
|
} \
|
||||||
} while (0)
|
} while (0)
|
||||||
|
|
||||||
#define REQUIRE_PROMISE(promise) \
|
#define REQUIRE_PROMISE(promise) \
|
||||||
do { \
|
do { \
|
||||||
if (current->process().has_promises() \
|
if (current->process().has_promises() \
|
||||||
&& !current->process().has_promised(Pledge::promise)) { \
|
&& !current->process().has_promised(Pledge::promise)) { \
|
||||||
dbg() << *current << " has not pledged " << #promise; \
|
dbg() << "Has not pledged " << #promise; \
|
||||||
cli(); \
|
cli(); \
|
||||||
current->process().crash(SIGABRT, 0); \
|
current->process().crash(SIGABRT, 0); \
|
||||||
ASSERT_NOT_REACHED(); \
|
ASSERT_NOT_REACHED(); \
|
||||||
|
|
|
@ -82,7 +82,7 @@ Thread::Thread(Process& process)
|
||||||
m_tid = Process::allocate_pid();
|
m_tid = Process::allocate_pid();
|
||||||
}
|
}
|
||||||
process.m_thread_count++;
|
process.m_thread_count++;
|
||||||
dbgprintf("Thread{%p}: New thread TID=%u in %s(%u)\n", this, m_tid, process.name().characters(), process.pid());
|
dbg() << "Created new thread " << process.name() << "(" << process.pid() << ":" << m_tid << ")";
|
||||||
set_default_signal_dispositions();
|
set_default_signal_dispositions();
|
||||||
m_fpu_state = (FPUState*)kmalloc_aligned(sizeof(FPUState), 16);
|
m_fpu_state = (FPUState*)kmalloc_aligned(sizeof(FPUState), 16);
|
||||||
memcpy(m_fpu_state, &s_clean_fpu_state, sizeof(FPUState));
|
memcpy(m_fpu_state, &s_clean_fpu_state, sizeof(FPUState));
|
||||||
|
@ -143,7 +143,6 @@ Thread::Thread(Process& process)
|
||||||
|
|
||||||
Thread::~Thread()
|
Thread::~Thread()
|
||||||
{
|
{
|
||||||
dbgprintf("~Thread{%p}\n", this);
|
|
||||||
kfree_aligned(m_fpu_state);
|
kfree_aligned(m_fpu_state);
|
||||||
{
|
{
|
||||||
InterruptDisabler disabler;
|
InterruptDisabler disabler;
|
||||||
|
@ -282,7 +281,7 @@ void Thread::finalize()
|
||||||
{
|
{
|
||||||
ASSERT(current == g_finalizer);
|
ASSERT(current == g_finalizer);
|
||||||
|
|
||||||
dbgprintf("Finalizing Thread %u in %s(%u)\n", tid(), m_process.name().characters(), pid());
|
dbg() << "Finalizing thread " << *this;
|
||||||
set_state(Thread::State::Dead);
|
set_state(Thread::State::Dead);
|
||||||
|
|
||||||
if (m_joiner) {
|
if (m_joiner) {
|
||||||
|
@ -308,7 +307,6 @@ void Thread::finalize_dying_threads()
|
||||||
return IterationDecision::Continue;
|
return IterationDecision::Continue;
|
||||||
});
|
});
|
||||||
}
|
}
|
||||||
dbgprintf("Finalizing %u dying threads\n", dying_threads.size());
|
|
||||||
for (auto* thread : dying_threads) {
|
for (auto* thread : dying_threads) {
|
||||||
auto& process = thread->process();
|
auto& process = thread->process();
|
||||||
thread->finalize();
|
thread->finalize();
|
||||||
|
@ -316,7 +314,6 @@ void Thread::finalize_dying_threads()
|
||||||
if (process.m_thread_count == 0)
|
if (process.m_thread_count == 0)
|
||||||
process.finalize();
|
process.finalize();
|
||||||
}
|
}
|
||||||
dbgprintf("Done\n");
|
|
||||||
}
|
}
|
||||||
|
|
||||||
bool Thread::tick()
|
bool Thread::tick()
|
||||||
|
|
|
@ -570,7 +570,7 @@ bool MemoryManager::validate_range(const Process& process, VirtualAddress base_v
|
||||||
VirtualAddress vaddr = base_vaddr.page_base();
|
VirtualAddress vaddr = base_vaddr.page_base();
|
||||||
VirtualAddress end_vaddr = base_vaddr.offset(size - 1).page_base();
|
VirtualAddress end_vaddr = base_vaddr.offset(size - 1).page_base();
|
||||||
if (end_vaddr < vaddr) {
|
if (end_vaddr < vaddr) {
|
||||||
dbg() << *current << " Shenanigans! Asked to validate " << base_vaddr << " size=" << size;
|
dbg() << "Shenanigans! Asked to validate " << base_vaddr << " size=" << size;
|
||||||
return false;
|
return false;
|
||||||
}
|
}
|
||||||
const Region* region = nullptr;
|
const Region* region = nullptr;
|
||||||
|
|
|
@ -444,7 +444,7 @@ PageFaultResponse Region::handle_inode_fault(size_t page_index_in_region)
|
||||||
cli();
|
cli();
|
||||||
|
|
||||||
#ifdef PAGE_FAULT_DEBUG
|
#ifdef PAGE_FAULT_DEBUG
|
||||||
dbg() << *current << " inode fault in " << name() << " page index: " << page_index_in_region;
|
dbg() << "Inode fault in " << name() << " page index: " << page_index_in_region;
|
||||||
#endif
|
#endif
|
||||||
|
|
||||||
if (!vmobject_physical_page_entry.is_null()) {
|
if (!vmobject_physical_page_entry.is_null()) {
|
||||||
|
|
Loading…
Reference in a new issue