FTD Deployment stalls on LSP file copy

catkins · ‎03-06-2024

We have several deployments failing when there is a new LSP update on the FMC that gets pushed to the FTDs. It seems like the file copy jus stalls out anywhere between 10-90%. From the /ngfw/var/log/messages i see the following repeating until it times out

[52861] sftunneld:stream_file [INFO] ELASTIC_FSTREAM status: curr_read=53645312, curr_write=53645312, total_bytes=60528640, stream_id_src=0, stream_id_dest=51744, seq_id_src=7484, seq_id_dest=7484, state =Processing, started:2024 03 06 19:13:11 UTC, expires:2024 03 06 19:49:47 UTC
[52861] sftunneld:stream_file [INFO] ELASTIC_FSTREAM status:: File copy 88 % completed, 53645312 bytes of file copied out of 60528640
[52861] sftunneld:control_services [INFO] FSTREAM_STATUS: Sending back task status 'Processing'
[52861] sftunneld:stream_file [INFO] task_id=51744
[52861] sftunneld:stream_file [INFO] peer=XXXXXX
[52861] sftunneld:stream_file [INFO] ELASTIC_FSTREAM status: curr_read=53645312, curr_write=53645312, total_bytes=60528640, stream_id_src=0, stream_id_dest=51744, seq_id_src=7484, seq_id_dest=7484, state =Processing, started:2024 03 06 19:13:11 UTC, expires:2024 03 06 19:49:47 UTC
[52861] sftunneld:stream_file [INFO] ELASTIC_FSTREAM status:: File copy 88 % completed, 53645312 bytes of file copied out of 60528640
[52861] sftunneld:control_services [INFO] FSTREAM_STATUS: Sending back task status 'Processing'
[52861] sftunneld:stream_file [INFO] task_id=51744
[52861] sftunneld:stream_file [INFO] peer=XXXXXX
[52861] sftunneld:stream_file [INFO] ELASTIC_FSTREAM status: curr_read=53645312, curr_write=53645312, total_bytes=60528640, stream_id_src=0, stream_id_dest=51744, seq_id_src=7484, seq_id_dest=7484, state =Processing, started:2024 03 06 19:13:11 UTC, expires:2024 03 06 19:49:47 UTC
[52861] sftunneld:stream_file [INFO] ELASTIC_FSTREAM status:: File copy 88 % completed, 53645312 bytes of file copied out of 60528640
[52861] sftunneld:control_services [INFO] FSTREAM_STATUS: Sending back task status 'Processing'
[52861] sftunneld:stream_file [INFO] task_id=51744
[52861] sftunneld:stream_file [INFO] peer=XXXXXX
[52861] sftunneld:stream_file [INFO] ELASTIC_FSTREAM status: curr_read=53645312, curr_write=53645312, total_bytes=60528640, stream_id_src=0, stream_id_dest=51744, seq_id_src=7484, seq_id_dest=7484, state =Processing, started:2024 03 06 19:13:11 UTC, expires:2024 03 06 19:49:47 UTC
[52861] sftunneld:stream_file [INFO] ELASTIC_FSTREAM status:: File copy 88 % completed, 53645312 bytes of file copied out of 60528640
[52861] sftunneld:control_services [INFO] FSTREAM_STATUS: Sending back task status 'Processing'

In the pigtail output on the device, we see the same message repeated as well

NGFW: 03-05 18:36:35 ccm[32798] FileStreamerTh: DEBUG com.cisco.sftunnel.file.FileStreamer- File status: Processing
NGFW: 03-05 18:36:35 ccm[32798] FileStreamerTh: DEBUG com.cisco.sftunnel.file.FileStreamer- file /var/sf/lsp/active-lsp/lsp-rel-20240228-1902.tar.xz.REL.tar is being transferred from xxxxx to xxxxxx
NGFW: 03-05 18:36:35 ccm[32798] FileStreamerTh: DEBUG com.cisco.sftunnel.file.FileStreamer- calling status handlers...
NGFW: 03-05 18:36:35 ccm[32798] FileStreamerTh: DEBUG com.cisco.ccm.RequiredPackageDownloader- handling file status for /var/cisco/deploy/pkg/var/sf/lsp/active-lsp/lsp-rel-20240228-1902.tar.xz.REL.tar(task status = 2)
NGFW: 03-05 18:36:36 ccm[32798] FileStreamerTh: DEBUG com.cisco.sftunnel.file.FileStreamer- File status: Processing
NGFW: 03-05 18:36:36 ccm[32798] FileStreamerTh: DEBUG com.cisco.sftunnel.file.FileStreamer- file /var/sf/lsp/active-lsp/lsp-rel-20240228-1902.tar.xz.REL.tar is being transferred from xxxxx to xxxxxx
NGFW: 03-05 18:36:36 ccm[32798] FileStreamerTh: DEBUG com.cisco.sftunnel.file.FileStreamer- calling status handlers...
NGFW: 03-05 18:36:36 ccm[32798] FileStreamerTh: DEBUG com.cisco.ccm.RequiredPackageDownloader- handling file status for /var/cisco/deploy/pkg/var/sf/lsp/active-lsp/lsp-rel-20240228-1902.tar.xz.REL.tar(task status = 2)
NGFW: 03-05 18:36:37 ccm[32798] FileStreamerTh: DEBUG com.cisco.sftunnel.file.FileStreamer- File status: Processing
NGFW: 03-05 18:36:37 ccm[32798] FileStreamerTh: DEBUG com.cisco.sftunnel.file.FileStreamer- file /var/sf/lsp/active-lsp/lsp-rel-20240228-1902.tar.xz.REL.tar is being transferred from xxxxx to xxxxxx