Exception of type 'Veeam.Backup.AgentProvider.AgentClosedException' was throw

[jhide]

Case ID - Case #04238020

Hi,

running Backup & replication v10.0.0.4461 P1 with a HP MSL2024. Since I upgraded to v10 I sometimes get the
18/06/2020 13:39:36 :: Incremental backup: Exception of type 'Veeam.Backup.AgentProvider.AgentClosedException' was thrown.

Just restarting the job manually then resolved the issue. However, since 1 week, I can't restart the job manually neither. It continues to fail with the same error.

In the log files I find no clues on what is going wrong. Anyone any idea?

Code: Select all

18.06.2020 13:39:32.297] < 12096> cli| Thread finished. Role: 'Client processor thread (192.168.2.77:65175)'.
[18.06.2020 13:39:32.297] <   216> srv| 
[18.06.2020 13:39:32.297] <   216> srv| Waiting for the next server command.
[18.06.2020 13:39:32.297] <   216> srv| _______________________________________________________________________________
[18.06.2020 13:39:32.297] < 11992> cli| Next client command: [setTrafficCompressionLevel].
[18.06.2020 13:39:32.297] < 11992> cli|       :>  0
[18.06.2020 13:39:32.297] < 11992> stg| Specified traffic compression level: 'No compression', is forced: 'true'.
[18.06.2020 13:39:32.297] < 11992> cli| 
[18.06.2020 13:39:32.297] < 11992> cli| _______________________________________________________________________________
[18.06.2020 13:39:32.297] < 11992> cli| Waiting for the next command.
[18.06.2020 13:39:32.313] < 12444> cli| Thread started. Thread id: 12444, parent id: 12708, role: (async) reconn. receiver {7ab0eb3c-0b02-4fd9-a5d9-d8a9d694d7e4}
[18.06.2020 13:39:32.313] < 12444> alg| Receiver stage: running recv cycle.
[18.06.2020 13:39:32.313] < 12708> net| Multiplexed AUX sender channel is established.
[18.06.2020 13:39:32.313] < 12708> cli| Thread finished. Role: 'Client processor thread (192.168.2.77:65176)'.
[18.06.2020 13:39:32.313] <  3824> cli| Thread started. Thread id: 3824, parent id: 12708, role: (async) reconn. sender {7ab0eb3c-0b02-4fd9-a5d9-d8a9d694d7e4}
[18.06.2020 13:39:32.313] <  3824> alg| Sender stage: running send cycle. Resend list: [0].
[18.06.2020 13:39:32.328] < 10540> cli| Thread started. Thread id: 10540, parent id: 12364, role: (async) reconn. receiver {c47fdac0-052d-4a27-9899-6a55a7087732}
[18.06.2020 13:39:32.328] < 10540> alg| Receiver stage: running recv cycle.
[18.06.2020 13:39:32.328] < 12364> net| Multiplexed AUX receiver channel is established.
[18.06.2020 13:39:32.328] < 12364> cli| Thread finished. Role: 'Client processor thread (192.168.2.77:65177)'.
[18.06.2020 13:39:32.328] <  1964> cli| Thread started. Thread id: 1964, parent id: 12364, role: (async) reconn. sender {c47fdac0-052d-4a27-9899-6a55a7087732}
[18.06.2020 13:39:32.328] <  1964> alg| Sender stage: running send cycle. Resend list: [0].
[18.06.2020 13:39:32.328] < 11804> cli| Thread started. Thread id: 11804, parent id: 12708, role: (async) AUX channel sender
[18.06.2020 13:39:32.344] < 13104> cli| Thread started. Thread id: 13104, parent id: 12364, role: (async) AUX channel receiver
[18.06.2020 13:39:36.484] < 13104> net| Acknowledging synchronization request {6a5ddc2e-c8c7-45c6-8c91-7c2c08c2c8c9}
[18.06.2020 13:39:36.484] <   216> srv| retrieved command: 2 (Quit(2))
[18.06.2020 13:39:36.484] <   216> srv| Received 'quit' signal. Server is shutting down.
[18.06.2020 13:39:36.484] <   216> srv| Closing server socket.
[18.06.2020 13:39:36.484] <   216> srv| Socket is closed.
[18.06.2020 13:39:36.484] <   216> net| AUX channel shutdown triggered.
[18.06.2020 13:39:36.484] < 11804> net| AUX data sender: sending shutdown marker.
[18.06.2020 13:39:36.484] < 10540> alg| Reconnectable protocol stop request was received on {c47fdac0-052d-4a27-9899-6a55a7087732}.
[18.06.2020 13:39:36.484] <  3824> alg| Reconnectable stop request was sent on {7ab0eb3c-0b02-4fd9-a5d9-d8a9d694d7e4}.
[18.06.2020 13:39:36.484] < 13104> net| AUX data receiver: shutdown marker received. Waiting for shutdown.
[18.06.2020 13:39:36.484] <  1964> alg| Reconnectable stop confirmation was sent on {c47fdac0-052d-4a27-9899-6a55a7087732}.
[18.06.2020 13:39:36.484] < 12444> alg| Reconnectable protocol stop request confirmation was received on {7ab0eb3c-0b02-4fd9-a5d9-d8a9d694d7e4}.
[18.06.2020 13:39:36.484] <  1964> alg| Reconnectable stop request was sent on {c47fdac0-052d-4a27-9899-6a55a7087732}.
[18.06.2020 13:39:36.484] < 12444> alg| Reconnectable protocol stop request was received on {7ab0eb3c-0b02-4fd9-a5d9-d8a9d694d7e4}.
[18.06.2020 13:39:36.484] < 12444> alg| Receiver: finishing on {7ab0eb3c-0b02-4fd9-a5d9-d8a9d694d7e4}.
[18.06.2020 13:39:36.484] < 12444> cli| Thread finished. Role: '(async) reconn. receiver {7ab0eb3c-0b02-4fd9-a5d9-d8a9d694d7e4}'.
[18.06.2020 13:39:36.484] < 10540> alg| Reconnectable protocol stop request confirmation was received on {c47fdac0-052d-4a27-9899-6a55a7087732}.
[18.06.2020 13:39:36.484] < 10540> alg| Receiver: finishing on {c47fdac0-052d-4a27-9899-6a55a7087732}.
[18.06.2020 13:39:36.484] < 10540> cli| Thread finished. Role: '(async) reconn. receiver {c47fdac0-052d-4a27-9899-6a55a7087732}'.
[18.06.2020 13:39:36.484] <  3824> alg| Reconnectable stop confirmation was sent on {7ab0eb3c-0b02-4fd9-a5d9-d8a9d694d7e4}.
[18.06.2020 13:39:36.484] <  3824> alg| Sender stage is finishing.
[18.06.2020 13:39:36.484] <  3824> cli| Closing socket device.
[18.06.2020 13:39:36.484] <  3824> cli| Thread finished. Role: '(async) reconn. sender {7ab0eb3c-0b02-4fd9-a5d9-d8a9d694d7e4}'.
[18.06.2020 13:39:36.484] <  1964> alg| Sender stage is finishing.
[18.06.2020 13:39:36.484] <  1964> cli| Closing socket device.
[18.06.2020 13:39:36.484] <  1964> cli| Thread finished. Role: '(async) reconn. sender {c47fdac0-052d-4a27-9899-6a55a7087732}'.
[18.06.2020 13:39:36.500] < 11804> alg| Traffic history max size: [8].
[18.06.2020 13:39:36.500] < 11804> cli| Thread finished. Role: '(async) AUX channel sender'.
[18.06.2020 13:39:36.500] < 13104> alg| Traffic history max size: [2].
[18.06.2020 13:39:36.500] < 13104> cli| Thread finished. Role: '(async) AUX channel receiver'.
[18.06.2020 13:39:36.500] <   216> cli| Thread finished. Role: 'Srv thread'.
[18.06.2020 13:39:36.500] < 12676> srv|   Clearing finished srv. sessions.
[18.06.2020 13:39:36.500] < 12676> srv|     Srv. session [{4b08cc9f-4b0b-41af-b0d0-90a5c39b2cf9}] is finished.
[18.06.2020 13:39:47.375] <  7956> alg| Reconnectable protocol stop request was received on {c0c8a5b7-a2fa-4ed3-9cc3-69325b4174d8}.
[18.06.2020 13:39:47.375] <  8160> alg| Reconnectable stop confirmation was sent on {c0c8a5b7-a2fa-4ed3-9cc3-69325b4174d8}.
[18.06.2020 13:39:47.375] <  8160> alg| Reconnectable stop request was sent on {c0c8a5b7-a2fa-4ed3-9cc3-69325b4174d8}.
[18.06.2020 13:39:47.375] <  7956> alg| Reconnectable protocol stop request confirmation was received on {c0c8a5b7-a2fa-4ed3-9cc3-69325b4174d8}.
[18.06.2020 13:39:47.375] <  7956> alg| Receiver: finishing on {c0c8a5b7-a2fa-4ed3-9cc3-69325b4174d8}.
[18.06.2020 13:39:47.375] <  7956> cli| Thread finished. Role: '(async) reconn. receiver {c0c8a5b7-a2fa-4ed3-9cc3-69325b4174d8}'.
[18.06.2020 13:39:47.375] <  8160> alg| Sender stage is finishing.
[18.06.2020 13:39:47.375] <  8160> cli| Closing socket device.
[18.06.2020 13:39:47.375] <  8160> cli| Thread finished. Role: '(async) reconn. sender {c0c8a5b7-a2fa-4ed3-9cc3-69325b4174d8}'.
[18.06.2020 13:39:47.375] < 11992> cli| WARN|Input TCP stream was closed
[18.06.2020 13:39:47.375] < 11992> cli| Removing stdin/stdout redirector: '1648543044352'.
[18.06.2020 13:39:47.375] < 11992> alg| Traffic history max size: [3].
[18.06.2020 13:39:47.375] < 11992> cli| Thread finished. Role: '(async) client session (192.168.2.77:65169)'.
[18.06.2020 13:39:47.375] <  4836> cli| -------------------------------------------------------------------------------
[18.06.2020 13:39:47.375] <  4836> cli| Generic.AbortReconnects
[18.06.2020 13:39:47.375] <  4836> cli| - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
[18.06.2020 13:39:47.375] <  4836> cli| All reconnects will be disabled permanently.
[18.06.2020 13:39:47.375] <  4836> cli| -------------------------------------------------------------------------------
[18.06.2020 13:39:47.438] <  1728> cli| Next client command: [shutdown].
[18.06.2020 13:39:47.438] <  1728> cli| Processing shutdown command.
[18.06.2020 13:39:47.438] <  1728> net| Connection closed...
[18.06.2020 13:39:47.438] <  1728> cli| Thread finished. Role: 'Client processor thread (127.0.0.1:65167)'.
[18.06.2020 13:39:47.438] <  7776> net| Terminating by stop event in CTcpThread::WaitOrStop.
[18.06.2020 13:39:47.438] <  7776> net| Stopping client sessions.
[18.06.2020 13:39:47.438] <  4836> net| Terminating by stop event in CTcpThread::WaitOrStop.
[

[Dima P.]

Hello jhide,

Please keep working with our support team and let us know how investigation goes. Cheers!

[edsribeiro]

******************** Veeam Support - Case # 04538446 **************************************
Hello everyone

I have a Windows 2019 / SMB server that is my repository containing my .vbk backups etc. and my tape drive is connected to it.
When I start backup to tape after an hour I get the following message: "
Full backup: Exception of type 'Veeam.Backup.AgentProvider.AgentClosedException' was thrown. "

Analyzing the logs I noticed that the job stays with this message for a long time until it fails.

Code: Select all

[10.12.2020 08:26:55] <  6208> srv| Waiting for the next server command.
[10.12.2020 08:26:55] <  6208> srv| _______________________________________________________________________________
[10.12.2020 08:31:33] <  6064> cli| Number of sessions: 4. Interval: 277 sec. 
[10.12.2020 08:36:33] <  6064> cli| Number of sessions: 4. Interval: 577 sec. 
[10.12.2020 08:41:33] <  6064> cli| Number of sessions: 4. Interval: 877 sec. 
[10.12.2020 08:46:33] <  6064> cli| Number of sessions: 4. Interval: 1177 sec. 
[10.12.2020 08:51:33] <  6064> cli| Number of sessions: 4. Interval: 1477 sec. 
[10.12.2020 08:56:33] <  6064> cli| Number of sessions: 4. Interval: 1777 sec. 
[10.12.2020 09:01:33] <  6064> cli| Number of sessions: 4. Interval: 2077 sec. 
[10.12.2020 09:06:33] <  6064> cli| Number of sessions: 4. Interval: 2377 sec. 
[10.12.2020 09:11:33] <  6064> cli| Number of sessions: 4. Interval: 2677 sec. 
[10.12.2020 09:16:33] <  6064> cli| Number of sessions: 4. Interval: 2977 sec. 
[10.12.2020 09:21:33] <  6064> cli| Number of sessions: 4. Interval: 3277 sec. 
[10.12.2020 09:26:33] <  7312> srv|   There was no finalized server sessions during the last 60 minutes.
[10.12.2020 09:26:33] <  6064> cli| Number of sessions: 4. Interval: 3577 sec. 
[10.12.2020 09:31:33] <  6064> cli| Number of sessions: 4. Interval: 3877 sec. 
[10.12.2020 09:36:33] <  6064> cli| Number of sessions: 4. Interval: 4177 sec. 
[10.12.2020 09:41:33] <  6064> cli| Number of sessions: 4. Interval: 4477 sec. 
[10.12.2020 09:46:33] <  6064> cli| Number of sessions: 4. Interval: 4777 sec. 
[10.12.2020 09:51:33] <  6064> cli| Number of sessions: 4. Interval: 5077 sec. 
[10.12.2020 09:56:33] <  6064> cli| Number of sessions: 4. Interval: 5377 sec. 
[10.12.2020 10:01:33] <  6064> cli| Number of sessions: 4. Interval: 5677 sec. 
[10.12.2020 10:06:33] <  6064> cli| Number of sessions: 4. Interval: 5977 sec. 
[10.12.2020 10:11:33] <  6064> cli| Number of sessions: 4. Interval: 6277 sec. 
[10.12.2020 10:11:55] <  7004> net|   Accepted incoming vRPC connection from 'My VEEAM SERVER IP''.
[10.12.2020 10:11:55] <  9144> cli| Thread started. Thread id: 9144, parent id: 7004, role: Client processor thread 

Does anyone have any idea what may be happening?

I appreciate a possible help

[Natalia Lupacheva]

Hi @edsribeiro,

Thank you for sharing your case ID.
Moved your post to the existing thread with the same exceptions to keep similar issues together.
Please keep working with support, it seems the logs analysis is required here.

Thanks!

[mkretzer]

Oh man, having this issue as well - since all our backups are corrupted because of the hotadd proxy mount bug we have to do active fulls via NBD - and after 12 hours or so the backups like to fail the AgentClosedException... So all our backups are slightly corrupt, we can't usw hotadd and NBD hangs at ~90 % of the backups so we can't get new backups... This week sucks...
Maybe the only way out are linux proxies?!

Case 04768332

[Dima P.]

mkretzer,

Just to clarify, the similar error is displayed within VM backup job or during the backup to tape? We will check the case details with QA team, thanks for sharing!

[mkretzer]

Hi,

sorry for the late answer.
Its only happening in backup jobs, never when backing up to tape or with copy jobs.

Support is really quiet for a SEV1/2 case - i have not heard one word from them!

Markus

[Dima P.]

Thanks for the update Markus! I've support management to review the investigation process.

[Murshid]

Having the same issue when taking backup to Tape

My software version are all latest

Does anyone found a solution or cause