Merge branch 'dbg'

exch/exmdb/parser.cpp

@@ -22,6 +22,7 @@
 #include <sys/socket.h>
 #include <sys/types.h>
 #include <libHX/socket.h>
+#include <gromox/clock.hpp>
 #include <gromox/defs.h>
 #include <gromox/exmdb_common_util.hpp>
 #include <gromox/exmdb_ext.hpp>
@@ -145,6 +146,7 @@ static BOOL exmdb_parser_dispatch2(const exreq *prequest, std::unique_ptr<exresp
 
 static BOOL exmdb_parser_dispatch(const exreq *prequest, std::unique_ptr<exresp> &presponse)
 {
+	auto tstart = tp_now();
 	if (*prequest->dir != '\0' && access(prequest->dir, R_OK | X_OK) < 0)
 		mlog(LV_DEBUG, "exrpc %s access(\"%s\"): %s",
 			exmdb_rpc_idtoname(prequest->call_id),
@@ -155,9 +157,11 @@ static BOOL exmdb_parser_dispatch(const exreq *prequest, std::unique_ptr<exresp>
 		presponse->call_id = prequest->call_id;
 	if (g_exrpc_debug == 0)
 		return ret;
+	auto tend = tp_now();
 	if (!ret || g_exrpc_debug == 2)
-		mlog(LV_DEBUG, "EXRPC %s %s (%s)",
+		mlog(LV_DEBUG, "EXRPC %s %5luµs %s (%s)",
 		        ret == 0 ? "FAIL" : "ok  ",
+		        static_cast<unsigned long>(std::chrono::duration_cast<std::chrono::microseconds>(tend - tstart).count()),
 		        exmdb_rpc_idtoname(prequest->call_id),
 		        znul(prequest->dir));
 	return ret;

exch/zcore/rpc_parser.cpp

@@ -1,4 +1,6 @@
 // SPDX-License-Identifier: GPL-2.0-only WITH linking exception
+// SPDX-FileCopyrightText: 2021–2024 grommunio GmbH
+// This file is part of Gromox.
 #include <chrono>
 #include <climits>
 #include <condition_variable>
@@ -71,6 +73,7 @@ BOOL rpc_parser_activate_connection(int clifd)
 static int rpc_parser_dispatch(const zcreq *q0, std::unique_ptr<zcresp> &r0) try
 {
 	auto tstart = tp_now();
+	GUID dbg_hsession{};
 	switch (q0->call_id) {
 #include <zrpc_dispatch.cpp>
 	default:
@@ -84,12 +87,15 @@ static int rpc_parser_dispatch(const zcreq *q0, std::unique_ptr<zcresp> &r0) try
 	r0->call_id = q0->call_id;
 	if (g_zrpc_debug == 0)
 		return DISPATCH_TRUE;
-	if (r0->result != 0 || g_zrpc_debug == 2)
-		mlog(LV_DEBUG, "ZRPC %s %8xh %5luµs %s",
+	if (r0->result != 0 || g_zrpc_debug == 2) {
+		auto info = zs_query_session(dbg_hsession);
+		mlog(LV_DEBUG, "ZRPC %s %s %8xh %5luµs %s",
+		        info != nullptr ? info->username.c_str() : "<>",
 		        r0->result == 0 ? "ok  " : "FAIL",
 		        r0->result,
 		        static_cast<unsigned long>(std::chrono::duration_cast<std::chrono::microseconds>(tend - tstart).count()),
 		        zcore_rpc_idtoname(q0->call_id));
+	}
 	return DISPATCH_TRUE;
 } catch (const std::bad_alloc &) {
 	return DISPATCH_FALSE;

exch/zcore/zserver.cpp

@@ -63,14 +63,8 @@ struct NOTIFY_ITEM {
 	time_t last_time = 0;
 };
 
-struct user_info_del {
-	void operator()(USER_INFO *x);
-};
-
 }
 
-using USER_INFO_REF = std::unique_ptr<USER_INFO, user_info_del>;
-
 static size_t g_table_size;
 static gromox::atomic_bool g_notify_stop;
 static int g_ping_interval;
@@ -118,7 +112,7 @@ static int zs_get_user_id(GUID hsession)
 	return user_id;
 }
 
-static USER_INFO_REF zs_query_session(GUID hsession)
+USER_INFO_REF zs_query_session(GUID hsession)
 {
 	auto user_id = zs_get_user_id(hsession);
 	std::unique_lock tl_hold(g_table_lock);

exch/zcore/zserver.hpp

@@ -47,11 +47,18 @@ struct USER_INFO {
 	std::recursive_mutex lock;
 };
 
+struct user_info_del {
+	void operator()(USER_INFO *x);
+};
+
+using USER_INFO_REF = std::unique_ptr<USER_INFO, user_info_del>;
+
 extern void zserver_init(size_t table_size, int cache_interval, int ping_interval);
 extern int zserver_run();
 extern void zserver_stop();
 extern void zs_notification_proc(const char *dir, BOOL table, uint32_t notify_id, const DB_NOTIFY *);
 extern USER_INFO *zs_get_info();
+extern USER_INFO_REF zs_query_session(GUID);
 extern ec_error_t zs_logon_token(const char *token, const char *rhost, GUID *ses);
 extern ec_error_t zs_logon(const char *username, const char *password, const char *rhost, uint32_t flags, GUID *ses);
 extern ec_error_t zs_checksession(GUID ses);

mra/imap/imap_parser.cpp

@@ -1405,12 +1405,14 @@ static int imap_parser_dispatch_cmd(int argc, char **argv, imap_context *ctx) tr
 		 * Can't really hide AUTHENTICATE because the prompts
 		 * and answers are backend-specific.
 		 */
+		fprintf(stderr, "[%s]:%hu ", ctx->connection.client_ip, ctx->connection.client_port);
 		if (strcasecmp(argv[1], "LOGIN") == 0) {
 			fprintf(stderr, "< LOGIN ****: ret=%xh code=%u\n", ret, code);
 		} else {
 			fprintf(stderr, "<");
 			for (int i = 0; i < argc; ++i)
-				fprintf(stderr, " %s", argv_copy[i].c_str());
+				fprintf(stderr, " %s", argv_copy[i].empty() ?
+				        "\"\"" : argv_copy[i].c_str());
 			fprintf(stderr, ": ret=%xh code=%u\n", ret, code);
 		}
 	}

mra/pop3/pop3_parser.cpp

@@ -1,4 +1,6 @@
 // SPDX-License-Identifier: GPL-2.0-only WITH linking exception
+// SPDX-FileCopyrightText: 2021–2024 grommunio GmbH
+// This file is part of Gromox.
 /* pop3 parser is a module, which first read data from socket, parses the pop3 
  * commands and then do the corresponding action. 
  */ 
@@ -595,7 +597,8 @@ static int pop3_parser_dispatch_cmd(const char *line, int len, pop3_context *ctx
 	auto ret = pop3_parser_dispatch_cmd2(line, len, ctx);
 	auto code = ret & DISPATCH_VALMASK;
 	if (g_popcmd_debug >= 2 || (g_popcmd_debug >= 1 && code != 0 && code != 1700)) {
-		if (strcasecmp(line, "PASS") == 0)
+		fprintf(stderr, "[%s]:%hu ", ctx->connection.client_ip, ctx->connection.client_port);
+		if (strncasecmp(line, "PASS", 4) == 0)
 			fprintf(stderr, "< PASS ****: ret=%xh code=%u\n", ret, code);
 		else
 			fprintf(stderr, "< %s: ret=%xh code=%u\n", line, ret, code);

tools/exmidl.pl

@@ -14,16 +14,17 @@
 if ($gen_mode eq "CLN" || $gen_mode eq "SDP") {
 	print "#include <$_>\n" for qw(cstring utility gromox/exmdb_client.hpp gromox/exmdb_rpc.hpp);
 	if ($gen_mode eq "SDP") {
-		print "#include <$_>\n" for qw(gromox/exmdb_common_util.hpp gromox/exmdb_ext.hpp gromox/exmdb_provider_client.hpp gromox/exmdb_server.hpp);
+		print "#include <$_>\n" for qw(gromox/clock.hpp gromox/exmdb_common_util.hpp gromox/exmdb_ext.hpp gromox/exmdb_provider_client.hpp gromox/exmdb_server.hpp);
 	}
 	print "using namespace gromox;\n";
 }
 if ($gen_mode eq "SDP") {
 	print "extern unsigned int g_exrpc_debug;\n";
 	print "unsigned int g_exrpc_debug;\n\n";
-	print "static inline void smlpc_log(bool ok, const char *dir, const char *func)\n{\n";
+	print "static void smlpc_log(bool ok, const char *dir, const char *func, gromox::time_point tstart, gromox::time_point tend)\n{\n";
 	print "\tif (g_exrpc_debug >= 2 || (!ok && g_exrpc_debug == 1))\n";
-	print "\t\tmlog(LV_DEBUG, \"SMLPC \%s \%s (\%s)\", ok == 0 ? \"FAIL\" : \"ok  \", func, dir);\n";
+	print "\t\tmlog(LV_DEBUG, \"SMLPC \%s \%5luµs \%s (\%s)\", ok == 0 ? \"FAIL\" : \"ok  \",\n";
+	print "\t\t\tstatic_cast<unsigned long>(std::chrono::duration_cast<std::chrono::microseconds>(tend - tstart).count()), func, dir);\n";
 	print "}\n\n";
 }
 
@@ -45,9 +46,10 @@
 		print "\tBOOL xb_private;\n\n";
 		print "\tif (!exmdb_client_is_local(dir, &xb_private))\n";
 		print "\t\treturn exmdb_client_remote::$func(".join(", ", @anames).");\n";
+		print "\tauto tstart = gromox::tp_now();\n";
 		print "\texmdb_server::build_env(EM_LOCAL | (xb_private ? EM_PRIVATE : 0), dir);\n";
 		print "\tauto xbresult = exmdb_server::$func(".join(", ", @anames).");\n";
-		print "\tsmlpc_log(xbresult, dir, \"$func\");\n";
+		print "\tsmlpc_log(xbresult, dir, \"$func\", tstart, gromox::tp_now());\n";
 		print "\texmdb_server::free_env();\n";
 		print "\treturn xbresult;\n";
 		print "}\n\n";

tools/mkmidb.cpp

@@ -149,7 +149,7 @@ int main(int argc, const char **argv)
 		printf("Failed to initialize sqlite engine\n");
 		return EXIT_FAILURE;
 	}
-	auto cl_0 = make_scope_exit([]() { sqlite3_shutdown(); });
+	auto cl_0 = make_scope_exit(sqlite3_shutdown);
 	if (sqlite3_open_v2(temp_path.c_str(), &psqlite,
 	    SQLITE_OPEN_READWRITE | SQLITE_OPEN_CREATE, nullptr) != SQLITE_OK) {
 		printf("fail to create store database\n");

tools/mkprivate.cpp

@@ -201,7 +201,7 @@ int main(int argc, const char **argv)
 		printf("Failed to initialize sqlite engine\n");
 		return EXIT_FAILURE;
 	}
-	auto cl_0 = make_scope_exit([]() { sqlite3_shutdown(); });
+	auto cl_0 = make_scope_exit(sqlite3_shutdown);
 	if (opt_upgrade)
 		return mbop_upgrade(temp_path.c_str(), sqlite_kind::pvt);
 	if (sqlite3_open_v2(temp_path.c_str(), &psqlite,

tools/mkpublic.cpp

@@ -148,7 +148,7 @@ int main(int argc, const char **argv)
 		printf("Failed to initialize sqlite engine\n");
 		return EXIT_FAILURE;
 	}
-	auto cl_0 = make_scope_exit([]() { sqlite3_shutdown(); });
+	auto cl_0 = make_scope_exit(sqlite3_shutdown);
 	if (opt_upgrade)
 		return mbop_upgrade(temp_path.c_str(), sqlite_kind::pub);
 	if (sqlite3_open_v2(temp_path.c_str(), &psqlite,

tools/zcidl.pl

@@ -31,6 +31,10 @@
 		print "case zcore_callid::$func: {\n";
 		if (scalar(@$iargs) > 0) {
 			print "\tauto &q = *static_cast<const zcreq_$func *>(q0);\n";
+			if ($iargs->[0][0] eq "GUID" &&
+			    $iargs->[0][1] eq "hsession") {
+				print "\tdbg_hsession = q.hsession;\n";
+			}
 		}
 		print "\tauto r1 = std::make_unique<zcresp_$func>();\n";
 		if (scalar(@$oargs) > 0) {