Garbled apinger messages in the system log



  • I'm running snapshot 2.0-RC1 (i386)
    built on Mon Mar 7 12:03:17 EST 2011

    In system log I see entries of the form:

    Mar 10 11:34:54 apinger: alarm canceled: GW_WAN(F¶óýÔxÙ?;ßOM-^MM-^WnÚ?o^RM-^CÀÊ¡Ý?\M-^OÂõ(\ß?Õxé&1^HÜ?j¼tM-^S^X^DÞ?M-^MM-^Wn^RM-^CÀÚ?ö(\M-^OÂõØ?) *** down ***
    Mar 10 11:35:02 check_reload_status: reloading filter
    Mar 10 11:35:04 check_reload_status: reloading filter
    Mar 10 11:35:14 apinger: ALARM: GW_WAN(^B+M-^G^VÙÎß?ßOM-^MM-^Wn^RÛ?^Y^DV^N-²Ý?shM-^Qí|?Ý?ºI^L^B+M-^GÞ?w¾M-^^Z/ÝÜ?þÔxé&1à?Õxé&1^HÜ?) *** down ***
    Mar 10 11:35:16 apinger: alarm canceled: GW_WAN(^B+M-^G^VÙÎß?-²M-^]ï§ÆÛ?o^RM-^CÀÊ¡Ý?¤p= ×£Ø?ºI^L^B+M-^GÞ?w¾M-^
    ^Z/ÝÜ?þÔxé&1à?Õxé&1^HÜ?) *** down ***
    Mar 10 11:35:24 check_reload_status: reloading filter

    My WAN link is a PPP link to my ISP. At the time it was down because ppp had dropped out and ddn't automatically restore itself. After I successfully restarted the WAN link the garbled message was not in the system log when next I looked.



  • Here are the apinger reports from bootup to around the time I reset the hurricane electric IPV4 "remote tunnel endpoint". I deleted some of the garbled entries in between the two endpoints of the segment in order to reduce the size of the post (and because they didn't seem to add any value).

    clog /var/log/system.log | grep apinger

    Mar 10 17:09:27 pfsense apinger: Starting Alarm Pinger, apinger(62457)
    Mar 10 17:09:38 pfsense apinger: ALARM: HE_NET(2001:470:1f04:14b3::1)  *** down ***
    Mar 10 17:09:46 pfsense apinger: Exiting on signal 15.
    Mar 10 17:09:48 pfsense apinger: Starting Alarm Pinger, apinger(51188)
    Mar 10 17:09:59 pfsense apinger: ALARM: HE_NET(2001:470:1f04:14b3::1)  *** down ***
    Mar 10 17:10:43 pfsense apinger: ALARM: GW_WAN(����x��?^FM-^AM-^UCM-^Kl�?�tM-^S^X^DV�?j�tM-^S^X^D�?M-^ZM-^YM-^YM-^YM-^YM-^Y�?T��M-^[� �?�tM-^S^X^DV�?DM-^Kl����?)  *** down ***
    Mar 10 17:10:48 pfsense apinger: Error while feeding rrdtool: Broken pipe
    Mar 10 17:10:48 pfsense kernel: pid 51188 (apinger), uid 0: exited on signal 11
    Mar 10 17:13:22 pfsense apinger: Starting Alarm Pinger, apinger(49293)
    Mar 10 17:13:32 pfsense apinger: ALARM: HE_NET(2001:470:1f04:14b3::1)  *** down ***
    Mar 10 17:14:21 pfsense apinger: ALARM: GW_WAN(�E�����?Zd;�OM-^M�?Nb^PX9��?^L^B+M-^G^V��?X9��v��?R�^^M-^E�Q�? ףp= �?�rhM-^Q�|�?)  *** down ***
    Mar 10 17:14:27 pfsense apinger: alarm canceled: GW_WAN(M-^C�ʡE��?�M-^^Z/�$�?��v�M-^^Z�?^T�G�z^T�?X9��v��?R�^^M-^E�Q�? ףp= �?��x�&1�?)  *** down ***
    Mar 10 17:14:37 pfsense apinger: ALARM: GW_WAN( ףp= �?��"���?)  *** down *** Mar 10 17:15:13 pfsense apinger: alarm canceled: GW_WAN(}?5^�I�?^PX9��v�?^DV^N-�M-^]�?ffffff�?M-^VCM-^Kl���?ffffff�?�G�z^T��?^?j�tM-^S^X�?)  *** down *** Mar 10 17:15:23 pfsense apinger: ALARM: GW_WAN(���x�&�?^H�^\Zd;�?��K7M- A�?�M-^]���K�?����Mb�?hM-^Q�|?5�?uM-^S^X^DV^N�?Zd;�OM-^M�?)  *** down *** Mar 10 17:15:23 pfsense apinger: alarm canceled: GW_WAN(���x�&�?^H�^\Zd;�?��K7M- A�?�M-^]���K�?����Mb�?hM-^Q�|?5�?uM-^S^X^DV^N�?Zd;�OM-^M�?)  *** down *** Mar 10 17:16:27 pfsense apinger: ALARM: GW_WAN(M-^Xn^RM-^C���?^RM-^C�ʡE�?�M-^]���K�?�M-^]���K�?\M-^O��(\�?M-^^���K7�?^PX9��v�?)  *** down *** Mar 10 17:16:32 pfsense apinger: alarm canceled: GW_WAN(M-^Xn^RM-^C���?^RM-^C�ʡE�?+M-^G^V����?�"��~j�?m������?^PX9��v�?M-^MM-^Wn^RM-^C��?^H�^\Zd;�?)  *** down *** Mar 10 17:17:12 pfsense apinger: ALARM: GW_WAN(+M-^G^V����?���Mb^P�?7M- A���?uM-^S^X^DV^N�?M-^C�ʡE��? ףp= �?�G�z^T��?;�OM-^MM-^Wn�?)  *** down ***
    Mar 10 17:17:40 pfsense apinger: alarm canceled: GW_WAN(R�^^M-^E�Q�?Nb^PX9��?^PX9��v�?^L^B+M-^G^V��?= ףp=�?ffffff�?^RM-^C�ʡE�?��~j�t�?)  *** down ***
    Mar 10 17:18:19 pfsense apinger: ALARM: GW_WAN(�$^FM-^AM-^UC�?� �rhM-^Q�?ˡE����?�^^M-^E�Q��?�~j�tM-^S�?J^L^B+M-^G^V�?��x�&1�?R�^^M-^E�Q�?)  *** down ***
    Mar 10 17:18:24 pfsense apinger: alarm canceled: GW_WAN(�$^FM-^AM-^UC�?� �rhM-^Q�?ˡE����?�^^M-^E�Q��?���x�&�?�|?5^��?7M- A���?^B+M-^G^V���?)  *** down *** Mar 10 17:18:35 pfsense apinger: ALARM: GW_WAN(d;�OM-^MM-^W�?�"��~j�?shM-^Q�|?�?X9��v��?�S��M-^[��??5^�I^L�?�E�����?J^L^B+M-^G^V�?)  *** down *** Mar 10 17:18:57 pfsense apinger: alarm canceled: GW_WAN(^?j�tM-^S^X�?M-^Kl�����?w�M-^_^Z/��?�$^FM-^AM-^UC�?/�$^FM-^AM-^U�?M-^Q�|?5^�?F����x�?M-^Q�|?5^�?)  *** down *** Mar 10 17:19:14 pfsense apinger: ALARM: GW_WAN(�^Z/�$^F�?H�z^T�G�?7M- A���?9��v�M-^_�?uM-^S^X^DV^N�?��"��~�?^B+M-^G^V���?/�$^FM-^AM-^U�?)  *** down ***
    Mar 10 17:19:26 pfsense apinger: alarm canceled: GW_WAN(���x�&�?\M-^O��(\�?��(\M-^O��?-�M-^]����?��x�&1�?d;�OM-^MM-^W�?^L^B+M-^G^V��?�&1^H�^\�?)  *** down ***
    Mar 10 17:19:36 pfsense apinger: ALARM: GW_WAN(H�z^T�G�?���x�&�?M-^ZM-^YM-^YM-^YM-^YM-^Y�?M-^Kl�����?ףp= ��?�OM-^MM-^Wn^R�?�z^T�G��?Nb^PX9��?)  *** down ***
    Mar 10 17:21:00 pfsense apinger: Exiting on signal 15.
    Mar 10 17:21:02 pfsense apinger: Starting Alarm Pinger, apinger(40386)
    Mar 10 17:21:14 pfsense apinger: ALARM: HE_NET(2001:470:1f04:14b3::1)  *** down ***
    Mar 10 17:24:14 pfsense apinger: ALARM: GW_WAN(M-^C�ʡE��?5^�I^L^B�?^FM-^AM-^UCM-^Kl�?Nb^PX9��?M-^VCM-^Kl���?M-^O��(\M-^O�?M-^S^X^DV^N-�?)  *** down ***
    Mar 10 17:24:24 pfsense apinger: alarm canceled: GW_WAN(M-^S^X^DV^N-�?}?5^�I�?^T�G�z^T�?�����M�?M-^G^V���S�?V^N-�M-^]��?/�$^FM-^AM-^U�?^B+M-^G^V���?)  *** down ***

    Mar 10 17:57:36 pfsense apinger: alarm canceled: GW_WAN(�Q�^^M-^E��?M-^G^V���S�?!�rhM-^Q��?/�$^FM-^AM-^U�?7M- A���?5^�I^L^B�?^W���S��?�M-^_^Z/�$�?)  *** down *** Mar 10 17:58:21 pfsense apinger: ALARM: GW_WAN(;�OM-^MM-^Wn�?m������?�"��~j�?shM-^Q�|?�?R�^^M-^E�Q�?^L^B+M-^G^V��?��K7M- A�?�������?)  *** down *** Mar 10 17:58:27 pfsense apinger: Exiting on signal 15. Mar 10 17:58:29 pfsense apinger: Starting Alarm Pinger, apinger(49037) Mar 10 17:58:39 pfsense apinger: ALARM: HE_NET(2001:470:1f04:14b3::1)  *** down *** Mar 10 17:59:06 pfsense apinger: ALARM: GW_WAN(�E�����?J^L^B+M-^G^V�?^RM-^C�ʡE�?7M- A���?^�I^L^B+�?M-^Xn^RM-^C���?��v�M-^_^Z�?^_M-^E�Q�^^�?)  *** down ***
    Mar 10 17:59:07 pfsense apinger: alarm canceled: GW_WAN(�E�����?J^L^B+M-^G^V�?^RM-^C�ʡE�?7M- A`���?^�I^L^B+�?9��v�M-^_�?^PX9��v�?^_M-^E�Q�^^�?)  *** down ***

    Mar 10 19:01:21 pfsense apinger: ALARM: GW_WAN(?5^�I^L�?���x�&�?����x��?^H�^\Zd;�?q= ףp�?X9��v��?M-^E�Q�^^M-^E�?^[/�$^FM-^A�?)  *** loss ***
    Mar 10 19:02:08 pfsense apinger: alarm canceled: GW_WAN(`��"���?�I^L^B+M-^G�?M-^O��(\M-^O�?!�rhM-^Q��?�G�z^T��?M-^G^V���S�?333333�?M-^C�ʡE��?)  *** loss ***
    Mar 10 19:02:25 pfsense apinger: alarm canceled: HE_NET(2001:470:1f04:14b3::1)  *** down ***
    [/quote]


  • Rebel Alliance Developer Netgate

    Is that on a standard 2.0 image or are you on the ipv6 code?



  • @jimp:

    Is that on a standard 2.0 image or are you on the ipv6 code?

    IPv6.


  • Rebel Alliance Developer Netgate

    This may be a side effect of the ipv6 code. I haven't heard of that happening on a stock 2.0 image, and there are probably several places in the ipv6 where such a buglet may have slipped in. I moved the thread to the ipv6 board in case someone else there might have seen it.



  • Not sure if this is related to the IPv6 code at all. Never seen it before though.



  • @databeestje:

    Not sure if this is related to the IPv6 code at all. Never seen it before though.

    I thought since apinger was reporting the garbled message and the apinger application on my system is dated 2009 that it probably was more an apinger problem than a problem in the IPv6 mods. But maybe the IPv6 mods touch a file used by apinger in a way that causes confusion in apinger.



  • Here are the current apinger configuration file and status file.

    It is perhaps curious that though there are 4 targets in the configuration file (SROUTE1 seemingly duplicating SROUTE0) there seem to be only 3 entries in the status file.

    more /var/etc/apinger.conf

    pfSense apinger configuration file. Automatically Generated!

    User and group the pinger should run as

    user "root"
    group "wheel"

    Mailer to use (default: "/usr/lib/sendmail -t")

    #mailer "/var/qmail/bin/qmail-inject"

    Location of the pid-file (default: "/var/run/apinger.pid")

    pid_file "/var/run/apinger.pid"

    Format of timestamp (%s macro) (default: "%b %d %H:%M:%S")

    #timestamp_format "%Y%m%d%H%M%S"

    status {
           ## File where the status information whould be written to
           file "/tmp/apinger.status"
           ## Interval between file updates
           ## when 0 or not set, file is written only when SIGUSR1 is received
           interval 5s
    }

    ########################################

    RRDTool status gathering configuration

    Interval between RRD updates

    rrd interval 60s;

    These parameters can be overriden in a specific alarm configuration

    alarm default {
           command on "/usr/local/sbin/pfSctl -c 'filter reload'"
           command off "/usr/local/sbin/pfSctl -c 'filter reload'"
           combine 10s
    }

    "Down" alarm definition.

    This alarm will be fired when target doesn't respond for 30 seconds.

    alarm down "down" {
           time 10s
    }

    "Delay" alarm definition.

    This alarm will be fired when responses are delayed more than 200ms

    it will be canceled, when the delay drops below 100ms

    alarm delay "delay" {
           delay_low 200ms
           delay_high 500ms
    }

    "Loss" alarm definition.

    This alarm will be fired when packet loss goes over 20%

    it will be canceled, when the loss drops below 10%

    alarm loss "loss" {
           percent_low 10
           percent_high 20
    }

    target default {
           ## How often the probe should be sent  
           interval 1s
           
           ## How many replies should be used to compute average delay
           ## for controlling "delay" alarms
           avg_delay_samples 10
           
           ## How many probes should be used to compute average loss
           avg_loss_samples 50

    ## The delay (in samples) after which loss is computed
           ## without this delays larger than interval would be treated as loss
           avg_loss_delay_samples 20

    ## Names of the alarms that may be generated for the target
           alarms "down","delay","loss"

    ## Location of the RRD
           #rrd file "/var/db/rrd/apinger-%t.rrd"
    }
    target "121.50.212.5" {
           description "GW_WAN"
           srcip "203.144.5.171"
           alarms override "loss","delay","down";
           rrd file "/var/db/rrd/GW_WAN-quality.rrd"
    }

    target "192.168.211.217" {
           description "SROUTE0"
           srcip "192.168.211.173"
           alarms override "loss","delay","down";
           rrd file "/var/db/rrd/SROUTE0-quality.rrd"
    }

    target "192.168.211.217" {
           description "SROUTE1"
           srcip "192.168.211.173"
           alarms override "loss","delay","down";
           rrd file "/var/db/rrd/SROUTE1-quality.rrd"
    }

    target "2001:470:1f04:14b3::1" {
           description "HE_NET"
           srcip "2001:470:1f04:14b3::2"
           alarms override "loss","delay","down";
           rrd file "/var/db/rrd/HE_NET-quality.rrd"
    }

    more /tmp/apinger.status

    sh<91><ed>|?

    <dd>?<bc>t<93>^X^DV<d6>?^_<85><eb>Q<b8>^^<d5>?'<ac>^\Z<e0>?ESC/</e0></ac></d5></b8></eb></d6></bc></dd>

    <dd>$^F<81><d5>?<d1>"<db><f9>~j<e0>?^Y^DV^N- <b2><d5>? <c5><b0>rh<91></b0></c5></d5></b2></e0></f9></db></d1></d5></dd>

    <dd>?|203.144.5.171|GW_WAN|56|55|1299819488|40.422ms||none
    192.168.211.217|192.168.211.173|SROUTE1|56|55|1299819488|0.473ms||none
    2001:470:1f04:14b3::1|2001:470:1f04:14b3::2|HE_NET|56|0|0|0.000ms||down
    #</dd></ed>

    I guess the two apinger targets seemingly the same are from two static routes: 192.168.217.0/24 and 192.168.51.0/24 are both accessible through 192.168.211.217.


  • Rebel Alliance Developer Netgate

    Looks like the entry with 203.144.5.171 is corrupt, that "sh …" stuff shouldn't be there. It should look like the other lines.

    Side note: The timestamp is kept on some files even if their contents have been updated. It's unlikely that your apinger binary is really from 2009.



  • Ok, that is a upgrade bug that exists in 2.0-RC1. When we originally wrote the static route upgrade code it appears we've forgotten to collapse the routes by target. This is a clear bug.

    2 routes pointing to the same IP should always result in a single target. This was clearly a oversight.

    Is this a install upgraded from 1.2.3 or is this a upgrade from a 2.0-RC or BETA install



  • @databeestje:

    Is this a install upgraded from 1.2.3 or is this a upgrade from a 2.0-RC or BETA install

    Upgrade from 1.2.3 through various 2.0 BETA snapshot builds.



  • Aha! That explains it



  • Can you please provide the 1.2.3 config static route section?



  • Create a 1.2.3 vm, create 2 routes to a lan IP. Upgrade that and it should trigger it


Locked