How to use logger command on Sierra?

Question

I'm trying to log events/check-points from my shell-script using logger.

How to use logger or syslog utility in OS X (version 10.12 (16A323)). I have tried

logger "Hello world" and checked /var/log/system.log using Console app, the following was the log entry created

Failed to harvest strings for binary named '–Xó^H'

How to use logger in OS X ? Is there anything to be specified to create/add an entry to OS X system log ?

Answer 1

Because Apple's logging system changed in macOS sierra. They are moving from the Apple System Log facility to unified logging.

Here's a link to the developer documentation.

The following filters the new unified log for text "Message4me"

$logger -is -t LogTest "Message4Me" 
Oct 15 13:19:27  LogTest[51173] <Notice>: Message4Me

$log show --predicate 'eventMessage contains "Message4Me"' --last 3m

Skipping info and debug messages, pass --info and/or --debug to include.
Filtering the log data using "eventMessage CONTAINS "Message4Me""
Timestamp                       Thread     Type        Activity             PID    
2016-10-15 13:19:27.666574+0900 0x33b62c   Default     0x0                  51173  logger: Message4Me
 --------------------------------------------------------------------------------------------------------------------
Log      - Default:          1, Info:                0, Debug:             0, Error:          0, Fault:          0

=======

If you add --info you will see the event message itself in the output as well.

In the previous OS versions the logger command would send to the /var/log/system.log file if the priority was high enough (e.g. using -p alert) as well as to the syslog database. In Sierra the system.log is not written to when logger is used with -p alert -not in 10.12.1 anyway. This could be a bug.

You can still use logger to send to he new logging system, but will have to use the Console app or the cli log utility or the new API to see the results.

Answer 2

To expand on the answer provided by @japanese and @arno-van-wyk...

macOS Unified Logging

The following is current as of 10.15.4. Knowing Apple it'll be wrong come 10.16.

Apple rejigged macOS' logging system in 10.12 (Sierra), replacing traditional syslog style service with a new "unified logging system". This new system, which has no formal name other than "unified logging system" (or os_log in the system man pages), has a number of goals - primarily aimed at app debugging rather than sysadmin. The sheer volume of log messages being generated under this regime is astounding.

Good overview: https://eclecticlight.co/2018/03/19/macos-unified-log-1-why-what-and-how/

Practically, this means that log events are generally not viewable in any file, e.g. /var/log/system.log, or even the Console app. Rather, the cli log utility must be used; or one of the apps provided by eclecticlight.co, above.

Generating Log Messages

As of 10.15, the traditional syslog interface seems to still be functional. e.g. logger works.

os_log has multiple levels, including Default, Info, Debug, and some others. syslog levels seem to be mapped to the these: evidently debug > Debug, info > Info, all others to Default.

Viewing Log Messages

• use the log command, ref the man page for details; useful sub-commands:

  • show: query logs
    • --info and/or --debug to see info/debug level logs; need to provide both to get both
    • --last time[h|m|d]: show recent events, sec/min/hrs/days
  • stream: tail logs
    • --level info|debug to see info messages; debug includes info
    • can provide --process (pid|name) to filter a specific process name (shortcut for --predicate "process ...")
  • note: sub-commands vary in how the log level is provided and support for process name (yay consistency...)

• output can be in a few different formats, including:

  • --style compact: briefest: timestamp (sans TZ), abbreviated Type (e.g. Df = Default, I = Info, Db = Debug), process name and PID:ThreadID, and the log message
  • --style syslog: traditional syslog
  • JSON and JSON lines (JSONL aka NDJSON) formats
  • as well as the default comprehensive "human readable" form

• a "filter" mechanism is provided - and practically required - to extract the desired logs: --predicate [filter]

  • a filter is one or more patterns of the form "[key] [operator] [value]", e.g. process == "logger"
    • string operators are case- and diacratic- sensitive by default, append [cd] to make insensitive
  • useful keys are
    • process: process name
    • eventMessage: message content
    • logType: default, info, debug, etc
  • useful operators are
    • ==/BEGINSWITH: anchored string match (==[cd] for case-insensitive string comparison)
    • MATCHES: regex ("ICU Regular Expressions")
      • regexes are anchored start and end, i.e. MATCHES "Foo" will not match "Foo was here", whereas MATCHES "Foo.*" will; MATCHES[cd] "foo.*" will also hit
      • take care to escape \ from the shell

Examples

Everything logged by logger in the last 20 minutes:

% for sev in alert error warning notice info debug; do
  logger -p user.$sev "log test user.$sev"
done

% log show --style compact --info --debug --predicate 'process == "logger"' --last 20m
Filtering the log data using "process == "logger""
Timestamp               Ty Process[PID:TID]
2020-05-22 21:06:05.697 Df logger[52036:f75d81] log test user.alert
2020-05-22 21:06:06.709 Df logger[52038:f75d8b] log test user.error
2020-05-22 21:06:07.721 Df logger[52040:f75d95] log test user.warning
2020-05-22 21:06:08.732 Df logger[52042:f75dad] log test user.notice
2020-05-22 21:06:09.741 I  logger[52044:f75db7] log test user.info
2020-05-22 21:06:10.752 Db logger[52046:f75dbc] log test user.debug

Every log message in the last 24 hours matching the regex .*log\s+test.*er.*

% log show --style compact --info  --debug --predicate 'eventMessage MATCHES[cd] ".*log\\s+test.*er.*"' --last 24h
...

Continual stream of logger logs:

% log stream --process logger --level debug --style syslog
Filtering the log data using "process BEGINSWITH[cd] "logger""
Timestamp                       (process)[PID]
2020-05-22 21:16:16.593184+1000  localhost logger[52341]: log test user.alert
2020-05-22 21:16:16.599099+1000  localhost logger[52342]: log test user.error
2020-05-22 21:16:16.604287+1000  localhost logger[52343]: log test user.warning
2020-05-22 21:16:16.608727+1000  localhost logger[52344]: log test user.notice
2020-05-22 21:16:16.613164+1000  localhost logger[52345]: log test user.info
2020-05-22 21:16:16.617368+1000  localhost logger[52346]: log test user.debug
...

Answer 3

I solved this issue by having a script that uses netcat to send specific logs every 10min from a launchdaemon. Edit as needed.

#!/bin/bash

while read line    
do
    #drop log entries in the log file you don't want to sent to syslog server
   if [[ "$line" =~ ^.*recurring\ check-in.* || "$line" =~ ^.*Executing\ Policy\ Update\ Inventory.* ]]; then
     /bin/echo "" > /dev/null;
   else
     ## send logs to syslog server using netcat. Edit IP and UDP port as necessary
     echo $line | nc -v -u -w 0 10.10.1.9 514
   fi
done < /var/log/system.log

Answer 4

This is no real answer but a workaround and too long for a comment.

I faced the same problem in Sierra trying to log a homebrew update shell script including logger commands (which worked in El Capitan). I had to abandon logger and simply used echo, output redirection and a new log file:

#!/bin/bash

Brew=/usr/local/bin/brew
Brewup_Log=/Users/user/Library/Logs/brewup.log

echo "$(date "+%Y.%m.%d %H:%M:%S")" >> $Brewup_Log 2>&1
$Brew update 2>&1 >>$Brewup_Log
....