search

ultrabug / py3status

py3status is an extensible i3status wrapper written in python
https://ultrabug.github.io/py3status/
BSD 3-Clause "New" or "Revised" License
890 stars 261 forks source link

py3status doesn't restart after unlocking the screen #941

Closed guiniol closed 5 years ago

guiniol commented 7 years ago

Sometimes, py3status does not restart updating after locking the screen. Sending it a SIGCONT unblocks it.

To debug this, I started py3status with status_command strace -f -t -qq -yy -e trace=signal -o ~/.i3/py3status.strace py3status -c ~/.i3/i3status.conf -d -l ~/.i3/py3status.log to trace all signals sent to py3status as well as enable its builtin debugging. I also added logging inside core.py in i3bar_stop and i3bar_start: self.log('GUINIOL stopping py3status') and self.log('GUINIOL starting py3status'). The GUINIOL is for easy grepping.

Here are the full log files. py3status stopped working at 16:05:42.

py3status.log.txt py3status.strace.txt

The relevant excerpts:

I just added signal(SIGSTOP, self.i3bar_stop) in core.py and will see if that fixes the issue, as the STOP signal doesn't to have been handled. EDIT: SIGSTOP cannot be caught.

guiniol commented 7 years ago

Since it's py3status sending a SIGSTOP to i3status because i3status is set to ignore SIGTSTP (why?), I currently added self.i3status_thread.i3status_pipe.send_signal(SIGCONT) to i3bar_start in core.py to see if this gets i3status to restart updating properly.

EDIT: this doesn't work. The SIGCONT must be sent to py3status and not to i3status.

tobes commented 7 years ago

Sometimes, i3lock does not restart updating after locking the screen. Sending it a SIGCONT unblocks it.

Is this correct or do you mean py3status?

guiniol commented 7 years ago

Sorry, I meant py3status of course ^^. I'll fix the original post since this is the first thing people see.

guiniol commented 7 years ago

BTW, it's not very clear in my report, but py3status only stops updating and doesn't restart when it receives a SIGSTOP. Most of the time, when I lock the screen, py3status does not receive a SIGSTOP (and no SIGTSTP either), but sometimes, for whatever reasons, it does.

tobes commented 7 years ago

This is strange. We ask i3bar to send a SIGTSTP because we can catch this. SIGSTOP caused some modules to misbehave/crash i3.

i3status wants the SIGSTOP which is why we change the SIGSTP to a SIGSTOP for it and ignore the SIGSTP

what are you using to lock your screen? i3lock?

guiniol commented 7 years ago

Yes, i3lock. i3lock -c 000000 to be exact. What's weird is that most of the time, py3status doesn't receive a SIGSTOP or a SIGTSTP, but it always receives a SIGCONT. And it only does not restart when it receives a SIGSTOP Could anyone try to check if their py3status is receiving SIGSTOP/SIGTSTP ?

lasers commented 6 years ago

@guiniol Can we get an update on this? Same behavior for 3.7?

guiniol commented 6 years ago

@lasers I don't have the computer where it used to happen all the time. I tried on my home computer where I had seen it happen and it seems fixed. I had a loop launching i3lock, waiting, killing it, waiting again so I could check if it had restarted, and after 20+ iterations it always restarted, which certainly wasn't the case previously. AFAICT, this seems to be fixed, but I'll keep you guys posted if it happens again.

What was the fix?

lasers commented 6 years ago

@guiniol You could close this issue if you believe it's fixed. I don't know what the fix was, but it was a series of pull requests from @tobes to address many performance issues including potential memory leak issue #1074.

See 3.7 Milestone

This release will be vastly focused on performance consideration and lowering the load footprint of py3status. Bug fixes will also get through. New modules will not be allowed unless they are trivial so expect delay for those kind of PRs.

guiniol commented 6 years ago

Alright. Thanks!

guiniol commented 6 years ago

Sadly, I am reopening this issue as it has happened again. I have a new computer at work running debian (so python2) and my computer at home running arch (so python3), and it has happened on both.

lasers commented 6 years ago

So I tried to understand the issue here. I'd like more information... What i3modules do you use? I notice that py3status will always react when it received a signal, but it can be very late sometimes.

strace shows that py3status received the signal, but on the other terminal, py3 logging does not always print the signal immediately... until 5 seconds later.

Most of the time, when I lock the screen, py3status does not receive a SIGSTOP (and no SIGTSTP either), but sometimes, for whatever reasons, it does.

It'd be nice to find out what stopped py3status in first place. My i3lock doesn't do that either. Also, what made you notice this behavior so maybe I can try and reproduce it? I think that it's not that py3status does not restart... but that whatever gave py3status the SIGSTOP/SIGTSTP signal in first place didn't fire off another signal when you came back.

Could anyone try to check if their py3status is receiving SIGSTOP/SIGTSTP ?

I'll try and see if I can log them. Maybe we can get name, pid, etc from the sender.

EDIT: Possibly it skipped. It does not always receive signals, it seems.

guiniol commented 6 years ago

I have attached the list of modules I use at home (I can attach the list of modules used at work later): i3status.txt

What happens is that when I unlock the screen, py3status doesn't update anymore. It doesn't happen all the time, but when it happens, it doesn't restart at all ever. I don't spend my time looking at it, but there have been times it had stopped updating for hours.

I believe it is i3lock sending the SIGSTP signal. I use the following command to start i3lock: i3lock -d -c 000000

I think py3status is indeed skipping some signals as sending a SIGCONT will restart it.

lasers commented 6 years ago

I believe it is i3lock sending the SIGSTP signal.

For what it's worth, DPMS support (-d) is not in i3lock since version 2.8 (2016-06-04) and I asked if i3lock send signals to i3bar and/or i3. The answer was No, it doesn't. https://github.com/i3/i3/pull/3329

guiniol commented 6 years ago

I wonder what is sending the signal then.

I'll remove -d from my config, but I don't think it will change much.

ultrabug commented 6 years ago

Hello

It seems that the issue has been fixed here https://github.com/i3/i3/issues/2539

I'll close this issue, re-open if needed please

guiniol commented 6 years ago

Sure, thanks

introspectionism commented 5 years ago

hiya. i see this is an old issue. however, i have this exact problem myself. shall i add more info here (reopen the issue) or do you prefer a new issue?

cyrinux commented 5 years ago

Hi, I have since recently the same problem too. I run

❯ py3status --version
py3status version 3.18 (python 3.7.3) on i3
introspectionism commented 5 years ago

i'm having this problem on two different systems. both are manjaro i3.

[klevstul@x280manjaro ~]$ py3status --version
py3status version 3.16 (python 3.7.2)
ultrabug commented 5 years ago

So we'll have to investigate again. I'm not affected and it was previously related to i3 itself not sending the right SIG.

@cyrinux @klevstul could you please give your exact i3 version?

Thanks

introspectionism commented 5 years ago

@ultrabug - thanks for looking into this.

$ i3 -version
i3 version 4.16.1 (2019-01-27) © 2009 Michael Stapelberg and contributors
ultrabug commented 5 years ago

@klevstul alright so something else is happening...

when py3status receives signals, it prints a log, can you check your logs to see when it gets the SIGSTP? it should get a SIGCONT after unlocking, do you see that happen?

also, if you're on IRC, raise your hand plz

introspectionism commented 5 years ago

@ultrabug

additional info found when reading the i3 debugging page:

[klevstul@silentGamerMjr ~]$ i3 --moreversion 2>&- || i3 --version
Binary i3 version:  4.16.1 (2019-01-27) © 2009 Michael Stapelberg and contributors
Running i3 version: 4.16.1 (2019-01-27) (pid 7224)abort…)
Loaded i3 config: /home/klevstul/.i3/config (Last modified: Wed 03 Apr 2019 09:36:36 AM CEST, 89438 seconds ago)

The i3 binary you just called: /usr/bin/i3
The i3 binary you are running: i3

can you check your logs

where do i find the logs? at first glance, i can't see anything relevant at /var/log nor ~/. i guess i'm overlooking something.

i'm not on irc. if it helps though i can be reached on keybase.

ultrabug commented 5 years ago

@klevstul

Logs are found on your user logs (depends on your syslog).

If you use systemd, you can get them using journalctl

Cheers

introspectionism commented 5 years ago

@ultrabug

here is output from the logs. note that this doesn't happen every time though. most times it works fine. however, once in a while it freezes. maybe it's related to the "i3status died and said: exiting due to signal."?

$ journalctl -r /usr/bin/py3status

-- Logs begin at Wed 2019-02-13 15:52:53 CET, end at Sat 2019-04-06 10:40:58 CEST. --
Apr 06 10:30:39 silentGamerMjr /py3status[20692]: received SIGCONT
Apr 06 10:30:39 silentGamerMjr /py3status[20692]: received SIGTSTP
Apr 06 10:30:39 silentGamerMjr /py3status[20692]: received SIGCONT
Apr 05 21:40:50 silentGamerMjr /py3status[20692]: received SIGTSTP
Apr 05 20:56:01 silentGamerMjr /py3status[20692]: received SIGCONT
Apr 05 20:56:01 silentGamerMjr /py3status[20692]: received SIGTSTP
Apr 05 20:56:01 silentGamerMjr /py3status[20692]: received SIGCONT
Apr 05 20:30:06 silentGamerMjr /py3status[20692]: received SIGTSTP
Apr 05 19:24:57 silentGamerMjr /py3status[20692]: received SIGCONT
Apr 05 19:24:57 silentGamerMjr /py3status[20692]: received SIGTSTP
Mar 23 23:14:03 silentGamerMjr /py3status[16288]: received SIGTSTP
Mar 23 21:29:26 silentGamerMjr /py3status[16288]: starting module net_rate
Mar 23 21:29:26 silentGamerMjr /py3status[16288]: starting module whatismyip
Mar 23 21:29:26 silentGamerMjr /py3status[16288]: starting module spotify
Mar 23 21:29:26 silentGamerMjr /py3status[16288]: loading module "whatismyip" from py3status.modules.w>
Mar 23 21:29:26 silentGamerMjr /py3status[16288]: loading module "spotify" from py3status.modules.spot>
Mar 23 21:29:26 silentGamerMjr /py3status[16288]: loading module "net_rate" from py3status.modules.net>
Mar 23 21:29:26 silentGamerMjr /py3status[16288]: i3status spawned using config file /tmp/py3status_su>
Mar 23 21:29:26 silentGamerMjr /py3status[16288]: Starting py3status version 3.16 python 3.7.2
Mar 23 21:29:26 silentGamerMjr /py3status[16288]: ========
Mar 23 21:29:26 silentGamerMjr /py3status[19704]: i3status died and said: Exiting due to signal.
Mar 23 21:29:26 silentGamerMjr /py3status[19704]: received SIGTERM
Mar 18 08:30:59 silentGamerMjr /py3status[19704]: starting module net_rate
Mar 18 08:30:59 silentGamerMjr /py3status[19704]: starting module whatismyip
Mar 18 08:30:59 silentGamerMjr /py3status[19704]: starting module spotify
Mar 18 08:30:59 silentGamerMjr /py3status[19704]: loading module "whatismyip" from py3status.modules.w>
Mar 18 08:30:59 silentGamerMjr /py3status[19704]: loading module "spotify" from py3status.modules.spot>
Mar 18 08:30:59 silentGamerMjr /py3status[19704]: loading module "net_rate" from py3status.modules.net>
Mar 18 08:30:59 silentGamerMjr /py3status[19704]: i3status spawned using config file /tmp/py3status_me>
Mar 18 08:30:59 silentGamerMjr /py3status[19704]: Starting py3status version 3.16 python 3.7.2
Mar 18 08:30:59 silentGamerMjr /py3status[19704]: ========
Mar 18 08:30:58 silentGamerMjr /py3status[19496]: i3status died and said: Exiting due to signal.
Mar 18 08:30:58 silentGamerMjr /py3status[19496]: received SIGTERM
Mar 18 08:29:15 silentGamerMjr /py3status[19496]: starting module net_rate
Mar 18 08:29:15 silentGamerMjr /py3status[19496]: starting module whatismyip
Mar 18 08:29:15 silentGamerMjr /py3status[19496]: starting module spotify
Mar 18 08:29:15 silentGamerMjr /py3status[19496]: loading module "whatismyip" from py3status.modules.w>
Mar 18 08:29:15 silentGamerMjr /py3status[19496]: loading module "spotify" from py3status.modules.spot>
Mar 18 08:29:15 silentGamerMjr /py3status[19496]: loading module "net_rate" from py3status.modules.net>
Mar 18 08:29:15 silentGamerMjr /py3status[19496]: i3status spawned using config file /tmp/py3status_38>
Mar 18 08:29:15 silentGamerMjr /py3status[19496]: Starting py3status version 3.16 python 3.7.2
Mar 18 08:29:15 silentGamerMjr /py3status[19496]: ========
Mar 18 08:29:14 silentGamerMjr /py3status[19119]: i3status died and said: Exiting due to signal.
Mar 18 08:29:14 silentGamerMjr /py3status[19119]: received SIGTERM
Mar 18 08:24:44 silentGamerMjr /py3status[19119]: starting module net_rate
Mar 18 08:24:44 silentGamerMjr /py3status[19119]: starting module whatismyip
Mar 18 08:24:44 silentGamerMjr /py3status[19119]: starting module spotify
Mar 18 08:24:44 silentGamerMjr /py3status[19119]: loading module "whatismyip" from py3status.modules.w>
Mar 18 08:24:44 silentGamerMjr /py3status[19119]: loading module "spotify" from py3status.modules.spot>
Mar 18 08:24:44 silentGamerMjr /py3status[19119]: loading module "net_rate" from py3status.modules.net>
Mar 18 08:24:44 silentGamerMjr /py3status[19119]: i3status spawned using config file /tmp/py3status__i>
Mar 18 08:24:44 silentGamerMjr /py3status[19119]: Starting py3status version 3.16 python 3.7.2
Mar 18 08:24:44 silentGamerMjr /py3status[19119]: ========
Mar 18 08:24:44 silentGamerMjr /py3status[17569]: received SIGTERM

src

lasers commented 5 years ago

@klevstul Can you share your untampered config? Replace passwds/keys/apis etc with 'OMITTED'.

introspectionism commented 5 years ago

@ultrabug

here you go: https://gitlab.com/klevstul/linuxftw/blob/master/config/i3status.conf

ultrabug commented 5 years ago

hmm there's indeed something fishy here.. looks like you trimmed some logs tho, can we have it all to download somewhere? only for an entire day when you encountered the issue

but that's too much SIGSTP / SIGCONT I think

@klevstul you confirm to be using i3lock right?

introspectionism commented 5 years ago

@ultrabug

can we have it all to download somewhere?

journalctl -r /usr/bin/py3status -S "2019-03-18 00:00:00.000000" -U "2019-03-19 00:00:00.000000" > /media/dataDrive/downloads/190318_py3status.log

journalctl -r -S "2019-03-18 00:00:00.000000" -U "2019-03-19 00:00:00.000000" > /media/dataDrive/downloads/190318.log

you confirm to be using i3lock right?

exec --no-startup-id xautolock -time 30 -locker 'i3lock -c 000000'
see full i3 config

lasers commented 5 years ago

@klevstul

py3status doesn't restart after unlocking the screen

You can try py3status --debug --log /tmp/py3status_bottom.log and play with locking. Next time it happened, check the logs. Is it still logging? If not:

If possible, keep an eye on the logs and study the behaviors between logs + modules. If py3status is stuck on the bar, but the log is still logging results, then we might want to know that. Does it happen with other locks too (i.e. slock)? To rule i3lock out.

maybe it's related to the "i3status died and said: exiting due to signal."?

This is probably from restarting i3. Your (reverse) logs puts newest entries fist. It should look like:

# executing i3-msg restart via keyboard binding or such

Mar 18 08:30:58 py3status: received SIGTERM
Mar 18 08:30:58 py3status: i3status died and said: Exiting due to signal.
Mar 18 08:30:59 py3status: ========
Mar 18 08:30:59 py3status: Starting py3status version 3.16 python 3.7.2
Mar 18 08:30:59 py3status: i3status spawned using config file /tmp/py3status_me...
Mar 18 08:30:59 py3status: starting several modules again

Also, you can use py3status --debug --log /tmp/py3status_bottom.log and tail -f /tmp/py3status_bottom.log instead to get the log without clutter.

Sorry for the wall of text. As you might notice, we can't reproduce this. I hope you find something new.

ultrabug commented 5 years ago

Yep I must admit that I can't reproduce it either... there's nothing special about the logs (btw **I recommend you delete those files now that we've looked at them)

So lasers procedure might help

introspectionism commented 5 years ago

@lasers @ultrabug thanks for the feedback. i will attack the wall of text, trying to get a better understanding when this happens and report back. i'm actually having this problem on two separate machines. both are running manjaro i3, using the same py3status config.

cyrinux commented 5 years ago

Hi guys, py3status still get stuck after unlock my screen, but not always... This morning on resume it was lock, and a killall -SIGCONT py3status wake it up.

introspectionism commented 5 years ago

a little update from me. i've done some debugging. what seems to be the case is that whenever this do happen py3status doesn't receive sigcont when i unlock my computer. actually, when unlocking my computer several sigstp and sigcont are sent.

for example, just now, upon unlocking, the following signals were sent:

Apr 30 08:30:01 x280manjaro /py3status[4772]: received SIGCONT
Apr 30 08:30:01 x280manjaro /py3status[4772]: received SIGCONT
Apr 30 08:30:01 x280manjaro /py3status[4772]: received SIGTSTP

since sigstp was the last signal py3status stays in stopped mode.

and, when things do work sigcontis the last signal sent:

Apr 30 09:47:06 x280manjaro /py3status[27325]: received SIGCONT
Apr 30 09:47:06 x280manjaro /py3status[27325]: received SIGTSTP
Apr 30 09:47:06 x280manjaro /py3status[27325]: received SIGCONT

seems to be random in which order these signals are sent. which might explain why py3status sometimes start, sometimes not.

ultrabug commented 5 years ago

Thanks for following up @klevstul .. so it looks like py3status does what it's being asked to do here right?... I have no clue as to why it gets so many conflicting signals then. i3 related? some other system broadcasting messages?

The only thing I could imagine is to add some kind of throttling to py3status signal management so that we consider signals not one by one, but within a time frame.

introspectionism commented 5 years ago

@ultrabug you're welcome. yes, it looks like py3status is working just as expected. the conflicting signals might be i3 related since this happens on two of my computers, both running manjaro i3.

if py3status would only take action for the first signal received, during a one second period, it looks like it would work fine. the correct signal seems to be sent and received as the first signal.

unfortunately, i don't know why and how the signalling system works. it would be nice to figure out exactly why multiple signals are sent.

@cyrinux - are you on i3wm as well?

lasers commented 5 years ago

@klevstul What's your setup? Both bars (top/bottom) or two monitors? I'm wondering if it is i3bar sending signal to each bar or if we're printing signals twice because there are multiple bars, but the log is often viewed as a log for a single bar.

introspectionism commented 5 years ago

@lasers for the above example three monitors, with a bar on every monitor. so, maybe py3status receives one signal for each monitor?

lasers commented 5 years ago

Definitely a bug, but likely not a py3status bug. Closing this in favor of https://github.com/i3/i3/issues/3242.