Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

CODENVY-1407: Log agent output on fail #3961

Merged
merged 5 commits into from
Feb 2, 2017
Merged

CODENVY-1407: Log agent output on fail #3961

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
38e4512
CODENVY-1407: Log agent output on fail
Jan 30, 2017
93aab7c
CODENVY-1407: Log agent output on fail
Jan 31, 2017
d98536b
Merge branch 'master' into CODENVY-1407
Jan 31, 2017
bba91ca
Merge branch 'master' into CODENVY-1407
Feb 1, 2017
67429a6
CODENVY-1407: Log agent output on fail
Feb 1, 2017
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
49 changes: 33 additions & 16 deletions ...-agent/src/main/java/org/eclipse/che/api/agent/server/launcher/AbstractAgentLauncher.java
View file
Open in desktop
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() {
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

CompositeLineConsumer?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Possible, but in that case we shouldn't close CompositeLineConsumer, only agentLogger (which is part of composite consumer).

@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
Open in desktop
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