[MINOR] Prevent WebSocket tickets from being logged

zeppelin-server/src/main/java/org/apache/zeppelin/rest/LoginRestApi.java

@@ -242,7 +242,8 @@ public Response postLogin(@FormParam("userName") String userName,
       response = new JsonResponse<>(Response.Status.FORBIDDEN, "", null);
     }
 
-    LOGGER.info(response.toString());
+    LOGGER.info("Login request completed: principal={}, success={}",
+        userName, response.getCode() == Response.Status.OK);
     return response.build();
   }
 

zeppelin-server/src/main/java/org/apache/zeppelin/rest/SecurityRestApi.java

@@ -79,7 +79,8 @@ public Response ticket() {
     data.put("ticket", ticketEntry.getTicket());
 
     JsonResponse<Map<String, String>> response = new JsonResponse<>(Response.Status.OK, "", data);
-    LOGGER.warn("{}", response);
+    LOGGER.info("WebSocket ticket request completed: principal={}, success=true",
+        ticketEntry.getPrincipal());
     return response.build();
   }
 

zeppelin-server/src/main/java/org/apache/zeppelin/socket/NotebookServer.java

@@ -274,17 +274,15 @@ public void onMessage(Session session, String msg) {
   }
 
   public void onMessage(NotebookSocket conn, String msg) {
+    Message receivedMessage = null;
     try {
-      Message receivedMessage = deserializeMessage(msg);
+      receivedMessage = deserializeMessage(msg);
       if (receivedMessage.op != OP.PING) {
-        LOGGER.debug("RECEIVE: " + receivedMessage.op +
-            ", RECEIVE PRINCIPAL: " + receivedMessage.principal +
-            ", RECEIVE ROLES: " + receivedMessage.roles +
-            ", RECEIVE DATA: " + receivedMessage.data);
-      }
-      if (LOGGER.isTraceEnabled()) {
-        LOGGER.trace("RECEIVE MSG = " + receivedMessage);
+        LOGGER.debug("WebSocket message received: operation={}, principal={}",
+            receivedMessage.op, receivedMessage.principal);
       }
+      LOGGER.trace("WebSocket message processing started: operation={}, principal={}",
+          receivedMessage.op, receivedMessage.principal);
 
       TicketContainer.Entry ticketEntry = TicketContainer.instance.getTicketEntry(receivedMessage.principal);
       if (ticketEntry == null || StringUtils.isEmpty(ticketEntry.getTicket())) {
@@ -485,7 +483,13 @@ public void onMessage(NotebookSocket conn, String msg) {
           break;
       }
     } catch (Exception e) {
-      LOGGER.error("Can't handle message: {}", msg, e);
+      String operation = receivedMessage == null || receivedMessage.op == null
+          ? "unknown" : receivedMessage.op.name();
+      String principal = receivedMessage == null || StringUtils.isEmpty(receivedMessage.principal)
+          ? "unknown" : receivedMessage.principal;
+      LOGGER.error("WebSocket message handling completed: operation={}, principal={}, "
+              + "success=false, errorType={}",
+          operation, principal, e.getClass().getSimpleName());
       try {
         conn.send(serializeMessage(new Message(OP.ERROR_INFO).put("info", e.getMessage())));
       } catch (IOException iox) {

zeppelin-server/src/test/java/org/apache/zeppelin/rest/SecurityRestApiTest.java

@@ -19,9 +19,18 @@
 import com.google.gson.Gson;
 import com.google.gson.reflect.TypeToken;
 
+import org.apache.http.NameValuePair;
+import org.apache.http.client.entity.UrlEncodedFormEntity;
 import org.apache.http.client.methods.CloseableHttpResponse;
+import org.apache.http.client.methods.HttpPost;
+import org.apache.http.message.BasicNameValuePair;
 import org.apache.http.util.EntityUtils;
+import org.apache.log4j.AppenderSkeleton;
+import org.apache.log4j.Level;
+import org.apache.log4j.Logger;
+import org.apache.log4j.spi.LoggingEvent;
 import org.apache.zeppelin.MiniZeppelinServer;
+import org.apache.zeppelin.ticket.TicketContainer;
 import org.hamcrest.CoreMatchers;
 import org.junit.jupiter.api.AfterAll;
 import org.junit.jupiter.api.BeforeAll;
@@ -30,10 +39,14 @@
 
 import java.io.IOException;
 import java.nio.charset.StandardCharsets;
+import java.util.ArrayList;
 import java.util.List;
 import java.util.Map;
+import java.util.concurrent.CopyOnWriteArrayList;
 
 import static org.hamcrest.MatcherAssert.assertThat;
+import static org.junit.jupiter.api.Assertions.assertFalse;
+import static org.junit.jupiter.api.Assertions.assertTrue;
 
 class SecurityRestApiTest extends AbstractTestRestApi {
   Gson gson = new Gson();
@@ -69,6 +82,80 @@ void testTicket() throws IOException {
     get.close();
   }
 
+  @Test
+  void testLoginTicketIsNotLogged() throws IOException {
+    String principal = "user1";
+    TicketContainer.instance.removeTicket(principal);
+    TestAppender appender = new TestAppender();
+    Logger logger = Logger.getLogger(LoginRestApi.class);
+    Level previousLevel = logger.getLevel();
+    boolean previousAdditivity = logger.getAdditivity();
+    logger.setLevel(Level.TRACE);
+    logger.setAdditivity(false);
+    logger.addAppender(appender);
+
+    try {
+      HttpPost login = new HttpPost(getUrlToTest(zConf) + "/login");
+      login.addHeader("Origin", getUrlToTest(zConf));
+      List<NameValuePair> parameters = new ArrayList<>();
+      parameters.add(new BasicNameValuePair("password", "password2"));
+      parameters.add(new BasicNameValuePair("userName", principal));
+      login.setEntity(new UrlEncodedFormEntity(parameters, StandardCharsets.UTF_8));
+
+      try (CloseableHttpResponse post = getHttpClient().execute(login)) {
+        Map<String, Object> resp = gson.fromJson(
+            EntityUtils.toString(post.getEntity(), StandardCharsets.UTF_8),
+            new TypeToken<Map<String, Object>>(){}.getType());
+        Map<String, String> body = (Map<String, String>) resp.get("body");
+        String ticket = body.get("ticket");
+        assertThat("Login response ticket", ticket, CoreMatchers.notNullValue());
+        assertThat("Login response ticket", ticket, CoreMatchers.not("anonymous"));
+        assertTrue(appender.contains("principal=" + principal));
+        assertTrue(appender.contains("success=true"));
+        assertFalse(appender.contains(ticket), "Login logs must not contain the ticket");
+      }
+    } finally {
+      logger.removeAppender(appender);
+      logger.setLevel(previousLevel);
+      logger.setAdditivity(previousAdditivity);
+      appender.close();
+      TicketContainer.instance.removeTicket(principal);
+    }
+  }
+
+  @Test
+  void testSecurityTicketIsNotLogged() throws IOException {
+    String principal = "user2";
+    TicketContainer.instance.removeTicket(principal);
+    TestAppender appender = new TestAppender();
+    Logger logger = Logger.getLogger(SecurityRestApi.class);
+    Level previousLevel = logger.getLevel();
+    boolean previousAdditivity = logger.getAdditivity();
+    logger.setLevel(Level.TRACE);
+    logger.setAdditivity(false);
+    logger.addAppender(appender);
+
+    try (CloseableHttpResponse get =
+             httpGet("/security/ticket", principal, "password3")) {
+      Map<String, Object> resp = gson.fromJson(
+          EntityUtils.toString(get.getEntity(), StandardCharsets.UTF_8),
+          new TypeToken<Map<String, Object>>(){}.getType());
+      Map<String, String> body = (Map<String, String>) resp.get("body");
+      String ticket = body.get("ticket");
+      assertThat("Security response ticket", ticket, CoreMatchers.notNullValue());
+      assertThat("Security response ticket", ticket, CoreMatchers.not("anonymous"));
+      assertTrue(appender.contains("principal=" + principal));
+      assertTrue(appender.contains("success=true"));
+      assertFalse(appender.contains(ticket), "Security ticket logs must not contain the ticket");
+    } finally {
+      logger.removeAppender(appender);
+      logger.setLevel(previousLevel);
+      logger.setAdditivity(previousAdditivity);
+      appender.close();
+      TicketContainer.instance.removeTicket(principal);
+    }
+  }
+
   @Test
   void testGetUserList() throws IOException {
     CloseableHttpResponse get = httpGet("/security/userlist/admi", "admin", "password1");
@@ -102,4 +189,40 @@ void testRolesEscaped() throws IOException {
     get.close();
   }
 
+  private static class TestAppender extends AppenderSkeleton {
+    private final List<LoggingEvent> events = new CopyOnWriteArrayList<>();
+
+    @Override
+    protected void append(LoggingEvent event) {
+      events.add(event);
+    }
+
+    boolean contains(String value) {
+      for (LoggingEvent event : events) {
+        String message = event.getRenderedMessage();
+        if (message != null && message.contains(value)) {
+          return true;
+        }
+        String[] throwable = event.getThrowableStrRep();
+        if (throwable != null) {
+          for (String line : throwable) {
+            if (line.contains(value)) {
+              return true;
+            }
+          }
+        }
+      }
+      return false;
+    }
+
+    @Override
+    public void close() {
+    }
+
+    @Override
+    public boolean requiresLayout() {
+      return false;
+    }
+  }
+
 }

zeppelin-server/src/test/java/org/apache/zeppelin/socket/NotebookServerLoggingTest.java

@@ -0,0 +1,133 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements.  See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License.  You may obtain a copy of the License at
+ *
+ *    http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.zeppelin.socket;
+
+import static org.junit.jupiter.api.Assertions.assertFalse;
+import static org.junit.jupiter.api.Assertions.assertTrue;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.when;
+
+import java.util.Collections;
+import java.util.List;
+import java.util.UUID;
+import java.util.concurrent.CopyOnWriteArrayList;
+
+import org.apache.log4j.AppenderSkeleton;
+import org.apache.log4j.Level;
+import org.apache.log4j.spi.LoggingEvent;
+import org.apache.zeppelin.common.Message;
+import org.apache.zeppelin.common.Message.OP;
+import org.apache.zeppelin.conf.ZeppelinConfiguration;
+import org.apache.zeppelin.ticket.TicketContainer;
+import org.junit.jupiter.api.Test;
+
+class NotebookServerLoggingTest {
+
+  @Test
+  void testWebSocketTicketIsNotLoggedOnMessageFailure() {
+    String principal = "ticket-log-test-" + UUID.randomUUID();
+    TicketContainer.Entry ticketEntry =
+        TicketContainer.instance.getTicketEntry(principal, Collections.emptySet());
+    String ticket = ticketEntry.getTicket();
+    String sensitivePayload = "sensitive-payload-" + UUID.randomUUID();
+
+    ZeppelinConfiguration zConf = mock(ZeppelinConfiguration.class);
+    when(zConf.isAnonymousAllowed()).thenReturn(true);
+    NotebookServer notebookServer = new NotebookServer();
+    notebookServer.setZeppelinConfiguration(zConf);
+    NotebookSocket conn = mock(NotebookSocket.class);
+    when(conn.getUser()).thenReturn(principal);
+
+    Message message = new Message(OP.CONVERT_NOTE_NBFORMAT)
+        .put("ticketCopy", ticket)
+        .put("sensitivePayload", sensitivePayload);
+    message.principal = principal;
+    message.roles = "[]";
+    message.ticket = ticket;
+
+    TestAppender appender = new TestAppender();
+    org.apache.log4j.Logger logger = org.apache.log4j.Logger.getLogger(NotebookServer.class);
+    Level previousLevel = logger.getLevel();
+    boolean previousAdditivity = logger.getAdditivity();
+    logger.setLevel(Level.TRACE);
+    logger.setAdditivity(false);
+    logger.addAppender(appender);
+
+    try {
+      notebookServer.onMessage(conn, message.toJson());
+
+      assertTrue(appender.hasLevel(Level.ERROR), "The WebSocket error path must be exercised");
+      assertTrue(appender.containsMessage("operation=" + OP.CONVERT_NOTE_NBFORMAT));
+      assertTrue(appender.containsMessage("principal=" + principal));
+      assertFalse(appender.contains(ticket), "WebSocket logs must not contain the ticket");
+      assertFalse(appender.contains(sensitivePayload),
+          "WebSocket logs must not contain message payload data");
+    } finally {
+      logger.removeAppender(appender);
+      logger.setLevel(previousLevel);
+      logger.setAdditivity(previousAdditivity);
+      appender.close();
+      TicketContainer.instance.removeTicket(principal);
+    }
+  }
+
+  private static class TestAppender extends AppenderSkeleton {
+    private final List<LoggingEvent> events = new CopyOnWriteArrayList<>();
+
+    @Override
+    protected void append(LoggingEvent event) {
+      events.add(event);
+    }
+
+    boolean hasLevel(Level level) {
+      return events.stream().anyMatch(event -> level.equals(event.getLevel()));
+    }
+
+    boolean containsMessage(String value) {
+      return events.stream()
+          .map(LoggingEvent::getRenderedMessage)
+          .anyMatch(message -> message != null && message.contains(value));
+    }
+
+    boolean contains(String value) {
+      for (LoggingEvent event : events) {
+        String message = event.getRenderedMessage();
+        if (message != null && message.contains(value)) {
+          return true;
+        }
+        String[] throwable = event.getThrowableStrRep();
+        if (throwable != null) {
+          for (String line : throwable) {
+            if (line.contains(value)) {
+              return true;
+            }
+          }
+        }
+      }
+      return false;
+    }
+
+    @Override
+    public void close() {
+    }
+
+    @Override
+    public boolean requiresLayout() {
+      return false;
+    }
+  }
+}

zeppelin-web-angular/projects/zeppelin-sdk/src/message.ts

@@ -126,7 +126,7 @@ export class Message {
         retryWhen(errors => errors.pipe(mergeMap(() => this.close$.pipe(take(1), delay(4000)))))
       )
       .subscribe(e => {
-        console.log('Receive:', e);
+        console.log('Receive:', e.op);
         this.received$.next(this.interceptReceived(e as WebSocketMessage<MessageReceiveDataTypeMap>));
       });
   }
@@ -166,7 +166,7 @@ export class Message {
       data,
       ...this.ticket
     };
-    console.log('Send:', message);
+    console.log('Send:', message.op, message.principal);
 
     this.ws.next(message);
     this.sent$.next(message);

zeppelin-web/src/components/websocket/websocket-event.factory.js

@@ -45,7 +45,7 @@ function WebsocketEventFactory($rootScope, $websocket, $location, baseUrlSrv, sa
     }
 
     data.msgId = uniqueClientId + '-' + ++lastMsgIdSeqSent;
-    console.log('Send >> %o, %o, %o, %o, %o', data.op, data.principal, data.ticket, data.roles, data);
+    console.log('Send >> %o, %o', data.op, data.principal);
     return websocketCalls.ws.send(JSON.stringify(data));
   };
 
@@ -59,7 +59,7 @@ function WebsocketEventFactory($rootScope, $websocket, $location, baseUrlSrv, sa
       payload = angular.fromJson(event.data);
     }
 
-    console.log('Receive << %o, %o', payload.op, payload);
+    console.log('Receive << %o', payload.op);
 
     let op = payload.op;
     let data = payload.data;