From cc00429f44abb0a78f4489744fb6c25cc4722d1c Mon Sep 17 00:00:00 2001 From: Ulf Norell Date: Tue, 19 May 2020 09:07:05 +0200 Subject: [PATCH 1/2] Clean up roster logging --- apps/roster/include/roster.hrl | 6 + apps/roster/src/api/regexp_api.erl | 3 - apps/roster/src/protocol/micro_auth.erl | 36 +-- apps/roster/src/protocol/micro_profile.erl | 29 +- apps/roster/src/protocol/micro_roster.erl | 12 +- apps/roster/src/protocol/roster_auth.erl | 168 +++--------- apps/roster/src/protocol/roster_bpe.erl | 26 +- apps/roster/src/protocol/roster_favorite.erl | 17 +- apps/roster/src/protocol/roster_friend.erl | 18 +- apps/roster/src/protocol/roster_history.erl | 272 +++++++++---------- apps/roster/src/protocol/roster_link.erl | 97 ++++--- apps/roster/src/protocol/roster_message.erl | 43 +-- apps/roster/src/protocol/roster_presence.erl | 17 +- apps/roster/src/protocol/roster_profile.erl | 102 +++---- apps/roster/src/protocol/roster_room.erl | 122 +++++---- apps/roster/src/protocol/roster_roster.erl | 18 +- apps/roster/src/protocol/roster_search.erl | 43 ++- apps/roster/src/roster.erl | 28 +- apps/roster/src/roster_proto.erl | 10 +- 19 files changed, 496 insertions(+), 571 deletions(-) diff --git a/apps/roster/include/roster.hrl b/apps/roster/include/roster.hrl index f8375165b..851dd76a0 100644 --- a/apps/roster/include/roster.hrl +++ b/apps/roster/include/roster.hrl @@ -47,6 +47,12 @@ -define(GEO_URL , "http://geolite.maxmind.com/download/geoip/database/GeoLite2-City.tar.gz"). -define(AUTH_GROUP , <<"AUTH_DATA">>). +%% Logging +-define(ROSTER_LOG_REQ(ReqType, Status, ClientId, Fmt, Args), + ?LOG_INFO("~s/~s(~s): " Fmt, [ReqType, Status, ClientId | Args])). +-define(ROSTER_LOG_REQ(ReqType, Status, ClientId, Fmt), ?ROSTER_LOG_REQ(ReqType, Status, ClientId, Fmt, [])). +-define(ROSTER_LOG_REQ(ReqType, Status, ClientId), ?ROSTER_LOG_REQ(ReqType, Status, ClientId, "", [])). + -record(chain, {?CONTAINER, aclver = [], unread = {[],[]}}). -record(push, {model = [] :: [] | term(), diff --git a/apps/roster/src/api/regexp_api.erl b/apps/roster/src/api/regexp_api.erl index 357d8ec69..c033f3274 100644 --- a/apps/roster/src/api/regexp_api.erl +++ b/apps/roster/src/api/regexp_api.erl @@ -12,8 +12,6 @@ validate_string(String) when String == [] orelse String == <<>> -> {ok, []}; validate_string(String) -> validate_string(String, <<"^[a-zA-Z0-9_].{1,32}$">>). validate_string(String, RegExp) -> - ?LOG_INFO("StringToValidate:~p", [String]), - ?LOG_INFO("RegExp:~p", [RegExp]), Status = try case re:run(String, RegExp) of {match, _} -> ok; @@ -23,7 +21,6 @@ validate_string(String, RegExp) -> ?LOG_INFO("RegExpError:~p:~p", [E, R]), error end, - ?LOG_INFO("ValidationStatus:~p", [Status]), {Status, String}. %% ------------------------------------------------------------------ diff --git a/apps/roster/src/protocol/micro_auth.erl b/apps/roster/src/protocol/micro_auth.erl index 0748a0c67..a0bb2b30d 100644 --- a/apps/roster/src/protocol/micro_auth.erl +++ b/apps/roster/src/protocol/micro_auth.erl @@ -19,13 +19,13 @@ init([Listeners]) -> {ok, Listeners}. description() -> "Micro Authentication Module". check(#mqtt_client{client_id = <<"sys_micro_", _/binary>> = ClientId, client_pid = ClientPid}, _Pwd, _State) -> - ?LOG_INFO("~p:Auth:auth(micro)/check", [ClientId]), + ?ROSTER_LOG_REQ('Auth', check, ClientId), emqttd_client:subscribe(ClientPid, [{roster:action_topic(ClientId), 2}]), ignore; check(#mqtt_client{client_id = <<"emqttd_", _/binary>> = ClientId, username = <<"micro">>, ws_initial_headers = [_|_] = Headers} = MC, Pwd, State) when not is_tuple(Pwd) -> - ?LOG_INFO("~p:Auth:auth(micro)/check/ws headers: ~p", [ClientId, Headers]), + ?ROSTER_LOG_REQ('Auth', check, ClientId, "Headers=~p", [Headers]), Jwt = get_token(normalize(Headers)), check(MC, {token, Jwt}, State); check(#mqtt_client{client_id = <<"emqttd_", _/binary>>, @@ -35,7 +35,7 @@ check(#mqtt_client{client_id = <<"emqttd_", _/binary>> = ClientId, username = <<"micro">>, client_pid = ClientPid, will_topic = WT}, {token, Token}, _State) -> - ?LOG_INFO("~p:Auth:auth(micro)/check", [ClientId]), + ?ROSTER_LOG_REQ('Auth', check, ClientId), case WT of <<"version/", BVer/binary>> -> M = application:get_env(roster, validate_token, ?MODULE), @@ -44,13 +44,13 @@ check(#mqtt_client{client_id = <<"emqttd_", _/binary>> = ClientId, emqttd_client:subscribe(ClientPid, [{roster:action_topic(ClientId), 2}]), PhoneId = micro:uuid_to_id('LinkRoster', AccUuid), AuthPid = n2o_async:pid(system, ?MODULE), - [ ?LOG_ERROR("~p:Auth:auth(micro)/AuthPid not existing", [ClientId]) || not is_pid(AuthPid) ], + [ ?LOG_ERROR("~s: AuthPid not existing", [ClientId]) || not is_pid(AuthPid) ], Ver = binary_to_list(BVer), case kvs:get('Auth', ClientId) of {ok, #'Auth'{user_id = PhoneId, type = logout} = Auth0} -> Auth1 = Auth0#'Auth'{last_online = roster:now_msec(), type = verified}, kvs:put(Auth1), - ?LOG_INFO("~p:Auth:auth(micro)/check:session created, post logout ", [ClientId]), + ?ROSTER_LOG_REQ('Auth', check, ClientId, "session created, post logout "), roster:sub_client(subscribe, ClientId, PhoneId), AuthPid ! roster_auth:control_ver(Auth1, Ver), ok; @@ -63,12 +63,13 @@ check(#mqtt_client{client_id = <<"emqttd_", _/binary>> = ClientId, {error, invalid_account_id}; {error, _} -> case PhoneId of - [] -> ?LOG_INFO("account not found: ~p", [AccUuid]), + [] -> + ?LOG_INFO("account not found: ~p", [AccUuid]), {error, roster_not_found}; _ -> kvs:put(Auth = #'Auth'{client_id = ClientId, user_id = PhoneId, phone = roster:phone(PhoneId), - created = roster:now_msec(), last_online = roster:now_msec(), type = verified}), - ?LOG_INFO("~p:Auth:auth(micro)/check:session created", [ClientId]), + created = roster:now_msec(), last_online = roster:now_msec(), type = verified}), + ?ROSTER_LOG_REQ('Auth', check, ClientId, "session created"), roster:sub_client(subscribe, ClientId, PhoneId), AuthPid ! roster_auth:control_ver( Auth#'Auth'{client_id = ClientId, user_id = PhoneId, type = verified}, Ver), @@ -76,19 +77,19 @@ check(#mqtt_client{client_id = <<"emqttd_", _/binary>> = ClientId, end end; error -> - ?LOG_INFO("~p:Auth:auth(micro)/check:invalid_token", [ClientId]), + ?ROSTER_LOG_REQ('Auth', check, ClientId, "invalid token: ~s", [Token]), {error, invalid_token} end; _ -> {error, invalid_version} end; check(#mqtt_client{client_id = <<"emqttd_", _/binary>> = ClientId, username = Username}, _,_State) when Username /= <<"api">>, Username /= <<"micro">> -> - ?LOG_INFO("~p:Auth:auth(micro)/check:invalid_username: ~p", [ClientId, Username]), + ?ROSTER_LOG_REQ('Auth', check, ClientId, "invalid_username: ~p", [Username]), {error, invalid_username}; check(_Client, _Password, _Opts) -> ignore. -info(#'Auth'{type = update, client_id = <<"emqttd_", _/binary>> = ClientId, token = Token, settings = Settings} = Auth, Req, - #cx{params = <<"sys_", _/binary>>, client_pid = C} = State) -> - ?LOG_INFO("~p:Auth/update(micro):~p", [ClientId, Auth]), +info(#'Auth'{type = update, client_id = <<"emqttd_", _/binary>> = ClientId, token = Token, settings = Settings}, Req, + #cx{params = <<"sys_", _/binary>> = Sys, client_pid = C} = State) -> + ?ROSTER_LOG_REQ('Auth', update, Sys, "ClientId=~s, Token=~s", [ClientId, Token]), IO = case kvs:get('Auth', ClientId) of {ok, #'Auth'{type = Type} = StoredAuth} -> %% TODO merge or set settings? SendAuth = StoredAuth#'Auth'{token = Token, settings = Settings, type = update}, @@ -105,6 +106,7 @@ info(#'Auth'{type = delete, client_id = <<"emqttd_", _/binary>> = ClientId} = Au Reply = {reply, {bert, IO}, _, _} = roster_auth:info(Auth, State#cx{params = ClientId}), roster:send_action(C, ClientId, IO), Reply; info(#'Auth'{type = logout, client_id = <<"emqttd_", _/binary>> = ClientId} = Auth, Req, #cx{params = SysClientId, client_pid = C} = State) -> + ?ROSTER_LOG_REQ('Auth', logout, SysClientId, "ClientId=~s", [ClientId]), IO = case kvs:get('Auth', ClientId) of {ok, #'Auth'{} = StoredAuth} -> roster_presence:on_disconnect(StoredAuth#'Auth'{type = logout}, C), @@ -115,8 +117,8 @@ info(#'Auth'{type = logout, client_id = <<"emqttd_", _/binary>> = ClientId} = Au {reply, {bert, IO}, Req, State}; -info(#'Auth'{phone = Phone} = Auth, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:~p:Auth/unknown(micro):~p", [Phone, ClientId, Auth]), +info(#'Auth'{type = Status}, Req, #cx{params = ClientId} = State) -> + ?ROSTER_LOG_REQ('Auth', Status, ClientId, "Unknown request"), {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State}. %% micro_auth handlers @@ -129,7 +131,7 @@ proc(init, #handler{name = micro_auth} = Async) -> proc(#'Auth'{type = {ver, Ver}, phone = Phone, client_id = <<"emqttd_", _/binary>> = ClientId}, #handler{state = C} = H) -> - ?LOG_INFO("~p:~p:Auth(micro)/login", [Phone, ClientId]), + ?ROSTER_LOG_REQ('Auth', proc, ClientId, "login, Phone=~s", [Phone]), catch roster_presence:on_connect(Phone, ClientId, C, Ver), %%TODO send Auth updated session? {reply, [], H}; @@ -140,7 +142,7 @@ proc({disconnect, #'Auth'{client_id = <<"emqttd_", _/binary>>} = Auth}, proc(#'Auth'{type = {reg, Ver}, client_id = <<"emqttd_", _/binary>> = ClientId, phone = Phone, user_id = UserId}, #handler{state = C} = H) -> - ?LOG_INFO("~p:~p:Auth(micro)/login(created session)", [Phone, ClientId]), + ?ROSTER_LOG_REQ('Auth', proc, ClientId, "created session, Phone=~s", [Phone]), roster_presence:on_verify(ClientId, UserId), roster_presence:on_connect(Phone, ClientId, C, Ver), {reply, [], H}; diff --git a/apps/roster/src/protocol/micro_profile.erl b/apps/roster/src/protocol/micro_profile.erl index 6466db228..d9526bd75 100644 --- a/apps/roster/src/protocol/micro_profile.erl +++ b/apps/roster/src/protocol/micro_profile.erl @@ -8,11 +8,11 @@ info(#'Profile'{phone=LinkPhone, rosters=Rosters, status=create, settings = Settings} = Profile, Req, %% TODO are Rosters sent? #cx{params = ClientId = <<"sys_", _/binary>>, client_pid = C} = State) -> Phone = micro:uuid_to_id('LinkProfile', LinkPhone), - ?LOG_INFO("~p:~p:Profile/create:~p", [LinkPhone,ClientId,Profile]), + ?ROSTER_LOG_REQ('Profile', create, ClientId, "LinkPhone=~s", [LinkPhone]), IO2 = case kvs:get('Profile', Phone) of {ok, #'Profile'{}} -> - ?LOG_INFO("~p:~p:Profile/already_exist", [LinkPhone, ClientId]), + ?LOG_INFO("Profile already exists: ~p", [Phone]), #io{code = #error{code = already_exist}, data = LinkPhone}; _ -> OldPhone = roster:get_data_val(<<"PHONE">>, Settings), @@ -57,13 +57,12 @@ info(#'Profile'{phone=LinkPhone, rosters=Rosters, status=create, settings = Sett end end end, - ?LOG_INFO("~p:~p:Profile/create.result:~p", [LinkPhone,ClientId, IO2]), {reply, {bert, IO2}, Req, State}; info(#'Profile'{phone=LinkPhone, rosters=[], status = update} = Profile, Req, - #cx{params = ClientId = <<"sys_", _/binary>>, client_pid = C} = State) -> + #cx{params = ClientId = <<"sys_", _/binary>>, client_pid = C} = State) -> + ?ROSTER_LOG_REQ('Profile', update, ClientId, "LinkPhone=~s", [LinkPhone]), Phone = micro:uuid_to_id('LinkProfile', LinkPhone), - ?LOG_INFO("~p:~p:Profile(micro)/update:~s", [LinkPhone,ClientId,io_lib:format("~p",[Profile])]), IO = case kvs:get('Profile', Phone) of {ok, #'Profile'{phone = Phone} = StoredProfile} -> P = roster:patch_profile(StoredProfile, Profile), @@ -75,20 +74,22 @@ info(#'Profile'{phone=LinkPhone, rosters=[], status = update} = Profile, Req, end, {reply, {bert, IO}, Req, State}; -info(#'Profile'{status = remove, phone=UUID, rosters =Accounts }=Data, Req, - #cx{params = ClientId= <<"sys_", _/binary>>} = State) -> - ?LOG_INFO("~p:~p:Accounts/remove:~s", [UUID,ClientId,io_lib:format("~p",[Data])]), +info(#'Profile'{status = remove, phone = UUID, rosters = Accounts}, Req, + #cx{params = <<"sys_", _/binary>> = ClientId} = State) -> + ?ROSTER_LOG_REQ('Profile', remove, ClientId, "Phone=~s", [UUID]), Rosters = lists:flatten([begin [_,RId]=roster:parts_phone_id(micro:uuid_to_id('LinkRoster',A)), RId end || A <- Accounts]), - UID = micro:uuid_to_id('LinkProfile',UUID), + UID = micro:uuid_to_id('LinkProfile', UUID), case roster_profile:info(#'Profile'{status = delete, phone=UID, rosters = [_|_]=Rosters}, Req,State) of {reply, {bert, {io, {error, _R}, <<>>}}, Req, State}=E -> E; {reply, {bert, P=#'Profile'{phone=UID, rosters = NewRosters}}, Req, State} -> - Accs=[ begin kvs:delete('LinkRoster', Id), micro:norm_uuid(Id) end - || RosterId <- Rosters--NewRosters, #'LinkRoster'{id=Id} <- kvs:index('LinkRoster',phone_id,roster:phone_id(UID,RosterId))], - {reply, {bert, P#'Profile'{rosters = Accs}}, Req, State} + Accs=[ begin kvs:delete('LinkRoster', Id), + micro:norm_uuid(Id) + end || RosterId <- Rosters -- NewRosters, + #'LinkRoster'{id = Id} <- kvs:index('LinkRoster', phone_id, roster:phone_id(UID, RosterId)) ], + {reply, {bert, P#'Profile'{rosters = Accs}}, Req, State} end; -info(#'Profile'{phone = LinkPhone} = Profile, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:Profile/unknown:~p", [ClientId, Profile]), +info(#'Profile'{phone = LinkPhone, status = Status}, Req, #cx{params = ClientId} = State) -> + ?ROSTER_LOG_REQ('Profile', Status, ClientId, "Unknown request, LinkPhone=~s", [LinkPhone]), {reply, {bert, #io{code = #error{code = invalid_data}, data = LinkPhone}}, Req, State}. diff --git a/apps/roster/src/protocol/micro_roster.erl b/apps/roster/src/protocol/micro_roster.erl index 9468a61d9..c0df66b8c 100644 --- a/apps/roster/src/protocol/micro_roster.erl +++ b/apps/roster/src/protocol/micro_roster.erl @@ -11,7 +11,7 @@ info(#'Roster'{status = add, phone = LinkPhone, nick = Nick, id = LinkRosterId} #cx{params = <<"sys_", _/binary>> = ClientId} = State) -> Phone = micro:uuid_to_id('LinkProfile', LinkPhone), PhoneId = micro:uuid_to_id('LinkRoster', LinkRosterId), - ?LOG_INFO("~p:~p:Roster(micro)/add:~s", [LinkRosterId, ClientId, io_lib:format("~p", [Roster])]), + ?ROSTER_LOG_REQ('Roster', add, ClientId, "Id=~s, Nick=~s", [LinkRosterId, Nick]), IO = case kvs:get('Profile', Phone) of {ok, #'Profile'{rosters = RosterIds} = Profile} -> RosterId = roster:roster_id(PhoneId), @@ -32,7 +32,7 @@ info(#'Roster'{status = add, phone = LinkPhone, nick = Nick, id = LinkRosterId} kvs:put(Profile#'Profile'{phone = Phone, rosters = RosterIds++[NewRosterId], update = roster:now_msec()}), Roster; - {reply, {bert, #io{code = #error{}} = Err}, _, _} -> + {reply, {bert, #io{code = #error{}} = Err}, _, _} -> kvs:delete('Roster', NewRosterId), Err end @@ -41,9 +41,9 @@ info(#'Roster'{status = add, phone = LinkPhone, nick = Nick, id = LinkRosterId} end, {reply, {bert, IO}, Req, State#cx{state = []}}; info(#'Roster'{status = update, id = LinkRosterId, nick = Nick} = Roster, Req, - #cx{params = <<"sys_", _/binary>> = ClientId} = State) when Nick /= []-> + #cx{params = <<"sys_", _/binary>> = ClientId} = State) when Nick /= []-> + ?ROSTER_LOG_REQ('Roster', update, ClientId, "Id=~s, Nick=~s", [LinkRosterId, Nick]), PhoneId = micro:uuid_to_id('LinkRoster', LinkRosterId), - ?LOG_INFO("~p:~p:Roster(micro)/update:~s", [LinkRosterId, ClientId, io_lib:format("~p", [Roster])]), IO2 = case kvs:get('Roster', RosterId = roster:roster_id(PhoneId)) of {ok, #'Roster'{}} -> @@ -60,7 +60,7 @@ info(#'Roster'{status = update, id = LinkRosterId, nick = Nick} = Roster, Req, {error, _} -> #io{code = {error, roster_not_found}} end, {reply, {bert, IO2}, Req, State}; -info(#'Roster'{} = Roster, Req, #cx{params = <<"sys_", _/binary>> = ClientId} = State) -> - ?LOG_INFO("~p:Profile(micro)/unknown:~p", [ClientId, Roster]), +info(#'Roster'{status = Status}, Req, #cx{params = <<"sys_", _/binary>> = ClientId} = State) -> + ?ROSTER_LOG_REQ('Roster', Status, ClientId, "Unknown request"), {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State}. diff --git a/apps/roster/src/protocol/roster_auth.erl b/apps/roster/src/protocol/roster_auth.erl index 17a19d77b..1b66fbd24 100644 --- a/apps/roster/src/protocol/roster_auth.erl +++ b/apps/roster/src/protocol/roster_auth.erl @@ -35,27 +35,20 @@ check(#mqtt_client{ client_id = <<"reg_", _/binary>> = ClientId, username = <<"api">>, client_pid = ClientPid, - will_topic = <<"version/", _BVer/binary>> - }, _, _) -> - ?LOG_INFO("~p:Auth:reg/check", [ClientId]), + will_topic = <<"version/", _BVer/binary>> }, _, _) -> + ?ROSTER_LOG_REQ('Auth', check, ClientId), emqttd_client:subscribe(ClientPid, [{roster:action_topic(ClientId), 2}]), ignore; check(#mqtt_client{ client_id = <<"reg_", _/binary>> = ClientId, username = <<"api">>, - will_topic = _WT - }, _, _) -> - ?LOG_ERROR("~p:Auth:reg/check:error:version ~s", [ClientId, _WT]), + will_topic = WT }, _, _) -> + ?ROSTER_LOG_REQ('Auth', check, ClientId, "Invalid version: ~p", [WT]), {error, invalid_version}; -check(#mqtt_client{ - client_id = <<"emqttd_", _/binary>> = ClientId, - username = <<"api">> - }, - undefined, - _State) -> - ?LOG_ERROR("~p:Auth:auth/check:error:token undefined", [ClientId]), +check(#mqtt_client{ client_id = <<"emqttd_", _/binary>> = ClientId, username = <<"api">> }, undefined, _State) -> + ?ROSTER_LOG_REQ('Auth', check, ClientId, "Undefined token"), {error, invalid_token}; check(#mqtt_client{ @@ -75,8 +68,7 @@ check(#mqtt_client{ } = Auth) when Type == verified; Type == []; Type == expired -> - ?LOG_INFO("[WS Headers]: ~p", [Headers]), - ?LOG_INFO("~p:Auth:auth/check:token_equal:~p~n~p", [ClientId, WT, binary:part(Token,0,min(16,size(Token)))]), + ?ROSTER_LOG_REQ('Auth', check, ClientId, "Headers=~p, Topic=~p, Token=match", [Headers, WT]), emqttd_client:subscribe(ClientPid, [{roster:action_topic(ClientId), 2}]), IpF = #'Feature'{ id = <>, @@ -155,7 +147,7 @@ check(#mqtt_client{ token = Tok, phone = Phone } = Auth) -> - ?LOG_INFO("~p:Auth:auth/check:token_differ~p~n~p", [ClientId, WT, binary:part(Token, 0, min(16, size(Token)))]), + ?ROSTER_LOG_REQ('Auth', check, ClientId, "Topic=~p, Token=mismatch", [WT]), case roster:parse_token2(Token) of {error, invalid_token} -> @@ -187,7 +179,7 @@ check(#mqtt_client{ } = MqttClient, Token, State) -> - ?LOG_INFO("~p:Auth:auth/check:getting_auth:~p~n~p", [ClientId, WT, binary:part(Token,0,min(16,size(Token)))]), + ?ROSTER_LOG_REQ('Auth', check, ClientId, "Topic=~s", [WT]), %%%% case maybe_get_auth(State, ClientId) of {ok, Auth} -> @@ -212,11 +204,9 @@ check(#mqtt_client{ check(#mqtt_client{ client_id = <<"emqttd_", _/binary>> = ClientId, username = Username - }, - _, - _State) when Username /= <<"api">>, - Username /= <<"micro">> -> - ?LOG_INFO("~p:Auth:auth/check:invalid_username: ~p", [ClientId, Username]), + }, _, _State) when Username /= <<"api">>, + Username /= <<"micro">> -> + ?ROSTER_LOG_REQ('Auth', check, ClientId, "Invalid username: ~p", [Username]), {error, invalid_username}; check(_Client, _Password, _Opts) -> ignore. @@ -225,38 +215,21 @@ maybe_get_auth(#'Auth'{}=State, _ClientId) -> {ok, State}; maybe_get_auth(_State, ClientId) -> kvs:get('Auth', ClientId). -info(#'Auth'{ - type = reg, - token = [], - services = [], - phone = {fake, Phone} - } = Auth, - Req, - #cx{params = <<"reg_", _/binary>> = RegClientId} = State) -> +info(#'Auth'{ type = reg, token = [], services = [], phone = {fake, Phone} } = Auth, Req, + #cx{params = <<"reg_", _/binary>> = RegClientId} = State) -> ClientId = client(RegClientId), kvs:delete('Auth', ClientId), kvs:put(Auth2 = Auth#'Auth'{ phone = Phone, client_id = RegClientId }), - ?LOG_INFO("~p:~p:Auth/fake", [Phone, RegClientId]), - info(Auth2#'Auth'{ - type = verify, - token = [] - }, - Req, - State); - -info(#'Auth'{ - type = reg, - token = [], - services = Services, - phone = Phone - } = Auth, - Req, + ?ROSTER_LOG_REQ('Auth', fake_reg, RegClientId, "Phone=~s", [Phone]), + info(Auth2#'Auth'{ type = verify, token = [] }, Req, State); + +info(#'Auth'{ type = reg, token = [], services = Services, phone = Phone } = Auth, Req, #cx{params = <<"reg_", _/binary>> = RegClientId, - client_pid = C} = State) when Services == []; - Services == [jwt] -> + client_pid = C} = State) when Services == []; Services == [jwt] -> + ?ROSTER_LOG_REQ('Auth', reg, RegClientId, "Phone=~s", [Phone]), case kvs:get('Auth', RegClientId) of {error, _} -> case kvs:get('Auth', client(RegClientId)) of @@ -271,7 +244,6 @@ info(#'Auth'{ {reply, {bert, #io{ code = case check_fake_numbers(Phone) of {ok, _} -> - ?LOG_INFO("~p:~p:Auth/reg.FakeNumber", [Phone, RegClientId]), kvs:put(Auth#'Auth'{ sms_code = ?FAKE_SMS, attempts = ?MAX_ATTEMPTS, @@ -281,7 +253,6 @@ info(#'Auth'{ _ -> case check_whitelist(Phone) of {error, _} -> - ?LOG_INFO("~p:~p:Auth/reg.NotAllowed", [Phone, RegClientId]), #error{code = number_not_allowed}; {ok, _} -> Fun = case Services of @@ -294,14 +265,6 @@ info(#'Auth'{ attempts = ?MAX_ATTEMPTS, client_id = RegClientId }), - ?LOG_INFO( - "~p:~p:Auth/reg~p:~p", - [ - Phone, - RegClientId, - Services, - lists:sublist(binary_to_list(Codes), 16) - ]), case Services of [] -> roster:n2o_pid(?MODULE) ! {sms, Phone, Codes}, @@ -313,15 +276,9 @@ info(#'Auth'{ end }}, Req, State}; -info(#'Auth'{ - type = resend, - token = [], - dev_key = DevKey, - phone = Phone - }, - Req, - #cx{params = <<"reg_", _/binary>> = RegClientId} = State) when DevKey /= [] -> - ?LOG_INFO("~p:Auth/resend", [RegClientId]), +info(#'Auth'{ type = resend, token = [], dev_key = DevKey, phone = Phone }, Req, + #cx{params = <<"reg_", _/binary>> = RegClientId} = State) when DevKey /= [] -> + ?ROSTER_LOG_REQ('Auth', resend, RegClientId), {reply, {bert, #io{ code = case kvs:get('Auth', RegClientId) of {ok, #'Auth'{ @@ -347,16 +304,9 @@ info(#'Auth'{ #error{code = session_not_found} end}}, Req, State}; -info(#'Auth'{ - type = voice, - token = [], - services = [Lang], - phone = Phone, - dev_key = DevKey - }, - Req, - #cx{params = <<"reg_", _/binary>> = RegClientId} = State) -> - ?LOG_INFO("~p:~p:Auth/voice", [Phone, RegClientId]), +info(#'Auth'{ type = voice, token = [], services = [Lang], phone = Phone, dev_key = DevKey }, Req, + #cx{params = <<"reg_", _/binary>> = RegClientId} = State) -> + ?ROSTER_LOG_REQ('Auth', resend, RegClientId), {reply, {bert, #io{ code = case kvs:get('Auth', RegClientId) of {ok, #'Auth'{ @@ -372,16 +322,8 @@ info(#'Auth'{ #error{code = session_not_found} end}}, Req, State}; -info(#'Auth'{ - type = verify, - phone = Phone, - dev_key = DevKey, - settings = Settings, - services = Services, - sms_code = Code, - token = [] - }, - Req, +info(#'Auth'{ type = verify, phone = Phone, dev_key = DevKey, settings = Settings, + services = Services, sms_code = Code, token = [] }, Req, #cx{params = <<"reg_", _/binary>> = RegClientId} = State) when Code /= [], DevKey /= [], Settings /= [] -> @@ -394,7 +336,7 @@ info(#'Auth'{ } = Stored} -> case verify(Services, Code) of true -> - ?LOG_INFO("~p:~p:Auth/verify~p:~p", [Phone, RegClientId, Services, DevKey]), + ?ROSTER_LOG_REQ('Auth', verify, RegClientId, "Phone=~s, Services=~p, DevKey=~p", [Phone, Services, DevKey]), {roster, RosterId} = case kvs:get('Profile', Phone) of {ok, #'Profile'{ @@ -478,15 +420,9 @@ info(#'Auth'{ end, {reply, {bert, IO}, Req, State}; -info(#'Auth'{ - type = push, - push = Push, - os = OS, - settings = AuthSettings - }, - Req, +info(#'Auth'{ type = push, push = Push, os = OS, settings = AuthSettings }, Req, #cx{params = <<"emqttd_", _/binary>> = ClientId} = State) -> - ?LOG_INFO("~p:Auth/push.Request:~p:~p", [ClientId, OS, Push]), + ?ROSTER_LOG_REQ('Auth', push, ClientId, "OS=~p, Push=~p", [OS, Push]), R = case kvs:get('Auth', ClientId) of {ok, Auth2} -> %% check for push token uniqueness @@ -500,13 +436,11 @@ info(#'Auth'{ {error, _} -> #error{code = mismatch_user_data} end, - ?LOG_INFO("~p:Auth/push.Response:~p", [ClientId, R]), {reply, {bert, #io{code = R}}, Req, State}; -info(#'Auth'{type = clear}, - Req, - #cx{params = <<"emqttd_", _/binary>> = ClientId} = State) -> - ?LOG_INFO("~p:Auth/clear", [ClientId]), +info(#'Auth'{type = clear}, Req, + #cx{params = <<"emqttd_", _/binary>> = ClientId} = State) -> + ?ROSTER_LOG_REQ('Auth', clear, ClientId), IO = #io{ code = case kvs:get('Auth', ClientId) of {ok, #'Auth'{user_id = PhoneId}} -> @@ -522,20 +456,12 @@ info(#'Auth'{type = clear}, }, {reply, {bert, IO}, Req, State}; -info(#'Auth'{ - type = delete, - client_id = ClientId - }, - Req, +info(#'Auth'{ type = delete, client_id = ClientId }, Req, #cx{params = <<"emqttd_", _/binary>> = ClientId} = State) -> {reply, {bert, #io{code = #error{code = delete_active_session}}}, Req, State}; -info(#'Auth'{ - type = delete, - client_id = ClientId2 - } = Auth, - Req, - #cx{params = <<"emqttd_", _/binary>> = ClientId} = State) -> - ?LOG_INFO("~p:Auth/delete", [ClientId]), +info(#'Auth'{ type = delete, client_id = ClientId2 } = Auth, Req, + #cx{params = <<"emqttd_", _/binary>> = ClientId} = State) -> + ?ROSTER_LOG_REQ('Auth', delete, ClientId), IO = case kvs:get('Auth', ClientId) of {ok, #'Auth'{user_id = PhoneId}} -> case [roster:force_logout(A) || #'Auth'{client_id = ClId} = A <- kvs:index('Auth', user_id, PhoneId), ClId == ClientId2] of @@ -549,10 +475,8 @@ info(#'Auth'{ end, {reply, {bert, IO}, Req, State}; -info(#'Auth'{type = get}, - Req, - #cx{params = <<"emqttd_", _/binary>> = ClientId} = State) -> - ?LOG_INFO("~p:Auth/get", [ClientId]), +info(#'Auth'{type = get}, Req, #cx{params = <<"emqttd_", _/binary>> = ClientId} = State) -> + ?ROSTER_LOG_REQ('Auth', get, ClientId), IO = case kvs:get('Auth', ClientId) of {ok, #'Auth'{user_id = PhoneId}} -> [ @@ -564,10 +488,8 @@ info(#'Auth'{type = get}, end, {reply, {bert, IO}, Req, State}; -info(#'Auth'{type = logout}, - Req, - #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:Auth/logout", [ClientId]), +info(#'Auth'{type = logout}, Req, #cx{params = ClientId} = State) -> + ?ROSTER_LOG_REQ('Auth', logout, ClientId), D = case ClientId of <<"emqttd_", _/binary>> -> case kvs:get('Auth', ClientId) of @@ -582,10 +504,8 @@ info(#'Auth'{type = logout}, end, {reply, D, Req, State}; -info(#'Auth'{phone = Phone} = Auth, - Req, - #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:~p:Auth/unknown:~p", [Phone, ClientId, Auth]), +info(#'Auth'{type = Type, phone = Phone}, Req, #cx{params = ClientId} = State) -> + ?ROSTER_LOG_REQ('Auth', Type, ClientId, "Unknown request, Phone=~p", [Phone]), {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State}. %% roster_auth handlers diff --git a/apps/roster/src/protocol/roster_bpe.erl b/apps/roster/src/protocol/roster_bpe.erl index 31a8e7a9e..23052e1d5 100644 --- a/apps/roster/src/protocol/roster_bpe.erl +++ b/apps/roster/src/protocol/roster_bpe.erl @@ -17,7 +17,7 @@ start() -> n2o_async:start(#handler{module = ?MODULE, class = system, group = ro info(#'History'{roster_id = Roster, feed = Feed, size = N, entity_id = MId, status = get} = Data, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:~p:History/get:~p", [Roster, ClientId, Feed]), + ?ROSTER_LOG_REQ('History', get, ClientId, "Feed=~p, N=~p, MId=~p", [Feed, N, MId]), PhoneId = roster:phone_id(ClientId), %FId = roster:roster_id(Roster), %N0=case N of Size when N < -8 -> -7; _ when MId=:=0 -> -7; Size when N > 8 -> 7; Size -> Size end, @@ -72,7 +72,7 @@ info(#'History'{roster_id = Roster, feed = Feed, size = N, entity_id = MId, stat info(#'Job'{id = [], feed_id = {act, <<"publish">>, PhoneId} = Feed, time = [], data = [#'Message'{} | _] = Msgs, status = init} = RequestData, R, #cx{params = ClientId} = S) -> - ?LOG_INFO("Job/init:~p", [Feed]), + ?ROSTER_LOG_REQ('Job', init, ClientId, "Feed=~p", [Feed]), %J = J0#'Job'{id = Id = kvs:next_id('Job', 1)}, Replay = case roster:phone_id(ClientId) of PhoneId -> %roster:restart_module(Pid,?MODULE), @@ -84,7 +84,7 @@ info(#'Job'{id = [], feed_id = {act, <<"publish">>, PhoneId} = Feed, time = [], info(#'Job'{id = [], feed_id = {act, <<"roster">>,PhoneId} = Feed, time = [], data = Actions, status = init} = RequestData, R, #cx{params = ClientId} = S) -> - ?LOG_INFO("Job/init:~p", [Feed]), + ?ROSTER_LOG_REQ('Job', init, ClientId, "Feed=~p", [Feed]), %J = J0#'Job'{id = Id = kvs:next_id('Job', 1)}, Replay = case roster:phone_id(ClientId) of PhoneId ->[ action(A, R, S) || A <-Actions]; @@ -98,7 +98,7 @@ info(#'Job'{id = [], feed_id = {act, <<"publish">>, PhoneId} = Feed, time = Time #cx{params = ClientId} = S) -> %J = J0#'Job'{id = Id = kvs:next_id('Job', 1)}, Current = roster:now_msec(), - ?LOG_INFO("Create Job :~p :Time ~p", [Feed, roster:msToUT(Time)]), + ?ROSTER_LOG_REQ('Job', init, ClientId, "Feed=~p, Time=~p", [Feed, roster:msToUT(Time)]), % Size=length(D0), %{D,T}=lists:split( case Size > ?JOBS_MS_LIMIT of true -> ?JOBS_MS_LIMIT; false -> Size end, D0), D = D0, @@ -119,9 +119,9 @@ info(#'Job'{id = [], feed_id = {act, <<"publish">>, PhoneId} = Feed, time = Time end, {reply, {bert, Replay}, R, S}; -info(#'Job'{id = Id, time = T0, feed_id = {act, <<"publish">>, PhoneId}, data = D, settings = Stt, status = update} = RequestData, R, +info(#'Job'{id = Id, time = T0, feed_id = {act, <<"publish">>, PhoneId} = Feed, data = D, settings = Stt, status = update} = RequestData, R, #cx{params = ClientId, client_pid = C} = S) -> - ?LOG_INFO("UPDATE Time:~p", [roster:msToUT(T0)]), + ?ROSTER_LOG_REQ('Job', update, ClientId, "Feed=~p, Time=~p", [Feed, roster:msToUT(T0)]), Current = roster:now_msec(), Replay = case roster:phone_id(ClientId) of PhoneId when T0 > Current -> @@ -154,13 +154,13 @@ info(#'Job'{id = Id, time = T0, feed_id = {act, <<"publish">>, PhoneId}, data = {reply, {bert, Replay}, R, S}; -info(#'Job'{proc = Proc, data = <<"stop">>, status = update} = M, R, S) -> - ?LOG_INFO("STOP:~w", [M]), +info(#'Job'{proc = Proc, data = <<"stop">>, status = update}, R, #cx{params = ClientId} = S) -> + ?ROSTER_LOG_REQ('Job', update, ClientId, "stop"), Docs = #'act'{data = <<"stop">>}, {reply, {bert, {io, bpe:amend(Proc, Docs, noflow), <<>>}}, R, S}; -info(#'Job'{proc = Proc, data = D, time = Time, events = [], status = restart} = J0, R, S) -> - ?LOG_INFO("UPDATE :~w", [J0]), +info(#'Job'{proc = Proc, data = D, time = Time, events = [], status = restart}, R, #cx{params = ClientId} = S) -> + ?ROSTER_LOG_REQ('Job', restart, ClientId, "Data=~p, Time=~p", [D, roster:msToUT(Time)]), P = bpe:load(Proc), % bpe:find_pid(Proc) ! {'DOWN', <<>>, <<>>, <<>>, <<>>}, T = calendar:time_difference(erlang:universaltime(), roster:msToUT(Time)), @@ -170,7 +170,7 @@ info(#'Job'{proc = Proc, data = D, time = Time, events = [], status = restart} = info(#'Job'{id = Id, feed_id = {act, <<"publish">>, UID} = Feed, status = delete} = RequestData, R, #cx{params = ClientId, client_pid = C} = S) -> - ?LOG_INFO("JOB delete:~w", [Feed]), + ?ROSTER_LOG_REQ('Job', delete, ClientId, "Feed=~p", [Feed]), PhoneId = roster:phone_id(ClientId), D = case kvs:get('Job', Id) of {ok, #'Job'{feed_id = {act, <<"publish">>, PhoneId}} = J} when UID == PhoneId -> @@ -187,8 +187,8 @@ info(#'Job'{id = Id, feed_id = {act, <<"publish">>, UID} = Feed, status = delete %timer:apply_after(Time, bpe, cleanup, [Id]), {reply, {bert, D}, R, S}; -info(#'Job'{feed_id = Feed} = RequestData, R, S) -> - ?LOG_INFO("~p::Job/unknown", [Feed]), +info(#'Job'{feed_id = Feed, status = Status} = RequestData, R, #cx{params = ClientId} = S) -> + ?ROSTER_LOG_REQ('Job', Status, ClientId, "Unknown request, Feed=~p", [Feed]), {reply, {bert, roster_channel_helper:error_response_400(RequestData) %% #io{code = #error{code = invalid_data}} }, R, S}; diff --git a/apps/roster/src/protocol/roster_favorite.erl b/apps/roster/src/protocol/roster_favorite.erl index cc47393d7..e0afd8031 100644 --- a/apps/roster/src/protocol/roster_favorite.erl +++ b/apps/roster/src/protocol/roster_favorite.erl @@ -5,20 +5,20 @@ -compile(export_all). info(#'Tag'{status = create} = Tag, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:Tag/create:~p", [ClientId, Tag]), + ?ROSTER_LOG_REQ('Tag', create, ClientId), {reply, {bert, Tag}, Req, State}; info(#'Tag'{status = remove} = Tag, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:Tag/remove:~p", [ClientId, Tag]), + ?ROSTER_LOG_REQ('Tag', remove, ClientId), {reply, {bert, Tag}, Req, State}; info(#'Tag'{status = edit} = Tag, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:Tag/edit:~p", [ClientId, Tag]), + ?ROSTER_LOG_REQ('Tag', edit, ClientId), {reply, {bert, Tag}, Req, State}; info(#'ExtendedStar'{}, Req, #cx{params = ClientId, client_pid = C} = State) -> - RosterId = roster:roster_id(PhoneId = roster:phone_id(ClientId)), - ?LOG_INFO("~p:ExtendedStar/get:~p", [ClientId, PhoneId]), + RosterId = roster:roster_id(roster:phone_id(ClientId)), + ?ROSTER_LOG_REQ('ExtendedStar', "", ClientId), IO = case kvs:get('Roster', RosterId) of #error{} = Err -> #io{code = Err}; {ok, #'Roster'{favorite = Favs} = Roster} -> @@ -29,7 +29,7 @@ info(#'ExtendedStar'{}, Req, #cx{params = ClientId, client_pid = C} = State) -> {reply, {bert, IO}, Req, State}; info(#'Star'{status = add, message = #'Message'{id = MsgId} = Msg} = Data, Req, #cx{params = ClientId, client_pid = C} = State) -> - ?LOG_INFO("~p:Star/add:~p", [ClientId, Data]), + ?ROSTER_LOG_REQ('Star', add, ClientId, "MsgId=~p", [MsgId]), RosterId = roster:roster_id(PhoneId = roster:phone_id(ClientId)), IO = case kvs:get('Roster', RosterId) of {ok, #'Roster'{favorite = StFavMsgs} = Roster} -> @@ -46,8 +46,8 @@ info(#'Star'{status = add, message = #'Message'{id = MsgId} = Msg} = Data, Req, end, {reply, {bert, IO}, Req, State}; -info(#'Star'{id = MsgId, status = remove} = Data, Req, #cx{params = ClientId, client_pid = C} = State) -> - ?LOG_INFO("~p:Star/remove:~p", [ClientId, Data]), +info(#'Star'{id = MsgId, status = remove}, Req, #cx{params = ClientId, client_pid = C} = State) -> + ?ROSTER_LOG_REQ('Star', remove, ClientId, "MsgId=~p", [MsgId]), Response = case kvs:get('Roster', roster:roster_id(ClientId)) of {ok, #'Roster'{favorite = StFavMsgs} = Roster} -> case lists:keyfind(MsgId, #'Star'.id, StFavMsgs) of @@ -60,7 +60,6 @@ info(#'Star'{id = MsgId, status = remove} = Data, Req, #cx{params = ClientId, cl end; #error{} -> #io{code = #error{code = roster_not_found}} end, - ?LOG_INFO("Debug.Response:~p", [Response]), {reply, {bert, Response}, Req, State}; info(#'Star'{} = Star, Req, #cx{params = ClientId} = State) -> diff --git a/apps/roster/src/protocol/roster_friend.erl b/apps/roster/src/protocol/roster_friend.erl index 092301498..7e3587fea 100644 --- a/apps/roster/src/protocol/roster_friend.erl +++ b/apps/roster/src/protocol/roster_friend.erl @@ -10,6 +10,7 @@ start() -> n2o_async:start(#handler{module = ?MODULE, class = system, group = ro info(#'Friend'{phone_id = Me, friend_id = Friend, settings = FriendSettings, status = request}, {Req, handled}, #cx{params = ClientId, client_pid = C} = State) -> + ?ROSTER_LOG_REQ('Friend', request, ClientId, "Me=~s, Friend=~s", [Me, Friend]), [From, FromId] = roster:parts_phone_id(Me), [To, ToId] = roster:parts_phone_id(Friend), {ok, FromR} = kvs:get('Roster', FromId), @@ -30,7 +31,6 @@ info(#'Friend'{phone_id = Me, friend_id = Friend, settings = FriendSettings, sta roster:send_ses(C, To, roster:presence(#'Contact'{reader = Rs} = roster:readmsgs(Mec, Friend))), roster:send_ses(C, From, roster:presence(Friendc#'Contact'{reader = lists:reverse(Rs)})), n2o_async:pid(system, ?MODULE) ! {send_push, Me, Friend, <<"request">>}, - ?LOG_INFO("~p:~p:Friend/request:~p", [Me, ClientId, Friend]), <<>> end end, @@ -54,7 +54,7 @@ info(#'Friend'{phone_id = Me, status = request} = F, Req, #cx{params = ClientId} info(#'Friend'{friend_id = Friend, status = ignore}, Req, #cx{params = ClientId, client_pid = C} = State) -> Me = roster:phone_id(ClientId), - ?LOG_INFO("~p:~p:Friend/ignore:~p", [Me, ClientId, Friend]), + ?ROSTER_LOG_REQ('Friend', ignore, ClientId, "Friend=~s", [Friend]), IO = case roster:get_contact(Me, Friend) of {error, _} = E -> #io{code = E}; #'Contact'{status = authorization} = Contact -> @@ -67,7 +67,7 @@ info(#'Friend'{friend_id = Friend, status = ignore}, Req, #cx{params = ClientId, info(#'Friend'{friend_id = Friend, phone_id = Sender, status = confirm}, Req, #cx{params = ClientId, client_pid = C} = State) -> Me = case ClientId of <<"sys_", _/binary>> -> Sender; <<"emqttd_", _/binary>> -> roster:phone_id(ClientId) end, - ?LOG_INFO("~p:Friend/confirm:~p:~p", [ClientId, Me, Friend]), + ?ROSTER_LOG_REQ('Friend', confirm, ClientId, "Me=~s, Friend=~s", [Me, Friend]), [{ok, #'Roster'{phone = From} = FromR}, {ok, #'Roster'{phone = To} = ToR}] = [kvs:get('Roster', roster:roster_id(PId)) || PId <- [Me, Friend]], D = case {roster:get_contact(FromR, Friend), roster:get_contact(ToR, Me)} of @@ -102,7 +102,7 @@ info(#'Friend'{friend_id = Friend, phone_id = Sender, status = confirm}, Req, #c info(#'Friend'{friend_id = Friend, status = Status}, Req, #cx{params = ClientId, client_pid = C} = State) when Status == ban; Status == unban -> Me = roster:phone_id(ClientId), - ?LOG_INFO("~p:Friend/~p:~p:~p", [ClientId, Status, Me, Friend]), + ?ROSTER_LOG_REQ('Friend', Status, ClientId, "Friend=~s", [Friend]), [From, FromId] = roster:parts_phone_id(Me), [To, ToId] = roster:parts_phone_id(Friend), [_Tos, Froms] = [emqttd_pubsub:subscribers(roster:ses_topic(P)) || P <- [To, From]], @@ -141,8 +141,8 @@ info(#'Friend'{friend_id = Friend, status = Status}, Req, {reply, {bert, IO}, Req, State}; info(#'Friend'{phone_id = PhoneId, friend_id = Friend, settings = NewSets, status = update}, Req, - #cx{client_pid = C, params = ClientId} = State) -> - ?LOG_INFO("~p:Friend/update:~p", [ClientId, Friend]), + #cx{client_pid = C, params = ClientId} = State) -> + ?ROSTER_LOG_REQ('Friend', update, ClientId, "Friend=~s", [Friend]), IO = case roster:phone_id(ClientId) of PhoneId -> case kvs:get('Roster', roster:roster_id(PhoneId)) of {ok, #'Roster'{userlist = Contacts} = Roster} -> @@ -165,9 +165,9 @@ info(#'Friend'{phone_id = PhoneId, friend_id = Friend, settings = NewSets, statu {reply, {bert, IO}, Req, State}; -info(#'Friend'{phone_id = Roster} = F, Req, State) -> - ?LOG_INFO("~p:~p:Friend/unknown", [Roster, F]), - {reply, {bert, <<>>}, Req, State}. +info(#'Friend'{status = Status}, Req, State = #cx{params = ClientId}) -> + ?ROSTER_LOG_REQ('Friend', Status, ClientId, "Unknown request"), + {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State}. proc(init, #handler{name = ?MODULE} = Async) -> ?LOG_INFO("ASYNC", []), diff --git a/apps/roster/src/protocol/roster_history.erl b/apps/roster/src/protocol/roster_history.erl index cd0284d26..ba1af15f8 100644 --- a/apps/roster/src/protocol/roster_history.erl +++ b/apps/roster/src/protocol/roster_history.erl @@ -12,9 +12,9 @@ start() -> n2o_async:start(#handler{module = ?MODULE, class = system, group = ro % Main Logic Section -info(#'History'{roster_id = RosterId, feed = #'StickerPack'{} = Feed, size = N, status = get} = Data, Req, +info(#'History'{roster_id = RosterId, feed = #'StickerPack'{}, size = N, status = get} = Data, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:~p:History/get:~p", [RosterId, ClientId, Feed]), + ?ROSTER_LOG_REQ('History', get, ClientId, "N=~p, Feed=StickerPack", [N]), Stickers = case kvs:get('Roster', roster:roster_id(RosterId)) of {ok, #'Roster'{}} -> S = kvs:all('StickerPack'), case N of [] -> S; _ -> lists:sublist(S, N) end; %%TODO Temporary all sticker packs @@ -23,15 +23,15 @@ info(#'History'{roster_id = RosterId, feed = #'StickerPack'{} = Feed, size = N, info(#'History'{status = get_reply, entity_id = Id} = History, Req, #cx{params = ClientId} = State) when Id /= [] -> - PhoneId = roster:phone_id(ClientId), - ?LOG_INFO("~p:~p:History/get_reply:~p", [PhoneId, ClientId, Id]), + ?ROSTER_LOG_REQ('History', get_reply, ClientId, "Id=~p", [Id]), Msgs = case kvs:get('Message', Id) of {ok, #'Message'{repliedby = [_|_] = Replyes}} -> [case kvs:get('Message', ReplId) of {ok, Msg} -> Msg; _ -> [] end || ReplId<-Replyes]; _ -> [] end, {reply, {bert, History#'History'{data = lists:flatten(Msgs)}}, Req, State}; info(#'History'{status = double_get, size = N, entity_id = MId, data = []} = History, Req, - #cx{} = State) when N > 0, MId > 0 -> + #cx{params = ClientId} = State) when N > 0, MId > 0 -> + ?ROSTER_LOG_REQ('History', double_get, ClientId), {reply, {bert, #'History'{data = Msgs1}}, _, _} = info(History#'History'{status = get, size = N}, Req, State), {reply, {bert, #'History'{data = Msgs2}}, _, _} = @@ -42,12 +42,13 @@ info(#'History'{status = double_get, size = N, entity_id = MId, data = []} = His {_, [_ | Msgs2x]} -> Msgs1 ++ Msgs2x end, {reply, {bert, History#'History'{ data = Msgs, size = length(Msgs) }}, Req, State}; -info(#'History'{status = Status, data = Msgs} = History, Req, #cx{state = []} = State) - when Status == image; Status == video; Status == file; Status == link; Status == audio; - Status == contact; Status == location; Status == get_lost; Status == text -> +info(#'History'{status = Status, data = Msgs} = History, Req, #cx{params = ClientId, state = []} = State) + when Status == image; Status == video; Status == file; Status == link; Status == audio; + Status == contact; Status == location; Status == get_lost; Status == text -> + ?ROSTER_LOG_REQ('History', Status, ClientId), info(History#'History'{status = get, - data = [Msg#'Message'{files = [#'Desc'{mime = atom_to_binary(Status, latin1)}]} || #'Message'{} = Msg<-Msgs]}, - Req, State#cx{state = {status, Status}}); + data = [Msg#'Message'{files = [#'Desc'{mime = atom_to_binary(Status, latin1)}]} || #'Message'{} = Msg<-Msgs]}, + Req, State#cx{state = {status, Status}}); info(#'History'{status = get} = History, Req, #cx{state = []} = State) -> info(History, Req, State#cx{state = {status, get}}); info(#'History'{status = get, feed = [], data = [#'Message'{feed_id = Feed}|_]} = History, Req, State) when Feed /= []-> @@ -57,7 +58,7 @@ info(#'History'{status = get, roster_id = Roster0, feed = Feed, size = N, entity when N /= 0 andalso (is_record(Feed, p2p) orelse is_record(Feed, muc)) andalso (MsgData == [] andalso InitialStatus == get orelse MsgData /= []) -> PhoneId = roster:phone_id(ClientId), - ?LOG_INFO("~p:~p:History/get:~p:~p", [PhoneId, ClientId, Feed, History]), + ?ROSTER_LOG_REQ('History', get, ClientId, "N=~p, Id=~p, Feed=~p", [N, MId, Feed]), {UID, R, LastMsgId, _Unit} = case PhoneId == Roster0 of true -> roster:get_feed_data(Feed, PhoneId); @@ -65,131 +66,127 @@ info(#'History'{status = get, roster_id = Roster0, feed = Feed, size = N, entity end, IO = case UID of - error -> ?LOG_INFO("History/get.Error:~p", [R]), + error -> + ?LOG_INFO("Error: ~p", [R]), #io{code = #error{code = R}}; _ -> - try %% Fix indentation later! - {N2, FId} = - case {N, MsgData} of - {_, [#'Message'{id = MId}]} when is_integer(MId) -> - throw({error, invalid_data}); - {_, [#'Message'{id = FinishId}]} when is_integer(FinishId), FinishId /= MId -> - K = FinishId-MId, - {case is_integer(N) of true -> round(abs(N)*abs(K)/K); _ -> K end, FinishId}; - {[], []} -> - #writer{count = Count} = kvs_stream:load_writer(Feed), - {case MId > 0 of true -> Count; _ -> -Count end, []}; - _ -> - {N, []} - end, - Reader = #reader{cache = Cache} = kvs_stream:load_reader(R), %% load the reader - %% Set starting point, 0 means do it automatically - MId2 = - case MId of - %% N > 0 means going forward find cached or first MsgId (if any) - 0 when N>0 andalso N/=[] andalso Cache/=[] -> {_, MsId} = Cache, MsId; - 0 when N>0 andalso N/=[] -> - case kvs:get(writer, Feed) of - {ok, #writer{first=#'Message'{id = MsId}}} -> MsId; - _ -> LastMsgId %% Last resort, there are no messages in this Feed?! - end; - 0 -> LastMsgId; - _ -> MId - end, - %% Normalize if MId was too large... - StartId = min(MId2, LastMsgId), + try + {N2, FId} = + case {N, MsgData} of + {_, [#'Message'{id = MId}]} when is_integer(MId) -> + throw({error, invalid_data}); + {_, [#'Message'{id = FinishId}]} when is_integer(FinishId), FinishId /= MId -> + K = FinishId-MId, + {case is_integer(N) of true -> round(abs(N)*abs(K)/K); _ -> K end, FinishId}; + {[], []} -> + #writer{count = Count} = kvs_stream:load_writer(Feed), + {case MId > 0 of true -> Count; _ -> -Count end, []}; + _ -> + {N, []} + end, + Reader = #reader{cache = Cache} = kvs_stream:load_reader(R), %% load the reader + %% Set starting point, 0 means do it automatically + MId2 = + case MId of + %% N > 0 means going forward find cached or first MsgId (if any) + 0 when N>0 andalso N/=[] andalso Cache/=[] -> {_, MsId} = Cache, MsId; + 0 when N>0 andalso N/=[] -> + case kvs:get(writer, Feed) of + {ok, #writer{first=#'Message'{id = MsId}}} -> MsId; + _ -> LastMsgId %% Last resort, there are no messages in this Feed?! + end; + 0 -> LastMsgId; + _ -> MId + end, + %% Normalize if MId was too large... + StartId = min(MId2, LastMsgId), - %% History limits are encoded in the reader of a member. The - %% message corresponding to #reader.pos = 1 is the first - %% message the member is allowed to read. So, to make sure we - %% respect the history limit we need to know the reader - %% position of StartId, if any. Fail if StartId is before - %% history limit. If StartId is unread we handle reader pos in - %% FoldFun. - Reader1 = - case roster:message_within_history_limit(StartId, Reader) of - unread -> Reader; - {reader_pos, P} -> Reader#reader{pos = P, cache = {'Message', StartId}}; - forbidden -> throw({error, invalid_data}) - end, + %% History limits are encoded in the reader of a member. The + %% message corresponding to #reader.pos = 1 is the first + %% message the member is allowed to read. So, to make sure we + %% respect the history limit we need to know the reader + %% position of StartId, if any. Fail if StartId is before + %% history limit. If StartId is unread we handle reader pos in + %% FoldFun. + Reader1 = + case roster:message_within_history_limit(StartId, Reader) of + unread -> Reader; + {reader_pos, P} -> Reader#reader{pos = P, cache = {'Message', StartId}}; + forbidden -> throw({error, invalid_data}) + end, - {Mime, MatchMime} = - case MsgData of - [#'Message'{files = [#'Desc'{mime = Mime1 = <<_:8, _/binary>>}]}] -> - {Mime1, fun(#'Message'{files = Descs}) -> - lists:keymember(Mime1, #'Desc'.mime, Descs) - end}; - _ -> - {[], fun(_) -> true end} - end, + {Mime, MatchMime} = + case MsgData of + [#'Message'{files = [#'Desc'{mime = Mime1 = <<_:8, _/binary>>}]}] -> + {Mime1, fun(#'Message'{files = Descs}) -> + lists:keymember(Mime1, #'Desc'.mime, Descs) + end}; + _ -> + {[], fun(_) -> true end} + end, - Dir = case N2 > 0 of true -> fwd; false -> bwd end, + Dir = case N2 > 0 of true -> fwd; false -> bwd end, - AccFun = fun(Msg, Count, Acc) -> - case roster:msg_filter(Msg, UID) > 0 andalso MatchMime(Msg) of - false -> {Count, Acc}; - true -> {Count - 1, [roster:wrap_msg(Msg) | Acc]} - end end, + AccFun = fun(Msg, Count, Acc) -> + case roster:msg_filter(Msg, UID) > 0 andalso MatchMime(Msg) of + false -> {Count, Acc}; + true -> {Count - 1, [roster:wrap_msg(Msg) | Acc]} + end end, - FoldFun = - case Dir of - fwd -> - fun(_, {0, _, Acc}) -> {stop, Acc}; - (#'Message'{id = Id}, {_, _, Acc}) when Id > FId -> {stop, Acc}; - (Msg, {Count, _Unused, Acc}) -> - {Count1, Acc1} = AccFun(Msg, Count, Acc), - {cont, {Count1, unused, Acc1}} - end; - bwd -> - IsInSync = - case Reader1 of - #reader{cache = {'Message', CursorId}} -> - fun(#'Message'{id = Id}) -> Id =< CursorId end; - _ -> - fun(_) -> false end - end, - fun(_, {0, _, Acc}) -> {stop, Acc}; - (#'Message'{id = Id}, {_, _, Acc}) when is_integer(FId), Id < FId -> {stop, Acc}; - (Msg, {Count, Pos, Acc}) -> - {Count1, Acc1} = AccFun(Msg, Count, Acc), - InSync = IsInSync(Msg), %% If we started on an unread message we might - Pos1 = if InSync -> Pos - 1; true -> Pos end, %% not yet be in sync with the reader pos. - if InSync, Pos =< 0 -> {stop, Acc}; %% Reached history limit - true -> {cont, {Count1, Pos1, Acc1}} - end - end - end, + FoldFun = + case Dir of + fwd -> + fun(_, {0, _, Acc}) -> {stop, Acc}; + (#'Message'{id = Id}, {_, _, Acc}) when Id > FId -> {stop, Acc}; + (Msg, {Count, _Unused, Acc}) -> + {Count1, Acc1} = AccFun(Msg, Count, Acc), + {cont, {Count1, unused, Acc1}} + end; + bwd -> + IsInSync = + case Reader1 of + #reader{cache = {'Message', CursorId}} -> + fun(#'Message'{id = Id}) -> Id =< CursorId end; + _ -> + fun(_) -> false end + end, + fun(_, {0, _, Acc}) -> {stop, Acc}; + (#'Message'{id = Id}, {_, _, Acc}) when is_integer(FId), Id < FId -> {stop, Acc}; + (Msg, {Count, Pos, Acc}) -> + {Count1, Acc1} = AccFun(Msg, Count, Acc), + InSync = IsInSync(Msg), %% If we started on an unread message we might + Pos1 = if InSync -> Pos - 1; true -> Pos end, %% not yet be in sync with the reader pos. + if InSync, Pos =< 0 -> {stop, Acc}; %% Reached history limit + true -> {cont, {Count1, Pos1, Acc1}} + end + end + end, - Msgs0 = - case roster:fold_stream('Message', FoldFun, StartId, {abs(N2), Reader1#reader.pos, []}, Dir) of - {ok, Ms} -> Ms; - {eos, {_, _, Ms}} -> Ms - end, - Msgs = case Dir of bwd -> lists:reverse(Msgs0); fwd -> Msgs0 end, + Msgs0 = + case roster:fold_stream('Message', FoldFun, StartId, {abs(N2), Reader1#reader.pos, []}, Dir) of + {ok, Ms} -> Ms; + {eos, {_, _, Ms}} -> Ms + end, + Msgs = case Dir of bwd -> lists:reverse(Msgs0); fwd -> Msgs0 end, - Msgs2 = - case is_integer(MId) of - true when MId > 0, Mime == [] -> - case kvs:get('Message', MId) of - {ok, #'Message'{} = EntityMsg} -> - lists:reverse(lists:ukeymerge(#'Message'.id, lists:reverse(Msgs), - [EntityMsg#'Message'{files = []}])); - {error, _} -> - ?LOG_INFO("message ~p not found", [MId]), - #error{code = invalid_data} - end; - _ -> Msgs - end, -%% ResponseMsgs = case MId of %%TODO remove this after testing -%% 0 -> -%%%% nullify Message.next for last message in query -%%%% [LastMsgObject, ] = lists:reverse(Msgs2), -%% LastMsgObject = lists:last(Msgs2), -%% lists:sublist(Msgs2, length(Msgs2) -1) ++ [LastMsgObject#'Message'{next = []}]; -%% _ -> Msgs2 end, -%% CheckedResponseMsgs = [roster:check_message(Msg) || Msg <- ResponseMsgs], - case Msgs2 of #error{} = E -> #io{code = E}; _ -> - History#'History'{data = Msgs2, size = length(Msgs2), status = InitialStatus} end + Msgs2 = + case is_integer(MId) of + true when MId > 0, Mime == [] -> + case kvs:get('Message', MId) of + {ok, #'Message'{} = EntityMsg} -> + lists:reverse(lists:ukeymerge(#'Message'.id, lists:reverse(Msgs), + [EntityMsg#'Message'{files = []}])); + {error, _} -> + ?LOG_INFO("message ~p not found", [MId]), + #error{code = invalid_data} + end; + _ -> Msgs + end, + case Msgs2 of + #error{} = E -> #io{code = E}; + _ -> + History#'History'{data = Msgs2, size = length(Msgs2), status = InitialStatus} + end catch throw:#error{} = Err -> #io{code = Err} end @@ -200,7 +197,7 @@ info(#'History'{status = update, feed = Feed, entity_id = MId}, Req, #cx{client_pid = C, params = ClientId, state = verified} = State) -> PhoneId = roster:phone_id(ClientId), From = roster:phone(PhoneId), - ?LOG_INFO("~p:History/update:~p,~p", [From, Feed, MId]), + ?ROSTER_LOG_REQ('History', update, ClientId, "Id=~p, Feed=~p", [MId, Feed]), {UID, R, LastMsgId, Unit} = roster:get_feed_data(Feed, PhoneId), MId2 = case MId > LastMsgId of true -> LastMsgId; _ -> MId end, {Unread, UpdReader} = @@ -208,7 +205,7 @@ info(#'History'{status = update, feed = Feed, entity_id = MId}, Req, {ok, #reader{cache = []} = Rdr0} -> W = #writer{count = Count, first = #'Message'{}} = kvs_stream:load_writer(Feed), case Count of - 0 -> ?LOG_INFO("ThereAreNotMessages:~p", [W]), <<>>; + 0 -> ?LOG_INFO("There are no messages: ~p", [W]), <<>>; _ -> Rdr = kvs_stream:bot((Rdr0#reader{dir = 0})), Reader = kvs_stream:save(roster:mover(Rdr, {'Message', MId2})), {roster:nentries(kvs:get('Message', MId2), Count + 1, UID) - roster:nentries(kvs:get('Message', MId2), 0, UID), Reader} @@ -252,15 +249,18 @@ info(#'History'{status = update, feed = Feed, entity_id = MId}, Req, {reply, {bert, D}, Req, State#cx{state = []}}; info(#'History'{status = update, entity_id = MId} = History, Req, #cx{} = State) when MId == 0; MId == []-> info(History, Req, State#cx{state = verified}); -info(#'History'{status = update, feed = Feed, entity_id = MId} = History, Req, #cx{} = State) -> +info(#'History'{status = update, feed = Feed, entity_id = MId} = History, Req, #cx{params = ClientId} = State) -> case kvs:get('Message', MId) of {ok, #'Message'{feed_id = Feed}} -> info(History, Req, State#cx{state = verified}); - _ -> {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State} end; + _ -> + ?ROSTER_LOG_REQ('History', update, ClientId, "Feed=~p, Invalid message: ~p", [Feed, MId]), + {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State} + end; info(#'History'{feed = Feed, status = delete}, Req, #cx{client_pid = C, params = ClientId} = State) -> PhoneId = roster:phone_id(ClientId), - ?LOG_INFO("~p:History/delete:~p", [PhoneId, Feed]), + ?ROSTER_LOG_REQ('History', delete, ClientId, "Feed=~p", [Feed]), IO = case clean_history(Feed, PhoneId) of #error{} = Res -> #io{code = Res}; {_Unread, #'Message'{}=Internal} -> @@ -274,19 +274,19 @@ info(#'History'{feed = Feed, status = delete}, Req, #cx{client_pid = C, params = info(#'History'{roster_id = PhoneId, status = draft}, Req, #cx{params = ClientId} = State) -> PhoneId = roster:phone_id(ClientId), + ?ROSTER_LOG_REQ('History', draft, ClientId), IO = case kvs:get('Roster', roster:roster_id(PhoneId)) of {ok, #'Roster'{userlist = Conts, roomlist = Rooms}} -> RMs=[M|| #'Room'{last_msg = M}<-Rooms], CMs=[M|| #'Contact'{last_msg = M}<-Conts], #'Draft'{data=lists:flatten(CMs++RMs), status = get}; E -> #io{code = E} end, - ?LOG_INFO("~p:History/draft:~p", [PhoneId, IO]), {reply, {bert, IO}, Req, State}; -info(#'History'{} = Data, Req, State) -> - ?LOG_INFO("History/unknown:~p", [Data]), - {reply, {bert, <<>>}, Req, State}. +info(#'History'{status = Status}, Req, #cx{params = ClientId} = State) -> + ?ROSTER_LOG_REQ('History', Status, ClientId, "Unknown request"), + {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State}. % Helper Section diff --git a/apps/roster/src/protocol/roster_link.erl b/apps/roster/src/protocol/roster_link.erl index 4cb2ed867..70176a81b 100644 --- a/apps/roster/src/protocol/roster_link.erl +++ b/apps/roster/src/protocol/roster_link.erl @@ -11,9 +11,9 @@ % ====================================== % API % ====================================== -info(#'Link'{id = LinkId, type = group, status = join = LStatus} = RequestData, - Req, #cx{params = ClientId} = State) when LinkId /= [] -> - ?LOG_INFO("~p:Link/~p:~p", [ClientId, LStatus, RequestData]), +info(#'Link'{id = LinkId, type = group, status = join}, Req, + #cx{params = ClientId} = State) when LinkId /= [] -> + ?ROSTER_LOG_REQ('Link', join, ClientId, "Id=~p, Type=group", [LinkId]), LD=kvs:get('Link',LinkId), Res = case get_entity(LD) of {ok, #'Room'{id = RoomId, last_msg = MsgId} = Room} -> @@ -29,59 +29,56 @@ info(#'Link'{id = LinkId, type = group, status = join = LStatus} = RequestData, NewRoom#'Room'{members = [roster:muc_member(PhoneId,RoomId) | Members], links=[Link], admins = Admins, last_msg = LastMsg, status=joined }; {error, not_found} = Err -> #io{code = Err} end, - ?LOG_INFO("Link/~p.Response:~p", [Res, LStatus]), - {reply, {bert, Res}, Req, State}; + {reply, {bert, Res}, Req, State}; -info(#'Link'{id = LinkId, status = get = LStatus} = RequestData, - Req, #cx{params = ClientId} = State) when LinkId /= [] -> - ?LOG_INFO("~p:Link/~p:~p", [ClientId, LStatus, RequestData]), - LD=kvs:get('Link',LinkId), - Res = case get_entity(LD) of - {ok, #'Room'{id = RoomId, last_msg = MsgId} = Room} -> - {Admins, Members} = roster:split_members(roster:members(#muc{name = RoomId}, active)), - LastMsg = case kvs:get('Message', MsgId) of - {ok, Message} -> Message; - {error, not_found} -> [] - end, - {ok,Link}=LD, - Room#'Room'{members = Members, admins = Admins, links=[Link], last_msg = LastMsg, status = info}; - {error, not_found} = Err -> #io{code = Err} - end, - ?LOG_INFO("Link/~p.Response:~p", [Res, LStatus]), +info(#'Link'{id = LinkId, status = get}, Req, + #cx{params = ClientId} = State) when LinkId /= [] -> + ?ROSTER_LOG_REQ('Link', get, ClientId, "Id=~p", [LinkId]), + LD = kvs:get('Link',LinkId), + Res = case get_entity(LD) of + {ok, #'Room'{id = RoomId, last_msg = MsgId} = Room} -> + {Admins, Members} = roster:split_members(roster:members(#muc{name = RoomId}, active)), + LastMsg = case kvs:get('Message', MsgId) of + {ok, Message} -> Message; + {error, not_found} -> [] + end, + {ok, Link} = LD, + Room#'Room'{members = Members, admins = Admins, links=[Link], last_msg = LastMsg, status = info}; + {error, not_found} = Err -> + #io{code = Err} + end, {reply, {bert, Res}, Req, State}; %% NOTE - Not used at the moment, to be finished in next release % -info(#'Link'{id = LinkId, room_id = RoomId, status = update = LStatus} = RequestData, +info(#'Link'{id = LinkId, room_id = RoomId, status = update} = RequestData, Req, #cx{params = ClientId} = State) when RoomId /= [], LinkId /= [] -> - ?LOG_INFO("~p:Link/~p:~p", [ClientId, LStatus, RequestData]), - Res = case roster:muc_member(ClientId, RoomId) of - #'Member'{status = Status} when Status == owner; Status == admin -> - case update_link(RequestData) of - {error, _} = Err -> #io{code = Err}; - NewLink -> NewLink - end; - #'Member'{status = member} -> - #io{code = #error{code = permission_denied}}; - _ -> - #io{code = #error{code = invalid_data}} - end, - ?LOG_INFO("Link/~p.Response:~p", [Res, LStatus]), + ?ROSTER_LOG_REQ('Link', update, ClientId, "Id=~p, RoomId=~p", [LinkId, RoomId]), + Res = case roster:muc_member(ClientId, RoomId) of + #'Member'{status = Status} when Status == owner; Status == admin -> + case update_link(RequestData) of + {error, _} = Err -> #io{code = Err}; + NewLink -> NewLink + end; + #'Member'{status = member} -> + #io{code = #error{code = permission_denied}}; + _ -> + #io{code = #error{code = invalid_data}} + end, {reply, {bert, Res}, Req, State}; %% NOTE - Not used at the moment, to be finished in next release % -info(#'Link'{type = group, status = delete = LStatus} = RequestData, +info(#'Link'{type = group, status = delete}, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:Link/~p:~p", [ClientId, LStatus, RequestData]), - % Res = delete_link(ClientId, RequestData), - Res = #io{code = #error{code = permission_denied}}, - ?LOG_INFO("Link/~p.Response:~p", [Res, LStatus]), - {reply, {bert, Res}, Req, State}; + ?ROSTER_LOG_REQ('Link', delete, ClientId, "Type=group"), + % Res = delete_link(ClientId, RequestData), + Res = #io{code = #error{code = permission_denied}}, + {reply, {bert, Res}, Req, State}; -info(#'Link'{} = RequestData, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:Link/unknown:~p", [ClientId, RequestData]), - {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State}. +info(#'Link'{status = Status}, Req, #cx{params = ClientId} = State) -> + ?ROSTER_LOG_REQ('Link', Status, ClientId, "Unknown request"), + {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State}. % ====================================== % Helper functions @@ -89,25 +86,25 @@ info(#'Link'{} = RequestData, Req, #cx{params = ClientId} = State) -> update_link(#'Link'{id = NewLinkId, room_id = RoomId, type = NewType}) -> case get_link(kvs:get('Room', RoomId)) of - #'Link'{id = NewLinkId, room_id = RoomId} = Link -> + #'Link'{id = NewLinkId, room_id = RoomId} = Link -> kvs:put(NewLink = Link#'Link'{type = NewType}), NewLink#'Link'{status = update}; - #'Link'{id = CurrentLink, room_id = RoomId} = Link -> + #'Link'{id = CurrentLink, room_id = RoomId} = Link -> case kvs:get('Link', NewLinkId) of - {error, not_found} -> + {error, not_found} -> ok = kvs:delete('Link', CurrentLink), kvs:put(NewLink = Link#'Link'{id = NewLinkId, type = NewType, created = roster:now_msec()}), NewLink#'Link'{status = update}; - {ok, _} -> + {ok, _} -> {error, link_already_exists} end; - {error, not_found} -> + {error, not_found} -> {error, invalid_data}; - E -> + E -> E end. diff --git a/apps/roster/src/protocol/roster_message.erl b/apps/roster/src/protocol/roster_message.erl index c56d6d4c1..d96cd2d77 100644 --- a/apps/roster/src/protocol/roster_message.erl +++ b/apps/roster/src/protocol/roster_message.erl @@ -13,13 +13,13 @@ start() -> n2o_async:start(#handler{module = ?MODULE, class = system, group = roster, name = ?MODULE, state = []}). -info(#'Typing'{phone_id = Phone, comments = Comments}, Req, - #cx{} = State) -> - ?LOG_INFO("~p:Typing/:~p", [Phone, Comments]), +info(#'Typing'{phone_id = Phone, comments = Comments}, Req, #cx{params = ClientId} = State) -> + ?ROSTER_LOG_REQ('Typing', "", ClientId, "Phone=~s, Comments=~p", [Phone, Comments]), {reply, {bert, <<>>}, Req, State}; -info(#'Message'{msg_id=MsgID, files=Descs, status=Status, feed_id = F} = M, Req, #cx{state=[]}=State) when MsgID /= [], Status/=update-> - ?LOG_INFO("~p:~p:Message/:~p", [MsgID, State, Status]), +info(#'Message'{msg_id = MsgID, files = Descs, status = Status, feed_id = F, to = To} = M, Req, + #cx{params = ClientId, state = []} = State) when MsgID /= [], Status /= update-> + ?ROSTER_LOG_REQ('Message', Status, ClientId, "ClientMsgId=~s, State=[], To=~s", [MsgID, To]), case {kvs:index('Message', msg_id, MsgID), has_flag(Descs, message_ack)} of {[#'Message'{id = ServerId, feed_id = Feed, next = Next}], true} -> {reply, {bert, #'MessageAck'{id = ServerId, @@ -43,7 +43,9 @@ info(#'Message'{feed_id = #muc{name = To}, to = []} = RequestData, Req, State) w info(RequestData#'Message'{to = To}, Req, #cx{state=ack}=State); info(#'Message'{status = [], id = [], feed_id = F, from=From0, to = To, type = Type, msg_id = ClientMsgId, files = Descs} = Msg, - Req, #cx{client_pid = C, params = ClientId, state=ack} = State) -> + Req, #cx{client_pid = C, params = ClientId, state=ack} = State) -> + ?ROSTER_LOG_REQ('Message', [], ClientId, "ClientMsgId=~s, Files=~p", + [ClientMsgId, [PL || #'Desc'{payload = PL} <- Descs]]), try From = case hd(binary:split(ClientId, <<"_">>)) of <<"sys">> -> From0; @@ -168,7 +170,8 @@ info(#'Message'{status = edit, id = Id, msg_id = ClMID, feed_id = Feed, from = F files = [#'Desc'{} | _] = Descs}, Req, #cx{params = ClientId, client_pid = C, state=ack} = State) -> PhoneId = roster:phone_id(ClientId, From), - ?LOG_INFO("~p:Message/edit:~p", [PhoneId, To]), + ?ROSTER_LOG_REQ('Message', edit, ClientId, "ClientMsgId=~s, MsgId=~p, Files=~p", + [ClMID, Id, [PL || #'Desc'{payload = PL} <- Descs]]), DV = length([D || D = #'Desc'{id = ID} <- Descs, is_binary(ID), ID /= <<>>]) == length(Descs), Data = case kvs:get('Message', Id) of @@ -222,9 +225,9 @@ info(#'Message'{status = edit, id = Id, msg_id = ClMID, feed_id = Feed, from = F info(#'Message'{id = Id, msg_id = ClMID, feed_id = Feed, from = From0, seenby = Seen, status = delete}, Req, #cx{params = ClientId, client_pid = C, state=ack} = State) when is_integer(Id) -> - ?LOG_INFO("~p:~p:Message/delete:~p", [Feed, From0, Id]), + ?ROSTER_LOG_REQ('Message', delete, ClientId, "ClientMsgId=~s, MsgId=~p, Feed=~p", [ClMID, Id, Feed]), %%TODO for security From= - PhoneId = roster:phone_id(ClientId, From0), + PhoneId = roster:phone_id(ClientId, From0), D = case kvs:get('Message', Id) of {ok, #'Message'{type=[sys|_]}} -> #io{code = #error{code = invalid_data}}; @@ -323,7 +326,8 @@ info(#'Message'{status = update, type = [draft], feed_id = Feed0, from = From, t files = File}=M, Req, #cx{params = ClientId, client_pid = C, state=ack} = State) -> PhoneId = case ClientId of <<"sys_bpe">> -> From; <<"emqttd_", _/binary>> -> roster:phone_id(ClientId) end, - ?LOG_INFO("~p:Message/Draft:~p", [PhoneId, Feed0]), + ?ROSTER_LOG_REQ('Message', update, ClientId, "Type=draft, Feed=~p, Files=~p", + [Feed0, [PL || #'Desc'{payload = PL} <- File]]), {Feed,M1,D}=case File of [] -> {Feed0,[],#'Draft'{data =[M], status = delete}}; [#'Desc'{} | _] -> @@ -353,14 +357,15 @@ info(#'Message'{status = update, type = [draft], feed_id = Feed0, from = From, t info(#'Message'{status = update, id = Id, files = [#'Desc'{mime = <<"transcribe">>, payload = [], data = Data} = Desc | _]} = Msg, Req, #cx{params = ClientId, state = ack} = State) when is_integer(Id), not is_tuple(Req) -> + ?ROSTER_LOG_REQ('Message', update, ClientId, "Type=transcribe, Id=~p", [Id]), Type = case roster:get_data_val(<<"TYPE">>, Data) of [] -> short; T -> binary_to_atom(T, utf8) end, Lang = roster:get_data_val(?LANG_KEY, Data), Pid = n2o_async:pid(system, roster_message), case kvs:get('Message', Id) of - {ok, #'Message'{feed_id = Feed, from = From, to = To, files = [#'Desc'{mime = <<"audio">>, payload = Uri} | _]}} -> - ?LOG_INFO("enter ~p transcribe process with ~p", [Type, Uri]), - ErrMsg = #'Message'{id = Id, feed_id = Feed, from = From, to = To}, - case Type of + {ok, #'Message'{feed_id = Feed, from = From, to = To, files = [#'Desc'{mime = <<"audio">>, payload = Uri} | _]}} -> + ?LOG_INFO("enter ~p transcribe process with ~p, (Lang=~p)", [Type, Uri, Lang]), + ErrMsg = #'Message'{id = Id, feed_id = Feed, from = From, to = To}, + case Type of short -> spawn(fun() -> Res = @@ -405,7 +410,7 @@ info(#'Message'{status = update, id = Id, feed_id = Feed, from = From, files = [#'Desc'{id = ID, payload = Payload, data = Data, mime = DMime} = ND | _]}, Req, #cx{params = ClientId, client_pid = C, state=ack} = State) when is_integer(Id) -> PhoneId = case ClientId of <<"sys_bpe">> -> From; <<"emqttd_", _/binary>> -> roster:phone_id(ClientId) end, - ?LOG_INFO("~p:Message/update:~p", [PhoneId, Id]), + ?ROSTER_LOG_REQ('Message', update, ClientId, "Id=~p", [Id]), Lang = roster:get_data_val(?LANG_KEY, Data), IO = case kvs:get('Message', Id) of {ok, #'Message'{feed_id = Feed, files = Descs} = Msg} -> @@ -453,8 +458,8 @@ info(#'Message'{status = update, id = Id, feed_id = Feed, from = From, {reply, {bert, IO}, Req, State}; -info(#'Message'{from = From, to = To} = ReqData, Req, State) -> - ?LOG_INFO("~p:~p:Message/unknown:~p", [From, To, {ReqData, Req}]), +info(#'Message'{from = From, to = To, status = Status}, Req, #cx{params = ClientId} = State) -> + ?ROSTER_LOG_REQ('Message', Status, ClientId, "Unknown request, From=~p, To=~p", [From, To]), {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State}. proc(init, #handler{name = roster_message} = Async) -> @@ -486,8 +491,8 @@ proc({#'Message'{status = update} = Msg, ClientId}, #handler{state = C} = H) -> ?LOG_INFO("UPDATE TRANSCRIBE: ~p", [Msg]), try {reply, {bert, IO}, _, _} = info(Msg, {[], handled}, #cx{params = ClientId, client_pid = C, state = ack}), roster:send_action(C, ClientId, IO) - catch Err:Rea -> - ?LOG_ERROR(":~p~n", [n2o:stack_trace(Err, Rea)]) + catch Err:Rea:Sta -> + ?LOG_ERROR("~p:~p:~p", [Err, Rea, Sta]) end, {reply, [], H}; proc({mqttc, C, connected}, State = #handler{state = C, seq = S}) -> {ok, State#handler{seq = S + 1}}; diff --git a/apps/roster/src/protocol/roster_presence.erl b/apps/roster/src/protocol/roster_presence.erl index 1b169ab05..bf0245696 100644 --- a/apps/roster/src/protocol/roster_presence.erl +++ b/apps/roster/src/protocol/roster_presence.erl @@ -5,17 +5,17 @@ -include_lib("rest_static.hrl"). -compile(export_all). -info(#'Presence'{status=Status} = RequestData, Req, #cx{params = ClientId, client_pid = C} = State) -> - ?LOG_INFO("~p:Presence/Status:~p", [ClientId, RequestData]), +info(#'Presence'{status = Status}, Req, #cx{params = ClientId, client_pid = C} = State) -> + ?ROSTER_LOG_REQ('Presence', Status, ClientId), {reply, {bert, send_presence(Status, roster:phone_id(ClientId), C)}, Req, State}. on_connect(Phone, ClientId, C)-> on_connect(Phone, ClientId, C, ?VERSION). on_connect(Phone, ClientId, C, Ver) -> - ?LOG_INFO("~p:~p:CONNECT with Version:~p", [Phone, ClientId,Ver]), + ?LOG_INFO("CONNECT ~s: Phone=~s, Version=~s", [ClientId, Phone, Ver]), try case send_presence(online, Phone, C, ClientId) of {error, profile_not_found} -> - ?LOG_INFO("~p:~p:Connect:ProfileNotFound", [Phone, ClientId]), + ?LOG_INFO("CONNECT ~s: ProfileNotFound", [ClientId]), roster:delete_sessions(Phone); #'Profile'{} when Ver == ?VERSION -> roster:send_cache(ClientId, C); @@ -24,13 +24,13 @@ on_connect(Phone, ClientId, C, Ver) -> roster:send_profile(P2, [], 0, ClientId, C), roster:send_cache(ClientId, C) end - catch Err:Rea -> - ?LOG_INFO("Catch:~p", [n2o:stack_trace(Err, Rea)]) + catch Err:Rea:Sta -> + ?LOG_INFO("Catch: ~p", [{Err, Rea, Sta}]) end. on_disconnect(#'Auth'{type = Type, phone = Phone, client_id = ClientId}, C) when Type == logout; Type == disconnect -> - ?LOG_INFO("~p:~p:DISCONNECT - ~p", [Phone, ClientId, Type]), + ?LOG_INFO("DISCONNECT ~s: Phone=~s, Type=~p", [ClientId, Phone, Type]), send_presence(offline, Phone, C, ClientId), roster:unsubscribe_client(ClientId), case Type == disconnect andalso should_preserve_auth_record(ClientId) of @@ -40,7 +40,7 @@ on_disconnect(#'Auth'{type = Type, phone = Phone, client_id = ClientId}, C) roster:final_disconnect(ClientId); on_disconnect(#'Auth'{phone = Phone, client_id = ClientId, type=Type}, C) -> - ?LOG_INFO("~p:~p:DISCONNECT:~p", [Phone, ClientId, Type]), + ?LOG_INFO("DISCONNECT ~s: Phone=~s, Type=~p", [ClientId, Phone, Type]), send_presence(offline, Phone, C, ClientId). on_verify(_ClientId, _PhoneId) -> ok. @@ -68,7 +68,6 @@ send_presence(Status, Phone, C, ClientId) when Status == online; Status == offli [do_send_presence(C, RId, MkContact) || RId <- Rosters], P2; _ -> - ?LOG_INFO("~p:~p:~p",[Phone, ClientId,P]), P end; _ -> {error, profile_not_found} diff --git a/apps/roster/src/protocol/roster_profile.erl b/apps/roster/src/protocol/roster_profile.erl index 66d270a12..f97a2e286 100644 --- a/apps/roster/src/protocol/roster_profile.erl +++ b/apps/roster/src/protocol/roster_profile.erl @@ -23,42 +23,46 @@ start() -> n2o_async:start(#handler{ %% _ -> #io{code=#error{code=invalid_data}} end, %% {reply, {bert, D}, Req, State}; -info(#'Profile'{status=patch, phone=Phone, balance = Balance} = Data, Req, - #cx{params = ClientId} = State) when Balance >= 0 -> - ?LOG_INFO("~p:~p:Profile/patch", [Phone,ClientId]), - Res = case kvs:get('Profile', Phone) of - {ok, #'Profile'{}=Profile} -> - P = roster:patch_profile(Profile, Data), - kvs:put(P#'Profile'{status = []}), - P#'Profile'{status = patch, rosters = []}; - {error, _} = E -> #io{code = E} end, - {reply, {bert, Res}, Req, State}; - -info(#'Profile'{status = delete, phone=UID, rosters = [_|_]=Rs }=Data, Req, - #cx{params = ClientId, client_pid = C} = State) -> - ?LOG_INFO("~p:~p:Profile/remove:~s", [UID,ClientId,io_lib:format("~p",[Data])]), - case kvs:get('Profile',UID) of - {ok,#'Profile'{rosters=Rosters}=P}-> - NewRosters=(Rosters--Rs), - case Rosters--NewRosters of - [] -> {reply, {bert, {io, {error, roster_not_found}, <<>>}}}; - List -> Deleted=lists:flatten([begin PId=roster:phone_id(UID,X), - [begin [UIDF, FId]=roster:parts_phone_id(Friend), - roster:update_contact(FId,Cont=#'Contact'{phone_id = PId, reader = Rd, nick= <<"Deleted user">>, status=deleted}), - roster:send_ses(C, UIDF, Cont) end - || #'Contact'{phone_id = Friend, reader = Rd} <- roster:get_contacts(X), Friend =/=PId], - roster:send_ses(C, UID, #'Roster'{id = X, status=del}), - del_roster(UID,X) end - || X<- List ]), +info(#'Profile'{status = patch, phone = Phone, balance = Balance} = Data, Req, + #cx{params = ClientId} = State) when Balance >= 0 -> + ?ROSTER_LOG_REQ('Profile', patch, ClientId, "Phone=~s, Balance=~p", [Phone, Balance]), + Res = case kvs:get('Profile', Phone) of + {ok, #'Profile'{}=Profile} -> + P = roster:patch_profile(Profile, Data), + kvs:put(P#'Profile'{status = []}), + P#'Profile'{status = patch, rosters = []}; + {error, _} = E -> #io{code = E} + end, + {reply, {bert, Res}, Req, State}; + +info(#'Profile'{status = delete, phone = UID, rosters = [_|_] = Rs }, Req, + #cx{params = ClientId, client_pid = C} = State) -> + ?ROSTER_LOG_REQ('Profile', delete, ClientId, "Phone=~s, Rosters=~p", [UID, Rs]), + case kvs:get('Profile',UID) of + {ok,#'Profile'{rosters=Rosters}=P}-> + NewRosters=(Rosters--Rs), + case Rosters--NewRosters of + [] -> {reply, {bert, {io, {error, roster_not_found}, <<>>}}}; + List -> + Deleted = lists:flatten( + [ begin + PId=roster:phone_id(UID,X), + [begin [UIDF, FId]=roster:parts_phone_id(Friend), + roster:update_contact(FId,Cont=#'Contact'{phone_id = PId, reader = Rd, nick= <<"Deleted user">>, status=deleted}), + roster:send_ses(C, UIDF, Cont) + end || #'Contact'{phone_id = Friend, reader = Rd} <- roster:get_contacts(X), Friend =/=PId], + roster:send_ses(C, UID, #'Roster'{id = X, status=del}), + del_roster(UID,X) + end || X <- List ]), % TODO kvs:put if Profile will not have information about deleted accounts NewP=P#'Profile'{rosters=Rosters--Deleted}, - {reply, {bert, NewP}, Req, State} end; - {error, R} -> {reply, {bert, {io, {error, R}, <<>>}}, Req, State} end; + {reply, {bert, NewP}, Req, State} + end; + {error, R} -> {reply, {bert, {io, {error, R}, <<>>}}, Req, State} + end; - -info(#'Profile'{status = remove, phone = Phone}=Data, Req, - #cx{params = ClientId, client_pid = C} = State) -> - ?LOG_INFO("~p:~p:Profile/remove:~s", [Phone,ClientId,io_lib:format("~p",[Data])]), +info(#'Profile'{status = remove, phone = Phone}, Req, #cx{params = ClientId, client_pid = C} = State) -> + ?ROSTER_LOG_REQ('Profile', remove, ClientId, "Phone=~s", [Phone]), case kvs:get('Profile',Phone) of {ok,#'Profile'{rosters=Rosters}} -> [ begin PhoneId=roster:phone_id(Phone,X), [begin [PhoneF, _]=roster:parts_phone_id(Friend), @@ -71,19 +75,10 @@ info(#'Profile'{status = remove, phone = Phone}=Data, Req, {reply, {bert, P}, Req, State}; {error, R} -> {reply, {bert, {io, {error, R}, <<>>}}, Req, State} end; -info(#'Profile'{ - status = get, - update = LastSync, - settings = Settings - } = P2, - Req, - #cx{ - params = ClientId, - client_pid = ClientPid - } = State) -> - ?LOG_INFO("~p:Profile/get.Request/enter:~p", [ClientId, P2]), +info(#'Profile'{ status = get, update = LastSync, settings = Settings }, Req, + #cx{ params = ClientId, client_pid = ClientPid } = State) -> Phone = roster:phone(ClientId), - ?LOG_INFO("~p:Profile/get.Request:~p", [ClientId, Phone]), + ?ROSTER_LOG_REQ('Profile', get, ClientId, "Phone=~s", [Phone]), R = case kvs:get('Profile', Phone) of {ok, #'Profile'{} = P} -> Size = case {LastSync, catch binary_to_integer(roster:get_data_val(<<"size">>, Settings))} of @@ -91,19 +86,10 @@ info(#'Profile'{ {Time, V} when Time =< 1 -> V; {_, _} -> ?DEFAULT_ROSTER_SIZE end, - {Timer, _Result} = timer:tc(roster, send_profile, - [ - P#'Profile'{ - status = get, - update = LastSync, - settings = roster_presence:amazon_settings(P) - }, - Size, - LastSync, - ClientId, - ClientPid - ]), - ?LOG_INFO("timer_send_profile in microseconds ~p", [Timer]), + roster:send_profile(P#'Profile'{ status = get, + update = LastSync, + settings = roster_presence:amazon_settings(P) }, + Size, LastSync, ClientId, ClientPid), <<>>; {error, Reason} -> #io{code = #error{code = Reason}} diff --git a/apps/roster/src/protocol/roster_room.erl b/apps/roster/src/protocol/roster_room.erl index 4410a2d1d..ebe9436ce 100644 --- a/apps/roster/src/protocol/roster_room.erl +++ b/apps/roster/src/protocol/roster_room.erl @@ -22,10 +22,10 @@ info(#'Room'{status = create, id = Room, admins = [Admin|_], type=Type} = R, Req info(R#'Room'{status = add, id = Room}, Req, State#cx{state = create}); info(#'Room'{status = create, id = <>, name = Name, admins = [_Owner], members = []} = R, Req, - #cx{params = <<"emqttd_", _/binary>>=ClientId} = State) -> + #cx{params = <<"emqttd_", _/binary>>=ClientId} = State) -> + ?ROSTER_LOG_REQ('Room', create, ClientId, "Name=~s (single room)", [Name]), Length = length(unicode:characters_to_list(Name)), ExistingRoom = element(1, kvs:get('Room', Room)) == error, - ?LOG_INFO("~p:Room/create single room:~p", [ClientId, Name]), if not(Length >= ?MIN_ROOM_LENGTH) -> {reply, {bert, #io{code = #error{code = room_name_too_short}}}, Req, State}; not(Length =< ?MAX_ROOM_LENGTH) -> {reply, {bert, #io{code = #error{code = room_name_too_long}}}, Req, State}; not(ExistingRoom) -> {reply, {bert, #io{code = #error{code = room_already_exists}}}, Req, State}; @@ -38,8 +38,8 @@ info(#'Room'{status = create, id = <>, name = Name, admins = [_Owne info(#'Room'{status = create, id = <>, name = Name, admins = [Owner|TA]= Admins, members = Members} = R, Req, #cx{params = ClientId} = State) -> Length = length(unicode:characters_to_list(Name)), - ?LOG_INFO("~p:Room/create:~p", [ClientId, Name]), - Prefix = hd(binary:split(ClientId, <<"_">>)), + ?ROSTER_LOG_REQ('Room', create, ClientId, "Name=~s", [Name]), + Prefix = hd(binary:split(ClientId, <<"_">>)), case Length >= ?MIN_ROOM_LENGTH andalso Length =< ?MAX_ROOM_LENGTH andalso element(1, kvs:get('Room', Room)) == error andalso roster:is_unimembers(Admins ++ Members) @@ -60,7 +60,7 @@ info(#'Room'{status = create, id = <>, name = Name, admins = [Owner _ -> {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State} end; info(#'Room'{status = patch, id = Room, name = Name, data = AvatarDesc} = R, Req, #cx{params = ClientId, client_pid = C} = State) when Room /= [] -> - ?LOG_INFO("~p:Room/patch:~p", [ClientId, R]), + ?ROSTER_LOG_REQ('Room', patch, ClientId, "Id=~s, Name=~s", [Room, Name]), roster:verify_descs(AvatarDesc), {reply, {bert, case kvs:get('Room', Room) of @@ -116,7 +116,7 @@ info(#'Room'{status = patch, id = Room, name = Name, data = AvatarDesc} = R, Req end}, Req, State}; info(#'Member'{status = patch, id = Id} = Member, Req, #cx{params = ClientId, from = From} = State) -> - ?LOG_INFO("~p:Member/patch:~p", [ClientId, Member]), + ?ROSTER_LOG_REQ('Member', patch, ClientId, "Id=~s", [Id]), PhoneId = roster:phone_id(ClientId), {IO, Topic} = case kvs:get('Member', Id) of @@ -124,26 +124,31 @@ info(#'Member'{status = patch, id = Id} = Member, Req, #cx{params = ClientId, fr kvs:put(M2 = roster:patch_member(M, Member)), {roster:reader_cache(M2#'Member'{status = patch}), roster:room_topic(Room)}; {ok, #'Member'{}} -> {#io{code = #error{code = permission_denied}}, From}; - #error{} -> {#io{code = #error{code = member_not_found}}, From} end, + #error{} -> {#io{code = #error{code = member_not_found}}, From} + end, {reply, {bert, IO}, Req, State#cx{from = Topic}}; info(#'Room'{status = St, id = Room, members = Members, admins = Admins, readers = HL}, Req, #cx{params = ClientId, client_pid = C, state = RStatus} = State) when (St == add orelse (St == join andalso RStatus /= create)) andalso (Members /= [] orelse Admins /= []) -> - ?LOG_INFO("~p:Room/~p:~p", [ClientId, St, Room]), - APId = case Prefix = hd(binary:split(ClientId, <<"_">>)) of - <<"sys">> when St == add andalso Admins /= [] orelse St == join -> - (hd(case St of join -> Members; _ -> Admins end))#'Member'.phone_id; - <<"emqttd">> -> roster:phone_id(ClientId); - _ -> [] - end, + ?ROSTER_LOG_REQ('Room', St, ClientId, "Id=~s, State=~p, Adm=~p, Mem=~p", + [Room, RStatus, + [PId || #'Member'{phone_id = PId} <- Admins], + [PId || #'Member'{phone_id = PId} <- Members]]), + {IsSys, APId} = + case ClientId of + <<"sys", _/binary>> when St == add andalso Admins /= [] orelse St == join -> + {true, (hd(case St of join -> Members; _ -> Admins end))#'Member'.phone_id}; + <<"emqttd", _/binary>> -> {false, roster:phone_id(ClientId)}; + _ -> {false, []} + end, IO = case kvs:get('Room', Room) of {ok, #'Room'{} = StoredRoom} -> case roster:muc_member(APId, Room) of Mmbr when RStatus == create orelse St == join orelse (is_record(Mmbr, 'Member') andalso (Mmbr#'Member'.status == admin) orelse - Mmbr#'Member'.status == removed andalso Prefix == <<"sys">>) -> + Mmbr#'Member'.status == removed andalso IsSys) -> {Mmbrs, Aliases, NewMmbrs, StoredRoom2} = lists:foldl( fun(#'Member'{phone_id = PhoneId, status = Status} = Member, {Ms, Alss, NewMs, TmpRoom}) @@ -233,11 +238,14 @@ info(#'Room'{status = St, id = Room, members = Members, admins = Admins, readers info(#'Room'{status = remove, members = Members, admins = Admins0, id = Room}, Req, #cx{params = ClientId, client_pid = C} = State) -> - ?LOG_INFO("~p:Room/remove:~p", [ClientId, Room]), - {APId, Admins} = case hd(binary:split(ClientId, <<"_">>)) of - <<"sys">> -> {(hd(Admins0))#'Member'.phone_id, []}; - <<"emqttd">> -> {roster:phone_id(ClientId), Admins0} - end, + ?ROSTER_LOG_REQ('Room', remove, ClientId, "Id=~s, Adm=~p, Mem=~p", + [Room, [PId || #'Member'{phone_id = PId} <- Admins0], + [PId || #'Member'{phone_id = PId} <- Members]]), + {APId, Admins} = + case ClientId of + <<"sys", _/binary>> -> {(hd(Admins0))#'Member'.phone_id, []}; + <<"emqttd", _/binary>> -> {roster:phone_id(ClientId), Admins0} + end, IO = case kvs:get('Room', Room) of {ok, #'Room'{} = StoredRoom} -> case roster:muc_member(APId, Room) of @@ -278,7 +286,7 @@ info(#'Room'{status = remove, members = Members, admins = Admins0, id = Room}, R info(#'Room'{status = delete, members = [], admins = [], id = RoomId} = Room, Req, #cx{params = <<"sys_", _/binary>> = ClientId, client_pid = C} = State) -> - ?LOG_INFO("~p:Room/delete:~p", [ClientId, RoomId]), + ?ROSTER_LOG_REQ('Room', delete, ClientId, "Id=~s", [RoomId]), case kvs_stream:load_writer(Feed = #muc{name = RoomId}) of #writer{cache = #'Message'{id = LastMsgId}} -> Fun = fun(#'Message'{type = [sys | _]}, _) -> {cont, false}; @@ -322,7 +330,7 @@ info(#'Room'{status = delete, members = [], admins = [], id = RoomId} = Room, Re {reply, {bert, <<>>}, Req, State}; info(#'Room'{status = leave, id = RoomId}, Req, #cx{params = ClientId, client_pid = C} = State) -> - ?LOG_INFO("~p:Room/leave:~p", [ClientId, RoomId]), + ?ROSTER_LOG_REQ('Room', leave, ClientId, "Id=~s", [RoomId]), {reply, {bert, case kvs:get('Room', RoomId) of {ok, #'Room'{} = Room1} -> @@ -364,41 +372,53 @@ info(#'Room'{status = leave, id = RoomId}, Req, #cx{params = ClientId, client_pi end}, Req, State}; info(#'Room'{status = get, id = Room}, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:Room/get:~p", [ClientId, Room]), - {reply, {bert, case kvs:get('Room', Room) of - {ok, #'Room'{} = R} -> - case roster:muc_member(ClientId, Room) of - #'Member'{id = Id, reader = Reader} = M -> - {As, Ms} = roster:split_members(roster:members(#muc{name = Room}, presence)), - case roster:member_lastmsg(M) of - {error, _} = Err -> #io{code = Err}; - {_, LM} -> {Unread, _LM, _} = roster:unread_msg({'Message', LM}, Reader, Id), - roster:reader_cache(R#'Room'{status = get, last_msg = [], unread = Unread, links=[roster_link:get_link({ok,R})], - members = Ms, admins = As}) end; - _ -> #io{code = #error{code = permission_denied}} end; - #error{} -> #io{code = #error{code = room_not_found}} end}, Req, State}; + ?ROSTER_LOG_REQ('Room', get, ClientId, "Id=~s", [Room]), + IO = + case kvs:get('Room', Room) of + {ok, #'Room'{} = R} -> + case roster:muc_member(ClientId, Room) of + #'Member'{id = Id, reader = Reader} = M -> + {As, Ms} = roster:split_members(roster:members(#muc{name = Room}, presence)), + case roster:member_lastmsg(M) of + {error, _} = Err -> #io{code = Err}; + {_, LM} -> {Unread, _LM, _} = roster:unread_msg({'Message', LM}, Reader, Id), + roster:reader_cache(R#'Room'{status = get, last_msg = [], unread = Unread, links=[roster_link:get_link({ok,R})], + members = Ms, admins = As}) + end; + _ -> #io{code = #error{code = permission_denied}} + end; + #error{} -> #io{code = #error{code = room_not_found}} + end, + {reply, {bert, IO}, Req, State}; info(#'Room'{status = Mute, id = Room}, Req, #cx{params = ClientId, client_pid = C} = State) when Mute == mute;Mute == unmute -> - ?LOG_INFO("~p:Room/~p:~p", [ClientId, Mute, Room]), + ?ROSTER_LOG_REQ('Room', Mute, ClientId, "Id=~s", [Room]), Mute2 = case Mute of mute -> Mute;_ -> [] end, - {reply, {bert, case roster:muc_member(ClientId, Room) of - #'Member'{phone_id = PhoneId} -> - [Phone, RosterId] = roster:parts_phone_id(PhoneId), - case kvs:get('Roster', RosterId) of - {ok, #'Roster'{roomlist = Rooms} = Roster} -> - #'Room'{} = R = lists:keyfind(Room, #'Room'.id, Rooms), - kvs:put(Roster#'Roster'{roomlist = - lists:ukeymerge(#'Room'.id, [R#'Room'{status = Mute2}], Rooms)}), - roster:send_ses(C, Phone, R#'Room'{status = Mute}), <<>>; - #error{} -> #io{code = #error{code = roster_not_found}} end; - _ -> #io{code = #error{code = not_member}} end}, Req, State}; + IO = + case roster:muc_member(ClientId, Room) of + #'Member'{phone_id = PhoneId} -> + [Phone, RosterId] = roster:parts_phone_id(PhoneId), + case kvs:get('Roster', RosterId) of + {ok, #'Roster'{roomlist = Rooms} = Roster} -> + #'Room'{} = R = lists:keyfind(Room, #'Room'.id, Rooms), + Roomlist = lists:ukeymerge(#'Room'.id, [R#'Room'{status = Mute2}], Rooms), + kvs:put(Roster#'Roster'{roomlist = Roomlist}), + roster:send_ses(C, Phone, R#'Room'{status = Mute}), + <<>>; + #error{} -> + #io{code = #error{code = roster_not_found}} + end; + _ -> + #io{code = #error{code = not_member}} + end, + {reply, {bert, IO}, Req, State}; -info(#'Room'{} = Room, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:Room/unknown:~p", [ClientId, Room]), +info(#'Room'{status = Status, id = Room}, Req, #cx{params = ClientId} = State) -> + ?ROSTER_LOG_REQ('Room', Status, ClientId, "Unknown request, Id=~s", [Room]), {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State}; -info(#'Member'{} = Member, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:Member/unknown:~p", [ClientId, Member]), +info(#'Member'{status = Status, phone_id = Id}, Req, #cx{params = ClientId} = State) -> + ?ROSTER_LOG_REQ('Member', Status, ClientId, "Unknown request, Id=~s", [Id]), {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State}. diff --git a/apps/roster/src/protocol/roster_roster.erl b/apps/roster/src/protocol/roster_roster.erl index 01542644e..728ea7526 100644 --- a/apps/roster/src/protocol/roster_roster.erl +++ b/apps/roster/src/protocol/roster_roster.erl @@ -15,7 +15,7 @@ info(#'Roster'{status = patch, avatar = Avatar} = Data, Req, state = {verified, #'Roster'{id = RosterId0, phone = Phone, avatar = OldAvatar, roomlist = Rooms, status = Status} = Roster}} = State) -> RosterId = case ClientId of <<"sys_", _/binary>> -> RosterId0; _ -> roster:roster_id(ClientId) end, - ?LOG_INFO("~p:~p:Roster/patch:~s", [RosterId, ClientId, io_lib:format("~p", [Data])]), + ?ROSTER_LOG_REQ('Roster', patch, ClientId), IO = case PreUpdRoster = roster:patch_roster(Roster, Data) of #error{code = invalid_data} = Err -> #io{code = Err}; _ -> @@ -67,11 +67,11 @@ info(#'Roster'{id = RosterId0, status = patch, names = Names, surnames = Surname end end; -info(#'Roster'{id = RosterId, nick = NickToBeValidated, status = nick} = Data, Req, #cx{params = ClientId, client_pid = C} = State) -> +info(#'Roster'{id = RosterId, nick = NickToBeValidated, status = nick}, Req, #cx{params = ClientId, client_pid = C} = State) -> ActedRosterId = case ClientId of <<"sys_", _/binary>> -> RosterId; _ -> roster:roster_id(ClientId) end, - ?LOG_INFO("~p:~p:Roster/nick.Request:~p", [ClientId, ActedRosterId, Data]), + ?ROSTER_LOG_REQ('Roster', nick, ClientId, "Nick=~s", [NickToBeValidated]), R = case kvs:get('Roster', ActedRosterId) of {error, Reason} -> #io{code = #error{code = Reason}}; {ok, Roster = #'Roster'{phone = Phone, nick = OldNick, status = Status}} -> @@ -116,11 +116,11 @@ info(#'Roster'{id = RosterId, nick = NickToBeValidated, status = nick} = Data, R end end end, - ?LOG_INFO("~p:~p:Roster/nick.Response:~p", [ClientId, ActedRosterId, R]), {reply, {bert, R}, Req, State}; info(#'Roster'{id=RosterId, status=get},Req, #cx{params = ClientId }=State) -> ?LOG_INFO("~p:~p:Roster/get",[RosterId,ClientId]), + ?ROSTER_LOG_REQ('Roster', get, ClientId, "Id=~p", [RosterId]), {reply,{bert, case kvs:get('Roster', RosterId) of {ok,#'Roster'{id = Id, phone = Phone, userlist = Contacts}=Roster} -> Roster#'Roster'{userlist = @@ -144,20 +144,20 @@ info(#'Roster'{id=RosterId, status=get},Req, #cx{params = ClientId }=State) -> info(#'Roster'{id = RosterId, userlist = List, status = del}, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:~p:Roster/del:~p", [RosterId, ClientId, length(List)]), + ?ROSTER_LOG_REQ('Roster', del, ClientId, "Id=~p", [RosterId]), {reply, {bert, #io{code = case roster:remove_contacts(RosterId, List, ClientId) of #ok2{} = O -> O; E -> E end}}, Req, State}; info(#'Roster'{id = RosterId, userlist = RosterList, status = add}, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:~p:Roster/add:~p", [RosterId, ClientId, length(RosterList)]), + ?ROSTER_LOG_REQ('Roster', add, ClientId, "Id=~p", [RosterId]), List = roster:to_contact(RosterList, request), {reply, {bert, #io{code = roster:add_contacts(RosterId, List)}}, Req, State}; info(#'Roster'{phone = Phone, status = list}, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:~p:Roster/list", [Phone, ClientId]), + ?ROSTER_LOG_REQ('Roster', list, ClientId, "Phone=~s", [Phone]), {reply, {bert, {io, roster:list_rosters(Phone), <<>>}}, Req, State}; -info(#'Roster'{id = RosterId, status = Status}, Req, #cx{params = ClientId} = State) -> - ?LOG_INFO("~p:~p:Roster/unknown:~p", [RosterId, ClientId, Status]), +info(#'Roster'{status = Status}, Req, #cx{params = ClientId} = State) -> + ?ROSTER_LOG_REQ('Roster', Status, ClientId, "Unknown request"), {reply, {bert, #io{code = #error{code = invalid_data}}}, Req, State}. proc(init, #handler{name = ?MODULE} = Async) -> diff --git a/apps/roster/src/protocol/roster_search.erl b/apps/roster/src/protocol/roster_search.erl index 9ef565803..c80b09906 100644 --- a/apps/roster/src/protocol/roster_search.erl +++ b/apps/roster/src/protocol/roster_search.erl @@ -7,27 +7,25 @@ %start() -> n2o_async:start(#handler{module = ?MODULE, class = system, group = roster, name = ?MODULE, state = []}). info(#'Search'{id = FromRosterId, ref = Ref, field = <<"link">>, type = '==', value = SearchVal, status = room}, Req, - #cx{params = <<"emqttd_",_/binary>> = ClientId} = State) -> - ?LOG_INFO("~p:~p:Search/RoomByLink:~p", [FromRosterId, ClientId, SearchVal]), - ResRoom = case roster_channel_helper:get_channel_by_link(SearchVal) of - [] -> []; - R -> [R] - end, - Res = #'Roster'{id = FromRosterId, roomlist = ResRoom, status = search}, - ?LOG_INFO("Res.Search/RoomByLink:~p", [Res]), - {reply, {bert, {io, {ok, Ref}, Res}}, Req, State}; + #cx{params = <<"emqttd_",_/binary>> = ClientId} = State) -> + ?ROSTER_LOG_REQ('Search', room, ClientId, "Field=link, Value=~p", [SearchVal]), + ResRoom = case roster_channel_helper:get_channel_by_link(SearchVal) of + [] -> []; + R -> [R] + end, + Res = #'Roster'{id = FromRosterId, roomlist = ResRoom, status = search}, + {reply, {bert, {io, {ok, Ref}, Res}}, Req, State}; -info(#'Search'{id = FromRosterId, ref = Ref, field = <<"phone_id">>, type = '==', value = [UUID], status = contact}, Req, +info(#'Search'{ref = Ref, field = <<"phone_id">>, type = '==', value = [UUID], status = contact}, Req, #cx{params = <<"emqttd_",_/binary>> = ClientId} = State) -> - ?LOG_INFO("~p:~p:Search/UUIDk:~p", [FromRosterId, ClientId, UUID]), + ?ROSTER_LOG_REQ('Search', contact, ClientId, "Field=phone_id, Value=~p", [UUID]), Res = #'Contact'{phone_id = micro:uuid_to_id('LinkRoster', UUID)}, - ?LOG_INFO("Res.Search/UUID:~p", [Res]), {reply, {bert, {io, {ok, Ref}, Res}}, Req, State}; info(#'Search'{id = From, ref = Ref, field = <<"nick">>, type = '==', value = Q, status = contact}, Req, #cx{params = <<"emqttd_", _/binary>> = ClientId} = State) when Ref /=[] -> - ?LOG_INFO("~p:~p:Search/contact:~p", [From, ClientId, Q]), + ?ROSTER_LOG_REQ('Search', contact, ClientId, "Field=nick, Value=~p", [Q]), PhoneId = case ClientId of % <<"sys_bpe">> -> From0; <<"emqttd_", _/binary>> -> roster:phone_id(ClientId); @@ -42,12 +40,11 @@ info(#'Search'{id = From, ref = Ref, field = <<"nick">>, type = '==', value = Q, Cont#'Contact'{reader = []}; _ -> [] end end || RosterId <- Rs] end || V <- Q] end, Res = #'Roster'{id = From, userlist = lists:flatten(L), status = contact}, - ?LOG_INFO("Res.Search/contact:~p", [Res]), {reply, {bert, {io, {ok, Ref}, Res}}, Req, State}; info(#'Search'{id = From, ref = Ref, field = <<"phone">>, type = '==', value = Phones, status = contact}, Req, #cx{params = <<"emqttd_", _/binary>> = ClientId} = State) when is_list(Phones), Ref /=[] -> - %?LOG_INFO("~p:~p:Search/phone:~p", [From, ClientId, Phones]), + ?ROSTER_LOG_REQ('Search', contact, ClientId, "Field=phone, Value=~p", [Phones]), PhoneId = case ClientId of % <<"sys_bpe">> -> From0; <<"emqttd_", _/binary>> -> roster:phone_id(ClientId); @@ -63,21 +60,19 @@ info(#'Search'{id = From, ref = Ref, field = <<"phone">>, type = '==', value = P end end || Phone <- lists:usort(Phones), #'Roster'{id=FriendId, phone=_ToPhone}=R <- kvs:index('Roster',phone, Phone)] end, Res = #'Roster'{id = From, userlist = lists:flatten(Result), status = contact}, - ?LOG_INFO(":~P", [Res, 30]), - %?LOG_INFO("Res.Search/phone:~p", [Res]), {reply, {bert, {io, {ok, Ref}, Res}}, Req, State}; %% TBD is this method neccesery? -info(#'Search'{id = From, ref = Ref, field = K, type = 'like', value = V, status = roster}, Req, - #cx{params = <<"emqttd_", _/binary>> = ClientId} = State) when is_atom(K), Ref /=[] -> - ?LOG_INFO("~p:~p:Search/names:~p", [From, ClientId, V]), +info(#'Search'{ref = Ref, field = K, type = 'like', value = V, status = roster}, Req, + #cx{params = <<"emqttd_", _/binary>> = ClientId} = State) when is_atom(K), Ref /=[] -> + ?ROSTER_LOG_REQ('Search', roster, ClientId, "Field=~s, Type=like, Value=~p", [K, V]), L = [binary_to_list(string:lowercase(V)) ++ F || F <- ets:match(K, {binary_to_list(string:lowercase(V)) ++ '$1'})], {reply, {bert, {io, {ok, Ref}, L}}, Req, State}; -info(#'Search'{} = Data, Req, State) -> - ?LOG_INFO("Search/unknown:~p", [Data]), - {reply, {bert, {io, {error,invalid_data}}}, Req, State}. +info(#'Search'{status = Status}, Req, #cx{params = ClientId} = State) -> + ?ROSTER_LOG_REQ('Search', Status, ClientId, "Unknown request"), + {reply, {bert, {io, {error, invalid_data}}}, Req, State}. %% TODO search by prefix %%proc(init, #handler{name = roster_search} = Async) -> @@ -106,4 +101,4 @@ info(#'Search'{} = Data, Req, State) -> %% _ -> skip %% end, %% index_next(R, K, Next),ok -%% end. \ No newline at end of file +%% end. diff --git a/apps/roster/src/roster.erl b/apps/roster/src/roster.erl index da83c466b..b40dafc87 100644 --- a/apps/roster/src/roster.erl +++ b/apps/roster/src/roster.erl @@ -195,13 +195,11 @@ create_length_feature(Key, Size) -> group = <<"PAGINATION">>}. send_profile(#'Profile'{rosters = []}, _N, _LastSync, _ClientId, _ClientPid) -> - ?LOG_INFO("SEND PROFILE []", []), ok; send_profile(#'Profile'{rosters = [[]|TRosterIds]} = Profile, N, LastSync, ClientId, ClientPid) -> - ?LOG_INFO("SEND PROFILE []", []), send_profile(Profile#'Profile'{rosters = TRosterIds}, N, LastSync, ClientId, ClientPid); send_profile(#'Profile'{ - rosters = [RosterId | TRosterIds] = Rosters, + rosters = [RosterId | TRosterIds], phone = Phone, settings = Settings } = Profile, @@ -209,7 +207,6 @@ send_profile(#'Profile'{ LastSync, ClientId, ClientPid) -> - ?LOG_INFO("SEND PROFILE [~p]", [length(Rosters)]), case kvs:get('Roster', RosterId) of {error, _} -> ?LOG_INFO("roster ~p not found in profile ~p", [RosterId, Phone]); @@ -236,7 +233,7 @@ send_profile(#'Profile'{ end end; send_profile(#'Profile'{ - rosters = [RosterId | TRosterIds] = Rosters, + rosters = [RosterId | TRosterIds], phone = Phone, settings = Settings } = Profile, @@ -244,7 +241,6 @@ send_profile(#'Profile'{ LastSync, ClientId, ClientPid) -> - ?LOG_INFO("SEND PROFILE [~p]", [length(Rosters)]), case kvs:get('Roster', RosterId) of {error, _} -> ?LOG_INFO("roster ~p not found in profile ~p", [RosterId, Phone]); @@ -257,7 +253,6 @@ send_profile(#'Profile'{ skip -> ok; NewRoster -> - ?LOG_INFO("Sending roster, length ~p", [length(NonEmptyOb)]), roster:send_action(ClientPid, ClientId, ProfileWithNewSettings#'Profile'{ @@ -486,7 +481,6 @@ add_contacts(#'Roster'{userlist=List}=Roster, Contacts) -> false -> [Phone, _] = parts_phone_id(PhoneId), - ?LOG_INFO("ContactServices:~p",[{PhoneId,Phone}]), %% {ok, #'Profile'{services = Services}} = kvs:get('Phone', Phone), {A, [C#'Contact'{presence=[], services = get_services(Phone)}|L]}; _F -> {[PhoneId|A],L} end end,{[],List},Contacts), @@ -569,25 +563,24 @@ unload() -> emqttd:unhook('session.terminated', fun ?MODULE:on_session_terminated/4), emqttd:unhook('client.disconnected', fun ?MODULE:on_client_disconnected/3). -on_client_disconnected(_Reason, #mqtt_client{client_id = <<"emqttd_", _/bytes>> = ClientId} = Client, _Env) -> - ?LOG_INFO("~p:MQTT_CLIENT DISCONNECT ~p",[ClientId, Client]), +on_client_disconnected(_Reason, #mqtt_client{client_id = <<"emqttd_", _/bytes>> = ClientId}, _Env) -> + ?LOG_INFO("CLIENT DISCONNECT ~s",[ClientId]), % TODO: mqttc:publish(C, lists:concat(["ses/",Phone])) on_disconnect(ClientId); -on_client_disconnected(_Reason, #mqtt_client{client_id = <<"reg_", _/bytes>> = ClientId} = Client, _) -> - ?LOG_INFO("~p:MQTT_CLIENT DISCONNECT ~p",[ClientId, Client]), +on_client_disconnected(_Reason, #mqtt_client{client_id = <<"reg_", _/bytes>> = ClientId}, _) -> + ?LOG_INFO("CLIENT DISCONNECT ~s",[ClientId]), unsubscribe_client(ClientId), final_disconnect(ClientId); -on_client_disconnected(_Reason, #mqtt_client{client_id = <<"sys_", _/bytes>> = ClientId} = Client, _) -> - ?LOG_INFO("~p:MQTT_CLIENT DISCONNECT ~p",[ClientId, Client]), +on_client_disconnected(_Reason, #mqtt_client{client_id = <<"sys_", _/bytes>> = ClientId}, _) -> + ?LOG_INFO("CLIENT DISCONNECT ~s",[ClientId]), unsubscribe_client(ClientId), final_disconnect(ClientId); -on_client_disconnected(_Reason, #mqtt_client{client_id = ClientId} = Client, _Env) -> - ?LOG_INFO("~p:MQTT_CLIENT DISCONNECT ~p",[ClientId, Client]), +on_client_disconnected(_Reason, #mqtt_client{client_id = ClientId}, _Env) -> + ?LOG_INFO("CLIENT DISCONNECT ~s",[ClientId]), ok. on_disconnect(<<"emqttd_", _/binary>> = ClientId) -> - ?LOG_INFO("~p:CLIENT DISCONNECT",[ClientId]), case kvs:get('Auth', ClientId) of {ok, Auth} -> n2o_async:pid(system, roster_auth) ! {disconnect, Auth#'Auth'{type = disconnect}}, @@ -1367,7 +1360,6 @@ objlist([Object | _] = Objects, end, [[]], Objects), - ?LOG_INFO("Objlist args ~p ~p ~p", [LastSync, N, length(hd(Objs))]), case Objs of [[] | TObjs] -> TObjs; diff --git a/apps/roster/src/roster_proto.erl b/apps/roster/src/roster_proto.erl index 98f671450..6533775c0 100644 --- a/apps/roster/src/roster_proto.erl +++ b/apps/roster/src/roster_proto.erl @@ -7,11 +7,17 @@ -compile({parse_transform, bert_swift}). -export([info/3]). -info(BusinessObject, Req, State) -> +info(BusinessObject, Req, State) -> StartTime = os:system_time(), %% Start execution time Response = do_info(BusinessObject, Req, State), %% Execute Code Logic ExecutionTimeInMicroSeconds = roster:execution_time(StartTime), %% Finish execution time + case Response of + {reply, {bert, #io{code = #error{} = Error}}} -> + ?LOG_INFO("~p request failed with ~p", [element(1, BusinessObject), Error]); + _ -> ok + end, + [RecordName | RecordValues] = tuple_to_list(BusinessObject), [RecordFields] = [Fields || #table{fields = Fields, name = RName} <- kvs:tables(), RName == RecordName], RequestName = proplists:get_value(status, lists:zip(RecordFields, RecordValues), default), @@ -43,4 +49,4 @@ do_info(#'Auth'{} = Auth, Req, do_info(Message, Req, State) -> ?LOG_INFO("UNKNOWN:~p, ~p", [Message, State]), - {unknown, Message, Req, State}. \ No newline at end of file + {unknown, Message, Req, State}. -- GitLab From f8fda84ad4b7d370466e46b61be032b6dcde83b2 Mon Sep 17 00:00:00 2001 From: Ulf Norell Date: Tue, 19 May 2020 16:05:16 +0200 Subject: [PATCH 2/2] Point to updated n2o and emqttd --- rebar.config | 2 +- rebar.lock | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/rebar.config b/rebar.config index 4b3d2a4a6..de212121a 100644 --- a/rebar.config +++ b/rebar.config @@ -10,7 +10,7 @@ {bert, {git, "git://github.com/NYNJA-MC/bert.git", {branch, master}}}, {esockd, {git, "https://github.com/voxoz/esockd", {branch, "master"}}}, {bpe, {git, "git://github.com/synrc/bpe", {tag,"4.4"}}}, - {emqttd, {git, "git://github.com/NYNJA-MC/emqttd", {branch,"switch-from-lager-to-logger"}}}, + {emqttd, {git, "git://github.com/NYNJA-MC/emqttd", {branch,"master"}}}, {n2o, {git, "git://github.com/NYNJA-MC/n2o", {branch,"v6.4-otp21"}}}, {emqttc, {git, "git://github.com/NYNJA-MC/emqttc", {branch,"master"}}}, {rest, {git, "git://github.com/synrc/rest", {tag,"5.10"}}}, diff --git a/rebar.lock b/rebar.lock index 930b18f4a..0c378341d 100644 --- a/rebar.lock +++ b/rebar.lock @@ -43,7 +43,7 @@ 0}, {<<"emqttd">>, {git,"git://github.com/NYNJA-MC/emqttd", - {ref,"82488e8cf78fddb025a0dcc6e3caa567e75918bf"}}, + {ref,"1010714c50515ee31277f45ee4b274573a0b0cd7"}}, 0}, {<<"enenra">>, {git,"https://github.com/nlfiedler/enenra", @@ -143,7 +143,7 @@ 1}, {<<"n2o">>, {git,"git://github.com/NYNJA-MC/n2o", - {ref,"a90d3660196abe9dc6f260680dd85f44ca6ad755"}}, + {ref,"a8e04f36598af17624a9145f21ffa67d578a3261"}}, 0}, {<<"nitro">>, {git,"git://github.com/synrc/nitro", -- GitLab