v4 - linelog taking 1 second to write to local file

Thu Apr 2 21:41:27 UTC 2026

Hi,

I have the following config in radiusd.conf:

log {
        destination = file
        file = ${logdir}/radius.log
}

When configured with destination = file, it's taking 1 second to write to
the file exactly for any linelog configured output. If I change it to
syslog instead of file, it's instant. This results in a one-second delay in
the reply back to the client.

Here is the verbose log output:

2026-04-02T21:31:26.150850Z: (0) [4] unlang_module - linelog
(log_auth_access_accept) 2026-04-02T21:31:26.150900Z: (0) ** [5] frame_eval
<< pushed-child (noop not-set) 2026-04-02T21:31:26.150942Z: (0) ** [5]
unlang_interpret - frame action next 2026-04-02T21:31:26.151011Z: (0) **
[5] frame_eval >> function 2026-04-02T21:31:26.151055Z: (0) Calling
function 0x7f65be0b9924 (call_env_expand_start)
2026-04-02T21:31:26.151154Z: (0) Calling repeat function 0x7f65be0ba182
(call_env_expand_repeat) 2026-04-02T21:31:26.151239Z: (0) ** [5] frame_eval
<< calculate-result (... not-set) 2026-04-02T21:31:26.151255Z: (0) ** [5]
result_calculate - skipping frame, no result set
2026-04-02T21:31:26.151323Z: (0) ** [5] frame_eval - done current
subsection with (noop not-set), will NOT set higher frame rcode (p_result)
2026-04-02T21:31:26.151379Z: (0) ** [5] unlang_interpret - frame action pop
2026-04-02T21:31:26.151393Z: (0) ** [5] unlang_interpret - frame popped
2026-04-02T21:31:26.151441Z: (0) ** [4] unlang_interpret - frame action
next 2026-04-02T21:31:26.151486Z: (0) ** [4] frame_eval >> module
2026-04-02T21:31:26.151559Z: (0) [4] unlang_module - linelog
(log_auth_access_accept) 2026-04-02T21:31:26.151581Z: (0)
log_auth_access_accept - Using default message 2026-04-02T21:31:26.151656Z:
(0) log_auth_access_accept - ** [5] frame_eval << pushed-child (noop
not-set) 2026-04-02T21:31:26.151867Z: (0) log_auth_access_accept - ** [5]
unlang_interpret - frame action next 2026-04-02T21:31:26.151915Z: (0)
log_auth_access_accept - ** [5] frame_eval >> tmpl
2026-04-02T21:31:26.151964Z: (0) log_auth_access_accept - ** [5] frame_eval
<< calculate-result (ok not-set) 2026-04-02T21:31:26.152036Z: (0)
log_auth_access_accept - ** [5] result_calculate - have (... not-set) frame
or module returned (ok not-set) 2026-04-02T21:31:26.152082Z: (0)
log_auth_access_accept - ** [5] result_calculate - using default
instruction priority for ok, not-set 2026-04-02T21:31:26.152156Z: (0)
log_auth_access_accept - ** [5] result_calculate - overwriting existing
result (... not-set) with higher priority (ok not-set)
2026-04-02T21:31:26.152174Z: (0) log_auth_access_accept - ** [5] frame_eval
- done current subsection with (ok not-set), will set higher frame rcode
2026-04-02T21:31:26.152271Z: (0) log_auth_access_accept - ** [5]
unlang_interpret - frame action pop 2026-04-02T21:31:26.152289Z: (0)
log_auth_access_accept - ** [5] unlang_interpret - frame popped
2026-04-02T21:31:26.152325Z: (0) log_auth_access_accept - ** [4] result_pop
- using instruction priority for higher frame (ok, 3)
2026-04-02T21:31:26.152399Z: (0) log_auth_access_accept - ** [4]
result_calculate - have (ok 3) frame or module returned (ok 3)
2026-04-02T21:31:26.152444Z: (0) log_auth_access_accept - Setting
request->rcode to 'ok' 2026-04-02T21:31:26.152459Z: (0)
log_auth_access_accept - ** [4] result_calculate - overwriting existing
result (ok 3) with higher priority (ok 3) 2026-04-02T21:31:26.152534Z: (0)
log_auth_access_accept - ** [4] unlang_interpret - frame action next
2026-04-02T21:31:26.152553Z: (0) log_auth_access_accept - ** [4] frame_eval
>> module 2026-04-02T21:31:26.152711Z: (0) log_auth_access_accept - ** [4]
frame_eval << yield (noop not-set) 2026-04-02T21:31:26.152851Z: (0)
log_auth_access_accept - ** [4] frame_eval - yielding with current (noop
not-set) 2026-04-02T21:31:26.152983Z: (0) log_auth_access_accept - ** [4]
unlang_interpret - frame action yield 2026-04-02T21:31:26.153089Z: (0)
log_auth_access_accept - ** [4] unlang_interpret - interpret yielding
2026-04-02T21:31:26.153136Z: (0) log_auth_access_accept -
_worker_request_yield - Request yielded 2026-04-02T21:31:27.155378Z: (0)
log_auth_access_accept - Interpreter - Request marked as runnable
2026-04-02T21:31:27.155422Z: (0) log_auth_access_accept -
_worker_request_runnable - Request marked as runnable
2026-04-02T21:31:27.155484Z: (0) log_auth_access_accept - ** [4]
unlang_interpret - interpret entered 2026-04-02T21:31:27.155494Z: (0)
log_auth_access_accept - _worker_request_resume - Request resuming
2026-04-02T21:31:27.155503Z: (0) log_auth_access_accept - ** [4]
unlang_interpret - frame action next 2026-04-02T21:31:27.155514Z: (0)
log_auth_access_accept - log_auth_access_accept - Resuming execution
2026-04-02T21:31:27.155523Z: (0) log_auth_access_accept - ** [4] frame_eval
>> module 2026-04-02T21:31:27.155536Z: (0) log_auth_access_accept -
log_auth_access_accept (noop) 2026-04-02T21:31:27.155544Z: (0) ** [4]
frame_eval << next (noop not-set) 2026-04-02T21:31:27.155556Z: (0) ** [4]
frame_eval - done current subsection with (ok 3), will set higher frame
rcode 2026-04-02T21:31:27.155564Z: (0) ** [4] unlang_interpret - frame
action pop 2026-04-02T21:31:27.155571Z: (0) ** [4] unlang_interpret - frame
popped 2026-04-02T21:31:27.155580Z: (0) ** [3] result_pop - using
instruction priority for higher frame (ok, not-set)
2026-04-02T21:31:27.155589Z: (0) ** [3] result_calculate - have (noop
not-set) frame or module returned (ok not-set) 2026-04-02T21:31:27.155597Z:
(0) ** [3] result_calculate - using default instruction priority for ok,
not-set 2026-04-02T21:31:27.155606Z: (0) ** [3] result_calculate -
overwriting existing result (noop not-set) with higher priority (ok
not-set) 2026-04-02T21:31:27.155621Z: (0) } # send Access-Accept ((ok))
2026-04-02T21:31:27.155629Z: (0) ** [3] unlang_interpret - done current
subsection with (... not-set) 2026-04-02T21:31:27.155636Z: (0) ** [3]
unlang_interpret - frame action pop 2026-04-02T21:31:27.155643Z: (0) ** [3]
unlang_interpret - frame popped 2026-04-02T21:31:27.155650Z: (0) ** [2]
unlang_interpret - frame action next 2026-04-02T21:31:27.155658Z: (0) **
[2] frame_eval >> module 2026-04-02T21:31:27.155674Z: (0) Entered state
resume_access_accept 2026-04-02T21:31:27.155685Z: (0)
request_data_reference: No request data found at 0x5608d64308d0:0
2026-04-02T21:31:27.155693Z: (0) Adding Proxy-State attributes from request
2026-04-02T21:31:27.155703Z: (0) default (noop)
2026-04-02T21:31:27.155710Z: (0) ** [2] frame_eval << calculate-result
(noop not-set) 2026-04-02T21:31:27.155718Z: (0) ** [2] result_calculate -
have (... not-set) frame or module returned (noop not-set)
2026-04-02T21:31:27.155727Z: (0) Setting request->rcode to 'noop'
2026-04-02T21:31:27.155734Z: (0) ** [2] result_calculate - using default
instruction priority for noop, not-set 2026-04-02T21:31:27.155742Z: (0) **
[2] result_calculate - overwriting existing result (... not-set) with
higher priority (noop not-set) 2026-04-02T21:31:27.155751Z: (0) ** [2]
frame_eval - done current subsection with (noop not-set), will set higher
frame rcode 2026-04-02T21:31:27.155759Z: (0) ** [2] unlang_interpret -
frame action pop 2026-04-02T21:31:27.155766Z: (0) ** [2] unlang_interpret -
frame popped 2026-04-02T21:31:27.155774Z: (0) ** [1] result_pop - using
instruction priority for higher frame (noop, not-set)
2026-04-02T21:31:27.155782Z: (0) ** [1] result_calculate - have (...
not-set) frame or module returned (noop not-set)
2026-04-02T21:31:27.155790Z: (0) ** [1] result_calculate - using default
instruction priority for noop, not-set 2026-04-02T21:31:27.155798Z: (0) **
[1] result_calculate - overwriting existing result (... not-set) with
higher priority (noop not-set) 2026-04-02T21:31:27.155806Z: (0) ** [1]
unlang_interpret - frame action next 2026-04-02T21:31:27.155815Z: (0) **
[1] frame_eval >> call 2026-04-02T21:31:27.155822Z: (0) ** [1] frame_eval
<< calculate-result (... not-set) 2026-04-02T21:31:27.155830Z: (0) ** [1]
result_calculate - skipping frame, no result set
2026-04-02T21:31:27.155837Z: (0) } # default (noop)
2026-04-02T21:31:27.155844Z: (0) ** [1] frame_eval - done current
subsection with (noop not-set), will set higher frame rcode
2026-04-02T21:31:27.155852Z: (0) ** [1] unlang_interpret - frame action pop
2026-04-02T21:31:27.155859Z: (0) ** [1] unlang_interpret - frame popped
2026-04-02T21:31:27.155866Z: (0) ** [0] result_calculate - have (...
not-set) frame or module returned (noop not-set)
2026-04-02T21:31:27.155874Z: (0) ** [0] result_calculate - using default
instruction priority for noop, not-set 2026-04-02T21:31:27.155882Z: (0) **
[0] result_calculate - overwriting existing result (... not-set) with
higher priority (noop not-set) 2026-04-02T21:31:27.155891Z: (0) ** [0]
unlang_interpret - interpret exiting, returning (noop)
2026-04-02T21:31:27.155914Z: (0) Done request 2026-04-02T21:31:27.155920Z:
(0) Time tracking ended 2026-04-02T21:31:27.155974Z: stk: Currently in
fr_radius_encode_pair 2026-04-02T21:31:27.156041Z: stk: > [0] uint32:
Acct-Interim-Interval, vendor: 0x0 (0), attr: 0x55 (85)
2026-04-02T21:31:27.156050Z: stk: 2026-04-02T21:31:27.156056Z: stk:
Currently in encode_rfc 2026-04-02T21:31:27.156061Z: stk: > [0] uint32:
Acct-Interim-Interval, vendor: 0x0 (0), attr: 0x55 (85)
2026-04-02T21:31:27.156069Z: stk: 2026-04-02T21:31:27.156074Z: stk:
Currently in encode_child 2026-04-02T21:31:27.156079Z: stk: > [0] uint32:
Acct-Interim-Interval, vendor: 0x0 (0), attr: 0x55 (85)
2026-04-02T21:31:27.156086Z: stk: 2026-04-02T21:31:27.156091Z: stk:
Currently in encode_value 2026-04-02T21:31:27.156096Z: stk: > [0] uint32:
Acct-Interim-Interval, vendor: 0x0 (0), attr: 0x55 (85)
2026-04-02T21:31:27.156104Z: stk: 2026-04-02T21:31:27.156115Z: hex: --
value uint32 -- 2026-04-02T21:31:27.156123Z: hex: 0000: 00 00 00 f0
2026-04-02T21:31:27.156131Z: hex: -- header rfc --
2026-04-02T21:31:27.156137Z: hex: 0000: 55 06 2026-04-02T21:31:27.156143Z:
stk: Currently in fr_radius_encode_pair 2026-04-02T21:31:27.156148Z: stk: >
[0] string: User-Name, vendor: 0x0 (0), attr: 0x1 (1)
2026-04-02T21:31:27.156155Z: stk: 2026-04-02T21:31:27.156160Z: stk:
Currently in encode_rfc 2026-04-02T21:31:27.156166Z: stk: > [0] string:
User-Name, vendor: 0x0 (0), attr: 0x1 (1) 2026-04-02T21:31:27.156172Z: stk:
2026-04-02T21:31:27.156177Z: stk: Currently in encode_child
2026-04-02T21:31:27.156182Z: stk: > [0] string: User-Name, vendor: 0x0 (0),
attr: 0x1 (1) 2026-04-02T21:31:27.156189Z: stk:
2026-04-02T21:31:27.156200Z: stk: Currently in encode_value
2026-04-02T21:31:27.156205Z: stk: > [0] string: User-Name, vendor: 0x0 (0),
attr: 0x1 (1) 2026-04-02T21:31:27.156212Z: stk:
2026-04-02T21:31:27.156217Z: hex: -- value string --
2026-04-02T21:31:27.156224Z: hex: 0000: 6d 61 63 61 75 74 68 40 34 41 2d 39
42 2d 44 42 2026-04-02T21:31:27.156231Z: hex: 0010: 2d 37 36 2d 44 36 2d 35
33 2026-04-02T21:31:27.156238Z: hex: -- header rfc --
2026-04-02T21:31:27.156243Z: hex: 0000: 01 1b 2026-04-02T21:31:27.156249Z:
hex: -- fr_radius_encode encoded packet -- 2026-04-02T21:31:27.156256Z:
hex: 0000: 02 94 00 47 19 d6 f5 64 9e 8d 68 bf d1 e9 f5 3b
2026-04-02T21:31:27.156264Z: hex: 0010: b5 ed df 2c 50 12 00 00 00 00 00 00
00 00 00 00 2026-04-02T21:31:27.156272Z: hex: 0020: 00 00 00 00 00 00 55 06
00 00 00 f0 01 1b 6d 61 2026-04-02T21:31:27.156280Z: hex: 0030: 63 61 75 74
68 40 34 41 2d 39 42 2d 44 42 2d 37 2026-04-02T21:31:27.156286Z: hex: 0040:
36 2d 44 36 2d 35 33 2026-04-02T21:31:27.156477Z: (0) Sending Access-Accept
ID 148 from 0.0.0.0/0:1812 to 127.0.0.1:33797 length 71 via socket
radius_udp server * port 1812 2026-04-02T21:31:27.156509Z: (0)
Acct-Interim-Interval = 240 2026-04-02T21:31:27.156499Z: (0) Packet-Type =
Access-Accept 2026-04-02T21:31:27.156531Z: (0) Finished request
2026-04-02T21:31:27.156547Z: (0) Request deinitialising (0x5608d7a25220)

In particular, you can see the exact one-second gap:

2026-04-02T21:31:26.153136Z: (0) log_auth_access_accept -
_worker_request_yield - Request yielded 2026-04-02T21:31:27.155378Z: (0)
log_auth_access_accept - Interpreter - Request marked as runnable

Any thoughts on why this would be the case?

Thanks,

James

-- 

Visit purple.ai <https://purple.ai/>

Purple on LinkedIn 
<https://uk.linkedin.com/company/purple-wifi>

Email disclaimer 
<http://www.purple.ai/email-disclaimer/>