From b3ba0d934670df86adaac8b110c9f75fd901921b Mon Sep 17 00:00:00 2001 From: Michael Turner Date: Thu, 8 Dec 2022 14:48:03 -0800 Subject: [PATCH] Add debug messages for DHCP state changes, Tftp progress, and PxeBc progress. (#188) ## Description Add DEBUG message to Dhcp4Dxe - [ No] Breaking change? - Will this change break pre-existing builds or functionality without action being taken? ## How This Was Tested Not tested ## Integration Instructions To only get the DHCP debug messages, edit your platform build .dsc to add the debug flag to Current: NetworkPkg/Dhcp4Dxe/Dhcp4Dxe.inf To get the new DEBUG_NET messages from Dhcp4Dxe: NetworkPkg/Dhcp4Dxe/Dhcp4Dxe.inf { gEfiMdePkgTokenSpaceGuid.PcdDebugPrintErrorLevel|0x80084246 gEfiMdePkgTokenSpaceGuid.PcdFixedDebugPrintErrorLevel|0x80084246 } Co-authored-by: kuqin12 <42554914+kuqin12@users.noreply.github.com> --- NetworkPkg/Dhcp4Dxe/Dhcp4Impl.c | 7 ++++++ NetworkPkg/Dhcp4Dxe/Dhcp4Io.c | 38 ++++++++++++++++++++++++++++- NetworkPkg/Mtftp4Dxe/Mtftp4Impl.c | 12 +++++++++ NetworkPkg/Mtftp4Dxe/Mtftp4Rrq.c | 16 ++++++++++++ NetworkPkg/Mtftp4Dxe/Mtftp4Wrq.c | 6 +++++ NetworkPkg/UefiPxeBcDxe/PxeBcBoot.c | 3 +++ NetworkPkg/UefiPxeBcDxe/PxeBcImpl.c | 6 +++++ 7 files changed, 87 insertions(+), 1 deletion(-) diff --git a/NetworkPkg/Dhcp4Dxe/Dhcp4Impl.c b/NetworkPkg/Dhcp4Dxe/Dhcp4Impl.c index 24a0693942..351487b446 100644 --- a/NetworkPkg/Dhcp4Dxe/Dhcp4Impl.c +++ b/NetworkPkg/Dhcp4Dxe/Dhcp4Impl.c @@ -788,11 +788,13 @@ EfiDhcp4Start ( DhcpSb = Instance->Service; if (DhcpSb->DhcpState == Dhcp4Stopped) { + DEBUG ((DEBUG_NET | DEBUG_ERROR, "%a: failed, in stopped state.\n", __FUNCTION__)); Status = EFI_NOT_STARTED; goto ON_ERROR; } if ((DhcpSb->DhcpState != Dhcp4Init) && (DhcpSb->DhcpState != Dhcp4InitReboot)) { + DEBUG ((DEBUG_NET | DEBUG_ERROR, "%a: failed, !Init and !InitReboot state.\n", __FUNCTION__)); Status = EFI_ALREADY_STARTED; goto ON_ERROR; } @@ -903,11 +905,13 @@ EfiDhcp4RenewRebind ( DhcpSb = Instance->Service; if (DhcpSb->DhcpState == Dhcp4Stopped) { + DEBUG ((DEBUG_NET, "%a: failed, Dhcp4Stopped.\n", __FUNCTION__)); Status = EFI_NOT_STARTED; goto ON_EXIT; } if (DhcpSb->DhcpState != Dhcp4Bound) { + DEBUG ((DEBUG_NET, "%a: failed, !Dhcp4Bound.\n", __FUNCTION__)); Status = EFI_ACCESS_DENIED; goto ON_EXIT; } @@ -1016,6 +1020,7 @@ EfiDhcp4Release ( DhcpSb = Instance->Service; if ((DhcpSb->DhcpState != Dhcp4InitReboot) && (DhcpSb->DhcpState != Dhcp4Bound)) { + DEBUG ((DEBUG_NET, "%a: failed, !InitReboot and !Bound.\n", __FUNCTION__)); Status = EFI_ACCESS_DENIED; goto ON_EXIT; } @@ -1085,6 +1090,8 @@ EfiDhcp4Stop ( DhcpCleanLease (DhcpSb); + DEBUG ((DEBUG_NET, "%a: new state is Dhcp4Stopped.\n", __FUNCTION__)); + DhcpSb->DhcpState = Dhcp4Stopped; DhcpSb->ServiceState = DHCP_UNCONFIGED; diff --git a/NetworkPkg/Dhcp4Dxe/Dhcp4Io.c b/NetworkPkg/Dhcp4Dxe/Dhcp4Io.c index 238e186c5b..e53b7c66e3 100644 --- a/NetworkPkg/Dhcp4Dxe/Dhcp4Io.c +++ b/NetworkPkg/Dhcp4Dxe/Dhcp4Io.c @@ -39,6 +39,7 @@ DhcpInitRequest ( Status = DhcpSendMessage (DhcpSb, NULL, NULL, DHCP_MSG_DISCOVER, NULL); if (EFI_ERROR (Status)) { + DEBUG ((DEBUG_NET | DEBUG_ERROR, "%a: SendError, new state is Dhcp4Init. Code=%r\n", __FUNCTION__, Status)); DhcpSb->DhcpState = Dhcp4Init; return Status; } @@ -47,6 +48,7 @@ DhcpInitRequest ( Status = DhcpSendMessage (DhcpSb, NULL, NULL, DHCP_MSG_REQUEST, NULL); if (EFI_ERROR (Status)) { + DEBUG ((DEBUG_NET | DEBUG_ERROR, "%a: SendError, new state is Dhcp4InitReboot. Code-%r\n", __FUNCTION__, Status)); DhcpSb->DhcpState = Dhcp4InitReboot; return Status; } @@ -86,6 +88,8 @@ DhcpCallUser ( *NewPacket = NULL; } + DEBUG ((DEBUG_NET, "%a: Calling user code with DhcpState=%d.\n", __FUNCTION__, Event)); + // // If user doesn't provide the call back function, return the value // that directs the client to continue the normal process. @@ -184,6 +188,8 @@ DhcpSetState ( { EFI_STATUS Status; + DEBUG ((DEBUG_NET, "%a: Setting state to %d, CallUser=%d.\n", __FUNCTION__, State, CallUser)); + if (CallUser) { Status = EFI_SUCCESS; @@ -425,6 +431,8 @@ DhcpCleanLease ( IN DHCP_SERVICE *DhcpSb ) { + DEBUG ((DEBUG_NET, "%a: Setting state to Init.\n", __FUNCTION__)); + DhcpSb->DhcpState = Dhcp4Init; DhcpSb->Xid = DhcpSb->Xid + 1; DhcpSb->ClientAddr = 0; @@ -568,8 +576,10 @@ DhcpEndSession ( ) { if (DHCP_CONNECTED (DhcpSb->DhcpState)) { + DEBUG ((DEBUG_NET, "%a: AddressLost.\n", __FUNCTION__)); DhcpCallUser (DhcpSb, Dhcp4AddressLost, NULL, NULL); } else { + DEBUG ((DEBUG_NET, "%a: Fail.\n", __FUNCTION__)); DhcpCallUser (DhcpSb, Dhcp4Fail, NULL, NULL); } @@ -869,22 +879,28 @@ DhcpHandleReboot ( DhcpCallUser (DhcpSb, Dhcp4RcvdNak, Packet, NULL); DhcpSb->ClientAddr = 0; - DhcpSb->DhcpState = Dhcp4Init; + DEBUG ((DEBUG_NET, "%a: NAK received, going to Init\n", __FUNCTION__)); + + DhcpSb->DhcpState = Dhcp4Init; Status = DhcpInitRequest (DhcpSb); goto ON_EXIT; } + DEBUG ((DEBUG_NET, "%a: ACK Received.\n", __FUNCTION__)); + // // Check whether the ACK matches the selected offer // if (EFI_NTOHL (Head->YourAddr) != DhcpSb->ClientAddr) { + DEBUG ((DEBUG_NET, "%a: ACK didn't match offer.\n", __FUNCTION__)); Status = EFI_DEVICE_ERROR; goto ON_EXIT; } Status = DhcpCallUser (DhcpSb, Dhcp4RcvdAck, Packet, NULL); if (EFI_ERROR (Status)) { + DEBUG ((DEBUG_NET, "%a: Error from CallUser - %r.\n", __FUNCTION__, Status)); goto ON_EXIT; } @@ -893,6 +909,7 @@ DhcpHandleReboot ( // DhcpSb->Para = AllocateCopyPool (sizeof (DHCP_PARAMETER), Para); if (DhcpSb->Para == NULL) { + DEBUG ((DEBUG_NET, "%a: Out of resources.\n", __FUNCTION__)); Status = EFI_OUT_OF_RESOURCES; goto ON_EXIT; } @@ -900,11 +917,13 @@ DhcpHandleReboot ( DhcpSb->Selected = Packet; Status = DhcpLeaseAcquired (DhcpSb); if (EFI_ERROR (Status)) { + DEBUG ((DEBUG_NET, "%a: Error from LeaseAcquired - %r.\n", __FUNCTION__, Status)); return Status; } DhcpSb->IoStatus = EFI_SUCCESS; DhcpNotifyUser (DhcpSb, DHCP_NOTIFY_COMPLETION); + DEBUG ((DEBUG_NET, "%a: DHCP Complete.\n", __FUNCTION__)); return EFI_SUCCESS; ON_EXIT: @@ -954,6 +973,7 @@ DhcpInput ( ASSERT (UdpPacket != NULL); if (DhcpSb->DhcpState == Dhcp4Stopped) { + DEBUG ((DEBUG_NET, "%a: Restarting due to state == Stopped.\n", __FUNCTION__)); goto RESTART; } @@ -961,6 +981,7 @@ DhcpInput ( // Validate the packet received // if (UdpPacket->TotalSize < sizeof (EFI_DHCP4_HEADER)) { + DEBUG ((DEBUG_NET, "%a: Restarting due to invalid header size.\n", __FUNCTION__)); goto RESTART; } @@ -971,6 +992,7 @@ DhcpInput ( Packet = (EFI_DHCP4_PACKET *)AllocatePool (Len); if (Packet == NULL) { + DEBUG ((DEBUG_NET, "%a: Restarting due to out of resources.\n", __FUNCTION__)); goto RESTART; } @@ -979,6 +1001,7 @@ DhcpInput ( Packet->Length = NetbufCopy (UdpPacket, 0, UdpPacket->TotalSize, (UINT8 *)Head); if (Packet->Length != UdpPacket->TotalSize) { + DEBUG ((DEBUG_NET, "%a: Restarting due to incorrect packet length.\n", __FUNCTION__)); goto RESTART; } @@ -989,6 +1012,7 @@ DhcpInput ( (NTOHL (Head->Xid) != DhcpSb->Xid) || (CompareMem (DhcpSb->ClientAddressSendOut, Head->ClientHwAddr, Head->HwAddrLen) != 0)) { + DEBUG ((DEBUG_NET, "%a: Restarting due to not our answer.\n", __FUNCTION__)); goto RESTART; } @@ -1000,6 +1024,7 @@ DhcpInput ( (Packet->Dhcp4.Magik == DHCP_OPTION_MAGIC) && EFI_ERROR (DhcpValidateOptions (Packet, &Para))) { + DEBUG ((DEBUG_NET, "%a: Restarting due to bad options.\n", __FUNCTION__)); goto RESTART; } @@ -1017,10 +1042,12 @@ DhcpInput ( switch (DhcpSb->DhcpState) { case Dhcp4Selecting: Status = DhcpHandleSelect (DhcpSb, Packet, Para); + DEBUG ((DEBUG_NET, "%a: Selecting - code=%r.\n", __FUNCTION__, Status)); break; case Dhcp4Requesting: Status = DhcpHandleRequest (DhcpSb, Packet, Para); + DEBUG ((DEBUG_NET, "%a: Requesting - code=%r.\n", __FUNCTION__, Status)); break; case Dhcp4InitReboot: @@ -1029,6 +1056,7 @@ DhcpInput ( // // Ignore the packet in INITREBOOT, INIT and BOUND states // + DEBUG ((DEBUG_NET, "%a: Ignoring Init, InitReboot, Bound.\n", __FUNCTION__)); FreePool (Packet); Status = EFI_SUCCESS; break; @@ -1036,10 +1064,12 @@ DhcpInput ( case Dhcp4Renewing: case Dhcp4Rebinding: Status = DhcpHandleRenewRebind (DhcpSb, Packet, Para); + DEBUG ((DEBUG_NET, "%a: Renew/Rebinding - code=%r.\n", __FUNCTION__, Status)); break; case Dhcp4Rebooting: Status = DhcpHandleReboot (DhcpSb, Packet, Para); + DEBUG ((DEBUG_NET, "%a: Rebooting - code=%r.\n", __FUNCTION__, Status)); break; } @@ -1391,6 +1421,8 @@ DhcpRetransmit ( ASSERT (DhcpSb->LastPacket != NULL); + DEBUG ((DEBUG_NET, "%a: Entry...\n", __FUNCTION__)); + // // For REQUEST message in Dhcp4Requesting state, do not change the secs fields. // @@ -1523,6 +1555,7 @@ DhcpOnTimerTick ( } DhcpSb->IoStatus = EFI_TIMEOUT; + DEBUG ((DEBUG_NET, "%a: Timeout\n", __FUNCTION__)); DhcpNotifyUser (DhcpSb, DHCP_NOTIFY_RENEWREBIND); } } else { @@ -1607,6 +1640,7 @@ DhcpOnTimerTick ( Instance = NET_LIST_USER_STRUCT (Entry, DHCP_PROTOCOL, Link); Instance->Timeout--; if ((Instance->Timeout == 0) && (Instance->Token != NULL)) { + DEBUG ((DEBUG_NET, "%a: Calling PxeDhcpDone\n", __FUNCTION__)); PxeDhcpDone (Instance); } } @@ -1614,6 +1648,8 @@ DhcpOnTimerTick ( return; END_SESSION: + DEBUG ((DEBUG_NET, "%a: Ending session with timeout\n", __FUNCTION__)); + DhcpEndSession (DhcpSb, EFI_TIMEOUT); return; diff --git a/NetworkPkg/Mtftp4Dxe/Mtftp4Impl.c b/NetworkPkg/Mtftp4Dxe/Mtftp4Impl.c index 211ddbcdcc..b9fd80fa20 100644 --- a/NetworkPkg/Mtftp4Dxe/Mtftp4Impl.c +++ b/NetworkPkg/Mtftp4Dxe/Mtftp4Impl.c @@ -492,6 +492,8 @@ Mtftp4Start ( // Token->Status = EFI_NOT_READY; + DEBUG ((DEBUG_NET, "%a: Starting request, type=%d\n", __FUNCTION__, (UINT32)Operation)); + // // Build and send an initial requests // @@ -637,6 +639,8 @@ EfiMtftp4Configure ( return EFI_INVALID_PARAMETER; } + DEBUG ((DEBUG_NET, "%a: Entry\n", __FUNCTION__)); + Instance = MTFTP4_PROTOCOL_FROM_THIS (This); if (ConfigData == NULL) { @@ -693,6 +697,8 @@ EfiMtftp4Configure ( gBS->RestoreTPL (OldTpl); } + DEBUG ((DEBUG_NET, "%a: Exit Success\n", __FUNCTION__)); + return EFI_SUCCESS; } @@ -794,6 +800,8 @@ EfiMtftp4ReadFile ( IN EFI_MTFTP4_TOKEN *Token ) { + DEBUG ((DEBUG_NET, "%a: Entry\n", __FUNCTION__)); + return Mtftp4Start (This, Token, EFI_MTFTP4_OPCODE_RRQ); } @@ -854,6 +862,8 @@ EfiMtftp4WriteFile ( IN EFI_MTFTP4_TOKEN *Token ) { + DEBUG ((DEBUG_NET, "%a: Entry\n", __FUNCTION__)); + return Mtftp4Start (This, Token, EFI_MTFTP4_OPCODE_WRQ); } @@ -923,6 +933,8 @@ EfiMtftp4ReadDirectory ( IN EFI_MTFTP4_TOKEN *Token ) { + DEBUG ((DEBUG_NET, "%a: Entry\n", __FUNCTION__)); + return Mtftp4Start (This, Token, EFI_MTFTP4_OPCODE_DIR); } diff --git a/NetworkPkg/Mtftp4Dxe/Mtftp4Rrq.c b/NetworkPkg/Mtftp4Dxe/Mtftp4Rrq.c index 75aaa80617..4962797632 100644 --- a/NetworkPkg/Mtftp4Dxe/Mtftp4Rrq.c +++ b/NetworkPkg/Mtftp4Dxe/Mtftp4Rrq.c @@ -49,6 +49,8 @@ Mtftp4RrqStart ( { EFI_STATUS Status; + DEBUG ((DEBUG_NET, "%a: Entry\n", __FUNCTION__)); + // // The valid block number range are [1, 0xffff]. For example: // the client sends an RRQ request to the server, the server @@ -273,6 +275,7 @@ Mtftp4RrqHandleData ( Status = Mtftp4RrqSaveBlock (Instance, Packet, Len); if (EFI_ERROR (Status)) { + DEBUG ((DEBUG_NET, "%a: Error = %r\n", __FUNCTION__, Status)); return Status; } @@ -429,6 +432,7 @@ Mtftp4RrqConfigMcastPort ( Status = McastIo->Protocol.Udp4->Configure (McastIo->Protocol.Udp4, &UdpConfig); if (EFI_ERROR (Status)) { + DEBUG ((DEBUG_NET, "%a: Error = %r\n", __FUNCTION__, Status)); return Status; } @@ -448,6 +452,7 @@ Mtftp4RrqConfigMcastPort ( ); if (EFI_ERROR (Status)) { + DEBUG ((DEBUG_NET, "%a: Error2 = %r\n", __FUNCTION__, Status)); McastIo->Protocol.Udp4->Configure (McastIo->Protocol.Udp4, NULL); return Status; } @@ -527,6 +532,8 @@ Mtftp4RrqHandleOack ( ); } + DEBUG ((DEBUG_NET, "%a: TFTP ERROR(%d) = %r\n", __FUNCTION__, __LINE__, Status)); + return EFI_TFTP_ERROR; } @@ -546,6 +553,8 @@ Mtftp4RrqHandleOack ( (UINT8 *)"Illegal multicast setting" ); + DEBUG ((DEBUG_NET, "%a: TFTP ERROR(%d) = %r\n", __FUNCTION__, __LINE__, Status)); + return EFI_TFTP_ERROR; } @@ -592,6 +601,8 @@ Mtftp4RrqHandleOack ( (UINT8 *)"Failed to create socket to receive multicast packet" ); + DEBUG ((DEBUG_NET, "%a: TFTP ERROR(%d) = %r\n", __FUNCTION__, __LINE__, Status)); + return Status; } @@ -669,6 +680,7 @@ Mtftp4RrqInput ( if (EFI_ERROR (IoStatus)) { Status = IoStatus; + DEBUG ((DEBUG_NET, "%a: TFTP ERROR(%d) = %r\n", __FUNCTION__, __LINE__, Status)); goto ON_EXIT; } @@ -744,6 +756,8 @@ Mtftp4RrqInput ( ); } + DEBUG ((DEBUG_NET, "%a: TFTP ERROR(%d) = %r\n", __FUNCTION__, __LINE__, Status)); + Status = EFI_ABORTED; goto ON_EXIT; } @@ -798,6 +812,8 @@ Mtftp4RrqInput ( } } + DEBUG ((DEBUG_NET, "%a: Completed=%d. Code=%r\n", __FUNCTION__, Completed, Status)); + if (EFI_ERROR (Status) || Completed) { Mtftp4CleanOperation (Instance, Status); } diff --git a/NetworkPkg/Mtftp4Dxe/Mtftp4Wrq.c b/NetworkPkg/Mtftp4Dxe/Mtftp4Wrq.c index 9ebefc74ec..0fe0658de6 100644 --- a/NetworkPkg/Mtftp4Dxe/Mtftp4Wrq.c +++ b/NetworkPkg/Mtftp4Dxe/Mtftp4Wrq.c @@ -465,6 +465,8 @@ Mtftp4WrqInput ( Status = UdpIoRecvDatagram (Instance->UnicastPort, Mtftp4WrqInput, Instance, 0); } + DEBUG ((DEBUG_NET, "%a: Completed=%d. Code=%r\n", __FUNCTION__, Completed, Status)); + // // Status may have been updated by UdpIoRecvDatagram // @@ -495,6 +497,8 @@ Mtftp4WrqStart ( { EFI_STATUS Status; + DEBUG ((DEBUG_NET, "%a: Entry\n", __FUNCTION__)); + // // The valid block number range are [0, 0xffff]. For example: // the client sends an WRQ request to the server, the server @@ -504,12 +508,14 @@ Mtftp4WrqStart ( Status = Mtftp4InitBlockRange (&Instance->Blocks, 0, 0xffff); if (EFI_ERROR (Status)) { + DEBUG ((DEBUG_NET, "%a: TFTP ERROR(%d) = %r\n", __FUNCTION__, __LINE__, Status)); return Status; } Status = Mtftp4SendRequest (Instance); if (EFI_ERROR (Status)) { + DEBUG ((DEBUG_NET, "%a: TFTP ERROR(%d) = %r\n", __FUNCTION__, __LINE__, Status)); return Status; } diff --git a/NetworkPkg/UefiPxeBcDxe/PxeBcBoot.c b/NetworkPkg/UefiPxeBcDxe/PxeBcBoot.c index 54aeb1d30e..1d92f48be3 100644 --- a/NetworkPkg/UefiPxeBcDxe/PxeBcBoot.c +++ b/NetworkPkg/UefiPxeBcDxe/PxeBcBoot.c @@ -1219,6 +1219,7 @@ PxeBcLoadBootFile ( // Begin to download the bootfile if everything is ready. // AsciiPrint ("\n Downloading NBP file...\n"); + DEBUG ((DEBUG_NET, "%a: Downloading NBP file...\n", __FUNCTION__)); if (PxeBcMode->UsingIpv6) { Status = PxeBcReadBootFileList ( Private, @@ -1244,6 +1245,8 @@ PxeBcLoadBootFile ( *BufferSize = (UINTN)CurrentSize; PxeBcUninstallCallback (Private, NewMakeCallback); + DEBUG ((DEBUG_NET, "%a: Complete, code = %r\n", __FUNCTION__, Status)); + if (Status == EFI_SUCCESS) { AsciiPrint ("\n NBP file downloaded successfully.\n"); return EFI_SUCCESS; diff --git a/NetworkPkg/UefiPxeBcDxe/PxeBcImpl.c b/NetworkPkg/UefiPxeBcDxe/PxeBcImpl.c index eb21c38727..e4e823e31a 100644 --- a/NetworkPkg/UefiPxeBcDxe/PxeBcImpl.c +++ b/NetworkPkg/UefiPxeBcDxe/PxeBcImpl.c @@ -2375,6 +2375,8 @@ EfiPxeLoadFile ( EFI_STATUS Status; EFI_STATUS MediaStatus; + DEBUG ((DEBUG_NET, "%a: Entry\n", __FUNCTION__)); + if ((This == NULL) || (BufferSize == NULL) || (FilePath == NULL) || !IsDevicePathEnd (FilePath)) { return EFI_INVALID_PARAMETER; } @@ -2383,6 +2385,7 @@ EfiPxeLoadFile ( // Only support BootPolicy // if (!BootPolicy) { + DEBUG ((DEBUG_NET, "%a: !BootPolicy\n", __FUNCTION__)); return EFI_UNSUPPORTED; } @@ -2398,6 +2401,7 @@ EfiPxeLoadFile ( MediaStatus = EFI_SUCCESS; NetLibDetectMediaWaitTimeout (Private->Controller, PXEBC_CHECK_MEDIA_WAITING_TIME, &MediaStatus); if (MediaStatus != EFI_SUCCESS) { + DEBUG ((DEBUG_NET, "%a: No Media\n", __FUNCTION__)); return EFI_NO_MEDIA; } @@ -2449,6 +2453,8 @@ EfiPxeLoadFile ( } } + DEBUG ((DEBUG_NET, "%a: Completed, Code = %r\n", __FUNCTION__, Status)); + return Status; }