Description

This article describes the issue of the set security alg ftp traceoptions flag all command not providing the information that is related to the FTP ALG.

Symptoms

  • Trying to troubleshoot issues with the FTP ALG. 
  • Committed the set security alg ftp traceoptions flag all configuration.
  • The expected information to determine why the pinhole for FTP is not processing properly is not generated.

Solution


Prior to Junos 11.4, to obtain useful traceoptions data for FTP, you would have to apply the following commands:

set security alg ftp traceoptions flag all
set security traceoptions file ftp-test size 1m world-readable
set security traceoptions flag all

The issue with set security traceoptions flag all is that it may be obtaining too much data and can cause high CPU usage.

With Junos 11.4 or later, there were optimizations to the ALG structure.  The recommended traceoptions to run is the following:
set security alg ftp traceoptions flag all
set security alg traceoptions file ftp-test size 1m world-readable
set security alg traceoptions level verbose
JUnos 11.4 is also recommended for FTP ALG issues.

Here is a sample output of the above traceoptions:

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE ftp_need_nat:1332

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE ftp_need_dst_nat:1313

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: No NAT is needed

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE ftp_do_rm:1776

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE ftp_create_asl_group:1492

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: rm_Create_Group succeeded

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE ftp_create_asl_resource:1545

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE ftp_get_state:1069

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: jsf_asl_create_resource succeed

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE ftp_set_asl_pinhole:1606

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE ftp_get_state:1069

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: FTP create pinhole, orig two sides: 172.16.100.3/0 ~ 172.22.152.251/59362

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: FTP create pinhole, xlated two sides: 172.22.135.251/0 ~ 172.22.152.251/59362

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE ftp_open_asl_pinhole:1720

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: asl open pinhole succeeded.

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE ftp_free:248

Mar 27 13:36:59 13:36:59.100785:CID-0:RT:[ALG_FTP] INFO: End FTP processing with ok, return PKT_FORWARD.

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_ftp_line_brk:2399

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: FTP line-breaker found, total length = 6, residual length = 0

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_ftp_tcp_pkt_handler:2300

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE is_pkt_parse_needed:2033

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: FTP Control Message: MLSD

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_ftp_alg_data_handler:3006

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_alg_ftp_gate_hit_handler:2779

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_alg_ftp_is_ftps_control_session:2546

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: jsf_asl_process_gate_hit OK.

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_ftp_alg_data_handler:3006

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_alg_ftp_sess_interest_handler:2498

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_ftp_alg_data_handler:3006

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_alg_ftp_sess_create_handler:2561

Mar 27 13:36:59 13:36:59.107966:CID-0:RT:[ALG_FTP] INFO: Data session created sid=8589953762.

Mar 27 13:36:59 13:36:59.113509:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_ftp_line_brk:2399

Mar 27 13:36:59 13:36:59.113509:CID-0:RT:[ALG_FTP] INFO: FTP line-breaker found, total length = 25, residual length = 0

Mar 27 13:36:59 13:36:59.113509:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_ftp_tcp_pkt_handler:2300

Mar 27 13:36:59 13:36:59.113509:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE is_pkt_parse_needed:2033

Mar 27 13:36:59 13:36:59.113509:CID-0:RT:[ALG_FTP] INFO: FTP Control Message: 150

Mar 27 13:36:59 13:36:59.113509:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_ftp_line_brk:2399

Mar 27 13:36:59 13:36:59.113509:CID-0:RT:[ALG_FTP] INFO: FTP line-breaker found, total length = 17, residual length = 0

Mar 27 13:36:59 13:36:59.113509:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_ftp_tcp_pkt_handler:2300

Mar 27 13:36:59 13:36:59.113509:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE is_pkt_parse_needed:2033

Mar 27 13:36:59 13:36:59.113509:CID-0:RT:[ALG_FTP] INFO: FTP Control Message: 226

Mar 27 13:37:00 13:37:00.159732:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_ftp_alg_data_handler:3006

Mar 27 13:37:00 13:37:00.159732:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_alg_ftp_sess_close_check_handler:2595

Mar 27 13:37:00 13:37:00.159732:CID-0:RT:[ALG_FTP] INFO: Data session close check, OK.

Mar 27 13:37:00 13:37:00.159732:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_ftp_alg_data_handler:3006

Mar 27 13:37:02 13:37:02.157681:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_ftp_alg_data_handler:3006

Mar 27 13:37:02 13:37:02.157681:CID-0:RT:[ALG_FTP] INFO: ALG FTP TRACE jsf_alg_ftp_sess_destroy_handler:2622

Mar 27 13:37:02 13:37:02.157681:CID-0:RT:[ALG_FTP] INFO: Data Session destroy for sid 8589953762.