Automation

Hello,

 

I have event script where I use  jcs:syslog() to send some strings to local messages file. I use latest 9.5R1.8 and found that log string appears to messages file only after somesthing else is being logged. Looks likethis mesaage justs sits in some buffer and will be flushed only after sysog message from any other dæmon

 

Has anyone else seen such behaviour? Should I create JTAC case or do you have any other ideas is it intentional or is there any workaround to avoid this delay?

 

-- 

Cougar

 

#eventscript
#junoscript
#syslog

I've seen a variable length delay (from zero seconds to up to a minute) but I've never noticed that it corresponded with another logged message.  What is the maximum delay that you're seeing?

 

I can't see any specific delay. Looks like always last string from jcs:syslog() is buffered as long as there is no other messages logged.

 

For example:

 

May 22 09:01:51  LAB-m10i file[6834]: UI_JUNOSCRIPT_CMD: User 'root' used JUNOScript client to run command 'get-interface-information level-extra=descriptions snmp-index=117'
May 22 09:01:51  LAB-m10i file[6834]: UI_CHILD_START: Starting child '/sbin/ifinfo'
May 22 09:01:51  LAB-m10i file[6834]: UI_CHILD_STATUS: Cleanup child '/sbin/ifinfo', PID 6836, status 0
May 22 09:01:51  LAB-m10i file[6834]: UI_LOGOUT_EVENT: User 'root' logout
[…now waiting for a long time and the jcs:syslog() string comes together with a new message to the syslog…]

May 22 09:01:51  LAB-m10i cscript: IFNAME: ge-0/0/0 went down IFDESCR: -> 3750-1 GigabitEthernet1/0/28
May 22 09:39:58  LAB-m10i chassisd[1141]: CHASSISD_SNMP_TRAP6: SNMP trap generated: Power Supply failed (jnxContentsContainerIndex 2, jnxContentsL1Index 3, jnxContentsL2Index 0, jnxContentsL3Index 0, jnxContentsDescr Power Supply 2, jnxOperatingState/Temp 6)

 

 

As you can see, the timestamp is right but I got message this time more than half hour later.

 

I also tested with more than one line and all lines are waiting in buffer. This does not happen with local messages file only but also with remote syslog server. It can't be just some missing fsync or flush but something more (some kind of buffering in syslog daemon?)

 

This sounds like a bug to me, that delay is far too long, could you open a case with JTAC?

There is now PR 449778 filed to fix this issue.

This bug is fixed in 10.2-20091029.1

 

Workaround for older versions: put jcs:sleep(4) just after last jcs:syslog() call