Troubleshooting policy extensions
If your extension function is not behaving as expected, you can use extension tracing functionality to verify the behavior of your extension function. You can also add logging to your extension function by using the custom logging functionality, where you can define the log level to be captured on the Citrix ADC appliance.
This topic provides information on:
- Extension tracing
- Custom logging
Extension tracing
To show what your extension function is doing, extension tracing functionality logs the execution of the function to the Citrix ADC system log ( /var/log/ns.log ). The trace logging uses the DEBUG log level, which normally is not enabled. Therefore, you have to enable ALL log levels. Then you can enable tracing by setting the -trace option of the set ns extension command. The available settings are:
- off turn off tracing (equivalent to unset ns extension -trace).
- calls trace function calls with arguments and function returns with the first return value.
- lines trace the above plus line numbers for executed lines.
- all trace the above plus local variables changed by executed lines.
Example:
set audit syslogParams -loglevel ALL
set ns extension combine_headers -trace all
<!--NeedCopy-->
Each trace message has the format
log-header : default NSEXTENSION Message message-number 0 : "TRACE function-name CALL call-number: event"
Where,
- log-header supplies timestamps, the Citrix ADC IP address, and the Packet Engine ID.
- message-number is a sequential number identifying the log message.
- function-name is the extension function name.
- call-number is a sequential number for each extension function call. It can be used to group all the trace messages for an extension function call.
- event is one of the following:
- CALL function-name ; parameter-values indicates that the function has been called with the specified parameters.
- RETURN FROM function-name ; return = value indicates that a function has returned the specified (first) value. (Additional return values are not reported.)
- LINE line-number ; variable-values indicates that a line has been executed and lists any variables with changed values.
Where,
- value or values is
- a number, with or without a decimal point,
- a string, enclosed in double quotes and with escaped characters as described earlier,
- a boolean true or false,
- nil,
- a table constructor, of the format {[key1]=value1,[key2]=value2, …}.
- parameter-values is parameter1 = value1 ; parameter2 = value2 , …
- variable-values is variable1 = value1 ; variable2 = value2 , …
An example of abbreviated log messages:
>shell tail -f /var/log/ns.log | grep TRACE | more
... NSEXTENSION Message 3035 0 : "TRACE combine_headers CALL 30 : CALL COMBINE_HEADERS; self = "User-Agent: curl/7.24.0 (amd64-portbld-freebsd8.4) libcurl/7.24.0 OpenSSL/0.9.8y zlib/1.2.3\r\nHost: 10.217.24.7\r\nAccept: */*\r\nH2: h2val1\r\nH1: abcd\r\nH2: h2val2\r\nH2: h2val3\r\n\r\n""
... NSEXTENSION Message 3036 0 : "TRACE combine_headers CALL 30 : LINE 4; headers = {}"
... NSEXTENSION Message 3037 0 : "TRACE combine_headers CALL 30 : LINE 5; combined_headers = {}"
... NSEXTENSION Message 3038 0 : "TRACE combine_headers CALL 30 : CALL gmatch"
... NSEXTENSION Message 3039 0 : "TRACE combine_headers CALL 30 : RETURN FROM gmatch; return = function 0x2bee5a80"
... NSEXTENSION Message 3040 0 : "TRACE combine_headers CALL 30 : CALL for iterator"
... NSEXTENSION Message 3041 0 : "TRACE combine_headers CALL 30 : RETURN FROM for iterator; return = " curl/7.24.0 (amd64-portbld-freebsd8.4) libcurl/7.24.0 OpenSSL/0.9.8y zlib/1.2.3""
... NSEXTENSION Message 3042 0 : "TRACE combine_headers CALL 30 : LINE 9; name = "User-Agent"; value = " curl/7.24.0 (amd64-portbld-freebsd8.4) libcurl/7.24.0 OpenSSL/0.9.8y zlib/1.2.3""
... NSEXTENSION Message 3043 0 : "TRACE combine_headers CALL 30 : LINE 10"
... NSEXTENSION Message 3044 0 : "TRACE combine_headers CALL 30 : LINE 14; headers = {["User-Agent"]={[1]="User-Agent: curl/7.24.0 (amd64-portbld-freebsd8.4) libcurl/7.24.0 OpenSSL/0.9.8y zlib/1.2.3"}}"
. . .
... NSEXTENSION Message 3117 0 : "TRACE combine_headers CALL 30 : CALL for iterator"
... NSEXTENSION Message 3118 0 : "TRACE combine_headers CALL 30 : RETURN FROM for iterator; return = nil"
... NSEXTENSION Message 3119 0 : "TRACE combine_headers CALL 30 : LINE 19"
... NSEXTENSION Message 3120 0 : "TRACE combine_headers CALL 30 : CALL concat"
... NSEXTENSION Message 3121 0 : "TRACE combine_headers CALL 30 : RETURN FROM concat; return = "User-Agent: curl/7.24.0 (amd64-portbld-freebsd8.4) libcurl/7.24.0 OpenSSL/0.9.8y zlib/1.2.3\r\nH1: abcd\r\nAccept: */*\r\nHost: 10.217.24.7\r\nH2: h2val1, h2val2, h2val3"" ... NSEXTENSION Message 3122 0 : "TRACE combine_headers CALL 30 : LINE 25; result_str = "User-Agent: curl/7.24.0 (amd64-portbld-freebsd8.4) libcurl/7.24.0 OpenSSL/0.9.8y zlib/1.2.3\r\nH1: abcd\r\nAccept: */*\r\nHost: 10.217.24.7\r\nH2: h2val1, h2val2, h2val3\r\n\r\n""
... NSEXTENSION Message 3123 0 : "TRACE combine_headers CALL 30 : RETURN FROM COMBINE_HEADERS; return = "User-Agent: curl/7.24.0 (amd64-portbld-freebsd8.4) libcurl/7.24.0 OpenSSL/0.9.8y zlib/1.2.3\r\nH1: abcd\r\nAccept: */*\r\nHost: 10.217.24.7\r\nH2: h2val1, h2val2, h2val3\r\n\r\n""
<!--NeedCopy-->
Custom logging
You can also add your own logging to your extension function. To do so, use the built-in ns.logger:level() function, where level is emergency , alert , critical , error , warning , notice , info , or debug . The parameters are the same as the C printf() function: a format string, and a variable number of arguments to supply values for the % specified in the format string. For example, you might add the following to the COMBINE_HEADERS function to log the result of a call:
local result_str = table.concat(combined_headers, "\r\n") .. "\r\n\r\n"
ns.logger:info("Result: %s", result_str)
return result_str
<!--NeedCopy-->
The above function would log the following message to/var/log/ns.log for the sample input shown in the abbreviated log messages examples in the Extension Tracing section above.
... : default NSEXTENSION Message 143 0 : "Result: Host: 10.217.24.7:2000^M H1: abcd, 1234^M User-Agent: curl/7.24.0 (amd64-portbld-freebsd8.4) libcurl/7.24.0 OpenSSL/0.9.8y zlib/1.2.3^M Accept: */*^M H2: h2val1, h2val2, h2val3^M ^M"