search

raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.22k stars 5.03k forks source link

Unexpected interrupt: 8 on SC16IS752 #2529

Closed hardikharpal closed 6 years ago

hardikharpal commented 6 years ago

Hi,

I am Interfacing SC16IS752(custom board) on SPI0 of raspberry pi 3B.I have latest stretch lite version as on 24-April-2018. I created dts file and generated dtbo file and copied dtbo to /boot/overlay. Also edited /boot/config.txt to load overlay. `/dts-v1/; /plugin/; / { compatible = "brcm,bcm2835", "brcm,bcm2708", "brcm,bcm2709";

    fragment@0 {
    target = <&spidev0>;
    __overlay__ {
        status = "disabled";
    };
};

    fragment@1 {
            target = <&gpio>;
            __overlay__ {
                    spi0_pins: spi0_pins {
                            brcm,pins = <9 10 11>;
                            brcm,function = <4>; /* alt 0 */
                    };

                    spi0_cs_pins: spi0_cs_pins {
                            brcm,pins = <8>;
                            brcm,function = <1>; /* output */
                    };
            };
    };

    fragment@2 {
    target = <&spi0>;
    frag1: __overlay__ {
        #address-cells = <1>;
        #size-cells = <0>;
        pinctrl-names = "default";
        pinctrl-0 = <&spi0_pins &spi0_cs_pins>;
        cs-gpios = <&gpio 8 1>;
        status = "okay";

        sc16is752: sc16is752@0 {
            compatible = "nxp,sc16is752";
            reg = <0>; /* CE0 */
            clocks = <&sc16is752_clk>;
            interrupt-parent = <&gpio>;
            interrupts = <24 2>; /* IRQ_TYPE_EDGE_FALLING */
            gpio-controller;
            #gpio-cells = <2>;
            spi-max-frequency = <4000000>;

            sc16is752_clk: sc16is752_clk {
               compatible = "fixed-clock";
               #clock-cells = <0>;
               clock-frequency = <14745600>;
            };
        };
    };
    };

    fragment@3 {
            target = <&aux>;
            __overlay__ {
                    status = "okay";
            };
    };

__overrides__ {
  int_pin = <&sc16is752>,"interrupts:0";
};

};` My problem is when open port on minicom . IRQ pin remains low for all time and UART communication not working. Getting below message on dmesg .

[1293.489435] sc16is7xx spi0.0: ttySC0: Unexpected interrupt: 8 [ 1293.490328] sc16is7xx spi0.0: ttySC0: Unexpected interrupt: 0 [ 1293.490460] sc16is7xx spi0.0: ttySC0: Unexpected interrupt: 0

Getting bellow output for sudo vcdbg log msg

002047.676: dtparam: spi=on 002062.027: brfs: File read: 1630 bytes 002075.726: brfs: File read: /mfs/sd/overlays/sc16is752-spi0.dtbo 002097.865: Loaded overlay 'sc16is752-spi0'

So I tried with SC16IS750 (sparkfun breakout board) which has one UART channel. I have connected to same pins on raspberry pi and made changes(just replaced sc16is752 with sc16is750) to dts file and generated dtbo file copied to /boot/overlay and edited /boot/config.txt to load overlay. And It works perfectly able to send data and receive data.

Am I missing something ? Any Hint will be Helpful. I read here https://raw.githubusercontent.com/janztec/empc-arpi-linux/rpi-3.18.y/drivers/tty/serial/sc16is7xx.c that sc16is7xx_startup() one comment is there

/ ama 2016-12: fixed error message "unexpected interrupt: 8" in dmesg by added mdelay(1) without delay, after enabling the interrupts in IER, set_baud/set_termios is immediatly called, enables enhanced register ("config mode") with LCR = 0xBF and the first interrupt occurs at the same time, resulting in reading the IIR interrupt status register in the wrong mode. This problematic time window, from enabling the interrupts to handling them, is about 100µs, so a delay of 1000µs=1ms was choosen/ mdelay(1);

But in case of raspberry pi driver for SC16IS7XX https://github.com/raspberrypi/linux/blob/rpi-4.14.y/drivers/tty/serial/sc16is7xx.c the delay is no there.

Do you think this is the cause of my issue?

Thanks and Regards, Hardik Harpal

6by9 commented 6 years ago

Can you verify that your SC16IS752 works on SPI1 as there is already an overlay for that which is known to work. There was work on the driver with #2241 in February that solved some problems with it.

Your random hack is from a 3.18 kernel - a lot has changed between 3.18 and 4.14.

pelwell commented 6 years ago

I'm guessing the custom board has a 40-pin header, in which case changing the SPI bus is hard.

I do now have an SC16IS752 board, so I'll take a quick look.

hardikharpal commented 6 years ago

@pelwell @6by9 yes I tested with SPI1 but issue was same. Yeah its 40 pin header but as It did not worked I tested with Jumper wires for SPI1 But today I am able to communicate with SC16IS752. What I have done is take blank PCB and only soldered SC16IS752 related components and it worked :) . I am guessing its because of 12pf Capacitors for 14.74567 MHz crystal. I will change it to 22pf and let you know, what is wrong with my hardware.

But ,

sc16is7xx spi0.0: ttySC0: Unexpected interrupt: 8

Now only this message comes in dmesg every time when I open port using minicom but only one time. I guess that is because the delay required as I mentioned in my issue post.

pelwell commented 6 years ago

I've not seen the "Unexpected interrupt: 8" message that you get, so I can't really test the patch. However, building a custom kernel doesn't take so long with a 3B or 3B+ - a few hours, not overnight. Follow our kernel building guide, modifying the sc16is7xx driver by adding the delay, then see if the message goes away.

hardikharpal commented 6 years ago

@pelwell sure I will do that and I will update the result here. I am newbie to linux/raspberypi .

I have query out of this issue: Is it possible to read/write GPIO0-GPIO7 of SC16IS752? How can I do that?

pelwell commented 6 years ago

The various sc16is7xx overlays declare the devices as GPIO controllers, and the driver supports this feature, so Linux creates an entry in /sys/class/gpio (for me it's gpiochip504). Using this you can export and control each of the GPIO pins.

The sysfs GPIO mechanism is documented here.

hardikharpal commented 6 years ago

After Adding mdelay(1); "Unexpected interrupt: 8" is not coming when I open port.

pelwell commented 6 years ago

Thanks for the feedback - I'll patch our kernel tree.

paulenuta commented 6 years ago

Hi, I got same messages "Unexpected interrupt:" mostly ":0", ":8" only sometimes at startup, on a custom board with 2 x SC16IS752IBS on I2C bus, after adding mdelay(1) they still appear but, much less. I have no communication problem, but I'm polling(every 2 seconds) a GPIO on sc16is752 to see if my device is hardware attached. What tests should I do? Thanks a lot, Paul

dmesg
.....
[   20.919081] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[   20.920579] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[   25.995331] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[   25.996840] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[   43.238668] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[   43.240186] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[   45.276452] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[   45.277970] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  118.954099] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  118.955612] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  126.061755] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  126.063279] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  128.097273] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  128.098786] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  136.220751] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  168.668602] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  168.670064] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  194.021112] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  194.022627] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  203.157776] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  203.159290] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  271.098112] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  271.099630] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  277.191823] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  277.193337] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  303.557974] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  303.559431] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  324.855986] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  324.856835] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  325.877898] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  325.878751] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  326.899897] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  326.900746] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  327.921917] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  327.922767] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  328.943881] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  328.944731] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  329.965804] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  329.966655] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  330.988277] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  330.989164] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  332.011295] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  332.012183] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  333.034399] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  333.035291] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  334.057591] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  334.058477] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  335.080988] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  335.081874] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  336.104273] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  336.105160] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  337.127693] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  337.128580] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  338.150931] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  338.151836] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  339.174306] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  339.175213] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  340.197729] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  340.198625] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  341.222065] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  341.222961] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  342.244404] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  342.245294] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  343.270521] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  343.271415] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  344.293987] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  344.294866] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  345.316180] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  345.317029] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  346.338092] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  346.338943] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  362.566841] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  362.567691] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  363.589084] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  363.589934] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  364.611304] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  364.612162] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  365.633416] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  365.634266] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  366.655599] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  366.656467] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  367.677756] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  367.678609] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  368.700343] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  368.701197] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  369.724275] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  369.725128] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  370.746533] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  370.747382] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  371.768445] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  371.769294] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  372.790636] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  372.791486] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  373.812822] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  373.813672] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  374.835029] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  374.835901] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  374.837473] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  375.857951] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  375.858801] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  376.881949] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  377.903961] sc16is7xx_port_irq: 1 callbacks suppressed
[  377.903969] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  377.904818] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  378.925962] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  378.926812] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  379.947866] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  379.948717] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  380.970018] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  380.970868] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  381.992760] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  381.993648] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  383.015974] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  383.016861] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  384.038921] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  384.039808] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  385.062313] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  385.063200] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  386.085995] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  386.086883] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  387.108927] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  387.109815] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  388.132084] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  388.132974] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  636.423028] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  636.423879] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  638.468695] sc16is7xx_port_irq: 2 callbacks suppressed
....
root@raspberrypi:/home/pi# uname -a
Linux raspberrypi 4.14.39-v7+ #2 SMP Tue May 8 09:51:25 EEST 2018 armv7l GNU/Linux

sc16is752-i2c-01.dts

/dts-v1/;
/plugin/;

/ {
    compatible = "brcm,bcm2835", "brcm,bcm2836", "brcm,bcm2708", "brcm,bcm2709"; // Depending on your RPi Board Chip

    fragment@0 {
        target = <&i2c_arm>;        
        __overlay__ {
            #address-cells = <1>;
            #size-cells = <0>;
            status = "okay";

            sc16is752: sc16is752@48 {               // changed to 48 aka 0x48
                compatible = "nxp,sc16is752";
                reg = <0x48>;                       // I2C address
                clocks = <&sc16is752_clk>;
                interrupt-parent = <&gpio>;
                interrupts = <20 2>;                // GPIO20 IRQ_TYPE_EDGE_FALLING
                gpio-controller;
                #gpio-cells = <2>;
                i2c-max-frequency = <400000>;

                sc16is752_clk: sc16is752_1_clk {
                    compatible = "fixed-clock";
                    #clock-cells = <0>;
                    clock-frequency = <18432000>;
                };
            };
        };
    };

    __overrides__ {
        int_pin = <&sc16is752>,"interrupts:0";
        addr = <&sc16is752>,"reg:0";
    };
};

sc16is752-i2c-02.dts

/dts-v1/;
/plugin/;

/ {
    compatible = "brcm,bcm2835", "brcm,bcm2836", "brcm,bcm2708", "brcm,bcm2709"; // Depending on your RPi Board Chip

    fragment@0 {
        target = <&i2c_arm>;       
        __overlay__ {
            #address-cells = <1>;
            #size-cells = <0>;
            status = "okay";

            sc16is752: sc16is752@4D {               // corrected to 4D
                compatible = "nxp,sc16is752";
                reg = <0x4D>;                       // I2C address
                clocks = <&sc16is752_clk>;
                interrupt-parent = <&gpio>;
                interrupts = <16 2>;                // GPIO16 IRQ_TYPE_EDGE_FALLING
                gpio-controller;
                #gpio-cells = <2>;
                i2c-max-frequency = <400000>;

                sc16is752_clk: sc16is752_2_clk {
                    compatible = "fixed-clock";
                    #clock-cells = <0>;
                    clock-frequency = <18432000>;
                };
            };
        };
    };

    __overrides__ {
        int_pin = <&sc16is752>,"interrupts:0";
        addr = <&sc16is752>,"reg:0";
    };
};

Update: My initial loop was opened serial port and read the gpio, now, first I read the gpio and only if device is present it open serial and send data, but still message appear on dmesg.

[  854.337999] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  854.338851] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  856.449865] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  856.450717] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[  858.668596] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: a
[  858.669448] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: a
[  860.748607] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: a
[  860.749459] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: a
paulenuta commented 6 years ago

Update: I have resurrected an older pi installation and using same custom board with 2 x SC16IS752IBS on I2C bus I have no "Unexpected interrupt: 0" in dmesg.

root@raspberrypi:/home/pi# ./serial_write.py /dev/ttySC0
/dev/ttySC0  was setup

 Start with:  /dev/ttySC0
<
/dev/ttySC0  opened
@Write line:  0
 data was sent to printer /dev/ttySC0
/dev/ttySC0  closed
>

^CTraceback (most recent call last):
  File "./serial_write.py", line 81, in <module>
    time.sleep(2)
KeyboardInterrupt
root@raspberrypi:/home/pi# uname -a
Linux raspberrypi 4.9.33-v7+ #95 SMP Sun Jun 25 20:36:46 CEST 2017 armv7l GNU/Linux

root@raspberrypi:/home/pi# cat /etc/*release
PRETTY_NAME="Raspbian GNU/Linux 8 (jessie)"
NAME="Raspbian GNU/Linux"
VERSION_ID="8"
VERSION="8 (jessie)"
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"
root@raspberrypi:/home/pi#

root@raspberrypi:/home/pi# dmesg -w
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.9.33-v7+ (peter@lamerx) (gcc version 4.8.3 201401                                                                                                                                                             06 (prerelease) (crosstool-NG linaro-1.13.1-4.8-2014.01 - Linaro GCC 2013.11) )                                                                                                                                                              #95 SMP Sun Jun 25 20:36:46 CEST 2017
[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instructio                                                                                                                                                             n cache
[    0.000000] OF: fdt:Machine model: Raspberry Pi 3 Model B Rev 1.2
[    0.000000] cma: Reserved 8 MiB at 0x3a800000
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] On node 0 totalpages: 241664
[    0.000000] free_area_init_node: node 0, pgdat 80c6ee00, node_mem_map b9faa00                                                                                                                                                             0
[    0.000000]   Normal zone: 2124 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 241664 pages, LIFO batch:31
[    0.000000] percpu: Embedded 14 pages/cpu @b9f63000 s25600 r8192 d23552 u5734                                                                                                                                                             4
[    0.000000] pcpu-alloc: s25600 r8192 d23552 u57344 alloc=14*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pag                                                                                                                                                             es: 239540
[    0.000000] Kernel command line: 8250.nr_uarts=1 bcm2708_fb.fbwidth=656 bcm27                                                                                                                                                             08_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3dc00000 vc_mem.mem_siz                                                                                                                                                             e=0x3f000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUU                                                                                                                                                             ID=c1a66bc0-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait quiet                                                                                                                                                              splash plymouth.ignore-serial-consoles
[    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Memory: 936296K/966656K available (7168K kernel code, 483K rwdata                                                                                                                                                             , 2012K rodata, 1024K init, 778K bss, 22168K reserved, 8192K cma-reserved)
[    0.000000] Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xbb800000 - 0xff800000   (1088 MB)
    lowmem  : 0x80000000 - 0xbb000000   ( 944 MB)
    modules : 0x7f000000 - 0x80000000   (  16 MB)
      .text : 0x80008000 - 0x80800000   (8160 kB)
      .init : 0x80b00000 - 0x80c00000   (1024 kB)
      .data : 0x80c00000 - 0x80c78fbc   ( 484 kB)
       .bss : 0x80c7a000 - 0x80d3ca64   ( 779 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000]  Build-time adjustment of leaf fanout to 32.
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] arm_arch_timer: Architected cp15 timer(s) running at 19.20MHz (ph                                                                                                                                                             ys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles:                                                                                                                                                              0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000008] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 43980                                                                                                                                                             46511078ns
[    0.000021] Switching to timer-based delay loop, resolution 52ns
[    0.000316] Console: colour dummy device 80x30
[    0.000337] console [tty1] enabled
[    0.000372] Calibrating delay loop (skipped), value calculated using timer fr                                                                                                                                                             equency.. 38.40 BogoMIPS (lpj=192000)
[    0.000388] pid_max: default: 32768 minimum: 301
[    0.000705] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.000715] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001701] Disabling cpuset control group subsystem
[    0.001858] CPU: Testing write buffer coherency: ok
[    0.001903] ftrace: allocating 22386 entries in 66 pages
[    0.054431] CPU0: update cpu_capacity 1024
[    0.054448] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.054529] Setting up static identity map for 0x100000 - 0x100034
[    0.056736] CPU1: update cpu_capacity 1024
[    0.056743] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.057415] CPU2: update cpu_capacity 1024
[    0.057422] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.058057] CPU3: update cpu_capacity 1024
[    0.058063] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.058149] Brought up 4 CPUs
[    0.058159] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.058163] CPU: All CPU(s) started in HYP mode.
[    0.058167] CPU: Virtualization extensions available.
[    0.058972] devtmpfs: initialized
[    0.070805] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3                                                                                                                                                              rev 4
[    0.071079] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, ma                                                                                                                                                             x_idle_ns: 19112604462750000 ns
[    0.071095] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.071660] pinctrl core: initialized pinctrl subsystem
[    0.072578] NET: Registered protocol family 16
[    0.074904] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.083835] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint                                                                                                                                                              registers.
[    0.083841] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.083996] Serial: AMBA PL011 UART driver
[    0.085993] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.086520] uart-pl011 3f201000.serial: could not find pctldev for node /soc/                                                                                                                                                             gpio@7e200000/uart0_pins, deferring probe
[    0.087039] irq: no irq domain found for /soc/aux@0x7e215000 !
[    0.155010] bcm2835-dma 3f007000.dma: DMA legacy API manager at bb80f000, dma                                                                                                                                                             chans=0x1
[    0.156855] SCSI subsystem initialized
[    0.157016] usbcore: registered new interface driver usbfs
[    0.157093] usbcore: registered new interface driver hub
[    0.157182] usbcore: registered new device driver usb
[    0.163969] raspberrypi-firmware soc:firmware: Attached to firmware from 2017                                                                                                                                                             -05-15 16:57
[    0.165435] clocksource: Switched to clocksource arch_sys_counter
[    0.209885] VFS: Disk quotas dquot_6.6.0
[    0.209960] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.210163] FS-Cache: Loaded
[    0.210409] CacheFiles: Loaded
[    0.222616] NET: Registered protocol family 2
[    0.223510] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.223619] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    0.223803] TCP: Hash tables configured (established 8192 bind 8192)
[    0.223890] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.223931] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.224136] NET: Registered protocol family 1
[    0.224541] RPC: Registered named UNIX socket transport module.
[    0.224546] RPC: Registered udp transport module.
[    0.224550] RPC: Registered tcp transport module.
[    0.224555] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.225699] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counter                                                                                                                                                             s available
[    0.228004] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    0.243998] FS-Cache: Netfs 'nfs' registered for caching
[    0.244977] NFS: Registering the id_resolver key type
[    0.245003] Key type id_resolver registered
[    0.245007] Key type id_legacy registered
[    0.247342] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 2                                                                                                                                                             51)
[    0.247446] io scheduler noop registered
[    0.247452] io scheduler deadline registered (default)
[    0.247708] io scheduler cfq registered
[    0.253405] BCM2708FB: allocated DMA memory fa910000
[    0.253429] BCM2708FB: allocated DMA channel 0 @ bb80f000
[    0.262144] Console: switching to colour frame buffer device 82x26
[    0.267478] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[    0.268095] bcm2835-aux-uart 3f215040.serial: could not get clk: -517
[    0.269352] bcm2835-rng 3f104000.rng: hwrng registered
[    0.269471] vc-cma: Videocore CMA driver
[    0.269477] vc-cma: vc_cma_base      = 0x00000000
[    0.269482] vc-cma: vc_cma_size      = 0x00000000 (0 MiB)
[    0.269487] vc-cma: vc_cma_initial   = 0x00000000 (0 MiB)
[    0.269681] vc-mem: phys_addr:0x00000000 mem_base=0x3dc00000 mem_size:0x3f000                                                                                                                                                             000(1008 MiB)
[    0.284892] brd: module loaded
[    0.293801] loop: module loaded
[    0.293812] Loading iSCSI transport class v2.0-870.
[    0.294340] usbcore: registered new interface driver smsc95xx
[    0.294356] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.520421] Core Release: 2.80a
[    0.520429] Setting default values for core params
[    0.520459] Finished setting default values for core params
[    0.720848] Using Buffer DMA mode
[    0.720854] Periodic Transfer Interrupt Enhancement - disabled
[    0.720859] Multiprocessor Interrupt Enhancement - disabled
[    0.720865] OTG VER PARAM: 0, OTG VER FLAG: 0
[    0.720880] Dedicated Tx FIFOs mode
[    0.721224] WARN::dwc_otg_hcd_init:1032: FIQ DMA bounce buffers: virt = 0xba9                                                                                                                                                             04000 dma = 0xfa904000 len=9024
[    0.721247] FIQ FSM acceleration enabled for :
Non-periodic Split Transactions
Periodic Split Transactions
High-Speed Isochronous Endpoints
Interrupt/Control Split Transaction hack enabled
[    0.721254] dwc_otg: Microframe scheduler enabled
[    0.721301] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x8057cb58
[    0.721311] WARN::hcd_init_fiq:460: FIQ ASM at 0x8057ceb4 length 36
[    0.721322] WARN::hcd_init_fiq:486: MPHI regs_base at 0xbb87a000
[    0.721380] dwc_otg 3f980000.usb: DWC OTG Controller
[    0.721415] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number                                                                                                                                                              1
[    0.721445] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[    0.721491] Init: Port Power? op_state=1
[    0.721496] Init: Power Port (0)
[    0.721699] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    0.721710] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=                                                                                                                                                             1
[    0.721718] usb usb1: Product: DWC OTG Controller
[    0.721725] usb usb1: Manufacturer: Linux 4.9.33-v7+ dwc_otg_hcd
[    0.721733] usb usb1: SerialNumber: 3f980000.usb
[    0.722515] hub 1-0:1.0: USB hub found
[    0.722552] hub 1-0:1.0: 1 port detected
[    0.723168] dwc_otg: FIQ enabled
[    0.723173] dwc_otg: NAK holdoff enabled
[    0.723177] dwc_otg: FIQ split-transaction FSM enabled
[    0.723190] Module dwc_common_port init
[    0.723416] usbcore: registered new interface driver usb-storage
[    0.723623] mousedev: PS/2 mouse device common for all mice
[    0.724653] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[    0.724939] bcm2835-cpufreq: min=600000 max=1200000
[    0.725347] sdhci: Secure Digital Host Controller Interface driver
[    0.725351] sdhci: Copyright(c) Pierre Ossman
[    0.725663] sdhost-bcm2835 3f202000.sdhost: could not get clk, deferring prob                                                                                                                                                             e
[    0.727844] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[    0.727945] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.735242] ledtrig-cpu: registered to indicate activity on CPUs
[    0.735461] hidraw: raw HID events driver (C) Jiri Kosina
[    0.735654] usbcore: registered new interface driver usbhid
[    0.735658] usbhid: USB HID core driver
[    0.736444] vchiq: vchiq_init_state: slot_zero = 0xba980000, is_master = 0
[    0.743052] Initializing XFRM netlink socket
[    0.743075] NET: Registered protocol family 17
[    0.743192] Key type dns_resolver registered
[    0.743672] Registering SWP/SWPB emulation handler
[    0.744379] registered taskstats version 1
[    0.744825] vc-sm: Videocore shared memory driver
[    0.744833] [vc_sm_connected_init]: start
[    0.751301] [vc_sm_connected_init]: end - returning 0
[    0.757436] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud                                                                                                                                                              = 0) is a PL011 rev2
[    0.759027] console [ttyS0] disabled
[    0.759054] 3f215040.serial: ttyS0 at MMIO 0x0 (irq = 220, base_baud = 312500                                                                                                                                                             00) is a 16550
[    0.765667] console [ttyS0] enabled
[    0.766329] sdhost: log_buf @ ba907000 (fa907000)
[    0.845462] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    0.847659] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[    0.847667] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[    0.925570] of_cfs_init
[    0.925760] of_cfs_init: OK
[    0.926236] Waiting for root device PARTUUID=c1a66bc0-02...
[    0.935637] Indeed it is in host mode hprt0 = 00021501
[    1.002606] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    1.005004] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.007148] mmc0: host does not support reading read-only switch, assuming wr                                                                                                                                                             ite-enable
[    1.007448] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.009570] mmc0: new high speed SDHC card at address aaaa
[    1.010205] mmcblk0: mmc0:aaaa SL32G 29.7 GiB
[    1.011851] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    1.013007]  mmcblk0: p1 p2
[    1.016542] random: fast init done
[    1.069720] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. O                                                                                                                                                             pts: (null)
[    1.069771] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    1.074244] devtmpfs: mounted
[    1.075740] Freeing unused kernel memory: 1024K (80b00000 - 80c00000)
[    1.104166] mmc1: new high speed SDIO card at address 0001
[    1.135486] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    1.135626] Indeed it is in host mode hprt0 = 00001101
[    1.333175] systemd[1]: systemd 215 running in system mode. (+PAM +AUDIT +SEL                                                                                                                                                             INUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ -SECCOMP -APPARMOR)
[    1.333545] systemd[1]: Detected architecture 'arm'.
[    1.365758] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[    1.365773] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.366589] hub 1-1:1.0: USB hub found
[    1.366677] hub 1-1:1.0: 5 ports detected
[    1.429921] NET: Registered protocol family 10
[    1.431404] systemd[1]: Inserted module 'ipv6'
[    1.436996] systemd[1]: Set hostname to <raspberrypi>.
[    1.437212] systemd[1]: Initializing machine ID from random generator.
[    1.437428] systemd[1]: Installed transient /etc/machine-id file.
[    1.695495] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    1.789684] systemd[1]: Cannot add dependency job for unit regenerate_ssh_hos                                                                                                                                                             t_keys.service, ignoring: Unit regenerate_ssh_host_keys.service failed to load:                                                                                                                                                              No such file or directory.
[    1.793127] systemd[1]: Starting Forward Password Requests to Wall Directory                                                                                                                                                              Watch.
[    1.793464] systemd[1]: Started Forward Password Requests to Wall Directory W                                                                                                                                                             atch.
[    1.793535] systemd[1]: Expecting device dev-ttyS0.device...
[    1.825964] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    1.825981] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber                                                                                                                                                             =0
[    1.831712] smsc95xx v1.0.5
[    1.920485] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-                                                                                                                                                             1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:cd:a1:f9
[    1.959514] fuse init (API version 7.26)
[    1.991003] i2c /dev entries driver
[    2.247944] systemd-udevd[146]: starting version 215
[    2.844777] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    3.810497] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f2                                                                                                                                                             00000
[    3.936052] tpm_tis_spi spi0.1: 2.0 TPM (device-id 0x1B, rev-id 16)
[    3.996047] tpm tpm0: A TPM error (256) occurred continue selftest
[    3.997756] rtc-ds1307 1-006f: rtc core: registered mcp7941x as rtc0
[    3.997790] rtc-ds1307 1-006f: 64 bytes nvram
[    4.035699] usbcore: registered new interface driver brcmfmac
[    4.168339] brcmfmac: Firmware version = wl0: May 27 2016 00:13:38 version 7.                                                                                                                                                             45.41.26 (r640327) FWID 01-df77e4a7
[    4.490794] systemd-journald[139]: Received request to flush runtime journal                                                                                                                                                              from PID 1
[    5.391388] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    5.391420] brcmfmac: power management disabled
[    5.651574] uart-pl011 3f201000.serial: no DMA platform data
[    6.336792] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[    6.337009] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[    6.722794] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[    6.742355] Adding 102396k swap on /var/swap.  Priority:-1 extents:6 across:2                                                                                                                                                             617340k SSFS
[   10.106304] Bluetooth: Core ver 2.22
[   10.106359] NET: Registered protocol family 31
[   10.106362] Bluetooth: HCI device and connection manager initialized
[   10.106374] Bluetooth: HCI socket layer initialized
[   10.106382] Bluetooth: L2CAP socket layer initialized
[   10.106402] Bluetooth: SCO socket layer initialized
[   10.122021] Bluetooth: HCI UART driver ver 2.3
[   10.122030] Bluetooth: HCI UART protocol H4 registered
[   10.122033] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   10.122176] Bluetooth: HCI UART protocol Broadcom registered
[   10.413761] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   10.413768] Bluetooth: BNEP filters: protocol multicast
[   10.413783] Bluetooth: BNEP socket layer initialized
[   59.046084] random: crng init done
paulenuta commented 6 years ago

I will made a test from a fresh image of Jessie to see how it works.

root@raspberrypi:/home/pi# lsmod
Module                  Size  Used by
bnep                   11959  2
hci_uart               20480  1
btbcm                   7597  1 hci_uart
bluetooth             370485  22 hci_uart,bnep,btbcm
brcmfmac              208935  0
rtc_ds1307             13454  0
brcmutil                9159  1 brcmfmac
sc16is7xx              13373  1
hwmon                  10569  1 rtc_ds1307
cfg80211              542965  1 brcmfmac
snd_bcm2835            23042  1
rfkill                 21072  4 bluetooth,cfg80211
snd_pcm                97920  1 snd_bcm2835
snd_timer              23802  1 snd_pcm
tpm_tis_spi             4066  0
tpm_tis_core            7814  1 tpm_tis_spi
tpm                    32243  2 tpm_tis_spi,tpm_tis_core
spidev                  7314  0
snd                    69677  5 snd_timer,snd_bcm2835,snd_pcm
i2c_bcm2835             6331  0
bcm2835_gpiomem         3823  0
spi_bcm2835             7456  0
uio_pdrv_genirq         3788  0
uio                    10278  1 uio_pdrv_genirq
fixed                   3061  0
i2c_dev                 7159  0
fuse                  100998  3
ipv6                  409752  48
root@raspberrypi:/home/pi# sudo vcdbg log msg
001316.670: HDMI:EDID error reading EDID block 0 attempt 0
001317.933: HDMI:EDID error reading EDID block 0 attempt 1
001319.192: HDMI:EDID error reading EDID block 0 attempt 2
001320.450: HDMI:EDID error reading EDID block 0 attempt 3
001321.709: HDMI:EDID error reading EDID block 0 attempt 4
001322.967: HDMI:EDID error reading EDID block 0 attempt 5
001324.226: HDMI:EDID error reading EDID block 0 attempt 6
001325.484: HDMI:EDID error reading EDID block 0 attempt 7
001326.743: HDMI:EDID error reading EDID block 0 attempt 8
001328.001: HDMI:EDID error reading EDID block 0 attempt 9
001329.023: HDMI:EDID giving up on reading EDID block 0
001346.875: HDMI:Setting property pixel encoding to Default
001346.896: HDMI:Setting property pixel clock type to PAL
001346.915: HDMI:Setting property content type flag to No data
001346.934: HDMI:Setting property fuzzy format match to enabled
001590.836: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
001590.862: hdmi: HDMI:>>>>>>>>>>>>>Rx sensed, reading EDID<<<<<<<<<<<<<
001591.169: hdmi: HDMI:EDID error reading EDID block 0 attempt 0
001592.432: hdmi: HDMI:EDID error reading EDID block 0 attempt 1
001593.695: hdmi: HDMI:EDID error reading EDID block 0 attempt 2
001594.958: hdmi: HDMI:EDID error reading EDID block 0 attempt 3
001596.221: hdmi: HDMI:EDID error reading EDID block 0 attempt 4
001597.485: hdmi: HDMI:EDID error reading EDID block 0 attempt 5
001598.749: hdmi: HDMI:EDID error reading EDID block 0 attempt 6
001600.012: hdmi: HDMI:EDID error reading EDID block 0 attempt 7
001601.276: hdmi: HDMI:EDID error reading EDID block 0 attempt 8
001602.539: hdmi: HDMI:EDID error reading EDID block 0 attempt 9
001603.566: hdmi: HDMI:EDID giving up on reading EDID block 0
001603.600: hdmi: HDMI: No lookup table for resolution group 0
001603.616: hdmi: HDMI: hotplug attached with DVI support
001603.645: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
001603.939: hdmi: HDMI:EDID error reading EDID block 0 attempt 0
001605.202: hdmi: HDMI:EDID error reading EDID block 0 attempt 1
001606.464: hdmi: HDMI:EDID error reading EDID block 0 attempt 2
001607.727: hdmi: HDMI:EDID error reading EDID block 0 attempt 3
001608.989: hdmi: HDMI:EDID error reading EDID block 0 attempt 4
001610.251: hdmi: HDMI:EDID error reading EDID block 0 attempt 5
001611.514: hdmi: HDMI:EDID error reading EDID block 0 attempt 6
001612.776: hdmi: HDMI:EDID error reading EDID block 0 attempt 7
001614.038: hdmi: HDMI:EDID error reading EDID block 0 attempt 8
001615.301: hdmi: HDMI:EDID error reading EDID block 0 attempt 9
001616.326: hdmi: HDMI:EDID giving up on reading EDID block 0
001618.669: hdmi: HDMI: hotplug deassert
001618.684: hdmi: HDMI: HDMI is currently off
001618.698: hdmi: HDMI: changing mode to unplugged
001618.719: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
001621.761: *** Restart logging
001626.801: Read command line from file 'cmdline.txt'
dwc_otg.lpm_enable=0 console=serial0,115200 console=tty1 root=PARTUUID=c1a66bc0-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait quiet splash plymouth.ignore-serial-consoles
001963.293: Loading 'kernel7.img' to 0x8000 size 0x45d270
001966.947: No kernel trailer (run mkknlimg to fix) - assuming DT-capable
001973.294: Loading 'bcm2710-rpi-3-b.dtb' to 0x465270 size 0x44d8
002091.908: dtparam: i2c_arm=on
002101.167: dtparam: spi=on
002131.939: Loaded overlay 'letstrust-tpm'
002132.042: dtparam: audio=on
002188.021: Loaded overlay 'gpio-poweroff'
002188.036: dtparam: gpiopin=27
002188.709: dtparam: active_low=true
002244.818: Loaded overlay 'i2c-rtc'
002244.834: dtparam: mcp7941x=true
002290.746: Loaded overlay 'sc16is752-i2c-02'
002352.712: Loaded overlay 'sc16is752-i2c-01'
003513.045: Device tree loaded to 0x2effb200 (size 0x4d7d)
003518.612: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
004715.705: vchiq_core: vchiq_init_state: slot_zero = 0xfa980000, is_master = 1
004719.817: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
root@raspberrypi:/home/pi# ls -l /dev/ttyS*
crw--w---- 1 root tty       4, 64 May 10 10:36 /dev/ttyS0
crw-rw---- 1 root dialout 241,  0 May 10 10:43 /dev/ttySC0
crw-rw---- 1 root dialout 241,  1 May 10 10:36 /dev/ttySC1
crw-rw---- 1 root dialout 241,  2 May 10 10:36 /dev/ttySC2
crw-rw---- 1 root dialout 241,  3 May 10 10:36 /dev/ttySC3
root@raspberrypi:/home/pi#
paulenuta commented 6 years ago

Update: I have test Strech Raspbian Lite release from 18-04-2018 and 13-03-2018. Error seem to manifest only on 18-04-2018.

2018-03-13-raspbian-stretch-lite.img works fine

pi@raspberrypi:~ $ uname -a
Linux raspberrypi 4.9.80-v7+ #1098 SMP Fri Mar 9 19:11:42 GMT 2018 armv7l GNU/Linux
pi@raspberrypi:~ $ cat /etc/*release
PRETTY_NAME="Raspbian GNU/Linux 9 (stretch)"
NAME="Raspbian GNU/Linux"
VERSION_ID="9"
VERSION="9 (stretch)"
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs

on which I run:

# get Pi up to date
sudo apt-get clean -y; sudo apt-get update -y; sudo apt-get upgrade -y; sudo apt-get dist-upgrade -y; sudo apt-get autoremove -y
sudo apt-get clean -y; sudo apt-get install avrdude mc pigpio build-essential git python3-pip python-pip python-dev python-smbus sysbench -y
pip install python-periphery; pip install pyserial; pip install spidev
....
sudo sh -c "echo 'sc16is7xx' >> /etc/modules"
sudo dtc -@ -I dts -O dtb -o sc16is752-i2c-01.dtbo sc16is752-i2c-01.dts
sudo dtc -@ -I dts -O dtb -o sc16is752-i2c-02.dtbo sc16is752-i2c-02.dts
sudo cp sc16is752-i2c-01.dtbo /boot/overlays/
sudo cp sc16is752-i2c-02.dtbo /boot/overlays/
echo 'Add in config.txt dtoverlay section:'
sudo sh -c "echo '' >> /boot/config.txt"
sudo sh -c "echo '# Enable PI_OS LivePIN' >> /boot/config.txt"
sudo sh -c "echo 'dtoverlay=gpio-poweroff,gpiopin=27,active_low \n' >> /boot/config.txt"
sudo sh -c "echo '# Enable MCP74912 RTC' >> /boot/config.txt"
sudo sh -c "echo 'dtoverlay=i2c-rtc,mcp7941x \n' >> /boot/config.txt"
sudo sh -c "echo '# Enable I2C UARTEXP 2 modules' >> /boot/config.txt"
sudo sh -c "echo '# ttySC2, ttySC3' >> /boot/config.txt"
sudo sh -c "echo 'dtoverlay=sc16is752-i2c-02' >> /boot/config.txt"
sudo sh -c "echo '# ttySC0, ttySC1' >> /boot/config.txt"
sudo sh -c "echo 'dtoverlay=sc16is752-i2c-01 \n' >> /boot/config.txt"
sudo sh -c "echo '# Enable PI UART' >> /boot/config.txt"
sudo sh -c "echo 'enable_uart=1 \n' >> /boot/config.txt"

and test with:

#!/usr/bin/env python      
import sys
import time
from serial import *
from periphery import GPIO

if len(sys.argv) > 1:
    ports = sys.argv
    del ports[0]
    #print ports
else:
    ports = ['/dev/ttyUSB0', '/dev/ttyS0', '/dev/ttySC0', '/dev/ttySC1', '/dev/ttySC2', '/dev/ttySC3']
    #ports = ['/dev/ttyUSB0', '/dev/ttySC1']
    #ports = ['/dev/ttySC1']

counter=0
# How to get GPIO ??
# gpiochip496 -> ../../devices/platform/soc/3f804000.i2c/i2c-1/1004d/gpio/gpiochip496
# DSRA = GPIO4 = 500 | DSRB = GPIO0= 496
# gpiochip504 -> ../../devices/platform/soc/3f804000.i2c/i2c-1/10048/gpio/gpiochip504
# GPIO0-8 > 504, 505, 506, 507, 508
# DSRA = GPIO4 = 508 | DSRB = GPIO0= 504

esc_buzz = b'\x10' + b'\x14' + b'\x03' + b'\x00' + b'\x00' + b'\x01' + b'\x00'
esc_drawer = b'\x1B' + b'\x70' + b'\x00' + b'\x0A' + b'\xFF'
esc_cutter = b'\x1D' + b'\x56' + b'\x42'
to_send = b'\x0A'

OpenPorts = []
for port in ports:
    try:
        #print port
        ser = Serial()
        ser.port = port
        ser.baudrate = 9600
        ser.xonxoff = True
        ser.rtscts = False
        ser.timeout = 1
        print ser.name, ' was setup'
        ser.close()
        OpenPorts.append(ser)
        #print OpenPorts
    except SerialException:
        print 'serial port unavailable', port
        continue

if ( ser.name == '/dev/ttySC0' ):
    DSR = GPIO(508, "in")

if ( ser.name == '/dev/ttySC1' ):
    DSR = GPIO(504, "in")

if ( ser.name == '/dev/ttySC2' ):
    DSR = GPIO(500, "in")

if ( ser.name == '/dev/ttySC3' ):
    DSR = GPIO(496, "in")

while 1:
    for ser in OpenPorts:
        ser.open()
        print '\n Start with: ', ser.name
        if ser.isOpen():
            print '<'
            print ser.name, ' opened'
            if ( DSR.read() == 0 ):
                print '@Write line: ', counter
                ser.write('@Write line: %d \n'%(counter))
                ser.write('\n')
                ser.write('\n')
                ser.write(to_send)
                ser.write(esc_drawer)
                ser.write(esc_cutter)
                counter += 1            
                print ' data was sent to printer', ser.name
            else:
                print ' CTS_{:s} is NotSet - Printer Error @ '.format(ser.name[-1:]), ser.name
        ser.close()
        print ser.name, ' closed'
        print '> \n'
        time.sleep(2)

2018-04-18-raspbian-stretch-lite.img throws "Unexpected interrupt" on every serial or gpio call to the sc16is7xx

[  627.437693] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: 8
[  632.199867] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  634.227692] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  636.248385] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  638.269045] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  640.290448] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  642.311459] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
paulenuta commented 6 years ago

@pelwell Any advice?

pelwell commented 6 years ago

I requested a Pull Request from @hardikharpal in #2542, but I've not received a response.

Since this issue is affecting quite a few people I started to prepare a patch but didn't like the approach taken elsewhere. The issue is caused by the fact that the SC16IS752 has an Enhanced Feature Register which is aliased at the same address as the Interrupt Identification Register; accessing it requires that a magic value is written to the Line Configuration Register. If an interrupt is raised while the EFR is mapped in then the interrupt handler won't be able to access the IIR, leading to the error messages you've seen.

The workaround discussed here is to add a delay between enabling interrupts from the device and returning from the startup method, the idea being that the set_baud method which accesses the EFR is called shortly afterwards. However, this doesn't protect against other calls to set_baud. My preferred solution is to explicitly mask the interrupt from the device for the critical period while the EFR register is swapped in, but I don't have the means to test the change.

Is anyone running the -v7 kernel (Pi2, Pi3, Pi3+, CM3) willing to try a special build of the module including the interrupt masking? You can download the module from here.

N.B. You will first need to sudo rpi-update to get the latest kernel version, then with the new module in the current working directory I suggest you run:

$ sudo mv /lib/modules/`uname -r`/kernel/drivers/tty/serial/sc16is7xx.ko{,.orig}
$ sudo cp sc16is7xx.ko /lib/modules/`uname -r`/kernel/drivers/tty/serial/

Then reboot and see if the interface works and doesn't report errors.

After the test you can revert to the original version with:

$ sudo mv /lib/modules/`uname -r`/kernel/drivers/tty/serial/sc16is7xx.ko{.orig,}

I look forward to some feedback.

paulenuta commented 6 years ago

The workaround discussed here is to add a delay between enabling interrupts from the device and returning from the startup method, the idea being that the set_baud method which accesses the EFR is called shortly afterwards.

I have tried mdelay(1) as showed above on a kernel re-build on which I also activate TPM driver as documented here, but it just reduce the number of error messages.

Is anyone running the -v7 kernel (Pi2, Pi3, Pi3+, CM3) willing to try a special build of the module including the interrupt masking?

Is this OK for you?

pi@raspberrypi:~ $ uname -a
Linux raspberrypi 4.9.80-v7+ #1098 SMP Fri Mar 9 19:11:42 GMT 2018 armv7l GNU/Linux
pi@raspberrypi:~ $ cat /etc/*release
PRETTY_NAME="Raspbian GNU/Linux 9 (stretch)"
NAME="Raspbian GNU/Linux"
VERSION_ID="9"
VERSION="9 (stretch)"
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs

I also have a card with 2018-04-18-raspbian-stretch-lite.img. I can test on Pi3, Pi3+.

pelwell commented 6 years ago

Modules have to match the running kernel fairly precisely, so your current, old kernel won't work. Fortunately you can revert to your current kernel+firmware using sudo rpi-update 936a8dc, so it is safe to update to the 4.14 kernel using sudo rpi-update in order to apply the patched module, as described above.

paulenuta commented 6 years ago

Now on:

root@raspberrypi:/home/pi# uname -a
Linux raspberrypi 4.14.39-v7+ #1112 SMP Sat May 5 12:01:33 BST 2018 armv7l GNU/Linux

with the module downloaded from above link still there are errors.

[   12.601004] Bluetooth: HCI UART driver ver 2.3
[   12.601019] Bluetooth: HCI UART protocol H4 registered
[   12.601025] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   12.602247] Bluetooth: HCI UART protocol Broadcom registered
[   12.878142] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   12.878150] Bluetooth: BNEP filters: protocol multicast
[   12.878167] Bluetooth: BNEP socket layer initialized
[  167.593284] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: 8
[  177.647082] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  182.669447] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  187.693995] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  196.718369] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  201.742118] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  206.761328] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  211.783646] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  216.805630] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  241.909223] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  246.930364] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  256.969775] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
pelwell commented 6 years ago

Would you say this is an improvement over the original, unpatched driver? It's possible I've missed another place that needs protection.

paulenuta commented 6 years ago

I have run

After the test you can revert to the original version with:

$ sudo mv /lib/modules/uname -r/kernel/drivers/tty/serial/sc16is7xx.ko{.orig,}

then reboot and this is the output (script is waiting one second + ser.out_waiting between writes):

[   12.341142] Bluetooth: HCI UART driver ver 2.3
[   12.341156] Bluetooth: HCI UART protocol H4 registered
[   12.341162] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   12.341359] Bluetooth: HCI UART protocol Broadcom registered
[   12.518602] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   12.518609] Bluetooth: BNEP filters: protocol multicast
[   12.518622] Bluetooth: BNEP socket layer initialized
[   76.652563] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[   88.693679] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[   88.695194] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[   94.717621] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[   94.719134] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  106.762782] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  106.764304] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  112.786679] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  112.788184] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  112.789047] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  124.831409] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  124.832972] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  130.854054] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  130.855567] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a

I got 14 "Unexpected..."

And this is the output after applying you patched module and restart (no other changes in system or script)

[   25.940200] Bluetooth: HCI UART driver ver 2.3
[   25.940218] Bluetooth: HCI UART protocol H4 registered
[   25.940224] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   25.940449] Bluetooth: HCI UART protocol Broadcom registered
[   26.100663] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   26.100670] Bluetooth: BNEP filters: protocol multicast
[   26.100686] Bluetooth: BNEP socket layer initialized
[  131.862362] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  137.885442] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  143.911167] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  149.931522] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  149.933485] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  155.956271] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  161.976532] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  168.000119] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  174.023469] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  180.046545] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  192.090521] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a

I got 11 "Unexpected..." Script has a counter (initialized at 0) and port is opened and data sent until counter is <=11. So 14(original) to 11(patched). I reboot and run a second test on original and got 13.

[   12.444358] Bluetooth: HCI UART driver ver 2.3
[   12.444373] Bluetooth: HCI UART protocol H4 registered
[   12.444379] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   12.444601] Bluetooth: HCI UART protocol Broadcom registered
[   12.650108] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   12.650124] Bluetooth: BNEP filters: protocol multicast
[   12.650145] Bluetooth: BNEP socket layer initialized
[   14.006702] random: crng init done
[   14.006714] random: 7 urandom warning(s) missed due to ratelimiting
[  140.378203] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: 8
[  140.379091] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: 8
[  146.417132] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  152.442414] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  158.467297] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  164.492694] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  170.517538] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  176.542827] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  182.567566] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  188.592233] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  194.616907] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  200.641619] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  206.666570] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
pelwell commented 6 years ago

The set_termios is another user of the EFR register and needed the same treatment. Try this module (yes, the URL is unchanged - it's using versioning in Google Drive)

paulenuta commented 6 years ago

I replace the module and this are the results:

( I have not use copy/paste in above lines :) )

[   12.438135] Bluetooth: BNEP socket layer initialized
[   95.605189] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  101.629754] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  113.670660] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  125.714546] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  131.737532] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  143.781530] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  149.804654] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  155.827732] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a

[  760.060005] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  766.084792] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  772.109343] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  778.133892] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  784.158429] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  790.183436] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  796.208341] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  802.232890] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  808.257814] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  814.282367] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  820.303415] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  826.330438] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a

[  886.036865] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  892.061106] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  898.086195] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  904.110817] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  910.136787] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  916.156922] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  928.204194] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  934.228931] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  940.253443] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  946.278117] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a
[  952.302655] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: a

In the script I'm also using chip GPIO as a CTS pin because I couldn't read CTS state

#!/usr/bin/env python      
import sys
import time
import serial
from serial import *
from periphery import GPIO

if len(sys.argv) > 1:
    ports = sys.argv
    del ports[0]
    #print ports
else:
    ports = ['/dev/ttyUSB0', '/dev/ttyS0', '/dev/ttySC0', '/dev/ttySC1', '/dev/ttySC2', '/dev/ttySC3']
    #ports = ['/dev/ttyUSB0']
    #ports = ['/dev/ttySC0']
    #ports = ['/dev/ttySC1']

counter=0
# How to get GPIO ??
# gpiochip496 -> ../../devices/platform/soc/3f804000.i2c/i2c-1/1004d/gpio/gpiochip496
# DSRA = GPIO4 = 500 | DSRB = GPIO0= 496
# gpiochip504 -> ../../devices/platform/soc/3f804000.i2c/i2c-1/10048/gpio/gpiochip504
# GPIO0-8 > 504, 505, 506, 507, 508
# DSRA = GPIO4 = 508 | DSRB = GPIO0= 504

esc_buzz = b'\x10' + b'\x14' + b'\x03' + b'\x00' + b'\x00' + b'\x01' + b'\x00'
esc_drawer = b'\x1B' + b'\x70' + b'\x00' + b'\x0A' + b'\xFF'
esc_cutter = b'\x1D' + b'\x56' + b'\x42'
to_send = b'\x0A'
scrollH = b'\x1B' + b'\x13'
scrollV = b'\x1B' + b'\x12'
getPSTAT = serial.to_bytes([0x10,0x04,0x01])
getPSTS = serial.to_bytes([0x1D,0x72,0x01])
setCD5220 = serial.to_bytes([0x02,0x05,0x43,0x37,0x03]) 
runDEMO = serial.to_bytes([0x02,0x05,0x44,0x08,0x03])
scrollCC = serial.to_bytes([0x1B,0x51,0x44,0x41,0x6e,0x7a,0x69,0x53,0x6f,0x66,0x74,0x20,0x2d,0x20,0x53,0x6f,0x6c,0x75,0x74,0x69,0x69,0x20,0x46,0x69,0x73,0x63,0x61,0x6c,0x65,0x20,0x50,0x65,0x72,0x66,0x6f,0x72,0x6d,0x61,0x6e,0x74,0x65,0x20,0x0D])
ds_CLR = b'\x0C'
esc_OVR = serial.to_bytes([0x1F,0x01])
line1 = serial.to_bytes([0x02,0x05,0x4C,0x31,0x20,0x20,0x20,0x20,0x20,0x20,0x20,0x50,0x4f,0x53,0x52,0x33,0x31,0x34,0x20,0x20,0x20,0x20,0x20,0x03])
line2 = serial.to_bytes([0x02,0x05,0x4C,0x32,0x41,0x6e,0x7a,0x69,0x53,0x6f,0x66,0x74,0x20,0x2d,0x20,0x53,0x6f,0x6c,0x75,0x74,0x69,0x69,0x20,0x46,0x69,0x73,0x63,0x61,0x6c,0x65,0x20,0x50,0x65,0x72,0x66,0x6f,0x72,0x6d,0x61,0x6e,0x74,0x65,0x20,0x03])

ser_Buff = [0]

OpenPorts = []
for port in ports:
    try:
        #print port
        ser = Serial()
        ser.port = port
        ser.baudrate = 9600
        ser.xonxoff  = True
        #ser.rtscts = False
        ser.timeout = 1
        # print ser.name, ' was setup'
        ser.close()
        OpenPorts.append(ser)
        #print OpenPorts
    except SerialException:
        # print 'serial port unavailable', port
        continue

if ( ser.name == '/dev/ttySC0' ):
    DSR = GPIO(508, "in")

if ( ser.name == '/dev/ttySC1' ):
    DSR = GPIO(504, "in")

if ( ser.name == '/dev/ttySC2' ):
    DSR = GPIO(500, "in")

if ( ser.name == '/dev/ttySC3' ):
    DSR = GPIO(496, "in")

while counter <= 11:
    if ( DSR.read() == 0 ):
        for ser in OpenPorts:
            ser.open()
            # print '\n Start with: ', ser.name
            if ser.isOpen():
                # print '<'
                # print ser.name, ' opened'
                # print '@Write line: ', counter
                # ser.write( 'Write line: %d'%(counter))
                # print (ser.read())
                ser.write(ds_CLR)
                if counter < 1:
                    ser.write(setCD5220)
                    ser.write(line1)
                else:
                    ser.write(esc_OVR)
                    ser.write('Write line: %d'%(counter))
                time.sleep(1)
                # ser.write('\n')
                # ser.write(to_send)
                # ser.write(esc_drawer)
                # ser.write(esc_cutter)
                counter += 1            
                # print ' data was sent to printer', ser.name
                # print 'Data on buffer '
                while ser.out_waiting:
                    ser_Buff.append(ser.out_waiting)
                # print ''.join('{:02X} |\t'.format(a) for a in (ser_Buff))
            ser.close()
            ser_Buff = []
            # print ser.name, ' closed'
            # print '> \n'
    else:
        # print ' CTS_{:s} is NotSet - Printer Error @ '.format(ser.name[-1:]), ser.name
        counter = 0
    time.sleep(5)
pelwell commented 6 years ago

I don't suppose you have some spare hardware I could borrow for a while, do you?

paulenuta commented 6 years ago

I have available and I can talk and get approval for sending, how do we move on this?

pelwell commented 6 years ago

Email me at phil@raspberrypi.org and we can arrange shipping (and any guarantees you need).

pelwell commented 6 years ago

The issue is caused by the fact that the IIR (Interrupt Identification Register) is not available in all modes - the EFR (Enhanced Features Register) can be mapped into its place to control certain functionality (e.g. auto CTS/RTS). As a result it is possible that an interrupt handler can end up reading the EFR when it thinks it is accessing the IIR, leading to these error messages and potentially incorrect operation.

A problem like this is fixed by the introduction of some kind of critical section to prevent IIR access while the EFR is mapped in. A spinlock would be the natural choice, but because the I2C interface is slow and requires interrupts to function the bulk of the sc16is7xx interrupt processing happens in a work queue job and is handled by a kernel thread, making a mutex a better choice of interlock. This mutex must be claimed around the code that activates the EFR, and also from the interrupt handler thread where the IIR is read.

I've just pushed a patch to the rpi-4.14.y tree that should fix this problem.

paulenuta commented 6 years ago

In my use case and with bellow test script I have not received "Unexpected interrupt", so for me the patch is correct.

#!/usr/bin/env python
import sys
import time
import threading
from serial import *

if len(sys.argv) > 1:
    ports = sys.argv
    del ports[0]
    #print ports
else:
    ports = ['/dev/ttySC0', '/dev/ttySC1', '/dev/ttySC2', '/dev/ttySC3']

counter = 1
maxCtr = 10 + counter
baud = 9600
out = "[ABCDEFGHIJKLMNOPQRSTUVXYZabcdefghijklmnopqrstuvxyz0123456789]\n"
inp = ""

for i in range(0, 3, 2):
    ser0 = Serial(ports[i], baud, timeout=1, rtscts=0)
    ser1 = Serial(ports[i+1], baud, timeout=1, rtscts=0)
    ser0.flush()
    ser1.flush()
    while counter < maxCtr:
        print '-------- Start --------'
        print '|{:^21}|'.format(counter)
        print '#{:03d} > {} {}.'.format(counter, out, ser0.name)
        print 'Snd {} bytes.'.format(ser0.write( out ))
        time.sleep(1)
        inp = ser1.readline()
        print '#{:03d} < {:s} {}.'.format(counter, inp, ser1.name)
        print 'Rcv {} bytes.'.format(len(inp))
        if (inp == out):
            print '|{:^21}|'.format('Received OK.')
        else:
            print '|{:^21}|'.format('Received ERROR!')
            exit()
        print '-------- Stop  --------'
        print '\r\n'
        counter += 1
        time.sleep(2)

    ser0.flush()
    ser1.flush()
    ser0.close()
    ser1.close()
    counter = 1

    def serialDataSnd():
        global counter
        ser0 = Serial(ports[i], baud, timeout=1, rtscts=0)
        while counter < maxCtr:
            print "#{:03d} Sending  > {:s}".format( counter, out )
            ser0.write(out)
            time.sleep(2)

    def serialDataRcv():
        global counter
        ser1 = Serial(ports[i+1], baud, timeout=1, rtscts=0)
        while counter < maxCtr:
            time.sleep(1)
            line = ser1.readline()
            sys.stdout.write('#{:03d} Received < {:s}\r\n'.format(counter, line))
            counter += 1

    def SerialTestMain():
        thread1 = threading.Thread(target = serialDataSnd)
        thread2 = threading.Thread(target = serialDataRcv)
        thread1.start()
        thread2.start()
        thread1.join()
        time.sleep(2)

    SerialTestMain()
    ser0.close()
    ser1.close()
    counter = 1

exit()
JamesH65 commented 6 years ago

@paulenuta So are you happy for this issue to be closed?

paulenuta commented 6 years ago

@JamesH65 Yes.