Log connection related events

added capture_logs function to the ibmmq_helper
but not called until I figure out how to add
extra logging. So far the only auth events captured
are those originated from the admin ui

Author: MarcialRosales

deps/amqp10_client/src/amqp10_client_connection.erl

@@ -228,13 +228,17 @@ sasl_hdr_rcvds({call, From}, begin_session,
 
 sasl_init_sent(_EvtType, #'v1_0.sasl_outcome'{code = {ubyte, 0}},
                #state{socket = Socket} = State) ->
+    logger:warning("sasl_init_sent "),
     ok = socket_send(Socket, ?AMQP_PROTOCOL_HEADER),
+    logger:warning("sasl_init_sent socket_send AMQP_PROTOCOL_HEADER ok"),
     {next_state, hdr_sent, State};
 sasl_init_sent(_EvtType, #'v1_0.sasl_outcome'{code = {ubyte, C}},
                #state{} = State) when C==1;C==2;C==3;C==4 ->
+   logger:warning("sasl_init_sent sasl_auth_failure"),
     {stop, sasl_auth_failure, State};
 sasl_init_sent({call, From}, begin_session,
                #state{pending_session_reqs = PendingSessionReqs} = State) ->
+    logger:warning("sasl_init_sent call to begin_session"),
     State1 = State#state{pending_session_reqs = [From | PendingSessionReqs]},
     {keep_state, State1}.
 
@@ -243,7 +247,7 @@ hdr_sent(_EvtType, {protocol_header_received, 0, 1, 0, 0}, State) ->
     case send_open(State) of
         ok    -> {next_state, open_sent, State};
         Error ->
-                logger:warning("client_connection hdr_sent ~p", [Error]), 
+                logger:warning("client_connection hdr_sent ~p", [Error]),
                 {stop, Error, State}
     end;
 hdr_sent(_EvtType, {protocol_header_received, Protocol, Maj, Min,
@@ -253,15 +257,15 @@ hdr_sent(_EvtType, {protocol_header_received, Protocol, Maj, Min,
     {stop, normal, State};
 hdr_sent({call, From}, begin_session,
          #state{pending_session_reqs = PendingSessionReqs} = State) ->
-    logger:warning("hdr_sent received call begin_session"),        
+    logger:warning("hdr_sent received call begin_session"),
     State1 = State#state{pending_session_reqs = [From | PendingSessionReqs]},
     {keep_state, State1}.
 
 open_sent(_EvtType, #'v1_0.open'{max_frame_size = MaybeMaxFrameSize,
                                  idle_time_out = Timeout} = Open,
           #state{pending_session_reqs = PendingSessionReqs,
                  config = Config} = State0) ->
-    logger:warning("open_sent received 'v1_0.open' with pending_session_reqs: ~p", [PendingSessionReqs]),                            
+    logger:warning("open_sent received 'v1_0.open' with pending_session_reqs: ~p", [PendingSessionReqs]),
     State = case Timeout of
                 undefined -> State0;
                 {uint, T} when T > 0 ->
@@ -288,16 +292,16 @@ open_sent(_EvtType, #'v1_0.open'{max_frame_size = MaybeMaxFrameSize,
     {next_state, opened, State2#state{pending_session_reqs = []}};
 open_sent({call, From}, begin_session,
           #state{pending_session_reqs = PendingSessionReqs} = State) ->
-    logger:warning("open_sent received call begin_session with pending_session_reqs: ~p", [PendingSessionReqs]),                                    
+    logger:warning("open_sent received call begin_session with pending_session_reqs: ~p", [PendingSessionReqs]),
     State1 = State#state{pending_session_reqs = [From | PendingSessionReqs]},
     {keep_state, State1};
 open_sent(info, {'DOWN', MRef, _, _, _},
           #state{reader_m_ref = MRef}) ->
-    logger:warning("open_sent received 'DOWN"),        
+    logger:warning("open_sent received 'DOWN"),
     {stop, {shutdown, reader_down}}.
 
 opened(_EvtType, heartbeat, State = #state{idle_time_out = T}) ->
-    logger:warning("opened received heartbeat"),        
+    logger:warning("opened received heartbeat"),
     ok = send_heartbeat(State),
     {ok, Tmr} = start_heartbeat_timer(T),
     {keep_state, State#state{heartbeat_timer = Tmr}};
@@ -482,7 +486,10 @@ send_sasl_init(State, {plain, User, Pass}) ->
     Response = <<0:8, User/binary, 0:8, Pass/binary>>,
     Frame = #'v1_0.sasl_init'{mechanism = {symbol, <<"PLAIN">>},
                               initial_response = {binary, Response}},
-    send(Frame, 1, State).
+    logger:warning("send_sasl_init ~p ~p", [User, Pass]),
+    Ret = send(Frame, 1, State),
+    logger:warning("send_sasl_init ~p ~p Ret : ~p", [User, Pass, Ret]),
+    Ret.
 
 send(Record, FrameType, #state{socket = Socket}) ->
     Encoded = amqp10_framing:encode_bin(Record),

deps/amqp10_client/test/ibmmq_ct_helpers.erl

@@ -12,6 +12,7 @@
 -export([setup_steps/0,
          teardown_steps/0,
          init_config/1,
+         capture_logs/1,
          start_ibmmq_server/1,
          stop_ibmmq_server/1]).
 
@@ -30,7 +31,7 @@ init_config(Config) ->
     rabbit_ct_helpers:set_config(Config, [  {rmq_nodes, [NodeConfig]},
                                             {rmq_hostname, "localhost"},
                                             {tcp_hostname_amqp, "localhost"},
-                                            {sasl, {plain, <<"app">>, <<"passw0rd">>}} ]).
+                                            {sasl, {plain, <<"app">>, <<"passw10rd">>}} ]).
 
 start_ibmmq_server(Config) ->
     IBMmqCmd = filename:join([?config(data_dir, Config), "ibmmq_runner"]),
@@ -78,6 +79,16 @@ wait_for_ibmmq_port(Hostname, Port, Retries) ->
             Error
     end.
 
+capture_logs(Config) ->
+    IBMmqCmd = filename:join([?config(data_dir, Config), "ibmmq_runner"]),
+    Cmd = [IBMmqCmd, "logs", "/tmp/ibmmq.log"],
+    ct:log("Running command ~p", [Cmd]),
+    case rabbit_ct_helpers:exec(Cmd, []) of
+        {ok, _} -> Config;
+        Error   -> ct:pal("Error: ~tp", [Error]),
+                   {skip, "Failed to stop IBM MQ"}
+    end.
+
 stop_ibmmq_server(Config) ->
     IBMmqCmd = filename:join([?config(data_dir, Config), "ibmmq_runner"]),
     Cmd = [IBMmqCmd, "stop"],

deps/amqp10_client/test/system_SUITE_data/ibmmq_runner

@@ -76,7 +76,10 @@ invoke_start(){
   sleep 10
   print "Waited 10 seconds for container to start"
 }
-
+capture_logs() {
+    print "Capturing ibmmq logs to $1"
+    docker logs ibmmq > $1
+}
 invoke_stop(){
   kill_container_if_exist ibmmq
 }
@@ -88,6 +91,9 @@ case "$1" in
   build)
     build_docker_image
     ;;
+  logs)
+    capture_logs "$2"
+    ;;
   start)
     invoke_start
     ;;