Bug #15031: Installing to a device that previously had an hybrid ISO copied to it is fragile

Bug #15031

Installing to a device that previously had an hybrid ISO copied to it is fragile

Added by intrigeri 2017-12-09 15:00:51 . Updated 2018-05-10 10:59:50 .

Status:

Resolved

Priority:

Elevated

Assignee:

Category:

Installation

Target version:

Tails_3.7

Start date:

2017-12-09

Due date:

% Done:

100%

Feature Branch:

bug/15031-isohybrid-by-cloning-often-fails, installer:kurono/bug/15031-isohybrid-by-cloning-often-fails

Type of work:

Research

Blueprint:

Starter:

Affected tool:

Installer

Deliverable for:

Description

I don’t know if it’s a bug in Tails Installer or in our test suite. The attached screenshot reads: “‘NoneType’ object has no attribute ‘props’”.

  Scenario: Writing a Tails isohybrid to a USB drive and booting it, then installing Tails on top of it using Tails Installer, and it still boots # features/usb_install.feature:104
    Given a computer                                                                                                                              # features/step_definitions/common_steps.rb:46
    And I temporarily create a 7200 MiB disk named "isohybrid"                                                                                    # features/step_definitions/common_steps.rb:59
00:57:05.550577319: libguestfs: trace: set_autosync true
00:57:05.550726607: libguestfs: trace: set_autosync = 0
00:57:05.550802746: libguestfs: trace: add_drive "/var/lib/jenkins/workspace/test_Tails_ISO_stable/tmp/tails-amd64-stable-3.3.1-20171209T0717Z-15ff263293.iso" "readonly:true" "format:raw"
00:57:05.550875146: libguestfs: trace: get_tmpdir
00:57:05.550926565: libguestfs: trace: get_tmpdir = "/tmp/TailsToaster"
00:57:05.551154663: libguestfs: trace: disk_create "/tmp/TailsToaster/libguestfs0rfoWs/overlay1" "qcow2" -1 "backingfile:/var/lib/jenkins/workspace/test_Tails_ISO_stable/tmp/tails-amd64-stable-3.3.1-20171209T0717Z-15ff263293.iso" "backingformat:raw"
00:57:05.579030575: libguestfs: trace: disk_create = 0
00:57:05.579201015: libguestfs: trace: add_drive = 0
00:57:05.579284348: libguestfs: trace: add_drive "/tmp/TailsToaster/TailsToasterStorage/isohybrid" "format:qcow2"
00:57:05.579569412: libguestfs: trace: add_drive = 0
00:57:05.579633214: libguestfs: trace: launch
00:57:05.579713084: libguestfs: trace: get_backend_setting "force_tcg"
00:57:05.579798129: libguestfs: trace: get_backend_setting = NULL (error)
00:57:05.580110985: libguestfs: trace: get_cachedir
00:57:05.580174768: libguestfs: trace: get_cachedir = "/tmp/TailsToaster"
00:57:05.622928849: libguestfs: trace: get_cachedir
00:57:05.623092760: libguestfs: trace: get_cachedir = "/tmp/TailsToaster"
00:57:05.623441255: libguestfs: trace: get_sockdir
00:57:05.623552604: libguestfs: trace: get_sockdir = "/tmp"
00:57:05.623736442: libguestfs: trace: get_backend_setting "gdb"
00:57:05.623814286: libguestfs: trace: get_backend_setting = NULL (error)
00:57:09.872461138: libguestfs: trace: launch = 0
00:57:09.873668738: libguestfs: trace: list_devices
00:57:09.874559509: libguestfs: trace: list_devices = ["/dev/sda", "/dev/sdb"]
00:57:09.874697398: libguestfs: trace: copy_device_to_device "/dev/sda" "/dev/sdb"
00:57:13.280787443: libguestfs: trace: copy_device_to_device = 0
00:57:13.281530238: libguestfs: trace: close
00:57:13.281751741: libguestfs: trace: internal_autosync
00:57:13.285347754: libguestfs: trace: internal_autosync = 0
    And I write the Tails ISO image to disk "isohybrid"                                                                                           # features/step_definitions/untrusted_partitions.rb:30
00:57:15.511200761: [log] CLICK on L(1023,384)@S(0)[0,0 1024x768]
00:57:18.464493348: [log]  TYPE " autotest_never_use_this_option blacklist=psmouse #ENTER."
00:58:31.329441732: calling as root: echo 'hello?'
00:58:31.580749618: call returned: [0, "hello?\n", ""]
00:58:31.581234839: calling as root: service tor status
00:58:31.886917552: call returned: [3, "â— tor.service - Anonymizing overlay network for TCP (multi-instance-master)\n   Loaded: loaded (/lib/systemd/system/tor.service; disabled; vendor preset: enabled)\n   Active: inactive (dead)\n", ""]
00:58:31.887399714: opening file /etc/tor/torrc in 'append' mode
00:58:32.117561470: append complete
00:58:32.914113117: [log] CLICK on L(767,159)@S(0)[0,0 1024x768]
00:58:32.914711994: calling as root: loginctl
00:58:33.164239184: call returned: [0, "   SESSION        UID USER             SEAT             TTY             \n        c1        150 Debian-gdm       seat0            /dev/tty1       \n\n1 sessions listed.\n", ""]
00:58:34.164964513: calling as root: loginctl
00:58:34.388422846: call returned: [0, "   SESSION        UID USER             SEAT             TTY             \n         5       1000 amnesia          seat0            /dev/tty2       \n        c1        150 Debian-gdm       seat0            /dev/tty1       \n\n2 sessions listed.\n", ""]
00:58:52.641655215: calling as amnesia: gsettings set org.gnome.desktop.session idle-delay 0
00:58:52.859365047: call returned: [0, "", ""]
00:58:52.859694847: calling as amnesia: gsettings set org.gnome.desktop.interface toolkit-accessibility true
00:58:53.020689674: call returned: [0, "", ""]
00:58:53.021051002: executing Python as amnesia: 
    import dogtail.config
    import dogtail.tree
    import dogtail.predicate
    dogtail.config.logDebugToFile = False
    dogtail.config.logDebugToStdOut = False
    dogtail.config.blinkOnActions = True
    dogtail.config.searchShowingOnly = True
    node133 = dogtail.tree.root.application('gnome-shell')
00:58:54.380157294: execution complete
00:58:55.107919556: executing Python as amnesia: node134 = node133.child('No Notifications', roleName='label')
00:58:55.137823667: [log] CLICK on L(512,10)@S(0)[0,0 1024x768]
00:58:56.930571727: execution complete
00:58:56.930787423: executing Python as amnesia: node135 = node133.child('No Notifications', roleName='label')
00:58:58.358828894: execution complete
00:58:58.401186412: [log]  TYPE "#ESC."
    And I start Tails from USB drive "isohybrid" with network unplugged and I login                                                               # features/step_definitions/common_steps.rb:137
00:58:58.404163065: calling as root: udevadm info --device-id-of-file=/lib/live/mount/medium
00:58:58.696822251: call returned: [0, "8:1\n", ""]
00:58:58.697011300: calling as root: readlink -f /dev/block/'8:1'
00:58:59.062760544: call returned: [0, "/dev/sda1\n", ""]
00:58:59.062958109: calling as root: udevadm info --query=property --name='/dev/sda1'
00:58:59.453972185: call returned: [0, "DEVLINKS=/dev/disk/by-path/pci-0000:02:00.0-usb-0:2:1.0-scsi-0:0:0:0-part1 /dev/disk/by-id/usb-QEMU_QEMU_HARDDISK_1-0000:00:01.1:00.0-2-0:0-part1 /dev/disk/by-uuid/2017-11-15-12-11-29-00 /dev/disk/by-partuuid/0000002a-01 /dev/disk/by-label/TAILS\\x203.3.1\\x20-\\x2020171115\nDEVNAME=/dev/sda1\nDEVPATH=/devices/pci0000:00/0000:00:01.1/0000:02:00.0/usb2/2-2/2-2:1.0/host6/target6:0:0/6:0:0:0/block/sda/sda1\nDEVTYPE=partition\nID_BUS=usb\nID_DRIVE_DETACHABLE=0\nID_FS_APPLICATION_ID=THE\\x20AMNESIC\\x20INCOGNITO\\x20LIVE\\x20SYSTEM\nID_FS_BOOT_SYSTEM_ID=EL\\x20TORITO\\x20SPECIFICATION\nID_FS_LABEL=TAILS_3.3.1_-_20171115\nID_FS_LABEL_ENC=TAILS\\x203.3.1\\x20-\\x2020171115\nID_FS_PUBLISHER_ID=HTTPS:\\x2f\\x2fTAILS.BOUM.ORG\\x2f\nID_FS_TYPE=iso9660\nID_FS_USAGE=filesystem\nID_FS_UUID=2017-11-15-12-11-29-00\nID_FS_UUID_ENC=2017-11-15-12-11-29-00\nID_FS_VERSION=Joliet Extension\nID_INSTANCE=0:0\nID_MODEL=QEMU_HARDDISK\nID_MODEL_ENC=QEMU\\x20HARDDISK\\x20\\x20\\x20\nID_MODEL_ID=0001\nID_PART_ENTRY_DISK=8:0\nID_PART_ENTRY_FLAGS=0x80\nID_PART_ENTRY_NUMBER=1\nID_PART_ENTRY_OFFSET=0\nID_PART_ENTRY_SCHEME=dos\nID_PART_ENTRY_SIZE=2377620\nID_PART_ENTRY_TYPE=0x17\nID_PART_ENTRY_UUID=0000002a-01\nID_PART_TABLE_TYPE=dos\nID_PART_TABLE_UUID=0000002a\nID_PATH=pci-0000:02:00.0-usb-0:2:1.0-scsi-0:0:0:0\nID_PATH_TAG=pci-0000_02_00_0-usb-0_2_1_0-scsi-0_0_0_0\nID_REVISION=2.5+\nID_SERIAL=QEMU_QEMU_HARDDISK_1-0000:00:01.1:00.0-2-0:0\nID_SERIAL_SHORT=1-0000:00:01.1:00.0-2\nID_TYPE=disk\nID_USB_DRIVER=usb-storage\nID_USB_INTERFACES=:080650:\nID_USB_INTERFACE_NUM=00\nID_VENDOR=QEMU\nID_VENDOR_ENC=QEMU\\x20\\x20\\x20\\x20\nID_VENDOR_ID=46f4\nMAJOR=8\nMINOR=1\nPARTN=1\nSUBSYSTEM=block\nTAGS=:systemd:\nUDISKS_IGNORE=1\nUDISKS_SYSTEM=1\nUSEC_INITIALIZED=6800938\n", ""]
00:58:59.454296650: calling as root: udevadm info --device-id-of-file=/lib/live/mount/medium
00:58:59.672356551: call returned: [0, "8:1\n", ""]
00:58:59.672547437: calling as root: readlink -f /dev/block/'8:1'
00:58:59.938788418: call returned: [0, "/dev/sda1\n", ""]
    Then Tails is running from USB drive "isohybrid"                                                                                              # features/step_definitions/usb.rb:390
00:59:00.009208548: spawning as root: poweroff
    When I shutdown Tails and wait for the computer to power off                                                                                  # features/step_definitions/common_steps.rb:530
00:59:11.180385404: [log] CLICK on L(1023,384)@S(0)[0,0 1024x768]
00:59:14.302285520: [log]  TYPE " autotest_never_use_this_option blacklist=psmouse #ENTER."
01:00:21.685616292: calling as root: echo 'hello?'
01:00:21.949790648: call returned: [0, "hello?\n", ""]
01:00:21.950308176: calling as root: service tor status
01:00:22.245776433: call returned: [3, "â— tor.service - Anonymizing overlay network for TCP (multi-instance-master)\n   Loaded: loaded (/lib/systemd/system/tor.service; disabled; vendor preset: enabled)\n   Active: inactive (dead)\n", ""]
01:00:22.246294696: opening file /etc/tor/torrc in 'append' mode
01:00:22.443410316: append complete
01:00:23.231986449: calling as root: loginctl
01:00:23.252455366: [log] CLICK on L(767,159)@S(0)[0,0 1024x768]
01:00:23.474391981: call returned: [0, "   SESSION        UID USER             SEAT             TTY             \n        c1        150 Debian-gdm       seat0            /dev/tty1       \n\n1 sessions listed.\n", ""]
01:00:24.474871169: calling as root: loginctl
01:00:24.679676655: call returned: [0, "   SESSION        UID USER             SEAT             TTY             \n        c1        150 Debian-gdm       seat0            /dev/tty1       \n         5       1000 amnesia          seat0            /dev/tty2       \n\n2 sessions listed.\n", ""]
01:00:41.360845473: calling as amnesia: gsettings set org.gnome.desktop.session idle-delay 0
01:00:41.539484364: call returned: [0, "", ""]
01:00:41.539778350: calling as amnesia: gsettings set org.gnome.desktop.interface toolkit-accessibility true
01:00:41.714149882: call returned: [0, "", ""]
01:00:41.714572090: executing Python as amnesia: 
    import dogtail.config
    import dogtail.tree
    import dogtail.predicate
    dogtail.config.logDebugToFile = False
    dogtail.config.logDebugToStdOut = False
    dogtail.config.blinkOnActions = True
    dogtail.config.searchShowingOnly = True
    node136 = dogtail.tree.root.application('gnome-shell')
01:00:43.113322251: execution complete
01:00:43.837864555: [log] CLICK on L(512,10)@S(0)[0,0 1024x768]
01:00:43.838288692: executing Python as amnesia: node137 = node136.child('No Notifications', roleName='label')
01:00:45.610529214: execution complete
01:00:45.610752212: executing Python as amnesia: node138 = node136.child('No Notifications', roleName='label')
01:00:46.831920886: execution complete
    And I start Tails from DVD with network unplugged and I login                                                                                 # features/step_definitions/common_steps.rb:116
01:00:46.880538187: calling as root: pidof -x -o '%PPID' gnome-terminal-server
01:00:46.897873733: [log]  TYPE "#ESC."
01:00:47.308373704: call returned: [1, "", ""]
01:00:47.369734931: calling as amnesia: xdotool key Super
01:00:47.597787327: call returned: [0, "", ""]
01:00:49.113528940: [log]  TYPE "commandline"
01:00:49.179179893: [log] ( Ctrl )  TYPE "#ENTER."
01:00:55.928519855: [log]  TYPE "/usr/bin/tails-installer --verbose > /tmp/tails-installer.log 2>&1#ENTER."
01:00:55.930245654: executing Python as amnesia: 
    import dogtail.config
    import dogtail.tree
    import dogtail.predicate
    dogtail.config.logDebugToFile = False
    dogtail.config.logDebugToStdOut = False
    dogtail.config.blinkOnActions = True
    dogtail.config.searchShowingOnly = True
    node139 = dogtail.tree.root.application('tails-installer')
01:00:57.908432368: execution complete
01:00:57.908663389: executing Python as amnesia: node140 = node139.child('Tails Installer', roleName='frame')
01:00:58.042805189: execution complete
01:01:01.043144445: calling as amnesia: xdotool search --name 'Tails Installer' windowactivate --sync
01:01:01.295541366: call returned: [0, "", ""]
01:01:01.328945711: executing Python as amnesia: node141 = node139.child('Target USB stick:', roleName='label')
01:01:01.399729367: execution complete
01:01:01.400078269: executing Python as amnesia: node142 = node141.parent
01:01:01.430241793: execution complete
01:01:01.430511328: executing Python as amnesia: node143 = node142.child('', roleName='combo box', recursive=False)
01:01:01.475447265: execution complete
01:01:01.475615301: executing Python as amnesia: print(node143.name)
01:01:01.509398991: execution complete
01:01:01.509909565: executing Python as amnesia: node144 = node139.button('Install')
01:01:01.637976230: execution complete
01:01:01.638173120: executing Python as amnesia: node144.click()
01:01:02.681601377: execution complete
01:01:02.681893539: executing Python as amnesia: node145 = node139.child('Question', roleName='alert')
01:01:02.755520177: execution complete
01:01:02.755759349: executing Python as amnesia: node146 = node145.button('Yes')
01:01:02.800689752: execution complete
01:01:02.800849315: executing Python as amnesia: node146.click()
01:01:03.846015158: execution complete
01:01:03.846382116: executing Python as amnesia: node147 = node139.child('Information', roleName='alert')
01:01:14.966754392: execution complete
01:01:15.967220395: executing Python as amnesia: node148 = node139.child('Information', roleName='alert')
01:01:27.562471027: execution complete
01:01:28.562951480: executing Python as amnesia: node149 = node139.child('Information', roleName='alert')
01:01:39.666474440: execution complete
01:01:40.667150989: executing Python as amnesia: node150 = node139.child('Information', roleName='alert')
01:01:51.860633064: execution complete
01:01:52.861118009: executing Python as amnesia: node151 = node139.child('Information', roleName='alert')
01:02:04.358282000: execution complete
01:02:05.358776670: executing Python as amnesia: node152 = node139.child('Information', roleName='alert')
01:02:16.814084339: execution complete
01:02:17.814545272: executing Python as amnesia: node153 = node139.child('Information', roleName='alert')
01:02:29.173825685: execution complete
01:02:30.174329016: executing Python as amnesia: node154 = node139.child('Information', roleName='alert')
01:02:41.126350135: execution complete
01:02:42.126773884: executing Python as amnesia: node155 = node139.child('Information', roleName='alert')
01:02:53.168471496: execution complete
01:02:54.168993110: executing Python as amnesia: node156 = node139.child('Information', roleName='alert')
01:03:05.033703688: execution complete
01:03:06.034298660: executing Python as amnesia: node157 = node139.child('Information', roleName='alert')
01:03:17.538883716: execution complete
01:03:18.539296914: executing Python as amnesia: node158 = node139.child('Information', roleName='alert')
01:03:29.852279679: execution complete
01:03:30.852687962: executing Python as amnesia: node159 = node139.child('Information', roleName='alert')
01:03:42.300939755: execution complete
01:03:43.301551901: executing Python as amnesia: node160 = node139.child('Information', roleName='alert')
01:03:54.218559211: execution complete
01:03:55.219043695: executing Python as amnesia: node161 = node139.child('Information', roleName='alert')
01:04:06.579836355: execution complete
01:04:07.580320535: executing Python as amnesia: node162 = node139.child('Information', roleName='alert')
01:04:18.887323398: execution complete
01:04:19.887689036: executing Python as amnesia: node163 = node139.child('Information', roleName='alert')
01:04:31.311057493: execution complete
01:04:32.311587634: executing Python as amnesia: node164 = node139.child('Information', roleName='alert')
01:04:43.859466284: execution complete
01:04:44.859826100: executing Python as amnesia: node165 = node139.child('Information', roleName='alert')
01:04:56.080986696: execution complete
01:04:57.081364031: executing Python as amnesia: node166 = node139.child('Information', roleName='alert')
01:05:08.271339918: execution complete
01:05:09.271742973: executing Python as amnesia: node167 = node139.child('Information', roleName='alert')
01:05:20.753699875: execution complete
01:05:21.754096202: executing Python as amnesia: node168 = node139.child('Information', roleName='alert')
01:05:32.724372287: execution complete
01:05:33.724850648: executing Python as amnesia: node169 = node139.child('Information', roleName='alert')
01:05:45.379189577: execution complete
01:05:46.379662310: executing Python as amnesia: node170 = node139.child('Information', roleName='alert')
01:05:57.603166279: execution complete
01:05:58.603547653: executing Python as amnesia: node171 = node139.child('Information', roleName='alert')
01:06:09.543439344: execution complete
01:06:10.543822052: executing Python as amnesia: node172 = node139.child('Information', roleName='alert')
01:06:21.639450846: execution complete
01:06:22.639957965: executing Python as amnesia: node173 = node139.child('Information', roleName='alert')
01:06:33.508917439: execution complete
01:06:34.509403801: executing Python as amnesia: node174 = node139.child('Information', roleName='alert')
01:06:46.143308999: execution complete
01:06:47.143694055: executing Python as amnesia: node175 = node139.child('Information', roleName='alert')
01:06:58.005667808: execution complete
01:06:59.006072611: executing Python as amnesia: node176 = node139.child('Information', roleName='alert')
01:07:10.067510870: execution complete
01:07:11.067951371: executing Python as amnesia: node177 = node139.child('Information', roleName='alert')
01:07:22.089735890: execution complete
01:07:23.090131385: executing Python as amnesia: node178 = node139.child('Information', roleName='alert')
01:07:33.952007384: execution complete
01:07:34.952360550: executing Python as amnesia: node179 = node139.child('Information', roleName='alert')
01:07:46.210074970: execution complete
01:07:47.210439216: executing Python as amnesia: node180 = node139.child('Information', roleName='alert')
01:07:58.049670047: execution complete
01:07:59.050168549: executing Python as amnesia: node181 = node139.child('Information', roleName='alert')
01:08:10.029370136: execution complete
01:08:11.029804538: executing Python as amnesia: node182 = node139.child('Information', roleName='alert')
01:08:21.985672691: execution complete
01:08:22.986141348: executing Python as amnesia: node183 = node139.child('Information', roleName='alert')
01:08:33.797863077: execution complete
01:08:34.798318866: executing Python as amnesia: node184 = node139.child('Information', roleName='alert')
01:08:45.822277319: execution complete
01:08:46.822815784: executing Python as amnesia: node185 = node139.child('Information', roleName='alert')
01:08:57.647495708: execution complete
01:08:58.647935011: executing Python as amnesia: node186 = node139.child('Information', roleName='alert')
01:09:09.472290664: execution complete
01:09:10.472731726: executing Python as amnesia: node187 = node139.child('Information', roleName='alert')
01:09:21.422976929: execution complete
01:09:22.423413866: executing Python as amnesia: node188 = node139.child('Information', roleName='alert')
01:09:33.259841489: execution complete
01:09:34.260289875: executing Python as amnesia: node189 = node139.child('Information', roleName='alert')
01:09:45.093082049: execution complete
01:09:46.093570707: executing Python as amnesia: node190 = node139.child('Information', roleName='alert')
01:09:56.909205881: execution complete
01:09:57.909683110: executing Python as amnesia: node191 = node139.child('Information', roleName='alert')
01:10:08.733467040: execution complete
01:10:09.733906711: executing Python as amnesia: node192 = node139.child('Information', roleName='alert')
01:10:20.551534775: execution complete
01:10:21.551947763: executing Python as amnesia: node193 = node139.child('Information', roleName='alert')
01:10:32.380758264: execution complete
01:10:33.381126427: executing Python as amnesia: node194 = node139.child('Information', roleName='alert')
01:10:44.220098221: execution complete
01:10:45.220582445: executing Python as amnesia: node195 = node139.child('Information', roleName='alert')
01:10:56.183364498: execution complete
01:10:57.183901452: executing Python as amnesia: node196 = node139.child('Information', roleName='alert')
01:11:08.252378429: execution complete
01:11:09.252889690: executing Python as amnesia: node197 = node139.child('Information', roleName='alert')
01:11:20.754025699: execution complete
01:11:21.754511168: executing Python as amnesia: node198 = node139.child('Information', roleName='alert')
01:11:32.647834297: execution complete
01:11:33.648323074: executing Python as amnesia: node199 = node139.child('Information', roleName='alert')
01:11:44.464359632: execution complete
01:11:45.464748786: executing Python as amnesia: node200 = node139.child('Information', roleName='alert')
01:11:56.562098506: execution complete
01:11:57.562522734: executing Python as amnesia: node201 = node139.child('Information', roleName='alert')
01:12:08.369873824: execution complete
01:12:09.370299351: executing Python as amnesia: node202 = node139.child('Information', roleName='alert')
01:12:20.278510227: execution complete
01:12:21.278949128: executing Python as amnesia: node203 = node139.child('Information', roleName='alert')
01:12:32.284324048: execution complete
01:12:33.284669529: executing Python as amnesia: node204 = node139.child('Information', roleName='alert')
01:12:44.150743799: execution complete
01:12:45.151212373: executing Python as amnesia: node205 = node139.child('Information', roleName='alert')
01:12:55.940304786: execution complete
01:12:56.940757090: executing Python as amnesia: node206 = node139.child('Information', roleName='alert')
01:13:07.792239910: execution complete
01:13:08.792695521: executing Python as amnesia: node207 = node139.child('Information', roleName='alert')
01:13:19.614065055: execution complete
01:13:20.614581079: executing Python as amnesia: node208 = node139.child('Information', roleName='alert')
01:13:31.434393095: execution complete
01:13:32.434927501: executing Python as amnesia: node209 = node139.child('Information', roleName='alert')
01:13:43.481264761: execution complete
01:13:44.481703053: executing Python as amnesia: node210 = node139.child('Information', roleName='alert')
01:13:55.381156164: execution complete
01:13:56.381533770: executing Python as amnesia: node211 = node139.child('Information', roleName='alert')
01:14:07.335274261: execution complete
01:14:08.335742320: executing Python as amnesia: node212 = node139.child('Information', roleName='alert')
01:14:19.236740293: execution complete
01:14:20.237155502: executing Python as amnesia: node213 = node139.child('Information', roleName='alert')
01:14:31.112704419: execution complete
01:14:32.119810308: executing Python as amnesia: node214 = node139.child('Information', roleName='alert')
01:14:43.011016524: execution complete
01:14:44.011539166: executing Python as amnesia: node215 = node139.child('Information', roleName='alert')
01:14:54.797487738: execution complete
01:14:55.797856406: executing Python as amnesia: node216 = node139.child('Information', roleName='alert')
01:15:06.847465129: execution complete
01:15:07.847910160: executing Python as amnesia: node217 = node139.child('Information', roleName='alert')
01:15:18.649313703: execution complete
01:15:19.649721431: executing Python as amnesia: node218 = node139.child('Information', roleName='alert')
01:15:30.476329088: execution complete
01:15:31.476820581: executing Python as amnesia: node219 = node139.child('Information', roleName='alert')
01:15:42.299152774: execution complete
01:15:43.299697135: executing Python as amnesia: node220 = node139.child('Information', roleName='alert')
01:15:54.178949839: execution complete
01:15:55.179410801: executing Python as amnesia: node221 = node139.child('Information', roleName='alert')
01:16:06.004259960: execution complete
01:16:07.004715013: executing Python as amnesia: node222 = node139.child('Information', roleName='alert')
01:16:17.988827186: execution complete
01:16:18.989232422: executing Python as amnesia: node223 = node139.child('Information', roleName='alert')
01:16:29.846757854: execution complete
01:16:30.848935308: executing Python as amnesia: node224 = node139.child('Information', roleName='alert')
01:16:41.785566775: execution complete
01:16:42.786040386: executing Python as amnesia: node225 = node139.child('Information', roleName='alert')
01:16:53.783270817: execution complete
01:16:54.783750714: executing Python as amnesia: node226 = node139.child('Information', roleName='alert')
01:17:05.608256741: execution complete
01:17:06.608730279: executing Python as amnesia: node227 = node139.child('Information', roleName='alert')
01:17:17.463727610: execution complete
01:17:18.464076979: executing Python as amnesia: node228 = node139.child('Information', roleName='alert')
01:17:29.314779047: execution complete
01:17:30.315123928: executing Python as amnesia: node229 = node139.child('Information', roleName='alert')
01:17:41.120457833: execution complete
01:17:42.120955587: executing Python as amnesia: node230 = node139.child('Information', roleName='alert')
01:17:52.968425550: execution complete
01:17:53.968877114: executing Python as amnesia: node231 = node139.child('Information', roleName='alert')
01:18:04.839813808: execution complete
01:18:05.840384324: executing Python as amnesia: node232 = node139.child('Information', roleName='alert')
01:18:16.707395941: execution complete
01:18:17.707862081: executing Python as amnesia: node233 = node139.child('Information', roleName='alert')
01:18:28.821963336: execution complete
01:18:29.822572495: executing Python as amnesia: node234 = node139.child('Information', roleName='alert')
01:18:40.635211106: execution complete
01:18:41.635671464: executing Python as amnesia: node235 = node139.child('Information', roleName='alert')
01:18:52.413912679: execution complete
01:18:53.414379713: executing Python as amnesia: node236 = node139.child('Information', roleName='alert')
01:19:04.314365224: execution complete
01:19:05.314978962: executing Python as amnesia: node237 = node139.child('Information', roleName='alert')
01:19:16.280811204: execution complete
01:19:17.281249135: executing Python as amnesia: node238 = node139.child('Information', roleName='alert')
01:19:28.102574338: execution complete
01:19:29.102947339: executing Python as amnesia: node239 = node139.child('Information', roleName='alert')
01:19:40.197223596: execution complete
01:19:41.197701269: executing Python as amnesia: node240 = node139.child('Information', roleName='alert')
01:19:52.049909819: execution complete
01:19:53.050359766: executing Python as amnesia: node241 = node139.child('Information', roleName='alert')
01:20:03.851228560: execution complete
01:20:04.851586364: executing Python as amnesia: node242 = node139.child('Information', roleName='alert')
01:20:15.714954013: execution complete
01:20:16.718225842: executing Python as amnesia: node243 = node139.child('Information', roleName='alert')
01:20:27.556384726: execution complete
01:20:28.556847535: executing Python as amnesia: node244 = node139.child('Information', roleName='alert')
01:20:39.329016047: execution complete
01:20:40.329461341: executing Python as amnesia: node245 = node139.child('Information', roleName='alert')
01:20:51.186500223: execution complete
01:20:52.186925074: executing Python as amnesia: node246 = node139.child('Information', roleName='alert')
01:21:03.148930147: execution complete
01:21:04.149460776: executing Python as amnesia: node247 = node139.child('Information', roleName='alert')
01:21:16.021867943: execution complete
01:21:17.022338542: executing Python as amnesia: node248 = node139.child('Information', roleName='alert')
01:21:27.830609274: execution complete
01:21:28.831043467: executing Python as amnesia: node249 = node139.child('Information', roleName='alert')
01:21:39.599832782: execution complete
01:21:40.600236116: executing Python as amnesia: node250 = node139.child('Information', roleName='alert')
01:21:51.399064221: execution complete
01:21:52.399422073: executing Python as amnesia: node251 = node139.child('Information', roleName='alert')
01:22:03.201347134: execution complete
01:22:04.201810275: executing Python as amnesia: node252 = node139.child('Information', roleName='alert')
01:22:15.102101983: execution complete
01:22:16.102571389: executing Python as amnesia: node253 = node139.child('Information', roleName='alert')
01:22:27.050704470: execution complete
01:22:28.051098297: executing Python as amnesia: node254 = node139.child('Information', roleName='alert')
01:22:39.076853642: execution complete
01:22:40.077373226: executing Python as amnesia: node255 = node139.child('Information', roleName='alert')
01:22:50.893816504: execution complete
01:22:51.894308087: executing Python as amnesia: node256 = node139.child('Information', roleName='alert')
01:23:02.628748043: execution complete
01:23:03.629221407: executing Python as amnesia: node257 = node139.child('Information', roleName='alert')
01:23:14.397530607: execution complete
01:23:15.397939227: executing Python as amnesia: node258 = node139.child('Information', roleName='alert')
01:23:26.209498837: execution complete
01:23:27.210016170: executing Python as amnesia: node259 = node139.child('Information', roleName='alert')
01:23:38.028576050: execution complete
01:23:39.028989420: executing Python as amnesia: node260 = node139.child('Information', roleName='alert')
01:23:49.946063899: execution complete
01:23:50.946457916: executing Python as amnesia: node261 = node139.child('Information', roleName='alert')
01:24:02.079375498: execution complete
01:24:03.079877825: executing Python as amnesia: node262 = node139.child('Information', roleName='alert')
01:24:13.916796437: execution complete
01:24:14.917334381: executing Python as amnesia: node263 = node139.child('Information', roleName='alert')
01:24:25.767635246: execution complete
01:24:26.768080207: executing Python as amnesia: node264 = node139.child('Information', roleName='alert')
01:24:37.505982009: execution complete
01:24:38.506447296: executing Python as amnesia: node265 = node139.child('Information', roleName='alert')
01:24:49.984507672: execution complete
01:24:50.984844226: executing Python as amnesia: node266 = node139.child('Information', roleName='alert')
01:25:01.936692563: execution complete
01:25:02.937026870: executing Python as amnesia: node267 = node139.child('Information', roleName='alert')
01:25:13.706502769: execution complete
01:25:14.706942512: executing Python as amnesia: node268 = node139.child('Information', roleName='alert')
01:25:25.635579645: execution complete
01:25:26.636022964: executing Python as amnesia: node269 = node139.child('Information', roleName='alert')
01:25:37.455222074: execution complete
01:25:38.455621036: executing Python as amnesia: node270 = node139.child('Information', roleName='alert')
01:25:49.264692721: execution complete
01:25:50.265048038: executing Python as amnesia: node271 = node139.child('Information', roleName='alert')
01:26:01.068727872: execution complete
01:26:02.069281846: executing Python as amnesia: node272 = node139.child('Information', roleName='alert')
01:26:13.183715527: execution complete
01:26:14.185868972: executing Python as amnesia: node273 = node139.child('Information', roleName='alert')
01:26:24.970883633: execution complete
01:26:25.971319225: executing Python as amnesia: node274 = node139.child('Information', roleName='alert')
01:26:36.803997074: execution complete
01:26:37.804364189: executing Python as amnesia: node275 = node139.child('Information', roleName='alert')
01:26:48.638860998: execution complete
01:26:49.639398801: executing Python as amnesia: node276 = node139.child('Information', roleName='alert')
01:27:00.741237252: execution complete
01:27:01.741618634: executing Python as amnesia: node277 = node139.child('Information', roleName='alert')
01:27:12.621476878: execution complete
01:27:13.622080063: executing Python as amnesia: node278 = node139.child('Information', roleName='alert')
01:27:24.403090800: execution complete
01:27:25.403453246: executing Python as amnesia: node279 = node139.child('Information', roleName='alert')
01:27:36.363667339: execution complete
01:27:37.364185455: executing Python as amnesia: node280 = node139.child('Information', roleName='alert')
01:27:48.219554332: execution complete
01:27:49.219998539: executing Python as amnesia: node281 = node139.child('Information', roleName='alert')
01:28:00.057568088: execution complete
01:28:01.058014176: executing Python as amnesia: node282 = node139.child('Information', roleName='alert')
01:28:11.949078027: execution complete
01:28:12.949494920: executing Python as amnesia: node283 = node139.child('Information', roleName='alert')
01:28:23.705011234: execution complete
01:28:24.705521029: executing Python as amnesia: node284 = node139.child('Information', roleName='alert')
01:28:35.585494296: execution complete
01:28:36.585925375: executing Python as amnesia: node285 = node139.child('Information', roleName='alert')
01:28:47.415791818: execution complete
01:28:48.416159249: executing Python as amnesia: node286 = node139.child('Information', roleName='alert')
01:28:59.526033701: execution complete
01:29:00.526528044: executing Python as amnesia: node287 = node139.child('Information', roleName='alert')
01:29:11.434082997: execution complete
01:29:12.434433332: executing Python as amnesia: node288 = node139.child('Information', roleName='alert')
01:29:23.405546510: execution complete
01:29:24.406005336: executing Python as amnesia: node289 = node139.child('Information', roleName='alert')
01:29:35.281927675: execution complete
01:29:36.282387200: executing Python as amnesia: node290 = node139.child('Information', roleName='alert')
01:29:47.275905184: execution complete
01:29:48.276389539: executing Python as amnesia: node291 = node139.child('Information', roleName='alert')
01:29:59.102144399: execution complete
01:30:00.102648124: executing Python as amnesia: node292 = node139.child('Information', roleName='alert')
01:30:10.907058846: execution complete
01:30:11.907591618: executing Python as amnesia: node293 = node139.child('Information', roleName='alert')
01:30:22.694091250: execution complete
01:30:23.694522660: executing Python as amnesia: node294 = node139.child('Information', roleName='alert')
01:30:34.510449988: execution complete
01:30:35.510909093: executing Python as amnesia: node295 = node139.child('Information', roleName='alert')
01:30:46.304613642: execution complete
01:30:47.305131717: executing Python as amnesia: node296 = node139.child('Information', roleName='alert')
01:30:58.211729479: execution complete
01:30:59.212118027: executing Python as amnesia: node297 = node139.child('Information', roleName='alert')
01:31:03.847305940: opening file /tmp/tails-installer.log in 'read' mode
01:31:09.994967739: Dropped out-of-order remote shell response: got id 1267 but expected id 1268
01:31:11.551816880: read complete
01:31:11.552074227: Tails Installer debug log:
2017-12-09 09:10:17,262 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop14
2017-12-09 09:10:17,262 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop14 which has no associated drive
2017-12-09 09:10:17,262 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/drives/QEMU_QEMU_HARDDISK_1_0000_3a00_3a01_2e1_3a00_2e0_2
2017-12-09 09:10:17,262 [creator.py:598 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/drives/QEMU_QEMU_HARDDISK_1_0000_3a00_3a01_2e1_3a00_2e0_2 which is not a block device
2017-12-09 09:10:17,263 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop9
2017-12-09 09:10:17,263 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop9 which has no associated drive
2017-12-09 09:10:17,263 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop18
2017-12-09 09:10:17,264 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop18 which has no associated drive
2017-12-09 09:10:17,264 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop10
2017-12-09 09:10:17,264 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop10 which has no associated drive
2017-12-09 09:10:17,264 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop16
2017-12-09 09:10:17,265 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop16 which has no associated drive
2017-12-09 09:10:17,265 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop8
2017-12-09 09:10:17,265 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop8 which has no associated drive
2017-12-09 09:10:17,265 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop6
2017-12-09 09:10:17,265 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop6 which has no associated drive
2017-12-09 09:10:17,266 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop31
2017-12-09 09:10:17,266 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop31 which has no associated drive
2017-12-09 09:10:17,266 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop30
2017-12-09 09:10:17,266 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop30 which has no associated drive
2017-12-09 09:10:17,266 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop4
2017-12-09 09:10:17,270 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop4 which has no associated drive
2017-12-09 09:10:17,270 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop3
2017-12-09 09:10:17,270 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop3 which has no associated drive
2017-12-09 09:10:17,270 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop2
2017-12-09 09:10:17,271 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop2 which has no associated drive
2017-12-09 09:10:17,271 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop11
2017-12-09 09:10:17,271 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop11 which has no associated drive
2017-12-09 09:10:17,271 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop0
2017-12-09 09:10:17,272 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop0 which has no associated drive
2017-12-09 09:10:17,272 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/sda1
2017-12-09 09:10:17,274 [creator.py:686 (detect_supported_drives)] DEBUG: {'bootable': None,
 'device': '/dev/sda1',
 'free': None,
 'fstype': 'iso9660',
 'fsversion': 'Joliet Extension',
 'is_device_big_enough_for_installation': True,
 'is_optical': False,
 'label': '',
 'model': 'QEMU HARDDISK',
 'mount': None,
 'mounted_partitions': set([]),
 'parent': '/dev/sda',
 'parent_size': 7549747200,
 'parent_udi': '/org/freedesktop/UDisks2/block_devices/sda',
 'removable': True,
 'size': 7549747200,
 'udi': '/org/freedesktop/UDisks2/block_devices/sda1',
 'uuid': '2017-11-15-12-11-29-00',
 'vendor': 'QEMU'}
2017-12-09 09:10:17,274 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop29
2017-12-09 09:10:17,274 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop29 which has no associated drive
2017-12-09 09:10:17,274 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop28
2017-12-09 09:10:17,274 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop28 which has no associated drive
2017-12-09 09:10:17,274 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop27
2017-12-09 09:10:17,275 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop27 which has no associated drive
2017-12-09 09:10:17,275 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop26
2017-12-09 09:10:17,275 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop26 which has no associated drive
2017-12-09 09:10:17,275 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop25
2017-12-09 09:10:17,275 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop25 which has no associated drive
2017-12-09 09:10:17,275 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop24
2017-12-09 09:10:17,276 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop24 which has no associated drive
2017-12-09 09:10:17,276 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop23
2017-12-09 09:10:17,276 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop23 which has no associated drive
2017-12-09 09:10:17,276 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop22
2017-12-09 09:10:17,276 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop22 which has no associated drive
2017-12-09 09:10:17,276 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop21
2017-12-09 09:10:17,276 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop21 which has no associated drive
2017-12-09 09:10:17,276 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop20
2017-12-09 09:10:17,277 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop20 which has no associated drive
2017-12-09 09:10:17,277 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/sda
2017-12-09 09:10:17,278 [creator.py:686 (detect_supported_drives)] DEBUG: {'bootable': None,
 'device': '/dev/sda',
 'free': None,
 'fstype': 'iso9660',
 'fsversion': 'Joliet Extension',
 'is_device_big_enough_for_installation': True,
 'is_optical': False,
 'label': 'QEMU-QEMU-HARDDISK-1-0000:00:01.1:00.0-2',
 'model': 'QEMU HARDDISK',
 'mount': None,
 'mounted_partitions': set([]),
 'parent': None,
 'parent_size': None,
 'parent_udi': None,
 'removable': True,
 'size': 7549747200,
 'udi': '/org/freedesktop/UDisks2/block_devices/sda',
 'uuid': '2017-11-15-12-11-29-00',
 'vendor': 'QEMU'}
2017-12-09 09:10:17,278 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop15
2017-12-09 09:10:17,278 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop15 which has no associated drive
2017-12-09 09:10:17,278 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/drives/QEMU_DVD_ROM_QM00005
2017-12-09 09:10:17,278 [creator.py:598 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/drives/QEMU_DVD_ROM_QM00005 which is not a block device
2017-12-09 09:10:17,278 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop5
2017-12-09 09:10:17,279 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop5 which has no associated drive
2017-12-09 09:10:17,279 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop12
2017-12-09 09:10:17,279 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop12 which has no associated drive
2017-12-09 09:10:17,279 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop17
2017-12-09 09:10:17,279 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop17 which has no associated drive
2017-12-09 09:10:17,279 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/sr0
2017-12-09 09:10:17,280 [creator.py:636 (detect_supported_drives)] WARNING: Skipping device '/org/freedesktop/UDisks2/block_devices/sr0' connected to '' interface
2017-12-09 09:10:17,280 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop19
2017-12-09 09:10:17,280 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop19 which has no associated drive
2017-12-09 09:10:17,280 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop13
2017-12-09 09:10:17,280 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop13 which has no associated drive
2017-12-09 09:10:17,280 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop7
2017-12-09 09:10:17,280 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop7 which has no associated drive
2017-12-09 09:10:17,280 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop1
2017-12-09 09:10:17,281 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop1 which has no associated drive
2017-12-09 09:10:17,281 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/Manager
2017-12-09 09:10:17,281 [creator.py:598 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/Manager which is not a block device
2017-12-09 09:10:17,281 [creator.py:712 (detect_supported_drives)] DEBUG: {}
2017-12-09 09:10:17,281 [gui.py:531 (add_devices)] DEBUG: drives: {'/dev/sda': {'size': 7549747200, 'is_optical': False, 'vendor': 'QEMU', 'fsversion': 'Joliet Extension', 'parent': None, 'bootable': None, 'mount': None, 'parent_size': None, 'mounted_partitions': set([]), 'removable': True, 'free': None, 'label': 'QEMU-QEMU-HARDDISK-1-0000:00:01.1:00.0-2', 'is_device_big_enough_for_installation': True, 'fstype': 'iso9660', 'parent_udi': None, 'device': '/dev/sda', 'model': 'QEMU HARDDISK', 'udi': '/org/freedesktop/UDisks2/block_devices/sda', 'uuid': '2017-11-15-12-11-29-00'}}
2017-12-09 09:10:21,170 [creator.py:527 (_set_drive)] DEBUG: /dev/sda selected: {'size': 7549747200, 'is_optical': False, 'vendor': 'QEMU', 'fsversion': 'Joliet Extension', 'parent': None, 'bootable': None, 'mount': None, 'parent_size': None, 'mounted_partitions': set([]), 'removable': True, 'free': None, 'label': 'QEMU-QEMU-HARDDISK-1-0000:00:01.1:00.0-2', 'is_device_big_enough_for_installation': True, 'fstype': 'iso9660', 'parent_udi': None, 'device': '/dev/sda', 'model': 'QEMU HARDDISK', 'udi': '/org/freedesktop/UDisks2/block_devices/sda', 'uuid': '2017-11-15-12-11-29-00'}
2017-12-09 09:10:22,323 [creator.py:803 (unmount_device)] DEBUG: Entering unmount_device for '/dev/sda'
2017-12-09 09:10:22,325 [creator.py:806 (unmount_device)] DEBUG: {'bootable': None,
 'device': '/dev/sda',
 'free': None,
 'fstype': 'iso9660',
 'fsversion': 'Joliet Extension',
 'is_device_big_enough_for_installation': True,
 'is_optical': False,
 'label': 'QEMU-QEMU-HARDDISK-1-0000:00:01.1:00.0-2',
 'model': 'QEMU HARDDISK',
 'mount': None,
 'mounted_partitions': set([]),
 'parent': None,
 'parent_size': None,
 'parent_udi': None,
 'removable': True,
 'size': 7549747200,
 'udi': '/org/freedesktop/UDisks2/block_devices/sda',
 'uuid': '2017-11-15-12-11-29-00',
 'vendor': 'QEMU'}
2017-12-09 09:10:22,335 [creator.py:297 (popen)] DEBUG: sync
2017-12-09 09:10:25,403 [creator.py:297 (popen)] DEBUG: /sbin/sgdisk --print /dev/sda
2017-12-09 09:10:25,529 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop14
2017-12-09 09:10:25,529 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop14 which has no associated drive
2017-12-09 09:10:25,529 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/drives/QEMU_QEMU_HARDDISK_1_0000_3a00_3a01_2e1_3a00_2e0_2
2017-12-09 09:10:25,530 [creator.py:598 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/drives/QEMU_QEMU_HARDDISK_1_0000_3a00_3a01_2e1_3a00_2e0_2 which is not a block device
2017-12-09 09:10:25,530 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop9
2017-12-09 09:10:25,530 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop9 which has no associated drive
2017-12-09 09:10:25,530 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop18
2017-12-09 09:10:25,530 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop18 which has no associated drive
2017-12-09 09:10:25,530 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop10
2017-12-09 09:10:25,532 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop10 which has no associated drive
2017-12-09 09:10:25,532 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop16
2017-12-09 09:10:25,532 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop16 which has no associated drive
2017-12-09 09:10:25,532 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop8
2017-12-09 09:10:25,532 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop8 which has no associated drive
2017-12-09 09:10:25,533 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop6
2017-12-09 09:10:25,533 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop6 which has no associated drive
2017-12-09 09:10:25,538 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop31
2017-12-09 09:10:25,538 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop31 which has no associated drive
2017-12-09 09:10:25,538 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop30
2017-12-09 09:10:25,539 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop30 which has no associated drive
2017-12-09 09:10:25,539 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop4
2017-12-09 09:10:25,539 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop4 which has no associated drive
2017-12-09 09:10:25,539 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop3
2017-12-09 09:10:25,543 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop3 which has no associated drive
2017-12-09 09:10:25,557 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop2
2017-12-09 09:10:25,569 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop2 which has no associated drive
2017-12-09 09:10:25,572 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop11
2017-12-09 09:10:25,580 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop11 which has no associated drive
2017-12-09 09:10:25,582 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/loop0
2017-12-09 09:10:25,584 [creator.py:604 (detect_supported_drives)] DEBUG: skip /org/freedesktop/UDisks2/block_devices/loop0 which has no associated drive
2017-12-09 09:10:25,587 [creator.py:596 (detect_supported_drives)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/sda1
2017-12-09 09:10:25,599 [creator.py:686 (detect_supported_drives)] DEBUG: {'bootable': None,
 'device': '/dev/sda1',
 'free': None,
 'fstype': 'iso9660',
 'fsversion': 'Joliet Extension',
 'is_device_big_enough_for_installation': True,
 'is_optical': False,
 'label': '',
 'model': 'QEMU HARDDISK',
 'mount': None,
 'mounted_partitions': set([]),
 'parent': '/dev/sda',
 'parent_size': 7549747200,
 'parent_udi': '/org/freedesktop/UDisks2/block_devices/sda',
 'removable': True,
 'size': 7549747200,
 'udi': '/org/freedesktop/UDisks2/block_devices/sda1',
 'uuid': '2017-11-15-12-11-29-00',
 'vendor': 'QEMU'}
2017-12-09 09:10:25,600 [gui.py:264 (run)] ERROR: 'NoneType' object has no attribute 'props'
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/tails_installer/gui.py", line 198, in run
    self.rescan_devices(force_partitions=False)
  File "/usr/lib/python2.7/dist-packages/tails_installer/gui.py", line 177, in rescan_devices
    force_partitions=force_partitions)
  File "/usr/lib/python2.7/dist-packages/tails_installer/creator.py", line 689, in detect_supported_drives
    if self.device_can_be_upgraded(data):
  File "/usr/lib/python2.7/dist-packages/tails_installer/creator.py", line 937, in device_can_be_upgraded
    return self.is_partition_GPT(device) and device['fstype'] == 'vfat' \
  File "/usr/lib/python2.7/dist-packages/tails_installer/creator.py", line 920, in is_partition_GPT
    if not obj.props.partition :
AttributeError: 'NoneType' object has no attribute 'props'
2017-12-09 09:10:25,601 [gui.py:265 (run)] DEBUG: Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/tails_installer/gui.py", line 198, in run
    self.rescan_devices(force_partitions=False)
  File "/usr/lib/python2.7/dist-packages/tails_installer/gui.py", line 177, in rescan_devices
    force_partitions=force_partitions)
  File "/usr/lib/python2.7/dist-packages/tails_installer/creator.py", line 689, in detect_supported_drives
    if self.device_can_be_upgraded(data):
  File "/usr/lib/python2.7/dist-packages/tails_installer/creator.py", line 937, in device_can_be_upgraded
    return self.is_partition_GPT(device) and device['fstype'] == 'vfat' \
  File "/usr/lib/python2.7/dist-packages/tails_installer/creator.py", line 920, in is_partition_GPT
    if not obj.props.partition :
AttributeError: 'NoneType' object has no attribute 'props'
    And I install Tails to USB drive "isohybrid" by cloning                                                                                       # features/step_definitions/usb.rb:129
      try_for() timeout expired
      Last ignored exception was: RuntimeError: The Dogtail script raised: SearchError: descendent of [application | tails-installer]: child with name="Information" roleName='alert' (Timeout::Error)
      ./features/support/helpers/misc_helpers.rb:90:in `rescue in try_for'
      ./features/support/helpers/misc_helpers.rb:36:in `/^I (install|reinstall|upgrade) Tails (?:to|on) USB drive "([^"]+)" (by cloning|from an ISO)$/'
      features/usb_install.feature:112:in `And I install Tails to USB drive "isohybrid" by cloning'

Files

01_31_14_Writing_a_Tails_isohybrid_to_a_USB_drive_and_booting_it,_then_installing_Tails_on_top_of_it_using_Tails_Installer,_and_it_still_boots.png (46267 B)	intrigeri, 2017-12-09 14:58:37
#15031 (77692 B)	mercedes508, 2018-01-19 12:11:13

Subtasks

Related issues

Related to Tails - ~~Bug #10988~~: Tails Installer workarounds for UDisks 2 bugs are not robust enough	Rejected	2015-12-07
Related to Tails - ~~Bug #14724~~: Make Tails Installer's isohybrid detection code robust	Rejected	2017-09-25
Related to Tails - ~~Bug #10912~~: Tails Installer fails to install on USB stick that has a isohybrid dd'ed to it	Resolved	2016-01-12

History

#1 Updated by intrigeri 2017-12-09 15:02:11

related to ~~Bug #10988~~: Tails Installer workarounds for UDisks 2 bugs are not robust enough added

#2 Updated by intrigeri 2017-12-15 06:22:48

related to ~~Bug #14724~~: Make Tails Installer's isohybrid detection code robust added

#3 Updated by intrigeri 2017-12-15 06:37:21

Actually, I think it’s a bug in Tails Installer, that our test suite happens to expose currently, but I don’t see why it would not happen to real users: ~~Bug #14724~~.

#4 Updated by mercedes508 2018-01-14 12:36:37

Assignee set to intrigeri

I just received a bug report from someone experiencing this issue. So certainly a bug in Tails Installer.

Do you need some logs to investigate?

#5 Updated by intrigeri 2018-01-15 11:18:27

Category changed from Test suite to Installation
Assignee changed from intrigeri to mercedes508

> I just received a bug report from someone experiencing this issue. So certainly a bug in Tails Installer.

Thanks! Adjusting metadata accordingly.

> Do you need some logs to investigate?

Yes, I’ll need the full output of tails-installer --verbose.

#6 Updated by mercedes508 2018-01-19 12:11:31

File #15031 added
Assignee changed from mercedes508 to intrigeri

Hi,

> Yes, I’ll need the full output of tails-installer --verbose.

here they are attached

#7 Updated by intrigeri 2018-01-20 09:00:17

Assignee changed from intrigeri to kurono
Target version set to Tails_3.6

kurono, I think this is either the same bug as ~~Bug #14724~~, or will be incidentally fixed when you fix ~~Bug #14724~~.

#8 Updated by intrigeri 2018-03-05 07:31:48

Priority changed from Normal to Elevated

(This is making my work on ~~Feature #14595~~ more painful than it should be.)

#9 Updated by kurono 2018-03-10 12:20:27

Assignee changed from kurono to intrigeri
QA Check set to Ready for QA
Feature Branch set to kurono/bug/15031-isohybrid-by-cloning-often-fails

intrigeri wrote:
> (This is making my work on ~~Feature #14595~~ more painful than it should be.)

Sorry about it :/

I have added a small fix that “should” help with this specific ticket, however I still would need to run the testing setup, which I haven’t tried to use since long time ago. Also I am still reviewing the isohybrid stuff related ~~Bug #14724~~

#10 Updated by intrigeri 2018-03-10 23:50:50

Target version changed from Tails_3.6 to Tails_3.7

Thanks! It’s too late for 3.6 IMO so I’ll take a look at it ASAP i.e. in a week or so.

#11 Updated by kurono 2018-03-11 13:42:21

intrigeri wrote:
> Thanks! It’s too late for 3.6 IMO so I’ll take a look at it ASAP i.e. in a week or so.

cool :) I have added a small fix. I have actually checked it with the test suite (only the current scenario) and it passes.

#12 Updated by intrigeri 2018-03-22 09:17:55

Status changed from Confirmed to In Progress
Assignee changed from intrigeri to kurono
% Done changed from 0 to 10
QA Check changed from Ready for QA to Dev Needed

kurono wrote:
> cool :) I have added a small fix. I have actually checked it with the test suite (only the current scenario) and it passes.

Did you ever see that scenario fail without your fix? (on our Jenkins it often fails, but not always, which triggers my race condition detector)

I suspect you mean if obj is None or not obj.props.partition, don’t you?

I wonder if we’re papering over the bug here: it looks like we somehow pass is_partition_GPT a weird argument that will make self._get_object(drive['udi']) to be None. I’m not opposed to adding the check you’re proposing but I think we should also:

modify device_can_be_upgraded so that it checks if device_is_isohybrid before calling is_partition_GPT, which should 1. avoid running code we know cannot possibly work; and 2. produce easier to understand tracebacks next time we have issues in this area. What do you think?
take a look at detect_supported_drives to see if we should use device_is_isohybrid in the code that’s run if not force_partitions and self.opts.partition; honestly I don’t understand this part of the code anymore :/

I’ll now import your topic branch as a patch in tails.git so we see how it fares on Jenkins :)

#13 Updated by intrigeri 2018-03-22 09:23:44

Feature Branch changed from kurono/bug/15031-isohybrid-by-cloning-often-fails to bug/15031-isohybrid-by-cloning-often-fails, installer:kurono/bug/15031-isohybrid-by-cloning-often-fails

#14 Updated by intrigeri 2018-03-22 14:06:16

intrigeri wrote:
> I’ll now import your topic branch as a patch in tails.git so we see how it fares on Jenkins :)

It breaks (almost?) all scenarios that use Tails Installer.

#15 Updated by kurono 2018-04-01 20:48:42

Assignee changed from kurono to intrigeri
% Done changed from 10 to 20
QA Check changed from Dev Needed to Ready for QA

intrigeri wrote:
> kurono wrote:
> > cool :) I have added a small fix. I have actually checked it with the test suite (only the current scenario) and it passes.
>
> Did you ever see that scenario fail without your fix? (on our Jenkins it often fails, but not always, which triggers my race condition detector)
>

Yes, I could reproduce this bug.

> I suspect you mean if obj is None or not obj.props.partition, don’t you?
>

ahh, yes I have fixed this.

> I wonder if we’re papering over the bug here: it looks like we somehow pass is_partition_GPT a weird argument that will make self._get_object(drive['udi']) to be None. I’m not opposed to adding the check you’re proposing but I think we should also:
> * modify device_can_be_upgraded so that it checks if device_is_isohybrid before calling is_partition_GPT, which should 1. avoid running code we know cannot possibly work; and 2. produce easier to understand tracebacks next time we have issues in this area. What do you think?

Yeah :) I have added your recommendation and I have changed that method parameter name “drive” ==> “device_data”, so it is more readable.

> * take a look at detect_supported_drives to see if we should use device_is_isohybrid in the code that’s run if not force_partitions and self.opts.partition; honestly I don’t understand this part of the code anymore :/
>

well I think that is already being verified now in device_can_be_upgraded.

> I’ll now import your topic branch as a patch in tails.git so we see how it fares on Jenkins :)

I have run all the tests scenarios, but the ones that involve a persistence partition fail. I don’t think it is related to my new fix.

#16 Updated by intrigeri 2018-04-10 07:22:25

Hi kurono!

First, I see you’ve merged the current master branch into yours. It was a great idea except someone had erroneously pushed the Debian packaging Git history to our master branch (that’s meant for upstream development). I’ve fixed our master branch and I’ve transplanted your topic branch to it with git rebase --onto master 5b0e8ee bug/15031-isohybrid-by-cloning-often-fails. I’ve then taken the liberty to force-push your topic branch. FTR it was at commit db80859 before I rewrote its history.

kurono wrote:
> intrigeri wrote:
>> kurono wrote:
>> > cool :) I have added a small fix. I have actually checked it with the test suite (only the current scenario) and it passes.
>>
>> Did you ever see that scenario fail without your fix? (on our Jenkins it often fails, but not always, which triggers my race condition detector)

> Yes, I could reproduce this bug.

Great!

>> I suspect you mean if obj is None or not obj.props.partition, don’t you?

> ahh, yes I have fixed this.

ACK, looks good to me.

>> I wonder if we’re papering over the bug here: it looks like we somehow pass is_partition_GPT a weird argument that will make self._get_object(drive['udi']) to be None. I’m not opposed to adding the check you’re proposing but I think we should also:
>> * modify device_can_be_upgraded so that it checks if device_is_isohybrid before calling is_partition_GPT, which should 1. avoid running code we know cannot possibly work; and 2. produce easier to understand tracebacks next time we have issues in this area. What do you think?

> Yeah :) I have added your recommendation and I have changed that method parameter name “drive” ==> “device_data”, so it is more readable.

Looks good to me.

>> * take a look at detect_supported_drives to see if we should use device_is_isohybrid in the code that’s run if not force_partitions and self.opts.partition; honestly I don’t understand this part of the code anymore :/
>>

> well I think that is already being verified now in device_can_be_upgraded.

OK.

>> I’ll now import your topic branch as a patch in tails.git so we see how it fares on Jenkins :)

> I have run all the tests scenarios, but the ones that involve a persistence partition fail. I don’t think it is related to my new fix.

I suspect you’re hit by ~~Bug #12142~~ aka https://bugs.debian.org/851694. We’ve been maintaining a package with the fix in deb http://deb.tails.boum.org/ isotester-stretch main that we use on our Jenkins setup. anonym and I run sid where this bug has been fixed already.

I’ll now run the full test suite with your code in! :)

#17 Updated by intrigeri 2018-04-10 12:13:41

> I’ll now run the full test suite with your code in! :)

No relevant failure on my first runs (1 locally + 1 on Jenkins). But the problem this ticket is about does not happen every time so I’ll wait for more test suite runs before I call it done.

#18 Updated by intrigeri 2018-04-10 14:01:26

related to ~~Bug #10912~~: Tails Installer fails to install on USB stick that has a isohybrid dd'ed to it added

#19 Updated by intrigeri 2018-04-11 13:00:14

Subject changed from 'I install Tails to USB drive "isohybrid" by cloning' test step often fails to Installing to a device that previously had an hybrid ISO copied to it is fragile
% Done changed from 20 to 50
Parent task deleted (~~Bug #10288~~)

All tests pass so far so I’ve merged this into the master branch of the Installer. I’m now going to release Tails Installer 5.0.6 and will upload it to the topic branch’s APT overlay.

#20 Updated by intrigeri 2018-04-11 13:26:48

Status changed from In Progress to Fix committed
Assignee deleted (~~intrigeri~~)
% Done changed from 50 to 100
QA Check changed from Ready for QA to Pass

Released and uploaded, merged into stable and devel. Thanks!

#21 Updated by intrigeri 2018-04-11 23:52:23

Status changed from Fix committed to In Progress

Applied in changeset commit:faf428d112ef2b73bf126624bbd89d2e2544cf4f.

#22 Updated by intrigeri 2018-04-12 07:13:04

Status changed from In Progress to Fix committed

#23 Updated by bertagaz 2018-05-10 10:59:50

Status changed from Fix committed to Resolved