-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Hi, I have observed that, sometimes, when the modem connection goes down, the pppd daemon doesn't always call ip-down - or rather, not /etc/ppp/ip-down.local. The pppd daemon calls /etc/ppp/ip-up when the connection goes up, and /etc/ppp/ip-down when it goes down. Those scripts, written by SuSE, call in turn /etc/ppp/ip-up.local and /etc/ppp/ip-down.local, where we can place our customization. I employ those scripts (.local) to launch mail fetch/send cycles and a few things more, like clock sync. In fact, ip-down is a symlink to ip-up: there is only one script, but with two different sections based on the basename. The "down" section code of ip-down contains this: ip-down) restore_nameservers isdn_restartinterface start_firewall # call ip-down.local if it exists and is executable: if test -x /etc/ppp/ip-down.local ; then /etc/ppp/ip-down.local "$@" | logger -p security.notice -t ip-down.local > /dev/null & fi ... For example, tonight it failed. I can see that the pppd daemon calls ip-down: Nov 7 23:58:29 nimrodel pppd[7913]: Terminating connection due to lack of activity. Nov 7 23:58:29 nimrodel pppd[7913]: Connect time 4.4 minutes. Nov 7 23:58:29 nimrodel pppd[7913]: Sent 29179 bytes, received 144156 bytes. Nov 7 23:58:29 nimrodel pppd[7913]: Script /etc/ppp/ip-down started (pid 9097) Nov 7 23:58:29 nimrodel pppd[7913]: sent [LCP TermReq id=0x6 "Link inactive"] Nov 7 23:58:29 nimrodel pppd[7913]: rcvd [LCP TermAck id=0x6] Nov 7 23:58:29 nimrodel pppd[7913]: Connection terminated. Nov 7 23:58:29 nimrodel pppd[7913]: Waiting for 1 child processes... Nov 7 23:58:29 nimrodel pppd[7913]: script /etc/ppp/ip-down, pid 9097 * Nov 7 23:58:30 nimrodel pppd[7913]: Terminating on signal 15 * Nov 7 23:58:30 nimrodel pppd[7913]: sending SIGTERM to process 9097 * Nov 7 23:58:30 nimrodel pppd[7913]: Exit. Nov 7 23:58:29 nimrodel snort: pcap_loop: recvfrom: Network is down But ip-down does not run, it doesn't print anything. Normally, it would print something like this, at least: Nov 4 03:27:39 nimrodel ip-down: SuSEfirewall2: Warning: ip6tables does not support state matching. Extended IPv6 support disabled. _________________________^^^^^^^ but sometimes, like tonight, it doesn't print. Some times it runs, sometimes it doesn't. An intermittent failure... In fact, looking again at it, I think pppd is killing the script ip-down ("sending sigterm..."). Why? When it works, the log is somewhat different (the differences are marked with an *): Nov 7 21:52:41 nimrodel pppd[32132]: Terminating connection due to lack of activity. Nov 7 21:52:41 nimrodel pppd[32132]: Connect time 3.5 minutes. Nov 7 21:52:41 nimrodel pppd[32132]: Sent 42882 bytes, received 86405 bytes. Nov 7 21:52:41 nimrodel pppd[32132]: Script /etc/ppp/ip-down started (pid 649) Nov 7 21:52:41 nimrodel pppd[32132]: sent [LCP TermReq id=0x6 "Link inactive"] Nov 7 21:52:41 nimrodel pppd[32132]: rcvd [LCP TermAck id=0x6] Nov 7 21:52:41 nimrodel pppd[32132]: Connection terminated. Nov 7 21:52:41 nimrodel pppd[32132]: Waiting for 1 child processes... Nov 7 21:52:41 nimrodel pppd[32132]: script /etc/ppp/ip-down, pid 649 * Nov 7 21:52:44 nimrodel pppd[32132]: Script /etc/ppp/ip-down finished (pid 649), status = 0x0 Nov 7 21:52:44 nimrodel pppd[32132]: Exit. Where should I loot at? Ideas? (I have SuSE 9.3, but I have seen this behavior previously, I think). - -- Cheers, Carlos Robinson -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.0 (GNU/Linux) Comment: Made with pgp4pine 1.76 iD8DBQFDb+wqtTMYHG2NR9URAgKIAKCTtA0+45JphEBe0igV5gCQpwbOBgCfajcd Qsq5AMZf/w4UQn1SFf4XNQs= =SAVJ -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 The Tuesday 2005-11-08 at 01:06 +0100, I wrote:
I have observed that, sometimes, when the modem connection goes down, the pppd daemon doesn't always call ip-down -
This is a failure log; the sequence is: 11:15:58 - pppd decides to terminate the connection due to lack of activity. - calls script /etc/ppp/ip-down 11:15:58 - script ip-down reports entry 11:16:03 - script ip-down reports modyfing firewall settings 11:16:03 - pppd sends SIGTERM to ip-down, killing it before it can do its job. 11:19:04 - I notice it and manually call ip-kill to clean up. Why does pppd decide to kill ip-down? ip-down had no chance to do all its jobs. The log itself is this: Nov 10 11:15:58 nimrodel pppd[20671]: Terminating connection due to lack of activity. Nov 10 11:15:58 nimrodel pppd[20671]: Connect time 5.1 minutes. Nov 10 11:15:58 nimrodel pppd[20671]: Sent 63619 bytes, received 485374 bytes. Nov 10 11:15:58 nimrodel pppd[20671]: Script /etc/ppp/ip-down started (pid 22743) Nov 10 11:15:58 nimrodel pppd[20671]: sent [LCP TermReq id=0x6 "Link inactive"] Nov 10 11:15:58 nimrodel pppd[20671]: rcvd [LCP TermAck id=0x6] Nov 10 11:15:58 nimrodel pppd[20671]: Connection terminated. Nov 10 11:15:58 nimrodel pppd[20671]: Waiting for 1 child processes... Nov 10 11:15:58 nimrodel pppd[20671]: script /etc/ppp/ip-down, pid 22743 Nov 10 11:15:58 nimrodel ip-down: -> Entrando a /etc/ppp/ip-down - ppp0 /dev/ttyS1 115200 L: 81.41.201.228 R: 80.58.197.105 Prm: Nov 10 11:15:59 nimrodel snort: pcap_loop: recvfrom: Network is down Nov 10 11:16:03 nimrodel ip-down: SuSEfirewall2: Warning: ip6tables does not support state matching. Extended IPv6 support disabled Nov 10 11:16:03 nimrodel pppd[20671]: sending SIGTERM to process 22743 Nov 10 11:16:03 nimrodel pppd[20671]: Exit. --> Terminating connection due to lack of activity. --> Connect time 5.1 minutes. --> Script /etc/ppp/ip-down started --> Terminate Request (Message: "Link inactive" ) --> Disconnecting at Thu Nov 10 11:16:04 2005 Nov 10 11:19:04 nimrodel ip-kill: --> Manual kill (fetchmail, fetchnews, binkd). This is a normal log, for comparison: Nov 10 11:26:08 nimrodel pppd[23408]: Terminating on signal 15 Nov 10 11:26:08 nimrodel pppd[23408]: Connect time 6.5 minutes. Nov 10 11:26:08 nimrodel pppd[23408]: Sent 146728 bytes, received 622066 bytes. Nov 10 11:26:08 nimrodel pppd[23408]: Script /etc/ppp/ip-down started (pid 24384) Nov 10 11:26:08 nimrodel pppd[23408]: sent [LCP TermReq id=0x6 "User request"] Nov 10 11:26:08 nimrodel ip-down: -> Entrando a /etc/ppp/ip-down - ppp0 /dev/ttyS1 115200 L: 81.41.198.184 R: 80.58.197.102 Prm: Nov 10 11:26:08 nimrodel snort: pcap_loop: recvfrom: Network is down Nov 10 11:26:08 nimrodel ip-down: SuSEfirewall2: Warning: ip6tables does not support state matching. Extended IPv6 support disabled Nov 10 11:26:10 nimrodel ip-down: -> Saliendo de /etc/ppp/ip-down - ppp0 /dev/ttyS1 115200 L: 81.41.198.184 R: 80.58.197.102 Prm: Nov 10 11:26:10 nimrodel ip-down.local: -> Llamando a /etc/ppp/ip-down.local ppp0 /dev/ttyS1 115200 L: 81.41.198.184 R: 80.58.197.102 Prm: Nov 10 11:26:10 nimrodel fetchmail[24043]: terminated with signal 15 Nov 10 11:26:16 nimrodel ip-down.local: --> Down ppp0 Recvd/Snt: 622066/146728 in 387 S. Nov 10 11:26:16 nimrodel ip-down.local: -> Saliendo de /etc/ppp/ip-down.local - ppp0 /dev/ttyS1 115200 L: 81.41.198.184 R: 80.58.197.102 Prm: It is seen there the entry and exit points to ip-down. - -- Cheers, Carlos Robinson -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.0 (GNU/Linux) Comment: Made with pgp4pine 1.76 iD8DBQFDc+PdtTMYHG2NR9URAi41AJ4luPkwv6dgjX1x+xXdpfGxvV4GtgCcDU1a +Qg7onK17YLK0EcUhPsbfi4= =8Fs8 -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 The Friday 2005-11-11 at 01:20 +0100, I wrote:
The Tuesday 2005-11-08 at 01:06 +0100, I wrote:
I have observed that, sometimes, when the modem connection goes down, the pppd daemon doesn't always call ip-down -
This is a failure log; the sequence is:
11:15:58 - pppd decides to terminate the connection due to lack of activity. - calls script /etc/ppp/ip-down 11:15:58 - script ip-down reports entry 11:16:03 - script ip-down reports modyfing firewall settings 11:16:03 - pppd sends SIGTERM to ip-down, killing it before it can do its job. 11:19:04 - I notice it and manually call ip-kill to clean up.
Why does pppd decide to kill ip-down? ip-down had no chance to do all its jobs.
To learn what was happening, I wrote a hack to /etc/ppp/ip-down script; the key is that I decided to trap the signal SIGTERM, and also I added some trace points (echo to log): ip-down) #CER: pppd sometimes kills ip-down with sigterm before time. trap 'logger -s -t $BASENAME -p mail.warn "SIGTERM TRAPPED!" ; "echo" ' SIGTERM logger -t $BASENAME -p mail.debug " -> ip-down code: restore_nameservers" restore_nameservers logger -t $BASENAME -p mail.debug " -> ip-down code: isdn_restartinterface" isdn_restartinterface logger -t $BASENAME -p mail.debug " -> ip-down code: start_firewall" start_firewall logger -t $BASENAME -p mail.debug " -> ip-down code: ip-down.local?" # call ip-down.local if it exists and is executable: if test -x /etc/ppp/ip-down.local ; then logger -t $BASENAME -p mail.debug " -> ip-down code: call ip-down.local" /etc/ppp/ip-down.local "$@" | logger -p security.notice -t ip-down.local > /dev/null & fi logger -t $BASENAME -p mail.debug " -> ip-down code: ip_resend hook" # ip_resend hook test "$IP_RESEND" = "yes" -a -x /usr/sbin/ip_resend && \ /usr/sbin/ip_resend -o $INTERFACE $IP_RESEND_PARAMETER logger -t $BASENAME -p mail.debug " -> ip-down code: any ip-down.d scripts?" # run additional scripts if they exist if [ -d /etc/ppp/ip-down.d ]; then for SCRIPT in /etc/ppp/ip-down.d/*; do [ -d $SCRIPT -o ! -x $SCRIPT ] && continue; # ignore backup files and leftovers from rpm case $SCRIPT in *.rpmsave|*.rpmnew|*rpmorig|*~) continue ;; esac $SCRIPT "$@" | logger -p security.notice -t $SCRIPT > /dev/null & done fi logger -t $BASENAME -p mail.debug " -> ip-down code: end" #run_ifdown #CER: pppd sometimes kills ip-down with sigterm before time. trap - SIGTERM ;; The problem only happens very occasionally, but tonight it happened; see the log: Dec 9 01:22:11 nimrodel ip-down: -> Entrando a /etc/ppp/ip-down - ppp0 /dev/ttyS1 115200 L: 81.41.201.248 R: 80.58.197.105 Prm: Dec 9 01:22:12 nimrodel ip-down: -> ip-down code: restore_nameservers Dec 9 01:22:12 nimrodel ip-down: -> ip-down code: isdn_restartinterface Dec 9 01:22:12 nimrodel ip-down: -> ip-down code: start_firewall Dec 9 01:22:18 nimrodel ip-down: SIGTERM TRAPPED! Dec 9 01:22:18 nimrodel ip-down: -> ip-down code: ip-down.local? Dec 9 01:22:18 nimrodel ip-down: -> ip-down code: call ip-down.local Dec 9 01:22:18 nimrodel ip-down: -> ip-down code: ip_resend hook Dec 9 01:22:18 nimrodel ip-down: -> ip-down code: any ip-down.d scripts? Dec 9 01:22:18 nimrodel ip-down: -> ip-down code: end Dec 9 01:22:18 nimrodel ip-down: -> Saliendo de /etc/ppp/ip-down Dec 9 01:22:18 nimrodel ip-down.local: -> Llamando a /etc/ppp/ip-down.local ppp0 /dev/ttyS1 115200 L: 81.41.201.248 R: 80.58.197.105 Prm: When the script (/etc/ppp/ip-down) was waiting for the call to "/sbin/SuSEfirewall2" to return (for six seconds), pppd decided to stop waiting and sent a SIGTERM signal to /etc/ppp/ip-down, which I trapped and ignored. I noticed that this happened while the daily cron jobs were running, probably the updatedb part, having the system HD pretty occupied, so that the call to SuSEfirewall2 took longer than normal. Trapping SIGTERM solves the issue. - -- Cheers, Carlos Robinson -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.0 (GNU/Linux) Comment: Made with pgp4pine 1.76 iD8DBQFDmNRhtTMYHG2NR9URAs18AJsE+6yJRs9dgFsrpJwXx3V/Q9VC6gCffNRy PAk3uX88SKDtiadzZjLmfhc= =tU5q -----END PGP SIGNATURE-----
participants (1)
-
Carlos E. R.