Sporadic TCL errors from iRule showing up in logs

Question

Hello!
I noticed a few errors are showing up on /var/log/ltm. To be able to further debug it, I added a log statement to the script. It then became evident that the log message comes up only ~10% of the time, and on different line numbers. Also, on show rule command, the errors count are zero!
Can anyone help me clear this one? I was thinking perhaps a bug is causing this... (it is running v11.4.1)

Script:
ltm rule add_clientIP_header_2 {
    when HTTP_REQUEST {
        if { [HTTP::header exists "ClientIPAddress"] }  {
            log local0. "header ClientIPAddress already present"
        } else {
             Insert client ip HTTP Header
            set clientip [ scan [IP::client_addr] {%[^\%]\%%} ]
            log local0. "request from $clientip"
            HTTP::header insert ClientIPAddress $clientip
            log local0. "header inserted $clientip"
            unset clientip
        }
    }
}

Log sample:
Jun 22 17:14:01 my_bigip info tmm3[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:01 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
**Jun 22 17:14:01 my_bigip err tmm[9237]: 01220001:3: TCL error: /Common/my_rule  - Operation not supported (line 7)     invoked from within "HTTP::header insert ClientIPAddress $clientip"**
Jun 22 17:14:01 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:01 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:27 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:27 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:27 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:27 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:27 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:27 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:28 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:28 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:28 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:29 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:29 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:29 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:29 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:29 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:29 my_bigip info tmm2[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:29 my_bigip info tmm2[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:29 my_bigip info tmm2[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:30 my_bigip info tmm2[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:30 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:30 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:32 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:33 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:33 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:33 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:33 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:33 my_bigip info tmm2[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:33 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:34 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:34 my_bigip info tmm2[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:34 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:34 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:34 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:34 my_bigip info tmm2[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:34 my_bigip info tmm2[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:34 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:35 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:39 my_bigip info tmm3[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:39 my_bigip info tmm3[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:39 my_bigip info tmm1[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
**Jun 22 17:14:39 my_bigip err tmm1[9237]: 01220001:3: TCL error: /Common/my_rule  - Operation not supported (line 1)     invoked from within "HTTP::header insert ClientIPAddress $clientip"**
Jun 22 17:14:39 my_bigip info tmm3[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:39 my_bigip info tmm3[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
Jun 22 17:14:39 my_bigip info tmm[9237]: Rule /Common/my_rule : request from xx.xx.xx.xx
**Jun 22 17:14:39 my_bigip err tmm[9237]: 01220001:3: TCL error: /Common/my_rule  - Operation not supported (line 7)     invoked from within "HTTP::header insert ClientIPAddress $clientip"**

arpydays · Answer

Hi, &nbsp;
do you have any other irules running on the VS?&nbsp;

sfuerst_116779 · Answer

I bet you have another iRule that does a HTTP::respond or HTTP::redirect&nbsp;
Once those commands have run, the HTTP context is gone, and other HTTP iRule commands will not work.  This will mean other iRules that trigger on the same event will have issues, and trigger log messages like this.&nbsp;

leo_rodrigues_1 · Answer

hmm no, this is the only iRule associated with the virtual servers... The same iRule is applied to multiple VS though...&nbsp;

stephanmanthey · Answer

Hi Leo,&nbsp;
the scan in your code works fine to remove the trailing route domain information.&nbsp;
In my sample (tested on TMOS v10.2.4) below I use getfield instead.&nbsp;
I´m testing for the variable and validate the IPv4 address before logging it.&nbsp;
In case the variable does not exist or catch detects an invalid IPv4 address an error will be logged.  &nbsp;
set client_ip "[getfield [IP::client_addr] "%" 1]"

if { [info exists client_ip] } {
    if { [catch {IP::addr ${client_ip} mask 255.255.255.255}] } {
        log local0. "error: no valid IPv4 address found (${client_ip})"
    } else {
        log local0. "address found (${client_ip})"
    }
} else {
    log local0. "error: variable \$client_ip does not exist"
}

Regarding the error: I guess the result of the scan may contain white space characters or invalid characters causing the TCL error. My sample code might help to figure out these strings.&nbsp;
Thanks,&nbsp;
Stephan&nbsp;

leo_rodrigues_1 · Answer

hmm I`ll give it a try... Thanks!&nbsp;

Forum Discussion

Sporadic TCL errors from iRule showing up in logs

5 Replies

Recent Discussions

F5Access | MacOS Sonoma

Rewrite uri translation not working

Chrome V 124+ on MacOS - Virtual Server Access Issue

Transaction looks successful but file not downloading

Overwriting or adding LTM SSL Traffic cert and key using iControlREST

Related Content

F5 BIGIP showing wrong time

Insufficient permissions BIG-IQ login error

captcha not show after enable header security

Bot Log is not showing in BIG-IQ

not show barcode google authenticator mfa