Re: [systemd-devel] systemd-journald missing crash logs

[林自均]

Hi Farzad,

It seems that you missed Lennart's comments? It's here:
https://lists.freedesktop.org/archives/systemd-devel/2018-January/040162.html

John

Farzad Panahi  於 2018年1月20日 週六 05:52 寫道：

> Hey guys. I really appreciate any comment on this issue. Please let me
> know if this question does not belong to this mailing list.
>
> On Fri, Jan 12, 2018 at 4:13 PM, Farzad Panahi 
> wrote:
>
>> I am running Arch-ARM on RPi3. I have noticed when system crashes I
>> cannot find any related crash log in journal logs.
>>
>> Arch Linux ARM on RPi3: `Linux 4.4.37-1-ARCH #1 SMP armv7l GNU/Linux`
>>
>> Systemd: `systemd 232`
>>
>> `/etc/systemd/journald.conf`:
>>
>>
>> [Journal]
>> Storage=persistent
>> Compress=yes
>> #Seal=yes
>> #SplitMode=uid
>> SyncIntervalSec=1
>> #RateLimitIntervalSec=30s
>> #RateLimitBurst=1000
>> SystemMaxUse=1.5G
>> #SystemKeepFree=
>> #SystemMaxFileSize=
>> #SystemMaxFiles=100
>> #RuntimeMaxUse=
>> #RuntimeKeepFree=
>> #RuntimeMaxFileSize=
>> #RuntimeMaxFiles=100
>> MaxRetentionSec=1month
>> MaxFileSec=3hour
>> #ForwardToSyslog=no
>> #ForwardToKMsg=no
>> #ForwardToConsole=no
>> #ForwardToWall=yes
>> #TTYPath=/dev/console
>> #MaxLevelStore=debug
>> #MaxLevelSyslog=debug
>> #MaxLevelKMsg=notice
>> #MaxLevelConsole=info
>> #MaxLevelWall=emerg
>>
>> Recent crash log:
>>
>> Dec 29 03:43:48 sudo[21861]:  my_user : TTY=unknown ;
>> PWD=/opt/my_app/repo/src ; USER=root ; COMMAND=/usr/sbin/hciconfig hci0
>> reset
>> Dec 29 03:43:48 sudo[21861]: pam_unix(sudo:session): session opened
>> for user root by (uid=0)
>> Dec 29 03:43:48 sudo[21861]: pam_unix(sudo:session): session closed
>> for user root
>> Dec 29 03:43:48 my_app.py[17773]: trying to connect to
>> XX:XX:XX:XX:XX:XX
>> Dec 29 03:43:48 systemd-udevd[21865]: Process '/bin/hciconfig hci0:64
>> up' failed with exit code 1.
>> Dec 29 03:43:51 my_app.py[17773]: connection successful :)
>> -- Reboot --
>> Jan 03 16:31:25 systemd[1]: Time has been changed
>> Jan 03 16:31:26 dhcpcd[470]: forked to background, child pid 587
>> Jan 03 16:31:25 systemd-timesyncd[360]: Synchronized to time server
>> 206.108.0.133:123 (2.arch.pool.ntp.org).
>> Jan 03 16:31:25 systemd[1]: Starting Update man-db cache...
>> Jan 03 16:31:25 systemd[1]: Starting Rotate log files...
>> Jan 03 16:31:25 systemd[1]: Started Verify integrity of password and
>> group files.
>> Jan 03 16:31:25 systemd[1]: ssh-tunnel.service: Service hold-off time
>> over, scheduling restart.
>>
>>
>> **Looks like that somehow `journald` is failing to `sync` logs when a
>> crash happens.**
>>
>>  - Is this a known behaviour?
>>  - Is there a workaround for this?
>>
>>
>> --
>> Also I am curious to know if the following claim from [Arch Linux
>> wiki][1] is still valid:
>>
>> > Since the syslog component of systemd, journald, does not flush its
>> > logs to disk during normal operation, these logs will be gone when the
>> > machine is shut down abnormally (power loss, kernel lock-ups, ...). In
>> > the case of kernel lock-ups, it is pretty important to have some
>> > kernel logs for debugging. Until journald gains a configuration option
>> > for flushing kernel logs, rsyslog can be used in conjunction with
>> > journald.
>>
>>
>> --
>> related bug report (old): [Bug 61411 - All logs since last boot gone
>> after crash/hard reboot][2]
>>
>> similar issue (old):
>> https://unix.stackexchange.com/questions/67394/debugging-lock-up-systemd-loses-my-logs
>>
>>   [1]:
>> https://wiki.archlinux.org/index.php/Rsyslog#journald_with_rsyslog_for_kernel_messages
>>   [2]:
>> https://bugs.freedesktop.org/show_bug.cgi?id=61411
>>
>>
> ___
> systemd-devel mailing list
> systemd-devel@lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/systemd-devel
>
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

Re: [systemd-devel] (no subject)

[Reindl Harald]

Am 19.01.2018 um 18:22 schrieb Matt Zagrabelny:
On Fri, Jan 19, 2018 at 11:16 AM, Reindl Harald > wrote:


if you don't bother to write a subject it can't be that important

Sometimes people make mistakes. Like forgetting to enter a subject. 
Don't assume the worst


proper mail clients ask if you menat that serious and before compose a 
mail i normally summarize it's content in the subejct before start to 
write it anyways

___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

Re: [systemd-devel] systemd-journald missing crash logs

[Farzad Panahi]

Hey guys. I really appreciate any comment on this issue. Please let me know
if this question does not belong to this mailing list.

On Fri, Jan 12, 2018 at 4:13 PM, Farzad Panahi 
wrote:

> I am running Arch-ARM on RPi3. I have noticed when system crashes I cannot
> find any related crash log in journal logs.
>
> Arch Linux ARM on RPi3: `Linux 4.4.37-1-ARCH #1 SMP armv7l GNU/Linux`
>
> Systemd: `systemd 232`
>
> `/etc/systemd/journald.conf`:
>
>
> [Journal]
> Storage=persistent
> Compress=yes
> #Seal=yes
> #SplitMode=uid
> SyncIntervalSec=1
> #RateLimitIntervalSec=30s
> #RateLimitBurst=1000
> SystemMaxUse=1.5G
> #SystemKeepFree=
> #SystemMaxFileSize=
> #SystemMaxFiles=100
> #RuntimeMaxUse=
> #RuntimeKeepFree=
> #RuntimeMaxFileSize=
> #RuntimeMaxFiles=100
> MaxRetentionSec=1month
> MaxFileSec=3hour
> #ForwardToSyslog=no
> #ForwardToKMsg=no
> #ForwardToConsole=no
> #ForwardToWall=yes
> #TTYPath=/dev/console
> #MaxLevelStore=debug
> #MaxLevelSyslog=debug
> #MaxLevelKMsg=notice
> #MaxLevelConsole=info
> #MaxLevelWall=emerg
>
> Recent crash log:
>
> Dec 29 03:43:48 sudo[21861]:  my_user : TTY=unknown ;
> PWD=/opt/my_app/repo/src ; USER=root ; COMMAND=/usr/sbin/hciconfig hci0
> reset
> Dec 29 03:43:48 sudo[21861]: pam_unix(sudo:session): session opened
> for user root by (uid=0)
> Dec 29 03:43:48 sudo[21861]: pam_unix(sudo:session): session closed
> for user root
> Dec 29 03:43:48 my_app.py[17773]: trying to connect to
> XX:XX:XX:XX:XX:XX
> Dec 29 03:43:48 systemd-udevd[21865]: Process '/bin/hciconfig hci0:64
> up' failed with exit code 1.
> Dec 29 03:43:51 my_app.py[17773]: connection successful :)
> -- Reboot --
> Jan 03 16:31:25 systemd[1]: Time has been changed
> Jan 03 16:31:26 dhcpcd[470]: forked to background, child pid 587
> Jan 03 16:31:25 systemd-timesyncd[360]: Synchronized to time server
> 206.108.0.133:123 (2.arch.pool.ntp.org).
> Jan 03 16:31:25 systemd[1]: Starting Update man-db cache...
> Jan 03 16:31:25 systemd[1]: Starting Rotate log files...
> Jan 03 16:31:25 systemd[1]: Started Verify integrity of password and
> group files.
> Jan 03 16:31:25 systemd[1]: ssh-tunnel.service: Service hold-off time
> over, scheduling restart.
>
>
> **Looks like that somehow `journald` is failing to `sync` logs when a
> crash happens.**
>
>  - Is this a known behaviour?
>  - Is there a workaround for this?
>
>
> --
> Also I am curious to know if the following claim from [Arch Linux wiki][1]
> is still valid:
>
> > Since the syslog component of systemd, journald, does not flush its
> > logs to disk during normal operation, these logs will be gone when the
> > machine is shut down abnormally (power loss, kernel lock-ups, ...). In
> > the case of kernel lock-ups, it is pretty important to have some
> > kernel logs for debugging. Until journald gains a configuration option
> > for flushing kernel logs, rsyslog can be used in conjunction with
> > journald.
>
>
> --
> related bug report (old): [Bug 61411 - All logs since last boot gone after
> crash/hard reboot][2]
>
> similar issue (old): https://unix.stackexchange.
> com/questions/67394/debugging-lock-up-systemd-loses-my-logs
>
>   [1]: https://wiki.archlinux.org/index.php/Rsyslog#journald_
> with_rsyslog_for_kernel_messages
>   [2]:
> https://bugs.freedesktop.org/show_bug.cgi?id=61411
>
>
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

Re: [systemd-devel] sd_watchdog_enabled: how to use when forking process?

[Simon McVittie]

On Fri, 19 Jan 2018 at 17:22:51 +, philip is hungry wrote:
> however if i run the forkme function (to put process in the background) it
> behaves as follows:
> 
> Jan 18 15:06:25 thinkpad waitonly[11228]: Return from forkme = 11228
> Jan 18 15:06:25 thinkpad waitonly[11228]: Return from lockme = 0
> Jan 18 15:06:25 thinkpad waitonly[11228]: PID to compare with watchdog_pid:
> 11228

systemd tells your service which process it expects to be sending
keepalives ($WATCHDOG_PID), and only accepts keepalives from that
process. The forked child process has some other process ID, so
sd_watchdog_enabled() returns false for it.

If you want to use the watchdog, don't fork and go to the background: it's
unnecessary for systemd services. To notify systemd that your process
is ready to receive requests (which was done via the double-fork trick
in init-script-based init systems), a daemon that natively supports
systemd features can use sd_notify() and Type=notify.

If you want your service to continue to support non-systemd init systems,
you might want to add a --no-fork command-line option and make the systemd
unit's ExecStart use that option. For example, that's how it works for
dbus-daemon, which needs to continue to default to forking for
compatibility with what it does on non-Linux OSs or non-systemd init.
Or, if your service will only ever run under systemd, you can make it
not fork/background itself at all.

smcv
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

[systemd-devel] sd_watchdog_enabled: how to use when forking process?

[philip is hungry]

I am trying to use "sd_watchdog_enabled".  If I run my service without forking, 
the sd_watchdog_enabled function works as expected:

Jan 18 15:05:29 thinkpad systemd[1]: Starting WaitonlyServer...
Jan 18 15:05:30 thinkpad waitonly[11172]: PID before fork  = 11172
Jan 18 15:05:30 thinkpad waitonly[11172]: Return from lockme = 0
Jan 18 15:05:30 thinkpad waitonly[11172]: PID to compare with watchdog_pid: 
11172
Jan 18 15:05:30 thinkpad waitonly[11172]: Return from watchdog = 1

however if i run the forkme function (to put process in the background) it 
behaves as follows:

Jan 18 15:06:25 thinkpad waitonly[11228]: Return from forkme = 11228
Jan 18 15:06:25 thinkpad waitonly[11228]: Return from lockme = 0
Jan 18 15:06:25 thinkpad waitonly[11228]: PID to compare with watchdog_pid: 
11228
Jan 18 15:06:25 thinkpad waitonly[11228]: systemd watchdog not enabled - not 
sending watchdog keepalives!
Jan 18 15:06:25 thinkpad waitonly[11228]: systemd watchdog pid = -1905553534
Jan 18 15:06:25 thinkpad waitonly[11228]: Return from watchdog = 0

where am I going wrong? any help with this is greatly appreciated.

thanks!

main.c ---

pid_t pid;
int watchdogInfo = 0;
int ret;

int main() {

  setlogmask (LOG_UPTO (LOG_INFO));
  openlog (NULL, LOG_CONS | LOG_PID | LOG_NDELAY, LOG_LOCAL1);

  pid = getpid();
  syslog (LOG_NOTICE, "PID before fork  = %d", pid);
  ret = forkme();
  syslog (LOG_NOTICE, "Return from forkme = %d", ret);

  ret = lockme();
  syslog (LOG_NOTICE, "Return from lockme = %d", ret);

  pid = getpid();
  syslog (LOG_NOTICE, "PID after fork  = %d", pid);

  watchdogInfo = systemd_get_watchdog_time();
  syslog (LOG_NOTICE, "Return from watchdog = %d", watchdogInfo);

  for (;;) { // Run forever
    sleep(10);
    syslog (LOG_NOTICE, "Service Running...");
}
}

forkme.c ---

pid_t pid;
int forkme(void) {
  if ((pid = fork()) < 0)
    exit(1);
  else if(pid != 0) /* parent */
    exit(0);
  setsid();
}

lockme.c ---

#define LOCKFILE "/var/run/waitonly.pid"
#define LOCKMODE (S_IRUSR|S_IWUSR|S_IRGRP|S_IROTH)

int lockme(void)
{
  int fd;
  char buf[16];
  fd = open(LOCKFILE, O_RDWR|O_CREAT, LOCKMODE);
  if (fd < 0) {
    syslog(LOG_ERR, "can’t open %s: %s", LOCKFILE, strerror(errno));
    exit(1);
  }
  ftruncate(fd, 0);
  sprintf(buf, "%ld", (long)getpid());
  write(fd, buf, strlen(buf)+1);
  return(0);
}

systemd.c ---

//  return watchdog - 0 means that watchdog is not enabled
int systemd_get_watchdog_time(void)
{
uint64_t usec;
char *watchdog = NULL;
char *watchdog_pid = NULL;
int ret;

ret = sd_watchdog_enabled(0, );

if (ret == 0) {
  syslog (LOG_NOTICE, "systemd watchdog not enabled - not sending watchdog 
keepalives!");
  watchdog_pid = getenv("WATCHDOG_PID");
  syslog (LOG_NOTICE, "systemd watchdog pid = %d", watchdog_pid);
}
if (ret < 0) {
  syslog (LOG_NOTICE, "systemd watchdog returned error %d - not sending 
watchdog keepalives", ret);
}
}
waitonly.service 
---
[Unit]Description=WaitonlyServer 
After=syslog.target networking.service
OnFailure=heartbeat-failed@%n.service

[Service]
Nice=-5
Type=forking
NotifyAccess=all
StartLimitInterval=3m
StartLimitBurst=3
TimeoutSec=1m
WatchdogSec=60s
PIDFile=/var/run/waitonly.pid
RestartSec=5
Restart=on-abnormal
LimitNOFILE=1024
ExecStart=/usr/bin/waitonly
ExecStop=/usr/bin/kill $MAINPID
ExecReload=/usr/bin/kill -HUP $MAINPID


[Install]
WantedBy=multi-user.target___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

Re: [systemd-devel] (no subject)

[Matt Zagrabelny]

On Fri, Jan 19, 2018 at 11:16 AM, Reindl Harald 
wrote:

> if you don't bother to write a subject it can't be that important
>

Sometimes people make mistakes. Like forgetting to enter a subject. Don't
assume the worst.

-m
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

Re: [systemd-devel] (no subject)

[Reindl Harald]

if you don't bother to write a subject it can't be that important
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

[systemd-devel] (no subject)

[philip is hungry]

I am trying to use "sd_watchdog_enabled".  If I run my service without forking, 
the sd_watchdog_enabled function works as expected:

Jan 18 15:05:29 thinkpad systemd[1]: Starting WaitonlyServer...
Jan 18 15:05:30 thinkpad waitonly[11172]: PID before fork  = 11172
Jan 18 15:05:30 thinkpad waitonly[11172]: Return from lockme = 0
Jan 18 15:05:30 thinkpad waitonly[11172]: PID to compare with watchdog_pid: 
11172
Jan 18 15:05:30 thinkpad waitonly[11172]: Return from watchdog = 1

however if i run the forkme function (to put process in the background) it 
behaves as follows:

Jan 18 15:06:25 thinkpad waitonly[11228]: Return from forkme = 11228
Jan 18 15:06:25 thinkpad waitonly[11228]: Return from lockme = 0
Jan 18 15:06:25 thinkpad waitonly[11228]: PID to compare with watchdog_pid: 
11228
Jan 18 15:06:25 thinkpad waitonly[11228]: systemd watchdog not enabled - not 
sending watchdog keepalives!
Jan 18 15:06:25 thinkpad waitonly[11228]: systemd watchdog pid = -1905553534
Jan 18 15:06:25 thinkpad waitonly[11228]: Return from watchdog = 0

where am I going wrong? any help with this is greatly appreciated.

thanks!

main.c ---

pid_t pid;
int watchdogInfo = 0;
int ret;

int main() {

  setlogmask (LOG_UPTO (LOG_INFO));
  openlog (NULL, LOG_CONS | LOG_PID | LOG_NDELAY, LOG_LOCAL1);

  pid = getpid();
  syslog (LOG_NOTICE, "PID before fork  = %d", pid);
  ret = forkme();
  syslog (LOG_NOTICE, "Return from forkme = %d", ret);

  ret = lockme();
  syslog (LOG_NOTICE, "Return from lockme = %d", ret);

  pid = getpid();
  syslog (LOG_NOTICE, "PID after fork  = %d", pid);

  watchdogInfo = systemd_get_watchdog_time();
  syslog (LOG_NOTICE, "Return from watchdog = %d", watchdogInfo);

  for (;;) { // Run forever
    sleep(10);
    syslog (LOG_NOTICE, "Service Running...");
}
}

forkme.c ---

pid_t pid;
int forkme(void) {
  if ((pid = fork()) < 0)
    exit(1);
  else if(pid != 0) /* parent */
    exit(0);
  setsid();
}

lockme.c ---

#define LOCKFILE "/var/run/waitonly.pid"
#define LOCKMODE (S_IRUSR|S_IWUSR|S_IRGRP|S_IROTH)

int lockme(void)
{
  int fd;
  char buf[16];
  fd = open(LOCKFILE, O_RDWR|O_CREAT, LOCKMODE);
  if (fd < 0) {
    syslog(LOG_ERR, "can’t open %s: %s", LOCKFILE, strerror(errno));
    exit(1);
  }
  ftruncate(fd, 0);
  sprintf(buf, "%ld", (long)getpid());
  write(fd, buf, strlen(buf)+1);
  return(0);
}

systemd.c ---

//  return watchdog - 0 means that watchdog is not enabled
int systemd_get_watchdog_time(void)
{
uint64_t usec;
char *watchdog = NULL;
char *watchdog_pid = NULL;
int ret;

ret = sd_watchdog_enabled(0, );

if (ret == 0) {
  syslog (LOG_NOTICE, "systemd watchdog not enabled - not sending watchdog 
keepalives!");
  watchdog_pid = getenv("WATCHDOG_PID");
  syslog (LOG_NOTICE, "systemd watchdog pid = %d", watchdog_pid);
}
if (ret < 0) {
  syslog (LOG_NOTICE, "systemd watchdog returned error %d - not sending 
watchdog keepalives", ret);
}
}
waitonly.service 
---
[Unit]Description=WaitonlyServer 
After=syslog.target networking.service
OnFailure=heartbeat-failed@%n.service

[Service]
Nice=-5
Type=forking
NotifyAccess=all
StartLimitInterval=3m
StartLimitBurst=3
TimeoutSec=1m
WatchdogSec=60s
PIDFile=/var/run/waitonly.pid
RestartSec=5
Restart=on-abnormal
LimitNOFILE=1024
ExecStart=/usr/bin/waitonly
ExecStop=/usr/bin/kill $MAINPID
ExecReload=/usr/bin/kill -HUP $MAINPID


[Install]
WantedBy=multi-user.target
   ___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel