Bug 1615014

Harald,
Can you please provide relevant part of your configuration? Do not see this message with default config we ship...

Thanks

Also, can you please try using new WorkAroundJournalBug parameter[1] introduced by this update and see if it removes the messages for you?

[1] https://www.rsyslog.com/doc/v8-stable/configuration/modules/imjournal.html#workaroundjournalbug

[root@rh:~]$ cat rsyslog.conf
#### MODULES ####

$ModLoad imjournal
$MainMsgQueueSize 100000
$WorkDirectory /var/lib/rsyslog
$IMJournalStateFile imjournal.state

$ModLoad ommysql

#### GLOBAL DIRECTIVES ####

$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$MaxMessageSize 4096
global(parser.escapeControlCharactersOnReceive="off")

template(name="stdSQLformat" type="string" option.sql="on"
 string="insert into SystemEvents (DeviceReportedTime, FromHost, Message, SysLogTag) values ('%timereported:::date-mysql%', '%HOSTNAME%', '%msg%', '%syslogtag%')"
)

#### RULES ####

# iptables in seperated logfile
:msg, contains, "Firewall " -/var/log/firewall.log
& stop

# Ignored messages
:msg, contains, "Cannot add dependency job for unit proc-sys-fs-binfmt_misc.automount" stop
:msg, contains, "Forwarding to syslog missed" stop
:msg, contains, "HostIF_ReadUptime" stop
:msg, contains, "Group with unexpected replay counter" stop
:msg, contains, "smbd/service.c:942(make_connection_snum)" stop
:msg, contains, "Can't become connected user" stop
:msg, contains, "util_sock.c:1432(get_peer_addr_internal)" stop
:msg, contains, "getpeername failed. Error was Der Socket ist nicht verbunden" stop
:msg, contains, "read_fd_with_timeout: client 0.0.0.0 read error = Keine Route zum Zielrechner" stop
:msg, contains, "uid=0 from=<root>" stop
:msg, contains, "selinux sandbox not useful" stop
:msg, contains, "/etc/ssh/ssh_host_ecdsa_key" stop
:msg, contains, "Vacuuming done, freed" stop
:msg, contains, "interface=\"org.freedesktop.login1.Manager\" member=\"ReleaseSession\"" stop
:msg, contains, "automatic empty zone" stop
:msg, contains, "Failed to mark scope session" stop
:msg, contains, "Failed to open private bus connection" stop
:msg, contains, "colord.service" stop
:msg, contains, "upower.service" stop
:msg, contains, "Activating via systemd: service name='org.freedesktop.Avahi'" stop
:msg, contains, "Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service'" stop
:msg, contains, "dbus-protocol.c: Too many objects for client" stop
:msg, contains, "Failed at step CGROUP spawning /usr/lib/systemd/systemd" stop
:msg, contains, "Starting Letsencrypt-Updateservice" stop
:msg, contains, "Started Letsencrypt-Updateservice" stop

# unwanted desktop messages
:msg,contains,"WARNING **: Property get or set does not have an interface string as first arg" stop
:msg, contains, "CdSane-DEBUG" stop
:msg, contains, "HDMI hot plug event" stop
:msg, contains, "HDMI status" stop
:msg, contains, "Activating service name='org.freedesktop.PolicyKit1'" stop
:msg, contains, "Successfully activated service 'org.freedesktop.ConsoleKit'" stop
:msg, contains, "Activating service name='org.freedesktop.UPower'" stop
:msg, contains, "Successfully activated service 'org.freedesktop.UPower'" stop
:msg, contains, "Activating service name='org.freedesktop.UDisks'" stop
:msg, contains, "Successfully activated service 'org.freedesktop.UDisks'" stop
:msg, contains, "Activating via systemd: service name='org.freedesktop.RealtimeKit1'" stop
:msg, contains, "Successfully activated service 'org.freedesktop.RealtimeKit1'" stop
:msg, contains, "Successfully made thread" stop
:msg, contains, "Activating via systemd: service name='org.freedesktop.ColorManager'" stop
:msg, contains, "Successfully activated service 'org.freedesktop.ColorManager'" stop
:msg, contains, "Activating via systemd: service name='org.freedesktop.colord-sane'" stop
:msg, contains, "Successfully activated service 'org.freedesktop.colord-sane'" stop
:msg, contains, "CHECK POWER STATUS spins up disk" stop
:msg, contains, "CHECK POWER STATUS returned 129, not ATA compliant" stop
:msg, contains, "Reloading\." stop
:msg, contains, "received packet on bond0 with own address" stop
:msg, contains, "DHCPREQUEST on eth" stop
:msg, contains, "Process '/usr/sbin/crda' failed with exit code 251" stop

# unwanted desktop messages Fedora 22
:msg, contains, "ignoring: Unit dnf-makecache.timer is masked" stop
:msg, contains, "GLib-GIO-Message: Using the 'memory' GSettings backend" stop
:msg, contains, "dbus-org.freedesktop.NetworkManager.service" stop
:msg, contains, "kuiserver: removing jobview" stop
:msg, contains, "kuiserver: making async call" stop
:msg, contains, "kuiserver: adding job contact" stop
:msg, contains, "kuiserver: current pending calls" stop
:msg, contains, "kuiserver: no more async calls left" stop
:msg, contains, "kuiserver: making async terminate" stop
:msg, contains, "kuiserver: this was because a pending" stop
:msg, contains, "Your keyboard setup doesn't provide a key to use for meta" stop

# unwanted desktop messages Fedora 24
:programname, isequal, "plasmashell" stop
:programname, isequal, "kwin_x11" stop
:programname, isequal, "kscreenlocker_greet" stop
:programname, isequal, "kdeinit4" stop
:programname, isequal, "kdeinit5" stop
:programname, isequal, "ksmserver" stop
:msg, contains, "QXcbConnection: XCB error" stop
:msg, contains, "QObject::connect" stop
:msg, contains, "org.kde.plasma.taskmanager/contents/ui/ToolTipDelegate.qml" stop
:msg, contains, "QPainter::" stop
:msg, contains, "QPixmap::grabWidget" stop
:msg, contains, "QXcbClipboard: SelectionRequest" stop
:msg, contains, "Solid::Backends::UPower::UPowerManager::allDevices" stop

# unwanted desktop messages Fedora 25
:programname, isequal, "ksmserver-logout-greeter" stop
:programname, isequal, "krunner" stop
:programname, isequal, "kactivitymanagerd" stop
:programname, isequal, "kglobalaccel5" stop
:programname, isequal, "kaccess" stop
:msg, contains, "Connecting to deprecated signal QDBus" stop
:msg, contains, "QProcess: Destroyed while process" stop
:msg, contains, "User of KWidgetItemDelegate should not delete widgets" stop
:msg, contains, "kf5.kio.widgets: Tried to unregister a kio job that hasn" stop
:msg, contains, "Layout or DefaultLayout tag without the mandatory Merge tag inside" stop
:msg, contains, "QLayout: Cannot add a null widget" stop
:msg, contains, "QLayout: Attempting to add QLayout" stop
:msg, contains, "Trying to convert empty KLocalizedString to QString" stop
:msg, contains, "Cannot creat accessible child interface for object:  PlacesView" stop

# unwanted desktop messages Fedora 27
:msg, contains, "'hostapd': attribute type 213 has an invalid length" stop
:msg, contains, "Acquired the name org.freedesktop.UDisks2 on the system message bus" stop
:msg, contains, "Activating service name='ca.desrt.dconf'" stop
:msg, contains, "Activating service name='org.a11y.atspi.Registry'" stop
:msg, contains, "Activating service name='org.gnome.GConf'" stop
:msg, contains, "Activating service name='org.kde.ActivityManager'" stop
:msg, contains, "Activating service name='org.kde.KScreen'" stop
:msg, contains, "Activating service name='org.kde.kdeconnect'" stop
:msg, contains, "Activating service name='org.kde.kglobalaccel'" stop
:msg, contains, "Activating service name='org.kde.kuiserver'" stop
:msg, contains, "Activating service name='org.kde.kwalletd5' requested by" stop
:msg, contains, "Activating service name='org.kde.powerdevil.backlighthelper'" stop
:msg, contains, "Activating service name='org.kde.powerdevil.discretegpuhelper'" stop
:msg, contains, "Activating service name='org.kde.runners.baloo'" stop
:msg, contains, "Activating via systemd: service name='org.a11y.Bus' unit='at-spi-dbus-bus.service'" stop
:msg, contains, "Activating via systemd: service name='org.freedesktop.PolicyKit1'" stop
:msg, contains, "Activating via systemd: service name='org.freedesktop.UDisks2'" stop
:msg, contains, "Activating via systemd: service name='org.freedesktop.hostname1'" stop
:msg, contains, "Activating via systemd: service name='org.gtk.vfs.Daemon'" stop
:msg, contains, "Activating via systemd: service name='org.gtk.vfs.Metadata'" stop
:msg, contains, "Activating via systemd: service name='org.gtk.vfs.UDisks2VolumeMonitor'" stop
:msg, contains, "Cannot open file \"/root/.vmware/config\"" stop
:msg, contains, "Cannot open file \"/usr/lib/vmware/messages/de/vmware.vmsg\"" stop
:msg, contains, "Cannot open file \"/usr/lib/vmware/settings\"" stop
:msg, contains, "Gwenview can only apply color profile on RGB32" stop
:msg, contains, "Icon theme \"cantata\" not found" stop
:msg, contains, "Illegal icon group:" stop
:msg, contains, "No file found for \".xml\" , even though update-mime-info said it would exist" stop
:msg, contains, "Please fix the \"kio_kamera\" KIO slave" stop
:msg, contains, "Please fix the \"kio_mtp\" KIO slave" stop
:msg, contains, "QCoreApplication::postEvent: Unexpected null receiver" stop
:msg, contains, "QDBusConnection: name 'org.freedesktop.UDisks2' had owner" stop
:msg, contains, "QObject: Cannot create children for a parent that is in a different thread" stop
:msg, contains, "QObject: Timers cannot be stopped from another thread" stop
:msg, contains, "QObject::disconnect: Unexpected null parameter" stop
:msg, contains, "QObject::killTimer: Timers cannot be stopped from another thread" stop
:msg, contains, "QSocketNotifier: Can only be used with threads started with QThread" stop
:msg, contains, "Session management error: networkIdsList argument is NULL" stop
:msg, contains, "Started Accessibility services bus" stop
:msg, contains, "Started Hostname Service" stop
:msg, contains, "Started Virtual filesystem metadata service" stop
:msg, contains, "Started Virtual filesystem service - disk device monitor" stop
:msg, contains, "Started Virtual filesystem service" stop
:msg, contains, "Starting Accessibility services bus" stop
:msg, contains, "Starting Hostname Service" stop
:msg, contains, "Starting Virtual filesystem metadata service" stop
:msg, contains, "Starting Virtual filesystem servic" stop
:msg, contains, "Starting Virtual filesystem service - disk device monitor" stop
:msg, contains, "Successfully activated service 'ca.desrt.dconf'" stop
:msg, contains, "Successfully activated service 'org.a11y.Bus'" stop
:msg, contains, "Successfully activated service 'org.a11y.atspi.Registry'" stop
:msg, contains, "Successfully activated service 'org.freedesktop.PolicyKit1'" stop
:msg, contains, "Successfully activated service 'org.freedesktop.UDisks2'" stop
:msg, contains, "Successfully activated service 'org.freedesktop.hostname1'" stop
:msg, contains, "Successfully activated service 'org.gnome.GConf'" stop
:msg, contains, "Successfully activated service 'org.gtk.vfs.Daemon'" stop
:msg, contains, "Successfully activated service 'org.gtk.vfs.Metadata'" stop
:msg, contains, "Successfully activated service 'org.gtk.vfs.UDisks2VolumeMonitor'" stop
:msg, contains, "Successfully activated service 'org.kde.ActivityManager'" stop
:msg, contains, "Successfully activated service 'org.kde.KScreen'" stop
:msg, contains, "Successfully activated service 'org.kde.kdeconnect'" stop
:msg, contains, "Successfully activated service 'org.kde.kglobalaccel'" stop
:msg, contains, "Successfully activated service 'org.kde.kuiserver'" stop
:msg, contains, "Successfully activated service 'org.kde.kwalletd5'" stop
:msg, contains, "Successfully activated service 'org.kde.powerdevil.backlighthelper'" stop
:msg, contains, "Successfully activated service 'org.kde.powerdevil.discretegpuhelper'" stop
:msg, contains, "Successfully activated service 'org.kde.runners.baloo'" stop
:msg, contains, "TypeError: Cannot read property 'Layout' of null" stop
:msg, contains, "UDSEntry for '.' not found, creating a default one. Please fix the" stop
:msg, contains, "[origin software=\"rsyslogd\" swVersion=\"" stop
:msg, contains, "ark.kerfuffle: Could not find a plugin to handle" stop
:msg, contains, "ark.kerfuffle: Mimetype for filename extension" stop
:msg, contains, "ark.main: \"\" is not a supported mimetype" stop
:msg, contains, "ark.main: \"application/pdf\" is not a supported mimetype" stop
:msg, contains, "ark.main: \"application/x-php\" is not a supported mimetype" stop
:msg, contains, "daemon is running with well-known name - org.a11y.atspi.Registry" stop
:msg, contains, "error activating kdeconnectd: QDBusError" stop
:msg, contains, "imjournal: journal reloaded..." stop
:msg, contains, "is not really an animated image (only one frame)" stop
:msg, contains, "kf5.kded: No X-KDE-DBus-ServiceName found" stop
:msg, contains, "kf5.kio.core: Invalid URL: QUrl" stop
:msg, contains, "kf5.kio.widgets: No node found for item that was just removed" stop
:msg, contains, "kf5.kxmlgui: cannot find .rc file" stop
:msg, contains, "libpng warning: iCCP: known incorrect sRGB profile" stop
:msg, contains, "org.kde.dolphin: Ignore KIO url" stop
:msg, contains, "org.kde.kcoreaddons: Expected JSON property \"X-KDE-OnlyShowOnQtPlatforms\"" stop
:msg, contains, "org.kde.knotifications: warning: failed to connect to ActionInvoked dbus signal" stop
:msg, contains, "org.kde.knotifications: warning: failed to connect to NotificationClosed dbus signal" stop
:msg, contains, "powerdevil: Handle button events action could not check for screen configuration" stop
:msg, contains, "powerdevil: No outputs have backlight property" stop
:msg, contains, "powerdevil: The profile  \"AC\" tried to activate \"DimDisplay\"" stop
:msg, contains, "powerdevil: Xrandr not supported, trying ddc, helper" stop
:msg, contains, "powerdevil: [DDCutilBrightness] compiled without DDC/CI support" stop
:msg, contains, "powerdevil: no kernel backlight interface found" stop
:msg, contains, "powerdevil: org.kde.powerdevil.backlighthelper.brightness failed" stop
:msg, contains, "preferences file not found at /root/.vmware/config" stop
:msg, contains, "qt.accessibility.core: Cannot create accessible child interface for object" stop
:msg, contains, "set with QAction::setShortcut()! Use KActionCollection::setDefaultShortcut(s) instead" stop
:msg, contains, "setTrapReturnKey not supported with a non-KLineEdit" stop
:msg, contains, "using kwallet without parent window" stop
:msg, contains, "mimeType \"\" not found" stop
:msg, contains, "Activating service name='org.kde.kioexecd'" stop
:msg, contains, "Successfully activated service 'org.kde.kioexecd'" stop
:msg, contains, "Found no root index for QUrl(" stop
:msg, contains, "ark.kerfuffle: Detected existing file:" stop
:msg, contains, "org.kde.dolphin: could not find entry for charset" stop
:msg, contains, "QPixmap::scaled: Pixmap is a null pixmap" stop
:msg, contains, "Cannot initialize model with data QJsonObject" stop
:msg, contains, "UdevQt: unhandled device action \"bind\"" stop
:msg, contains, "QWidget::insertAction: Attempt to insert null action" stop
:msg, contains, "No text-to-speech plug-ins were found" stop
:msg, contains, "The X11 connection broke (error 1)" stop
:msg, contains, "kf5.kio.kio_file: \"Couldn't preserve group for" stop
:msg, contains, "kf5.kio.kio_file: \"Couldn't preserve access and modification time for" stop

# log dhcpd in own file
:programname, isequal, "dhcpd"                      -/var/log/dhcpd.log
:programname, isequal, "dhcpd" stop
:programname, isequal, "vmnet-dhcpd"                -/var/log/dhcpd.log
:programname, isequal, "vmnet-dhcpd" stop

# dracut messages not in /var/log/messages (F20)
:programname, isequal, "dracut"                     -/var/log/dracut.log
:programname, isequal, "dracut" stop

# log hostapd in own file
:programname, isequal, "hostapd"                    -/var/log/hostapd.log
:programname, isequal, "hostapd" stop

# log cups in own file
:programname, isequal, "cupsd"                      -/var/log/cups/access_log
:programname, isequal, "cupsd" stop

# do not log 'yum' in /var/log/yum.log AND /var/log/messages
:programname, isequal, "yum" stop

# drop most systemd-session-log and move remaining to /var/log/secure
if $programname == 'systemd' or $programname == 'systemd-logind' then {
 if $syslogseverity == 6 then {
  :msg, startswith, "Starting Session" stop
  :msg, startswith, "Started Session" stop
  :msg, startswith, "Stopping Session" stop
  :msg, startswith, "Stopped Session" stop
  :msg, startswith, "New session" stop
  :msg, startswith, "Removed session" stop
  :msg, startswith, "Starting Paths" stop
  :msg, startswith, "Reached target Paths" stop
  :msg, startswith, "Starting Timers" stop
  :msg, startswith, "Reached target Timers" stop
  :msg, startswith, "Starting Sockets" stop
  :msg, startswith, "Reached target Sockets" stop
  :msg, startswith, "Starting Basic System" stop
  :msg, startswith, "Reached target Basic System" stop
  :msg, startswith, "Starting Default" stop
  :msg, startswith, "Reached target Default" stop
  :msg, startswith, "Startup finished" stop
  :msg, startswith, "Stopping Default" stop
  :msg, startswith, "Stopped target Default" stop
  :msg, startswith, "Stopping Basic System" stop
  :msg, startswith, "Stopped target Basic System" stop
  :msg, startswith, "Stopping Paths" stop
  :msg, startswith, "Stopped target Paths" stop
  :msg, startswith, "Stopping Timers" stop
  :msg, startswith, "Stopped target Timers" stop
  :msg, startswith, "Stopping Sockets" stop
  :msg, startswith, "Stopped target Sockets" stop
  :msg, startswith, "Starting Shutdown" stop
  :msg, startswith, "Reached target Shutdown" stop
  :msg, startswith, "Starting Exit the Session" stop
  :msg, startswith, "Received SIGRTMIN" stop
  :msg, startswith, "Failed to abandon session scope" stop
  :msg, startswith, "Starting user-" stop
  :msg, startswith, "Created slice user-" stop
  :msg, startswith, "Starting User Manager for" stop
  :msg, startswith, "Started User Manager for" stop
  :msg, startswith, "Stopping User Manager for" stop
  :msg, startswith, "Stopped User Manager for" stop
  :msg, startswith, "Stopping user-" stop
  :msg, startswith, "Removed slice user-" stop
 }
 :programname, isequal, "systemd-logind" -/var/log/secure
 :programname, isequal, "systemd-logind" stop
}

# Include config snippets
$IncludeConfig /etc/rsyslog.d/

# Log anything (except mail) of level info or higher
# Don't log private authentication messages
*.info;mail.none;authpriv.none;cron.none            -/var/log/messages

# The authpriv file has restricted access
authpriv.*                                          -/var/log/secure

# Log all the mail messages in one place
mail.*                                              -/var/log/maillog

# Log cron stuff
cron.*                                              -/var/log/cron

# Everybody gets emergency messages
*.emerg                                             :omusrmsg:*

# Save news errors of crit in special file
uucp,news.crit                                      -/var/log/spooler

# Save boot messages also to boot.log
local7.*                                            -/var/log/boot.log

### DATABASE-LOGGING ###

$ActionQueueType LinkedList                         # use asynchronous processing
$ActionResumeRetryCount -1                          # infinite retries on insert failure
*.info;mail.none;authpriv.none;cron.none            action(type="ommysql" server="localhost" serverport="3306" db="dbmail" uid="vm_syslog" pwd="*****" template="stdSQLformat")
mail.*                                              action(type="ommysql" server="localhost" serverport="3306" db="dbmail" uid="vm_syslog" pwd="*****" template="stdSQLformat")

both don't work - if that needs to be written somehow different please don't throw random params where you need to study rsyslog into the game

$WorkAroundJournalBug on
$ImjournalWorkAroundJournalBug on

Aug 13 10:35:55 rh rsyslogd[28961]: invalid or yet-unknown config file command 'WorkAroundJournalBug' - have you forgotten to load a module? [v8.37.0 try http://www.rsyslog.com/e/3003 ]

Aug 13 10:38:13 rh rsyslogd[31182]: invalid or yet-unknown config file command 'ImjournalWorkAroundJournalBug' - have you forgotten to load a module? [v8.37.0 try http://www.rsyslog.com/e/3003 ]

most likely that happens everytime journald rotates

cat /etc/systemd/journald.conf
[Journal]
Storage=volatile
Compress=yes
RateLimitInterval=10s
RateLimitBurst=5000
RuntimeMaxUse=10M
ForwardToSyslog=no

Aug 10 23:00:01 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 11 05:01:01 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 11 10:45:01 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 11 16:35:01 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 11 23:00:01 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 12 05:00:01 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 12 11:00:01 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 12 16:45:01 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 12 20:00:33 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 12 22:00:12 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 13 00:02:01 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 13 02:49:34 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 13 05:01:02 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 13 07:35:02 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]
Aug 13 09:40:00 localhost rsyslogd[1808578]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.37.0]

(In reply to Harald Reindl from comment #4)
> both don't work - if that needs to be written somehow different please don't
> throw random params where you need to study rsyslog into the game
> 
> $WorkAroundJournalBug on
> $ImjournalWorkAroundJournalBug on
> 

Yes, they will not work this way. As stated in upstream doc this parameter (and some others) have obsolete legacy directive "none", meaning that if you want to use them you have to use new syntax for module loading (which is BTW recommended anyway).

So instead of 
$ModLoad imjournal
and
$IMJournalStateFile imjournal.state

try 
module(load="imjournal" StateFile="imjournal.state" WorkAroundJournalBug="on")

Thanks

module(load="imjournal" StateFile="imjournal.state" WorkAroundJournalBug="on")
seems to be a workaround - may i suggest set this as implicit default?

all the syntax changes from ~ to stop and so on are simply annoying BTW and that shiny URLs in the warnings most of the time lead to non existing pages or descriptions not really helpful to solve warnings

(In reply to Harald Reindl from comment #7)
> module(load="imjournal" StateFile="imjournal.state"
> WorkAroundJournalBug="on")
> seems to be a workaround - may i suggest set this as implicit default?
> 
May be, however this is really new code and I wanted to first verify how many users are actually impacted (need the workaround) and whether there actually is any performance impact (even after long upstream discussion we are not sure, need some real-world data first).

well, than please simply don't throw it to users of a GA release to begin with which are waiting F28 become stable enough for production servers and have way too much follout within a few days (see borked libssh update and so on)

You may very well help with that, if you have any bigger amount of data flowing from the journal to rsyslog can you measure any flow rate difference with(out) the switch?

Thanks.

not really, i try to minimize logging in general as you can see in my rsyslog.conf above and more difficult: i do not know how to write some test to measure, spit a ton of messages to the journal is easy, but benchmark such asynchron stuff?

(In reply to Harald Reindl from comment #11)
> not really, i try to minimize logging in general as you can see in my
> rsyslog.conf above 
then you are fine using a "workaround" which should net you more reliable journal logging, especially concerning possible duplicates and errors as ones in your initial report.

NOTABUG is simply wrong!

nothing has to spit the words "error" and "warn" to syslog at regular operations and developers/maintainers should start to read their syslogs and clean the mess

one should not need to apply workarounds manually or write such amount of exceptions to prevent get flooded by useless noise and any sane admin is looking for "warn", "fail" and "error" regulary and after every reboot of every machine

[root@rh:~]$ cat /scripts/system-errors.sh
#!/usr/bin/bash
dmesg -T | grep --color -i warn | grep -v 'Perf event create on CPU' | grep -v 'Hardware RNG Device' | grep -v 'TPM RNG Device' | grep -v 'Correctable Errors collector initialized' | grep -v 'error=format-security' | grep -v 'MHD_USE_THREAD_PER_CONNECTION'
grep --color -i warn /var/log/messages | grep -v 'Perf event create on CPU' | grep -v 'Hardware RNG Device' | grep -v 'TPM RNG Device' | grep -v 'Correctable Errors collector initialized' | grep -v 'error=format-security' | grep -v 'MHD_USE_THREAD_PER_CONNECTION'
dmesg -T | grep --color -i fail | grep -v 'BAR 13' | grep -v 'Perf event create on CPU' | grep -v 'Hardware RNG Device' | grep -v 'TPM RNG Device' | grep -v 'Correctable Errors collector initialized' | grep -v 'error=format-security' | grep -v 'MHD_USE_THREAD_PER_CONNECTION'
grep --color -i fail /var/log/messages | grep -v 'BAR 13' | grep -v 'Perf event create on CPU' | grep -v 'Hardware RNG Device' | grep -v 'TPM RNG Device' | grep -v 'Correctable Errors collector initialized' | grep -v 'error=format-security' | grep -v 'MHD_USE_THREAD_PER_CONNECTION'
dmesg -T | grep --color -i error | grep -v 'Perf event create on CPU' | grep -v 'Hardware RNG Device' | grep -v 'TPM RNG Device' | grep -v 'Correctable Errors collector initialized' | grep -v 'error=format-security' | grep -v 'MHD_USE_THREAD_PER_CONNECTION'
grep --color -i error /var/log/messages | grep -v 'Perf event create on CPU' | grep -v 'Hardware RNG Device' | grep -v 'TPM RNG Device' | grep -v 'Correctable Errors collector initialized' | grep -v 'error=format-security' | grep -v 'MHD_USE_THREAD_PER_CONNECTION'

Ok, if you wish I can leave it open and mark it resolved with the next batch of imjournal fixes, even when they will not target this problem specifically (although it should get the message go away).

I'm also seeing this bug on several servers with moderate to high log activity.
The only change from stock configuration is that imjournal is loaded this way:

module(load="imjournal" 	    # provides access to the systemd journal
       ratelimit.interval="0"
       ratelimit.burst="0"
       StateFile="imjournal.state") # File to store the position in the journal


I'll be trying WorkAroundJournalBug="on".

Seeing this Fedora 28, rsyslogd[4022]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.38.0]

and a whole lot of:
Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: journal reloaded... [v8.38.0 try http://www.rsyslog.com/e/0 ]
Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: journal reloaded... [v8.38.0 try http://www.rsyslog.com/e/0 ]
Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: loaded invalid cursor, seeking to the head of journal : Cannot assign requested address [v8.38.0 try http://www.rsyslog.com/
e/2027 ]
Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: journal reloaded... [v8.38.0 try http://www.rsyslog.com/e/0 ]
Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: sd_journal_next() failed: Bad message [v8.38.0]
Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: trying to recover from unexpected journal error [v8.38.0 try http://www.rsyslog.com/e/0 ]
Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: sd_journal_get_cursor() failed: Bad message [v8.38.0]

(In reply to RobbieTheK from comment #16)
> Seeing this Fedora 28, rsyslogd[4022]: imjournal: sd_journal_get_cursor()
> failed: Cannot assign requested address [v8.38.0]
> 
> and a whole lot of:
> Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: journal reloaded... [v8.38.0
> try http://www.rsyslog.com/e/0 ]
> Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: journal reloaded... [v8.38.0
> try http://www.rsyslog.com/e/0 ]
> Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: loaded invalid cursor,
> seeking to the head of journal : Cannot assign requested address [v8.38.0
> try http://www.rsyslog.com/
> e/2027 ]
> Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: journal reloaded... [v8.38.0
> try http://www.rsyslog.com/e/0 ]
> Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: sd_journal_next() failed: Bad
> message [v8.38.0]
> Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: trying to recover from
> unexpected journal error [v8.38.0 try http://www.rsyslog.com/e/0 ]
> Oct 29 10:51:44 dsm rsyslogd[4022]: imjournal: sd_journal_get_cursor()
> failed: Bad message [v8.38.0]

This particular issue (reloading multiple times per second despite journald not actually performing rotation) will be fixed with 8.39.0 rebase.

This message began appearing once-daily on (AWS) RHEL7 systems immediately after updating from RHEL 7.5 -> 7.6.

-----------------------------------------------------------------------
Nov  8 06:40:01 ip-10-196-16-116 rsyslogd: sd_journal_get_cursor() failed: 'Cannot assign requested address'  [v8.24.0-34.el7]
Nov  8 06:40:01 ip-10-196-16-116 rsyslogd: imjournal: journal reloaded... [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ]
-----------------------------------------------------------------------

NB: only the 'Cannot assign..' message is new. The imjournal message has been present for some time prior to updating.


A few system details -

# cat /etc/redhat-release 
Red Hat Enterprise Linux Server release 7.6 (Maipo)

......

# rpm -qa | grep -E 'rsyslog|systemd-[0-9]'
systemd-219-62.el7.x86_64
rsyslog-8.24.0-34.el7.x86_64

......

# cat /etc/rsyslog.conf 
$ModLoad imuxsock
$ModLoad imjournal
$ModLoad immark

$WorkDirectory /var/lib/rsyslog
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$IncludeConfig /etc/rsyslog.d/*.conf
$OmitLocalLogging on
$IMJournalStateFile imjournal.state
$FileCreateMode 0640

*.info;mail.none;authpriv.none;cron.none        /var/log/messages
authpriv.*                                      /var/log/secure
mail.*                                          -/var/log/maillog
cron.*                                          /var/log/cron
*.emerg                                         :omusrmsg:*
uucp,news.crit                                  /var/log/spooler
local7.*                                        /var/log/boot.log

(In reply to Philippe Troin from comment #15)
> I'll be trying WorkAroundJournalBug="on".

That didn't help, I'm still seeing:
imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.38.0]
even with WorkAroundJournalBug="on".

(In reply to Erik S. from comment #18)
> This message began appearing once-daily on (AWS) RHEL7 systems immediately
> after updating from RHEL 7.5 -> 7.6.
> 
> -----------------------------------------------------------------------
> Nov  8 06:40:01 ip-10-196-16-116 rsyslogd: sd_journal_get_cursor() failed:
> 'Cannot assign requested address'  [v8.24.0-34.el7]
> Nov  8 06:40:01 ip-10-196-16-116 rsyslogd: imjournal: journal reloaded...
> [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ]
> -----------------------------------------------------------------------
> 
> NB: only the 'Cannot assign..' message is new. The imjournal message has
> been present for some time prior to updating.
> 

Unless you are seeing any other symptoms (missing and/or duplicated messages etc) this is relatively normal, it is a result of journald returning error, the 'Cannot assign..' message message itself originates in systemd/journald, rsyslog only forwards it; the following 'reloaded' message is notifying you that imjournal detected error in journald and tried to fix it by re-initiating journal connection. By the way do you know of any daily-scheduled job on those boxes or underlying AWS involving time/date adjustments or general manipulation? From past reports this is usually the kind of thing which triggers said journald error.

Thanks

(In reply to Jiří Vymazal from comment #20)
> Unless you are seeing any other symptoms (missing and/or duplicated messages
> etc) this is relatively normal, it is a result of journald returning error..

That is good to know. The only symptom I've observed has been the sudden appearance of the message itself.


> By the way do you know of any
> daily-scheduled job on those boxes or underlying AWS involving time/date
> adjustments or general manipulation? From past reports this is usually the
> kind of thing which triggers said journald error.

Just now looked into this, and (with the exception of the recent switch from EDT -> EST timezone) I see no date/time manipulation occurring on the systems. The ntpd service is always running, but 'journalctl -u ntpd' shows no entries. There is nothing else running on via cron or anacron that should be messing with the time.

Upgraded Centos 7 last night. Ossec reporting this exact error on my system.

Name        : rsyslog
Arch        : x86_64
Version     : 8.24.0
Release     : 34.el7
Size        : 1.9 M
Repo        : installed
From repo   : base

Package updated from 8.24.0

-pid="1012" x-info="http://www.rsyslog.com"] exiting on signal 15.
Dec  4 21:26:39 nzmwtplc01 rsyslogd: [origin software="rsyslogd" swVersion="8.24.0" x-pid="59885" x-info="http://www.rsyslog.com"] start
Dec  4 21:26:39 nzmwtplc01 rsyslogd: rsyslogd's groupid changed to 4
Dec  4 21:33:35 nzmwtplc01 yum[53776]: Updated: rsyslog-8.24.0-34.el7.x86_64
Dec  4 21:36:32 nzmwtplc01 rsyslogd: imjournal: journal reloaded... [v8.24.0 try http://www.rsyslog.com/e/0 ]
Dec  4 21:36:32 nzmwtplc01 rsyslogd: imjournal: journal reloaded... [v8.24.0 try http://www.rsyslog.com/e/0 ]
Dec  4 21:38:40 nzmwtplc01 rsyslogd: [origin software="rsyslogd" swVersion="8.24.0" x-pid="59885" x-info="http://www.rsyslog.com"] exiting on signal 15.
Dec  4 21:38:40 nzmwtplc01 rsyslogd: [origin software="rsyslogd" swVersion="8.24.0-34.el7" x-pid="67353" x-info="http://www.rsyslog.com"] start
Dec  4 21:38:40 nzmwtplc01 rsyslogd: rsyslogd's groupid changed to 4

Behaviour starts shortly after.

Dec  4 21:39:23 nzmwtplc01 auditd: type=SERVICE_START msg=audit(1543912763.086:394344): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=rsyslog comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Dec  4 22:28:31 nzmwtplc01 rsyslogd: sd_journal_get_cursor() failed: 'Cannot assign requested address'  [v8.24.0-34.el7]
Dec  4 22:28:31 nzmwtplc01 rsyslogd: imjournal: journal reloaded... [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ]
Dec  4 23:27:11 nzmwtplc01 rsyslogd: sd_journal_get_cursor() failed: 'Cannot assign requested address'  [v8.24.0-34.el7]
Dec  4 23:27:11 nzmwtplc01 rsyslogd: imjournal: journal reloaded... [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ]


What changed between 8.24.0 and 34.el7?

(In reply to Andrew Hardy from comment #22)
> Upgraded Centos 7 last night. Ossec reporting this exact error on my system.

I can confirm the same exact issue. Upgraded from rsyslog-8.24.0-16.el7_5.4.x86_64 to rsyslog-8.24.0-34.el7.x86_64 and these errors started happening. The above mentioned workarounds causes syntax errors/do not work on CentOS 7.

(In reply to Danny from comment #23)
> ...
> The above mentioned workarounds causes syntax
> errors/do not work on CentOS 7.

As explained in Comment 6 the workaround is only usable with non-legacy syntax, are you using it?

module(load="imjournal" StateFile="imjournal.state" WorkAroundJournalBug="on")

but i still could puke about all the workariunds left and right as well as tabs in niecl formatted log messages are escaped while disable sanitize at all is a bad idea

(In reply to Jiří Vymazal from comment #24)
> As explained in Comment 6 the workaround is only usable with non-legacy
> syntax, are you using it?

Sorry yes, I should have mentioned I copied and pasted directly from Comment 6, restarted and get:

Dec  5 13:12:01 server rsyslogd: error during parsing file /etc/rsyslog.conf, on or before line 22: parameter 'WorkAroundJournalBug' not known -- typo in config file? [v8.24.0-34.el7 try http://www.
rsyslog.com/e/2207 ]
Dec  5 13:12:01 server rsyslogd: error during parsing file /etc/rsyslog.conf, on or before line 22: parameter 'StateFile' not known -- typo in config file? [v8.24.0-34.el7 try http://www.rsyslog.com
/e/2207 ]

Danny this is not true and it's annyoing that you simply don't post your config file so that opthers can seek your mistake instead pretend it does not work without any proof


[root@hosting:~]$ cat /etc/redhat-release
CentOS Linux release 7.6.1810 (Core)

[root@hosting:~]$ cat rsyslog.conf 
#### MODULES ####

$MainMsgQueueSize 100000
$WorkDirectory /var/lib/rsyslog

module(load="imjournal" StateFile="imjournal.state" WorkAroundJournalBug="on")

#### GLOBAL DIRECTIVES ####

$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$MaxMessageSize 4096

Harald sorry for annoying you. Here is the relevant config settings:

[root@server:~]$ cat /etc/centos-release
CentOS Linux release 7.6.1810 (Core)

[root@server:~]$ grep -vE '^.*#|^;|^$' /etc/rsyslog.conf
$WorkDirectory /var/lib/rsyslog
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$IncludeConfig /etc/rsyslog.d/*.conf
$OmitLocalLogging on
$IMJournalStateFile imjournal.state
module(load="imjournal" StateFile="imjournal.state" WorkAroundJournalBug="on")
*.info;mail.none;authpriv.none;cron.none                /var/log/messages
authpriv.*                                              /var/log/secure
mail.*                                                  -/var/log/maillog
cron.*                                                  /var/log/cron
*.emerg                                                 :omusrmsg:*
uucp,news.crit                                          /var/log/spooler
local7.*                                                /var/log/boot.log
*.* @@192.168.0.1:514

(In reply to Danny from comment #28)
> Harald sorry for annoying you. Here is the relevant config settings:
> 
> [root@server:~]$ cat /etc/centos-release
> CentOS Linux release 7.6.1810 (Core)
> 
> [root@server:~]$ grep -vE '^.*#|^;|^$' /etc/rsyslog.conf
> $WorkDirectory /var/lib/rsyslog
> $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
> $IncludeConfig /etc/rsyslog.d/*.conf
> $OmitLocalLogging on
> $IMJournalStateFile imjournal.state
> module(load="imjournal" StateFile="imjournal.state"
> WorkAroundJournalBug="on")
> *.info;mail.none;authpriv.none;cron.none                /var/log/messages
> authpriv.*                                              /var/log/secure
> mail.*                                                  -/var/log/maillog
> cron.*                                                  /var/log/cron
> *.emerg                                                 :omusrmsg:*
> uucp,news.crit                                          /var/log/spooler
> local7.*                                                /var/log/boot.log
> *.* @@192.168.0.1:514

Now you are both duplicating imjournal module settings and mixing legacy and current syntax, neither of which is supported by rsyslog.

why don't you just remove "$IMJournalStateFile imjournal.state" as common sense says anything relevent for "imjournal" is now in the new synatx line with it#s options?

(In reply to Harald Reindl from comment #30)
> why don't you just remove "$IMJournalStateFile imjournal.state" as common
> sense says anything relevent for "imjournal" is now in the new synatx line
> with it#s options?

My apologies for the lack of common sense. That is working as expected. Thank you for the help.

rsyslog-8.39.0-1.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-e9aff9e571

rsyslog-8.39.0-1.fc29 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2018-1cfc468f26

rsyslog-8.39.0-1.fc28 has been pushed to the Fedora 28 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-e9aff9e571

rsyslog-8.39.0-1.fc29 has been pushed to the Fedora 29 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-1cfc468f26

rsyslog-8.39.0-1.fc28 has been pushed to the Fedora 28 stable repository. If problems still persist, please make note of it in this bug report.

rsyslog-8.39.0-1.fc29 has been pushed to the Fedora 29 stable repository. If problems still persist, please make note of it in this bug report.

Still happening:

Dec 18 15:28:37 sys rsyslogd[29588]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.39.0]
Dec 18 15:28:37 sys rsyslogd[29588]: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]
Dec 19 06:18:12 sys rsyslogd[29588]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.39.0]
Dec 19 06:18:12 sys rsyslogd[29588]: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]

Here too:

imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.39.0]
PRIORITY	3
SYSLOG_FACILITY	5
SYSLOG_IDENTIFIER	rsyslogd


[root@maggie ~]# dnf list rsys*                                                                                                                                                                            
Last metadata expiration check: 3:08:53 ago on Wed 19 Dec 2018 10:59:02 CET.                                                                                                                               
Installed Packages                                                                                                                                                                                         
rsyslog.x86_64                                                                                           8.39.0-1.fc29                                                                             @updates

Same here with rsyslog-8.39.0-1.fc29.x86_64. Re-opening.

upstream PR has been merged

This message is a reminder that Fedora 28 is nearing its end of life.
On 2019-May-28 Fedora will stop maintaining and issuing updates for
Fedora 28. It is Fedora's policy to close all bug reports from releases
that are no longer maintained. At that time this bug will be closed as
EOL if it remains open with a Fedora 'version' of '28'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 28 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Although I'mm not the original reporter or the maintainer, just wanted to be sure it was noted that Fedora 29 still has this issue. Will be interesting to see if Fedora 30 is the same but I'm not ready to upgrade to that at the moment.

Nothing has changed rsyslog-8.39.0-3.fc30.x86_64
May 03 06:07:01 corsair.sunwire.eu rsyslogd[1153]: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.39.0]
May 03 06:07:01 corsair.sunwire.eu rsyslogd[1153]: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]
May 03 06:07:01 corsair.sunwire.eu rsyslogd[1153]: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]
May 03 06:07:01 corsair.sunwire.eu rsyslogd[1153]: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]
May 03 06:07:02 corsair.sunwire.eu rsyslogd[1153]: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]
May 03 06:07:02 corsair.sunwire.eu rsyslogd[1153]: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]
May 03 06:07:02 corsair.sunwire.eu rsyslogd[1153]: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]

This will be solved by rsyslog rebase

rsyslog-8.1904.0-1.fc30 has been submitted as an update to Fedora 30. https://bodhi.fedoraproject.org/updates/FEDORA-2019-8f4e1cea73

rsyslog-8.1904.0-1.fc29 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2019-bb8e71f461

rsyslog-8.1904.0-1.fc30 has been pushed to the Fedora 30 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2019-8f4e1cea73

rsyslog-8.1904.0-1.fc29 has been pushed to the Fedora 29 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2019-bb8e71f461

rsyslog-8.1904.0-1.fc30 has been pushed to the Fedora 30 stable repository. If problems still persist, please make note of it in this bug report.

rsyslog-8.1904.0-1.fc29 has been pushed to the Fedora 29 stable repository. If problems still persist, please make note of it in this bug report.