Bug#930446: popularity-contest: unable to submit report, impossible to debug
On Sun, Sep 01, 2019 at 05:52:37PM +0200, Ludovic Rousseau wrote: > So the cron job is executed at 7h57. > > > > > In which case, could you check what is the issue with the timestamp > > > > (see the full buildlog) ? > > > > > > Can you be more specific about what you want me to check? > > > > What gives > > ls -l /var/log/popularity-contest* > > $ LANG=C ls -l /var/log/popularity-contest* > -rw-r--r-- 1 root root 24169 Aug 29 07:57 /var/log/popularity-contest > -rw-r--r-- 1 root root 0 Aug 29 07:57 /var/log/popularity-contest.0 > -rw-r--r-- 1 root root 5563 Aug 22 07:57 /var/log/popularity-contest.1.gz > -rw-r--r-- 1 root root41 Aug 22 07:57 /var/log/popularity-contest.2.gz > -rw-r--r-- 1 root root 5541 Aug 15 07:57 /var/log/popularity-contest.3.gz > -rw-r--r-- 1 root root41 Aug 15 07:57 /var/log/popularity-contest.4.gz > -rw-r--r-- 1 root root 5583 Aug 8 07:57 /var/log/popularity-contest.5.gz > -rw-r--r-- 1 root root41 Aug 8 07:57 /var/log/popularity-contest.6.gz > -rw-r--r-- 1 root root 8451 Aug 1 07:57 /var/log/popularity-contest.new.gpg This seems good, except there might be an issue with logrotate or whoever create the empty /var/log/popularity-contest.0. > > Do you run some program that change the timestamp of the file > > /var/log/popularity-contest ? maybe logrotate ? > > Not that I am aware of. > > > > > In you have an unrelated problem, please open a separate bug report. > > > > > > > > The debug output you got just means that the server failed to answer. > > > > > > Sure. > > > Why did the server failed to answer? > > > > Probably too many people are trying to submit at the same time. Hence the > > move > > to cron.d with a user specific submission time. > > popcon.debian.org is hosted by pinel.debian.org. > I could not find a real load issue from munin graphs at > https://munin.debian.org/debian.org/pinel.debian.org/index.html > (login dsa-guest, password dsa-guest) It is too thin to show on munin, but doing external measurement show the problem. > Ah OK. > popularity-contest has TWO cron configurations: > - /etc/cron.daily/popularity-contest > - /etc/cron.d/popularity-contest > > Should I just ignore the messages generated by the cron.daily job? For the time being, yes. I finally found the root of the problem, by writing a submission simulator. There was a logic error in /etc/cron.daily/popularity-contest that leads to the cron.daily to have higher priority than the cron.d. Maybe it makes sense when cron.d was introduced, but not now. I will fix it in the next update. Thanks for following up on this painful issue and sorry for the delay. Cheers, -- Bill. Imagine a large red swirl here.
Bug#930446: popularity-contest: unable to submit report, impossible to debug
Le 01/09/2019 à 09:51, Bill Allombert a écrit : On Sat, Aug 31, 2019 at 06:22:03PM +0200, Ludovic Rousseau wrote: Hello Ludovic, This report is about Stefan problem. Stefan problem is that popcon is reporting twice, one with cron.d time and one with the cron.daily fallback, which means somehow the mechanism to detect that the report was already sent did not work. Is it your problem too ? According to the email you send me, your report is also sent at 6:25 which suggests this is the case, since the cron.daily fallback run at 6:25. My problem is the same as the original issue reported by Stefan Fritsch. In my logs I get (same as Stefan): Aug 29 06:25:15 PiHole popularity-contest: unable to submit report to http://popcon.debian.org/cgi-bin/popcon.cgi. Aug 29 06:25:15 PiHole popularity-contest: unable to submit report I have no idea if the submission worked or not. Check /etc/cron.d/popularity-contest for the time of the cron.d report. $ cat /etc/cron.d/popularity-contest SHELL=/bin/sh PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin 57 7 * * * roottest -x /etc/cron.daily/popularity-contest && /etc/cron.daily/popularity-contest --crond So the cron job is executed at 7h57. In which case, could you check what is the issue with the timestamp (see the full buildlog) ? Can you be more specific about what you want me to check? What gives ls -l /var/log/popularity-contest* $ LANG=C ls -l /var/log/popularity-contest* -rw-r--r-- 1 root root 24169 Aug 29 07:57 /var/log/popularity-contest -rw-r--r-- 1 root root 0 Aug 29 07:57 /var/log/popularity-contest.0 -rw-r--r-- 1 root root 5563 Aug 22 07:57 /var/log/popularity-contest.1.gz -rw-r--r-- 1 root root41 Aug 22 07:57 /var/log/popularity-contest.2.gz -rw-r--r-- 1 root root 5541 Aug 15 07:57 /var/log/popularity-contest.3.gz -rw-r--r-- 1 root root41 Aug 15 07:57 /var/log/popularity-contest.4.gz -rw-r--r-- 1 root root 5583 Aug 8 07:57 /var/log/popularity-contest.5.gz -rw-r--r-- 1 root root41 Aug 8 07:57 /var/log/popularity-contest.6.gz -rw-r--r-- 1 root root 8451 Aug 1 07:57 /var/log/popularity-contest.new.gpg Do you run some program that change the timestamp of the file /var/log/popularity-contest ? maybe logrotate ? Not that I am aware of. In you have an unrelated problem, please open a separate bug report. The debug output you got just means that the server failed to answer. Sure. Why did the server failed to answer? Probably too many people are trying to submit at the same time. Hence the move to cron.d with a user specific submission time. popcon.debian.org is hosted by pinel.debian.org. I could not find a real load issue from munin graphs at https://munin.debian.org/debian.org/pinel.debian.org/index.html (login dsa-guest, password dsa-guest) Ah OK. popularity-contest has TWO cron configurations: - /etc/cron.daily/popularity-contest - /etc/cron.d/popularity-contest Should I just ignore the messages generated by the cron.daily job? Bye -- Dr. Ludovic Rousseau
Bug#930446: popularity-contest: unable to submit report, impossible to debug
On Sat, Aug 31, 2019 at 06:22:03PM +0200, Ludovic Rousseau wrote: > > Hello Ludovic, > > > > This report is about Stefan problem. > > > > Stefan problem is that popcon is reporting twice, one with cron.d > > time and one with the cron.daily fallback, which means somehow the > > mechanism to detect that the report was already sent did not work. > > > > Is it your problem too ? According to the email you send me, your report > > is also sent at 6:25 which suggests this is the case, since the cron.daily > > fallback run at 6:25. > > My problem is the same as the original issue reported by Stefan Fritsch. > In my logs I get (same as Stefan): > Aug 29 06:25:15 PiHole popularity-contest: unable to submit report to > http://popcon.debian.org/cgi-bin/popcon.cgi. > Aug 29 06:25:15 PiHole popularity-contest: unable to submit report > > I have no idea if the submission worked or not. Check /etc/cron.d/popularity-contest for the time of the cron.d report. > > In which case, could you check what is the issue with the timestamp > > (see the full buildlog) ? > > Can you be more specific about what you want me to check? What gives ls -l /var/log/popularity-contest* Do you run some program that change the timestamp of the file /var/log/popularity-contest ? maybe logrotate ? > > In you have an unrelated problem, please open a separate bug report. > > > > The debug output you got just means that the server failed to answer. > > Sure. > Why did the server failed to answer? Probably too many people are trying to submit at the same time. Hence the move to cron.d with a user specific submission time. Cheers, -- Bill. Imagine a large red swirl here.
Bug#930446: popularity-contest: unable to submit report, impossible to debug
Le 31/08/2019 à 16:05, Bill Allombert a écrit : On Thu, Aug 29, 2019 at 10:38:29PM +0200, Ludovic Rousseau wrote: On Wed, 12 Jun 2019 22:52:59 +0200 Bill Allombert wrote: On Wed, Jun 12, 2019 at 09:46:58PM +0200, Stefan Fritsch wrote: Package: popularity-contest Version: 1.67 Severity: normal Dear Maintainer, on several of my hosts, popularity-contest logs unable to submit report to http://popcon.debian.org/cgi-bin/popcon.cgi. unable to submit report. But it does not log why and there is no way that I could find to trigger the sending from the command line with debug output enabled. http://popcon.debian.org/cgi-bin/pop is reachable from the host via curl. Also, according to the documentation it should fall back to email, which it does not do. It does not log why it does not do that. Hello Stefan! This comes from /etc/cron.daily/popularity-contest: # try to post the report through http POST if [ "$SUBMITURLS" ] && [ "yes" = "$USEHTTP" ]; then for URL in $SUBMITURLS ; do if setsid /usr/share/popularity-contest/popcon-upload \ -u $URL -f $POPCON 2>/dev/null ; then SUBMITTED=yes else logger -t popularity-contest "unable to submit report to $URL." fi done fi /usr/share/popularity-contest/popcon-upload has an option -d for debugging that you could try. I added the -d to get some more debug. Hello Ludovic, This report is about Stefan problem. Stefan problem is that popcon is reporting twice, one with cron.d time and one with the cron.daily fallback, which means somehow the mechanism to detect that the report was already sent did not work. Is it your problem too ? According to the email you send me, your report is also sent at 6:25 which suggests this is the case, since the cron.daily fallback run at 6:25. My problem is the same as the original issue reported by Stefan Fritsch. In my logs I get (same as Stefan): Aug 29 06:25:15 PiHole popularity-contest: unable to submit report to http://popcon.debian.org/cgi-bin/popcon.cgi. Aug 29 06:25:15 PiHole popularity-contest: unable to submit report I have no idea if the submission worked or not. In which case, could you check what is the issue with the timestamp (see the full buildlog) ? Can you be more specific about what you want me to check? In you have an unrelated problem, please open a separate bug report. The debug output you got just means that the server failed to answer. Sure. Why did the server failed to answer? I have the same problem on different systems, not just one. Bye -- Dr. Ludovic Rousseau
Bug#930446: popularity-contest: unable to submit report, impossible to debug
On Thu, Aug 29, 2019 at 10:38:29PM +0200, Ludovic Rousseau wrote: > On Wed, 12 Jun 2019 22:52:59 +0200 Bill Allombert wrote: > > On Wed, Jun 12, 2019 at 09:46:58PM +0200, Stefan Fritsch wrote: > > > Package: popularity-contest > > > Version: 1.67 > > > Severity: normal > > > > Dear Maintainer, > > > > on several of my hosts, popularity-contest logs > > > > unable to submit report to > > http://popcon.debian.org/cgi-bin/popcon.cgi. > > > unable to submit report. > > > > But it does not log why and there is no way that I could find to > > trigger > > > the sending from the command line with debug output enabled. > > > > http://popcon.debian.org/cgi-bin/pop is reachable from the host via > > curl. Also, > > > according to the documentation it should fall back to email, which it > > > does not > > > do. It does not log why it does not do that. > > > > Hello Stefan! > > > > This comes from /etc/cron.daily/popularity-contest: > > # try to post the report through http POST > > if [ "$SUBMITURLS" ] && [ "yes" = "$USEHTTP" ]; then > > for URL in $SUBMITURLS ; do > > if setsid /usr/share/popularity-contest/popcon-upload \ > > -u $URL -f $POPCON 2>/dev/null ; then > > SUBMITTED=yes > > else > > logger -t popularity-contest "unable to submit report to > > $URL." > > fi > > done > > fi > > > > /usr/share/popularity-contest/popcon-upload has an option -d for > > debugging that you could try. > > I added the -d to get some more debug. Hello Ludovic, This report is about Stefan problem. Stefan problem is that popcon is reporting twice, one with cron.d time and one with the cron.daily fallback, which means somehow the mechanism to detect that the report was already sent did not work. Is it your problem too ? According to the email you send me, your report is also sent at 6:25 which suggests this is the case, since the cron.daily fallback run at 6:25. In which case, could you check what is the issue with the timestamp (see the full buildlog) ? In you have an unrelated problem, please open a separate bug report. The debug output you got just means that the server failed to answer. Cheers, -- Bill. Imagine a large red swirl here.
Bug#930446: popularity-contest: unable to submit report, impossible to debug
On Wed, 12 Jun 2019 22:52:59 +0200 Bill Allombert wrote: On Wed, Jun 12, 2019 at 09:46:58PM +0200, Stefan Fritsch wrote: > Package: popularity-contest > Version: 1.67 > Severity: normal > > Dear Maintainer, > > on several of my hosts, popularity-contest logs > > unable to submit report to http://popcon.debian.org/cgi-bin/popcon.cgi. > unable to submit report. > > But it does not log why and there is no way that I could find to trigger > the sending from the command line with debug output enabled. > > http://popcon.debian.org/cgi-bin/pop is reachable from the host via curl. Also, > according to the documentation it should fall back to email, which it does not > do. It does not log why it does not do that. Hello Stefan! This comes from /etc/cron.daily/popularity-contest: # try to post the report through http POST if [ "$SUBMITURLS" ] && [ "yes" = "$USEHTTP" ]; then for URL in $SUBMITURLS ; do if setsid /usr/share/popularity-contest/popcon-upload \ -u $URL -f $POPCON 2>/dev/null ; then SUBMITTED=yes else logger -t popularity-contest "unable to submit report to $URL." fi done fi /usr/share/popularity-contest/popcon-upload has an option -d for debugging that you could try. I added the -d to get some more debug. But what I got is not really helpfull. I got an email from cron: From: r...@pihole.xxx.fr (Cron Daemon) To: r...@pihole.xxx.fr Subject: Cron test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ) Date: Thu, 29 Aug 2019 06:25:15 +0200 /etc/cron.daily/popularity-contest: Failed to upload, answer '' And in /var/log/messages I have the classic: Aug 29 06:25:15 PiHole popularity-contest: unable to submit report to http://popcon.debian.org/cgi-bin/popcon.cgi. Aug 29 06:25:15 PiHole popularity-contest: unable to submit report I am using Debian stable (buster) with popularity-contest 1.67 Bye -- Dr. Ludovic Rousseau
Bug#930446: popularity-contest: unable to submit report, impossible to debug
Am 20.06.19 um 13:25 schrieb Bill Allombert: >> When submission fails, popcon-upload dies with a timeout. There should >> probably be a randomized sleep to distribute the server load better. I >> think there could be a lot more popcon submissions if this is done. > > What is the time in /etc/cron.d/popularity-contest ? > (something like 33 5 * * *) > > Does it work better if you change it to some other time ? > What cron ae you using # cat /etc/cron.d/popularity-contest SHELL=/bin/sh PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin 41 4 * * * roottest -x /etc/cron.daily/popularity-contest && /etc/cron.daily/popularity-contest --crond # dpkg -l *cron* Desired=Unknown/Install/Remove/Purge/Hold | Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend |/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad) ||/ Name Version Architecture Description +++-==---= un anacron (no description available) ii cron 3.0pl1-133 amd64process scheduling daemon un cron-daemon (no description available) It seems it is run twice, once from /etc/cron.d/popularity-contest and once from /etc/cron.daily . And the run from cron.d is at a different time on each host and was successful and did not log anything. But the second run via run-parts /etc/cron.daily (without --crond) fails because it is at the same time on all systems. And that produces log spam. # grep daily /etc/crontab 25 6* * * roottest -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ) Maybe the successful run should be remembered somehow?
Bug#930446: popularity-contest: unable to submit report, impossible to debug
On Thu, Jun 20, 2019 at 11:09:10AM +0200, Stefan Fritsch wrote: > Hi Bill, > > I have some new info: Thanks for coming back to me! > When submission fails, popcon-upload dies with a timeout. There should > probably be a randomized sleep to distribute the server load better. I > think there could be a lot more popcon submissions if this is done. What is the time in /etc/cron.d/popularity-contest ? (something like 33 5 * * *) Does it work better if you change it to some other time ? What cron ae you using > Also, popcon-upload should log errors to syslog. > > The fallback to email only happens if "$MODE" = "--crond". But if the > script is called via cron.daily it gets called without parameters and > this never happens. Is this intentional? This is to avoid sending the email twice. The problem is that there is no way to know if the email was received. The script is normally called by /etc/cron.d/popularity-contest with --crond. Cheers, -- Bill. Imagine a large red swirl here.
Bug#930446: popularity-contest: unable to submit report, impossible to debug
Hi Bill, I have some new info: When submission fails, popcon-upload dies with a timeout. There should probably be a randomized sleep to distribute the server load better. I think there could be a lot more popcon submissions if this is done. Also, popcon-upload should log errors to syslog. The fallback to email only happens if "$MODE" = "--crond". But if the script is called via cron.daily it gets called without parameters and this never happens. Is this intentional? Cheers, Stefan
Bug#930446: popularity-contest: unable to submit report, impossible to debug
Hmm. After comparing the log files, I think I may have found the issue: Jun 05 06:25:01 c CRON[8719]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily )) Jun 05 06:25:05 c runuser[8833]: pam_unix(runuser:session): session opened for user nobody by (uid=0) Jun 05 06:25:33 c runuser[8833]: pam_unix(runuser:session): session closed for user nobody Jun 05 06:25:34 c popularity-contest[8857]: unable to submit report to http://popcon.debian.org/cgi-bin/popcon.cgi. Jun 05 06:25:34 c popularity-contest[8858]: unable to submit report. Jun 05 06:25:34 c CRON[8718]: pam_unix(cron:session): session closed for user root When it fails, it always does between 6:25 and 6:26 which is the time /etc/cron.daily is run. Maybe the popcon server is overloaded at that time and the 30s timeout in popcon-upload triggers?
Bug#930446: popularity-contest: unable to submit report, impossible to debug
Am 12.06.19 um 22:52 schrieb Bill Allombert: > /usr/share/popularity-contest/popcon-upload has an option -d for > debugging that you could try. >From the command line, this works without errors: /usr/share/popularity-contest/popcon-upload -d -u http://popcon.debian.org/cgi-bin/popcon.cgi -f /var/log/popularity-contest.new.gpg I will put some debugging output into the script and wait for cron to run it again, but there really should be an option in popularity-contest.conf to enable debugging. BTW, the use of setsid seems to be wrong, it hides the error code: # setsid /bin/false ; echo $? 0 You probably want setsid -w . Or why use setsid at all?
Bug#930446: popularity-contest: unable to submit report, impossible to debug
On Wed, Jun 12, 2019 at 09:46:58PM +0200, Stefan Fritsch wrote: > Package: popularity-contest > Version: 1.67 > Severity: normal > > Dear Maintainer, > > on several of my hosts, popularity-contest logs > > unable to submit report to http://popcon.debian.org/cgi-bin/popcon.cgi. > unable to submit report. > > But it does not log why and there is no way that I could find to trigger > the sending from the command line with debug output enabled. > > http://popcon.debian.org/cgi-bin/pop is reachable from the host via curl. > Also, > according to the documentation it should fall back to email, which it does not > do. It does not log why it does not do that. Hello Stefan! This comes from /etc/cron.daily/popularity-contest: # try to post the report through http POST if [ "$SUBMITURLS" ] && [ "yes" = "$USEHTTP" ]; then for URL in $SUBMITURLS ; do if setsid /usr/share/popularity-contest/popcon-upload \ -u $URL -f $POPCON 2>/dev/null ; then SUBMITTED=yes else logger -t popularity-contest "unable to submit report to $URL." fi done fi /usr/share/popularity-contest/popcon-upload has an option -d for debugging that you could try. Cheers, -- Bill. Imagine a large red swirl here.
Bug#930446: popularity-contest: unable to submit report, impossible to debug
Package: popularity-contest Version: 1.67 Severity: normal Dear Maintainer, on several of my hosts, popularity-contest logs unable to submit report to http://popcon.debian.org/cgi-bin/popcon.cgi. unable to submit report. But it does not log why and there is no way that I could find to trigger the sending from the command line with debug output enabled. http://popcon.debian.org/cgi-bin/pop is reachable from the host via curl. Also, according to the documentation it should fall back to email, which it does not do. It does not log why it does not do that. Cheers, Stefan Relevant parts of /etc/popularity-contest.conf (without MY_HOSTID): PARTICIPATE="yes" USEHTTP="yes" DAY="2" -- System Information: Debian Release: 10.0 APT prefers testing APT policy: (990, 'testing'), (500, 'unstable') Architecture: amd64 (x86_64) Kernel: Linux 4.19.0-5-amd64 (SMP w/2 CPU cores) Kernel taint flags: TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE=en_US:en (charmap=UTF-8) Shell: /bin/sh linked to /bin/dash Init: systemd (via /run/systemd/system) LSM: AppArmor: enabled Versions of packages popularity-contest depends on: ii debconf [debconf-2.0] 1.5.71 ii dpkg 1.19.7 Versions of packages popularity-contest recommends: ii cron [cron-daemon] 3.0pl1-133 ii exim4-daemon-light [mail-transport-agent] 4.92-7 ii gnupg 2.2.12-1 Versions of packages popularity-contest suggests: pn anacron pn tor pn torsocks -- debconf information: * popularity-contest/participate: true popularity-contest/submiturls:
