https://github.com/lldap/lldap logo
Powered by
RuneSiren - lldap will occasionally (every few ...
# troubleshooting
r
lldap will occasionally (~every few weeks) hang and stop serving requests. There is nothing in the logs other than 
2024-10-10T00:00:00.012960927+00:00  INFO     cleanup_db [ 11.8ms | 100.00% ]
At the time when I detected the failure (the next morning), this log message, which is normally hourly, was 10 hours old. lldap was still running. What is the best method to diagnose this issue?
a
message has been deleted
n
Hmm, that log is only printed once the query finishes, due to our log processor (which helps with async queries and tells you the runtime, among other things). Which means, if it's stuck processing one query, you won't get anything about it in the logs. I can check whether there is an easy env variable setup to also enable a raw log, otherwise I can send you a patch that will enable that. At least, we'll get a log when the query (any query) starts, so we know what it's doing
r
I do not have debug logging enabled at this time. I could, but that's a lot of logs, particularly considering this issue tends to come up every few weeks.
If it's helpful, though, I'll turn it on.
n
No, it's not about debug
I just merged a PR that'll give you raw logs if you set LLDAP_RAW_LOG=1
It'll (only) double the size of the logs
r
Thanks! I'll put that in as soon as I get time.
n
And once it's stuck, can you check htop or similar? To see what's running, if it's a zombie process, stuck on I/O, spinning on CPU...
Also, SQLite or PG?
And what FS if SQLite?
r
SQLite. I wish everything I had to support had PGSQL adapters... ext4
I have atop running. I'll check its historic records...
n
No NFS or similar?
r
No NFS.
atop says that lldap was in the D state with 0% CPU usage at 6am today.
(and indeed, all morning)
(dmesg shows no filesystem errors)
It appears to have been consistently reading 191 KB/s from disk that entire time.
(Like, on literally every 10 minute interval, the stat was 190 or 191)
n
So, stuck on I/O
r
Apparently.
There were no other obvious issues with the VPS during that time, other than nslcd going at insane CPU because of the lldap failure.
Copy code
nslcd[14811]: [301253] <passwd="db2inst1"> no available LDAP server found: Server is unavailable: Broken pipe
nslcd[14811]: [bb39e3] <passwd="db2inst1"> no available LDAP server found: Server is unavailable: Broken pipe
nslcd[14811]: [beef24] <passwd="tutu"> no available LDAP server found: Server is unavailable: Broken pipe
Seems like it's just constantly failing lookups from a ssh scan attack.
Continues up until I restart lldap, at which point everything is fine.
n
That could make LLDAP unresponsive, I haven't stress tested it
r
Since I restarted it, I'm down to ~3 'validnames' failures in the log.
n
(if you had a DDoS)
It's essentially single threaded (though that's just a matter of changing the number of threads in main)
r
I suppose that is in fact a DDoS, but any authentication mechanism kindof needs to be able to handle "the standard internet background ssh password spraying".
And it apparently did handle it fine after the restart?
I'll confirm the attack was still ongoing
Yep.
n
Well, the nscld integration is a bit uncharted territory, especially for me
r
Hmm...
n
But if it's just doing a user lookup, that should be very fast
r
I wish the log indicated what IP/port the requests came from.
Then I could at least know which machine's logs to review.
Wait no, wrong logs, these are local...
Yeah, ok, not sure then. It's possible it fell over due to DoS, I suppose.
But I would get the impression the DoS started in response to it ceasing to respond...
hmm
n
If nscld spawns a new LDAP connection for each query, that's kinda expensive (~600ms)
r
The problem with running an auth service is this happens. Hard to say what the best approach is on the systems level.
n
The request itself is 2ms
r
How do I check if it does this?
n
You should have logs in lldap for login attempts (if you have a quite recent LLDAP)
Or, just look at the size of each LDAP session in the logs. Is it 3-4 message? Then it spawns a new connection every time
r
zero lines. I'm not on debug logging. I'll turn that on. Remind me the env var?
n
Actually, if it keeps the session open, you won't have any logs about it until it closes the session
r
Ah.
n
LLDAP_RAW_LOG
(that helps work around the issue as well)
r
That needs the new build right?
I'll work on that...
n
Yep
What was the memory consumption of LLDAP? If there's a weeks-long LLDAP session with a DDoS, it might have... grown to buffer the logs of the entire session
r
Isn't this itself a dangerous opening for a DOS attack on the memory footprint of the lldap process if nscld behaves properly and reuses a long running session?
n
Great minds think alike 🙂
r
vsize 378M rsize 684K psize 543K swapsz 1.8M
Seems normalish
current footprint is vsize 552.7M rsize 8.8M psize 0B swapsz 4.7M (wtf is psize 0?)
So honestly 'much worse than at 1:40am'
n
What is psize?
r
I would guess that's in reference to Proportional Set Size...
but that can't be 0
n
Let me see what an unladen LLDAP clocks in at
r
Yes, psize is proportional set size. I assume the calculation is just not correct
Yeah, ignore that stat. psize is 7.5M. (the calculation was just disabled by default, or I bumped 'R')
n
355M? I'm surprised
r
That's Virtual Size though.
It doesn't reflect actual ram usage or swap usage t all
You want to be looking at the rsize 8.8MB + swapsz 4.7M more likely.
n
Yeah, then we're in the 10s of kB
r
I'll get you the /proc/pid/maps though if you want
Still in the process of building from master though
I do this often enough I really should automate it
Alright, raw logging is on.
and I have a a script to auto-build&tar
Copy code
2024-10-10T20:46:14.352583Z  WARN LDAP session:LDAP request: lldap::domain::ldap::group: Ignoring unknown group attribute "unix-username" in filter.\n\
Sure, expected.
Copy code
2024-10-10T20:46:14.356230Z  WARN LDAP session:LDAP request: lldap::domain::ldap::user: Ignoring unrecognized group attribute: unix\n\
Less so,w hen I account for one being ""'d and one not
Sadly no IP/port so I can't trace the originating service.
n
Yeah, the quoting is not consistent
Since you're rebuilding already, you can try changing the logging format in server/src/infra/logging.rs
r
nah, that build takes forever. I'll live with it.
It's just odd cause I dont feel like anything should be quering the attribute 'unix'
n
In "on_request_start", you can add 
ip = request.peer_addr()
Is it a user attribute maybe? If a request is top scope, it'll hit both users and groups
r
any way to get peer port?
n
That's included
r
I assume I need the 
.to_string()
or at least it wont hurt
Alright, that's building. In the meantime, it's running. Things are quiet enough for now...
Do I need debug log or is raw log enough? If so what's the var again?
n
Debug log will give you lots of info... about the internals of LLDAP 🙂 You can also get the actual query that was run that way
LLDAP_RAW_LOG is for the long sessions/hanging
r
Sorry if I'm a bit repetitive. This happens on the order of weeks so I want to get the logging right rather than miss a chance.
n
No news is good news 🙂 I'll cut a release today
r
Oh! Yeah. Go for it!
No active icinga alerts!
On that note I'll turn off my logging...
Now running 
v0.6.0-0-g098745e
! 🎉 Thanks for all your help these last few weeks!
PreviousNext
Powered by