LINUX-22 SYSTEM LOGGING (RHEL-7) (PART-5)

LINUX-22 SYSTEM LOGGING (RHEL-7)

                            (PART-5)

RHEL7 SYSTEM LOGGING-P1
RHEL7 SYSTEM LOGGING-P2
RHEL7 SYSTEM LOGGING-P3
RHEL7 SYSTEM LOGGING-P4
RHEL7 SYSTEM LOGGING-P5
RHEL7 SYSTEM LOGGING-P6

                     --------JOURNAL-1--------

Syslog is working fine for log collection/movement/rotation; simply it is taking care of system logs by all manners.

But we have a new service for logs called “JOURNALCTL” which is managed by “SYSTEMD-JOURNALD” daemon. Obviously this new service is part of “SYSTEMD”.

What “systemd-journald” is doing for us?

·         Kernel and daemon process log management.

·         Collecting alerts generated during boot.

·         Syslog and initial ram disk messages management.

·         Log messages are stored in “binary” format in a file called “journals”.

·         To view journal logs we need to use “Journalctl” command.

·         Journalctl is getting/collecting log info from journald.

·         Located under /run/log/journal

·         By default it is not enabled.

·         It collects information from different sources and loads the messages in the journal.

·         Journal started before mounting of file systems.

Well, now we know at least what system-journald is.

Ok, but why “Journalctl” is required…??

Do we have any problem with existing log management…?

No… world is running excellent without Journalctl.

Is it…??

Ask a system admin, how he/she feel while troubleshooting. For everything we have a separate log file, with might be separate time stamp if log rotation is enabled. Check all then correlate all, just it!!!

Really world is running excellent!!!, because nobody has nothing to do with pain of a system admin, I don’t know about the rest of technicality but this one is major favor for sys admin that somebody arrived like angel to collect all system and application level logs at one location.

We will see later that how “journalctl” makes our life easier.

Ok, move ahead…

I think there is one point which must be noticed…

·         Located under /run/log/journal

Why under /run…?

As per theory we know that the /run is a virtual file system, its life span begins with system booting, remains during system up and axed at the time of system shut.

Means whatever inside this path will remain till system is up and wipe out as system reboot.

Ohhh… it seems that journal logs are not persistent.

Can we store it permanently…?

First look the “system-journald” service status.

[root@rhel7-client /]# systemctl status systemd-journald

systemd-journald.service - Journal Service

   Loaded: loaded (/usr/lib/systemd/system/systemd-journald.service; static)

   Active: active (running) since Fri 2017-01-20 14:07:41 IST; 1h 23min ago

     Docs: man:systemd-journald.service(8)

           man:journald.conf(5)

 Main PID: 433 (systemd-journal)

   Status: "Processing requests..."

   CGroup: /system.slice/systemd-journald.service

           └─433 /usr/lib/systemd/systemd-journald

Jan 20 14:07:42 rhel7-client systemd-journal[433]: Runtime journal is using 6.1M (max 49.5M, leaving 74.3M of free 489.1M, cu...9.5M).

Jan 20 14:07:42 rhel7-client systemd-journal[433]: Runtime journal is using 6.1M (max 49.5M, leaving 74.3M of free 489.1M, cu...9.5M).

Jan 20 14:07:42 rhel7-client systemd-journal[433]: Journal started

Jan 20 14:07:50 rhel7-client systemd-journal[433]: Runtime journal is using 6.1M (max 49.5M, leaving 74.3M of free 488.3M, cu...9.5M).

Hint: Some lines were ellipsized, use -l to show in full.

It is running; now check its log storage location.

[root@rhel7-client ~]# ls -ltr  /run/log/journal

total 0

drwxr-sr-x. 2 root systemd-journal 80 Jan 21 00:33 7d3eade1a0b140cca61f2d12bd64b4d0

[root@rhel7-client ~]# ls -ltr/run/log/journal/7d3eade1a0b140cca61f2d12bd64b4d0/

total 12688

-rw-r-----. 1 root root            6496256 Jan 21 00:33 system@689c624c67f041e38cebbf6a00910bf0-0000000000000001-000546828f6ec592.journal

-rw-r-----. 1 root systemd-journal 6496256 Jan 21 05:49 system.journal

Hmmm… interesting,

Can I use both “rsyslogd” as well as “journald”…??

Obviously, YES…

The systemd journal can either be used with an existing syslog implementation, or it can replace the syslog functionality.

Now time to see, how journald is helping us…

Simple command “Journalctl” and it will display all logs since last boot.

[root@rhel7-client ~]# journalctl

-- Logs begin at Fri 2017-01-20 14:07:29 IST, end at Sat 2017-01-21 11:06:57 IST. --

Jan 20 14:07:29 rhel7-test2 systemd-journal[143]: Runtime journal is using 6.1M (max 49.5M, leaving 74.3M of free 489.1M, current limi

Jan 20 14:07:29 rhel7-test2 systemd-journal[143]: Runtime journal is using 6.1M (max 49.5M, leaving 74.3M of free 489.1M, current limi

Jan 20 14:07:29 rhel7-test2 kernel: Initializing cgroup subsys cpuset

Jan 20 14:07:29 rhel7-test2 kernel: Initializing cgroup subsys cpu

Jan 20 14:07:29 rhel7-test2 kernel: Initializing cgroup subsys cpuacct

Jan 20 14:07:29 rhel7-test2 kernel: Linux version 3.10.0-121.el7.x86_64

============blah===blah======blah=======blah=========blah========blah=======

Jan 21 11:06:56 rhel7-client root[18579]: root [18069]: vi /etc/rsyslog.conf [0]

Jan 21 11:06:56 rhel7-client root[18585]: root [18069]: vi /etc/rsyslog.conf [0]

Jan 21 11:06:57 rhel7-client root[18591]: root [18069]: vi /etc/rsyslog.conf [0]

Jan 21 11:06:57 rhel7-client root[18597]: root [18069]: vi /etc/rsyslog.conf [0]

Jan 21 11:06:57 rhel7-client root[18603]: root [18069]: vi /etc/rsyslog.conf [0]

Jan 21 11:07:01 rhel7-client systemd[1]: Created slice user-1002.slice.

Jan 21 11:07:01 rhel7-client systemd[1]: Starting Session 662 of user user1.

Jan 21 11:07:01 rhel7-client systemd[1]: Started Session 662 of user user1.

Jan 21 11:07:01 rhel7-client CROND[18608]: (user1) CMD (/usr/bin/ping -c 3 192.168.234.143 >> /tmp/etc_cron_d)

[root@rhel7-client ~]# journalctl |wc -l

5709  çç  Too many logs…

[root@rhel7-client ~]# reboot

login as: root

root@192.168.234.142's password:

Last login: Sat Jan 21 10:43:44 2017 from 192.168.234.1

[root@rhel7-client ~]# journalctl |wc -l

2289 çç Logs should increase, but here why the count is reduced…?

Remember “it runs from last reboot”

[root@rhel7-client ~]# journalctl

-- Logs begin at Sat 2017-01-21 11:10:38 IST, end at Sat 2017-01-21 11:30:01 IST. --

Jan 21 11:10:38 rhel7-test2 systemd-journal[143]: Runtime journal is using 6.1M (max 49.5M, leaving 74.3M of free 489.1M, current limi

Jan 21 11:10:38 rhel7-test2 systemd-journal[143]: Runtime journal is using 6.1M (max 49.5M, leaving 74.3M of free 489.1M, current limi

Jan 21 11:10:38 rhel7-test2 kernel: Initializing cgroup subsys cpuset

Jan 21 11:10:38 rhel7-test2 kernel: Initializing cgroup subsys cpu

Jan 21 11:10:38 rhel7-test2 kernel: Initializing cgroup subsys cpuacct

Jan 21 11:10:38 rhel7-test2 kernel: Linux version 3.10.0-121.el7.x86_64 (mockbuild@x86-021.build.eng.bos.redhat.com) (gcc version 4.8.

Jan 21 11:10:38 rhel7-test2 kernel: Command line: BOOT_IMAGE=/vmlinuz-3.10.0-121.el7.x86_64 root=UUID=3e83a294-acf9-4b89-8e05-0bfde05b

Jan 21 11:10:38 rhel7-test2 kernel: Disabled fast string operations

============blah===blah======blah=======blah=========blah========blah=======

Jan 21 11:33:01 rhel7-client systemd[1]: Created slice user-1002.slice.

Jan 21 11:33:01 rhel7-client systemd[1]: Starting Session 26 of user user1.

Jan 21 11:33:01 rhel7-client systemd[1]: Started Session 26 of user user1.

Jan 21 11:33:01 rhel7-client CROND[2191]: (user1) CMD (/usr/bin/ping -c 3 192.168.234.143 >> /tmp/etc_cron_d)

Great…

But while scrolling the logs I had seen few things that should be in notice,

Few logs are in Bold and few are in Red…

Bifurcation of logs…??? Is it true, that journald is doing this for us…??

Yes…

Priority level “err” & “crit” are in BOLD

Priority level “alert” & “emerg” are in RED

But isn’t it good if we get only the required logs instead of flood.

Here we go…

Find the logs with particular priority level.

[root@rhel7-client ~]# journalctl -p err

[root@rhel7-client ~]# journalctl -p crit

Superb… but … but … still it is too long,

Isn’t it possible to have some more concise log…?

This is too much… J …let’s cut it short by (--since=today)

[root@rhel7-client ~]# journalctl --since=today -p warning

-- Logs begin at Sat 2017-01-21 11:10:38 IST, end at Sun 2017-01-22 03:34:23 IST. –

[root@rhel7-client ~]# journalctl --since=today -p err

-- Logs begin at Sat 2017-01-21 11:10:38 IST, end at Sun 2017-01-22 03:34:32 IST. –

[root@rhel7-client ~]# journalctl --since=today -p info

-- Logs begin at Sat 2017-01-21 11:10:38 IST, end at Sun 2017-01-22 03:34:40 IST. --

Jan 22 00:00:01 rhel7-client systemd[1]: Starting Session 69 of user root.

Jan 22 00:00:01 rhel7-client systemd[1]: Started Session 69 of user root.

Jan 22 00:00:01 rhel7-client systemd[1]: Created slice user-1002.slice.

Jan 22 00:00:01 rhel7-client systemd[1]: Starting Session 70 of user user1.

Jan 22 00:00:01 rhel7-client systemd[1]: Started Session 70 of user user1.

Jan 22 00:00:02 rhel7-client CROND[3706]: (root) CMD (/usr/lib64/sa/sa1 1 1)

Jan 22 00:00:02 rhel7-client CROND[3707]: (user1) CMD (/usr/bin/ping -c 3 192.168.234.143 >> /tmp/etc_cron_d)

Jan 22 00:01:01 rhel7-client systemd[1]: Starting Session 71 of user root.

Jan 22 00:01:01 rhel7-client systemd[1]: Started Session 71 of user root.

=========================O/P REMOVED======================================

Happy…??

WHAT…??????

Still it is long!!  L

Now this is height of demanding… He He He J

Let’s check what we can do for you…

[root@rhel7-client ~]# date

Sun Jan 22 10:03:57 IST 2017

[root@rhel7-client ~]# journalctl --since "8:00" --until "9:30"

-- Logs begin at Sat 2017-01-21 11:10:38 IST, end at Sun 2017-01-22 10:04:01 IST. --

Jan 22 09:21:03 rhel7-client systemd[1]: Time has been changed

Jan 22 09:21:03 rhel7-client kernel: e1000: ens37 NIC Link is Down

Jan 22 09:21:03 rhel7-client kernel: e1000: ens38 NIC Link is Down

Jan 22 09:21:03 rhel7-client kernel: e1000: ens39 NIC Link is Down

Jan 22 09:21:03 rhel7-client kernel: e1000: ens33 NIC Link is Down

Jan 22 09:21:03 rhel7-client NetworkManager[662]: <info> (ens37): link disconnected

Jan 22 09:21:04 rhel7-client NetworkManager[662]: <info> (ens38): link disconnected

That was final, Now Happy…?

What…??

Still you are not satisfied…?

Ok, but mark this one final, after that I will not ask about your satisfaction.

L

[root@rhel7-client ~]# journalctl -r --since "8:00" --until "9:30"

-- Logs begin at Sat 2017-01-21 11:10:38 IST, end at Sun 2017-01-22 10:08:16 IST. --

Jan 22 09:29:01 rhel7-client CROND[11246]: (user1) CMD (/usr/bin/ping -c 3 192.168.234.143 >> /tmp/etc_cron_d)

Jan 22 09:29:01 rhel7-client systemd[1]: Started Session 268 of user user1.

Jan 22 09:29:01 rhel7-client systemd[1]: Starting Session 268 of user user1.

Jan 22 09:29:01 rhel7-client systemd[1]: Created slice user-1002.slice.

Jan 22 09:28:01 rhel7-client CROND[11210]: (user1) CMD (/usr/bin/ping -c 3 192.168.234.143 >> /tmp/etc_cron_d)

Wow… that was superb, but I am unable to understand the meaning of logs, what they are trying to say…??

It is your luck that you are not in front of me… L

Now I want the logs in detail,

[root@rhel7-client ~]# journalctl -r -o verbose

-- Logs begin at Sat 2017-01-21 11:10:38 IST, end at Sun 2017-01-22 10:49:39 IST. --

Sun 2017-01-22 10:49:39.861056 IST [s=36bc0b8f934d4b3db0742f5df2234779;i=100f;b=5d257f7a38c44886ace791060fbbf172;m=4549a67

    _TRANSPORT=syslog

    _UID=0

    _GID=0

    _CAP_EFFECTIVE=1fffffffff

    _AUDIT_LOGINUID=0

    _BOOT_ID=5d257f7a38c44886ace791060fbbf172

    _MACHINE_ID=7d3eade1a0b140cca61f2d12bd64b4d0

    _HOSTNAME=rhel7-client

    _SYSTEMD_CGROUP=/

    PRIORITY=7

    SYSLOG_FACILITY=22

    SYSLOG_IDENTIFIER=root

    _COMM=logger

    _SELINUX_CONTEXT=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023

    _AUDIT_SESSION=263

    MESSAGE=root [11030]: journalctl -o [1]

    _PID=14469

    _SOURCE_REALTIME_TIMESTAMP=1485062379861056

Let’s apply some flags…..

-k:            Kernel message

-b:            Display logs from current boot only

-u:            Filter logs by specific systemd unit      

-f:            Shows the most recent journal messages (like tail –f)

-e:            Print the logs and jump to last to view latest logs

-r:            Prints the messages of the journal in reverse order

               so that latest logs are viewed first.

-o:            Change journal output mode (short, short-iso,

               short-precise, short-monotonic, verbose,

               export, json, json-pretty, json-sse, cat)

-n <no>:       Number of journal entries to show

--system:      Show only the system journal

--user:        Show only the user journal for the current user

--since:       Filter logs from

--until:       Filter logs till

-p <priority>: Priority

Absolute-path: Filtering based on file path locations.

--no-pager     Do not pipe output into a pager, can be used for text

               processing

_PID/UID/GID=<pid/uid/gid>:   Filter logs based on fields like PID/UID/GID

for more info on fields refer,

[root@rhel7-client /]# man systemd.journal-fields

“:” is not the part of command.

Consider examples for all,

# journalctl –k                                       [kernel logs]

# journalctl –b                                       [boot logs]

# journalctl -u abrt-vmcore.service                   [logs by unit]

# journalctl -u systemd-ask-password-console.path     [logs by unit]

# journalctl -u tdir1.mount                           [logs by unit]

# journalctl -u crond.service -u sshd                 [logs by unit]

From where to get system units…?

# journalctl -F _SYSTEMD_UNIT

# systemctl list-unit-files                           [list system units]

# systemctl list-units –all                           [list system units]

# systemctl list-units --all --state=active     [list active system units]

# systemctl list-units --type=service                 [list system units]

# journalctl –f                                       [live logs]

# journalctl –e                                      [jump to latest logs]

# journalctl –r                                   [first show the latest]

# journalctl –o verbose                               [detailed logs]

# journalctl –n 20                                    [no of pages]

# journalctl –-system                                 [only system logs]

Regular user can also view, if there are generated by them any

[user1@rhel7-client ~]$ journalctl –user              [user logs]

# journalctl --since 2017-01-22                       [filtered logs]

Date format=YYYY-MM-DD

# journalctl --since "2017-01-22 10:30"               [filtered logs]

Time format=HH:MM

# journalctl -r --since "2017-01-22 10:30"            [filtered logs]

# journalctl -r -o verbose --since "2017-01-22 11:00" [filtered logs]

# journalctl -r -o verbose --since "2017-01-22 11:00" -n 2 [filtered logs]

# journalctl -r -o cat -n 5             [check it with –r or without –r]

# journalctl -r -o short -n 5             [for old syslog style format]

# journalctl --until 2017-01-22                 [filtered logs]

# journalctl --until "2017-01-22 11:10"         [filtered logs]

# journalctl --since "2017-01-22 10:30" --until "2017-01-22 11:10"

# journalctl --since "2017-01-22 10:30" --until "2017-01-22 11:10" -p info -n 5

# journalctl --until=today –p warn              [filtered logs]        

# journalctl --until=yesterday                  [filtered logs]

# journalctl --until=tomorrow                   [filtered logs]

# journalctl --since=tomorrow                   [filtered logs]

# journalctl --since=yesterday                  [filtered logs]

# journalctl --since=today                      [filtered logs]

# journalctl -u sshd --since=today -b -o verbose -n 4 [filtered & formatted logs]

# journalctl --since 10:00 --until "1 hour ago" [filtered & formatted logs]

If current time is 12:10, then the above command will display logs from 9:00 to 11:10

# journalctl -r -p err -n 5               [recursive with priority]

0: emerg
1: alert
2: crit
3: err
4: warning
5: notice
6: info

7: debug


# journalctl -u cron -p info          [filter by priority & unit]

# journalctl -u crond -p debug        [filter by priority & unit]

# journalctl -p err –b                    [filter by priority]

# journalctl _UID=1002                    [filter by user id]

# journalctl _GID=5001                    [filter by group id]

# journalctl _PID=28                      [filter by process id]

Which group/user IDs the systemd journal has entries for,

# journalctl -F _GID

# journalctl -F _PID

# journalctl /sbin/crond                  [filter by service path]

# journalctl /sbin/sshd                   [filter by service path]

# journalctl /dev/sdb

# journalctl --no-pager                   [show all in one go]

# journalctl --no-pager |grep -i err      [applied text processing]

# journalctl --disk-usage             [space occupied by journal on disk]

Journals take up 12.3M on disk.

TO BE CONTINUED…………………………………………