Skip to content

Commit a7cf5c0

Browse files
matyhtfmatyhtf
authored
Optimize log format, fix tests (swoole#4311)
* Logger::get_pretty_name * fix tests * optimize error log * fix tests[2] * Added c-ares * Added c-ares * fix tests * fix tests[4] * Code reuse * fix tests[5] * fix core tests * fix core-tests [2]
1 parent 0e91dfc commit a7cf5c0

32 files changed

+258
-195
lines changed

‎core-tests/src/core/channel.cpp

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -43,7 +43,7 @@ TEST(channel, push) {
4343
bytes += n;
4444
}
4545

46-
swTrace("size=%d\n", m.size());
46+
swTrace("size=%lu", m.size());
4747

4848
thread t1([&]() {
4949
auto next = m.find(0);
@@ -52,7 +52,7 @@ TEST(channel, push) {
5252

5353
while (bytes < N) {
5454
if (c->push(next->second.c_str(), next->second.length()) == SW_OK) {
55-
swTrace("[PUSH] index=%d, size=%d\n", index, next->second.length());
55+
swTrace("[PUSH] index=%d, size=%lu", index, next->second.length());
5656
bytes += next->second.length();
5757
next = m.find(index++);
5858
if (next == m.end()) {
@@ -71,7 +71,7 @@ TEST(channel, push) {
7171
while (bytes < N) {
7272
int retval = c->pop(buf, sizeof(buf));
7373
if (retval > 0) {
74-
swTrace("[POP] index=%d, size=%ld\n", index, retval);
74+
swTrace("[POP] index=%d, size=%d", index, retval);
7575
string &_data = m[index++];
7676
bytes += retval;
7777
ASSERT_EQ(_data, string(buf, retval));

‎core-tests/src/core/log.cpp

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -119,3 +119,32 @@ TEST(log, redirect) {
119119

120120
ASSERT_TRUE(content->contains(SW_STRL("hello world\n")));
121121
}
122+
123+
namespace TestA {
124+
class TestPrettyName {
125+
public:
126+
static void fun(bool strip, const char *expect_str);
127+
};
128+
129+
void TestPrettyName::fun(bool strip, const char *expect_str) {
130+
ASSERT_STREQ(Logger::get_pretty_name(__PRETTY_FUNCTION__, strip).c_str(), expect_str);
131+
}
132+
133+
void test_pretty_name(bool strip, const char *expect_str) {
134+
ASSERT_STREQ(Logger::get_pretty_name(__PRETTY_FUNCTION__, strip).c_str(), expect_str);
135+
}
136+
} // namespace TestA
137+
138+
void test_pretty_name(bool strip, const char *expect_str) {
139+
ASSERT_STREQ(Logger::get_pretty_name(__PRETTY_FUNCTION__, strip).c_str(), expect_str);
140+
}
141+
142+
TEST(log, pretty_name) {
143+
TestA::TestPrettyName::fun(false, "TestA::TestPrettyName::fun");
144+
TestA::test_pretty_name(false, "TestA::test_pretty_name");
145+
test_pretty_name(false, "test_pretty_name");
146+
147+
TestA::TestPrettyName::fun(true, "TestPrettyName::fun");
148+
TestA::test_pretty_name(true, "test_pretty_name");
149+
test_pretty_name(true, "test_pretty_name");
150+
}

‎core-tests/src/coroutine/async.cpp

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -8,8 +8,8 @@
88
#include <regex>
99

1010
using namespace std;
11-
using swoole::test::coroutine;
1211
using swoole::AsyncEvent;
12+
using swoole::test::coroutine;
1313

1414
const int magic_code = 0x7009501;
1515

@@ -52,3 +52,13 @@ TEST(coroutine_async, gethostbyname) {
5252
}
5353
});
5454
}
55+
56+
TEST(coroutine_async, error) {
57+
coroutine::run([](void *arg) {
58+
int retval;
59+
const char *test_file = "/tmp/swoole_core_test_file_not_exists";
60+
swoole::coroutine::async([&](void) { retval = open(test_file, O_RDONLY); }, -1);
61+
ASSERT_EQ(retval, -1);
62+
ASSERT_EQ(errno, ENOENT);
63+
});
64+
}

‎include/swoole_log.h

Lines changed: 14 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -76,6 +76,7 @@ class Logger {
7676
bool redirect_stdout_and_stderr(int enable);
7777
void set_date_with_microseconds(bool enable);
7878
std::string gen_real_file(const std::string &file);
79+
static std::string get_pretty_name(const std::string &prettyFunction, bool strip = true);
7980

8081
void display_backtrace() {
8182
display_backtrace_ = true;
@@ -84,6 +85,7 @@ class Logger {
8485
} // namespace swoole
8586

8687
swoole::Logger *sw_logger();
88+
#define __SW_FUNC__ (swoole::Logger::get_pretty_name(__PRETTY_FUNCTION__).c_str())
8789

8890
#define swInfo(str, ...) \
8991
if (SW_LOG_INFO >= sw_logger()->get_level()) { \
@@ -104,7 +106,7 @@ swoole::Logger *sw_logger();
104106
size_t _sw_error_len = sw_snprintf(sw_error, \
105107
SW_ERROR_MSG_SIZE, \
106108
"%s(:%d): " str ", Error: %s[%d]", \
107-
__func__, \
109+
__SW_FUNC__, \
108110
__LINE__, \
109111
##__VA_ARGS__, \
110112
swoole_strerror(errno), \
@@ -116,7 +118,7 @@ swoole::Logger *sw_logger();
116118
#define swWarn(str, ...) \
117119
do { \
118120
if (SW_LOG_WARNING >= sw_logger()->get_level()) { \
119-
size_t _sw_error_len = sw_snprintf(sw_error, SW_ERROR_MSG_SIZE, str, ##__VA_ARGS__); \
121+
size_t _sw_error_len = sw_snprintf(sw_error, SW_ERROR_MSG_SIZE, "%s(): " str, __SW_FUNC__, ##__VA_ARGS__); \
120122
sw_logger()->put(SW_LOG_WARNING, sw_error, _sw_error_len); \
121123
} \
122124
} while (0)
@@ -127,9 +129,8 @@ swoole::Logger *sw_logger();
127129
if (SW_LOG_ERROR >= sw_logger()->get_level()) { \
128130
size_t _sw_error_len = sw_snprintf(sw_error, \
129131
SW_ERROR_MSG_SIZE, \
130-
"%s(:%d): " str ", Error: %s[%d]", \
131-
__func__, \
132-
__LINE__, \
132+
"%s(): " str ", Error: %s[%d]", \
133+
__SW_FUNC__, \
133134
##__VA_ARGS__, \
134135
swoole_strerror(errno), \
135136
errno); \
@@ -148,9 +149,8 @@ swoole::Logger *sw_logger();
148149
do { \
149150
size_t _sw_error_len = sw_snprintf(sw_error, \
150151
SW_ERROR_MSG_SIZE, \
151-
"%s(:%d): " str ", Error: %s[%d]", \
152-
__func__, \
153-
__LINE__, \
152+
"%s(): " str ", Error: %s[%d]", \
153+
__SW_FUNC__, \
154154
##__VA_ARGS__, \
155155
swoole_strerror(errno), \
156156
errno); \
@@ -161,15 +161,15 @@ swoole::Logger *sw_logger();
161161
#define swFatalError(code, str, ...) \
162162
do { \
163163
SwooleG.fatal_error(code, str, ##__VA_ARGS__); \
164-
exit(255); \
164+
exit(255); \
165165
} while (0)
166166

167-
#define swoole_error_log(level, __errno, str, ...) \
167+
#define swoole_error_log(level, error, str, ...) \
168168
do { \
169-
swoole_set_last_error(__errno); \
169+
swoole_set_last_error(error); \
170170
if (level >= sw_logger()->get_level()) { \
171171
size_t _sw_error_len = \
172-
sw_snprintf(sw_error, SW_ERROR_MSG_SIZE, "(ERRNO %d) " str, __errno, ##__VA_ARGS__); \
172+
sw_snprintf(sw_error, SW_ERROR_MSG_SIZE, "%s() (ERRNO %d): " str, __SW_FUNC__, error, ##__VA_ARGS__); \
173173
sw_logger()->put(level, sw_error, _sw_error_len); \
174174
} \
175175
} while (0)
@@ -178,7 +178,7 @@ swoole::Logger *sw_logger();
178178
#define swDebug(str, ...) \
179179
if (SW_LOG_DEBUG >= sw_logger()->get_level()) { \
180180
size_t _sw_error_len = \
181-
sw_snprintf(sw_error, SW_ERROR_MSG_SIZE, "%s(:%d): " str, __func__, __LINE__, ##__VA_ARGS__); \
181+
sw_snprintf(sw_error, SW_ERROR_MSG_SIZE, "%s(:%d): " str, __SW_FUNC__, __LINE__, ##__VA_ARGS__); \
182182
sw_logger()->put(SW_LOG_DEBUG, sw_error, _sw_error_len); \
183183
}
184184

@@ -252,7 +252,7 @@ enum swTrace_type {
252252
#define swTraceLog(what, str, ...) \
253253
if (SW_LOG_TRACE >= sw_logger()->get_level() && (what & SwooleG.trace_flags)) { \
254254
size_t _sw_error_len = \
255-
sw_snprintf(sw_error, SW_ERROR_MSG_SIZE, "%s(:%d): " str, __func__, __LINE__, ##__VA_ARGS__); \
255+
sw_snprintf(sw_error, SW_ERROR_MSG_SIZE, "%s(:%d): " str, __SW_FUNC__, __LINE__, ##__VA_ARGS__); \
256256
sw_logger()->put(SW_LOG_TRACE, sw_error, _sw_error_len); \
257257
}
258258
#else

‎include/swoole_process_pool.h

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -290,6 +290,7 @@ struct ProcessPool {
290290
int listen(const char *socket_file, int blacklog);
291291
int listen(const char *host, int port, int blacklog);
292292
int schedule();
293+
static void kill_timeout_worker(Timer *timer, TimerNode *tnode);
293294
};
294295
}; // namespace swoole
295296

‎src/core/log.cc

Lines changed: 34 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,38 @@
2525

2626
namespace swoole {
2727

28+
std::string Logger::get_pretty_name(const std::string &pretty_function, bool strip) {
29+
size_t brackets = pretty_function.find_first_of("(");
30+
if (brackets == pretty_function.npos) {
31+
return "";
32+
}
33+
34+
size_t begin = pretty_function.substr(0, brackets).rfind(" ") + 1;
35+
size_t end = brackets - begin;
36+
if (!strip) {
37+
return pretty_function.substr(begin, end);
38+
}
39+
40+
auto method_name = pretty_function.substr(begin, end);
41+
size_t count = 0, index = method_name.length();
42+
while (true) {
43+
index = method_name.rfind("::", index);
44+
if (index == method_name.npos) {
45+
if (count == 1) {
46+
return method_name.substr(method_name.rfind("::") + 2);
47+
}
48+
break;
49+
}
50+
count++;
51+
if (count == 2) {
52+
return method_name.substr(index + 2);
53+
}
54+
index -= 2;
55+
}
56+
57+
return method_name;
58+
}
59+
2860
bool Logger::open(const char *_log_file) {
2961
if (opened) {
3062
close();
@@ -256,8 +288,8 @@ void Logger::put(int level, const char *content, size_t length) {
256288

257289
if (date_with_microseconds) {
258290
auto now_us = std::chrono::duration_cast<std::chrono::microseconds>(now.time_since_epoch()).count();
259-
l_data_str +=
260-
sw_snprintf(date_str + l_data_str, SW_LOG_DATE_STRLEN - l_data_str, "<.%lld>", (long long) now_us - now_sec * 1000000);
291+
l_data_str += sw_snprintf(
292+
date_str + l_data_str, SW_LOG_DATE_STRLEN - l_data_str, "<.%lld>", (long long) now_us - now_sec * 1000000);
261293
}
262294

263295
char process_flag = '@';

‎src/coroutine/system.cc

Lines changed: 21 additions & 58 deletions
Original file line numberDiff line numberDiff line change
@@ -190,16 +190,18 @@ std::string System::gethostbyname(const std::string &hostname, int domain, doubl
190190

191191
#ifdef SW_USE_CARES
192192
auto result_list = dns_lookup_impl_with_cares(hostname.c_str(), domain, timeout);
193-
if (SwooleG.dns_lookup_random) {
194-
result = result_list[rand() % result_list.size()];
195-
} else {
196-
result = result_list[0];
193+
if (!result_list.empty()) {
194+
if (SwooleG.dns_lookup_random) {
195+
result = result_list[rand() % result_list.size()];
196+
} else {
197+
result = result_list[0];
198+
}
197199
}
198200
#else
199201
result = gethostbyname_impl_with_async(hostname, domain, timeout);
200202
#endif
201203

202-
if (dns_cache) {
204+
if (dns_cache && !result.empty()) {
203205
dns_cache->set(cache_key, std::make_shared<std::string>(result), dns_cache_expire);
204206
}
205207

@@ -620,20 +622,10 @@ static void async_task_completed(AsyncEvent *event) {
620622
co->resume();
621623
}
622624

623-
static void async_task_timeout(Timer *timer, TimerNode *tnode) {
624-
AsyncEvent *event = (AsyncEvent *) tnode->data;
625-
event->canceled = 1;
626-
event->retval = -1;
627-
event->error = SW_ERROR_AIO_TIMEOUT;
628-
Coroutine *co = (Coroutine *) event->object;
629-
co->resume();
630-
}
631-
632625
/**
633626
* @error: swoole_get_last_error()
634627
*/
635628
bool async(async::Handler handler, AsyncEvent &event, double timeout) {
636-
TimerNode *timer = nullptr;
637629
Coroutine *co = Coroutine::get_current_safe();
638630

639631
event.object = co;
@@ -644,33 +636,18 @@ bool async(async::Handler handler, AsyncEvent &event, double timeout) {
644636
if (_ev == nullptr) {
645637
return false;
646638
}
647-
if (timeout > 0) {
648-
timer = swoole_timer_add((long) (timeout * 1000), false, async_task_timeout, _ev);
649-
}
650-
651-
Coroutine::CancelFunc cancel_fn = [_ev](Coroutine *co) {
652-
_ev->canceled = true;
653-
_ev->error = SW_ERROR_AIO_CANCELED;
654-
_ev->retval = -1;
655-
co->resume();
656-
return true;
657-
};
658-
co->yield(&cancel_fn);
659-
660-
event.canceled = _ev->canceled;
661-
event.error = _ev->error;
662-
event.retval = _ev->retval;
663-
664-
errno = _ev->error;
665-
swoole_set_last_error(_ev->error);
666639

667-
if (event.catch_error()) {
640+
if (!co->yield_ex(timeout)) {
641+
event.canceled = _ev->canceled = true;
642+
event.retval = -1;
643+
event.error = errno = swoole_get_last_error();
668644
return false;
645+
} else {
646+
event.canceled = _ev->canceled;
647+
event.error = errno = _ev->error;
648+
event.retval = _ev->retval;
649+
return true;
669650
}
670-
if (timer) {
671-
swoole_timer_del(timer);
672-
}
673-
return true;
674651
}
675652

676653
struct AsyncLambdaTask {
@@ -694,7 +671,6 @@ static void async_lambda_callback(AsyncEvent *event) {
694671
}
695672

696673
bool async(const std::function<void(void)> &fn, double timeout) {
697-
TimerNode *timer = nullptr;
698674
AsyncEvent event{};
699675
AsyncLambdaTask task{Coroutine::get_current_safe(), fn};
700676

@@ -706,28 +682,15 @@ bool async(const std::function<void(void)> &fn, double timeout) {
706682
if (_ev == nullptr) {
707683
return false;
708684
}
709-
if (timeout > 0) {
710-
timer = swoole_timer_add((long) (timeout * 1000), false, async_task_timeout, _ev);
711-
}
712685

713-
Coroutine::CancelFunc cancel_fn = [_ev](Coroutine *co) {
686+
if (!task.co->yield_ex(timeout)) {
714687
_ev->canceled = true;
715-
_ev->error = SW_ERROR_AIO_CANCELED;
716-
_ev->retval = -1;
717-
co->resume();
718-
return true;
719-
};
720-
task.co->yield(&cancel_fn);
721-
722-
errno = _ev->error;
723-
swoole_set_last_error(_ev->error);
724-
if (_ev->catch_error()) {
688+
errno = swoole_get_last_error();
725689
return false;
690+
} else {
691+
errno = _ev->error;
692+
return true;
726693
}
727-
if (timer) {
728-
swoole_timer_del(timer);
729-
}
730-
return true;
731694
}
732695

733696
} // namespace coroutine

‎src/network/dns.cc

Lines changed: 12 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -503,13 +503,23 @@ std::vector<std::string> dns_lookup_impl_with_cares(const char *domain, int fami
503503
ares_cancel(ctx.channel);
504504
} else if (co->is_timedout()) {
505505
ares_process_fd(ctx.channel, ARES_SOCKET_BAD, ARES_SOCKET_BAD);
506-
swoole_set_last_error(SW_ERROR_DNSLOOKUP_RESOLVE_TIMEOUT);
506+
ctx.error = ARES_ETIMEOUT;
507507
} else {
508508
swTraceLog(SW_TRACE_CARES, "lookup success, result_count=%lu", ctx.result.size());
509509
}
510510
_destroy:
511511
if (ctx.error) {
512-
swoole_set_last_error(ctx.error == ARES_ECANCELLED ? SW_ERROR_CO_CANCELED : SW_ERROR_DNSLOOKUP_RESOLVE_FAILED);
512+
switch (ctx.error) {
513+
case ARES_ECANCELLED:
514+
swoole_set_last_error(SW_ERROR_CO_CANCELED);
515+
break;
516+
case ARES_ETIMEOUT:
517+
swoole_set_last_error(SW_ERROR_DNSLOOKUP_RESOLVE_TIMEOUT);
518+
break;
519+
default:
520+
swoole_set_last_error(SW_ERROR_DNSLOOKUP_RESOLVE_FAILED);
521+
break;
522+
}
513523
}
514524
ares_destroy(ctx.channel);
515525
_return:

0 commit comments

Comments
 (0)