Error: Timed out requesting agent port for client sessions. --tr:Failed to initialize agent.

[mriksman]

I have a Veeam Windows Agent Free 2.2.0.589 backing up to a Veeam B&R 9.5 Update 4. The support contract has expired. We are currently in the process of overhauling the entire system to use VUL and license each of our Agents. But for now, it is what it is.

This PC is on an industrial network, and is locked down. It hasn't had any configuration changes in over a year. Yet 2 days ago, the backups started failing. The error on the Veeam Agent is

Code: Select all

Error: Timed out requesting agent port for client sessions. --tr:Failed to initialize agent.

I tried a restart, but it didn't help.

The Job.Backup_Job_SA-SH-T34.Backup shows the following.

Code: Select all

[05.04.2023 08:32:33] <01> Error    Failed to call RPC function 'StartAgent'. InParams: '<InputArguments><logName value="Backup_Job_SA-SH-T34/Agent.Backup_Job_SA-SH-T34.Source.SA-SH-T34.log" /><skipSecureMessages value="False" /><fileCacheLimitPercent value="25" /><vddkLogLevel value="1" /><maxPendingBlocks value="10000" /><isLowPriorityProcess value="False" /><BackgroundMode value="False" /><isRepositoryAgent value="True" /><portRangeStart value="2500" /><portrangeEnd value="5000" /><mgmtKeySet value="AQAAAAAAAAAjAAAATWFuYWdlciB0byBBZ2VudCBjaGFubmVsIGVuY3J5cHRpb24BAAAAAQAAAAAAAABganW0h2fZAQIAAABKAAAAAAAAAAAAAAAAAAAAAAAAAAAAIAAAABAAAAA9F9Z3eC5Nq5AFU1lkxP8p82zcvcfwBfM0MYY3TjDsLnmdeC1vhPSNdHWcB15d/lcQAAAABRoqnw+KZNHzPs3DLolvlw==" /><ownerJob BackupConsole="SA-SH-T34" JobName="Backup Job SA-SH-T34" /></InputArguments>'. 
[05.04.2023 08:32:33] <01> Error    Timed  out requesting agent port for client sessions.
[05.04.2023 08:32:33] <01> Error    --tr:Failed to initialize agent ( specified agent path: [C:\Program Files\Veeam\Endpoint Backup\x64\VeeamAgent.exe], arguments: [ -g"2500-5000" -i"{742eba33-ab34-4ff1-b7f9-74aca989053b}" -l"flush,C:\ProgramData\Veeam\Endpoint\Backup__Job__SA_BSH_BT34/Agent.Backup__Job__SA_BSH_BT34.Source.SA_BSH_BT34.log" -f 25 --vddkLogLevel 1 --maxPendingBlocks 10000 -n -x"{397c1db5-7faf-490d-920d-18d56033d18e}" --mgmtConnKey "AQAAAAAAAAAjAAAATWFuYWdlciB0byBBZ2VudCBjaGFubmVsIGVuY3J5cHRpb24BAAAAAQAAAAAAAABganW0h2fZAQIAAABKAAAAAAAAAAAAAAAAAAAAAAAAAAAAIAAAABAAAAA9F9Z3eC5Nq5AFU1lkxP8p82zcvcfwBfM0MYY3TjDsLnmdeC1vhPSNdHWcB15d/lcQAAAABRoqnw+KZNHzPs3DLolvlw=="])
[05.04.2023 08:32:33] <01> Error    --tr:Failed to initialize agent instance {742eba33-ab34-4ff1-b7f9-74aca989053b}. (System.ApplicationException)
[05.04.2023 08:32:33] <01> Error       at VeeamProxyClient.RegenerateCLRException(exception* excBase)
[05.04.2023 08:32:33] <01> Error       at VeeamProxyClient.CCliProxyRpcInvoker.DoRpc(String cmdName, String inXml, String& outXml)
[05.04.2023 08:32:33] <01> Error       at Veeam.Backup.ProxyProvider.CProxyRpcInvoker.Call(String methodName, CProxyInvokeInputArg inputArgs, Boolean secureCall)
[05.04.2023 08:32:33] <01> Info     Disposing CBackupRepositoryClient [0x39a1422]
[05.04.2023 08:32:33] <01> Info     Disposing CBackupClient [0x6ab532]
[05.04.2023 08:32:33] <01> Info             [AP] Disposing client from thread 1
[05.04.2023 08:32:33] <01> Info     Disposing BaseAgentProtocol [0x3c05ec2]
[05.04.2023 08:32:33] <01> Info     Disposing CSocketAgentService [0x1c354d3], sessionId [c605]
[05.04.2023 08:32:33] <01> Info     [SocketAgentService] Closing connection to agent 'SA-FILE-SRV1', id c605
[05.04.2023 08:32:33] <01> Info     [ReconnectableSocket] Stop request was sent on [7a6bddcf-0e4c-4caa-ae00-a5d0007e063c].
[05.04.2023 08:32:33] <31> Info     [ReconnectableSocket][StopCondition] Stop confirmation was received on [7a6bddcf-0e4c-4caa-ae00-a5d0007e063c].
[05.04.2023 08:32:33] <31> Info     [ReconnectableSocket] Stop confirmation was sent on [7a6bddcf-0e4c-4caa-ae00-a5d0007e063c].
[05.04.2023 08:32:33] <31> Info     [ReconnectableSocket][StopCondition] Stop request was received on [7a6bddcf-0e4c-4caa-ae00-a5d0007e063c].
[05.04.2023 08:32:33] <01> Info     Disposing CBackupClient [0x3ddfb6e]
[05.04.2023 08:32:33] <01> Info             [AP] Disposing client from thread 1
[05.04.2023 08:32:33] <01> Info     Disposing BaseAgentProtocol [0x2cdd6e5]
[05.04.2023 08:32:33] <01> Info     Disposing CSocketAgentService [0x13c8e0f], sessionId [aadc]
[05.04.2023 08:32:33] <01> Info     [SocketAgentService] Closing connection to agent 'SA-FILE-SRV1', id aadc
[05.04.2023 08:32:33] <01> Info     [ReconnectableSocket] Stop request was sent on [730058d8-9206-4f1b-9155-4c5cf1b0b6c0].
[05.04.2023 08:32:33] <31> Info     [ReconnectableSocket][StopCondition] Stop confirmation was received on [730058d8-9206-4f1b-9155-4c5cf1b0b6c0].
[05.04.2023 08:32:33] <31> Info     [ReconnectableSocket] Stop confirmation was sent on [730058d8-9206-4f1b-9155-4c5cf1b0b6c0].
[05.04.2023 08:32:33] <31> Info     [ReconnectableSocket][StopCondition] Stop request was received on [730058d8-9206-4f1b-9155-4c5cf1b0b6c0].
[05.04.2023 08:32:33] <01> Info     Disposing CProxyAgent [0x320fe8f], agent id 09340ba6-c5f8-43c3-9a4b-609a2f10bd4d
[05.04.2023 08:32:33] <16> Info             [AP] (cde6) command: 'Invoke: Generic.AbortReconnects\n'
[05.04.2023 08:32:33] <30> Info           [AP] (cde6) output: <VCPCommandResult result="true" exception="" />
[05.04.2023 08:32:33] <30> Info           [AP] (cde6) output: <VCPCommandArgs />
[05.04.2023 08:32:33] <30> Info           [AP] (cde6) output: >
[05.04.2023 08:32:33] <16> Info     [RemoteAgentSystemSession] Keep-alive thread operation is canceled.
[05.04.2023 08:32:33] <01> Info     Disposing CBackupClient [0x28f30d]
[05.04.2023 08:32:33] <01> Info             [AP] Disposing client from thread 1
[05.04.2023 08:32:33] <01> Info     Disposing BaseAgentProtocol [0x1708b7a]
[05.04.2023 08:32:33] <01> Info     Disposing CSocketAgentService [0xf4e74f], sessionId [cde6]
[05.04.2023 08:32:33] <01> Info     [SocketAgentService] Closing connection to agent 'SA-FILE-SRV1', id cde6
[05.04.2023 08:32:35] <01> Info     On-demand scoped repository client was stoped.
[05.04.2023 08:32:35] <01> Error    AgentManagerService: Failed to start agent, Host 'SA-SH-T34'   at Veeam.Backup.Core.CWinAgentManager.StartAgent()
[05.04.2023 08:32:35] <01> Error       at Veeam.Backup.AgentProvider.CProxyAgent..ctor(IProxyAgentStarter agentStarter)
[05.04.2023 08:32:35] <01> Error       at Veeam.EndPoint.CEndPointBackupSource..ctor(CEndPointBackupTask task, CBackupTaskSession taskSess, CSnapshotContext snapshotContext, CDigestsContext digestsContext, CBackupCacheState backupCacheState)
[05.04.2023 08:32:35] <01> Error       at Veeam.EndPoint.CEndPointBackupJobPerformer.ExecuteTask(CBackupTaskContext backupTaskContext)
[05.04.2023 08:32:35] <01> Error    Failed to start agent on host SA-SH-T34   at Veeam.Backup.Common.CExceptionUtil.RegenTraceExc(Exception originalExc, String formatString, Object[] args)
[05.04.2023 08:32:35] <01> Error       at Veeam.Backup.ProxyProvider.CTransportService.StartAgent(String logName, IPAddress[] connectIPs, Boolean withLowerPriority, Boolean inBackgroundMode, Boolean is64Bit, Int32 portRangeStart, Int32 portRangeEnd, CSvcLockJobInfo ownerInfo, CSerializedKeySet mgmtKeySet, String privPasswordHash)
[05.04.2023 08:32:35] <01> Error       at Veeam.Backup.Core.CWinAgentManager.StartAgent()
[05.04.2023 08:32:35] <01> Error    Timed  out requesting agent port for client sessions.
[05.04.2023 08:32:35] <01> Error    --tr:Failed to initialize agent ( specified agent path: [C:\Program Files\Veeam\Endpoint Backup\x64\VeeamAgent.exe], arguments: [ -g"2500-5000" -i"{742eba33-ab34-4ff1-b7f9-74aca989053b}" -l"flush,C:\ProgramData\Veeam\Endpoint\Backup__Job__SA_BSH_BT34/Agent.Backup__Job__SA_BSH_BT34.Source.SA_BSH_BT34.log" -f 25 --vddkLogLevel 1 --maxPendingBlocks 10000 -n -x"{397c1db5-7faf-490d-920d-18d56033d18e}" --mgmtConnKey "AQAAAAAAAAAjAAAATWFuYWdlciB0byBBZ2VudCBjaGFubmVsIGVuY3J5cHRpb24BAAAAAQAAAAAAAABganW0h2fZAQIAAABKAAAAAAAAAAAAAAAAAAAAAAAAAAAAIAAAABAAAAA9F9Z3eC5Nq5AFU1lkxP8p82zcvcfwBfM0MYY3TjDsLnmdeC1vhPSNdHWcB15d/lcQAAAABRoqnw+KZNHzPs3DLolvlw=="])
[05.04.2023 08:32:35] <01> Error    --tr:Failed to initialize agent instance {742eba33-ab34-4ff1-b7f9-74aca989053b}.
[05.04.2023 08:32:35] <01> Error    Timed  out requesting agent port for client sessions.
[05.04.2023 08:32:35] <01> Error       at Veeam.Backup.ProxyProvider.CProxyRpcInvoker.Call(String methodName, CProxyInvokeInputArg inputArgs, Boolean secureCall)
[05.04.2023 08:32:35] <01> Error       at Veeam.Backup.ProxyProvider.CTransportService.StartAgent(String logName, IPAddress[] connectIPs, Boolean withLowerPriority, Boolean inBackgroundMode, Boolean is64Bit, Int32 portRangeStart, Int32 portRangeEnd, CSvcLockJobInfo ownerInfo, CSerializedKeySet mgmtKeySet, String privPasswordHash)
[05.04.2023 08:32:35] <01> Error    Timed  out requesting agent port for client sessions.
[05.04.2023 08:32:35] <01> Error    --tr:Failed to initialize agent ( specified agent path: [C:\Program Files\Veeam\Endpoint Backup\x64\VeeamAgent.exe], arguments: [ -g"2500-5000" -i"{742eba33-ab34-4ff1-b7f9-74aca989053b}" -l"flush,C:\ProgramData\Veeam\Endpoint\Backup__Job__SA_BSH_BT34/Agent.Backup__Job__SA_BSH_BT34.Source.SA_BSH_BT34.log" -f 25 --vddkLogLevel 1 --maxPendingBlocks 10000 -n -x"{397c1db5-7faf-490d-920d-18d56033d18e}" --mgmtConnKey "AQAAAAAAAAAjAAAATWFuYWdlciB0byBBZ2VudCBjaGFubmVsIGVuY3J5cHRpb24BAAAAAQAAAAAAAABganW0h2fZAQIAAABKAAAAAAAAAAAAAAAAAAAAAAAAAAAAIAAAABAAAAA9F9Z3eC5Nq5AFU1lkxP8p82zcvcfwBfM0MYY3TjDsLnmdeC1vhPSNdHWcB15d/lcQAAAABRoqnw+KZNHzPs3DLolvlw=="])
[05.04.2023 08:32:35] <01> Error    --tr:Failed to initialize agent instance {742eba33-ab34-4ff1-b7f9-74aca989053b}.   at VeeamProxyClient.RegenerateCLRException(exception* excBase)
[05.04.2023 08:32:35] <01> Error       at VeeamProxyClient.CCliProxyRpcInvoker.DoRpc(String cmdName, String inXml, String& outXml)
[05.04.2023 08:32:35] <01> Error       at Veeam.Backup.ProxyProvider.CProxyRpcInvoker.Call(String methodName, CProxyInvokeInputArg inputArgs, Boolean secureCall)
[05.04.2023 08:32:36] <01> Info     Retrieving space info for repository : Id [f7ac2fbf-6311-49b8-b177-1f5a26d5c4dd]
[05.04.2023 08:32:36] <01> Info     [Repository] Updating repository space info, id: 'f7ac2fbf-6311-49b8-b177-1f5a26d5c4dd', total space: 11453402710016, free: 5159080296448
[05.04.2023 08:32:36] <01> Info     Checking free space
[05.04.2023 08:32:36] <01> Info     Deleting empty storages from backup 'e482324b-72a3-4de7-bd46-49a21243eca4'
[05.04.2023 08:32:37] <01> Info     [StorageLock] Locking 1 storage(s) as write-only
[05.04.2023 08:32:38] <01> Warning  Error occured by deleting storage 'Backup_Job_SA-SH-T34\Backup Job SA-SH-T342023-04-05T082719.vib'
[05.04.2023 08:32:38] <01> Warning  Exception has been thrown by the target of an invocation. (System.Reflection.TargetInvocationException)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Core.CForeignInvokerClient.InvokeInternal(CForeignInvokerParams invokerParams)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Core.CForeignInvokerClient.InvokeWithRetry(CForeignInvokerParams invokerParams)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Core.CForeignInvokerClient.Invoke(CForeignInvokerParams invokerParams)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Core.CForeignBackupService.InvokeWithSessionConnection(CForeignInvokerSpec spec)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Core.CForeignLockService.LockGroups(Guid leaseId, CLockGroup[] lockGroups)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Core.CDisposableLockGroup..ctor(Guid leaseId, CLockGroup[] lockGroup, ILockService lockService)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Core.Jobs.CForeignLockResolver.ResolveAndLockGroups(CDisposableLock lockDisposables, Guid leaseId, CLockGroup[] lockGroup)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Core.CStoragesAlgLocker.ResolveAndLockGroups(Guid sessionId, CLockGroup[] lockGroups)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Core.CStoragesAlgLocker.Lock(Guid sessionId, IEnumerable`1 storages, LockTypes lockType)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Core.CStoragesAlgLocker.LockForWrite(Guid sessionId, CStorage[] storages)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Core.CStorageEx.DeleteWithLockCheckSafe(CStorage storage, CRepositoryAccessor repositoryAccessor, IBackupClientHolder client, Boolean logExceptionAsWaring)
[05.04.2023 08:32:38] <01> Warning  Item [Backup Job SA-SH-T342023-04-05T082719.vib] is locked by running session Backup Job SA-SH-T34 [Agent Backup] (Veeam.Backup.Common.CustomStackException)
[05.04.2023 08:32:38] <01> Warning  Veeam.Backup.Interaction.Management.LockedStorageException:
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.ServiceLib.CStorageLockLegacyImpl.CheckForReadyLocks(CLockRequest[] lockRequests)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Service.CStgLockManager.LockGroups(CLockGroup[] lockGroups, Guid leaseId)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Service.CLockService.LockGroups(Guid leaseId, CLockGroup[] lockGroups)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Service.CForeignInvokerSpecSl.Executor.Execute()
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Service.CForeignInvokerSpecExecuter.ExecuteSl(CForeignInvokerSlSpec spec, CInputXmlData response)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Service.CForeignInvokerSpecExecuter.Excecute(CForeignInvokerSpec spec, EForeignInvokerScope scope, EndPoint remoteEndPoint, String agentThumbprint)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Service.CForeignInvokerSpecExecuter.Execute(EndPoint remoteEndPoint, WindowsIdentity identity, CDbAccountInfo accoutnInfo, String agentThumbprint, CSpecDeserializationContext context, CRemoteExceptionSerializer exceptionSerializer)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.ServiceLib.CForeignInvokerAsyncExecuter.ThreadProc(Object parameter)
[05.04.2023 08:32:38] <01> Warning  --- End of stack trace from previous location where exception was thrown ---
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.ServiceLib.CForeignInvokerAsyncExecuter.TryGetResult(String& result)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.ServiceLib.CForeignInvokerAsyncExecuter.Wait(String execResponse, Boolean& isCompleted)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Service.CForeignInvokerServer.DoExecute(CSpecDeserializationContext context, ConnectionState state)
[05.04.2023 08:32:38] <01> Warning     at Veeam.Backup.Service.CForeignInvokerServer.ExecThreadProc(Object parameters)

Is anyone able to diagnose this?

Thanks.

[Mildur]

Hi Michael

This forum is run by product management. We don't have the necessary training or tools to diagnose such issues.
I can only see from the logs that the agent couldn't be initialized. Most likely there is more information in other logs.
But please don't post logs to this forum. It's forbidden by our forum rules.

You can open a support case for the community edition. But even with a paid contract, probably you must upgrade to a supported Veeam version first. Which is not possible without an active maintenance contract.

Best,
Fabian

[mriksman]

Thanks for letting me know.