gabime / spdlog

Fast C++ logging library.
Other
24.35k stars 4.55k forks source link

Repeated logs #2926

Closed WorstCodeWay closed 10 months ago

WorstCodeWay commented 1 year ago

Hi, all. I meet a strange problem that my logs are repeated every line. Such like,

[I][VT][22240][2023/11/01 09:51:50:607] HttpServer 0.0.0.0_20003 started.
[I][VT][22240][2023/11/01 09:51:50:607] HttpServer 0.0.0.0_20003 started.
[I][VT][22240][2023/11/01 09:51:50:610] [TcpServers] Server(0.0.0.0:20007) started.
[I][VT][22240][2023/11/01 09:51:50:610] [TcpServers] Server(0.0.0.0:20007) started.
[I][VT][22240][2023/11/01 09:51:50:626] [TrackerLoader] Find tracker EndoScopeAlgoVt.
[I][VT][22240][2023/11/01 09:51:50:626] [TrackerLoader] Find tracker EndoScopeAlgoVt.

We may notice every line is repeated twice. This situation will come up sometime, not every time when starting my problem.

How could that happen? My suggest is whether it is about my program is start by another program, but former is stopped, from below,

:~/Documents/Tool$ sudo ps -aux | grep Vis
root     22167  0.1  0.0 891732  5060 ?        Ssl  09:38   0:01 /opt/VisTrack-Daemon/vt-daemon
root     22186  0.3  0.0      0     0 ?        Z    09:38   0:04 [Tool] <defunct>
root     22240  4.1  0.0      0     0 ?        Z    09:51   0:16 [Tool] <defunct>
seer     22289  0.0  0.0   7420   628 pts/0    S+   09:58   0:00 grep --color=auto Vis

We can know logs are from Tool, which is started by vt-daemon. However its dead? I don't know if it has some relationship with that problem? Or what else?

tt4g commented 1 year ago

Duplicate #2920 (daemon() calls fork())

See also: #2874

tt4g commented 1 year ago

https://github.com/gabime/spdlog/issues/2874#issuecomment-1788975363

spdlog works even if you use fork() (#865) However, calling an operation such as spdlog::shutdown(), which releases spdlog objects that exist in memory shared between processes, will make spdlog unusable by other processes. And it is not possible to call an operation that creates a thread before fork() due to the specification of fork(). spdlog::flush_every() must be called after fork() to work. See: #2309 (comment)

@tt4g Hi I'm redirected to here by your answer in my question, I want to know what the meaning of spdlog::flush_every() must be called after fork(). And in my situation, I have a parent process which has no spdlog included and it starts a subprocess by fork() like following:

int pid;
if(pid = fork())
{
   // parent
}
else
{
   // child
   int ret = execl("/opt/Tool-Dir/Tool", (char*)0);
}

So, should I call spdlog::flush_every() in parent process, even where spdlog library is not included? Or what should I do to solve my problem? #2926

Do not write questions on closed issues.

It is recommended that you go check the fork() specification first. And spdlog::flush_every() must be called after fork() because it creates a thread inside spdlog::flush_every(). If the thread is created before fork(), it may crash. It has nothing to do with this issue of yours of the same log message being output twice.

Regarding the usage of fork(), the return value of fork() is 0 in the child process and the parent process returns the PID of the child process. Your code is wrong and you should first learn how to use fork() and fix your source code.

pid_t pid = fork();
if(pid < 0)
{
  // Failed to fork.
}
else if (pid == 0) {
   // child process.
}
else
{
   // parend process.
}
WorstCodeWay commented 7 months ago

@tt4g @gabime Hi, I'm so sorry to bother you, and it's a long time passed since this problem was met. But now, I find something new, the repeated log are fromspdlog::sinks::stdout_color_sink_mt and spdlog::sinks::daily_file_format_sink_mt and they indeed have nothing about #2920 #2870, at least in my opinion.

Here are my original codes to create these two instances, they share same pattern format, and they will produce repeated messages like first time I met this problem:

auto stdSink = std::make_shared<spdlog::sinks:: stdout_color_sink_mt >();
auto fileSink = std::make_shared<spdlog::sinks:: daily_file_format_sink_mt >("%Y-%m-%d.log", 23, 59);
auto logger = std::make_shared<spdlog::logger> ("VT", stdSink);
logger->sinks.push_back(fileSink);
logger->set_pattern("[%L][%n][%t][%Y/%m/%d %H:%M:%S:%e] %v");

But now, I find new thing by adding different format(add 'Std' and 'File' respectively) to each sink like:

auto stdSink = std::make_shared<spdlog::sinks:: stdout_color_sink_mt >();
stdSink->set_pattern("[Std ][%L][%n][%t][%Y/%m/%d %H:%M:%S:%e] %v");
auto logger = std::make_shared<spdlog::logger> ("VT", stdSink);
auto fileSink = std::make_shared<spdlog::sinks:: daily_file_format_sink_mt >("%Y-%m-%d.log", 23, 59);
fileSink->set_pattern("[File][%L][%n][%t][%Y/%m/%d %H:%M:%S:%e] %v");
logger->sinks.push_back(fileSink);

this time, logs are different in very beginning of each log line, leaving the User defined logs the same.

But my question is why my logs will be output into log file twice while some of them should be in standard out? How can I fix it?

tt4g commented 7 months ago

@WorstCodeWay I have already answered that the use of fork() is wrong: https://github.com/gabime/spdlog/issues/2926#issuecomment-1789007848

WorstCodeWay commented 7 months ago

@WorstCodeWay I have already answered that the use of fork() is wrong: #2926 (comment)

@tt4g Sorry, I forget to mention that I have removed fork method, instead just calling system function to start up my program, and the problem is still there.

int i = system("/path/to/myprogram &");
tt4g commented 7 months ago

@WorstCodeWay If the source code is different from before, please open a new issue and provide the minimum source code that can reproduce the problem. Fragmentary information tells us nothing.