Forum Discussion

Josh_B_152229's avatar
Josh_B_152229
Icon for Nimbostratus rankNimbostratus
Mar 23, 2015

iRule logging [LB::server pool] crashes tmm on 11.4.1 HF3

F5 support suggested I post on DevCentral to ask if selecting a pool in the Client_Accepted event would mark that pool active (yes) and if making this selection so early in the process I am able to "override" the default pool configured for a virtual server (as far as I can tell, yes).

Instead of posting the question to DevCentral I thought I should just write a rule and test with some log messages. I found out I was right, but I also found out the rule I was using to test crashed tmm on 11.4.1 HF3 three times in a row. This did not happen in my DR environment which is on 11.6.0 HF3.

Basically, the rule and procs just log which pool is selected multiple times between events and function calls. I suspect there must be some difference in how [LB::server pool] is being used between versions. It seems like I have experienced a ton of odd behavior while working with my LTMs.

In the messages below there appears to be a time difference between the log message from the rule and the emerg logger messages. This was not the case in reality. I was monitoring the ltm log for my test messages with tail -f ltm | grep TEST and issuing a request I knew would trigger the rule execution. I saw my first log statement as expected and immediately the emerg logger statements were injected into my console.

  • Has someone else experienced this?
  • Does anyone know what causes this?
  • Do I have to upgrade my production units to 11.6.0 HF3 to fix this?

Messages from daemon.log:

   Mar 19 16:33:52 f5cm2 emerg logger: Re-starting tmm
    Mar 19 16:33:52 f5cm2 emerg logger: Re-starting tmm1
    Mar 19 16:37:24 f5cm2 emerg logger: Re-starting tmm
    Mar 19 16:37:24 f5cm2 emerg logger: Re-starting tmm1
    Mar 19 16:38:54 f5cm2 emerg logger: Re-starting tmm
    Mar 19 16:38:54 f5cm2 emerg logger: Re-starting tmm1
`

Messages from ltm log:

`Mar 19 16:33:20 f5cm2 debug tmm1[8361]: Rule /Common/test : TEST: start pool in rule CLIENT_ACCEPT /Common/expected_pool_name
            Mar 19 16:33:20 f5cm2 notice sod[5545]: 01140045:5: HA reports tmm NOT ready.
            Mar 19 16:33:20 f5cm2 notice sod[5545]: 010c0050:5: Sod requests links down.
            Mar 19 16:33:20 f5cm2 info lacpd[5552]: 01160016:6: Failover event detected. (Switchboard failsafe disabled while offline)
            Mar 19 16:33:20 f5cm2 err bcm56xxd[6270]: 012c0010:3: Failover event detected.  Marking external interfaces down. bsx.c(3724)

            ...snip...

            Mar 19 16:36:54 f5cm2 debug tmm[15613]: Rule /Common/test : TEST: start pool in rule CLIENT_ACCEPT /Common/expected_pool_name
            Mar 19 16:36:54 f5cm2 notice sod[5545]: 01140045:5: HA reports tmm NOT ready.
            Mar 19 16:36:54 f5cm2 notice sod[5545]: 010c0050:5: Sod requests links down.
            Mar 19 16:36:54 f5cm2 info lacpd[5552]: 01160016:6: Failover event detected. (Switchboard failsafe disabled while offline)
            Mar 19 16:36:55 f5cm2 err bcm56xxd[6270]: 012c0010:3: Failover event detected.  Marking external interfaces down. bsx.c(3724)

            ...snip...

            Mar 19 16:38:24 f5cm2 debug tmm1[16328]: Rule /Common/test : TEST: start pool in rule CLIENT_ACCEPT /Common/expected_pool_name
            Mar 19 16:38:24 f5cm2 notice sod[5545]: 01140045:5: HA reports tmm NOT ready.
            Mar 19 16:38:24 f5cm2 notice sod[5545]: 010c0050:5: Sod requests links down.
            Mar 19 16:38:24 f5cm2 err bcm56xxd[6270]: 012c0010:3: Failover event detected.  Marking external interfaces down. bsx.c(3724)
    `

test2 rule:

when CLIENT_ACCEPTED { 
      log local0.debug "TEST: start pool in rule CLIENT_ACCEPT [LB::server pool]"
      call test::client_accepted
      log local0.debug "TEST: pool in CLIENT_ACCEPT after function [LB::server pool]"
    }
    when HTTP_REQUEST {
      log local0.debug "TEST: start pool in rule HTTP_REQUEST [LB::server pool]"
      call test::http_request
      log local0.debug "TEST: pool in HTTP_REQUEST after function [LB::server pool]"
      }

test rule

proc client_accepted {
      log local0.debug "TEST: pool coming into client_accept [LB::server pool]"
      set var 1 
      switch $var {
        "0" {
          log local0.debug "TEST: var was set to $var."
        }   
        "1" {
          log local0.debug "TEST: var was set to $var."
          pool pool_name
          log local0.debug "TEST: pool selected in switch on var of client_accept [LB::server pool]"
        }   
      }
      log local0.debug "TEST: pool selected in client_accept [LB::server pool]"
    }
proc http_request {
  log local0.debug "TEST: pool coming into http_request [LB::server pool]"
  pool pool2_name
  log local0.debug "TEST: pool selected in http_request [LB::server pool]"
}        
  • Edits to this post are because of formatting. This is truly infuriating. Repeated edits for formatting got the post flagged as spam.
  • Hi Josh,

     

    it´s a common approach to use [LB::server pool] in the context of
    CLIENT_ACCEPTED
    to store the virtual server´s default pool to a variable.

     

    By now I haven´t seen this function causing TMM restarts.

     

    Did you check /var/core/ for core dumps?

     

    I would recommend to make the behavior reproducible, i.e. by reducing to a single event with i.e.

     

    when CLIENT_ACCEPTED {
       log local0.debug "TEST: start pool in rule CLIENT_ACCEPT [LB::server pool]"
    }
    

    Does it still cause TMM restarts after establishing a new connection to the virtual server?

     

    Perhaps it´s not the LB-command but the usage of procedures?

     

    As you are using the
    HTTP_REQUEST
    context I guess you have an http-profile or a fasthttp-profile assigned.

     

    To parse http, it would be required to terminate SSL, in case you are using encrypted traffic (only available in virtual server standard mode operation).

     

    What type of virtual server are you using, what profiles are assigned (
    tmsh list ltm virtual
    )?

     

    Do you have a default pool configured?

     

    Did you try iHealth to validate your configuration?

     

    Thanks, Stephan

     

    PS: Formatting a post can be frustrating, I agree. For long posts I used to put everything into a plaintext editor (no formatting, no indent for first and last line of code sections, no text bullets etc.). Now paste in and format each section separately.

     

    Sometimes indented code or paragraphs seem to be formatted automatically. Please remove and re-insert allowing you to format manually.

     

    • Josh_B_152229's avatar
      Josh_B_152229
      Icon for Nimbostratus rankNimbostratus
      Thanks for the link relating to core files. It is a SIGSEGV and I have opened a support ticket.
    • Josh_B_152229's avatar
      Josh_B_152229
      Icon for Nimbostratus rankNimbostratus
      Thanks for the link relating to core files. It is a SIGSEGV and I have opened a support ticket.
  • Support ticket for reference in case someone else experiences something simlar: 1-1069084162