Add debug logging

This commit is contained in:
kuroppoi 2023-11-19 15:17:21 +01:00
parent f3809f4a54
commit 163ced2333
17 changed files with 153 additions and 38 deletions

View File

@ -177,14 +177,14 @@ public class UserManager {
/**
* Registers a user with the given ID and password.
* @return {@code true} if the registration was successful.
* Otherwise, if this user ID has already been registered, or if the user data could not be saved, {@code false} is returned instead.
* @return The {@link User} object of the newly registered user if the registration was successful.
* Otherwise, if this user ID has already been registered, or if the user data could not be saved, {@code null} is returned instead.
*/
public boolean registerUser(String userId, String plainPassword) {
public User registerUser(String userId, String plainPassword) {
// Check if user id already exists
if(users.containsKey(userId)) {
logger.warn("Attempted to register user with duplicate ID: {}", userId);
return false;
return null;
}
// Create user
@ -192,11 +192,11 @@ public class UserManager {
// Save user data and return null if it fails
if(!saveUser(user)) {
return false;
return null;
}
users.put(userId, user);
return true;
return user;
}
/**

View File

@ -28,6 +28,7 @@ public class DnsQueryHandler extends SimpleChannelInboundHandler<DatagramDnsQuer
@Override
protected void channelRead0(ChannelHandlerContext ctx, DatagramDnsQuery query) throws Exception {
DefaultDnsQuestion question = query.recordAt(DnsSection.QUESTION);
logger.debug("Received {}", question);
DnsRecordType type = question.type();
// We only need type A (32 bit IPv4) for the DS

View File

@ -28,6 +28,7 @@ import io.netty.channel.ChannelFuture;
import io.netty.channel.ChannelFutureListener;
import io.netty.channel.ChannelHandlerContext;
import io.netty.channel.SimpleChannelInboundHandler;
import io.netty.handler.timeout.ReadTimeoutException;
/**
* GameSpy request handler.
@ -50,6 +51,7 @@ public class GameSpyHandler extends SimpleChannelInboundHandler<GameSpyRequest>
@Override
public void channelActive(ChannelHandlerContext ctx) {
channel = ctx.channel();
logger.debug("Sending GameSpy server challenge");
// Generate random server challenge
serverChallenge = CredentialGenerator.generateChallenge(10);
@ -60,6 +62,8 @@ public class GameSpyHandler extends SimpleChannelInboundHandler<GameSpyRequest>
@Override
public void channelInactive(ChannelHandlerContext ctx) {
logger.debug("User {} disconnected from GameSpy server", user == null ? null : user.getFormattedId());
// Clear data
serverChallenge = null;
sessionKey = -1;
@ -69,15 +73,23 @@ public class GameSpyHandler extends SimpleChannelInboundHandler<GameSpyRequest>
@Override
protected void channelRead0(ChannelHandlerContext ctx, GameSpyRequest request) throws Exception {
logger.debug("Received {}", request);
request.process(this);
}
@Override
public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) throws Exception {
if(cause instanceof ClosedChannelException) {
logger.debug("Silently discarded ClosedChannelException");
return; // Ignore this stupid exception.
}
// Handle timeout
if(cause instanceof ReadTimeoutException) {
logger.debug("User {} timed out", user == null ? null : user.getFormattedId());
return;
}
logger.error("Exception caught in GameSpy handler", cause);
// Send error message and close channel afterwards.
@ -92,6 +104,7 @@ public class GameSpyHandler extends SimpleChannelInboundHandler<GameSpyRequest>
ServiceSession session = userManager.getServiceSession(authToken, "gamespy");
if(session == null) {
logger.debug("Rejecting GameSpy login request because the partner token is invalid");
sendErrorMessage(0x200, "Invalid partner token.", request.sequenceId());
return;
}
@ -101,6 +114,7 @@ public class GameSpyHandler extends SimpleChannelInboundHandler<GameSpyRequest>
String expectedResponse = createCredentialHash(partnerChallengeHash, authToken, clientChallenge, serverChallenge);
if(!expectedResponse.equals(request.response())) {
logger.debug("Rejecting GameSpy login request because the challenge response is invalid");
sendErrorMessage(0x202, "Invalid response.", request.sequenceId());
return;
}
@ -127,7 +141,9 @@ public class GameSpyHandler extends SimpleChannelInboundHandler<GameSpyRequest>
user.setProfileIdOverride(0);
userManager.saveUser(user); // It's not too big of a deal if this fails for some reason
}
logger.info("User {} logged in with profile {}", user.getFormattedId(), profile.getId());
// Prepare and send response
sessionKey = secureRandom.nextInt(Integer.MAX_VALUE);
String proof = createCredentialHash(partnerChallengeHash, authToken, serverChallenge, clientChallenge);
@ -180,10 +196,9 @@ public class GameSpyHandler extends SimpleChannelInboundHandler<GameSpyRequest>
passwordHash));
}
public void destroySessionKey(int sessionKey) {
if(validateSessionKey(sessionKey)) {
sessionKey = -1;
}
public void handleLogout() {
logger.info("User {} logged out of profile {}", user.getFormattedId(), profile.getId());
sessionKey = -1; // Is there a point?
}
public boolean validateSessionKey(int sessionKey) {

View File

@ -26,6 +26,7 @@ import io.netty.channel.ChannelPipeline;
import io.netty.channel.epoll.EpollServerSocketChannel;
import io.netty.channel.socket.nio.NioServerSocketChannel;
import io.netty.handler.codec.DelimiterBasedFrameDecoder;
import io.netty.handler.timeout.ReadTimeoutHandler;
import io.netty.util.concurrent.DefaultEventExecutor;
import io.netty.util.concurrent.EventExecutorGroup;
@ -64,6 +65,7 @@ public class GameSpyServer extends NettyServerBase {
@Override
protected void initChannel(Channel channel) throws Exception {
ChannelPipeline pipeline = channel.pipeline();
pipeline.addLast(new ReadTimeoutHandler(180));
pipeline.addLast(new DelimiterBasedFrameDecoder(512, Unpooled.wrappedBuffer("\\final\\".getBytes())));
pipeline.addLast(new GameSpyRequestDecoder(mapper, requestTypes));
pipeline.addLast(new GameSpyMessageEncoder(mapper));

View File

@ -1,13 +1,9 @@
package entralinked.network.gamespy.request;
import entralinked.network.gamespy.GameSpyHandler;
import entralinked.network.gamespy.message.GameSpyMessage;
@GameSpyMessage(name = "ka")
public record GameSpyKeepAliveRequest() implements GameSpyRequest {
@Override
public void process(GameSpyHandler handler) {
handler.sendMessage(this); // Pong it back
}
public void process(GameSpyHandler handler) {}
}

View File

@ -28,4 +28,11 @@ public record GameSpyLoginRequest(
public void process(GameSpyHandler handler) {
handler.handleLoginRequest(this);
}
@Override
public String toString() {
return ("GameSpyLoginRequest[sequenceId=%s, userId=%s, gameName=%s, profileId=%s, namespaceId=%s, partnerId=%s, productId=%s, "
+ "sdkRevision=%s, firewall=%s, port=%s, quiet=%s]")
.formatted(sequenceId, userId, gameName, profileId, namespaceId, partnerId, productId, sdkRevision, firewall, port, quiet);
}
}

View File

@ -10,6 +10,14 @@ public record GameSpyLogoutRequest(
@Override
public void process(GameSpyHandler handler) {
handler.destroySessionKey(sessionKey);
if(handler.validateSessionKey(sessionKey)) {
handler.handleLogout();
}
}
@Override
public String toString() {
// Exlude session key
return "GameSpyLogoutRequest[]";
}
}

View File

@ -16,4 +16,10 @@ public record GameSpyProfileRequest(
handler.handleProfileRequest(this);
}
}
@Override
public String toString() {
// Exlude session key
return "GameSpyProfileRequest[sequenceId=%s, profileId=%s]".formatted(sequenceId, profileId);
}
}

View File

@ -21,4 +21,11 @@ public record GameSpyProfileUpdateRequest(
handler.handleUpdateProfileRequest(this);
}
}
@Override
public String toString() {
// Exlude session key
return "GameSpyProfileUpdateRequest[partnerId=%s, firstName=%s, lastName=%s, aimName=%s, zipCode=%s]"
.formatted(partnerId, firstName, lastName, aimName, zipCode);
}
}

View File

@ -14,4 +14,10 @@ public record GameSpyStatusRequest(
public void process(GameSpyHandler handler) {
handler.validateSessionKey(sessionKey);
}
@Override
public String toString() {
// Exlude session key
return "GameSpyStatusRequest[statusString=%s, locationString=%s]".formatted(statusString, locationString);
}
}

View File

@ -4,6 +4,9 @@ import java.io.FileInputStream;
import java.io.IOException;
import java.util.List;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import com.fasterxml.jackson.databind.ObjectMapper;
import entralinked.Entralinked;
@ -25,6 +28,7 @@ import io.javalin.http.HttpStatus;
*/
public class DlsHandler implements HttpHandler {
private static final Logger logger = LogManager.getLogger();
private final ObjectMapper mapper = new ObjectMapper(new UrlEncodedFormFactory());
private final DlcList dlcList;
private final UserManager userManager;
@ -45,11 +49,13 @@ public class DlsHandler implements HttpHandler {
private void handleDownloadRequest(Context ctx) throws IOException {
// Deserialize request body
DlsRequest request = mapper.readValue(ctx.body().replace("%2A", "*"), DlsRequest.class);
logger.debug("Received {}", request);
// Check if service session is valid
ServiceSession session = userManager.getServiceSession(request.serviceToken(), "dls1.nintendowifi.net");
if(session == null) {
logger.debug("Rejecting DLS request because the service session has expired");
ctx.status(HttpStatus.UNAUTHORIZED);
return;
}

View File

@ -21,5 +21,13 @@ public record DlsRequest(
@JsonProperty("contents") String dlcName, // action=contents
@JsonProperty("attr1") String dlcType, // action=list
@JsonProperty("attr2") int dlcIndex, // action=list
@JsonProperty("offset") int offset, // ?
@JsonProperty("num") int num) {} // ?
@JsonProperty("offset") int offset, // Start offset in the list
@JsonProperty("num") int num) { // Number of entries
@Override
public String toString() {
return ("DlsRequest[userId=%s, gameCode=%s, accessPointInfo=%s, action=%s, dlcGameCode=%s, dlcName=%s, dlcType=%s, "
+ "dlcIndex=%s, offset=%s, num=%s]")
.formatted(userId, gameCode, accessPointInfo, action, dlcGameCode, dlcName, dlcType, dlcIndex, offset, num);
}
}

View File

@ -2,6 +2,9 @@ package entralinked.network.http.nas;
import java.io.IOException;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import com.fasterxml.jackson.databind.ObjectMapper;
import com.fasterxml.jackson.datatype.jsr310.JavaTimeModule;
@ -21,6 +24,7 @@ import io.javalin.http.Context;
*/
public class NasHandler implements HttpHandler {
private static final Logger logger = LogManager.getLogger();
private final ObjectMapper mapper = new ObjectMapper(new UrlEncodedFormFactory()).registerModule(new JavaTimeModule());
private final Configuration configuration;
private final UserManager userManager;
@ -42,6 +46,7 @@ public class NasHandler implements HttpHandler {
private void handleNasRequest(Context ctx) throws IOException {
// Deserialize body into a request object
NasRequest request = mapper.readValue(ctx.body(), NasRequest.class);
logger.debug("Received {}", request);
// Determine handler function based on request action
HttpRequestHandler<NasRequest> handler = switch(request.action()) {
@ -61,6 +66,7 @@ public class NasHandler implements HttpHandler {
private void handleLogin(NasRequest request, Context ctx) throws IOException {
// Make sure branch code is present
if(request.branchCode() == null) {
logger.debug("Rejecting NAS login request because no branch code is present");
result(ctx, NasReturnCode.BAD_REQUEST);
return;
}
@ -77,7 +83,7 @@ public class NasHandler implements HttpHandler {
// Try to register, if the configuration allows it
if(!UserManager.isValidUserId(userId) || userManager.doesUserExist(userId)
|| !userManager.registerUser(userId, request.password())) {
|| userManager.registerUser(userId, request.password()) == null) {
// Oh well, try again!
result(ctx, NasReturnCode.USER_NOT_FOUND);
return;
@ -85,10 +91,12 @@ public class NasHandler implements HttpHandler {
// Should *never* return null in this location
user = userManager.authenticateUser(userId, request.password());
logger.info("Created account for user {}", user.getFormattedId());
}
// Prepare GameSpy server credentials
ServiceCredentials credentials = userManager.createServiceSession(user, "gamespy", request.branchCode());
logger.info("Created GameSpy session for user {}", user.getFormattedId());
result(ctx, new NasLoginResponse("gamespy.com", credentials.authToken(), credentials.challenge()));
}
@ -105,11 +113,14 @@ public class NasHandler implements HttpHandler {
}
// Try to register user
if(!userManager.registerUser(userId, request.password())) {
User user = userManager.registerUser(userId, request.password());
if(user == null) {
result(ctx, NasReturnCode.INTERNAL_SERVER_ERROR);
return;
}
logger.info("Created account for user {}", user.getFormattedId());
result(ctx, NasReturnCode.REGISTRATION_SUCCESS);
}
@ -125,15 +136,19 @@ public class NasHandler implements HttpHandler {
return;
}
String type = request.serviceType();
// Determine service location from type
String service = switch(request.serviceType()) {
String service = switch(type) {
case "0000" -> "external"; // External game-specific service
case "9000" -> "dls1.nintendowifi.net"; // Download server
default -> throw new IllegalArgumentException("Invalid service type: " + request.serviceType());
default -> throw new IllegalArgumentException("Invalid service type: " + type);
};
// Prepare user credentials
ServiceCredentials credentials = userManager.createServiceSession(user, service, null);
logger.info("Created {} session for user {}",
type.equals("0000") ? "PGL" : type.equals("9000") ? "DLS1" : "this should never be logged", user.getFormattedId());
result(ctx, new NasServiceLocationResponse(true, service, credentials.authToken()));
}

View File

@ -29,4 +29,13 @@ public record NasRequest(
// Request-specific info
@JsonProperty(value = "action", required = true) String action,
@JsonProperty("gsbrcd") String branchCode, // action=login
@JsonProperty("svc") String serviceType) {} // action=SVCLOC
@JsonProperty("svc") String serviceType) { // action=SVCLOC
@Override
public String toString() {
return ("NasRequest[userId=%s, gameCode=%s, makerCode=%s, unitCode=%s, sdkVersion=%s, language=%s, bssid=%s, "
+ "accessPointInfo=%s, deviceTime=%s, action=%s, serviceType=%s]")
.formatted(userId, gameCode, makerCode, unitCode, sdkVersion, language, bssid,
accessPointInfo, deviceTime, action, serviceType);
}
}

View File

@ -93,6 +93,7 @@ public class PglHandler implements HttpHandler {
if(credentials == null ||
!username.equals(credentials.getUsername()) || !password.equals(credentials.getPassword())) {
logger.debug("Rejecting PGL request because the auth credentials were incorrect");
ctx.status(HttpStatus.UNAUTHORIZED);
clearTasks(ctx);
return;
@ -100,11 +101,13 @@ public class PglHandler implements HttpHandler {
// Deserialize the request
PglRequest request = mapper.readValue(ctx.queryString(), PglRequest.class);
logger.debug("Received {}", request);
// Verify the service session token
ServiceSession session = userManager.getServiceSession(request.token(), "external");
if(session == null) {
logger.debug("Rejecting PGL request because the service session has expired");
ctx.status(HttpStatus.UNAUTHORIZED);
clearTasks(ctx);
return;
@ -131,7 +134,7 @@ public class PglHandler implements HttpHandler {
};
// Handle the request
handler.process(request, ctx);
handler.process(request, ctx);
}
/**
@ -198,13 +201,14 @@ public class PglHandler implements HttpHandler {
return;
}
logger.info("Player {} is downloading save data as user {}", player.getGameSyncId(), user.getFormattedId());
// Write status code
writeStatusCode(outputStream, 0);
// Allow it to wake up anyway, maybe the poor sap is stuck..
// Just don't send any other data.
if(player.getStatus() == PlayerStatus.AWAKE) {
logger.info("Player {} is downloading save data, but is already awake!", player.getGameSyncId());
return;
}
@ -312,7 +316,7 @@ public class PglHandler implements HttpHandler {
// Full visitor type consists of a trainer class and what I call a 'personality' index
// that, along with the trainer class, determines which phrases the visitor uses.
// The shope type is calculated in such an odd manner because for some reason,
// The shop type is calculated in such an odd manner because for some reason,
// the 'starting' index of the shop type used increases by 2 for each visitor type.
// For example, if the visitor type is '0', then shop type '0' would be a raffle.
// However, if the visitor type is '2', then shop type '0' results in a dojo instead.
@ -343,6 +347,7 @@ public class PglHandler implements HttpHandler {
private void handleMemoryLink(PglRequest request, Context ctx) throws IOException {
LEOutputStream outputStream = new LEOutputStream(ctx.outputStream());
Player player = playerManager.getPlayer(request.gameSyncId());
User user = ctx.attribute("user");
// Check if player exists
if(player == null) {
@ -364,6 +369,8 @@ public class PglHandler implements HttpHandler {
return;
}
logger.info("User {} is Memory Linking with player {}", user.getFormattedId(), player.getGameSyncId());
// Send the save data!
try(FileInputStream inputStream = new FileInputStream(file)) {
writeStatusCode(outputStream, 0);
@ -422,12 +429,11 @@ public class PglHandler implements HttpHandler {
* POST handler for {@code /dsio/gw?p=savedata.upload}
*/
private void handleUploadSaveData(PglRequest request, Context ctx) throws IOException {
// Prepare response
LEOutputStream outputStream = new LEOutputStream(ctx.outputStream());
Player player = playerManager.getPlayer(request.gameSyncId());
User user = ctx.attribute("user");
// Check if the player exists, has no Pokémon tucked in already and uses the same game version
Player player = playerManager.getPlayer(request.gameSyncId());
if(player == null
|| (!configuration.allowOverwritingPlayerDreamInfo() && player.getStatus() != PlayerStatus.AWAKE)
|| (!configuration.allowPlayerGameVersionMismatch() && player.getGameVersion() != null
@ -444,6 +450,8 @@ public class PglHandler implements HttpHandler {
return;
}
logger.info("Player {} is uploading save data as user {}", player.getGameSyncId(), user.getFormattedId());
// Try to store save data
if(!playerManager.storePlayerGameSaveFile(player, ctx.bodyInputStream())) {
writeStatusCode(outputStream, 4); // Game save data IO error

View File

@ -17,4 +17,11 @@ public record PglRequest(
public GameVersion gameVersion() {
return GameVersion.lookup(romCode(), languageCode());
}
@Override
public String toString() {
// Exlude token
return "PglRequest[gameSyncId=%s, type=%s, romCode=%s, languageCode=%s, dreamWorld=%s]"
.formatted(gameSyncId, type, romCode, languageCode, dreamWorld);
}
}

View File

@ -1,25 +1,39 @@
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE xml>
<Configuration status="off" packages="entralinked.utility">
<Configuration status="WARN" packages="entralinked.utility">
<Properties>
<Property name="LOGS_DIR">logs</Property>
<Property name="PATTERN_MINIMAL">%d{yyyy-MM-dd HH:mm:ss.SSS} %5level : %msg%n</Property>
<Property name="PATTERN_DETAILED">%d{yyyy-MM-dd HH:mm:ss.SSS} %5level [%32t] %-48c{1.2*} : %msg%n</Property>
</Properties>
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %5level [%32t] %-48c{1.2*} : %msg%n"/>
<PatternLayout pattern="${PATTERN_DETAILED}"/>
</Console>
<RollingFile name="LogFile" fileName="logs/latest.log" filePattern="logs/%d{yyyy-MM-dd}-%i.log.gz">
<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %5level [%16t] %-48c{1.2*} : %msg%n"/>
<RollingFile name="LogFile" fileName="${LOGS_DIR}/latest.log" filePattern="${LOGS_DIR}/%d{yyyy-MM-dd}-%i.log.gz">
<PatternLayout pattern="${PATTERN_DETAILED}"/>
<ThresholdFilter level="INFO"/>
<Policies>
<OnStartupTriggeringPolicy/>
</Policies>
</RollingFile>
<ConsumerAppender name="GuiOutput">
<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %5level : %msg%n"/>
<PatternLayout pattern="${PATTERN_MINIMAL}"/>
<ThresholdFilter level="INFO"/>
</ConsumerAppender>
<File name="DebugLogFile" fileName="${LOGS_DIR}/debug.log" append="false">
<PatternLayout pattern="${PATTERN_DETAILED}"/>
<ThresholdFilter level="DEBUG"/>
</File>
</Appenders>
<Loggers>
<Root level="info">
<AppenderRef ref="Console"/>
<Logger name="entralinked" additivity="false">
<AppenderRef ref="LogFile"/>
<AppenderRef ref="GuiOutput"/>
<AppenderRef ref="DebugLogFile"/>
</Logger>
<Root level="all">
<AppenderRef ref="Console"/>
</Root>
</Loggers>
</Configuration>