From 38e4512f5fb660e5932699be18afaed0dce1678a Mon Sep 17 00:00:00 2001 From: Mykola Morhun Date: Mon, 30 Jan 2017 16:38:21 +0200 Subject: [PATCH 1/3] CODENVY-1407: Log agent output on fail Signed-off-by: Mykola Morhun --- .../launcher/AbstractAgentLauncher.java | 36 +++++++--- .../launcher/AbstractAgentLauncherTest.java | 67 ++++++++++++++++--- 2 files changed, 84 insertions(+), 19 deletions(-) diff --git a/agents/che-core-api-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java b/agents/che-core-api-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java index 1ec0f12f79c..2a08ad21b16 100644 --- a/agents/che-core-api-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java +++ b/agents/che-core-api-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java @@ -10,6 +10,7 @@ *******************************************************************************/ package org.eclipse.che.api.agent.server.launcher; +import com.google.common.annotations.VisibleForTesting; import com.google.common.util.concurrent.ThreadFactoryBuilder; import org.eclipse.che.api.agent.shared.model.Agent; @@ -18,6 +19,7 @@ import org.eclipse.che.api.core.model.machine.Command; import org.eclipse.che.api.core.util.AbstractLineConsumer; import org.eclipse.che.api.core.util.LineConsumer; +import org.eclipse.che.api.core.util.ListLineConsumer; import org.eclipse.che.api.machine.server.exception.MachineException; import org.eclipse.che.api.machine.server.model.impl.CommandImpl; import org.eclipse.che.api.machine.server.spi.Instance; @@ -71,8 +73,16 @@ public void launch(Instance machine, Agent agent) throws ServerException { if (isNullOrEmpty(agent.getScript())) { return; } + ListLineConsumer agentLogger = new ListLineConsumer(); try { - final InstanceProcess process = start(machine, agent); + LineConsumer lineConsumer = new AbstractLineConsumer() { + @Override + public void writeLine(String line) throws IOException { + machine.getLogger().writeLine(line); + agentLogger.writeLine(line); + } + }; + final InstanceProcess process = start(machine, agent, lineConsumer); LOG.debug("Waiting for agent {} is launched. Workspace ID:{}", agent.getId(), machine.getWorkspaceId()); final long pingStartTimestamp = System.currentTimeMillis(); @@ -86,26 +96,22 @@ public void launch(Instance machine, Agent agent) throws ServerException { process.kill(); } catch (MachineException e) { + logAsErrorAgentStartLogs(agent.getName(), agentLogger.getText()); throw new ServerException(e.getServiceError()); } catch (InterruptedException e) { Thread.currentThread().interrupt(); throw new ServerException(format("Launching agent %s is interrupted", agent.getName())); + } finally { + agentLogger.close(); } - final String errMsg = format("Fail launching agent %s. Workspace ID:%s", agent.getName(), machine.getWorkspaceId()); - LOG.error(errMsg); - throw new ServerException(errMsg); + logAsErrorAgentStartLogs(agent.getName(), agentLogger.getText()); + throw new ServerException(format("Fail launching agent %s. Workspace ID:%s", agent.getName(), machine.getWorkspaceId())); } - protected InstanceProcess start(Instance machine, Agent agent) throws ServerException { + protected InstanceProcess start(Instance machine, Agent agent, LineConsumer lineConsumer) throws ServerException { Command command = new CommandImpl(agent.getId(), agent.getScript(), "agent"); InstanceProcess process = machine.createProcess(command, null); - LineConsumer lineConsumer = new AbstractLineConsumer() { - @Override - public void writeLine(String line) throws IOException { - machine.getLogger().writeLine(line); - } - }; CountDownLatch countDownLatch = new CountDownLatch(1); executor.execute(ThreadLocalPropagateContext.wrap(() -> { @@ -133,4 +139,12 @@ public void writeLine(String line) throws IOException { return process; } + + @VisibleForTesting + void logAsErrorAgentStartLogs(String agentName, String logs) { + LOG.error("An error occurs while starting '{}' agent. Detailed log:\n{}", + agentName, + logs); + } + } diff --git a/agents/che-core-api-agent/src/test/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncherTest.java b/agents/che-core-api-agent/src/test/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncherTest.java index 2b10a7388a6..d3b49331084 100644 --- a/agents/che-core-api-agent/src/test/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncherTest.java +++ b/agents/che-core-api-agent/src/test/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncherTest.java @@ -12,6 +12,7 @@ import org.eclipse.che.api.agent.shared.model.Agent; import org.eclipse.che.api.core.ServerException; +import org.eclipse.che.api.core.util.LineConsumer; import org.eclipse.che.api.machine.server.exception.MachineException; import org.eclipse.che.api.machine.server.model.impl.CommandImpl; import org.eclipse.che.api.machine.server.spi.Instance; @@ -26,9 +27,11 @@ import java.util.ArrayList; import static org.mockito.Matchers.any; +import static org.mockito.Matchers.anyString; import static org.mockito.Matchers.eq; import static org.mockito.Mockito.atLeast; import static org.mockito.Mockito.doReturn; +import static org.mockito.Mockito.doThrow; import static org.mockito.Mockito.never; import static org.mockito.Mockito.spy; import static org.mockito.Mockito.times; @@ -59,7 +62,7 @@ public void setUp() throws Exception { launcher = spy(new TestAgentLauncher(500, 100, agentChecker)); when(agent.getScript()).thenReturn("script content"); - doReturn(process).when(launcher).start(any(Instance.class), any(Agent.class)); + doReturn(process).when(launcher).start(any(Instance.class), any(Agent.class), any(LineConsumer.class)); when(agentChecker.isLaunched(any(Agent.class), any(InstanceProcess.class), any(Instance.class))).thenReturn(true); @@ -85,7 +88,7 @@ public void doNothingIfAgentScriptIsNull() throws Exception { launcher.launch(machine, agent); // then - verify(launcher, never()).start(any(Instance.class), any(Agent.class)); + verify(launcher, never()).start(any(Instance.class), any(Agent.class), any(LineConsumer.class)); verify(agent).getScript(); verifyNoMoreInteractions(agent); verifyZeroInteractions(machine); @@ -100,7 +103,7 @@ public void doNothingIfAgentScriptIsEmpty() throws Exception { launcher.launch(machine, agent); // then - verify(launcher, never()).start(any(Instance.class), any(Agent.class)); + verify(launcher, never()).start(any(Instance.class), any(Agent.class), any(LineConsumer.class)); verify(agent).getScript(); verifyNoMoreInteractions(agent); verifyZeroInteractions(machine); @@ -130,7 +133,7 @@ public void shouldCheckIfAgentIsLaunchedUntilItIsLaunched() throws Exception { public void shouldNotCheckIfAgentIsLaunchedMoreThanAgentMaxStartTime() throws Exception { // given launcher = spy(new TestAgentLauncher(200, 100, agentChecker)); - doReturn(process).when(launcher).start(any(Instance.class), any(Agent.class)); + doReturn(process).when(launcher).start(any(Instance.class), any(Agent.class), any(LineConsumer.class)); when(agentChecker.isLaunched(any(Agent.class), any(InstanceProcess.class), any(Instance.class))).thenReturn(false) @@ -153,7 +156,7 @@ public void shouldNotCheckIfAgentIsLaunchedMoreThanAgentMaxStartTime() throws Ex public void shouldNotCheckMoreFrequentThanAgentCheckDelay() throws Exception { // given launcher = spy(new TestAgentLauncher(200, 10, agentChecker)); - doReturn(process).when(launcher).start(any(Instance.class), any(Agent.class)); + doReturn(process).when(launcher).start(any(Instance.class), any(Agent.class), any(LineConsumer.class)); // record time of each check of agent state ArrayList checkTimestamps = new ArrayList<>(5); Answer recordTimestampAndReturnFalse = invocationOnMock -> { @@ -241,7 +244,7 @@ public void shouldStartMachineProcessWithAgentScriptExecution() throws Exception String agentScript = "testAgentScript"; when(agent.getId()).thenReturn(agentId); when(agent.getScript()).thenReturn(agentScript); - when(launcher.start(any(Instance.class), any(Agent.class))).thenCallRealMethod(); + when(launcher.start(any(Instance.class), any(Agent.class), any(LineConsumer.class))).thenCallRealMethod(); // when launcher.launch(machine, agent); @@ -250,6 +253,54 @@ public void shouldStartMachineProcessWithAgentScriptExecution() throws Exception verify(machine).createProcess(eq(new CommandImpl(agentId, agentScript, "agent")), eq(null)); } + @Test(expectedExceptions = ServerException.class, expectedExceptionsMessageRegExp = "Fail launching agent .*\\. Workspace ID:.*") + public void shouldLogAgentStartLogsIfTimeoutReached() throws Exception { + // given + launcher = spy(new TestAgentLauncher(-1, 100, agentChecker)); + when(agentChecker.isLaunched(any(Agent.class), + any(InstanceProcess.class), + any(Instance.class))).thenReturn(false); + + doReturn(process).when(launcher).start(any(Instance.class), any(Agent.class), any(LineConsumer.class)); + + // when + launcher.launch(machine, agent); + + // then + verify(launcher).logAsErrorAgentStartLogs(anyString(), anyString()); + } + + @Test(expectedExceptions = ServerException.class, expectedExceptionsMessageRegExp = "An error on agent start") + public void shouldLogAgentStartLogsIfMachineExceptionOccurs() throws Exception { + // given + doThrow(new MachineException("An error on agent start")) + .when(launcher).start(any(Instance.class), any(Agent.class), any(LineConsumer.class)); + + // when + launcher.launch(machine, agent); + + // then + verify(launcher).logAsErrorAgentStartLogs(anyString(), anyString()); + } + + @Test(expectedExceptions = ServerException.class, expectedExceptionsMessageRegExp = "An error on process kill") + public void shouldLogAgentStartLogsIfMachineExceptionOccursAfterAgentStartTimeoutHadReached() throws Exception { + // given + launcher = spy(new TestAgentLauncher(-1, 100, agentChecker)); + when(agentChecker.isLaunched(any(Agent.class), + any(InstanceProcess.class), + any(Instance.class))).thenReturn(false); + + doReturn(process).when(launcher).start(any(Instance.class), any(Agent.class), any(LineConsumer.class)); + doThrow(new MachineException("An error on process kill")).when(process).kill(); + + // when + launcher.launch(machine, agent); + + // then + verify(launcher).logAsErrorAgentStartLogs(anyString(), anyString()); + } + private static class TestAgentLauncher extends AbstractAgentLauncher { public TestAgentLauncher(long agentMaxStartTimeMs, long agentPingDelayMs, @@ -258,8 +309,8 @@ public TestAgentLauncher(long agentMaxStartTimeMs, } @Override - protected InstanceProcess start(Instance machine, Agent agent) throws ServerException { - return super.start(machine, agent); + protected InstanceProcess start(Instance machine, Agent agent, LineConsumer lineConsumer) throws ServerException { + return super.start(machine, agent, lineConsumer); } @Override From 93aab7c74f92e74b2020741e8e5a08c7b0451ff5 Mon Sep 17 00:00:00 2001 From: Mykola Morhun Date: Tue, 31 Jan 2017 13:31:10 +0200 Subject: [PATCH 2/3] CODENVY-1407: Log agent output on fail Signed-off-by: Mykola Morhun --- .../launcher/AbstractAgentLauncher.java | 45 ++++++++++++------- 1 file changed, 30 insertions(+), 15 deletions(-) diff --git a/agents/che-core-api-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java b/agents/che-core-api-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java index 2a08ad21b16..3c33f31c970 100644 --- a/agents/che-core-api-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java +++ b/agents/che-core-api-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java @@ -68,20 +68,32 @@ public AbstractAgentLauncher(long agentMaxStartTimeMs, this.agentLaunchingChecker = agentLaunchingChecker; } + /** + * Launches agent script in machine and waits until agent starts. + * The machine should be started. + * Retrieves agent's logs if its start fails. + * + * @param machine + * the machine instance in which agent will be started. The machine should be started. + * @param agent + * the agent to start + * @throws ServerException + * if script execution failed + */ @Override public void launch(Instance machine, Agent agent) throws ServerException { if (isNullOrEmpty(agent.getScript())) { return; } ListLineConsumer agentLogger = new ListLineConsumer(); + LineConsumer lineConsumer = new AbstractLineConsumer() { + @Override + public void writeLine(String line) throws IOException { + machine.getLogger().writeLine(line); + agentLogger.writeLine(line); + } + }; try { - LineConsumer lineConsumer = new AbstractLineConsumer() { - @Override - public void writeLine(String line) throws IOException { - machine.getLogger().writeLine(line); - agentLogger.writeLine(line); - } - }; final InstanceProcess process = start(machine, agent, lineConsumer); LOG.debug("Waiting for agent {} is launched. Workspace ID:{}", agent.getId(), machine.getWorkspaceId()); @@ -102,6 +114,10 @@ public void writeLine(String line) throws IOException { Thread.currentThread().interrupt(); throw new ServerException(format("Launching agent %s is interrupted", agent.getName())); } finally { + try { + lineConsumer.close(); + } catch (IOException ignored) { + } agentLogger.close(); } @@ -123,11 +139,6 @@ protected InstanceProcess start(Instance machine, Agent agent, LineConsumer line machine.getLogger().writeLine(format("[ERROR] %s", e.getMessage())); } catch (IOException ignored) { } - } finally { - try { - lineConsumer.close(); - } catch (IOException ignored) { - } } })); try { @@ -142,9 +153,13 @@ protected InstanceProcess start(Instance machine, Agent agent, LineConsumer line @VisibleForTesting void logAsErrorAgentStartLogs(String agentName, String logs) { - LOG.error("An error occurs while starting '{}' agent. Detailed log:\n{}", - agentName, - logs); + if (!logs.isEmpty()) { + LOG.error("An error occurs while starting '{}' agent. Detailed log:\n{}", + agentName, + logs); + } else { + LOG.error("An error occurs while starting '{}' agent. The agent didn't produce any logs.", agentName); + } } } From 67429a676eeac16f15a66d89a6ca8d0822e0cd18 Mon Sep 17 00:00:00 2001 From: Mykola Morhun Date: Wed, 1 Feb 2017 10:44:12 +0200 Subject: [PATCH 3/3] CODENVY-1407: Log agent output on fail Signed-off-by: Mykola Morhun --- .../agent/server/launcher/AbstractAgentLauncher.java | 12 ------------ 1 file changed, 12 deletions(-) diff --git a/agents/che-core-api-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java b/agents/che-core-api-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java index 3c33f31c970..df74a67f75d 100644 --- a/agents/che-core-api-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java +++ b/agents/che-core-api-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java @@ -68,18 +68,6 @@ public AbstractAgentLauncher(long agentMaxStartTimeMs, this.agentLaunchingChecker = agentLaunchingChecker; } - /** - * Launches agent script in machine and waits until agent starts. - * The machine should be started. - * Retrieves agent's logs if its start fails. - * - * @param machine - * the machine instance in which agent will be started. The machine should be started. - * @param agent - * the agent to start - * @throws ServerException - * if script execution failed - */ @Override public void launch(Instance machine, Agent agent) throws ServerException { if (isNullOrEmpty(agent.getScript())) {