You are not logged in.

#1 2019-01-30 05:35:03

rossboulet
Member
Registered: 2017-12-13
Posts: 36

getting many audit log entries from crond

On a system I run, I frequently compile the latest stable kernel and usually do pacman upgrades at the same time. Last week, I did this and my logwatch report ballooned to 10MB. The logwatch report was filled with unmatched audit messages. Further investigation reveled (not surprisingly) these messages in /var/log/everything/current. I have a cron job that runs every minute and every time it runs now, I get multiple log entries:

Jan 29 23:25:01 [kernel] [ 4573.490818] audit: type=1101 audit(1548825901.045:1412): pid=2174 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="rossboulet" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 29 23:25:01 [kernel] [ 4573.494287] audit: type=1103 audit(1548825901.048:1413): pid=2174 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="rossboulet" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 29 23:25:01 [kernel] [ 4573.496992] audit: type=1006 audit(1548825901.051:1414): pid=2174 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=193 res=1
Jan 29 23:25:01 [kernel] [ 4573.499287] audit: type=1101 audit(1548825901.051:1415): pid=2173 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="rossboulet" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 29 23:25:01 [kernel] [ 4573.501038] audit: type=1103 audit(1548825901.055:1416): pid=2173 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="rossboulet" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 29 23:25:01 [kernel] [ 4573.501805] audit: type=1006 audit(1548825901.055:1417): pid=2173 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=194 res=1
Jan 29 23:25:01 [kernel] [ 4573.501914] audit: type=1105 audit(1548825901.055:1418): pid=2174 uid=0 auid=1000 ses=193 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="rossboulet" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 29 23:25:01 [kernel] [ 4573.507376] audit: type=1105 audit(1548825901.061:1419): pid=2173 uid=0 auid=1000 ses=194 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="rossboulet" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 29 23:25:01 [kernel] [ 4573.513323] audit: type=1110 audit(1548825901.068:1420): pid=2174 uid=0 auid=1000 ses=193 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="rossboulet" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 29 23:25:01 [kernel] [ 4573.518954] audit: type=1110 audit(1548825901.071:1421): pid=2173 uid=0 auid=1000 ses=194 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="rossboulet" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'

Any ideas for:
1) What causes this?
2) Is there a way to turn them off?
3) Why does logwatch sees them as "unmatched"?

If I stop the cronie service, the messages stop. If I comment out the jobs in my crontab, the messages stop. So it's only when crond actually runs a task that I get these messages. I also tried installing a kernel from the repository to see if it was something in my home brew kernel, but it made no difference. If needed, I can also post my pacman.log.

Last edited by rossboulet (2019-01-31 02:24:15)

Offline

#2 2019-01-31 05:39:02

deep42thought
Administrator
From: Jena, Germany
Registered: 2017-06-17
Posts: 433

Re: getting many audit log entries from crond

What command do you run by cron?
Does that also happen when you run the command manually?

logwatch sees much stuff as "unmatched" on my system - usually I add rules to ignore that noise
to 1&2 I cannot say much as you didn't mention the command which is being executed.

regards,
deep42thought

Offline

#3 2019-01-31 05:44:30

rossboulet
Member
Registered: 2017-12-13
Posts: 36

Re: getting many audit log entries from crond

command being run is a simple touch.

crontab:
* * * * * touch $HOME/cron.touch

I just ran it manually and it did not generate any log entries.

Offline

#4 2019-01-31 05:54:38

levi
Moderator
From: Yorkshire, UK
Registered: 2018-06-16
Posts: 393

Re: getting many audit log entries from crond

Yes, those log lines all look like PAM lines to me; the root level crond is logging on as you to run your command.  if you run it locally, you don't have to go through any of those hoops.

I've no idea why this didn't used to end up in your logs; maybe the format of the messaging has changed, and your rules need updating or adding to.  But it seems to me the kind of stuff that absolutely should get logged so that if you do care about it, you can find it out.


Architecture: pentium4, Testing repos: Yes, Hardware: EeePC 901+2GB RAM+OS half on the SD card.

Offline

#5 2019-01-31 06:08:31

rossboulet
Member
Registered: 2017-12-13
Posts: 36

Re: getting many audit log entries from crond

levi wrote:

Yes, those log lines all look like PAM lines to me; the root level crond is logging on as you to run your command.  if you run it locally, you don't have to go through any of those hoops.

I've no idea why this didn't used to end up in your logs; maybe the format of the messaging has changed, and your rules need updating or adding to.  But it seems to me the kind of stuff that absolutely should get logged so that if you do care about it, you can find it out.

When you mention rules, are you referring to logwatch rules or are there rules somewhere for what gets journaled?

Offline

#6 2019-01-31 06:16:20

deep42thought
Administrator
From: Jena, Germany
Registered: 2017-06-17
Posts: 433

Re: getting many audit log entries from crond

rossboulet wrote:

When you mention rules, are you referring to logwatch rules or are there rules somewhere for what gets journaled?

yes, logwatch rules.
Have a look in /usr/share/logwatch/scripts/services/ - and put modifications thereof into /etc/logwatch/scripts/services/

regards,
deep42thought

Offline

#7 2019-01-31 07:50:25

rossboulet
Member
Registered: 2017-12-13
Posts: 36

Re: getting many audit log entries from crond

Okay, here is more info. In addition to my minimal 32-bit VM, I also built a similar 64-bit machine. Running the same cron job on both. On the 32-bit machine, I get 16 lines in the journal, but on the 64-bit machine, only four.

32-bit journal:

Jan 31 01:25:01 auditor audit[401]: USER_ACCT pid=401 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor audit[401]: CRED_ACQ pid=401 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor crond[401]: pam_unix(crond:session): session opened for user root by (uid=0)
Jan 31 01:25:01 auditor audit[401]: USER_START pid=401 uid=0 auid=0 ses=14 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor kernel: audit: type=1101 audit(1548919501.573:116): pid=401 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor kernel: audit: type=1103 audit(1548919501.573:117): pid=401 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor kernel: audit: type=1006 audit(1548919501.573:118): pid=401 uid=0 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=14 res=1
Jan 31 01:25:01 auditor kernel: audit: type=1105 audit(1548919501.573:119): pid=401 uid=0 auid=0 ses=14 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor audit[401]: CRED_REFR pid=401 uid=0 auid=0 ses=14 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor CROND[402]: (root) CMD (touch /root/cron.touch)
Jan 31 01:25:01 auditor kernel: audit: type=1110 audit(1548919501.576:120): pid=401 uid=0 auid=0 ses=14 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor audit[401]: CRED_DISP pid=401 uid=0 auid=0 ses=14 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor kernel: audit: type=1104 audit(1548919501.580:121): pid=401 uid=0 auid=0 ses=14 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor CROND[401]: pam_unix(crond:session): session closed for user root
Jan 31 01:25:01 auditor audit[401]: USER_END pid=401 uid=0 auid=0 ses=14 msg='op=PAM:session_close grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor kernel: audit: type=1106 audit(1548919501.583:122): pid=401 uid=0 auid=0 ses=14 msg='op=PAM:session_close grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'

64-bit journal:

Jan 31 01:25:01 audit64 crond[669]: pam_unix(crond:session): session opened for user root by (uid=0)
Jan 31 01:25:01 audit64 kernel: audit: type=1006 audit(1548919501.959:56): pid=669 uid=0 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=19 res=1
Jan 31 01:25:01 audit64 CROND[670]: (root) CMD (touch $HOME/cron.touch)
Jan 31 01:25:01 audit64 CROND[669]: pam_unix(crond:session): session closed for user root

Offline

#8 2019-01-31 17:28:54

levi
Moderator
From: Yorkshire, UK
Registered: 2018-06-16
Posts: 393

Re: getting many audit log entries from crond

Hmm, that does seem abberant now you present both of them.  It seems to be the 32-bit kernel is spitting out these extra log lines:

an 31 01:25:01 auditor audit[401]: USER_ACCT pid=401 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor audit[401]: CRED_ACQ pid=401 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor audit[401]: USER_START pid=401 uid=0 auid=0 ses=14 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor kernel: audit: type=1101 audit(1548919501.573:116): pid=401 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor kernel: audit: type=1103 audit(1548919501.573:117): pid=401 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor kernel: audit: type=1105 audit(1548919501.573:119): pid=401 uid=0 auid=0 ses=14 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor audit[401]: CRED_REFR pid=401 uid=0 auid=0 ses=14 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor kernel: audit: type=1110 audit(1548919501.576:120): pid=401 uid=0 auid=0 ses=14 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor audit[401]: CRED_DISP pid=401 uid=0 auid=0 ses=14 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor kernel: audit: type=1104 audit(1548919501.580:121): pid=401 uid=0 auid=0 ses=14 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor audit[401]: USER_END pid=401 uid=0 auid=0 ses=14 msg='op=PAM:session_close grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'
Jan 31 01:25:01 auditor kernel: audit: type=1106 audit(1548919501.583:122): pid=401 uid=0 auid=0 ses=14 msg='op=PAM:session_close grantors=pam_loginuid,pam_limits,pam_unix acct="root" exe="/usr/bin/crond" hostname=? addr=? terminal=cron res=success'

And for reference, these lines (taken from the 32-bit listings) are effectively common:

Jan 31 01:25:01 auditor crond[401]: pam_unix(crond:session): session opened for user root by (uid=0)
Jan 31 01:25:01 auditor kernel: audit: type=1006 audit(1548919501.573:118): pid=401 uid=0 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=14 res=1
Jan 31 01:25:01 auditor CROND[402]: (root) CMD (touch /root/cron.touch)
Jan 31 01:25:01 auditor CROND[401]: pam_unix(crond:session): session closed for user root

I'll just note that now it's not trying to log in as you, although it does seem to be spawning a separate (root) session to do its work in still.   This appears to be a change in your configuration, but I think we can cope with that.


Architecture: pentium4, Testing repos: Yes, Hardware: EeePC 901+2GB RAM+OS half on the SD card.

Offline

#9 2019-01-31 19:50:36

rossboulet
Member
Registered: 2017-12-13
Posts: 36

Re: getting many audit log entries from crond

levi wrote:

I'll just note that now it's not trying to log in as you, although it does seem to be spawning a separate (root) session to do its work in still.   This appears to be a change in your configuration, but I think we can cope with that.

Yes, for my test VMs I just set up the cron job as root for simplicity's sake. I built two VMs, one 64-bit and one 32-bit with just the base install to eliminate as many variables as possible. I did compare packages between the two and I see a few packages including the kernel version that have slightly different versions.

Packages with different versions:

< archlinux32-keyring-20190108-1
< ca-certificates-mozilla-3.41-1
> ca-certificates-mozilla-3.42-1
< device-mapper-2.02.183-1
> device-mapper-2.02.183-2
< glib2-2.58.2-1
> glib2-2.58.3-1
< libgpg-error-1.34-1
> libgpg-error-1.35-1
< libpipeline-1.5.0-1
> libpipeline-1.5.1-1
< libsasl-2.1.26-13
> libsasl-2.1.26-16
< libutil-linux-2.33.1-1
> libutil-linux-2.33.1-2
< linux-4.20.2.arch1-1
> linux-4.20.5.arch1-1
< linux-firmware-20181218.0f22c85-1
> linux-firmware-20190118.a8b75ca-1
< ncurses-6.1-4
> ncurses-6.1-6
< pacman-mirrorlist-20181003-1
> pacman-mirrorlist-20190109-1
< pcmciautils-018-8
< vim-8.1.0570-1
< vim-runtime-8.1.0570-1
> vim-8.1.0751-1
> vim-runtime-8.1.0751-1

Offline

Board footer

Powered by FluxBB