Skip to content

Commit

Permalink
CODENVY-1407: Log agent output on fail (#3961)
Browse files Browse the repository at this point in the history 
CODENVY-1407: Log agent output on fail
  • Loading branch information
Mykola Morhun authored Feb 2, 2017
1 parent 63ab642 commit c0f75d3
Show file tree
Hide file tree
Showing 2 changed files with 92 additions and 24 deletions.
49 changes: 33 additions & 16 deletions ...-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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;
Expand Down Expand Up @@ -71,8 +73,16 @@ 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 {
final InstanceProcess process = start(machine, agent);
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();
Expand All @@ -86,26 +96,26 @@ 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 {
try {
lineConsumer.close();
} catch (IOException ignored) {
}
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(() -> {
Expand All @@ -117,11 +127,6 @@ public void writeLine(String line) throws IOException {
machine.getLogger().writeLine(format("[ERROR] %s", e.getMessage()));
} catch (IOException ignored) {
}
} finally {
try {
lineConsumer.close();
} catch (IOException ignored) {
}
}
}));
try {
Expand All @@ -133,4 +138,16 @@ public void writeLine(String line) throws IOException {

return process;
}

@VisibleForTesting
void logAsErrorAgentStartLogs(String agentName, String 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);
}
}

}
67 changes: 59 additions & 8 deletions ...nt/src/test/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncherTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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;
Expand Down Expand Up @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand Down Expand Up @@ -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)
Expand All @@ -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<Long> checkTimestamps = new ArrayList<>(5);
Answer<Boolean> recordTimestampAndReturnFalse = invocationOnMock -> {
Expand Down Expand Up @@ -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);
Expand All @@ -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,
Expand All @@ -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
Expand Down

0 comments on commit c0f75d3

Please sign in to comment.